pino-instrumentation not injecting trace_id into logs when used with TypeScript

[armandAkop]

What version of OpenTelemetry are you using?

    "@opentelemetry/auto-instrumentations-node": "^0.25.0",
    "@opentelemetry/core": "^1.0.1",
    "@opentelemetry/exporter-collector": "^0.24.0",
    "@opentelemetry/exporter-prometheus": "^0.18.2",
    "@opentelemetry/instrumentation": "^0.24.0",
    "@opentelemetry/instrumentation-pino": "^0.28.1",
    "@opentelemetry/metrics": "^0.18.2",
    "@opentelemetry/node": "^0.24.0",
    "@opentelemetry/propagator-b3": "^1.0.0",
    "@opentelemetry/resources": "^0.18.2",
    "@opentelemetry/sdk-trace-node": "^1.0.1",
    "@opentelemetry/semantic-conventions": "^1.0.0",
    "pino": "^7.6.4",
   "express": "^4.17.1",
  "my-logger": "file: ../my-logger"

What version of Node are you using?

v16.6.1

What did you do?

"my-logger" is a separate typescript project on my machine, here is the simple implementation which instantiates an instance of pino and exports as default. https://gist.github.com/armandAkop/3e064c2e378cdd8a442b339f3b5e28f6

I am running "tsc" in the repo and outputting the transpiled file to "dist/index.js", which contains

"use strict";
Object.defineProperty(exports, "__esModule", { value: true });
const pino_1 = require("pino");
const logger = pino_1.pino;
exports.default = (0, pino_1.pino)();
//# sourceMappingURL=index.js.map

Here is the script I am testing with auto-instrumentation-node and pino-instrumentation. This script lives in a folder called project-A and has a local reference to "my-logger" project on line 157 https://gist.github.com/armandAkop/d2fb6f806b31b6844262918489bf0679

What did you expect to see?

I expected my test scripts log entry to contain the trace_id field

What did you see instead?

trace_id is not present in the log message. When I change the my-logger project to be a regular Javascript project with an index.js which looks like

module.exports = require('pino')();

AND changed package.json to "main" property to "main": "index.js"

The trace_id appears in the log as expected

Additional context

[Flarna]

Not sure if this is the root cause but there is quite a mix/max of older and newer versions of the various otel packages. There is a compatibility matrix - which is unfortunately not completely up to date.

I recommend to retry with latest versions of the packages and keeping the compat matrix in mind.

[armandAkop]

Not sure if this is the root cause but there is quite a mix/max of older and newer versions of the various otel packages. There is a compatibility matrix - which is unfortunately not completely up to date.

I recommend to retry with latest versions of the packages and keeping the compat matrix in mind.

Tried a few combinations but still wasn't able to find a working version. Even the basic example on the README of instrumentation-pino is not working. @politician would you happen to know what versions I could try that would give me the best luck?

Dependencies

  "dependencies": {
    "@opentelemetry/instrumentation": "^0.27.0",
    "@opentelemetry/instrumentation-pino": "^0.28.1",
    "@opentelemetry/sdk-trace-node": "^1.0.1",
    "pino": "^7.6.4"
  }

index.js

const { NodeTracerProvider } = require('@opentelemetry/sdk-trace-node');
const { PinoInstrumentation } = require('@opentelemetry/instrumentation-pino');
const { registerInstrumentations } = require('@opentelemetry/instrumentation');

const provider = new NodeTracerProvider();
provider.register();

registerInstrumentations({
  instrumentations: [
    new PinoInstrumentation({
      // Optional hook to insert additional context to log object.
      logHook: (span, record) => {
        record['resource.service.name'] = provider.resource.attributes['service.name'];
      },
    }),
    // other instrumentations
  ],
});

const pino = require('pino');
const logger = pino();
logger.info('foobar'); // outputs only {"level":30,"time":1643311923234,"pid":93489,"hostname":"johndoe","msg":"foobar"}

[Flarna]

Could you try to replace import { pino } from 'pino' by import pino = require('pino') in your code?

And please note that you will see only a traceId in the logs if you log in the context of an active span otherwise there is no traceId to log.

[armandAkop]

