From 602cff0e2d65462fde36e0a29c0a6d0336ff2062 Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 27 Sep 2026 05:31:13 +0200 Subject: [PATCH 01/14] rootfs: a disk that does not answer ROOT's hold is named, never a panic `usb_transport_break` has been red since #506: its `transport_gives_up` boot leaves the gate's disk offline and still registered, `hold_source` asked `gpt::claimable` for ROOT's partition, the offline disk's table read failed, `claimable` answered `Unusable` before it had looked at the boot stick, and `hold_source` panicked the boot on it. A device crashed the kernel. `gpt::seek` now reads every disk and names the ones that did not answer instead of stopping at the first. `hold_source` holds ROOT's span when a disk that answered carries it: a silent disk that answers later either lacks it, or carries it again and makes every claim of it `Ambiguous`. Every other outcome (on no disk that answered, carried twice, refused by its table, no span a view can hold) withholds ROOT's GUID from every claim through `gpt::withhold`, which `claimable` answers `KernelDriven`, the same answer a claim of the held span gets. Neither path refuses the boot. `claimable` keeps its answers: a silent disk still makes it `Unusable`. `transport_gives_up` now asserts the hold line names the disk the gate left offline. Measured: - fix: `cargo test --test toyos-build -- --nightly usb_transport_break` EXIT=0, three runs. - negative control, the whole fix reverted onto 1ce71831 as a checked patch: EXIT=1, `PANIC: panicked at src/rootfs.rs:177:19: boot: the partition ROOT was read from, ..., cannot be held: Unusable`, wide and alone. - mutation, a silent disk not recorded (`silent.clear()`): EXIT=1 on the new assertion, wide and alone. Co-Authored-By: Claude Opus 5.5 (1M context) Claude-Session: https://claude.ai/code/session_014iqcj4jDKpaiDX8B7CMvmK --- kernel/src/gpt.rs | 72 ++++++++++++++++++++++++++++++++++++++------ kernel/src/rootfs.rs | 57 ++++++++++++++++++++++------------- tests/common/usb.rs | 9 ++++++ 3 files changed, 107 insertions(+), 31 deletions(-) diff --git a/kernel/src/gpt.rs b/kernel/src/gpt.rs index 04984b591b..c2a1530f06 100644 --- a/kernel/src/gpt.rs +++ b/kernel/src/gpt.rs @@ -334,6 +334,25 @@ pub struct Claimable { pub unique: Guid, } +/// Partitions no claim may take whatever a table says: ROOT's source, when +/// the boot could not hold its span (`rootfs::hold_source`). +static WITHHELD: Lock> = Lock::new(Vec::new()); + +/// Refuse every claim of `guid` for the machine's life, as the kernel's. +pub fn withhold(guid: PartGuid) { + WITHHELD.lock().push(Guid(guid.0)); +} + +/// Where one partition is on the disks that answered, and which did not. +pub struct Sought { + /// The one partition carrying the GUID, `None` where no table that + /// answered carries it, or the refusal a table's answer makes. + pub found: Result, ClaimError>, + /// The disks that did not answer a read of their table, of which neither + /// "none" nor "one" is known. + pub silent: Vec, +} + /// The one partition on this machine whose unique GUID is `guid`, past the /// range and overlap checks `toyos_gpt::locate` makes (UEFI 2.10 §5.3.3). /// @@ -341,12 +360,33 @@ pub struct Claimable { /// partition, so no claim can write one. `Absent` for a GUID no table carries /// and for the zero GUID, which GPT gives every unused entry; `Ambiguous` for /// one carried twice, on one disk or across two; `Unusable` for a disk that -/// did not answer, since then neither "none" nor "one" is known. +/// did not answer, since then neither "none" nor "one" is known; +/// `KernelDriven` for a GUID [`withhold`] named. pub fn claimable(guid: PartGuid) -> Result { let target = Guid(guid.0); if target.is_zero() { return Err(ClaimError::Absent); } + if WITHHELD.lock().contains(&target) { + log!("partclaim: {target} is where ROOT was read from, and the kernel withholds it"); + return Err(ClaimError::KernelDriven); + } + let sought = seek(guid); + let found = sought.found?; + if !sought.silent.is_empty() { + return Err(ClaimError::Unusable); + } + found.ok_or(ClaimError::Absent) +} + +/// Look for `guid` on every disk [`probe`] read, reading past a disk that does +/// not answer and naming it. +pub fn seek(guid: PartGuid) -> Sought { + let target = Guid(guid.0); + let mut silent = Vec::new(); + if target.is_zero() { + return Sought { found: Err(ClaimError::Absent), silent }; + } let disks = DISKS.lock().clone(); let mut found: Option = None; for (handle, lba_bytes) in &disks { @@ -354,7 +394,11 @@ pub fn claimable(guid: PartGuid) -> Result { let part = match toyos_gpt::locate(&mut DeviceSectors::new(handle, *lba_bytes), target) { Ok(located) => located.partition, Err(e) => { - table_refused(id, target, e)?; + match table_refused(id, target, e) { + Ok(Unread::Lacks) => {} + Ok(Unread::Silent) => silent.push(id), + Err(refused) => return Sought { found: Err(refused), silent }, + } continue; } }; @@ -364,7 +408,7 @@ pub fn claimable(guid: PartGuid) -> Result { partition", first.volume.device ); - return Err(ClaimError::Ambiguous); + return Sought { found: Err(ClaimError::Ambiguous), silent }; } found = Some(Claimable { volume: Volume { @@ -376,17 +420,25 @@ pub fn claimable(guid: PartGuid) -> Result { unique: part.unique_guid, }); } - found.ok_or(ClaimError::Absent) + Sought { found: Ok(found), silent } +} + +/// A disk whose table gave no partition for a GUID, and no refusal. +enum Unread { + /// Its table does not carry the GUID. + Lacks, + /// It did not answer a read of its table. + Silent, } -/// What a table's refusal means for a claim: `Ok` for a disk that does not -/// carry the partition, or the claim's refusal. -fn table_refused(id: DeviceId, target: Guid, e: GptError) -> Result<(), ClaimError> { +/// What a table's refusal means for a claim: a disk that does not carry the +/// partition, one that did not answer, or the claim's refusal. +fn table_refused(id: DeviceId, target: Guid, e: GptError) -> Result { match e { - GptError::NotFound { .. } => Ok(()), + GptError::NotFound { .. } => Ok(Unread::Lacks), GptError::ReadFailed(lba) => { log!("partclaim: device {id} did not answer a read of LBA {lba} while looking for {target}"); - Err(ClaimError::Unusable) + Ok(Unread::Silent) } GptError::DuplicateUniqueGuid { first, second } => { log!("partclaim: device {id} carries {target} in entries {first} and {second}"); @@ -412,7 +464,7 @@ fn table_refused(id: DeviceId, target: Guid, e: GptError) -> Result<(), ClaimErr | GptError::EntryArrayTooBig { .. } | GptError::EntryArrayMisplaced { .. } | GptError::EntryArrayCrc { .. } - | GptError::UsableRangeCoversBackup { .. } => Ok(()), + | GptError::UsableRangeCoversBackup { .. } => Ok(Unread::Lacks), } } diff --git a/kernel/src/rootfs.rs b/kernel/src/rootfs.rs index a6fce2f923..cf1c3ec9ea 100644 --- a/kernel/src/rootfs.rs +++ b/kernel/src/rootfs.rs @@ -8,8 +8,8 @@ //! `mm::init` keeps out of the allocator. [`mount`] refuses the boot by name on //! a handoff with no image, and on an image whose superblock is not the one //! `root=` names. [`hold_source`] holds the partition the image came from once -//! the disks are up, so no claim writes the slot this boot runs, and refuses -//! the boot when it cannot say that no claim will. The image's bytes crossed a +//! the disks are up, so no claim writes the slot this boot runs, and withholds +//! its GUID from every claim when it cannot hold it. The image's bytes crossed a //! trust boundary like any disk's, so every read of it is bounds-checked and a //! block outside it is a refused read, never a panic. @@ -161,20 +161,26 @@ pub fn mount() -> Mounted { /// Hold the partition ROOT was read from, so no process's claim writes the /// slot this boot is running. Runs once the disks are probed. /// -/// A partition on no disk this kernel drives is one no claim can write either, -/// and one carried twice is one every claim is refused as carried twice, since -/// the disks a claim looks on only grow and no claim holds a table. Every other -/// answer leaves a later claim free to find the partition, so it refuses the -/// boot. +/// Found on the disks that answered, its span is held: a disk that did not +/// answer and later does either lacks it, or carries it again and makes every +/// claim of it `Ambiguous`. Anywhere else — on no disk that answered, carried +/// twice, refused by its own table, or no span a view can hold — its GUID is +/// withheld from every claim instead, so no disk's answer, now or later, can +/// hand it out. Neither path refuses the boot: a disk is a device, and a device +/// never crashes this kernel. pub fn hold_source() { - let guid = toyos_gpt::Guid(BOOT.lock().source); - let found = match crate::gpt::claimable(toyos_abi::part::PartGuid(guid.0)) { - Ok(found) => found, - Err(e @ (ClaimError::Absent | ClaimError::Ambiguous)) => { - log!("root: the partition ROOT was read from, {guid}, is claimable by no one ({e:?})"); - return; + let guid = toyos_abi::part::PartGuid(BOOT.lock().source); + let sought = crate::gpt::seek(guid); + let found = match sought.found { + Ok(Some(found)) => found, + Ok(None) | Err(ClaimError::Absent) => { + return withhold(guid, "it is on no disk that answered", &sought.silent) + } + Err(ClaimError::Ambiguous) => return withhold(guid, "it is carried twice", &sought.silent), + Err(ClaimError::Unusable) => return withhold(guid, "its table refuses it", &sought.silent), + Err(e @ (ClaimError::Owned | ClaimError::KernelDriven | ClaimError::Exhausted)) => { + panic!("rootfs: gpt::seek answered {e:?}, which no table read makes") } - Err(e) => panic!("boot: the partition ROOT was read from, {guid}, cannot be held: {e:?}"), }; let volume = found.volume; let view = crate::block::open(volume.device) @@ -187,14 +193,23 @@ pub fn hold_source() { }); match view { Ok(view) => { - log!("root: holding {}, the partition ROOT was read from, on device {}", found.unique, volume.device); + log!( + "root: holding {}, the partition ROOT was read from, on device {}; disks that did \ + not answer: {:?}", + found.unique, volume.device, sought.silent + ); *SOURCE.lock() = Some(view); } - // The same refusals a claim of it meets in `device::partition_view`, - // so a partition this cannot hold is one no claim can take either. - Err(()) => log!( - "root: the partition ROOT was read from, {}, is on device {} and is no span a view can hold", - found.unique, volume.device - ), + Err(()) => withhold(guid, "it is no span a view can hold", &sought.silent), } } + +/// Refuse every claim of ROOT's source, saying why it was not held. +fn withhold(guid: toyos_abi::part::PartGuid, why: &str, silent: &[crate::block::DeviceId]) { + log!( + "root: the partition ROOT was read from, {}, is not held because {why}; every claim of it \ + is refused; disks that did not answer: {silent:?}", + toyos_gpt::Guid(guid.0) + ); + crate::gpt::withhold(guid); +} diff --git a/tests/common/usb.rs b/tests/common/usb.rs index 6cd53913a9..7a277c8ec4 100644 --- a/tests/common/usb.rs +++ b/tests/common/usb.rs @@ -2733,6 +2733,15 @@ fn transport_gives_up( } gate_ran(&boot, 2)?; check_geometry(&boot, bytes, lba)?; + // The gate leaves its disk offline and still registered, so ROOT's hold + // reads a table that does not answer: it holds ROOT off the boot stick and + // names that disk, rather than refusing the boot over it. + let Some(held) = boot.lines().find(|l| l.contains("root: holding ")) else { + return Err(format!("the boot never held the partition ROOT was read from\n{log}")); + }; + if held.ends_with("disks that did not answer: []") { + return Err(format!("{held:?}: the disk the gate left offline answered ROOT's hold\n{log}")); + } // The budget is the kernel's declaration, read off the gate's own line. let Some(budget) = boot From dbf4ace5655651d2ca773323637ec579f28f35e0 Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 27 Sep 2026 05:41:16 +0200 Subject: [PATCH 02/14] boot: the i8042 probe runs first in the device phase, after storage `screen_diag_boot` has been red since #506. #506 moved storage behind init's spawn, which left the i8042 probe in the peripherals phase, before NVMe, xHCI, the USB disks, ROOT's hold and the mounts. The first `i8042:` line then sat 86 rows above `Boot: complete`. The diagnostic boot's panel shows the log's tail, and the T14's panel holds 67 rows, so the line that answers "why is the keyboard dead" was off the flashed machine's screen. QEMU's 3-page log no longer showed it on its last page either. Before #506 the probe ran after storage (run 36111884575's diag boot: 57 rows above the end). It now runs first in the device phase, which is after storage again. Nothing between the two positions reads a key: no task runs before `smp::set_ready`. Measured: - before: `cargo test --test toyos-build -- --nightly screen_diag_boot` EXIT=1, `"i8042:" is not on screen five seconds after the boot finished`, wide and alone. - after: EXIT=0, the first `i8042:` line 16 rows above the end. - the suites the probe's position can move, after: `--nightly i8042` EXIT=0 (13 tests), `screen_` EXIT=0 (22), `pre_idle` EXIT=0, `keyboard` EXIT=0, `console_locale` EXIT=0. Co-Authored-By: Claude Opus 5.5 (1M context) Claude-Session: https://claude.ai/code/session_014iqcj4jDKpaiDX8B7CMvmK --- kernel/src/main.rs | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/kernel/src/main.rs b/kernel/src/main.rs index 14da5f126f..2965c69819 100644 --- a/kernel/src/main.rs +++ b/kernel/src/main.rs @@ -425,7 +425,6 @@ pub(crate) unsafe extern "C" fn kernel_main(kernel_args: &KernelArgs) -> ! { arch::watchdog::init(&pci_devices); file_cache::init(); gpt::init(kernel_args); - arch::boot::platform_devices(kernel_args.rsdp_addr); acpi::init_power(kernel_args.rsdp_addr); boot_phase!("peripherals ready", t_periph); @@ -586,6 +585,10 @@ pub(crate) unsafe extern "C" fn kernel_main(kernel_args: &KernelArgs) -> ! { let t_devices = clock::nanos_since_boot(); + // First in the device phase, after storage: its lines are the diagnostic + // boot's answer for a dead keyboard, and a panel shows the log's tail. + arch::boot::platform_devices(kernel_args.rsdp_addr); + // Runs once for the machine: it touches no device, so per-driver repetition would say the same thing four times. #[cfg(feature = "boot-actuators")] if actuator::virtio_used_selftest() { From bf4fb069febeaf4067f0ef7cd4670ee849aec80b Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 27 Sep 2026 06:19:13 +0200 Subject: [PATCH 03/14] fsync-budget-spent: each run's first attempt is refused once, not every flush's `home_budget_refusal_retried` and `log_flush_retry` timed out waiting for `===READY===` on the nightly (run 36285169430). Both arm `fsync-budget-spent`, which ran the first attempt of every `until_answered` run under an operation already over. Since logd owns `/log`, logd flushes after every round it wrote a line in, and each refused-then-retried flush commits four kernel records. Those records are the next round's lines, so the next flush is refused too. The storm never ends. In CI it reached `_0003.log` by 28 s and `===READY===` never reached the console. The actuator now refuses once per run: a file's `SYS_FSYNC` keyed by its `FileId`, and a claimed partition's read, write and flush keyed by device, unique GUID and kind. That matches what the actuator stands in for: a loaded host whose budget ran out once, not on every flush forever. Each of its tests still has its own first attempt refused. The loop itself is a logd defect on a device whose every flush overruns its budget. It is filed as issues/filesystem/logd-flushes-the-records-its-own-refused-flush-made.md. `home_budget_refusal_retried` now judges the storm's absence: no flush retried in the 2 s after the guest's. Measured: - negative control, the kernel half reverted as a checked patch with the new judge kept: `cargo test --test toyos-build -- --nightly home_budget_refusal_retried` EXIT=1, `220 flush(es) retried in the 2 s after the guest's` wide and `131` alone. - fix: EXIT=0. - every arm of the actuator, after: `--nightly log_flush_retry` EXIT=0, `partition_claim` EXIT=0 (3), `fsync` EXIT=0 (6), `quiesce` EXIT=0 (5), `home_` EXIT=0. Co-Authored-By: Claude Opus 5.5 (1M context) Claude-Session: https://claude.ai/code/session_014iqcj4jDKpaiDX8B7CMvmK --- ...-the-records-its-own-refused-flush-made.md | 33 ++++++++++++++ kernel/src/actuator.rs | 6 +-- kernel/src/object/ops.rs | 43 +++++++++++++++++-- kernel/src/syscall/device.rs | 6 ++- tests/common/storage.rs | 16 +++++++ tests/common/volumes.rs | 6 +-- 6 files changed, 98 insertions(+), 12 deletions(-) create mode 100644 issues/filesystem/logd-flushes-the-records-its-own-refused-flush-made.md diff --git a/issues/filesystem/logd-flushes-the-records-its-own-refused-flush-made.md b/issues/filesystem/logd-flushes-the-records-its-own-refused-flush-made.md new file mode 100644 index 0000000000..5f614f1708 --- /dev/null +++ b/issues/filesystem/logd-flushes-the-records-its-own-refused-flush-made.md @@ -0,0 +1,33 @@ +--- +status: open +kind: defect +opened: 2026-09-27 +--- + +# `logd` flushes the records its own refused flush made, for as long as flushes are refused + +`logd` makes the volume durable after every round it wrote a line in. A +flush whose first attempt is budget-refused and then retried commits four +kernel records: the storage driver's `not issued` and `ran out of its +operation budget`, the volume's `the device would not answer in the caller's +own budget`, and `fsync: durable on attempt 2`. Those records are the +next round's lines, so that round flushes again. While every flush's first +attempt is refused, the log never goes quiet. It grows by those four records +per round, rotates, and the boot's own early files are rotated away. + +Measured at dbf4ace5 with `fsync-budget-spent` refusing every flush's first +attempt, as it did before this branch. In the 2 s after +`home_budget_refusal_retried`'s guest finished, 220 and 131 `/log` flushes +were retried (two runs, `cargo test --test toyos-build -- --nightly +home_budget_refusal_retried`, TCG on the dev host). In CI (run 36285169430, +KVM) the same storm reached `_0003.log` by 28 s, and neither +`home_budget_refusal_retried` nor `log_flush_retry` saw `===READY===`. + +The actuator now refuses once per file, so no test stages this any more. On +hardware the loop needs a device whose every flush overruns its operation +budget. Each round then costs at least that budget, so the loop is slow, but +it never ends while the device stays that slow. + +**Exit**: a refused-then-retried flush's own records do not by themselves make +`logd` flush again without end, shown by a boot that refuses every flush's +first attempt and whose log goes quiet. diff --git a/kernel/src/actuator.rs b/kernel/src/actuator.rs index 805501daf4..3a52e83685 100644 --- a/kernel/src/actuator.rs +++ b/kernel/src/actuator.rs @@ -244,9 +244,9 @@ actuators! { /// Put the shared-object cache's byte budget within reach of the libraries a guest can build, so the shipped refusal runs at all. so_cache_tiny = "so-cache-tiny"; - /// Run the first attempt of every block operation `object::ops::until_answered` - /// retries — `SYS_FSYNC`, a partition transfer — under an operation that is - /// already over. + /// Run the first attempt of each run `object::ops::until_answered` retries — + /// a file's `SYS_FSYNC`, a claimed partition's read, write or flush — under an + /// operation that is already over, once per file and per partition and kind. fsync_budget_spent = "fsync-budget-spent"; /// Make the deadman of every run `object::ops::until_answered` makes already diff --git a/kernel/src/object/ops.rs b/kernel/src/object/ops.rs index 596ce5965b..ccc2f28fc5 100644 --- a/kernel/src/object/ops.rs +++ b/kernel/src/object/ops.rs @@ -625,7 +625,7 @@ pub fn fsync(object: &KObjectRef) -> u64 { // A refused attempt can leave the two FATs split, and the park between two attempts is where the machine's stop would find this thread. let _update = crate::block::begin_update(); // A refused attempt discards nothing — an unsettled debt needs no restoring. - let run = until_answered(|| { + let run = until_answered(Run::Fsync(file_id), || { // Outside `FileObject`'s lock: this and `OpenFileState::drop` take the VFS lock in the same order. // Flush and sync share one acquisition so this file cannot be unmounted between them. let mut vfs = crate::vfs::lock(); @@ -676,13 +676,47 @@ pub(crate) enum Answered { Deadman { attempts: u32, took: crate::time::Duration }, } +/// Whose run of attempts [`until_answered`] makes: what `fsync-budget-spent` +/// refuses the first attempt of, once. +#[derive(Clone, Copy, PartialEq, Eq, PartialOrd, Ord)] +#[cfg_attr(not(feature = "boot-actuators"), allow(dead_code))] +pub(crate) enum Run { + /// `SYS_FSYNC` on one file. + Fsync(file_cache::FileId), + /// One kind of transfer on one claimed partition; `None` for a claim + /// whose partition is already let go, whose every attempt answers `Gone`. + Claim(Option<(crate::block::DeviceId, [u8; 16])>, ClaimOp), +} + +/// A partition claim's kinds of transfer, each refused once on its own. +#[derive(Clone, Copy, PartialEq, Eq, PartialOrd, Ord)] +pub(crate) enum ClaimOp { + Read, + Write, + Flush, +} + +/// Whether `run`'s first attempt goes under an operation already over: once +/// per run, so a writer whose every flush leaves records to flush (`logd`) +/// is refused once and not on every flush it will ever make. +#[cfg(feature = "boot-actuators")] +fn staged_spent(run: Run) -> bool { + static REFUSED: crate::sync::Lock> = + crate::sync::Lock::new(alloc::collections::BTreeSet::new()); + crate::actuator::fsync_budget_spent() && REFUSED.lock().insert(run) +} + /// `attempt` run until it answers anything but `WouldBlock` — a budget that /// expired on a live device, never a device fact — each time on a fresh /// budget, parked between two (`block::between_attempts`), and given up once /// [`crate::block::DEADMAN`] is spent. The one loop in this kernel that asks a /// block device again, for a caller holding no spinlock: nothing it holds can /// be held across the wait, so no disk wait here is under one. -pub(crate) fn until_answered(mut attempt: impl FnMut() -> Result<(), SyscallError>) -> Answered { +#[cfg_attr(not(feature = "boot-actuators"), allow(unused_variables))] +pub(crate) fn until_answered( + run: Run, + mut attempt: impl FnMut() -> Result<(), SyscallError>, +) -> Answered { let began = crate::clock::now(); // Bounds the run of attempts, never a single attempt's elapsed time. let deadman = Deadline::at(began + crate::block::DEADMAN.duration()); @@ -694,7 +728,7 @@ pub(crate) fn until_answered(mut attempt: impl FnMut() -> Result<(), SyscallErro let answer = { // Stages a first attempt with its budget already spent, exercising the shipped refusal itself. #[cfg(feature = "boot-actuators")] - let _spent = (attempts == 1 && crate::actuator::fsync_budget_spent()) + let _spent = (attempts == 1 && staged_spent(run)) .then(|| crate::scheduler::Operation::begin(Deadline::passed())); attempt() }; @@ -737,7 +771,8 @@ fn partition_fsync(claim: &DeviceClaim) -> u64 { return SyscallError::PermissionDenied.to_u64(); } } - let run = until_answered(|| match claim.partition_view() { + let whose = Run::Claim(claim.partition_on(), ClaimOp::Flush); + let run = until_answered(whose, || match claim.partition_view() { Some(view) => view.flush().map_err(block_word), None => Err(SyscallError::Gone), }); diff --git a/kernel/src/syscall/device.rs b/kernel/src/syscall/device.rs index b084c9b943..ea31aee73f 100644 --- a/kernel/src/syscall/device.rs +++ b/kernel/src/syscall/device.rs @@ -415,14 +415,16 @@ pub(super) fn sys_partition_transfer( match transfer { Transfer::Write(from) => { from.read_at(0, &mut bounce); - let run = ops::until_answered(|| match claim.partition_view() { + let whose = ops::Run::Claim(claim.partition_on(), ops::ClaimOp::Write); + let run = ops::until_answered(whose, || match claim.partition_view() { Some(view) => view.write_blocks(first, count, &bounce).map_err(ops::block_word), None => Err(SyscallError::Gone), }); ops::partition_word("a write", run) } Transfer::Read(into) => { - let run = ops::until_answered(|| match claim.partition_view() { + let whose = ops::Run::Claim(claim.partition_on(), ops::ClaimOp::Read); + let run = ops::until_answered(whose, || match claim.partition_view() { Some(view) => view.read_blocks(first, count, &mut bounce).map_err(ops::block_word), None => Err(SyscallError::Gone), }); diff --git a/tests/common/storage.rs b/tests/common/storage.rs index ddd9519497..65644a28cc 100644 --- a/tests/common/storage.rs +++ b/tests/common/storage.rs @@ -598,6 +598,22 @@ pub fn home_budget_refusal_retried( })? .trim() .to_string(); + // And the refusal was one per file, not one per flush: `logd` flushes every + // round it wrote a line in, and a refused flush is lines of its own, so a + // refusal on every flush keeps `/log` retrying for as long as the machine + // runs and rotates the boot's own log away. An absence, so it is judged + // over a window with nothing left to flush in it. + let after = qemu.drain_serial(Duration::from_secs(2)); + let again: Vec<&str> = + after.lines().filter(|l| l.contains("fsync: ") && l.contains("durable on attempt")).collect(); + if !again.is_empty() { + return Err(format!( + "{} flush(es) retried in the 2 s after the guest's, first {:?}: every flush is \ + being refused, and each refusal's records are the next flush\n{after}", + again.len(), + again[0] + )); + } let image = qemu.nvme_image().to_path_buf(); writeln!(qemu.stdin_mut(), "run shutdown").expect("write to QEMU stdin"); diff --git a/tests/common/volumes.rs b/tests/common/volumes.rs index 25c0e85057..c07eafeaa7 100644 --- a/tests/common/volumes.rs +++ b/tests/common/volumes.rs @@ -2830,11 +2830,11 @@ pub fn log_partition_identity( /// one volume: /// /// 1. **Retry keeps the volume, and a refused attempt discarded nothing.** -/// `fsync-budget-spent` runs every `SYS_FSYNC`'s first attempt under an +/// `fsync-budget-spent` runs each file's first `SYS_FSYNC` attempt under an /// already-spent operation — the state a loaded dev host reproduced 1 in /// 73 full 12-wide suites (2026-08-22, this test's own blob fsync on -/// `/log`) — so every flush in the boot is refused once -/// at the shipped site and retried on a fresh budget. The guest's own +/// `/log`) — so each file's first flush is refused once at the shipped site +/// and retried on a fresh budget. The guest's own /// fsync must succeed, logd must never give its volume up, and the blob is /// then read off the *image* by the host: the safety invariant is that the /// refused attempt left every un-flushed page dirty, so the retry delivered From 89fa84f8b529a9f29d518c20d8144c8f51abedf3 Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 27 Sep 2026 06:31:53 +0200 Subject: [PATCH 04/14] quiesce: the stop puts every queued console line on the wire before the last word Since #527, a console holder's line (every program's, through logd) waits in `log::console`'s queue for `klogd`. `klogd` takes a chunk of records and then a chunk of the queue per hold of the wire. The stop never drained that queue. A line queued just before the stop was written either after `Rebooting.` by the power-off's `flush_final`, or not at all if the reset came first. This is issues/kernel/a-holders-queued-line-can-reach-the-console-after-the-last-word.md. It is also the shape of the nightly's `metal_job_reboot` and `quiesce_wakes_on_the_last_exit` reds: `===READY===` never reached, or a drain after `===READY===` with no kernel line in it, because the job's own kernel lines had gone out ahead of the queued marker. `quiesce()` now drains every record and queued line under the wire right after `quiesce::stop()` has stopped every holder, before `Syncing filesystems...`. `console-queue-at-the-stop` is the deterministic stimulus. It queues one line once every holder is stopped, and keeps `klogd` off the queue from the stop's claim on. `quiesce_stops_the_machine` arms it and judges that line above the last word. Measured: - negative control, the drain disabled as a checked patch that builds (`if false { ... }`): `cargo test --test toyos-build -- --nightly quiesce_stops_the_machine` EXIT=1, `1 line(s) reached the console after the boot's last word: console: a holder's line, queued once the stop had stopped every holder`, wide and alone. - with the drain: EXIT=0. Co-Authored-By: Claude Opus 5.5 (1M context) Claude-Session: https://claude.ai/code/session_014iqcj4jDKpaiDX8B7CMvmK --- ...n-reach-the-console-after-the-last-word.md | 19 +++++++++++++ kernel/src/actuator.rs | 6 +++++ kernel/src/log/console.rs | 27 +++++++++++++++++-- kernel/src/quiesce.rs | 6 +++++ kernel/src/syscall/machine.rs | 13 +++++++++ tests/common/power.rs | 25 +++++++++++++++-- 6 files changed, 92 insertions(+), 4 deletions(-) diff --git a/issues/kernel/a-holders-queued-line-can-reach-the-console-after-the-last-word.md b/issues/kernel/a-holders-queued-line-can-reach-the-console-after-the-last-word.md index 82fba9808d..89d283f588 100644 --- a/issues/kernel/a-holders-queued-line-can-reach-the-console-after-the-last-word.md +++ b/issues/kernel/a-holders-queued-line-can-reach-the-console-after-the-last-word.md @@ -35,3 +35,22 @@ only a `klogd` slower than `logd` gives. No holder's line can follow the last word by construction, and a test that leaves a line in the queue at the stop goes red without that and green with it. + +## The stop now drains the queue + +On `nightly-green2` the stop drains the queue on the wire right after +`quiesce::stop()`, before `Syncing filesystems...` +(`log::console::drain_for_the_stop`). `console-queue-at-the-stop` is the +deterministic stimulus: it queues one line after every holder is stopped and +keeps `klogd` off the queue from the stop's claim on. +`quiesce_stops_the_machine` arms it and judges the line above the last word. +- The drain disabled as a checked patch: `cargo test --test toyos-build -- + --nightly quiesce_stops_the_machine` EXIT=1, `1 line(s) reached the + console after the boot's last word: console: a holder's line, queued once + the stop had stopped every holder`, wide and alone. The power-off's + `serial::flush_final` wrote it. +- With the drain: EXIT=0. + +What is left of "by construction" is a stop that did not stop every holder, +which it reports at alert level. A holder that still runs after the drain +can queue a line that follows the last word. diff --git a/kernel/src/actuator.rs b/kernel/src/actuator.rs index 3a52e83685..83be30c1c7 100644 --- a/kernel/src/actuator.rs +++ b/kernel/src/actuator.rs @@ -395,6 +395,12 @@ actuators! { /// stop did not stop. quiesce_late_word = "quiesce-late-word"; + /// Queue one console holder's line once the stop has stopped every holder, + /// and keep `klogd` off the queue from the stop's claim on: a line still queued + /// at the stop with `klogd` behind it, which otherwise only a `klogd` slower + /// than `logd` stages. Judged by `quiesce_stops_the_machine`. + console_queue_at_the_stop = "console-queue-at-the-stop"; + /// Make the shutdown's bounded acquisitions of the xHCI controller lock /// find it busy for their whole bound — the negative control on "no /// shutdown path may fail to reset". A boot armed with it must still hand diff --git a/kernel/src/log/console.rs b/kernel/src/log/console.rs index 321ac4d4cb..2125d106e3 100644 --- a/kernel/src/log/console.rs +++ b/kernel/src/log/console.rs @@ -107,6 +107,19 @@ pub fn drain_all(wire: &SleepGuard<'_, ()>) { drain_queue(wire, usize::MAX); } +/// Every record and queued line onto the wire, for the stop once it has +/// stopped every console holder: nothing can add to the queue any more, so +/// what a holder queued before it was stopped goes on the wire under the +/// boot's last word and never after it. +pub fn drain_for_the_stop() { + if !serial::has_console() { + return; + } + let parkable = scheduler::Parkable::at_entry(); + let wire = serial::wire(&parkable); + drain_all(&wire); +} + /// Records and queued lines `klogd` takes per hold of the wire, so a console /// holder's line is never behind the whole backlog of records, nor the other /// way round. @@ -397,6 +410,16 @@ impl RecordSink for Raw { } } +/// Whether `klogd` leaves the queue to the stop: `console-queue-at-the-stop`'s +/// `klogd`, behind a stop that has been claimed. +fn left_to_the_stop() -> bool { + #[cfg(feature = "boot-actuators")] + if crate::actuator::console_queue_at_the_stop() { + return crate::quiesce::claimed(); + } + false +} + extern "C" fn body(_arg: u64) -> ! { // First, before any drain: stages a panic inside a kernel thread to test the panic handler's branch. #[cfg(feature = "boot-actuators")] @@ -411,7 +434,7 @@ extern "C" fn body(_arg: u64) -> ! { // A chunk of each per hold, with interrupts on throughout. let wire = serial::wire(&parkable); drain_records(&wire, CHUNK); - drain_queue(&wire, CHUNK as usize) + !left_to_the_stop() && drain_queue(&wire, CHUNK as usize) } else { discard_pending(); discard_queue() @@ -440,7 +463,7 @@ extern "C" fn body(_arg: u64) -> ! { // Safe with no backend because `discard_pending` still advances the position each pass. if shard::arm_waiter(shard::log_waiter(), || { // Under the lock `queue` stores under, ahead of the fence its wake takes. - DRAINED.any_pending() || QUEUE.lock().len > 0 + DRAINED.any_pending() || (!left_to_the_stop() && QUEUE.lock().len > 0) }) { continue; } diff --git a/kernel/src/quiesce.rs b/kernel/src/quiesce.rs index 5b42565c89..234fa2911f 100644 --- a/kernel/src/quiesce.rs +++ b/kernel/src/quiesce.rs @@ -116,6 +116,12 @@ pub fn claim_the_shutdown() -> bool { static CLAIMED: AtomicBool = AtomicBool::new(false); +/// Whether a stop has been claimed, for `console-queue-at-the-stop`'s `klogd`. +#[cfg(feature = "boot-actuators")] +pub fn claimed() -> bool { + CLAIMED.load(core::sync::atomic::Ordering::Acquire) +} + /// What the stop's caller parks on between two sweeps. static PROGRESS: Watch = Watch::new(); diff --git a/kernel/src/syscall/machine.rs b/kernel/src/syscall/machine.rs index bc91cb9c00..d69028a278 100644 --- a/kernel/src/syscall/machine.rs +++ b/kernel/src/syscall/machine.rs @@ -44,6 +44,10 @@ pub(super) fn sys_log_read( } } +/// The line `console-queue-at-the-stop` queues once every holder is stopped. +#[cfg(feature = "boot-actuators")] +const QUEUED_AT_THE_STOP: &str = "console: a holder's line, queued once the stop had stopped every holder"; + fn quiesce(last: &str) -> Result<(), SyscallError> { // Refused by name, and first: nothing below runs twice. if !crate::quiesce::claim_the_shutdown() { @@ -90,6 +94,15 @@ fn quiesce(last: &str) -> Result<(), SyscallError> { #[cfg(feature = "boot-actuators")] crate::quiesce::last::await_the_held_thread(); let stopped = crate::quiesce::stop(); + // A line queued behind the stop, where `klogd` has not reached it. + #[cfg(feature = "boot-actuators")] + if crate::actuator::console_queue_at_the_stop() { + let queued = crate::log::console::queue(QUEUED_AT_THE_STOP.as_bytes(), false); + assert!(queued, "console-queue-at-the-stop: the queue had no room for its one line"); + } + // Every console holder is stopped, so the queue only shrinks from here: + // what they queued goes on the wire now, above the boot's last word. + crate::log::console::drain_for_the_stop(); #[cfg(feature = "boot-actuators")] if crate::actuator::quiesce_dump() { crate::sched::dump::serve_for_the_stop(); diff --git a/tests/common/power.rs b/tests/common/power.rs index 266d7329b1..5d4bd759f1 100644 --- a/tests/common/power.rs +++ b/tests/common/power.rs @@ -172,8 +172,29 @@ pub fn quiesce_stops_the_machine( // thread, parked on init's answer; `test-runner`'s main and deadline // threads; and `logd`'s. `init` asked for the stop and is its caller. const OTHERS: u32 = 4; - let (whole, record) = - stopped_boot("tests/quiescecase/system.toml", JOB, &[LATE_WORD], rust_bins)?; + /// Mirrored in `kernel/src/syscall/machine.rs`, which queues it. + const QUEUED: &str = "console: a holder's line, queued once the stop had stopped every holder"; + let (whole, record) = stopped_boot( + "tests/quiescecase/system.toml", + JOB, + &[LATE_WORD, "console-queue-at-the-stop"], + rust_bins, + )?; + // **A holder's line still queued at the stop is the stop's to put on the + // wire**, above the last word: `klogd` is kept off the queue from the + // stop's claim on, so without that drain the line is never written. + let lines: Vec<&str> = whole.lines().collect(); + let queued = lines.iter().position(|l| l.contains(QUEUED)); + let last = lines.iter().position(|l| l.contains(REBOOTING)); + match (queued, last) { + (Some(queued), Some(last)) if queued < last => {} + _ => { + return Err(format!( + "the line queued at the stop is at {queued:?} and the last word at {last:?}: \ + a holder's line the stop left in the queue is lost at the reset\n{whole}" + )); + } + } if record.in_flight != 0 { return Err(format!( "the block layer still had {} operation(s) open on a thread this stop had stopped, so \ From 15408f8ae78fe8f385c11e02a78317ec185f58bc Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 27 Sep 2026 07:15:04 +0200 Subject: [PATCH 05/14] tests: two stop judges read the log as #527 left it Both were red on main's nightly at 1ce71831 (run 36290616312), wide and alone. Each judge's premise was the log before #527. - `usb_reset_hands_devices_back`: `nothing_after_the_last_word` took the text's last `Rebooting.`. Since #527 the next loader pass prints the boot's newest records under `log-tail:`, newest first. The last `Rebooting.` in the text is that copy, and the older records under it read as spawns after the last word ("3 of 4 reset path(s) unmet: a process started after "Rebooting."... "| log-tail: ... spawn: ..."). The judge now takes the last `Rebooting.` that is not a `log-tail:` line, and reads to the next loader pass as before. - `usb_flush_optional`: it wanted `Shutting down.` in `/log`. Since #527 `/log` ends at init's stop line, because the stop stops logd with every other thread, so the kernel's last word is on the console alone. The judge now wants init's stop line (`bootlog::stopping_line`). Measured, `cargo test --test toyos-build -- --nightly `: - `usb_reset_hands_devices_back`: the old judge restored as a checked patch EXIT=1 (`3 of 4 reset path(s) unmet`), the new one EXIT=0. - `usb_flush_optional`: before EXIT=1 (`the shutdown's last line never reached the file`, wide and alone), after EXIT=0. Co-Authored-By: Claude Opus 5.5 (1M context) Claude-Session: https://claude.ai/code/session_014iqcj4jDKpaiDX8B7CMvmK --- tests/common/power.rs | 18 ++++++++++++++---- tests/common/usb.rs | 7 +++++-- 2 files changed, 19 insertions(+), 6 deletions(-) diff --git a/tests/common/power.rs b/tests/common/power.rs index 5d4bd759f1..2228d9a8d3 100644 --- a/tests/common/power.rs +++ b/tests/common/power.rs @@ -2707,11 +2707,21 @@ fn one_reset_path(case: &Path, arm: &ResetPath) -> Result<(), String> { /// CPU's `sched:` report can land there — and nothing is left running to take /// it anywhere but the console. A *spawn* is a process that was still on a run /// queue after the stop said it had stopped every one. +/// +/// **The boot's own word, not the next pass's copy of it**: that pass prints +/// the boot's newest records under [`bootlog::LOG_TAIL`], newest first, so the +/// copy of the last word heads records that were written before it. fn nothing_after_the_last_word(text: &str) -> Result<(), String> { - let Some(at) = text.rfind(REBOOTING) else { return Ok(()) }; - let after = &text[at + REBOOTING.len()..]; - let window = after.split(bootlog::LOADER_FIRST_LINE).next().unwrap_or(after); - match window.lines().find(|line| line.contains(bootlog::SPAWN)) { + let lines: Vec<&str> = text.lines().collect(); + let Some(at) = lines + .iter() + .rposition(|line| line.contains(REBOOTING) && !line.contains(bootlog::LOG_TAIL)) + else { + return Ok(()); + }; + let mut window = + lines[at + 1..].iter().take_while(|line| !line.contains(bootlog::LOADER_FIRST_LINE)); + match window.find(|line| line.contains(bootlog::SPAWN)) { None => Ok(()), Some(line) => Err(format!( "a process started after {REBOOTING:?}, which is the boot's own last word and what a \ diff --git a/tests/common/usb.rs b/tests/common/usb.rs index 7a277c8ec4..b1725550af 100644 --- a/tests/common/usb.rs +++ b/tests/common/usb.rs @@ -1006,9 +1006,12 @@ fn optional_flush_keeps_the_log( let after = super::volumes::newest_log(&image_path, start, len)?.1; let after = String::from_utf8_lossy(&after).into_owned(); - if !after.contains("Shutting down.") { + // `/log` ends at init's stop line: the kernel's own last word comes after + // the stop of every thread, `logd` among them, and is on the console alone. + if toyos_build::bootlog::stopping_line(&after).is_none() { return Err(format!( - "the shutdown's last line never reached the file: {} bytes", + "init's stop line never reached the file, so the log did not survive to the \ + shutdown: {} bytes", after.len() )); } From 82f4187429e538d1f322306e32924c2c9e00fb79 Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 27 Sep 2026 07:28:57 +0200 Subject: [PATCH 06/14] updatecase: `reboot` asks init's power port, as #527 made every stop do Four update tests stalled on main's nightly at 1ce71831 (run 36290616312), wide and alone: `update_boots_the_new_kernel`, `update_falls_back_from_a_dying_kernel`, `update_floor_is_the_images_own` and `update_refusals_boot_the_other_slot`. #527 moved every stop onto init's `power` port, so the `reboot` applet (`toyos::power::stop`) asks init, which has logd make the log whole and then stops the machine. `tests/updatecase/system.toml` still gave toybox `syscap = ["power"]` and no `power` connector. The host's `reboot` over ssh was "accepted" and the machine never went down. toybox now receives `power`, as it does in `system.toml`. The `SysCap` power right goes with the change, because no applet in this image uses it any more. Measured: `cargo test --test toyos-build -- --nightly update_boots_the_new_kernel` before, EXIT=1 (STALLED after the reboot, wide and alone). After, `--nightly update_` EXIT=0 (7 of 7). Co-Authored-By: Claude Opus 5.5 (1M context) Claude-Session: https://claude.ai/code/session_014iqcj4jDKpaiDX8B7CMvmK --- tests/updatecase/system.toml | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/tests/updatecase/system.toml b/tests/updatecase/system.toml index ca95cc23d4..b8cf0b1014 100644 --- a/tests/updatecase/system.toml +++ b/tests/updatecase/system.toml @@ -28,9 +28,11 @@ slots = true [programs.test-runner] syscap = ["logread"] -# `reboot` is how the host hands the machine to the slot `update` marked. +# `reboot` is how the host hands the machine to the slot `update` marked: the +# connector to init's `power` port, where init has `logd` make the log whole +# and then stops the machine. [programs.toybox] -syscap = ["power"] +receives = ["power"] [symlinks] "bin/reboot" = "/system/bin/toybox" From 97fa54077b6a24b24c0fc03f8fa39ddbc2f5ed8b Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 27 Sep 2026 07:30:39 +0200 Subject: [PATCH 07/14] issues: what main's nightly at 1ce71831 left red that this branch does not fix Run 36290616312, read after #527: - gate A's `audio_tone_load.smp1` median against the dev host's TCG sample: a new sighting added to issues/audio/gate-a-has-no-runner-baseline.md. It is the instrument. Harm was null, and the same lane passed on this branch's nightly and on the one before #527. - `wake_storm_cost`: a third sighting added to its issue, green alone. - `swap_crash_rolls_back` and `i8042_health_cadence`: each red once wide and green alone twice, filed as findings. - `log_ring_keeps_the_owners_slots`, seen on the dev host: a ring's owner is named only when logd reads init's registration, so a child that floods first takes the owner's slots. Filed with the mechanism and the rates. The closing fix is in `toyos/src`. Co-Authored-By: Claude Opus 5.5 (1M context) Claude-Session: https://claude.ai/code/session_014iqcj4jDKpaiDX8B7CMvmK --- issues/audio/gate-a-has-no-runner-baseline.md | 13 ++++++ ...edial-turned-away-once-on-mains-nightly.md | 25 +++++++++++ ...-storm-cost-red-under-induced-host-load.md | 6 +++ ...unted-three-lines-once-on-mains-nightly.md | 16 ++++++++ ...d-only-when-logd-reads-its-registration.md | 41 +++++++++++++++++++ 5 files changed, 101 insertions(+) create mode 100644 issues/build/swap-crash-rolls-back-redial-turned-away-once-on-mains-nightly.md create mode 100644 issues/hardware/i8042-health-cadence-counted-three-lines-once-on-mains-nightly.md create mode 100644 issues/kernel/a-log-rings-owner-is-named-only-when-logd-reads-its-registration.md diff --git a/issues/audio/gate-a-has-no-runner-baseline.md b/issues/audio/gate-a-has-no-runner-baseline.md index 0a5e712096..3fa6c4e8c2 100644 --- a/issues/audio/gate-a-has-no-runner-baseline.md +++ b/issues/audio/gate-a-has-no-runner-baseline.md @@ -111,3 +111,16 @@ still the dev host's under cross-arch TCG, so this record is unchanged in what it says and only narrower in where a fresh sample can come from: a hosted sample is a sample over unnamed CPUs, and a T14 sample is now a job of `issues/hardware/the-t14-boots-toyos-unattended.md` rather than of a CI lane. + +## Main's nightly at 1ce71831 reds on it + +Run 36290616312, `audio (2)`: `audio_tone_load.smp1 wake lateness: median +5765 -> 6650 (Mann-Whitney z=4.03 > 3.09)`. Dropouts were 0/60, underruns 0, +ceiling breaches 0/60, and wakes 1396-1426 against the recorded 856-887, +the 1.6x KVM-over-TCG ratio this file records. The same lane on the nightly +before #527 (run 36285169430) read median 6478 with wakes 1394-1425 and +passed. On `nightly-green2` at dbf4ace5 (run 36292135439) it passed too. The +fresh samples agree with each other and differ from the dev host's TCG +sample, so this is the instrument, as above. Until a per-host baseline +exists, whether a KVM runner's gate A reds depends on where its median lands +against the TCG sample's. diff --git a/issues/build/swap-crash-rolls-back-redial-turned-away-once-on-mains-nightly.md b/issues/build/swap-crash-rolls-back-redial-turned-away-once-on-mains-nightly.md new file mode 100644 index 0000000000..dff945e548 --- /dev/null +++ b/issues/build/swap-crash-rolls-back-redial-turned-away-once-on-mains-nightly.md @@ -0,0 +1,25 @@ +--- +status: open +kind: finding +opened: 2026-09-27 +--- + +# `swap_crash_rolls_back`'s redial was turned away to its ceiling once on main's nightly + +Main's nightly at 1ce71831 (run 36290616312), one guest shard, wide: + +``` +FAIL swap_crash_rolls_back: 2 finding(s): + init's words on netd were ["accepted"] ending in None, where Restored is owed (the stream had 1 connection(s) before the ask and 1 after) + the stream's redial was turned away 64 time(s), its ceiling of 64, and gave up +``` + +`ALONE swap_crash_rolls_back: GREEN` twice. It was not red on the nightlies +before #527, which changed how `logd` turns readers away across a swap. +`cargo run -- --known-red swap_crash_rolls_back` answers NO. + +Not shown: why `logd` was still turning the redial away, 64 times, after the +old netd was gone. + +**Exit**: a cause for a redial turned away to its ceiling on a swap that +rolled back, or a rate with enough runs to call it gone. diff --git a/issues/build/wake-storm-cost-red-under-induced-host-load.md b/issues/build/wake-storm-cost-red-under-induced-host-load.md index c47db5b0a2..5b21b25001 100644 --- a/issues/build/wake-storm-cost-red-under-induced-host-load.md +++ b/issues/build/wake-storm-cost-red-under-induced-host-load.md @@ -55,3 +55,9 @@ on a quiet host and on a loaded one, several runs of each, with the host's load recorded per run. If the ratio moves with the load, the assertion needs a denominator that host time cannot inflate — a count of claims rather than a span of cycles. If it does not, the finding is the kernel's and this is a `defect`. + +## Third sighting, main's nightly at 1ce71831 + +Run 36290616312, one guest shard: `FAIL rs::wake_storm_cost: exit code 101` +wide, then `ALONE wake_storm_cost: GREEN` twice. This is again a hosted +four-core shard running eight-vCPU guests, so an oversubscribed host. diff --git a/issues/hardware/i8042-health-cadence-counted-three-lines-once-on-mains-nightly.md b/issues/hardware/i8042-health-cadence-counted-three-lines-once-on-mains-nightly.md new file mode 100644 index 0000000000..852c68d886 --- /dev/null +++ b/issues/hardware/i8042-health-cadence-counted-three-lines-once-on-mains-nightly.md @@ -0,0 +1,16 @@ +--- +status: open +kind: finding +opened: 2026-09-27 +--- + +# `i8042_health_cadence` counted three counter lines for two keystrokes once on main's nightly + +Main's nightly at 1ce71831 (run 36290616312), one guest shard, wide: +`FAIL i8042_health_cadence: two keystrokes three seconds apart, 3 counter +lines — the report is on a timer rather than on the pin`. `ALONE +i8042_health_cadence: GREEN` twice. +`cargo run -- --known-red i8042_health_cadence` answers NO. + +**Exit**: the red run's three counter lines matched to the edges that +produced them, or a rate with enough runs to call it gone. diff --git a/issues/kernel/a-log-rings-owner-is-named-only-when-logd-reads-its-registration.md b/issues/kernel/a-log-rings-owner-is-named-only-when-logd-reads-its-registration.md new file mode 100644 index 0000000000..0de87177ad --- /dev/null +++ b/issues/kernel/a-log-rings-owner-is-named-only-when-logd-reads-its-registration.md @@ -0,0 +1,41 @@ +--- +status: open +kind: defect +opened: 2026-09-27 +--- + +# A log ring's owner is named only when `logd` reads its registration, so a child that floods first takes the owner's slots + +`toyos::log::Ring::push` keeps `CHILD_KEEP` shared slots free for the ring's +owner, but only once the owner word is set. `logd` sets it (`origin.rs`, +`ring.own(pid)`) when it reads init's `REGISTER` frame. init sends that +frame after it spawns the program (`userland/init/src/main.rs`, `register`). +Until `logd` reads the frame the owner word is 0, and `push` then keeps +nothing for anyone. A child that starts flooding in that window can take +every slot, the owner's included. + +`log_ring_keeps_the_owners_slots` (fast tier) is red this way beside the +other `log_` guests and green alone. Its `/log` holds `===READY===`, +`===TEST_START test_rs_log_flood===` and 1917 flood lines: exactly the ring's +1919 shared slots, with no slot left for test-runner's `===TEST_END`. +`logd: reading test-runner again ... with 1919 of its ring's 1919 records +waiting`. + +Rates on the dev host (TCG), `cargo test --test toyos-build -- --nightly +log_`, interleaved in one session: +- `nightly-green2` (the branch that filed this): 3 red of 9. Each red was + this failure. +- `origin/main` at 1ce71831: 0 of 8. + +No mechanism on that branch reaches the ring, init or logd. The window is a +race on both trees, and the difference between the two rates is not shown to +be more than chance. + +The fix belongs where the owner is decided: +- init names the owner itself, after the spawn and before the frame. That + narrows the window and does not close it. +- Or `Ring::push` treats an unowned ring as one in which every writer leaves + `CHILD_KEEP`, which closes it. That is `toyos/src`, the SDK. + +**Exit**: a child writing before the ring's owner is named cannot take the +slots the owner is kept, shown by a test that makes it write in that window. From 11af9249db7ca2ae1977031a1996c8b1d45eb67c Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 27 Sep 2026 07:30:50 +0200 Subject: [PATCH 08/14] issues: the swap finding claims no cause it did not measure Co-Authored-By: Claude Opus 5.5 (1M context) Claude-Session: https://claude.ai/code/session_014iqcj4jDKpaiDX8B7CMvmK --- ...ash-rolls-back-redial-turned-away-once-on-mains-nightly.md | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/issues/build/swap-crash-rolls-back-redial-turned-away-once-on-mains-nightly.md b/issues/build/swap-crash-rolls-back-redial-turned-away-once-on-mains-nightly.md index dff945e548..631d0b0bd3 100644 --- a/issues/build/swap-crash-rolls-back-redial-turned-away-once-on-mains-nightly.md +++ b/issues/build/swap-crash-rolls-back-redial-turned-away-once-on-mains-nightly.md @@ -14,8 +14,8 @@ FAIL swap_crash_rolls_back: 2 finding(s): the stream's redial was turned away 64 time(s), its ceiling of 64, and gave up ``` -`ALONE swap_crash_rolls_back: GREEN` twice. It was not red on the nightlies -before #527, which changed how `logd` turns readers away across a swap. +`ALONE swap_crash_rolls_back: GREEN` twice. It was not red on the nightly +before #527 (run 36285169430). `cargo run -- --known-red swap_crash_rolls_back` answers NO. Not shown: why `logd` was still turning the redial away, 64 times, after the From df641f5898487c025468eccef95d544d837a9c1b Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 27 Sep 2026 07:30:58 +0200 Subject: [PATCH 09/14] issues: the swap finding claims no cause it did not measure Co-Authored-By: Claude Opus 5.5 (1M context) Claude-Session: https://claude.ai/code/session_014iqcj4jDKpaiDX8B7CMvmK --- ...rash-rolls-back-redial-turned-away-once-on-mains-nightly.md | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/issues/build/swap-crash-rolls-back-redial-turned-away-once-on-mains-nightly.md b/issues/build/swap-crash-rolls-back-redial-turned-away-once-on-mains-nightly.md index 631d0b0bd3..f9a3abde49 100644 --- a/issues/build/swap-crash-rolls-back-redial-turned-away-once-on-mains-nightly.md +++ b/issues/build/swap-crash-rolls-back-redial-turned-away-once-on-mains-nightly.md @@ -18,8 +18,7 @@ FAIL swap_crash_rolls_back: 2 finding(s): before #527 (run 36285169430). `cargo run -- --known-red swap_crash_rolls_back` answers NO. -Not shown: why `logd` was still turning the redial away, 64 times, after the -old netd was gone. +Not shown: what turned the redial away 64 times, and why. **Exit**: a cause for a redial turned away to its ceiling on a swap that rolled back, or a rate with enough runs to call it gone. From baf679b64e6eeea2b646c9a1f904bdba31436b85 Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 27 Sep 2026 08:19:24 +0200 Subject: [PATCH 10/14] issues: the log ring owner race is red on main at the same rate Five more interleaved rounds after the merge of 16d2e645: branch 0 of 5, origin/main 2 of 5, each red the owner-word race. Co-Authored-By: Claude Opus 5.5 (1M context) Claude-Session: https://claude.ai/code/session_014iqcj4jDKpaiDX8B7CMvmK --- ...-named-only-when-logd-reads-its-registration.md | 14 ++++++-------- 1 file changed, 6 insertions(+), 8 deletions(-) diff --git a/issues/kernel/a-log-rings-owner-is-named-only-when-logd-reads-its-registration.md b/issues/kernel/a-log-rings-owner-is-named-only-when-logd-reads-its-registration.md index 0de87177ad..0579384cef 100644 --- a/issues/kernel/a-log-rings-owner-is-named-only-when-logd-reads-its-registration.md +++ b/issues/kernel/a-log-rings-owner-is-named-only-when-logd-reads-its-registration.md @@ -22,14 +22,12 @@ other `log_` guests and green alone. Its `/log` holds `===READY===`, waiting`. Rates on the dev host (TCG), `cargo test --test toyos-build -- --nightly -log_`, interleaved in one session: -- `nightly-green2` (the branch that filed this): 3 red of 9. Each red was - this failure. -- `origin/main` at 1ce71831: 0 of 8. - -No mechanism on that branch reaches the ring, init or logd. The window is a -race on both trees, and the difference between the two rates is not shown to -be more than chance. +log_`, interleaved per round against `origin/main`'s kernel and tests: +- the branch that filed this, `nightly-green2`: 3 red of 14 (3 of 9 before + its merge of 16d2e645, one of those in a run before the interleaving + began; 0 of 5 after); +- `origin/main`: 2 red of 13 (0 of 8 at 1ce71831, 2 of 5 at 16d2e645). +Each red was this failure. The race is on `main`. The fix belongs where the owner is decided: - init names the owner itself, after the spawn and before the frame. That From 64c4636a6600ae9942bfdb8d3f85f9a7c903a60f Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 27 Sep 2026 12:21:48 +0200 Subject: [PATCH 11/14] issues: gate A red and green on unchanged runner samples around #527 Co-Authored-By: Claude Opus 5.5 (1M context) Claude-Session: https://claude.ai/code/session_014iqcj4jDKpaiDX8B7CMvmK --- issues/audio/gate-a-has-no-runner-baseline.md | 9 +++++++++ 1 file changed, 9 insertions(+) diff --git a/issues/audio/gate-a-has-no-runner-baseline.md b/issues/audio/gate-a-has-no-runner-baseline.md index 3fa6c4e8c2..4abe837bfc 100644 --- a/issues/audio/gate-a-has-no-runner-baseline.md +++ b/issues/audio/gate-a-has-no-runner-baseline.md @@ -124,3 +124,12 @@ fresh samples agree with each other and differ from the dev host's TCG sample, so this is the instrument, as above. Until a per-host baseline exists, whether a KVM runner's gate A reds depends on where its median lands against the TCG sample's. + +The four `audio (2)` samples of `audio_tone_load.smp1` around #527 have +medians of 6453 (before #527, passed), 6648 (main at 1ce71831, red), 6190 +(`nightly-green2` at dbf4ace5, passed) and 6520 (`nightly-green2` at +c2715880, red, run 36297455432). Mann-Whitney of each later sample against +the one before #527, on the gate's 30-value arrays: z=1.40, -1.20 and 0.84. +None is a difference at the gate's alpha. The runner's sample did not move. +The gate's verdict flips because that sample's median sits about 0.8 ms above +the TCG sample's 5765, right at the gate's edge. From a4f68c5afd5a9cd6b7e20c7d08fa5d5f853fbb69 Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 27 Sep 2026 12:49:17 +0200 Subject: [PATCH 12/14] review #535: the withhold path gets its boot, and the NOTEs that were cheap The review sent #535 back because nothing tested the withhold path: deleting the `WITHHELD` check in `gpt::claimable`, or `crate::gpt::withhold(guid)` in `rootfs::withhold`, survived every test. - `partclaim-root-withheld` (new actuator): device block 0 of every NVMe disk refuses reads across `rootfs::hold_source` alone, then answers again. On `InternalDisk` the one disk carries ROOT, so the hold finds it silent and withholds the GUID; `partition_claim_gives_up`'s third boot then claims ROOT's GUID, which the disk now answers for and nothing holds, and wants `PermissionDenied` (KernelDriven's word) plus the kernel's `partclaim: ... withholds it` line. - `gpt::seek` answers its own `Unnamed { Ambiguous, Unusable }`, so `hold_source`'s match has no arm for a claim error no table read makes. - `transport_gives_up` wants the hold line to name the gate's disk alone (`16 + index`, the index off `usb-gate: disk N designated`). - `nothing_after_the_last_word` moves to `bootlog` with a host `#[test]` over a crafted log-tail copy and a spawn after the real word. - `ssh_fire` refuses any answer but accepted/closed/silent; the client's `fire` reports `exited ` when the program came back, which a `reboot` that ended the machine never does. - The run key `fsync-budget-spent` refuses once is a closure, evaluated only in actuator kernels: a shipping partition transfer no longer takes `described`'s lock to build a key nothing reads. - The stop drains the console queue only; the record backlog stays `klogd`'s, so the sync is not spent behind a slow wire. - The false "the queue only shrinks from here" comment and the issue's contradicted paragraph are deleted; the storage-phase i8042 ordering is filed as issues/panic-path/a-storage-phase-panic-reads-its-key-off-an-unconfigured-i8042.md. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_014iqcj4jDKpaiDX8B7CMvmK --- ...n-reach-the-console-after-the-last-word.md | 5 -- ...reads-its-key-off-an-unconfigured-i8042.md | 32 +++++++++++ kernel/src/actuator.rs | 6 ++ kernel/src/gpt.rs | 32 ++++++++--- kernel/src/log/console.rs | 10 ++-- kernel/src/main.rs | 8 +++ kernel/src/object/ops.rs | 12 ++-- kernel/src/page_cache.rs | 26 ++++++--- kernel/src/rootfs.rs | 13 ++--- kernel/src/syscall/device.rs | 4 +- kernel/src/syscall/machine.rs | 2 - src/bootlog.rs | 56 +++++++++++++++++++ tests/common/partclaim.rs | 56 +++++++++++++++++-- tests/common/power.rs | 41 +------------- tests/common/ssh.rs | 8 ++- tests/common/storage.rs | 5 +- tests/common/usb.rs | 11 +++- tests/ssh-client-host/src/main.rs | 19 ++++++- .../src/bin/partition_claimant.rs | 17 ++++++ tests/toyos.rs | 5 +- 20 files changed, 270 insertions(+), 98 deletions(-) create mode 100644 issues/panic-path/a-storage-phase-panic-reads-its-key-off-an-unconfigured-i8042.md diff --git a/issues/kernel/a-holders-queued-line-can-reach-the-console-after-the-last-word.md b/issues/kernel/a-holders-queued-line-can-reach-the-console-after-the-last-word.md index 89d283f588..7c6c4b0b70 100644 --- a/issues/kernel/a-holders-queued-line-can-reach-the-console-after-the-last-word.md +++ b/issues/kernel/a-holders-queued-line-can-reach-the-console-after-the-last-word.md @@ -26,11 +26,6 @@ stop stops every userland thread and writes its last word as a record, which queue then goes after it, inside `quiesce-late-word`'s window. `main` has no queue — a holder wrote the wire itself — so this is the branch's. -The likely fix is a drain of the queue on the wire between the stop of every -holder and the last word, where nothing can add to it. No deterministic -stimulus exists yet: the red needs the queue non-empty at the last word, which -only a `klogd` slower than `logd` gives. - ## Exit condition No holder's line can follow the last word by construction, and a test that diff --git a/issues/panic-path/a-storage-phase-panic-reads-its-key-off-an-unconfigured-i8042.md b/issues/panic-path/a-storage-phase-panic-reads-its-key-off-an-unconfigured-i8042.md new file mode 100644 index 0000000000..3c9c27ed47 --- /dev/null +++ b/issues/panic-path/a-storage-phase-panic-reads-its-key-off-an-unconfigured-i8042.md @@ -0,0 +1,32 @@ +--- +status: open +kind: defect +opened: 2026-09-27 +--- + +# A panic in the storage phase reads its key off an i8042 the kernel has not configured + +The panic panel's reset bound is retired by a key press +(`kernel/src/drivers/panic_console/mod.rs`, `read_key`), which polls port +`0x60` through `keyboard_controller::poll_byte`. `i8042::init` +(`kernel/src/arch/x86_64/i8042/mod.rs`) is what turns translation on, stops +and restarts scanning and enables the port-1 clock. It now runs first in the +device phase (`arch::boot::platform_devices` in `kernel/src/main.rs`), after +storage, so its lines stay on a panel that shows the log's tail. + +So a panic anywhere in the storage phase — NVMe or xHCI init, +`rootfs::hold_source`, the DATA and FAT mounts — meets the controller as the +firmware left it. Whether a key press then reaches `read_key` as a set-1 make +code depends on the firmware: with translation off or scanning off it does +not, and the panel resets at its bound however many keys are pressed. That +ordering is the one the tree had before storage moved behind init's spawn, so +it has shipped before; it is still a weakness. No boot exercises a panic in +the storage phase with the firmware's controller state left unconfigured. + +## Exit condition + +A key press retires the panel's bound for a panic anywhere after the i8042 +probe could have run — the controller configured before the first phase that +can panic on a device, without moving its lines off the panel's tail — and a +boot that panics in the storage phase on the metal-sim shape shows the press +retiring it. diff --git a/kernel/src/actuator.rs b/kernel/src/actuator.rs index 83be30c1c7..20fe2123af 100644 --- a/kernel/src/actuator.rs +++ b/kernel/src/actuator.rs @@ -529,6 +529,12 @@ actuators! { /// `partition_claim_gives_up`. partclaim_table_unanswered = "partclaim-table-unanswered"; + /// Refuse every read of device block 0 of each NVMe disk across + /// `rootfs::hold_source` alone, so ROOT's hold finds the disk carrying it + /// silent and withholds its GUID, and the disk answers every read after. + /// Judged by `partition_claim_gives_up`. + partclaim_root_withheld = "partclaim-root-withheld"; + /// Reopen init by pid once it is spawned, the way `SYS_PROCESS_OPEN` does. process_reopen_selftest = "process-reopen-selftest"; diff --git a/kernel/src/gpt.rs b/kernel/src/gpt.rs index c2a1530f06..a83625d0b2 100644 --- a/kernel/src/gpt.rs +++ b/kernel/src/gpt.rs @@ -346,13 +346,31 @@ pub fn withhold(guid: PartGuid) { /// Where one partition is on the disks that answered, and which did not. pub struct Sought { /// The one partition carrying the GUID, `None` where no table that - /// answered carries it, or the refusal a table's answer makes. - pub found: Result, ClaimError>, + /// answered carries it, or why the tables that answered name no one. + pub found: Result, Unnamed>, /// The disks that did not answer a read of their table, of which neither /// "none" nor "one" is known. pub silent: Vec, } +/// Why the tables that answered name no one partition for a GUID. +#[derive(Clone, Copy, Debug)] +pub enum Unnamed { + /// Carried twice, on one disk or across two. + Ambiguous, + /// Named by a table that refuses it. + Unusable, +} + +impl From for ClaimError { + fn from(unnamed: Unnamed) -> Self { + match unnamed { + Unnamed::Ambiguous => ClaimError::Ambiguous, + Unnamed::Unusable => ClaimError::Unusable, + } + } +} + /// The one partition on this machine whose unique GUID is `guid`, past the /// range and overlap checks `toyos_gpt::locate` makes (UEFI 2.10 §5.3.3). /// @@ -385,7 +403,7 @@ pub fn seek(guid: PartGuid) -> Sought { let target = Guid(guid.0); let mut silent = Vec::new(); if target.is_zero() { - return Sought { found: Err(ClaimError::Absent), silent }; + return Sought { found: Ok(None), silent }; } let disks = DISKS.lock().clone(); let mut found: Option = None; @@ -408,7 +426,7 @@ pub fn seek(guid: PartGuid) -> Sought { partition", first.volume.device ); - return Sought { found: Err(ClaimError::Ambiguous), silent }; + return Sought { found: Err(Unnamed::Ambiguous), silent }; } found = Some(Claimable { volume: Volume { @@ -433,7 +451,7 @@ enum Unread { /// What a table's refusal means for a claim: a disk that does not carry the /// partition, one that did not answer, or the claim's refusal. -fn table_refused(id: DeviceId, target: Guid, e: GptError) -> Result { +fn table_refused(id: DeviceId, target: Guid, e: GptError) -> Result { match e { GptError::NotFound { .. } => Ok(Unread::Lacks), GptError::ReadFailed(lba) => { @@ -442,11 +460,11 @@ fn table_refused(id: DeviceId, target: Guid, e: GptError) -> Result { log!("partclaim: device {id} carries {target} in entries {first} and {second}"); - Err(ClaimError::Ambiguous) + Err(Unnamed::Ambiguous) } GptError::PartitionRange { .. } | GptError::PartitionOverlap { .. } => { log!("partclaim: device {id} names {target} and its own table refuses it: {e:?}"); - Err(ClaimError::Unusable) + Err(Unnamed::Unusable) } // No table this kernel parses: a disk that carries no partition, which // is what `probe` concluded of it too. diff --git a/kernel/src/log/console.rs b/kernel/src/log/console.rs index 2125d106e3..4e9b1a2345 100644 --- a/kernel/src/log/console.rs +++ b/kernel/src/log/console.rs @@ -107,17 +107,17 @@ pub fn drain_all(wire: &SleepGuard<'_, ()>) { drain_queue(wire, usize::MAX); } -/// Every record and queued line onto the wire, for the stop once it has -/// stopped every console holder: nothing can add to the queue any more, so -/// what a holder queued before it was stopped goes on the wire under the -/// boot's last word and never after it. +/// Every queued line onto the wire, for the stop once it has stopped every +/// console holder: what a holder queued before it was stopped goes on the wire +/// under the boot's last word and never after it. The record backlog stays +/// `klogd`'s, so the sync behind this is not spent behind a slow wire. pub fn drain_for_the_stop() { if !serial::has_console() { return; } let parkable = scheduler::Parkable::at_entry(); let wire = serial::wire(&parkable); - drain_all(&wire); + drain_queue(&wire, usize::MAX); } /// Records and queued lines `klogd` takes per hold of the wire, so a console diff --git a/kernel/src/main.rs b/kernel/src/main.rs index 2965c69819..bada52f057 100644 --- a/kernel/src/main.rs +++ b/kernel/src/main.rs @@ -508,7 +508,15 @@ pub(crate) unsafe extern "C" fn kernel_main(kernel_args: &KernelArgs) -> ! { } // After xhci::init, not beside the NVMe probe: a USB-booted disk doesn't exist until the controller binds it. fat32_adapter::probe_boot_disks(); + #[cfg(feature = "boot-actuators")] + if actuator::partclaim_root_withheld() { + page_cache::refuse_table_reads(); + } rootfs::hold_source(); + #[cfg(feature = "boot-actuators")] + if actuator::partclaim_root_withheld() { + page_cache::answer_table_reads(); + } // One filesystem, four paths: each of `DATA_PATHS` is a directory of DATA, // so one sync settles them all and none can outlive the others. diff --git a/kernel/src/object/ops.rs b/kernel/src/object/ops.rs index ccc2f28fc5..3808154fb2 100644 --- a/kernel/src/object/ops.rs +++ b/kernel/src/object/ops.rs @@ -625,7 +625,7 @@ pub fn fsync(object: &KObjectRef) -> u64 { // A refused attempt can leave the two FATs split, and the park between two attempts is where the machine's stop would find this thread. let _update = crate::block::begin_update(); // A refused attempt discards nothing — an unsettled debt needs no restoring. - let run = until_answered(Run::Fsync(file_id), || { + let run = until_answered(|| Run::Fsync(file_id), || { // Outside `FileObject`'s lock: this and `OpenFileState::drop` take the VFS lock in the same order. // Flush and sync share one acquisition so this file cannot be unmounted between them. let mut vfs = crate::vfs::lock(); @@ -700,10 +700,10 @@ pub(crate) enum ClaimOp { /// per run, so a writer whose every flush leaves records to flush (`logd`) /// is refused once and not on every flush it will ever make. #[cfg(feature = "boot-actuators")] -fn staged_spent(run: Run) -> bool { +fn staged_spent(run: impl Fn() -> Run) -> bool { static REFUSED: crate::sync::Lock> = crate::sync::Lock::new(alloc::collections::BTreeSet::new()); - crate::actuator::fsync_budget_spent() && REFUSED.lock().insert(run) + crate::actuator::fsync_budget_spent() && REFUSED.lock().insert(run()) } /// `attempt` run until it answers anything but `WouldBlock` — a budget that @@ -714,7 +714,7 @@ fn staged_spent(run: Run) -> bool { /// be held across the wait, so no disk wait here is under one. #[cfg_attr(not(feature = "boot-actuators"), allow(unused_variables))] pub(crate) fn until_answered( - run: Run, + run: impl Fn() -> Run, mut attempt: impl FnMut() -> Result<(), SyscallError>, ) -> Answered { let began = crate::clock::now(); @@ -728,7 +728,7 @@ pub(crate) fn until_answered( let answer = { // Stages a first attempt with its budget already spent, exercising the shipped refusal itself. #[cfg(feature = "boot-actuators")] - let _spent = (attempts == 1 && staged_spent(run)) + let _spent = (attempts == 1 && staged_spent(&run)) .then(|| crate::scheduler::Operation::begin(Deadline::passed())); attempt() }; @@ -771,7 +771,7 @@ fn partition_fsync(claim: &DeviceClaim) -> u64 { return SyscallError::PermissionDenied.to_u64(); } } - let whose = Run::Claim(claim.partition_on(), ClaimOp::Flush); + let whose = || Run::Claim(claim.partition_on(), ClaimOp::Flush); let run = until_answered(whose, || match claim.partition_view() { Some(view) => view.flush().map_err(block_word), None => Err(SyscallError::Gone), diff --git a/kernel/src/page_cache.rs b/kernel/src/page_cache.rs index f8540fe254..8c54517a8c 100644 --- a/kernel/src/page_cache.rs +++ b/kernel/src/page_cache.rs @@ -19,12 +19,15 @@ pub struct Cached { part: Partition, } -/// Wraps `dev` in the read-fault injector when `pc-unbind-selftest` or -/// `partclaim-table-unanswered` is armed — at registration, so it sits under -/// the one device object consumers share. +/// Wraps `dev` in the read-fault injector when `pc-unbind-selftest`, +/// `partclaim-table-unanswered` or `partclaim-root-withheld` is armed — at +/// registration, so it sits under the one device object consumers share. pub fn instrumented(dev: Box) -> Box { #[cfg(feature = "boot-actuators")] - if crate::actuator::pc_unbind_selftest() || crate::actuator::partclaim_table_unanswered() { + if crate::actuator::pc_unbind_selftest() + || crate::actuator::partclaim_table_unanswered() + || crate::actuator::partclaim_root_withheld() + { return Box::new(read_fault::FaultDevice(dev)); } dev @@ -466,13 +469,20 @@ mod read_fault { } } -/// `partclaim-table-unanswered`: every instrumented disk refuses reads of its -/// device block 0 from here on. Armed after the mounts, which read their own -/// partitions and nothing there again. +/// Every instrumented disk refuses reads of its device block 0 until +/// [`answer_table_reads`]: `partclaim-table-unanswered` arms it after the +/// mounts, which read their own partitions and nothing there again, and +/// `partclaim-root-withheld` across ROOT's hold alone. #[cfg(feature = "boot-actuators")] pub fn refuse_table_reads() { read_fault::FAIL_BLOCK.store(0, core::sync::atomic::Ordering::Relaxed); - log!("partclaim-table-unanswered: device block 0 of every NVMe disk refuses reads from now on"); + log!("read-fault: device block 0 of every NVMe disk refuses reads from now on"); +} + +#[cfg(feature = "boot-actuators")] +pub fn answer_table_reads() { + read_fault::FAIL_BLOCK.store(u64::MAX, core::sync::atomic::Ordering::Relaxed); + log!("read-fault: device block 0 of every NVMe disk answers reads again"); } /// The un-index control, behind `pc-unbind-selftest`, for `PageCache::read`'s diff --git a/kernel/src/rootfs.rs b/kernel/src/rootfs.rs index cf1c3ec9ea..cfc137d0b9 100644 --- a/kernel/src/rootfs.rs +++ b/kernel/src/rootfs.rs @@ -18,7 +18,7 @@ use toyos_abi::boot::{KernelArgs, MemoryMapEntry}; use toyos_rootimage::handoff::{held, Descriptor}; use crate::block::{BlockError, Holder, Partition}; -use crate::device::ClaimError; +use crate::gpt::Unnamed; use crate::mm::{DirectMap, Region}; use crate::sync::Lock; @@ -173,14 +173,9 @@ pub fn hold_source() { let sought = crate::gpt::seek(guid); let found = match sought.found { Ok(Some(found)) => found, - Ok(None) | Err(ClaimError::Absent) => { - return withhold(guid, "it is on no disk that answered", &sought.silent) - } - Err(ClaimError::Ambiguous) => return withhold(guid, "it is carried twice", &sought.silent), - Err(ClaimError::Unusable) => return withhold(guid, "its table refuses it", &sought.silent), - Err(e @ (ClaimError::Owned | ClaimError::KernelDriven | ClaimError::Exhausted)) => { - panic!("rootfs: gpt::seek answered {e:?}, which no table read makes") - } + Ok(None) => return withhold(guid, "it is on no disk that answered", &sought.silent), + Err(Unnamed::Ambiguous) => return withhold(guid, "it is carried twice", &sought.silent), + Err(Unnamed::Unusable) => return withhold(guid, "its table refuses it", &sought.silent), }; let volume = found.volume; let view = crate::block::open(volume.device) diff --git a/kernel/src/syscall/device.rs b/kernel/src/syscall/device.rs index ea31aee73f..8472b219b3 100644 --- a/kernel/src/syscall/device.rs +++ b/kernel/src/syscall/device.rs @@ -415,7 +415,7 @@ pub(super) fn sys_partition_transfer( match transfer { Transfer::Write(from) => { from.read_at(0, &mut bounce); - let whose = ops::Run::Claim(claim.partition_on(), ops::ClaimOp::Write); + let whose = || ops::Run::Claim(claim.partition_on(), ops::ClaimOp::Write); let run = ops::until_answered(whose, || match claim.partition_view() { Some(view) => view.write_blocks(first, count, &bounce).map_err(ops::block_word), None => Err(SyscallError::Gone), @@ -423,7 +423,7 @@ pub(super) fn sys_partition_transfer( ops::partition_word("a write", run) } Transfer::Read(into) => { - let whose = ops::Run::Claim(claim.partition_on(), ops::ClaimOp::Read); + let whose = || ops::Run::Claim(claim.partition_on(), ops::ClaimOp::Read); let run = ops::until_answered(whose, || match claim.partition_view() { Some(view) => view.read_blocks(first, count, &mut bounce).map_err(ops::block_word), None => Err(SyscallError::Gone), diff --git a/kernel/src/syscall/machine.rs b/kernel/src/syscall/machine.rs index d69028a278..541cf8fee0 100644 --- a/kernel/src/syscall/machine.rs +++ b/kernel/src/syscall/machine.rs @@ -100,8 +100,6 @@ fn quiesce(last: &str) -> Result<(), SyscallError> { let queued = crate::log::console::queue(QUEUED_AT_THE_STOP.as_bytes(), false); assert!(queued, "console-queue-at-the-stop: the queue had no room for its one line"); } - // Every console holder is stopped, so the queue only shrinks from here: - // what they queued goes on the wire now, above the boot's last word. crate::log::console::drain_for_the_stop(); #[cfg(feature = "boot-actuators")] if crate::actuator::quiesce_dump() { diff --git a/src/bootlog.rs b/src/bootlog.rs index 5e54c80c39..14aa18ad1e 100644 --- a/src/bootlog.rs +++ b/src/bootlog.rs @@ -500,10 +500,66 @@ pub fn verdict(log: &str) -> Result { Ok(boot_ms) } +/// **`Rebooting.` is the last record, and nothing this boot still holds may +/// write one after it.** +/// +/// The runner's deadline kills the job it is watching, which releases the `wait` +/// its own job loop is inside, and that loop can spawn the next job into the +/// window between the boot's last word and the reset. +/// +/// A boot with no such word — a panic — is not asked: it correctly writes none. +/// The window ends at the next loader pass, because everything that pass prints +/// is after the reset by construction. +/// +/// **A spawn record and not every record**, because those are the two different +/// claims. `quiesce` writes after its own last word by construction — an idle +/// CPU's `sched:` report can land there — and nothing is left running to take +/// it anywhere but the console. A *spawn* is a process that was still on a run +/// queue after the stop said it had stopped every one. +/// +/// **The boot's own word, not the next pass's copy of it**: that pass prints +/// the boot's newest records under [`LOG_TAIL`], newest first, so the +/// copy of the last word heads records that were written before it. +pub fn nothing_after_the_last_word(text: &str) -> Result<(), String> { + let lines: Vec<&str> = text.lines().collect(); + let Some(at) = lines + .iter() + .rposition(|line| line.contains(REBOOTING) && !line.contains(LOG_TAIL)) + else { + return Ok(()); + }; + let mut window = + lines[at + 1..].iter().take_while(|line| !line.contains(LOADER_FIRST_LINE)); + match window.find(|line| line.contains(SPAWN)) { + None => Ok(()), + Some(line) => Err(format!( + "a process started after {REBOOTING:?}, which is the boot's own last word and what a \ + metal boot is judged on: {line:?}" + )), + } +} + #[cfg(test)] mod tests { use super::*; + /// A spawn after the boot's own last word is refused; the next pass's + /// newest-first copy of that word, which heads records written before it, + /// opens no window, and the next pass is after the reset. + #[test] + fn a_spawn_after_the_boots_own_last_word_is_refused() { + let word = format!("[kernel 23.340 cpu1] {REBOOTING}\n"); + let spawn = format!("[kernel 23.341 cpu0] {SPAWN}late pid=9\n"); + let loader = format!("{LOADER_FIRST_LINE}\n"); + let tail = format!( + "| {LOG_TAIL}[kernel 23.340 cpu1] {REBOOTING}\n| {LOG_TAIL}[kernel 1.0 cpu0] {SPAWN}init pid=1\n" + ); + assert_eq!(nothing_after_the_last_word(&format!("{word}{loader}{tail}")), Ok(())); + assert!(nothing_after_the_last_word(&format!("{word}{spawn}{loader}{tail}")).is_err()); + assert_eq!(nothing_after_the_last_word(&format!("{word}{loader}{spawn}")), Ok(())); + assert_eq!(nothing_after_the_last_word(&spawn), Ok(())); + } + /// The half-told boot: the kernel got all the way up and the log stops /// there, so the machine either never asked for the reset or `logd` never /// made the log whole before it. diff --git a/tests/common/partclaim.rs b/tests/common/partclaim.rs index 7828bc1b2c..e613a46a8f 100644 --- a/tests/common/partclaim.rs +++ b/tests/common/partclaim.rs @@ -217,12 +217,13 @@ pub fn partition_claim( Ok(()) } -/// The two exits of a claim that gets no answer: a disk that does not answer a +/// The exits of a claim that gets no answer: a disk that does not answer a /// read of its table refuses the claim rather than resolving it on the disks -/// that did, and a transfer every attempt of which is refused on its budget -/// ends at the deadman with the device's word. +/// that did, a transfer every attempt of which is refused on its budget ends +/// at the deadman with the device's word, and ROOT's source, whose disk did +/// not answer its hold, stays the kernel's once the disk answers. pub fn partition_claim_gives_up( - _test_config: &Path, + test_config: &Path, c_bins: &[(String, Vec)], rust_bins: &[(String, Vec)], ) -> Result<(), String> { @@ -276,6 +277,53 @@ pub fn partition_claim_gives_up( } } let _ = std::fs::remove_file(&nvme); + root_withheld(test_config, c_bins, rust_bins) +} + +/// ROOT's source on the one disk, which did not answer ROOT's hold and answers +/// every read after it: its GUID is withheld, so the claim that now finds its +/// span on a disk that answers, and unheld, is refused as the kernel's. +fn root_withheld( + test_config: &Path, + c_bins: &[(String, Vec)], + rust_bins: &[(String, Vec)], +) -> Result<(), String> { + const PARAMS: &[&str] = &["partclaim-root-withheld"]; + let image = super::lane::dir().join("partclaim-root-withheld.img"); + std::fs::write(&image, qemu::build_boot_image(test_config, c_bins, rust_bins, PARAMS)) + .map_err(|e| format!("write the boot image: {e}"))?; + let [_, _, root] = boot_stick_guids(&image)?; + let mut qemu = QemuInstance::boot_with_options( + test_config, + c_bins, + rust_bins, + BootOptions { + profile: qemu::Profile::InternalDisk, + boot_image: Some(Staged::Pristine(image.clone())), + kernel_params: PARAMS, + ..Default::default() + }, + ); + let boot = qemu.boot_log().to_string(); + no_panic("withheld", &boot)?; + let not_held = format!( + "root: the partition ROOT was read from, {root}, is not held because it is on no disk \ + that answered" + ); + if !boot.contains(¬_held) { + return Err(format!("withheld: the kernel never said {not_held:?}:\n{boot}")); + } + let result = + qemu.run_test(&format!("test_rs_partition_claimant withheld {root}"), Duration::from_secs(180)); + let tail = shut_down(qemu); + let kernel = guest_verdict(&result, &tail, 1).map_err(|e| format!("withheld: {e}"))?; + let want = format!("partclaim: {root} is where ROOT was read from, and the kernel withholds it"); + if !kernel.contains(&want) { + return Err(format!("withheld: the kernel never said {want:?}:\n{kernel}")); + } + no_panic("withheld", &tail)?; + let _ = std::fs::remove_file(&image); + eprintln!(" [partclaim] withheld: {want}"); Ok(()) } diff --git a/tests/common/power.rs b/tests/common/power.rs index 2228d9a8d3..198952e044 100644 --- a/tests/common/power.rs +++ b/tests/common/power.rs @@ -2678,7 +2678,7 @@ fn one_reset_path(case: &Path, arm: &ResetPath) -> Result<(), String> { a controller's registers without settling the command a device was inside" )); } - nothing_after_the_last_word(after.text()).map_err(|why| format!("{path}: {why}"))?; + bootlog::nothing_after_the_last_word(after.text()).map_err(|why| format!("{path}: {why}"))?; ended_in_a_reset(&mut resets).map_err(|why| format!("{path}: {why}"))?; // And the machine comes back on the same device. The pass after the chain's @@ -2691,45 +2691,6 @@ fn one_reset_path(case: &Path, arm: &ResetPath) -> Result<(), String> { Ok(()) } -/// **`Rebooting.` is the last record, and nothing this boot still holds may -/// write one after it.** -/// -/// The runner's deadline kills the job it is watching, which releases the `wait` -/// its own job loop is inside, and that loop can spawn the next job into the -/// window between the boot's last word and the reset. -/// -/// A boot with no such word — a panic — is not asked: it correctly writes none. -/// The window ends at the next loader pass, because everything that pass prints -/// is after the reset by construction. -/// -/// **A spawn record and not every record**, because those are the two different -/// claims. `quiesce` writes after its own last word by construction — an idle -/// CPU's `sched:` report can land there — and nothing is left running to take -/// it anywhere but the console. A *spawn* is a process that was still on a run -/// queue after the stop said it had stopped every one. -/// -/// **The boot's own word, not the next pass's copy of it**: that pass prints -/// the boot's newest records under [`bootlog::LOG_TAIL`], newest first, so the -/// copy of the last word heads records that were written before it. -fn nothing_after_the_last_word(text: &str) -> Result<(), String> { - let lines: Vec<&str> = text.lines().collect(); - let Some(at) = lines - .iter() - .rposition(|line| line.contains(REBOOTING) && !line.contains(bootlog::LOG_TAIL)) - else { - return Ok(()); - }; - let mut window = - lines[at + 1..].iter().take_while(|line| !line.contains(bootlog::LOADER_FIRST_LINE)); - match window.find(|line| line.contains(bootlog::SPAWN)) { - None => Ok(()), - Some(line) => Err(format!( - "a process started after {REBOOTING:?}, which is the boot's own last word and what a \ - metal boot is judged on: {line:?}" - )), - } -} - /// The T14's judge for [`usb_reset_hands_devices_back`]. /// /// **The machine is the judge of the device, and nothing else is.** QEMU cannot diff --git a/tests/common/ssh.rs b/tests/common/ssh.rs index 83e88fc960..fa6857082f 100644 --- a/tests/common/ssh.rs +++ b/tests/common/ssh.rs @@ -119,9 +119,15 @@ pub fn ssh_pipe(host: &str, port: u16, identity: &Identity, command: &str, stdin /// Ask for `command` and answer the guest's reply to the request, without /// waiting for the program: `reboot`, whose status no client can collect. +/// A refused request, or a program that came back, is an error by name: the +/// command did not end the machine. pub fn ssh_fire(host: &str, port: u16, identity: &Identity, command: &str) -> Result { let said = client(&["fire", host, &port.to_string(), str(&identity.private), command])?; - Ok(said.lines().last().unwrap_or("").to_string()) + let said = said.lines().last().unwrap_or("").to_string(); + match said.as_str() { + "accepted" | "closed" | "silent" => Ok(said), + _ => Err(format!("`{command}` over ssh answered {said:?}, so it did not end the machine")), + } } /// Run `command` with `stdin` on its input, after asking the guest to set an diff --git a/tests/common/storage.rs b/tests/common/storage.rs index 65644a28cc..fe93ca226d 100644 --- a/tests/common/storage.rs +++ b/tests/common/storage.rs @@ -601,8 +601,9 @@ pub fn home_budget_refusal_retried( // And the refusal was one per file, not one per flush: `logd` flushes every // round it wrote a line in, and a refused flush is lines of its own, so a // refusal on every flush keeps `/log` retrying for as long as the machine - // runs and rotates the boot's own log away. An absence, so it is judged - // over a window with nothing left to flush in it. + // runs and rotates the boot's own log away. An absence has no event to wait + // on, so it is judged over a fixed window: the storm retries there without + // pause, the once-per-file refusal never. let after = qemu.drain_serial(Duration::from_secs(2)); let again: Vec<&str> = after.lines().filter(|l| l.contains("fsync: ") && l.contains("durable on attempt")).collect(); diff --git a/tests/common/usb.rs b/tests/common/usb.rs index b1725550af..333a93fd16 100644 --- a/tests/common/usb.rs +++ b/tests/common/usb.rs @@ -2742,8 +2742,15 @@ fn transport_gives_up( let Some(held) = boot.lines().find(|l| l.contains("root: holding ")) else { return Err(format!("the boot never held the partition ROOT was read from\n{log}")); }; - if held.ends_with("disks that did not answer: []") { - return Err(format!("{held:?}: the disk the gate left offline answered ROOT's hold\n{log}")); + let Some(gate) = boot.lines().find_map(|l| { + l.split_once("usb-gate: disk ")?.1.split_once(" designated")?.0.parse::().ok() + }) else { + return Err(format!("the gate never said which disk it designated\n{log}")); + }; + // A USB disk's `DeviceId` is 16 past its index (`drivers/usb_storage.rs`). + let silent = format!("disks that did not answer: [{}]", 16 + gate); + if !held.ends_with(&silent) { + return Err(format!("{held:?}: ROOT's hold did not name the gate's disk alone, {silent:?}\n{log}")); } // The budget is the kernel's declaration, read off the gate's own line. diff --git a/tests/ssh-client-host/src/main.rs b/tests/ssh-client-host/src/main.rs index fc76e06031..316a527ff1 100644 --- a/tests/ssh-client-host/src/main.rs +++ b/tests/ssh-client-host/src/main.rs @@ -21,7 +21,8 @@ //! toyos_ssh abandon → ok //! toyos_ssh fire //! → accepted | refused | closed | silent -//! toyos_ssh put → ok +//! | exited +//! toyos_ssh put → ok //! toyos_ssh get → ok //! toyos_ssh list → entry …, ok //! toyos_ssh swap @@ -331,13 +332,25 @@ async fn fire(host: &str, port: &str, key: &str, command: &str) -> Result<(), St // whose connection is gone, so a client that left the moment the request // was accepted could end the very `reboot` it asked for before it reached // its syscall. + // A status is the program coming back, which one that ended the machine + // never does: `exited ` rather than `accepted`. + let mut exited = None; if answer == "accepted" { let _ = tokio::time::timeout(FIRE_ANSWER, async { - while !matches!(channel.wait().await, Some(ChannelMsg::Close) | None) {} + loop { + match channel.wait().await { + Some(ChannelMsg::ExitStatus { exit_status }) => exited = Some(exit_status), + Some(ChannelMsg::Close) | None => break, + Some(_) => {} + } + } }) .await; } - println!("{answer}"); + match exited { + Some(status) => println!("exited {status}"), + None => println!("{answer}"), + } // Dropped rather than disconnected: the machine this was fired at may // already be gone, and a goodbye to it is one more wait on nothing. drop(session); diff --git a/tests/toyos-rust-tests/src/bin/partition_claimant.rs b/tests/toyos-rust-tests/src/bin/partition_claimant.rs index e9c7d2205c..b1ed0356d1 100644 --- a/tests/toyos-rust-tests/src/bin/partition_claimant.rs +++ b/tests/toyos-rust-tests/src/bin/partition_claimant.rs @@ -16,6 +16,8 @@ //! - `endowed` — finds the claim its parent moved to it, by the label init //! endows a `part:` row under; //! - `unanswered` — a claim while a disk does not answer a read of its table; +//! - `withheld ` — a claim of ROOT's source, whose disk did not answer +//! ROOT's hold and answers now; //! - `deadman` — transfers whose every attempt is refused on its budget until //! the deadman; //! - `departure`, `silent`, `untold` — claims on one USB stick whose device @@ -114,6 +116,7 @@ fn main() { Some("holder") => holder(&cap), Some("endowed") => endowed(), Some("unanswered") => unanswered(&cap), + Some("withheld") => withheld(&cap, &args[1..]), Some("deadman") => deadman(&cap), Some("departure") => departure(&cap), Some("silent") => silent(&cap), @@ -364,6 +367,20 @@ fn unanswered(cap: &SysCap) { println!("partition_claimant: PASS"); } +/// ROOT's source, which the boot withheld when its disk did not answer: the +/// disk answers now and nothing holds the span, and the claim is still the +/// kernel's to refuse. +fn withheld(cap: &SysCap, root: &[String]) { + let [root] = root else { panic!("withheld takes ROOT's GUID, got {root:?}") }; + refused( + cap, + "ROOT, withheld when its disk did not answer the boot's hold,", + guid(root), + SyscallError::PermissionDenied, + ); + println!("partition_claimant: PASS"); +} + /// Every attempt of a transfer is refused on its budget until the deadman: each /// ends `Io`, the device's word, and not another ask-again. (NVMe's flush asks /// the device nothing, so it has no budget to refuse.) diff --git a/tests/toyos.rs b/tests/toyos.rs index bcb78025cf..1e413c4835 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -993,8 +993,9 @@ const MACHINE_TESTS: &[(&str, Sched, Tier)] = &[ // the neighbours and the target judged off the image. Body in // `tests/common/partclaim.rs`, as are the two below. ("partition_claim", Sched::Parallel, Tier::Fast), - // Two boots: a disk that does not answer a read of its table, and every - // attempt refused until the deadman. + // Three boots: a disk that does not answer a read of its table, every + // attempt refused until the deadman, and ROOT's source withheld from every + // claim once its disk did not answer the boot's hold. ("partition_claim_gives_up", Sched::Parallel, Tier::Fast), // Three boots, a USB stick's device leaving owing one claim's write and // coming back on another port each time: each partition's fsync answers From 877b8c950bc29cdf6407403d99379679cd73c720 Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 27 Sep 2026 13:25:12 +0200 Subject: [PATCH 13/14] rootfs: hold_source calls withhold from one place, and the round-2 NOTEs hold_source computed one Result per arm and called withhold from four sites, so the only tested arm was Ok(None); the other three could drop their withhold silently and nothing would notice. Fold the found partition and its view into one Result<(found, view), &'static str> keyed on why it failed, and call withhold once from the single Err arm the existing test already exercises. The log text is unchanged. Also: drop the false and the branch-scoped lines from the console queue issue (main has had the queue since #527, and the branch name rots at the merge), and align the `put` row in toyos_ssh's usage table with its neighbours. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_014iqcj4jDKpaiDX8B7CMvmK --- ...n-reach-the-console-after-the-last-word.md | 5 +-- kernel/src/rootfs.rs | 39 ++++++++++--------- tests/ssh-client-host/src/main.rs | 2 +- 3 files changed, 24 insertions(+), 22 deletions(-) diff --git a/issues/kernel/a-holders-queued-line-can-reach-the-console-after-the-last-word.md b/issues/kernel/a-holders-queued-line-can-reach-the-console-after-the-last-word.md index 7c6c4b0b70..dba8388abb 100644 --- a/issues/kernel/a-holders-queued-line-can-reach-the-console-after-the-last-word.md +++ b/issues/kernel/a-holders-queued-line-can-reach-the-console-after-the-last-word.md @@ -23,8 +23,7 @@ The mechanism read off the code: `logd` puts a program's line in and then a chunk of queued lines per hold of the wire, whatever their age. The stop stops every userland thread and writes its last word as a record, which `drain_inline` or `klogd`'s next pass puts on the wire; a line still in the -queue then goes after it, inside `quiesce-late-word`'s window. `main` has no -queue — a holder wrote the wire itself — so this is the branch's. +queue then goes after it, inside `quiesce-late-word`'s window. ## Exit condition @@ -33,7 +32,7 @@ leaves a line in the queue at the stop goes red without that and green with it. ## The stop now drains the queue -On `nightly-green2` the stop drains the queue on the wire right after +The stop drains the queue on the wire right after `quiesce::stop()`, before `Syncing filesystems...` (`log::console::drain_for_the_stop`). `console-queue-at-the-stop` is the deterministic stimulus: it queues one line after every holder is stopped and diff --git a/kernel/src/rootfs.rs b/kernel/src/rootfs.rs index cfc137d0b9..1c82fcee30 100644 --- a/kernel/src/rootfs.rs +++ b/kernel/src/rootfs.rs @@ -171,31 +171,34 @@ pub fn mount() -> Mounted { pub fn hold_source() { let guid = toyos_abi::part::PartGuid(BOOT.lock().source); let sought = crate::gpt::seek(guid); - let found = match sought.found { - Ok(Some(found)) => found, - Ok(None) => return withhold(guid, "it is on no disk that answered", &sought.silent), - Err(Unnamed::Ambiguous) => return withhold(guid, "it is carried twice", &sought.silent), - Err(Unnamed::Unusable) => return withhold(guid, "its table refuses it", &sought.silent), + let held: Result<(crate::gpt::Claimable, Partition), &'static str> = match sought.found { + Ok(Some(found)) => { + let volume = found.volume; + crate::block::open(volume.device) + .ok_or(()) + .and_then(|handle| { + let (first, blocks) = + crate::block::span_blocks(volume.start_lba, volume.blocks, volume.lba_bytes) + .map_err(drop)?; + Partition::of(handle, first, blocks, Holder::Kernel("system")).map_err(drop) + }) + .map(|view| (found, view)) + .map_err(|()| "it is no span a view can hold") + } + Ok(None) => Err("it is on no disk that answered"), + Err(Unnamed::Ambiguous) => Err("it is carried twice"), + Err(Unnamed::Unusable) => Err("its table refuses it"), }; - let volume = found.volume; - let view = crate::block::open(volume.device) - .ok_or(()) - .and_then(|handle| { - let (first, blocks) = - crate::block::span_blocks(volume.start_lba, volume.blocks, volume.lba_bytes) - .map_err(drop)?; - Partition::of(handle, first, blocks, Holder::Kernel("system")).map_err(drop) - }); - match view { - Ok(view) => { + match held { + Ok((found, view)) => { log!( "root: holding {}, the partition ROOT was read from, on device {}; disks that did \ not answer: {:?}", - found.unique, volume.device, sought.silent + found.unique, found.volume.device, sought.silent ); *SOURCE.lock() = Some(view); } - Err(()) => withhold(guid, "it is no span a view can hold", &sought.silent), + Err(why) => withhold(guid, why, &sought.silent), } } diff --git a/tests/ssh-client-host/src/main.rs b/tests/ssh-client-host/src/main.rs index 316a527ff1..67d9ebe02d 100644 --- a/tests/ssh-client-host/src/main.rs +++ b/tests/ssh-client-host/src/main.rs @@ -22,7 +22,7 @@ //! toyos_ssh fire //! → accepted | refused | closed | silent //! | exited -//! toyos_ssh put → ok +//! toyos_ssh put → ok //! toyos_ssh get → ok //! toyos_ssh list → entry …, ok //! toyos_ssh swap From 00ec52ecae171a8b2d82edb50bf3b19f092cf900 Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 27 Sep 2026 15:19:40 +0200 Subject: [PATCH 14/14] issues: the three nightly reds on #535 are main's, each at its owner Nightly 36314576406 at a4f68c5a reddened lan_swap and xhci_flap in guest (1) and handle_kill_policy in guest (8). None of them is this branch's. Each is filed where its code lives, with the recommendation that it goes on #542's disabled list when that lands. - xhci_flap: a lost wake in main's driver. Slot_gone's Teardown arm leaves the port Settled with the device in it and CSC unacknowledged, and poll steps no port unless one is dirty or outstanding. The same sentence was red on wt/toyos-lld at a55d62c6 (run 36287592139). On the dev host, QEMU 11.1.1 TCG, a printed serial shows every other collapse stuck about 700 ms until the next cycle's edges. The committed four-cycle gate is green by parity. At CYCLES = 3 it is red (EXIT=1), and adding `self.ports_dirty = true;` after torn_down() makes it green (EXIT=0). All measurement patches were applied checked and reverted, and the tree is clean. - lan_swap: the redial ceiling that is already recorded (issues/diagnostics/a-swaps-redial-asks-again-with-no-event-to-wait-on.md), reached on the 82574 bench. The branch changes nothing on that path. - handle_kill_policy: the same failure text, byte for byte, on main's nightly at 16d2e645. Consistent with the deferred release this branch does not touch. Named runs, dev host, one at a time, branch 877b8c95 / main 16d2e645: xhci_flap 0/0, lan_swap 0/0, handle_kill_policy 0/0, log_reserve_window_negative 0/0. The shard-8 `log-gate: FAILED` line is that negative control's owed refusal, printed by a passing test on both trees. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_014iqcj4jDKpaiDX8B7CMvmK --- ...al-spent-its-ceiling-on-a-nightly-shard.md | 44 ++++++++++++ ...ed-only-when-another-port-event-arrives.md | 68 +++++++++++++++++++ ...sus-grew-one-sharedmem-on-two-nightlies.md | 42 ++++++++++++ 3 files changed, 154 insertions(+) create mode 100644 issues/build/lan-swap-redial-spent-its-ceiling-on-a-nightly-shard.md create mode 100644 issues/hardware/a-collapsed-replug-is-enumerated-only-when-another-port-event-arrives.md create mode 100644 issues/kernel/handle-kill-policy-census-grew-one-sharedmem-on-two-nightlies.md diff --git a/issues/build/lan-swap-redial-spent-its-ceiling-on-a-nightly-shard.md b/issues/build/lan-swap-redial-spent-its-ceiling-on-a-nightly-shard.md new file mode 100644 index 0000000000..e76e81fa8f --- /dev/null +++ b/issues/build/lan-swap-redial-spent-its-ceiling-on-a-nightly-shard.md @@ -0,0 +1,44 @@ +--- +status: open +kind: defect +opened: 2026-09-27 +--- + +# `lan_swap`'s redial spent its ceiling on a nightly shard + +PR #535's nightly (run 36314576406, `guest (1)`, a4f68c5a, KVM, QEMU 11.1.0): + +``` +FAIL lan_swap: 2 finding(s): + init's words on netd were ["accepted"] ending in None, where InService is owed (the stream had 1 connection(s) before the ask and 1 after) + the stream's redial was turned away 64 time(s), its ceiling of 64, and gave up +``` + +The guest completed the swap. Its console has `init: swap netd: in service` +at 6.141 s, and `logd: serving this boot's log on port 41337` at 1.176 s +through the new netd. After that `logd` admitted no reader: no second +`serving this boot's log to 10.0.2.2:…` line. So none of the host's 64 dials +reached `logd` once it listened again. That is consistent with all of them +ending inside the guest's gap, which runs from `logd`'s `netd is being +replaced` (1.000 s), through init stopping the old netd (1.080 s), to `logd` +listening again (1.176 s). The alone re-run was green with 4 dials turned away. + +This is `issues/build/swap-crash-rolls-back-reds-when-its-redial-spends-its-ceiling-under-load.md` +on the 82574 bench: the compromise +`issues/diagnostics/a-swaps-redial-asks-again-with-no-event-to-wait-on.md` +records, reached. A redial asks again at once, and the ceiling counts dials, +not time. `lan_swap`'s path (`Ssh::swap`, `metalswap::swap`, `Stream::redial`, +`logd`, netd, init) has no change on #535. Main's nightly at 16d2e645 (run +36306830048) was green. Main's nightly at 1ce71831 (run 36290616312) had the +same two findings on `swap_crash_rolls_back`. + +Dev host, QEMU 11.1.1, TCG, one named run each: `nightly-green2` at 877b8c95, +`EXIT=0`, 12 dials turned away; `main` at 16d2e645, `EXIT=0`, 11. Not measured: +how fast a KVM guest turns a dial away, and so how many dials fit inside the +gap there. + +`cargo run -- --known-red lan_swap` answers NO. + +**Exit**: the redial waits on a guest-side event (the diagnostics issue's exit). +Until then `lan_swap` reds on the nightly at a rate. It should go on #542's +disabled list when that lands, citing this file. diff --git a/issues/hardware/a-collapsed-replug-is-enumerated-only-when-another-port-event-arrives.md b/issues/hardware/a-collapsed-replug-is-enumerated-only-when-another-port-event-arrives.md new file mode 100644 index 0000000000..c1ae44693a --- /dev/null +++ b/issues/hardware/a-collapsed-replug-is-enumerated-only-when-another-port-event-arrives.md @@ -0,0 +1,68 @@ +--- +status: open +kind: defect +opened: 2026-09-27 +--- + +# A collapsed replug is enumerated only when another port event arrives + +A device pulled and pushed back between two looks is torn down +(`Step::Teardown(Gone::Replugged)`), and its slot's Disable Slot completes in a +later `Controller::poll` (`kernel/src/drivers/xhci/mod.rs`). There +`slot_gone`'s `AfterSlot::Teardown` calls `PortState::torn_down`, which leaves +the port `Settled` and not attached with the device still in it. `poll` steps +the ports only when `ports_dirty` is set or a port is `outstanding`. Neither is +true then, so nothing looks at the port again. `PORT_WORK_AT` goes to 0, and +PORTSC's CSC stays set because the teardown step returns ahead of the +acknowledge. QEMU raises no further Port Status Change for that port +(`xhci_port_notify` returns while the bit is set), so the device in the port is +never enumerated. It stays dead until an unrelated event marks the ports dirty. +The next unplug is one such event. On the T14 this is a replugged mouse that +does not come back. + +Whether the wake is lost depends on how QEMU's two edge events fall across +polls: `xhci_port_update` clears PORTSC and then notifies, so the detach and +the attach each raise their own event. The wake survives when the attach's +event is drained in the same poll as the completion or later. It is lost when +both events are drained before the completion. + +## Evidence + +- The PR #535 nightly (run 36314576406, `guest (1)`, a4f68c5a) was red with + `0 slot(s) enabled and never disabled ([]) after 4 replugs`. The first three + collapses re-enumerated 100 ms after their teardown (1.780 → 1.881 s). The + fourth was torn down at 3.586 s, and nothing followed in the 900 ms before + the guest's input ended. `wt/toyos-lld` at a55d62c6, an ancestor of `main` + (run 36287592139, `guest (1)`), was red with the same sentence. Its first + collapse (1.971 s) was enumerated only at 2.674 s, 700 ms later, when the + next cycle's edges arrived. +- The dev host, QEMU 11.1.1, TCG, on `nightly-green2` at 877b8c95. QEMU's + `hw/usb/hcd-xhci.c` is byte-identical at v11.1.0 and v11.1.1. With only a + print of the serial added, every other collapse sits about 700 ms until the + next cycle rescues it: 1.022 → 1.725 s and 2.232 → 2.938 s. The test is + green because the fourth cycle is a rescue. With `self.ports_dirty = true;` + added after `torn_down()` in `AfterSlot::Teardown`, all four collapses are + seen as such and each re-enumerates 100 ms after its teardown + (`4 replugs collapsed inside the debounce (4 seen as such): 5 slot(s) + enabled`). +- The same tree with `CYCLES = 3`: red, `EXIT=1`, `0 slot(s) enabled and never + disabled ([]) after 3 replugs`, red again in the harness's alone re-run. + With the one-line wake added it is green, `EXIT=0`, `3 seen as such`. +- One named run of `xhci_flap` as committed is green on `nightly-green2` + (`EXIT=0`) and on `main` at 16d2e645 (`EXIT=0`). + +So the gate as committed passes by parity wherever every collapse loses its +wake. On the dev host it cannot go red. It reds on CI's KVM shards only when +the last collapse is the one that loses it. + +`AfterSlot::Again` ends in the same `torn_down()` with no look after it; that +arm was not staged. + +## Exit condition + +A port torn down with its device still in it is looked at again without +waiting for another event, shown by a gate that goes red on the lost wake on +every host. `xhci_flap` at an odd cycle count is one such gate. An assertion +that every collapsed teardown is enumerated before the next cycle's edges is +another. Until then `xhci_flap` reds on main's nightly at a rate. It should go +on #542's disabled list when that lands, citing this file. diff --git a/issues/kernel/handle-kill-policy-census-grew-one-sharedmem-on-two-nightlies.md b/issues/kernel/handle-kill-policy-census-grew-one-sharedmem-on-two-nightlies.md new file mode 100644 index 0000000000..5d2870a54a --- /dev/null +++ b/issues/kernel/handle-kill-policy-census-grew-one-sharedmem-on-two-nightlies.md @@ -0,0 +1,42 @@ +--- +status: open +kind: defect +opened: 2026-09-27 +--- + +# `handle_kill_policy`'s census grew by one `SharedMem` on two nightlies in a row + +Main's nightly at 16d2e645 (run 36306830048, `guest (8)`) and PR #535's at +a4f68c5a (run 36314576406, `guest (8)`), KVM, QEMU 11.1.0, both red with +byte-identical text, numbers included: + +``` +16 more killed processes left more live objects behind: [("SharedMem", 9, 10)] — first PipeRead 6, PipeWrite 5, Connection 2, Device 1, Acceptor 5, Inbox 6, SharedMem 9, ... +``` + +Both had `ALONE handle_kill_policy: GREEN`. It was green on the nightlies at +1ce71831 (run 36290616312) and at c2715880 (run 36297455432). c2715880 already +carries 16d2e645, so this is a rate on `main`'s code. The actuator boot it +shares carried the same eight tests in all four runs, and test-runner runs +one job at a time. + +Dev host, QEMU 11.1.1, TCG, one named run each: `nightly-green2` at 877b8c95, +`EXIT=0`; `main` at 16d2e645, `EXIT=0`. + +What is known: every holder the test kills holds one `SharedMem` region and +one pipe, and `settled_census` answers once two readings 10 ms apart agree. +The mechanism +`issues/kernel/deferred-release-outlives-its-syscall.md` records is a release +still in flight on another CPU when both readings are taken. That would read +exactly like this: one killed holder's region is not yet released at the +second census. The red boot's kernel reports a TLB shootdown wait of up to +13667 us (`tlb: … max=13667us`), longer than the settle's 10 ms. +Not shown: which process held the tenth `SharedMem`, or that its release was +the one in flight. + +`cargo run -- --known-red handle_kill_policy` answers NO. + +**Exit**: the census names the owner of a grown kind, and the red is +attributed or the release is shown to finish before `wait` returns. Until then +`handle_kill_policy` reds on main's nightly at a rate. It should go on #542's +disabled list when that lands, citing this file.