Properly logging errors with nodejs bunyan?

Question

I read through Joyent's postmortem debug article and they recommended we use bunyan.

They talk about how the quality of the log information is very important and can help in solving errors when they arise. Then there are external blog sites which show how to get bunyan install and running in their Nodejs application, which is nice.

But I am new and in the dark on how to use logging effectively (both specific to bunyan and logging practices in general). I have three questions that are related to each other.

(1) Am I supposed to use bunyan to log every action that happens in my application?

ie,

router.post('/submit', function(req, res) {
    log.info({ req:req }, req.user.name + ' has called /submit');

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

... And so on everywhere in my application?

(2) If so, then wouldn't I get log output in disjointed pieces? For example, if we have 3 concurrent users calling /submit, then the messages could be:

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

Is that right? If I have a stacktrace for Bob and I'm trying to get prior knowledge of the system state before the program broke, I would have to somehow filter out everyone else and sort by timestamp to get a coherent order of events for Bob?

(3) Should I be using bunyan to log stacktraces? ie, adding err.stack to the bunyan logger:

.error(function(err) {
    log.error({ err: err, stacktrace: err.stack }, req.user.name + ' has caused an error in /submit ');
    res.status(500).json("error": err});
});

... Or is there some other standard practice to logging and reporting errors (which basically means saving stacktraces?)?

This is an opinion-based question, so it doesn't have an answer. You should log anything that would be useful for you. For an application with what looks like some state, you should probably log a session ID so that you can filter by a certain session to see that user's actions. You can set up a second log sink that is only for stack traces so they don't get intermixed. — Interrobang, May 04 '15 at 02:10

score 6 · Accepted Answer · answered May 04 '15 at 02:15

(1) Am I supposed to use bunyan to log every action that happens in my application?

Yes, basically. There are some finer points to this, but basically you want to make a good signal/noise tradeoff while retaining reasonable likelihood of successful postmortem debugging. Log too much about code paths that never fail and you drown in noise. Don't log enough and you can be literally clueless as to what caused an issue. Don't fret about this too much. It's a sense you only gain with experience and it's easy enough to see from log analysis where you are generating noise and can tone stuff down or filter it out after the fact and where you have a big set of complex code executing with no details logged and you need to add more logging there.

(2) If so, then wouldn't I get log output in disjointed pieces?

Yes, but that's fine. You use postprocessing tools to reconnect them into a more coherent narrative. Common techniques including logging both a unique request ID for each request as well as the sessionID. That way you can filter a single user's session or just a single interesting request.

(3) Should I be using bunyan to log stacktraces?

Yes, but bunyan includes standard serializers for Error instances, so just name the property err and enable the standard serializers and you'll get the error message and stack trace properly logged.

For **(3)**, do you mean something like: `var log = bunyan.createLogger({ serializers: bunyan.stdSerializers });` and then when logging regular info, `log.info({ data: data }, 'some info');` and for errors: `log.error({err:err.stack}, 'stacktrace');`? — rublex, May 04 '15 at 17:15
Yes. The only change is do `log.error({err: err})` - just pass the whole error instance, don't access the `.stack` property. — Peter Lyons, May 04 '15 at 17:19
For (2), bunyan provides log.child() which allows you to tie a request with all its log. try that. — Akshat Goel, Jan 08 '16 at 12:42

Properly logging errors with nodejs bunyan?

1 Answers1