instrumentation-http: ESM instrumentation does not work on outgoing requests

[constb]

What happened?

Steps to Reproduce

with node v20.17.0 or v18.20.4, install latest (0.53.0) opentelemetry sdk-node and instrumentation-http
enable ESM (set type: module in package.json)

a client makes a http request in context with trace id using http.request()

Expected Result

server receives traceparent header and runs in a context with same traceId.

Actual Result

server does not receive traceparent header and runs handler in a separate trace context.

Additional Details

might be related to #5001

OpenTelemetry Setup Code

// register.js

import { register } from 'node:module';
import { HttpInstrumentation } from '@opentelemetry/instrumentation-http';
import { node, NodeSDK } from '@opentelemetry/sdk-node';

const OPENTELEMETRY_SDK = Symbol('openTelemetrySdk');

register('@opentelemetry/instrumentation/hook.mjs', import.meta.url);

globalThis[OPENTELEMETRY_SDK] = new NodeSDK({
  serviceName: 'test',
  instrumentations: [new HttpInstrumentation({ enabled: true })],
});
globalThis[OPENTELEMETRY_SDK].start();

const shutdownFn = async () => globalThis[OPENTELEMETRY_SDK].shutdown().then(() => console.log('shutdown')).catch((error) => console.error(error));
let shutdownStarted = false;
const signals = ['SIGHUP', 'SIGINT', 'SIGQUIT', 'SIGILL', 'SIGTRAP', 'SIGABRT', 'SIGBUS', 'SIGFPE', 'SIGSEGV', 'SIGUSR2', 'SIGTERM'];
const signalHandler = (signal) => {
  if (shutdownStarted) return;
  shutdownStarted = true;
  shutdownFn().then(() => {
    signals.forEach((s) => process.removeListener(s, signalHandler));
    process.kill(process.pid, signal);
  });
};
signals.forEach((s) => process.on(s, signalHandler));

// index.js

import { api } from '@opentelemetry/sdk-node';
import http from 'node:http';

const span = api.trace.getTracer().startSpan('test');
const ctx = api.trace.setSpan(api.context.active(), span);

const server = http.Server((req, res) => {
  console.log('server', { heades: req.headers, span: api.trace.getActiveSpan().spanContext() });
  res.writeHead(204);
  res.end();
});
await new Promise(res => server.listen(8080).once('listening', res));

await api.context.with(ctx, async () => {
  console.log('client', { span: api.trace.getActiveSpan().spanContext() });
  await new Promise(resolve => {
    const req = http.request('http://localhost:8080/ping', (res) => {
      res.on('data', () => {});
      res.on('end', resolve);
    });
    req.end();
  });
});

process.kill(process.pid, 'SIGTERM');

package.json

{
  "name": "otel-reproduce",
  "version": "0.0.1",
  "main": "index.js",
  "type": "module",
  "scripts": {
    "start": "cross-env OTEL_PROPAGATORS=tracecontext OTEL_TRACES_EXPORTER=console OTEL_NODE_RESOURCE_DETECTORS=none node --import ./register.js ./index.js"
  },
  "author": "",
  "license": "UNLICENSED",
  "description": "",
  "dependencies": {
    "@opentelemetry/instrumentation": "0.53.0",
    "@opentelemetry/instrumentation-http": "0.53.0",
    "@opentelemetry/sdk-node": "0.53.0",
    "cross-env": "7.0.3"
  }
}

Relevant log output

client {
  span: {
    traceId: '92a751c98e9a4c3d782cc6c877fd8502',
    spanId: '74ae11ca029180a3',
    traceFlags: 1,
    traceState: undefined
  }
}
server {
  heades: { host: 'localhost:8080', connection: 'close' },
  span: {
    traceId: 'c94c82377ce8920746fc79e664303ebc',
    spanId: '64f65ad6b638654a',
    traceFlags: 1,
    traceState: undefined
  }
}

[constb]

