ALWAYS send the ORIGINAL, unmutated info object to each registered logger transport

[fourpastmidnight]

Please tell us about your environment:

• winston version? 3.3.3
  • winston@2
  • winston@3
• node -v outputs: N/A
• Operating System? Windows
• Language? All

What is the problem?

I realize that in the README for this repository, the project points out that Winston is a mutating logger. However, what is really unexpected is that Winston sends mutated instances of a TransformableInfo object into transports.

What do you expect to happen instead?

I expect that each transport would receive an unmutated (i.e. original) version of the TransformableInfo object. In this way, for a single logger instance, each transport could "mutate" the object as required for that particular transport. However, that is not what's happening.

Other information

I thought I'd share with you some output I generated as Winston passed along the info object through some of my formatters for formatting transport output....

For each transport, the order of formatters was kept the same. I ensured that each formatter which I created does not mutate the info object passed into it, but returns a new, "transformed" info object. Here's my logger definition:

const logger: Logger = createLogger(<LoggerOptions>{
  // This is a "global" log formatter. It gets
  // `format.combine()`ed with specified transport formatters,
  // if any.
  format: format.timestamp(<TimestampOptions>{ format: 'YYYY-MM-DD HH:mm:ss.SSSZZ'}),
  levels: config.syslog.levels,
  transports: [
    new transports.File({
      filename: 'structured.log',
      level: 'info',
      format: loggedDefaultStructuredLogFormat
    }),
    new transports.File({
      filename: 'readable.log',
      format: loggedDefaultUnstructuredLogFormat,
      level: 'info'
    }),
    new transports.Console({format: loggedDefaultConsoleFormat}),
  ],
  exitOnError: false
});

So, looking at the below output, every line that starts with ==> Default * Format: pre-formatting: ``info``:, I expect the following info object definition to be exactly the same for each transport. But you will see that it is not. For example, the very first log entry starts with the Structured Log transport. You can see that, pre-formatting, there's a correlationId property field on the info object. However, once we get to the second transport for the unstructured log file, the info object doesn't even have a correlationId property at this point! Where did it go? After analyzing the formatters, it seems the key difference is the info[Symbol(splat)] property's value between the two transports. It seems as if format.splat is mutating the original info object's value for that property, and subsequent transports use the mutated value, losing log data along the way. In addition, something is stripping off the extra metadata between transports. At the end of the first transport, there are correlationId and deploymentTargetId properties on the info object, but they don't appear by the time the next transport gets it. But again, had the info[Symbol(splat)] property value not change between transports, that would be a non-issue. So again, it seems like format.splat is the culprit here, BUT, Winston SHOULD NOT be passing a mutated info object between transports.

