Meta properties omitted if message matches splat regex

[murrayju]

Please tell us about your environment:

• winston version?
  • winston@2
  • winston@3
• node -v outputs: v12.11.0
• Operating System? Linux
• Language? ES6

What is the problem?

If the log message matches the splat regex, the behavior of the logging changes even if the splat formatter is not used. Any meta data passed to the logger is not passed through to the underlying transport when the regex matches.

Given a logger created with a transport configured not to use the splat formatter:

const log = winston.createLogger({
  level: 'debug',
  transports: [
    new ConsoleTransport({
      format: winston.format.combine(
        winston.format.timestamp(),
        winston.format.printf(info => {
          // ... do something with `info`
        }),
      ),
    }),
  ],
});

The following works as expected, extraThing is available as a property of the info object in the transport.

log.info('this is a test', { extraThing: 7 });

The following unexpectedly does not include extraThing as a property of the info object in the transport.

log.info('this is %c a test', { extraThing: 7 });

Complete running example on runkit:
https://runkit.com/murrayju/winston-format-behavior

What do you expect to happen instead?

When not using the splat formatter, the splat regex should not be tested against the message, and the behavior should not vary by the content of the message.

[maverick1872]

Verified that this issue still exists in the latest version of Winston. I think a proper resolution of this may warrant a larger discussion to determine the most appropriate solution. I have not tested the implementation in #1710 although it seems odd to me that the logger instance does a determination on splat behavior and makes some assumptions on it rather than just passing all the necessary data to the formatter itself for the transformation.

MWE that proves this is still an issue:

const logger = winston.createLogger({
  level: "debug",
  defaultMeta: { id: 'APP', service: 'Authentication' },
  transports: [mockTransports.inMemory(actualOutput)]
});

logger.info('this is a test', { extraThing: 7 });
logger.info('this is %c a test', { extraThing: 7 });
assume(actualOutput.every((msg) =>
    msg.hasOwnProperty("extraThing")
)).is.true("Not all messages include the additional metadata")

Edit: While this issue is related to our metadata master issue the root cause is not metadata related. Instead this is an issue with the backwards compatability hotpath optimizations. As such I'm removing it from the list of referenced issues in #2029.