feat(tracing): added hook to integrate with pino logger (#17)

* feat(tracing): added hook to integrate with pino logger

* refactor(tracing): simplified building the args for the logfn

* test(tracing): removed code duplication from tests

package.json

@@ -45,17 +45,21 @@
     "@opentelemetry/metrics": "^0.18.2",
     "@opentelemetry/node": "^0.18.2",
     "@opentelemetry/tracing": "^0.18.2",
+    "@types/pino": "^6.3.7",
     "env-var": "^7.0.0"
   },
   "devDependencies": {
     "@commitlint/cli": "^11.0.0",
     "@commitlint/config-conventional": "^11.0.0",
     "@map-colonies/eslint-config": "^2.2.0",
+    "@opentelemetry/context-async-hooks": "^0.18.2",
+    "@types/faker": "^5.5.3",
     "@types/jest": "^26.0.19",
     "@types/node": "^14.14.12",
     "commitlint": "^11.0.0",
     "cz-conventional-changelog": "^3.3.0",
     "eslint": "^7.8.1",
+    "faker": "^5.5.3",
     "husky": "^4.3.5",
     "jest": "^26.6.3",
     "jest-create-mock-instance": "^1.1.0",
@@ -65,6 +69,6 @@
     "standard-version": "^9.0.0",
     "ts-jest": "^26.4.4",
     "ts-node": "^9.1.1",
-    "typescript": "^3.8.3"
+    "typescript": "^4.2.4"
   }
 }

src/tracing/index.ts

@@ -1 +1,2 @@
 export { Tracing } from './tracing';
+export { logMethod } from './loggerHook';

src/tracing/loggerHook.ts

@@ -0,0 +1,28 @@
+import { getSpan, context } from '@opentelemetry/api';
+import { LogFn, Logger } from 'pino';
+
+// ignored because its the same type needed for LogFn
+// eslint-disable-next-line @typescript-eslint/ban-types, @typescript-eslint/no-explicit-any
+export type LogFnArgs = [obj: object, msg?: string, ...args: any[]] | [msg: string, ...args: any[]];
+
+// disabled because this function signature is required by pino
+// eslint-disable-next-line @typescript-eslint/no-unused-vars
+export function logMethod(this: Logger, args: LogFnArgs, method: LogFn, level: number): void {
+  const span = getSpan(context.active());
+
+  if (!span) {
+    method.apply<Logger, LogFnArgs, void>(this, args);
+    return;
+  }
+  const traceObj = { spanId: span.context().spanId, traceId: span.context().traceId };
+
+  let logFnArgs: LogFnArgs;
+  const [firstArg, ...rest] = args;
+  if (typeof firstArg === 'object') {
+    logFnArgs = [{ ...firstArg, ...traceObj }, ...rest];
+  } else {
+    logFnArgs = [traceObj, firstArg, ...rest];
+  }
+
+  method.apply<Logger, LogFnArgs, void>(this, logFnArgs);
+}

src/tracing/tracing.ts

@@ -3,6 +3,7 @@ import { CollectorTraceExporter } from '@opentelemetry/exporter-collector';
 import { SimpleSpanProcessor } from '@opentelemetry/tracing';
 import { InstrumentationOption, registerInstrumentations } from '@opentelemetry/instrumentation';
 import { NoopTracerProvider, Tracer } from '@opentelemetry/api';
+import { AsyncHooksContextManager } from '@opentelemetry/context-async-hooks';
 import { TelemetryBase } from '../common/interfaces';
 import { getTracingConfig, TracingConfig } from './config';
 
@@ -33,7 +34,7 @@ export class Tracing implements TelemetryBase<Tracer> {
 
     // consider batch processor
     this.provider.addSpanProcessor(new SimpleSpanProcessor(exporter));
-    this.provider.register();
+    this.provider.register({ contextManager: new AsyncHooksContextManager() });
 
     return this.provider.getTracer(this.tracerName);
   }

tests/configurations/jest.config.js

