Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[BUG]: Inconsistent metadata overrides (master issue) #2029

Open
maverick1872 opened this issue Jan 14, 2022 · 12 comments · Fixed by #1989 · May be fixed by #2284
Open

[BUG]: Inconsistent metadata overrides (master issue) #2029

maverick1872 opened this issue Jan 14, 2022 · 12 comments · Fixed by #1989 · May be fixed by #2284
Assignees
Labels
Bug Child Loggers Applies to the implementation of child loggers Groomed Issue has been reviewed and is ready for handling Important Metadata Applies to Metadata behavior Profiling Applies to Profiling behavior

Comments

@maverick1872
Copy link
Member

maverick1872 commented Jan 14, 2022

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

Original Issues:

Pull Requests:

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
Copy link
Contributor

DABH commented Jan 15, 2022

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

@maverick1872
Copy link
Member Author

@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
Copy link
Member Author

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.
Screen Shot 2022-01-29 at 12 27 57 AM

@maverick1872
Copy link
Member Author

@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
Copy link

FoxxMD commented Feb 8, 2022

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
Copy link
Member Author

maverick1872 commented Feb 8, 2022

@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
Copy link
Member Author

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
Copy link

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 maverick1872 reopened this Feb 27, 2023
@maverick1872
Copy link
Member Author

@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.

@maverick1872 maverick1872 linked a pull request Feb 28, 2023 that will close this issue
5 tasks
@wbt
Copy link
Contributor

wbt commented May 26, 2023

Looks like #2306 fits in this list.

@coma-toast
Copy link

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
Copy link

ReSpawN commented Aug 9, 2024

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"}

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Bug Child Loggers Applies to the implementation of child loggers Groomed Issue has been reviewed and is ready for handling Important Metadata Applies to Metadata behavior Profiling Applies to Profiling behavior
Projects
None yet
7 participants