feat: pino instrumentation #432

seemk · 2021-04-19T10:56:24Z

Which problem is this PR solving?

Adds automatic injection of trace context to pino (5.x and 6.x) similarly to bunyan and winston instrumentations.

codecov · 2021-04-19T11:25:13Z

Codecov Report

Merging #432 (7bad699) into main (230ce49) will not change coverage.
The diff coverage is n/a.

❗ Current head 7bad699 differs from pull request most recent head cb9ecb4. Consider uploading reports for the commit cb9ecb4 to get more accurate results

@@           Coverage Diff           @@
##             main     #432   +/-   ##
=======================================
  Coverage   95.83%   95.83%           
=======================================
  Files          15       15           
  Lines         624      624           
  Branches       94       94           
=======================================
  Hits          598      598           
  Misses         26       26

naseemkullah · 2021-04-19T12:48:22Z

cc @mcollina @davidmarkclements if you'd like to take a look

vmarchaud · 2021-04-19T12:55:13Z

plugins/node/opentelemetry-instrumentation-pino/src/pino.ts

+          }
+
+          if (semver.satisfies(version, pino5Versions)) {
+            const proto = Object.getPrototypeOf(pinoModule());


do the constructor have a side effect ? I mean we are creating a new instance here which can be problematic

Afaik it does not, it's just a factory function: https://github.com/pinojs/pino/blob/v5.17.0/pino.js#L63 so no global state gets set.

I think what would make more sense is to retrieve the lib/proto file to patch it, WDYT ?

The thing with this is that the file hook gets called first, but in order to patch the prototype I need the value of writeSym. lib/proto gets loaded before lib/symbols, not sure if there is a non-hackish way to do it. Will give it some thought 🙂

Indeed, i don't think its possible then. Might be worth checking though

Changed it to mixins patching now, should be simpler.

mcollina · 2021-04-19T22:55:22Z

I would like to ask why would you need to monkeypatch pino? Pino is inherently sync in how it logs, so there should not be no need to monkeypatch anything here.

(streams are async, but those are separate).

mcollina · 2021-04-19T22:55:43Z

could this be turned off anyway?

naseemkullah · 2021-04-20T00:12:07Z

I would like to ask why would you need to monkeypatch pino? Pino is inherently sync in how it logs, so there should not be no need to monkeypatch anything here.

(streams are async, but those are separate).

The end goal is to 💯% offload the logic of adding span context fields (when available) to the logs. The span context consists of trace_id, span_id and trace_flags fields as per https://github.com/open-telemetry/opentelemetry-specification/blob/main/specification/logs/overview.md#json-formats (though trace_flags seems to be missing in that example). Monkey patching via this instrumentation package is the means to that end.

could this be turned off anyway?

Yes, it will never be turned on unless the user has installed the opentelemetry-pino-instrumentation package and configured it in the instrumentations option of the registerInstrumentations() function, unless it becomes a turned on by default instrumentation (examples of turned on by default include http(s) , grpc, redis, ioredis, mysql, express, hapi, koa[would love to see fastify there as well ;) ]). In the event that it does become turned on by default, it could be overridden with enabled: false passed into the instrumentation config.

dyladan · 2021-04-20T02:44:53Z

I wonder if "Instrumentation" is a bad name for this, since it isn't actually instrumenting anything? Maybe we should use some other name like LogInjection or something like that?

dyladan · 2021-04-20T02:47:11Z

Also, pino supports "mixins" as a first party API. Maybe we should just release an official opentelemetry pino mixin that injects the span data. It would likely be a much more stable interface than patching internal methods.

dyladan · 2021-04-20T02:49:05Z

For now I'm retracting my approval until we are sure this is the direction we want to go.

seemk · 2021-04-20T06:10:56Z

I don't get it, it's meant for automatic instrumentation and is completely optional. If you want to use a mixin and have separate configuration for this, fine.

Besides, the spec even has a section for auto instrumentation about this exact same use case: https://github.com/open-telemetry/opentelemetry-specification/blob/main/specification/logs/overview.md#auto-instrumenting-existing-logging

Other languages already have similar mechanisms, e.g. Java

@naseemkullah is completely correct on this one.

I would like to ask why would you need to monkeypatch pino? Pino is inherently sync in how it logs, so there should not be no need to monkeypatch anything here.

(streams are async, but those are separate).

On a side note, what does it being sync or async have to do with this PR? It's about achieving log correlation.

Flarna · 2021-04-20T06:26:13Z

To avoid monkey patching a pino API to register global mixins would be needed.

vmarchaud · 2021-04-20T08:08:27Z

I wonder if "Instrumentation" is a bad name for this, since it isn't actually instrumenting anything? Maybe we should use some other name like LogInjection or something like that?

i would prefer to keep them as instrumentation, someone could decide to add metrics for how much logs you are emitting etc.

mcollina · 2021-04-20T09:16:45Z

The feature we added for supporting this use case was the mixin as @Flarna said! Can you please check if it's sufficient for the use case? In theory you can use it to add the relevant data to all the log lines: it was added specifically to support the APM use case.

