Pino instrumentation fails when using ES modules

[nlindley]

What version of OpenTelemetry are you using?

• @opentelemetry/api: 1.4.1
• @opentelemetry/instrumentation: 0.41.0
• @opentelemetry/instrumentation-pino: 0.34.0
• @opentelemetry/sdk-node: 0.41.0
• @opentelemetry/sdk-trace-base: 1.15.0

What version of Node are you using?

18.16.1

What did you do?

Attempted to instrument pino using either default or named imports.

What did you expect to see?

Trace information in the logs.

What did you see instead?

When using default imports, the application crashes when pino() is called. When using named imports, trace information is not added to the logs.

Additional context

We have minimal reproductions of the issues:

• Default import: https://github.com/nlindley/otel-esm-examples/tree/master/pino-default
• Named import: https://github.com/nlindley/otel-esm-examples/tree/master/pino-named

[dyladan]

I think this is the same as open-telemetry/opentelemetry-js#3976

For now you may be able to just use the previous version until we can provide a fix.

[klippx]

They reverted open-telemetry/opentelemetry-js#4011 maybe you should do the same?

[github-actions]

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.

[jacobwood091]

This appears to still be an issue. We may want to look towards a solution such as that proposed by #1694, as this seems to be a resolution difference within the ECMAScript Module Namespace Object versus that of the CommonJS resolved Namespace. This comment, especially the Aside, provides an excellent analysis relevant to the underlying issue.

[mbrevda]

are we sure this was fixed? It doesn't look like Pino is being instrumented, even with 0.34.4.

otel config

import {
  CompositePropagator,
  W3CTraceContextPropagator,
} from '@opentelemetry/core';
import {SimpleSpanProcessor} from '@opentelemetry/sdk-trace-base';
import {NodeTracerProvider} from '@opentelemetry/sdk-trace-node';
import {registerInstrumentations} from '@opentelemetry/instrumentation';
import {OTLPTraceExporter} from '@opentelemetry/exporter-trace-otlp-http';
import {HttpInstrumentation} from '@opentelemetry/instrumentation-http';
import {ExpressInstrumentation} from '@opentelemetry/instrumentation-express';
import {TraceExporter} from '@google-cloud/opentelemetry-cloud-trace-exporter';
import {PinoInstrumentation} from '@opentelemetry/instrumentation-pino';
import {FetchInstrumentation} from 'opentelemetry-instrumentation-fetch-node';
import {CloudPropagator} from '@google-cloud/opentelemetry-cloud-trace-propagator';
import {Resource} from '@opentelemetry/resources';
import {SemanticResourceAttributes} from '@opentelemetry/semantic-conventions';

const {
  // @ts-ignore
  default: {diag, DiagConsoleLogger, DiagLogLevel},
} = await import('@opentelemetry/api');
diag.setLogger(new DiagConsoleLogger(), DiagLogLevel.DEBUG);
const provider = new NodeTracerProvider({
  resource: new Resource({
    [SemanticResourceAttributes.SERVICE_NAME]: 'api',
    [SemanticResourceAttributes.SERVICE_VERSION]: '1.0',
  }),
});

provider.register({
  propagator: new CompositePropagator({
    propagators: [new W3CTraceContextPropagator(), new CloudPropagator()],
  }),
});

// const exporter = process.env.K_SERVICE
//   ? new TraceExporter()
//   : new OTLPTraceExporter({});

// const processor = new SimpleSpanProcessor(exporter);
// provider.addSpanProcessor(processor);

registerInstrumentations({
  instrumentations: [
    // not working: https://github.com/open-telemetry/opentelemetry-js-contrib/issues/1587
    new PinoInstrumentation({
      logHook: (span, record, level) => {
        console.log('HERE');
        record['resource.service.name'] =
          provider.resource.attributes['service.name'];
      },
    }),
    // new FsInstrumentation(),
    new FetchInstrumentation({
      onRequest: ({request, span}) => {
        span.updateName(`${request.method}: ${request.path}`);
      },
    }),
    new ExpressInstrumentation(),
    new HttpInstrumentation({
      requestHook: (span, req) => {
        // req can be of different types that don't share a common interface
        let path = 'url' in req ? req.url : '';
        path ?? ('path' in req ? req.path : '');
        span.updateName(`${req.method}: ${path}`);
      },
    }),
  ],
});

logs

@opentelemetry/api: Registered a global for diag v1.7.0.
@opentelemetry/api: Registered a global for trace v1.7.0.
@opentelemetry/api: Registered a global for context v1.7.0.
@opentelemetry/api: Registered a global for propagation v1.7.0.
@opentelemetry/instrumentation-http Applying patch for http@21.3.0
@opentelemetry/instrumentation-http Applying patch for https@21.3.0

being called as an import on the first line of code

[trentm]

@mbrevda I'll take a look.

[trentm]

I think it is basically working. Here is a full run of npm run test-all-versions in a git clone running on my machine, FWIW: https://gist.github.com/trentm/853da0a159d0fcb8a09e05ac2282fcc3

@mbrevda Your log output shows @opentelemetry/instrumentation-http Applying patch for http and for https, but does not show it for pino. I'd expect to see that output from this code line if the instrumentation was picked up at all:

opentelemetry-js-contrib/plugins/node/opentelemetry-instrumentation-pino/src/instrumentation.ts

Line 45 in 60328af

diag.debug(`Applying patch for pino@${moduleVersion}`);

That suggests to me that this may be about import order, rather than about the recent change to support pino in ESM code. I'm not sure of that though. If import order was an issue, I thought @opentelemetry/instrumentation would diag.warn about pino already having been imported, and your log output doesn't show that either.

I see @ts-ignore in your posted code above. Is this TypeScript code that is being compiled to ESM? Are you able to post a small repro case that shows the compiled JS that is being executed. That might help pinpoint the issue.

[mbrevda]

I'd expect to see that output from this code line if the instrumentation

Same 😁

I think this repo should explain it. When running with import "./otel.mjs" in index.mjs, I get the warning about pino already being imported (and instrumentation doesn't work). When that's commented out and running node --import ./otel.mjs index.mjs, the warning doesn't even show.

Is my setup incorrect?

[OliverJAsh]

I am encountering the same issue. Reduced test case: https://github.com/OliverJAsh/esm-otel.

Presumably this has the same root cause as #1849.

[mbrevda]

Confirmed this related to the esm loading issues (especially with bundled code). So technically this does work