diff --git a/lib/winston/common.js b/lib/winston/common.js index ac8e99d49..23a10514b 100644 --- a/lib/winston/common.js +++ b/lib/winston/common.js @@ -44,3 +44,30 @@ exports.warn = { }); } }; + + +exports.dataUtils = { + /** + * Creates a deep copy of an object + * @param {Object | string} data The data to clone + * @returns {Object} A deep copy of the parameter object + */ + cloneObject(data) { + const isError = Object.prototype.toString.call(data) === '[object Error]'; + const isObject = typeof data === 'object'; + + if (isError) { + let nextErr = new Error(data.message); + + nextErr.stack = data.stack; + Object.assign(nextErr, data); + + return nextErr; + } else if (isObject) { + return Object.assign({}, data); + } + + // Assume the primitive case + return data; + } +}; diff --git a/lib/winston/create-logger.js b/lib/winston/create-logger.js index e868aeaad..54085445c 100644 --- a/lib/winston/create-logger.js +++ b/lib/winston/create-logger.js @@ -10,6 +10,7 @@ const { LEVEL } = require('triple-beam'); const config = require('./config'); const Logger = require('./logger'); +const { dataUtils } = require('./common'); const debug = require('@dabh/diagnostics')('winston:create-logger'); function isLevelEnabledFunctionName(level) { @@ -75,7 +76,7 @@ module.exports = function (opts = {}) { // Optimize the hot-path which is the single object. if (args.length === 1) { const [msg] = args; - const info = msg && msg.message && msg || { message: msg }; + const info = msg && msg.message && dataUtils.cloneObject(msg) || { message: msg }; info.level = info[LEVEL] = level; self._addDefaultMeta(info); self.write(info); diff --git a/lib/winston/logger.js b/lib/winston/logger.js index 5f8758c89..26435d53b 100644 --- a/lib/winston/logger.js +++ b/lib/winston/logger.js @@ -15,7 +15,7 @@ const ExceptionHandler = require('./exception-handler'); const RejectionHandler = require('./rejection-handler'); const LegacyTransportStream = require('winston-transport/legacy'); const Profiler = require('./profiler'); -const { warn } = require('./common'); +const { warn, dataUtils } = require('./common'); const config = require('./config'); /** @@ -205,30 +205,33 @@ class Logger extends Transform { */ /* eslint-enable valid-jsdoc */ log(level, msg, ...splat) { + let msgCopy; // eslint-disable-line max-params // Optimize for the hotpath of logging JSON literals if (arguments.length === 1) { // Yo dawg, I heard you like levels ... seriously ... // In this context the LHS `level` here is actually the `info` so read // this as: info[LEVEL] = info.level; - level[LEVEL] = level.level; - this._addDefaultMeta(level); - this.write(level); + msgCopy = dataUtils.cloneObject(level); + msgCopy[LEVEL] = level.level; + this._addDefaultMeta(msgCopy); + this.write(msgCopy); return this; } // Slightly less hotpath, but worth optimizing for. if (arguments.length === 2) { if (msg && typeof msg === 'object') { - msg[LEVEL] = msg.level = level; - this._addDefaultMeta(msg); - this.write(msg); + msgCopy = dataUtils.cloneObject(msg); + msgCopy[LEVEL] = msgCopy.level = level; + this._addDefaultMeta(msgCopy); + this.write(msgCopy); return this; } - msg = { [LEVEL]: level, level, message: msg }; - this._addDefaultMeta(msg); - this.write(msg); + msgCopy = { [LEVEL]: level, level, message: msg }; + this._addDefaultMeta(msgCopy); + this.write(msgCopy); return this; } @@ -243,7 +246,7 @@ class Logger extends Transform { [LEVEL]: level, [SPLAT]: splat, level, - message: msg + message: dataUtils.cloneObject(msg) }); if (meta.message) info.message = `${info.message} ${meta.message}`; diff --git a/test/unit/formats/errors.test.js b/test/unit/formats/errors.test.js index 400de910a..d64958705 100644 --- a/test/unit/formats/errors.test.js +++ b/test/unit/formats/errors.test.js @@ -35,14 +35,19 @@ function assumeExpectedInfo(info, target = {}) { }); } +function assumeNonMutatedObject(originalObject) { + assume(originalObject[LEVEL]).equals(undefined); +} + describe('format.errors (integration)', function () { it('logger.log(level, error)', (done) => { const logger = helpers.createLogger(function (info) { assumeExpectedInfo(info); done(); }, format.errors()); + const err = new Error('Errors lack .toJSON() lulz'); - logger.log('info', new Error('Errors lack .toJSON() lulz')); + logger.log('info', err); }); it('logger.log(level, error) [custom error properties]', (done) => { @@ -51,7 +56,7 @@ describe('format.errors (integration)', function () { something: true, wut: 'another string' }); - + assumeNonMutatedObject(err); done(); }, format.errors()); @@ -67,13 +72,15 @@ describe('format.errors (integration)', function () { thisIsMeta: true, anyValue: 'a string' }; + const err = new Error('Errors lack .toJSON() lulz'); const logger = helpers.createLogger(function (info) { assumeExpectedInfo(info, meta); + assumeNonMutatedObject(err); done(); }, format.errors()); - logger.log('info', new Error('Errors lack .toJSON() lulz'), meta); + logger.log('info', err, meta); }); it('logger.log(level, error, meta) [custom error properties]', (done) => { @@ -87,6 +94,7 @@ describe('format.errors (integration)', function () { something: true, wut: 'another string' }, meta)); + assumeNonMutatedObject(err); done(); }, format.errors()); @@ -103,14 +111,14 @@ describe('format.errors (integration)', function () { assumeExpectedInfo(info, { message: 'Caught error: Errors lack .toJSON() lulz' }); - + assumeNonMutatedObject(err); done(); }, format.combine( format.errors(), format.printf(info => info.message) )); - - logger.log('info', 'Caught error:', new Error('Errors lack .toJSON() lulz')); + const err = new Error('Errors lack .toJSON() lulz'); + logger.log('info', 'Caught error:', err); }); it('logger.log(level, msg, meta) [custom error properties]', (done) => { @@ -125,7 +133,7 @@ describe('format.errors (integration)', function () { something: true, wut: 'another string' }); - + assumeNonMutatedObject(err); done(); }, format.combine( format.errors(), @@ -138,10 +146,12 @@ describe('format.errors (integration)', function () { it('logger.(error)', (done) => { const logger = helpers.createLogger(function (info) { assumeExpectedInfo(info); + assumeNonMutatedObject(err); done(); }, format.errors()); + const err = new Error('Errors lack .toJSON() lulz') - logger.info(new Error('Errors lack .toJSON() lulz')); + logger.info(err); }); it('logger.(error) [custom error properties]', (done) => { @@ -150,7 +160,7 @@ describe('format.errors (integration)', function () { something: true, wut: 'another string' }); - + assumeNonMutatedObject(err); done(); }, format.errors()); @@ -169,10 +179,11 @@ describe('format.errors (integration)', function () { const logger = helpers.createLogger(function (info) { assumeExpectedInfo(info, meta); + assumeNonMutatedObject(err); done(); }, format.errors()); - - logger.info(new Error('Errors lack .toJSON() lulz'), meta); + const err = new Error('Errors lack .toJSON() lulz'); + logger.info(err, meta); }); it('logger.(error, meta) [custom error properties]', (done) => { @@ -186,7 +197,7 @@ describe('format.errors (integration)', function () { something: true, wut: 'another string' }, meta)); - + assumeNonMutatedObject(err); done(); }, format.errors()); @@ -202,14 +213,15 @@ describe('format.errors (integration)', function () { assumeExpectedInfo(info, { message: 'Caught error: Errors lack .toJSON() lulz' }); - + assumeNonMutatedObject(err); done(); }, format.combine( format.errors(), format.printf(info => info.message) )); + const err = new Error('Errors lack .toJSON() lulz'); - logger.info('Caught error:', new Error('Errors lack .toJSON() lulz')); + logger.info('Caught error:', err); }); it('logger.(msg, meta) [custom error properties]', (done) => { @@ -224,7 +236,7 @@ describe('format.errors (integration)', function () { something: true, wut: 'another string' }); - + assumeNonMutatedObject(err); done(); }, format.combine( format.errors(), @@ -264,4 +276,4 @@ describe('format.errors (integration)', function () { throw err; }).catch(logger.error.bind(logger)); }); -}); + }); diff --git a/test/unit/winston/logger.test.js b/test/unit/winston/logger.test.js index 83504f594..6d5209ac2 100755 --- a/test/unit/winston/logger.test.js +++ b/test/unit/winston/logger.test.js @@ -15,7 +15,7 @@ const util = require('util'); const { EOL } = require('os'); const isStream = require('is-stream'); const stdMocks = require('std-mocks'); -const { MESSAGE, SPLAT } = require('triple-beam'); +const { MESSAGE, SPLAT, LEVEL } = require('triple-beam'); const winston = require('../../../lib/winston'); const TransportStream = require('winston-transport'); const format = require('../../../lib/winston').format; @@ -695,13 +695,15 @@ describe('Logger Instance', function () { // TODO: Revisit to improve these describe('Logging non-primitive data types', function () { describe('.log', function () { - it(`.log(new Error()) uses Error instance as info`, function (done) { + it(`.log(new Error()) uses Error instance data as info`, function (done) { const err = new Error('test'); err.level = 'info'; const logger = helpers.createLogger(function (info) { assume(info).instanceOf(Error); - assume(info).equals(err); + assume(info.message).equals(err.message); + assume(info.stack).equals(err.stack); + assume(info.level).equals(err.level); done(); }); @@ -747,6 +749,46 @@ describe('Logger Instance', function () { logger.info('Hello', {label: 'world'}); logger.info('Hello %d', 100, {label: 'world'}); }); + + it(`.log(level, object) does not mutate input`, function (done) { + const data = { message: 'hello' }; + + const logger = helpers.createLogger(function (info) { + assume(info[LEVEL]).equals('info'); + assume(info.message).equals('hello'); + assume(data[LEVEL]).equals(undefined); + assume(data).deep.equal({ message: 'hello' }); + done(); + }); + + logger.log('info', data); + }); + + it(`.log(level, array) does not mutate input`, function (done) { + const data = ['one', 'two', 'three']; + + const logger = helpers.createLogger(function (info) { + assume(info[LEVEL]).equals('info'); + assume(data[LEVEL]).equals(undefined); + assume(data).deep.equal(['one', 'two', 'three']); + done(); + }); + + logger.log('info', data); + }); + + it(`.log(level, object, splat) does not mutate input`, function (done) { + const data = { message: 'hello' }; + + const logger = helpers.createLogger(function (info) { + assume(info[LEVEL]).equals('info'); + assume(data[LEVEL]).equals(undefined); + assume(data).deep.equal({ message: 'hello' }); + done(); + }); + + logger.log('info', data, { label: 'test' }); + }); }); describe('.info', function () { @@ -768,17 +810,58 @@ describe('Logger Instance', function () { logger.info(null); }); - it('.info(new Error()) uses Error instance as info', function (done) { + it('.info(new Error()) uses Error instance data as info', function (done) { const err = new Error('test'); const logger = helpers.createLogger(function (info) { assume(info).instanceOf(Error); - assume(info).equals(err); + assume(info.message).equals(err.message); + assume(info.stack).equals(err.stack); done(); }); logger.info(err); }); + it(`.info(object) does not mutate input`, function (done) { + const data = { message: 'hello' }; + + const logger = helpers.createLogger(function (info) { + assume(info.message).equals('hello'); + assume(info[LEVEL]).equals('info'); + assume(data).deep.equal({ message: 'hello' }); + assume(data[LEVEL]).equals(undefined); + done(); + }); + + logger.info(data); + }); + + it(`.info(array) does not mutate input`, function (done) { + const data = ['one', 'two', 'three']; + + const logger = helpers.createLogger(function (info) { + assume(info[LEVEL]).equals('info'); + assume(data).deep.equal(['one', 'two', 'three']); + assume(data[LEVEL]).equals(undefined); + done(); + }); + + logger.info(data); + }); + + it(`.info(array) does not mutate input`, function (done) { + const data = { message: ['one', 'two', 'three'] }; + + const logger = helpers.createLogger(function (info) { + assume(info[LEVEL]).equals('info'); + assume(data).deep.equal({ message: ['one', 'two', 'three'] }); + assume(data[LEVEL]).equals(undefined); + done(); + }); + + logger.info(data); + }); + // TODO: This test needs finished or removed it.skip(`.info('any string', new Error())`, function (done) { const err = new Error('test'); @@ -955,11 +1038,12 @@ describe('Logger Instance', function () { logger.log('info', null); }); - it(`.log(level, new Error()) uses Error instance as info`, function (done) { + it(`.log(level, new Error()) uses Error instance data as info`, function (done) { const err = new Error('test'); const logger = helpers.createLogger(function (info) { assume(info).instanceOf(Error); - assume(info).equals(err); + assume(info.message).equals(err.message); + assume(info.stack).equals(err.stack); done(); });