OTel Span/Trace duplication when using a middleware #51231
Description
Verify canary release
- I verified that the issue exists in the latest Next.js canary release
Provide environment information
Volta error: Could not find executable "pnpm"
Use `volta install` to add a package to your toolchain (see `volta help install` for more info).
Error details written to /Users/rudi/.volta/log/volta-error-2023-06-13_13_41_47.105.log
Operating System:
Platform: darwin
Arch: arm64
Version: Darwin Kernel Version 22.4.0: Mon Mar 6 20:59:28 PST 2023; root:xnu-8796.101.5~3/RELEASE_ARM64_T6000
Binaries:
Node: 20.3.0
npm: 9.6.7
Yarn: 3.6.0-git.20230603.hash-3c8237cb
pnpm: N/A
Relevant packages:
next: 13.4.6-canary.0
eslint-config-next: N/A
react: 18.2.0
react-dom: 18.2.0
typescript: 4.9.5
warn - Latest canary version not detected, detected: "13.4.6-canary.0", newest: "13.4.6-canary.1".
Please try the latest canary version (`npm install next@canary`) to confirm the issue still exists before creating a new issue.
Read more - https://nextjs.org/docs/messages/opening-an-issueWhich area(s) of Next.js are affected? (leave empty if unsure)
Link to the code that reproduces this issue or a replay of the bug
https://github.com/valkum/next-js-repro/tree/middleware-request-duplication
To Reproduce
- Add instrumentation.ts with the
vercel/otelpackage - Add a middleware that just does nothing.
- Start a local OTel collector with UI (e.g. Jaeger all in one).
- Set env var
export OTEL_EXPORTER_OTLP_ENDPOINT=http://localhost:4317 - Build and start the repro app
- See two traces generated for the single HTTP request
Describe the Bug
Normally, you would expect a single trace to be generated when requesting a page from the next server.
Because of the worker mode, in production, spans are only generated in the renderWorker.
For some reason, having a middleware present results in two requests from the routerWorker to the renderWorker.
The first request has 'x-middleware-invoke': '1' set and the second possibly 'x-middleware-next': '1'.
TraceIds get generated randomly on the first span (rootSpan) in a service (if no remote context is present). Because both requests to the renderWorker are both considered rootSpans, a single HTTP request to the top most HTTP server (start-server.ts) results in two traces (different traceIds) being generated.
Expected Behavior
Normally, you would propagate the trace state between processes if they are part of the same trace (see https://www.w3.org/TR/trace-context/#tracestate-header). This makes sure that a single traceId is used for all spans that are part of responding to a request.
The way next.js uses its TracerImpl creates some burden on doing this. Child spans can set attributes on the rootSpan as the TracerImpl stores the rootSpanId and hands out the attributes of it. This is used to attach the next.route attribute.
This information is in-process. There is no way to change the attributes of a remote span; thus it's not possible to create a rootSpan in the routerWorker and propagate the context to the request handlers for the two requests issued against the renderWorker. As the renderWorker would not be able to find the rootSpan
This issue is somehow mitigated if an upstream service in front of next.js creates a span and the BaseServer::handleRequest fn extracts the trace context from the HTTP headers. This way there would be two spans with the same remote parent. Note that this is currently not the case.
Which browser are you using? (if relevant)
No response
How are you deploying your application? (if relevant)
next start