Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Merged
merged 10 commits into from
Jan 7, 2024
Merged

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

Show file tree
Hide file tree
Changes from 1 commit
Commits
Show all changes
10 commits
Select commit Hold shift + click to select a range
8be98f4
Allow configuring pino to log with different keys
drewcorlin1 Dec 17, 2023
8a5009a
Update README and add jsdoc
drewcorlin1 Dec 18, 2023
d918f92
Still have 2 failing tests
drewcorlin1 Dec 18, 2023
8a4bb4a
Break tests out
drewcorlin1 Dec 20, 2023
359d726
Return test context
drewcorlin1 Dec 21, 2023
96e2986
Simplify
drewcorlin1 Dec 21, 2023
41d6a3a
Merge branch 'main' into pino-keys
drewcorlin1 Dec 28, 2023
991545f
Merge branch 'main' into pino-keys
blumamir Dec 31, 2023
a0362f1
Merge branch 'main' into pino-keys
drewcorlin1 Jan 4, 2024
b179e33
Merge branch 'main' into pino-keys
pichlermarc Jan 5, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
9 changes: 8 additions & 1 deletion plugins/node/opentelemetry-instrumentation-pino/README.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Flarna marked this conversation as resolved.
Show resolved Hide resolved
logKeys: {
traceId: 'traceId',
spanId: 'spanId',
traceFlags: 'traceFlags',
},
}),
// other instrumentations
Expand Down
14 changes: 11 additions & 3 deletions plugins/node/opentelemetry-instrumentation-pino/src/instrumentation.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand Down Expand Up @@ -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);
Expand Down
5 changes: 5 additions & 0 deletions plugins/node/opentelemetry-instrumentation-pino/src/types.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -26,4 +26,9 @@ export type LogHookFunction = (

export interface PinoInstrumentationConfig extends InstrumentationConfig {
logHook?: LogHookFunction;
logKeys?: {
traceId: string;
spanId: string;
traceFlags: string;
};
}
55 changes: 44 additions & 11 deletions plugins/node/opentelemetry-instrumentation-pino/test/pino.test.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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();
Expand All @@ -37,31 +37,50 @@ 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;
let pino: typeof Pino;
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() {
Expand All @@ -87,10 +106,16 @@ describe('PinoInstrumentation', () => {
}
}

before(() => {
instrumentation = new PinoInstrumentation();
function setup() {
instrumentation = new PinoInstrumentation({
logKeys,
});
instrumentation.enable();
pino = require('pino');
}

before(() => {
setup();
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If I understand this correct this causes that all tests below use the new keys, not just the new injects span context to records with custom keys test.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That's right. I was having trouble configuring just one test independently of the others with the current setup. I can spend a bit more time on it

Copy link
Contributor Author

@drewcorlin1 drewcorlin1 Dec 18, 2023 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Cleaned them up so that the logKeys config only applies to a single test but the tests are interfering with each other causing the "disabled instrumentation" block of tests to fail. If I comment out all the other describe blocks then they pass. I'm stumped at the moment but will revisit this in the next couple days

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Seems like the pino tests were written in a way to instrument just once and then run all tests.
Don't know if there was a reason. Theoretically .disable() should cause to de-instrument and therefore should allow side effect free tests.
But there might be cases where de-instrument doesn't work, e.g. if pino caches some stuff internal.

Copy link
Contributor Author

@drewcorlin1 drewcorlin1 Dec 18, 2023 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I definitely don't have a perfect understanding of this patching, but I tried creating a new instrumentation + explicitly calling enable() on it as well as clearing the require cache via delete require.cache[require.resolve('pino')] but it made no difference. Would love to hear alternatives to try as welll

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I broke the enabled + disabled tests out into their own modules to skirt the problem. Let me know what you think

});

describe('enabled instrumentation', () => {
Expand All @@ -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) {
Expand Down
Loading