I'm in development!
Application started. Listening on http://*:5000
==> Default Structured Log Format: pre-formatting `info`: {
  level: 'info',
  message: "Processing deployment target ID '%s'...",
  timestamp: '2021-06-11 15:03:21.833-0400',
  [Symbol(level)]: 'info',
  [Symbol(splat)]: [
    'Machines-197',
    {
      deploymentTargetId: 'Machines-197',
      correlationId: '2fc14439-84c9-4698-99c5-d7913bdead34'
    }
  ]
}
--> Default Structured Log Format: post-splat `info`: {
  level: 'info',
  message: "Processing deployment target ID 'Machines-197'...",
  timestamp: '2021-06-11 15:03:21.833-0400',
  deploymentTargetId: 'Machines-197',
  correlationId: '2fc14439-84c9-4698-99c5-d7913bdead34',
  [Symbol(level)]: 'info',
  [Symbol(splat)]: [ 'Machines-197' ]
}
--> Default Structured Log Format: post-json `info`: {
  level: 'info',
  message: "Processing deployment target ID 'Machines-197'...",
  timestamp: '2021-06-11 15:03:21.833-0400',
  deploymentTargetId: 'Machines-197',
  correlationId: '2fc14439-84c9-4698-99c5-d7913bdead34',
  [Symbol(level)]: 'info',
  [Symbol(splat)]: [ 'Machines-197' ],
  [Symbol(message)]: `{"level":"info","message":"Processing deployment target ID 'Machines-197'...","timestamp":"2021-06-11 15:03:21.833-0400","deploymentTargetId":"Machines-197","correlationId":"2fc14439-84c9-4698-99c5-d7913bdead34"}`
}
==> Default Structured Log Format: Done!
==> Default Unstructured Log Format: pre-formatting `info`: {
  level: 'info',
  message: "Processing deployment target ID '%s'...",
  timestamp: '2021-06-11 15:03:21.833-0400',
  [Symbol(level)]: 'info',
  [Symbol(splat)]: [ 'Machines-197' ]
}
--> Default Unstructured Log Format: post-LogLevelFormat `info`: {
  level: 'info',
  message: "Processing deployment target ID '%s'...",
  timestamp: '2021-06-11 15:03:21.833-0400',
  [Symbol(level)]: 'info',
  [Symbol(splat)]: [ 'Machines-197' ]
}
--> Default Unstructured Log Format: post-splat `info`: {
  level: 'info',
  message: "Processing deployment target ID 'Machines-197'...",
  timestamp: '2021-06-11 15:03:21.833-0400',
  [Symbol(level)]: 'info',
  [Symbol(splat)]: [ 'Machines-197' ]
}
--> Default Unstructured Log Format: post-CorrelationIdEnricherFormat `info`: {
  message: "Processing deployment target ID 'Machines-197'...",
  correlationId: undefined,
  level: 'info',
  timestamp: '2021-06-11 15:03:21.833-0400',
  [Symbol(level)]: 'info',
  [Symbol(splat)]: [ 'Machines-197' ]
}
--> Default Unstructured Log Format: post-StandardUnstructuredFormat `info`: {
  message: "Processing deployment target ID 'Machines-197'...",
  correlationId: undefined,
  level: 'info',
  timestamp: '2021-06-11 15:03:21.833-0400',
  [Symbol(level)]: 'info',
  [Symbol(splat)]: [ 'Machines-197' ],
  [Symbol(message)]: "[2021-06-11 15:03:21.833-0400] [info] Processing deployment target ID 'Machines-197'... {}"
}
==> Default Unstructured Log Format: Done!
==> Default Console Log Format: pre-formatting `info`: {
  level: 'info',
  message: "Processing deployment target ID '%s'...",
  timestamp: '2021-06-11 15:03:21.833-0400',
  [Symbol(level)]: 'info',
  [Symbol(splat)]: [ 'Machines-197' ]
}
--> Default Console Log Format: post-LogLevelFormat `info`: {
  level: 'info',
  message: "Processing deployment target ID '%s'...",
  timestamp: '2021-06-11 15:03:21.833-0400',
  [Symbol(level)]: 'info',
  [Symbol(splat)]: [ 'Machines-197' ]
}
--> Default Console Log Format: post-splat `info`: {
  level: 'info',
  message: "Processing deployment target ID 'Machines-197'...",
  timestamp: '2021-06-11 15:03:21.833-0400',
  [Symbol(level)]: 'info',
  [Symbol(splat)]: [ 'Machines-197' ]
}
--> Default Console Log Format: post-CorrelationIdEnricherFormat `info`: {
  message: "Processing deployment target ID 'Machines-197'...",
  correlationId: undefined,
  level: 'info',
  timestamp: '2021-06-11 15:03:21.833-0400',
  [Symbol(level)]: 'info',
  [Symbol(splat)]: [ 'Machines-197' ]
}
--> Default Console Log Format: post-StandardUnstructuredFormat `info`: {
  message: "Processing deployment target ID 'Machines-197'...",
  correlationId: undefined,
  level: 'info',
  timestamp: '2021-06-11 15:03:21.833-0400',
  [Symbol(level)]: 'info',
  [Symbol(splat)]: [ 'Machines-197' ],
  [Symbol(message)]: "[2021-06-11 15:03:21.833-0400] [info] Processing deployment target ID 'Machines-197'... {}"
}
==> Default Console Log Format: Done!
[2021-06-11 15:03:21.833-0400] [info] Processing deployment target ID 'Machines-197'... {}

Should I also file a bug on the logform project?

[fourpastmidnight]

More Information

So thinking that format.splat is a culprit, I tried writing a wrapper splat formatter around format.splat():

const SplatFormat: Format = format((info: TransformableInfo) => {
  // @ts-ignore
  const { [LEVEL]: symLevel, [SPLAT]: symSplat } = info;
  const symSplatCopy = (<Array<Object>>symSplat).map(o => o);
  const transformedInfo = <TransformableInfo>format.splat().transform(info);
  // @ts-ignore
  console.log("[SplatFormat]: Post-splat() - transformedInfo[Symbol(splat)] - ", transformedInfo[SPLAT]);
  // @ts-ignore
  info = <TransformableInfo>{
    ...transformedInfo,
    // @ts-ignore
    [SPLAT]: symSplatCopy,
  }
  console.log("[SplatFormat]: Post-splat() - transformedInfo - ", transformedInfo);
  console.log("[SplatFormat]: Mutated info - ", info);
  return info;
})();

