diff --git a/package-lock.json b/package-lock.json index 129dd708d8..f7347c06d1 100644 --- a/package-lock.json +++ b/package-lock.json @@ -1309,6 +1309,26 @@ "version": "5.0.3", "resolved": "https://registry.npmjs.org/semver/-/semver-5.0.3.tgz", "integrity": "sha1-d0Zt5YnNXTyV8TiqeLxWmjy10no=" + }, + "winston": { + "version": "2.4.4", + "resolved": "https://registry.npmjs.org/winston/-/winston-2.4.4.tgz", + "integrity": "sha512-NBo2Pepn4hK4V01UfcWcDlmiVTs7VTB1h7bgnB0rgP146bYhMxX0ypCz3lBOfNxCO4Zuek7yeT+y/zM1OfMw4Q==", + "requires": { + "async": "~1.0.0", + "colors": "1.0.x", + "cycle": "1.0.x", + "eyes": "0.1.x", + "isstream": "0.1.x", + "stack-trace": "0.0.x" + }, + "dependencies": { + "async": { + "version": "1.0.0", + "resolved": "https://registry.npmjs.org/async/-/async-1.0.0.tgz", + "integrity": "sha1-+PwEyjoTeErenhZBr5hXjPvWR6k=" + } + } } } }, @@ -13949,32 +13969,55 @@ "integrity": "sha1-+OGqHuWlPsW/FR/6CXQqatdpeHY=" }, "winston": { - "version": "2.4.4", - "resolved": "https://registry.npmjs.org/winston/-/winston-2.4.4.tgz", - "integrity": "sha512-NBo2Pepn4hK4V01UfcWcDlmiVTs7VTB1h7bgnB0rgP146bYhMxX0ypCz3lBOfNxCO4Zuek7yeT+y/zM1OfMw4Q==", + "version": "3.2.1", + "resolved": "https://registry.npmjs.org/winston/-/winston-3.2.1.tgz", + "integrity": "sha512-zU6vgnS9dAWCEKg/QYigd6cgMVVNwyTzKs81XZtTFuRwJOcDdBg7AU0mXVyNbs7O5RH2zdv+BdNZUlx7mXPuOw==", "requires": { - "async": "~1.0.0", - "colors": "1.0.x", - "cycle": "1.0.x", - "eyes": "0.1.x", - "isstream": "0.1.x", - "stack-trace": "0.0.x" + "async": "^2.6.1", + "diagnostics": "^1.1.1", + "is-stream": "^1.1.0", + "logform": "^2.1.1", + "one-time": "0.0.4", + "readable-stream": "^3.1.1", + "stack-trace": "0.0.x", + "triple-beam": "^1.3.0", + "winston-transport": "^4.3.0" }, "dependencies": { "async": { - "version": "1.0.0", - "resolved": "https://registry.npmjs.org/async/-/async-1.0.0.tgz", - "integrity": "sha1-+PwEyjoTeErenhZBr5hXjPvWR6k=" + "version": "2.6.3", + "resolved": "https://registry.npmjs.org/async/-/async-2.6.3.tgz", + "integrity": "sha512-zflvls11DCy+dQWzTW2dzuilv8Z5X/pjfmZOWba6TNIVDm+2UDaJmXSOXlasHKfNBs8oo3M0aT50fDEWfKZjXg==", + "requires": { + "lodash": "^4.17.14" + } + }, + "is-stream": { + "version": "1.1.0", + "resolved": "https://registry.npmjs.org/is-stream/-/is-stream-1.1.0.tgz", + "integrity": "sha1-EtSj3U5o4Lec6428hBc66A2RykQ=" + }, + "readable-stream": { + "version": "3.6.0", + "resolved": "https://registry.npmjs.org/readable-stream/-/readable-stream-3.6.0.tgz", + "integrity": "sha512-BViHy7LKeTz4oNnkcLJ+lVSL6vpiFeX6/d3oSH8zCW7UxP2onchk+vTGB143xuFjHS3deTgkKoXXymXqymiIdA==", + "requires": { + "inherits": "^2.0.3", + "string_decoder": "^1.1.1", + "util-deprecate": "^1.0.1" + } } } }, "winston-loggly-bulk": { - "version": "2.0.3", - "resolved": "https://registry.npmjs.org/winston-loggly-bulk/-/winston-loggly-bulk-2.0.3.tgz", - "integrity": "sha512-OdpOo+nwVD6TAKv5z+FnvtG2mPhJAfLYgL2Vou+mAF5LaKRloo6I3plx4333pY9XHVI1RsSDYwbSabGcYiMIvQ==", + "version": "3.0.1", + "resolved": "https://registry.npmjs.org/winston-loggly-bulk/-/winston-loggly-bulk-3.0.1.tgz", + "integrity": "sha512-C86aohUze/qCRYhOVyxgqTuz3HmDK4mLss3OsVHxb4hfD+gw8jAEl3LEMOsqWHEnoJp/MC0wE1N3PeUcisLi2g==", "requires": { + "clone": "^2.1.1", "node-loggly-bulk": "^2.0.1", - "winston": "^2.3.1" + "winston": "^3.0", + "winston-transport": "^4.2.0" } }, "winston-transport": { diff --git a/package.json b/package.json index 8237f4a05d..3acbabcc95 100644 --- a/package.json +++ b/package.json @@ -69,8 +69,8 @@ "uuid": "^3.4.0", "validator": "^11.0.0", "vinyl-buffer": "^1.0.1", - "winston": "^2.4.3", - "winston-loggly-bulk": "^2.0.2", + "winston": "^3.2.1", + "winston-loggly-bulk": "^3.0.1", "xml2js": "^0.4.23" }, "private": true, diff --git a/test/api/unit/libs/logger.js b/test/api/unit/libs/logger.js index c9878f36fa..7683c8b076 100644 --- a/test/api/unit/libs/logger.js +++ b/test/api/unit/libs/logger.js @@ -1,14 +1,27 @@ -import winston from 'winston'; -import logger from '../../../../website/server/libs/logger'; +import logger, { _loggerConfig } from '../../../../website/server/libs/logger'; import { NotFound, } from '../../../../website/server/libs/errors'; describe('logger', () => { - let logSpy; + let infoSpy; + let warnSpy; + let errorSpy; + + const originalLoggingEnabled = _loggerConfig.loggingEnabled; + + before(() => { // enable logging in tests + _loggerConfig.loggingEnabled = true; + }); + + after(() => { // reset value of _loggerConfig.loggingEnabled + _loggerConfig.loggingEnabled = originalLoggingEnabled; + }); beforeEach(() => { - logSpy = sandbox.stub(winston.Logger.prototype, 'log'); + infoSpy = sandbox.stub(_loggerConfig.logger, 'info'); + warnSpy = sandbox.stub(_loggerConfig.logger, 'warn'); + errorSpy = sandbox.stub(_loggerConfig.logger, 'error'); }); afterEach(() => { @@ -18,8 +31,8 @@ describe('logger', () => { describe('info', () => { it('calls winston\'s info log', () => { logger.info(1, 2, 3); - expect(logSpy).to.be.calledOnce; - expect(logSpy).to.be.calledWith('info', 1, 2, 3); + expect(infoSpy).to.be.calledOnce; + expect(infoSpy).to.be.calledWith(1, 2, 3); }); }); @@ -27,8 +40,8 @@ describe('logger', () => { context('non-error object', () => { it('passes through arguments if the first arg is not an error object', () => { logger.error(1, 2, 3, 4); - expect(logSpy).to.be.calledOnce; - expect(logSpy).to.be.calledWith('error', 1, 2, 3, 4); + expect(errorSpy).to.be.calledOnce; + expect(errorSpy).to.be.calledWith(1, 2, 3, 4); }); }); @@ -39,9 +52,8 @@ describe('logger', () => { data: 1, }, 2, 3); - expect(logSpy).to.be.calledOnce; - expect(logSpy).to.be.calledWith( - 'error', + expect(errorSpy).to.be.calledOnce; + expect(errorSpy).to.be.calledWith( errInstance.stack, { data: 1, fullError: errInstance }, 2, @@ -58,9 +70,8 @@ describe('logger', () => { fullError: anotherError, }, 2, 3); - expect(logSpy).to.be.calledOnce; - expect(logSpy).to.be.calledWith( - 'error', + expect(errorSpy).to.be.calledOnce; + expect(errorSpy).to.be.calledWith( errInstance.stack, { data: 1, fullError: anotherError }, 2, @@ -73,9 +84,8 @@ describe('logger', () => { logger.error(errInstance, null, 2, 3); - expect(logSpy).to.be.calledOnce; - expect(logSpy).to.be.calledWith( - 'error', + expect(errorSpy).to.be.calledOnce; + expect(errorSpy).to.be.calledWith( errInstance.stack, null, 2, @@ -88,9 +98,8 @@ describe('logger', () => { logger.error(errInstance, true, 2, 3); - expect(logSpy).to.be.calledOnce; - expect(logSpy).to.be.calledWith( - 'error', + expect(errorSpy).to.be.calledOnce; + expect(errorSpy).to.be.calledWith( errInstance.stack, true, 2, @@ -103,9 +112,8 @@ describe('logger', () => { logger.error(errInstance, { httpCode: 400 }, 2, 3); - expect(logSpy).to.be.calledOnce; - expect(logSpy).to.be.calledWith( - 'error', + expect(errorSpy).to.be.calledOnce; + expect(errorSpy).to.be.calledWith( errInstance.stack, { httpCode: 400, fullError: errInstance }, 2, @@ -121,9 +129,8 @@ describe('logger', () => { httpCode: 502, }, 2, 3); - expect(logSpy).to.be.calledOnce; - expect(logSpy).to.be.calledWith( - 'error', + expect(errorSpy).to.be.calledOnce; + expect(errorSpy).to.be.calledWith( errInstance.stack, { httpCode: 502, isHandledError: true, fullError: errInstance }, 2, @@ -139,9 +146,8 @@ describe('logger', () => { httpCode: 403, }, 2, 3); - expect(logSpy).to.be.calledOnce; - expect(logSpy).to.be.calledWith( - 'warn', + expect(warnSpy).to.be.calledOnce; + expect(warnSpy).to.be.calledWith( errInstance.stack, { httpCode: 403, isHandledError: true, fullError: errInstance }, 2, @@ -156,9 +162,8 @@ describe('logger', () => { logger.error(errInstance, {}, 2, 3); - expect(logSpy).to.be.calledOnce; - expect(logSpy).to.be.calledWith( - 'error', + expect(errorSpy).to.be.calledOnce; + expect(errorSpy).to.be.calledWith( errInstance.stack, { fullError: { diff --git a/website/server/libs/logger.js b/website/server/libs/logger.js index 2e753828d4..180f0ca8aa 100644 --- a/website/server/libs/logger.js +++ b/website/server/libs/logger.js @@ -1,6 +1,6 @@ // Logger utility import winston from 'winston'; -import 'winston-loggly-bulk'; +import { Loggly } from 'winston-loggly-bulk'; import nconf from 'nconf'; import _ from 'lodash'; import { @@ -10,38 +10,91 @@ import { const IS_PROD = nconf.get('IS_PROD'); const IS_TEST = nconf.get('IS_TEST'); const ENABLE_LOGS_IN_TEST = nconf.get('ENABLE_CONSOLE_LOGS_IN_TEST') === 'true'; -const ENABLE_LOGS_IN_PROD = nconf.get('ENABLE_CONSOLE_LOGS_IN_PROD') === 'true'; +const ENABLE_CONSOLE_LOGS_IN_PROD = nconf.get('ENABLE_CONSOLE_LOGS_IN_PROD') === 'true'; -const logger = new winston.Logger(); +const LOGGLY_TOKEN = nconf.get('LOGGLY_TOKEN'); +const LOGGLY_SUBDOMAIN = nconf.get('LOGGLY_SUBDOMAIN'); + +const logger = winston.createLogger(); + +const _config = { + logger, + loggingEnabled: true, // false if no transport has been configured +}; + +export { _config as _loggerConfig }; // exported for use during tests if (IS_PROD) { - if (ENABLE_LOGS_IN_PROD) { - logger.add(winston.transports.Console, { - timestamp: true, - colorize: false, - prettyPrint: false, - }); - logger.add(winston.transports.Loggly, { - inputToken: nconf.get('LOGGLY_TOKEN'), - subdomain: nconf.get('LOGGLY_SUBDOMAIN'), - tags: ['Winston-NodeJS'], - json: true, - }); + if (ENABLE_CONSOLE_LOGS_IN_PROD) { + logger.add(new winston.transports.Console({ + format: winston.format.combine( + winston.format.timestamp(), + winston.format.json(), + ), + })); } + if (LOGGLY_TOKEN && LOGGLY_SUBDOMAIN) { + logger.add(new Loggly({ + inputToken: LOGGLY_TOKEN, + subdomain: LOGGLY_SUBDOMAIN, + tags: ['Winston-NodeJS'], + json: true, + })); + } // Do not log anything when testing unless specified } else if (!IS_TEST || (IS_TEST && ENABLE_LOGS_IN_TEST)) { logger - .add(winston.transports.Console, { - timestamp: true, - colorize: true, - prettyPrint: true, - }); + .add(new winston.transports.Console({ + level: 'warn', // warn and errors (text part) + format: winston.format.combine( + winston.format.colorize(), + winston.format.timestamp(), + winston.format.printf( + info => `${info.timestamp} - ${info.level} ${info.message}`, + ), + ), + })) + .add(new winston.transports.Console({ + level: 'warn', // warn and errors (json part) + format: winston.format.combine( + // Remove stacktrace from json, printed separately + winston.format(info => { + const message = info.message.split('\n')[0]; + info.message = message; + return info; + })(), + winston.format.prettyPrint({ + colorize: true, + }), + ), + })) + .add(new winston.transports.Console({ + level: 'info', // info messages as text + format: winston.format.combine( + // Ignores warn and errors + winston.format(info => { + if (info.level === 'error' || info.level === 'warn') { + return false; + } + + return info; + })(), + winston.format.timestamp(), + winston.format.colorize(), + winston.format.splat(), + winston.format.printf(info => `${info.timestamp} - ${info.level} ${info.message}`), + ), + })); +} else { + _config.loggingEnabled = false; } // exports a public interface insteaf of accessing directly the logger module const loggerInterface = { info (...args) { + if (!_config.loggingEnabled) return; + logger.info(...args); }, @@ -50,6 +103,7 @@ const loggerInterface = { // and an object of additional data to log alongside the error // If the first argument isn't an Error, it'll call logger.error with all the arguments supplied error (...args) { + if (!_config.loggingEnabled) return; const [err, errorData = {}, ...otherArgs] = args; if (err instanceof Error) {