Skip to content

A log read answers an unpublished ring at its first number, as the console does - #1207

Merged
Japabu merged 2 commits into
mainfrom
log-unpublished-ring-position
Nov 11, 2026
Merged

Japabu merged 2 commits into
mainfrom
log-unpublished-ring-position

Conversation

@Japabu

@Japabu Japabu commented Nov 11, 2026 •

Copy link
Copy Markdown
Collaborator

Problem

virt_reboot_refused_without_psci stalled on the guest runner on every run
(issues/virt-reboot-refused-without-psci-goes-quiet-before-its-job.md):
the console stopped at the kernel's Boot: complete and the job never
ended on it.

The cause is not the row's. A machine whose firmware names a CPU that never
starts has no console after the kernel hands the UART over:

  • logkeeper hands the UART's carrier the log once its read positions reach
    what the kernel says the console spoke (SYS_LOG_SPOKEN), ring by ring.
  • The console's positions start at each ring's first number, 1, a ring no
    CPU published among them.
  • A read clamped a zeroed position to 1 only in a ring it opened. The
    never-started CPU's ring is never opened, so its position stayed 0.
  • 0 >= 1 never held, the carrier's start was never said, and the UART
    carried nothing for the machine's life.

psci-withheld leaves the second CPU off. Userland itself ran: with the
kernel kept on the wire (a diagnostic commit, run 42922032425) the same boot
showed the job refused and ended with exit 1 at 2.04 s.

It was not the only row. virt_failed_ap_leaves_no_hole, whose
smp-skip-ap leaves one CPU of four unstarted, stalls the same way on the
base (run 42943718738) and is green with the fix. The first commit's message
calls virt_reboot_refused_without_psci "the only AArch64 one"; that is
wrong, and the review found it.

Resulting behavior

A caller's cursor is answered from each ring's first number on, an
unpublished ring's too, where it becomes a walk (Cursor::from_reader).
open no longer repeats the clamp. A reader's position and the console's
now compare in every ring.

Checks

check revision result
virt_reboot_refused_without_psci virt_reboot virt_smp, guest runner (AArch64, emulated) fa3559395 run 42923130251, green, 3 passed
virt_failed_ap_leaves_no_hole console_image_boots, guest runner fa3559395 run 42923761824, green, 2 passed
the base, virt_reboot_refused_without_psci main ec8912181 run 42094494342, red: the stall
the base, virt_failed_ap_leaves_no_hole d49f4834e run 42943718738, red: waiting for the job unmap_touch to end
kernel-loom's log_cursor, host fa3559395 5 passed, exit 0
the same with read.rs's change reverted fa3559395 exit 101: [3, 0] is behind [3, 1]
cargo run -- --ci host, macOS fa3559395 109 of 110 green; the red is issues/the-llvm-environment-test-breaks-git-on-macos.md

The new host test asks the console's positions with zeros, as logkeeper
does, through the kernel's own Published, and requires a zeroed cursor's
read to reach them beside an unpublished ring.

Evidence: https://github.com/ToyOSOrg/evidence/tree/4eaca7b33acf5a0b5d7f06c2c001aaeecd8fca99/r1

The diagnostic arm is diagnostic-kernel-keeps-the-wire-d49f4834e..096b67e4a.patch
there: three lines of kernel/src/log/console.rs on d49f4834e. The patch
first published under the shorter name was a diff against a newer main and
is corrected in the README.

Review r1

The head, 094c03964, is fa3559395 plus comments and one issue file. No
check ran again for it. What changed in code, comments only:

  • sdk/abi/src/log.rs, the cursor contract: one sentence, that no position
    is answered below 1 by a read or by SYS_LOG_SPOKEN.
  • kernel/src/log/read.rs, on Positions: one sentence, that every
    position is at or past FIRST_SEQ.

Records

Closes issues/virt-reboot-refused-without-psci-goes-quiet-before-its-job.md.
Nothing outside issues/ cited it.

New: issues/logkeepers-uart-carrier-waits-for-its-start-with-no-bound-and-no-report.md.
Hub::wire_start waits with no bound and no report, which is what turned
the kernel's answer into a silent UART. This PR removes the cause and not
that wait; it is recorded and not fixed here.

Risks

The same silence would have held on x86-64 metal with a CPU the MADT
enables that never starts, where the UART is the console. No bench has such
a CPU, so that is inferred from the code and not measured.

🤖 Generated with Claude Code

…nsole does

A machine whose firmware names a CPU that never starts had no console
after the kernel's hand-over. logkeeper hands the UART's carrier the log
once its read positions reach what the kernel says the console spoke
(SYS_LOG_SPOKEN), ring by ring. The console's positions start at each
ring's first number, 1, a ring no CPU published among them; a read
clamped a zeroed position only in a ring it opened, so the never-started
CPU's position stayed 0, 0 >= 1 never held, the carrier's start was
never said and the UART carried nothing for the machine's life.

