wilkins

A multi-transport async logging library for node.js. "CHILL WILKINS! ... I put it in the logs."

Motivation

Wilkins is designed to be a simple and universal logging library with support for multiple transports. A transport is essentially a storage device for your logs. Each instance of a wilkins logger can have multiple transports configured at different levels. For example, one may want error logs to be stored in a persistent remote location (like a database), but all logs output to the console or a local file.

There also seemed to be a lot of logging libraries out there that coupled their implementation of logging (i.e. how the logs are stored / indexed) to the API that they exposed to the programmer. This library aims to decouple those parts of the process to make it more flexible and extensible.

Installation

npm install wilkins

Usage

There are two different ways to use wilkins: directly via the default logger, or by instantiating your own Logger. The former is merely intended to be a convenient shared logger to use throughout your application if you so choose.

• Logging
  • Using the Default Logger
  • Instantiating your own Logger
  • Logging with Metadata
  • String interpolation
• Transports
  • Multiple transports of the same type
• Profiling
• Streaming Logs
• Querying Logs
• Exceptions
  • Handling Uncaught Exceptions with wilkins
  • To Exit or Not to Exit
• Logging Levels
  • Using Logging Levels
  • Using Custom Logging Levels
• Further Reading
  • Events and Callbacks in Wilkins
  • Working with multiple Loggers in wilkins
  • Using wilkins in a CLI tool
  • Filters and Rewriters
  • Adding Custom Transports
• Installation
• Run Tests

Logging

Logging levels in wilkins conform to the severity ordering specified by RFC5424: severity of all levels is assumed to be numerically ascending from most important to least important.

Using the Default Logger

The default logger is accessible through the wilkins module directly. Any method that you could call on an instance of a logger is available on the default logger:

  var wilkins = require('wilkins');

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

  wilkins.level = 'debug';
  wilkins.log('debug', 'Now my debug messages are written to console!');

By default, only the Console transport is set on the default logger. You can add or remove transports via the add() and remove() methods:

  wilkins.add(wilkins.transports.File, { filename: 'somefile.log' });
  wilkins.remove(wilkins.transports.Console);

Or do it with one call to configure():

  wilkins.configure({
    transports: [
      new (wilkins.transports.File)({ filename: 'somefile.log' })
    ]
  });

For more documentation about working with each individual transport supported by Wilkins see the Wilkins Transports document.

Instantiating your own Logger

If you would prefer to manage the object lifetime of loggers you are free to instantiate them yourself:

  var logger = new (wilkins.Logger)({
    transports: [
      new (wilkins.transports.Console)(),
      new (wilkins.transports.File)({ filename: 'somefile.log' })
    ]
  });

You can work with this logger in the same way that you work with the default logger:

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

  //
  // Adding / Removing Transports
  //   (Yes It's chainable)
  //
  logger
    .add(wilkins.transports.File)
    .remove(wilkins.transports.Console);

You can also wholesale reconfigure a wilkins.Logger instance using the configure method:

  var logger = new wilkins.Logger({
    level: 'info',
    transports: [
      new (wilkins.transports.Console)(),
      new (wilkins.transports.File)({ filename: 'somefile.log' })
    ]
  });

  //
  // Replaces the previous transports with those in the
  // new configuration wholesale.
  //
  logger.configure({
    level: 'verbose',
    transports: [
      new (require('wilkins-daily-rotate-file'))(opts)
    ]
  });

Logging with Metadata

In addition to logging string messages, wilkins will also optionally log additional JSON metadata objects. Adding metadata is simple:

  wilkins.log('info', 'Test Log Message', { anything: 'This is metadata' });

The way these objects are stored varies from transport to transport (to best support the storage mechanisms offered). Here's a quick summary of how each transports handles metadata:

1. Console: Logged via util.inspect(meta)
2. File: Logged via util.inspect(meta)

Multiple transports of the same type

It is possible to use multiple transports of the same type e.g. wilkins.transports.File by passing in a custom name when you construct the transport.

var logger = new (wilkins.Logger)({
  transports: [
    new (wilkins.transports.File)({
      name: 'info-file',
      filename: 'filelog-info.log',
      level: 'info'
    }),
    new (wilkins.transports.File)({
      name: 'error-file',
      filename: 'filelog-error.log',
      level: 'error'
    })
  ]
});

