Skip to content

Commit 741135e

Browse files
fix(node): End Express layer spans when next is called (#24854)
- [x] If you've added code that should be tested, please add tests. - [x] Ensure your code lints and the test suite passes (scoped to the affected packages, see Testing below). - [x] Link an issue if there is one related to your pull request. Closes #24853 Express layer spans were ended on the tracing channel's `asyncEnd`, which only fires once `next()` *returns*. Express runs the rest of the chain synchronously inside `next()`, so every layer on the synchronous chain kept its span open, together with the response `finish` listener that `getSpanForLayer` registers, until the whole chain unwound. As a result: - Requests that pass through roughly 9 or more synchronous layers log `MaxListenersExceededWarning: ... 11 finish listeners added to [ServerResponse]`, one per request. Unsampled requests are affected too. - Each middleware span absorbs the synchronous work of every downstream layer. A no-op middleware reported 50ms when the route handler after it did 50ms of synchronous work. This PR ends the layer span on `asyncStart` instead: when the layer calls `next()`, before the downstream layer runs. That matches what the surrounding comments and the orchestrion config already describe. - Layers that never call `next()` still end on the response `finish`. These are route handlers and routers that handle the request themselves, so router spans still enclose the handler they dispatch. - The helper's later `asyncEnd` is a no-op, because `span.end()` is idempotent. - `next(err)` still marks the span as errored, because the channel publishes `error` before `asyncStart`. ### Testing New `node-integration-tests` suite `express/layer-span-end`, with 12 synchronous middleware and a handler that does 50ms of synchronous work. It asserts that: - every middleware span ends before the request handler span starts - the response has fewer `finish` listeners than `EventEmitter.defaultMaxListeners` Both tests fail without the change (16 listeners, and middleware spans ending about 51ms after the handler starts) and pass with it. Ran locally on Node 24.18: - `suites/express/**`: 15 files, 132 tests pass - the other 44 suite directories that use Express: 51 files, 395 tests pass - `@sentry/server-utils` unit tests: 1152 pass - `oxfmt --check` and `oxlint` on the changed files I also checked Express 5 against the published 11.1.0 build with this change applied: listeners went from 12 to 2, no warning, and span names were unchanged. I couldn't run the Bun and Deno node-suite projects locally. --------- Co-authored-by: Nicolas Hrubec <nico.hrubec@sentry.io>
1 parent 0a39acf commit 741135e

4 files changed

Lines changed: 118 additions & 9 deletions

File tree

Lines changed: 9 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,9 @@
1+
import * as Sentry from '@sentry/node';
2+
import { loggingTransport } from '@sentry-internal/node-integration-tests';
3+
4+
Sentry.init({
5+
dsn: 'https://public@dsn.ingest.sentry.io/1337',
6+
release: '1.0',
7+
tracesSampleRate: 1.0,
8+
transport: loggingTransport,
9+
});
Lines changed: 29 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,29 @@
1+
import express from 'express';
2+
import { startExpressServerAndSendPortToRunner } from '@sentry-internal/node-integration-tests';
3+
4+
const MIDDLEWARE_COUNT = 12;
5+
6+
const app = express();
7+
8+
// More synchronous middleware than Node's default of 10 listeners per event, so
9+
// layer spans that stayed open until `next()` returned would pile up a response
10+
// `finish` listener per layer.
11+
for (let i = 0; i < MIDDLEWARE_COUNT; i++) {
12+
app.use(function syncMiddleware(_req, _res, next) {
13+
next();
14+
});
15+
}
16+
17+
app.get('/test/express', (_req, res) => {
18+
const finishListeners = res.listenerCount('finish');
19+
20+
// Without the fix, this work is included in every preceding middleware's span.
21+
const until = Date.now() + 50;
22+
while (Date.now() < until) {
23+
// busy-wait
24+
}
25+
26+
res.send({ finishListeners });
27+
});
28+
29+
startExpressServerAndSendPortToRunner(app);
Lines changed: 48 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,48 @@
1+
import { EventEmitter } from 'node:events';
2+
import { afterAll, describe, expect } from 'vitest';
3+
import { cleanupChildProcesses, createEsmAndCjsTests } from '../../../utils/runner';
4+
5+
const MIDDLEWARE_COUNT = 12;
6+
7+
describe('express layer span end', () => {
8+
afterAll(() => {
9+
cleanupChildProcesses();
10+
});
11+
12+
createEsmAndCjsTests(__dirname, 'scenario.mjs', 'instrument.mjs', (createRunner, test) => {
13+
test('ends each middleware span when it calls `next`, before the route handler runs', async () => {
14+
const runner = createRunner()
15+
.unordered()
16+
.expect({
17+
span: container => {
18+
const middlewareSpans = container.items.filter(
19+
item => item.attributes['express.type']?.value === 'middleware',
20+
);
21+
const handlerSpan = container.items.find(
22+
item => item.attributes['express.type']?.value === 'request_handler',
23+
);
24+
25+
// Express 4 also runs its built-in `query` and `expressInit` middleware.
26+
expect(middlewareSpans.filter(span => span.name === 'syncMiddleware')).toHaveLength(MIDDLEWARE_COUNT);
27+
expect(handlerSpan).toBeDefined();
28+
29+
for (const middlewareSpan of middlewareSpans) {
30+
expect(middlewareSpan.end_timestamp).toBeLessThanOrEqual(handlerSpan!.start_timestamp);
31+
}
32+
},
33+
})
34+
.start();
35+
36+
runner.makeRequest('get', '/test/express');
37+
await runner.completed();
38+
});
39+
40+
test('does not accumulate a response `finish` listener per layer', async () => {
41+
const runner = createRunner().start();
42+
43+
const response = await runner.makeRequest<{ finishListeners: number }>('get', '/test/express');
44+
45+
expect(response?.finishListeners).toBeLessThan(EventEmitter.defaultMaxListeners);
46+
});
47+
});
48+
});

‎packages/server-utils/src/integrations/express/instrumentation.ts‎

Lines changed: 32 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -94,17 +94,21 @@ export function instrumentExpress(
9494
},
9595
});
9696