The clamp moves to where a caller's cursor becomes a walk, so every
position is answered from its ring's first number on, and `open` no
longer repeats it.

This is what `virt_reboot_refused_without_psci` stalled on: `psci-withheld`
leaves the second CPU off, and the row is the only AArch64 one that reads
a program's line off the PL011 without the kernel's stop putting the log
there. Seen on main in guest-rows run 42094494342; with the kernel kept
on the wire (run 42922032425) the same boot showed the job refused and
ended with exit 1 at 2.04 s while the UART's carrier said nothing.

Closes issues/virt-reboot-refused-without-psci-goes-quiet-before-its-job.md.

Co-Authored-By: Claude Fable 5.2 <noreply@anthropic.com>
@Japabu

Japabu commented Nov 11, 2026

Copy link
Copy Markdown
Collaborator Author

Review r1 of #1207 at fa35593

Base d49f483. It merges cleanly into main fb88cec, which has not touched kernel/src/log, kernel/loom or system/logkeeper since that base.

Assessment

The cause is established and the fix is at the right owner. The code is ready; one published evidence file is wrong.

  • Cause, by inspection. logkeeper asks SYS_LOG_SPOKEN with zeros and is answered DRAINED's positions, which Published::new and size start at FIRST_SEQ and nothing moves in a ring that is None. Its own read went through Cursor::from_reader unclamped, and open returned at ring? before its clamp, so that ring's position came back 0. system/logkeeper/src/main.rs:601 (read >= spoken in every ring) then never held, set_wire_from never ran, and the UART's feed stayed in Hub::wire_start.
  • Evidence. Red at ec89121 (run 42094494342) and at d49f483 plus the diagnostic (run 42922032425, which checked out 096b67e). Green at fa35593 (run 42923130251, whose git log -1 reads fa35593). The red and green arms on d49f483 differ by this diff alone. The host control fails as claimed ([3, 0] is behind [3, 1], exit 101), together with the rewritten assertion at kernel/loom/tests/log_cursor.rs:120. The diagnostic run shows what the PR says and no more: kernel records after the hand-over, the refusal at 2.033 s, exit: reboot ... code=1 at 2.042 s and no carried line. It does not show the comparison; inspection and the host control do.
  • Owner. from_reader is where a caller's words become a walk, so normalising once there and dropping the second clamp in open is the right single home; userland should not know FIRST_SEQ. After the change, every position either syscall answers is at or past FIRST_SEQ. I found no other consumer that compares an answered position with 0: on_the_uart, written_through, Carriers::spoken, the guest readers, and the trace reader, whose rings are never None. This holds by construction at the constructors, not by type: zero remains an accepted input alias.
  • The hand-over condition. For this design it is the simplest correct one. The carrier needs one replay offset past every record the kernel put on the UART itself, and per-ring read >= spoken is exactly that. Its weakness is not the comparison but that a start that never comes is silent (item 3).
  • Machines with every ring published. The change is neutral there. A drain opens every ring before it returns, so the clamp was always applied; Published never holds less than FIRST_SEQ; loss accounting is unchanged, which a_cursors_loss_claim_is_not_read holds.

Net: production +4/-4 (kernel/src/log/read.rs), tests +21/-2, records -23. The issue's close is clean: nothing in the branch or in the merged tree cites the slug, its exit is met, and the invariant is folded into from_reader's doc.

BLOCKER

  1. Evidence r1/diagnostic-kernel-keeps-the-wire.patch and r1/README — the published patch is not the diagnostic. It is byte-identical to git diff 9349705ce 096b67e4a: 22 files, 47 KB, the reverse of The loader boots the marked slot or nothing #1201 plus the diagnostic. The README says the run was "main d49f483 plus" that patch. The commit the run checked out, 096b67e, has d49f483 as its parent and changes three lines of kernel/src/log/console.rs (HANDED stored false, WIRE released). Its branch stalls-diag-psci is deleted, so the patch file is the only published account of the arm, and as published it reads as a confounded arm. The run and the claim it supports stand. Fix: append git diff d49f4834e 096b67e4a to pr-1207 and point the PR body at the new evidence commit. No code change, no rerun.

