Node Logging Basics

Node provides an easily extensible logging system, allowing you to control which messages get logged and to where they are output. Additionally, it has good support for structured logging using JSON. JSON allows more advanced logging patterns such as recording data fields for analysis and extending log objects to track complex call graphs. We’ll give examples for each of these in the sections below.

Logging to File

When they are first getting started with logging, most people will log to files. The code below is all that’s required to log to file in Winston. I’ll describe each of these parts in more detail below.

var winston = require('winston')

winston.add(
  winston.transports.File, {
    filename: 'somefile.log',
    level: 'info',
    json: true,
    eol: 'rn', // for Windows, or `eol: ‘n’,` for *NIX OSs
    timestamp: true
  }
)

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

The example starts off by importing the Winston library and then adds a File transport, which is one of the five core transports. I passed in a number of configuration options to give it a sense of substance. These are:

filename The filename of the logfile to write output to
level Level of messages that this transport should log
json If true, messages will be logged as JSON
eol String indicating the end-of-line characters to use
timestamp Boolean flag indicating if we should prepend output with timestamps

Based on the calls to log and info, this configuration will create log messages such as the one below, in a new file called somefile.log:

{"level":"info","message":"Hello distributed log files!","timestamp":"2015-02-11T08:41:03.576Z"}

Log Levels

It is clear that not all log messages have the same priority. Some of them are informative, whereas others are critical to report for application processing. In order to separate log messages by their priority, a standard set of log levels usually includes the following six levels:

  • FATAL – The application is in a critical state and cannot proceed with the execution of the current operation. In this case, the application usually reports such message and terminates.
  • ERROR – A serious problem occurred while processing the current operation. Such a message usually requires the user to interact with the application or research the problem in order to find the reason and resolve it.
    (Tip: Exceptions are usually reported as errors because they usually have a similar meaning.)
  • WARNING – Such messages are reported when something unusual happened that is not critical to process the current operation (and the application in general), but it would be useful to review this situation to decide if it should be resolved. (Tip: This level is usually selected as active for applications in production.)
  • INFO – Informative messages are usually used for reporting significant application progress and stages. Informative messages should not be reported too frequently because they can quickly become “noise.”
  • DEBUG – Used for debugging messages with extended information about application processing. Such messages usually report calls of important functions along with results they return and values of specific variables, or parameters.
  • TRACE – This level is most informative (and usually even excessive). Trace messages report most of application actions or events and are mostly used to follow application logic in full detail.

Setting Your Log Levels

Log levels are used to specify which messages should be logged and which should be ignored based on severity. Once the log level is specified it is applied to all subsequent messages until changed.

While setting a minimal logging level, some frameworks allow you to use two additional log levels: ALL and OFF/NONE.

(Tip: It is a good choice to set the minimal log level to “warning” even in a production environment.)

(Tip: While you’re researching a specific problem, you will probably want to set the minimal log level to “debug” temporarily to get additional info from your logs.)

Log Levels in Action

The Bunyan, log4js, and Winston frameworks support all six logging levels. Please note that Winston has specific names for “warning” log level (“verbose”) and “trace” log level (“silly”).

Sample Usage in Winston

var winston = require('winston');
winston.level = 'debug';
winston.log('info', 'Book ‘ALICE IN WONDERLAND’ has been added to database');

It will produce the following log:

info: Book ‘ALICE IN WONDERLAND’ has been added to database

Sample Usage in Bunyan

var bunyan = require('bunyan');
var log = bunyan.createLogger({name: 'play', level: 'debug'});
log.info('Book ‘ALICE IN WONDERLAND’ has been added to database');

It will produce the following log entries:

{"name":"loggly","hostname":"mainserv","pid":32411,"level":30,"msg":"Book ‘ALICE IN WONDERLAND’ has been added to database","time":"2015-05-19T23:57:12.112Z","v":0}

As we can see, the log level is encoded using the number in the “level” property of the resulting JSON object.

Sample Usage in log4js

var log4js = require('log4js');
var log = log4js.getLogger('mylogger');
log.setLevel('ERROR');
log.fatal('Update could not be complete. Database is corrupted.');

The produced log would be:

[2015-05-18 10:33:33.460] [FATAL] 'mylogger' - Update could not be complete. Database is corrupted.

Logging Exceptions

Winston provides a simple method to log exceptions. It allows a custom message to be added for simple log analysis and debugging.

winston.error("Call to undefined method stringToFloat");

Alternatively, you can use the following syntax:

