A streamed turn logs nothing when it ends, so it cannot be diagnosed afterwards #268

New Issue

grenade · 2026-08-19T13:37:50Z

grenade commented

2026-08-19 13:37:50 +00:00

A non-streaming request closes its journal trail with everything an
operator needs:

INFO tp_chat{req_id=a68df6}: TP chat_completion: done
     prompt_tokens=15 completion_tokens=2 finish_reason=stop total_ms=100779

A streamed request logs nothing at all. No token counts, no
finish_reason, no duration. The trail simply stops after prefill, and
whether the turn finished cleanly, hit its output cap, or was abandoned
by a disconnecting client is unrecoverable from the journal.

Streaming is the path essentially every interactive client uses, so the
requests we can least reconstruct are the ones most likely to go wrong.

What it cost

This is not theoretical — it is the single largest reason the 2026-08-19
investigation (#267) took a morning:

Twice I concluded "no work is happening" from an absence of log
lines, when the batch-engine decode path simply emits none per token.
The daemon was healthy and decoding both times. One of those wrong
conclusions was published as a root-cause analysis and had to be
retracted.
With the fixes deployed, a dsh turn wrote two of three files and
stopped. Whether it exhausted max_new or ended some other way could
not be answered from the server at all — only guessed from file
timestamps and an in_flight count dropping.

Absence of logging is being read as absence of work, by humans and by
machines, and it is correct to read it that way — nothing distinguishes
"quiet because finished" from "quiet because wedged".

Fix

Emit the same completion line the non-streaming path emits, at the end
of a streamed turn: prompt_tokens, completion_tokens,
reasoning_tokens, finish_reason, and elapsed time.

It should fire on every terminal outcome, not just clean completion —
stop, length, tool-call finish, admission rejection, and client
disconnect. The disconnect case matters most: an abandoned request runs
to completion holding its permit and the TP pool lock, and today that
happens silently.

The InferenceEvent::Finish variant already carries
reason / prompt_tokens / completion_tokens / reasoning_tokens / timing,
so the data is in hand at the right moment — this is a logging call at
the point the projection already handles Finish, not new
instrumentation.

Worth logging the request's peak in_flight or its admission wait too,
so a slow turn can be attributed to contention versus generation without
correlating against /health polls after the fact.

Related: #267 (the investigation this obstructed), #98 (the batch engine
whose decode path is silent), #137 (metrics — the aggregate view; this is
the per-request view that no metric can replace).

A non-streaming request closes its journal trail with everything an operator needs: ``` INFO tp_chat{req_id=a68df6}: TP chat_completion: done prompt_tokens=15 completion_tokens=2 finish_reason=stop total_ms=100779 ``` A **streamed** request logs nothing at all. No token counts, no `finish_reason`, no duration. The trail simply stops after prefill, and whether the turn finished cleanly, hit its output cap, or was abandoned by a disconnecting client is unrecoverable from the journal. Streaming is the path essentially every interactive client uses, so the requests we can least reconstruct are the ones most likely to go wrong. ## What it cost This is not theoretical — it is the single largest reason the 2026-08-19 investigation (#267) took a morning: - **Twice** I concluded "no work is happening" from an absence of log lines, when the batch-engine decode path simply emits none per token. The daemon was healthy and decoding both times. One of those wrong conclusions was published as a root-cause analysis and had to be retracted. - With the fixes deployed, a dsh turn wrote two of three files and stopped. Whether it exhausted `max_new` or ended some other way could not be answered from the server at all — only guessed from file timestamps and an `in_flight` count dropping. Absence of logging is being read as absence of work, by humans and by machines, and it is correct to read it that way — nothing distinguishes "quiet because finished" from "quiet because wedged". ## Fix Emit the same completion line the non-streaming path emits, at the end of a streamed turn: `prompt_tokens`, `completion_tokens`, `reasoning_tokens`, `finish_reason`, and elapsed time. It should fire on **every** terminal outcome, not just clean completion — `stop`, `length`, tool-call finish, admission rejection, and client disconnect. The disconnect case matters most: an abandoned request runs to completion holding its permit and the TP pool lock, and today that happens silently. The `InferenceEvent::Finish` variant already carries `reason / prompt_tokens / completion_tokens / reasoning_tokens / timing`, so the data is in hand at the right moment — this is a logging call at the point the projection already handles `Finish`, not new instrumentation. Worth logging the request's peak `in_flight` or its admission wait too, so a slow turn can be attributed to contention versus generation without correlating against `/health` polls after the fact. Related: #267 (the investigation this obstructed), #98 (the batch engine whose decode path is silent), #137 (metrics — the aggregate view; this is the per-request view that no metric can replace).

grenade referenced this issue from a commit

2026-08-19 13:43:18 +00:00

fix(neuron): a streamed turn now says how it ended

grenade referenced this issue from a commit

2026-08-19 14:21:18 +00:00

fix(neuron): cover the CUDA-only streaming paths

grenade closed this issue

2026-08-19 14:41:35 +00:00

grenade referenced this issue

2026-08-19 15:14:00 +00:00

[epic] Sampling correctness: honour the caller's parameters and the model's own generation_config #271

Sign in to join this conversation.