Merge pull request #11887 from HabitRPG/stackdriver-winston

Logs improvements

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": {

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,

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: {

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) {