timestamps disappear when adding the line number configuration in node.js winston for logging

Question

I am using winston to make a self logger, which allow me to add the timestamps and line number in the logging. The code can accomplish the functionality each, but when combined, they don't work as expected.

// **help to add timestamp**
var logger = new (winston.Logger)({
  transports : [new (winston.transports.Console)({
    json : false,
    timestamp : true,
    colorize: true
  }), new winston.transports.File({
    filename : __dirname + '/debug.log',
    json : true
  })]
  ,exitOnError : false
});

// **help me to add line number**
var logger_info_old = winston.info;
logger.info = function(msg) {
    var fileAndLine = traceCaller(1);
    return logger_info_old.call(this, fileAndLine + ":" + msg);
}

However, when line number configuration is added, timestamp for the logging will disappear.

For example, before adding the line number configuration.

logger.info("abc");
2013-11-24T09:49:15.914Z - info:339:abc

when adding the line number configuration

logger.info("abc");
info: (H:\Dropbox\node\fablab\utils\logging.js:85:abc

The optimal result i want is like

logger.info("abc");
2013-11-24T09:49:15.914Z - info: (H:\Dropbox\node\fablab\app.js:339:abc

Can I fix this?

score 3 · Accepted Answer · edited May 23 '17 at 11:54

3

I got this to work and this is how I did it.

var transports = [
  new(winston.transports.Console)({
    colorize: true,
    prettyPrint: true,
    timestamp : true,
    level: 'debug',
  })
];

var log = new(winston.Logger)({
  "transports": transports
});

for (var func in winston.levels) {
  var oldFunc = log[func];

  log[func] = function() {
    var args = Array.prototype.slice.call(arguments);
    args.unshift(traceCaller(1));
    oldFunc.apply(log, args);
  }
}

With that I got both the timestamp and the file. (note traceCaller(1) is from this stackoverflow question: I want to display the file Name in the log statement). I did the for loop over the winston.levels so I would pickup all the functions not just info.

The reason yours didn't work was your logger_info_old was from winston and not from logger. So

var logger_info_old = winston.info;

should have been

var logger_info_old = logger.info;

edited May 23 '17 at 11:54

Community

1
1

answered Dec 06 '13 at 19:18

Jeff Whiting

432
4
5

Just did a benchmark. Be warned that adding the stack trace is much, much slower. Doing 10,000 logs the time went from 71ms with no file and line number to 4666ms. That is 65 times slower. traceCaller maybe inefficient but I'm guessing that most of the time is actually taken in generating the stack trace: (new Error).stack – Jeff Whiting Dec 06 '13 at 19:22
agree, traceCaller is inefficient, but it will be used for debug, so that is ok. Thanks a lot , jeff – user824624 Dec 06 '13 at 20:20
There should be a closure to capture `oldFunc`, otherwise all log func will be replaced by the last one (`error()` in default settings). Also, why are you using `winston.levels` instead of `logger.levels`? – leesei Sep 12 '14 at 18:00

leesei · Answer 2 · 2016-12-19T17:49:00.000

I updated @jeff-whiting's answer (use closure and fix for string interpolation) and make it a single function.
Pass an existing logger to add callsite info to its level functions.
Note logger.log() is not changed, only logger.{level}() are changed.

// add callsite info to winston logger instance
function addCallSite(logger) {
  // WARNING: traceCaller is slow
  // http://stackoverflow.com/a/20431861/665507
  // http://stackoverflow.com/a/13411499/665507
  /**
  * examines the call stack and returns a string indicating
  * the file and line number of the n'th previous ancestor call.
  * this works in chrome, and should work in nodejs as well.
  *
  * @param n : int (default: n=1) - the number of calls to trace up the
  *   stack from the current call.  `n=0` gives you your current file/line.
  *  `n=1` gives the file/line that called you.
  */
  function traceCaller(n) {
    if( isNaN(n) || n<0) n=1;
    n+=1;
    var s = (new Error()).stack
      , a=s.indexOf('\n',5);
    while(n--) {
      a=s.indexOf('\n',a+1);
      if( a<0 ) { a=s.lastIndexOf('\n',s.length); break;}
    }
    b=s.indexOf('\n',a+1); if( b<0 ) b=s.length;
    a=Math.max(s.lastIndexOf(' ',b), s.lastIndexOf('/',b));
    b=s.lastIndexOf(':',b);
    s=s.substring(a+1,b);
    return s;
  }

  // assign to `logger.{level}()`
  for (var func in logger.levels) {
    (function (oldFunc) {
      logger[func] = function() {
        var args = Array.prototype.slice.call(arguments);
        if (typeof args[0] === 'string') {
          args[0] = traceCaller(1) + ' ' + args[0];
        }
        else {
          args.unshift(traceCaller(1));
        }
        oldFunc.apply(logger, args);
      };
    })(logger[func]);
  };
}

timestamps disappear when adding the line number configuration in node.js winston for logging

2 Answers2

Linked