Friday, August 29, 2014

Valuable Logging

I was attempting to debug through an issue and ran into this line in the logs:

2014-08-29T15:14:53.648Z - info: Getting install data... 
2014-08-29T15:14:54.015Z - info: Query took 2msec 

Not having gained any additional insight or value from the message I decided to track it down to determine if it was part of my bug. It was not. Not even close.  But who would have known, except for the author of log entry, what "install data" or "query" it was referring to.

In order to be valuable, log entries should probably have a little more info.  I propose the following:

date:time - log level: file/location [function] MSG: reasonable description

eg.
2014-08-29T15:15:36.398Z - error: util/workday.js [getLinkedPerson] ERROR: TypeError: Cannot read property '68582' of undefined

If you have an error (either from a try/catch or from a promise), I would highly recommend writing out the stack like this:


try { 
 ... 

catch(err) { 
  log.error(file + ' [' + fn + '] ERROR: ' + err.stack);
}

2 comments:

  1. I wonder how much value including the file provides?

    Chances are you are going to search for the text anyways - which should take you to the file and the line number it is on. Another reason I think it may not be a good idea is that filenames and locations change and this is one more thing you would have to refactor (or more likely miss in a refactor).

    It would be nice if the logger we were using had an option to include the filename and location if you wanted (like a stacktrace).

    Also to make formatting log messages easier you might find util.format() useful. It is a standard node module and does string interpolation.

    util.format('Found account with number: %s, has systemId of: %s, account.number, account.systemId);

    If you are using winston as your logger, you might find that its ability to include metadata helpful as well.

    ReplyDelete
  2. I agree with most of what you say, but would like some more concrete detail, examples, etc.

    I strongly believe that including the file is important. Otherwise you see function names like "getData" that are worthless outside the context of the file. A function name like "getData" is more useful if you know that it is inside a file called "customer-address-info.js".

    ReplyDelete