feat: Allow configuring pino to log with different keys (#1867)

* Allow configuring pino to log with different keys

* Update README and add jsdoc

* Still have 2 failing tests

* Break tests out

* Return test context

* Simplify

---------

Co-authored-by: Amir Blum <[email protected]>
Co-authored-by: Marc Pichler <[email protected]>

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

@@ -30,7 +30,15 @@ registerInstrumentations({
     new PinoInstrumentation({
       // Optional hook to insert additional context to log object.
       logHook: (span, record, level) => {
-        record['resource.service.name'] = provider.resource.attributes['service.name'];
+        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',
       },
     }),
     // other instrumentations
@@ -45,7 +53,7 @@ logger.info('foobar');
 
 ### Fields added to pino log objects
 
-For the current active span, the following fields are injected:
+For the current active span, the following fields are injected. These field names can be optionally configured via `logKeys` in the PinoInstrumentation config:
 
 * `trace_id`
 * `span_id`

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

@@ -31,6 +31,12 @@ import { VERSION } from './version';
 
 const pinoVersions = ['>=5.14.0 <9'];
 
+const DEFAULT_LOG_KEYS = {
+  traceId: 'trace_id',
+  spanId: 'span_id',
+  traceFlags: 'trace_flags',
+};
+
 export class PinoInstrumentation extends InstrumentationBase {
   constructor(config: PinoInstrumentationConfig = {}) {
     super('@opentelemetry/instrumentation-pino', VERSION, config);
@@ -137,10 +143,12 @@ export class PinoInstrumentation extends InstrumentationBase {
         return {};
       }
 
+      const logKeys = instrumentation.getConfig().logKeys ?? DEFAULT_LOG_KEYS;
+
       const record = {
-        trace_id: spanContext.traceId,
-        span_id: spanContext.spanId,
-        trace_flags: `0${spanContext.traceFlags.toString(16)}`,
+        [logKeys.traceId]: spanContext.traceId,
+        [logKeys.spanId]: spanContext.spanId,
+        [logKeys.traceFlags]: `0${spanContext.traceFlags.toString(16)}`,
       };
 
       instrumentation._callHook(span, record, level);

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

@@ -26,4 +26,11 @@ export type LogHookFunction = (
 
 export interface PinoInstrumentationConfig extends InstrumentationConfig {
   logHook?: LogHookFunction;
+
+  /** Configure the names of field injected into logs when there is span context available.  */
+  logKeys?: {
+    traceId: string;
+    spanId: string;
+    traceFlags: string;
+  };
 }

plugins/node/opentelemetry-instrumentation-pino/test/common.ts

@@ -0,0 +1,121 @@
+/*
+ * Copyright The OpenTelemetry Authors
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      https://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+import * as assert from 'assert';
+import * as sinon from 'sinon';
+
+import { PinoInstrumentation, PinoInstrumentationConfig } from '../src';
+
+import type { pino as Pino } from 'pino';
+import { Span } from '@opentelemetry/api';
+import { Writable } from 'stream';
+
+export const kMessage = 'log-message';
+
+export interface TestContext {
+  stream: Writable;
+  writeSpy: sinon.SinonSpy;
+  logger: Pino.Logger;
+}
+
+export interface TestInstrumentation {
+  instrumentation: PinoInstrumentation;
+  pino: typeof Pino;
+}
+
+export type TestInstrumentationAndContext = TestContext & TestInstrumentation;
+
+export function assertRecord(
+  record: any,
+  span: Span,
+  expectedKeys?: PinoInstrumentationConfig['logKeys']
+) {
+  const { traceId, spanId, traceFlags } = span.spanContext();
+  assert.strictEqual(record[expectedKeys?.traceId ?? 'trace_id'], traceId);
+  assert.strictEqual(record[expectedKeys?.spanId ?? 'span_id'], spanId);
+  assert.strictEqual(
+    record[expectedKeys?.traceFlags ?? 'trace_flags'],
+    `0${traceFlags.toString(16)}`
+  );
+  assert.strictEqual(kMessage, record['msg']);
+}
+
+export function assertInjection(
+  span: Span,
+  testContext: TestContext,
+  expectedKeys?: PinoInstrumentationConfig['logKeys']
+) {
+  sinon.assert.calledOnce(testContext.writeSpy);
+  const record = JSON.parse(testContext.writeSpy.firstCall.args[0].toString());
+  assertRecord(record, span, expectedKeys);
+  return record;
+}
+
+export function testInjection(
+  span: Span,
+  testContext: TestContext,
+  expectedKeys?: PinoInstrumentationConfig['logKeys']
+) {
+  testContext.logger.info(kMessage);
+  return assertInjection(span, testContext, expectedKeys);
+}
+
+export function testNoInjection(testContext: TestContext) {
+  testContext.logger.info(kMessage);
+  sinon.assert.calledOnce(testContext.writeSpy);
+  const record = JSON.parse(testContext.writeSpy.firstCall.args[0].toString());
+  assert.strictEqual(record['trace_id'], undefined);
+  assert.strictEqual(record['span_id'], undefined);
+  assert.strictEqual(record['trace_flags'], undefined);
+  assert.strictEqual(kMessage, record['msg']);
+  return record;
+}
+
+export function initTestContext(
+  testInstrumentation: TestInstrumentation,
+  importType: 'global' | 'default' | 'pino' = 'global'
+): TestContext {
+  const stream = new Writable();
+  stream._write = () => {};
+  const writeSpy = sinon.spy(stream, 'write');
+  const logger =
+    importType === 'global'
+      ? testInstrumentation.pino(stream)
+      : // @ts-expect-error the same function reexported
+        testInstrumentation.pino[importType](stream);
+
+  return { stream, writeSpy, logger };
+}
+
+export function setupInstrumentation(
+  config?: PinoInstrumentationConfig
+): TestInstrumentation {
+  const instrumentation = new PinoInstrumentation(config);
+  if (config?.enabled !== false) {
+    instrumentation.enable();
+  }
+  const pino = require('pino');
+  return { instrumentation, pino };
+}
+
+export function setupInstrumentationAndInitTestContext(
+  config?: PinoInstrumentationConfig,
+  importType: 'global' | 'default' | 'pino' = 'global'
+) {
+  const instrumentation = setupInstrumentation(config);
+  const context = initTestContext(instrumentation, importType);
+  return { ...instrumentation, ...context };
+}

plugins/node/opentelemetry-instrumentation-pino/test/pino-disabled.test.ts

@@ -0,0 +1,86 @@
+/*
+ * Copyright The OpenTelemetry Authors
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      https://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+import * as assert from 'assert';
+
+import {
+  InMemorySpanExporter,
+  SimpleSpanProcessor,
+} from '@opentelemetry/sdk-trace-base';
+import {
+  TestContext,
+  TestInstrumentation,
+  initTestContext,
+  setupInstrumentation,
+  testInjection,
+  testNoInjection,
+} from './common';
+import { context, trace } from '@opentelemetry/api';
+
+import { AsyncHooksContextManager } from '@opentelemetry/context-async-hooks';
+import { NodeTracerProvider } from '@opentelemetry/sdk-trace-node';
+
+const memoryExporter = new InMemorySpanExporter();
+const provider = new NodeTracerProvider();
+const tracer = provider.getTracer('default');
+provider.addSpanProcessor(new SimpleSpanProcessor(memoryExporter));
+context.setGlobalContextManager(new AsyncHooksContextManager());
+
+describe('PinoInstrumentation', () => {
+  describe('disabled instrumentation', () => {
+    let testInstrumentation: TestInstrumentation;
+    let testContext: TestContext;
+    before(() => {
+      testInstrumentation = setupInstrumentation();
+      testContext = initTestContext(testInstrumentation);
+      testInstrumentation.instrumentation.disable();
+    });
+    after(() => testInstrumentation.instrumentation.enable());
+
+    beforeEach(() => {
+      testContext = initTestContext(testInstrumentation);
+    });
+
+    it('does not inject span context', () => {
+      const span = tracer.startSpan('abc');
+      context.with(trace.setSpan(context.active(), span), () => {
+        testNoInjection(testContext);
+      });
+    });
+
+    it('does not call log hook', () => {
+      const span = tracer.startSpan('abc');
+      testInstrumentation.instrumentation.setConfig({
+        enabled: false,
+        logHook: (_span, record) => {
+          record['resource.service.name'] = 'test-service';
+        },
+      });
+      context.with(trace.setSpan(context.active(), span), () => {
+        const record = testNoInjection(testContext);
+        assert.strictEqual(record['resource.service.name'], undefined);
+      });
+    });
+
+    it('injects span context once re-enabled', () => {
+      testInstrumentation.instrumentation.enable();
+      const span = tracer.startSpan('abc');
+      context.with(trace.setSpan(context.active(), span), () => {
+        testInjection(span, testContext);
+      });
+    });
+  });
+});