97-
// Pop the layer path when the layer hands off via `next`. `asyncStart` fires
98-
// when `next` is called and *before* the downstream layer runs, so the
99-
// per-request path chain reflects only the current chain when each layer
100-
// reconstructs its route. The `error` event captures throws at the layer
101-
// level (see `captureLayerError`), before any user error-handling middleware.
97+
// Pop the layer path and end the layer span when the layer hands off via
98+
// `next`. `asyncStart` fires when `next` is called and *before* the
99+
// downstream layer runs, so the per-request path chain reflects only the
100+
// current chain when each layer reconstructs its route, and each span covers
101+
// only its own layer. The `error` event captures throws at the layer level
102+
// (see `captureLayerError`), before any user error-handling middleware.
102103
channel.subscribe({
103104
start: NOOP,
104105
asyncEnd: NOOP,
105106
end: NOOP,
106107
error: data => captureLayerError(data, options.shouldHandleError),
107-
asyncStart: popLayerPathForLayer,
108+
asyncStart: data => {
109+
popLayerPathForLayer(data);
110+
endLayerSpanOnNext(data);
111+
},
108112
});
109113
}
110114
}
@@ -202,6 +206,25 @@ function popLayerPathForLayer(data: HandleChannelContext): void {
202206
}
203207
}
204208

209+
/**
210+
* End a layer's span once it hands control onward via `next`.
211+
*
212+
* The tracing-channel helper would otherwise end it on `asyncEnd`, which only
213+
* fires once `next` *returns*. Express runs the rest of the chain synchronously
214+
* inside `next`, so that would keep every layer on the synchronous chain open
215+
* (each holding a response `finish` listener) until the whole chain unwinds,
216+
* and inflate each span with the downstream layers' synchronous work. The
217+
* helper's later `asyncEnd` is then a no-op, since `span.end()` is idempotent.
218+
*/
219+
function endLayerSpanOnNext(data: HandleChannelContext): void {
220+
const span = data._sentrySpan;
221+
if (!span) {
222+
return;
223+
}
224+
data._sentryCleanup?.();
225+
span.end();
226+
}
227+
205228
/**
206229
* Open a span for one layer invocation. Returns `undefined` to opt the layer
207230
* out (error handlers, or a layer with no active parent trace) — the helper
@@ -326,9 +349,9 @@ function getSpanForLayer(data: HandleChannelContext, options: ExpressIntegration
326349
});
327350

328351
// A layer that sends the response (route handlers, typically) never calls
329-
// `next`, so the channel's `asyncEnd` never fires. End on the response's
330-
// `finish` in that case. When `next` *is* called, the helper ends the span
331-
// (via `asyncEnd`) and `beforeSpanEnd` removes this now-redundant listener.
352+
// `next`, so the channel's `asyncStart` never fires. End on the response's
353+
// `finish` in that case. When `next` *is* called, `endLayerSpanOnNext` ends
354+
// the span and removes this now-redundant listener.
332355
if (res && typeof res.once === 'function') {
333356
const onFinish = (): void => {
334357
span.end();

0 commit comments

Comments
 (0)