Logging in a Node.js Express app with Morgan and Bunyan

I recently had to add logging to an Express app. I was going to go with console.log that was until I did some research.

So why not use console.log, console.error or console.warn:

• 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.
• These functions are synchronous when the destination is a terminal or a file, so they are not suitable for production, unless you pipe the output to another program.

So I had to find an alternative. I came across Morgan, Bunyan and Winston and I eventually decided to go with Morgan and Bunyan.

The base app for this tutorial is available here: https://github.com/tobydigz/node_js_logging_example/tree/4e8e77191818802d5c95769045d0d530587c7dd1. It’s a basic Express app with two endpoints. The first endpoint is a GET endpoint/healthand it isn’t going to be logged. The second is a POST endpoint /stuff. It accepts the POST body:

{
 "firstname":"tobi",
 "lastname":"allen"
}

And gives the response:

{
    "fullname": "tobi allen"
}

The first step was to add a request id to the request object. I did this to facilitating tying different log entries to each other. So a Request log and its associated Response log would have the same id. You can install it by running npm install express-request-id. Then in the file app.js, add these two lines

const addRequestId = require('express-request-id')();
app.use(addRequestId);

The request id is added to the req object and can be retrieved by calling req.id.

We’ll be adding the loggers as middleware. The positioning of the functions matter. Remember that in the base app, there are two endpoints /health and /stuff. We only want to log requests on /stuff so the placement of the middleware comes after /health.

MORGAN

The next step is to add the library Morgan. Install it by running npm install morgan. We’ll need Morgan to know of the request id we added to the request body in the last step. So in the file app.js.

const morgan = require('morgan');
morgan.token('id', function getId(req) {
    return req.id
});

Then we specify a logger format.

var loggerFormat = ':id [:date[web]]" :method :url" :status :responsetime';

Then we define streams for Morgan while placing it on our middleware. This logs to stderr for status codes greater than 400 and stdout for status codes less than 400.

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

The file app.js looks like this now:

BUNYAN

The second logging library is Bunyan. Bunyan uses the concept of “serializer” functions to produce a JSON-able object from a JavaScript object. We are going to be using a custom serializer for the req object. You can install it by running npm install bunyan bunyan-express-serializer.

We need the custom serializer to handle the differences between the Node core req object (http.IncomingMessage) and the Express req object. Specifically, to log req.originalUrl.

We create a new file named logger.js and instantiate the logger.

var bunyan = require('bunyan')
exports.loggerInstance = bunyan.createLogger({
    name: 'transaction-notifier',
    serializers: {
        req: require('bunyan-express-serializer'),
        res: bunyan.stdSerializers.res,
        err: bunyan.stdSerializers.err
    },
    level: 'info'
});

Bunyan intentionally forgoes logging the body of requests and responses. If you want to add this and other fields to the logs, you can do so with the use of a child logger. We’ll be using this to add the fields ‘id’, ‘body’ and ‘statusCode’ to a custom log.

In the same file logger.js

exports.logResponse = function (id, body, statusCode) {
    var log = this.loggerInstance.child({
        id: id,
        body: body,
        statusCode: statusCode
    }, true)
    log.info('response')
}

The logger.js file now looks like

We now add the bunyan logger to our middleware

In app.js we first require the logger module

const logger = require('./logger');

We then add logger for requests and use the concept of a child logger to log the request id and body

app.use(function (req, res, next){
    var log = logger.loggerInstance.child({
        id: req.id,
        body: req.body
    }, true)
    log.info({req: req})
    next();
});

We also add a logger for responses. We need the log to happen after a response has been sent, like an ‘after’ hook

app.use(function (req, res, next) {
    function afterResponse() {
        res.removeListener('finish', afterResponse);
        res.removeListener('close', afterResponse);
        var log = logger.loggerInstance.child({
            id: req.id
        }, true)
        log.info({res:res}, 'response')
    }
    res.on('finish', afterResponse);
    res.on('close', afterResponse);
    next();
});

We also log the endpoint

app.post("/stuff", function (req, res) {
    var response = {
        fullname: `${req.body.firstname} ${req.body.lastname}`
    }
    logger.logResponse(req.id, response, 200);
    res.status(200).send(response);
});

The app.js files looks like this at this point

Bunyan also supports Streams. A stream is basically a definition of where the log output should go. We define two streams here stdout and an external file. In the logger.js file we update the loggerInstance variable

exports.loggerInstance = bunyan.createLogger({
    name: 'transaction-notifier',
    serializers: {
        req: require('bunyan-express-serializer'),
        res: bunyan.stdSerializers.res,
        err: bunyan.stdSerializers.err
    },
    level: 'info',
    streams: [
        {
            path: './foo.log'
        },
        {
            stream: process.stdout
        }
    ]
});

The final result can be found here https://github.com/tobydigz/node_js_logging_example