If you later want to remove one of these transports you can do so by using the string name. e.g.:

logger.remove('info-file');

In this example, one could also remove by passing in the instance of the Transport itself. e.g. this is equivalent to the string example above:

// Notice it was first in the Array above
var infoFile = logger.transports[0];
logger.remove(infoFile);

Profiling

In addition to logging messages and metadata, wilkins also has a simple profiling mechanism implemented for any logger:

  //
  // Start profile of 'test'
  // Remark: Consider using Date.now() with async operations
  //
  wilkins.profile('test');

  setTimeout(function () {
    //
    // Stop profile of 'test'. Logging will now take place:
    //   "17 Jan 21:00:00 - info: test duration=1000ms"
    //
    wilkins.profile('test');
  }, 1000);

All profile messages are set to 'info' level by default and both message and metadata are optional. There are no plans in the Roadmap to make this configurable, but I'm open to suggestions / issues.

String interpolation

The log method provides the same string interpolation methods like util.format.

This allows for the following log messages.

logger.log('info', 'test message %s', 'my string');
// info: test message my string

logger.log('info', 'test message %d', 123);
// info: test message 123

logger.log('info', 'test message %j', {number: 123}, {});
// info: test message {"number":123}
// meta = {}

logger.log('info', 'test message %s, %s', 'first', 'second', {number: 123});
// info: test message first, second
// meta = {number: 123}

logger.log('info', 'test message', 'first', 'second', {number: 123});
// info: test message first second
// meta = {number: 123}

logger.log('info', 'test message %s, %s', 'first', 'second', {number: 123}, function(){});
// info: test message first, second
// meta = {number: 123}
// callback = function(){}

logger.log('info', 'test message', 'first', 'second', {number: 123}, function(){});
// info: test message first second
// meta = {number: 123}
// callback = function(){}

Querying Logs

Wilkins supports querying of logs with Loggly-like options. See Loggly Search API. Specifically: File, Couchdb, Redis, Loggly, Nssocket, and Http.

  var options = {
    from: new Date - 24 * 60 * 60 * 1000,
    until: new Date,
    limit: 10,
    start: 0,
    order: 'desc',
    fields: ['message']
  };

  //
  // Find items logged between today and yesterday.
  //
  wilkins.query(options, function (err, results) {
    if (err) {
      throw err;
    }

    console.log(results);
  });

Streaming Logs

Streaming allows you to stream your logs back from your chosen transport.

  //
  // Start at the end.
  //
  wilkins.stream({ start: -1 }).on('log', function(log) {
    console.log(log);
  });

Exceptions

Handling Uncaught Exceptions with wilkins

With wilkins, it is possible to catch and log uncaughtException events from your process. There are two distinct ways of enabling this functionality either through the default wilkins logger or your own logger instance.

If you want to use this feature with the default logger, simply call .handleExceptions() with a transport instance.

  //
  // You can add a separate exception logger by passing it to `.handleExceptions`
  //
  wilkins.handleExceptions(new wilkins.transports.File({ filename: 'path/to/exceptions.log' }))

  //
  // Alternatively you can set `.handleExceptions` to true when adding transports to wilkins.
  // You can use the `.humanReadableUnhandledException` option to get more readable exceptions.
  //
  wilkins.add(wilkins.transports.File, {
    filename: 'path/to/all-logs.log',
    handleExceptions: true,
    humanReadableUnhandledException: true
  });

  //
  // Exceptions can also be handled by multiple transports.
  //
  wilkins.handleExceptions([ transport1, transport2, ... ]);

To Exit or Not to Exit

By default, wilkins will exit after logging an uncaughtException. If this is not the behavior you want, set exitOnError = false

  var logger = new (wilkins.Logger)({ exitOnError: false });

  //
  // or, like this:
  //
  logger.exitOnError = false;

When working with custom logger instances, you can pass in separate transports to the exceptionHandlers property or set .handleExceptions on any transport.

