Production Ready Node: Logging
oggng is one of the those things that many developers don't put much thought towards until it is a little too late. Having some kind of audit trail of what the application behavior, state, and any errors that may occur is critical to developing and maintaining complex systems. However, javascript developers are typically accustomed to just peppering `console.log` when ever and where ever they see fit. During development this may seem like a fine idea, but this quickly proves to be a insufficient logging solution.
Firstly, the console interface in Node writes to one of the standard outputs in the host system, which may or may not be captured so you may inspect it. There is also no concept of message severity, order or context. In a complex, asynchronous & non-blocking system, messages will often come out of order or from different running instances. Trying to aggregate any meaningful information is next to impossible.
Secondly, it keeps all of the important information local to the host machine which means if developers ever need to get at the logs, they need access to a production machine, or may occupy additional resources to obtain them. Another problem that is becoming more prevalent in containerized environments , like docker, is that if/when the container is restarted or replaced, all of your logs will be lost. That is less than ideal for sure.
Lastly, it isn't very configurable. Logging solutions are going to be different based on environment. For example, in development, writing to standard out is fine. In production, we may want to write to syslog. Or, more realistically, we may want to set up a file rotation, in addition to syslog on the host machine, and send errors off to a remote service like Sentry with an alert mail to a system administrator in the case of a critical or fatal error. We will also probably want a way to configure different remote locations between staging and production environments for example so we don't clutter up our production data.
What we really want to do is set up a centralized, transport based logging module that will be used in place of console. There are a couple of great modules out there in the node community to help us out here - Bunyan and Winston. Each is great in there own right. I tend to reach for winston most often, so that is what we'll be covering. Hopefully you have been following along with the previous installments in series, Packaging & Structure and Configuration, as we are going to be building on top of the concepts established there.
Logging Package
To get started we are going to add a log packages to our internal packages directory and set up a sub-directory to hold our different transports, and configuration.
.
|-- packages
|-- project-log
|-- conf
| `-- index.js
|--transports
| |-- index.js
| `-- stdout.js
|-- package.json
|-- README.md
`-- index.js
Once our package structure is in place, we can go ahead and install winston
cd packages/project-log
npm install --save winston
Once winston is installed we can start the logging module itself. To make the switch from the global console object to our package as seamless as possible, our package is going to export a configured logging instance, so all we need to do is var logger = require('package-log'), and be on our way. do accomplish this our entry point ( index.js ) is going to have to do a couple of things:
- Establish default logging levels
- Load all configured transports
- Create a dedicated Error Handler
- Export a Winston Instance
var winston = require( 'winston' )
, conf = require( 'project-conf' )
, path = require( 'path' )
, util = require( 'util' )
, domain = require( 'domain' )
, events = require( 'events' )
, loggerdomain = domain.create()
, loggers = []
, emitter = new events.EventEmitter()
, log_types
, levels
, colors
, exceptionloggers
, loggerdomain
, logger
;
levels = {
emerg: 8,
alert: 7,
crit: 6,
error: 5,
warning: 4,
notice: 3,
info: 2,
debug: 1,
http: 0
};
colors = {
emerg: 'red',
alert: 'yellow',
crit: 'red',
error: 'red',
warning: 'red',
notice: 'yellow',
info: 'green',
debug: 'blue',
http: 'cyan'
};
log = conf.get('log');
log_types = conf.get('logger');
log_types = Array.isArray( log_types ) ? log_types : [log_types];
// try to resolve a module to load a
// logging backend
log_types.forEach(function( type ){
var backend = null // the backend we are about to load
, backendconf // derived configuration for the logging backend
, e; // potention error
try{
backend = require("./transports/" + type )
} catch( err ){
// allow ad-hoc log types
backendconf = conf.get( type );
if( backendconf && backendconf.module ){
backend = require( backendconf.module );
} else {
e = new Error();
e.name="InvalidLogType";
e.message = util.format( "unable to load logging module %s", type);
emitter.emit('error', e);
}
}
// if we made it this far, add the transport
if( backend ){
loggers.push( new backend( log[ type ] ) );
}
})
// create a dedicated logger for uncaught exceptions.
exceptionloggers = [
new winston.transports.Console( conf.get('log:stderr') )
];
// Set up an error domain for the logger
loggerdomain.on('error', function( err ){
process.stderr.write("problem writing to log %s\n %s", err.message, err.stack )
});
// run the loggers under a domain
loggerdomain.run( function(){
logger = new (winston.Logger)({
transports:loggers,
exceptionHandlers:exceptionloggers
addColors:true,
levels:levels,
colors:colors,
padLevels:true
});
});
// expose error and traceback helpers
logger.exception = winston.exception;
// export the logger instance.
module.exports = logger
This is a pretty short, but dense piece of code that does a couple of interesting things. The first is that it coerces the logger types into an array if it is not already. This allows us to specify and use more than one transport type. For example, if I wanted to use a file, syslog and sentry as my transports, I could do the following.
node app --logger=file --logger=syslog --logger=sentry
The most interesting bit is the catch block during the part that tries to require the transport:
catch( err ){
// allow ad-hoc log types
backendconf = conf.get( type );
if( backendconf && backendconf.module ){
backend = require( backendconf.module );
} else {
e = new Error();
e.name="InvalidLogType";
e.message = util.format( "unable to load logging module %s", type);
emitter.emit('error', e);
}
}
This allows a fully qualified path to a module to be passed, which would allow someone to add a logger on the fly with out having it live in the code base with a simple flag. For example if I wanted to use a syslog module I were working on / testing, I could use it like this:
node app --logger=syslog --syslog:module=/path/to/my/syslog
Transports
Winston's logging facility is transport ( plugin ) based. It can support any number of logging transports, which is an object that implements the winston log interface. In ot set up we want each of our transports to export a log class that we will instantiate later. Right now we have a stdout module stubbed out. This one is pretty easy, because winston ships with a stdout transport, So our module is really just a thin abstraction wrapper.
STDOUT Transport
var winston = require( 'winston' );
module.exports = winston.transports.Console;
Our default stdout transport looks something like this.
DailyFile Rotation Transport
Winston also ships with a handy file based transport that automatically rotates the file every day. We can easily expose that in a similar manner.
// project-log/transports/file.js
var winston = require( 'winston' );
module.exports = winston.transports.DailyRotateFile;
With this simple pattern, adding additional transport types is very straight forward and easy to do. Matched with the configuration system we have in place, it is also easy change how logs are collected at the drop of a hat.
Configuration
The last thing to take note of in our package is right after the try/catch block
loggers.push( new backend( log[ type ] ) );
If we have found a backend transport, we create a new one passing it whatever was in our configuration under the same name as the transport. So, if we are loading the stdout transport, it would be instantiated in the same manner as doing new stdout( conf.get('log:stdout') ). This allows us to override all configuration options for each of the winston transports we select.
node app --logger=stdout --log:stdout:colorize=true --log:stdout:timestamp=true --log:stdout:prettyPrint=true
This, of course, is a lot to type every time just to get some logging. The last thing we need to do is define some sane defaults for our stdout and file transports that we have defined. They are defined either as a node module or JSON file in the conf directory as we talked about previously.
// project-log/conf/index.js
var path = require( 'path' );
var util = require( 'util' );
module.exports = {
log:{
stdout:{
label: util.format( "project ( %s ) %s", os.hostname(), process.pid )
, prettyPrint:true
, colorize:true
, exitOnError:false
, timestamp:true
, level:"info"
}
,stderr:{
label: util.format( "project ( %s ) %s", os.hostname(), process.pid )
, prettyPrint:true
, colorize:true
, handleExceptions: true
, exitOnError:false
, timestamp:true
, level:"error"
, json:false
}
,file:{
label: util.format( "project ( %s ) %s", os.hostname(), process.pid )
, dir:"."
, filename: path.join( process.cwd(), 'project.log' )
, prettyPrint:false
, level:"http"
, json: false
, options:{
highWatermark:24
,flags:'a'
}
}
}
}
That is pretty much it. When how we log needs to change, it is a matter of adding a new transport type and/or changing some configuration options.