rbrooks/Quest-Board

Watch

Fork 0

Beat extraction silently loses whole windows on the local Qwen router, and logs the failure with an empty message #572

New issue

Closed

opened 2026-09-09 06:29:43 +00:00 by claude-bot · 3 comments

claude-bot commented

2026-09-09 06:29:43 +00:00

Collaborator

Seen on the dev replay of the 2026-09-09 session (same audio and transcript as prod, qwen3.5 on the shared llama.cpp router, 5 extraction windows, 4 passes):

05:53:17 WARNING Beat extraction failed for window 4/5 (pass 1):
05:59:10 WARNING Beat extraction failed for window 2/5 (pass 2):
06:06:03 WARNING Beat extraction failed for window 4/5 (pass 2):
06:16:13 WARNING Beat extraction failed for window 4/5 (pass 3):
06:22:02 WARNING Beat extraction failed for window 2/5 (pass 4):
06:28:08 WARNING Beat extraction failed for window 4/5 (pass 4):
06:28:20 INFO    Beat validation: 27/99 beats validated across 5 window(s)

Window 4 (00:55 to 01:14, the journal, the circus crest, the cant, the whole payoff of the session) failed in every pass, so the composed summary is built with no events from that stretch, and nothing tells the GM. Window 2 failed in two of four. The failures arrive about ten minutes after each window is submitted, which points at the per-call LLM timeout rather than at the model's output; the message is empty because _extract_one_pass logs %s of the exception and an httpx timeout stringifies to nothing.

Three things to fix.

Log type(exc).__name__ and repr(exc), never bare %s, in audio_service._extract_one_pass and anywhere else a provider exception is summarised into a log line.
When a window fails in every pass, the run record should say so. summarisation_runs has capability_gaps and now hallucination_drops; a windows_failed count (or the list of failed window indices) belongs beside them, and the GM-facing summary should carry a note that a stretch of the session was not summarised, rather than reading as complete.
Decide what a slow local model should get: a longer timeout for extraction (its output length scales with the window), a smaller extraction window when the provider is local (_EXTRACTION_CONTEXT_CAP is already an env knob), or one retry of a failed window before the pass ends. Measure on the replay: window 4 is the reproducible case.

Related: #568 (summary length is set by verified beats) and the model comparison notes on #566, where the same audio verified 21 to 93 beats on hosted models with no window failures.

**Seen on the dev replay of the 2026-09-09 session** (same audio and transcript as prod, qwen3.5 on the shared llama.cpp router, 5 extraction windows, 4 passes): ``` 05:53:17 WARNING Beat extraction failed for window 4/5 (pass 1): 05:59:10 WARNING Beat extraction failed for window 2/5 (pass 2): 06:06:03 WARNING Beat extraction failed for window 4/5 (pass 2): 06:16:13 WARNING Beat extraction failed for window 4/5 (pass 3): 06:22:02 WARNING Beat extraction failed for window 2/5 (pass 4): 06:28:08 WARNING Beat extraction failed for window 4/5 (pass 4): 06:28:20 INFO Beat validation: 27/99 beats validated across 5 window(s) ``` Window 4 (00:55 to 01:14, the journal, the circus crest, the cant, the whole payoff of the session) failed in **every** pass, so the composed summary is built with no events from that stretch, and nothing tells the GM. Window 2 failed in two of four. The failures arrive about ten minutes after each window is submitted, which points at the per-call LLM timeout rather than at the model's output; the message is empty because `_extract_one_pass` logs `%s` of the exception and an httpx timeout stringifies to nothing. **Three things to fix.** 1. Log `type(exc).__name__` and `repr(exc)`, never bare `%s`, in `audio_service._extract_one_pass` and anywhere else a provider exception is summarised into a log line. 2. When a window fails in every pass, the run record should say so. `summarisation_runs` has `capability_gaps` and now `hallucination_drops`; a `windows_failed` count (or the list of failed window indices) belongs beside them, and the GM-facing summary should carry a note that a stretch of the session was not summarised, rather than reading as complete. 3. Decide what a slow local model should get: a longer timeout for extraction (its output length scales with the window), a smaller extraction window when the provider is local (`_EXTRACTION_CONTEXT_CAP` is already an env knob), or one retry of a failed window before the pass ends. Measure on the replay: window 4 is the reproducible case. Related: #568 (summary length is set by verified beats) and the model comparison notes on #566, where the same audio verified 21 to 93 beats on hosted models with no window failures.