Example 1

  var logger = new (wilkins.Logger)({
    transports: [
      new wilkins.transports.File({ filename: 'path/to/all-logs.log' })
    ],
    exceptionHandlers: [
      new wilkins.transports.File({ filename: 'path/to/exceptions.log' })
    ]
  });

Example 2

var logger = new wilkins.Logger({
  transports: [
    new wilkins.transports.Console({
      handleExceptions: true,
      json: true
    })
  ],
  exitOnError: false
});

The exitOnError option can also be a function to prevent exit on only certain types of errors:

  function ignoreEpipe(err) {
    return err.code !== 'EPIPE';
  }

  var logger = new (wilkins.Logger)({ exitOnError: ignoreEpipe });

  //
  // or, like this:
  //
  logger.exitOnError = ignoreEpipe;

Logging Levels

Each level is given a specific integer priority. The higher the priority the more important the message is considered to be, and the lower the corresponding integer priority. For example, npm logging levels are prioritized from 0 to 5 (highest to lowest):

{ error: 0, warn: 1, info: 2, verbose: 3, debug: 4, silly: 5 }

Similarly, as specified exactly in RFC5424 the syslog levels are prioritized from 0 to 7 (highest to lowest).

{ emerg: 0, alert: 1, crit: 2, error: 3, warning: 4, notice: 5, info: 6, debug: 7 }

If you do not explicitly define the levels that wilkins should use the npm levels above will be used.

Using Logging Levels

Setting the level for your logging message can be accomplished in one of two ways. You can pass a string representing the logging level to the log() method or use the level specified methods defined on every wilkins Logger.

  //
  // Any logger instance
  //
  logger.log('silly', "127.0.0.1 - there's no place like home");
  logger.log('debug', "127.0.0.1 - there's no place like home");
  logger.log('verbose', "127.0.0.1 - there's no place like home");
  logger.log('info', "127.0.0.1 - there's no place like home");
  logger.log('warn', "127.0.0.1 - there's no place like home");
  logger.log('error', "127.0.0.1 - there's no place like home");
  logger.info("127.0.0.1 - there's no place like home");
  logger.warn("127.0.0.1 - there's no place like home");
  logger.error("127.0.0.1 - there's no place like home");

  //
  // Default logger
  //
  wilkins.log('info', "127.0.0.1 - there's no place like home");
  wilkins.info("127.0.0.1 - there's no place like home");

wilkins allows you to define a level property on each transport which specifies the maximum level of messages that a transport should log. For example, using the npm levels you could log only error messages to the console and everything info and below to a file (which includes error messages):

  var logger = new (wilkins.Logger)({
    transports: [
      new (wilkins.transports.Console)({ level: 'error' }),
      new (wilkins.transports.File)({
        filename: 'somefile.log',
        level: 'info'
      })
    ]
  });

You may also dynamically change the log level of a transport:

  var logger = new (wilkins.Logger)({
    transports: [
      new (wilkins.transports.Console)({ level: 'warn' }),
      new (wilkins.transports.File)({ filename: 'somefile.log', level: 'error' })
    ]
  });
  logger.debug("Will not be logged in either transport!");
  logger.transports.console.level = 'debug';
  logger.transports.file.level = 'verbose';
  logger.verbose("Will be logged in both transports!");

As of 0.2.0, wilkins supports customizable logging levels, defaulting to npm style logging levels. Changing logging levels is easy:

  //
  // Change levels on the default wilkins logger
  //
  wilkins.setLevels(wilkins.config.syslog.levels);

  //
  // Change levels on an instance of a logger
  //
  logger.setLevels(wilkins.config.syslog.levels);

Calling .setLevels on a logger will remove all of the previous helper methods for the old levels and define helper methods for the new levels. Thus, you should be careful about the logging statements you use when changing levels. For example, if you ran this code after changing to the syslog levels:

  //
  // Logger does not have 'silly' defined since that level is not in the syslog levels
  //
  logger.silly('some silly message');

Using Custom Logging Levels

In addition to the predefined npm and syslog levels available in Wilkins, you can also choose to define your own:

  var myCustomLevels = {
    levels: {
      foo: 0,
      bar: 1,
      baz: 2,
      foobar: 3
    },
    colors: {
      foo: 'blue',
      bar: 'green',
      baz: 'yellow',
      foobar: 'red'
    }
  };

  var customLevelLogger = new (wilkins.Logger)({ levels: myCustomLevels.levels });
  customLevelLogger.foobar('some foobar level-ed message');

