diff --git a/.eslintrc b/.eslintrc index 54abcead2..ffae4d782 100644 --- a/.eslintrc +++ b/.eslintrc @@ -2,6 +2,7 @@ "extends": "@dabh/eslint-config-populist", "rules": { "one-var": ["error", { "var": "never", "let": "never", "const": "never" }], + "semi": "error", "strict": 0 }, "parserOptions": { diff --git a/.nycrc.yml b/.nycrc.yml index ce121842b..37ef1b757 100644 --- a/.nycrc.yml +++ b/.nycrc.yml @@ -4,5 +4,5 @@ reporter: check-coverage: true branches: 61.51 lines: 70.85 -functions: 73.21 +functions: 73.08 statements: 70.54 \ No newline at end of file diff --git a/lib/winston/logger.js b/lib/winston/logger.js index febfb67f7..dbcbfb557 100644 --- a/lib/winston/logger.js +++ b/lib/winston/logger.js @@ -9,7 +9,7 @@ const { Stream, Transform } = require('readable-stream'); const asyncForEach = require('async/forEach'); -const { LEVEL, SPLAT } = require('triple-beam'); +const { LEVEL, SPLAT, MESSAGE } = require('triple-beam'); const isStream = require('is-stream'); const ExceptionHandler = require('./exception-handler'); const RejectionHandler = require('./rejection-handler'); @@ -17,6 +17,7 @@ const LegacyTransportStream = require('winston-transport/legacy'); const Profiler = require('./profiler'); const { warn } = require('./common'); const config = require('./config'); +const jsonStringify = require('safe-stable-stringify'); /** * Captures the number of format (i.e. %s strings) in a given string. @@ -42,30 +43,12 @@ class Logger extends Transform { this.configure(options); } - child(defaultRequestMetadata) { + child(childMetadata) { const logger = this; + const clonedParentMetadata = JSON.parse(jsonStringify(this.defaultMeta)); return Object.create(logger, { - write: { - value: function (info) { - const infoClone = Object.assign( - {}, - defaultRequestMetadata, - info - ); - - // Object.assign doesn't copy inherited Error - // properties so we have to do that explicitly - // - // Remark (indexzero): we should remove this - // since the errors format will handle this case. - // - if (info instanceof Error) { - infoClone.stack = info.stack; - infoClone.message = info.message; - } - - logger.write(infoClone); - } + defaultMeta: { + value: Object.assign({}, clonedParentMetadata, childMetadata) } }); } @@ -288,6 +271,10 @@ class Logger extends Transform { info[LEVEL] = info.level; } + if (!info[MESSAGE]) { + info[MESSAGE] = info.message; + } + // Remark: really not sure what to do here, but this has been reported as // very confusing by pre winston@2.0.0 users as quite confusing when using // custom levels. @@ -647,7 +634,9 @@ class Logger extends Transform { _addDefaultMeta(msg) { if (this.defaultMeta) { - Object.assign(msg, this.defaultMeta); + // The msg must be cloned as it is being mutated, but any metadata provided with the msg takes precedence over default + const msgClone = JSON.parse(jsonStringify(msg)); + Object.assign(msg, this.defaultMeta, msgClone); } } } diff --git a/lib/winston/profiler.js b/lib/winston/profiler.js index edcc5a65a..a8dda1351 100644 --- a/lib/winston/profiler.js +++ b/lib/winston/profiler.js @@ -21,6 +21,8 @@ module.exports = class Profiler { * @private */ constructor(logger) { + // TODO there is no restriction on what the Profiler considers a Logger. As such there is no guarantees it adheres + // to the proper interface. This needs to hardened. if (!logger) { throw new Error('Logger is required for profiling.'); } @@ -32,7 +34,8 @@ module.exports = class Profiler { /** * Ends the current timer (i.e. Profiler) instance and logs the `msg` along * with the duration since creation. - * @returns {mixed} - TODO: add return description. + * @returns {boolean} - `false` if the logger stream wishes for the calling code to wait for the 'drain' event to be + * emitted before continuing to write additional data; otherwise `true` * @private */ done(...args) { @@ -45,7 +48,7 @@ module.exports = class Profiler { const info = typeof args[args.length - 1] === 'object' ? args.pop() : {}; info.level = info.level || 'info'; info.durationMs = (Date.now()) - this.start; - + if (this.logger._addDefaultMeta) this.logger._addDefaultMeta(info); return this.logger.write(info); } }; diff --git a/package.json b/package.json index 07cdaa8bd..e1bdbbbf4 100644 --- a/package.json +++ b/package.json @@ -60,6 +60,7 @@ "types": "./index.d.ts", "scripts": { "lint": "eslint lib/*.js lib/winston/*.js lib/winston/**/*.js --resolve-plugins-relative-to ./node_modules/@dabh/eslint-config-populist", + "lint:fix": "npm run lint -- --fix", "test": "mocha", "test:coverage": "nyc npm run test:unit", "test:unit": "mocha test/unit", diff --git a/test/helpers/mocks/mock-transport.js b/test/helpers/mocks/mock-transport.js index 5522143a9..0355e4584 100644 --- a/test/helpers/mocks/mock-transport.js +++ b/test/helpers/mocks/mock-transport.js @@ -1,9 +1,10 @@ const stream = require('stream') const winston = require('../../../lib/winston'); +const {Writable} = require("stream"); /** * Returns a new Winston transport instance which will invoke - * the `write` method on each call to `.log` + * the `write` method on each call to `.log` * * @param {function} write Write function for the specified stream * @returns {StreamTransportInstance} A transport instance @@ -17,6 +18,23 @@ function createMockTransport(write) { return new winston.transports.Stream({ stream: writeable }) } +/** + * Returns a valid Winston transport that writes to the passed array object + * @param array Array to be used to store the "written" chunks + * @returns {winston.transports.Stream} + */ +function inMemory(array, options = {}) { + const memoryStream = new Writable({ + objectMode: true, + write: (chunk, encoding, next) => { + array.push(chunk); + next() + } + }); + return new winston.transports.Stream({stream: memoryStream, ...options}) +} + module.exports = { - createMockTransport + createMockTransport, + inMemory }; diff --git a/test/unit/winston/logger.test.js b/test/unit/winston/logger.test.js index 83504f594..6910dded9 100755 --- a/test/unit/winston/logger.test.js +++ b/test/unit/winston/logger.test.js @@ -10,8 +10,6 @@ const assume = require('assume'); const path = require('path'); -const stream = require('readable-stream'); -const util = require('util'); const { EOL } = require('os'); const isStream = require('is-stream'); const stdMocks = require('std-mocks'); @@ -20,10 +18,18 @@ const winston = require('../../../lib/winston'); const TransportStream = require('winston-transport'); const format = require('../../../lib/winston').format; const helpers = require('../../helpers'); -const mockTransport = require('../../helpers/mocks/mock-transport'); +const mockTransports = require('../../helpers/mocks/mock-transport'); const testLogFixturesPath = path.join(__dirname, '..', '..', 'fixtures', 'logs'); describe('Logger Instance', function () { + let levelOutput = []; + let logOutput = []; + + beforeEach(() => { + levelOutput = []; + logOutput = []; + }); + describe('Configuration', function () { it('.configure()', function () { let logger = winston.createLogger({ @@ -198,6 +204,30 @@ describe('Logger Instance', function () { assume(isStream(outStream)).true(); }); }); + + describe('Multiple Transports', function () { + it('should log the same thing to every configured transport', function () { + console.log('Reproduction of Issue #1430'); + this.skip(); + const transport1Output = []; + const transport2Output = []; + const customFormat = winston.format.combine( + winston.format.splat(), + winston.format.printf((info) => JSON.stringify(info)) + ); + + const logger = winston.createLogger(); + + logger.add(mockTransports.inMemory(transport1Output, {format: customFormat})); + logger.add(mockTransports.inMemory(transport2Output, {format: customFormat})); + + for (let index = 0; index < 10; index++) { + logger.info("test %s" + index, "blub", "metainfo"); + } + + assume(transport1Output).eqls(transport2Output); + }); + }); }); describe('Log Levels', function () { @@ -670,15 +700,10 @@ describe('Logger Instance', function () { }, 100); }); - it('should stop a timer when `done` is called on it', function (done) { - let logger = helpers.createLogger(function (info) { - assume(info).is.an('object'); - assume(info.something).equals('ok'); - assume(info.level).equals('info'); - assume(info.durationMs).is.a('number'); - assume(info.message).equals('testing1'); - assume(info[MESSAGE]).is.a('string'); - done(); + it('should stop a profiler instance generated via `startTimer()` when `done()` is called on it', function (done) { + const logger = winston.createLogger({ + transports: [mockTransports.inMemory(levelOutput)], + defaultMeta: {rootLogger: true} }); let timer = logger.startTimer(); @@ -688,6 +713,14 @@ describe('Logger Instance', function () { something: 'ok', level: 'info' }); + assume(levelOutput).is.length(1); + assume(levelOutput[0]).contains('durationMs'); + assume(levelOutput[0].durationMs).is.a('number'); + assume(levelOutput[0].message).equals('testing1'); + assume(levelOutput[0].level).equals('info'); + assume(levelOutput[0].something).equals('ok'); + assume(levelOutput[0].rootLogger).is.true(); + done() }, 100); }); }); @@ -779,150 +812,675 @@ describe('Logger Instance', function () { logger.info(err); }); - // TODO: This test needs finished or removed - it.skip(`.info('any string', new Error())`, function (done) { + it(`.info('any string', new Error())`, function () { + console.log(`The current result of this log statement results in the error message being concatenated with \ +the log message provided.\nThis behavior needs to be verified if it's intentional IMO`) + this.skip(); const err = new Error('test'); - const logger = helpers.createLogger(function (info) { - done(); + const logger = winston.createLogger({ + transports: [mockTransports.inMemory(levelOutput)] }); - logger.info(err); + logger.info('test message!', err); + + assume(levelOutput[0].level).eqls("info"); + assume(levelOutput[0].message).eqls("test message! test"); + assume(levelOutput[0].stack).exists("stack trace must exist"); }); }); }); - describe('Metadata Precedence', function () { - describe('Should support child loggers & defaultMeta', () => { - it('sets child meta for text messages correctly', (done) => { - const assertFn = ((msg) => { - assume(msg.level).equals('info'); - assume(msg.message).equals('dummy message'); - assume(msg.requestId).equals('451'); - done(); + describe('Children', () => { + it('handles error stack traces in child loggers correctly', (done) => { + const assertFn = ((msg) => { + assume(msg.level).equals('error'); + assume(msg.message).equals('dummy error'); + assume(msg.stack).includes('logger.test.js'); + assume(msg.service).equals('user-service'); + done(); + }); + + const logger = winston.createLogger({ + transports: [ + mockTransports.createMockTransport(assertFn) + ] + }); + + const childLogger = logger.child({service: 'user-service'}); + childLogger.error(Error('dummy error')); + }); + + it('defaultMeta should autobind correctly', (done) => { + const logger = helpers.createLogger(info => { + assume(info.message).equals('test'); + done(); + }); + + const log = logger.info; + log('test'); + }); + }); + + describe('Metadata with non-primitive data types', function() { + it('should support a Map', function() { + const expectedOutput = [ + {level: "info", message: "test message", someMap: new Map([["val1","c"], ["val2", "b"]])} + ]; + + const logger1 = winston.createLogger({ + transports: [mockTransports.inMemory(levelOutput)] + }); + const logger2 = winston.createLogger({ + transports: [mockTransports.inMemory(logOutput)] + }); + const logMeta = { + someMap: new Map([["val1","a"], ["val2", "b"], ["val1","c"]]) + }; + + logger1.info("test message", logMeta); + logger2.info({level: "info", message: "test message", ...logMeta}); + + assume(levelOutput).eqls(logOutput); + assume(expectedOutput).eqls(levelOutput); + assume(expectedOutput).eqls(logOutput); + }); + + it('should support a Set', function() { + const expectedOutput = [ + {level: "info", message: "test message", someSet: new Set(["a", "b"])} + ] + + const logger1 = winston.createLogger({ + transports: [mockTransports.inMemory(levelOutput)] + }); + const logger2 = winston.createLogger({ + transports: [mockTransports.inMemory(logOutput)] + }); + const logMeta = { + someSet: new Set(["a","b", "a"]) + }; + + logger1.info("test message", logMeta); + logger2.info({level: "info", message: "test message", ...logMeta}); + + assume(levelOutput).eqls(logOutput); + assume(expectedOutput).eqls(levelOutput); + assume(expectedOutput).eqls(logOutput); + }); + }); + + describe('Metadata Precedence', () => { + describe('Single logger instance', () => { + it('should log to passed array correctly when using the `inMemory` transport', () => { + const expectedOutput = [ + {message: "some message", level: "info"}, + {message: "I'm a test", level: "warn"} + ]; + + const logger1 = winston.createLogger({ + transports: [mockTransports.inMemory(levelOutput)] + }); + const logger2 = winston.createLogger({ + transports: [mockTransports.inMemory(logOutput)] }); - const logger = winston.createLogger({ - transports: [ - mockTransport.createMockTransport(assertFn) - ] + logger1.info("some message"); + logger1.warn("I'm a test"); + logger2.log({level: 'info', message: "some message"}); + logger2.log({level: 'warn', message: "I'm a test"}); + + assume(levelOutput).eqls(logOutput); + assume(expectedOutput).eqls(levelOutput); + assume(expectedOutput).eqls(logOutput); + }); + + it('should include default metadata defined on the logger instance', () => { + const expectedOutput = [ + {message: "some message", level: "info", isRoot: true}, + ]; + + const logger1 = winston.createLogger({ + transports: [mockTransports.inMemory(levelOutput)], + defaultMeta: {isRoot: true} + }); + const logger2 = winston.createLogger({ + transports: [mockTransports.inMemory(logOutput)], + defaultMeta: {isRoot: true} }); - const childLogger = logger.child({requestId: '451'}); - childLogger.info('dummy message'); + logger1.info("some message"); + logger2.log({level: "info", message: "some message"}); + + assume(levelOutput).eqls(logOutput); + assume(expectedOutput).eqls(levelOutput); + assume(expectedOutput).eqls(logOutput); }); - it('sets child meta for json messages correctly', (done) => { - const assertFn = ((msg) => { - assume(msg.level).equals('info'); - assume(msg.message.text).equals('dummy'); - assume(msg.requestId).equals('451'); - done(); + it('should include metadata log specific metadata', () => { + const expectedOutput = [ + {message: "some message", level: "info", logMeta: true}, + ]; + + const logger1 = winston.createLogger({ + transports: [mockTransports.inMemory(levelOutput)], + }); + const logger2 = winston.createLogger({ + transports: [mockTransports.inMemory(logOutput)], }); - const logger = winston.createLogger({ - transports: [ - mockTransport.createMockTransport(assertFn) - ] + logger1.info("some message", {logMeta: true}); + logger2.log({level: "info", message: "some message", logMeta: true}); + + assume(levelOutput).eqls(logOutput); + assume(expectedOutput).eqls(levelOutput); + assume(expectedOutput).eqls(logOutput); + }); + + it('should include both default metadata & log specific metadata', () => { + const expectedOutput = [ + {message: "some message", level: "info", isRoot: true, logMeta: true}, + ]; + + const logger1 = winston.createLogger({ + transports: [mockTransports.inMemory(levelOutput)], + defaultMeta: {isRoot: true} + }); + const logger2 = winston.createLogger({ + transports: [mockTransports.inMemory(logOutput)], + defaultMeta: {isRoot: true} }); - const childLogger = logger.child({requestId: '451'}); - childLogger.info({text: 'dummy'}); + logger1.info("some message", {logMeta: true}); + logger2.log({level: "info", message: "some message", logMeta: true}); + + assume(levelOutput).eqls(logOutput); + assume(expectedOutput).eqls(levelOutput); + assume(expectedOutput).eqls(logOutput); }); - it('merges child and provided meta correctly', (done) => { - const assertFn = ((msg) => { - assume(msg.level).equals('info'); - assume(msg.message).equals('dummy message'); - assume(msg.service).equals('user-service'); - assume(msg.requestId).equals('451'); - done(); + it('should override default metadata with log specific metadata', () => { + const expectedOutput = [ + {message: "some message", level: "info", isRoot: false}, + ]; + + const logger1 = winston.createLogger({ + transports: [mockTransports.inMemory(levelOutput)], + defaultMeta: {isRoot: true} + }); + const logger2 = winston.createLogger({ + transports: [mockTransports.inMemory(logOutput)], + defaultMeta: {isRoot: true} }); - const logger = winston.createLogger({ - transports: [ - mockTransport.createMockTransport(assertFn) - ] + logger1.info("some message", {isRoot: false}); + logger2.log({level: "info", message: "some message", isRoot: false}); + + assume(levelOutput).eqls(logOutput); + assume(expectedOutput).eqls(levelOutput); + assume(expectedOutput).eqls(logOutput); + }); + }); + + describe('Multiple logger instances', () => { + it('should log to passed array correctly when using the `inMemory` transport', () => { + const expectedOutput = [ + {message: "some message", level: "info"}, + {message: "I'm a test", level: "warn"} + ]; + + const logger1 = winston.createLogger({ + transports: [mockTransports.inMemory(levelOutput)] + }); + const logger1a = winston.createLogger({ + transports: [mockTransports.inMemory(levelOutput)] + }); + const logger2 = winston.createLogger({ + transports: [mockTransports.inMemory(logOutput)] + }); + const logger2a = winston.createLogger({ + transports: [mockTransports.inMemory(logOutput)] }); - const childLogger = logger.child({service: 'user-service'}); - childLogger.info('dummy message', {requestId: '451'}); + logger1.info("some message"); + logger1a.warn("I'm a test"); + logger2.log({level: "info", message: "some message"}); + logger2a.log({level: "warn", message: "I'm a test"}); + + assume(levelOutput).eqls(logOutput); + assume(expectedOutput).eqls(levelOutput); + assume(expectedOutput).eqls(logOutput); }); + + it('should include default metadata defined on all logger instances', () => { + const expectedOutput = [ + {message: "some message", level: "info", loggerName: "logger1"}, + {message: "some message", level: "info", loggerName: "logger2"}, + ]; + + const logger1 = winston.createLogger({ + transports: [mockTransports.inMemory(levelOutput)], + defaultMeta: {loggerName: "logger1"} + }); + const logger1a = winston.createLogger({ + transports: [mockTransports.inMemory(levelOutput)], + defaultMeta: {loggerName: "logger2"} + }); + const logger2 = winston.createLogger({ + transports: [mockTransports.inMemory(logOutput)], + defaultMeta: {loggerName: "logger1"} + }); + const logger2a = winston.createLogger({ + transports: [mockTransports.inMemory(logOutput)], + defaultMeta: {loggerName: "logger2"} + }); + + logger1.info("some message"); + logger1a.info("some message"); + logger2.log({level: "info", message: "some message"}); + logger2a.log({level: "info", message: "some message"}); + + assume(levelOutput).eqls(logOutput); + assume(expectedOutput).eqls(levelOutput); + assume(expectedOutput).eqls(logOutput); }); - it('provided meta take precedence over defaultMeta', (done) => { - const assertFn = ((msg) => { - assume(msg.level).equals('info'); - assume(msg.message).equals('dummy message'); - assume(msg.service).equals('audit-service'); - assume(msg.requestId).equals('451'); - done(); + it('should include log specific metadata', () => { + const expectedOutput = [ + {message: "some message", level: "info", logMetadata: true}, + {message: "some message", level: "info", logMetadata: false}, + ]; + + const logger1 = winston.createLogger({ + transports: [mockTransports.inMemory(levelOutput)] + }); + const logger1a = winston.createLogger({ + transports: [mockTransports.inMemory(levelOutput)] + }); + const logger2 = winston.createLogger({ + transports: [mockTransports.inMemory(logOutput)] + }); + const logger2a = winston.createLogger({ + transports: [mockTransports.inMemory(logOutput)] }); - const logger = winston.createLogger({ - defaultMeta: {service: 'user-service'}, - transports: [ - mockTransport.createMockTransport(assertFn) - ] + logger1.info("some message", {logMetadata: true}); + logger1a.info("some message", {logMetadata: false}); + logger2.log({level: "info", message: "some message", logMetadata: true}); + logger2a.log({level: "info", message: "some message", logMetadata: false}); + + assume(levelOutput).eqls(logOutput); + assume(expectedOutput).eqls(levelOutput); + assume(expectedOutput).eqls(logOutput); + }); + + it('should include both default metadata & log specific metadata', () => { + const expectedOutput = [ + {message: "some message", level: "info", loggerName: "logger1", logMetadata: true}, + {message: "some message", level: "info", loggerName: "logger2", logMetadata: false}, + ]; + + const logger1 = winston.createLogger({ + transports: [mockTransports.inMemory(levelOutput)], + defaultMeta: {loggerName: "logger1"} + }); + const logger1a = winston.createLogger({ + transports: [mockTransports.inMemory(levelOutput)], + defaultMeta: {loggerName: "logger2"} + }); + const logger2 = winston.createLogger({ + transports: [mockTransports.inMemory(logOutput)], + defaultMeta: {loggerName: "logger1"} }); + const logger2a = winston.createLogger({ + transports: [mockTransports.inMemory(logOutput)], + defaultMeta: {loggerName: "logger2"} + }); + + logger1.info("some message", {logMetadata: true}); + logger1a.info("some message", {logMetadata: false}); + logger2.log({level: "info", message: "some message", logMetadata: true}); + logger2a.log({level: "info", message: "some message", logMetadata: false}); + + assume(levelOutput).eqls(logOutput); + assume(expectedOutput).eqls(levelOutput); + assume(expectedOutput).eqls(logOutput); + }); + + it('should include overridden default metadata with log specific metadata', () => { + const expectedOutput = [ + {message: "some message", level: "info", loggerName: "logger1-override"}, + {message: "some message", level: "info", loggerName: "logger2-override"}, + ]; - logger.info('dummy message', { - requestId: '451', - service: 'audit-service' + const logger1 = winston.createLogger({ + transports: [mockTransports.inMemory(levelOutput)], + defaultMeta: {loggerName: "logger1"} }); + const logger1a = winston.createLogger({ + transports: [mockTransports.inMemory(levelOutput)], + defaultMeta: {loggerName: "logger2"} + }); + const logger2 = winston.createLogger({ + transports: [mockTransports.inMemory(logOutput)], + defaultMeta: {loggerName: "logger1"} + }); + const logger2a = winston.createLogger({ + transports: [mockTransports.inMemory(logOutput)], + defaultMeta: {loggerName: "logger2"} + }); + + logger1.info("some message", {loggerName: "logger1-override"}); + logger1a.info("some message", {loggerName: "logger2-override"}); + logger2.log({level: "info", message: "some message", loggerName: "logger1-override"}); + logger2a.log({level: "info", message: "some message", loggerName: "logger2-override"}); + + assume(levelOutput).eqls(logOutput); + assume(expectedOutput).eqls(levelOutput); + assume(expectedOutput).eqls(logOutput); }); + }); - it('provided meta take precedence over child meta', (done) => { - const assertFn = ((msg) => { - assume(msg.level).equals('info'); - assume(msg.message).equals('dummy message'); - assume(msg.service).equals('audit-service'); - assume(msg.requestId).equals('451'); - done(); + describe('Single child logger instance', () => { + it("should inherit the parent's default metadata", () => { + const expectedOutput = [ + {message: "some message", level: "info", loggerName: "root"}, // root logger + {message: "some message", level: "info", loggerName: "root"}, // child logger + ]; + + const rootLogger1 = winston.createLogger({ + transports: [mockTransports.inMemory(levelOutput)], + defaultMeta: {loggerName: "root"} }); + const childLogger1 = rootLogger1.child(); + const rootLogger2 = winston.createLogger({ + transports: [mockTransports.inMemory(logOutput)], + defaultMeta: {loggerName: "root"} + }); + const childLogger2 = rootLogger2.child(); - const logger = winston.createLogger({ - transports: [ - mockTransport.createMockTransport(assertFn) - ] + rootLogger1.info("some message"); + childLogger1.info("some message"); + rootLogger2.log({level: "info", message: "some message"}); + childLogger2.log({level: "info", message: "some message"}); + + assume(levelOutput).eqls(logOutput); + assume(expectedOutput).eqls(levelOutput); + assume(expectedOutput).eqls(logOutput); + }); + + it("should not reflect changes to the parent's metadata if it changes after the child is created", () => { + const expectedOutput = [ + {message: "some message", level: "info", label: "parent"}, // child logger + {message: "some message", level: "info", label: "parent"}, // child logger + ]; + + const rootLogger1 = winston.createLogger({ + transports: [mockTransports.inMemory(levelOutput)], + defaultMeta: {label: "parent"} + }); + const childLogger1 = rootLogger1.child(); + const rootLogger2 = winston.createLogger({ + transports: [mockTransports.inMemory(logOutput)], + defaultMeta: {label: "parent"} }); + const childLogger2 = rootLogger2.child(); + + childLogger1.info("some message"); + rootLogger1.defaultMeta = { + defaultMeta: {label: "updatedLabel"} + }; + childLogger1.info("some message"); + childLogger2.log({level: "info", message: "some message"}); + rootLogger2.defaultMeta = { + defaultMeta: {label: "updatedLabel"} + }; + childLogger2.log({level: "info", message: "some message"}); + + assume(levelOutput).eqls(logOutput); + assume(expectedOutput).eqls(levelOutput); + assume(expectedOutput).eqls(logOutput); + }); + + it("should include both the parent's & child's default metadata", () => { + const expectedOutput = [ + {message: "some message", level: "info", loggerName: "root"}, // root logger + {message: "some message", level: "info", loggerName: "root", isChild: true}, // child logger + ]; - const childLogger = logger.child({service: 'user-service'}); - childLogger.info('dummy message', { - requestId: '451', - service: 'audit-service' + const rootLogger1 = winston.createLogger({ + transports: [mockTransports.inMemory(levelOutput)], + defaultMeta: {loggerName: "root"} }); + const childLogger1 = rootLogger1.child({isChild: true}); + const rootLogger2 = winston.createLogger({ + transports: [mockTransports.inMemory(logOutput)], + defaultMeta: {loggerName: "root"} + }); + const childLogger2 = rootLogger2.child({isChild: true}); + + rootLogger1.info("some message"); + childLogger1.info("some message"); + rootLogger2.log({level: "info", message: "some message"}); + childLogger2.log({level: "info", message: "some message"}); + + assume(levelOutput).eqls(logOutput); + assume(expectedOutput).eqls(levelOutput); + assume(expectedOutput).eqls(logOutput); }); - it('handles error stack traces in child loggers correctly', (done) => { - const assertFn = ((msg) => { - assume(msg.level).equals('error'); - assume(msg.message).equals('dummy error'); - assume(msg.stack).includes('logger.test.js'); - assume(msg.service).equals('user-service'); - done(); + it("should override the parent's default metadata with the child's default metadata", () => { + const expectedOutput = [ + {message: "some message", level: "info", loggerName: "root"}, // root logger + {message: "some message", level: "info", loggerName: "child"}, // child logger + ]; + + const rootLogger1 = winston.createLogger({ + transports: [mockTransports.inMemory(levelOutput)], + defaultMeta: {loggerName: "root"} }); + const childLogger1 = rootLogger1.child({loggerName: "child"}); + const rootLogger2 = winston.createLogger({ + transports: [mockTransports.inMemory(logOutput)], + defaultMeta: {loggerName: "root"} + }); + const childLogger2 = rootLogger2.child({loggerName: "child"}); - const logger = winston.createLogger({ - transports: [ - mockTransport.createMockTransport(assertFn) - ] + rootLogger1.info("some message"); + childLogger1.info("some message"); + rootLogger2.log({level: "info", message: "some message"}); + childLogger2.log({level: "info", message: "some message"}); + + assume(levelOutput).eqls(logOutput); + assume(expectedOutput).eqls(levelOutput); + assume(expectedOutput).eqls(logOutput); + }); + + it("should override the parent's default metadata without affecting the parent", () => { + const expectedOutput = [ + {message: "some message", level: "info", loggerName: "child"}, // child logger + {message: "some message", level: "info", loggerName: "child-override"}, // child logger overridden + {message: "some message", level: "info", loggerName: "root"}, // root logger + ]; + + const rootLogger1 = winston.createLogger({ + transports: [mockTransports.inMemory(levelOutput)], + defaultMeta: {loggerName: "root"} + }); + const childLogger1 = rootLogger1.child({loggerName: "child"}); + const rootLogger2 = winston.createLogger({ + transports: [mockTransports.inMemory(logOutput)], + defaultMeta: {loggerName: "root"} + }); + const childLogger2 = rootLogger2.child({loggerName: "child"}); + + childLogger1.info("some message"); + childLogger1.info("some message", {loggerName: "child-override"}); + rootLogger1.info("some message"); + childLogger2.log({level: "info", message: "some message"}); + childLogger2.log({level: "info", message: "some message", loggerName: "child-override"}); + rootLogger2.log({level: "info", message: "some message"}); + + assume(levelOutput).eqls(logOutput); + assume(expectedOutput).eqls(levelOutput); + assume(expectedOutput).eqls(logOutput); + }); + + it("should override the parent's default metadata with the log specific metadata", () => { + const expectedOutput = [ + {message: "some message", level: "info", loggerName: "root"}, // root logger + {message: "some message", level: "info", loggerName: "child"}, // child logger + ]; + + const rootLogger1 = winston.createLogger({ + transports: [mockTransports.inMemory(levelOutput)], + defaultMeta: {loggerName: "root"} + }); + const childLogger1 = rootLogger1.child(); + const rootLogger2 = winston.createLogger({ + transports: [mockTransports.inMemory(logOutput)], + defaultMeta: {loggerName: "root"} }); + const childLogger2 = rootLogger2.child(); + + rootLogger1.info("some message"); + childLogger1.info("some message", {loggerName: "child"}); + rootLogger2.log({level: "info", message: "some message"}); + childLogger2.log({level: "info", message: "some message", loggerName: "child"}); - const childLogger = logger.child({service: 'user-service'}); - childLogger.error(Error('dummy error')); + assume(levelOutput).eqls(logOutput); + assume(expectedOutput).eqls(levelOutput); + assume(expectedOutput).eqls(logOutput); }); - it('defaultMeta() autobinds correctly', (done) => { - const logger = helpers.createLogger(info => { - assume(info.message).equals('test'); - done(); + it("should override the child's default metadata with the log specific metadata", () => { + const expectedOutput = [ + {message: "some message", level: "info", loggerName: "root"}, // root logger + {message: "some message", level: "info", loggerName: "root", isChild: null}, // child logger + ]; + + const rootLogger1 = winston.createLogger({ + transports: [mockTransports.inMemory(levelOutput)], + defaultMeta: {loggerName: "root"} }); + const childLogger1 = rootLogger1.child({isChild: true}); + const rootLogger2 = winston.createLogger({ + transports: [mockTransports.inMemory(logOutput)], + defaultMeta: {loggerName: "root"} + }); + const childLogger2 = rootLogger2.child({isChild: true}); + + rootLogger1.info("some message"); + childLogger1.info("some message", {isChild: null}); + rootLogger2.log({level: "info", message: "some message"}); + childLogger2.log({level: "info", message: "some message", isChild: null}); - const log = logger.info; - log('test'); + assume(levelOutput).eqls(logOutput); + assume(expectedOutput).eqls(levelOutput); + assume(expectedOutput).eqls(logOutput); }); + + it("should override both the parent's & child's default metadata with the log specific metadata", + () => { + const expectedOutput = [ + {message: "some message", level: "info", loggerName: "root"}, // root logger + {message: "some message", level: "info", loggerName: "child", isChild: null}, // child logger + ]; + + const rootLogger1 = winston.createLogger({ + transports: [mockTransports.inMemory(levelOutput)], + defaultMeta: {loggerName: "root"} + }); + const childLogger1 = rootLogger1.child({isChild: true}); + const rootLogger2 = winston.createLogger({ + transports: [mockTransports.inMemory(logOutput)], + defaultMeta: {loggerName: "root"} + }); + const childLogger2 = rootLogger2.child({isChild: true}); + + rootLogger1.info("some message"); + childLogger1.info("some message", {loggerName: "child", isChild: null}); + rootLogger2.log({level: "info", message: "some message"}); + childLogger2.log({level: "info", message: "some message", loggerName: "child", isChild: null}); + + assume(levelOutput).eqls(logOutput); + assume(expectedOutput).eqls(levelOutput); + assume(expectedOutput).eqls(logOutput); + }); + }); + + describe('Multiple child logger instances', () => { + it("should have independent default metadata that overrides the parent's", () => { + const expectedOutput = [ + {message: "some message", level: "info", loggerInfo: {name: "root", isChild: false}}, // root logger + {message: "some message", level: "info", loggerInfo: {name: "child1", isChild: true}}, // child1 logger + {message: "some message", level: "info", loggerInfo: {name: "child1-override", isChild: false}}, // child1 logger override + {message: "some message", level: "info", loggerInfo: {name: "child2", isChild: true}}, // child2 logger + {message: "some message", level: "info", loggerInfo: {name: "child2-override", isChild: false}}, // child2 logger override + {message: "some message", level: "info", loggerInfo: {name: "child3", isChild: true}}, // child3 logger + {message: "some message", level: "info", loggerInfo: {name: "child3-override", isChild: false}}, // child3 logger override + {message: "some message", level: "info", loggerInfo: {name: "root", isChild: false}}, // root logger + ]; + + const rootLogger1 = winston.createLogger({ + transports: [mockTransports.inMemory(levelOutput)], + defaultMeta: {loggerInfo: {name: "root", isChild: false}} + }); + const childLogger1 = rootLogger1.child({loggerInfo: {name: "child1", isChild: true}}); + const childLogger1a = rootLogger1.child({loggerInfo: {name: "child2", isChild: true}}); + const childLogger1b = rootLogger1.child({loggerInfo: {name: "child3", isChild: true}}); + const rootLogger2 = winston.createLogger({ + transports: [mockTransports.inMemory(logOutput)], + defaultMeta: {loggerInfo: {name: "root", isChild: false}} + }); + const childLogger2 = rootLogger2.child({loggerInfo: {name: "child1", isChild: true}}); + const childLogger2a = rootLogger2.child({loggerInfo: {name: "child2", isChild: true}}); + const childLogger2b = rootLogger2.child({loggerInfo: {name: "child3", isChild: true}}); + + rootLogger1.info("some message"); + childLogger1.info("some message"); + childLogger1.info("some message", {loggerInfo: {name: "child1-override", isChild: false}}); + childLogger1a.info("some message"); + childLogger1a.info("some message", {loggerInfo: {name: "child2-override", isChild: false}}); + childLogger1b.info("some message"); + childLogger1b.info("some message", {loggerInfo: {name: "child3-override", isChild: false}}); + rootLogger1.info("some message"); + + rootLogger2.log({level: "info", message: "some message"}); + childLogger2.log({level: "info", message: "some message"}); + childLogger2.log({level: "info", message: "some message", loggerInfo: {name: "child1-override", isChild: false}}); + childLogger2a.log({level: "info", message: "some message"}); + childLogger2a.log({level: "info", message: "some message", loggerInfo: {name: "child2-override", isChild: false}}); + childLogger2b.log({level: "info", message: "some message"}); + childLogger2b.log({level: "info", message: "some message", loggerInfo: {name: "child3-override", isChild: false}}); + rootLogger2.log({level: "info", message: "some message"}); + + assume(levelOutput).eqls(logOutput); + assume(expectedOutput).eqls(levelOutput); + assume(expectedOutput).eqls(logOutput); + }); }); }); + describe('Metadata application with formats', () => { + describe('Printf Format', () => { + it('should result in equivalent messages when using log() and [LEVEL]()', () => { + const logger = winston.createLogger({ + level: "debug", + defaultMeta: { id: 'APP', service: 'Authentication' }, + format: winston.format.combine( + winston.format.printf( + info => `${info.service} - ${info.level}: [${info.id}] ${info.message}` + ) + ), + transports: [mockTransports.inMemory(levelOutput)] + }); + + logger.info("This is my info"); + logger.log({level: "info", message: "This is my info"}); + assume(levelOutput[0][MESSAGE]).eqls(levelOutput[1][MESSAGE]); + }); + }); + }) + describe('Backwards Compatability', function () { describe('Winston V2 Log', function () { it('.log(level, message)', function (done) {