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(metadata precedence) - fix metadata override issues #1989

Merged
Show file tree
Hide file tree
Changes from 39 commits
Commits
Show all changes
42 commits
Select commit Hold shift + click to select a range
e2d4402
chore: wrap logger tests in top-level describe
maverick1872 Jan 29, 2022
29a9ff7
chore: restructure tests directory
maverick1872 Jan 29, 2022
23d9036
chore: restructure logger tests
maverick1872 Jan 30, 2022
5df5786
chore: cleanup test descriptions
maverick1872 Jan 30, 2022
4b0624b
fix: fix ci step to account for npm script rename
maverick1872 Jan 30, 2022
d23801d
Merge branch 'master' into chore/organize-logger-tests
maverick1872 Jan 30, 2022
c942452
chore: rename tests dir back to test
maverick1872 Jan 30, 2022
e72d96b
fix: correct relative file paths
maverick1872 Jan 30, 2022
4495caa
make sure all tests actually run
maverick1872 Jan 30, 2022
f951b9a
feat: add nyc configuration file
maverick1872 Jan 30, 2022
6ba9967
chore: fix missing end of file newlines
maverick1872 Jan 30, 2022
fd14dfe
fix: ci steps
maverick1872 Jan 30, 2022
70fa754
fix: ci steps try 2
maverick1872 Jan 30, 2022
e18e1bb
chore: rename ci jobs
maverick1872 Jan 30, 2022
692de0d
chore: leverage yaml file for nyc configuration
maverick1872 Jan 31, 2022
dc005b7
chore: move nyc configuration from npm script to associated configura…
maverick1872 Jan 31, 2022
f2ee50a
chore: move common mocha configurations from npm script to dedicated …
maverick1872 Jan 31, 2022
85ea8a6
feat: introduce a in-memory mock transport generator
maverick1872 Jan 31, 2022
b233a8b
chore: make test callback functions consistent
maverick1872 Jan 31, 2022
ce2f607
feat: introduce tests proving issues with metadata precedence
maverick1872 Jan 31, 2022
96dfeda
fix: introduce fix for application of default metadata
maverick1872 Jan 31, 2022
b44d4b1
feat: add equivalent tests for .log() method
maverick1872 Jan 31, 2022
f748636
chore: update nyc coverage
maverick1872 Jan 31, 2022
f350f2c
Merge remote-tracking branch 'upstream/master' into bugfix/child-logg…
maverick1872 Feb 8, 2022
f89285a
chore: undo accidental indent
maverick1872 Feb 8, 2022
b2efe8f
chore: add new test to ensure a parents metadata updates don't propog…
maverick1872 Feb 8, 2022
010e955
chore: fix nyc coverage requirements
maverick1872 Feb 8, 2022
f393a50
feat: introduce test proving issue with Profilers instance not includ…
maverick1872 Feb 9, 2022
3577d1d
feat: ensure Profiler triggers the logger's add default metadata func…
maverick1872 Feb 9, 2022
fc39513
fix: add a safety net to calling 'addDefaultMeta' on the logger instance
maverick1872 Feb 9, 2022
d9f105c
chore: fix failing build issues
maverick1872 Feb 9, 2022
8eab107
feat: add test to ensure changes to parents metadata are not propogat…
maverick1872 Feb 12, 2022
4c544f1
Merge remote-tracking branch 'upstream/master' into bugfix/child-logg…
maverick1872 Feb 12, 2022
4e830d6
fix: remove linebreak configuration from editorconfig
maverick1872 Feb 12, 2022
8724f4b
chore: combine level and log tests of same kind to ensure both output…
maverick1872 Feb 12, 2022
a2ec0c2
feat: introduce tests proving issues reported
maverick1872 Feb 12, 2022
c4dd5ea
feat: introduce tests for non-primitive data types in metadata
maverick1872 Feb 13, 2022
b36158f
chore: deep clone when instantiating child logger
maverick1872 Feb 13, 2022
830d15b
chore: remove unused imports
maverick1872 Feb 13, 2022
97a87b6
chore: address comments on logger test additions
maverick1872 Feb 21, 2022
ddb4dd1
Replace JSON.stringify with one that accounts for cyclical refs
maverick1872 Feb 21, 2022
0198284
Add lint rule for semicolons. Add script to run linter fix operation.…
maverick1872 Feb 21, 2022
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 0 additions & 1 deletion .editorconfig
Original file line number Diff line number Diff line change
Expand Up @@ -6,7 +6,6 @@ root = true
# default configuration
[*]
charset = utf-8
end_of_line = crlf
trim_trailing_whitespace = true
insert_final_newline = true
indent_style = space
Expand Down
2 changes: 1 addition & 1 deletion .nycrc.yml
Original file line number Diff line number Diff line change
Expand Up @@ -4,5 +4,5 @@ reporter:
check-coverage: true
branches: 61.51
lines: 70.85
functions: 73.21
functions: 73.08
statements: 70.54
36 changes: 12 additions & 24 deletions lib/winston/logger.js
Original file line number Diff line number Diff line change
Expand Up @@ -9,7 +9,7 @@