I also found a solution but it's really weird:

• create register-http.cjs containing a single line require('http');
• add to the beginning of index.js a line import './register-http.cjs';

run npm run start and it works as expected:

client {
  span: {
    traceId: '48e7d9a0bdc06b1ca8cf64bbbc9fd553',
    spanId: 'e3e29f7e7b31f9a3',
    traceFlags: 1,
    traceState: undefined
  }
}
server {
  heades: {
    traceparent: '00-48e7d9a0bdc06b1ca8cf64bbbc9fd553-36ce064562d577d1-01',
    host: 'localhost:8080',
    connection: 'close'
  },
  span: {
    traceId: '48e7d9a0bdc06b1ca8cf64bbbc9fd553',
    spanId: 'e87449781fba712a',
    traceFlags: 1,
    traceState: undefined
  }
}

somehow requiring http in commonjs execution context fixed http-instrumentation hooks 🤷🏻‍♂️

[pichlermarc]

Hi @constb, thanks for reaching out. This is really weird.

I have tried to reproduce this locally and it behaves the exact same way for me as it does for you.
I broke it down even further to full manual SDK setup - turns out that when I include the Zipkin exporter (which is included in @opentelemetry/sdk-node), propagation breaks.

I'll investigate further and will let you know what I find.

[pichlermarc]

Labelling as zipkin exporter bug (and, by proxy, sdk-node bug) as that's what's needed to surface this behavior.

[olabodeIdowu]

api.trace.getActiveSpan() returns undefined

[pichlermarc]

I'm still somewhat confused about this situation and have not had much time to look into this. I'll try to find someone who has more context to look into this. I suspect that importing the Zipkin exporter requires the node:http module and that causes the http client instrumentation to break, hence no traceparent added by the client to the outgoing request and no traceparent received by the server.

Here is a link to the reproducer that I created: https://github.com/pichlermarc/repro-5024

[dyladan]

It's the load order issue. Zipkin requires http during the initial require https://github.com/open-telemetry/opentelemetry-js/blob/main/packages/opentelemetry-exporter-zipkin/src/platform/node/util.ts#L19

The way to solve this is to enable all instrumentations before any other part of the SDK is even required. Our node SDK package may need to be restructured even to make this happen, or the logic which enables all instrumentations maybe should be moved to the instrumentation package.

[trentm]

I believe I understand what is happening.
There are two issues here.

issue 1: whether require('http') happens after new HttpInstrumentation()

Let's look at smaller examples:

foo.mjs

import http from 'node:http';
import {request} from 'node:http';
console.log('http.request is:', http.request);
console.log('request is:', request);

Running that without instrumentation, request is the name of the internal http.request function.

% node foo.mjs
http.request is: [Function: request]
request is: [Function: request]

Let's just instrument CommonJS loading of http:

something-that-requires-http.cjs

require('http');

telemetry1.cjs

const { diag, DiagConsoleLogger, DiagLogLevel } = require('@opentelemetry/api');
diag.setLogger(new DiagConsoleLogger(), DiagLogLevel.DEBUG);

require('./something-that-requires-http.cjs');

const {HttpInstrumentation} = require("@opentelemetry/instrumentation-http");
new HttpInstrumentation();

Running that loads http, but before HttpInstrumentation is actively hooking require('http'), so http is not instrumented.

% node -r ./telemetry1.cjs foo.mjs
@opentelemetry/api: Registered a global for diag v1.9.0.
http.request is: [Function: request]
request is: [Function: request]

If we load http after new HttpInstrumentation():

telemetry2.cjs

const { diag, DiagConsoleLogger, DiagLogLevel } = require('@opentelemetry/api');
diag.setLogger(new DiagConsoleLogger(), DiagLogLevel.DEBUG);

require('./something-that-requires-http.cjs');

const {HttpInstrumentation} = require("@opentelemetry/instrumentation-http");
new HttpInstrumentation();

require('http');

