Express doesn't get instrumented with ESM

[kevinmarks]

What version of OpenTelemetry are you using?

"@opentelemetry/api": "^1.6.0",
"@opentelemetry/auto-instrumentations-node": "^0.40.1",

What version of Node are you using?

v16.20.1

What did you do?

Instrumented a minimal node app with honeycombio

What did you expect to see?

Traces that included the express auto instrumentation

What did you see instead?

Traces that only included http and net instrumentation

Additional context

Example project here - needs a honeycomb api key in telemetry.mjs to run
https:/kevinmarks/OT-testbed

[Flarna]

Seems you use ECMA script modules. Support is experimental and requires some extra love on how you call node. see here

[kevinmarks]

If I run it with that prefix, I get a logline after the debug output saying:

Applying patch for [email protected]
OT-testbed Listening on 8989

but no events sent to honeycomb at all. Removing that again, http events show up.

[JamieDanielson]

I'm taking a look into this. The Applying patch for [email protected] log is a good sign of express instrumentation patching, but I'll report back what I find.

[JamieDanielson]

I guess this is similar to some of our other ESM problems. I can do a very small reproducer using just the ExpressInstrumentation (not fully set up to instrument, just to show the problem) that I believe is a good indicator of the problem, and I think it's related to how modules are loaded in ESM vs CJS.

import { diag, DiagConsoleLogger, DiagLogLevel } from '@opentelemetry/api';
diag.setLogger(new DiagConsoleLogger(), DiagLogLevel.DEBUG);

import { ExpressInstrumentation } from '@opentelemetry/instrumentation-express';
new ExpressInstrumentation();

import express from 'express';
const app = express();

app.get('/', (req, res) => {
  res.send('Hello World!');
});

app.listen(3000, () => console.log('Example app listening on port 3000!'));

This ESM app test.mjs shows a loading error in output, with and without the loader hook

✗ node --experimental-loader=@opentelemetry/instrumentation/hook.mjs test.mjs
(node:16336) ExperimentalWarning: Custom ESM Loaders is an experimental feature and might change at any time
(Use `node --trace-warnings ...` to show where the warning was created)
@opentelemetry/api: Registered a global for diag v1.6.0.
@opentelemetry/instrumentation-express Module express has been loaded before @opentelemetry/instrumentation-express so it might not work, please initialize it before requiring express
Example app listening on port 3000!

An identical app called test.cjs that uses const and require does not have the same error

✗ node test.cjs
@opentelemetry/api: Registered a global for diag v1.6.0.
Applying patch for [email protected]
Example app listening on port 3000!

In both, the order of everything in the code is identical. This will need more time to sort out.

[OliverJAsh]

I am encountering the same issue. I created a reduced test case before discovering this issue. Sharing in case it's helpful: https:/OliverJAsh/esm-otel.

As the reduced test case demonstrates, this issue also affects the Pino instrumentation.

[JamieDanielson]

@kevinmarks sorry for the delay on this, I had gotten stuck on it and picked up some other things in the meantime. I've come back around to it and believe I have a solution as I was able to use your example repro.

The key issue is that express is getting loaded before the instrumentation can monkey-patch it. So we can use top-level awaits available in ESM to solve this.

The main changes I made to make your app work were to make the tracing an async function with an awaited default export, and then await the import of express in the app. I also ran the start command with the loader hook.

// tracing.mjs
...
export const startTracing = async () => {
  const node_sdk = new NodeSDK({
  ...
  });

  node_sdk.start()
}
export default await startTracing;

// index.mjs
import startTracing from './tracing.mjs';
startTracing();

const expressModule = await import('express');
const express = expressModule.default;
...

Now with debug enabled, my log includes the patch logs I expect, and hitting the endpoint results in spans for http and express.

➜  OT-testbed git:(main) ✗ npm run start:mjs

> [email protected] start:mjs
> node --experimental-loader=@opentelemetry/instrumentation/hook.mjs ./index.mjs
...
@opentelemetry/instrumentation-http Applying patch for [email protected]
Applying patch for net module
Applying patch for [email protected]
OT-testbed Listening on 3000
...

Would you be able to give this a try with your app and confirm it works properly?

[JamieDanielson]

Actually you might even be able to keep your app and tracing module as is, and instead change the start script to ensure the tracing file is loaded first. node --experimental-loader=@opentelemetry/instrumentation/hook.mjs --import ./tracing.mjs ./index.mjs. Doing this I also got instrumentation as expected for express and http, though note I'm on Node 18.18.2.

[jeffbicca]

Doing some testing as @JamieDanielson said and this also seems to do the trick, just in case for those who want to use @opentelemetry/auto-instrumentations-node register script instead of developing it's own otel bootstrap file (the good part of this is to configure otel directly into the env vars):

node --loader @opentelemetry/instrumentation/hook.mjs --import @opentelemetry/auto-instrumentations-node/register index

Tested in node 20.12.1 with Express 4.18.2

[vchirikov]

--experimental-loader=@opentelemetry/instrumentation/hook.mjs doesn't work with astro for example.

[trentm]

doesn't work with astro for example.

@vchirikov If you are able to help provide more details, it would be best to open a separate issue to for getting things working with Astro. Ideally that would include a small and complete reproduction so maintainers don't have to learn how to build an astro-based app. My total guess is that astro is a web framework that is doing bundling. If so, then bundling currently breaks any auto-instrumentation because included packages are no longer loaded using require or import.

[vchirikov]

Offtopic

Astro is based on vite, vite uses ESM. The first error was `SyntaxError: The requested module './bundle-full.mjs' does not provide an export named 'codeToHast'` from `shiki` and some of astro internals (`dist/cookies` as far as I can remember). It's an issue with `import-in-the-middle`. I found a workaround - hook ONLY the desired modules (`node:*` in my case), I have to create a git patch to do it (with `patch-package`), but at least it works.

Anyway, I think the usage of opentelemetry-js packages should be much easier & better documented.

[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.

[trentm]

@vchirikov

still Offtopic

I found a workaround - hook ONLY the desired modules

I hope that OTel will get to doing that by default now that import-in-the-middle supports it via nodejs/import-in-the-middle#146

[atsu85]

@JamieDanielson, thanks for good explanation!
Any updates related to this issue?

[JamieDanielson]

@JamieDanielson, thanks for good explanation! Any updates related to this issue?

@atsu85 this should work with the suggestions listed above. I've finally added a doc with these details as well, which I'm working on getting into the main docs site.

[JamieDanielson]

I will close this specific issue with the above note but if any new issues arise please feel free to open a new issue!