Could you try to replace import { pino } from 'pino' by import pino = require('pino') in your code?

And please note that you will see only a traceId in the logs if you log in the context of an active span otherwise there is no traceId to log.

Tried the first recommendation, no avail.

Manually creating a span doesn't seem to work either

const { NodeTracerProvider } = require('@opentelemetry/sdk-trace-node');
const { PinoInstrumentation } = require('@opentelemetry/instrumentation-pino');
const { registerInstrumentations } = require('@opentelemetry/instrumentation');
const opentelemetry = require('@opentelemetry/api');

const provider = new NodeTracerProvider();
provider.register();

registerInstrumentations({
  instrumentations: [
    new PinoInstrumentation({
      // Optional hook to insert additional context to log object.
      logHook: (span, record) => {
        record['resource.service.name'] = provider.resource.attributes['service.name'];
      },
    }),
    // other instrumentations
  ],
});

const logger = require('pino')();
const tracer = opentelemetry.trace.getTracer('example-basic-tracer-node');
const parent = tracer.startSpan('init');
for (let i = 0; i < 3; i++) {
  logger.info(`expect trace_id to be in this log ${i}`);
}
parent.end();

Output in my terminal

{"level":30,"time":1643315253091,"pid":95282,"hostname":"johndoe","msg":"expect trace_id to be in this log 0"}
{"level":30,"time":1643315253092,"pid":95282,"hostname":"johndoe","msg":"expect trace_id to be in this log 1"}
{"level":30,"time":1643315253092,"pid":95282,"hostname":"johndoe","msg":"expect trace_id to be in this log 2"}

Console Span Exporter

{
  traceId: '41a935b0ad8272ab5e81dd65096dfdf4',
  parentId: undefined,
  name: 'init',
  id: '2015e92bb9bb914d',
  kind: 0,
  timestamp: 1643315446739236,
  duration: 846,
  attributes: {},
  status: { code: 0 },
  events: []
}

[Flarna]

The created span is not set as active therefore the pino instrumenation will not see it. Try the following:

tracer.startActiveSpan('init', (span) => {
    for (let i = 0; i < 3; i++) {
    logger.info(`expect trace_id to be in this log ${i}`);
    }
    span.end();
});

if you log within an HTTP request (and add HTTP instrumentation) it works without any manual span creation as the instrumentation is doing this for you.

const http = require('http')
http.createServer((req, res) => {
    logger.info(`inside HTTP request`);
    res.end();
}).listen(8000, () => {
    http.get({ port: 8000 });
});

important is that require('http') is done after the HttpInstrumenation has been created/registered.

[armandAkop]

That seemed to do the trick, but still the original problem still persists unfortunately. Really not sure why a TypeScript implementation screws with the functionality

[Flarna]

Ported to typescript and there seems to be a bug in the instrumentation resulting in non working setups depending on how you import and if esModuleInterop is set in tsconfig.js. see below for details.

import { NodeTracerProvider } from '@opentelemetry/sdk-trace-node';
import { PinoInstrumentation } from '@opentelemetry/instrumentation-pino';
import { registerInstrumentations } from '@opentelemetry/instrumentation';
import * as opentelemetry from '@opentelemetry/api';

const provider = new NodeTracerProvider();
provider.register();

registerInstrumentations({
  instrumentations: [
    new PinoInstrumentation({
      // Optional hook to insert additional context to log object.
      logHook: (span, record) => {
        record['resource.service.name'] = provider.resource.attributes['service.name'];
      },
    }),
    // other instrumentations
  ],
});

// ok
import pino = require('pino');
const logger = (pino as any)();

// not ok
//import { pino } from 'pino';
//const logger = pino();

// ok if "esModuleInterop": true is in tsconfig.js
//import pino from 'pino';
//const logger = pino();

const tracer = opentelemetry.trace.getTracer('example-basic-tracer-node');
tracer.startActiveSpan('init', (span) => {
    for (let i = 0; i < 3; i++) {
        logger.info(`expect trace_id to be in this log ${i}`);
    }
    span.end();
});

root cause is that pino exports itself several times:

