fix(logger): improve logging and make sure no data is lost

2025-12-17 06:37:23 +01:00 · 2020-03-24 20:29:31 +01:00
parent 3458d89c1d
commit 2cd0ed5973
5 changed files with 130 additions and 46 deletions
--- 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,
        );
      });
    });
--- 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');
--- 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);
    }
  },
 };
--- 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 });
                }
              });
            })
--- 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;