Merge pull request #7905 from overleaf/em-request-logging

Make request logging configurable

GitOrigin-RevId: 15281664bc32f5cdafa1b99d9a755d2bf8671a08

libraries/metrics/http.js

@@ -1,15 +1,15 @@
 const Metrics = require('./index')
 
-module.exports.monitor = logger =>
+function monitor(logger, level = 'debug') {
-  function (req, res, next) {
+  return function (req, res, next) {
     const startTime = Date.now()
+    req.logger = new RequestLogger(logger, level)
     const { end } = res
     res.end = function (...args) {
       end.apply(this, args)
       const responseTimeMs = Date.now() - startTime
       const requestSize = parseInt(req.headers['content-length'], 10)
       const routePath = getRoutePath(req)
-      const reqUrl = req.originalUrl || req.url
 
       if (routePath != null) {
         Metrics.timing('http_request', responseTimeMs, null, {
@@ -25,10 +25,12 @@ module.exports.monitor = logger =>
           })
         }
       }
-      logger.info({ req, res, responseTimeMs }, '%s %s', req.method, reqUrl)
+      req.logger.addFields({ responseTimeMs })
+      req.logger.emit(req, res)
     }
     next()
   }
+}
 
 function getRoutePath(req) {
   if (req.route && req.route.path != null) {
@@ -43,3 +45,34 @@ function getRoutePath(req) {
   }
   return null
 }
+
+class RequestLogger {
+  constructor(logger, level) {
+    this._logger = logger
+    this._level = level
+    this._info = {}
+  }
+
+  addFields(fields) {
+    Object.assign(this._info, fields)
+  }
+
+  setLevel(level) {
+    this._level = level
+  }
+
+  disable() {
+    this._disabled = true
+  }
+
+  emit(req, res) {
+    if (this._disabled) {
+      return
+    }
+    this.addFields({ req, res })
+    const url = req.originalUrl || req.url
+    this._logger[this._level](this._info, '%s %s', req.method, url)
+  }
+}
+
+module.exports.monitor = monitor

libraries/metrics/test/unit/js/http.js

@@ -0,0 +1,171 @@
+const Path = require('path')
+const SandboxedModule = require('sandboxed-module')
+const sinon = require('sinon')
+
+const MODULE_PATH = Path.join(__dirname, '../../../http.js')
+
+describe('http.monitor', function () {
+  beforeEach(function () {
+    this.req = {
+      method: 'POST',
+      url: '/project/1234/cleanup',
+      headers: {
+        'content-length': '123',
+      },
+      route: {
+        path: '/project/:id/cleanup',
+      },
+    }
+    this.originalResponseEnd = sinon.stub()
+    this.res = {
+      end: this.originalResponseEnd,
+    }
+    this.data = 'data'
+    this.logger = {
+      debug: sinon.stub(),
+      info: sinon.stub(),
+      warn: sinon.stub(),
+    }
+    this.Metrics = {
+      timing: sinon.stub(),
+      summary: sinon.stub(),
+    }
+    this.clock = sinon.useFakeTimers()
+
+    this.http = SandboxedModule.require(MODULE_PATH, {
+      requires: {
+        './index': this.Metrics,
+      },
+    })
+  })
+
+  afterEach(function () {
+    this.clock.restore()
+  })
+
+  describe('with the default options', function () {
+    beforeEach('set up the monitor', function (done) {
+      this.http.monitor(this.logger)(this.req, this.res, done)
+    })
+
+    describe('after a simple request', function () {
+      endRequest()
+      expectOriginalEndCalled()
+      expectMetrics()
+
+      it('logs the request at the DEBUG level', function () {
+        sinon.assert.calledWith(
+          this.logger.debug,
+          { req: this.req, res: this.res, responseTimeMs: 500 },
+          '%s %s',
+          this.req.method,
+          this.req.url
+        )
+      })
+    })
+
+    describe('when logging is disabled', function () {
+      beforeEach('disable logging', function () {
+        this.req.logger.disable()
+      })
+
+      endRequest()
+      expectOriginalEndCalled()
+      expectMetrics()
+
+      it("doesn't log the request", function () {
+        sinon.assert.notCalled(this.logger.debug)
+      })
+    })
+
+    describe('with custom log fields', function () {
+      beforeEach('add custom fields', function () {
+        this.req.logger.addFields({ a: 1, b: 2 })
+      })
+
+      endRequest()
+
+      it('logs the request with the custom log fields', function () {
+        sinon.assert.calledWith(
+          this.logger.debug,
+          { req: this.req, res: this.res, responseTimeMs: 500, a: 1, b: 2 },
+          '%s %s',
+          this.req.method,
+          this.req.url
+        )
+      })
+    })
+
+    describe('when setting the log level', function () {
+      beforeEach('set custom level', function () {
+        this.req.logger.setLevel('warn')
+      })
+
+      endRequest()
+
+      it('logs the request at the custom level', function () {
+        sinon.assert.calledWith(
+          this.logger.warn,
+          { req: this.req, res: this.res, responseTimeMs: 500 },
+          '%s %s',
+          this.req.method,
+          this.req.url
+        )
+      })
+    })
+  })
+
+  describe('with a different default log level', function () {
+    beforeEach('set up the monitor', function (done) {
+      this.http.monitor(this.logger, 'info')(this.req, this.res, done)
+    })
+
+    endRequest()
+
+    it('logs the request at that level', function () {
+      sinon.assert.calledWith(
+        this.logger.info,
+        { req: this.req, res: this.res, responseTimeMs: 500 },
+        '%s %s',
+        this.req.method,
+        this.req.url
+      )
+    })
+  })
+})
+
+function endRequest() {
+  beforeEach('end the request', function () {
+    this.clock.tick(500)
+    this.res.end(this.data)
+  })
+}
+
+function expectOriginalEndCalled() {
+  it('calls the original res.end()', function () {
+    sinon.assert.calledWith(this.originalResponseEnd, this.data)
+  })
+}
+
+function expectMetrics() {
+  it('records the response time', function () {
+    sinon.assert.calledWith(this.Metrics.timing, 'http_request', 500, null, {
+      method: this.req.method,
+      status_code: this.res.status_code,
+      path: 'project_id_cleanup',
+    })
+  })
+
+  it('records the request size', function () {
+    sinon.assert.calledWith(
+      this.Metrics.summary,
+      'http_request_size_bytes',
+      123,
+      {
+        method: this.req.method,
+        status_code: this.res.status_code,
+        path: 'project_id_cleanup',
+      }
+    )
+  })
+}