Although there is slight repetition in this data structure, it enables simple encapsulation if you do not want to have colors. If you do wish to have colors, in addition to passing the levels to the Logger itself, you must make wilkins aware of them:

  //
  // Make wilkins aware of these colors
  //
  wilkins.addColors(myCustomLevels.colors);

This enables transports with the 'colorize' option set to appropriately color the output of custom levels.

Further Reading

Events and Callbacks in Wilkins

Each instance of wilkins.Logger is also an instance of an EventEmitter. A log event will be raised each time a transport successfully logs a message:

  logger.on('logging', function (transport, level, msg, meta) {
    // [msg] and [meta] have now been logged at [level] to [transport]
  });

  logger.info('CHILL WILKINS!', { seriously: true });

It is also worth mentioning that the logger also emits an 'error' event which you should handle or suppress if you don't want unhandled exceptions:

  //
  // Handle errors
  //
  logger.on('error', function (err) { /* Do Something */ });

  //
  // Or just suppress them.
  //
  logger.emitErrs = false;

Every logging method described in the previous section also takes an optional callback which will be called only when all of the transports have logged the specified message.

  logger.info('CHILL WILKINS!', { seriously: true }, function (err, level, msg, meta) {
    // [msg] and [meta] have now been logged at [level] to **every** transport.
  });

Working with multiple Loggers in wilkins

Often in larger, more complex, applications it is necessary to have multiple logger instances with different settings. Each logger is responsible for a different feature area (or category). This is exposed in wilkins in two ways: through wilkins.loggers and instances of wilkins.Container. In fact, wilkins.loggers is just a predefined instance of wilkins.Container:

  var wilkins = require('wilkins');

  //
  // Configure the logger for `category1`
  //
  wilkins.loggers.add('category1', {
    console: {
      level: 'silly',
      colorize: true,
      label: 'category one'
    },
    file: {
      filename: '/path/to/some/file'
    }
  });

  //
  // Configure the logger for `category2`
  //
  wilkins.loggers.add('category2', {
    couchdb: {
      host: '127.0.0.1',
      port: 5984
    }
  });

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

  var wilkins = require('wilkins');

  //
  // Grab your preconfigured logger
  //
  var category1 = wilkins.loggers.get('category1');

  category1.info('logging from your IoC container-based logger');

If you prefer to manage the Container yourself, you can simply instantiate one:

  var wilkins = require('wilkins'),
      container = new wilkins.Container();

  container.add('category1', {
    console: {
      level: 'silly',
      colorize: true
    },
    file: {
      filename: '/path/to/some/file'
    }
  });

Sharing transports between Loggers in wilkins

  var wilkins = require('wilkins');

  //
  // Setup transports to be shared across all loggers
  // in three ways:
  //
  // 1. By setting it on the default Container
  // 2. By passing `transports` into the constructor function of wilkins.Container
  // 3. By passing `transports` into the `.get()` or `.add()` methods
  //

  //
  // 1. By setting it on the default Container
  //
  wilkins.loggers.options.transports = [
    // Setup your shared transports here
  ];

  //
  // 2. By passing `transports` into the constructor function of wilkins.Container
  //
  var container = new wilkins.Container({
    transports: [
      // Setup your shared transports here
    ]
  });

  //
  // 3. By passing `transports` into the `.get()` or `.add()` methods
  //
  wilkins.loggers.add('some-category', {
    transports: [
      // Setup your shared transports here
    ]
  });

  container.add('some-category', {
    transports: [
      // Setup your shared transports here
    ]
  });

Using wilkins in a CLI tool

A common use-case for logging is output to a CLI tool. Wilkins has a special helper method which will pretty print output from your CLI tool. Here's an example from the require-analyzer written by Nodejitsu:

  info:   require-analyzer starting in /Users/Charlie/Nodejitsu/require-analyzer
  info:   Found existing dependencies
  data:   {
  data:     colors: '0.x.x',
  data:     eyes: '0.1.x',
  data:     findit: '0.0.x',
  data:     npm: '1.0.x',
  data:     optimist: '0.2.x',
  data:     semver: '1.0.x',
  data:     wilkins: '0.2.x'
  data:   }
  info:   Analyzing dependencies...
  info:   Done analyzing raw dependencies
  info:   Retrieved packages from npm
  warn:   No additional dependencies found

