Node.js real time logging with Winston, Redis and Socket.io, p2

Following up on my last blog post Node.js real time logging with Winston, Redis and Socket.io, p1 I want to get into the integration of winston with Socekt.io to stream logs real time to a browser.

So just a quick recap, the idea here is to have a mechanism that logs messages categorized by different levels in the server and displays them at the same time in the browser, keeping the user informed at all times of the action in the back end, or helping a developer spot some bugs without the need to keep an eye on the terminal console or searching for log files buried in the server.

Socket.io

So first we need to initialize the socket.io lib.
This part could be done several different ways, I haven’t found a baseline to follow when initializing and sharing a socket.io handler on express, so if anybody knows please hit me up in the comments.
Anyway, the approach I decided to take was:

  1. Initialize the logger
  2. Register an event listener on the logger instance.
  3. Start the express http server
  4. Start the socket.io server
  5. Fire event on the logger instance
// Create logger
var di = {};
di.config = require('./config/config.js');
var logger = require('./utils/logger.js').inject(di);

// Start listening for socket event on the logger
logger.on("socket", function () {
  this.socketIO = loggerSocket;
});

// Create && Start http server
var server = http.createServer(app);
server.listen(app.get('port'), function() {
  console.log("Express server listening on port " + app.get('port'));
});

// Create socket.io connection
var io = require('socket.io')
console.log("creating socket connection");
var loggerSocket = io.listen(server, {log: false}).of('/logger');

loggerSocket.on('connection', function(socket){
  socket.join(socket.handshake.sessionID);
  // Emit event to logger
  logger.emit("socket");
});

As you can see in the code snippet above, all the dependencies for the logger are saved in an object and injected on the module, in the case it only depends on config.js.
And since the logger is a singleton, all other modules that require the logger will get an already initialized instance.

After we get a handle on the logger, we start listening for the ‘socket’ event, the name could be anything since we are firing the event later in the code. The reason behind this event is that we can to grab a hold of the socket connection and save it inside the logger so we can start streaming logs once they are generated.
We could simply set the reference to socketIO on the logger inside the connection event for the socket, however, by decoupling the socket connection with the logger socket.io handler initialization gives us the flexibility to move things around to different places.

Last, we start the http and socket.io server and fire a socket event whenever the socket.io finishes connecting.

Streaming logs with winston

Now that the logger has a handle of the socket.io connection it can start streaming logs to the browser in real time.

var CustomLogger = function (config) {

  ....
  ....

  winston.stream({ start: -1 }).on('log', function(log) {
    var type = log.transport[0];
    if (self.socketIO && type === "redis") {
      console.log("\n**emitting socket msg");
      self.socketIO.emit("newLog", log);
    }
  });
}

In the logger constructor we initialize the winston stream which listens for all new logs added to different Transports.
That’s why we check for the redis Transports specifically before emitting the logĀ  with socket.io, since we don’t want to emit repeated logs.

Displaying logs on the client

Looking at the client side code

    // Create socketIO connection
    this.logger = io.connect('/logger');
    // Incoming log via socket connection
    this.logger.on('newLog', function (data) {
      var log = new app.Log({
        'timestamp' : data.timestamp,
        'file'      : data.file,
        'line'      : data.line,
        'message'   : data.message,
        'level'     : data.level,
        'id'        : data.id,
      });
      self.socketLog = true;
      self.collections[data.level].add(log);
    });

We create a socket connection with the server and start listening for the ‘newLog’ event, which contains the log data being streamed from winston.
For our app, since we are using Backbone, we create a new Log model and add that Log to the Logger collection, which contains a bunch of Logs.

Just to give an idea of how the Logger prototype is shaping up:
Screen Shot 2013-03-19 at 2.38.14 PM

In the end this works, but it could be better.
My idea is to deeply integrate a socket.io streaming functionality with winston, providing the option to start streaming logs straight out of the box. The goal is to make logs as useful as possible, and not just something that’s there but never used.

Node.js real time logging with Winston, Redis and Socket.io, p1

After I had the chance to hack some bugs on Firefox I noticed that they had a very strong logging system built in the project which made the act of logging stuff very easy and standardize.

A few built in logging macros that is very common to see across Firefox code are:

  • NS_ASSERTION
  • NS_WARNING
  • NS_ERROR

The complete list of macros can be found here

Keeping that in mind I thought it would be beneficial to implement something similar in the WebVirt project.
It not only helps developers to spot bugs and keep track of old issues that were appearing in the application, but it also helps users to have a direct access to the server logs, without the need to dig deep through several directories to find one text file with thousands of logs which makes very difficult to get any useful information out of it.

So the basic idea was to have different levels of logs, to make them more granular and provide a simple interface to allow users and developers to use the logs as a debugging tool.

Winston Logging Library

If you are working with Node.js there is a very solid library that is well maintained and used across several projects, the library being winston.

The beauty of winston it is the flexibility and the power it provides.
A quick overview on winston:

Transports
You can create different “Transports”, which are the final location where your logs are stored.
So it is possible to log everything to a database, the console and to a file at the same time.

Metadata
There is support for metadata on a per log basis. Which can be very useful to add extra information about an error that you might be logging.

Querying Logs
Another functionality that is built in the library is the querying of existing logs.
Independently of the Transport you might be using to save your logs, winston can query all the logs and provide them to you in json format with all the metadata tags parsed.