The idea was to get the splatted message, but "mutate" the info object to restore the original info[Symbol(splat)] property that was passed into format.splat().transform(). From the log console logging shown below, you can see that at the end of the Structured Log Format (the first transport in my logger), I did successfully restore the state of info to what it was when format.splat().transform(...) was first entered, however with the additional "metadata" properties as comes back from format.splat().transform(...).

However, once the second transport got the info object, it did NOT receive the original, nor mutated info object that came out of the first transport. So somewhere, Winston is mutating the info object between transports, losing log data! This is a bit concerning for a log framework.

I'm in development!
Application started. Listening on http://*:5000
==> Default Structured Log Format: pre-formatting `info`: {
  level: 'info',
  message: "Processing deployment target ID '%s'...",
  timestamp: '2021-06-11 16:27:22.254-0400',
  [Symbol(level)]: 'info',
  [Symbol(splat)]: [
    'Machines-197',
    {
      deploymentTargetId: 'Machines-197',
      correlationId: '09f30d21-5c9f-4695-b604-7ecd7da14e6e'
    }
  ]
}
[SplatFormat]: Post-splat() symSplat -  [ 'Machines-197' ]
[SplatFormat]: Post-splat() symSplatCopy -  [
  'Machines-197',
  {
    deploymentTargetId: 'Machines-197',
    correlationId: '09f30d21-5c9f-4695-b604-7ecd7da14e6e'
  }
]
[SplatFormat]: Post-splat() - transformedInfo[Symbol(splat)] -  [ 'Machines-197' ]
[SplatFormat]: Post-splat() - transformedInfo -  {
  level: 'info',
  message: "Processing deployment target ID 'Machines-197'...",
  timestamp: '2021-06-11 16:27:22.254-0400',
  deploymentTargetId: 'Machines-197',
  correlationId: '09f30d21-5c9f-4695-b604-7ecd7da14e6e',
  [Symbol(level)]: 'info',
  [Symbol(splat)]: [ 'Machines-197' ]
}
[SplatFormat]: Mutated info -  {
  level: 'info',
  message: "Processing deployment target ID 'Machines-197'...",
  timestamp: '2021-06-11 16:27:22.254-0400',
  deploymentTargetId: 'Machines-197',
  correlationId: '09f30d21-5c9f-4695-b604-7ecd7da14e6e',
  [Symbol(level)]: 'info',
  [Symbol(splat)]: [
    'Machines-197',
    {
      deploymentTargetId: 'Machines-197',
      correlationId: '09f30d21-5c9f-4695-b604-7ecd7da14e6e'
    }
  ],
  [Symbol(message)]: undefined
}
--> Default Structured Log Format: post-SplatFormat `info`: {
  level: 'info',
  message: "Processing deployment target ID 'Machines-197'...",
  timestamp: '2021-06-11 16:27:22.254-0400',
  deploymentTargetId: 'Machines-197',
  correlationId: '09f30d21-5c9f-4695-b604-7ecd7da14e6e',
  [Symbol(level)]: 'info',
  [Symbol(splat)]: [
    'Machines-197',
    {
      deploymentTargetId: 'Machines-197',
      correlationId: '09f30d21-5c9f-4695-b604-7ecd7da14e6e'
    }
  ],
  [Symbol(message)]: undefined
}
--> Default Structured Log Format: post-json `info`: {
  level: 'info',
  message: "Processing deployment target ID 'Machines-197'...",
  timestamp: '2021-06-11 16:27:22.254-0400',
  deploymentTargetId: 'Machines-197',
  correlationId: '09f30d21-5c9f-4695-b604-7ecd7da14e6e',
  [Symbol(level)]: 'info',
  [Symbol(splat)]: [
    'Machines-197',
    {
      deploymentTargetId: 'Machines-197',
      correlationId: '09f30d21-5c9f-4695-b604-7ecd7da14e6e'
    }
  ],
  [Symbol(message)]: `{"level":"info","message":"Processing deployment target ID 'Machines-197'...","timestamp":"2021-06-11 16:27:22.254-0400","deploymentTargetId":"Machines-197","correlationId":"09f30d21-5c9f-4695-b604-7ecd7da14e6e"}`
}
==> Default Structured Log Format: Done!
==> Default Unstructured Log Format: pre-formatting `info`: {
  level: 'info',
  message: "Processing deployment target ID '%s'...",
  timestamp: '2021-06-11 16:27:22.254-0400',
  [Symbol(level)]: 'info',
  [Symbol(splat)]: [ 'Machines-197' ]
}

[fourpastmidnight]

This comment on #1430 resolves the issue with info "losing data" between transports. However, I view this as a workaround, since winston should guarantee that the unmodified copy of info is passed to all transports defined on a logger.