chore(api): log client-aborted requests in responseTimeLogger - #1820
Conversation
|
@Paul-AUB — heads-up that the review above appears to have landed on the wrong PR, so I haven't actioned any of it. The review header states its own target:
This PR is a single file —
Three things that may help track down the tooling issue:
Since the |
responseTimeLogger only logs on res.on('finish'), which never fires when a
client disconnects mid-flight. An aborted request therefore logged a
'Req ::' line on the way in and nothing on the way out, leaving the 499
visible only in the reverse proxy's access log. #1818 had to be
reconstructed from proxy logs for exactly this reason, and the missing
timing is what made benign instant disconnects look like slow responses:
the aborts recorded there range from 1ms to 1109ms, and nobody abandons a
2ms request.
Nothing was broken by the abort itself. The handler runs to completion and
the late write is silently discarded, so this closes an observability gap
rather than a fault.
- Log on res.on('close') when res.writableEnded is false; normal
completion also emits 'close', right after 'finish', so that guard is
what separates the two
- Report the literal 499, the nginx convention for "client closed
request", so these lines correlate with the proxy's access log
- Log at info, not error: an abort is ordinary client behaviour and must
not count against the 5xx error budget
- Track elapsed time from middleware entry instead of reading
X-Response-Time, which is unreliable here because an aborted response
often never writes its headers
Applies to every route through the shared middleware, since a client can
abandon any request, not just the full-world geoloc coordinate dumps that
surfaced it.
Closes #1818
- Add integration test mounting the real responseTimeLogger middleware - Assert an aborted request logs one line tagged 499 at info level - Assert the elapsed wait is reported and no second line is emitted - Assert a normal completion is still logged once and not as an abort
7112fcb to
0050c50
Compare
Paul-AUB
left a comment
Paul-AUB
left a comment
There was a problem hiding this comment.
Suggestions (Should Consider)
- [test/integration/4_routes/client-abort-logging.test.js:63] Consider starting the 100 ms abort timer after the server receives the request. It currently starts immediately after
http.get(), so a delayed connection or a busy CI worker can destroy the socket beforeresponseTimeLoggerruns, leavinglinesempty and making the test fail for reasons unrelated to the middleware. A signal from the handler would make the disconnect deterministic.
The close handler and its writableEnded guard behave as intended in the covered abort and normal-response cases. All seven new cases passed in an isolated Express run using the real middleware. The full integration bootstrap could not run locally because PostgreSQL refused the connection.
- Signal from the terminal handler once responseTimeLogger has run - Start the abort and settle timers from that signal, not from http.get - Reject with an explicit message if the handler is never reached A slow connect could previously destroy the socket before the middleware ran, logging nothing and failing the test for an unrelated reason.
|
Good catch, and it was a real bug rather than a theoretical one. Fixed in 766040e. I reproduced it before fixing it, by shrinking Empty The fix is the handler signal you suggested. The terminal middleware runs strictly after app.use((req, res) => {
handlerReached.emit('reached');
setTimeout(() => res.json([1, 2, 3]), HANDLER_DELAY);
});Two details beyond the literal suggestion: The settle timer is anchored on the signal too, not just the abort timer. It was also measured from A missed signal now fails loudly. If the request never reaches the handler the promise rejects with Verification, on the same On the local bootstrap — the suite needs a PostgreSQL instance; |
Paul-AUB
left a comment
Paul-AUB
left a comment
There was a problem hiding this comment.
Reviewed the current PR head (766040ee) against develop, including the change since the previous review.
The handler signal now starts both the abort and settle timers after responseTimeLogger has registered its listeners. The explicit timeout also makes a request that never reaches the handler fail clearly. This resolves my previous test timing suggestion; I found no remaining issues.
All seven focused tests passed locally against the real middleware in the isolated Express harness. The repository's full integration bootstrap was unavailable locally because PostgreSQL refused the connection.
This branch was successfully deployed
2 participants
🤔 What
Makes client-aborted requests visible in the API's own logs.
responseTimeLoggergains ares.on('close')branch alongside the existingfinishone.Res :: (client aborted) GET /path 499 101msline atinfoRes ::line (thefinishbranch is untouched)22 added lines in
config/http.jsplus one integration test, no behaviour change for normal requests.🤷♂️ Why
res.on('finish')never fires when a client disconnects mid-flight. An aborted request logged aReq ::line on the way in and nothing on the way out, so the 499 existed only in the reverse proxy's access log. chore(api): log client-aborted requests (499) in responseTimeLogger #1818 had to be reconstructed from proxy logs for exactly this reason.perf(api)against the four full-world bbox geoloc coordinate endpoints. Curling production disproved it — all four return200and complete reliably (warm connection:entrancesCoordinates308ms TTFB / 822ms total for 133 970 points,massifsCoordinates170/324ms,organizations417/420ms,networksCoordinates627/628ms; all four in parallel, 3.09s wall clock, 4× 200). The recorded aborts range from 1ms to 1109ms, and nobody abandons a 2ms request.AbortControllerin the map fetch path (packages/web-app/src/actions/Map.js), each session aborts all four endpoints in the same millisecond — the signature of leaving the page — and 1 of the 4 observed sessions isHeadlessChrome/152. The "27 aborts" are ~4 events × 4 endpoints.Worth stating plainly: this is a hygiene fix, not a stability or performance fix. Nothing was broken by the abort — the handler runs to completion and the late write is silently discarded. Nothing here makes anything faster.
🔍 How
Four decisions worth a reviewer's attention:
res.writableEndedis the discriminator. A normal response emitsclosetoo, immediately afterfinish. Verified ordering: on completionclosefires withwritableEnded === true; on abort it fires withwritableEnded === false. So the early return is the whole mechanism, and becausefinishnever fires after an abort there is no double-logging in either direction.Elapsed time is tracked from middleware entry, not read from
X-Response-Time. An aborted response often never writes its headers, so that header is unreliable precisely in the case being logged. The elapsed value is the field that separates a benign instant disconnect from a genuinely slow response someone gave up on — the distinction that was missing when #1818 was triaged.info, noterror. An abort is not a server fault and must not count against the 5xx error budget, so it deliberately does not reuse thestatusCode >= 500branch. It also does not dump the request body the way the 5xx path does.The literal
499. Not a real HTTP status — it is the nginx convention for "client closed request". Reusing it lets these lines be grepped against the proxy access log that was previously the only record.🧪 Testing
test/integration/4_routes/client-abort-logging.test.js— 7 tests, all passing. It requires the realresponseTimeLoggerout ofconfig/http.jsand mounts it on a throwaway Express app, with a handler that responds 300ms after it is reached and a client that destroys its socket 100ms after it is reached. Same directory astraceId.test.jsandsecurity-headers.test.js, which coverconfig/http.jsmiddleware the same way.A throwaway app rather than supertest against the lifted server: the abort has to land while the handler is still running, so the handler's duration has to be controlled, and supertest offers no way to destroy the socket at a chosen moment.
Asserted on abort — one line, tagged
499, atinfoand noterror, elapsed ms present, and no second line from the late discarded write. Asserted on normal completion — still exactly one line, tagged200, not misreported as an abort (this is the test that fails if theres.writableEndedguard is dropped).Both client timers are anchored on a signal from the handler, not on
http.get()(thanks @Paul-AUB). The terminal handler runs strictly afterresponseTimeLogger, so when it signals, thecloselistener is registered andstartedAtis recorded. Anchoring onhttp.get()instead meant a connect slower than the 100ms abort delay would destroy the socket before the middleware ever ran, logging nothing and failing the test for a reason unrelated to the middleware. Reproduced by setting the abort delay to 0 — 5 failures, empty capture — then 7 passing on that same configuration after the fix. The settle window is anchored the same way, so a slow connect cannot eat the margin that exists to catch a second log line. A request that never reaches the handler now rejects with an explicit message rather than hanging to mocha's timeout.Also confirmed the underlying premise directly — after the abort,
finishnever fires, the handler still runs to completion, and the late write throws nothing:eslintandprettier --checkclean on both changed files.Full suite: 3483 passing, 0 failing. That reconciles exactly against the
developbaseline of 3471 passing / 5 failing — 3476 tests, plus the 7 new ones. The 5 baseline failures (shard 0: 1, shard 3: 4, all inChanges/get-recent-comment-relevance-swap.test.js, which passes standalone) happened to pass this run, confirming they are pre-existing parallel-shard DB contention rather than anything related to this PR. Not addressed here.📸 Previews
n/a — log output only, shown above.
Related, deliberately not in this PR
networksCoordinatescosts ~630ms server-side to return 455 points / 6.9 KB — the slowest TTFB of the four while returning the least data. It andorganizationsare the two coordinate endpoints without a snapshot service. Reviewed and accepted as-is; no follow-up issue.entrancesCoordinates. True cancellation needspg_cancel_backendover a second connection; not worth that complexity at ~4 abort events/day.Map.js:57-64documents it: bulk coordinates fetched once at startup, feeding a supercluster kD-tree so panning needs no further API calls. Capping bbox area on these four, as chore(api): log client-aborted requests (499) in responseTimeLogger #1818 originally proposed, would break the map. (perf(db): geoloc entrances sort spills to disk on large bounding boxes (work_mem undersized) #1812's cap applies toGET /geoloc/entrances, a different bounded endpoint.)Map.js:57-64claims "~2.6 MB uncompressed, ~700 KB gzipped"; actual is 3.82 MB / 1.51 MB. Frontend repo.