Logging: records from every producer, and a kernel that waits on nobody

[Japabu]

Userland logging, rebuilt: every program writes into a log ring of its own, and the kernel waits on no userland program to log, panic or stop. This covers changes 1–4 of the logging roast and its small defects. Change 5, the kernel's own ring rebuilt printk-style, is item 1 of the track issues/kernel/logging-records-from-every-producer-and-a-kernel-that-waits-on-nobody.md.

What changed, per decision

1. A log ring per program, written without a syscall (toyos/src/log/)

• init makes a 2 MiB shared-memory ring for every program it starts or launches, maps it into the child, and names it to logd in an IPC frame. The frame carries the program's name, so the identity on a line is the one init stamped, not one the program claims.
• A push allocates nothing and makes no syscall. Threads share a CAS multi-producer ring, and a thread that asks for it gets a single-producer lane, which is wait-free. A full ring drops the record and counts it, and logd says the count. The time, severity, pid and tid are stamped when the record is written. A stdout/stderr write takes the stream's partial-line spinlock (Held); that is filed, below.
• stdout and stderr go into the ring as FLAG_UNENDED/FLAG_CLOSES records. logd joins them into lines per (pid, tid), up to 64 KiB and 16 joins.
• CHILD_KEEP = 64 shared slots stay free for the ring's owner (Ring::own, set by logd), so a flooding child does not take its parent's next lines. The owner word and a record's pid are memory the child can write, so this holds against a child that floods, not one that forges.
• soundd's say.rs, its log thread, logd's queues and the say! workarounds are deleted. soundd's mix thread writes its own lane.
• A record's stamp is the writer's word: logd reads one more than 1 ms past the moment it read it as that moment, and says how many it did (origin::clamp_ahead). A stamp in the future no longer holds its line out of every round.

2. The clock is a page (toyos-abi/src/clock.rs): a record is stamped without a syscall, the counter read behind lfence (x86-64) or isb (AArch64). The ABI changed, so the SDK versions go past main's: toyos-abi 0.16.0, toyos 0.18.0, toyos-window 0.20.0.

• The kernel publishes the page from clock::set_counter, which each architecture's boot calls once it has the counter's period.
• The thread's tid is in its TCB, where each architecture's psABI leaves room (toyos_abi::tcb): x86-64 (TLS variant II) at TP+16, AArch64 (variant I) at TP+8, the word the psABI leaves to the implementation. The loader main now carries lays variant I out as TP+0 the DTV pointer and TP+8 zeroed (loader/tls.rs), so process::spawn_thread's tid store at TP + TCB_TID lands on that zeroed word and not on the DTV pointer. TP+16 on AArch64 is the first TLS block, so the layout is a compile-time assertion.
• std's side is the fork, pinned at 64a2050c484: this branch's 23783dc3524 merged with main's c34ecdf0ab6, on the fork's wt-toyos-logtrack and merged into toyos-inbox (645d1c70732). Its compiler/ is c34ecdf0ab6's byte for byte.

3. A kernel that waits on nobody

• A panic stops the other CPUs before anything else in panic::halt_all_cpus, then seals its tail in the black box; the next loader pass copies that tail onto its page.
• A stop goes through init's power port (toyos::power::stop): init has logd flush, then stops the machine. logd writes a flush's rounds and makes them durable once, then holds lines back from the file, up to 1 MiB (STOPPING_BYTES), counting and saying what is past it; /log ends at init's STOPPING line.
• A stop the kernel refuses is init's RESUME frame (toyos-logstream): logd writes what it held and says the stop was refused. logd reads init's frames up to a flush and runs the flush before it reads on, so a RESUME queued behind a FLUSH it has not run (init waited the flush out, then the stop was refused) answers that flush instead of finding no stop to resume. init's resume survives a gone logd as its flush does, and init counts the flushes it waited out, so a late FLUSHED is not taken for the next stop's answer.
• Deleted: wait_for_durable, wait_for_log_file and its budget, LOG_HOLDERS, holds_the_log, and the durable field. Quiesce is one stage behind a Gate.

4. One console writer, with interrupts on

• klogd writes the console. A console holder's write goes to a 64-line queue and never touches the device; the queue's length is read under its lock.
• The virtio console masks interrupts only to publish a burst and for each look at its completion; its doorbell is rung after the lock is let go (Virtqueue::publish, Doorbell), because QEMU runs the device's output into its chardev inside that MMIO write. The panic path rings again before it waits a burst out, since a CPU stopped between publishing and ringing never rings. Every wait on a used ring is one function, virtio::wait_used; past its 5 s bound it looks once more before it panics.
• The UART's burst is what its transmitter takes once ready (console_uart::TX_BURST): 16 on the 16550, 1 on the PL011.
• A program's line reaches the console only through logd, under the program's name. A child given a console is refused a write (PermissionDenied). The console-unbuffered actuator and serial::write_console, which no test armed any more, are deleted.
• logd holds up to 1 MiB of lines the console has not taken; past that the oldest are dropped, counted, and still in /log.

5. logd's duties

• Every round's lines are written and the volume made durable before the next round, as main's logd did. A sync the kernel declines to start is owed and asked again each round.
• It keeps each boot's first part, allows each program 4096 records a second, rate-limits the kernel's exit log, and lets a network reader that takes nothing for 10 s go. Shipped images do not serve the log on the network (no_shipped_image_serves_the_log_on_the_network, over every non-test config ALL_CONFIGS walks).

6. Defects fixed along the way, on main too

• A syscall wrote through a read-only user mapping. A copy into user memory translates through AddressSpace::translate_writable, USER and WRITE at every level of the walk. Filed as issues/isolation/a-syscall-writes-through-a-read-only-user-mapping.md.
• A typed copy touched a frame a sibling could free under it. copy_in and copy_out translated under the address-space lock, let it go, then read or wrote the frame through the direct map unpinned, so a sibling thread's munmap could free it and the PMM reissue it in between. Both now go through user_ptr::window, which pins the frames under the lock for the copy's life; the unpinned translate is deleted and object is is_user_object's bound over a pinned window. window's walk is toyos_userbound::contiguous, pure and host-tested: a write is asked at every 4 KiB page, a read at every 2 MiB page.
• find_gap is bounded by its floor; a SleepLock taken before the scheduler starts does not post; init serves the requests that arrived before it expires a silent client; a /log part is not preallocated.

7. Tests

• user_copy_races_munmap (new, fast): copy-meets-a-remap holds a typed copy whose destination carries a mark between its translation and its store, until its own process has mapped memory again; the program unmaps the destination on the kernel's cue and maps a fresh region, and asserts the region is still all zeroes.
• log_resume_meets_its_flush (new, fast): tests/logflushcase has logd hold its first flush until init speaks again (--hold-flush), so init waits the flush out, the kernel refuses the stop, and the resume meets the flush unrun. logd must live and the job's line after the refusal must be in /log.
• log_stream_stalled_reader floods until every stalled reader is let go, bounded by the flood's ceiling, rather than by one fixed flood; log_flood's line-count argument goes.
• log_ring_keeps_the_owners_slots fails with its own verdict when the stop's flush was not answered: init's warning on the console, init's stop line missing from /log, or the kernel's Syncing filesystems... record FLUSH_BOUND or more after that line.

Filed: the track; issues/design-debt/a-rust-program-holds-two-copies-of-its-stream-state.md; issues/design-debt/a-programs-two-streams-map-its-one-ring-twice.md; issues/design-debt/a-stream-write-spins-on-a-lock-its-own-panic-can-hold.md; issues/design-debt/a-console-holders-line-state-guards-writers-that-no-longer-exist.md; issues/audio/a-megabyte-written-to-the-stick-starves-a-tone-beside-it.md; issues/build/qemu-drops-console-output-the-harness-is-slow-to-read.md.

Filed this round: issues/kernel/a-holders-queued-line-can-reach-the-console-after-the-last-word.md, a red seen once under load and not fixed here.

Gates