@@ -12,7 +12,7 @@ module.exports = {
     'default',
     ['jest-html-reporters', { multipleReportsUnitePath: './reports', pageTitle: 'tests', publicPath: './reports', filename: 'tests.html' }],
   ],
-  collectCoverageFrom: ['<rootDir>/src/**/*.ts', '!**/node_modules/**', '!**/vendor/**'],
+  collectCoverageFrom: ['<rootDir>/src/**/*.ts', '!**/node_modules/**', '!**/vendor/**', '!<rootDir>/src/metrics/meterWrapper.ts'],
   coverageDirectory: '<rootDir>/coverage',
   coverageReporters: ['text-summary', 'html', 'json'],
   coverageThreshold: {

tests/tracing/loggerHook.spec.ts

@@ -0,0 +1,64 @@
+import { trace, context, setSpan, Tracer } from '@opentelemetry/api';
+import { NodeTracerProvider } from '@opentelemetry/node';
+import * as faker from 'faker';
+import { AsyncHooksContextManager } from '@opentelemetry/context-async-hooks';
+import { LogFn, Logger } from 'pino';
+import { logMethod } from '../../src';
+import { LogFnArgs } from '../../src/tracing/loggerHook';
+
+describe('#logMethod', () => {
+  let provider: NodeTracerProvider;
+  let tracer: Tracer;
+
+  beforeAll(() => {
+    provider = new NodeTracerProvider();
+    provider.register({ contextManager: new AsyncHooksContextManager() });
+    tracer = trace.getTracer('test_tracer');
+  });
+
+  afterAll(async () => {
+    await provider.shutdown();
+  });
+
+  it('should call the method with the same args if tracer is not enabled', () => {
+    const args = [faker.random.word()] as [string];
+    const logFn = jest.fn();
+
+    logMethod.apply(({} as unknown) as Logger, [args, logFn, 5]);
+
+    expect(logFn).toHaveBeenLastCalledWith(...args);
+  });
+
+  it('should add traceId and spanId when logging only msg', () => {
+    const args = [faker.random.word()] as [string];
+    const logFn = jest.fn();
+
+    const span = tracer.startSpan('test_span');
+    const ctx = setSpan(context.active(), span);
+
+    context.with<[LogFnArgs, LogFn, number], typeof logMethod>(ctx, logMethod, ({} as unknown) as Logger, args, logFn, 5);
+
+    span.end();
+
+    const { spanId, traceId } = span.context();
+    expect(logFn).toHaveBeenLastCalledWith({ spanId, traceId }, ...args);
+  });
+
+  it('should add traceId and spanId to the logging only obj', () => {
+    // pino logfn uses the type object
+    // eslint-disable-next-line @typescript-eslint/ban-types
+    const args = [{ test: faker.random.word() }, faker.random.word()] as [object, string];
+    const logFn = jest.fn();
+
+    const span = tracer.startSpan('test_span');
+    const ctx = setSpan(context.active(), span);
+
+    context.with<[LogFnArgs, LogFn, number], typeof logMethod>(ctx, logMethod, ({} as unknown) as Logger, args, logFn, 5);
+
+    span.end();
+
+    const { spanId, traceId } = span.context();
+    const [obj, ...rest] = args;
+    expect(logFn).toHaveBeenLastCalledWith({ spanId, traceId, ...obj }, ...rest);
+  });
+});

tests/tracing/tracing.spec.ts

@@ -22,14 +22,6 @@ describe('tracing', function () {
     await expect(tracing.stop()).resolves.toBeUndefined();
   });
 
-  it('should return an error if url is not configured', function () {
-    process.env.TELEMETRY_TRACING_ENABLED = 'true';
-
-    const action = () => new Tracing('test');
-
-    expect(action).toThrow('env-var: "TELEMETRY_TRACING_URL" is a required variable, but it was not set');
-  });
-
   it('should return a tracer if everything is configured', async function () {
     process.env.TELEMETRY_TRACING_ENABLED = 'true';
     process.env.TELEMETRY_TRACING_URL = 'http://localhost:55681/v1/trace';