diff --git a/test/api/unit/libs/logger.js b/test/api/unit/libs/logger.js index 7683c8b076..ea6d6bd627 100644 --- a/test/api/unit/libs/logger.js +++ b/test/api/unit/libs/logger.js @@ -30,18 +30,52 @@ describe('logger', () => { describe('info', () => { it('calls winston\'s info log', () => { - logger.info(1, 2, 3); + logger.info('1', 2); expect(infoSpy).to.be.calledOnce; - expect(infoSpy).to.be.calledWith(1, 2, 3); + expect(infoSpy).to.be.calledWith('1', { extraData: 2 }); + }); + + it('allows up to two arguments', () => { + expect(() => logger.info('1', 2, 3)).to.throw; + expect(infoSpy).to.not.be.called; + }); + + it('has default message', () => { + logger.info(1); + expect(infoSpy).to.be.calledOnce; + expect(infoSpy).to.be.calledWith('No message provided for log.', { extraData: 1 }); + }); + + it('wraps non objects', () => { + logger.info('message', [1, 2]); + expect(infoSpy).to.be.calledOnce; + expect(infoSpy).to.be.calledWithMatch('message', { extraData: [1, 2] }); + }); + + it('does not wrap objects', () => { + logger.info('message', { a: 1, b: 2 }); + expect(infoSpy).to.be.calledOnce; + expect(infoSpy).to.be.calledWithMatch('message', { a: 1, b: 2 }); + }); + + it('throws if two arguments and no message', () => { + expect(() => logger.info({ a: 1 }, { b: 2 })).to.throw; + expect(infoSpy).to.not.be.called; }); }); describe('error', () => { - context('non-error object', () => { - it('passes through arguments if the first arg is not an error object', () => { - logger.error(1, 2, 3, 4); - expect(errorSpy).to.be.calledOnce; - expect(errorSpy).to.be.calledWith(1, 2, 3, 4); + it('allows up to two arguments', () => { + expect(() => logger.error('1', 2, 3)).to.throw; + expect(errorSpy).to.not.be.called; + }); + + it('handled non-error object', () => { + logger.error(1, 2); + expect(errorSpy).to.be.calledOnce; + expect(errorSpy).to.be.calledWithMatch('logger.error expects an Error instance', { + invalidErr: 1, + extraData: 2, }); }); @@ -50,14 +84,12 @@ describe('logger', () => { const errInstance = new Error('An error.'); logger.error(errInstance, { data: 1, - }, 2, 3); + }); expect(errorSpy).to.be.calledOnce; expect(errorSpy).to.be.calledWith( errInstance.stack, { data: 1, fullError: errInstance }, - 2, - 3, ); }); @@ -68,56 +100,60 @@ describe('logger', () => { logger.error(errInstance, { data: 1, fullError: anotherError, - }, 2, 3); + }); expect(errorSpy).to.be.calledOnce; expect(errorSpy).to.be.calledWith( errInstance.stack, { data: 1, fullError: anotherError }, - 2, - 3, ); }); it('logs the error when errorData is null', () => { const errInstance = new Error('An error.'); - logger.error(errInstance, null, 2, 3); + logger.error(errInstance, null); expect(errorSpy).to.be.calledOnce; - expect(errorSpy).to.be.calledWith( + expect(errorSpy).to.be.calledWithMatch( errInstance.stack, - null, - 2, - 3, + { }, ); }); it('logs the error when errorData is not an object', () => { const errInstance = new Error('An error.'); - logger.error(errInstance, true, 2, 3); + logger.error(errInstance, true); expect(errorSpy).to.be.calledOnce; - expect(errorSpy).to.be.calledWith( + expect(errorSpy).to.be.calledWithMatch( errInstance.stack, - true, - 2, - 3, + { extraData: true }, + ); + }); + + it('logs the error when errorData is a string', () => { + const errInstance = new Error('An error.'); + + logger.error(errInstance, 'a string'); + + expect(errorSpy).to.be.calledOnce; + expect(errorSpy).to.be.calledWithMatch( + errInstance.stack, + { extraMessage: 'a string' }, ); }); it('logs the error when errorData does not include isHandledError property', () => { const errInstance = new Error('An error.'); - logger.error(errInstance, { httpCode: 400 }, 2, 3); + logger.error(errInstance, { httpCode: 400 }); expect(errorSpy).to.be.calledOnce; expect(errorSpy).to.be.calledWith( errInstance.stack, { httpCode: 400, fullError: errInstance }, - 2, - 3, ); }); @@ -127,14 +163,12 @@ describe('logger', () => { logger.error(errInstance, { isHandledError: true, httpCode: 502, - }, 2, 3); + }); expect(errorSpy).to.be.calledOnce; expect(errorSpy).to.be.calledWith( errInstance.stack, { httpCode: 502, isHandledError: true, fullError: errInstance }, - 2, - 3, ); }); @@ -144,14 +178,12 @@ describe('logger', () => { logger.error(errInstance, { isHandledError: true, httpCode: 403, - }, 2, 3); + }); expect(warnSpy).to.be.calledOnce; expect(warnSpy).to.be.calledWith( errInstance.stack, { httpCode: 403, isHandledError: true, fullError: errInstance }, - 2, - 3, ); }); @@ -160,7 +192,7 @@ describe('logger', () => { errInstance.customField = 'Some interesting data'; - logger.error(errInstance, {}, 2, 3); + logger.error(errInstance, {}); expect(errorSpy).to.be.calledOnce; expect(errorSpy).to.be.calledWith( @@ -170,8 +202,6 @@ describe('logger', () => { customField: 'Some interesting data', }, }, - 2, - 3, ); }); }); diff --git a/website/server/index.js b/website/server/index.js index b0c1a8a823..832a06cc74 100644 --- a/website/server/index.js +++ b/website/server/index.js @@ -34,7 +34,7 @@ if (CORES !== 0 && cluster.isMaster && (IS_DEV || IS_PROD)) { cluster.on('disconnect', worker => { const w = cluster.fork(); // replace the dead worker - logger.info('[%s] [master:%s] worker:%s disconnect! new worker:%s fork', new Date(), process.pid, worker.process.pid, w.process.pid); + logger.info(`[${new Date()}] [master:${process.pid}] worker:${worker.process.pid} disconnect! new worker:${w.process.pid} fork`); }); } else { module.exports = require('./server.js'); diff --git a/website/server/libs/logger.js b/website/server/libs/logger.js index 354a54498f..2842fd17eb 100644 --- a/website/server/libs/logger.js +++ b/website/server/libs/logger.js @@ -81,7 +81,7 @@ if (IS_PROD) { ), })) .add(new winston.transports.Console({ - level: 'info', // info messages as text + level: 'info', // text part format: winston.format.combine( // Ignores warn and errors winston.format(info => { @@ -93,9 +93,28 @@ if (IS_PROD) { })(), winston.format.timestamp(), winston.format.colorize(), - winston.format.splat(), winston.format.printf(info => `${info.timestamp} - ${info.level} ${info.message}`), ), + })) + .add(new winston.transports.Console({ + level: 'info', // json part + format: winston.format.combine( + // Ignores warn and errors + winston.format(info => { + if (info.level === 'error' || info.level === 'warn') { + return false; + } + + // If there are only two keys (message and level) it means there's nothing + // to print as json + if (Object.keys(info).length <= 2) return false; + + return info; + })(), + winston.format.prettyPrint({ + colorize: true, + }), + ), })); } else { _config.loggingEnabled = false; @@ -106,7 +125,27 @@ const loggerInterface = { info (...args) { if (!_config.loggingEnabled) return; - logger.info(...args); + const [_message, _data] = args; + const isMessageString = typeof _message === 'string'; + + const message = isMessageString ? _message : 'No message provided for log.'; + let data; + + if (args.length === 1) { + if (isMessageString) { + data = {}; + } else { + data = { extraData: _message }; + } + } else if (!isMessageString || args.length > 2) { + throw new Error('logger.info accepts up to two arguments: a message and an object with extra data to log.'); + } else if (_.isPlainObject(_data)) { + data = _data; + } else { + data = { extraData: _data }; + } + + logger.info(message, data); }, // Accepts two argument, @@ -115,13 +154,27 @@ const loggerInterface = { // 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; + const [err, _errorData] = args; + + if (args.length > 2) { + throw new Error('logger.error accepts up to two arguments: an error and an object with extra data to log.'); + } + + let errorData = {}; + + if (typeof _errorData === 'string') { + errorData = { extraMessage: _errorData }; + } else if (_.isPlainObject(_errorData)) { + errorData = _errorData; + } else if (_errorData) { + errorData = { extraData: _errorData }; + } if (err instanceof Error) { // pass the error stack as the first parameter to logger.error const stack = err.stack || err.message || err; - if (_.isPlainObject(errorData) && !errorData.fullError) { + if (!errorData.fullError) { // If the error object has interesting data // (not only httpCode, message and name from the CustomError class) // add it to the logs @@ -136,7 +189,7 @@ const loggerInterface = { } } - const loggerArgs = [stack, errorData, ...otherArgs]; + const loggerArgs = [stack, errorData]; // Treat 4xx errors that are handled as warnings, 5xx and uncaught errors as serious problems if (!errorData || !errorData.isHandledError || errorData.httpCode >= 500) { @@ -145,7 +198,8 @@ const loggerInterface = { logger.warn(...loggerArgs); } } else { - logger.error(...args); + errorData.invalidErr = err; + logger.error('logger.error expects an Error instance', errorData); } }, }; diff --git a/website/server/libs/pushNotifications.js b/website/server/libs/pushNotifications.js index 437c29fd45..25e6cdba15 100644 --- a/website/server/libs/pushNotifications.js +++ b/website/server/libs/pushNotifications.js @@ -71,9 +71,9 @@ function sendNotification (user, details = {}) { .then(response => { response.failed.forEach(failure => { if (failure.error) { - logger.error('APN error', failure.error); + logger.error(new Error('APN error'), { failure }); } else { - logger.error('APN transmissionError', failure.status, notification, failure.device); + logger.error(new Error('APN transmissionError'), { failure, notification }); } }); }) diff --git a/website/server/libs/webhook.js b/website/server/libs/webhook.js index 64691996f5..81f2a5b482 100644 --- a/website/server/libs/webhook.js +++ b/website/server/libs/webhook.js @@ -19,7 +19,7 @@ function sendWebhook (webhook, body, user) { retry: 3, // retry the request up to 3 times }).catch(webhookErr => { // Log the error - logger.error(webhookErr); + logger.error(webhookErr, 'Error while sending a webhook request.'); let _failuresReset = false;