On the dev host, which other worktrees load; every exit is the command's own. The head, a8c37cf, differs from 618e68e only under issues/.

gate	head	exit	notes
cargo run -- --ci host	618e68e	0	48 steps green, the loom controls among them
cargo run -- --ci abi-split	618e68e	0	toyos-abi 0.15.0 → 0.16.0, toyos 0.17.0 → 0.18.0, toyos-window 0.19.0 → 0.20.0
loom log_ring (--features loom --test log_ring --release)	618e68e	0	3 of 3
toyos-userbound suite	618e68e	0	19 of 19
cargo test --test toyos-build (fast tier)	618e68e	1	406 of 407. lan_mdns_answer: a tap socket path past SUN_LEN; main 5e446e5 in the same session, exit 1 on the same message (issues/build/a-lane-s-tap-socket-path-is-past-sun-len-on-the-dev-host.md). Run beside the stalled-reader loop below.
the fast tier again, as the loop's load	618e68e	1	403 of 407: lan_mdns_answer as above; quiesce_stops_the_machine, launcher_refusals and port_poll_churn red wide and green alone, at 1-minute loads up to 96. The first is filed with its mechanism (above); the other two were not investigated.
--nightly log_stream_stalled_reader, 20 runs beside the fast tier	618e68e	0 × 20	1-minute load 16.6–96.3 (median 36.3); 13–37 floods before all 8 readers were let go
--nightly log_	b601025	0	25 of 25
--nightly console_line_atomicity	618e68e	0
user_copy_races_munmap, log_resume_meets_its_flush, log_after_a_refused_stop, abuse_readonly_copyout, munmap_reissues_read_window, panic_halts_the_others_first, virtio_used_ring	76bd2bc	0 each
log_ring_keeps_the_owners_slots, 5 runs	b601025	0 × 5	the kernel synced 185–203 ms after init's stop line

Negative controls

Each a checked patch: applied, the tree shown to build, run, restored, at the head its green arm ran on.

mutation	head	red	exit
object put back on the unpinned translate_user, the copy's frame not pinned (the code before this round)	76bd2bc	user_copy_races_munmap: "a copy held across a sibling's munmap stored into the region mapped after it: byte 0 is 0x1", wide and alone	1
logd's from_init and init back to 348b497 (actuator, config and test kept)	76bd2bc	log_resume_meets_its_flush: "logd ended before the machine did: exit: logd pid=4 code=101", wide and alone	1
let keep = { let _ = owner; 0 }; in Ring::push	b601025	log_ring_keeps_the_owners_slots: "/log carries no "===TEST_END test_rs_log_flood exit=0===": the child's flood took the slots its parent's line needed (1917 flood lines in /log)", wide and alone	1
logd --hold-flush in tests/logkeepcase: a flush init waits out	b601025	log_ring_keeps_the_owners_slots: "the stop went ahead without the flush's answer (init's stop line never reached /log)", wide and alone	1
Access::Write => PAGE_2M in toyos_userbound::contiguous	618e68e	a_write_across_a_read_only_page_between_writable_ones_is_refused, 18 of 19	101
translate_writable and the Access threading reverted whole (the tree main had)	round 1	abuse_readonly_copyout: "read wrote into a read-only mmap"	1
logd's stamp clamp reverted	round 1	log_program_forgery: the u64::MAX line "is after init's stop line in /log"	1
init's RESUME and logd's hold/resume reverted (actuator and test kept)	round 1	log_after_a_refused_stop: "/log carries no "log refused stop: said after the refusal""	1
AARCH64_TID = 16	round 1	toyos-abi does not build: the TCB assertion	101
wait_until's look past the bound replaced by None	round 1	virtio_used_ring: "wait selftest FAILED on a completion found after the bound"	1
the round-1 review's kick_all_but_self() + 500 ms spin before the halt IPI	round 1	panic_halts_the_others_first: "cpu2 made a record 500 ms after the fatal one on cpu1"	1
loom: the reader's progress store Relaxed (log-ring-tail-relaxed)	618e68e	red as registered: its --ci host step green	—
loom: a writer's tail/head loads swapped (log-ring-loads-swapped)	618e68e	red as registered: its --ci host step green	—

The first five pairs ran their green arm at the same head as the red (Gates). The "round 1" rows are that round's measurements, at heads before 348b497, not repeated.

Independent oracles

• The read-only check is the MMU's own rule for a ring 3 store, Intel SDM vol. 3A §4.6.1 (R/W and U/S at every level under CR0.WP); the gate compares memory byte for byte, not the return value.
• The copy race's harm is read off the memory the physical allocator zeroes as it hands a region out, by the process that was handed it, not off the kernel's account.
• The TCB layout is the AArch64 and x86-64 psABIs' TLS variants I and II.
• loom, a third-party model checker, on the ring's protocol, with three registered controls.
• The audio verdicts are the wav QEMU's device captured, judged against main built from the merge-base in the same session.
• The console loss is QEMU's own hw/char/virtio-console.c (flush_buf, v11.1.0), which drops on EAGAIN only for a console port.

Measurements

