Hierarchical Logging

These are my ramblings of thought on logging. More to come.

Hierarchical logging means we get some insight into the flow of our application. It would allow expanding and collapsing of our logs based on where at in the component hierarchy we currently are.

In order to achieve this, all of our components need a way to set their logging contexts. For the db module, I could easily see something like this:

// Some module
var logger = require('logger')('Some Module');

// Get new instance of users with logging parent set `Some-Module`
var users = db.users.extend({ parentLogger: logger });

Any logs that occur within db.users will now be in a sub-log of Some Module.

For an HTTP server, we would create a new Logging instance as a request comes in. This would be a child of the Request Logger:

var logger  = require('logger')('App');
var rLogger = logger('Requests');

logger.info('Configuring...');

app.use( m.requestLogger({
  parent: rLogger
, msg:    '{method} {path}'
}));

// Some other middleware later
app.use( function( req, res, next ){
  var logger = req.logger('Some-other-middleware');
  
  logger.info( "Looking up something", { poop: true } );
  
  somethingAsync( function( error, stats ){
    if ( error ){
      logger.error( "Error with lookup!", error );
      return next( error );
    }
    
    logger.info( "Complete", stats );
    
    return next();
  });
});

A GET to /users/:id could look something like this:

[App] - Configuring...
...
[App]
  |- [Requests]
    |- [GET /users/:id]
      |- [Some-other-middleware] looking up something
      |- [Some-other-middleware] Error with lookup!

It would require some special aggregation, but just the fact that it could represented that way is solid.

The JSON structure might look like:

{
  timestamp
, component
, parent_components // i.e. [App, Requests, GET /users:id]
, level
, msg
, data
}

This would give us nice context in the hierarchy of events in our components App->Requests->GetUser->DB, but should we create a logger instance for each method/route pair? The alternative would be to just keep everything on the Requests level and have the method/route in the data field. It doesn't really matter where it's available I suppose, as long as it is available. And the point of having the parent->child relationship is organization. We should organize when we can, and we've made it very easy to create children. Creating children makes it easy to collapse noise, and expand it again when you need it.

Putting it into MongoDB

There are a number of reasons why we should use Mongo for logging. Foremost, I think is the robust querying ability. If we want to see all logs for a particular order:

var $where = {
  $or: [
    { 'data.order.id': 1000 }
  , { 'data.order_id': 1000 }
    // ... Other formats
  ]
};

Hell, given our use-case, it might even be useful to put an order_id on all log records, though I think that that might get us in trouble from time-to-time.