Improve logging middleware to add info methods to request object

services/filestore/app.js

@@ -26,7 +26,9 @@ if (Metrics.event_loop) {
   Metrics.event_loop.monitor(logger)
 }
 
-app.use(Metrics.http.monitor(logger))
+app.use(RequestLogger.middleware)
+app.use(RequestLogger.errorHandler)
+
 app.use(function(req, res, next) {
   Metrics.inc('http-request')
   res.logInfo = {}
@@ -140,9 +142,6 @@ app.get('/status', function(req, res) {
 
 app.get('/health_check', healthCheckController.check)
 
-app.use(RequestLogger.logRequest)
-app.use(RequestLogger.logError)
-
 const port = settings.internal.filestore.port || 3009
 const host = '0.0.0.0'
 

services/filestore/app/js/FileController.js

@@ -27,15 +27,21 @@ function getFile(req, res, next) {
   }
 
   metrics.inc('getFile')
-  res.logMsg = 'getting file'
-  res.logInfo = { key, bucket, format, style, cacheWarm: req.query.cacheWarm }
+  req.setLogMessage('getting file')
+  req.addLogFields({
+    key,
+    bucket,
+    format,
+    style,
+    cacheWarm: req.query.cacheWarm
+  })
 
   if (req.headers.range) {
     const range = _getRange(req.headers.range)
     if (range) {
       options.start = range.start
       options.end = range.end
-      res.logInfo.range = range
+      req.addLogField('range', range)
     }
   }
 
@@ -43,8 +49,6 @@ function getFile(req, res, next) {
     if (err) {
       if (err instanceof Errors.NotFoundError) {
         res.sendStatus(404)
-        res.logInfo.notFound = true
-        next()
       } else {
         next(err)
       }
@@ -52,8 +56,7 @@ function getFile(req, res, next) {
     }
 
     if (req.query.cacheWarm) {
-      res.sendStatus(200)
-      return next()
+      return res.sendStatus(200).end()
     }
 
     pipeline(fileStream, res, err => {
@@ -64,8 +67,6 @@ function getFile(req, res, next) {
             info: { bucket, key, format, style }
           }).withCause(err)
         )
-      } else {
-        next()
       }
     })
   })
@@ -75,15 +76,13 @@ function getFileHead(req, res, next) {
   const { key, bucket } = req
 
   metrics.inc('getFileSize')
-  res.logMsg = 'getting file size'
-  res.logInfo = { key, bucket }
+  req.setLogMessage('getting file size')
+  req.addLogFields({ key, bucket })
 
   FileHandler.getFileSize(bucket, key, function(err, fileSize) {
     if (err) {
       if (err instanceof Errors.NotFoundError) {
         res.sendStatus(404)
-        res.logInfo.notFound = true
-        next()
       } else {
         next(err)
       }
@@ -91,7 +90,6 @@ function getFileHead(req, res, next) {
     }
     res.set('Content-Length', fileSize)
     res.status(200).end()
-    next()
   })
 }
 
@@ -99,15 +97,14 @@ function insertFile(req, res, next) {
   metrics.inc('insertFile')
   const { key, bucket } = req
 
-  res.logMsg = 'inserting file'
-  res.logInfo = { key, bucket }
+  req.setLogMessage('inserting file')
+  req.addLogFields({ key, bucket })
 
   FileHandler.insertFile(bucket, key, req, function(err) {
     if (err) {
       next(err)
     } else {
       res.sendStatus(200)
-      next()
     }
   })
 }
@@ -118,13 +115,13 @@ function copyFile(req, res, next) {
   const oldProjectId = req.body.source.project_id
   const oldFileId = req.body.source.file_id
 
-  req.logInfo = {
+  req.addLogFields({
     key,
     bucket,
     oldProject_id: oldProjectId,
     oldFile_id: oldFileId
-  }
-  req.logMsg = 'copying file'
+  })
+  req.setLogMessage('copying file')
 
   PersistorManager.copyFile(
     bucket,
@@ -134,8 +131,6 @@ function copyFile(req, res, next) {
       if (err) {
         if (err instanceof Errors.NotFoundError) {
           res.sendStatus(404)
-          res.logInfo.notFound = true
-          next()
         } else {
           next(err)
         }
@@ -143,7 +138,6 @@ function copyFile(req, res, next) {
       }
 
       res.sendStatus(200)
-      next()
     }
   )
 }
@@ -152,15 +146,14 @@ function deleteFile(req, res, next) {
   metrics.inc('deleteFile')
   const { key, bucket } = req
 
-  req.logInfo = { key, bucket }
-  req.logMsg = 'deleting file'
+  req.addLogFields({ key, bucket })
+  req.setLogMessage('deleting file')
 
   FileHandler.deleteFile(bucket, key, function(err) {
     if (err) {
       next(err)
     } else {
       res.sendStatus(204)
-      next()
     }
   })
 }
@@ -169,8 +162,8 @@ function directorySize(req, res, next) {
   metrics.inc('projectSize')
   const { project_id: projectId, bucket } = req
 
-  req.logMsg = 'getting project size'
-  req.logInfo = { projectId, bucket }
+  req.setLogMessage('getting project size')
+  req.addLogFields({ projectId, bucket })
 
   FileHandler.getDirectorySize(bucket, projectId, function(err, size) {
     if (err) {
@@ -178,8 +171,7 @@ function directorySize(req, res, next) {
     }
 
     res.json({ 'total bytes': size })
-    req.logInfo.size = size
-    next()
+    req.addLogField('size', size)
   })
 }
 

services/filestore/app/js/RequestLogger.js

@@ -1,32 +1,83 @@
 const logger = require('logger-sharelatex')
+const metrics = require('metrics-sharelatex')
 
 module.exports = {
-  logRequest,
-  logError
+  errorHandler,
+  middleware
 }
 
-function logRequest(req, res) {
-  // response has already been sent, but we log what happened here
-  logger.log(
-    {
-      info: res.logInfo,
-      url: req.originalUrl,
-      params: req.params
-    },
-    res.logMsg || 'HTTP request'
-  )
+function errorHandler(err, req, res, next) {
+  req._logInfo.set('error', err)
+  res
+    .send(err.message)
+    .status(500)
+    .end()
 }
 
-function logError(err, req, res, next) {
-  logger.err(
+function middleware(req, res, next) {
+  const startTime = new Date()
+
+  // methods to allow the setting of additional information to be logged for the request
+  req._logInfo = {}
+  req._logMessage = 'http request'
+  req.addLogField = function(field, value) {
+    req._logInfo[field] = value
+  }
+  req.addLogFields = function(fields) {
+    Object.assign(req._logInfo, fields)
+  }
+  req.setLogMessage = function(message) {
+    req._logMessage = message
+  }
+
+  // override the 'end' method to log and record metrics
+  const end = res.end
+  res.end = function() {
+    // apply the standard request 'end' method before logging and metrics
+    end.apply(this, arguments)
+
+    const responseTime = new Date() - startTime
+
+    const routePath = req.route && req.route.path.toString()
+
+    if (routePath) {
+      metrics.timing('http_request', responseTime, null, {
+        method: req.method,
+        status_code: res.statusCode,
+        path: routePath
+          .replace(/\//g, '_')
+          .replace(/:/g, '')
+          .slice(1)
+      })
+    }
+
+    const level = res.statusCode >= 500 ? 'err' : 'log'
+    logger[level](
       {
-      err,
-      info: res.logInfo,
-      url: req.originalUrl,
-      params: req.params,
-      msg: res.logMsg
+        req: {
+          url: req.originalUrl || req.url,
+          route: routePath,
+          method: req.method,
+          referrer: req.headers.referer || req.headers.referrer,
+          'remote-addr':
+            req.ip ||
+            (req.socket && req.socket.remoteAddress) ||
+            (req.socket &&
+              req.socket.socket &&
+              req.socket.socket.remoteAddress),
+          'user-agent': req.headers['user-agent'],
+          'content-length': req.headers['content-length']
         },
-    err.message
+        res: {
+          'content-length': res._headers['content-length'],
+          statusCode: res.statusCode,
+          'response-time': responseTime
+        },
+        info: req._logInfo
+      },
+      req._logMessage
     )
-  next(err) // use the standard error handler to send the response
+  }
+
+  next()
 }

services/filestore/test/unit/js/FileControllerTests.js

@@ -72,7 +72,10 @@ describe('FileController', function() {
         project_id: projectId,
         file_id: fileId
       },
-      headers: {}
+      headers: {},
+      setLogMessage: sinon.stub(),
+      addLogField: sinon.stub(),
+      addLogFields: sinon.stub()
     }
 
     res = {