Audio A/B (the round-1 review's instrument): --nightly hda_tone (its own smp 2) and --nightly audio_tone_load (smp 1 and 8), 40 rounds per arm interleaved, 4 spinning host threads as the fixed load, the 1-minute load average recorded before every run. A boot is gapped when its first capture has a mid-tone silence; the harness's confirming re-boot is not counted.

The arms, with the fork commit each tree pins. The fork checkout each arm's worktree actually held at build time was not recorded, and arm A's worktree is gone, so that the build used the pinned std is not established.

run	arm	tree	rust it pins
1	A	17eb66a (main, the merge-base)	80ea645f83b
1	B	11bb949	23783dc3524
1	C	11bb949 with logd's sync interval at zero	23783dc3524
2	A	fd62f56 (main, the merge-base)	80ea645f83b
2	B	d3512de	23783dc3524

Run 1:

arm	hda_tone	atl smp 1	atl smp 8	gapped / boots	underruns	load (min / median / max)
A	0/40	0/40	0/40	0/120	0	7.3 / 14.2 / 37.5
B	2/40	1/40 (6)	1/40 (5)	4/120	11	6.8 / 11.6 / 37.1
C	1/40	0/40	0/40	1/120	0	7.9 / 14.1 / 47.2

B is above A (one-sided Fisher, pooled 4/120 against 0/120: p = 0.062). B against C is p ≈ 0.19, and C gapped in round 7, where two of B's four were, so the sync cadence is not established as the cause. logd syncs every round since 6f35787.

Run 2, confirming, the final logd:

arm	hda_tone	atl smp 1	atl smp 8	gapped / boots	underruns	load (min / median / max)
A	0/40	0/40	0/40	0/120	0	7.7 / 9.4 / 23.3
B	0/40	0/40	0/40	0/120	0	7.3 / 9.5 / 18.3

Every run's arm, round, exit and load, and every boot's gaps and underruns, are in the round-1 hand-back comment.

Interrupts off. The sampler is a measurement patch, never committed, applied identically to both arms; it is posted in the round-2 hand-back comment and applies to both 17eb66a and 11bb949 (git apply --check, 0 each). hw::IrqGuard and serial::BackendGuard record, per outermost window once virtio-console is ready, the time from the close to the restore and the #[track_caller] site that opened it, and log each new longest; command cargo test --test toyos-build -- --nightly --show-output audio_tone_load, 12 rounds per arm interleaved, the longest window per boot (confirming re-boots included). A = main 17eb66a, B = 11bb949.

	boots	min	median	max	site of every boot's longest
A smp 1	13	376 µs	1720 µs	16827 µs	log/console.rs:89 (drain_inline, a chunk of records under the backend lock)
B smp 1	14	< 100 µs	163 µs	5126 µs	virtio_console.rs:133 (a burst's submit), :151 (one look at its completion)
A smp 8	12	602 µs	871 µs	6246 µs	log/console.rs:89
B smp 8	16	< 100 µs	113 µs	528 µs	virtio_console.rs:133, :151

The 10.8 ms window of the old table did not recur in 16 smp-8 boots. The usb-reset-moves cue is armed in none of these boots and never appears. :133's bracket held the MMIO notify, which QEMU serves synchronously in the vCPU thread by running virtio-console's output into its chardev: emulated device work, which this branch now does after the bracket (§4). The sampler was not re-run after that change. :151 is one used-ring load, which only vCPU descheduling or an NMI can stretch.

Net lines (git diff --numstat origin/main...HEAD at a8c37cf, 186 files; production is everything outside tests/, toyos/src/log/proof.rs, src/, issues/ and lockfiles, inline #[cfg(test)] modules included): production +4961 −2075 = +2886; tests +1986 −852 = +1134; src/ +105; issues +41; lockfiles +11. The same count at 348b497 gives production +2648 (the round-2 review, counting its own way, gave +2433). This round deleted the unpinned translate, the console-unbuffered actuator and serial::write_console, log_flood's argument and the log-file wait the merge brought back; it added the copy race's actuator and test program, toyos_userbound::contiguous with its host tests (+95), the resume ordering, init's flush count, the bounded hold-back, Doorbell and the UART burst. ConsoleLine's state and stdio's second mapping were not deleted: each needs something no code here says yet, recorded in its issue. The roast's "about −500" was not delivered.

What I am unsure of

• A console holder's queued line can follow the stop's last word (filed, not fixed): klogd drains records before queued lines whatever their age, and nothing drains the queue between the stop of every holder and the last word. Seen once under load; no deterministic stimulus yet.
• launcher_refusals and port_poll_churn were red once each in the load run, wide, and green alone; not investigated.
• copy-meets-a-remap holds the copy on a spinning CPU with interrupts off, answering shootdowns itself (tlb::poll); its red arm depends on the physical allocator handing the just-freed frame to the next mmap, which it did in every run here.
• The interrupts-off sampler sees IrqGuard and BackendGuard windows only, and was not re-run after the doorbell moved out of the bracket.
• The audio A/B's fixed load is 4 spinning threads on a host other worktrees also load; run 2's ambient load was lower than run 1's, so it has less power.
• flush_final says in the black box that it gave up, and still spins rather than parking with a deadline: the wire is a ticket SleepLock, which has no timed acquire.
• issues/isolation/a-syscall-writes-through-a-read-only-user-mapping.md records a defect this branch fixes; it says the landing's first successor deletes it. The copy race, also on main, is not filed separately.
• hda_tone ran at its own smp 2; only audio_tone_load ran at smp 8.
• A ring costs 2 MiB per program, the shared-memory granule.

🤖 Generated with Claude Code

https://claude.ai/code/session_014iqcj4jDKpaiDX8B7CMvmK

[Japabu]

Review of #527 at 512da5e, against .claude/agents/reviewer.md. Read only; nothing run.

Readiness: PR CI green (abi-split success; host skipped on pull requests by design, and the body gives --ci host exit 0 at 512da5e). Added tests green per the body, except the modified log_stream_stalled_reader (see below). Reviewed.

Net lines (git diff --shortstat origin/main...HEAD): 156 files, +6046 −3286. Split by numstat: production +4223 −2002 = +2221 (about 400 of those are inline #[cfg(test)] modules); tests +1338 −805 = +533; build src/ +90; issues −95; lockfiles +11. The roast's named workarounds did go: say.rs, the say! macros, logd's Own/Theirs/Echo, LOG_HOLDERS, wait_for_* and durable. But the roast's "about −500" was meant as a net saving (≈ −100 to −300 across changes 1–4). The branch instead grows production by about +1.8k net of tests, so that was not delivered.

BLOCKER

• kernel/src/user_ptr.rs:327 (window) and :144 (copy_out), with kernel/src/clock.rs:140 — the clock page is not read-only to userland. The kernel's user copies check that the page is present, never that it is writable, so read(fd, 0x1_0000_0000, 24) or any copy_out makes the kernel write the one frame every address space shares. After that, every process's nanos_since_boot asserts on the magic or returns garbage, soundd's mix thread included. That is a cross-process isolation hole. Refuse writes into non-writable user mappings, and add a guest test in which one process's read into CLOCK_PAGE is refused with BadAddress and a second process still reads the magic.

• userland/logd/src/main.rs:478-480 with userland/logd/src/origin.rs:100,111 — a record's at_ns is writer-controlled and never clamped. A program stamping u64::MAX gets every line parked in self.waiting for good: it never reaches /log, and it is re-sorted every round. Its growth is bounded only by the allowance (8192 records/s, about 8 MB/s), so one hostile program can OOM logd and take the log from every other program. Clamp to cut at read, and add a test with a writer that stamps u64::MAX: its line is in /log and logd's heap stays bounded.

• userland/logd/src/main.rs:720 with userland/init/src/main.rs:846-851 — stopping = true is set on FLUSH and never cleared. If the kernel refuses init's stop (for example a shutdown with no S5, which init does handle and report), logd writes nothing to /log for the rest of the boot and says nothing about it. That is silent data loss on a path init treats as survivable. init has to tell logd to resume on refusal, and a test should refuse a stop and then find a later line in /log.

• toyos-abi/src/lib.rs:601-610 — aarch64 current_tid reads TP+16. Under the AArch64 psABI (TLS variant 1), TP+16 is the start of the first TLS block, not TCB space, so the port in flight would stamp user TLS data as the tid, and the kernel would write the tid into that data. This is untested code for an unbuilt target. Delete the arm (a compile_error! until ARM defines its TCB) rather than ship a guess.

• rust @ 39c642fe04f — this commit exists only on ToyOSOrg/rust branch wt-toyos-logtrack. git merge-base --is-ancestor gives exit 1 against both origin/toyos-inbox (ba6055ac) and origin/main (87971e6d). Main's toolchain would therefore depend on a feature branch whose deletion unpins it. The body names this precondition itself, and it is not met.

• audio: hda_tone gapped in 3 of 14 boots on the branch against main's recorded 1 of 11, with no same-load A/B, under the owner's hard rule. The diff is plausibly on the path. It moves logd's device flushes from every round to 2 s batches plus rotation syncs, which is the burst the filed a-megabyte-written-to-the-stick-starves-a-tone-beside-it.md measures. The allowance still lets one program put about 4 MB/s on the stick. klogd now busy-polls the virtio TX completion on a preemptible vCPU. What settles it:

  • build git merge-base origin/main 512da5e4 and 512da5e in two worktrees (free the disk; that is not a reason to skip);
  • run --nightly hda_tone and --nightly audio_tone_load (smp 8) interleaved A,B,A,B…, at least 40 boots per arm, under one fixed background load, recording the 1-min load average per boot;
  • add a third arm, B with SYNC_INTERVAL forced to per-round, to test the sync cadence as the mechanism.

  It lands only if B's gapped-boot count is not above A's (one-sided Fisher p ≥ 0.2), with every boot's gap count and underrun count in the body.

• measurement — the body's "1636–2518 µs → 87–298 µs" names no instrument, command, exit code or log, so the claim does not stand. Its own table also shows an smp-8 window of 10822 µs, which is 4× main's worst. On the PR's own numbers that is a regression until attributed. Give the sampler's command and the site/RIP of the 10.8 ms window, and repeat at smp 8 enough times to report a distribution rather than one boot. Candidates to rule out:

  • the actuator xhci::reset_moves::cue (kernel/src/drivers/xhci/wait/msc.rs:624), which calls write_bytes_locked → submit_and_wait with IF off for host latency;
  • tx_slot's spin under BackendGuard in write_burst (kernel/src/drivers/virtio_console.rs:142);
  • vCPU steal inside a short IF-off bracket, which a guest TSC sampler cannot tell from a long one.

• tests/common/logstream.rs:263 log_stream_stalled_reader — this is a new flaky red: 2 hangs in 8, not on the redlist, and no same-load A/B against main. The attribution to QEMU's virtconsole dropping output is sound as a mechanism (flush_buf drops for is_console). But the test waits for ===TEST_END=== through run_test on that same console, a channel this PR itself says can drop lines (logd's console bound, the queue, QEMU). The branch also made every flood line 15× wider (log_flood.rs WIDTH 64→960) and routes all of them to the console through logd. Fix the channel (the filed issue's exit: a file chardev or virtserialport), or take the runner's end from a channel that cannot drop, and show 20 of 20 beside a full nightly.

• kernel/src/drivers/virtio_console.rs:119-131,137-183,186-212 (tx_slot, write_burst's poll, Answers) — this is a second and third copy of Virtqueue::submit_and_wait's poll_used-until-5 s-then-panic (kernel/src/drivers/virtio.rs:645-682). Fold them into one Virtqueue wait that takes a between-polls hook.

• surviving mutation, panic path (high-risk). Patch kernel/src/arch/apic.rs:194, before the Reg::Icr.write, with:

  kick_all_but_self(); let d = crate::clock::now() + Duration::from_millis(500); while crate::clock::now() < d { core::hint::spin_loop() }
  

  I expect screen_fatal_halt_composited to stay green, because it reads only the black box. The claim "a panic halts the other CPUs first and runs no userland again" has no test that can fail. Add one: a program writes a monotonically numbered file on the stick until the panic, and nothing on the stick may be stamped after the panic's record. That test must go red under this patch.

• surviving mutation, ring. Patch toyos/src/log/region.rs:201 to let keep = 0;. slots_left_to_others_are_theirs calls push_leaving directly and never reaches Ring::push's owner test, and I find no guest assertion that the parent's line survives a child's flood. Name the test that goes red under this patch, or add one: a test-runner job floods, and test-runner's next line is in /log.

NOTE

• toyos/src/log/stdio.rs:128-157 — Held is a userland spinlock on every stdout/stderr write to a ring, and on libc fds 1 and 2 (posix_io.rs:64). An RT-lent thread spinning on it against a preempted holder at smp 1 never yields. Also, a panic raised inside with re-enters it and deadlocks. The mix thread is safe (it uses a lane), but "a write never waits" is false for this path.
• toyos-abi/src/clock.rs:65,75 — rdtsc without lfence and CNTVCT_EL0 without isb can execute ahead of earlier loads. A record stamped after reading another writer's record can then sort before it. Linux's vDSO orders both reads, and correctness should not rest on x86 here.
• kernel/src/drivers/virtio_console.rs:186-212 — Answers measures wall time across preemption (klogd is preemptible now), so a klogd descheduled for 5 s panics the kernel even when the device finished long before. Re-poll once after the deadline before asserting.
• kernel/src/drivers/serial.rs:256-264 flush_final — it spins 100M iterations on try_wire against a sleep lock whose holder may be preempted on the same CPU, then gives up silently. Park on wire() with a deadline and say so on expiry.
• kernel/src/drivers/serial.rs:327-329 — uart_write_fifo drops the rest of a write after THRE_SPIN_LIMIT with no count. Count it in UNSHOWN, or say it.
• kernel/src/drivers/xhci/wait/msc.rs:625 — the usb-reset-moves cue writes the registers without WIRE. It is a second console writer (actuator-only), and it contradicts serial.rs:3's module doc.
• kernel/src/log/console.rs:211 QUEUED — the mirror counter is the source of the wrap bug this branch fixed, and nothing tests it. Read QUEUE.len under the lock in has_room and in klogd's recheck, and delete the mirror.
• kernel/src/drivers/serial.rs:367-442 ConsoleLine — with logd the only holder that may write, the per-holder splice protection and the held/piece state guard two writers that can no longer exist. Consider having logd hand whole lines of at most MAX_CONSOLE_LINE and deleting that state.
• userland/logd/src/main.rs:139 with :528,533 — only Alert forces a sync. A userland panic (stderr = Error) followed within 2 s by a kernel panic loses the userland line entirely, because the black box holds only kernel records. Consider syncing at Error.
• toyos/src/log/stdio.rs:236-246 — Out and Err dup and map the same ring separately, which is two handles and two 2 MiB mappings per process.
• kernel-loom — the only registered control is publish-relaxed. Register the reader's tail store at ring.rs:192 going Relaxed, and swapped tail/head loads at ring.rs:107-108, as controls in src/ci.rs CONTROLS. The model should red on both, and nothing records that it does.
• src/build.rs:2771 — no_shipped_image_serves_the_log_on_the_network hard-codes three configs, so a new shipped config escapes it. Derive the list the way ALL_CONFIGS is derived.
• userland/logd/src/origin.rs:193 — the parent/child allowance split keys on the writer-claimed pid, so it is advisory. The same holds for CHILD_KEEP, whose owner word the child can rewrite. Say "a flooding child", not "a child cannot".

REMOVE

• toyos/src/log/mod.rs:7 — "Writing never waits": false for stdio::write (Held).
• kernel/src/drivers/serial.rs:3-4 and kernel/src/log/console.rs:7-8 — "Nothing else writes the wire but …" is false while xhci::reset_moves::cue exists.
• src/metalprofile.rs:27 — "test-runner's deadline reads clock_nanos": that syscall is retired.
• issues/hardware/a-t14-boot-wedges-after-a-jobs-exit-and-nothing-said-why.md:39,54 — cites the deleted log::wait_for_durable.
• issues/kernel/the-shutdowns-drain-counts-the-queue-while-iod-holds-an-entry.md:17 — cites the deleted wait_for_durable.
• issues/filesystem/an-nvme-flush-issues-no-command.md:15 — cites the deleted LOG_DURABLE_NS.
• issues/kernel/the-capability-end-state-is-twelve-answers.md:169 — lists the retired SYS_CLOCK.
• PR body, "Independent oracles" — "T14 … left to the orchestrator" and "Linux printk" are not oracles that were run. The body becomes main's record.

SEND BACK

[Japabu]

Hand-back for the review at 512da5e. Head 348b497; the body is current. Every exit below is the command's own.

BLOCKERs

#	what was done	red (mutation or scenario)	exit	green at head	exit
1	Copies into user memory translate through translate_writable (USER+WRITE at every level, per 4 KiB page). Exists on main: the unfixed user_ptr.rs is main's byte for byte, and the gate's mmap(PROT_READ) and own-.text arms need nothing this branch adds. Filed issues/isolation/a-syscall-writes-through-a-read-only-user-mapping.md.	whole fix reverted → abuse_readonly_copyout "read wrote into a read-only mmap"	1	abuse_readonly_copyout	0
2	logd reads a stamp > 1 ms past its read time as that time, and says so	clamp reverted → log_program_forgery: the u64::MAX line is after the stop line	1	log_program_forgery	0
3	init sends RESUME on a refused stop; logd writes what it held and says the stop was refused; actuator power-refused-once	init/logd/logstream change reverted → log_after_a_refused_stop	1	same	0
4	toyos_abi::tcb: AArch64 (variant I) tid at TP+8, x86-64 at TP+16, compile-time asserted. #524's worktree has no variant I loader yet.	AARCH64_TID = 16	build 101	toyos-abi suite	0
5	39c642fe04f merged into toyos-inbox (655c73def50), then the pin moved to 23783dc3524 (with main's 80ea645f83b), merged into inbox as 26f662d303a. git merge-base --is-ancestor 23783dc3524 origin/toyos-inbox: 0. Not the inbox head: that carries #524's compiler/ change, which sysroot::check_compiler refuses.
6	Audio A/B, below. B was worse; the cause was logd's 2 s batched sync; logd now syncs every round.	run 1, B 4/120 gapped vs A 0/120		run 2, B 0/120 vs A 0/120
7	Interrupts-off distribution, below; 10.8 ms not reproduced.
8	BootOptions::console_file (file chardev + FIFO input) for log_stream_stalled_reader; flood widened 4× after logd's sync change	20 runs before the widening: 18/20 (one TLB-shootdown panic on a starved vCPU, one 0-of-8 let-go under full host slots)		20 runs at 558dca9	0 × 20
9	One virtio::wait_used; Answers and the two copies deleted; a look past the bound before the panic	look replaced by None → virtio_used_ring "wait selftest FAILED"	1	virtio_used_ring	0
10	panic_halts_the_others_first	the review's 500 ms kick-and-spin → "cpu2 made a record 500 ms after the fatal one"	1	same	0
11	log_ring_keeps_the_owners_slots on tests/logkeepcase	let keep = 0; (as { let _ = owner; 0 }) → no TEST_END, 1917 flood lines	1	same	0
12	Production +2401 net (+330 of it inline tests), against +2221 at 512da5e. The −500 was not delivered.

NOTEs: lfence/isb done; flush_final says so in the black box (still spins: no timed acquire on a ticket SleepLock); UART refusal said once; QUEUED deleted (read under the lock); panic-line sync added then removed as moot once every round syncs; loom controls log-ring-tail-relaxed (101) and log-ring-loads-swapped (101) registered; shipped configs derived from ALL_CONFIGS; "a flooding child" wording. Filed: Held, the double ring mapping, ConsoleLine's state (owner's: moves a kernel/CLAUDE.md line). The xhci cue's contradiction went with the REMOVEd sentences. All REMOVE items deleted.

Gates

gate	head	exit
cargo run -- --ci host	558dca9	0 (46 green)
fast tier ×3	558dca9	1, 1, 1 (400, 401, 401/402: lan_mdns_answer ×3, syscall_window_nmi ×1)
fast tier ×3 on main fd62f56, same session		1, 1, 1 (lan_mdns_answer ×3, syscall_window_nmi ×1, quiesce_wakes_on_the_last_exit, metal_job_reboot)
syscall_window_nmi alone, 8 rounds × 2 arms, 14 spinning host threads		A 8/8 0, B 8/8 0
--nightly log_	d3512de	0 (24/24)
--nightly quiesce ×6 interleaved	11bb949	B 6/6 0; A 5/6
loom log_ring	75adfa1	0; controls 101, 101

Audio A/B, every boot

Tables are in the body; here every boot.

run 1 — per round 1..40: gaps in the first capture / soundd underruns (atl only) / the 1-min load before the run

atl1  A gaps       0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
atl1  A underruns  0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
atl1  A load       13 13 12 11 33 20 22 37 22 21 15 22 21 14 14 12 10 8 14 15 16 13 21 14 14 13 21 21 13 10 23 14 10 11 10 8 7 8 8 10
atl1  B gaps       0 0 0 0 0 0 1 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
atl1  B underruns  0 0 0 0 0 0 6 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
atl1  B load       21 11 10 29 28 18 16 37 15 14 13 22 15 11 11 9 9 12 12 11 14 10 17 11 21 10 25 15 10 8 20 11 11 10 10 7 7 7 7 10
atl1  C gaps       0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
atl1  C underruns  0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
atl1  C load       19 14 14 47 23 24 23 31 20 11 21 20 11 9 9 8 8 18 12 9 18 17 20 16 18 13 21 18 12 16 17 13 13 9 9 8 8 9 10 8
atl8  A gaps       0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
atl8  A underruns  0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
atl8  A load       13 13 12 11 33 20 22 37 22 21 15 22 21 14 14 12 10 8 14 15 16 13 21 14 14 13 21 21 13 10 23 14 10 11 10 8 7 8 8 10
atl8  B gaps       0 0 0 1 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
atl8  B underruns  0 0 0 5 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
atl8  B load       21 11 10 29 28 18 16 37 15 14 13 22 15 11 11 9 9 12 12 11 14 10 17 11 21 10 25 15 10 8 20 11 11 10 10 7 7 7 7 10
atl8  C gaps       0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
atl8  C underruns  0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
atl8  C load       19 14 14 47 23 24 23 31 20 11 21 20 11 9 9 8 8 18 12 9 18 17 20 16 18 13 21 18 12 16 17 13 13 9 9 8 8 9 10 8
hda   A gaps       0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
hda   A load       10 15 13 11 37 18 26 38 25 23 17 20 24 16 15 12 11 8 16 16 17 14 21 16 13 15 19 23 14 10 21 15 11 11 10 8 8 8 9 10
hda   B gaps       0 0 0 0 0 1 1 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
hda   B load       17 12 10 10 28 19 19 37 17 16 13 22 17 12 11 10 9 9 12 13 14 11 17 12 19 11 24 16 11 9 22 12 9 10 11 7 7 7 7 11
hda   C gaps       0 0 0 0 0 0 3 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
hda   C load       22 14 15 43 25 21 19 35 20 12 18 21 12 9 9 9 8 19 12 10 20 15 22 16 21 14 21 20 13 13 18 14 12 9 9 8 9 10 9 9

run 2 — per round 1..40: gaps in the first capture / soundd underruns (atl only) / the 1-min load before the run

atl1  A gaps       0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
atl1  A underruns  0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
atl1  A load       21 14 10 10 9 9 9 8 9 9 10 8 9 8 9 8 8 9 10 9 8 8 9 10 9 9 10 10 10 11 12 10 11 12 10 11 9 9 10 11
atl1  B gaps       0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
atl1  B underruns  0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
atl1  B load       16 13 10 8 11 9 9 8 8 8 9 10 9 9 9 9 10 10 9 8 9 8 9 10 10 9 11 10 11 10 10 13 11 10 9 10 10 9 10 12
atl8  A gaps       0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
atl8  A underruns  0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
atl8  A load       21 14 10 10 9 9 9 8 9 9 10 8 9 8 9 8 8 9 10 9 8 8 9 10 9 9 10 10 10 11 12 10 11 12 10 11 9 9 10 11
atl8  B gaps       0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
atl8  B underruns  0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
atl8  B load       16 13 10 8 11 9 9 8 8 8 9 10 9 9 9 9 10 10 9 8 9 8 9 10 10 9 11 10 11 10 10 13 11 10 9 10 10 9 10 12
hda   A gaps       0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
hda   A load       23 13 11 9 10 9 9 9 8 9 8 8 9 8 9 8 9 9 10 8 8 9 8 10 10 10 10 10 9 12 10 10 11 11 10 9 9 10 9 11
hda   B gaps       0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
hda   B load       18 12 10 9 9 10 9 8 8 9 9 8 9 8 10 8 10 9 9 9 7 8 9 10 11 9 10 11 10 11 11 11 12 10 10 10 9 9 10 10

[Japabu]

Review of #527, round 2, at 348b497 against .claude/agents/reviewer.md. I read the code and ran nothing.

Readiness: CI at 348b497 has abi-split SUCCESS and host SKIPPED (by design on pull requests). The hand-back gives --ci host exit 0 at 558dca9, and 348b497 differs from that only under issues/. Reviewed.

Net lines (git diff --shortstat origin/main...HEAD): 173 files, +6929 −3300. Split by numstat:

• production +4463 −2030 = +2433 (toyos/src/log/proof.rs counted as a test);
• tests +1914 −823 = +1091;
• src/ +99; issues −5; lockfiles +11.

Round-1 BLOCKERs

• B1, read-only copy-out: CLOSED for the rights check.
  • Every copy into user memory reaches translate_writable (copy_out through object, and user_bytes_mut through window).
  • The futex word is only read (scheduler::futex_wait).
  • The kernel's other direct-map stores go into memory the kernel built itself: the TCB tid at process.rs:902, the TLS rebase, and the inbox ring. None of them goes through a user-chosen address.
  • The check is the MMU's: USER|WRITE ANDed across PML4E, PDPTE and PDE, and the PTE on a split window. The demand pager has no copy-on-write and no lazy write-enable, so refusing a present read-only leaf after handle_page_fault is right.
  • Measured: whole-fix revert gives abuse_readonly_copyout exit 1, and head gives exit 0.
  • The check-then-write race on the unpinned path is a new BLOCKER below.
• B2, the stamp clamp: CLOSED. log_program_forgery goes red (exit 1) with the clamp reverted, and clamp_ahead runs in both read and sweep.
• B3, a refused stop: OPEN. The ordered path is measured: log_after_a_refused_stop exits 1 reverted and 0 at head. The unordered path kills logd, and a gone logd kills init; see below.
• B4, the AArch64 tid: CLOSED. TP+8 is variant I's implementation word. The compile-time assertion reds on AARCH64_TID = 16 (build 101).
• B5, the rust pin: CLOSED. git -C rust merge-base --is-ancestor 23783dc3524 origin/toyos-inbox gives 0. The inbox head 26f662d303a also contains ARM64 port, stages 0 to 3: shared groundwork, aarch64-unknown-toyos with std and the userland, and the loader and kernel reach the PL011 on virt #524's pin c34ecdf0ab6 (ancestor check 0).
• B6, audio: CLOSED on round 1's own criterion at the final code. Run 2 has B 0/120 against A 0/120, so Fisher p = 1 ≥ 0.2.
  • The attribution to the sync cadence is not established. B (4/120) against C (1/120) is p ≈ 0.19 one-sided. C gapped (3 gaps) in the same round, 7, as two of B's four.
  • Run 2's ambient load was lower (median 9.5 against 11.6–14.2), so it has less power than run 1.
  • See REMOVE and NOTE.
• B7, interrupts-off: CLOSED. The command, the distribution, and the site of each boot's longest window are given, and 10.8 ms did not recur in 16 smp-8 boots.
  • Elimination is sound for virtio_console.rs:151: one used-ring load can only be stretched by vCPU descheduling or an NMI.
  • It is not sound for :133. The window includes the notify MMIO write, which QEMU serves synchronously in the vCPU thread by running virtio-console's output handler into the chardev. That is emulated device work the design runs with IF off, not just host load. See NOTE.
• B8, the stalled reader: OPEN.
  • The channel fix is right.
  • Round 1's bar was 20/20 beside a full nightly. The 20/20 was serial, at loads 3.9–9.0.
  • Before the widening, one red was logd letting 0 of 8 go under full host slots, and it was set aside as "green alone". That is the test's own verdict failing under load.
  • The widening shows the stimulus depends on logd's throughput (the "unsure" section says so). A slower logd is a smaller stimulus, so the test is flaky by construction. See below.
• B9, one used-ring wait: CLOSED. virtio_used_ring reds (exit 1) with the look past the bound replaced by None.
• B10, the panic halts the others first: CLOSED. The review's 500 ms kick-and-spin reds panic_halts_the_others_first (exit 1).
• B11, the owner's ring slots: OPEN.
  • The red for let keep = 0 was measured before 6f35787/0f18651e, and the green at head after them. The two arms are on different logd code.
  • 0f18651 itself records that this test gives the same verdict ("no TEST_END", 1022 flood lines) when the stop's flush outruns init's 5 s bound. So the red is not specific to the slots.
• B12, net lines: noted, not a round-1 BLOCKER. Production is +2433. Concrete deletions are under NOTE.

BLOCKER

• userland/logd/src/main.rs:368-369 with userland/init/src/main.rs:228-233,891-896 — a refused stop still loses the log, now by crashing its reader.
  • logd: from_init() drains every queued frame. FLUSH only sets flush = true, but RESUME calls resume() inline, which panics while stopping is None.
  • When logd is inside one round for longer than FLUSH_BOUND (a degraded volume's sync, the case logd is built to survive), init times out, the kernel refuses the stop, and init sends RESUME. logd then pumps FLUSH and RESUME in one call and dies. That loses /log for the rest of the boot.
  • init: flush() treats a gone logd as survivable ("logd is gone, so this stop has no log to flush"), but resume() two lines later panics on the same gone logd. So a crashed logd plus a refused stop ends init.
  • Fix: handle frames in order, running the flush when FLUSH is read so RESUME always follows it, or let RESUME cancel a pending flush. Make init's resume survive a gone logd, as flush does.
  • Test: an actuator that holds logd in a round past FLUSH_BOUND, then a refused stop. logd must still be alive, and a later line must be in /log. That test goes red at head.
• kernel/src/user_ptr.rs:84-111,158-170 — copy_in and copy_out translate under the address-space lock, drop it, then read or write the frame through the direct map, with no pin.
  • A sibling thread's munmap on another CPU can free that frame between the two steps (AddressSpace::unmap → pages.remove). The PMM can then reissue it, and the kernel's store lands in memory that belongs to someone else (and copy_in reads it).
  • This is on main too. The branch rewrote this function and wrote a module doc saying such a copy "lands only where a ring 3 store from the process itself could", which this path breaks.
  • The fix is a deletion: route copy_in and copy_out through window(ptr, size_of::<T>(), access), which already pins under the lock. Keep is_user_object's bound, and object and translate go. The existing window-pin gate then covers the path.
• tests/common/origin.rs:394-401 (keeps_the_owners_slots) — the test cannot tell a lost owner slot from a cut flush.
  • Fail with a distinct verdict when the drained console (tail) carries init's "did not answer the flush" warning.
  • Then re-run the review's let keep = 0 (as { let _ = owner; 0 }) at head: it must go red on the slot verdict, not the flush one. Both arms at head.
• tests/common/logstream.rs:278-284 (stalled_reader) — the stimulus is a fixed line count, so whether any reader stalls depends on how much logd takes.
  • Flood until logd's letting lines appear, bounded by the existing deadline, rather than a count. Or show round 1's bar: 20 of 20 at head beside a full nightly.
  • The "0 of 8 under full host slots" red is either explained by this or investigated. It is not set aside.

NOTE

• kernel/src/user_ptr.rs:365-378 — the per-4 KiB step for writes has no test that can fail.
  • The mutation Access::Write => crate::mm::PAGE_2M keeps abuse_readonly_copyout green: every arm is a uniform page, and the start and end - 1 checks already catch every transition.
  • No layout the loader builds today (RX, R, RW in order, padding Read) puts a read-only page between two writable ones in one window.
  • Either test it by hand-building such a window, or record that the start and end checks are what hold today.
• kernel/src/drivers/virtio_console.rs:133-143 — the notify MMIO write is inside BackendGuard, IF off. Publishing the avail entry under the guard and notifying after dropping it would leave only constant memory work in the bracket. That is :133's millisecond windows.
• PR body, interrupts-off — the sampler patch is "never committed" and not posted. Post it in a comment so the instrument can be read.
• Audio A/B — the body does not show which sources each arm built. sysroot::fork_checkout uses a fork checkout that is ahead of its pin as it stands, so a reused worktree keeps another arm's std. Record git rev-parse HEAD and git -C rust rev-parse HEAD for each arm's worktree at build time.
• Growth, concrete deletions:
  • ConsoleLine's per-holder buffer, pieces, continues and MID_LINE (serial.rs:367-452, console.rs's piece handling in drain_queue). logd would hand whole lines of at most MAX_CONSOLE_LINE, and the one kernel/CLAUDE.md sentence is proposed to the orchestrator rather than held as a reason to keep the code.
  • stdio::ask's second dup and map for stderr. init hands the ring in one slot and the SDK binds both streams to it.
  • object/translate in user_ptr (the BLOCKER above).
  • These go some way toward the −500; none is a reason to keep them.
• Fork pin, for whichever of ARM64 port, stages 0 to 3: shared groundwork, aarch64-unknown-toyos with std and the userland, and the loader and kernel reach the PL011 on virt #524 and Logging: records from every producer, and a kernel that waits on nobody #527 lands second:
  • Merge origin/main and set rust to a fork commit containing both pins. 26f662d303a (toyos-inbox head) does. Check it with merge-base --is-ancestor against 23783dc3524 and c34ecdf0ab6 both.
  • Never resolve the gitlink with --ours or --theirs: 24aed3f is that exact silent revert.
  • Rebuild the compiler, because check_compiler refuses ARM64 port, stages 0 to 3: shared groundwork, aarch64-unknown-toyos with std and the userland, and the loader and kernel reach the PL011 on virt #524's compiler/ change until the primary rebuilds it.
  • Re-bump toyos-abi, toyos and toyos-window past the first lander's versions.
  • If ARM64 port, stages 0 to 3: shared groundwork, aarch64-unknown-toyos with std and the userland, and the loader and kernel reach the PL011 on virt #524 is second: nothing on AArch64 may run userland until its loader lays out a variant I TCB and writes TCB_TID at TP+8, and maps the clock page. A variant-II-shaped AArch64 TCB would have process.rs:902 write the tid over the DTV pointer.
• userland/logd/src/main.rs:548-550 — stopping holds every line after the flush in an unbounded String until the stop or RESUME. Bound it, as console_held is.

REMOVE

• PR body, audio: "The cause is the flush cadence". B against C is p ≈ 0.19, and C gapped in B's round 7.
• userland/logd/src/main.rs:66-67 — "lines batched for one later sync put one larger flush on the stick, and a tone playing beside it gaps": the same unmeasured cause, stated in the source.
• PR body, interrupts-off: "which are constant work, so their length is host time inside the bracket". False for :133, whose bracket includes QEMU's synchronous notify.

SEND BACK

[Japabu]

Hand-back for the round-2 review at 348b497. Head a8c37cf, which differs from 618e68e only under issues/; the body is current. Every exit below is the command's own. origin/main (#524) is merged in 76bd2bc.

BLOCKERs

#	what was done	red: mutation or scenario (checked patch, built)	exit	green	exit	both at
copy race	copy_in/copy_out go through window, which pins under the address-space lock; translate deleted, object is is_user_object over a pinned window. user_copy_races_munmap + actuator copy-meets-a-remap	object put back on the unpinned translate_user (the old code) → "a copy held across a sibling's munmap stored into the region mapped after it: byte 0 is 0x1", wide and alone	1	user_copy_races_munmap	0	76bd2bc
B3	logd reads init's frames up to a FLUSH and runs it before reading on; --hold-flush; init's resume warns on a gone logd; init counts unanswered flushes. log_resume_meets_its_flush on tests/logflushcase	logd's from_init and init back to 348b497 (the actuator, config and test kept) → "logd ended before the machine did: exit: logd pid=4 code=101", wide and alone	1	log_resume_meets_its_flush	0	76bd2bc
B8	floods until all 8 let-go lines are seen, bounded by the flood's ceiling; log_flood's count argument deleted, its lines back to 64 bytes	—		20 runs beside the fast tier (below)	0 × 20	618e68e
B11	its own verdict when the stop's flush was not answered: init's warning on the console, init's stop line missing from /log, or the kernel's Syncing filesystems... ≥ 5000 ms after that line	let keep = { let _ = owner; 0 }; → "/log carries no "===TEST_END test_rs_log_flood exit=0===": the child's flood took the slots… (1917 flood lines)", wide and alone, the slot verdict	1	log_ring_keeps_the_owners_slots ×5 (185–203 ms stop to sync)	0 ×5	b601025
B11, flush verdict		logd --hold-flush in tests/logkeepcase → "the stop went ahead without the flush's answer (init's stop line never reached /log)", wide and alone	1			b601025

B11 found a real flake: with the flush verdict in place, 3 of 3 runs at 7544e7a were red wide on it (6118, 6088, 6185 ms from init's stop line to the kernel's sync, against init's 5000 ms bound) and green alone (3184, 2995 ms). A full ring of 960-byte flood lines was about 1.8 MB to flush. The width existed for the stalled reader, which no longer needs it; at 64 bytes the same test syncs 185–203 ms after the stop line.

NOTEs

• Audio arms: each arm's tree and the fork commit it pins are in the body. The fork checkout each worktree held at build time was not recorded and arm A's worktree is gone, so that is said as unestablished rather than filled in.
• REMOVE: logd's header sentence and the body's "The cause is the flush cadence" and "constant work" sentences are gone.
• virtio notify: write_burst publishes under BackendGuard and rings the doorbell after it (Virtqueue::publish, Doorbell); the panic path rings again before it waits a burst out. The sampler was not re-run after this.
• Sampler: below, as applied to both arms (git apply --check 0 against 17eb66a and against 11bb949).
• Per-4 KiB write step: the walk moved into toyos_userbound::contiguous, pure; a_write_across_a_read_only_page_between_writable_ones_is_refused builds a split window with page 2 read-only. The mutation Access::Write => PAGE_2M (now in span.rs): toyos-userbound suite 18 passed, 1 failed, exit 101; green 19 passed, exit 0.
• stopping bounded: 1 MiB (STOPPING_BYTES); past it lines are counted and said at a resume.
• B12 deletions: object/translate (as above); the console-unbuffered actuator and serial::write_console, which nothing armed; log_flood's argument; wait_for_log_file again, which the merge brought back from main's panic.rs. Not done, with the measurement in the issue: ConsoleLine's pieces and per-holder state carry a joined program line up to JOIN_BYTES (64 KiB), past MAX_CONSOLE_LINE and past the whole queue, so logd does not hand lines of at most MAX_CONSOLE_LINE and deleting them needs a line bound in toyos-abi (issues/design-debt/a-console-holders-line-state-guards-writers-that-no-longer-exist.md). stdio's second mapping: nothing tells a program its two slots name one ring, so binding stderr to stdout's mapping is wrong for a child with two rings, and init handing one slot changes every program's inherited slot 2 (issues/design-debt/a-programs-two-streams-map-its-one-ring-twice.md).
• Net lines (git diff --numstat origin/main...HEAD, production = everything but tests/, toyos/src/log/proof.rs, src/, issues/, lockfiles; inline #[cfg(test)] counted as production): production +4961 −2075 = +2886 at a8c37cf, against +2648 counted the same way at 348b497; tests +1134; src/ +105; issues +41; lockfiles +11.

The merge and the pin

• rust is at 64a2050c484: 23783dc3524 merged with main's c34ecdf0ab6 in the fork, pushed to wt-toyos-logtrack and merged into toyos-inbox (645d1c70732). git merge-base --is-ancestor: 23783dc3524 → 64a2050c484 0, c34ecdf0ab6 → 64a2050c484 0, 64a2050c484 → origin/toyos-inbox 0. 26f662d303a was not taken: it also carries a84b4aa849c, x86-64's switch to rust-lld, another branch's compiler/ change. The pin's compiler/ is c34ecdf0ab6's byte for byte, so this worktree builds on compiler 7db54a511d66ac60, the one main needs.
• AArch64 TCB: the loader main now carries lays variant I out (TP+0 the DTV pointer, TP+8 zeroed), and TCB_TID is TP+8 there, so the tid store is on the zeroed word, not the DTV pointer.
• SDK: toyos-abi 0.16.0, toyos 0.18.0, toyos-window 0.20.0 (main is at 0.15.0, 0.17.0, 0.19.0); --ci abi-split says so.
• main's new architecture rule redded --ci host on this branch's asm!/target_arch in toyos-abi's clock.rs and lib.rs: they moved unchanged to toyos-abi/src/arch/, which the rule now names, and three guest probes joined the declared exceptions (618e68e).

Gates

gate	head	exit	notes
cargo run -- --ci host	618e68e	0	48 steps green, the loom controls among them
cargo run -- --ci abi-split	618e68e	0	toyos-abi 0.15.0 → 0.16.0, toyos 0.17.0 → 0.18.0, toyos-window 0.19.0 → 0.20.0
loom log_ring (--features loom --test log_ring --release)	618e68e	0	3 of 3
toyos-userbound suite	618e68e	0	19 of 19
cargo test --test toyos-build (fast tier)	618e68e	1	406 of 407. lan_mdns_answer: a tap socket path past SUN_LEN; main 5e446e5 in the same session, exit 1 on the same message (issues/build/a-lane-s-tap-socket-path-is-past-sun-len-on-the-dev-host.md). Run beside the stalled-reader loop below.
the fast tier again, as the loop's load	618e68e	1	403 of 407: lan_mdns_answer as above; quiesce_stops_the_machine, launcher_refusals and port_poll_churn red wide and green alone, at 1-minute loads up to 96. The first is filed with its mechanism, issues/kernel/a-holders-queued-line-can-reach-the-console-after-the-last-word.md, not fixed; the other two were not investigated.
--nightly log_stream_stalled_reader, 20 runs beside the fast tier	618e68e	0 × 20	1-minute load 16.6–96.3 (median 36.3); 13–37 floods before all 8 readers were let go
--nightly log_	b601025	0	25 of 25
--nightly console_line_atomicity	618e68e	0
user_copy_races_munmap, log_resume_meets_its_flush, log_after_a_refused_stop, abuse_readonly_copyout, munmap_reissues_read_window, panic_halts_the_others_first, virtio_used_ring	76bd2bc	0 each
log_ring_keeps_the_owners_slots, 5 runs	b601025	0 × 5	the kernel synced 185–203 ms after init's stop line

The interrupts-off sampler, as run

diff --git a/kernel/src/drivers/serial.rs b/kernel/src/drivers/serial.rs
index d2489db3..45f9b87e 100644
--- a/kernel/src/drivers/serial.rs
+++ b/kernel/src/drivers/serial.rs
@@ -98,7 +98,7 @@ pub struct BackendGuard {
 
 /// This CPU's own `RFLAGS`, captured by `pushfq`; the only value `popfq` may be given.
 /// Not `Copy`/`Clone`: one CPU's state at one instant, not to be duplicated.
-pub struct SavedFlags(u64);
+pub struct SavedFlags(u64, u64, &'static core::panic::Location<'static>);
 
 impl SavedFlags {
     /// Restores the flags; `&self` because `Drop` cannot move a field out, and restoring twice is idempotent.
@@ -114,10 +114,12 @@ impl SavedFlags {
                 options(nomem),
             );
         }
+        crate::irqoff::closed(self.1, self.2, self.0);
     }
 }
 
 impl BackendGuard {
+    #[track_caller]
     pub fn lock() -> Self {
         let rflags = save_and_cli();
         while BACKEND_LOCKED
@@ -132,6 +134,7 @@ impl BackendGuard {
     }
 
     /// Non-blocking acquire: `None` if another CPU already holds the backend.
+    #[track_caller]
     pub fn try_lock() -> Option<Self> {
         let rflags = save_and_cli();
         if BACKEND_LOCKED
@@ -183,6 +186,7 @@ impl Drop for BackendGuard {
 /// This CPU's `RFLAGS`, captured with interrupts off in one instruction sequence:
 /// the value is stale if anything runs between the read and `cli`.
 #[inline]
+#[track_caller]
 fn save_and_cli() -> SavedFlags {
     let rflags: u64;
     // SAFETY: irreducible — `pushfq`/`cli` have no safe spelling; the asm reads
@@ -196,7 +200,7 @@ fn save_and_cli() -> SavedFlags {
             options(nomem),
         );
     }
-    SavedFlags(rflags)
+    SavedFlags(rflags, crate::irqoff::now(), core::panic::Location::caller())
 }
 
 pub fn has_data() -> bool {
diff --git a/kernel/src/hw.rs b/kernel/src/hw.rs
index 21fd5c78..4f03eef5 100644
--- a/kernel/src/hw.rs
+++ b/kernel/src/hw.rs
@@ -30,9 +30,12 @@ pub fn now_ns() -> u64 {
 #[must_use = "the interrupt gate closes when the guard drops"]
 pub struct IrqGuard {
     rflags: u64,
+    at: u64,
+    site: &'static core::panic::Location<'static>,
 }
 
 impl IrqGuard {
+    #[track_caller]
     pub fn close() -> Self {
         let rflags: u64;
         // SAFETY: touches only RFLAGS and one pushed-and-popped stack slot; `cli` cannot fail in
@@ -41,7 +44,7 @@ impl IrqGuard {
         unsafe {
             asm!("pushfq", "pop {}", "cli", out(reg) rflags, options(nomem));
         }
-        Self { rflags }
+        Self { rflags, at: crate::irqoff::now(), site: core::panic::Location::caller() }
     }
 }
 
@@ -52,6 +55,7 @@ impl Drop for IrqGuard {
         unsafe {
             asm!("push {}", "popfq", in(reg) self.rflags, options(nomem));
         }
+        crate::irqoff::closed(self.at, self.site, self.rflags);
     }
 }
 
@@ -79,6 +83,7 @@ impl Machine for KernelHw {
         apic::stop_timer();
     }
 
+    #[track_caller]
     fn irq_guard(&self) -> IrqGuard {
         IrqGuard::close()
     }
diff --git a/kernel/src/irqoff.rs b/kernel/src/irqoff.rs
new file mode 100644
index 00000000..5584093d
--- /dev/null
+++ b/kernel/src/irqoff.rs
@@ -0,0 +1,48 @@
+//! MEASUREMENT ONLY, never committed: the longest window an `IrqGuard` or a
+//! `BackendGuard` held interrupts off, from an outermost close to its restore,
+//! said with the site that opened it each time a longer one is seen.
+
+use core::panic::Location;
+use core::sync::atomic::{AtomicBool, AtomicU64, Ordering};
+
+static MAX_NS: AtomicU64 = AtomicU64::new(0);
+static REPORTING: AtomicBool = AtomicBool::new(false);
+const FLOOR_NS: u64 = 100_000;
+
+pub fn now() -> u64 {
+    crate::clock::nanos_since_boot()
+}
+
+pub fn closed(at: u64, site: &'static Location<'static>, rflags: u64) {
+    // After the boot's console is virtio's: the UART phase before it is the
+    // boot's, not what a running machine's audio meets.
+    if rflags & 0x200 == 0
+        || at == 0
+        || !crate::log::PERCPU_READY.load(Ordering::Relaxed)
+        || !crate::drivers::virtio_console::is_ready()
+    {
+        return;
+    }
+    let took = now().saturating_sub(at);
+    let mut max = MAX_NS.load(Ordering::Relaxed);
+    loop {
+        if took <= max || took < FLOOR_NS {
+            return;
+        }
+        match MAX_NS.compare_exchange_weak(max, took, Ordering::Relaxed, Ordering::Relaxed) {
+            Ok(_) => break,
+            Err(seen) => max = seen,
+        }
+    }
+    if REPORTING.swap(true, Ordering::Acquire) {
+        return;
+    }
+    crate::log!(
+        "irqoff: {} us at {}:{} on cpu{}",
+        took / 1000,
+        site.file(),
+        site.line(),
+        crate::arch::percpu::cpu_id()
+    );
+    REPORTING.store(false, Ordering::Release);
+}
diff --git a/kernel/src/main.rs b/kernel/src/main.rs
index 360ba473..988c31ca 100644
--- a/kernel/src/main.rs
+++ b/kernel/src/main.rs
@@ -81,6 +81,7 @@ mod irq_census;
 mod irq_ring;
 mod trace;
 mod time;
+mod irqoff;
 mod clock;
 mod rtc;
 

[Japabu]

Round-2 BLOCKERs closed and judged at a8c37cf: the user-copy race closed by routing copy_in/copy_out through window (user_copy_races_munmap red on the unpinned path), logd survives FLUSH and RESUME together (log_resume_meets_its_flush), the stalled-reader test floods until let-go (20/20 beside the fast tier at loads to 96), and the ring-slot verdict is separated from a waited-out flush (both arms at one head). T14 run 150 (orchestrator) at this head: metal_device_probe PASS, no panic, log partition passes toyos-fat32-check, kernel to Boot: complete 1225 ms. The console-after-last-word defect this branch introduces is filed with its mechanism. Landing.