• the export object itself (case const pino = require('pino')
• as pino property on the export (case `import { pino } from 'pino')
• as default property on the export (not sure when this is used, maybe by import pino from 'pino' if esModuleInterop: false)

The instrumentation covers only the first case above.

[armandAkop]

Ah you're right, in one of the libraries I had written which I was testing against, I had written

import { pino } from 'pino';

Thanks for the quick turn around and finding this!

[github-actions[bot]]

This issue is stale because it has been open 60 days with no activity. Remove stale label or comment or this will be closed in 14 days.

[dyladan]

Is this actually stale, resolved, or still open?

[Flarna]

The problem still exists but there is a workaround.

[jord1e]

I load my dotenv .js file with node -r which loads Pino before the instrumentation is initialized

How I fixed this is the following way for anyone interested:

import { registerInstrumentations } from "@opentelemetry/instrumentation";
import { Logger } from "./logger"; // my require('pino') resides here (logger.js)
import { PinoInstrumentation } from "@opentelemetry/instrumentation-pino";

// https://stackoverflow.com/questions/15666144/how-to-remove-module-after-require-in-node-js
delete require.cache[require.resolve("./logger.js")];

registerInstrumentations({
  instrumentations: [
    new PinoInstrumentation(),
  ],
});

Maybe not a workaround for this specific issue, but nonetheless useful for other people

[Flarna]

@jord1e No, this is a different issue. This on is about import { pino } from 'pino' is not working but import pino = require('pino') works. Cause is that pino exports itself more then once and one export is instrumented but the others are not.

For your issue I recommend to preload the Otel initialization before preload pino instead tinkering with require.cache. in your case you end up with two pino modules in your app - one is instrumented the other one is not. Removing it from require.cache doesn't remove all references to it. But as said it's a different topic so if you need more on this feel free to create a different issue/discussion.

[github-actions[bot]]

This issue is stale because it has been open 60 days with no activity. Remove stale label or comment or this will be closed in 14 days.

[rauno56]

We don't have a component owner for the pino instrumentation, but it was contributed by @seemk. Would you care to take a look, Siim?

[dmtrs]

Ported to typescript and there seems to be a bug in the instrumentation resulting in non working setups depending on how you import and if esModuleInterop is set in tsconfig.js. see below for details.

import { NodeTracerProvider } from '@opentelemetry/sdk-trace-node';
import { PinoInstrumentation } from '@opentelemetry/instrumentation-pino';
import { registerInstrumentations } from '@opentelemetry/instrumentation';
import * as opentelemetry from '@opentelemetry/api';

const provider = new NodeTracerProvider();
provider.register();

registerInstrumentations({
  instrumentations: [
    new PinoInstrumentation({
      // Optional hook to insert additional context to log object.
      logHook: (span, record) => {
        record['resource.service.name'] = provider.resource.attributes['service.name'];
      },
    }),
    // other instrumentations
  ],
});

// ok
import pino = require('pino');
const logger = (pino as any)();

// not ok
//import { pino } from 'pino';
//const logger = pino();

// ok if "esModuleInterop": true is in tsconfig.js
//import pino from 'pino';
//const logger = pino();

const tracer = opentelemetry.trace.getTracer('example-basic-tracer-node');
tracer.startActiveSpan('init', (span) => {
    for (let i = 0; i < 3; i++) {
        logger.info(`expect trace_id to be in this log ${i}`);
    }
    span.end();
});

root cause is that pino exports itself several times:

* the export object itself (case `const pino = require('pino'`)

* as `pino` property on the export (case `import { pino } from 'pino')

* as `default` property on the export (not sure when this is used, maybe by `import pino from 'pino'` if `esModuleInterop: false`)

The instrumentation covers only the first case above.

Can we consider adding this info and the 3 last bullets in pino instrumentation readme.md ? at https://github.com/open-telemetry/opentelemetry-js-contrib/blob/main/plugins/node/opentelemetry-instrumentation-pino/README.md

Could I help on adding this info there?

[Flarna]

@dmtrs the issue you mentioned should be solved via https://github.com/open-telemetry/opentelemetry-js-contrib/pull/1108. Are you using an instrumentation version which includes this fix?

Instead of adding above into the readme I would prefer to do add support for all export variants of pino.