claude-bot commented

2026-09-09 06:43:33 +00:00

Author

Collaborator

Two refinements from the completed replay (run 1h13m: 26 min transcription, 47 min summarisation, 17 LLM calls, 178k prompt tokens):

The failing windows are not necessarily timeouts. The delegate that ran the replay read the router's behaviour as an empty response for those windows, consistent with the standing note that this llama.cpp endpoint returns empty content under some output-length conditions. Fix 1 (log the exception type and repr) settles it either way; until then the ten-minute cadence is the only evidence.
Because window 4 never contributed, the composed summary has nothing from the journal, the circus crest or the cant, and reads as if the session ended at the cave mouth. The GM-visible gap note in fix 2 is the important part.

Also observed during the same run, filed separately: one summarisation-stage prompt of ~31k tokens was sent against a 22.9k budget (#575), the provider-slot cap is silently disabled in the post-session fan-out because the event loop is already closed (#573), and clean_term strips the closing parenthesis from "Viquilonto (Viq)" before it reaches Whisper (#574).

Two refinements from the completed replay (run 1h13m: 26 min transcription, 47 min summarisation, 17 LLM calls, 178k prompt tokens): - The failing windows are not necessarily timeouts. The delegate that ran the replay read the router's behaviour as an **empty response** for those windows, consistent with the standing note that this llama.cpp endpoint returns empty content under some output-length conditions. Fix 1 (log the exception type and repr) settles it either way; until then the ten-minute cadence is the only evidence. - Because window 4 never contributed, the composed summary has nothing from the journal, the circus crest or the cant, and reads as if the session ended at the cave mouth. The GM-visible gap note in fix 2 is the important part. Also observed during the same run, filed separately: one summarisation-stage prompt of ~31k tokens was sent against a 22.9k budget (#575), the provider-slot cap is silently disabled in the post-session fan-out because the event loop is already closed (#573), and `clean_term` strips the closing parenthesis from "Viquilonto (Viq)" before it reaches Whisper (#574).

claude-bot referenced this issue

2026-09-09 07:27:57 +00:00

Drop Whisper hallucination segments before the transcript is merged #569

rbrooks referenced this issue from a commit

2026-09-09 17:35:02 +00:00

fix(backend): retry, record and report a window beat extraction cannot read (#572)

rbrooks referenced this issue from a commit

2026-09-09 17:35:37 +00:00

fix(backend): retry, record and report a window beat extraction cannot read (#572)

claude-bot referenced this issue

2026-09-09 17:35:50 +00:00

fix(backend): four summarisation-pipeline defects found by replaying a real session (#566, #567, #572, #575) #583

claude-bot referenced this issue from a commit

2026-09-09 17:52:35 +00:00

Merge PR #583: fix(backend): four summarisation-pipeline defects found by replaying a real session (#566, #567, #572, #575)

claude-bot commented

2026-09-09 18:38:32 +00:00

Author

Collaborator

Measured after #583 on the dev replay (same audio, qwen3.5 9B): four passes, windows_failed = [], no window errored; window 5 (the post-game chatter) now logs "returned no beats … an answer, not a failure" on every pass instead of looking like a loss. Critic count 0 (#567), the highlights call ran windowed with no over-budget warning (#575), and the composed summary follows session order (#566). 19 of 30 beats verified; the remaining errors in the prose (the party placed in Ironroot Hold, a Foundry token glitch narrated as an event) are the model's, not the pipeline's.

Measured after #583 on the dev replay (same audio, qwen3.5 9B): four passes, `windows_failed = []`, no window errored; window 5 (the post-game chatter) now logs "returned no beats … an answer, not a failure" on every pass instead of looking like a loss. Critic count 0 (#567), the highlights call ran windowed with no over-budget warning (#575), and the composed summary follows session order (#566). 19 of 30 beats verified; the remaining errors in the prose (the party placed *in* Ironroot Hold, a Foundry token glitch narrated as an event) are the model's, not the pipeline's.

claude-bot referenced this issue

2026-09-12 02:43:35 +00:00

fix(webapp): recover from a context-window rejection instead of losing the window (#614, #613) #615

claude-bot commented

2026-09-12 19:41:35 +00:00

Author

Collaborator

Closing — this was fixed by #583 (commit e505d3f, "retry, record and report a window beat extraction cannot read") and never closed afterwards. Verified against main today rather than taken from the replay comment above:

Fix 1 — the empty log line. _extract_one_pass now names the exception type and repr, and its docstring calls out the original failure directly: "The line ended in %s of the exception, which for a provider error carrying no message — llama.cpp's, routinely — printed Beat extraction failed for window 4/5 (pass 1): and stopped." It also distinguishes "the model returned nothing parseable" from "the call raised", which the original line could not.

Fix 2 — the run record and the GM-facing note. summarisation_runs.windows_failed exists as a JSONB column (migration 7c8d9e0f1a2b), carried through the model, schema, session_beat_service and summary_recompose_service. It is a list of window indices rather than a count, and note_unsummarised_windows turns those into a plain sentence appended to the summary prose — placed before the hook when there is one — so a session with a lost stretch no longer reads as complete.

Fix 3 — what a slow local model gets. Decided as one retry, with the reasoning recorded at the constant:

_WINDOW_ATTEMPTS = 2 — "One retry, not a policy: the failures this exists for are intermittent — on the session that motivated it, window 4 of 5 failed on every pass while its neighbours went through against the same endpoint, the same model and the same prompt shape."

A ContextWindowExceededError is deliberately excluded from that retry (#613/#614) and re-split instead, since asking again with the same oversized prompt spends a call to learn nothing.

tests/test_failed_windows.py covers all three — a provider error with no message naming itself, an empty answer not being reported as a failure, the retry happening, an answered window never being called twice, the lost index reaching both the run and the API response, and the note's placement relative to the hook. 91 tests pass on main today (with test_highlights.py and test_empty_hook.py).

Closing — this was fixed by **#583** (commit `e505d3f`, "retry, record and report a window beat extraction cannot read") and never closed afterwards. Verified against `main` today rather than taken from the replay comment above: **Fix 1 — the empty log line.** `_extract_one_pass` now names the exception type and repr, and its docstring calls out the original failure directly: *"The line ended in `%s` of the exception, which for a provider error carrying no message — llama.cpp's, routinely — printed `Beat extraction failed for window 4/5 (pass 1): ` and stopped."* It also distinguishes "the model returned nothing parseable" from "the call raised", which the original line could not. **Fix 2 — the run record and the GM-facing note.** `summarisation_runs.windows_failed` exists as a JSONB column (migration `7c8d9e0f1a2b`), carried through the model, schema, `session_beat_service` and `summary_recompose_service`. It is a list of window indices rather than a count, and `note_unsummarised_windows` turns those into a plain sentence appended to the summary prose — placed before the hook when there is one — so a session with a lost stretch no longer reads as complete. **Fix 3 — what a slow local model gets.** Decided as one retry, with the reasoning recorded at the constant: > `_WINDOW_ATTEMPTS = 2` — *"One retry, not a policy: the failures this exists for are intermittent — on the session that motivated it, window 4 of 5 failed on every pass while its neighbours went through against the same endpoint, the same model and the same prompt shape."* A `ContextWindowExceededError` is deliberately excluded from that retry (#613/#614) and re-split instead, since asking again with the same oversized prompt spends a call to learn nothing. `tests/test_failed_windows.py` covers all three — a provider error with no message naming itself, an empty answer *not* being reported as a failure, the retry happening, an answered window never being called twice, the lost index reaching both the run and the API response, and the note's placement relative to the hook. 91 tests pass on `main` today (with `test_highlights.py` and `test_empty_hook.py`).

claude-bot closed this issue

2026-09-12 19:41:38 +00:00

claude-bot referenced this issue

2026-09-12 19:41:48 +00:00

A summarisation-stage prompt of ~31k tokens was sent against a 22.9k budget; find the call and chunk it #575