Created
August 31, 2013 18:31
-
-
Save dannycoates/6399856 to your computer and use it in GitHub Desktop.
logging with domains
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
/* 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 |
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
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" | |
} | |
] | |
} |
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
/*/ | |
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) | |
} |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
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 anonRequest
hook), but then you'd need to add a correspondingonPreResponse
ortail
hook to remove those listeners: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 justAccounts
. 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 passinglog
as an argument to each dependency, you could addvar log = require('overdrive').log
to the top. You could also export atraceProtected(request, handler)
function that creates a domain, adds therequest
to it, and executes thehandler
function viadomain.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...