Sentry creates three traces for a single http request (ESM, custom opentelemetry setup)

nlochschmidt commented 1 day ago

Is there an existing issue for this?

[x] I have checked for existing issues https://github.com/getsentry/sentry-javascript/issues
[x] I have reviewed the documentation https://docs.sentry.io/
[x] I am using the latest SDK release https://github.com/getsentry/sentry-javascript/releases

How do you use Sentry?

Sentry Saas (sentry.io)

Which SDK are you using?

@sentry/node

SDK Version

8.35.0

Framework Version

hapi 21.3.10

Link to Sentry event

No response

Reproduction Example/SDK Setup

https://github.com/nlochschmidt/sentry-duplicate-tracing-bug

Steps to Reproduce

I've setup Sentry and a custom otel setup as described in the docs we are not using Sentry for tracing but another service
Running the server I can see from the logs that instrumentations are setup
When I call the server e.g. curl localhost:3000 I get a spanId and traceId from inside the handler
The ConsoleSpanExporter will print the traces and spans collected after a short time.

Expected Result

I expect to get a single trace with two spans (one for http and one for hapi).

Actual Result

What actually happens is that there are three traces and only one of them (traceId: 9dbf48ed9eee5aa66cba36df77eef90b) has the two spans that are expected, while the other two traces have only a single http root span.

I can see some odd instrumentation scopes @opentelemetry_sentry-patched/instrumentation-http, but interestingly the @opentelemetry/instrumentation-http is on one of the traces with a single span.

Here is the output cleaned up a bit (full output in the example repo README):

{
  traceId: '9dbf48ed9eee5aa66cba36df77eef90b',
  id: '86279d018d1d20f4',
  parentId: 'bb6216be501f6924',
  instrumentationScope: {
    name: '@opentelemetry/instrumentation-hapi',
  },

  name: 'route - /',
  kind: 0,
  attributes: {
    'sentry.sample_rate': 1
  },
  status: { code: 0 },
}

{
  traceId: '04de96dc9304e6376ac87ffa038e53f4',
  id: 'e68a07918c660533',
  parentId: undefined,
  instrumentationScope: {
    name: '@opentelemetry/instrumentation-http',
  },
  name: 'GET',
  kind: 1,
  attributes: {
    'sentry.sample_rate': 1,
    'sentry.parentIsRemote': true,
  },
  status: { code: 0 },
}

{
  traceId: 'e82eb8fe28439cad4cb409199d1759f3',
  id: '01cf0d4b96a81e61',
  parentId: undefined,
  instrumentationScope: {
    name: '@opentelemetry_sentry-patched/instrumentation-http',
  },
  name: 'GET',
  kind: 1,
  attributes: {
    'sentry.sample_rate': 1,
    'sentry.parentIsRemote': true,
    'sentry.origin': 'auto.http.otel.http',
  },
  status: { code: 0 },
  events: [],
  links: []
}

{
  traceId: '9dbf48ed9eee5aa66cba36df77eef90b',
  id: 'bb6216be501f6924',
  parentId: undefined,
  instrumentationScope: {
    name: '@opentelemetry_sentry-patched/instrumentation-http',
  },
  name: 'GET',
  kind: 1,
  attributes: {
    'sentry.sample_rate': 1,
    'sentry.parentIsRemote': true,
    'sentry.origin': 'auto.http.otel.http',
  },
  status: { code: 0 },
}

It works as expected when removing Sentry

nlochschmidt commented 1 day ago

8.34.0 only creates a single trace, so it looks like this is a regression in 8.35.0. The problem is still present in 8.36.0-beta.0.

Some more things that I tried

HttpIntegration({ spans: false }): This does remove the @opentelemetry_sentry-patched/instrumentation-http spans, but now I get a double span for @opentelemetry/instrumentation-http instead of a single one, and also any captured exceptions no longer have the request data. So no good.
Keep HttpIntegration from Sentry, but remove the HttpInstrumentation from OTEL: The one additional @opentelemetry/instrumentation-http span goes away and I am left with two @opentelemetry_sentry-patched/instrumentation-http spans. However captured exceptions still have the request data
Use HttpIntegration({spans: false}) and remove HttpInstrumentation from OTEL (combination of the two above): With this the request data on captured exceptions works, but I no longer get any spans (neither from http nor from hapi.

nlochschmidt commented 1 day ago

@mydea could this be related to https://github.com/getsentry/sentry-javascript/pull/13763?

The release notes for 8.35.0 mention a SentryHttpInstrumentation that could be used with OTEL instead of the HttpInstrumentation:

This change introduces a new SentryHttpInstrumentation to handle non-span related HTTP instrumentation, allowing it to run side-by-side with OTel's HttpInstrumentation.

This sounds promising, however I don't think SentryHttpInstrumentation is exported from @sentry/node, and I haven't found documentation on how to use SentryHttpInstrumentation.

s1gr1d commented 1 day ago

Hy, your guess is right. This change was introduced in 8.35.0 and we still need to update documentation (created an issue). You have to add the following now, so Sentry does not emit spans (only your custom setup).

Sentry.init({
  integrations: [Sentry.httpIntegration({ spans: false })]
})

As you wrote you get double spans when setting this to false: This should not happen and I would have to reproduce this with your example (thanks for providing this).

Lms24 commented 1 day ago

Hey @nlochschmidt

So after hours of debugging and nearly loosing my mind, we found a solution. In your reproduction, two module.register() calls were made: one in the hooks.ts file, you --import when starting the app, and one in Sentry.init. I'm fairly confident that this caused the double wrapping of the http module, which caused duplicated spans. This, paired with Sentry.httpIntegration being enabled by default and therefore sending yet another root span/trace, brings us indeed to three traces/root spans.

To fix this:

As you already found out, register Sentry.httpIntegration({ spans: false }) in your Sentry.init call. This brings us down to two traces
Then, we need to take care of the double register calls. You have two options:
- Rely on Sentry's register call:
  - Remove hooks.ts
  - remove the import "instrument.ts" line in index.ts
  - change your start script to node --import instrument.js index.js
- Rely on your own register call:
  - Move the contents of hooks.ts to the top of instrument.ts
  - remove the import "instrument.ts" line in index.ts
  - change your start script to node --import instrument.js index.js
  - set registerEsmLoaderHooks: false in your Sentry.init options.

To sum up (we will update the Custom Otel Setup docs accordingly):

You should always only register the loader hook once. Either yourself or let Sentry take care of it.
Sentry still needs the Sentry.httpIntegration({spans: false}) for non-span related request handling, like isolating data and attaching request data to errors. This needs to be set explicitly because otherwise, we fall back to Sentry.httpIntegration({spans: true}) which creates another root span.

nlochschmidt commented 17 hours ago

@s1gr1d @Lms24 I was starting to loose my mind as well 😂 Thank you!

I can confirm that this works in the example project (with Sentry register call, with own register call).

It's interesting that the --import ./build/instrument.js is required to get the hapi instrumentation to work. The http instrumentation by itself works with a simple import "./instrument.js" at the top of the index.ts file and no --import. Very odd behavior.

Will try it in production next 🤞

Lms24 commented 17 hours ago

Http instrumentation works because it's a built-in module. All other instrumentations (node fetch being another exception) like hapi, express, pg, etc. need to be initialized beforehand (via --import loader).

getsentry / sentry-javascript