Implement child loggers

[kibertoad]

Note that this is a naive implementation that reinitializes each child logger completely which may be undesireable for performance reasons (didn't benchmark it, though, at a glance it doesn't look like any expensive operations are happening, but we may still squeeze some additional performance out of it). If this implementation is reviewed and accepted I am going to work on a follow-up optimization that will reuse original logger in hot-path cases.
Update for historical purposes: it was reworked for performance before being merged.

[kibertoad]

@DABH Any chance for a review?..

[DABH]

Not today but hopefully soon. Seems cool at first glance though! 😎

[kibertoad]

@DABH Any ETA for when you could possible have time to take a look?

[DABH]

Ok, I'm looking at this now in combination with #1482 . Can you help me understand why it isn't enough to just use a dynamic formatter? Something like

const childFormatter = (childMeta) => (info, opts) => {
    const meta = {foo: 'bar'};
    if(childMeta)
        meta[foo] = childMeta[foo];
    info['meta'] = meta;
    return info;
};

...hmmm... which I guess you could use like

const logger = winston.createLogger({
  level: 'info',
  format: winston.format.json(),
});
const defaultTransport = new winston.transports.Console({format: childFormatter()});
const reqTransport = new winston.transports.Console({format: childFormatter({foo: 'request')});
logger.add(reqTransport);
logger.add(defaultTransport);
reqTransport.log('info', 'test');
defaultTransport.log('info', 'test');

(code not tested!). Maybe a better idea since that got a bit inelegant is to add a function to logger called like logWithFormat, which allows you to pass in a custom formatter that will override whatever formatter is supplied to the log? Then you could just say

...
const reqFormat = childFormatter({foo: 'request'});
logger.logWithFormat(reqFormat, 'info', 'test');

Anyway, something like this could be more efficient than creating a bunch of different logger objects. Let me know what you think!

[DABH]

If you required an isomorphic interface, you could make some kind of wrapper so that a logger.child call would return an object that would somehow just forward all calls to logger.logWithFormat -- haven't thought through the details of that, but the point is that there should ideally be a way to do this with at most creating new formatters but re-using everything else.

[soldair]

@kibertoad would you consider making it so that the only argument a child logger could take is the default metadata? you could change it to use this more efficient instantiation pattern referenced here #1482 and enabled by #1483

our use case is a logger per request and it has to be as light as possible.
its also the only api surface other logging libraries like bunyan support for .child().

I'm not a member of the project so this is just a friendly suggestion =) i have no idea if it will make it more or less likely to merge. It's easier to add api later than take it away later.

[kibertoad]

Thanks for all the feedback and ideas! I'll definitely meditate over this during weekend and see what happens :)

[kibertoad]

@soldair @DABH @ofrobots Sorry it took so long; should be ready for the prime time now! Would appreciate a rereview.

[kibertoad]

@DABH Any chance for a rereview?..

[DABH]

@kibertoad Sure I'll take a look now

[DABH]

This looks good to me now but I'd like @indexzero to be the one to hit Merge in case there is anything he spots that I don't. Thanks for your effort and patience with this!

[DABH]

Also, did you do anything to verify that performance of the "hotpaths" in log() aren't affected for regular loggers without defaultMeta? I think this is a useful feature but want to be sure it doesn't slow down the core code paths if people don't use the feature.

[kibertoad]

@DABH How do you recommend to verify that?

[DABH]

@kibertoad So it looks like the path that's modified is if (msg && typeof msg === 'object') {. I would recommend a simple timer (there are many simple npm libs) and do something like:

start=timer.start();
for(int i=0;i<=1000;i++){ // maybe 10k or 100k
  logger.log('debug', { key: 'value' }); // this should reach the modified path?
}
end=timer.stop();
console.log(`time: {end-start}`);

and run it on your branch and on master. Does that make sense?

I doubt the extra _addDefaultMeta call is that expensive, especially if branch prediction works well, but let's check and see...

[kibertoad]

@DABH I've used benchmark library. Here are the results:

master:
Mean: 0.000002843738407635684 Count 32699
Mean: 0.000002886732308899111 Count 32425
Mean: 0.000002902891836593912 Count 34026
Mean: 0.000002956892970993915 Count 34000
Mean: 0.0000029766696514213577 Count 32152
Mean: 0.0000029823294393635728 Count 34488

branch:
Mean: 0.000002729320441547197 Count 31937
Mean: 0.000002758979822887772 Count 32137
Mean: 0.0000027981622873749474 Count 31231
Mean: 0.000002899554693805795 Count 33460
Mean: 0.000002936623295669092 Count 32872
Mean: 0.0000030185281107653257 Count 34325

I don't see any meaningful difference in two results.

[kibertoad]

Here is exact code so that anyone could reproduce it or point out flaws in the way it was tested:

const Benchmark = require('benchmark');
const winston = require('../lib/winston');

    it('measure performance', async function() {
        this.timeout(500000);
        const logger = winston.createLogger({
            level: 'info',
            format: winston.format.json(),
            transports: [
                new winston.transports.Console({
                    format: winston.format.simple()
                })
            ]
        });

        const benchmark = new Benchmark('logging', () => {
            logger.log('debug', { key: 'value' });
        }, { 'async': false, minSamples: 125, cycles: 30, initCount: 5 });

        benchmark            // add listeners
            .on('cycle', function(event) {
            })
            .on('complete', function() {
                console.log('Mean: '+this.stats.mean + ' Count '+ this.count);
            })
            .run();
    });

[DABH]

Nice! Thanks so much. You have my +1 -- as long as @indexzero is ok with this design, this is ready to merge.

[indexzero]

This is definitely moving in the right direction & this feature has been requested many times by the community. Will give this a deeper look over in the next week or so and then it will likely land. Tests look solid.

If you have the benchmark script you ran that would be very helpful!

[kibertoad]

@indexzero Please check previous comments for a benchmark script; the only thing it was missing were import statements, added them now.
Thanks!

[kibertoad]

@indexzero Is there enough information or do I need provide anything additionally?

[DABH]

@kibertoad We just ran out of time reviewing this in our last meeting so we didn't complete a final review -- but I am pretty sure there is enough info here. Assuming @indexzero +1's the design, the plan is to merge this and cut a new winston release to npm on 12/23. Apologies for the delay and thanks again for your patience!

[little-yao]

if info is a Error type value,this will lost some values,such as stack.

[kibertoad]

@little-yao Thank you for noticing this! I've fixed the case when error is passed as the only param; it doesn't look like Winston itself supports cases when you pass error message as string followed by Error message, but please correct me if I'm wrong or if there are additional cases that need handling. Also would appreciate if you could check latest commit for correctness.

[little-yao]

thank you for replying and editing!I looked for winston carefully, and also can't find somthing about surpporting Error.
I think how about use "info instanceof Error" to judging,Object.assign can't cover "stack" is because enumerable is false, but user can also set "stack" prop.
and how about set info prototype to result, here is my code
if (info instanceof Error) { infoClone.stack = info.stack; infoClone.message = info.message; } infoClone.__proto__ = info.__proto__;

[kibertoad]

Changed, thanks!

[kibertoad]

Note: I see same AppVeyor test failing in master, so probably it doesn't matter.

[ShqipognjaLL]

I've been looking through the source code and unlike creating multiple loggers, creating a child logger simply returns a new logger instance but does not actually add it to winston.loggers map. If this is correct then one would manually have to handle passing the created instance to the places it needs to be used as well as potentially removing it when done. Should the child loggers be maintained in an internal map to the logger container or the overall winston loggers map and in turn provide access and utility methods such as get, remove etc? What is the use case for using child logger instead of just creating a new logger? Are the child loggers that much more performant than base logger creation? I'm asking because I'm looking to dynamically create child loggers to include dynamic request meta in express app and want to avoid doing something like attaching the child instance to the req object and having to reference it that way. Would ideally like to import the base logger and perform a get based on a unique id attached to the child meta on creation.