Add option to log every request start and end to loggly (#15243)

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",

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;
+  });
+});

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);

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));
   }

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();
+};