fix(metadata precedence) - fix metadata override issues #1989

maverick1872 · 2021-12-15T16:32:48Z

Purpose

Fixes #2029 #1665

This PR intends to fix the issue regarding child loggers and the current implementation allowing them to override metadata from a parent. This PR is a reincarnation of #1598 now that we have some activity around the project again. I have pulled the latest changes in from master at this point but I will have to set aside a little time to go through these changes and re-verify them and the expected behavior.

Per the original PR I believe I had addressed all the feedback I had received from @DABH but I could be wrong. Holiday vacation starts for me this weekend so I'll add it to me to-do list in the near term to go back through all of this and re-verify they're still the most appropriate changes. In the meantime I'd love any feedback anyone wants to give on this implementation and I'll gladly keep it in mind as I'm doing my re-review!

Original PR Description

When creating a child logger with overrides for defaultMeta properties they do not actually override. Is due to the fact that the child logger is overriding the write function which is inappropriate. It should actually be overriding how the default metadata is being added to the log statement. I will have test cases incoming to prove functionality. All existing test cases are passing.

This should address issue #1596

maverick1872 · 2021-12-15T16:34:15Z

@fearphage @wbt - Pinging for awareness (hope you don't mind) as I've been informed you're currently the active maintainers. Please let me know if you need anything from me!

lib/winston/create-logger.js

lib/winston/logger.js

wbt · 2021-12-16T18:31:31Z

@fearphage @wbt - Pinging for awareness (hope you don't mind) as I've been informed you're currently the active maintainers. Please let me know if you need anything from me!

Thanks for getting back into this!

I think 'active maintainers' is a bit of an overstatement, at least speaking for myself. I'm likely able to chip in here and there, with initial motivation on getting out a release with a fix for a memory-leak problem I'd found & fixed a year and a half ago; I've already been able to help with releasing some important changes merged into winston-transport a while back. My JavaScript expertise level suffices for the applications I work on primarily, but a general-purpose logging library like Winston and PRs like this justifiably make more extensive use of lower-level language functions than is typical for my other current work. (My background goes down to the level of 'programming' via hardware configuration, so it's not completely out of scope, just not a current active focus.) I don't want to merge code into such a highly used library without a pretty high degree of confidence that it's not going to break a funky edge case (as examples across the long tail of rare occurrences can likely be found in practice with this library) or introduce a possible vulnerability.

Especially after Log4Shell, I'm especially sensitive around the potential security implications of introducing new paths by which data could be transferred into a more privileged setting. Allowing a log object which may be ultimately constructed on the basis of attacker-controllable inputs to arbitrarily override metadata fields which might've previously only been settable in more trusted contexts and which may control how the message is routed and handled at least raises flags that IMO require closer review.

The PR is appreciated, in solving what seems to be an issue worth solving. The proposed diff appears to include at least some changes where I don't understand how they contribute to solving the issue, but that might say more about the limits of my understanding than the specific changes themselves. (Some cases could also be the latter, just pending that re-review you've noted is on your to-do list.) I've added a few comments/questions but am not convinced that I presently have the unfunded bandwidth and/or expertise that a solid review of this PR as it stands would likely require. However, I hope this doesn't discourage you from still doing that re-review and improving the PR as you see fit, in the event that someone else is able to review it!

Also, if you send a private email to @DABH and @indexzero and can pass muster with them, you might be able to merge commits yourself if you have adequate confidence in the content. Also, if you know of organizations looking to make significant contributions toward the maintenance of widely-used open-source logging software (especially after recent news), please feel free to make an introduction!

DABH · 2021-12-23T05:10:36Z

Looks like @wbt left at least a few minor comments to address, but I will also try to help with a more thorough review once those are addressed. Also, I have invited @maverick1872 to be a maintainer -- more hands the better :) Looking forward to 3.4!

…tion file

maverick1872 · 2022-02-20T00:30:33Z

@wbt @fearphage @DABH Would it be possible for me to get some reviews on this implementation as it currently stands. Hoping to get it moved forward and get a fix out for the community.

DABH

A few comments and questions, but this is mostly looking good to me :) Thank you, @maverick1872 , for all of your work on this! Very excited to get your work into the hands of the community at last!

DABH · 2022-02-21T01:32:38Z

lib/winston/logger.js

    const logger = this;
+    const clonedParentMetadata = JSON.parse(JSON.stringify(this.defaultMeta))


