diff --git a/libraries/metrics/http.js b/libraries/metrics/http.js index 60c013719f..43568526c2 100644 --- a/libraries/metrics/http.js +++ b/libraries/metrics/http.js @@ -1,15 +1,15 @@ const Metrics = require('./index') -module.exports.monitor = logger => - function (req, res, next) { +function monitor(logger, level = 'debug') { + 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 diff --git a/libraries/metrics/test/unit/js/http.js b/libraries/metrics/test/unit/js/http.js new file mode 100644 index 0000000000..f049f293fd --- /dev/null +++ b/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', + } + ) + }) +}