From 9615a06e0fecd795d58b3f9ef7c978e0cd444beb Mon Sep 17 00:00:00 2001 From: Simon Detheridge Date: Fri, 10 Jan 2020 17:08:47 +0000 Subject: [PATCH] Improve logging middleware to add info methods to request object --- services/filestore/app.js | 7 +- services/filestore/app/js/FileController.js | 52 +++++----- services/filestore/app/js/RequestLogger.js | 99 ++++++++++++++----- .../test/unit/js/FileControllerTests.js | 5 +- 4 files changed, 104 insertions(+), 59 deletions(-) diff --git a/services/filestore/app.js b/services/filestore/app.js index 3147cd10c1..024ceb6834 100644 --- a/services/filestore/app.js +++ b/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' diff --git a/services/filestore/app/js/FileController.js b/services/filestore/app/js/FileController.js index a1508a20a4..c84ffa17d3 100644 --- a/services/filestore/app/js/FileController.js +++ b/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) }) } diff --git a/services/filestore/app/js/RequestLogger.js b/services/filestore/app/js/RequestLogger.js index 5d395097e8..1ae11020ce 100644 --- a/services/filestore/app/js/RequestLogger.js +++ b/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( - { - err, - info: res.logInfo, - url: req.originalUrl, - params: req.params, - msg: res.logMsg - }, - err.message - ) - next(err) // use the standard error handler to send the response +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]( + { + 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'] + }, + res: { + 'content-length': res._headers['content-length'], + statusCode: res.statusCode, + 'response-time': responseTime + }, + info: req._logInfo + }, + req._logMessage + ) + } + + next() } diff --git a/services/filestore/test/unit/js/FileControllerTests.js b/services/filestore/test/unit/js/FileControllerTests.js index c80938663d..579e0a59fa 100644 --- a/services/filestore/test/unit/js/FileControllerTests.js +++ b/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 = {