diff --git a/config.json.example b/config.json.example index 876f4e7c88..ebca73675c 100644 --- a/config.json.example +++ b/config.json.example @@ -32,6 +32,7 @@ "LOGGLY_CLIENT_TOKEN": "token", "LOGGLY_SUBDOMAIN": "example-subdomain", "LOGGLY_TOKEN": "example-token", + "LOG_REQUESTS_EXCESSIVE_MODE": "false", "MAINTENANCE_MODE": "false", "NODE_DB_URI": "mongodb://localhost:27017/habitica-dev?replicaSet=rs", "TEST_DB_URI": "mongodb://localhost:27017/habitica-test?replicaSet=rs", diff --git a/test/api/unit/middlewares/requestLogHandler.test.js b/test/api/unit/middlewares/requestLogHandler.test.js new file mode 100644 index 0000000000..d17a0deea4 --- /dev/null +++ b/test/api/unit/middlewares/requestLogHandler.test.js @@ -0,0 +1,37 @@ +/* eslint-disable global-require */ +import requireAgain from 'require-again'; +import { + generateRes, + generateReq, + generateNext, +} from '../../../helpers/api-unit.helper'; + +describe('requestLogHandler middleware', () => { + let res; let req; let + next; + const pathToMiddleWare = '../../../../website/server/middlewares/requestLogHandler'; + + beforeEach(() => { + res = generateRes(); + req = generateReq(); + next = generateNext(); + }); + + it('attaches start time and request ID object to req', () => { + const middleware = requireAgain(pathToMiddleWare); + + middleware.logRequestData(req, res, next); + + expect(req.requestStartTime).to.exist; + expect(req.requestStartTime).to.be.a('number'); + expect(req.requestIdentifier).to.exist; + expect(req.requestIdentifier).to.be.a('string'); + }); + + it('calls next', () => { + const middleware = requireAgain(pathToMiddleWare); + const spy = sinon.spy(); + middleware.logRequestData(req, res, spy); + expect(spy.calledOnce).to.be.true; + }); +}); diff --git a/test/helpers/api-unit.helper.js b/test/helpers/api-unit.helper.js index db867eb391..f56f2c477a 100644 --- a/test/helpers/api-unit.helper.js +++ b/test/helpers/api-unit.helper.js @@ -59,7 +59,17 @@ export function generateReq (options = {}) { header (header) { return this.headers[header]; }, + listeners: {}, session: {}, + on (key, func) { + if (!this.listeners[key]) { + this.listeners[key] = []; + } + this.listeners[key].push(func); + }, + end () { + this.listeners.close.forEach(func => func()); + }, }; const req = defaultsDeep(options, defaultReq); diff --git a/website/server/middlewares/index.js b/website/server/middlewares/index.js index 69639bdb1f..1fef88f054 100644 --- a/website/server/middlewares/index.js +++ b/website/server/middlewares/index.js @@ -31,10 +31,14 @@ import responseHandler from './response'; import { attachTranslateFunction, } from './language'; +import { + logRequestData, +} from './requestLogHandler'; const IS_PROD = nconf.get('IS_PROD'); const DISABLE_LOGGING = nconf.get('DISABLE_REQUEST_LOGGING') === 'true'; const ENABLE_HTTP_AUTH = nconf.get('SITE_HTTP_AUTH_ENABLED') === 'true'; +const LOG_REQUESTS_EXCESSIVE_MODE = nconf.get('LOG_REQUESTS_EXCESSIVE_MODE') === 'true'; // const PUBLIC_DIR = path.join(__dirname, '/../../client'); const SESSION_SECRET = nconf.get('SESSION_SECRET'); @@ -43,6 +47,10 @@ const TEN_YEARS = 1000 * 60 * 60 * 24 * 365 * 10; export default function attachMiddlewares (app, server) { setupExpress(app); + if (LOG_REQUESTS_EXCESSIVE_MODE) { + app.use(logRequestData); + } + if (ENABLE_CLUSTER) { app.use(domainMiddleware(server, mongoose)); } diff --git a/website/server/middlewares/requestLogHandler.js b/website/server/middlewares/requestLogHandler.js new file mode 100644 index 0000000000..b7d3a499a7 --- /dev/null +++ b/website/server/middlewares/requestLogHandler.js @@ -0,0 +1,30 @@ +import { v4 as uuid } from 'uuid'; +import logger from '../libs/logger'; + +export const logRequestEnd = (req, res) => { + const now = Date.now(); + const requestTime = now - req.requestStartTime; + logger.info('Request completed', { + requestId: req.requestIdentifier, + method: req.method, + url: req.originalUrl, + duration: requestTime, + endTime: now, + statusCode: res.statusCode, + }); +}; + +export const logRequestData = (req, res, next) => { + req.requestStartTime = Date.now(); + req.requestIdentifier = uuid(); + logger.info('Request started', { + requestId: req.requestIdentifier, + method: req.method, + url: req.originalUrl, + startTime: req.requestStartTime, + }); + req.on('close', () => { + logRequestEnd(req, res); + }); + next(); +};