Bunyan Loopback logging

01_chat.md

doublemarked 09:50

@pulkitsinghal here’s a gist of the core of it all:
https://gist.github.com/doublemarked/e4bf329d11c55baf468f

@pulkitsinghal this will log access tokens with all log messages.
Bunyan produces JSON, so you’re essentially going to need to parse
the log to fish out things, but JSON makes it easy to do that.

For simple things (like access tokens) you can also use grep
addressing some of the other reqs we discussed:
1. I figured out a way to mess around with debug,
   capturing its output and piping it to Bunyan instead of to stderr.
   You can see it doing that in the last file in the Gist.
   Cool thing about this too, is that it’s using the same logging mechanism,
   so all those debug messages get the access token and userid associated with them as well.
2. We discussed changing log level on the fly, without restarting node.
   I did a proof of concept on this, and it’s easy enough
   to capture a signal, USR2, which then can be hooked into changing log level.
   But I decided after playing with this that it’s just far too esoteric.
   It also has some problems with the debug module due to how that thing
   caches setup. But it would work fine with Bunyan.
3. Bunyan makes it easy to port data to other services (papertrailapp, etc)
4. Passing device info: You can send device info into your API via headers,
   and then fish them out in the request logger. It’s already supporting
   logging of all headers, btw.

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 TO PULKIT: This is an implementation of capturing the debug module output and prefixing it with context.
// It 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));
    };
};