const { Stream, Transform } = require('readable-stream');
const asyncForEach = require('async/forEach');
const { LEVEL, SPLAT } = require('triple-beam');
const { LEVEL, SPLAT, MESSAGE } = require('triple-beam');
const isStream = require('is-stream');
const ExceptionHandler = require('./exception-handler');
const RejectionHandler = require('./rejection-handler');
Expand Down Expand Up @@ -42,30 +42,12 @@ class Logger extends Transform {
this.configure(options);
}

child(defaultRequestMetadata) {
child(childMetadata) {
const logger = this;
const clonedParentMetadata = JSON.parse(JSON.stringify(this.defaultMeta))
Copy link
Contributor

Choose a reason for hiding this comment

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

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

Copy link
Contributor

Choose a reason for hiding this comment

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

Also can we do ; at ends of lines?

Copy link
Member Author

Choose a reason for hiding this comment

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

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.

Copy link
Contributor

Choose a reason for hiding this comment

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

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.

Copy link
Member Author

@maverick1872 maverick1872 Feb 21, 2022

Choose a reason for hiding this comment

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

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 😆

return Object.create(logger, {
write: {
maverick1872 marked this conversation as resolved.
Show resolved Hide resolved
value: function (info) {
const infoClone = Object.assign(
{},
defaultRequestMetadata,
info
);

// Object.assign doesn't copy inherited Error
// properties so we have to do that explicitly
//
// Remark (indexzero): we should remove this
// since the errors format will handle this case.
//
if (info instanceof Error) {
infoClone.stack = info.stack;
infoClone.message = info.message;
}

logger.write(infoClone);
}
defaultMeta: {
Copy link
Contributor

Choose a reason for hiding this comment

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

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 :)

Copy link
Member Author

@maverick1872 maverick1872 Feb 21, 2022

Choose a reason for hiding this comment

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

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.

value: Object.assign({}, clonedParentMetadata, childMetadata)
}
});
}
Expand Down Expand Up @@ -288,6 +270,10 @@ class Logger extends Transform {
info[LEVEL] = info.level;
}

if (!info[MESSAGE]) {
Copy link
Contributor

Choose a reason for hiding this comment

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

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?

Copy link
Member Author

@maverick1872 maverick1872 Feb 21, 2022

Choose a reason for hiding this comment

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

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.

info[MESSAGE] = info.message;
}

// Remark: really not sure what to do here, but this has been reported as
// very confusing by pre winston@2.0.0 users as quite confusing when using
// custom levels.
Expand Down Expand Up @@ -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
Copy link
Contributor

Choose a reason for hiding this comment

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

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?

Copy link
Member Author

@maverick1872 maverick1872 Feb 21, 2022

Choose a reason for hiding this comment

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

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.

const msgClone = JSON.parse(JSON.stringify(msg));
Object.assign(msg, this.defaultMeta, msgClone);
}
}
}
Expand Down
7 changes: 5 additions & 2 deletions lib/winston/profiler.js
Original file line number Diff line number Diff line change
Expand Up @@ -21,6 +21,8 @@ module.exports = class Profiler {
* @private
*/
constructor(logger) {
// TODO there is no restriction on what the Profiler considers a Logger. As such there is no guarantees it adheres
// to the proper interface. This needs to hardened.
maverick1872 marked this conversation as resolved.
Show resolved Hide resolved
if (!logger) {
throw new Error('Logger is required for profiling.');
}
Expand All @@ -32,7 +34,8 @@ module.exports = class Profiler {
/**
* Ends the current timer (i.e. Profiler) instance and logs the `msg` along
* with the duration since creation.
* @returns {mixed} - TODO: add return description.
* @returns {boolean} - `false` if the logger stream wishes for the calling code to wait for the 'drain' event to be
* emitted before continuing to write additional data; otherwise `true`
* @private
*/
done(...args) {
Expand All @@ -45,7 +48,7 @@ module.exports = class Profiler {
const info = typeof args[args.length - 1] === 'object' ? args.pop() : {};
info.level = info.level || 'info';
info.durationMs = (Date.now()) - this.start;

if (this.logger._addDefaultMeta) this.logger._addDefaultMeta(info);
return this.logger.write(info);
}
};
22 changes: 20 additions & 2 deletions test/helpers/mocks/mock-transport.js
Original file line number Diff line number Diff line change
@@ -1,9 +1,10 @@
const stream = require('stream')
const winston = require('../../../lib/winston');
const {Writable} = require("stream");

/**
* Returns a new Winston transport instance which will invoke
* the `write` method on each call to `.log`
* the `write` method on each call to `.log`
*
* @param {function} write Write function for the specified stream
* @returns {StreamTransportInstance} A transport instance
Expand All @@ -17,6 +18,23 @@ function createMockTransport(write) {
return new winston.transports.Stream({ stream: writeable })
}

/**
* Returns a valid Winston transport that writes to the passed array object
* @param array Array to be used to store the "written" chunks
* @returns {winston.transports.Stream}
*/
function inMemory(array, options = {}) {
const memoryStream = new Writable({
objectMode: true,
write: (chunk, encoding, next) => {
array.push(chunk);
next()
}
});
return new winston.transports.Stream({stream: memoryStream, ...options})
}

module.exports = {
createMockTransport
createMockTransport,
inMemory
};
Loading