Don't swallow Error message/stack when using formatter (#1188)

* Don't swallow Error message/stack when using formatter

Fixes #1178

When we use a formatter and pass an `Error` object in as `meta`,
we end up removing the Error's message and stack information when
`decycle`ing it. `clone` checks if the passed-in object is an `Error`
and does not `decycle` it in that case, but when we use a formatter,
this check does not happen because we `clone` the whole `options` object
instead of just cloning `options.meta`.

By `clone`ing `meta` alone when it is an Error,
the `instanceof Error` check will catch it and copy `message` and `stack`
into a new, non-Error object. So when that's buried in `options.meta`,
re-`clone`ing it won't hurt.

* Add test

Add test for "Don't swallow Error message/stack when using formatter",
which Fixes #1178

lib/winston/common.js

@@ -219,6 +219,11 @@ exports.log = function (options) {
   //
   if (typeof options.formatter == 'function') {
     options.meta = meta || options.meta;
+    if (options.meta instanceof Error) {
+      // Force converting the Error to an plain object now so it
+      // will not be messed up by decycle() when cloning options
+      options.meta = exports.clone(options.meta);
+    }
     return String(options.formatter(exports.clone(options)));
   }
 

test/custom-formatter-test.js

@@ -14,7 +14,7 @@ var assert = require('assert'),
     winston = require('../lib/winston'),
     helpers = require('./helpers');
 
-function assertFileFormatter (basename, options) {
+function assertFileFormatter (basename, options, meta) {
   var filename = path.join(__dirname, 'fixtures', 'logs', basename + '.log');
 
   try { fs.unlinkSync(filename) }
@@ -28,7 +28,7 @@ function assertFileFormatter (basename, options) {
       // We must wait until transport file has emitted the 'flush'
       // event to be sure the file has been created and written
       transport.once('flush', this.callback.bind(this, null, filename));
-      transport.log('info', 'What does the fox say?', null, function () {});
+      transport.log('info', 'What does the fox say?', meta || null, function () {});
     },
     "should log with the appropriate format": function (_, filename) {
       var data = fs.readFileSync(filename, 'utf8');
@@ -67,7 +67,19 @@ vows.describe('winston/transport/formatter').addBatch({
           return params.timestamp() +' '+ params.level.toUpperCase() +' '+ (undefined !== params.message ? params.message : '') +
             ( params.meta && Object.keys(params.meta).length ? '\n'+ JSON.stringify(params.meta) : '' );
         }
-      })
+      }),
+      "and function value with custom format and error as metadata":
+        assertFileFormatter('customFormatterErrorMetadata', {
+          pattern: /^\d{13,} INFO What does the fox say\?.*My very special error message/,
+          json: false,
+          timestamp: function() {
+            return Date.now();
+          },
+          formatter: function(params) {
+            return params.timestamp() +' '+ params.level.toUpperCase() +' '+ params.message +' '+
+              JSON.stringify(params.meta);
+          }
+        }, new Error("My very special error message"))
     }
   }
 }).export(module);