-
-
Notifications
You must be signed in to change notification settings - Fork 34.3k
[WIP] lib: added logger api in node core #60468
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
base: main
Are you sure you want to change the base?
[WIP] lib: added logger api in node core #60468
Conversation
|
Review requested:
|
lib/logger.js
Outdated
| constructor(options = {}) { | ||
| validateObject(options, 'options'); | ||
| const { | ||
| handler = new JSONHandler(), |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Rather than passing the handler directly in like this, it would be worth considering a design more like swift-log where there is a separate interface for indirectly attaching a consumer. That way it doesn't need to be the responsibility of each place a logger is constructed to decide where the logs are being shipped. I had planned on working on structured logging myself at some point, using diagnostics_channel to manage dispatching log events to consumers, and even support multiple consumers. In a lot of apps you might want console output but also to be writing logs to other places like log search services.
My original plan was to have separate channels for each log level, that way events of log levels not being listened to could be ignored entirely, but also it would enable each consumer to decide their own log level independently--a console logger might want to only listen to info+ levels while an attached diagnostics tool might want to see everything.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
+1 sound good, thanks for detail, I will apply this plan.
|
thats my first performance results: I think need improvement for child logger area, but ı'm so happy because other results it looks nice. node:logger vs pino ➜ node git:(mert/create-logger-api/node-core) ✗ ./node benchmark/logger/vs-pino.js n=100000
logger/vs-pino.js scenario="simple" logger="node-logger" n=100000: 5,240,540.823813018
logger/vs-pino.js scenario="child" logger="node-logger" n=100000: 2,635,847.7027229806
logger/vs-pino.js scenario="disabled" logger="node-logger" n=100000: 159,436,487.67795104
logger/vs-pino.js scenario="fields" logger="node-logger" n=100000: 3,619,336.304205216
logger/vs-pino.js scenario="simple" logger="pino" n=100000: 3,398,489.9761368227
logger/vs-pino.js scenario="child" logger="pino" n=100000: 4,489,799.803418606
logger/vs-pino.js scenario="disabled" logger="pino" n=100000: 119,772,384.56038144
logger/vs-pino.js scenario="fields" logger="pino" n=100000: 1,257,930.8609750536 |
|
I now learn this feat in Pino I will try add in node:logger |
|
This will require support for serializers |
I wonder, should we name them like Pino does (built-in serializers), or go with something like standardSerializers ? |
Follow pino and we’ll change it |
I tryed serializer implement for logger, and some bench result repaired and fields and simple are experiencing a decline; I will try to resolve these fields: 3.62M → 2.16M (-40%) previously, the results for the child logger were quite slow at around 70%, but the new results have dropped to 18% and have actually improved significantly. I continue to try new methods. |
I inspected pino and I learn some patterns, than I applied this commit and new results! 1ededc7 I used this patterns removed the cost of serializing bindings in each log for the child logger, simple: 6.06M vs 3.48M ops/s (+74% faster) |
|
hello @mcollina do you any comments or suggestions for this end commits, I'm curious 🙏 . |
Codecov Report❌ Patch coverage is
Additional details and impacted files@@ Coverage Diff @@
## main #60468 +/- ##
==========================================
- Coverage 88.55% 88.01% -0.54%
==========================================
Files 703 706 +3
Lines 208291 209417 +1126
Branches 40170 40283 +113
==========================================
- Hits 184443 184316 -127
- Misses 15874 17066 +1192
- Partials 7974 8035 +61
🚀 New features to boost your workflow:
|
259652e to
f5b0108
Compare
f5b0108 to
429359b
Compare
| * @returns {boolean} | ||
| */ | ||
| enabled(level) { | ||
| return LEVELS[level] >= this.#levelValue; |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Shouldn't this throw an explicit validation error if the provided level is unknown? (e.g., typo, wrong case, accidental leading/trailing space, etc.)
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Thank you for pointing this out! You're absolutely right if an unknown log level is provided (for example, due to a typo, incorrect capitalization, or extra spaces), it's much safer to throw an explicit error rather than silently returning an unexpected result.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Generally, a logger should not throw any errors once it has been initialized. What are the use cases where this error could be thrown?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Thank you for pointing this out! You're absolutely right if an unknown log level is provided (for example, due to a typo, incorrect capitalization, or extra spaces), it's much safer to throw an explicit error rather than silently returning an unexpected result.
Yes, I was mistaken here. Doing this would disrupt the flow. I'm wondering whether returning false here is appropriate.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
My concern is mostly about developer experience: enabled() is often used to guard expensive computations, for example:
if (logger.enabled('debug')) {
computeExtraDebugInfo();
}If someone makes a typo or uses the wrong case (e.g., logger.enabled('DEBUG') or even logger.enabled(20)) the call will silently return false. This means the guarded code is skipped without any indication that something is wrong, which can be quite hard to debug.
Given that log levels are a fixed, finite set, failing fast (or at least surfacing a warning) helps catch mistakes early in development instead of letting them silently pass.
Maybe throwing isn’t ideal at runtime, but completely silent failure is also risky.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I agree, I am open to the idea of mentioning this in the document.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This is a situation where it's probably best to avoid dynamic inputs. Having enabledDebug() is a strictly safer pattern because it will correctly throw when you try to call that for a non-existent level and will correctly never throw when using one that does exist. People might not like the greater API surface area, but it's certainly safer than trying to reduce surface area where it doesn't actually make sense to do so.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Fun fact: The logger I created for my company initially had isDebugEnabled(), isWarningEnabled(), etc., and only recently I switched to enabled(level) after seeing this PR and noticing it’s becoming standard.
I imagine enabled(level) was chosen to allow for dynamic log levels. But if the set of levels is truly fixed, the static methods might be a pragmatic choice: They won’t throw and they avoid bad user input for critical logging.
So my question is: Are log levels considered fixed? 🤔
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I greatly regret adding custom levels to Pino. I strongly recommend skipping them here.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Co-authored-by: Yagiz Nizipli <yagiz@nizipli.com>
Co-authored-by: Yagiz Nizipli <yagiz@nizipli.com>
Co-authored-by: Yagiz Nizipli <yagiz@nizipli.com>
Co-authored-by: Yagiz Nizipli <yagiz@nizipli.com>
23955ed to
76b0742
Compare
Qard
left a comment
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I think the general direction is good. I mostly have a few internal detail concerns. For API surface level, I think it's generally fine, but I'm not a huge fan of the logger.enabled(arbitraryString) thing and I'm also a bit confused by having level reconfigurable per-child. Why is that exactly? I'm unclear on the value of having independent log levels per child.
| * } }} req - HTTP request | ||
| * @returns {{ method: string, url: string, headers: object, remoteAddress?: string, remotePort?: string }} | ||
| */ | ||
| function req(req) { |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Might want to consider a similar pattern to https://nodejs.org/api/util.html#utilinspectcustom for these type-specific serializers.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
thanks for suggestion, I will try this pattern
Thanks for the review @Qard!
You mentioned earlier preferring logger.enabledTrace()
logger.enabledDebug()
logger.enabledInfo()Or should we keep both approaches? Independent log levels per child This pattern comes from Pino and has some real-world use cases: Module-specific debugging: Main logger at info, but a problematic module's child at debug for troubleshooting Example: const logger = new Logger({ level: 'info' });
const dbLogger = logger.child({ module: 'db' }, { level: 'warn' });
const authLogger = logger.child({ module: 'auth' }, { level: 'debug' });That said, if you think this adds unnecessary complexity, I can remove the level option from child() children would always inherit parent's level. |
I suppose the arbitrary string method (as currently implemented) makes sense if new log levels can be added at run-time. EDIT: Alternatively, change the function so that it (also) accepts number arguments, so that the log level const values (
This is a nice feature to have, and it would be unfortunate to have it removed now that it is already implemented. But I am not a maintainer, so I will not comment on it more than this. |
|
I'm not against keeping the per-child log levels, it just feels a bit weird to me that if I globally set a log level it could then get ignored and set to something else on child loggers. Seems to me like generally when a user configures the log level of the base logger they would want that to apply to ALL loggers descending from it and not just that base logger. I'm not sure how else to achieve the concepts you listed though beyond what some languages do of having logger names and filtering them like As for the |
|
Thanks for comments @TheOneTheOnlyJJ & @Qard Implemented logger..enabled getter ad43d25: if (logger.debug.enabled) {
logger.debug('expensive', computeData());
}
// Typos throw: logger.debg.enabled → TypeError
For per-child levels, keeping it as-is with clear docs - the use cases (module-specific debugging) seem valuable enough. |
|
I thought a bit more about the per-child log level thing. Do you think it would be reasonable to suggest in docs that module authors should NOT use it in their own code and that it should generally only be used in application code for isolating particular components or direct dependencies? I'm just thinking it would be annoying to have a transitive dependency not follow the log levels an application developer specifies. I would think the typical pattern with loggers, at least as I have seen before, would be to construct a child externally to the library you want to use the logger, that way you can control the behaviour external to that module? But then with a library calling another library it may construct another child but should just inherit the logger level it has been given by the application developer? What do you think? Should we document the feature as something generally only application code should use? |
| if (!ObjectHasOwn(LEVELS, level)) { | ||
| return false; | ||
| } |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
How fast is this check?
If it's slow, we can probably optimize it by using a #enabled helper.
i.e. .enabled() calls:
| if (!ObjectHasOwn(LEVELS, level)) { | |
| return false; | |
| } | |
| if (!ObjectHasOwn(LEVELS, level)) { | |
| return false; | |
| } | |
| this.#enabled(); |
Whereas internal tools, which know a given level is in the LEVELS list, would just call this.#enabled directly?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
objectHasOwn is already very fast since it is (hash table lookup). I didn't understand this part of your suggestion: could you explain what the call to this.#enabled() means?
the current application returns false for unknown levels to handle typos gracefully (as discussed in earlier sections of the topic).
| let json = '{"level":"' + record.level + '",' + | ||
| '"time":' + record.time + ',' + | ||
| '"msg":"' + record.msg + '"'; |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Why aren't we building the JSON like an object, and then using JSONStringify on the entire object? I feel like it'll be a lot more readable.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
we used manual concat for performance because JSONStringify slowly
| let hasCustom = false; | ||
| // Add custom serializers | ||
| for (const key in serializers) { | ||
| this.#serializers[key] = serializers[key]; | ||
| if (key !== 'err') { | ||
| hasCustom = true; | ||
| } | ||
| } | ||
| this.#hasCustomSerializers = hasCustom; |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
| let hasCustom = false; | |
| // Add custom serializers | |
| for (const key in serializers) { | |
| this.#serializers[key] = serializers[key]; | |
| if (key !== 'err') { | |
| hasCustom = true; | |
| } | |
| } | |
| this.#hasCustomSerializers = hasCustom; | |
| // Add custom serializers | |
| for (const key in serializers) { | |
| this.#serializers[key] = serializers[key]; | |
| if (key !== 'err') { | |
| this.#hasCustomSerializers = true; | |
| } | |
| } |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
it looks like it will be set in each iteration
| if (enabled) { | ||
| // Create bound log function | ||
| fn = (msgOrObj, fields) => { | ||
| this.#log(level, methodLevelValue, msgOrObj, fields); | ||
| }; | ||
| } else { | ||
| // Use noop for disabled levels | ||
| fn = noop; | ||
| } |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
What if the log is enabled at a point in the future? i.e. not on creation
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
this is a deliberate design decision for performance. daily methods are attached during construction, and their disable levels are converted to noop functions to prevent runtime checks.
If you need to dynamically change the logging level, we can create a new sub-logger at the desired level:
const debugLogger = logger.child({}, { level: ‘debug’ });this is the same pattern used by Pino.
| if (levelValue < this.#levelValue) { | ||
| return; | ||
| } |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Don't we have a this.#enabled(level) helper?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I know that public enabled() performs extra validation, this is for performance.
| * @private | ||
| */ | ||
| #createLogMethod(level, methodLevelValue, loggerLevelValue) { | ||
| const enabled = methodLevelValue >= loggerLevelValue; |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Don't we have a this.#enabled(level) helper?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
the public enabled() method performs validation for unknown levels. here we skip that since we're passing known valid levels internally, it's a performance optimization.
Yes, I agree. I added this note to the doc thanks for idea. 0cc656b |
for: #49296 (comment)
I try a draft development for new logger api, and i try create some benchmark for pino and node:logger package