diff --git a/package-lock.json b/package-lock.json index b3d86f0f4c..6ab3eb4f09 100644 --- a/package-lock.json +++ b/package-lock.json @@ -38725,7 +38725,6 @@ }, "devDependencies": { "@opentelemetry/api": "^1.3.0", - "@opentelemetry/context-async-hooks": "^1.8.0", "@opentelemetry/contrib-test-utils": "^0.40.0", "@opentelemetry/sdk-trace-base": "^1.8.0", "@opentelemetry/sdk-trace-node": "^1.8.0", @@ -47454,7 +47453,6 @@ "version": "file:plugins/node/opentelemetry-instrumentation-pino", "requires": { "@opentelemetry/api": "^1.3.0", - "@opentelemetry/context-async-hooks": "^1.8.0", "@opentelemetry/contrib-test-utils": "^0.40.0", "@opentelemetry/instrumentation": "^0.52.0", "@opentelemetry/sdk-trace-base": "^1.8.0", diff --git a/plugins/node/opentelemetry-instrumentation-pino/package.json b/plugins/node/opentelemetry-instrumentation-pino/package.json index 684b5a7e87..3d5bb458b1 100644 --- a/plugins/node/opentelemetry-instrumentation-pino/package.json +++ b/plugins/node/opentelemetry-instrumentation-pino/package.json @@ -45,7 +45,6 @@ }, "devDependencies": { "@opentelemetry/api": "^1.3.0", - "@opentelemetry/context-async-hooks": "^1.8.0", "@opentelemetry/contrib-test-utils": "^0.40.0", "@opentelemetry/sdk-trace-base": "^1.8.0", "@opentelemetry/sdk-trace-node": "^1.8.0", diff --git a/plugins/node/opentelemetry-instrumentation-pino/test/common.ts b/plugins/node/opentelemetry-instrumentation-pino/test/common.ts deleted file mode 100644 index 006f169e32..0000000000 --- a/plugins/node/opentelemetry-instrumentation-pino/test/common.ts +++ /dev/null @@ -1,121 +0,0 @@ -/* - * 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 }; -} diff --git a/plugins/node/opentelemetry-instrumentation-pino/test/pino-disabled.test.ts b/plugins/node/opentelemetry-instrumentation-pino/test/pino-disabled.test.ts deleted file mode 100644 index f8258db444..0000000000 --- a/plugins/node/opentelemetry-instrumentation-pino/test/pino-disabled.test.ts +++ /dev/null @@ -1,86 +0,0 @@ -/* - * 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); - }); - }); - }); -}); diff --git a/plugins/node/opentelemetry-instrumentation-pino/test/pino-enabled.test.ts b/plugins/node/opentelemetry-instrumentation-pino/test/pino-enabled.test.ts deleted file mode 100644 index 6262c1fdfe..0000000000 --- a/plugins/node/opentelemetry-instrumentation-pino/test/pino-enabled.test.ts +++ /dev/null @@ -1,310 +0,0 @@ -/* - * 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 semver from 'semver'; -import * as sinon from 'sinon'; - -import { INVALID_SPAN_CONTEXT, context, trace } from '@opentelemetry/api'; -import { - InMemorySpanExporter, - SimpleSpanProcessor, -} from '@opentelemetry/sdk-trace-base'; -import { - TestInstrumentationAndContext, - assertInjection, - assertRecord, - initTestContext, - kMessage, - setupInstrumentationAndInitTestContext, - testInjection, - testNoInjection, -} from './common'; -import { - runTestFixture, - TestCollector, -} from '@opentelemetry/contrib-test-utils'; - -import { AsyncHooksContextManager } from '@opentelemetry/context-async-hooks'; -import { NodeTracerProvider } from '@opentelemetry/sdk-trace-node'; -import type { pino as Pino } from 'pino'; - -const memoryExporter = new InMemorySpanExporter(); -const provider = new NodeTracerProvider(); -const tracer = provider.getTracer('default'); -provider.addSpanProcessor(new SimpleSpanProcessor(memoryExporter)); -context.setGlobalContextManager(new AsyncHooksContextManager()); - -describe('PinoInstrumentation', () => { - let testContext: TestInstrumentationAndContext; - - describe('enabled instrumentation', () => { - beforeEach(() => { - testContext = setupInstrumentationAndInitTestContext(); - }); - - it('injects span context to records', () => { - const span = tracer.startSpan('abc'); - context.with(trace.setSpan(context.active(), span), () => { - testInjection(span, testContext); - }); - }); - - it('injects span context to records with custom keys', () => { - const logKeys = { - traceId: 'traceId', - spanId: 'spanId', - traceFlags: 'traceFlags', - }; - - testContext = setupInstrumentationAndInitTestContext({ logKeys }); - - const span = tracer.startSpan('abc'); - context.with(trace.setSpan(context.active(), span), () => { - testInjection(span, testContext, logKeys); - }); - }); - - it('injects span context to records in default export', function () { - // @ts-expect-error the same function reexported - if (!testContext.pino.default) { - this.skip(); - } - initTestContext(testContext, 'default'); - const span = tracer.startSpan('abc'); - context.with(trace.setSpan(context.active(), span), () => { - testInjection(span, testContext); - }); - }); - - it('injects span context to records in named export', function () { - // @ts-expect-error the same function reexported - if (!testContext.pino.pino) { - this.skip(); - } - initTestContext(testContext, 'pino'); - const span = tracer.startSpan('abc'); - context.with(trace.setSpan(context.active(), 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 = testContext.logger.child({ foo: 42 }); - child.info(kMessage); - assertInjection(span, testContext); - }); - }); - - it('calls the users log hook', () => { - const span = tracer.startSpan('abc'); - testContext.instrumentation.setConfig({ - enabled: true, - logHook: (_span, record, level) => { - record['resource.service.name'] = 'test-service'; - if (semver.satisfies(testContext.pino.version, '>= 7.9.0')) { - assert.strictEqual(level, 30); - } - }, - }); - context.with(trace.setSpan(context.active(), 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(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(testContext); - }); - }); - - it('does not propagate exceptions from user hooks', () => { - const span = tracer.startSpan('abc'); - testContext.instrumentation.setConfig({ - enabled: true, - logHook: () => { - throw new Error('Oops'); - }, - }); - context.with(trace.setSpan(context.active(), span), () => { - testInjection(span, testContext); - }); - }); - }); - - describe('logger construction', () => { - let stdoutSpy: sinon.SinonSpy; - - beforeEach(() => { - testContext = setupInstrumentationAndInitTestContext(); - - stdoutSpy = sinon.spy(process.stdout, 'write'); - }); - - afterEach(() => { - stdoutSpy.restore(); - }); - - it('does not fail when constructing logger without arguments', () => { - testContext.logger = testContext.pino(); - const span = tracer.startSpan('abc'); - context.with(trace.setSpan(context.active(), span), () => { - testContext.logger.info(kMessage); - }); - const record = JSON.parse(stdoutSpy.firstCall.args[0].toString()); - assertRecord(record, span); - }); - - it('preserves user options and adds a mixin', () => { - testContext.logger = testContext.pino( - { name: 'LogLog' }, - testContext.stream - ); - - const span = tracer.startSpan('abc'); - context.with(trace.setSpan(context.active(), span), () => { - const record = testInjection(span, testContext); - assert.strictEqual(record['name'], 'LogLog'); - }); - }); - - describe('binary arguments', () => { - it('is possible to construct logger with undefined options', () => { - testContext.logger = testContext.pino( - undefined as unknown as Pino.LoggerOptions, - testContext.stream - ); - const span = tracer.startSpan('abc'); - context.with(trace.setSpan(context.active(), span), () => { - testInjection(span, testContext); - }); - }); - - it('preserves user mixins', () => { - testContext.logger = testContext.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, testContext); - assert.strictEqual(record['a'], 2); - assert.strictEqual(record['b'], 'bar'); - assert.strictEqual(record['name'], 'LogLog'); - }); - }); - - it('ensures user mixin values take precedence', () => { - testContext.logger = testContext.pino( - { - mixin() { - return { trace_id: '123' }; - }, - }, - testContext.stream - ); - - const span = tracer.startSpan('abc'); - context.with(trace.setSpan(context.active(), span), () => { - testContext.logger.info(kMessage); - }); - - const record = JSON.parse( - testContext.writeSpy.firstCall.args[0].toString() - ); - assert.strictEqual(record['trace_id'], '123'); - }); - }); - }); - - describe('ESM usage', () => { - it('should work with ESM default import', async function () { - testContext = setupInstrumentationAndInitTestContext(); - let logRecords: any[]; - await runTestFixture({ - cwd: __dirname, - argv: ['fixtures/use-pino-default-import.mjs'], - env: { - NODE_OPTIONS: - '--experimental-loader=@opentelemetry/instrumentation/hook.mjs', - NODE_NO_WARNINGS: '1', - }, - checkResult: (err, stdout, _stderr) => { - assert.ifError(err); - logRecords = stdout - .trim() - .split('\n') - .map(ln => JSON.parse(ln)); - assert.strictEqual(logRecords.length, 1); - }, - checkCollector: (collector: TestCollector) => { - // Check that both log records had the trace-context of the span injected. - const spans = collector.sortedSpans; - assert.strictEqual(spans.length, 1); - logRecords.forEach(rec => { - assert.strictEqual(rec.trace_id, spans[0].traceId); - assert.strictEqual(rec.span_id, spans[0].spanId); - }); - }, - }); - }); - - it('should work with ESM named import', async function () { - if (semver.lt(testContext.pino.version, '6.8.0')) { - // Pino 6.8.0 added named ESM exports (https://github.com/pinojs/pino/pull/936). - this.skip(); - } else { - let logRecords: any[]; - await runTestFixture({ - cwd: __dirname, - argv: ['fixtures/use-pino-named-import.mjs'], - env: { - NODE_OPTIONS: - '--experimental-loader=@opentelemetry/instrumentation/hook.mjs', - NODE_NO_WARNINGS: '1', - }, - checkResult: (err, stdout, _stderr) => { - assert.ifError(err); - logRecords = stdout - .trim() - .split('\n') - .map(ln => JSON.parse(ln)); - assert.strictEqual(logRecords.length, 1); - }, - checkCollector: (collector: TestCollector) => { - // Check that both log records had the trace-context of the span injected. - const spans = collector.sortedSpans; - assert.strictEqual(spans.length, 1); - logRecords.forEach(rec => { - assert.strictEqual(rec.trace_id, spans[0].traceId); - assert.strictEqual(rec.span_id, spans[0].spanId); - }); - }, - }); - } - }); - }); -}); diff --git a/plugins/node/opentelemetry-instrumentation-pino/test/pino.test.ts b/plugins/node/opentelemetry-instrumentation-pino/test/pino.test.ts new file mode 100644 index 0000000000..4b0936452d --- /dev/null +++ b/plugins/node/opentelemetry-instrumentation-pino/test/pino.test.ts @@ -0,0 +1,432 @@ +/* + * 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 { Writable } from 'stream'; + +import * as semver from 'semver'; +import * as sinon from 'sinon'; +import { INVALID_SPAN_CONTEXT, context, trace, Span } from '@opentelemetry/api'; +import { + InMemorySpanExporter, + SimpleSpanProcessor, +} from '@opentelemetry/sdk-trace-base'; +import { NodeTracerProvider } from '@opentelemetry/sdk-trace-node'; +import { + runTestFixture, + TestCollector, +} from '@opentelemetry/contrib-test-utils'; + +import { PinoInstrumentation, PinoInstrumentationConfig } from '../src'; + +import type { pino as Pino } from 'pino'; + +const tracerProvider = new NodeTracerProvider(); +tracerProvider.register(); +tracerProvider.addSpanProcessor( + new SimpleSpanProcessor(new InMemorySpanExporter()) +); +const tracer = tracerProvider.getTracer('default'); + +const instrumentation = new PinoInstrumentation(); +const pino = require('pino'); + +describe('PinoInstrumentation', () => { + describe('disabled instrumentation', () => { + let logger: Pino.Logger; + let stream: Writable; + let writeSpy: sinon.SinonSpy; + + beforeEach(() => { + instrumentation.disable(); + stream = new Writable(); + stream._write = () => {}; + writeSpy = sinon.spy(stream, 'write'); + logger = pino(stream); + }); + + after(() => { + instrumentation.enable(); + }); + + it('does not inject span context', () => { + tracer.startActiveSpan('abc', span => { + logger.info('a message'); + span.end(); + + sinon.assert.calledOnce(writeSpy); + const record = JSON.parse(writeSpy.firstCall.args[0].toString()); + assert.strictEqual(record['msg'], 'a message'); + assert.strictEqual(record['trace_id'], undefined); + assert.strictEqual(record['span_id'], undefined); + assert.strictEqual(record['trace_flags'], undefined); + }); + }); + + it('does not call log hook', () => { + instrumentation.setConfig({ + enabled: false, + logHook: (_span, record) => { + record['resource.service.name'] = 'test-service'; + }, + }); + tracer.startActiveSpan('abc', span => { + logger.info('a message'); + span.end(); + + sinon.assert.calledOnce(writeSpy); + const record = JSON.parse(writeSpy.firstCall.args[0].toString()); + assert.strictEqual(record['resource.service.name'], undefined); + }); + }); + + it('injects span context once re-enabled', () => { + instrumentation.enable(); + tracer.startActiveSpan('abc', span => { + logger.info('a message'); + span.end(); + + sinon.assert.calledOnce(writeSpy); + const record = JSON.parse(writeSpy.firstCall.args[0].toString()); + assertRecord(record, span); + }); + }); + }); + + describe('log correlation', () => { + let logger: Pino.Logger; + let stream: Writable; + let writeSpy: sinon.SinonSpy; + + beforeEach(() => { + instrumentation.setConfig({}); // reset to defaults + stream = new Writable(); + stream._write = () => {}; + writeSpy = sinon.spy(stream, 'write'); + logger = pino(stream); + }); + + it('injects span context to records', () => { + tracer.startActiveSpan('abc', span => { + logger.info('a message'); + span.end(); + + sinon.assert.calledOnce(writeSpy); + const record = JSON.parse(writeSpy.firstCall.args[0].toString()); + assertRecord(record, span); + assert.strictEqual(record['msg'], 'a message'); + }); + }); + + it('injects span context to records with custom keys', () => { + const logKeys = { + traceId: 'traceId', + spanId: 'spanId', + traceFlags: 'traceFlags', + }; + instrumentation.setConfig({ logKeys }); + tracer.startActiveSpan('abc', span => { + logger.info('a message'); + span.end(); + + sinon.assert.calledOnce(writeSpy); + const record = JSON.parse(writeSpy.firstCall.args[0].toString()); + assertRecord(record, span, logKeys); + assert.strictEqual(record['trace_id'], undefined); + assert.strictEqual(record['span_id'], undefined); + assert.strictEqual(record['trace_flags'], undefined); + assert.strictEqual(record['msg'], 'a message'); + }); + }); + + it('injects span context to child logger records', () => { + const child = logger.child({ childField: 42 }); + tracer.startActiveSpan('abc', span => { + child.info('a message'); + span.end(); + + sinon.assert.calledOnce(writeSpy); + const record = JSON.parse(writeSpy.firstCall.args[0].toString()); + assertRecord(record, span); + assert.strictEqual(record['msg'], 'a message'); + assert.strictEqual(record['childField'], 42); + }); + }); + + it('does not inject span context if no span is active', () => { + assert.strictEqual(trace.getSpan(context.active()), undefined); + + logger.info('a message'); + + 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); + }); + + 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), () => { + logger.info('a message'); + + 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); + }); + }); + + it('calls the logHook', () => { + instrumentation.setConfig({ + logHook: (_span, record, level) => { + record['resource.service.name'] = 'test-service'; + if (semver.satisfies(pino.version, '>=7.9.0')) { + assert.strictEqual(level, 30); + } + }, + }); + + tracer.startActiveSpan('abc', span => { + logger.info('a message'); + span.end(); + + sinon.assert.calledOnce(writeSpy); + const record = JSON.parse(writeSpy.firstCall.args[0].toString()); + assertRecord(record, span); + assert.strictEqual(record['resource.service.name'], 'test-service'); + }); + }); + + it('does not propagate exceptions from logHook', () => { + instrumentation.setConfig({ + logHook: (_span, record, level) => { + throw new Error('Oops'); + }, + }); + tracer.startActiveSpan('abc', span => { + logger.info('a message'); + span.end(); + + sinon.assert.calledOnce(writeSpy); + const record = JSON.parse(writeSpy.firstCall.args[0].toString()); + assertRecord(record, span); + }); + }); + + it('instrumentation of `pino.default(...)` works', function () { + if (!pino.default) { + this.skip(); + } + logger = pino.default(stream); + + tracer.startActiveSpan('abc', span => { + logger.info('a message'); + span.end(); + + const { traceId, spanId } = span.spanContext(); + sinon.assert.calledOnce(writeSpy); + const record = JSON.parse(writeSpy.firstCall.args[0].toString()); + assert.strictEqual(record['trace_id'], traceId); + assert.strictEqual(record['span_id'], spanId); + }); + }); + + it('instrumentation of `pino.pino(...)` works', function () { + if (!pino.default) { + this.skip(); + } + logger = pino.pino(stream); + + tracer.startActiveSpan('abc', span => { + logger.info('a message'); + span.end(); + + const { traceId, spanId } = span.spanContext(); + sinon.assert.calledOnce(writeSpy); + const record = JSON.parse(writeSpy.firstCall.args[0].toString()); + assert.strictEqual(record['trace_id'], traceId); + assert.strictEqual(record['span_id'], spanId); + }); + }); + }); + + describe('logger construction', () => { + let stdoutSpy: sinon.SinonSpy; + + beforeEach(() => { + instrumentation.setConfig({}); // reset to defaults + stdoutSpy = sinon.spy(process.stdout, 'write'); + }); + + afterEach(() => { + stdoutSpy.restore(); + }); + + it('`pino()` with no args works', () => { + const logger = pino(); + tracer.startActiveSpan('abc', span => { + logger.info('a message'); + span.end(); + + const record = JSON.parse(stdoutSpy.firstCall.args[0].toString()); + assertRecord(record, span); + }); + }); + + it('`pino(options)` works', () => { + const logger = pino({ name: 'LogLog' }); + tracer.startActiveSpan('abc', span => { + logger.info('a message'); + span.end(); + + const record = JSON.parse(stdoutSpy.firstCall.args[0].toString()); + assertRecord(record, span); + assert.strictEqual(record['name'], 'LogLog'); + }); + }); + + it('`pino(undefined, stream)` works', () => { + const logger = pino(undefined, process.stdout); + tracer.startActiveSpan('abc', span => { + logger.info('a message'); + span.end(); + + const record = JSON.parse(stdoutSpy.firstCall.args[0].toString()); + assertRecord(record, span); + }); + }); + + it('preserves user mixins', () => { + const logger = pino( + { name: 'LogLog', mixin: () => ({ a: 2, b: 'bar' }) }, + process.stdout + ); + tracer.startActiveSpan('abc', span => { + logger.info('a message'); + span.end(); + + const record = JSON.parse(stdoutSpy.firstCall.args[0].toString()); + assertRecord(record, span); + assert.strictEqual(record['a'], 2); + assert.strictEqual(record['b'], 'bar'); + assert.strictEqual(record['name'], 'LogLog'); + }); + }); + + it('ensures user mixin values take precedence', () => { + const logger = pino( + { + mixin() { + return { trace_id: '123' }; + }, + }, + process.stdout + ); + tracer.startActiveSpan('abc', span => { + logger.info('a message'); + span.end(); + + const { spanId } = span.spanContext(); + const record = JSON.parse(stdoutSpy.firstCall.args[0].toString()); + assert.strictEqual(record['trace_id'], '123'); + assert.strictEqual(record['span_id'], spanId); + }); + }); + }); + + describe('ESM usage', () => { + it('should work with ESM default import', async function () { + let logRecords: any[]; + await runTestFixture({ + cwd: __dirname, + argv: ['fixtures/use-pino-default-import.mjs'], + env: { + NODE_OPTIONS: + '--experimental-loader=@opentelemetry/instrumentation/hook.mjs', + NODE_NO_WARNINGS: '1', + }, + checkResult: (err, stdout, _stderr) => { + assert.ifError(err); + logRecords = stdout + .trim() + .split('\n') + .map(ln => JSON.parse(ln)); + assert.strictEqual(logRecords.length, 1); + }, + checkCollector: (collector: TestCollector) => { + // Check that both log records had the trace-context of the span injected. + const spans = collector.sortedSpans; + assert.strictEqual(spans.length, 1); + logRecords.forEach(rec => { + assert.strictEqual(rec.trace_id, spans[0].traceId); + assert.strictEqual(rec.span_id, spans[0].spanId); + }); + }, + }); + }); + + it('should work with ESM named import', async function () { + if (semver.lt(pino.version, '6.8.0')) { + // Pino 6.8.0 added named ESM exports (https://github.com/pinojs/pino/pull/936). + this.skip(); + } else { + let logRecords: any[]; + await runTestFixture({ + cwd: __dirname, + argv: ['fixtures/use-pino-named-import.mjs'], + env: { + NODE_OPTIONS: + '--experimental-loader=@opentelemetry/instrumentation/hook.mjs', + NODE_NO_WARNINGS: '1', + }, + checkResult: (err, stdout, _stderr) => { + assert.ifError(err); + logRecords = stdout + .trim() + .split('\n') + .map(ln => JSON.parse(ln)); + assert.strictEqual(logRecords.length, 1); + }, + checkCollector: (collector: TestCollector) => { + // Check that both log records had the trace-context of the span injected. + const spans = collector.sortedSpans; + assert.strictEqual(spans.length, 1); + logRecords.forEach(rec => { + assert.strictEqual(rec.trace_id, spans[0].traceId); + assert.strictEqual(rec.span_id, spans[0].spanId); + }); + }, + }); + } + }); + }); +}); + +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)}` + ); +}