TT-020: Node middleware() duration_ms times the request stream, not the response (5 ms reported for a 505 ms request)

[unjica]

Severity: P3 · Area: SDK: Node · Found by: QA

Summary

middleware() from @telemetry-tracker/node records duration_ms when the request stream emits end/close, not when the response finishes. Any app that reads the body before the handler runs (e.g. express.json() or another body parser) gets a duration_ms that covers only the upload time. In our test that was 5–7 ms for a request that took 505–508 ms.

On frameworks whose request object has no .on (Fastify request), the middleware calls next() twice and records ~0 ms. See the related existing issue #632.

Severity reason: P3. Performance data is wrong (under-reported by ~100× for POST/PUT with parsed bodies), but it doesn't crash or lose errors. It's the only metric the middleware produces.

Affected published versions

• @telemetry-tracker/node@1.3.0 (published 2026-07-02 16:14 CEST). The repo develop/main code (still 1.3.0) is identical for middleware().

Environment and versions

2026-09-26 10:45–10:50 CEST. Node 20.19.2, 22.23.3, 24.21.0, Linux. Express 4.22.3, Express 5.2.1, Fastify 5.12.5, plain node:http. Local mock ingest. next() was counted by wrapping the callback passed to middleware(). Every call was passed through.

Steps to reproduce

1. Run a mock ingest on :4318 that prints request bodies (e.g. the mock.mjs in TT-012: Node SDK drops uncaught exceptions (re-throws before the error is sent) #711).
2. npm i @telemetry-tracker/node@1.3.0 express@4, then create mw.mjs:

   import express from "express";
   import { init, middleware } from "@telemetry-tracker/node";
   init({ ingestUrl: "http://127.0.0.1:4318", app: "qa-node", apiKey: "test", environment: "qa", batchInterval: 0 });
   const app = express();
   app.use(middleware());
   app.use(express.json());
   app.post("/slow", async (req, res) => { await new Promise(r => setTimeout(r, 500)); res.send("ok"); });
   const srv = app.listen(3000, async () => {
     const t0 = Date.now();
     await fetch("http://127.0.0.1:3000/slow", { method: "POST", headers: { "content-type": "application/json" }, body: '{"a":1}' });
     console.log("client-measured ms:", Date.now() - t0); setTimeout(() => srv.close(), 300);
   });

3. node mw.mjs. It prints client-measured ms: 525. The mock receives $request … "duration_ms": 6.

Expected

duration_ms ≈ the time from middleware entry to response finish (≈ 500 ms here), with next() called exactly once.

Actual

Framework	Route	Response finished (ms)	Reported duration_ms	next() calls
Express 4 / 5, Node 20/22/24	GET /slow (500 ms, body never read)	500.7–501.1	501	1
Express 4 / 5	POST /slow-body + express.json() (500 ms)	505.1–508.3	5–7	1
node:http	GET /slow, POST /slow-body (body not read)	500.4–501.2	500–501	1
Fastify 5 onRequest hook	GET /slow (500 ms)	500.6–501.2	0–1	2
any	mw({ method, url }, {}, next) (object without .on, which the typings allow)	–	0	2

• GET looks right only by accident. Node emits end on an unread request body only when it discards the body after the response.
• Under Fastify, the double next() made the route handler run twice in 4 of 5 routes (handlerRuns=2 for /slow, /slow-body, /throw, /throw-async; /normal ran once; Node 20/22/24). That's the [Bug] Node middleware calls next() twice when req.on is missing #632 bug, now with a real framework that triggers it.
• Handler errors are never captured by the middleware: a sync throw or next(err) in Express → 500, and 0 /ingest/error. That's not a documented promise, so it's noted here only.

Root cause

• npm dist/index.js:36-47 (done computes Date.now() - start) and :49-52 (req.on("end", done), req.on("close", done)). It never listens to the response (_res is unused). :53-57: when req.on isn't a function, it calls next(); done(); and then falls through to another next().
• repo packages/telemetry-node/src/index.ts:66-85 (dist dist/index.js:53-61): the same.

Release coordination

Node package only, no core change needed. It can ship in the same node release as #711 / #719 (after the core release that #711 requires). Suggested fix: time on res.once("finish") / res.once("close") (fall back to req only if res has no .on), call next() exactly once on every path, and add framework tests (Express 4/5, Fastify hook, node:http).

Acceptance criteria

With the newly published @telemetry-tracker/node, on Node 20/22/24:

• Express 4 and 5 POST + express.json() + 500 ms handler: duration_ms within ±20 ms of the server-side response-finish time;
• GET unchanged;
• Fastify onRequest and plain-object calls: next() count = 1 and the route handler runs once;
• node:http unchanged.

Fix references

• Related: [Bug] Node middleware calls next() twice when req.on is missing #632 (double next() when req.on is missing). No fix yet.

History

• 2026-09-26 10:45–10:50 CEST: found and reproduced (4 frameworks × 3 Node versions).

---

Filed from the QA regression list on 2026-09-26. Source: QA report 2026-09-26-sdk-qa.md (#tt-020).