Description
Hi! I happened to hit this while using @vercel/resumable-stream, but it's not specific to that library:
I have a NestJS streaming handler where the interesting log data (usage accounting, final state, etc.) is computed once the stream's producer finishes. If the client disconnects mid-stream, the producer keeps running and finishes after res has already closed: the wide event log is then never emitted at all.
This isn't specific to streaming. The same thing happens in any slow handler where the client disconnects before res.end() (see reproduction).
Looking into it, the root of the "nothing gets emitted" behaviour seems to be in evlog/nestjs (same pattern in evlog/express):
|
res.on('finish', () => { |
|
finish({ status: res.statusCode }).catch(() => {}) |
|
}) |
The middleware only listens for the finish event. When the client disconnects before res.end(), Node emits close so finish() is not invoked.
The obvious fix is to listen on close too. However, doing only that would break the streaming case: the auto-emit would fire the moment the client disconnects, before the stream producer has finished, and the usage log would consistently land on a logger that has already emitted and get dropped.
For now, I came up with this workaround:
res.once("close", async () => {
if (!res.writableEnded) {
await finished; // wait for the producer
log.set({ connectionClosed: true });
log.emit(); // manual emit
}
});
So there are really two things going on: the middleware not listening to close, and the bigger question of what evlog should do when the work outlives the response.
Happy to provide a full repro or open a PR if that helps.
Thanks!
Reproduction
A simplified version of the stream handler:
@Post("resumable_stream")
async resumable_stream(@Res() res: Response) {
const log = useLogger();
log.set({ endpoint: "resumable_stream" });
const { stream, finished } = buildStream(); // `finished` resolves when the producer is done
// The log line I actually care about (with usage, final state, billing, etc.)
finished.then(() => {
log.set({ usage: { tokens: 1234 } });
});
res.writeHead(200, { "Content-Type": "text/plain" });
Readable.fromWeb(stream).pipe(res);
}
What I observed is that, when the client disconnects mid-stream (e.g. curl --max-time 2), res closes before the producer is done, the auto-emit never fires, and by the time finished resolves the logger context is already gone, so no wide event is emitted at all for that request, and the usage log is lost.
An even simpler reproduction:
@Get("slow")
async slow() {
const log = useLogger();
log.set({ step1_at: new Date().toISOString() });
await sleep(1000);
log.set({ step2_at: new Date().toISOString() });
await sleep(1000);
log.set({ step3_at: new Date().toISOString() });
await sleep(1000);
return { ok: true };
}
If the client hangs on long enough (curl --max-time 5), the wide event is emitted with all three steps. If they drop early (curl --max-time 1.5), the handler keeps executing in the background, but no wide event is ever emitted.
Logs
No response
Description
Hi! I happened to hit this while using
@vercel/resumable-stream, but it's not specific to that library:I have a NestJS streaming handler where the interesting log data (usage accounting, final state, etc.) is computed once the stream's producer finishes. If the client disconnects mid-stream, the producer keeps running and finishes after
reshas already closed: the wide event log is then never emitted at all.This isn't specific to streaming. The same thing happens in any slow handler where the client disconnects before
res.end()(see reproduction).Looking into it, the root of the "nothing gets emitted" behaviour seems to be in
evlog/nestjs(same pattern inevlog/express):evlog/packages/evlog/src/nestjs/index.ts
Lines 62 to 64 in e33ba92
The middleware only listens for the
finishevent. When the client disconnects beforeres.end(), Node emitsclosesofinish()is not invoked.The obvious fix is to listen on
closetoo. However, doing only that would break the streaming case: the auto-emit would fire the moment the client disconnects, before the stream producer has finished, and theusagelog would consistently land on a logger that has already emitted and get dropped.For now, I came up with this workaround:
So there are really two things going on: the middleware not listening to
close, and the bigger question of what evlog should do when the work outlives the response.Happy to provide a full repro or open a PR if that helps.
Thanks!
Reproduction
A simplified version of the stream handler:
What I observed is that, when the client disconnects mid-stream (e.g.
curl --max-time 2),rescloses before the producer is done, the auto-emit never fires, and by the timefinishedresolves the logger context is already gone, so no wide event is emitted at all for that request, and theusagelog is lost.An even simpler reproduction:
If the client hangs on long enough (
curl --max-time 5), the wide event is emitted with all three steps. If they drop early (curl --max-time 1.5), the handler keeps executing in the background, but no wide event is ever emitted.Logs
No response