Meta data doesn't get passed to info object after the update

[teneon]

Please tell us about your environment:

• _winston version: "^3.0.0",
  • winston@2
  • winston@3
• _node -v outputs: v9.8.0
• Operating System? (Linux)

What is the problem?

After updating to the latest version of Winston, 2 days ago, meta data is not added to the info object anymore in some cases!

EXAMPLE 1 (This one works fine!!):
If you log meta data like this, meta becomes part of 'message' object, so it seems to work fine.
logger.error('This is a test', { number: 123 });

'console.log' of the 'info' object looks like this:

{ number: 123,
  level: '\u001b[31merror\u001b[39m',
  message: 'This is a test',
  timestamp: '2018-06-28T09:42:04.036Z',
  [Symbol(level)]: 'error',
  [Symbol(splat)]: [ { number: 123 } ],
  [Symbol(message)]: '{"number":123,"level":"error","message":"This is a test"}' }

EXAMPLE 2 (This one doesn't seem to work properly!!):
If there is an additional argument included ( in this case 'first' ), meta data becomes an empty array in the info object and also it is not anywhere else in the 'message' object at all.
logger.error('This is a test %s', 'first', { number: 123 });

'console.log' of the 'info' object looks like this:

{ level: '\u001b[31merror\u001b[39m',
  message: 'This is a test first',
  timestamp: '2018-06-28T09:48:46.616Z',
  meta: [],
  [Symbol(level)]: 'error',
  [Symbol(splat)]: [ 'first' ],
  [Symbol(message)]: '{"level":"error","message":"This is a test %s"}' }

What do you expect to happen instead?

As you can see, meta data doesn't exist in the 'info' object at all, so there is no way to access it and print it to the console or to log it into the file or anything. This used to work fine before i updated winston npm package 2 days ago.

Thanks for the good work guys, the project is amazing!
Best regards!

[teneon]

I did some more tests and things are even more out of order regarding 'meta data', at least this is how i feel. If you test the examples below and you print out the 'info' object for each of them, you should see that 'meta' sometimes appear as info object property ,sometimes it appears as part of the 'message' object and if you test example 2 in my first post, you should see that sometimes meta data isn't passed to the info object at all.

// meta data
logger.error('This is a test', { number: 123 });

// 1 splat + meta data
logger.error('This is a test %s', 'first', { number: 123 });

// 2 splats
logger.error('This is a test %s %s', 'first', { number: 123 });

// Interpolation: meta data
logger.error(`Testing interpolation`,{ name: 'john'});

// Interpolation: variable + meta data
logger.error(`Testing ${12345} interpolation`,{ name: 'john'});

I think 'meta' property should always appear in the 'info' object at the exactly same place, otherwise it is really hard to check something like: if (info.meta) ...do something...
because info.meta exists in some scenarios, but appears elsewhere (in the different place or even different form) in another scenario and in some scenarios (which i believe is a bug) is not passed to info object at all.

I had to add lot code in my "logger configuration file" just to detect, if meta data exists or not (in all those different scenarios in the examples above), which i believe is totally unnecessary if the properties of info object were consistent. I simply think it would be easiest if we could always check against: if (info.meta) ...do something... else ...do something...

I hope that makes sense and keep up the good work,
best regards!

[GregKlarecky]

It's 2020 already. I had same problem and I guess I figured it out. Sad that docs don't provide that information and make people wrong. My solution - pass everything as an object to logger function:

logger.error({ label, message, url: req.originalUrl, status })

[amir-s]

I spend a good amount of time trying to debug why some of the logs are breaking things in production! Turns out a message we're logging has a %s and it breaks our contract of always having access to the meta object!

I implemented a workaround! it's not the most elegant solution, but it does work!
I added a custom format function that reads the splat data and puts the meta object back on the info object.

new transports.Console({
  format: format.combine({
    transform(info) {
      info.meta = info[Symbol.for('splat')][0].meta;
      return info;
    },
  },
  format.timestamp(),
  format.printf(info => {
    // info.meta is always present
  }
})

you can potentially use anything else other than meta as well if you are not looking for a conflict!

[maverick1872]

Reviewing this issue, as well as #1408 & winstonjs/logform #82 I feel like this issue is not directly caused by the issue that #2029 is currently tracking.

If my understanding is correct on this behavior it appears that the original complaint here is that we had a regression from V2 --> V3 Winston in how our SPLAT formatter handles metadata. As such I'd say this is an issue with the formatter itself, and not a direct issue with the metadata. After having read many issues (both opened and closed) I think there may be a larger issue at play that warrants a standalone issue to track issues and the associated fixes for SPLAT behavior, as well as the application of different formats.

Pinging for visibility - @wbt @fearphage @DABH
Should we generate another new master issue that's related to SPLAT behavior and the unexpected behavior caused by the hotpath optimizations on our backwards compatible log method I described in #1709. I'm not sure where the best place to initiate and have this discussion unfortunately.

Either way I feel like there's quite a few issues that are open, and a few PRs that are related to this behavior both in the logform repository as well as here and having a means to correlate them all would be nice IMO

[wbt]

Sounds like a good idea to me.