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

Fix how metadata works #2037

Closed
wants to merge 1 commit into from

Conversation

intentionally-left-nil
Copy link

@intentionally-left-nil intentionally-left-nil commented Jan 18, 2022

This PR rethinks how metadata works in Winston, supporting the following goals:

  • Metadata should always merge in this order: message metadata > splat > logger.defaultMeta > parent.defaultMeta -> grandparent.defaultMeta....
  • Metadata updated in a parent logger should be reflected dynamically when children log
  • Metadata should allow for javascript getters() so you can have dynamic metadata
  • Metadata should always be captured (in the case of dynamic metadata) at the same spot so callstacks are consistent

This PR attempts to solve all of these issues while making the smallest set of changes to the existing codebase.

Here's how it works:

Child loggers

Child logging now works by holding onto a reference to the parent logger (this.parentLogger).
Then, the defaultMetadata for the child only contains the metadata specific to the child (which may override any parent metadata).

Parent and child metadata are merged together during _addDefaultMeta (explained below)

Dynamic logging

Following the idea from #1626, this PR fully supports having dynamic metadata. The basic idea is you can do something like this:
createLogger({defaultMeta: { get caller() { return new Error().stack}}

Supporting this functionality requires two chages:

  1. We want to keep these getters around. Calling Object.assign() would lose the getter since it actualizes the value and stores the result instead. So, instead, I made this helper function which mimics Object.assign(), except that it copies properties as well.
function assignWithGetters(target, ...sources) {
  // eslint-disable-next-line no-shadow
  return sources.reduce((target, source) => {
    // eslint-disable-next-line eqeqeq
    if (source != null) {
      const enumerableKeys = Object.keys(source);
      const symbolKeys = Object.getOwnPropertySymbols(source);
      // Don't use Reflect.ownKeys here because we only want to assign enumerable ones
      for (const key of enumerableKeys.concat(symbolKeys)) {
        Object.defineProperty(target, key, Object.getOwnPropertyDescriptor(source, key));
      }
    }
    return target;
  }, target);
}

Then, we want to consistently actualize the final data when actually logging. The primary consideration here is to always have callstacks in the correct place (so that callers can do things like slice off a consistent number of frames). That is why this code exists:

  write(chunk, ...args) {
    if (!(chunk instanceof Error)) {
      chunk = Object.assign({}, chunk);
    }
    super.write(chunk, ...args);
  }

(Errors are treated special for winston. I'm not super thrilled with the cutout here - open for suggestions).

Merging metadata in the correct order

The main idea is to always use this function when dealing with metadata:

  _addDefaultMeta(msg) {
    const merged = {};
    if (this.parentLogger) {
      this.parentLogger._addDefaultMeta(merged);
    }
    assignWithGetters(merged, this.defaultMeta, msg);
    assignWithGetters(msg, merged);
  }

It keeps the same semantics of _addDefaultMeta() before, but it does the update in the correct order.
First, it recursively merges any parent logger metadata.
Then it adds the current metadata, and finally the metadata for the existing object.
Then, it re-uses the msg() object by merging everything into that object.

There's some additional logic changes needed to the log() method, since not every codepath goes through the _addDefaultMeta() flow.

Misc

Almost every test works out-of-the-box with this change.
The only test that doesn't work monkey-patches the write method, so it doesn't pick up all of my code changes. I fixed the test to properly use the transport to grab the data, but the logic of the test is unchanged

The nice thing about centralizing all of this behavior, is that it would make it easy to add new features in the future. For example, if you want to support custom merging (e.g #1884) then we could just add support for that in _addDefaultMeta

Closes #2029


});
if (mergeMessage && meta.message) info.message = `${info.message} ${meta.message}`;
if (mergeMessage && meta.stack) info.stack = meta.stack;
Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't really think this is a good idea, btw - but it keeps consistency with the existing behavior. If merging is desired, we should implement a custom merge function that callers can pass in when initializing the logger.

@wbt
Copy link
Contributor

wbt commented Jan 20, 2022

This seems related to a collection of related issues centered on #2029, which @maverick1872 is taking the lead on collating.

@maverick1872
Copy link
Member

@AnilRedshift Currently working on writing out a whole suite of test surrounding the merging of metadata and expected behavior as I want to be explicitly sure that we catch as many edge cases as possible. This includes ensuring no metadata manages to propagate from a given logger instance to that of it's parent/child/sibling. I anticipate having them wrapped up tomorrow when I will then be able to start reviewing both my own personal implementation as well as all of the others suggested at this point in time.

@intentionally-left-nil
Copy link
Author

intentionally-left-nil commented Jan 20, 2022

Cool, thanks for coordinating the work. Happy to help out where I can. I have questions about how this should work:

This includes ensuring no metadata manages to propagate from a given logger instance to that of it's parent/child/sibling

but probably the best place to have that discussion is in the mega-issue, or when you create your test cases

@maverick1872
Copy link
Member

Cool, thanks for coordinating the work. Happy to help out where I can. I have questions about how this should work:

This includes ensuring no metadata manages to propagate from a given logger instance to that of it's parent/child/sibling

but probably the best place to have that discussion is in the mega-issue, or when you create your test cases

Feel free to go ahead and ask here. Due to how metadata is currently handled though, I'm pretty positive mutations on a given object can be reflected in other logger instances because the object reference can be reused. Hence the reasoning for building out the tests prior to determining which implementation is the most appropriate.

@maverick1872
Copy link
Member

So having thought on this implementation for a bit and the stated goals it's intended to achieve; I have the following thoughts on two of them.

* Metadata updated in a parent logger should be reflected dynamically when children log

I pretty strongly disagree with the goal. This can cause weird end user behavior and will be a pretty significant breaking change from our current implementation. If this is something that is desired by the broader community I think the more appropriate avenue for this kind of feature set would be by allowing end-users to extend the Logger class with their own implementations, then override behavior however they see fit. As such I'm not sure this is something we would want to implement.

* Metadata should allow for javascript getters() so you can have dynamic metadata

Having the ability to configure metadata for a logger whose determination is delayed until the actual writing of the log message is a pretty useful thing and I think this is a pretty viable feature candidate. Biggest concern is of course breaking changes though. If you're interested in opening a PR that is limited in scope to this, that would be great.

@maverick1872
Copy link
Member

Ok, got a chance to test this implementation against the suite of tests I've built out in #1989. All are passing with this implementation. I think my biggest unknown with this current implementation is still the "parent metadata should be dynamically reflected" Since I don't have any tests that prove/disprove this in the current implementation I'm going to add a couple more to validate that behavior.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

[BUG]: Inconsistent metadata overrides (master issue)
3 participants