Menu
Menu

Logging in Node.js done right

Sunday, February 19, 2017

Logging can be one of the most important things in your application. Managed and correct logging can help your discover any problem quickly whereas a not so proper logging can leave you finding a trivial problem for hours. Therefore one should setup proper logging in their application before building anything serious.

Setting up proper logging in Node.js applications can be bit overwhelming at first due to the plethora of modules available through NPM. But its all about diving and testing a few modules and then getting comfortable with the ones you like. Some of the popular modules for logging in Node.js are -

You might be wondering by now that why can't we simply use console.log() for logging, afterall its built in. While console.log() can be good for immediate debugging it shouldn't be used a logger at the application level. Few of the reasons are -

  • You can't switch off the logs. Once a log statement is encountered, it will always be printed.
  • You can't assign levels to logging. For example you might want certain kinds of logs only in development and not in production.

Feel free to add more to this list in the comments below.

Getting back to the modules mentioned above, all of these modules are capable of logging but some of them are specialised for certain use cases. For example the Debug module is mostly used while creating modules which will be used by others later. It provides the users a way to enable the logging in external modules by simply enabling the Debug logging of that external module they are using. Another specialised module is Morgan which is used mostly as a middleware for logging HTTP requests. The rest of them are used for application level logging.

Generally we need to use a combination of 2 or more modules to get a proper logging environment setup. In this post we'll be making use of Morgan and Winston for our logging needs. We'll be using express.js for our web server. Now I'll be assuming that you've setup a simple express server or any server for that matter so we can get down to logging. If you haven't setup a server, you can follow this small example to set it up.

Now we'll be installing the two modules we need -

npm install winston morgan --save

As I mentioned before Morgan is a HTTP request logging middlewear. It integrates very well with express.js. It is also important to know that Node.js provides us with two default write streams - stdout and stderr. These two different streams can be helpful when we want to log to two different destinations. In this setup we'll use this feature to separate our out and error logs.

So this is how my setup file (any file with express.js setup) looks -

index.js

const express = require ('express'),
    morgan = require('morgan');

const PORT = 3000;

const app = express();

app.use(morgan('dev', {
    skip: function (req, res) {
        return res.statusCode < 400
    }, stream: process.stderr
}));

app.use(morgan('dev', {
    skip: function (req, res) {
        return res.statusCode >= 400
    }, stream: process.stdout
}));

app.get('/', function (req, res) {
  res.send('Hello World!')
})

app.listen(PORT, function(){
    console.log('Example app listening on port ' + PORT);
});

Morgan's constructor is as following -

morgan(format, options)

In the format argument we've passed using the dev format which logs the following information -

:method :url :status :response-time ms - :res[content-length]

So if you just open your browser and go the address your server running on like localhost:3000 in this case, you'll see this log in your console -

GET / 200 0.235 ms - 12

Now getting to the important part. As it can be seen we've used Morgan as a middleware twice. The reason is that we're using morgan to separate our logs to two different write streams based on the status code. Morgan provises the ability to skip logs using a skip function passed in the options argument. Using that we log the requests with statusCode < 400 to the stdout and requests with statusCode >= 400 to the stderr. This can be extremely helpful when we run our Node.js service using a tool like PM2. PM2 by default creates separate log files for our stdout and stderr streams. By using Morgan this way we have ensured that all out failed requests will be in a separate file and all the successful requests will a be in another file. Now whenever we want to check for failed requests on our server, we can simply go and view the specific file for it without having to go through the other irrelevant logs.

Note - Morgan provides many more formats for logging. Don't use dev format in production environments.

Now shifting our focus to Winston module. Winston is a multi-transport async logging library for Node.js. It is a very powerful tool with lots of features. It provides the following default log levels -

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

Whenever we use Winston, we can define a certain log level which determines what level of logs will be generated. Suppose I set the level to info then only error, warn and info logs will be printed. verbose logs and levels below it will not be printed. You'll understand this better when we use our code below.

We are only gonna be setting up a very basic logger with Winston which will allow us to set log level according to the environment and also print the timestamp for every log. We'll create a new file called logger.js which will act as our internal module.

logger.js

const winston = require("winston");

const level = process.env.LOG_LEVEL || 'debug';

const logger = new winston.Logger({
    transports: [
        new winston.transports.Console({
            level: level,
            timestamp: function () {
                return (new Date()).toISOString();
            }
        })
    ]
});

module.exports = logger

Winston allows us to use multiple transports and of different output types. We'll just be using a single transport which will write logs to our console. The important thing to note is how we've set the logging level. We take the logging level from the environment variable LOG_LEVEL. If the level is not passed explicitly then the default level is made debug meaning that all levels above debug including debug itself would be logged. Another thing we've added to our transport is the timestamp function which will print the timestamp along with every log entry it creates which can be very helpful while reading our logs.

Now that we've created the logger module, its time to use it in our code. This is how our index.js looks like finally -

index.js

const express = require ('express'),
    morgan = require('morgan'),
    logger = require('./logger');


const PORT = 3000;

const app = express();

app.use(morgan('dev', {
    skip: function (req, res) {
        return res.statusCode < 400
    }, stream: process.stderr
}));

app.use(morgan('dev', {
    skip: function (req, res) {
        return res.statusCode >= 400
    }, stream: process.stdout
}));

app.get('/', function (req, res) {
    logger.debug('Debug statement');
    logger.info('Info statement');
    res.send('Hello World!');
});

app.use(function(req, res, next){
    logger.error('404 page requested');
    res.status(404).send('This page does not exist!');
});

app.listen(PORT, function(){
    logger.info('Example app listening on port ' + PORT);
});

In our GET / API we're logging two statements with different log levels. Now If I simply run the server using the node index.js command and call this route then the output on our console would be like this -

2017-02-19T07:43:26.638Z - debug: Debug statement
2017-02-19T07:43:26.639Z - info: Info statement

But suppose I want to run this code in production environment then I'll simply pass the LOG_LEVEL environment variable to the server so that debug logs are not printed. The command would be as following - LOG_LEVEL=info node index.js . Now upon calling the the same route again, we'll see this output on our console -

2017-02-19T07:45:49.472Z - info: Info statement

Notice that the only the info level log was logged and the debug level was not logged. This is just an example to explain you how useful log levels can be when developing between different environments. You are free to experiment and use the log levels any way possible which best suits your needs. You can even create custom log levels with Winston. It is also important to mention that Winston too will write the error level logs to the stderr and the info level logs to stdout. This way Winston works well with Morgan as all our error and out logs would be in separate files.

Conclusion -

In this post we saw how we can use the Winston and Morgan modules to make logging in Node.js easy and properly managed. This is a very basic but powerful logging setup we've discussed. Feel free to add more tips in the comments.