From 8be98f4dbe426c2f8fe5072844d923fbb9a51f08 Mon Sep 17 00:00:00 2001 From: Drew Corlin Date: Sun, 17 Dec 2023 15:57:13 -0500 Subject: [PATCH 1/6] Allow configuring pino to log with different keys --- .../README.md | 9 ++- .../src/instrumentation.ts | 14 ++++- .../src/types.ts | 5 ++ .../test/pino.test.ts | 55 +++++++++++++++---- 4 files changed, 68 insertions(+), 15 deletions(-) diff --git a/plugins/node/opentelemetry-instrumentation-pino/README.md b/plugins/node/opentelemetry-instrumentation-pino/README.md index 288a69756b..1b42e635db 100644 --- a/plugins/node/opentelemetry-instrumentation-pino/README.md +++ b/plugins/node/opentelemetry-instrumentation-pino/README.md @@ -30,7 +30,14 @@ 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 + logKeys: { + traceId: 'traceId', + spanId: 'spanId', + traceFlags: 'traceFlags', }, }), // other instrumentations diff --git a/plugins/node/opentelemetry-instrumentation-pino/src/instrumentation.ts b/plugins/node/opentelemetry-instrumentation-pino/src/instrumentation.ts index c930c2fa99..20478464ed 100644 --- a/plugins/node/opentelemetry-instrumentation-pino/src/instrumentation.ts +++ b/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); @@ -128,10 +134,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); diff --git a/plugins/node/opentelemetry-instrumentation-pino/src/types.ts b/plugins/node/opentelemetry-instrumentation-pino/src/types.ts index 4bf80f5a34..b37d272cc7 100644 --- a/plugins/node/opentelemetry-instrumentation-pino/src/types.ts +++ b/plugins/node/opentelemetry-instrumentation-pino/src/types.ts @@ -26,4 +26,9 @@ export type LogHookFunction = ( export interface PinoInstrumentationConfig extends InstrumentationConfig { logHook?: LogHookFunction; + logKeys?: { + traceId: string; + spanId: string; + traceFlags: string; + }; } diff --git a/plugins/node/opentelemetry-instrumentation-pino/test/pino.test.ts b/plugins/node/opentelemetry-instrumentation-pino/test/pino.test.ts index 3f175bc90a..51aa1d216f 100644 --- a/plugins/node/opentelemetry-instrumentation-pino/test/pino.test.ts +++ b/plugins/node/opentelemetry-instrumentation-pino/test/pino.test.ts @@ -27,7 +27,7 @@ import * as sinon from 'sinon'; import * as semver from 'semver'; import type { pino as Pino } from 'pino'; -import { PinoInstrumentation } from '../src'; +import { PinoInstrumentation , PinoInstrumentationConfig} from '../src'; const memoryExporter = new InMemorySpanExporter(); const provider = new NodeTracerProvider(); @@ -37,6 +37,12 @@ context.setGlobalContextManager(new AsyncHooksContextManager()); const kMessage = 'log-message'; +const logKeys = { + traceId: 'traceId', + spanId: 'spanId', + traceFlags: 'traceFlags', +}; + describe('PinoInstrumentation', () => { let stream: Writable; let writeSpy: sinon.SinonSpy; @@ -44,24 +50,37 @@ describe('PinoInstrumentation', () => { let instrumentation: PinoInstrumentation; let logger: Pino.Logger; - function assertRecord(record: any, span: Span) { + function assertRecord( + record: any, + span: Span, + expectedKeys?: PinoInstrumentationConfig['logKeys'] + ) { const { traceId, spanId, traceFlags } = span.spanContext(); - assert.strictEqual(record['trace_id'], traceId); - assert.strictEqual(record['span_id'], spanId); - assert.strictEqual(record['trace_flags'], `0${traceFlags.toString(16)}`); + assert.strictEqual(record[logKeys.traceId], traceId); + assert.strictEqual(record[logKeys.spanId], spanId); + assert.strictEqual( + record[logKeys.traceFlags], + `0${traceFlags.toString(16)}` + ); assert.strictEqual(kMessage, record['msg']); } - function assertInjection(span: Span) { + function assertInjection( + span: Span, + expectedKeys?: PinoInstrumentationConfig['logKeys'] + ) { sinon.assert.calledOnce(writeSpy); const record = JSON.parse(writeSpy.firstCall.args[0].toString()); - assertRecord(record, span); + assertRecord(record, span, expectedKeys); return record; } - function testInjection(span: Span) { + function testInjection( + span: Span, + expectedKeys?: PinoInstrumentationConfig['logKeys'] + ) { logger.info(kMessage); - return assertInjection(span); + return assertInjection(span, expectedKeys); } function testNoInjection() { @@ -87,10 +106,16 @@ describe('PinoInstrumentation', () => { } } - before(() => { - instrumentation = new PinoInstrumentation(); + function setup() { + instrumentation = new PinoInstrumentation({ + logKeys, + }); instrumentation.enable(); pino = require('pino'); + } + + before(() => { + setup(); }); describe('enabled instrumentation', () => { @@ -105,6 +130,14 @@ describe('PinoInstrumentation', () => { }); }); + it('injects span context to records with custom keys', () => { + setup(); + const span = tracer.startSpan('abc'); + context.with(trace.setSpan(context.active(), span), () => { + testInjection(span); + }); + }); + it('injects span context to records in default export', function () { // @ts-expect-error the same function reexported if (!pino.default) { From 8a5009a83b6824a849f3a34f982851276afe5f4c Mon Sep 17 00:00:00 2001 From: Drew Corlin Date: Sun, 17 Dec 2023 19:07:03 -0500 Subject: [PATCH 2/6] Update README and add jsdoc --- plugins/node/opentelemetry-instrumentation-pino/README.md | 3 ++- plugins/node/opentelemetry-instrumentation-pino/src/types.ts | 2 ++ 2 files changed, 4 insertions(+), 1 deletion(-) diff --git a/plugins/node/opentelemetry-instrumentation-pino/README.md b/plugins/node/opentelemetry-instrumentation-pino/README.md index 1b42e635db..7d8c7393f1 100644 --- a/plugins/node/opentelemetry-instrumentation-pino/README.md +++ b/plugins/node/opentelemetry-instrumentation-pino/README.md @@ -34,6 +34,7 @@ registerInstrumentations({ 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', @@ -52,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` diff --git a/plugins/node/opentelemetry-instrumentation-pino/src/types.ts b/plugins/node/opentelemetry-instrumentation-pino/src/types.ts index b37d272cc7..52484885a7 100644 --- a/plugins/node/opentelemetry-instrumentation-pino/src/types.ts +++ b/plugins/node/opentelemetry-instrumentation-pino/src/types.ts @@ -26,6 +26,8 @@ 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; From d918f92442471e3bc29614cbf90244e0986f2c5b Mon Sep 17 00:00:00 2001 From: Drew Corlin Date: Sun, 17 Dec 2023 22:56:36 -0500 Subject: [PATCH 3/6] Still have 2 failing tests --- .../test/pino.test.ts | 74 +++++++++---------- 1 file changed, 37 insertions(+), 37 deletions(-) diff --git a/plugins/node/opentelemetry-instrumentation-pino/test/pino.test.ts b/plugins/node/opentelemetry-instrumentation-pino/test/pino.test.ts index 51aa1d216f..b7e1ef4ad1 100644 --- a/plugins/node/opentelemetry-instrumentation-pino/test/pino.test.ts +++ b/plugins/node/opentelemetry-instrumentation-pino/test/pino.test.ts @@ -14,20 +14,21 @@ * limitations under the License. */ +import * as assert from 'assert'; +import * as semver from 'semver'; +import * as sinon from 'sinon'; + +import { INVALID_SPAN_CONTEXT, Span, context, trace } from '@opentelemetry/api'; import { InMemorySpanExporter, SimpleSpanProcessor, } from '@opentelemetry/sdk-trace-base'; -import { context, trace, Span, INVALID_SPAN_CONTEXT } from '@opentelemetry/api'; -import { NodeTracerProvider } from '@opentelemetry/sdk-trace-node'; +import { PinoInstrumentation, PinoInstrumentationConfig } from '../src'; + import { AsyncHooksContextManager } from '@opentelemetry/context-async-hooks'; -import { Writable } from 'stream'; -import * as assert from 'assert'; -import * as sinon from 'sinon'; -import * as semver from 'semver'; +import { NodeTracerProvider } from '@opentelemetry/sdk-trace-node'; import type { pino as Pino } from 'pino'; - -import { PinoInstrumentation , PinoInstrumentationConfig} from '../src'; +import { Writable } from 'stream'; const memoryExporter = new InMemorySpanExporter(); const provider = new NodeTracerProvider(); @@ -37,12 +38,6 @@ context.setGlobalContextManager(new AsyncHooksContextManager()); const kMessage = 'log-message'; -const logKeys = { - traceId: 'traceId', - spanId: 'spanId', - traceFlags: 'traceFlags', -}; - describe('PinoInstrumentation', () => { let stream: Writable; let writeSpy: sinon.SinonSpy; @@ -56,10 +51,10 @@ describe('PinoInstrumentation', () => { expectedKeys?: PinoInstrumentationConfig['logKeys'] ) { const { traceId, spanId, traceFlags } = span.spanContext(); - assert.strictEqual(record[logKeys.traceId], traceId); - assert.strictEqual(record[logKeys.spanId], spanId); + assert.strictEqual(record[expectedKeys?.traceId ?? 'trace_id'], traceId); + assert.strictEqual(record[expectedKeys?.spanId ?? 'span_id'], spanId); assert.strictEqual( - record[logKeys.traceFlags], + record[expectedKeys?.traceFlags ?? 'trace_flags'], `0${traceFlags.toString(16)}` ); assert.strictEqual(kMessage, record['msg']); @@ -106,20 +101,17 @@ describe('PinoInstrumentation', () => { } } - function setup() { - instrumentation = new PinoInstrumentation({ - logKeys, - }); - instrumentation.enable(); + function setup(config?: PinoInstrumentationConfig) { + instrumentation = new PinoInstrumentation(config); + if (config?.enabled !== false) { + instrumentation.enable(); + } pino = require('pino'); } - before(() => { - setup(); - }); - describe('enabled instrumentation', () => { beforeEach(() => { + setup(); init(); }); @@ -131,10 +123,18 @@ describe('PinoInstrumentation', () => { }); it('injects span context to records with custom keys', () => { - setup(); + const logKeys = { + traceId: 'traceId', + spanId: 'spanId', + traceFlags: 'traceFlags', + }; + + setup({ logKeys }); + init(); + const span = tracer.startSpan('abc'); context.with(trace.setSpan(context.active(), span), () => { - testInjection(span); + testInjection(span, logKeys); }); }); @@ -218,9 +218,9 @@ describe('PinoInstrumentation', () => { let stdoutSpy: sinon.SinonSpy; beforeEach(() => { - stream = new Writable(); - stream._write = () => {}; - writeSpy = sinon.spy(stream, 'write'); + setup(); + init(); + stdoutSpy = sinon.spy(process.stdout, 'write'); }); @@ -297,15 +297,15 @@ describe('PinoInstrumentation', () => { }); describe('disabled instrumentation', () => { - before(() => { + beforeEach(() => { + setup({ enabled: false }); instrumentation.disable(); + init(); }); - after(() => { - instrumentation.enable(); - }); - - beforeEach(() => init()); + // afterEach(() => { + // instrumentation.enable(); + // }); it('does not inject span context', () => { const span = tracer.startSpan('abc'); From 8a4bb4a51e7460c4757582df53da3dd6792aa5cb Mon Sep 17 00:00:00 2001 From: Drew Corlin Date: Tue, 19 Dec 2023 21:46:01 -0800 Subject: [PATCH 4/6] Break tests out --- .../test/common.ts | 100 +++++++++++ .../test/pino-disabled.test.ts | 80 +++++++++ .../{pino.test.ts => pino-enabled.test.ts} | 166 ++++-------------- 3 files changed, 215 insertions(+), 131 deletions(-) create mode 100644 plugins/node/opentelemetry-instrumentation-pino/test/common.ts create mode 100644 plugins/node/opentelemetry-instrumentation-pino/test/pino-disabled.test.ts rename plugins/node/opentelemetry-instrumentation-pino/test/{pino.test.ts => pino-enabled.test.ts} (62%) diff --git a/plugins/node/opentelemetry-instrumentation-pino/test/common.ts b/plugins/node/opentelemetry-instrumentation-pino/test/common.ts new file mode 100644 index 0000000000..3142446515 --- /dev/null +++ b/plugins/node/opentelemetry-instrumentation-pino/test/common.ts @@ -0,0 +1,100 @@ +/* + * 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 let stream: Writable; +export let writeSpy: sinon.SinonSpy; +export let pino: typeof Pino; +export let instrumentation: PinoInstrumentation; +export let logger: Pino.Logger; + +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, + expectedKeys?: PinoInstrumentationConfig['logKeys'] +) { + sinon.assert.calledOnce(writeSpy); + const record = JSON.parse(writeSpy.firstCall.args[0].toString()); + assertRecord(record, span, expectedKeys); + return record; +} + +export function testInjection( + span: Span, + expectedKeys?: PinoInstrumentationConfig['logKeys'] +) { + logger.info(kMessage); + return assertInjection(span, expectedKeys); +} + +export function testNoInjection() { + logger.info(kMessage); + sinon.assert.calledOnce(writeSpy); + const record = JSON.parse(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 init(importType: 'global' | 'default' | 'pino' = 'global') { + stream = new Writable(); + stream._write = () => {}; + writeSpy = sinon.spy(stream, 'write'); + if (importType === 'global') { + logger = pino(stream); + } else { + // @ts-expect-error the same function reexported + logger = pino[importType](stream); + } +} + +export function setLogger(log: Pino.Logger) { + logger = log; +} + +export function setup(config?: PinoInstrumentationConfig) { + instrumentation = new PinoInstrumentation(config); + if (config?.enabled !== false) { + instrumentation.enable(); + } + pino = require('pino'); +} diff --git a/plugins/node/opentelemetry-instrumentation-pino/test/pino-disabled.test.ts b/plugins/node/opentelemetry-instrumentation-pino/test/pino-disabled.test.ts new file mode 100644 index 0000000000..de1290c401 --- /dev/null +++ b/plugins/node/opentelemetry-instrumentation-pino/test/pino-disabled.test.ts @@ -0,0 +1,80 @@ +/* + * 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 { context, trace } from '@opentelemetry/api'; +import { + init, + instrumentation, + setup, + testInjection, + testNoInjection, +} from './common'; + +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', () => { + before(() => { + setup(); + instrumentation.disable(); + }); + after(() => instrumentation.enable()); + + beforeEach(() => init()); + + it('does not inject span context', () => { + const span = tracer.startSpan('abc'); + context.with(trace.setSpan(context.active(), span), () => { + testNoInjection(); + }); + }); + + it('does not call log hook', () => { + const span = tracer.startSpan('abc'); + instrumentation.setConfig({ + enabled: false, + logHook: (_span, record) => { + record['resource.service.name'] = 'test-service'; + }, + }); + context.with(trace.setSpan(context.active(), span), () => { + const record = testNoInjection(); + assert.strictEqual(record['resource.service.name'], undefined); + }); + }); + + it('injects span context once re-enabled', () => { + instrumentation.enable(); + const span = tracer.startSpan('abc'); + context.with(trace.setSpan(context.active(), span), () => { + testInjection(span); + }); + }); + }); +}); diff --git a/plugins/node/opentelemetry-instrumentation-pino/test/pino.test.ts b/plugins/node/opentelemetry-instrumentation-pino/test/pino-enabled.test.ts similarity index 62% rename from plugins/node/opentelemetry-instrumentation-pino/test/pino.test.ts rename to plugins/node/opentelemetry-instrumentation-pino/test/pino-enabled.test.ts index b7e1ef4ad1..b744c8537a 100644 --- a/plugins/node/opentelemetry-instrumentation-pino/test/pino.test.ts +++ b/plugins/node/opentelemetry-instrumentation-pino/test/pino-enabled.test.ts @@ -18,17 +18,30 @@ import * as assert from 'assert'; import * as semver from 'semver'; import * as sinon from 'sinon'; -import { INVALID_SPAN_CONTEXT, Span, context, trace } from '@opentelemetry/api'; +import { INVALID_SPAN_CONTEXT, context, trace } from '@opentelemetry/api'; import { InMemorySpanExporter, SimpleSpanProcessor, } from '@opentelemetry/sdk-trace-base'; -import { PinoInstrumentation, PinoInstrumentationConfig } from '../src'; +import { + assertInjection, + assertRecord, + init, + instrumentation, + kMessage, + logger, + pino, + setLogger, + setup, + stream, + testInjection, + testNoInjection, + writeSpy, +} from './common'; import { AsyncHooksContextManager } from '@opentelemetry/context-async-hooks'; import { NodeTracerProvider } from '@opentelemetry/sdk-trace-node'; import type { pino as Pino } from 'pino'; -import { Writable } from 'stream'; const memoryExporter = new InMemorySpanExporter(); const provider = new NodeTracerProvider(); @@ -36,79 +49,7 @@ const tracer = provider.getTracer('default'); provider.addSpanProcessor(new SimpleSpanProcessor(memoryExporter)); context.setGlobalContextManager(new AsyncHooksContextManager()); -const kMessage = 'log-message'; - describe('PinoInstrumentation', () => { - let stream: Writable; - let writeSpy: sinon.SinonSpy; - let pino: typeof Pino; - let instrumentation: PinoInstrumentation; - let logger: Pino.Logger; - - 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']); - } - - function assertInjection( - span: Span, - expectedKeys?: PinoInstrumentationConfig['logKeys'] - ) { - sinon.assert.calledOnce(writeSpy); - const record = JSON.parse(writeSpy.firstCall.args[0].toString()); - assertRecord(record, span, expectedKeys); - return record; - } - - function testInjection( - span: Span, - expectedKeys?: PinoInstrumentationConfig['logKeys'] - ) { - logger.info(kMessage); - return assertInjection(span, expectedKeys); - } - - function testNoInjection() { - logger.info(kMessage); - sinon.assert.calledOnce(writeSpy); - const record = JSON.parse(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; - } - - function init(importType: 'global' | 'default' | 'pino' = 'global') { - stream = new Writable(); - stream._write = () => {}; - writeSpy = sinon.spy(stream, 'write'); - if (importType === 'global') { - logger = pino(stream); - } else { - // @ts-expect-error the same function reexported - logger = pino[importType](stream); - } - } - - function setup(config?: PinoInstrumentationConfig) { - instrumentation = new PinoInstrumentation(config); - if (config?.enabled !== false) { - instrumentation.enable(); - } - pino = require('pino'); - } - describe('enabled instrumentation', () => { beforeEach(() => { setup(); @@ -229,7 +170,7 @@ describe('PinoInstrumentation', () => { }); it('does not fail when constructing logger without arguments', () => { - logger = pino(); + setLogger(pino()); const span = tracer.startSpan('abc'); context.with(trace.setSpan(context.active(), span), () => { logger.info(kMessage); @@ -239,7 +180,7 @@ describe('PinoInstrumentation', () => { }); it('preserves user options and adds a mixin', () => { - logger = pino({ name: 'LogLog' }, stream); + setLogger(pino({ name: 'LogLog' }, stream)); const span = tracer.startSpan('abc'); context.with(trace.setSpan(context.active(), span), () => { @@ -250,7 +191,7 @@ describe('PinoInstrumentation', () => { describe('binary arguments', () => { it('is possible to construct logger with undefined options', () => { - logger = pino(undefined as unknown as Pino.LoggerOptions, stream); + setLogger(pino(undefined as unknown as Pino.LoggerOptions, stream)); const span = tracer.startSpan('abc'); context.with(trace.setSpan(context.active(), span), () => { testInjection(span); @@ -258,12 +199,14 @@ describe('PinoInstrumentation', () => { }); it('preserves user mixins', () => { - logger = pino( - { - name: 'LogLog', - mixin: () => ({ a: 2, b: 'bar' }), - }, - stream + setLogger( + pino( + { + name: 'LogLog', + mixin: () => ({ a: 2, b: 'bar' }), + }, + stream + ) ); const span = tracer.startSpan('abc'); @@ -276,13 +219,15 @@ describe('PinoInstrumentation', () => { }); it('ensures user mixin values take precedence', () => { - logger = pino( - { - mixin() { - return { trace_id: '123' }; + setLogger( + pino( + { + mixin() { + return { trace_id: '123' }; + }, }, - }, - stream + stream + ) ); const span = tracer.startSpan('abc'); @@ -295,45 +240,4 @@ describe('PinoInstrumentation', () => { }); }); }); - - describe('disabled instrumentation', () => { - beforeEach(() => { - setup({ enabled: false }); - instrumentation.disable(); - init(); - }); - - // afterEach(() => { - // instrumentation.enable(); - // }); - - it('does not inject span context', () => { - const span = tracer.startSpan('abc'); - context.with(trace.setSpan(context.active(), span), () => { - testNoInjection(); - }); - }); - - it('does not call log hook', () => { - const span = tracer.startSpan('abc'); - instrumentation.setConfig({ - enabled: false, - logHook: (_span, record) => { - record['resource.service.name'] = 'test-service'; - }, - }); - context.with(trace.setSpan(context.active(), span), () => { - const record = testNoInjection(); - assert.strictEqual(record['resource.service.name'], undefined); - }); - }); - - it('injects span context once re-enabled', () => { - instrumentation.enable(); - const span = tracer.startSpan('abc'); - context.with(trace.setSpan(context.active(), span), () => { - testInjection(span); - }); - }); - }); }); From 359d726e067946164d24c9488d41ea725118c1da Mon Sep 17 00:00:00 2001 From: Drew Corlin Date: Wed, 20 Dec 2023 16:27:13 -0800 Subject: [PATCH 5/6] Return test context --- .../test/common.ts | 66 ++++++----- .../test/pino-disabled.test.ts | 32 +++-- .../test/pino-enabled.test.ts | 111 +++++++++--------- 3 files changed, 112 insertions(+), 97 deletions(-) diff --git a/plugins/node/opentelemetry-instrumentation-pino/test/common.ts b/plugins/node/opentelemetry-instrumentation-pino/test/common.ts index 3142446515..0ab6431be8 100644 --- a/plugins/node/opentelemetry-instrumentation-pino/test/common.ts +++ b/plugins/node/opentelemetry-instrumentation-pino/test/common.ts @@ -25,11 +25,16 @@ import { Writable } from 'stream'; export const kMessage = 'log-message'; -export let stream: Writable; -export let writeSpy: sinon.SinonSpy; -export let pino: typeof Pino; -export let instrumentation: PinoInstrumentation; -export let logger: Pino.Logger; +export interface TestContext { + stream: Writable; + writeSpy: sinon.SinonSpy; + logger: Pino.Logger; +} + +export interface TestInstrumentation { + instrumentation: PinoInstrumentation; + pino: typeof Pino; +} export function assertRecord( record: any, @@ -48,26 +53,28 @@ export function assertRecord( export function assertInjection( span: Span, + testContext: TestContext, expectedKeys?: PinoInstrumentationConfig['logKeys'] ) { - sinon.assert.calledOnce(writeSpy); - const record = JSON.parse(writeSpy.firstCall.args[0].toString()); + 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'] ) { - logger.info(kMessage); - return assertInjection(span, expectedKeys); + testContext.logger.info(kMessage); + return assertInjection(span, testContext, expectedKeys); } -export function testNoInjection() { - logger.info(kMessage); - sinon.assert.calledOnce(writeSpy); - const record = JSON.parse(writeSpy.firstCall.args[0].toString()); +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); @@ -75,26 +82,29 @@ export function testNoInjection() { return record; } -export function init(importType: 'global' | 'default' | 'pino' = 'global') { - stream = new Writable(); +export function initTestContext( + testInstrumentation: TestInstrumentation, + importType: 'global' | 'default' | 'pino' = 'global' +): TestContext { + const stream = new Writable(); stream._write = () => {}; - writeSpy = sinon.spy(stream, 'write'); - if (importType === 'global') { - logger = pino(stream); - } else { - // @ts-expect-error the same function reexported - logger = pino[importType](stream); - } -} + const writeSpy = sinon.spy(stream, 'write'); + const logger = + importType === 'global' + ? testInstrumentation.pino(stream) + : // @ts-expect-error the same function reexported + testInstrumentation.pino[importType](stream); -export function setLogger(log: Pino.Logger) { - logger = log; + return { stream, writeSpy, logger }; } -export function setup(config?: PinoInstrumentationConfig) { - instrumentation = new PinoInstrumentation(config); +export function setupInstrumentation( + config?: PinoInstrumentationConfig +): TestInstrumentation { + const instrumentation = new PinoInstrumentation(config); if (config?.enabled !== false) { instrumentation.enable(); } - pino = require('pino'); + const pino = require('pino'); + return { instrumentation, pino }; } diff --git a/plugins/node/opentelemetry-instrumentation-pino/test/pino-disabled.test.ts b/plugins/node/opentelemetry-instrumentation-pino/test/pino-disabled.test.ts index de1290c401..f8258db444 100644 --- a/plugins/node/opentelemetry-instrumentation-pino/test/pino-disabled.test.ts +++ b/plugins/node/opentelemetry-instrumentation-pino/test/pino-disabled.test.ts @@ -20,14 +20,15 @@ import { InMemorySpanExporter, SimpleSpanProcessor, } from '@opentelemetry/sdk-trace-base'; -import { context, trace } from '@opentelemetry/api'; import { - init, - instrumentation, - setup, + 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'; @@ -40,40 +41,45 @@ context.setGlobalContextManager(new AsyncHooksContextManager()); describe('PinoInstrumentation', () => { describe('disabled instrumentation', () => { + let testInstrumentation: TestInstrumentation; + let testContext: TestContext; before(() => { - setup(); - instrumentation.disable(); + testInstrumentation = setupInstrumentation(); + testContext = initTestContext(testInstrumentation); + testInstrumentation.instrumentation.disable(); }); - after(() => instrumentation.enable()); + after(() => testInstrumentation.instrumentation.enable()); - beforeEach(() => init()); + beforeEach(() => { + testContext = initTestContext(testInstrumentation); + }); it('does not inject span context', () => { const span = tracer.startSpan('abc'); context.with(trace.setSpan(context.active(), span), () => { - testNoInjection(); + testNoInjection(testContext); }); }); it('does not call log hook', () => { const span = tracer.startSpan('abc'); - instrumentation.setConfig({ + testInstrumentation.instrumentation.setConfig({ enabled: false, logHook: (_span, record) => { record['resource.service.name'] = 'test-service'; }, }); context.with(trace.setSpan(context.active(), span), () => { - const record = testNoInjection(); + const record = testNoInjection(testContext); assert.strictEqual(record['resource.service.name'], undefined); }); }); it('injects span context once re-enabled', () => { - instrumentation.enable(); + testInstrumentation.instrumentation.enable(); const span = tracer.startSpan('abc'); context.with(trace.setSpan(context.active(), span), () => { - testInjection(span); + testInjection(span, testContext); }); }); }); diff --git a/plugins/node/opentelemetry-instrumentation-pino/test/pino-enabled.test.ts b/plugins/node/opentelemetry-instrumentation-pino/test/pino-enabled.test.ts index b744c8537a..ed0d49a708 100644 --- a/plugins/node/opentelemetry-instrumentation-pino/test/pino-enabled.test.ts +++ b/plugins/node/opentelemetry-instrumentation-pino/test/pino-enabled.test.ts @@ -24,19 +24,15 @@ import { SimpleSpanProcessor, } from '@opentelemetry/sdk-trace-base'; import { + TestContext, + TestInstrumentation, assertInjection, assertRecord, - init, - instrumentation, + initTestContext, kMessage, - logger, - pino, - setLogger, - setup, - stream, + setupInstrumentation, testInjection, testNoInjection, - writeSpy, } from './common'; import { AsyncHooksContextManager } from '@opentelemetry/context-async-hooks'; @@ -50,16 +46,18 @@ provider.addSpanProcessor(new SimpleSpanProcessor(memoryExporter)); context.setGlobalContextManager(new AsyncHooksContextManager()); describe('PinoInstrumentation', () => { + let testInstrumentation: TestInstrumentation; + let testContext: TestContext; describe('enabled instrumentation', () => { beforeEach(() => { - setup(); - init(); + testInstrumentation = setupInstrumentation(); + testContext = initTestContext(testInstrumentation); }); it('injects span context to records', () => { const span = tracer.startSpan('abc'); context.with(trace.setSpan(context.active(), span), () => { - testInjection(span); + testInjection(span, testContext); }); }); @@ -70,87 +68,87 @@ describe('PinoInstrumentation', () => { traceFlags: 'traceFlags', }; - setup({ logKeys }); - init(); + testInstrumentation = setupInstrumentation({ logKeys }); + testContext = initTestContext(testInstrumentation); const span = tracer.startSpan('abc'); context.with(trace.setSpan(context.active(), span), () => { - testInjection(span, logKeys); + testInjection(span, testContext, logKeys); }); }); it('injects span context to records in default export', function () { // @ts-expect-error the same function reexported - if (!pino.default) { + if (!testInstrumentation.pino.default) { this.skip(); } - init('default'); + initTestContext(testInstrumentation, 'default'); const span = tracer.startSpan('abc'); context.with(trace.setSpan(context.active(), span), () => { - testInjection(span); + testInjection(span, testContext); }); }); it('injects span context to records in named export', function () { // @ts-expect-error the same function reexported - if (!pino.pino) { + if (!testInstrumentation.pino.pino) { this.skip(); } - init('pino'); + initTestContext(testInstrumentation, 'pino'); const span = tracer.startSpan('abc'); context.with(trace.setSpan(context.active(), span), () => { - testInjection(span); + testInjection(span, testContext); }); }); it('injects span context to child logger records', () => { const span = tracer.startSpan('abc'); context.with(trace.setSpan(context.active(), span), () => { - const child = logger.child({ foo: 42 }); + const child = testContext.logger.child({ foo: 42 }); child.info(kMessage); - assertInjection(span); + assertInjection(span, testContext); }); }); it('calls the users log hook', () => { const span = tracer.startSpan('abc'); - instrumentation.setConfig({ + testInstrumentation.instrumentation.setConfig({ enabled: true, logHook: (_span, record, level) => { record['resource.service.name'] = 'test-service'; - if (semver.satisfies(pino.version, '>= 7.9.0')) { + if (semver.satisfies(testInstrumentation.pino.version, '>= 7.9.0')) { assert.strictEqual(level, 30); } }, }); context.with(trace.setSpan(context.active(), span), () => { - const record = testInjection(span); + const record = testInjection(span, testContext); assert.strictEqual(record['resource.service.name'], 'test-service'); }); }); it('does not inject span context if no span is active', () => { assert.strictEqual(trace.getSpan(context.active()), undefined); - testNoInjection(); + testNoInjection(testContext); }); it('does not inject span context if span context is invalid', () => { const span = trace.wrapSpanContext(INVALID_SPAN_CONTEXT); context.with(trace.setSpan(context.active(), span), () => { - testNoInjection(); + testNoInjection(testContext); }); }); it('does not propagate exceptions from user hooks', () => { const span = tracer.startSpan('abc'); - instrumentation.setConfig({ + testInstrumentation.instrumentation.setConfig({ enabled: true, logHook: () => { throw new Error('Oops'); }, }); context.with(trace.setSpan(context.active(), span), () => { - testInjection(span); + testInjection(span, testContext); }); }); }); @@ -159,8 +157,8 @@ describe('PinoInstrumentation', () => { let stdoutSpy: sinon.SinonSpy; beforeEach(() => { - setup(); - init(); + testInstrumentation = setupInstrumentation(); + testContext = initTestContext(testInstrumentation); stdoutSpy = sinon.spy(process.stdout, 'write'); }); @@ -170,48 +168,49 @@ describe('PinoInstrumentation', () => { }); it('does not fail when constructing logger without arguments', () => { - setLogger(pino()); + testContext.logger = testInstrumentation.pino(); const span = tracer.startSpan('abc'); context.with(trace.setSpan(context.active(), span), () => { - logger.info(kMessage); + testContext.logger.info(kMessage); }); const record = JSON.parse(stdoutSpy.firstCall.args[0].toString()); assertRecord(record, span); }); it('preserves user options and adds a mixin', () => { - setLogger(pino({ name: 'LogLog' }, stream)); + testContext.logger = testInstrumentation.pino( + { name: 'LogLog' }, + testContext.stream + ); const span = tracer.startSpan('abc'); context.with(trace.setSpan(context.active(), span), () => { - const record = testInjection(span); + const record = testInjection(span, testContext); assert.strictEqual(record['name'], 'LogLog'); }); }); describe('binary arguments', () => { it('is possible to construct logger with undefined options', () => { - setLogger(pino(undefined as unknown as Pino.LoggerOptions, stream)); + testContext.logger = testInstrumentation.pino( + undefined as unknown as Pino.LoggerOptions, + testContext.stream + ); const span = tracer.startSpan('abc'); context.with(trace.setSpan(context.active(), span), () => { - testInjection(span); + testInjection(span, testContext); }); }); it('preserves user mixins', () => { - setLogger( - pino( - { - name: 'LogLog', - mixin: () => ({ a: 2, b: 'bar' }), - }, - stream - ) + testContext.logger = testInstrumentation.pino( + { name: 'LogLog', mixin: () => ({ a: 2, b: 'bar' }) }, + testContext.stream ); const span = tracer.startSpan('abc'); context.with(trace.setSpan(context.active(), span), () => { - const record = testInjection(span); + const record = testInjection(span, testContext); assert.strictEqual(record['a'], 2); assert.strictEqual(record['b'], 'bar'); assert.strictEqual(record['name'], 'LogLog'); @@ -219,23 +218,23 @@ describe('PinoInstrumentation', () => { }); it('ensures user mixin values take precedence', () => { - setLogger( - pino( - { - mixin() { - return { trace_id: '123' }; - }, + testContext.logger = testInstrumentation.pino( + { + mixin() { + return { trace_id: '123' }; }, - stream - ) + }, + testContext.stream ); const span = tracer.startSpan('abc'); context.with(trace.setSpan(context.active(), span), () => { - logger.info(kMessage); + testContext.logger.info(kMessage); }); - const record = JSON.parse(writeSpy.firstCall.args[0].toString()); + const record = JSON.parse( + testContext.writeSpy.firstCall.args[0].toString() + ); assert.strictEqual(record['trace_id'], '123'); }); }); From 96e2986c0a766aae986baff9a855729a1eda66c3 Mon Sep 17 00:00:00 2001 From: Drew Corlin Date: Wed, 20 Dec 2023 16:30:56 -0800 Subject: [PATCH 6/6] Simplify --- .../test/common.ts | 11 +++++ .../test/pino-enabled.test.ts | 42 +++++++++---------- 2 files changed, 30 insertions(+), 23 deletions(-) diff --git a/plugins/node/opentelemetry-instrumentation-pino/test/common.ts b/plugins/node/opentelemetry-instrumentation-pino/test/common.ts index 0ab6431be8..006f169e32 100644 --- a/plugins/node/opentelemetry-instrumentation-pino/test/common.ts +++ b/plugins/node/opentelemetry-instrumentation-pino/test/common.ts @@ -36,6 +36,8 @@ export interface TestInstrumentation { pino: typeof Pino; } +export type TestInstrumentationAndContext = TestContext & TestInstrumentation; + export function assertRecord( record: any, span: Span, @@ -108,3 +110,12 @@ export function setupInstrumentation( 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 }; +} diff --git a/plugins/node/opentelemetry-instrumentation-pino/test/pino-enabled.test.ts b/plugins/node/opentelemetry-instrumentation-pino/test/pino-enabled.test.ts index ed0d49a708..10bce070dc 100644 --- a/plugins/node/opentelemetry-instrumentation-pino/test/pino-enabled.test.ts +++ b/plugins/node/opentelemetry-instrumentation-pino/test/pino-enabled.test.ts @@ -24,13 +24,12 @@ import { SimpleSpanProcessor, } from '@opentelemetry/sdk-trace-base'; import { - TestContext, - TestInstrumentation, + TestInstrumentationAndContext, assertInjection, assertRecord, initTestContext, kMessage, - setupInstrumentation, + setupInstrumentationAndInitTestContext, testInjection, testNoInjection, } from './common'; @@ -46,12 +45,11 @@ provider.addSpanProcessor(new SimpleSpanProcessor(memoryExporter)); context.setGlobalContextManager(new AsyncHooksContextManager()); describe('PinoInstrumentation', () => { - let testInstrumentation: TestInstrumentation; - let testContext: TestContext; + let testContext: TestInstrumentationAndContext; + describe('enabled instrumentation', () => { beforeEach(() => { - testInstrumentation = setupInstrumentation(); - testContext = initTestContext(testInstrumentation); + testContext = setupInstrumentationAndInitTestContext(); }); it('injects span context to records', () => { @@ -68,8 +66,7 @@ describe('PinoInstrumentation', () => { traceFlags: 'traceFlags', }; - testInstrumentation = setupInstrumentation({ logKeys }); - testContext = initTestContext(testInstrumentation); + testContext = setupInstrumentationAndInitTestContext({ logKeys }); const span = tracer.startSpan('abc'); context.with(trace.setSpan(context.active(), span), () => { @@ -79,10 +76,10 @@ describe('PinoInstrumentation', () => { it('injects span context to records in default export', function () { // @ts-expect-error the same function reexported - if (!testInstrumentation.pino.default) { + if (!testContext.pino.default) { this.skip(); } - initTestContext(testInstrumentation, 'default'); + initTestContext(testContext, 'default'); const span = tracer.startSpan('abc'); context.with(trace.setSpan(context.active(), span), () => { testInjection(span, testContext); @@ -91,10 +88,10 @@ describe('PinoInstrumentation', () => { it('injects span context to records in named export', function () { // @ts-expect-error the same function reexported - if (!testInstrumentation.pino.pino) { + if (!testContext.pino.pino) { this.skip(); } - initTestContext(testInstrumentation, 'pino'); + initTestContext(testContext, 'pino'); const span = tracer.startSpan('abc'); context.with(trace.setSpan(context.active(), span), () => { testInjection(span, testContext); @@ -112,11 +109,11 @@ describe('PinoInstrumentation', () => { it('calls the users log hook', () => { const span = tracer.startSpan('abc'); - testInstrumentation.instrumentation.setConfig({ + testContext.instrumentation.setConfig({ enabled: true, logHook: (_span, record, level) => { record['resource.service.name'] = 'test-service'; - if (semver.satisfies(testInstrumentation.pino.version, '>= 7.9.0')) { + if (semver.satisfies(testContext.pino.version, '>= 7.9.0')) { assert.strictEqual(level, 30); } }, @@ -141,7 +138,7 @@ describe('PinoInstrumentation', () => { it('does not propagate exceptions from user hooks', () => { const span = tracer.startSpan('abc'); - testInstrumentation.instrumentation.setConfig({ + testContext.instrumentation.setConfig({ enabled: true, logHook: () => { throw new Error('Oops'); @@ -157,8 +154,7 @@ describe('PinoInstrumentation', () => { let stdoutSpy: sinon.SinonSpy; beforeEach(() => { - testInstrumentation = setupInstrumentation(); - testContext = initTestContext(testInstrumentation); + testContext = setupInstrumentationAndInitTestContext(); stdoutSpy = sinon.spy(process.stdout, 'write'); }); @@ -168,7 +164,7 @@ describe('PinoInstrumentation', () => { }); it('does not fail when constructing logger without arguments', () => { - testContext.logger = testInstrumentation.pino(); + testContext.logger = testContext.pino(); const span = tracer.startSpan('abc'); context.with(trace.setSpan(context.active(), span), () => { testContext.logger.info(kMessage); @@ -178,7 +174,7 @@ describe('PinoInstrumentation', () => { }); it('preserves user options and adds a mixin', () => { - testContext.logger = testInstrumentation.pino( + testContext.logger = testContext.pino( { name: 'LogLog' }, testContext.stream ); @@ -192,7 +188,7 @@ describe('PinoInstrumentation', () => { describe('binary arguments', () => { it('is possible to construct logger with undefined options', () => { - testContext.logger = testInstrumentation.pino( + testContext.logger = testContext.pino( undefined as unknown as Pino.LoggerOptions, testContext.stream ); @@ -203,7 +199,7 @@ describe('PinoInstrumentation', () => { }); it('preserves user mixins', () => { - testContext.logger = testInstrumentation.pino( + testContext.logger = testContext.pino( { name: 'LogLog', mixin: () => ({ a: 2, b: 'bar' }) }, testContext.stream ); @@ -218,7 +214,7 @@ describe('PinoInstrumentation', () => { }); it('ensures user mixin values take precedence', () => { - testContext.logger = testInstrumentation.pino( + testContext.logger = testContext.pino( { mixin() { return { trace_id: '123' };