winston.log("error", "Call to undefined method stringToFloat");

This will store the exception message to the added log transport(s).

Uncaught Exceptions

Winston allows you to store all of your log entries, including uncaught exception entries, either within the same transport location or in separate transport locations. If you want all of your logs conglomerated into one log file, set handleExceptions to true when you’re adding the file transport. In this example, Winston will add uncaught exception logs along with all other logs into allLogs.log.

winston.add(winston.transports.File, {
  filename: 'path/to/allLogs.log',
  handleExceptions: true
});

Winston also provides an option to separate uncaught exception log entries from all other log entries. The following code will store exceptions in a separate log file named path/to/uncaughtExceptions.log.

winston.handleExceptions(new winston.transports.File({ filename: 'path/to/uncaughtExceptions.log' }));

Whenever Winston catches an exception that is not caught by the program, the program will terminate by default. If you would like the application to continue execution even after an exception is caught, set exitOnError to false.

winston.exitOnError = false;

Now that Winston is set up to log exceptions, you can query the logs to discover and analyze issues that exist in your application.

JSON

Increasingly, information is being sent and received as JSON, whereas it was once sent as XML. There are several reasons for this, one of the prime among them being simplicity and lower overhead.

What’s more, JSON fits better with data structures used in more modern programming languages. It’s handy to know that Node.js logging libraries accommodate, almost transparently, JSON objects as or within log messages. Take the follow code example, using Winston:

var winston = require('winston'),
  objects = require('./object-definitions');
 
require('winston-loggly');
 
var simpleObject = {
  fullname: "Barry Allen",
  employer: "Central City Police Department",
  country: "United States",
  skills: ['The Fastest Man Alive']
}
 
var logger = new (winston.Logger)({
  transports: [
    new (winston.transports.Console)({
      level: 'debug',
      json: true
    }),
    new (winston.transports.File)({
      filename: './data/json.log',
      level: 'warn',
      json: false
    })
  ]
});

logger.error(simpleObject)

You can see that it’s able to pass a semi-complex plain JavaScript object as the log message. Note, in each Transport, the json configuration item. When this code is run, here’s what will result:

Console error:  first=Barry, last=Allen, employer=Central City Police Department, country=Central City, skills=[The Fastest Man Alive]
File {“name”:{“first”:”Barry”,”last”:”Allen”},”employer”:”Central City Police Department”,”country”:”Central City”,”skills”:[“The Fastest Man Alive”],”level”:”error”,”message”:””,”timestamp”:”2015-03-19T16:40:01.928Z”}

See the difference. The object can be automatically stringify’d, or converted to plain text, as and when needed.

Object Literals and Stringify

You may be familiar only with logging messages of string data, which, in a compact format, contains all of the information you need. But that may not be the best approach for your situation, or all of them. Various libraries, available for Node.js, also allow objects, or object literals, to be used as log messages. Take the following two objects, the first one shallow, the second one more complex:

var shallowObject = {
  fullname: "Barry Allen",
  employer: "Central City Police Department",
  country: "United States",
  skills: ['The Fastest Man Alive']
}

var complexObject = {
  name: {
    first: "Barry",
    last: "Allen"
  },
  employer: "Central City Police Department",
  country: "United States",
  skills: [
    'The Fastest Man Alive'
  ]
}

Both of these contain a variety of information, which could be used in a personal management system. Attempting to store this information as a string would be quite difficult. So it’s best not to do so. Instead, keep information as this as an object literal and use functionality available in several Node.js libraries to stringify the information.

node object literal

Good logging systems and services will allow you to store and view the information in a stringified form, as you can see above, yet alo allow you to view it close to its original format, as in the screenshots below.

node parsed object

Not every library supports it, but here’s how you can log a JSON object with node-loggly. First initialize the object, setting the json property to true, as follows:

var client = loggly.createClient({
  // other configuration details
    json: true
});

Then pass the object to the log method, like this.

<preclient.log(complexObject);

Context or Child Loggers

When you’re logging, it’s often handy or even necessary to categorize or sub-categorize the logs so that more context can be added to the information that is logged. A number of the Node.js libraries offer this functionality under a number of names, including context or child loggers as in Bunyan. Let’s explore this by looking at Bunyan’s child loggers.

Child loggers specialize the parent logger object, effectively adding more context to the information which is logged. Let’s say that I want to write out the following log message, where you can see the environment’s been specified in the message.

