[Japabu]

Problem

the_log_lands_on_the_boot_stick waited on the console for the one exact line stick_load: line 1500 . Under the load the console falls behind, and logkeeper then sheds the oldest program lines it holds for the console. When line 1500 was among them, the test stalled with "it never stopped talking and never got there", while the guest was tens of thousands of lines further on. This is how the nightly's kvm / suite went red on 10-22, 10-24, 10-26 and 10-28 (runs 39745311509, 40075324820, 40291133102, 40661873043).

Change

The wait now goes through await_guest and accepts any stick_load: line N with N ≥ 1500. That is what the test needs before it presses the power button, and the stall message is true again. Nothing showed that QEMU dropped this line, so the QEMU console-drop record is unchanged. The branch is one commit on 965bb73de.

The PR also files issues/two-amdvi-boots-in-a-kvm-suite-wrote-not-one-byte.md for the two unrelated amdvi reds below. They do not fit issues/parallel-tests-red-under-other-suites.md: that suite ran alone on its host. The netcase silent-boot record is the nearest, but its boots printed the firmware's screen clears and these printed nothing.

Evidence (https://github.com/ToyOSOrg/evidence/tree/d06821d0cb6e754f1fec16a5921bc4378d9ba600/pr-1107/r2)

• The fix: a full cargo test --test toyos-build at 0eb2c09d0 on a Linux x86_64 KVM host. Exit 1, 82 of 84 passed, and the_log_lands_on_the_boot_stick passed in 18 s.
• The two reds are unrelated: amdvi_selftest and amdvi_firmware_left both had boots that printed nothing at all on the console or the UART for 63 s. The control below differs from this head only inside the stick test's wait, and both passed there. Recorded, not investigated.
• Control and mechanism: a temporary commit kept the old exact wait and printed a census of the console during it (controls/old-wait-census.patch). Full suite: exit 0, 84 of 84.
  • Lines 902 to 1466 (565 whole lines) were missing as one contiguous block. There were 0 partial lines and no went unshown report yet; logkeeper prints one only once its backlog falls below half.
  • Old lines missing whole, with nothing partial, is logkeeper's shedding, not QEMU dropping bytes.
  • That gap ended before line 1500, so the old wait passed this time.
  • I did not capture a stalling run.
• Round 1: the full-suite stall at e4bdb0a5d, at https://github.com/ToyOSOrg/evidence/tree/fab78429d25f1dbdd902d98a7f818987bb81f459/pr-1107/r1.

Checks

• cargo run -- --ci host at 0eb2c09d0: exit 0, all 105 steps green.
• At the reshaped head a3d97faec (the same test diff minus one doc comment, plus the issue file, on a newer main): exit 0, all 105 steps green (https://github.com/ToyOSOrg/evidence/tree/43ea93ef49205b2fbc5be429669c436112319ba0/pr-1107/r3). The guest runs above still apply, because deleting a comment and rebasing onto issue-only and unrelated commits cannot change this test's behaviour.

Risks

• None of the CI stalls was captured whole. Attributing them to logkeeper rests on the census above and on the stall shape matching it.
• The fix passes whichever mechanism dropped the line.

🤖 Generated with Claude Code

[Japabu]

Review: PR #1107 at bc280b4 (r1)

Scope: one commit, +11 lines in issues/qemu-drops-console-output-the-harness-is-slow-to-read.md, no code. I read the diff and the whole record, the_log_lands_on_the_boot_stick and usb_stopped_before_the_reset (tests/toyos.rs), stick_load.rs, await_guest/await_marker/drain_for (tests/common/qemu.rs), logkeeper's console path (system/logkeeper/src/main.rs), the kernel's virtio-console transmit, the three CI job logs, the other nightlies from 10-21 to 10-28, and the evidence at fab78429d.

Architectural assessment

The CI facts are mostly right. The record has two problems. It names a mechanism the evidence does not establish, and it files the red under a host-side chardev defect when the red comes from the test's own wait. Logkeeper's documented policy can drop line 1500 inside the guest, so the stall can happen on any host and the record's exit condition would not remove it. The test waits for one exact line of a flood on a channel that drops old lines under that flood. That wait is the defect. It has a cheap fix inside the test.

Findings

BLOCKER 1 — issues/qemu-drops-console-output-the-harness-is-slow-to-read.md:77,85-86 — The record says "red this way" (QEMU virtconsole dropping on EAGAIN) and says the exit condition "would also remove this test's exposure". Neither is established.

• A second drop mechanism, inside the guest: logkeeper keeps at most CONSOLE_BYTES (1 MiB, system/logkeeper/src/main.rs:130) of program lines that the console has not taken. Past that, "the oldest lines go, never the newest" (:540), and it says logkeeper: N line(s) went unshown on the console (:577). The guest's virtio-console sends one 4 KiB buffer at a time and waits for each to complete. A guest console slower than the load's ~180 KB/s grows this backlog until logkeeper cuts it.
• The numbers fit this mechanism (an inference, not a measurement): in run 40661873043 the harness received 10146 lines during the wait while the guest reached line 41767 in about 211 s. That is about 48 lines/s, or about 43 KB/s at ~900 B a line. At that rate the backlog passes 1 MiB about 7–8 s into the load, which is when line 1500 (~1.35 MB in) is written. Line 1500 is then among the oldest held lines and is cut.
• The test already expects console loss: its own comment at tests/toyos.rs:2989-2990 says a line "can be one the console dropped under the load", without naming which drop.
• The evidence cannot tell the two apart: each capture shows only its last 40 lines, about 0.2 s of output. QEMU's drop leaves partial lines and no in-guest report, which is the record's own signature. Logkeeper's drop leaves whole lines and a went unshown line.
• Consequence: if logkeeper is the cause, this sighting is in the wrong record and its exit claim is false. A file chardev or virtserialport does not make the guest console faster.
• Cheapest discriminating check: keep the whole wait capture from one stalling KVM run, for example with a temporary local print, and count went unshown on the console lines and partial lines. Short of that, write the attribution as an unestablished inference and drop the exit-condition sentence.

BLOCKER 2 — tests/toyos.rs:2957 — The test's wait is the defect, and the record does not name it.

• What the test claims: that the load is writing the stick when the power button is pressed. The stick contents are checked afterwards (≥ 1 MiB of load lines, the verdict).
• What it actually waits for: one exact mid-flood line, stick_load: line 1500 , on a console that drops old lines under this load by design.
• Why the failure is false: "STALLED: waiting for the load to write the stick — it never stopped talking" was reported while the guest was writing line 41767 at 200 lines/s. Under tests/CLAUDE.md's rules a red must mean what it says (a meaningful failure, and a lossy channel is not trusted for an exact item). This red does not mean what it says.
• The fix is cheap and works whichever mechanism drops the line: wait through await_guest with a predicate that accepts any stick_load: line N with N ≥ 1500. Logkeeper keeps the newest line, and the CI windows show new lines still arriving.
• Required: fix the wait in this PR, or file the wait as its own defect with that fix as its exit and the CI sightings as evidence. Either one is enough. The QEMU record can keep a one-line cross-reference only once BLOCKER 1's check shows QEMU dropped the line.
• On the brief's first question: if the wait is fixed, no new record is needed. If it is not fixed, the wait needs its own record and cannot live under the QEMU record's exit.

BLOCKER 3 — issues/...:82,84 — Two numbers say more than the logs show. Both are cheap wording fixes.

• "so at least half the load's lines never reached the harness": the logs give at least 36806 − 18767 = 18039 lines lost, which is 49.0%, not half. The 18767 window lines include some non-load lines, so the true loss is higher, but the claim as written does not follow from the numbers given. Say "about half", or count the stick_load lines in the window.
• "the console it had read held 10146 lines in all": the harness's "(the last 40 of the 10146 lines in it)" counts only lines received since the wait began (await_guest's from = log.len()), not the whole console. Say "during the wait".

SUGGESTION — issues/...:79-81 — Add the earliest sighting. The test landed on 10-21 (fa0f43485). Nightly 39745311509 (10-22) stalled on the same line in kvm / suite ("1 of those reds are the ceiling: the_log_lands_on_the_boot_stick"), and 10-23 passed. KVM is then red on 4 of the 7 nights the test has existed, not 3 of 5.

Claims checked against CI and evidence

• Runs: 40075324820 (10-24), 40291133102 (10-26) and 40661873043 (10-28) each have kvm / suite failing with STALL the_log_lands_on_the_boot_stick and tcg / suite succeeding. 40174619947 (10-25) and 40473903686 (10-27) pass this test on KVM in 16–17 s, and their TCG jobs succeed. Matches.
• 10-28 window: the last line is 41767, and the window has 10146 lines. Matches.
• Local full suite at e4bdb0a5d: exit 1, 82/84. The test stalled at line 36806 with an 18767-line window. Matches.
• Rerun at a5b330f39: both tests pass, exit 0. Matches.
• QEMU version: 11.1.2 is stated only in the evidence README. No log prints it. It is an unverified claim from the implementer.
• cargo run -- --ci host at bc280b4: reported green. That is enough for an issue-only change.

Identifying data

• Hostname: none in the PR, the commit or the record. The evidence README says only "a Linux x86_64 machine with KVM, Arch Linux".
• Home paths: masked as /home/<user> and /Users/<user>. ci-host.log keeps /Users/<user>/Dev/jan/.... build/sourcegate.rs:805 rules that "a home-directory path carrying the owner's first name is not private", so this is acceptable.
• Network and hardware identifiers: none found. I scanned for IPv4 addresses and MACs.

Net: +11 issue lines, 0 production, 0 tests.

SEND BACK

[Japabu]

Review r2: PR #1107 at 0eb2c09

Scope: against origin/main the PR now changes only tests/toyos.rs (+14/−1). The r1 issue text is reverted. Production code: 0 lines. I read the new wait, stick_load_line, await_guest, the harness reader thread (tests/common/qemu.rs:2629-2750), log_lines::say, logkeeper's console_line, and the r2 evidence at d06821d0c.

Architectural assessment

The fix is in the right place. The test only needs to know that the load has passed line 1500 before it presses the power button; the stick's contents (at least 1 MiB of load lines, and the verdict) are the real assertion. Logkeeper keeps the newest held console line, so "any load line ≥ 1500" works whichever mechanism drops lines. A stall now means what its message says: no load line ≥ 1500 reached the console while the guest was waited on. r1's BLOCKER 2 is resolved. BLOCKERs 1 and 3 fall away with the reverted issue text.

The mechanism evidence

• Control at 7745af98d: the PR head plus controls/old-wait-census.patch, which puts the old exact wait back and adds a census. Exit 0, 84/84.
• What the census shows: gap after line 901: next is 1467, 1 gap of 565 lines, partial 0, unshown reports 0, line 1500 seen true.
• The gap is logkeeper's half-MiB cut: 565 lines × 900 B ≈ 508 KB. That matches console_line, which keeps the first held line and cuts the next ones down to CONSOLE_BYTES / 2.
• Not QEMU: QEMU drops 4 KiB transmit buffers. That would leave partial lines at the edges of the gap, and there are none.
• The census counts partials correctly: it treats a line as whole when it runs 900 bytes from stick_load: to its end, which matches LINE_BYTES.
• What is still inference: the CI stalls were not captured, so attributing them to logkeeper rests on the matching shape. The PR's Risks section says so. The fix does not depend on it.

Findings

BLOCKER — tests/toyos.rs:2989-2990 — stick_load_line's doc comment, "A line cut short reads as a prefix of its number, never more than it", does not hold for the only way a stick_load line can reach the wait cut short.

• The harness never cuts a line: its reader splits on \n and publishes whole lines only. Only the EOF remainder can be unterminated, and that does not arise during this wait. So there is no "drain boundary" truncation. That phrase is also in the PR body.
• The only source of a cut-short line is QEMU byte loss: the existing console-drop record shows that loss joins a line's head to later bytes on the same console line.
• A joined line can read high: …stick_load: line 150 followed by 0 xxxx… from line 1010's number parses as 1500 while the guest is at 1010.
• The consequence is harmless: a premature press can only redden the stick's ≥ 1 MiB check, never produce a false green, and it needs a byte drop that QEMU's transmit-buffer loss makes unlikely. The code is fine. The comment states a guarantee the parser does not have.
• Fix: delete that sentence. The doc comment left, "The number of a stick_load line.", repeats the name and can go too. No rerun is needed.
• For the orchestrator: the PR body's "A line cut short by a drain boundary parses as a prefix of its number, so it can only under-count" should go for the same reason.

SUGGESTION — the repository merges with merge commits only (allow_squash_merge: false). Landing as is would put bc280b4bb's subject, "the stick test's KVM red is QEMU dropping console lines", into main's permanent history, even though the next commit refutes it. The branch is the implementer's own, so it could be reshaped to the one fix commit.

Note for the orchestrator (not blocking): in the fix run, amdvi_selftest and amdvi_firmware_left timed out together at 22:33:09 after 63 s, with "nothing at all" on both console and UART.

• Independence is established:
  • Both boots ran and failed before the stick test started (22:36:39).
  • The change is host-side predicate code inside that test's function and touches no guest image.
  • Both passed in the control run.
• Still unrecorded: a boot that prints nothing, not even early output, is a red with no explanation, and no issue I found covers it. Whether to record it is your call.

Other checks

• Predicate: log[from..].lines().any(…) uses from = console.len() taken after the run command, which is the same window await_guest reports in its stall message.
• No wrong speaker: no supervisor or job line contains stick_load: line followed by a number. The job's final line is stick_load: N lines said, with no line , so it does not match.
• Parse cost: scanning about 1.35 MB every 200 ms before a pass costs about what the old contains did.
• Fix run at 0eb2c09 (Linux KVM host): PASS the_log_lands_on_the_boot_stick (18s), [log] 5 file(s) on the stick, 2547028 bytes. The suite result was 82/84, with the two reds above.
• Host check: cargo run -- --ci host at 0eb2c09 reported exit 0. That is enough.
• Test coverage: no unit test of stick_load_line is needed. It is a three-line parse whose only use can be checked by inspection.
• Identifying data: the r2 evidence masks its paths as <user> and contains no hostname or network identifier.

SEND BACK

[Japabu]

Orchestrator: r2's blocker checked at a3d97fa, a single commit. The false doc comment and the PR body's under-count claim are gone. The new amdvi silent-boot record states only what the run showed and has an exit. The fix's jan-pc runs stand, since only a comment changed. Landing.