Bunyan Loopback logging

1:middleware.json

{
  "initial:before": {
    "loopback#context": {
      "params": { "enableHttpContext": true }
    },
    "loopback#token": {},
    "loopback#favicon": {
      "params": "$!../client/images/govright-favicon.ico"
    },
    "./middleware/logging": {},
    "./middleware/request-logging": {}
  },
  ...
}

2:logging.js

// FILE PATH: server/middleware/logging.js

var _ = require('lodash');
var fs = require('fs');
var appRoot = require('app-root-path');
var bunyan = require('bunyan');
var uuid = require('uuid');

var loopback = require('loopback');

var DEFAULT_CONFIG = {
  name: 'loopback',
  serializers: {
    req: bunyan.stdSerializers.req,
    res: bunyan.stdSerializers.res,
    err: bunyan.stdSerializers.err
  },
  streams: [{
    type: 'stream',
    stream: process.stderr,
    level: 'error'
  },
  {
    type: 'file',
    path: appRoot.resolve('/logs/common.log'),
    // FIXME: Use LB environment configs to control this
    level: (process.env.NODE_ENV !== 'production')?'debug':'info'
  }]
};

/**
 * The flow of an interaction is being tracked on 3 levels of specificity:
 * 1. a unique id for the request (most-specific)
 * 2. the accessToken for the request (semi-specific)
 * 3. the user's id (least-specific)
 *
 * What does specificity mean?
 * Example: Let's say that you want to mine the logs and trace what a client,
 *          who logged in-&-out, might have accomplished within that session.
 *          Then you should focus-on closing the net by aggregating all logs
 *          by #2 & #3 because there would be multiple unique #1s within
 *          that session.
 *
 * @param config
 * @returns {Function}
 */
module.exports = function (config) {
  config = _.merge(DEFAULT_CONFIG, config);

  // Attempt to ensure file logging output path is available
  var logPath = appRoot.resolve('/logs');
  if (!fs.existsSync(logPath)) {
    try {
      fs.mkdirSync(logPath);
    } catch (e) {} // TODO: eating an error ... bad idea?
  }

  var logger = bunyan.createLogger(config);

  return function (req, res, next) {
    // Generate a new unique request ID if necessary
    req.id = res.id = req.id || uuid.v4();
    res.setHeader('Request-Id', req.id);

    var logCtx = { requestId: req.id };
    if (req.accessToken) {
      logCtx.accessToken = req.accessToken.id;
      logCtx.userId = req.accessToken.userId;
    }

    req.log = logger.child(logCtx, true);

    var loopbackContext = loopback.getCurrentContext();
    if (loopbackContext) loopbackContext.set('logger', req.log);

    next();
  };
};

3:request-logging.js

// FILE PATH: server/middleware/request-logging.js

// Inspiration for this comes from https://github.com/villadora/express-bunyan-logger

var _ = require('lodash');
var appRoot = require('app-root-path');
var bunyan = require('bunyan');
var useragent = require('useragent');
var util = require('util');

var DEFAULT_CONFIG = {
  // Extended config which is removed
  features: ['ip','method','url','referer','userAgent','body','responseTime','statusCode'],
  parseUA: false,
  truncateBody: false,

  bunyan: {
    name: 'loopback-requests',
    serializers: {
      req: bunyan.stdSerializers.req,
      res: bunyan.stdSerializers.res,
      err: bunyan.stdSerializers.err
    },
    streams: [{
      type: 'file',
      path: appRoot.resolve('/logs/requests.log'),
      level: 'info'
    }]
  }
};

