feat(instrumentation-pino): add log sending to Logs Bridge API (#2249)

* feat(instrumentation-pino): add log sending to Logs Bridge API

* refactor tests (mostly from separate #2247 PR); lint:fix; some in-progress changes

* remove some old dev/debug code

* feat!: make it so re-enabled instr after creating a logger will NOT change 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.

* impl disableLogCorrelation config; undo the previous commit so that log-correlation *will* follow the live instr enable/disable state

* log sending: first tests; change impl to use pino.multistream

* edge case tests; almost complete

* more tests and a fix for 'useOnlyCustomLevels: true' usage

* lint:fix

* refactor some code out to utils file

* add some internal docs

* update readme

* fix lint

* avoid a possible flaky error if using pino 'unixTime' and logging in 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)'

* limit log-sending to pino@7 and later because that's when pino.multistream was added

* lint:fix

* discuss pino-opentelemetry-transport alternative

* fix a mis-merge

* update changed deps to their new latest

* typo in README

Co-authored-by: Hector Hernandez <[email protected]>

---------

Co-authored-by: Hector Hernandez <[email protected]>
Co-authored-by: Marc Pichler <[email protected]>

Author: 3 people

package-lock.json

@@ -3,7 +3,7 @@
 [![NPM Published Version][npm-img]][npm-url]
 [![Apache License][license-image]][license-image]
 
-This module provides automatic instrumentation for injection of trace context for the [`pino`](https://www.npmjs.com/package/pino) module, which may be loaded using the [`@opentelemetry/sdk-trace-node`](https://github.com/open-telemetry/opentelemetry-js/tree/main/packages/opentelemetry-sdk-trace-node) package and is included in the [`@opentelemetry/auto-instrumentations-node`](https://www.npmjs.com/package/@opentelemetry/auto-instrumentations-node) bundle.
+This module provides automatic instrumentation of the [`pino`](https://www.npmjs.com/package/pino) module to inject trace-context into Pino log records (log correlation) and to send Pino logging to the OpenTelemetry Logging SDK (log sending). It may be loaded using the [`@opentelemetry/sdk-trace-node`](https://github.com/open-telemetry/opentelemetry-js/tree/main/packages/opentelemetry-sdk-trace-node) package and is included in the [`@opentelemetry/auto-instrumentations-node`](https://www.npmjs.com/package/@opentelemetry/auto-instrumentations-node) bundle.
 
 If total installation size is not constrained, it is recommended to use the [`@opentelemetry/auto-instrumentations-node`](https://www.npmjs.com/package/@opentelemetry/auto-instrumentations-node) bundle with [@opentelemetry/sdk-node](`https://www.npmjs.com/package/@opentelemetry/sdk-node`) for the most seamless instrumentation experience.
 
@@ -15,60 +15,105 @@ Compatible with OpenTelemetry JS API and SDK `1.0+`.
 npm install --save @opentelemetry/instrumentation-pino
 ```
 
-### Supported Versions
+## Supported Versions
 
 - [`pino`](https://www.npmjs.com/package/pino) versions `>=5.14.0 <10`
+  - The "log sending" feature is only supported in pino v7 and later.
 
 ## Usage
 
 ```js
-const { NodeTracerProvider } = require('@opentelemetry/sdk-trace-node');
+const { NodeSDK, tracing, logs, api } = require('@opentelemetry/sdk-node');
 const { PinoInstrumentation } = require('@opentelemetry/instrumentation-pino');
-const { registerInstrumentations } = require('@opentelemetry/instrumentation');
-
-const provider = new NodeTracerProvider();
-provider.register();
-
-registerInstrumentations({
+const sdk = new NodeSDK({
+  spanProcessor: new tracing.SimpleSpanProcessor(new tracing.ConsoleSpanExporter()),
+  logRecordProcessor: new logs.SimpleLogRecordProcessor(new logs.ConsoleLogRecordExporter()),
   instrumentations: [
     new PinoInstrumentation({
-      // Optional hook to insert additional context to log object.
-      logHook: (span, record, level) => {
-        record['resource.service.name'] =
-          provider.resource.attributes['service.name'];
-      },
-      // Log span context under custom keys
-      // This is optional, and will default to "trace_id", "span_id" and "trace_flags" as the keys
-      logKeys: {
-        traceId: 'traceId',
-        spanId: 'spanId',
-        traceFlags: 'traceFlags',
-      },
+      // See below for Pino instrumentation options.
     }),
-    // other instrumentations
-  ],
-});
+  ]
+})
+sdk.start();
 
 const pino = require('pino');
 const logger = pino();
-logger.info('foobar');
-// {"msg":"foobar","trace_id":"fc30029f30df383a4090d3189fe0ffdf","span_id":"625fa861d19d1056","trace_flags":"01", ...}
+
+logger.info('hi');
+// 1. Log records will be sent to the SDK-registered log record processor, if any.
+//    This is called "log sending".
+
+const tracer = api.trace.getTracer('example');
+tracer.startActiveSpan('manual-span', span => {
+  logger.info('in a span');
+  // 2. Fields identifying the current span will be added to log records:
+  //    {"level":30,...,"msg":"in a span","trace_id":"d61b4e4af1032e0aae279d12f3ab0159","span_id":"d140da862204f2a2","trace_flags":"01"}
+  //    This feature is called "log correlation".
+});
 ```
 
-### Fields added to pino log objects
+### Log sending
+
+Creation of a Pino Logger will automatically add a [Pino destination](https://getpino.io/#/docs/api?id=pinooptions-destination-gt-logger) that sends log records to the OpenTelemetry Logs SDK. The OpenTelemetry SDK can be configured to handle those records -- for example, sending them on to an OpenTelemetry collector for log archiving and processing. The example above shows a minimal configuration that emits OpenTelemetry log records to the console for debugging.
+
+If the OpenTelemetry SDK is not configured with a Logger provider, then this added destination will be a no-op.
+
+Log sending can be disabled with the `disableLogSending: true` option.
 
-For the current active span, the following fields are injected. These field names can be optionally configured via `logKeys` in the PinoInstrumentation config:
+### Log correlation
+
+Pino logger calls in the context of a tracing span will have fields identifying the span added to the log record. This allows [correlating](https://opentelemetry.io/docs/specs/otel/logs/#log-correlation) log records with tracing data. The added fields are ([spec](https://opentelemetry.io/docs/specs/otel/compatibility/logging_trace_context/)):
 
 - `trace_id`
 - `span_id`
 - `trace_flags`
 
+These field names can optionally be configured via the `logKeys` option. For example:
+
+```js
+    new PinoInstrumentation({
+      logKeys: {
+        traceId: 'myTraceId',
+        spanId: 'mySpanId',
+        traceFlags: 'myTraceFlags',
+      },
+    }),
+```
+
+After adding these fields, the optional `logHook` is called to allow injecting additional fields. For example:
+
+```js
+  logHook: (span, record) => {
+    record['resource.service.name'] = provider.resource.attributes['service.name'];
+  }
+```
+
 When no span context is active or the span context is invalid, injection is skipped.
+Log injection can be disabled with the `disableLogCorrelation: true` option.
+
+### Pino instrumentation options
+
+| Option                  | Type              | Description |
+| ----------------------- | ----------------- | ----------- |
+| `disableLogSending`     | `boolean`         | Whether to disable [log sending](#log-sending). Default `false`. |
+| `disableLogCorrelation` | `boolean`         | Whether to disable [log correlation](#log-correlation). Default `false`. |
+| `logKeys`               | record            | A record with keys `traceId`, `spanId`, and `traceFlags` string fields giving the field names to use for log-correlation span data. |
+| `logHook`               | `LogHookFunction` | An option hook to inject additional context to a log record after trace-context has been added. This requires `disableLogCorrelation` to be false. |
 
 ## Semantic Conventions
 
 This package does not currently generate any attributes from semantic conventions.
 
+## Alternative log sending with `pino-opentelemetry-transport`
+
+A possible alternative to the "log sending" support provided by this instrumentation is the [`pino-opentelemetry-transport` package](https://github.com/pinojs/pino-opentelemetry-transport).
+
+Every Pino logger has an output ["destination"](https://getpino.io/#/docs/api?id=destination), for example, a file or stdout.  Since v7, Pino includes support for ["transports"](https://getpino.io/#/docs/transports), a type of destination that uses a [worker thread](https://nodejs.org/api/worker_threads.html) to run the transport code. When calling `logger.info("hi")`, Pino serializes the log record to a JSON string, [sends that string to the worker](https://nodejs.org/api/worker_threads.html#workerpostmessagevalue-transferlist) for it to be handled.
+
+The `pino-opentelemetry-transport` package uses this mechanism. It starts an OpenTelemetry SDK `LoggerProvider` in the worker thread, parses each log record string, translates it into the OpenTelemetry Logs data model and sends it. Note that this `LoggerProvider` is independent of any OpenTelemetry SDK components in the main thread.
+
+The log sending support in this instrumentation works on the main thread and uses the OpenTelemetry SDK configured in the main thread. Otherwise the two mechanisms are very similar. Note that because they are maintained separately, there might be small differences in how Pino log records are translated into the OpenTelemetry Logs data model.
+
 ## Useful links
 
 - For more information on OpenTelemetry, visit: <https://opentelemetry.io/>

plugins/node/opentelemetry-instrumentation-pino/README.md

@@ -49,6 +49,7 @@
     "@opentelemetry/contrib-test-utils": "^0.40.0",
     "@opentelemetry/sdk-trace-base": "^1.8.0",
     "@opentelemetry/sdk-trace-node": "^1.8.0",
+    "@opentelemetry/semantic-conventions": "^1.22.0",
     "@types/mocha": "7.0.2",
     "@types/node": "18.6.5",
     "@types/semver": "7.5.3",
@@ -64,6 +65,8 @@
     "typescript": "4.4.4"
   },
   "dependencies": {
+    "@opentelemetry/api-logs": "^0.52.0",
+    "@opentelemetry/core": "^1.25.0",
     "@opentelemetry/instrumentation": "^0.52.0"
   },
   "homepage": "https://github.com/open-telemetry/opentelemetry-js-contrib/tree/main/plugins/node/opentelemetry-instrumentation-pino#readme"

plugins/node/opentelemetry-instrumentation-pino/package.json

@@ -28,6 +28,7 @@ import {
 } from '@opentelemetry/instrumentation';
 import { PinoInstrumentationConfig } from './types';
 import { PACKAGE_NAME, PACKAGE_VERSION } from './version';
+import { getTimeConverter, OTelPinoStream } from './log-sending-utils';
 
 const pinoVersions = ['>=5.14.0 <10'];
 
@@ -48,30 +49,73 @@ export class PinoInstrumentation extends InstrumentationBase {
         const isESM = module[Symbol.toStringTag] === 'Module';
         const moduleExports = isESM ? module.default : module;
         const instrumentation = this;
+
         const patchedPino = Object.assign((...args: unknown[]) => {
-          if (args.length === 0) {
-            return moduleExports({
-              mixin: instrumentation._getMixinFunction(),
-            });
+          const config = instrumentation.getConfig();
+          const isEnabled = instrumentation.isEnabled();
+
+          const logger = moduleExports(...args);
+
+          // Setup "log correlation" -- injection of `trace_id` et al fields.
+          // Note: If the Pino logger is configured with `nestedKey`, then
+          // the `trace_id` et al fields added by `otelMixin` will be nested
+          // as well. https://getpino.io/#/docs/api?id=mixin-function
+          const otelMixin = instrumentation._getMixinFunction();
+          const mixinSym = moduleExports.symbols.mixinSym;
+          const origMixin = logger[mixinSym];
+          if (origMixin === undefined) {
+            logger[mixinSym] = otelMixin;
+          } else {
+            logger[mixinSym] = (ctx: object, level: number) => {
+              return Object.assign(
+                otelMixin(ctx, level),
+                origMixin(ctx, level)
+              );
+            };
           }
 
-          if (args.length === 1) {
-            // eslint-disable-next-line @typescript-eslint/no-explicit-any
-            const optsOrStream = args[0] as any;
-            if (
-              typeof optsOrStream === 'string' ||
-              typeof optsOrStream?.write === 'function'
-            ) {
-              args.splice(0, 0, {
-                mixin: instrumentation._getMixinFunction(),
-              });
-              return moduleExports(...args);
-            }
-          }
+          // Setup "log sending" -- sending log records to the Logs API.
+          // This depends on `pino.multistream`, which was added in v7.0.0.
+          if (
+            isEnabled &&
+            !config.disableLogSending &&
+            typeof moduleExports.multistream === 'function'
+          ) {
+            const otelTimestampFromTime = getTimeConverter(
+              logger,
+              moduleExports
+            );
+            const otelStream = new OTelPinoStream({
+              messageKey: logger[moduleExports.symbols.messageKeySym],
+              levels: logger.levels,
+              otelTimestampFromTime,
+            });
+            (otelStream as any)[Symbol.for('pino.metadata')] = true; // for `stream.lastLevel`
+
+            // An error typically indicates a Pino bug, or logger configuration
+            // bug. `diag.warn` *once* for the first error on the assumption
+            // subsequent ones stem from the same bug.
+            otelStream.once('unknown', (line, err) => {
+              instrumentation._diag.warn(
+                'could not send pino log line (will only log first occurrence)',
+                { line, err }
+              );
+            });
 
-          args[0] = instrumentation._combineOptions(args[0]);
+            // Use pino's own `multistream` to send to the original stream and
+            // to the OTel Logs API/SDK.
+            // https://getpino.io/#/docs/api?id=pinomultistreamstreamsarray-opts-gt-multistreamres
+            const origStream = logger[moduleExports.symbols.streamSym];
+            logger[moduleExports.symbols.streamSym] = moduleExports.multistream(
+              [
+                { level: logger.level, stream: origStream },
+                { level: logger.level, stream: otelStream },
+              ],
+              { levels: logger.levels.values }
+            );
+          }
 
-          return moduleExports(...args);
+          return logger;
         }, moduleExports);
 
         if (typeof patchedPino.pino === 'function') {
@@ -80,6 +124,7 @@ export class PinoInstrumentation extends InstrumentationBase {
         if (typeof patchedPino.default === 'function') {
           patchedPino.default = patchedPino;
         }
+        /* istanbul ignore if */
         if (isESM) {
           if (module.pino) {
             // This was added in [email protected] (https://github.com/pinojs/pino/pull/936).
@@ -122,7 +167,10 @@ export class PinoInstrumentation extends InstrumentationBase {
   private _getMixinFunction() {
     const instrumentation = this;
     return function otelMixin(_context: object, level: number) {
-      if (!instrumentation.isEnabled()) {
+      if (
+        !instrumentation.isEnabled() ||
+        instrumentation.getConfig().disableLogCorrelation
+      ) {
         return {};
       }
 
@@ -151,27 +199,4 @@ export class PinoInstrumentation extends InstrumentationBase {
       return record;
     };
   }
-
-  private _combineOptions(options?: any) {
-    if (options === undefined) {
-      return { mixin: this._getMixinFunction() };
-    }
-
-    if (options.mixin === undefined) {
-      options.mixin = this._getMixinFunction();
-      return options;
-    }
-
-    const originalMixin = options.mixin;
-    const otelMixin = this._getMixinFunction();
-
-    options.mixin = (context: object, level: number) => {
-      return Object.assign(
-        otelMixin(context, level),
-        originalMixin(context, level)
-      );
-    };
-
-    return options;
-  }
 }