Merge pull request #15419 from overleaf/em-error-request-logging

Use the request logger for errors in web

GitOrigin-RevId: f654fc69e0bbdab8b16d23b007aefbad08925358

services/web/app/src/Features/Collaborators/CollaboratorsInviteController.js

@@ -85,6 +85,7 @@ const CollaboratorsInviteController = {
     let { email, privileges } = req.body
     const sendingUser = SessionManager.getSessionUser(req.session)
     const sendingUserId = sendingUser._id
+    req.logger.addFields({ email, sendingUserId })
 
     if (email === sendingUser.email) {
       logger.debug(

services/web/app/src/Features/Errors/ErrorController.js

@@ -1,6 +1,5 @@
 let ErrorController
 const Errors = require('./Errors')
-const logger = require('@overleaf/logger')
 const SessionManager = require('../Authentication/SessionManager')
 const SamlLogHandler = require('../SamlLog/SamlLogHandler')
 const HttpErrorHandler = require('./HttpErrorHandler')
@@ -25,20 +24,20 @@ module.exports = ErrorController = {
   handleError(error, req, res, next) {
     const shouldSendErrorResponse = !res.headersSent
     const user = SessionManager.getSessionUser(req.session)
+    req.logger.addFields({ err: error })
     // log errors related to SAML flow
     if (req.session && req.session.saml) {
+      req.logger.setLevel('error')
       SamlLogHandler.log(req, { error })
     }
     if (error.code === 'EBADCSRFTOKEN') {
-      logger.warn(
-        { err: error, url: req.url, method: req.method, user },
-        'invalid csrf'
-      )
+      req.logger.addFields({ user })
+      req.logger.setLevel('warn')
       if (shouldSendErrorResponse) {
         res.sendStatus(403)
       }
     } else if (error instanceof Errors.NotFoundError) {
-      logger.warn({ err: error, url: req.url }, 'not found error')
+      req.logger.setLevel('warn')
       if (shouldSendErrorResponse) {
         ErrorController.notFound(req, res)
       }
@@ -46,46 +45,40 @@ module.exports = ErrorController = {
       error instanceof URIError &&
       error.message.match(/^Failed to decode param/)
     ) {
-      logger.warn({ err: error, url: req.url }, 'Express URIError')
+      req.logger.setLevel('warn')
       if (shouldSendErrorResponse) {
         res.status(400)
         res.render('general/500', { title: 'Invalid Error' })
       }
     } else if (error instanceof Errors.ForbiddenError) {
-      logger.error({ err: error }, 'forbidden error')
+      req.logger.setLevel('warn')
       if (shouldSendErrorResponse) {
         ErrorController.forbidden(req, res)
       }
     } else if (error instanceof Errors.TooManyRequestsError) {
-      logger.warn({ err: error, url: req.url }, 'too many requests error')
+      req.logger.setLevel('warn')
       if (shouldSendErrorResponse) {
         res.sendStatus(429)
       }
     } else if (error instanceof Errors.InvalidError) {
-      logger.warn({ err: error, url: req.url }, 'invalid error')
+      req.logger.setLevel('warn')
       if (shouldSendErrorResponse) {
         res.status(400)
         plainTextResponse(res, error.message)
       }
     } else if (error instanceof Errors.InvalidNameError) {
-      logger.warn({ err: error, url: req.url }, 'invalid name error')
+      req.logger.setLevel('warn')
       if (shouldSendErrorResponse) {
         res.status(400)
         plainTextResponse(res, error.message)
       }
     } else if (error instanceof Errors.SAMLSessionDataMissing) {
-      logger.warn(
-        { err: error, url: req.url },
-        'missing SAML session data error'
-      )
+      req.logger.setLevel('warn')
       if (shouldSendErrorResponse) {
         HttpErrorHandler.badRequest(req, res, error.message)
       }
     } else {
-      logger.error(
-        { err: error, url: req.url, method: req.method, user },
-        'error passed to top level next middleware'
-      )
+      req.logger.setLevel('error')
       if (shouldSendErrorResponse) {
         ErrorController.serverError(req, res)
       }
@@ -97,21 +90,19 @@ module.exports = ErrorController = {
     }
   },
 
-  handleApiError(error, req, res, next) {
-    if (error instanceof Errors.NotFoundError) {
-      logger.warn({ err: error, url: req.url }, 'not found error')
+  handleApiError(err, req, res, next) {
+    req.logger.addFields({ err })
+    if (err instanceof Errors.NotFoundError) {
+      req.logger.setLevel('warn')
       res.sendStatus(404)
     } else if (
-      error instanceof URIError &&
-      error.message.match(/^Failed to decode param/)
+      err instanceof URIError &&
+      err.message.match(/^Failed to decode param/)
     ) {
-      logger.warn({ err: error, url: req.url }, 'Express URIError')
+      req.logger.setLevel('warn')
       res.sendStatus(400)
     } else {
-      logger.error(
-        { err: error, url: req.url, method: req.method },
-        'error passed to top level next middleware'
-      )
+      req.logger.setLevel('error')
       res.sendStatus(500)
     }
   },

services/web/app/src/Features/Errors/HttpErrorHandler.js

@@ -45,14 +45,15 @@ function handleGeneric400Error(req, res, statusCode, message, info = {}) {
 
 let HttpErrorHandler
 module.exports = HttpErrorHandler = {
-  handleErrorByStatusCode(req, res, error, statusCode) {
+  handleErrorByStatusCode(req, res, err, statusCode) {
     const is400Error = statusCode >= 400 && statusCode < 500
     const is500Error = statusCode >= 500 && statusCode < 600
 
+    req.logger.addFields({ err })
     if (is400Error) {
-      logger.warn(error)
+      req.logger.setLevel('warn')
     } else if (is500Error) {
-      logger.error(error)
+      req.logger.setLevel('error')
     }
 
     if (statusCode === 403) {
@@ -68,10 +69,6 @@ module.exports = HttpErrorHandler = {
     } else if (is500Error) {
       handleGeneric500Error(req, res, statusCode)
     } else {
-      logger.error(
-        { err: error, statusCode },
-        `unable to handle error with status code ${statusCode}`
-      )
       res.sendStatus(500)
     }
   },
@@ -134,8 +131,9 @@ module.exports = HttpErrorHandler = {
     }
   },
 
-  legacyInternal(req, res, message, error) {
-    logger.error(error)
+  legacyInternal(req, res, message, err) {
+    req.logger.addFields({ err })
+    req.logger.setLevel('error')
     handleGeneric500Error(req, res, 500, message)
   },
 

services/web/app/src/Features/SamlLog/SamlLogHandler.js

@@ -29,16 +29,7 @@ function log(req, data, samlAssertion) {
       if (data.error.tryAgain) {
         errSerialized.tryAgain = data.error.tryAgain
       }
-      logger.error(
-        {
-          providerId,
-          sessionId,
-          userId,
-          path,
-          query,
-        },
-        'SAML Error Encountered'
-      )
+      req.logger.addFields({ providerId, sessionId, userId })
       data.error = errSerialized
     }
 

services/web/app/src/infrastructure/Server.js

@@ -130,6 +130,8 @@ app.set('views', Path.join(__dirname, '/../../views'))
 app.set('view engine', 'pug')
 Modules.loadViewIncludes(app)
 
+app.use(metrics.http.monitor(logger))
+
 Modules.registerAppMiddleware(app)
 app.use(bodyParser.urlencoded({ extended: true, limit: '2mb' }))
 app.use(bodyParser.json({ limit: Settings.max_json_request_size }))
@@ -137,8 +139,6 @@ app.use(methodOverride())
 // add explicit name for telemetry
 app.use(bearerTokenMiddleware())
 
-app.use(metrics.http.monitor(logger))
-
 if (Settings.blockCrossOriginRequests) {
   app.use(Csrf.blockCrossOriginRequests())
 }

services/web/test/unit/src/Errors/HttpErrorHandlerTests.js

@@ -340,7 +340,10 @@ describe('HttpErrorHandler', function () {
           'message',
           error
         )
-        expect(this.logger.error).to.have.been.calledWith(error)
+        expect(this.req.logger.setLevel).to.have.been.calledWith('error')
+        expect(this.req.logger.addFields).to.have.been.calledWith({
+          err: error,
+        })
       })
 
       it('should print a message when no content-type is included', function () {

services/web/test/unit/src/helpers/MockRequest.js

@@ -1,34 +1,32 @@
-// TODO: This file was created by bulk-decaffeinate.
-// Sanity-check the conversion and remove this comment.
-/*
- * decaffeinate suggestions:
- * DS206: Consider reworking classes to avoid initClass
- * Full docs: https://github.com/decaffeinate/decaffeinate/blob/master/docs/suggestions.md
- */
-class MockRequest {
-  static initClass() {
-    this.prototype.session = { destroy() {} }
+const sinon = require('sinon')
 
-    this.prototype.ip = '42.42.42.42'
-    this.prototype.headers = {}
-    this.prototype.params = {}
-    this.prototype.query = {}
-    this.prototype.body = {}
-    this.prototype._parsedUrl = {}
-    this.prototype.i18n = {
+class MockRequest {
+  constructor() {
+    this.session = { destroy() {} }
+
+    this.ip = '42.42.42.42'
+    this.headers = {}
+    this.params = {}
+    this.query = {}
+    this.body = {}
+    this._parsedUrl = {}
+    this.i18n = {
       translate(str) {
         return str
       },
     }
-    this.prototype.route = { path: '' }
-    this.prototype.accepts = () => {}
-    this.prototype.setHeader = () => {}
+    this.route = { path: '' }
+    this.accepts = () => {}
+    this.setHeader = () => {}
+    this.logger = {
+      addFields: sinon.stub(),
+      setLevel: sinon.stub(),
+    }
   }
 
   param(param) {
     return this.params[param]
   }
 }
-MockRequest.initClass()
 
 module.exports = MockRequest