From c9e880ca985d15211506de10968023c798ca988f Mon Sep 17 00:00:00 2001 From: Damian Fortuna Date: Tue, 25 Feb 2020 14:05:33 -0300 Subject: [PATCH] feat: Support logging an item on response by decorating request object (#34) This is a similar functionality to the one we have in auth0-server and allows as to add properties to the response log, this is useful to log the state of rate limits and things like those without having to add an extra log. --- eventlogger/hapi_server.js | 28 +++++++++++++++++---- eventlogger/hapi_server_v17.js | 26 ++++++++++++++++--- eventlogger/log_item_collector.js | 39 +++++++++++++++++++++++++++++ test/hapi_server.tests.js | 23 +++++++++++++++++ test/hapi_server_v17.tests.node8.js | 23 +++++++++++++++++ 5 files changed, 130 insertions(+), 9 deletions(-) create mode 100644 eventlogger/log_item_collector.js diff --git a/eventlogger/hapi_server.js b/eventlogger/hapi_server.js index 1a3b37b..b53c898 100644 --- a/eventlogger/hapi_server.js +++ b/eventlogger/hapi_server.js @@ -1,6 +1,8 @@ -var requests_start_time = {}; -var assign = require('lodash').assign; -var obfuscator = require('../lib/obfuscator'); +const requests_start_time = {}; +const assign = require('lodash').assign; +const obfuscator = require('../lib/obfuscator'); +const buildLogItemCollector = require('./log_item_collector'); +const LOG_ON_RESPONSE_SYMBOL = Symbol(); module.exports.watch = function (logger, server, options) { options = assign({}, { @@ -25,6 +27,17 @@ module.exports.watch = function (logger, server, options) { }; } + server.decorate('request', 'logOnResponse', (request) => { + const responseItemCollector = buildLogItemCollector(logger); + + request[LOG_ON_RESPONSE_SYMBOL] = responseItemCollector; + + return function logOnResponse(key, value) { + // Logs the value under the corresponding key on response log + responseItemCollector.addValue(key, value); + }; + }, { apply: true }); + server .on('request-internal', function (request, data, tags) { if (tags.received && request.path !== '/api/v2/test' && @@ -45,8 +58,13 @@ module.exports.watch = function (logger, server, options) { if (tags.response && request.path !== '/api/v2/test' && ignorePaths.indexOf(request.path) < 0) { - const rsponseLogEntry = createLogEntry(request, 'response'); - return logger.info(rsponseLogEntry, 'response'); + const responseLogEntry = createLogEntry(request, 'response'); + + if (request[LOG_ON_RESPONSE_SYMBOL]) { + request[LOG_ON_RESPONSE_SYMBOL].injectOn(responseLogEntry); + } + + return logger.info(responseLogEntry, 'response'); } }).on('request', function (request, data, tags) { const level = tags.debug ? 'debug': 'info'; diff --git a/eventlogger/hapi_server_v17.js b/eventlogger/hapi_server_v17.js index cd0914f..de562e5 100644 --- a/eventlogger/hapi_server_v17.js +++ b/eventlogger/hapi_server_v17.js @@ -1,5 +1,7 @@ -var assign = require('lodash').assign; -var obfuscator = require('../lib/obfuscator'); +const assign = require('lodash').assign; +const obfuscator = require('../lib/obfuscator'); +const LOG_ON_RESPONSE_SYMBOL = Symbol(); +const buildLogItemCollector = require('./log_item_collector'); module.exports.watch = function (logger, server, options) { options = assign({}, { @@ -76,8 +78,13 @@ module.exports.watch = function (logger, server, options) { if (ignorePaths.indexOf(request.path) >= 0) { return; } - const reponseLogEntry = createLogEntry(request, 'response'); - logger.info(reponseLogEntry, 'response'); + const responseLogEntry = createLogEntry(request, 'response'); + + if (request[LOG_ON_RESPONSE_SYMBOL]) { + request[LOG_ON_RESPONSE_SYMBOL].injectOn(responseLogEntry); + } + + logger.info(responseLogEntry, 'response'); } function onStartup() { @@ -91,6 +98,17 @@ module.exports.watch = function (logger, server, options) { logger.info({ log_type: 'server_log', data: event, tags }); } + server.decorate('request', 'logOnResponse', (request) => { + const responseItemCollector = buildLogItemCollector(logger); + + request[LOG_ON_RESPONSE_SYMBOL] = responseItemCollector; + + return function (key, value) { + // Logs the value under the corresponding key on response log + responseItemCollector.addValue(key, value); + }; + }, { apply: true }); + server.ext({ type: 'onRequest', method: onRequest }); server.events.on({ name: 'request', channels: 'internal' }, onRequestClosedOrAborted); server.events.on({ name: 'request', channels: 'error' }, onRequestError); diff --git a/eventlogger/log_item_collector.js b/eventlogger/log_item_collector.js new file mode 100644 index 0000000..41e8240 --- /dev/null +++ b/eventlogger/log_item_collector.js @@ -0,0 +1,39 @@ +const _ = require('lodash'); + +const MAX_LOG_ITEMS = 20; + +module.exports = (logger) => { + let items = []; + + function addValue(key, value) { + if (items.length > MAX_LOG_ITEMS) { + // This prevents memory leaks by not allowing an infinite amount + // of objects to be collected as part of log items + logger.error({ + log_type: 'too_many_log_on_response', + items + }, + 'The maximum amount of data to log has been exceed. We will ' + + 'log existing items as part of this error and cleanup items'); + + items = []; + } + + items.push({ key, value }); + } + + function injectOn(carrier) { + if (typeof carrier !== 'object' || carrier === null) { + return; + } + + for (let item of items) { + _.set(carrier, item.key, item.value); + } + } + + return { + addValue, + injectOn + }; +}; \ No newline at end of file diff --git a/test/hapi_server.tests.js b/test/hapi_server.tests.js index 389e60d..d37d73a 100644 --- a/test/hapi_server.tests.js +++ b/test/hapi_server.tests.js @@ -29,6 +29,15 @@ const startServer = (eventLoggerOptions, cb) => { return reply('Hello world!'); } }); + server.route({ + method: 'GET', + path: '/log_on_response', + handler: function(req, reply) { + req.logOnResponse('obj.value', 'test'); + + return reply('Hello world!'); + } + }); server.route({ method: 'GET', path: '/ignored', @@ -150,6 +159,20 @@ describe('watch Hapi server < v17', function () { }); }); + it('should log items on response time', function (done) { + eventLogger.logger.info = function(log_event) { + if (log_event.log_type === 'request') { + return; + } + + assert.equal(log_event.obj.value, 'test'); + }; + request.get(server.info.uri + '/log_on_response', function (error, response, body) { + assert.equal(body, 'Hello world!'); + done(); + }); + }); + it('should log server errors', function (done) { let event = null; let message = null; diff --git a/test/hapi_server_v17.tests.node8.js b/test/hapi_server_v17.tests.node8.js index 014be37..d8d695b 100644 --- a/test/hapi_server_v17.tests.node8.js +++ b/test/hapi_server_v17.tests.node8.js @@ -26,6 +26,15 @@ const startServer = async function(eventLoggerOptions) { return 'Hello world!'; } }); + server.route({ + method: 'GET', + path: '/log_on_response', + handler: function(req) { + req.logOnResponse('obj.value', 'test'); + + return 'Hello world!'; + } + }); server.route({ method: 'GET', path: '/ignored', @@ -111,6 +120,20 @@ describe('watch Hapi server v17', function () { }); }); + it('should log items on response time', function (done) { + eventLogger.logger.info = function(log_event) { + if (log_event.log_type === 'request') { + return; + } + + assert.equal(log_event.obj.value, 'test'); + }; + request.get(server.info.uri + '/log_on_response', function (error, response, body) { + assert.equal(body, 'Hello world!'); + done(); + }); + }); + it('should log request on aborted request', function (done) { eventLogger.logger.info = function(log_event, msg) { if (log_event.log_type === 'request') {