logging with domains

log.js

/* This Source Code Form is subject to the terms of the Mozilla Public
 * License, v. 2.0. If a copy of the MPL was not distributed with this
 * file, You can obtain one at http://mozilla.org/MPL/2.0/. */

var Domain = require('domain')
var inherits = require('util').inherits
var Logger = require('bunyan')

function Overdrive(options) {
  Logger.call(this, options)
}
inherits(Overdrive, Logger)

Overdrive.prototype.begin = function (op, request) {
  var domain = Domain.active
  if (domain) {
    domain.add(request)
    request.app.traced = []
  }
  this.trace({ op: op })
}

Overdrive.prototype.trace = function () {
  if (this._level <= Logger.TRACE && Domain.active) {
    var arg0 = arguments[0]
    if (typeof(arg0) === 'object') {
      var request = Domain.active.members[0]
      arg0.rid = arg0.rid || (request && request.id)
      if (request) {
        request.app.traced.push(arg0)
      }
    }
  }
  return Logger.prototype.trace.apply(this, arguments)
}

module.exports = function (config) {
  var logStreams = [
    {
      name: 'file',
      type: 'rotating-file',
      level: config.log.level,
      path: config.log.path,
      period: config.log.period,
      count: config.log.count
    }
  ]

  if (config.env !== 'production') {
    logStreams.push({ name:'console', stream: process.stdout, level: 'trace' })
  }

  var log = new Overdrive(
    {
      name: 'picl-idp',
      streams: logStreams
    }
  )

  log.info(config, "starting config")

  return log
}

// From https://github.com/dannycoates/picl-idp/blob/master/log.js

sample.log

Here's a real trace from a successful /auth/start request. Notice how each line has the same "rid"


[2013-08-31T18:08:46.423Z] TRACE: picl-idp/16031 on moz.local:  (op=Auth.start, rid=1377972526422-16031-64695)
[2013-08-31T18:08:46.423Z] TRACE: picl-idp/16031 on moz.local:  (op=Account.getByEmail, rid=1377972526422-16031-64695)
    email: 6236373532346631316232616137323465623134406578616d706c652e636f6d
[2013-08-31T18:08:46.423Z] TRACE: picl-idp/16031 on moz.local:  (op=Account.getId, rid=1377972526422-16031-64695)
    email: 6236373532346631316232616137323465623134406578616d706c652e636f6d
[2013-08-31T18:08:46.423Z] TRACE: picl-idp/16031 on moz.local:  (op=KV.get, rid=1377972526422-16031-64695)
    key: 6236373532346631316232616137323465623134406578616d706c652e636f6d/uid
[2013-08-31T18:08:46.423Z] TRACE: picl-idp/16031 on moz.local:  (op=KV.get.1, err=null, val=true, rid=1377972526422-16031-64695)
    key: 6236373532346631316232616137323465623134406578616d706c652e636f6d/uid
