Express 5, pino, ESM and Typescript - oh my (and not working)

[djMax]

We are looking to update a bunch of our infrastructure to OpenTelemetry. I've made a public repo:

https://github.com/gas-buddy/gasbuddy

The problem is pino does not appear to be getting instrumented. I'm wondering if it has to do with ESM. Here's what it prints:

@opentelemetry/api: Registered a global for diag v1.2.0.
Loading instrumentation for @opentelemetry/instrumentation-amqplib
Loading instrumentation for @opentelemetry/instrumentation-aws-lambda
No modules instrumentation has been defined, nothing will be patched
Loading instrumentation for @opentelemetry/instrumentation-aws-sdk
Loading instrumentation for @opentelemetry/instrumentation-bunyan
Loading instrumentation for @opentelemetry/instrumentation-cassandra-driver
Loading instrumentation for @opentelemetry/instrumentation-connect
Loading instrumentation for @opentelemetry/instrumentation-dns
Loading instrumentation for @opentelemetry/instrumentation-express
Loading instrumentation for @opentelemetry/instrumentation-fastify
Loading instrumentation for @opentelemetry/instrumentation-generic-pool
Loading instrumentation for @opentelemetry/instrumentation-graphql
Loading instrumentation for @opentelemetry/instrumentation-grpc
Loading instrumentation for @opentelemetry/instrumentation-hapi
Loading instrumentation for @opentelemetry/instrumentation-http
Loading instrumentation for @opentelemetry/instrumentation-ioredis
Loading instrumentation for @opentelemetry/instrumentation-knex
Loading instrumentation for @opentelemetry/instrumentation-koa
Loading instrumentation for @opentelemetry/instrumentation-lru-memoizer
Loading instrumentation for @opentelemetry/instrumentation-memcached
Loading instrumentation for @opentelemetry/instrumentation-mongodb
Loading instrumentation for @opentelemetry/instrumentation-mysql2
Loading instrumentation for @opentelemetry/instrumentation-mysql
Loading instrumentation for @opentelemetry/instrumentation-nestjs-core
Loading instrumentation for @opentelemetry/instrumentation-net
Loading instrumentation for @opentelemetry/instrumentation-pg
Loading instrumentation for @opentelemetry/instrumentation-pino
Loading instrumentation for @opentelemetry/instrumentation-redis
Loading instrumentation for @opentelemetry/instrumentation-redis-4
Loading instrumentation for @opentelemetry/instrumentation-restify
Loading instrumentation for @opentelemetry/instrumentation-winston
EnvDetector found resource. Resource { attributes: {} }
ProcessDetector found resource. Resource {
  attributes: {
    'process.pid': 89755,
    'process.executable.name': '/Users/max/.nvm/versions/node/v16.17.1/bin/node',
    'process.command': '/Users/max/dev/gb/gasbuddy/node_modules/.bin/start-service',
    'process.command_line': '/Users/max/.nvm/versions/node/v16.17.1/bin/node /Users/max/dev/gasbuddy/node_modules/.bin/start-service',
    'process.runtime.version': '16.17.1',
    'process.runtime.name': 'nodejs',
    'process.runtime.description': 'Node.js'
  }
}
@opentelemetry/api: Registered a global for trace v1.2.0.
@opentelemetry/api: Registered a global for context v1.2.0.
@opentelemetry/api: Registered a global for propagation v1.2.0.
Applying patch for dns
patch lookup function
patch lookup function
Applying patch for net module
Patching pg.Client.prototype.query
@opentelemetry/instrumentation-http Applying patch for [email protected]
Applying patch for [email protected]
@opentelemetry/instrumentation-http Applying patch for [email protected]
{"level":30,"time":1664502743292,"pid":89755,"hostname":"MaxM1Max.local","msg":"OpenTelemetry enabled"}
{"level":30,"time":1664502743294,"pid":89755,"hostname":"MaxM1Max.local","port":8001,"service":"token-serv","msg":"express listening"}

Those last two lines should have a trace/span in them, right?

[Flarna]