SUGGESTION

  1. PR body and commit message — the base scope looks understated, and one row has no base control. By inspection virt_failed_ap_leaves_no_hole had the same defect on the base. percpu::alloc publishes a ring only for a CPU that is attempted (kernel/src/arch/aarch64/smp.rs:76), so cpu3 of its four has none. Its judge waits on test-runner's ===TEST_END unmap_touch (tests/toyos.rs:3963). The stop puts only the kernel's records on the UART (kernel/src/log/console.rs header) while the feed is still in wire_start. So the commit message's "the only AArch64 one" is unverified and, I believe, wrong. That sentence does not land, since the squash takes the PR body, but the body's "with no stop to put the log there" carries the same idea. No run of that row on main exists since the condition landed on 2026-11-04; the last nightly is 2026-11-03. Cheapest check: dispatch virt_failed_ap_leaves_no_hole at d49f483. Red there is a second, independent guest control, and the body should then say the fix restores that row too. This is my inference from the code, not a run.
  2. system/logkeeper/src/serve.rs:147-155 (not in the diff) — Hub::wire_start waits on the condvar with no bound and no report. That wait is what turned an inconsistent kernel answer into a console silent for the machine's life, with nothing in /log either. This PR removes the cause, not the failure mode. It is worth a record (hang: a wait with no failure timeout), or a bound that says so and starts the carrier anyway; the port's STALL already holds that duplicated lines beat a silent UART. Out of this branch; the orchestrator's call.
  3. sdk/abi/src/log.rs:306-309 — the ABI's cursor contract says what a position of 0 reads from, not what is answered. logkeeper compares positions answered by two syscalls, which is valid only because neither answers 0. That rule now lives only in from_reader's doc inside the kernel. One clause here puts it at the boundary the next reader of cursors will read. A comment under sdk/abi/src changes no identity.
  4. kernel/src/log/read.rs:174-182 — open now counts a phantom lost record for a position of 0. It relies on every Positions being at or past FIRST_SEQ. That is true of from_reader and Published; Cursor::at (:89) takes anything and is safe only because nothing walks it. A clause on Positions would state the precondition.

The questions asked

  • The x86-64 metal consequence: no record and no new row. Nothing is owed once this lands, the Risks paragraph labels it as inference, and the defect and its fix are architecture-neutral code the host test holds. It was not specific to x86 either: any machine whose firmware names a CPU that never published a ring. x86 honours smp-skip-ap (kernel/src/arch/x86_64/smp.rs:205) and no row uses it; such a row would re-run shared code for the price of a boot.
  • The rows run are sufficient. The two rows with an unpublished ring cover the changed path. virt_smp covers eight published rings and the trace reader. console_image_boots is x86 under KVM on a machine with no console port, so its program lines crossed the UART hand-over with the fix. The one gap is item 2's base control.
  • Host CI. The macOS log ends 1 of 110 step(s) red: the build system: cargo test --lib, which is issues/the-llvm-environment-test-breaks-git-on-macos.md, independent of this change; log_cursor ran in it with five passing. GitHub's checks are skipped on the draft.

SEND BACK — for the evidence file in item 1 only.

…itions`, and the carrier's wait is recorded

Comments only in code:

- `sdk/abi/src/log.rs`, the cursor contract: no position is answered
  below 1, by a read or by `SYS_LOG_SPOKEN`, which is what lets a reader
  compare the two.
- `kernel/src/log/read.rs`, `Positions`: every position is at or past
  `FIRST_SEQ`, which `open` now relies on.

New record: `Hub::wire_start` waits for the carrier's start with no bound
and no report, which is what turned an unreachable kernel answer into a
UART silent for the machine's life. Not fixed here.

Co-Authored-By: Claude Fable 5.2 <noreply@anthropic.com>
@Japabu

Japabu commented Nov 11, 2026

Copy link
Copy Markdown
Collaborator Author

Orchestrator verification at 094c039, after review r1 (code accepted; SEND BACK for one evidence file).

  • Blocker 1: evidence commit 4eaca7b3 now holds r1/diagnostic-kernel-keeps-the-wire-d49f4834e..096b67e4a.patch, which I read: one file, kernel/src/log/console.rs, HANDED stored false and WIRE released. The PR body points at that commit.
  • fa3559395..094c03964 changes two doc comments (sdk/abi/src/log.rs, the cursor contract: no position is answered below 1; kernel/src/log/read.rs, on Positions) and adds issues/logkeepers-uart-carrier-waits-for-its-start-with-no-bound-and-no-report.md (r1's suggestion 3, recorded, not fixed). No code.
  • Suggestion 2's base control ran: virt_failed_ap_leaves_no_hole is red at d49f483 (run 42943718738), so the fix restores that row too and the body says so.

Queueing.

@Japabu
Japabu marked this pull request as ready for review November 11, 2026 02:37
@Japabu
Japabu added this pull request to the merge queue Nov 11, 2026
Merged via the queue into main with commit 31e8b35 Nov 11, 2026
10 checks passed
@Japabu
Japabu deleted the log-unpublished-ring-position branch November 11, 2026 02:57
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant