[BUG]: Inconsistent metadata overrides (master issue)

[maverick1872]

Purpose:

One of the current, most notable issues with Winston today is the how we handle the application of default metadata for a given instance of a logger. As it stands the current implementation makes some bad assumptions around metadata precedence in different contexts. This issue is being created to consolidate all relevant/duplicate issues & the associated Pull Requests.

Consolidations

Below is a compiled list of all issues and pull requests I have been able to find regarding this issue. They are sorted newest to oldest. All issues below are going to be marked as a duplicate and then closed. This is being done to hopefully centralize all efforts for resolving this issue to this issue moving forward.

Issues:

Potential Regression Issues

These are all the issues that reference 3.7.1 & 3.7.2

• Error objects can no longer be logged
• [Bug]: TypeError encountered when logging class extending superclass which contains protected property #2103
• [Bug]: defaultMeta returns object not string #2144
• [Bug]: default metadata is not added on log message of profiler #2162
• [Bug]: method logger.child({defaultMeta: true}) doesen't add default meta object in the splat property of the info object #2168
  • likely can be considered unrelated for time being as it's specific to the SPLAT format
• [Bug]: Message key in metadata overwrites original message #2306
  • Need to verify test cases cover this issue

Original Issues:

• Deep merge meta objects #1884 (I believe this would be a departure from currently documented behavior)
• Combine child metadata with additional metadata #1864
• Child Logger Doesn't Override Parent Metadata #1788
• defaultMeta ignored when using logger.log function but not in logger[level] functions #1759
• Profiler.done doesn't respect defaultMeta. #1665
• Log / info methods don't respect metadata overrides #1596
• Winston loses Map and Set properties on meta #1054

Pull Requests:

• Fix how metadata works #2037 (Centered around Request: Functions in Default Metadata #1626 but also claims to solve metadata override issues)
• fix(metadata precedence) - fix metadata override issues #1989 (Recreation of my original PR)
• Fix child logger overrides #1943
• Fix: Missing defaultMeta in log entry while using Profiler #1935 (Implements a fix for Profiler.done doesn't respect defaultMeta. #1665 but in a manner that I feel introduces maintenance burden)
• Deep merge meta objects #1885
• root & child meta-data #1883
• Default metadata application fixes #1879
• Fix defaultMeta override in child logger #1864 #1875
• Enable child logger to override parent metadata #1782
• Fix bug in overriding default metadata in child loggers. #1598 (opened by myself)

Notes

If you're aware of any other Issues or PRs (including those that have been closed) that are not included above please let me know and I'll get them added to the list.

[DABH]

@maverick1872 I think this one is related as well #1935

[maverick1872]

@maverick1872 I think this one is related as well #1935

It looks to be related but I'm not as familiar with the expected behavior of the profiler functionality. Will look into it though.

[maverick1872]

Was able to make some progress on this after-hours this week finally. I have a handful of new test cases setup that are expected failures on our current trunk. There's more general cleanup I'd like to do, as well as improving the structure of these tests to further improve their intent & readability. Hopefully I can make this a little easier for others to drop in and further improve the current test coverage, as it's currently in a state that needs some extra love/attention.

[maverick1872]

@wbt @fearphage @DABH

I've got a set suite of tests built out proving the current issue with our logic for applying metadata, as well as an associated fix that gets all of them to pass. As it stands the only other PR currently (that I'm aware of) that gets my tests to pass is #2037.

That implementation introduces a few things other than a fix for merge inconsistencies. Most notably it introduces a means to add getters for lazy determination of metadata. This is a feature that would honestly be pretty valuable in my opinion to have in future versions of Winston.

But, the implementation does come at a downside (in my opinion) with how it solves the merge issue. Each child that is generated holds on to a reference of the parents metadata. When generating metadata for a given log statement it recursively walks the parent chain to generate the output on the fly. This causes two things; first it's fairly inefficient and adds overhead to every write call which is something we should avoid where possible. But more severely, is that any changes to a parent's metadata will be reflected in any/every child due to the reference that's retained. I intend to add a handful of additional tests to prove out this behavior, both in mine and in #2037.

With that being said I am really interested to know what y'all's thoughts are regarding this.

[FoxxMD]

I'm actually a fan of the "downside". I'm doing exactly that (using getters for child metadata) because I specifically want the functionality of metadata being dynamic. It might not be the best solution at this point but having it as an option in my toolbelt has been extremely useful.

[maverick1872]

@FoxxMD I wholly understand the value in it, but I believe it to be a breaking change from our current implementation hence it being a "downside" Semi-related to our other discussion is that if we offer first-class support for extending the Logger class this becomes moot as one could just override our default implementation with their own metadata merge logic. Alternatively we could surface the merge logic as a configurable option to continue being backwards compatible while supporting this behavior.

In terms of resolution of the issue at hand, the smallest set of changes, that are non-breaking to our current behavior receives my vote. I'm not partial to any implementation beyond that.

Edit: per your linked implementation - this is different than the linked PR. You're leveraging getters for "dynamic" metadata where as the downside I'm talking about is the following (unverified but illustrates my point):

const rootLogger = winston.createLogger({
  transports: [mockTransports.inMemory(actualOutput)],
  defaultMeta: {label: "initialLabel"}
});
const childLogger = rootLogger.child();

childLogger.info("some message"); // will include <label: "initialLabel">
rootLogger.configure({
  defaultMeta: {label: "updatedLabel"}
});
childLogger.info("some message"); // will include <label: "updatedLabel">```

[maverick1872]

Added the above mentioned tested to my PR and have confirmed my implementation does not allow any modifications to the parent's metadata to propagate to the child, after the child has been created.

[bertho-zero]

This is due to:

winstonjs/winston@3998df0/lib/winston/logger.js#L235-L255

This processing should not exist and should be done by format if desired.

[maverick1872]

@wbt re-opening since we reverted and released a patch bump. Should have done this awhile ago. As such I'll be re-opening a PR that includes reverts the revert, and then publish a release candidate that's equivalent to 3.7.1; at that point I'll start iterating again on a fix for the regressions it introduced.

[wbt]

Looks like #2306 fits in this list.

[coma-toast]

In case someone else runs into this issue and needs a simple workaround, I just use nullish coalescing to provide default and custom output (remove the defaultMeta from your LoggerOptions and use this instead):

const logFormat = format.printf(({ level, message, label, timestamp, ...meta }) => {
    return `${timestamp} [${meta.service ?? "user-service"}] ${level}: ${message}`;
});

[ReSpawN]

Came across the same issue just now. Not a big problem at this time but the inconsistency is irritating.

"env":"development","level":"debug","message":"Example kicked off","service":"scraper-alpha","timestamp":"2024-08-09T09:50:10.341Z"}
{"durationMs":419,"level":"info","message":"adapter","timestamp":"2024-08-09T09:50:10.760Z"}
{"durationMs":1162,"level":"info","message":"adapter","timestamp":"2024-08-09T09:50:11.922Z"}
{"env":"development","level":"info","message":"Example authenticated","service":"scraper-alpha","timestamp":"2024-08-09T09:50:12.014Z"}
{"durationMs":121,"level":"info","message":"screenshot","timestamp":"2024-08-09T09:50:12.043Z"}