[2013-08-31T18:08:46.423Z] TRACE: picl-idp/16031 on moz.local:  (op=Account.get, uid=de45d10c-fff2-4239-abf5-fa266863f899, rid=1377972526422-16031-64695)
[2013-08-31T18:08:46.423Z] TRACE: picl-idp/16031 on moz.local:  (op=KV.get, key=de45d10c-fff2-4239-abf5-fa266863f899/user, rid=1377972526422-16031-64695)
[2013-08-31T18:08:46.423Z] TRACE: picl-idp/16031 on moz.local:  (op=KV.get.1, key=de45d10c-fff2-4239-abf5-fa266863f899/user, err=null, val=true, rid=1377972526422-16031-64695)
[2013-08-31T18:08:46.423Z] TRACE: picl-idp/16031 on moz.local:  (op=SrpSession.start, uid=de45d10c-fff2-4239-abf5-fa266863f899, rid=1377972526422-16031-64695)
[2013-08-31T18:08:46.423Z] TRACE: picl-idp/16031 on moz.local:  (op=SrpSession.create, uid=de45d10c-fff2-4239-abf5-fa266863f899, rid=1377972526422-16031-64695)
[2013-08-31T18:08:46.425Z] TRACE: picl-idp/16031 on moz.local:  (op=srpSession.save, id=f69c7585-a803-4a2d-843f-c2b8e9de6189, rid=1377972526422-16031-64695)
[2013-08-31T18:08:46.425Z] TRACE: picl-idp/16031 on moz.local:  (op=KV.set, key=f69c7585-a803-4a2d-843f-c2b8e9de6189/srp, rid=1377972526422-16031-64695)
[2013-08-31T18:08:46.425Z] TRACE: picl-idp/16031 on moz.local:  (op=KV.set.1, key=f69c7585-a803-4a2d-843f-c2b8e9de6189/srp, err=null, val=false, rid=1377972526422-16031-64695)
[2013-08-31T18:08:46.425Z] TRACE: picl-idp/16031 on moz.local:  (op=srpSession.clientData, id=f69c7585-a803-4a2d-843f-c2b8e9de6189, rid=1377972526422-16031-64695


And here's a failed /auth/start request. It also includes the response body sent to the client.
In a dev environment it includes the log objects of the request. The last log line is a good starting point to
finding where the error occurred.

[2013-08-31T18:08:46.448Z] TRACE: picl-idp/16031 on moz.local:  (op=Auth.start, rid=1377972526447-16031-459)
[2013-08-31T18:08:46.448Z] TRACE: picl-idp/16031 on moz.local:  (op=Account.getByEmail, rid=1377972526447-16031-459)
    email: 6236373532346631316232616137323465623134406578616d706c652e636f6d
[2013-08-31T18:08:46.448Z] TRACE: picl-idp/16031 on moz.local:  (op=Account.getId, rid=1377972526447-16031-459)
    email: 6236373532346631316232616137323465623134406578616d706c652e636f6d
[2013-08-31T18:08:46.448Z] TRACE: picl-idp/16031 on moz.local:  (op=KV.get, rid=1377972526447-16031-459)
    key: 6236373532346631316232616137323465623134406578616d706c652e636f6d/uid
[2013-08-31T18:08:46.448Z] TRACE: picl-idp/16031 on moz.local:  (op=KV.get.1, err=null, val=false, rid=1377972526447-16031-459)
    key: 6236373532346631316232616137323465623134406578616d706c652e636f6d/uid
[2013-08-31T18:08:46.448Z] TRACE: picl-idp/16031 on moz.local:  (op=Account.get, uid=null, rid=1377972526447-16031-459)
[2013-08-31T18:08:46.449Z] TRACE: picl-idp/16031 on moz.local:  (op=KV.get, key=null/user, rid=1377972526447-16031-459)
[2013-08-31T18:08:46.449Z] TRACE: picl-idp/16031 on moz.local:  (op=KV.get.1, key=null/user, err=null, val=false, rid=1377972526447-16031-459)
[2013-08-31T18:08:46.449Z] TRACE: picl-idp/16031 on moz.local:  (op=SrpSession.start, uid=null, rid=1377972526447-16031-459)
[2013-08-31T18:08:46.449Z] TRACE: picl-idp/16031 on moz.local:  (op=SrpSession.create, uid=null, rid=1377972526447-16031-459)
[2013-08-31T18:08:46.449Z] ERROR: picl-idp/16031 on moz.local:  (op=server.onPreResponse, rid=1377972526447-16031-459, path=/auth/start)
    err: {
      "code": 400,
      "error": "Bad Request",
      "message": "Unknown account",
      "errno": 102,
      "info": "http://errors.lcip.org/todo/102",
      "log": [
        {
          "op": "Auth.start",
          "rid": "1377972526447-16031-459"
        },
        {
          "op": "Account.getByEmail",
          "email": "6236373532346631316232616137323465623134406578616d706c652e636f6d",
          "rid": "1377972526447-16031-459"
        },
        {
          "op": "Account.getId",
          "email": "6236373532346631316232616137323465623134406578616d706c652e636f6d",
          "rid": "1377972526447-16031-459"
        },
        {
          "op": "KV.get",
          "key": "6236373532346631316232616137323465623134406578616d706c652e636f6d/uid",
          "rid": "1377972526447-16031-459"
        },
        {
          "op": "KV.get.1",
          "key": "6236373532346631316232616137323465623134406578616d706c652e636f6d/uid",
          "err": null,
          "val": false,
          "rid": "1377972526447-16031-459"
        },
        {
          "op": "Account.get",
          "uid": null,
          "rid": "1377972526447-16031-459"
        },
        {
          "op": "KV.get",
          "key": "null/user",
          "rid": "1377972526447-16031-459"
        },
        {
          "op": "KV.get.1",
          "key": "null/user",
          "err": null,
          "val": false,
          "rid": "1377972526447-16031-459"
        },
        {
          "op": "SrpSession.start",
          "uid": null,
          "rid": "1377972526447-16031-459"
        },
        {
          "op": "SrpSession.create",
          "uid": null,
          "rid": "1377972526447-16031-459"
        }
      ]
    }

snippets.js

/*/
The request handler opts in to domain logging by calling `log.begin`

From https://github.com/dannycoates/picl-idp/blob/master/routes/auth.js#L19-L25
/*/
handler: function (request) {
  log.begin('Auth.start', request)
  var reply = request.reply.bind(request)
  Account.getByEmail(request.payload.email)
    .then(SrpSession.start.bind(null))
    .done(reply, reply)
},
/*/
Any calls that are part of a domain automatically get the `request.id` added
to the log line. Here the handler called `Account.getByEmail` which has no
knowledge of the `request`. No code beyond the handler has a reference to
the `request` but the domain allows us to track the calls :)

From https://github.com/dannycoates/picl-idp/blob/master/models/account.js#L123-L126
/*/
Account.getByEmail = function (email) {
  log.trace({ op: 'Account.getByEmail', email: email })
  return Account.getId(email).then(Account.get)
}

Recently I've been experimenting with logging. I found a use for domains that makes logging requests pretty nice. The log.js file above has the interesting functions begin and trace, snippets.js shows the usage, and sample.log shows the console-ified output.

I think logging is a powerful way to leverage domains (it's already helped me find a few bugs) but I'm having trouble thinking of ways to generalize the approach. Domains are a bit messy because they're global, so unless you know how all of your dependencies use them you can't really be sure what a domain-aware log is going to look like.

What do you think of this logging approach? Should domain-aware logging be part of a general module, or is it too niche? If it could be general, how would you "package" it?

Here's the original PR for background an the full diff: mozilla/fxa-auth-server#168

I think this is incredibly clever—logging has been an open question for us, too. I agree that maintaining a clear separation between the model and requests is essential. Coupling the model class to an application-specific logger doesn't feel clean.

An approach I've been pondering is having the target object emit logging events, but this is cumbersome because Account.getByEmail is a static method. You could attach an event emitter instance to the model (Account.logEvents = new EventEmitter()) and have each request subscribe to the log events (possibly in an onRequest hook), but then you'd need to add a corresponding onPreResponse or tail hook to remove those listeners:

// In `/models/account.js`...
Account.logEvents = new EventEmitter()

Account.getByEmail = function (email) {
  Account.logEvents.emit('trace', { op: 'Account.getByEmail', email: email })
  return Account.getId(email).then(Account.get)
}

// In `/server/server.js`...
server.ext('onRequest', function (request, next) {
  var handleTrace = log.trace.bind(log)
  request.server.once('tail', Account.logEvents.removeListener.bind(Account.logEvents, 'trace', handleTrace))
  Account.logEvents.on('trace', handleTrace)
  next()
})

This preserves the separation between the model and business logic, and doesn't require a reference to the logger at all. But it's kludgy and framework-specific—what if your project uses a framework that doesn't define a deterministic request lifecycle? This also means that the onRequest extension point needs to wire up every model, not just Accounts. Your approach neatly sidesteps this, but raises some interesting questions.

A standalone Overdrive module could export a global logger (à la Domain.active) that would be used throughout your app. That way, instead of passing log as an argument to each dependency, you could add var log = require('overdrive').log to the top. You could also export a traceProtected(request, handler) function that creates a domain, adds the request to it, and executes the handler function via domain.run. I think this would be useful if you're using a framework that doesn't support domains out of the box (Express, Restify, etc).

On the other hand, if you're already using domains for error handling (or if your framework is managing that for you, as in the case of Hapi), you wouldn't want for traceProtected to create a new domain. Maybe it should create a new domain only if one isn't active? That seems wildly inconsistent, but avoids the issue of stealing objects from another domain.

I'll ponder this some more...