then (a) it is instrumented; and (b) it is instrumented for ESM usage of http (http.request is now the wrapper outgoingRequest function):

% node -r ./telemetry2.cjs foo.mjs
@opentelemetry/api: Registered a global for diag v1.9.0.
@opentelemetry/instrumentation-http Applying instrumentation patch for nodejs core module on require hook { module: 'http' }
http.request is: [Function: outgoingRequest]
request is: [Function: outgoingRequest]

The first surprise is here. If we instead re-require something-that-requires-http.cjs:

telemetry3.cjs

const { diag, DiagConsoleLogger, DiagLogLevel } = require('@opentelemetry/api');
diag.setLogger(new DiagConsoleLogger(), DiagLogLevel.DEBUG);

require('./something-that-requires-http.cjs');

const {HttpInstrumentation} = require("@opentelemetry/instrumentation-http");
new HttpInstrumentation();

require('./something-that-requires-http.cjs'); // changed from `require('http')`

Then something-that-requires-http.cjs is loaded from the require cache and http is not loaded again.

% node -r ./telemetry3.cjs foo.mjs
@opentelemetry/api: Registered a global for diag v1.9.0.
http.request is: [Function: request]
request is: [Function: request]

This is what is happening in the example given:

register.js

import { HttpInstrumentation } from '@opentelemetry/instrumentation-http';
import { node, NodeSDK } from '@opentelemetry/sdk-node'; 
    // This requires `exporter-zipkin`, which requires `http`
    // **before** `new HttpInstrumentation()`.
...
new HttpInstrumentation({ enabled: true });

index.js

import { api } from '@opentelemetry/sdk-node';
    // This gets `@opentelemetry/sdk-node` from the cache, so `http` is *not*
    // reloaded.
import http from 'node:http';
    // This triggers the ESM hook to instrument `http`, but it has a bug. See issue 2 below.
...

This is effectively the same issue hit recently here:
open-telemetry/opentelemetry-js-contrib#2440 (comment)

issue 2: ESM http instrumentation is only partially working

Ideally, none of the CommonJS loading of http should matter here. The app is using ESM code, and the ESM hooking (via import-in-the-middle) should work. E.g.:

foo.mjs (same as above)

import http from 'node:http';
import {request} from 'node:http';
console.log('http.request is:', http.request);
console.log('request is:', request);

Let's setup telemetry that sets up ESM hooking:

telemetry.mjs

import { register } from 'node:module';
register('@opentelemetry/instrumentation/hook.mjs', import.meta.url);

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

import {HttpInstrumentation} from "@opentelemetry/instrumentation-http";
new HttpInstrumentation();

Running that:

% node --import ./telemetry.mjs foo.mjs
@opentelemetry/api: Registered a global for diag v1.9.0.
@opentelemetry/instrumentation-http Applying instrumentation patch for nodejs core module on require hook { module: 'http' }
http.request is: [Function: request]
request is: [Function: outgoingRequest]

Note the surprise: http.request is instrumented via import {request} from 'node:http'; but NOT via import http from 'node:http'; http.request.

This is a bug in @opentelemetry/instrumentation-http.

Incidentally ESM instrumentation works via import * as http from 'node:http' as well.
This is the form that is tested in instrumentation-http's ESM test code:

opentelemetry-js/experimental/packages/opentelemetry-instrumentation-http/test/integrations/esm.test.mjs

Line 21 in 7ed67f9

import * as http from 'http';

This change breaks that test:

--- a/experimental/packages/opentelemetry-instrumentation-http/test/integrations/esm.test.mjs
+++ b/experimental/packages/opentelemetry-instrumentation-http/test/integrations/esm.test.mjs
@@ -18,7 +18,7 @@

 import * as assert from 'assert';
 import * as fs from 'fs';
-import * as http from 'http';
+import http from 'http';
 import * as https from 'https';

 import { SpanKind } from '@opentelemetry/api';

I can work on a fix.