[WIP] lib: added logger api in node core

[mertcanaltin]

for: #49296 (comment)

I try a draft development for new logger api, and i try create some benchmark for pino and node:logger package

[nodejs-github-bot]

Review requested:

• @nodejs/performance

[mertcanaltin]

thats my first performance results:

I think need improvement for child logger area, but ı'm so happy because other results it looks nice.
cc @mcollina @Qard @trentm @jsumners

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

[mertcanaltin]

I now learn this feat in Pino

pinojs/pino#2281

I will try add in node:logger

[mcollina]

This will require support for serializers

[mertcanaltin]

This will require support for serializers

I wonder, should we name them like Pino does (built-in serializers), or go with something like standardSerializers ?

[mcollina]

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

[mertcanaltin]

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%)
simple: 5.24M → 4.87M (-7%)

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.

➜  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: 4,868,164.032787085
logger/vs-pino.js scenario="child" logger="node-logger" n=100000: 3,894,327.425314102
logger/vs-pino.js scenario="disabled" logger="node-logger" n=100000: 160,503,080.85663706
logger/vs-pino.js scenario="fields" logger="node-logger" n=100000: 2,157,462.3927336666
logger/vs-pino.js scenario="simple" logger="pino" n=100000: 3,424,706.4418693925
logger/vs-pino.js scenario="child" logger="pino" n=100000: 4,753,595.477010947
logger/vs-pino.js scenario="disabled" logger="pino" n=100000: 122,100,122.10012211
logger/vs-pino.js scenario="fields" logger="pino" n=100000: 1,411,215.99189962
➜  node git:(mert/create-logger-api/node-core) ✗ 

[mertcanaltin]

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%) simple: 5.24M → 4.87M (-7%)

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.

➜  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: 4,868,164.032787085
logger/vs-pino.js scenario="child" logger="node-logger" n=100000: 3,894,327.425314102
logger/vs-pino.js scenario="disabled" logger="node-logger" n=100000: 160,503,080.85663706
logger/vs-pino.js scenario="fields" logger="node-logger" n=100000: 2,157,462.3927336666
logger/vs-pino.js scenario="simple" logger="pino" n=100000: 3,424,706.4418693925
logger/vs-pino.js scenario="child" logger="pino" n=100000: 4,753,595.477010947
logger/vs-pino.js scenario="disabled" logger="pino" n=100000: 122,100,122.10012211
logger/vs-pino.js scenario="fields" logger="pino" n=100000: 1,411,215.99189962
➜  node git:(mert/create-logger-api/node-core) ✗ 

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,
skipped unnecessary serializer checks,
used direct string concatenation instead of object merging,
sped up type checking

simple: 6.06M vs 3.48M ops/s (+74% faster)
child: 5.76M vs 4.41M ops/s (+31% faster)
disabled: 174M vs 146M ops/s (+19% faster)
fields: 2.13M vs 1.36M ops/s (+56% faster)

➜  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: 6,062,182.962986493
logger/vs-pino.js scenario="child" logger="node-logger" n=100000: 5,758,903.394222795
logger/vs-pino.js scenario="disabled" logger="node-logger" n=100000: 174,026,539.04720467
logger/vs-pino.js scenario="fields" logger="node-logger" n=100000: 2,126,059.37552321
logger/vs-pino.js scenario="simple" logger="pino" n=100000: 3,477,918.037575009
logger/vs-pino.js scenario="child" logger="pino" n=100000: 4,407,389.658686015
logger/vs-pino.js scenario="disabled" logger="pino" n=100000: 145,551,509.22359914
logger/vs-pino.js scenario="fields" logger="pino" n=100000: 1,363,125.197883181
➜  node git:(mert/create-logger-api/node-core) ✗ 

[mertcanaltin]

hello @mcollina do you any comments or suggestions for this end commits, I'm curious 🙏 .

[codecov]

Codecov Report

❌ Patch coverage is 88.62974% with 78 lines in your changes missing coverage. Please review.
✅ Project coverage is 89.74%. Comparing base (ea83d32) to head (e14b0bb).
⚠️ Report is 6 commits behind head on main.

Files with missing lines	Patch %	Lines
lib/logger.js	87.71%	73 Missing ⚠️
lib/internal/logger/serializers.js	93.50%	5 Missing ⚠️

Additional details and impacted files

@@            Coverage Diff             @@
##             main   #60468      +/-   ##
==========================================
- Coverage   89.79%   89.74%   -0.05%     
==========================================
  Files         673      675       +2     
  Lines      203852   204628     +776     
  Branches    39181    39281     +100     
==========================================
+ Hits       183044   183651     +607     
- Misses      13143    13308     +165     
- Partials     7665     7669       +4     

Files with missing lines	Coverage Δ
lib/internal/bootstrap/realm.js	96.00% <100.00%> (+<0.01%)	⬆️
lib/internal/process/pre_execution.js	96.66% <100.00%> (+0.69%)	⬆️
src/node_options.cc	76.30% <100.00%> (-1.60%)	⬇️
src/node_options.h	97.90% <100.00%> (+0.01%)	⬆️
lib/internal/logger/serializers.js	93.50% <93.50%> (ø)
lib/logger.js	87.71% <87.71%> (ø)

... and 45 files with indirect coverage changes

🚀 New features to boost your workflow:

• ❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.
• 📦 JS Bundle Analysis: Save yourself from yourself by tracking and limiting bundle sizes in JS merges.

[yvele]

Shouldn't this throw an explicit validation error if the provided level is unknown? (e.g., typo, wrong case, accidental leading/trailing space, etc.)

[mertcanaltin]

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.

[jsumners]

Generally, a logger should not throw any errors once it has been initialized. What are the use cases where this error could be thrown?

[mertcanaltin]

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.

@jsumners @yvele

[yvele]

@jsumners @mertcanaltin

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.

[Qard]

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.

[yvele]

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? 🤔

[jsumners]

I greatly regret adding custom levels to Pino. I strongly recommend skipping them here.

[mertcanaltin]

Thank you both for the discussion, I'll keep the current behavior where enabled() returns false for unknown levels. I agree with @jsumners that we shouldn't add custom levels, and the current implementation is simple and safe. I'll document this behavior clearly in the API docs 83a12b7.

[yvele]

Is this review is considered "resolved" @mertcanaltin ?
As seen in #60468 (comment) both logger.debug.enabled and logger.enabled("debug") are implemented.

Just for info the one of the most use-case I've seen is developers using "warning" instead of "warn".

Nice work 👍