feat(instrumentation-pino): add log sending to Logs Bridge API #2249
Conversation
…x; some in-progress changes
…hange behaviour for that logger This removes functionality that was there before, so technically could be breaking. The motivation is to have the contract of pino instrumentation be cleaner. With this change a pino Logger instance will not be touched if the PinoInstrumentation is disabled. I.e. we are hands-off as much as possible when disabled. Before this change, even when disabled, the instrumentation would tweak the pino Logger config to have a no-op mixin. If the instrumentation was later enabled, then the mixin would become active (adding trace_id et al fields in a span context). The coming "log sending" to the Logs Bridge API will *not* support this "work if instrumentation is re-enabled later", so I think it is clearer if neither "log sending" nor "log correlation" support this. We can back this out if we think it is important to support a possible future feature of the SDK doing live enabling/disabling of individual instrumentations.
…og-correlation *will* follow the live instr enable/disable state
Codecov ReportAll modified and coverable lines are covered by tests ✅
Additional details and impacted files@@ Coverage Diff @@
## main #2249 +/- ##
==========================================
- Coverage 90.97% 90.42% -0.56%
==========================================
Files 146 148 +2
Lines 7492 7322 -170
Branches 1502 1518 +16
==========================================
- Hits 6816 6621 -195
- Misses 676 701 +25
|
…the first half-second since process start Effectively the issue is that this sometimes returns true: node -e 'console.log(Math.round(Date.now() / 1e3) * 1e3 < performance.timeOrigin)'
| import { logs, Logger, SeverityNumber } from '@opentelemetry/api-logs'; | ||
| import { PACKAGE_NAME, PACKAGE_VERSION } from './version'; | ||
| import { millisToHrTime } from '@opentelemetry/core'; | ||
|
|
There was a problem hiding this comment.
Reviewer note: From here down to function severityNumberFromPinoLevel is basically identical to the equivalent level/severity mapping in instrumentation-bunyan, because Bunyan and Pino share the same level names and values.
|
|
||
| ## Semantic Conventions | ||
|
|
||
| This package does not currently generate any attributes from semantic conventions. | ||
|
|
||
| ## Alternative log sending with `pino-opentelemetry-transport` |
There was a problem hiding this comment.
I wonder if the instrumentation would be capable to know if pino-opentelemetry-transport is used when creating a new logger and disable sending in the main thread. Or maybe warn the user if this transport is detected and suggest to change its disableSending configuration if applies.
There was a problem hiding this comment.
First, I don't believe there is a way for instrumentation-pino to know if pino-opentelemetry-transport is being used. Here is an example script:
const otel = require('@opentelemetry/api');
const pino = require('pino');
const transport = pino.transport({ target: 'pino-opentelemetry-transport' });
const logger = pino({level: 'debug'}, transport);
console.log('XXX The logger stream is:', logger[pino.symbols.streamSym]);
logger.debug({foo: 'bar'}, 'hi');
const tracer = otel.trace.getTracer('example');
tracer.startActiveSpan('manual-span', span => {
logger.info('in a span');
span.end();
});
If instrumentation-pino is active, the only thing it has to look at is that logger[pino.symbols.streamSym] value -- the destination stream of the Pino Logger. This is the thing that the instrumentation calls origStream and wraps in a multistream.
That thing is a ThreadStream (from https://github.com/pinojs/thread-stream/blob/main/index.js):
XXX The logger stream is: <ref *1> ThreadStream {
_events: [Object: null prototype] {
message: [Function (anonymous)],
ready: [Function: onReady],
close: [Function (anonymous)]
},
_eventsCount: 3,
_maxListeners: undefined,
worker: Worker {
_events: [Object: null prototype] {
newListener: [Function (anonymous)],
removeListener: [Function (anonymous)],
message: [Function: onWorkerMessage],
exit: [Function: onWorkerExit]
},
_eventsCount: 4,
_maxListeners: undefined,
performance: { eventLoopUtilization: [Function: bound eventLoopUtilization] },
stream: FakeWeakRef { _value: [Circular *1] },
[Symbol(kCapture)]: false,
...
That ThreadStream provides no way to know what the target package or Node.js file is being run in the Worker thread. In other words, instr-pino can know that a Pino transport is being used (i.e. something running in a separate thread), but has no idea whether that is pino-opentelemetry-transport.
I think it would be overkill to look into instrumenting pino.transport() to tag any returned transport that is using pino-opentelemetry-transport to try to tell.
Second, I'm not sure that we'd want instr-pino to automatically do anything even if it did know.
- Automatically disabling log-sending if
pino-opentelemetry-transport(POT) was detected would potentially be surprising behaviour. I think to be explicit we'd then wantdisableLogSendingto be a tri-state config: true, false, "true-if-POT-detected". - Automatically warning if POT was detected? I suppose this would be fair. Most users would never want both active on a given Pino logger. (Eventually perhaps we'd want the ability for users to silence particular warnings from the OTel SDK that they don't care above -- something like Python's warnings filter https://docs.python.org/3/library/warnings.html#the-warnings-filter)
These are why I opted to just have documentation about this so that users are at least made aware of the options (assuming they get as far as reading this README). Perhaps a future "Troubleshooting" guide would merit a section on "I'm using Pino and getting double logs. Why?!".
There was a problem hiding this comment.
Those are valid points. Thanks for taking the time to give your reasoning :)
|
@hectorhdzg Would you be interested in reviewing this as well? I'm not sure if Pino is as important to some of the work you are doing as Winston. |
|
@trentm changes look good, my only question is related to pino-opentelemetry-transport usage , sorry if this was discussed somewhere else, why not using this package and patching the logger construction similar to Winston? is this related to having older pino version support? |
Co-authored-by: Hector Hernandez <39923391+hectorhdzg@users.noreply.github.com>
@hectorhdzg It hasn't been discussed elsewhere, so it is a good question. The decision to not just suggest users use
Please correct me if I miss something, but I see this as two separate questions. instrumentation no longer patches the logger constructor argsFirst, why I moved away from patching the logger constructor to instead creating the Logger instance and then tweaking it. I found that coping with all the possible input combinations to
This is the Pino internal code for normalizing the given After the pino logger is created, it has a well-defined shape that can be patched cleanly. why not just use 'pino-opentelemetry-transport'?This could either mean that we get instrumentation-pino to automatically use On the "for using pino-opentelemetry-transport" side:
My arguments for implementing it without POT are:
Downsides of adding log-sending support to instrumentation-pino:
Sorry, that got long. |
There was a problem hiding this comment.
LGTM, @trentm I appreciate your detailed response on my latest question.
This adds "log sending" -- sending log records to the Logs SDK -- for the
pinologger.(The same was done for Bunyan in #1713 and Winston in #1837.)
pino.multistreamthat sends to the original and to the Logs SDK (class OTelPinoStream).disableLogSendinganddisableLogCorrelationoptions, the same as in instr-bunyan and instr-winstonLimitations:
logSeverityoption. I prefer to do that in a separate change, because it might be involved with Pino loggers configured with custom levels.contrib-test-utilspackage.reviewer notes
The test file changes on this PR assume that #2247 gets merged first. Please review that PR first. After that is merged, then the test file changes here will be additive and more clear.
Update (2024-06-10): This is done now, so this PR is now ready for review.
checklist
logSeverity