Node.js Error Management and Logging
- Part 1 - Debugging Node.js
- Part 2 - Node.js Error Management and Logging
Hello, that's the new article for I Have Control series.
Before this one, I wrote about Node.js Debugging and now in this part, we're going to dive into the essential logging.
Logging is much more important within node.js, because logging is crucial for the one of node's main goals: scaling
Let's think this way: Before we've got Monolithic architechtured applications and they are relatively easier to manage. Application runs on a single machine, even on some cases on same machine with the DB. So writing and reading logs was easy as just couple of files or DB tables.
But with the coming use of microservices, wide acceptance of multi-tier architechtures, scaling etc., logging became a thorny field.
Clustering on multiple machines, or even on same machine with docker containers, multiple DB's like redis, mongodb, hadoop and instances of them and many more new technologies forces us to leave our safe and warm monolithic environment to this caotic one and this leads us to create radical solutions.
Before going that far, we need to act in an order. First things first: healty log management on node.js.
There are different ways to achieve this on node, though there are mandotary steps to do like levels on log messages, like catching unhandled exceptions and managing them.
My first recommendation is Winston and strange the name comes from this :/. By the way winston does async logging.
Winston
Setup:
1npm install winston --save
2npm install winston-redis --save
Levels
Levels orders from most important to least: error: 0, warn: 1, info: 2, verbose: 3, debug: 4, silly: 5
Usage:
1// default logger
2var winston = require('winston');
3
4// these are the same
5winston.log('info', 'Hello distributed log files!');
6winston.info('Hello again distributed logs');
Transports
The default logger's has a default transport type of winston.transports.Console, automatically outputs to console.
1winston.remove(winston.transports.Console);
2winston.info('This goes to nowhere!');
3
4winston.add(winston.transports.File, { filename: 'mylogfile.log' });
5winston.info('To the file!');
6
7winston.add(winston.transports.Console);
8winston.info('Both to file and console');
Winston have a lot of official transports like HTTP, redis, mongo etc. Also 3rd party options are exist.
Metadata
You can add various data to logs:
1winston.log('info', 'test mesajı', { bilgi: 'bu bir metadatadır' });
Interpolation
Helps to write parametrized logs. Parameter types are: %s string, %d number, %j json
1var util = require('util');
2
3winston.log('info', 'test message %s %d %j', 'first', 5, {number: 123}, {meta: "this is meta" }, function callback(transport, level, msg, meta){
4 console.log("logged");
5 console.log(util.format("transport -> %s, level -> %s, message -> %s, meta -> %j", transport, level, msg, meta));
6});
Exceptions
1winston.handleExceptions();
2
3// you can write unhandled exceptions to a special file if you want
4winston.handleExceptions(new winston.transports.File({ filename: 'path/to/exceptions.log' }))
5
6// or you can specify handleExceptions option while adding a transport
7// humanReadableUnhandledException means it outputs readable stack trace
8winston.add(winston.transports.File, {
9 filename: 'path/to/all-logs.log',
10 handleExceptions: true,
11 level: 'warn',
12 humanReadableUnhandledException: true
13});
14
15// prevent exiting from application after exception occurred:
16winston.exitOnError = false;
On above code, transport level specified as warn. This means warn and above it (important level) will ve logs which are warn, debug and error. Less important levels will not be logged: silly and verbose.
Demo
I'm determined to continue with our beloved repository chatcat :). Spoiler lovers can get codes of this chapter with:
1git clone https://github.com/dhalsim/chatcat.git
2cd chatchat
3git checkout alti
or you can go with the tutorial by git checkout bes and do the necessary changes yourself.
Note: I'm gonna use new advanced options and topics: colorize, zipping for File, tailing ve logging to Redis DB
src/lib/logging.js:
1var winston = require('winston');
2var moment = require('moment');
3var redis_config = require('src/config').redis;
4var extend = require('src/lib/utils').extend;
5require('winston-redis').Redis;
6
7var redisClient = require('src/lib/redisAdapters/redisConnection').getClient();
8var os = require('os');
9
10var errorMeta = {
11 hostname: os.hostname(),
12 pid: process.pid,
13 memory: process.memoryUsage(),
14 uptime: process.uptime(),
15 env: process.env.NODE_ENV || 'development'
16};
17
18var redisTransport = new (winston.transports.Redis)({
19 redis: redisClient
20});
21
22var errorFileTransport = new (winston.transports.File)({
23 filename: './logs/errors.log',
24 level: 'error',
25 colorize: true,
26 timestamp: function() {
27 return moment.utc().format();
28 },
29 maxsize: 10000, // 10 KB
30 maxFiles: 5,
31 //formatter: function () {},
32 tailable: true,
33 zippedArchive: true
34});
35
36// error: 0, warn: 1, info: 2, verbose: 3, debug: 4, silly: 5
37
38var logger = new (winston.Logger)({
39 transports: [
40 new (winston.transports.Console)({
41 level: 'debug',
42 colorize: true,
43 timestamp: function() {
44 return moment.utc().format();
45 },
46 json: true,
47 prettyPrint: true,
48 humanReadableUnhandledException: true,
49 }),
50 errorFileTransport,
51 redisTransport
52 ]
53});
54
55// I override logger function
56// in case of error I'll inject errorMeta to meta
57logger.log = function(){
58 var args = arguments;
59 var level = args[0];
60
61 if(level === 'error') {
62 var originalMeta = args[2] || {};
63 args[2] = extend(originalMeta, errorMeta);
64 }
65
66 winston.Logger.prototype.log.apply(this,args);
67};
68
69// logger hatası
70logger.on('error', function (err) {
71 console.error('Error occurred', err);
72});
73
74module.exports.log = logger;
75module.exports.loggerMiddleware = function (req, res, next) {
76 req.logger = logger;
77 next();
78};
79module.exports.exceptionMiddleware = function (err, req, res, next) {
80 logger.error(err.message, { stack: err.stack });
81 next(err);
82};
83module.exports.logAndCrash = function (err) {
84 logger.error(err.message, { stack: err.stack });
85 throw err;
86}
There are 3 exported functions here. logger is for general purpose in case of I need. I'll use loggerMiddleware in express and use it to add logger to req object. exceptionMiddleware is for exception management. This middleware will work when next(error) called.
logAndCrash function is a special one for using from process.uncaughtException. As you noticed, I re-throw the exception caught and this leads node process to exit. I'll be back on this later.
In case of an error, by overriding log function of logger, I add errorMeta as a useful meta.
Console transport for general purpose and File and Redis transports for error cases used. You can see a list called winston after log occurs on redis.
Now we will change a function in redisAdapter. If it couldn't find the wanted room, we will throw an Error object.
Note: Use promises to get asynchronous errors easily.
redisAdapter.js:
1...
2module.exports.getRoomById = function (roomId) {
3 var key = ROOMS + ':' + roomId;
4 return hgetall(key).then(function (room) {
5 if(!room) {
6 throw new Error('Room id not found:' + roomId);
7 }
8
9 return unflatten(room);
10 });
11};
12...
Here we catch exceptions with catch (clearly!) and send it to exception handler middleware with next(..).
routes/index.js:
1...
2router.get('/room/:id', securePage, function (req, res, next) {
3 var roomId = req.params.id;
4 roomAdapter.getRoomById(roomId).then(function (room) {
5 req.session.room = room;
6
7 res.render('room', {
8 user: JSON.stringify(req.user),
9 room: JSON.stringify(room),
10 socket_host: config.socket_host
11 });
12 }).catch(function (err) {
13 next(err);
14 }).done();
15});
16...
From express documentation: "If the current middleware does not end the request-response cycle, it must call next() to pass control to the next middleware, otherwise the request will be left hanging."
app.js:
1...
2var logger = require('src/lib/logging');
3...
4app.use(logger.loggerMiddleware);
5app.use(logger.exceptionMiddleware);
6process.on('uncaughtException', logger.logAndCrash);
7...
Let's look at logAndCrash now. We talked about node.js single threaded logic before. And with its async structure, it differs from languages/platforms like ASP.NET or Java as we can redirect a user to an error page in case of an error (like used with Application_Error on ASP.NET). We need to exit from node when we have an unhandled exception.
The best option to take is unfortunately let the program crash. On web applications like ASP.NET, every request works on a seperate thread thus lets rest of the process go on without restarting. But it's not the case with node.js
For this and other reasons (unhandled errors may broke reliability of the app), we let process to exit. To restart the application afterwards we can use solutions like Forever and PM2.
Sources:
Result
We proceed pretty much on error management and logging. Next article will be about logging in scaled systems. I'll write about how we log and gather these scaled node.js applications.
- Part 1 - Debugging Node.js
- Part 2 - Node.js Error Management and Logging