bunyan log.child correct use case?

Question

I've been looking at bunyan for logging in my nodejs app. I tried it out and everything seems to work pretty well. I had skipped over a section on log.child, but now I'm trying to understand how to use it. I think it's purpose is to allow me to specify some special identifier to the log entry, so that I can uniquely identify how that log is associated to some other log entry.

If that's the case, I would envision myself using log.child in every request:

var bunyan = require('bunyan');
var log = bunyan.createLogger({name: 'myapp'});

router.post('/submit', function(req, res) {
    var logChild = log.child({reqId: uuid.v4()});
    logChild.info({ req:req }, req.user.name + ' has called /submit');

    saveData(req)
    .then(function(data) {
        logChild.info({data: data}, req.user.name + ' has saved to DB successfully in /submit');
        res.json({'success': 'Saved!'});
    })
    .error(function(err) {
        logChild.error({ err: err }, req.user.name + ' has caused an error in /submit ');
        res.status(500).json("error": err});
    }); 
});

That way, if a user Bob POSTs to /submit twice in a 30 sec span, there will be some context that differentiates between two different calls in the log file.

That is, I'll see something like this (with context):

Bob has called /submit uuid: 109156be-c4fb-41ea-b1b4-efe1671c5836
Bob has called /submit uuid: 49dlsd7i-dapd-fdio-fei0-sd59fd0ph34d
Bob has saved to DB successfully in /submit uuid: 109156be-c4fb-41ea-b1b4-efe1671c5836
Bob has caused an error in /submit uuid: 49dlsd7i-dapd-fdio-fei0-sd59fd0ph34d

Instead of this (no context):

Bob has called /submit
Bob has called /submit
Bob has saved to DB successfully in /submit
Bob has caused an error in /submit

And so for all my routes in my Nodejs app, I would create the logChild object, then use the logChild to log the entries in that route.

Am I understanding and implementing the use case of log.child correctly?

score 14 · Answer 1 · answered May 18 '15 at 08:31

You seem to be using log.child appropriately. One suggestion I could make to assist you in "uniquely identifying how that log is associated to some other log entry" is by attaching log to the req object. This way, if you have different middleware, you can access the same logger with the same unique id from multiple places. For example:

var log = bunyan.createLogger({name: 'myapp'});

router.use(function(req, res, next) {
    req.log = log.child({ user : req.user.id });
});

router.post('/submit', function(req, res) {
    req.log.info('submitted request at ' + Date.now());
});

You will now see { user : some_user_id, msg: 'submitted request at 01/03/15' } in your logs which gives you the ability to tie any middleware in the request chain to a single user by using the req.log object.

bunyan log.child correct use case?

1 Answers1