If mixin is enough, I would recommend either:

you just wrap the pino factory and add a mixin() option. A bit of care must be taken so that user-provided mixins will still be supported.
add the concept of a global mixin to pino itself and you just use that in this library.

I do not have much time to work on this right now but happy to review. I'm ok with both approach with a slight preference to 1.

seemk · 2021-04-20T09:42:44Z

The feature we added for supporting this use case was the mixin as @Flarna said! Can you please check if it's sufficient for the use case? In theory you can use it to add the relevant data to all the log lines: it was added specifically to support the APM use case.

If mixin is enough, I would recommend either:

you just wrap the pino factory and add a mixin() option. A bit of care must be taken so that user-provided mixins will still be supported.

add the concept of a global mixin to pino itself and you just use that in this library.

I do not have much time to work on this right now but happy to review. I'm ok with both approach with a slight preference to 1.

I'm all for option 1, but with our current instrumentation API how can we achieve this? I am perhaps missing something here.

Edit: Can return the wrapper inside patch I guess. Reworking this a bit

naseemkullah · 2021-04-20T09:58:05Z

The feature we added for supporting this use case was the mixin as @Flarna said! Can you please check if it's sufficient for the use case? In theory you can use it to add the relevant data to all the log lines: it was added specifically to support the APM use case.
If mixin is enough, I would recommend either:

you just wrap the pino factory and add a mixin() option. A bit of care must be taken so that user-provided mixins will still be supported.

add the concept of a global mixin to pino itself and you just use that in this library.

I do not have much time to work on this right now but happy to review. I'm ok with both approach with a slight preference to 1.

I'm all for option 1, but with our current instrumentation API how can we achieve this? I am perhaps missing something here.

Edit: Can return the wrapper inside patch I guess. Reworking this a bit

You probably know this but I can confirm that mixin works great with the following option passed in to pino :

      mixin: () => (getSpan(context.active())?.context() ?? {}),

Flarna · 2021-04-20T10:16:24Z

Personally I'm in favor of option 2 as it requires no monkey patching of pino. Noone knows if we will be ever able to reliable monkey patch ESM modules therefore getting public APIs is future proof.

But clearly this can't happen within this PR.

dyladan · 2021-04-20T11:52:52Z

I don't get it, it's meant for automatic instrumentation and is completely optional. If you want to use a mixin and have separate configuration for this, fine.

Instrument (verb): equip (something) with measuring instruments.

Since we are not measuring anything, we are not instrumenting the module.

Besides, the spec even has a section for auto instrumentation about this exact same use case: https://github.com/open-telemetry/opentelemetry-specification/blob/main/specification/logs/overview.md#auto-instrumenting-existing-logging

If spec says this it's probably fine for now. I would also prefer to take advantage of public, supported APIs. As @Flarna says we will not be able to monkeypatch once ESM is widely supported.

I generally support option 2, but since it relies on options which don't yet exist 1 is probably a better solution at the moment.

dyladan · 2021-04-20T11:53:05Z

I'm going to approve anyways as this can always be reworked later.

seemk · 2021-04-20T12:04:01Z

Changing it to mixin patching, don't merge yet. This will bring the min version to 5.14, but should be fine

dyladan · 2021-04-20T12:32:36Z

Adding blocked label until you finish

…b into pino-instr

seemk · 2021-04-20T14:23:21Z

Adding blocked label until you finish

@dyladan Done. Added additional tests regarding options and mixins handling. Upped the required version to 5.14.0 and ran both 5.14.0 and 6.x through an example app.

dyladan

Looks good

plugins/node/opentelemetry-instrumentation-pino/src/pino.ts

dyladan · 2021-04-20T15:52:10Z

plugins/node/opentelemetry-instrumentation-pino/src/pino.ts

+                args.splice(0, 0, {
+                  mixin: instrumentation._getMixinFunction(),
+                });
+                return pinoModule(...(args as Parameters<Pino>));


This can be done in a single step I think

Suggested change

args.splice(0, 0, {

mixin: instrumentation._getMixinFunction(),

});

return pinoModule(...(args as Parameters<Pino>));

return pinoModule({ mixin: instrumentation._getMixinFunction() }, ...args);

Good point, although this won't compile due to pino taking 0-2 args and ...(args as Parameters<Pino>) already expands to 2 args and it can't be untyped 😦

We are under the case of args.length == 1, so it can also be written as return pinoModule({ mixin: instrumentation._getMixinFunction() }, args[0] as pino.DestinationStream) maybe?

obecny

lgtm, thx for contribution, one comment

obecny · 2021-04-20T18:44:03Z

plugins/node/opentelemetry-instrumentation-pino/src/pino.ts