Have you ensured that autoinstrumentations are registered before any of the modules to instrument are actually loaded/required?

Maybe do this by moving it from new opentelemetry.NodeSDK into a dedicated call to registerInstrumentations() because NodeSDK does this quite late (see #3146).

[djMax]

Usually it will give you a warning if you load the module first, and I'm not getting any warnings (and trying to be careful about load order). I did split it out into its own call, and I added a console.log in pino, and this is what it does:

@opentelemetry/api: Registered a global for trace v1.2.0.
@opentelemetry/api: Registered a global for context v1.2.0.
@opentelemetry/api: Registered a global for propagation v1.2.0.
Applying patch for dns
patch lookup function
patch lookup function
Applying patch for dns
patch lookup function
patch lookup function
Applying patch for net module
Applying patch for net module
Patching pg.Client.prototype.query
Patching pg.Client.prototype.query
@opentelemetry/instrumentation-http Applying patch for [email protected]
@opentelemetry/instrumentation-http Applying patch for [email protected]
IMPORTED PINO
Applying patch for [email protected]
Applying patch for [email protected]
@opentelemetry/instrumentation-http Applying patch for [email protected]
@opentelemetry/instrumentation-http Applying patch for [email protected]
{"level":30,"time":1664538210004,"pid":61333,"hostname":"MaxM1Max.local","msg":"OpenTelemetry enabled"}
{"level":30,"time":1664538210006,"pid":61333,"hostname":"MaxM1Max.local","port":8001,"service":"token-serv","msg":"express listening"}

Why is pino special?? I wonder if this could have to do with being in a monorepo? Is the auto instrumentation looking for node_modules content or doing require tomfoolery? I also tried requiring pino via a cjs file, but that didn't work either.

[Flarna]

auto instrumentations intercept require.
Even your app is ESM pino isn't to my understanding (see https://github.com/pinojs/pino/blob/v8.6.1/package.json#L6).

Note also that traceId/spanId is only added to log lines if there is an active trace. This is likely not the case for places where you log OpenTelemetry enabled and express listening.

[djMax]

I see there are three build-dirs for @opentelemetry/instrumentation - esm, esnext and src. I have verified I'm running in the "src" path, for whatever that is worth.

[djMax]

I logged during an active express request, that was/is also missing the span/trace. I agree that the app is ESM and pino is not, but what continues to confuse me is why the other instrumentations work (http, express) but pino does not.

[Flarna]

As said your example is quite big and honestly I don't want to invest a lot time in searching for the line where you call pino and it's not working. If you can create a reproducer which consists of a single ts file + a package.json it's by far easier to help.

If it is not that easy to reproduce you can do the iterative work to move from the small working sample to the bigger non working to find out what makes the difference.

[djMax]

It's ESM that kills it. And if that's not supported, then it's probably not something I want to build a massive infrastructure on top of... So I've bailed on ESM.

[djMax]

Is there a way to use OpenTelemetry without the require tricks? I'm fine specifying the "transforms" I want.

[Flarna]

You can call the OTel Api by yourself.

There is nothing like importing a module, manually call instrument() on the exports and reexport the instrumented variant. This might work for some modules where only the public API is instrumented but it won't work if internal files and internal used functions need to be instrumented.

[djMax]

I've abandoned ESM, it's just not ready for prime time. But, I still see this (seeming) error on startup:

No modules instrumentation has been defined, nothing will be patched

Yet everything goes on to be patched.

[Flarna]

it's hard to comment here without knowing your code. OTel works for a lot people but clearly it's easy to do something wrong as subtle differences may have high impact.

[djMax]

This line comes from the AWS Lambda auto instrumentation. It's just crappy code:

https://github.com/open-telemetry/opentelemetry-js/blob/main/experimental/packages/opentelemetry-instrumentation/src/platform/node/instrumentation.ts#L50

That should log the instrumentation name, if it should log anything at all. And in the case of auto instrumentation, I would submit that it's an expected situation and thus probably not something to log. But of course that layer doesn't know it's auto.