I am currently laid up from a recent hand injury, involving a bottle of wine and and a bad idea. Ironically, despite only having 1.2 hands to use for typing (pinky on right hand), being stuck at home has actually made it easier to get through some of my hacking todo list. The first item on that list is to release a little utility I have been using lately: stacklog.

What does it do?

Stacklog simply wraps another logging module (I like Winston) so that you can push logging prefixes onto a stack and they will be automatically prepended to the logger’s output. Something I used to do manually like this (real example from a recent project):

var log = require('./log')
...
function getVideosInReadyState(next) {
  log.debug('[videos][getVideosInReadyState]');

  VideoStore.loadQueue('readyQueue', function (err, videoDocList) {
    log.debug('[videos][getVideosInReadyState][x]');
    if (err) { return next(err); }
    if (!videoDocList) { 
      log.error('[videos][getVideosInReadyState][onloadQueue] no videos returned');
      return next(new Error('No videos returned'));
    }

    log.debug('[videos][getVideosInReadyState][onloadQueue] ' + videoDocList.length + ' videos found in ready state');

    return next(null, videoDocList);
  });
}

Now becomes this:

var log = require('./log')('videos');
...
function getVideosInReadyState(next) {
  var l = log.debug('getVideosInReadyState');

  VideoStore.loadQueue('readyQueue', function (err, videoDocList) {
    var l2 = l.debug('onLoadQueue');
    if (err) { return next(err); }
    if (!videoDocList) { 
      l2.error('no videos returned');
      return next(new Error('No videos returned'));
    }

    l2.debug(videoDocList.length + ' videos found in ready state');

    return next(null, videoDocList);
  });
}

In both cases, the output produced during a call with debug logging enabled would look like:

debug: [videos][getVideosInReadyState]
debug: [videos][getVideosInReadyState][onLoadQueue]
debug: [videos][getVideosInReadyState][onLoadQueue] 8 videos found in ready state

The advantage of the second case is simple. If I rename the module or function, I don’t have to go change every debug log statement. It also is also harder to forget to add the prefix in the call and leads to greater consistency in the various log statements sprinkled around the app.

But so much logging! and other whining

Yes, this approach still requires lots of manual log statements and somewhat unsightly variables named l and l2 floating around. I explored a few other options to get automatic tracing in Node, but there really isn’t a great solution to this problem. Error objects do get stack traces, but they are too expensive to create for non-error related debugging. This is JavaScript folks, and it is the world we have chosen to live in. It is a miracle that we can even take console.log for granted now (server side at least)!

My philosophical approach to logging is that it is worth the effort up front, rather than dropping debug statements in “when needed.” Some of our developers prefer to leave the code debug statement free on the basis that it is cleaner/prettier. I’m always greatly annoyed when I have to debug their apps in production.

Performance implications?

Yes. Not logging at all performs much better (as expected). Short of using dTrace, this is an unavoidable penalty that any logging solution will have to incur. The upside is that running stacklog at less verbose log levels (as you would in normal production operation) performs better than leaving console.log() statements in.

Tests were run on core i7 2012 Macbook Air w/ 8GB ram. Average over 100 runs of 1000 iterations. There was zero sciences involved in this experiment.

Test - average (microseconds)

  • nolog.js - 1.8
  • console.js - 22041.17
  • winston.js - 45438.45
  • stacklogon.js - 77842.35
  • stacklogoff.js - 14706.28

Where to get it

Stacklog is released under the MIT license and is available on npm and github. As always,

Feedback

If you find stacklog useful, or you have a better way of accomplishing the same task, or you are interested in joining the MLS Dev team, we would love to hear from you!

@jdslatts on twitter or Justin.Slattery@mlssoccer.com

New MLS Mobile App for 2015

January 12, 2015

Open beta for new MLSsoccer.com

December 04, 2014 Hans Gutknecht

Standings Visualizations

October 30, 2014 Tom Youds