+
+  disable() {
+    super.disable();
+    this._isEnabled = false;


hmm we already have such functionality, can you add todo here to remove it once the base class will be changed. I created an issue for that -> open-telemetry/opentelemetry-js#2131

Added a TODO, found it kinda awkward as well 😄

mcollina

lgtm, really good work!

plugins/node/opentelemetry-instrumentation-pino/src/pino.ts

feat: pino instrumentation

0d1e509

seemk requested a review from a team April 19, 2021 10:56

fix: move semver to deps

c228faa

naseemkullah approved these changes Apr 19, 2021

View reviewed changes

vmarchaud requested a review from a team April 19, 2021 12:52

vmarchaud reviewed Apr 19, 2021

View reviewed changes

seemk mentioned this pull request Apr 19, 2021

instrumentation: respect multiple instrumentation module definitions with different supported versions open-telemetry/opentelemetry-js#2119

Closed

seemk added 2 commits April 19, 2021 16:51

chore: fix readme

f077fa4

chore: update README

a0338ed

dyladan approved these changes Apr 19, 2021

View reviewed changes

Merge branch 'main' into pino-instr

664b8e8

dyladan self-requested a review April 20, 2021 02:48

dyladan approved these changes Apr 20, 2021

View reviewed changes

dyladan added the enhancement New feature or request label Apr 20, 2021

dyladan added the blocked label Apr 20, 2021

seemk added 3 commits April 20, 2021 17:13

fix: use mixins patching

b64cbe3

Merge branch 'pino-instr' of github.com:seemk/opentelemetry-js-contri…

69437ac

…b into pino-instr

chore: update README with supported versions

2e668b1

dyladan approved these changes Apr 20, 2021

View reviewed changes

dyladan removed the blocked label Apr 20, 2021

obecny approved these changes Apr 20, 2021

View reviewed changes

mcollina approved these changes Apr 20, 2021

View reviewed changes

chore: add TODO for instrumenation isEnabled

0a4131e

blumamir approved these changes Apr 21, 2021

View reviewed changes

plugins/node/opentelemetry-instrumentation-pino/src/pino.ts Outdated Show resolved Hide resolved

seemk added 2 commits April 21, 2021 12:38

refactor: simplify optsOrStream.write check

9200afa

Merge branch 'main' into pino-instr

cb9ecb4

dyladan merged commit 60dd7d1 into open-telemetry:main Apr 21, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

feat: pino instrumentation #432

feat: pino instrumentation #432

seemk commented Apr 19, 2021 •

edited

Loading

codecov bot commented Apr 19, 2021 •

edited

Loading

naseemkullah commented Apr 19, 2021

vmarchaud Apr 19, 2021

seemk Apr 19, 2021

vmarchaud Apr 19, 2021

seemk Apr 19, 2021

vmarchaud Apr 19, 2021

seemk Apr 20, 2021

mcollina commented Apr 19, 2021

mcollina commented Apr 19, 2021

naseemkullah commented Apr 20, 2021 •

edited

Loading

dyladan commented Apr 20, 2021

dyladan commented Apr 20, 2021

dyladan commented Apr 20, 2021

seemk commented Apr 20, 2021

Flarna commented Apr 20, 2021

vmarchaud commented Apr 20, 2021

mcollina commented Apr 20, 2021

seemk commented Apr 20, 2021 •

edited

Loading

naseemkullah commented Apr 20, 2021 •

edited

Loading

Flarna commented Apr 20, 2021

dyladan commented Apr 20, 2021

dyladan commented Apr 20, 2021

seemk commented Apr 20, 2021

dyladan commented Apr 20, 2021

seemk commented Apr 20, 2021

dyladan left a comment

dyladan Apr 20, 2021

seemk Apr 20, 2021

blumamir Apr 21, 2021 •

edited

Loading

obecny left a comment

obecny Apr 20, 2021

seemk Apr 20, 2021

mcollina left a comment

feat: pino instrumentation #432

feat: pino instrumentation #432

Conversation

seemk commented Apr 19, 2021 • edited Loading

Which problem is this PR solving?

codecov bot commented Apr 19, 2021 • edited Loading

Codecov Report

naseemkullah commented Apr 19, 2021

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mcollina commented Apr 19, 2021

mcollina commented Apr 19, 2021

naseemkullah commented Apr 20, 2021 • edited Loading

dyladan commented Apr 20, 2021

dyladan commented Apr 20, 2021

dyladan commented Apr 20, 2021

seemk commented Apr 20, 2021

Flarna commented Apr 20, 2021

vmarchaud commented Apr 20, 2021

mcollina commented Apr 20, 2021

seemk commented Apr 20, 2021 • edited Loading

naseemkullah commented Apr 20, 2021 • edited Loading

Flarna commented Apr 20, 2021

dyladan commented Apr 20, 2021

dyladan commented Apr 20, 2021

seemk commented Apr 20, 2021

dyladan commented Apr 20, 2021

seemk commented Apr 20, 2021

dyladan left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

blumamir Apr 21, 2021 • edited Loading

Choose a reason for hiding this comment

obecny left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mcollina left a comment

Choose a reason for hiding this comment

seemk commented Apr 19, 2021 •

edited

Loading

codecov bot commented Apr 19, 2021 •

edited

Loading

naseemkullah commented Apr 20, 2021 •

edited

Loading

seemk commented Apr 20, 2021 •

edited

Loading

naseemkullah commented Apr 20, 2021 •

edited

Loading

blumamir Apr 21, 2021 •

edited

Loading