Is this really the fastest way to clone an object in JS in 2022? :O

Also can we do ; at ends of lines?

Honestly I'm not entirely sure. Versions of node we currently support (>12) do not have a proper language native implementation for deep cloning objects. So as far as I can determine the only solutions available to us at this current juncture are the following:

naive stringify & reparse (my current implementation)

not the most performant but should function consistently

walking the object in it's entirety to clone without persisting object references

prone to implementation errors introducing additional edge cases

external dependency such as lodash.close/deepclone

don't like the idea of introducing additional external dependencies

I feel like none of these are good solutions. Recently there was an introduction of structuredClone but it's only bundled with Node v17.x.x. We could alternatively pull a pollyfill for the functionality but I'm not sure if that's something we want to do or not.

Alternatively if anyone knows of a better way to clone to deeply clone objects I'd love to learn as this has been a reoccurring pain point for myself.

I believe we're using a safe-stringify function in this library in general to avoid issues with circular references etc.; that might be a good idea here.

I believe we're using a safe-stringify function in this library in general to avoid issues with circular references etc.; that might be a good idea here.

I was unaware of this and typically I personally like to see when a resultant object has a circular reference myself so I default to letting it throw the TypeError. But in the context of a library such as Winston it probably is better to handle them gracefully. Will update.

Also can we do ; at ends of lines?

Since I forgot to address this directly; Sounds like we should make an addition to the linter config 😆

DABH · 2022-02-21T01:35:47Z

lib/winston/logger.js

-
-          logger.write(infoClone);
-        }
+      defaultMeta: {


I forget most of the design decisions here. Should this be called defaultMeta, or is meta more appropriate? I don't recall, maybe I will remember more or learn more as I read through 😬 Some docs around recommended usage for meta stuff would be useful (if we don't already have that), although I see a bunch of tests down below so maybe those are pretty self-documenting :)

So this is a great question. The short answer is that it's consistent with every other usage regarding configuring default metadata.

I want to preface the following with it's possible that I'm way off base in my understanding of how defaultMeta is supported overall. As far as I can tell there is no explicit definition of a defaultMeta property on our Logger instance anywhere. Although we reference it in so many places. As such I believe that this is a "convention" based implementation and not necessarily a 1st class implementation. If my presumptions here are accurate, it's extremely important that this convention is not broken.

P.S. It is possible that there's a configuration that I'm unaware of that's leveraged in the dynamic Object.defineProperty calls that would make this non convention based; but I haven't seen anything as of yet.

DABH · 2022-02-21T01:36:35Z

lib/winston/logger.js

@@ -288,6 +270,10 @@ class Logger extends Transform {
      info[LEVEL] = info.level;
    }

