[Backend] Hardware preflight's LLM probe fails on reasoning models, so the profile reads "Not measured" (#354) #507
Closed
opened 2026-09-05 07:31:47 +00:00 by claude-bot
·
5 comments
No Branch/Tag specified
main
feat/1328-fill-it-in
feat/1328-fill-frontend
feat/1328-fill-backend
feat/9-foundry-push
fix/9-foundry-live
feat/9-foundry-push-frontend
renovate/celery-5.x
feat/5-foundry-connect
feat/9-foundry-push-backend
feat/9-foundry-push-module
feat/5-foundry-frontend
feat/5-foundry-backend
feat/5-foundry-module
release/v4.8.0-rc1
docs/d341-convert-draft
feat/958-update-to-version
feat/958-convert-sheet
feat/958-pathbuilder-import-frontend
fix/1360-heading-order
feat/958-pathbuilder-import-backend
feat/11-weekly-digest
feat/1341-auto-update
docs/d332-superseded
chore/1345-names-cleanup
feat/1342-mentioned-pages
feat/1328-recipes
fix/1346-pgdg-key
perf/1247-shared-recording-stream
chore/132-gitleaks-allowlist
release/v4.7.1
spike/foundry-module
release/v4.7.1-rc1
docs/decisions-d332-d337
fix/bot-certifi
chore/release-4.7.0
chore/release-4.7.0-rc4
chore/deps-4.7.0
chore/release-4.7.0-rc3
fix/1280-quote-must-say-it
fix/1257-names-row-squeeze
chore/release-4.7.0-rc2
fix/1245-pg-upgrade-count
chore/release-4.7.0-rc1
feat/1257-names-in-prep
feat/1257-be
feat/1257-fe
feat/1257-rating-fixes
design/1328-fill-it-in
feat/1257-name-splits
fix/1326-redis-503
feat/1280-fact-suggestions
feat/1280-be
feat/1280-fe
design/1280-fact-suggestions
feat/1279-infobox
feat/1279-be
feat/1279-fe
feat/1321-shelf-copies
design/1279-infobox
feat/1243-table-find
feat/1257-who-rated
feat/1243-prep-drawer
feat/1243-sheet-pickers
design/1243-browse-in-place
feat/1315-hotwords-default
feat/1242-system-filters
feat/1257-more-name-styles
feat/506-leg3-hotwords
design/1242-system-filters
fix/1302-packs-polish
feat/1241-rules-library
design/1241-rules-library
feat/1245-postgres-18
integ/4.6.2
fix/1263-map-ui-2
fix/1263-map-server
fix/1263-map-ui-1
fix/1261-editor-link-menu
fix/1229-axe-4.14-name-mismatch
renovate/axllent-mailpit-1.x
renovate/eslint-monorepo
renovate/authlib-1.x
chore/release-4.6.0
chore/release-4.6.0-rc2
fix/460-rc2-screens
fix/460-rc2-server
fix/release-prerelease-exit
chore/release-4.6.0-rc1
feat/125-campaign-templates
feat/126-calendar
feat/1181-pictures-and-files
feat/1190-event-people
integ/4.6.0
feat/1191-line-of-the-night
feat/1200-starter-packs
chore/bot-multidict-and-playwright-group
fix/1202-this-week-answered-count
fix/122-124-leftovers
fix/1178-get-routes-that-write
fix/1203-journeys-check-names
design/125-campaign-templates
feat/126-calendar-engine
design/126-in-world-calendar
fix/1189-cited-stamp-in-range
fix/1189-v4-looser-check
fix/1189-richer-beats
fix/1113-export-bind-lists
fix/1154-release-notes-by-file
chore/release-4.5.0
chore/release-4.5.0-rc12
fix/1135-wiki-markup-as-text
fix/demo-usage-cost-in-window
chore/release-4.5.0-rc11
fix/1121-sheet-consistency
fix/1121-sheet-5e-terms-and-card-hp
copy/1122-busiest-pages
fix/1121-relevant-choices
fix/1121-wiki-create-npc-save-sheet-links
fix/1029-menu-stays-on-screen
docs/prototype-transcript-bin-wording
fix/1023-editor-save-row-back-scroll
fix/1020-search-exact-first
fix/1020-table-prep
fix/1020-shell-wordmark-footer-bell
fix/1020-wiki-article-party
fix/872-admin-kept-until-phone-tables
feat/l13-milestone-level-waiting
fix/1000-1001-bell-older-setup-context
fix/999-pronouns-in-prompts
fix/l19-other-class-feats
fix/1010-transcript-window-ordinary-confirm
docs/d254-d269-decisions
fix/702-member-search
fix/680-transcript-bin
fix/993-unidentified-prompts
fix/841-redis-timeouts
fix/990-binned-not-exported
fix/830-export-prep-shelf
fix/deps-audit-2026-10-01
fix/877-title-reads
fix/798-audio-received-at
build/lane11-17-j7
build/lane11-16-levelup
build/lane11-14-seams
build/lane11-14-seed
build/lane11-15-start
build/lane11-13-old-block-out
fix/980-review-r3
build/lane11-12-block
build/lane11-8-packs
fix/demo-seed-canonical-names
build/lane11-11-hot-half
docs/l11-decisions
build/lane11-7-convert
build/lane11-10-editing
fix/npm-audit-brace-expansion
build/lane11-9-sheet-page
fix/bot-pyjwt
build/lane11-6-content
fix/lane11-rank-names
build/lane11-2b-language
build/lane11-4-js-evaluator
build/lane11-3-server
build/lane11-5a-pf2e
build/lane11-5b-5e
feat/design-admin
build/lane11-2-evaluator
build/lane11-1-sheet-pieces
build/lane11-0-drawing
fix/943-quest-objectives-fk
fix/prepsheet-shelf-flake
fix/945-leftovers
build/demo-gm-copy
fix/901-email-landings
build/lane10-8-journeys
build/demo-seed-lanes-8-10
fix/887-gm-own-confirmation
build/lane9-5-j1-admin
fix/918-audience-click
fix/useasync-overtaken
ci/939-critical-path
test/937-backend-suite-speed
chore/claude-orchestration
fix/924-xp-gm-only
fix/session-stale-poll
docs/decisions-d239-d242
fix/930-pypdf
build/lane8-journeys
build/925-quest-editor
fix/894-private-page-pictures
build/lane8-p4-drafts
build/lane8-p7-map
build/lane8-p6-handouts-rules
fix/wiki-fixture-names
build/lane10-d227-test-usage
fix/rsvp-horizon-test-tuesday
fix/media-volume-owner
build/lane8-p3-editor
fix/912-unidentified-rename
build/lane8-p5-party-quests
build/lane8-handout-takeback
build/lane10-pickers
build/lane8-p2-article
build/lane8-6-map
build/lane10-7b-email-pages
build/lane8-5-handouts
build/lane10-7a-test-the-bot-pages
build/lane8-p1-pages
build/lane8-4-quests
build/lane8-2b-feeds
build/lane8-3-parties
build/lane8-2a-links
build/lane10-5-commands
build/lane9-6-seed
build/lane10-4b-reactions
build/lane9-4d-pages
build/lane9-4c-pages
build/lane10-4a-posts
build/lane10-3-email
fix/891-web-fonts
build/lane9-4b-pages
build/lane10-6-test-the-bot
build/lane10-2-notify-out
build/lane8-1-wiki-text
build/lane9-4a-frame
design/lane10-drawings
fix/j6-budget
fix/j5-phone-flake
fix/869-test-leaks
fix/843-record-start-followups
build/lane7-all
build/lane6-all
build/lane9-b2-server
chore/changelog-fragments
docs/decisions-d218
build/lane9-a-owner-overview
fix/rule-card-level-label
fix/834-retention-semantics
fix/o3c-record-without-announcement
docs/decisions-d179
docs/decisions-d131-d170
fix/851-commit-before-response
build/lane6-j3-seed
build/lane9-b1-d67-identity
fix/841-blocking-loop
build/lane9-c-backups-audit
fix/vote-race-and-start-commit
fix/recording-announcement
fix/proposal-read-leak
fix/last-admin-guard
build/lane6-p4c-planning
build/lane6-p4b-margin
build/lane6-p4a-sheet
build/lane5-j4-seed
build/lane6-base
build/lane7-pages-talk
build/lane5-pages
build/lane7-pages-safety
build/lane7-p3-safety
build/lane7-p2-notify
build/lane6-p3-planning
build/lane6-p2-history
build/lane6-p1b-items
build/lane7-p1-threads
build/lane5-p6-faces
build/lane6-p1a-sheet
build/lane5-p5-find
build/lane5-p4a-board
build/lane5-p4b-scenes
build/lane5-p3-live
build/lane5-base
build/lane5-p2-cards
docs/lane5-decisions
build/review-r2-wide
fix/review-r1
build/lane5-p1-scenes
build/demo-seed
build/lane4-journeys-j5
build/lane4-page-review-b
build/lane4-page-review-a
build/lane4-page-read
build/lane4-journeys
build/lane4-page-sess2
build/lane4-page-sess1
build/lane4-notes
build/lane4-discord-on-approval
build/lane4-scheduling
build/lane4-versions
build/760-session-number
build/lane4-decisions
build/797-erase-no-regenerate
build/test-race-audit
build/lane3-completions
build/794-dark-only
build/796-titles-scroll
build/791-retention-anchor
build/a11y-sweep
build/shell-followups
build/retention-preview
build/753-backup-readback
docs/d91-d93
build/lane3-j1
build/ci-harness-paths-selftest
fix/useauth-test-race
build/ci-harness-paths
build/777-ai-settings-read
build/lane3-settings-c
build/lane3-settings-b
build/lane3-j6
build/lane3-sessionform
build/lane3-settings-a
build/lane3-members
build/lane3-thisweek
build/lane3-story
chore/87-align-python-3.12
v4.8.0-rc1
v4.7.1
v4.7.1-rc1
v4.7.0
v4.7.0-rc4
v4.7.0-rc3
v4.7.0-rc2
v4.7.0-rc1
v4.6.2
v4.6.2-rc4
v4.6.2-rc3
v4.6.2-rc2
v4.6.2-rc1
v4.6.1
v4.6.1-rc1
v4.6.0
v4.6.0-rc2
v4.6.0-rc1
v4.5.3
v4.5.3-rc1
v4.5.2
v4.5.2-rc1
v4.5.1
v4.5.1-rc2
v4.5.1-rc1
v4.5.0
v4.5.0-rc12
v4.5.0-rc11
v4.5.0-rc10
v4.5.0-rc9
v4.5.0-rc8
v4.5.0-rc7
v4.5.0-rc6
v4.5.0-rc5
v4.5.0-rc4
v4.5.0-rc3
v4.5.0-rc2
v4.5.0-rc1
v4.4.1
v4.4.0
v4.3.0
v4.2.3
v4.2.2
v4.2.1
v4.2.0
v4.1.2
v4.1.1
v4.1.0
v4.0.1
v4.0.0
v3.11.4
v3.11.3
v3.11.2
v3.11.1
v3.11.0
v3.10.0
v3.9.1
v3.9.0
v3.8.0
v3.7.0
v3.6.1
v3.6.0
v3.5.0
v3.4.1
v3.4.0
v3.3.0
v3.2.0
v3.1.0
v3.0.0
v2.1.0
v2.0.0
v1.1.0
v1.0.0
v0.12.0
v0.11.0
v0.10.0
v0.9.1
v0.3.3
v0.9.0
v0.8.0
v0.3.2
v0.3.1
v0.3.0
v0.7.0
v0.6.0
v0.5.0
v0.4.0
v0.2.1
v0.2.0
v0.1.1
v0.1.0
Labels
Clear labels
backend
Issue related to the backend
bot
Issue related to the bot
bug
Something is not working
duplicate
This issue or pull request already exists
enhancement
New feature
frontend
Issue related to the frontend
help wanted
Need some help
invalid
Something is wrong
question
More information is needed
recording
Issue related to the recording system
security
Security hardening / vulnerability work
wontfix
This won't be fixed
No labels
backend
bot
bug
duplicate
enhancement
frontend
help wanted
invalid
question
recording
security
wontfix
Milestone
Clear milestone
No items
No milestone
Projects
Clear projects
No items
No project
Assignees
Clear assignees
No assignees
1 participant
Notifications
Due date
The due date is invalid or out of range. Please use the format "yyyy-mm-dd".
No due date set.
Dependencies
No dependencies set
Reference
rbrooks/Quest-Board#507
Loading…
Reference in a new issue
No description provided.
Delete branch "%!s()"
Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?
Found validating v4.2.0 on dev (2026-09-05), against the bundled llama.cpp endpoint running
qwen3.5.run_preflight(#354) stores this for the LLM half:The ASR half is fine (realtime factor 0.12, retained fraction 0.12, basis "measured over the last 2 run(s)", which means it correctly consumed the #357 usage rows). The failure is specific to the probe's token budget: the same endpoint summarised two full synthetic sessions (12 LLM calls) and passed the #359 canary in the same hour. Capability discovery already flags
reasoning: truefor this model, so the probe is asking a thinking model for prose inside a budget its hidden reasoning consumes. This is the same endpoint property recorded earlier: prose needsmax_tokensunset or well above 512.Effect: any self-hoster on a reasoning model behind llama.cpp gets "Not measured" and no timeout profile, and the Admin → AI → Preflight panel shows an error for a configuration that works.
Proposed fix, in order of preference:
reasoning, raise the probe'smax_tokensto what a thinking model needs (or leave it unset) and measure tokens per second on the visible completion only.max_tokensfor everyone and accept a slower probe.The error message is already right; it just should not be the normal outcome on the default self-hosted stack. Patch-sized, wants to go out in v4.2.1.
Picking this up for v4.2.1. Approach:
probe_llmreads the resolved provider's declaredreasoningcapability and, when set, gives the probe the budget a thinking model needs instead ofPROBE_MAX_TOKENS = 128; as a belt-and-braces path, a probe that hits the length limit with no visible text on a provider that did not declare reasoning retries once with the larger budget. Tokens per second is measured on what the provider reports as completion tokens, which on llama.cpp includes the reasoning tokens, and that is the right figure for extrapolating session time because the summariser pays for them too. Tests assert themax_tokensthe probe sends for a reasoning and a non-reasoning provider.Fixed in PR #509 (merged), shipping in v4.2.1.
The probe's output cap was a constant when it is really a capability question. 128 tokens is not a short answer for a thinking model, it is no answer at all: the hidden reasoning spends the whole budget before the first visible word, and llama.cpp returns
finish_reason='length'with empty content. On the bundled stack with qwen3.5, the default self-hosted configuration, that failed every time.Providers already declare this (
LlmCapabilities.reasoning), so the declaration now chooses the budget:PROBE_MAX_TOKENS_REASONING = 2048where it is declared, the cheap 128 everywhere else, resolved throughllm_provider_foron the config like every generation path and never sniffed from the URL. Bounded rather thanmax_tokens=None, because an uncapped generation is unbounded in time on exactly the slow hardware the preflight exists to describe, and 2048 still fits inside the deadline at the slowest rate the bands call viable.The declaration is per adapter and the model is the operator's choice, so a provider that declared no reasoning and ran out of budget anyway (the OpenAI adapter pointed at an o-series model, Ollama serving qwen3) is retried exactly once with the larger budget, and the result records
retried_with_reasoning_budgetso the panel can explain why that measurement took twice as long. One retry, never a loop.Detection is structural, not textual:
llm_service.OutputBudgetExhausted(aRuntimeErrorsubclass, so every existing caller and test is unchanged) types the llama.cpp raise, andUsageMeternow keeps the truncation flagUsagehas always carried per call, which is how the transports that return an empty string instead of raising are recognised.tokens_per_secondstill counts reasoning tokens, since they decode at the same rate and a real summarisation run pays for them through the same meter.Residual, recorded rather than fixed: a sub-10 tok/s box running a thinking model can now hit the HTTP deadline instead of returning empty. That is a different failure message for a box that could not be measured before either, and once a run classifies it CPU the deadlines are 6×.
Nine new tests assert on the
max_tokensthat goes over the wire through the existing mock transport, not on a patchedgenerate_structured_text. Full backend suite 2321 passed / 13 skipped, frontend 505 passed, ruff and eslint clean. Verify on dev after the v4.2.1 deploy: Admin → AI → Preflight should show a measured LLM rate and a profile band instead of "Not measured".Reopening: the v4.2.1 fix does not hold on the bundled stack. Live on dev after the v4.2.1 deploy,
run_preflightproduced:and the transport log line underneath:
llama.cpp returned empty content (finish_reason='length', usage={'completion_tokens': 2048, 'prompt_tokens': 197, 'total_tokens': 2245, ...}).So the declaration was honoured (
reasoning: true, budget 2048) and qwen3.5 still spent the entire 2048 tokens thinking. Raising the cap further is the wrong lever: it is unbounded on this prompt, and a cap large enough for a 3090 is a deadline timeout on a CPU box.The evidence also contains the fix. The endpoint reported 2048 completion tokens in 60.9 s, which is 33.6 tokens per second, and that is the measurement the preflight exists to take. Reasoning tokens decode at the same rate as visible ones, and a real summarisation run pays for them through the same meter (the point already made in the v4.2.1 comment). The probe was discarding a perfectly good throughput sample because the model had not finished its sentence.
Fix forward for v4.2.2: an exhausted output budget that comes with reported completion tokens is a successful rate measurement, with a separate flag saying no visible text was produced. The reasoning budget can then be modest (a few hundred tokens is a long enough decode sample and stays inside the deadline at CPU speeds); the retry for undeclared reasoning providers stays. The usage on the raise path must reach the meter or the exception, which is what the empty
completion_tokens: nullabove shows it currently does not.v4.2.1 is tagged and on dev; it is not going to prod. v4.2.2 will carry this and go to both.
Fixed for real in PR #512, shipping as v4.2.2. Verified live on dev.
The premise of the v4.2.1 fix was wrong rather than its number. Against llama.cpp serving qwen3.5 the probe spent all 2048 tokens thinking (60.9 s,
finish_reason='length', no visible text) and reported "Not measured" a second time. Raising the cap further is no lever at all: the thinking is unbounded on this prompt, and any budget a 3090 can finish inside is a deadline timeout on a CPU box. But 2048 tokens in 60.9 s is 33.6 tok/s, which is the only figure the preflight exists to obtain. Reasoning tokens decode at the same rate as visible ones andmeasure_llm_tokens_per_runalready counts them through the same meter. The probe was discarding a good throughput sample because the model had not finished its sentence.What changed:
OutputBudgetExhausted. It was the only transport raising ahead of_check_usage, which is why the probe sawcompletion_tokens: nullwhile the transport's own log line printed 2048. Recorded directly rather than through_check_usage, which underjson_moderaises before reaching the meter and would replace the typed exception. Session cost telemetry gains these tokens too, previously invisible GPU time.ok: true,visible_text: false, rate filled in,error: "", plus anotesaying where the sample came from. An exhausted budget with no usage staysok: falsewith the error, so a broken endpoint still reads as broken.PROBE_MAX_TOKENS_REASONING2048 → 512: a rate sample, not room for an answer (about 100 s at 5 tok/s, inside the 300 s deadline).PROBE_MAX_TOKENSstays 128, the single retry for undeclared reasoning providers stays, and the retry never replaces a measurement with a failure.run_preflightalready read the rate rather thanprobe["ok"], so the band, expected-session estimate and timeout profile follow; now stated in the code and covered end to end. Admin → Hardware profile explains a rate measured without a finished answer.Live on dev, v4.2.2, same endpoint that failed twice before:
The 512-token sample reads 25.4 tok/s against 33.6 for the 2048-token one, which is the per-request overhead the retry comment predicted; it errs conservative, which is the right direction for a timeout profile. Backend 2335 passed / 13 skipped, frontend 509 passed, ruff and eslint clean. Closing once prod is on v4.2.2 and shows the same.
Prod is on v4.2.2 (17:28 UTC) and shows the same. Preflight against prod's own configuration:
ok: true,visible_text: false, 512 tokens in 24.7 s → 20.75 tok/s, profilemodest("Modest GPU or fast CPU"), expected LLM time for a 3.5-hour session 578 s. The ASR half reads "not yet measured" there only because prod has no usage rows yet (its sessions predate #357); the first processed session fills it in. Closing.