StrongLoop makes it easy to develop APIs in Node, plus get DevOps capabilities like monitoring, debugging and clustering.

If you are writing a Node.js application, chances are you going to have some kind of API end points to be consumed by your frond end or expose data for others to take in. This is where RESTful APIs come in. And now you have a dilemma – what tools to use and what approach to take? So many choices…

Lets talk about logging, shall we? Arnold over here carrying a giant log feels like an appropriate intro to this article in which we are going to talk about popular Node.js logging frameworks.

If you are writing any kind of long living application, detailed logging is paramount to spotting problems and debugging. Without logs you would have few ways of telling how is your application behaving, are there errors, what’s the performance like, is it doing anything at all or is it just falling over every other request when you aren’t looking at it.

Requirements

Lets identify a few requirements which we can use to pit the frameworks against each other. Some of these requirements are pretty trivial, others are not so much.

  1. Time stamp each log line. This one is pretty self explanatory – you should be able to tell when each log entry occured.
  2. Logging format should be easily digestible by humans as well as machines.
  3. Allows for multiple configurable destination streams. For example, you might be writing trace logs to one file but when an error is encountered, write to the same file, then into error file and send an email at the same time.

Based on these requirements (and popularity) there are two logging frameworks for Node.js worth checking out, in particular:

console

Before we get to Bunyan and Winston, lets look at our old friend console. The most rudimentary type of logging you could do is using console.log and console.error methods. This is better than nothing but hardly the best solution. Console writes to STDOUT and STDERR respectively. There’s a very interesting caveat to know when it comes to console methods in Node.js.

The console functions are synchronous when the destination is a terminal or a file (to avoid lost messages in case of premature exit) and asynchronous when it’s a pipe (to avoid blocking for long periods of time).

That is, in the following example, stdout is non-blocking while stderr is blocking:

“`javascript
$ node script.js 2> error.log | tee info.log


This is basically a "roll your own" logging approach. It is fully manual, you have to come up with your own format and basically manage everything yourself. This is time consuming, prone to errors and you probably want to focus on your application features instead. Considering that there are open source logging libraries out there which are actively maintained, this is not worth the effort if you are trying to focus on delivering features. How does `console` satisfy our requirements? Well, out of the box it does nothing in that regard but with some elbow grease you can get everything implemented yourself. ## Winston <img src="http://npmawesome.com/wp-content/uploads/2014/06/lenny-henry.jpg" width="100%"/> One of the most popular Node.js logging frameworks is [Winston]. It's designed to be a simple and universal logging library with support for multiple transports (a transport in [Winston]'s world is essentially a storage device, eg where your logs end up being stored). Each instance of a [Winston] logger can have multiple transports configured at different logging levels. ### Installation ```javascript npm install winston

Usage

The most basic Winston usage consists of calling the default instance that is exported from the winston module.

var winston = require('winston');

winston.log('info', 'Hello distributed log files!');
winston.info('Hello again distributed logs');

The above is the same as:

var winston = require('winston');
var logger = new winston.Logger();

logger.log('info', 'Hello distributed log files!');
logger.info('Hello again distributed logs');

Both examples will produce the following output:

info: Hello distributed log files!
info: Hello again distributed logs

Formatting

Personally I’m a little bit puzzled by the lack of details in the default formatter. There’s no time stamp, machine name or process ID and the output format is mildly suitable for machine parsing. Having said that you can get all the information out yourself with just a little of extra work.

winston.info('Hello world!', {timestamp: Date.now(), pid: process.pid});

Produces the following output, which is more informative, but still not very much suitable for machine parsing.

info: Hello world! timestamp=1402286804314, pid=80481

Finally, the log method provides the same string interpolation methods as util.format, for example:

winston.log('info', 'test message %d', 123);

Transporters

Winston could be configured via constructor options or exposed method which are very thoroughly documented on the GitHub page. Most of the configuration typically revolves around various transports. Out of the box Winston comes with console and file based transports and if you have a look on npmjs.org you will see that there are community modules for pretty much everything imaginable ranging from MongoDB to commercial third party platforms.

One of the more notable transporters in my opinion is winston-irc by Nathan Zadoks which you can use to log errors to your team’s IRC channel. I can see this coming in very handy.

winston.add(require('winston-irc'), {
  host: 'irc.somewhere.net',
  nick: 'logger',
  pass: 'hunter2',
  channels: {
    '#logs': true,
    'sysadmin': ['warn', 'error']
  }
});

Multiple Loggers

Once your application starts to grow, chances are you will want to have multiple loggers with different configurations where each logger is responsible for a different feature area (or category). Winston supports that in two ways: through winston.loggers and instances of winston.Container. In fact, winston.loggers is just a predefined instance of winston.Container:

winston.loggers.add('category1', {console: { ... }, file: { ... }});
winston.loggers.add('category2', {irc: { ... }, file: { ... }});

Now that your loggers are configured you can require Winston in any file in your application and access these pre-configured loggers:

var category1 = winston.loggers.get('category1');
category1.info('logging from your IoC container-based logger');

More

This is most basic Winston usage, but there are quite a few other features, most notably:

Bunyan

Illustration by Brendan Corris

Bunyan by Trent Mick is another logging framework that I think should be considered. Bunyan takes a slightly different approach to logging than Winston making its mission to provide structured, machine readable logs as first class citizens. As a result, a log record from Bunyan is one line of JSON.stringify output with some common names for the requisite and common fields for a log record.

Installation

npm install bunyan

Usage

var bunyan = require('bunyan');
var log = bunyan.createLogger({name: 'myapp'});
log.info('hi');
log.warn({lang: 'fr'}, 'au revoir');

Which will produce the following output:

{"name":"myapp","hostname":"pwony-2","pid":12616,"level":30,"msg":"hi","time":"2014-05-26T17:58:32.835Z","v":0}
{"name":"myapp","hostname":"pwony-2","pid":12616,"level":40,"lang":"fr","msg":"au revoir","time":"2014-05-26T17:58:32.837Z","v":0}

As you can see, out of the box Bunyan is not very human friendly, however most modern logging systems understand JSON format natively, which means there’s little to do here to feed the logs elsewhere for storage and processing. By default, there’s quite a bit of meta data included with each message, such as time stamp, process ID, host name and application name.

Of course, us humans, don’t find this very digestible and to address that there’s a bunyan CLI tool to which takes in JSON via STDIN. Here’s the same example piped through bunyan:

node example.js | bunyan

Produces the following output:

[2014-05-26T18:03:40.820Z]  INFO: myapp/13372 on pwony-2: hi
[2014-05-26T18:03:40.824Z]  WARN: myapp/13372 on pwony-2: au revoir (lang=fr)

The main benefit here is that you don’t need to reconfigure anything for development environment, all you have to do is pipe to bunyan. Checkout the GitHub page for more documentation on the CLI tool.

JSON

One of the key differences between Bunyan and Winston is that Bunyan works really well when you want to log complex contexts and objects. Lets look at this line and its output from the example above:

log.warn({lang: 'fr'}, 'au revoir');
{"name":"myapp","hostname":"pwony-2","pid":12616,"level":40,"lang":"fr","msg":"au revoir","time":"2014-05-26T17:58:32.837Z","v":0}

You can see that {lang: 'fr'} got merged with the main log object and au revoir became msg. Now picture something like this:

log.info(user, 'registered');
log.info({user: user}, 'registered');

Which produces:

{"name":"myapp","hostname":"pwony-2","pid":14837,"level":30,"username":"alex","email":"...@gmail.com","msg":"registered","time":"2014-05-26T18:27:43.530Z","v":0}
{"name":"myapp","hostname":"pwony-2","pid":14912,"level":30,"user":{"username":"alex","email":"...@gmail.com"},"msg":"registered","time":"2014-05-26T18:28:19.874Z","v":0}

Or when piped through bunyan:

[2014-05-26T18:28:42.455Z]  INFO: myapp/14943 on pwony-2: registered (username=alex, email=...@gmail.com)
[2014-05-26T18:28:42.457Z]  INFO: myapp/14943 on pwony-2: registered
    user: {
      "username": "alex",
      "email": "...@gmail.com"
    }

The beauty of this approach will become clear when you we look at child loggers.

Child Loggers

Bunyan has a concept of child loggers, which allows to specialize a logger for a sub-component of your application, i.e. to create a new logger with additional bound fields that will be included in its log records. A child logger is created with log.child(...). This comes in incredibly handy if you want to have scoped loggers for different components in your system, requests, or just plain function calls. Lets look at some code.

Imagine you want to carry request ID through out all log lines for a given request so that you can tie them all together.

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

app.use(function(req, res, next) {
  req.log = log.child({reqId: uuid()});
  next();
});

app.get('/', function(req, res) {
  req.log.info({user: ...});
});

The req.log logger will always keep its context passed to the log.child() function and merge it with all subsequent calls, so the output would look something like this:

{"name":"myapp","hostname":"pwony-2","pid":14837,"level":30,"reqId":"XXXX-XX-XXXX","user":"...@gmail.com","time":"2014-05-26T18:27:43.530Z","v":0}

Serializers

Two problems arise when Bunyan tries to stringify entire objects:

  1. Circular references. Winston is a little bit smarter here and detects circular references when they occur (however the result output $ref=$ isn’t very useful).
  2. Unwanted noise. It feels to me that because objects are first class in Bunyan it’s much easier to get into a habit of just dumping everything into the log.

To help deal with both, Bunyan has a concept of serializers that are basically transformation functions which let you scope down commonly passed objects to just the fields that you are interested in:

function reqSerializer(req) {
  return {
    method: req.method,
    url: req.url,
    headers: req.headers
  }
}

var log = bunyan.createLogger({name: 'myapp', serializers: {req: reqSerializer}});
log.info({req: req});

Now trying to log req object would just include the three fields that we are interested in.

Streams

Streams in Bunyan are the same thing as transporters in Winston – it’s a way to send your logs elsewhere for display and storage purposes. Bunyan uses a Writable Stream interface with some additional attributes. A Bunyan logger instance has one or more streams and are specified with the streams option:

var log = bunyan.createLogger({
  name: "foo",
  streams: [
    {
      stream: process.stderr,
      level: "debug"
    },
    ...
  ]
});

More

Here are a few more notable things to explore in Bunyan:

What’s next?

Winston and Bunyan are both very mature and established logging frameworks and are very much on par in terms of features. Winston has a lot of community support with various logging modules. Bunyan makes it easy out of the box to parse logs but leaves consumption up the user (generally syslog drain works pretty well here). I feel it all comes down to preference and how easy it is to integrate with your stack.