How to log request & transaction id in each log line using winston for Node JS?

Question

I have built a Node JS REST service using Express. Every request which lands on this service has headers like 'X-org-ReqId' & 'X-org-Tid' which I need to log in all the log lines which are written during execution of this request. Basically I need to log some contextual information with each log line to help me do transaction/request tracing through multiple services.

I am using winston logger initialized like this:

var winston = require('winston');
var appLogger = new(winston.Logger)({
  transports: [
    new(winston.transports.Console)({
        level: 'info', //TODO: Should be changed to Error in prod
        colorize: true
    }),
    new(winston.transports.DailyRotateFile)({
        filename: '/var/log/org/my-service.log',
        datePattern: '.yyyy-MM-dd',
        tailable: true,
        // handleExceptions: true,
        json: true,
        logstash: true
    })
  ],
  exitOnError: false
});

appLogger.on('error', function(err) {
  console.error("Logger in error", err);
});

module.exports.logger = function() {
  return appLogger;
};

and in individual classes wherever I want to use it, I do like this:

var logger = require('../config/logger').logger();

myObject.on("error", function (err) {
                logger.error("Error connecting bucket=" + bucketId , err);
});

This will produce log like this:

{"level":"info","message":"Error connecting bucket=2.....","timestamp":"2015-06-10T06:44:48.690Z"}

Winston by default add timestamp to this log statement but I also want to log things like req.headers['X-org-ReqId'] & req.headers['X-org-Tid'] so that I know which transaction was failed and what was the error.

I want log like this:

{"level":"info","message":"Error connecting bucket=2....","timestamp":"2015-06-10T06:44:48.690Z", "tid":"a3e8b380-1caf-11e5-9a21-1697f925ec7b", "reqid":"aad28806-1caf-11e5-9a21-1697f925ec7b"}

In java world we used to have NDC, is there an equivalent in Node JS world?

Answer 1

I encountered the same issue as you. It may not be the best way of doing things because you have to propagate the 'req' object but it works.

I am willing to get any improvement :)

Frist I overwrite winston logging methods in my 'log.js' :

// MyLogger definition
function MyLogger() {
    this.__proto__.__proto__.constructor.apply(this, arguments);
}

// Inheritance
MyLogger.prototype.__proto__ = winston.Logger.prototype;

// Overwriting methods
MyLogger.prototype.log = function() {
    var args = [];
    // Copying arguments not to modify them
    for (var i = 0; i < arguments.length; i++) {
        args[i] = arguments[i];
    }

    // Adding information in logs
    var lastArg = args[arguments.length - 1];
    if (typeof lastArg === 'object'
        && lastArg.headers) {
        args[arguments.length - 1] = {
            // Liste des infos ajoutées dans les logs
            requestId: lastArg.headers['x-request-id'] ? lastArg.headers['x-request-id'] : arguments[arguments.length - 1].id,
            host: arguments[arguments.length - 1].headers.host,
            pId: process.pid
        };
    }

    // Calling super
    this.__proto__.__proto__.log.apply(this, args);
}

MyLogger.prototype.error = function() {
    var args = ["error"];
    for (var i = 0; i < arguments.length; i++) {
        args[i + 1] = arguments[i];
    }
    this.__proto__.log.apply(this, args);
}
MyLogger.prototype.warn = function() {
    var args = ["warn"];
    for (var i = 0; i < arguments.length; i++) {
        args[i + 1] = arguments[i];
    }
    this.__proto__.log.apply(this, args);
}
MyLogger.prototype.info = function() {
    var args = ["info"];
    for (var i = 0; i < arguments.length; i++) {
        args[i + 1] = arguments[i];
    }
    this.__proto__.log.apply(this, args);
}
MyLogger.prototype.verbose = function() {
    var args = ["verbose"];
    for (var i = 0; i < arguments.length; i++) {
        args[i + 1] = arguments[i];
    }
    this.__proto__.log.apply(this, args);
}
MyLogger.prototype.debug = function() {
    var args = ["debug"];
    for (var i = 0; i < arguments.length; i++) {
        args[i + 1] = arguments[i];
    }
    this.__proto__.log.apply(this, args);
}
MyLogger.prototype.silly = function() {
    var args = ["silly"];
    for (var i = 0; i < arguments.length; i++) {
        args[i + 1] = arguments[i];
    }
    this.__proto__.log.apply(this, args);
}

var logger = new MyLogger({
    transports: [
        new winston.transports.File({
            level: config.LOG_LEVEL,
            filename: config.LOG_FILE,
            handleExceptions: true,
            json: true,
            maxsize: 5242880, //5MB
            maxFiles: 5,
            colorize: false
        }),
        new winston.transports.Console({
            level: config.LOG_LEVEL,
            handleExceptions: true,
            json: false,
            colorize: true
        })
    ],
     exitOnError: false
});

module.exports                  = logger;

Then in every module that needs logging :

var logger          = require("../log.js");

...

logger.debug("My message", req);

Produces a log in console and a JSON log in log file with every information neede to to follow a stream.

My next step would be not to have to propagate 'req' and getting the needed infos from a context or a session.

Hope that helped :)

Answer 2

my 2 cent idea,

Use logFormatter from winston to add more fields to each logs:-

One example below:

const { format} = require("winston");
var reqId = '123123' //function or const request id
const addRequestId = format((info, opts) => {
    if(reqId)
        info.reqId= reqId;
    return info;
});

Then add below config while creating logger

var config = {
format: format.combine(
  addRequestId(),
  format.timestamp(new Date().toISOString()),
  format.json(),
),
transports: [new transports.Console()],
level: 'debug'
 }
const logger = createLogger(config);