{"name":"myapp","hostname":"Matts-Mac-3.fritz.box","pid":12941,"environment":"development","level":40,"msg":"Problem with MySQL server.","time":"2015-01-31T10:27:24.589Z","v":0}

To do that, I can create a new object, which creates a child logger from the parent logger which is passed to it in its constructor. In defining the child logger, it specifies a key of environment, with a value of development. This will customize the log message it writes, inserting the key/value pair. I’ve next defined a function on the object to log a message at the level of info.

While it may not seem like a lot on the surface, using child loggers helps identify a log message stream, allowing for a sort of trail or connection to be made throughout logs for a specific section of the application. Given that a lot of information can be stored, based on all kinds of criteria, child loggers make it easier to follow the information stored by a specific section of an application.

Pretty Print and Multi-Line Formatting

When you’re sending log messages, consider sending multi-line, instead of single, indiscernible long lines as log messages. If you have a JavaScript background, this may seem a little strange, perhaps even wrong.

node multiline formatting

But have a look at the log entries in this Gist, which I’ve included an excerpt of above, and tell me which ones are more readable. In hello.log, the first example, all of the entries, while containing a host of relevant information, scroll off the screen and make discerning the key information quite difficult.

Compare that, even superficially, with the log records in Example 2. There, the information is a lot clearer for us, as humans, to read and parse. In the code example below, you can see how to enable this using Winston.js.

var winston = require('winston')
var complexObject = {
  name: {
    first: "Barry",
    last: "Allen"
  },
  employer: "Central City Police Department",
  country: "United States",
  skills: [
    'The Fastest Man Alive'
  ]
}

var logger = new (winston.Logger)({
  transports: [
    new (winston.transports.Console)({
      level: 'silly',
      prettyPrint: true
    }),
  ]
})

logger.warn(complexObject)

This, then, results in the following output to the console:

warn:
{ name: { first: 'Matthew', last: 'Setter' },
  employment: 'Freelance Technical Writer',
  country: 'Germany',
  languages: [ 'PHP', 'Node.js', 'Bash', 'Ruby', 'Python', 'Go' ] }

Colors

Some libraries, such as Winston, allow for log entries to be colorized, as in the image below. Colorization enables transports with the “colorize” option set to appropriately color the output of custom levels.

winston color logging

Now while it is not altogether necessary, it can be handy to visually distinguish different logging levels when you’re viewing log data. However, before you implement this feature, check if your back end supports it; the screenshot above was taken using a console logger, which does.

Here is a simple example of how to configure colorization using Winston.

winston.loggers.add('development', {
console: {
level: 'silly',
colorize: 'true'
}
});

You can see that when a log message is sent at the level of silly, it will be colorized to green.

Express.js

Express.js is one of the most popular frameworks for creating web applications with Node.js. If you choose to use it, there will come a time when you’ll want to add logging. One of the great things about Express.js and Node.js in general is that the setup and configuration is so simple.

Let’s assume that you have a very basic application and you want to log details about each request. In the code example below, you can see how to do it using a combination of Winston along with the express-winston logging extension. express-winston is a middleware library for Express.js which provides request and error logging in express.js applications.

var express = require('express')
var app = express()
var winston = require('winston'),
    expressWinston = require('express-winston');

app.use(expressWinston.errorLogger({
  transports: [
    new winston.transports.Console({
    json: true,
    colorize: true
  })
  ],
  meta: true,
  msg: "HTTP {{req.method}} {{req.url}}",
  expressFormat: true,
  colorStatus: true
}));

I’ve deliberately left a lot of the other configuration out, so as not to confuse the example. All that was required to set up logging was to require the necessary libraries, then configure a logger on the app, which, in this case, logs to the console. Now, when a request is made, in the console, you’ll see details written out about it, such as:

 

curl -v http://127.0.0.1:3000
* Rebuilt URL to: http://127.0.0.1:3000/
* Hostname was NOT found in DNS cache
*   Trying 127.0.0.1...
* Connected to 127.0.0.1 (127.0.0.1) port 3000 (#0)
> GET / HTTP/1.1
> User-Agent: curl/7.37.1
> Host: 127.0.0.1:3000
> Accept: */*
>
< HTTP/1.1 200 OK
< X-Powered-By: Express
< Content-Type: text/html; charset=utf-8
< Content-Length: 35
< ETag: W/"23-2887faec"
< Date: Tue, 31 Mar 2015 18:54:59 GMT
< Connection: keep-alive
<
* Connection #0 to host 127.0.0.1 left intact
Hello World, here is Matthew Setter