From f7afe085399a3ff65f16c46696fd06fb18650c61 Mon Sep 17 00:00:00 2001 From: Aaron Houlihan Date: Tue, 9 Apr 2019 16:47:08 -0400 Subject: [PATCH 1/5] [SER-281] Entire Implementation --- package.json | 2 +- src/index.js | 64 ++++++++------ test/format.test.js | 207 +++++++++++++++++++++++++++++++++++--------- yarn.lock | 60 +++++++++---- 4 files changed, 250 insertions(+), 83 deletions(-) diff --git a/package.json b/package.json index 0e00ce5..918a327 100644 --- a/package.json +++ b/package.json @@ -39,7 +39,7 @@ "dependencies": { "lodash": "^4.17.11", "os": "^0.1.1", - "winston": "^3.1.0" + "winston": "^3.2.1" }, "devDependencies": { "@babel/cli": "^7.1.5", diff --git a/src/index.js b/src/index.js index e0a5119..09901bc 100644 --- a/src/index.js +++ b/src/index.js @@ -1,6 +1,7 @@ import winston from 'winston'; import _ from 'lodash'; import os from 'os'; +import util from 'util'; const { format } = winston; const { @@ -21,28 +22,17 @@ const addMetaFormat = format((info, opts) => { return _.defaults(info, options); }); -const consoleFormat = printf(info => `${info.timestamp} ${info.level}: ${info.message}`); +const consoleFormat = printf(info => util.format( + '%s %s %s %s %s', + info.timestamp, + info.level, + (typeof info.message === 'string') ? info.message : `\n${JSON.stringify(info.message, null, 2)}`, + (info.stack) ? `\n${info.stack}` : '', + (!_.isEmpty(parseInfo(info))) ? `\n${JSON.stringify(parseInfo(info), null, 2)}` : '' +)); const jsonFormat = printf((info) => { - function parseInfo(infoObj) { - return _.omit(infoObj, [ - 'err', - 'hostname', - 'level', - 'logger', - 'message', - 'meta', - 'name', - 'node_env', - 'service', - 'stack', - 'timestamp', - 'typeFormat', - 'version' - ]); - } - - return JSON.stringify({ + const logObject = { service: info.service || '', logger: info.logger || 'application-logger', hostname: info.hostname || '', @@ -57,12 +47,17 @@ const jsonFormat = printf((info) => { time: info.timestamp || '', }, event: parseInfo(info), - }, - err: { + } + }; + + if (info.stack) { + logObject.err = { name: info.name, stack: info.stack - } - }); + }; + } + + return JSON.stringify(logObject); }); /** @@ -97,9 +92,28 @@ function configuredFormatter(options = {}) { throw new Error(`${typeFormat} is not json or console.`); } +function parseInfo(infoObj) { + return _.omit(infoObj, [ + 'err', + 'hostname', + 'level', + 'logger', + 'message', + 'meta', + 'name', + 'node_env', + 'service', + 'stack', + 'timestamp', + 'typeFormat', + 'version' + ]); +} + module.exports = { addMetaFormat, configuredFormatter, consoleFormat, - jsonFormat + jsonFormat, + parseInfo }; diff --git a/test/format.test.js b/test/format.test.js index 3f0cfe7..f606e56 100644 --- a/test/format.test.js +++ b/test/format.test.js @@ -1,8 +1,10 @@ /* eslint-env jest */ -import winston from 'winston'; +import _ from 'lodash'; import SpyTransport from '@chrisalderson/winston-spy'; // eslint-disable-line no-unused-vars -import { configuredFormatter } from '../lib'; // eslint-disable-line import/named +import util from 'util'; +import winston from 'winston'; +import { configuredFormatter, parseInfo } from '../lib'; // eslint-disable-line import/named const { createLogger } = winston; @@ -10,9 +12,9 @@ let options; let logger; let spy; -function testLoggerInfo(testOptions, testSpy) { +function testLoggerInfo(testOptions, testSpy, ...loggerArgs) { logger.format = configuredFormatter(testOptions); - logger.info('message', { foo: 'bar' }); + logger.info(...loggerArgs); expect(testSpy).toHaveBeenCalled(); } @@ -37,77 +39,202 @@ describe('configuredFormatter testing', () => { spy = jest.fn((info) => { const sym = Symbol.for('message'); const testMsg = info[sym]; - expect(testMsg).toEqual(`${info.timestamp} ${info.level}: ${info.message}`); + const expectedMessage = util.format( + '%s %s %s %s %s', + info.timestamp, + info.level, + (typeof info.message === 'string') ? info.message : `\n${JSON.stringify(info.message, null, 2)}`, + (info.stack) ? `\n${info.stack}` : '', + (!_.isEmpty(parseInfo(info))) ? `\n${JSON.stringify(parseInfo(info), null, 2)}` : '' + ); + expect(testMsg).toEqual(expectedMessage); }); logger.add(new winston.transports.SpyTransport({ spy })); }); - test('it passes console format check', (done) => { + + test('it supports signature logger.info("message")', (done) => { + options.typeFormat = 'console'; + testLoggerInfo(options, spy, 'message'); + done(); + }); + + test('it supports signature logger.info(new Error("error message"))', (done) => { + options.typeFormat = 'console'; + testLoggerInfo(options, spy, new Error('error message')); + done(); + }); + + test('it supports signature logger.info("message", new Error("error message"))', (done) => { + options.typeFormat = 'console'; + testLoggerInfo(options, spy, 'message', new Error('error message')); + done(); + }); + + test('it supports signature logger.info({ a: "a", b: "b" })', (done) => { + options.typeFormat = 'console'; + testLoggerInfo(options, spy, { a: 'a', b: 'b' }); + done(); + }); + + test('it supports signature logger.info({ name: "some name", stack: "some stack" })', (done) => { + options.typeFormat = 'console'; + testLoggerInfo(options, spy, { name: 'some name', stack: 'some stack' }); + done(); + }); + + test('it supports signature logger.info("message", { a: "a", b: "b" })', (done) => { options.typeFormat = 'console'; - testLoggerInfo(options, spy); + testLoggerInfo(options, spy, 'message', { a: 'a', b: 'b' }); done(); }); + + test('it supports signature logger.info("message", { name: "some name", stack: "some stack" })', (done) => { + options.typeFormat = 'console'; + testLoggerInfo(options, spy, 'message', { name: 'some name', stack: 'some stack' }); + done(); + }); + + const errWithCode = new Error('error message'); + errWithCode.code = 'SOME_ERROR_CODE'; + + test('it supports signature logger.info(someError), where someError has additional members', (done) => { + options.typeFormat = 'console'; + testLoggerInfo(options, spy, errWithCode); + done(); + }); + + test('it supports signature logger.info("message", someError), where someError has additional members', (done) => { + options.typeFormat = 'console'; + testLoggerInfo(options, spy, 'message', errWithCode); + done(); + }); + test('it checks NODE_ENV for development and sets to console', (done) => { process.env.NODE_ENV = 'dev'; - testLoggerInfo(options, spy); + testLoggerInfo(options, spy, 'message', { foo: 'bar' }); done(); }); }); - describe('json output (info)', () => { + describe('json output', () => { beforeEach(() => { spy = jest.fn((info) => { const sym = Symbol.for('message'); const testMsg = info[sym]; const parsedTestMsg = JSON.parse(testMsg); - expect(parsedTestMsg.level).toEqual('info'); - expect(parsedTestMsg.msg).toEqual('message'); - expect(parsedTestMsg.service).toEqual(options.service); - expect(parsedTestMsg.logger).toEqual(options.logger); - expect(parsedTestMsg.meta.service.version).toEqual(options.version); - expect(parsedTestMsg.meta.event.foo).toEqual('bar'); + const expectedMessage = { + service: options.service, + logger: options.logger, + hostname: info.hostname, + level: 'info', + msg: info.message, + meta: { + service: { + version: options.version, + node_env: info.node_env + }, + logger: { + time: info.timestamp + }, + // The spy adds extra symbols to 'info' that a normal winston transport does + // not. They must be stripped in order to get the same result as the real + // formatter gets when it does `parseInfo(info)`. + event: parseInfo(stripSymbols(info)) + } + }; + + if (info.stack) { + expectedMessage.err = { + name: info.name, + stack: info.stack + }; + } + + expect(parsedTestMsg).toEqual(expectedMessage); }); logger.add(new winston.transports.SpyTransport({ spy })); }); - test('it passes json format check', (done) => { + + test('it supports signature logger.info("message")', (done) => { options.typeFormat = 'json'; - testLoggerInfo(options, spy); + testLoggerInfo(options, spy, 'message'); done(); }); + + test('it supports signature logger.info(new Error("error message"))', (done) => { + options.typeFormat = 'json'; + testLoggerInfo(options, spy, new Error('error message')); + done(); + }); + + test('it supports signature logger.info("message", new Error("error message"))', (done) => { + options.typeFormat = 'json'; + testLoggerInfo(options, spy, 'message', new Error('error message')); + done(); + }); + + test('it supports signature logger.info({ a: "a", b: "b" })', (done) => { + options.typeFormat = 'json'; + testLoggerInfo(options, spy, { a: 'a', b: 'b' }); + done(); + }); + + test('it supports signature logger.info({ name: "some name", stack: "some stack" })', (done) => { + options.typeFormat = 'json'; + testLoggerInfo(options, spy, { name: 'some name', stack: 'some stack' }); + done(); + }); + + test('it supports signature logger.info("message", { a: "a", b: "b" })', (done) => { + options.typeFormat = 'json'; + testLoggerInfo(options, spy, 'message', { a: 'a', b: 'b' }); + done(); + }); + + test('it supports signature logger.info("message", { name: "some name", stack: "some stack" })', (done) => { + options.typeFormat = 'json'; + testLoggerInfo(options, spy, 'message', { name: 'some name', stack: 'some stack' }); + done(); + }); + + const errWithCode = new Error('error message'); + errWithCode.code = 'SOME_ERROR_CODE'; + + test('it supports signature logger.info(someError), where someError has additional members', (done) => { + options.typeFormat = 'json'; + testLoggerInfo(options, spy, errWithCode); + done(); + }); + + test('it supports signature logger.info("message", someError), where someError has additional members', (done) => { + options.typeFormat = 'json'; + testLoggerInfo(options, spy, 'message', errWithCode); + done(); + }); + test('it checks NODE_ENV for other', (done) => { process.env.NODE_ENV = 'test'; - testLoggerInfo(options, spy); + testLoggerInfo(options, spy, 'message', { foo: 'bar' }); done(); }); test('it errors when typeFormat is incorrect', (done) => { try { options.typeFormat = 'test'; - testLoggerInfo(options, spy); + testLoggerInfo(options, spy, 'message', { foo: 'bar' }); } catch (e) { expect(e.message).toBe('test is not json or console.'); done(); } }); }); - - describe('json output (error)', () => { - beforeEach(() => { - spy = jest.fn((info) => { - const sym = Symbol.for('message'); - const testMsg = info[sym]; - const parsedTestMess = JSON.parse(testMsg); - expect(parsedTestMess.err.stack).toEqual(expect.stringMatching('Error: ')); - }); - logger.add(new winston.transports.SpyTransport({ spy })); - }); - test('error should appear in message', (done) => { - options.typeFormat = 'json'; - logger.format = configuredFormatter(options); - - const error = new Error('err'); - logger.error(error); - expect(spy).toHaveBeenCalled(); - done(); - }); - }); }); + +function stripSymbols(obj) { + const objWithoutSymbols = {}; + // eslint-disable-next-line no-restricted-syntax + for (const property of Object.keys(obj)) { + objWithoutSymbols[property] = obj[property]; + } + return objWithoutSymbols; +} diff --git a/yarn.lock b/yarn.lock index 89e5e7b..17cb2aa 100644 --- a/yarn.lock +++ b/yarn.lock @@ -751,12 +751,19 @@ async-limiter@~1.0.0: version "1.0.0" resolved "https://registry.yarnpkg.com/async-limiter/-/async-limiter-1.0.0.tgz#78faed8c3d074ab81f22b4e985d79e8738f720f8" -async@^2.1.4, async@^2.5.0, async@^2.6.0: +async@^2.1.4, async@^2.5.0: version "2.6.1" resolved "https://registry.yarnpkg.com/async/-/async-2.6.1.tgz#b245a23ca71930044ec53fa46aa00a3e87c6a610" dependencies: lodash "^4.17.10" +async@^2.6.1: + version "2.6.2" + resolved "https://registry.yarnpkg.com/async/-/async-2.6.2.tgz#18330ea7e6e313887f5d2f2a904bac6fe4dd5381" + integrity sha512-H1qVYh1MYhEEFLsP97cVKqCGo7KfCyTt6uEWqsTBr9SO84oK9Uwbyd/yCW+6rKJLHksBNUVWZDAjfS+Ccx0Bbg== + dependencies: + lodash "^4.17.11" + asynckit@^0.4.0: version "0.4.0" resolved "https://registry.yarnpkg.com/asynckit/-/asynckit-0.4.0.tgz#c79ed97f7f34cb8f2ba1bc9790bcc366474b4b79" @@ -2089,7 +2096,7 @@ inflight@^1.0.4: once "^1.3.0" wrappy "1" -inherits@2, inherits@^2.0.1, inherits@~2.0.3: +inherits@2, inherits@^2.0.1, inherits@^2.0.3, inherits@~2.0.3: version "2.0.3" resolved "https://registry.yarnpkg.com/inherits/-/inherits-2.0.3.tgz#633c2c83e3da42a502f52466022480f4208261de" @@ -2916,15 +2923,16 @@ lodash@^4.13.1, lodash@^4.17.10, lodash@^4.17.11, lodash@^4.17.4, lodash@^4.17.5 version "4.17.11" resolved "https://registry.yarnpkg.com/lodash/-/lodash-4.17.11.tgz#b39ea6229ef607ecd89e2c8df12536891cac9b8d" -logform@^1.9.1: - version "1.10.0" - resolved "https://registry.yarnpkg.com/logform/-/logform-1.10.0.tgz#c9d5598714c92b546e23f4e78147c40f1e02012e" +logform@^2.1.1: + version "2.1.2" + resolved "https://registry.yarnpkg.com/logform/-/logform-2.1.2.tgz#957155ebeb67a13164069825ce67ddb5bb2dd360" + integrity sha512-+lZh4OpERDBLqjiwDLpAWNQu6KMjnlXH2ByZwCuSqVPJletw0kTWJf5CgSNAUKn1KUkv3m2cUz/LK8zyEy7wzQ== dependencies: colors "^1.2.1" fast-safe-stringify "^2.0.4" fecha "^2.3.3" ms "^2.1.1" - triple-beam "^1.2.0" + triple-beam "^1.3.0" lolex@^2.3.2: version "2.7.5" @@ -3630,6 +3638,15 @@ readable-stream@^2.0.1, readable-stream@^2.0.2, readable-stream@^2.0.6, readable string_decoder "~1.1.1" util-deprecate "~1.0.1" +readable-stream@^3.1.1: + version "3.3.0" + resolved "https://registry.yarnpkg.com/readable-stream/-/readable-stream-3.3.0.tgz#cb8011aad002eb717bf040291feba8569c986fb9" + integrity sha512-EsI+s3k3XsW+fU8fQACLN59ky34AZ14LoeVZpYwmZvldCFo0r0gnelwF2TcMjLor/BTL5aDJVBMkss0dthToPw== + dependencies: + inherits "^2.0.3" + string_decoder "^1.1.1" + util-deprecate "^1.0.1" + readdirp@^2.0.0: version "2.2.1" resolved "https://registry.yarnpkg.com/readdirp/-/readdirp-2.2.1.tgz#0e87622a3325aa33e892285caf8b4e846529a525" @@ -4105,6 +4122,13 @@ string-width@^1.0.1: is-fullwidth-code-point "^2.0.0" strip-ansi "^4.0.0" +string_decoder@^1.1.1: + version "1.2.0" + resolved "https://registry.yarnpkg.com/string_decoder/-/string_decoder-1.2.0.tgz#fe86e738b19544afe70469243b2a1ee9240eae8d" + integrity sha512-6YqyX6ZWEYguAxgZzHGL7SsCeGx3V2TtOTqZz1xSTSWnqsbWwbptafNyvf/ACquZUXV3DANr5BDIwNYe1mN42w== + dependencies: + safe-buffer "~5.1.0" + string_decoder@~1.1.1: version "1.1.1" resolved "https://registry.yarnpkg.com/string_decoder/-/string_decoder-1.1.1.tgz#9cf1611ba62685d7030ae9e4ba34149c3af03fc8" @@ -4370,7 +4394,7 @@ use@^3.1.0: version "3.1.1" resolved "https://registry.yarnpkg.com/use/-/use-3.1.1.tgz#d50c8cac79a19fbc20f2911f56eb973f4e10070f" -util-deprecate@~1.0.1: +util-deprecate@^1.0.1, util-deprecate@~1.0.1: version "1.0.2" resolved "https://registry.yarnpkg.com/util-deprecate/-/util-deprecate-1.0.2.tgz#450d4dc9fa70de732762fbd2d4a28981419a0ccf" @@ -4475,26 +4499,28 @@ winston-transport@^3.2.1: version "3.2.1" resolved "https://registry.yarnpkg.com/winston-transport/-/winston-transport-3.2.1.tgz#5b79b294096b1a18bfe502e769491553a2cb1042" -winston-transport@^4.2.0: - version "4.2.0" - resolved "https://registry.yarnpkg.com/winston-transport/-/winston-transport-4.2.0.tgz#a20be89edf2ea2ca39ba25f3e50344d73e6520e5" +winston-transport@^4.3.0: + version "4.3.0" + resolved "https://registry.yarnpkg.com/winston-transport/-/winston-transport-4.3.0.tgz#df68c0c202482c448d9b47313c07304c2d7c2c66" + integrity sha512-B2wPuwUi3vhzn/51Uukcao4dIduEiPOcOt9HJ3QeaXgkJ5Z7UwpBzxS4ZGNHtrxrUvTwemsQiSys0ihOf8Mp1A== dependencies: readable-stream "^2.3.6" triple-beam "^1.2.0" -winston@^3.1.0: - version "3.1.0" - resolved "https://registry.yarnpkg.com/winston/-/winston-3.1.0.tgz#80724376aef164e024f316100d5b178d78ac5331" +winston@^3.2.1: + version "3.2.1" + resolved "https://registry.yarnpkg.com/winston/-/winston-3.2.1.tgz#63061377976c73584028be2490a1846055f77f07" + integrity sha512-zU6vgnS9dAWCEKg/QYigd6cgMVVNwyTzKs81XZtTFuRwJOcDdBg7AU0mXVyNbs7O5RH2zdv+BdNZUlx7mXPuOw== dependencies: - async "^2.6.0" + async "^2.6.1" diagnostics "^1.1.1" is-stream "^1.1.0" - logform "^1.9.1" + logform "^2.1.1" one-time "0.0.4" - readable-stream "^2.3.6" + readable-stream "^3.1.1" stack-trace "0.0.x" triple-beam "^1.3.0" - winston-transport "^4.2.0" + winston-transport "^4.3.0" wordwrap@~0.0.2: version "0.0.3" From a8ed890b60d6583bc87cba424417fc29bd81c4c2 Mon Sep 17 00:00:00 2001 From: Aaron Houlihan Date: Thu, 11 Apr 2019 20:20:15 -0400 Subject: [PATCH 2/5] Support logger.info(new Error('message'), {a:'a', b:'b'}) --- package.json | 4 ++ src/index.js | 83 +++++++++++++++++++++++++++++++---- test/format.test.js | 104 ++++++++++++++++++++++++++++++++++++++++++-- 3 files changed, 180 insertions(+), 11 deletions(-) diff --git a/package.json b/package.json index 918a327..045f469 100644 --- a/package.json +++ b/package.json @@ -34,6 +34,10 @@ { "name": "Ryan Harrison", "email": "ryan@amida.com" + }, + { + "name": "Aaron Houlihan", + "email": "aaron@amida.com" } ], "dependencies": { diff --git a/src/index.js b/src/index.js index 09901bc..9eeaf9c 100644 --- a/src/index.js +++ b/src/index.js @@ -22,14 +22,57 @@ const addMetaFormat = format((info, opts) => { return _.defaults(info, options); }); -const consoleFormat = printf(info => util.format( - '%s %s %s %s %s', - info.timestamp, - info.level, - (typeof info.message === 'string') ? info.message : `\n${JSON.stringify(info.message, null, 2)}`, - (info.stack) ? `\n${info.stack}` : '', - (!_.isEmpty(parseInfo(info))) ? `\n${JSON.stringify(parseInfo(info), null, 2)}` : '' -)); +const consoleFormat = printf((info) => { + let message; + if (info.message instanceof Error) { + // eslint-disable-next-line prefer-destructuring + message = info.message.message; + } else if (typeof info.message === 'string') { + // eslint-disable-next-line prefer-destructuring + message = info.message; + } else { + message = `\n${JSON.stringify(info.message, null, 2)}`; + } + + const stack = info.stack || info.message.stack; + + let event; + let eventString; + if (info.message instanceof Error) { + event = parseInfo(info); + + // Unfortunately, in this case... + // ``` + // const err = new Error('error message'); + // err.code = 'SOME_CODE' + // logger.info(err, { a: 'a', b: 'b' }) + // ``` + // ...the configured logger members (such as timestamp, service, node_env, etc.) + // are members of info (expected) but also get added as members of info.message + // (completely unexpected), so we have to parseInfo() those out. + const errorAdditionalMembers = parseInfo(info.message); + // eslint-disable-next-line no-restricted-syntax + for (const property of Object.keys(errorAdditionalMembers)) { + event[property] = errorAdditionalMembers[property]; + } + + eventString = JSON.stringify(event, null, 2); + } else if (!_.isEmpty(parseInfo(info))) { + event = parseInfo(info); + eventString = JSON.stringify(event, null, 2); + } else { + eventString = ''; + } + + return util.format( + '%s %s %s %s %s', + info.timestamp, + info.level, + message, + (stack) ? `\n${stack}` : '', + eventString ? `\n${eventString}` : '' + ); +}); const jsonFormat = printf((info) => { const logObject = { @@ -57,6 +100,30 @@ const jsonFormat = printf((info) => { }; } + if (info.message instanceof Error) { + // Unfortunately, in this case... + // ``` + // const err = new Error('error message'); + // err.code = 'SOME_CODE' + // logger.info(err, { a: 'a', b: 'b' }) + // ``` + // ...the configured logger members (such as timestamp, service, node_env, etc.) + // are members of info (expected) but also get added as members of info.message + // (completely unexpected), so we have to parseInfo() those out. + const errorAdditionalMembers = parseInfo(info.message); + // eslint-disable-next-line no-restricted-syntax + for (const property of Object.keys(errorAdditionalMembers)) { + logObject.meta.event[property] = errorAdditionalMembers[property]; + } + + logObject.msg = info.message.message; + + logObject.err = { + name: info.message.name, + stack: info.message.stack + }; + } + return JSON.stringify(logObject); }); diff --git a/test/format.test.js b/test/format.test.js index f606e56..1971741 100644 --- a/test/format.test.js +++ b/test/format.test.js @@ -39,14 +39,57 @@ describe('configuredFormatter testing', () => { spy = jest.fn((info) => { const sym = Symbol.for('message'); const testMsg = info[sym]; + + let message; + if (info.message instanceof Error) { + // eslint-disable-next-line prefer-destructuring + message = info.message.message; + } else if (typeof info.message === 'string') { + // eslint-disable-next-line prefer-destructuring + message = info.message; + } else { + message = `\n${JSON.stringify(info.message, null, 2)}`; + } + + const stack = info.stack || info.message.stack; + + let event; + let eventString; + if (info.message instanceof Error) { + event = parseInfo(info); + + // Unfortunately, in this case... + // ``` + // const err = new Error('error message'); + // err.code = 'SOME_CODE' + // logger.info(err, { a: 'a', b: 'b' }) + // ``` + // ...the configured logger members (such as timestamp, service, node_env, etc.) + // are members of info (expected) but also get added as members of info.message + // (completely unexpected), so we have to parseInfo() those out. + const errorAdditionalMembers = parseInfo(info.message); + // eslint-disable-next-line no-restricted-syntax + for (const property of Object.keys(errorAdditionalMembers)) { + event[property] = errorAdditionalMembers[property]; + } + + eventString = JSON.stringify(event, null, 2); + } else if (!_.isEmpty(parseInfo(info))) { + event = parseInfo(info); + eventString = JSON.stringify(event, null, 2); + } else { + eventString = ''; + } + const expectedMessage = util.format( '%s %s %s %s %s', info.timestamp, info.level, - (typeof info.message === 'string') ? info.message : `\n${JSON.stringify(info.message, null, 2)}`, - (info.stack) ? `\n${info.stack}` : '', - (!_.isEmpty(parseInfo(info))) ? `\n${JSON.stringify(parseInfo(info), null, 2)}` : '' + message, + (stack) ? `\n${stack}` : '', + eventString ? `\n${eventString}` : '' ); + expect(testMsg).toEqual(expectedMessage); }); logger.add(new winston.transports.SpyTransport({ spy })); @@ -94,6 +137,12 @@ describe('configuredFormatter testing', () => { done(); }); + test('it supports signature logger.info(new Error("error message"), { a: "a", b: "b" })', (done) => { + options.typeFormat = 'console'; + testLoggerInfo(options, spy, new Error('error message'), { a: 'a', b: 'b' }); + done(); + }); + const errWithCode = new Error('error message'); errWithCode.code = 'SOME_ERROR_CODE'; @@ -109,6 +158,12 @@ describe('configuredFormatter testing', () => { done(); }); + test('it supports signature logger.info(someError, { a: "a", b: "b" }), where someError has additional members', (done) => { + options.typeFormat = 'console'; + testLoggerInfo(options, spy, errWithCode, { a: 'a', b: 'b' }); + done(); + }); + test('it checks NODE_ENV for development and sets to console', (done) => { process.env.NODE_ENV = 'dev'; testLoggerInfo(options, spy, 'message', { foo: 'bar' }); @@ -151,6 +206,30 @@ describe('configuredFormatter testing', () => { }; } + if (info.message instanceof Error) { + // Unfortunately, in this case... + // ``` + // const err = new Error('error message'); + // err.code = 'SOME_CODE' + // logger.info(err, { a: 'a', b: 'b' }) + // ``` + // ...the configured logger members (such as timestamp, service, node_env, etc.) + // are members of info (expected) but also get added as members of info.message + // (completely unexpected), so we have to parseInfo() those out. + const errorAdditionalMembers = parseInfo(info.message); + // eslint-disable-next-line no-restricted-syntax + for (const property of Object.keys(errorAdditionalMembers)) { + expectedMessage.meta.event[property] = errorAdditionalMembers[property]; + } + + expectedMessage.msg = info.message.message; + + expectedMessage.err = { + name: info.message.name, + stack: info.message.stack + }; + } + expect(parsedTestMsg).toEqual(expectedMessage); }); logger.add(new winston.transports.SpyTransport({ spy })); @@ -180,6 +259,12 @@ describe('configuredFormatter testing', () => { done(); }); + test('it supports signature logger.info(new Error("error message"), { a: "a", b: "b" })', (done) => { + options.typeFormat = 'json'; + testLoggerInfo(options, spy, new Error('error message'), { a: 'a', b: 'b' }); + done(); + }); + test('it supports signature logger.info({ name: "some name", stack: "some stack" })', (done) => { options.typeFormat = 'json'; testLoggerInfo(options, spy, { name: 'some name', stack: 'some stack' }); @@ -198,6 +283,12 @@ describe('configuredFormatter testing', () => { done(); }); + test('it supports signature logger.info(new Error("error message"), { a: "a", b: "b" })', (done) => { + options.typeFormat = 'json'; + testLoggerInfo(options, spy, new Error('error message'), { a: 'a', b: 'b' }); + done(); + }); + const errWithCode = new Error('error message'); errWithCode.code = 'SOME_ERROR_CODE'; @@ -213,11 +304,18 @@ describe('configuredFormatter testing', () => { done(); }); + test('it supports signature logger.info(someError, { a: "a", b: "b" }), where someError has additional members', (done) => { + options.typeFormat = 'json'; + testLoggerInfo(options, spy, errWithCode, { a: 'a', b: 'b' }); + done(); + }); + test('it checks NODE_ENV for other', (done) => { process.env.NODE_ENV = 'test'; testLoggerInfo(options, spy, 'message', { foo: 'bar' }); done(); }); + test('it errors when typeFormat is incorrect', (done) => { try { options.typeFormat = 'test'; From a9116044b24c6ec00e4e83fba70dc88bcc6011d3 Mon Sep 17 00:00:00 2001 From: Aaron Houlihan Date: Thu, 11 Apr 2019 22:26:54 -0400 Subject: [PATCH 3/5] Update README.md with new examples --- README.md | 232 +++++++++++++++++++++++++++++++++++++++++++++++++----- 1 file changed, 211 insertions(+), 21 deletions(-) diff --git a/README.md b/README.md index 8b1ea53..58b521b 100644 --- a/README.md +++ b/README.md @@ -44,17 +44,69 @@ err = new Error('Heroic BSoD') logger.error(err) ``` +## Configuration +ENV +- `NODE_ENV=dev` || `NODE_ENV=development` => `options.typeFormat=console` +- Otherwise, `options.typeFormat=json` (default) + +| Option | Default | Type | +| -------------------- | ----------------------------- | ----------------------- | +| `options.typeFormat` | Default: 'json' | Enum: 'console', 'json' | +| `options.hostname` | Default: `os.hostname()` | String | +| `options.logger` | Default: 'application-logger' | String | +| `options.node_env` | Default: `ENV NODE_ENV` | String | +| `options.service` | | String | +| `options.version` | | String | + +## Test +```bash +yarn install +yarn test +yarn test:coverage +``` + ## Output ### Json logging ```javascript -> logger.info('message', {foo: 'bar', baz: 'qux'}); + +> const err = new Error('error message'); +> const err.code = 'SOME_CODE'; +> // The colon and space here are recommended due to this bug in winston (https://github.com/winstonjs/winston/issues/1634) +> logger.info('log message: ', err); { "service": "test-service", "logger": "Winston-JSON-Formatter", "hostname": "host", "level": "info", - "msg": "message", + "msg": "log message: error message", + "meta": { + "service": { + "version": "1.0.0", + "node_env": "" + }, + "logger": { + "time": "2018-11-28T02:52:06.700Z" + }, + "event": { + "code": "SOME_CODE" + } + }, + "err": { + // There should be a member `"name": "Error"` here if it were not for winston bug (https://github.com/winstonjs/winston/issues/1635) + "stack": "THE_ERROR_STACK" + } +} + +> const err = new Error('error message'); +> const err.code = 'SOME_CODE'; +> logger.info(err, {foo: 'bar', baz: 'qux'}); +{ + "service": "test-service", + "logger": "Winston-JSON-Formatter", + "hostname": "host", + "level": "info", + "msg": "message: error message", "meta": { "service": { "version": "1.0.0", @@ -65,33 +117,171 @@ logger.error(err) }, "event": { "foo": "bar", - "baz": "qux" + "baz": "qux", + "code": "SOME_CODE" } }, - "err": {} + "err": { + "name": "Error" + "stack": "THE_ERROR_STACK" + } } ``` ### Console logging ![console log style](docs/console-log-example.png) -## Configuration -ENV -- `NODE_ENV=dev` || `NODE_ENV=development` => `options.typeFormat=console` -- Otherwise, `options.typeFormat=json` (default) -| Option | Default | Type | -| -------------------- | ----------------------------- | ----------------------- | -| `options.typeFormat` | Default: 'json' | Enum: 'console', 'json' | -| `options.hostname` | Default: `os.hostname()` | String | -| `options.logger` | Default: 'application-logger' | String | -| `options.node_env` | Default: `ENV NODE_ENV` | String | -| `options.service` | | String | -| `options.version` | | String | +```sh +# Generally, the format is: -## Test -```bash -yarn install -yarn test -yarn test:coverage +# timestamp level message +# stack_if_one_exists +# { +# other: 'members-if-they-exist' +# } + +# > logger.info("log message") ------------------------------------------------------------------ +2019-04-12T02:10:11.091Z info log message +# ---- + + +# > logger.info(new Error("error message")) ------------------------------------------------------------------ +2019-04-12T02:10:11.094Z info error message +Error: error message + at Object. (/Users/houli/docs/gitrepos/amida-tech/winston-json-formatter/experiment.js:38:13) + at Module._compile (module.js:653:30) + at Object.Module._extensions..js (module.js:664:10) + at Module.load (module.js:566:32) + at tryModuleLoad (module.js:506:12) + at Function.Module._load (module.js:498:3) + at Function.Module.runMain (module.js:694:10) + at startup (bootstrap_node.js:204:16) + at bootstrap_node.js:625:3 +# ---- + + +# > logger.info("message", new Error("error message")) ------------------------------------------------------------------ +2019-04-12T02:10:11.095Z info log messageerror message +Error: error message + at Object. (/Users/houli/docs/gitrepos/amida-tech/winston-json-formatter/experiment.js:41:28) + at Module._compile (module.js:653:30) + at Object.Module._extensions..js (module.js:664:10) + at Module.load (module.js:566:32) + at tryModuleLoad (module.js:506:12) + at Function.Module._load (module.js:498:3) + at Function.Module.runMain (module.js:694:10) + at startup (bootstrap_node.js:204:16) + at bootstrap_node.js:625:3 +# ---- + + +# > logger.info({a: "a", b: "b"}) ------------------------------------------------------------------ +2019-04-12T02:10:11.095Z info +{ + "a": "a", + "b": "b" +} +# ---- + + +# > logger.info(new Error("error message"), { a: "a", b: "b" } ) ------------------------------------------------------------------ +2019-04-12T02:10:11.096Z info error message +Error: error message + at Object. (/Users/houli/docs/gitrepos/amida-tech/winston-json-formatter/experiment.js:47:13) + at Module._compile (module.js:653:30) + at Object.Module._extensions..js (module.js:664:10) + at Module.load (module.js:566:32) + at tryModuleLoad (module.js:506:12) + at Function.Module._load (module.js:498:3) + at Function.Module.runMain (module.js:694:10) + at startup (bootstrap_node.js:204:16) + at bootstrap_node.js:625:3 +{ + "a": "a", + "b": "b" +} +# ---- + + +# Logging an object that is not an Error that does have a member named stack will confuse the logger. This is unavoidable. +# > logger.info({ name: "some name", stack: "some stack" }) ------------------------------------------------------------------ +2019-04-12T02:10:11.096Z info +{ + "name": "some name", + "stack": "some stack" +} +some stack +# ---- + + +# Logging an object that is not an Error that does have a member named stack will confuse the logger. This is unavoidable. +# > logger.info("message", { name: "some name", stack: "some stack" }) ------------------------------------------------------------------ +2019-04-12T02:10:11.096Z info message +some stack +# ---- + + +# > logger.info("message", { a: "a", b: "b" }) ------------------------------------------------------------------ +2019-04-12T02:10:11.096Z info message +{ + "a": "a", + "b": "b" +} +# ---- + + +# > const err = new Error("error message"); err.code = "SOME_CODE"; logger.info("message", new Error("error message")) ------------------------------------------------------------------ +2019-04-12T02:10:11.097Z info messageError A +Error: Error A + at Object. (/Users/houli/docs/gitrepos/amida-tech/winston-json-formatter/experiment.js:58:14) + at Module._compile (module.js:653:30) + at Object.Module._extensions..js (module.js:664:10) + at Module.load (module.js:566:32) + at tryModuleLoad (module.js:506:12) + at Function.Module._load (module.js:498:3) + at Function.Module.runMain (module.js:694:10) + at startup (bootstrap_node.js:204:16) + at bootstrap_node.js:625:3 +{ + "code": "SOME_CODE" +} +# ---- + + +# > const err = new Error("error message"); err.code = "SOME_CODE"; logger.info(new Error("error message")) ------------------------------------------------------------------ +2019-04-12T02:10:11.097Z info Error A +Error: Error A + at Object. (/Users/houli/docs/gitrepos/amida-tech/winston-json-formatter/experiment.js:58:14) + at Module._compile (module.js:653:30) + at Object.Module._extensions..js (module.js:664:10) + at Module.load (module.js:566:32) + at tryModuleLoad (module.js:506:12) + at Function.Module._load (module.js:498:3) + at Function.Module.runMain (module.js:694:10) + at startup (bootstrap_node.js:204:16) + at bootstrap_node.js:625:3 +{ + "code": "SOME_CODE" +} +# ---- + + +# > const err = new Error("error message"); err.code = "SOME_CODE"; logger.info(new Error("error message"), { a: "a", b: "b" } ) ------------------------------------------------------------------ +2019-04-12T02:10:11.097Z info Error A +Error: Error A + at Object. (/Users/houli/docs/gitrepos/amida-tech/winston-json-formatter/experiment.js:58:14) + at Module._compile (module.js:653:30) + at Object.Module._extensions..js (module.js:664:10) + at Module.load (module.js:566:32) + at tryModuleLoad (module.js:506:12) + at Function.Module._load (module.js:498:3) + at Function.Module.runMain (module.js:694:10) + at startup (bootstrap_node.js:204:16) + at bootstrap_node.js:625:3 +{ + "a": "a", + "b": "b", + "code": "SOME_CODE" +} ``` From 8f686bb536c2a4d3803770669b5fca80ce581a57 Mon Sep 17 00:00:00 2001 From: Aaron Houlihan Date: Fri, 12 Apr 2019 17:03:20 -0400 Subject: [PATCH 4/5] add logLevelGte() --- README.md | 37 ++++++++++++++++ src/index.js | 23 +++++++++- test/logLevelGte.test.js | 95 ++++++++++++++++++++++++++++++++++++++++ 3 files changed, 154 insertions(+), 1 deletion(-) create mode 100644 test/logLevelGte.test.js diff --git a/README.md b/README.md index 58b521b..8094ac5 100644 --- a/README.md +++ b/README.md @@ -285,3 +285,40 @@ Error: Error A "code": "SOME_CODE" } ``` + +## Miscellaneous Goodies + +This repo also provides a function to check if a particular log level is greater than the currently configured log level. + +Example useage: + +```js +// In some service... + +// config.js +module.exports = { + logLevel: 'info', +} + +// FancyCustomError.js +import { initLogLevelGte } from 'winston-json-formatter' +const config = require('../config/index.js') +const logLevelGte = initLogLevelGte(config.logLevel) + +class FancyCustomError extends Error { + constructor(rootErrorThatCouldHaveSecretStuffInIt, message, foo, bar) { + super() + + this.message = message + + if (logLevelGte('debug')) { + this.rootErrorThatCouldHaveSecretStuffInIt = rootErrorThatCouldHaveSecretStuffInIt + } + } +} + +// someFile.js +logger.info(new FancyCustomError(err, 'Error creating user')) + +// When the configured log level is 'info', you would see logged only 'Error creating user', but when the configured log level is 'debug', you would see all the guts and glory. +``` diff --git a/src/index.js b/src/index.js index 9eeaf9c..180e3f7 100644 --- a/src/index.js +++ b/src/index.js @@ -177,10 +177,31 @@ function parseInfo(infoObj) { ]); } +function initLogLevelGte(configuredLogLevel = 'info') { + // Like JSON.parse(), this function and has the ability to throw errors. + // Therefore calls to it must be wrapped in try/catch. + return function logLevelGte(checkLogLevel) { + const validLogLevels = Object.keys(winston.config.npm.levels); + + // TODO: Improve checking via using some sort of typing instead?? + if (validLogLevels.indexOf(checkLogLevel) === -1) { + // eslint-disable-next-line max-len + throw new Error(`logLevelGte(): 'checkLogLevel' is ${checkLogLevel}, but it must be one of the valid levels ('error', 'warn', 'info', 'verbose', 'debug', 'silly').`); + } + + if (validLogLevels.indexOf(configuredLogLevel) >= validLogLevels.indexOf(checkLogLevel)) { + return true; + } + + return false; + }; +} + module.exports = { addMetaFormat, configuredFormatter, consoleFormat, jsonFormat, - parseInfo + parseInfo, + initLogLevelGte }; diff --git a/test/logLevelGte.test.js b/test/logLevelGte.test.js new file mode 100644 index 0000000..e171b5d --- /dev/null +++ b/test/logLevelGte.test.js @@ -0,0 +1,95 @@ +/* eslint-env jest */ + +import { initLogLevelGte } from '../src'; // eslint-disable-line import/named + +const logLevelGte = initLogLevelGte(); + +describe.only('#logLevelGte()', () => { + it('Throws error if called with invalid log level', () => { + expect(() => logLevelGte('not_a_real_log_level')).toThrow(); + }); + + it('Works when initialized with initLogLevelGte("error")', () => { + // eslint-disable-next-line no-shadow + const logLevelGte = initLogLevelGte('error'); + expect(logLevelGte('error')).toEqual(true); + expect(logLevelGte('warn')).toEqual(false); + expect(logLevelGte('info')).toEqual(false); + expect(logLevelGte('http')).toEqual(false); + expect(logLevelGte('verbose')).toEqual(false); + expect(logLevelGte('debug')).toEqual(false); + expect(logLevelGte('silly')).toEqual(false); + }); + + it('Works when initialized with initLogLevelGte("warn")', () => { + // eslint-disable-next-line no-shadow + const logLevelGte = initLogLevelGte('warn'); + expect(logLevelGte('error')).toEqual(true); + expect(logLevelGte('warn')).toEqual(true); + expect(logLevelGte('info')).toEqual(false); + expect(logLevelGte('http')).toEqual(false); + expect(logLevelGte('verbose')).toEqual(false); + expect(logLevelGte('debug')).toEqual(false); + expect(logLevelGte('silly')).toEqual(false); + }); + + it('Works when initialized with initLogLevelGte("info")', () => { + // eslint-disable-next-line no-shadow + const logLevelGte = initLogLevelGte('info'); + expect(logLevelGte('error')).toEqual(true); + expect(logLevelGte('warn')).toEqual(true); + expect(logLevelGte('info')).toEqual(true); + expect(logLevelGte('http')).toEqual(false); + expect(logLevelGte('verbose')).toEqual(false); + expect(logLevelGte('debug')).toEqual(false); + expect(logLevelGte('silly')).toEqual(false); + }); + + it('Works when initialized with initLogLevelGte("http")', () => { + // eslint-disable-next-line no-shadow + const logLevelGte = initLogLevelGte('http'); + expect(logLevelGte('error')).toEqual(true); + expect(logLevelGte('warn')).toEqual(true); + expect(logLevelGte('info')).toEqual(true); + expect(logLevelGte('http')).toEqual(true); + expect(logLevelGte('verbose')).toEqual(false); + expect(logLevelGte('debug')).toEqual(false); + expect(logLevelGte('silly')).toEqual(false); + }); + + it('Works when initialized with initLogLevelGte("verbose")', () => { + // eslint-disable-next-line no-shadow + const logLevelGte = initLogLevelGte('verbose'); + expect(logLevelGte('error')).toEqual(true); + expect(logLevelGte('warn')).toEqual(true); + expect(logLevelGte('info')).toEqual(true); + expect(logLevelGte('http')).toEqual(true); + expect(logLevelGte('verbose')).toEqual(true); + expect(logLevelGte('debug')).toEqual(false); + expect(logLevelGte('silly')).toEqual(false); + }); + + it('Works when initialized with initLogLevelGte("debug")', () => { + // eslint-disable-next-line no-shadow + const logLevelGte = initLogLevelGte('debug'); + expect(logLevelGte('error')).toEqual(true); + expect(logLevelGte('warn')).toEqual(true); + expect(logLevelGte('info')).toEqual(true); + expect(logLevelGte('http')).toEqual(true); + expect(logLevelGte('verbose')).toEqual(true); + expect(logLevelGte('debug')).toEqual(true); + expect(logLevelGte('silly')).toEqual(false); + }); + + it('Works when initialized with initLogLevelGte("silly")', () => { + // eslint-disable-next-line no-shadow + const logLevelGte = initLogLevelGte('silly'); + expect(logLevelGte('error')).toEqual(true); + expect(logLevelGte('warn')).toEqual(true); + expect(logLevelGte('info')).toEqual(true); + expect(logLevelGte('http')).toEqual(true); + expect(logLevelGte('verbose')).toEqual(true); + expect(logLevelGte('debug')).toEqual(true); + expect(logLevelGte('silly')).toEqual(true); + }); +}); From 9846b95ad83e5e46708ef3624ef008d8a93888b6 Mon Sep 17 00:00:00 2001 From: Aaron Houlihan Date: Fri, 12 Apr 2019 17:03:48 -0400 Subject: [PATCH 5/5] Make test file import from /src rather than /lib --- test/format.test.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/format.test.js b/test/format.test.js index 1971741..e77cfe6 100644 --- a/test/format.test.js +++ b/test/format.test.js @@ -4,7 +4,7 @@ import _ from 'lodash'; import SpyTransport from '@chrisalderson/winston-spy'; // eslint-disable-line no-unused-vars import util from 'util'; import winston from 'winston'; -import { configuredFormatter, parseInfo } from '../lib'; // eslint-disable-line import/named +import { configuredFormatter, parseInfo } from '../src'; // eslint-disable-line import/named const { createLogger } = winston;