Loopback: Alternative to `bunyan` logging via `debug` module

01_notes.md

//require('log-prefix')(function() { return '[' + Date.now() + '] %s'; });
// prints: [1465008912650] ...

//require('log-prefix')(function() { return '[' + new Date().toISOString() + '] %s'; });
// prints: [2016-06-04T02:54:36.488Z] ...

//require('log-prefix')(function() { return '[' + new Date().toUTCString() + '] %s'; });
// prints: [Sat, 04 Jun 2016 02:53:26 GMT] ...

//require('log-prefix')(function() { return '[' + new Date().toString() + '] %s'; });
// prints: [Fri Jun 03 2016 21:55:36 GMT-0500 (CDT)] ...

accessLogger.js

// path: server/middleware/accessLogger.js

'use strict';

var path = require('path');
var fileName = path.basename(__filename, '.js'); // gives the filename without the .js extension
var log = require('./../../common/lib/debug-extension')('server:middleware:'+fileName);

module.exports = function() {
  return function accessLogger(req, res, next) {
    log('accessLogger').trace('running');
    // enable audit log for API
    if (req.accessToken) {
      log.debug('req', req.method, req.originalUrl,
        //'\n\t', 'userId:', req.accessToken.id,
        /*'\n\t',*/ 'token:', JSON.stringify(req.accessToken,null,0)
      );
    }
    else {
      log.debug('req', req.method, req.originalUrl);
    }

    // http://www.senchalabs.org/connect/responseTime.html
    var start = new Date;
    if (res._responseTime) {
      return next();
    }
    res._responseTime = true;

    // install a listener for when the response is finished
    res.on('finish', function() { // the request was handled, print the log entry
      var duration = new Date - start;
      log.debug('res', req.method, req.originalUrl,
        JSON.stringify({
          lbHttpMethod:req.method,
          lbUrl:req.originalUrl,
          lbStatusCode:res.statusCode,
          lbResponseTime:duration,
          lbResponseTimeUnit:'ms'
        },null,0)
      );
    });

    // resume the routing pipeline,
    // let other middleware to actually handle the request
    next();
  };
};

debug-extension.js

// path: common/lib/debug-extension.js

'use strict';

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(':');
  /*console.log('scope:',scope);
  if(!scope) {
    console.trace();
  }*/
  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) {
  var logger;
  return function () {
    var params = arguments;
    //console.log('params', params);

    if (scope) {
      logger = logger || require('debug')(scope);
      if (_.isObject(params[0])) {
        params[0].scope = scope; // TODO: when can this ever happen?
      } else {
        // convert to array
        params = Array.prototype.slice.call(arguments);

        params.unshift(level.toUpperCase());

        var loopbackContext = loopback.getCurrentContext();
        if (loopbackContext) {
          // prep the all important identifier for wading through logs
          var identifier = loopbackContext.get('ip');
          if (loopbackContext.get('username')){
            identifier += '-' + loopbackContext.get('username');
          }
          else {
            identifier += '-X';
          }
          if (loopbackContext.get('accessToken')){
            // don't want prefixes to be too long, want logs to be human-readable
            identifier += '-' + loopbackContext.get('accessToken').slice(-6);
          }
          else {
            identifier += '-X';
          }
          // TODO: is there any merit yet, in adding individual requestIds too?
          //identifier += '-' + loopbackContext.get('requestId')

          // prefix it to every log statement
          params.unshift(identifier);
        }

        // place a stacktrace at the end, if you are feelign verbose
        //var stack = new Error().stack;
        //params.push(stack);
      }

      //return logger.apply(null, params);
    }
    else { // NOTE: no scope??? how did we reach this code block?
      // `scope` is absent in the very first call made from this file itself: `module.exports = mkLogger();`
      logger = logger || require('debug');
    }
    return logger.apply(logger, params);
    /*else {
      return console.log.apply(null,params);
    }*/
  };
}

example.js

'use strict';

var path = require('path');
var fileName = path.basename(__filename, '.js'); // gives the filename without the .js extension
//var log = require('debug')('common:models:'+fileName); // old way of using debug module
var appRoot = require('app-root-path');
var log = appRoot.require('/common/lib/debug-extension')('common:models:'+fileName); // new way of wrapping it

module.exports = function(module.exports = function(Example) {
  Example.someMethod = function () {
    //log('message', someObject); // old way
    log('someMethod').info('message', someObject); // new way
    log.info('message', someObject); // new way - this works too
  };
};

middleware.json

{
  "initial:before": {
    "loopback#favicon": {},
    "loopback#context": {},
    "loopback#token": {},
    "./middleware/userContext": {}
  },
  "initial": {
    "compression": {},
    "./middleware/accessLogger": {
      "paths": "/api/*"
    }
  },
  ...
}

userContext.js

// path: server/middleware/userContext.js

'use strict';

var loopback = require('loopback');

/*var path = require('path');
var fileName = path.basename(__filename, '.js'); // gives the filename without the .js extension
var log = require('./../../common/lib/debug-extension')('server:middleware:'+fileName);*/

module.exports = function() {
  // set current user to enable user access for remote methods
  return function userContext(req, res, next) {

    var loopbackContext = loopback.getCurrentContext();
    if (loopbackContext) {
      // starts : info for injecting into logs
      loopbackContext.set('ip', req.headers['x-real-ip'] ||
        req.ip ||
        req.connection.remoteAddress ||
        (req.socket && req.socket.remoteAddress) ||
        (req.socket.socket && req.socket.socket.remoteAddress)
      );

      if (!req.accessToken) {
        return next();
      }
      else {
        // info for injecting into logs
        loopbackContext.set('accessToken', req.accessToken.id);

        var app = req.app;
        app.models.UserModel.findById(req.accessToken.userId, function(err, user) {
          if (err) {
            return next(err);
          }
          if (!user) {
            return next(new Error('No user with this access token was found.'));
          }

          // TODO: what merit could this hold?
          //res.locals.currentUser = user;

          // info for use by remote methods
          loopbackContext.set('currentUser', user);

          // info for injecting into logs
          loopbackContext.set('username', user.username);

          next();
        });
      }
    }
    else {
      next();
    }
  };
};