fix(metadata precedence) - fix metadata override issues (#1989)

* chore: wrap logger tests in top-level describe

* chore: restructure tests directory

* chore: restructure logger tests

* chore: cleanup test descriptions

* fix: fix ci step to account for npm script rename

* chore: rename tests dir back to test

* fix: correct relative file paths

* make sure all tests actually run

* feat: add nyc configuration file

* chore: fix missing end of file newlines

* fix: ci steps

* fix: ci steps try 2

* chore: rename ci jobs

* chore: leverage yaml file for nyc configuration

* chore: move nyc configuration from npm script to associated configuration file

* chore: move common mocha configurations from npm script to dedicated configuration

* feat: introduce a in-memory mock transport generator

* chore: make test callback functions consistent

* feat: introduce tests proving issues with metadata precedence

* fix: introduce fix for application of default metadata

* feat: add equivalent tests for .log() method

* chore: update nyc coverage

* chore: undo accidental indent

* chore: add new test to ensure a parents metadata updates don't propogate to the child

* chore: fix nyc coverage requirements

* feat: introduce test proving issue with Profilers instance not including metadata

* feat: ensure Profiler triggers the logger's add default metadata functionality

* fix: add a safety net to calling 'addDefaultMeta' on the logger instance

* chore: fix failing build issues

* feat: add test to ensure changes to parents metadata are not propogated to a child

* fix: remove linebreak configuration from editorconfig

* chore: combine level and log tests of same kind to ensure both output the same

* feat: introduce tests proving issues reported

* feat: introduce tests for non-primitive data types in metadata

* chore: deep clone when instantiating child logger

* chore: remove unused imports

* chore: address comments on logger test additions

* Replace JSON.stringify with one that accounts for cyclical refs

* Add lint rule for semicolons. Add script to run linter fix operation. Fix missing semis

.eslintrc

@@ -2,6 +2,7 @@
   "extends": "@dabh/eslint-config-populist",
   "rules": {
     "one-var": ["error", { "var": "never", "let": "never", "const": "never" }],
+    "semi": "error",
     "strict": 0
   },
   "parserOptions": {

.nycrc.yml

@@ -4,5 +4,5 @@ reporter:
 check-coverage: true
 branches: 61.51
 lines: 70.85
-functions: 73.21
+functions: 73.08
 statements: 70.54

lib/winston/logger.js

@@ -9,14 +9,15 @@
 
 const { Stream, Transform } = require('readable-stream');
 const asyncForEach = require('async/forEach');
-const { LEVEL, SPLAT } = require('triple-beam');
+const { LEVEL, SPLAT, MESSAGE } = require('triple-beam');
 const isStream = require('is-stream');
 const ExceptionHandler = require('./exception-handler');
 const RejectionHandler = require('./rejection-handler');
 const LegacyTransportStream = require('winston-transport/legacy');
 const Profiler = require('./profiler');
 const { warn } = require('./common');
 const config = require('./config');
+const jsonStringify = require('safe-stable-stringify');
 
 /**
  * Captures the number of format (i.e. %s strings) in a given string.
@@ -42,30 +43,12 @@ class Logger extends Transform {
     this.configure(options);
   }
 
-  child(defaultRequestMetadata) {
+  child(childMetadata) {
     const logger = this;
+    const clonedParentMetadata = JSON.parse(jsonStringify(this.defaultMeta));
     return Object.create(logger, {
-      write: {
-        value: function (info) {
-          const infoClone = Object.assign(
-            {},
-            defaultRequestMetadata,
-            info
-          );
-
-          // Object.assign doesn't copy inherited Error
-          // properties so we have to do that explicitly
-          //
-          // Remark (indexzero): we should remove this
-          // since the errors format will handle this case.
-          //
-          if (info instanceof Error) {
-            infoClone.stack = info.stack;
-            infoClone.message = info.message;
-          }
-
-          logger.write(infoClone);
-        }
+      defaultMeta: {
+        value: Object.assign({}, clonedParentMetadata, childMetadata)
       }
     });
   }
@@ -288,6 +271,10 @@ class Logger extends Transform {
       info[LEVEL] = info.level;
     }
 
+    if (!info[MESSAGE]) {
+      info[MESSAGE] = info.message;
+    }
+
     // Remark: really not sure what to do here, but this has been reported as
     // very confusing by pre winston@2.0.0 users as quite confusing when using
     // custom levels.
@@ -647,7 +634,9 @@ class Logger extends Transform {
 
   _addDefaultMeta(msg) {
     if (this.defaultMeta) {
-      Object.assign(msg, this.defaultMeta);
+      // The msg must be cloned as it is being mutated, but any metadata provided with the msg takes precedence over default
+      const msgClone = JSON.parse(jsonStringify(msg));
+      Object.assign(msg, this.defaultMeta, msgClone);
     }
   }
 }

lib/winston/profiler.js

@@ -21,6 +21,8 @@ module.exports = class Profiler {
    * @private
    */
   constructor(logger) {
+    // TODO there is no restriction on what the Profiler considers a Logger. As such there is no guarantees it adheres
+    //   to the proper interface. This needs to hardened.
     if (!logger) {
       throw new Error('Logger is required for profiling.');
     }
@@ -32,7 +34,8 @@ module.exports = class Profiler {
   /**
    * Ends the current timer (i.e. Profiler) instance and logs the `msg` along
    * with the duration since creation.
-   * @returns {mixed} - TODO: add return description.
+   * @returns {boolean} - `false` if the logger stream wishes for the calling code to wait for the 'drain' event to be
+   *   emitted before continuing to write additional data; otherwise `true`
    * @private
    */
   done(...args) {
@@ -45,7 +48,7 @@ module.exports = class Profiler {
     const info = typeof args[args.length - 1] === 'object' ? args.pop() : {};
     info.level = info.level || 'info';
     info.durationMs = (Date.now()) - this.start;
-
+    if (this.logger._addDefaultMeta) this.logger._addDefaultMeta(info);
     return this.logger.write(info);
   }
 };

package.json

@@ -60,6 +60,7 @@
   "types": "./index.d.ts",
   "scripts": {
     "lint": "eslint lib/*.js lib/winston/*.js lib/winston/**/*.js --resolve-plugins-relative-to ./node_modules/@dabh/eslint-config-populist",
+    "lint:fix": "npm run lint -- --fix",
     "test": "mocha",
     "test:coverage": "nyc npm run test:unit",
     "test:unit": "mocha test/unit",

test/helpers/mocks/mock-transport.js

@@ -1,9 +1,10 @@
 const stream = require('stream')
 const winston = require('../../../lib/winston');
+const {Writable} = require("stream");
 
 /**
  * Returns a new Winston transport instance which will invoke
- * the `write` method on each call to `.log`
+ * the `write` method on each call to `.log`
  *
  * @param {function} write Write function for the specified stream
  * @returns {StreamTransportInstance} A transport instance
@@ -17,6 +18,23 @@ function createMockTransport(write) {
   return new winston.transports.Stream({ stream: writeable })
 }
 
+/**
+ * Returns a valid Winston transport that writes to the passed array object
+ * @param array Array to be used to store the "written" chunks
+ * @returns {winston.transports.Stream}
+ */
+function inMemory(array, options = {}) {
+  const memoryStream = new Writable({
+    objectMode: true,
+    write: (chunk, encoding, next) => {
+      array.push(chunk);
+      next()
+    }
+  });
+  return new winston.transports.Stream({stream: memoryStream, ...options})
+}
+
 module.exports = {
-  createMockTransport
+  createMockTransport,
+  inMemory
 };