module.exports = function (config) {
  config = _.merge(DEFAULT_CONFIG, config);

  var logger = bunyan.createLogger(config.bunyan);

  return function (req, res, next) {
    var startTime = process.hrtime();

    var logCtx = { requestId: req.id };
    if (req.accessToken) {
      logCtx.accessToken = req.accessToken.id;
      logCtx.userId = req.accessToken.userId;
    }

    var childLogger = logger.child(logCtx, true);

    res.on('finish', function() {
      childLogger.info(buildPayload(), 'request done');
    });

    res.on('close', function () {
      childLogger.warn(buildPayload(), 'socket closed');
    });

    next();

    function buildPayload() {
      var payload;
      var hrResponseTime = process.hrtime(startTime);
      var responseTime = hrResponseTime[0] * 1e3 + hrResponseTime[1] / 1e6;

      var properties = {
        ip: req.ip || req.connection.remoteAddress ||
              (req.socket && req.socket.remoteAddress) || (req.socket.socket && req.socket.socket.remoteAddress),
        method: req.method,
        url: (req.baseUrl || '') + (req.url || ''),
        referer: req.header('referer') || req.header('referrer'),
        userAgent: req.header('user-agent'),
        body: req.body,
        httpVersion: req.httpVersionMajor + '.' + req.httpVersionMinor,
        responseTime: responseTime,
        hrResponseTime: hrResponseTime,
        statusCode: res.statusCode,
        requestHeaders: req.headers,
        responseHeaders: res._headers,
        req: req,
        res: res
      };

      if (!config.features || config.features === '*') {
        payload = properties;
      } else {
        payload = _.pick(properties, config.features);
      }

      if (payload.userAgent && config.parseUA) {
        payload.userAgent = useragent.parse(payload.userAgent);
      }

      if (payload.body && config.truncateBody) {
        if (config.truncateBody === true) {
          config.truncateBody = 20;
        }
        payload.body = util.inspect(payload.body).substring(0, config.truncateBody);
      }

      return payload;
    }
  };
};

4:logger.js

// FILE PATH: common/lib/logger.js

var _ = require('lodash');
var loopback = require('loopback');

var LOG_LEVELS = [ 'fatal', 'error', 'warn', 'info','debug','trace'];
var _loggerCache = {};

module.exports = mkLogger();

function mkLogger () {
  // Recursive magic to allow us to build up scope. Enables us to do things like,
  // var log = logger('models:discussion');
  // ... later ...
  // log('functionName').info('...');
  var scope = Array.prototype.slice.call(arguments).join(':');
  if (_loggerCache[scope]) return _loggerCache[scope];

  var ctx =  scope ? mkLogger.bind(null, scope) : mkLogger.bind(null);

  LOG_LEVELS.forEach(function (level) {
    ctx[level] = mkLoggerLevel(level, scope);
  });

  _loggerCache[scope] = ctx;
  return ctx;
}

function mkLoggerLevel(level, scope) {
  return function () {
    var loopbackContext = loopback.getCurrentContext();
    if (!loopbackContext) return;

    var logger = loopbackContext.get('logger');
    if (!logger) {
      //return console.error('Logger missing from Loopback Context!');
      return;
    }

    var params = arguments;
    if (scope) {
      if (_.isObject(params[0])) {
        params[0].scope = scope;
      } else {
        params = Array.prototype.slice.call(arguments);
        params.unshift({ scope: scope });
      }
    }
    return logger[level].apply(logger, params);
  };
}

5:example.js

// FILE PATH: common/models/example.js

var appRoot = require('app-root-path');
var logger = appRoot.require('/common/lib/logger')('model:example');

module.exports = function(Example) {
  
  Example.someMethod = function () {
    logger('someMethod').info({ important: 'value'}, 'some associated message');)
  }
};

6:debug-capture.js

// NOTE: This doesn't fit correctly in with the other files in this Gist. It's from the module
// implementation that I scrapped. But I did test this out and it works...kind of. It's honestly
// a bit of a hack and there are various reasons why it's not something that should be generalized.
// But I think it would be totally fine to use it within your project :)

var _ = require('lodash');
var util = require('util');

// Important Note: We explicitly remove 'debug' from package.json
// to ensure we load the same copy as our calling application.
module.exports = function(logCtx) {
    var debugScope = logCtx.config.captureDebugging;
    if (!process.env.DEBUG && debugScope !== true) {
        // Auto-enable debugging when instructed via config
        process.env.DEBUG = debugScope;
    }
    // Fetch this module JIT to avoid require failures
    // for projects not using it.
    var debug = require('debug');

    debug.formatArgs = function () {
      var args = [this.namespace];
      _.each(arguments, function (val) {
        args.push(val);
      });
      return args;
    };

    // Overriding this is a documented feature of the debug module.
    debug.log = function () {

      var loopbackContext = logCtx.app.loopback.getCurrentContext();

      var logger = logCtx.bunyans.default;
      if (!logger) {
        // Initialization not yet finished
        return;
      }

      // Attempt to log within the request context.
      // Otherwise, use the top-level log.
      if (loopbackContext) {
        var http = loopbackContext.get('http');
        if (http && http.req) {
          logger = http.req.log;
        }
      }

      var scope = arguments[0];
      var args = Array.prototype.splice.call(arguments, 1);
      logger.trace({scope: scope}, util.format.apply(debug, args));
    };
};