Better Logging with Bunyan

Whenever there was any server alerts in my team at Adobe, the first thing that we used to do was to look at the logs. And in most cases, we would track down the issue within minutes. Logs can be valuable in security, debugging and analytics.

When debugging, your first friend is console. The most simple type of logging you could do is using console.log and console.error methods.

console.log("Hello World");

This would output Hello World in the terminal window.

But this is not enough in production because

1. Console logs are synchronous(unless you use pipe)
2. Console is completely manual, so you have to format, manage and debug on your own.

Given this, I was looking for some open source logging libraries. There are two that are well known: Winston and Bunyan. (There are always other options but given the time crunch, its best to do some reading and just choose one.) This article is very well written explaining about the difference in both these library

TL;DR Winston is easier to consume manually and has a lot of community support but by default does not log time stamp, machine name or process ID. Bunyan on the other hand makes it easy out of the box to parse logs but user consumption is a bit tedious.

Given this, I decided to go ahead with Bunyan because ultimately we want to use the logs primarily for analytics (and I liked there JSON format). Once I installed Bunyan

npm install bunyan

I played around a bit using the following example provided in their github

//app.js
var bunyan = require('bunyan');
var log = bunyan.createLogger({name: 'ShotPitch'});
log.info('Hello World');
log.warn({lang: 'fr'}, 'au revoir');

This would give us the following output.(Bunyan adds a few extra field on its own)

$ node app.js
{"name":"ShotPitch","hostname":"MBP.Home","pid":5354,"level":30,"msg":"hi","time":"2016-03-26T18:46:23.851Z","v":0}
{"name":"ShotPitch","hostname":"MBP.Home","pid":5354,"level":40,"lang":"fr","msg":"au revoir","time":"2016-03-26T18:46:23.853Z","v":0}

I was looking at solution that would help us put this log into a file. You can use the constructor API of bunyan to customise the options. To log it to a file

var log = bunyan.createLogger({
    name: 'ShotPitch',
    streams: [{
        path: '/var/log/ShotPitch.log',
        // `type: 'file'` is implied
    }]
});

This would start logging in a log file. Now we can do log rotation

Log Rotation

The primary reason for log rotation is to limit the total size of the log file. But it also gives you an easy way to segregate the logs based on time at a very basic level.

Luckily Bunyan has inbuilt way of doing Log rotation

var log = bunyan.createLogger({
    name: 'ShotPitch',
    streams: [{
        type: 'rotating-file',
        path: '/var/log/ShotPitch.log',
        period: '1d',   // daily rotation
        count: 3        // keep 3 back copies
    }]
});

With all these basic aspects taken care of, we were looking for a way to integrate the log stream for our Node application using Express Framework.

But I found a package, express-bunyan-logger, that was doing exactly what we were looking for.

After installing the package

npm install express-bunyan-logger

I introduced the following code in express.js before the controller code

app.use(require('express-bunyan-logger')({name: 'ShotPitch',
  streams: [{
    type: 'rotating-file',
    level: 'info',                  // loging level
    path: '/var/log/shotpitch.log',
    period: '1d',   // daily rotation
    count: 3,        // keep 3 back copies
  }]
}));

A simple API call to test logged the following data

{
  "name": "ShotPitch",
  "hostname": "MBP.local",
  "pid": 6732,
  "req_id": "aad7327d-eebe-46fa-baa7-e361eece7168",
  "level": 40,
  "remote-address": "127.0.0.1",
  "ip": "127.0.0.1",
  "method": "GET",
  "url": "\/startups",
  "referer": "-",
  "user-agent": {
    "family": "cURL",
    "major": "7",
    "minor": "43",
    "patch": "0",
    "device": {
      "family": "Other",
      "major": "0",
      "minor": "0",
      "patch": "0"
    },
    "os": {
      "family": "Other",
      "major": "0",
      "minor": "0",
      "patch": "0"
    }
  },
  "body": {
    
  },
  "short-body": "{}",
  "http-version": "1.1",
  "response-time": 14.040452,
  "response-hrtime": [
    0,
    14040452
  ],
  "status-code": 401,
  "req-headers": {
    "host": "localhost:9000",
    "user-agent": "curl\/7.43.0",
    "accept": "*\/*"
  },
  "res-headers": {
    "x-powered-by": "Express",
    "access-control-allow-origin": "*",
    "www-authenticate": [
      "Bearer realm=\"Users\""
    ]
  },
  "req": {
    "method": "GET",
    "url": "\/startups",
    "headers": "[Circular]",
    "remoteAddress": "127.0.0.1",
    "remotePort": 56433
  },
  "res": {
    "statusCode": 401,
    "header": "HTTP\/1.1 401 Unauthorized\r\nX-Powered-By: Express\r\nAccess-Control-Allow-Origin: *\r\nWWW-Authenticate: Bearer realm=\"Users\"\r\nDate: Sun, 27 Mar 2016 18:48:35 GMT\r\nConnection: keep-alive\r\nTransfer-Encoding: chunked\r\n\r\n"
  },
  "incoming": "<--",
  "msg": "127.0.0.1 <-- GET \/startups HTTP\/1.1 401 - - cURL 7.43 Other 0.0.0 14.040452 ms",
  "time": "2016-03-27T18:48:35.210Z",
  "v": 0
}

Although we can get most of these info from nginx and error logs, having it created like this opens up possibility to process it faster and a lot of different usage. As of now most information logged in are what is provided by default but when I can I will log in more info like user id, location etc.

P.S: I am new to node.js and exploring a lot of things. If you have something good to share, reach out to me.

Suggested Reading:

1. Logging CheckList
2. Bunyan Vs Winston