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

@@ -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';

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

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

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;

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') {