+    if (!info[MESSAGE]) {


What is this for? This looks unrelated to child loggers / metadata -- is this fixing some other issue, or is it indeed related? If it's related, a comment might be helpful explaining why?

I believe this to have been an issue with the SPLAT implementation and associated hotpath optimizations. If I am remembering correctly this stemmed from this comment on my previous PR. Additional discussion was had in #1596 way back when. If we want to remove this addition from this addition I'm happy to (so long as all my tests that I've written are still passing. 😃

Edit: I've verified all my tests work without this implementation. Happy to remove. Alternatively I can try and find some time to add in some additional SPLAT tests to re-verify my understanding of this addition; although that may take some time. About to be fairly busy in the coming weeks.

DABH · 2022-02-21T01:40:55Z

lib/winston/logger.js

@@ -647,7 +633,9 @@ class Logger extends Transform {

  _addDefaultMeta(msg) {
    if (this.defaultMeta) {
-      Object.assign(msg, this.defaultMeta);
+      // The msg must be cloned as it is being mutated, but any metadata provided with the msg takes precedence over default


Wait, so Object.assign(msg, this.defaultMeta); doesn't mutate msg? But Object.assign(msg, this.defaultMeta, msgClone); does? This comment confused me a bit... and then I'm also confused why msg is getting merged with msgClone. Is it just to ensure msgClone's metadata is used instead of defaultMeta? But then wouldn't there be some simpler way to write that rather than using Object.assign?

So this is a mutating operation. The issue with this mutation is that we lost the ability to apply the metadata defined in the appropriate order of precedence.

Considerations:

We don't want to mutate the logger's default metadata so we can't use it as the target.

We have to mutate the msg itself as it's what is used in the write method; therefore it must be the target of this operation

Order of precedence is the default metadata, then the msg's configured metadata

Due to the above, and the fact that we HAVE to mutate msg given the current dependency of other code paths (such as write), we have to have a means to reapply any msg specific metadata that overrides default metadata. Without this the default metadata will always take precedence.

lib/winston/profiler.js

test/unit/winston/logger.test.js

… Fix missing semis

maverick1872 · 2022-03-11T04:11:09Z

@DABH @wbt @fearphage Do any of you have any more feedback? I'd like to get this pushed over the finish line in the near future if possible and I'm not so inclined to merge without another maintainers approval.

wbt

I don't have enough in-depth knowledge of this part of the code-base to do a more detailed review within the time-budget available.

lib/winston/profiler.js

tyuv · 2022-03-23T22:42:18Z

@maverick1872 is it possible to separate out and merge the small _addDefaultMeta addition in profiler.js to fix #1665?
Could be very helpful and looks like it can be approved much more quickly

maverick1872 · 2022-03-24T01:05:06Z

@maverick1872 is it possible to separate out and merge the small _addDefaultMeta addition in profiler.js to fix #1665? Could be very helpful and looks like it can be approved much more quickly

Unfortunately that implementation is directly tied to the fixes for default metadata. I'm inclined to go ahead and merge this as I feel it's in the WinstonJS community's best interest. I'm hoping to spend some time this week sorting out how I would cut a new release prior to merging this so I can do it all back to back. Plus that should give the other maintainers some time to block this if they see fit for some reason.

wbt · 2022-03-24T12:22:20Z

I can also help with cutting a release if need be, especially if you update the changelog as that's the biggest part of the job.

maverick1872 · 2022-03-28T14:02:15Z

I can also help with cutting a release if need be, especially if you update the changelog as that's the biggest part of the job.

Ended up getting sick past couple days so I'll get the changelog updated early this week; if not today - I'd love some insight if possible though as to our process for that. Do we have it documented anywhere?

wbt · 2022-03-29T15:22:02Z

That's a good question. I've been mostly following along with the vbump script that @indexzero wrote several years ago, but the main steps I've been doing are as follows:

Complete merging in any PRs that should be part of the release.
Update the changelog. Check to make sure you've caught everything using GitHub's compare tool (example URL for next release is here. It's nice to thank the contributors here. It's nice to organize this by which changes would merit which level of semver bump, and especially call out any breaking changes (major-version-number) concisely at the start.
Update the version number in package.json, bumping as appropriate for semver based on the most significant position change trigger from the changelog you just wrote/reviewed. Do not miss this step!
Make sure your local master branch is up to date.
Make sure all the lint checks and tests pass, beyond what the CI might've told you.
On the Releases tab in the GitHub UI, click 'Draft a new release' in the upper right corner.
Under the 'Choose a tag' dropdown, type the name of the new version starting with a v (e.g. v3.7.0) and don't forget to click the 'Create new tag on publish' option below (this step is annoyingly easy to miss):
Paste the same version number, with or without the v (with is probably better) in the release title box.
Paste the contents of the changelog for this release in the 'Describe this release' box.
Click "Publish release."
Back on the command line, npm publish and complete npm 2FA as needed.
Keep a closer-than-usual eye on issues in the hours and days that follow, prepared to quickly revert/address anything that might be associated with that release.

A more professional version of this would probably use a release branch off master to make sure no other maintainers merge a PR into master between the loading of a compare view for changelog preparation and completion of the process, but we're such a small team that the extra steps are probably not needed. After release, you can also verify with the compare view between the new and prior release tags to see when the latest change was and verify it was before you started the process.

maverick1872 · 2022-03-29T20:51:52Z

That's a good question. I've been mostly following along with the vbump script that @indexzero wrote several years ago, but the main steps I've been doing are as follows:

I'll add a readme to the project for this if you're alright with that. More this is documented the better.

wbt · 2022-03-29T23:24:39Z

It probably doesn't need to go in the public readme which gets automatic visibility to users and potential users, but some other doc could be a good idea.

This reverts commit ba93eae.

* Revert "fix(metadata precedence) - fix metadata override issues (#1989)" This reverts commit ba93eae. * Update changelog * Update version number

jackkainov · 2022-04-07T17:41:31Z

lib/winston/logger.js

@@ -647,7 +634,9 @@ class Logger extends Transform {

  _addDefaultMeta(msg) {
    if (this.defaultMeta) {
-      Object.assign(msg, this.defaultMeta);
+      // The msg must be cloned as it is being mutated, but any metadata provided with the msg takes precedence over default
+      const msgClone = JSON.parse(jsonStringify(msg));


Super late to the party, but because of this change there is no possibility of logging instances of error objects in any way. All the previous suggestions of adding custom formatters in order to extract separate parts of the error object are not applicable anymore. By the time any formatter is called, the error object was already stringified and parsed back, thus losing message, stack, etc. props. As of now, a user of this library should choose: be able to log errors or use defaultMeta logger property.

This looks to be the case. I was under the impression at the time that the ErrorFormatter addressed the use case sufficiently. Obviously I was wrong in that respect. Hence why we did a patch release to "revert" the regression.

I'm going to be working through these scenarios this week ideally to fix the regression contained within the metadata fixes. Any test cases you have would be hugely appreciated!!

Are there any side-effects if I follow this approach?

const msgClone = JSON.parse(jsonStringify(msg)); Object.assign(msg, this.defaultMeta, msgClone);

cause I am facing the issue where defaultMeta is overriding my msg data.

wbt reviewed Dec 16, 2021

View reviewed changes

lib/winston/create-logger.js Outdated Show resolved Hide resolved

wbt reviewed Dec 16, 2021

View reviewed changes

lib/winston/logger.js Outdated Show resolved Hide resolved

wbt reviewed Dec 16, 2021

View reviewed changes

lib/winston/logger.js Show resolved Hide resolved

wbt mentioned this pull request Dec 17, 2021

Child logger from winston default logger #1767

Closed

2 tasks

wbt mentioned this pull request Jan 10, 2022

Overriding format elements in child logger? #1703

Open

maverick1872 mentioned this pull request Jan 14, 2022

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

Open

FoxxMD mentioned this pull request Jan 14, 2022

Deep merge meta objects #1885

Closed

maverick1872 added 10 commits January 29, 2022 15:33

chore: wrap logger tests in top-level describe

e2d4402

chore: restructure tests directory

29a9ff7

chore: restructure logger tests

23d9036

chore: cleanup test descriptions

5df5786

fix: fix ci step to account for npm script rename

4b0624b

Merge branch 'master' into chore/organize-logger-tests

d23801d

chore: rename tests dir back to test

c942452

fix: correct relative file paths

e72d96b

make sure all tests actually run

4495caa

feat: add nyc configuration file

f951b9a

maverick1872 mentioned this pull request Jan 30, 2022

Chore: Organize and restructure tests #2049

Merged

maverick1872 added 2 commits January 30, 2022 13:12

chore: fix missing end of file newlines

6ba9967

fix: ci steps

fd14dfe

maverick1872 force-pushed the bugfix/child-logger-metadata-override-fix branch from bcf5f1a to 5df5786 Compare January 30, 2022 20:30

maverick1872 added 2 commits January 30, 2022 14:44

fix: ci steps try 2

70fa754

chore: rename ci jobs

e18e1bb

maverick1872 closed this Jan 30, 2022

maverick1872 force-pushed the bugfix/child-logger-metadata-override-fix branch from e18e1bb to 237534a Compare January 30, 2022 22:01

maverick1872 added 2 commits January 30, 2022 19:36

chore: leverage yaml file for nyc configuration

692de0d

chore: move nyc configuration from npm script to associated configura…

dc005b7

…tion file

maverick1872 requested review from DABH and fearphage February 13, 2022 00:30

maverick1872 added 2 commits February 12, 2022 17:37

chore: deep clone when instantiating child logger

b36158f

chore: remove unused imports

830d15b

DABH reviewed Feb 21, 2022

View reviewed changes

chore: address comments on logger test additions

97a87b6

maverick1872 requested a review from DABH February 21, 2022 03:56

maverick1872 added 2 commits February 21, 2022 09:31

Replace JSON.stringify with one that accounts for cyclical refs

ddb4dd1

Add lint rule for semicolons. Add script to run linter fix operation.…

0198284

… Fix missing semis

wbt reviewed Mar 14, 2022

View reviewed changes

lib/winston/profiler.js Show resolved Hide resolved

maverick1872 mentioned this pull request Mar 15, 2022

[Bug]: Profiler constructor has no guardrails for what it's constructed from #2091

Closed

maverick1872 merged commit ba93eae into winstonjs:master Mar 31, 2022

maverick1872 deleted the bugfix/child-logger-metadata-override-fix branch March 31, 2022 00:38

wbt added a commit that referenced this pull request Apr 4, 2022

Revert "fix(metadata precedence) - fix metadata override issues (#1989)"

a9efd37

This reverts commit ba93eae.

wbt added a commit that referenced this pull request Apr 4, 2022

Revert for 2103 (#2104)

7937f33

* Revert "fix(metadata precedence) - fix metadata override issues (#1989)" This reverts commit ba93eae. * Update changelog * Update version number

jackkainov reviewed Apr 7, 2022

View reviewed changes

wbt mentioned this pull request Apr 28, 2022

Add publishing instructions #2121

Merged

bensandee mentioned this pull request May 20, 2022

Bump winston from 3.3.3 to 3.7.2 madisonbikes/cyclistsofmsn-backend#14

Closed

maverick1872 mentioned this pull request Jun 21, 2022

[Bug]: defaultMeta returns object not string #2144

Open

This was referenced Feb 28, 2023

issue/2029 #2284

Draft

[Bug]: Winston Error not output anything. #2133

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

fix(metadata precedence) - fix metadata override issues #1989

fix(metadata precedence) - fix metadata override issues #1989

maverick1872 commented Dec 15, 2021 •

edited

Loading

maverick1872 commented Dec 15, 2021

wbt commented Dec 16, 2021

DABH commented Dec 23, 2021

maverick1872 commented Feb 20, 2022

DABH left a comment

DABH Feb 21, 2022

DABH Feb 21, 2022

maverick1872 Feb 21, 2022

wbt Feb 21, 2022

maverick1872 Feb 21, 2022 •

edited

Loading

DABH Feb 21, 2022

maverick1872 Feb 21, 2022 •

edited

Loading

DABH Feb 21, 2022

maverick1872 Feb 21, 2022 •

edited

Loading

DABH Feb 21, 2022

maverick1872 Feb 21, 2022 •

edited

Loading

maverick1872 commented Mar 11, 2022

wbt left a comment

tyuv commented Mar 23, 2022

maverick1872 commented Mar 24, 2022

wbt commented Mar 24, 2022 •

edited

Loading

maverick1872 commented Mar 28, 2022

wbt commented Mar 29, 2022 •

edited

Loading

maverick1872 commented Mar 29, 2022

wbt commented Mar 29, 2022

jackkainov Apr 7, 2022

maverick1872 Apr 7, 2022 •

edited

Loading

amaaanpatel Apr 6, 2024

		const logger = this;
		const clonedParentMetadata = JSON.parse(JSON.stringify(this.defaultMeta))

fix(metadata precedence) - fix metadata override issues #1989

fix(metadata precedence) - fix metadata override issues #1989

Conversation

maverick1872 commented Dec 15, 2021 • edited Loading

Purpose

Original PR Description

maverick1872 commented Dec 15, 2021

wbt commented Dec 16, 2021

DABH commented Dec 23, 2021

maverick1872 commented Feb 20, 2022

DABH left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

maverick1872 Feb 21, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

maverick1872 Feb 21, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

maverick1872 Feb 21, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

maverick1872 Feb 21, 2022 • edited Loading

Choose a reason for hiding this comment

maverick1872 commented Mar 11, 2022

wbt left a comment

Choose a reason for hiding this comment

tyuv commented Mar 23, 2022

maverick1872 commented Mar 24, 2022

wbt commented Mar 24, 2022 • edited Loading

maverick1872 commented Mar 28, 2022

wbt commented Mar 29, 2022 • edited Loading

maverick1872 commented Mar 29, 2022

wbt commented Mar 29, 2022

Choose a reason for hiding this comment

maverick1872 Apr 7, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

maverick1872 commented Dec 15, 2021 •

edited

Loading

maverick1872 Feb 21, 2022 •

edited

Loading

maverick1872 Feb 21, 2022 •

edited

Loading

maverick1872 Feb 21, 2022 •

edited

Loading

maverick1872 Feb 21, 2022 •

edited

Loading

wbt commented Mar 24, 2022 •

edited

Loading

wbt commented Mar 29, 2022 •

edited

Loading

maverick1872 Apr 7, 2022 •

edited

Loading