Silence routine diagnostic noise; fix a real CRLF double-submit bug

Two separate fixes, found and closed together after task 3.9/prompt-
format landed (Captain Bob: "finish the work first then we'll do
cleanup before 3.10 begins").

1. Logging noise (confirmed live via QMP screendump): three sources
   were cluttering ordinary interactive console sessions.
   - INFERENCE "Output validation failed, ignoring results"
     (vm_runtime.c, kernel; vm_time.c, hosted mirror) and xhci "CSW
     status = FAILED"/"unit not ready -- retrying" (xhci.c) were
     already log_message(LOG_WARN/LOG_ERROR, ...) calls, just visible
     at the default runtime LOG_WARN level -- downgraded to LOG_INFO,
     all three fire routinely and self-resolve (xhci.c's own existing
     comment already documents the retry as expected SCSI UNIT
     ATTENTION behavior, not a driver defect).
   - Stadium: dispatch cell=... (stadium.c's stadium_dispatch()) was a
     genuine defect: an unconditional console_puts()/console_println()
     sequence with no level gating at all, printing on every single
     dispatch. Rewritten through log_message(LOG_DEBUG, ...).

2. CRLF double-submit (found while investigating why the cleaned-up
   noise still didn't look like a normal single-VM session):
   sk_console_readline() (repl.c) breaks on '\r' OR '\n' as independent
   terminators, so a line sent as both bytes submits twice -- the real
   line, then an immediate empty-line submit on the second byte, each
   printing its own " ok". Pre-dates Stage D entirely, not an async-
   relay artifact. Fixed with a single non-blocking peek-and-discard
   for the paired byte right where the line terminates.

Verified live on all three architectures for both fixes: zero UNKNOWN
WORD, dict_hash identical to every prior acceptance run in this
document (both changes are display/interaction-only).

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
This commit is contained in:
Robert Allan James
2026-09-22 16:33:29 -04:00
co-authored by Claude Sonnet 5
parent 5c07745c18
commit d4f8a568ee
22 changed files with 73490 additions and 17 deletions
+67
View File
@@ -1405,6 +1405,73 @@ not-yet-started item (memory `project_production_logging_cleanup_needed`:
`console_println()` overuse, much of it should be DEBUG-level). Captain Bob explicitly deferred
this to after the prompt-format fix landed — genuinely not started, no task number assigned yet.
**2026-09-22 — CLOSED**, after the task 3.8 payload-aliasing fix landed. The noise turned out to
be exactly three sources, found by tracing each visible line back to its actual call site rather
than auditing `console_println()` broadly:
1. **`INFERENCE: Output validation failed, ignoring results`** (`vm_runtime.c`, kernel; `vm_time.c`,
hosted mirror) — already `log_message(LOG_WARN, ...)`, level-gated, just visible at the default
runtime `LOG_WARN` level (`kernel_main.c` sets it there after POST). Fires routinely during
normal operation with the runtime self-recovering every time (the message says so). Downgraded
to `LOG_INFO` in both files (kept in sync, same duplicated-logic pattern this codebase already
uses elsewhere for the hosted/kernel split).
2. **`xhci: CSW status = FAILED`** (was `LOG_ERROR`) and **`xhci: unit not ready -- retrying TEST
UNIT READY`** (was `LOG_WARN`), both `xhci.c` — also already level-gated, same visibility
reason. `xhci.c`'s own existing comment right there confirms these are "a fresh SCSI target's
standard first-command UNIT ATTENTION behavior, not a driver defect" — the bounded retry
resolves it routinely. Downgraded both to `LOG_INFO`. The genuine terminal failure ("`xhci: unit
still not ready -- giving up`", after `XHCI_BOT_TUR_MAX_RETRIES`) was left at `LOG_ERROR`,
unchanged — that one is a real failure, not routine noise.
3. **`Stadium: dispatch cell=... behaviour=...`** (`stadium.c`'s `stadium_dispatch()`) — the one
genuine defect, not just a severity judgment call: an unconditional `console_puts()`/
`console_println()` sequence with **no level gating at all**, printing on every single Stadium
dispatch regardless of log level — confirmed live, interleaving visibly with ordinary
interactive console sessions (a live QMP `screendump` Captain Bob asked for caught it directly,
`logs/20260922-134049/aarch64/`'s own screendump before this fix). Rewritten to route through
`log_message(LOG_DEBUG, ...)`, one call per `StadiumBehaviour` case, matching every other
diagnostic trace in this codebase — silent at the default level, available with
`--log-level=debug`.
No sender/reader/call-site changes needed anywhere else — this was purely a severity/level
question for two sources and a genuine gating gap for the third, not an API or behavior change.
Verified live: a fresh screendump after the fix (`logs/20260922-142449/amd64/`) shows a clean
interactive session with none of the three noise sources present, confirmed against the exact
same mint→WIREBIND→`USE`→relay sequence that produced the noisy screendump earlier. Standard
three-ISA acceptance clean: `logs/20260922-142449/amd64/`, `logs/20260922-142835/aarch64/`,
`logs/20260922-143229/riscv64/` — zero `UNKNOWN WORD`, `dict_hash` identical across all three and
matching every prior acceptance run in this document (unaffected — display-only change). Also
confirmed the hosted build (`make`, no `ARCH=`) still compiles clean after the `vm_time.c` change.
**2026-09-22, real defect found and fixed while investigating a separate complaint (Captain Bob:
the interactive Stage D exchange "looks nothing like a normal single-VM session" — extra `ok`/
`ok>` cycles with no command typed in between).** Root cause traced via a live QMP `screendump`,
not guessed at: `sk_console_readline()` (`repl.c`) breaks its read loop on **either** `'\r'` or
`'\n'` as an independent terminator — a line sent as both bytes (a real terminal in CRLF mode, or
any scripted sender writing `"\r\n"`, which every QMP/socat-driven verification session in this
whole document has been doing) submits **twice**: once for the real line on the first byte, then
an immediate empty-line submit on the second byte the very next time the function is called, each
producing its own `" ok"`. Confirmed this pre-dates Stage D entirely — the very first `ok`/`ok>`
pair after `MINT` (Hera's own console, not `rajames`'s, not an async relay at all) already showed
doubled. **Not a Stage D async-relay artifact as first suspected** — every prior screendump and
every prior acceptance log in this document that shows doubled `ok`s is this same bug, present
since before this document opened.
Fixed at the source (`sk_console_readline()`, `repl.c`): after breaking on `'\r'` or `'\n'`, a
single non-blocking peek for the paired byte (the other one of the two) — discard it if present,
push it back via the existing `g_console_pending_key` single-slot buffer (the same mechanism
`sk_console_key_available()` already uses for "peeked but not this call's to consume") if it
turns out to be unrelated input for the next line. A byte that hasn't arrived yet is not waited
for, matching every other non-blocking read in this function.
Verified live: a fresh screendump after the fix (`logs/20260922-162219/amd64/`) shows exactly one
`ok`/`ok>` pair per typed line, matching normal single-VM interaction, with Stage D's own async
delivery timing unchanged (Captain Bob's own explicit choice: clean up the prompt noise, keep the
real delivery latency — the evidence line and result still land on a later idle-pump beat, just
without the doubled `ok` cluttering the wait). Standard three-ISA acceptance also clean on all
three architectures: `logs/20260922-162219/amd64/`, `logs/20260922-162531/aarch64/`,
`logs/20260922-162932/riscv64/` — zero `UNKNOWN WORD`, `dict_hash` identical to every prior run in
this document (unaffected).
---
## Out of scope, carried for visibility