Logging in Node.js
Once you start developing on Node.js, you'll very soon find out the need for logging. It of course has nothing to do with JavaScript or specifically Node.js, but rather with the need to log activities on production environment, and even on development one for that matter.
console.log
The most rudimentary type of logging you could do is using console.log and console.error methods. This is better than nothing, but hardly the best solution. Basically they work exactly as they do, when you used them in browsers. However since we're in the server dominion now, an interesting aspect is revealed. That is, the console functions are synchronous, when the destination is a terminal or a file (to avoid lost messages in case of premature exit) and asynchronous when it’s a pipe (to avoid blocking for long periods of time). It is fully manual and you'll have to come up with your own format and basically manage everything yourself.
Bunyan
Bunyan library makes its mission to provide structured, machine readable logs as first class citizens. As a result, a log record from Bunyan is one line of JSON.stringify output with some common names for the requisite and common fields for a log record. Use npm manager to install the package. If you're not familiar with the tool, please read the JavaScript Developer Toolkit article first.
npm install bunyan
Winston
Winston 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 winston 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. To install the library:
npm install winston
Integration
Integrating both libraries is as easy as requiring the modules and using info/error methods just as in console object:
var logger = require('winston');
logger.info('test');
logger = require('bunyan').createLogger({name: 'myapp'});
logger.info('test');
The difference between the libraries can be spotted from the first look at the console output. Bunyan serializes everything using JSON format, whereas Winston uses a readable text format.
info: test
{"name":"myapp","hostname":"CWLP-67","pid":3820,"level":30,"msg":"test",
"time":"2014-08-23T11:11:45.249Z","v":0}
Output destination
But what really makes the Winston shine is the diversity of supported transports, which especially kick in, when your application reaches production environment. Cause you agree that saving logs into terminal is not very useful, when you don't have access to the server or better yet a cluster. What you can do with transports is route your logs to MongoDB for instance or cloud-based service like Loggly. You can read more about the supported transports on the Winston's site. Bunyan also supports different transports, but much more modest. Read about it here.
Session logging
But even this appears to be not sufficient, if you want to take a full advantage out of your logs using analytics and mining. Consider the following Express example. It simulates some error happening after an asynchronous call is completed, just like your service or database request:
(function () {
'use strict';
var express = require('express'), app = express(), i = 0,
init = function init() {
app.get('/', function (req, res) {
var logger = require('winston');
logger.info(new Date() + ' call number: ' + (i++));
// do some logic
logger.info(new Date() + ' another log');
setTimeout(function () {
if (Math.random() > 0.2) {
logger.error(new Date() +
' something bad happened');
}
}, Math.round(Math.random() * 10000));
res.end();
});
app.listen('3000', '127.0.0.1');
};
init();
}());
Now, try accessing http://localhost:3000 for several times and observe the logs. While they are in place, there is no way of knowing to which call the errors relate:
info: Sat Aug 10 2014 11:33:11 call number: 0 info: Sat Aug 10 2014 11:33:11 another log info: Sat Aug 10 2014 11:33:12 call number: 1 info: Sat Aug 10 2014 11:33:12 another log info: Sat Aug 10 2014 11:33:12 call number: 2 info: Sat Aug 10 2014 11:33:12 another log error: Sat Aug 10 2014 11:33:16 something bad happened error: Sat Aug 10 2014 11:33:20 something bad happenedYou may add some identifier to each log call, but this way is treacherous and when, not if, someone forgets to add the token, you will face the wrath of maintenance God.
To tackle the issue, I've written a wrapper, which works both with Winston and Bunyan and adds the support for session logging. You can find it on GitHub and can use it however you like.
(function () {
'use strict';
var express = require('express'), app = express(),
nconf = require('nconf'), winston = require('winston'),
i = 0, LogManager = require("./common/LogManager.js"),
init = function init() {
var path = require('path');
nconf.file({
file : path.resolve(__dirname, 'config.json')
});
LogManager.init(nconf.get("logger"), {
transports: [
new (winston.transports.File)({
filename: 'common.log'
})
]
});
app.get('/', function (req, res) {
var logger = LogManager.getInstance(), delta;
logger.info('call number: ' + (i++));
// do some logic
logger.info('another log');
delta = logger.start('some async method');
setTimeout(function () {
logger.end(delta);
if (Math.random() > 0.2) {
logger.error('something bad happened');
}
}, Math.round(Math.random() * 10000));
res.end();
});
app.listen('3000', '127.0.0.1');
};
init();
}());
Observe the changes. Firstly we configure our LogManager object using nconf to load the configurations from json file. Then we configure it with another transport to output the logs into file. Lastly we create new instance of logger, using getInstance static method, on each GET request to track our requests. The result can be seen below - here the error from 10:25:54.188 can be clearly tracked to request 2, since they share the same token, b9188f46-0def-4c11-ae97-509e6d84bfaa.
info: d=6abb5532-acf5-4575-8ffb-ff1da549fd74, t=10:25:46.636, i=call number: 0
info: d=6abb5532-acf5-4575-8ffb-ff1da549fd74, t=10:25:46.639, i=another log
info: d=2e6d7bf6-8bdc-4b1a-8bee-9bb1eb17a30d, t=10:25:47.086, i=call number: 1
info: d=2e6d7bf6-8bdc-4b1a-8bee-9bb1eb17a30d, t=10:25:47.086, i=another log
info: d=b9188f46-0def-4c11-ae97-509e6d84bfaa, t=10:25:47.630, i=call number: 2
info: d=b9188f46-0def-4c11-ae97-509e6d84bfaa, t=10:25:47.630, i=another log
error: d=2e6d7bf6-8bdc-4b1a-8bee-9bb1eb17a30d, t=10:25:53.392, e=something bad>
happened, s=Error
info: d=2e6d7bf6-8bdc-4b1a-8bee-9bb1eb17a30d, t=10:25:53.392, i=delta of (some
async method): 6306 ms
at LogManager.info [as error] (C:\GitHub\LogManager\common\LogManager.js:53:68)
at null._onTimeout (C:\GitHub\LogManager\server.js:29:32)
at Timer.listOnTimeout [as ontimeout] (timers.js:110:15)
info: d=b9188f46-0def-4c11-ae97-509e6d84bfaa, t=10:25:54.188, i=delta of (some
async method): 6558 ms
error: d=b9188f46-0def-4c11-ae97-509e6d84bfaa, t=10:25:54.188, e=something bad
happened, s=Error
at LogManager.info [as error] (C:\GitHub\LogManager\common\LogManager.js:53:68)
at null._onTimeout (C:\GitHub\LogManager\server.js:29:32)
at Timer.listOnTimeout [as ontimeout] (timers.js:110:15)
info: d=6abb5532-acf5-4575-8ffb-ff1da549fd74, t=10:25:55.546, i=delta of (some
async method): 8906 ms
I've mentioned already that the library supports both Winston and Bunyan libraries. We do this using the configuration file, config.json, we pass to the logger. We can set here to use either Winston or Bunyan.
{
"logger": {
"IS_WINSTON": true,
"IS_BUNYAN": false,
"LOG_NAME": "myLog",
"LONG_STACK": false,
"STACK_LEVEL": 5
}
}
Stack Trace
One last thing, I promise :) You see how our error stack trace is appended into log. This happens because we specifically put it there using Error.stack. However what if we wanted to get the whole stack and not just last few calls. To do this you need to set LONG_STACK flag to true and specify the wanted STACK_LEVEL. The feature is implemented using longjohn library and produces much more elaborate log like this:
info: d=a6786546-2381-41a7-823c-f6ebafea0d06, t=10:50:38.119, i=call number: 0
info: d=a6786546-2381-41a7-823c-f6ebafea0d06, t=10:50:38.124, i=another log
info: d=a6786546-2381-41a7-823c-f6ebafea0d06, t=10:50:39.388, i=delta of (some
async method): 1264 ms
error: d=a6786546-2381-41a7-823c-f6ebafea0d06, t=10:50:39.388, e=something bad
happened, s=Error
at info (C:\GitHub\LogManager\common\LogManager.js:53:68)
at [object Object]. (C:\GitHub\LogManager\server.js:29:32)
at listOnTimeout (timers.js:110:15)
---------------------------------------------
at C:\GitHub\LogManager\server.js:26:17
at handle (C:\GitHub\LogManager\node_modules\express\lib\router\layer.js:76:5)
at next (C:\GitHub\LogManager\node_modules\express\lib\router\route.js:100:13)
at Route.dispatch (C:\GitHub\LogManager\node_modules\express\lib\
router\route.js:81:3)
at handle (C:\GitHub\LogManager\node_modules\express\lib\router\layer.js:76:5)
at C:\GitHub\LogManager\node_modules\express\lib\router\index.js:227:24
at proto.process_params (C:\GitHub\LogManager\node_modules\express\lib\
router\index.js:305:12)
at C:\GitHub\LogManager\node_modules\express\lib\router\index.js:221:12
---------------------------------------------
at new Server (http.js:1869:10)
at exports.createServer (http.js:1899:10)
at app.listen (C:\GitHub\LogManager\node_modules\express\lib\
application.js:545:21)
at init (C:\GitHub\LogManager\server.js:35:17)
at C:\GitHub\LogManager\server.js:37:5
at Object. (C:\GitHub\LogManager\server.js:38:2)
at Module._compile (module.js:456:26)
at Module._extensions..js (module.js:474:10)
Hope you find the library useful and be glad for any contribution.
Comments
Post a Comment