Winston Logging with Mongoose Docs

Question

I recently just switched over to Winston for logging and noticed an issue when logging mongoose docs after an exec.

Example:

Model.find().exec(function (err, docs) {
    console.log(docs) // Prints the collection fine
    winston.info(docs) // Prints a ton on mongoose stuff, related to the query
});

So basically how do I get winston logging to print the same way as you get from console.log? I'm guessing it must how it is being serialised before being logged by calling toJSON().

Do I have to manually call .toJSON() each time or have people done something else to make this work automatically?

Answer 1

Warning

I think the intended use of winston is to log string messages in first place and (if needed) additional meta information. Moreover, I do not quite get why you would like to log the whole collection returned from mongo and not - let say - just _ids (assuming docs may be pretty big).

Intro

I looked into winston source and here are relevant parts:

winston/logger.js

Logger.prototype.log = function (level) {
  var self = this,
      args = Array.prototype.slice.call(arguments, 1);

  ...

  var callback = typeof args[args.length - 1] === 'function' ? args.pop() : null,
      meta     = typeof args[args.length - 1] === 'object' ? args.pop() : {},
      msg      = util.format.apply(null, args);

  ...

}

Basically, single argument of type object is interpreted as the meta. Console transport layer (default) is mainly defined in winston/common.js and here is how meta is handled:

 ... if (Object.keys(meta).length > 0) {
      output += ' ' + (
        options.prettyPrint
          ? ('\n' + util.inspect(meta, false, null, options.colorize))
          : exports.serialize(meta)
      );
    }

serialize method iterates (recursively) over all keys of an object to form the final string (instead of calling .toString or similar).

Proposed Solutions

Both solutions force winston to interpret a single object argument not as meta but as the message string.

If you want to support different transport layers than they have to be modified.

Change winston source-code

Just fork the repo and make relevant changes to the source code. There is plenty of ways to accomplish it. One ugly could be:

 meta     = args.length === 1 ? {} :
          (typeof args[args.length - 1] === 'object' ? args.pop() : {}),

But much better would be to add special case in the .serialize method make special treatment if the object is mangoose model, very naive and incorrect:

 else if ('_doc' in obj && 'save' in obj){
        var result = [];
        msg += '{'
        for(var key in obj['_doc']){
            result.push (key + ':' + obj['_doc'][key]);
        }
        msg += result.join(', ');
        msg += '}';
    }

(Unfortunately there is a problem with this approach, as winston makes copy of the meta and all methods defined higher in prototypical chain are lost -- otherwise it would as easy as calling obj.toJSON and for sure it would be the most elegant and robust solution)

Override winston default behaviour

var original = winston.log;
winston.log = function(){
    if(arguments.length === 2){
        original.call(winston, arguments[0], arguments[1], {});
    }
    else {
        original.apply(winston, arguments);
    }
}

Explanation: arguments[0] defines level so arguments[1] is the actual object to be logged.

Answer 2

I've combined the ideas in the previous answers to provide a fairly robust method for logging out meta objects, which I've been running for many months in production without any issues.

The general idea is to override transport.log and convert the meta object to a JSON string, and back again. This ensures the meta object is preserved as an object, and hence take advantage of the winston goodies for meta objects, such as prettyPrint.

Here's the code for creating a new logger, with a prettyPrint option:

var transport = new (winston.transports.Console)({
  prettyPrint: function(meta) {
    return util.format('%j', meta);
  }
});

var originalLog = transport.log;
transport.log = function(level, msg, meta, callback) {
  if(meta) {
    if(meta instanceof Error) {
      // Errors cannot be stringified.
      meta = meta.toString();

    } else {
      // Keep meta as an object so that winston formats it
      // nicely, but ensure we don't have any weird ObjectIds
      meta = JSON.parse(JSON.stringify(meta));
    }
  }
  return originalLog.call(transport, level, msg, meta, callback);
};

var logger = new (winston.Logger)({
  transports: [transport]
});

You can now use the logger like so:

logger.debug('My Mongoose document:', doc);

Which will output something like:

debug: My Mongoose document: {"_id":"56f0598b130b3cfb16d76b3d","name":"Bob"}