Configuring output for this style is easy, just use the .cli() method on wilkins or an instance of wilkins.Logger:

  var wilkins = require('wilkins');

  //
  // Configure CLI output on the default logger
  //
  wilkins.cli();

  //
  // Configure CLI on an instance of wilkins.Logger
  //
  var logger = new wilkins.Logger({
    transports: [
      new (wilkins.transports.Console)()
    ]
  });

  logger.cli();

Filters and Rewriters

Filters allow modifying the contents of log messages, and Rewriters allow modifying the contents of log meta e.g. to mask data that should not appear in logs.

Both filters and rewriters are simple Arrays of functions which can be provided when creating a new wilkins.Logger(options). e.g.:

var logger = new wilkins.Logger({
  rewriters: [function (level, msg, meta) { /* etc etc */ }],
  filters:   [function (level, msg, meta) { /* etc etc */ }]
})

Like any Array, they can also be modified at runtime with no adverse side-effects to the wilkins internals.

logger.filters.push(function(level, msg, meta) {
  return meta.production
    ? maskCardNumbers(msg)
    : msg;
});

logger.info('transaction with card number 123456789012345 successful.');

This may result in this output:

info: transaction with card number 123456****2345 successful.

Where as for rewriters, if you wanted to sanitize the creditCard field of your meta you could:

logger.rewriters.push(function(level, msg, meta) {
  if (meta.creditCard) {
    meta.creditCard = maskCardNumbers(meta.creditCard)
  }

  return meta;
});

logger.info('transaction ok', { creditCard: 123456789012345 });

which may result in this output:

info: transaction ok creditCard=123456****2345

See log-filter-test.js, where card number masking is implemented as an example along with log-rewriter-test.js

Adding Custom Transports

Adding a custom transport is actually pretty easy. All you need to do is accept a couple of options, set a name, implement a log() method, and add it to the set of transports exposed by wilkins.

  var util = require('util'),
      wilkins = require('wilkins');

  var CustomLogger = wilkins.transports.CustomLogger = function (options) {
    //
    // Name this logger
    //
    this.name = 'customLogger';

    //
    // Set the level from your options
    //
    this.level = options.level || 'info';

    //
    // Configure your storage backing as you see fit
    //
  };

  //
  // Inherit from `wilkins.Transport` so you can take advantage
  // of the base functionality and `.handleExceptions()`.
  //
  util.inherits(CustomLogger, wilkins.Transport);

  CustomLogger.prototype.log = function (level, msg, meta, callback) {
    //
    // Store this message and metadata, maybe use some custom logic
    // then callback indicating success.
    //
    callback(null, true);
  };

Custom Log Format

To specify a custom log format for a transport, you should set a formatter function. Currently supported transports are: Console, File, Memory. An options object will be passed to the formatter function. It's general properties are: timestamp, level, message, meta. Depending on the transport type, there may be additional properties.

var logger = new (wilkins.Logger)({
  transports: [
    new (wilkins.transports.Console)({
      timestamp: function() {
        return Date.now();
      },
      formatter: function(options) {
        // Return string will be passed to logger.
        return options.timestamp() +' '+ options.level.toUpperCase() +' '+ (options.message ? options.message : '') +
          (options.meta && Object.keys(options.meta).length ? '\n\t'+ JSON.stringify(options.meta) : '' );
      }
    })
  ]
});
logger.info('Data to log.');

Inspirations

1. npm
2. log.js
3. socket.io
4. node-rlog
5. BigBrother
6. Loggly

Installation

Installing npm (node package manager)

  curl http://npmjs.org/install.sh | sh

Installing wilkins

  [sudo] npm install wilkins

Run Tests

All of the wilkins tests are written in vows, and designed to be run with npm.

  $ npm test

Author: Charlie Robbins

Contributors: Matthew Bergman, Marak Squires