Streaming Logs
This is a very handy feature if you are planning to implement a real time logging solution with web sockets for example.

After looking at all the features winston provided it was a no brainier to start leveraging its power instead of writing a new one from scratch.

So now lets get into the details of how winston is working on WebVirt.

WebVirt Custom Logger

First of all we created a CustomLogger module which wraped winston giving us the flexibility to play around with the CustomLogger implementation without breaking the whole system since we can keep the logger API constant through out the app.

var _logger;

var CustomLogger = function (config) {
}

CustomLogger.prototype = new events.EventEmitter();

CustomLogger.prototype.info = function (msg, metadata) {
};

CustomLogger.prototype.warn = function (msg, metadata) {
};

CustomLogger.prototype.error = function (msg, metadata) {
};

CustomLogger.prototype.query = function (options, cb) {
}

module.exports.inject = function (di) {
  if (!_logger) {
    _logger = new CustomLogger(di.config.logger);
  }
  return _logger;
}

The CustomLogger implements a Singleton pattern which only instantiate one object for the whole app.
We allow a set of custom dependencies to be injected on the module which gives us even more flexibility to move things around without the risk of coupling them together.
We are also extending the EventEmitter functionality to give the options for the CustomLogger to emit its own events to whoever chooses to listen, that could be one option to implementing a real time web socket logging system but later on I’ll show that there is an easier way.
Finally, we just defined all methods we want to make publicly available on the logger.

After creating the skeleton for our CustomLogger we started to integrate winston in it.

var CustomLogger = function (config) {
  require('../external/winston-redis/lib/winston-redis.js').Redis;

  winston.handleExceptions(new winston.transports.Redis());
  winston.exitOnError = false;

  winston.remove(winston.transports.Console);
  winston.add(winston.transports.Console, {
      handleExceptions: true,
      json: true
  });
}

CustomLogger.prototype.info = function (msg, metadata) {
  winston.info(msg, metadata);
};

CustomLogger.prototype.warn = function (msg, metadata) {
  winston.warn(msg, metadata);
};

CustomLogger.prototype.error = function (msg, metadata) {
  winston.error(msg, metadata);
};

As you can see it’s very straight forward, the CustomLogger info, warn and error methods make a direct call to winston.
To initialize winston we require the winston-redis lib, which exposes the Redis Transport for Winston.
This leads me to the next topic:

Winston Redis Transport

Since we are already using Redis to store user information as well host details we chose to use Redis to store the logs too.
The winston-redis module is very easy to use and works out of the box, however, it didn’t fit the exact idea I had about the logging system of WebVirt.

We wanted to display different levels of logs to the user directly in the browser, however, we would need to have some sort of pagination control since the number of logs could go up to the thousands depending on the usage.
Not only that, we would also want to be able to search all logs of a particular level and also have a real time feature built in to display the logs with a websocket on the browser and even set some triggers to send some emails or any sort of notification based on pre-set filters.

With that being said, winston-redis saves all logs, independently of their level, to a single list on redis:

Screen Shot 2013-03-18 at 4.15.02 PM

So the ability to search and paginate the logs based on their level would be lost since they are all living in the same list.

To fix this issue and save logs on separate lists based on their levels we forked the lib and added an option to set a namespace for the redis container:

Redis.prototype.log = function (level, msg, meta, callback) {
  var self = this,
      container = this.container(meta),
      channel = this.channel && this.channel(meta);

  // Separate logs based on their levels
  container += ":" + level;
  this.redis.llen(container, function (err, len) {
    if (err) {
      if (callback) callback(err, false);
      return self.emit('error', err);
    }
    // Assigns an unique ID to each log
    meta.id = len + 1
    var output = common.log({
      level: level,
      message: msg,
      meta: meta,
      timestamp: self.timestamp,
      json: self.json,
    });

    // RPUSH may be better for poll-streaming.
    self.redis.lpush(container, output, function (err) {
      console.log("lpush callback");
      console.log("err: ", err);
      if (err) {
        if (callback) callback(err, false);
        return self.emit('error', err);
      }

      self.redis.ltrim(container, 0, self.length, function () {
        if (err) {
          if (callback) callback(err, false);
          return self.emit('error', err);
        }

        if (channel) {
          self.redis.publish(channel, output);
        }

        // TODO: emit 'logged' correctly,
        // keep track of pending logs.
        self.emit('logged');

        if (callback) callback(null, true);
      });
    });
  });
};

The only difference is that instead of logging everything to to a single “container” we append the level of the log to the “container”, thus splitting the logs into different lists:

Screen Shot 2013-03-18 at 4.15.36 PM

Now when we need to retrieve the logs we can specify how many and on which list we want to perform the query:

CustomLogger.prototype.query = function (options, cb) {
  var start = options.start || 1
    , rows = options.rows || 50
    , type = options.type || 'redis'
    , level = options.level || 'error';

  winston.query({
    'start': +start,
    'rows': +rows,
    'level': level
  }, function (err, data) {
    cb(err, data.redis);
  })
}

Something to keep in mind is that winston.query searches all Transports you have registered.
So if you are logging to multiple transports make sure you only use one Transport when reading the data back or you’ll get repeated values.

This sums it up the first part of the post.
Next I’ll post about how to integrate Socket.IO with Winston and stream logs real time to a browser.