From 4c35a94b7462fb2911dbf05361a97fe625a8af99 Mon Sep 17 00:00:00 2001 From: japabu Date: Mon, 28 Sep 2026 21:23:59 +0200 Subject: [PATCH 1/4] K3: delete the logstorm and lognest kernel threads MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit kernel/src/log/storm.rs and kernel/src/log/nested.rs existed only to exercise four guest tests (log_conservation_smp1, log_nested_emit, log_reserve_window, log_reserve_window_negative). Delete both files, their kthread::spawn call sites, their five actuators and cmdline tokens (log-storm, log-unbracketed-reserve, log-nested-emit, log-nested-reserve, log-shared-reservation), the x86-64 log_nest IDT gate and vector, the aarch64 LogNest vector, the userland test-runner log-gate builtin those tests alone drove, and every test registration and helper that served them — leaving klogd and iod as the kernel's only remaining kthread::spawn sites. Two real claims those tests alone checked — same-CPU interrupt reentrancy inside emit's IF/TF-off bracket, and SYS_LOG_READ's conservation law under concurrent multi-shard write load — are now unverified, recorded in issues/kernel/deleting-logstorm-and-lognest-left-two-log-claims-unverified.md rather than left silent. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01W6rME2DoqwjcYFStYHHY4j --- ...-lognest-left-two-log-claims-unverified.md | 41 + .../the-kernel-still-creates-threads.md | 6 +- kernel-loom/src/lib.rs | 20 - kernel/src/actuator.rs | 15 - kernel/src/arch/aarch64/mod.rs | 24 - kernel/src/arch/aarch64/trap.rs | 2 - kernel/src/arch/x86_64/idt/log_nest.rs | 13 - kernel/src/arch/x86_64/idt/mod.rs | 18 +- kernel/src/arch/x86_64/mod.rs | 29 - kernel/src/arch/x86_64/percpu.rs | 2 - kernel/src/log/mod.rs | 11 - kernel/src/log/nested.rs | 143 ---- kernel/src/log/shard.rs | 4 - kernel/src/log/storm.rs | 62 -- kernel/src/log/user.rs | 11 - kernel/src/sched/kthread.rs | 5 +- kernel/src/watch.rs | 12 - src/build.rs | 2 +- tests/common/logread.rs | 382 +-------- tests/test-durations | 4 - tests/toyos.rs | 27 - userland/test-runner/src/log_close.rs | 4 +- userland/test-runner/src/log_gate.rs | 777 ------------------ userland/test-runner/src/main.rs | 2 - 24 files changed, 51 insertions(+), 1565 deletions(-) create mode 100644 issues/kernel/deleting-logstorm-and-lognest-left-two-log-claims-unverified.md delete mode 100644 kernel/src/arch/x86_64/idt/log_nest.rs delete mode 100644 kernel/src/log/nested.rs delete mode 100644 kernel/src/log/storm.rs delete mode 100644 userland/test-runner/src/log_gate.rs diff --git a/issues/kernel/deleting-logstorm-and-lognest-left-two-log-claims-unverified.md b/issues/kernel/deleting-logstorm-and-lognest-left-two-log-claims-unverified.md new file mode 100644 index 00000000000..00bee2a9e90 --- /dev/null +++ b/issues/kernel/deleting-logstorm-and-lognest-left-two-log-claims-unverified.md @@ -0,0 +1,41 @@ +--- +status: open +kind: finding +opened: 2026-09-28 +--- + +# Deleting `logstorm`/`lognest` left two log claims unverified + +`issues/kernel/the-kernel-still-creates-threads.md`'s K3 deletes +`kernel/src/log/storm.rs` and `kernel/src/log/nested.rs` — the kernel threads +that generated log-write load for four guest tests +(`log_conservation_smp1`, `log_nested_emit`, `log_reserve_window`, +`log_reserve_window_negative`) — and, with them, every test that used those +producers. Two real kernel claims were checked by nothing else, and are now +checked by nothing at all. + +**Same-CPU interrupt reentrancy inside `emit`'s IF/TF-off bracket.** +`log_nested_emit` and `log_reserve_window` (plus its negative control +`log_reserve_window_negative`, the only test that ever exercised +`arch::IrqGuard`'s bracket by removing it) staged a self-IPI from a kernel +thread — with `IF` set, unlike inside a syscall — landing inside another +`emit`'s own reservation/publication window. `kernel/src/log/nested.rs`'s own +header called this "the one case loom cannot express and the host cannot +stage": `kernel-loom/tests/log_record.rs` models cross-CPU memory ordering +only, since loom has no interrupts and no CPU flags to reenter. Nothing +else in the tree drives this case: `read.rs`'s `Descent::advance` (a shard's +sequence order is its timestamp order) rests on `emit`'s bracket alone, and +that rests on nothing now. + +**`SYS_LOG_READ`'s conservation law under concurrent multi-shard write +load.** `log_conservation_smp1` was the only guest test that read the log +while it was being written fast enough to exercise the ring's drop-oldest +path and the reader's lost/read accounting concurrently — ordinary kernel +log traffic is far too sparse to reach it. No other test replaces this. + +Reintroducing either check needs a producer that raises the load without a +kernel thread — for instance a syscall that a userland test binary calls in +a tight loop, one bound per CPU, rather than a persistent kthread — which is +a redesign outside K3's scope (delete only). Recorded here rather than +silently, per the owner's ruling that a tracked weakness stays "known, +tracked, still true," never unmentioned. diff --git a/issues/kernel/the-kernel-still-creates-threads.md b/issues/kernel/the-kernel-still-creates-threads.md index f9e353060f4..5f045fc738f 100644 --- a/issues/kernel/the-kernel-still-creates-threads.md +++ b/issues/kernel/the-kernel-still-creates-threads.md @@ -25,8 +25,10 @@ code creates a schedulable task other than the per-CPU idle loop. last thread tears down its own process on its way out of the kernel, and the scheduler frees that thread's kernel stack after switching away. Blocked on #549 landing. -- **K3:** the test-only `logstorm`/`lognest` producers are deleted if the log - gate does not need kernel-context producers. Blocked on nothing. +- **K3:** done — `kernel/src/log/storm.rs` and `kernel/src/log/nested.rs` are + deleted along with the tests that existed only to exercise them; the two + properties they alone checked are unverified now, recorded in + `issues/kernel/deleting-logstorm-and-lognest-left-two-log-claims-unverified.md`. - **K4:** `klogd` goes: the owner-approved driver-model design moves the console to logd, and this track owns that move. - **K5:** `iod` goes with the kernel's write-back queue; met only when #536 diff --git a/kernel-loom/src/lib.rs b/kernel-loom/src/lib.rs index 594fd0faa2a..4204f8a1e18 100644 --- a/kernel-loom/src/lib.rs +++ b/kernel-loom/src/lib.rs @@ -134,26 +134,6 @@ pub mod arch { } } -/// What the kernel has been told to break, and the models never are. -/// -/// A shim rather than a `cfg` at the call site, so `commit` is one statement in -/// every build and the model drives the same line the kernel does. -pub mod actuator { - /// The one `shard.rs` names: the nesting gate's mid-body injection point. - /// Loom has no CPU flags and no interrupts, which is exactly why that gate - /// exists on a machine instead — so the models drive the loop with nothing - /// in it. - pub const fn log_nested_emit() -> bool { - false - } -} - -/// `shard.rs` calls into this from the mid-body point; in the kernel it is -/// `crate::log::nested`, and here `super` is the crate root. -pub mod nested { - pub fn mid_body() {} -} - /// The contention and deadlock reports are unreachable in these models — the /// spin they fire from is what loom cannot explore — but the arguments are /// consumed so the kernel file's bindings are still live code here. diff --git a/kernel/src/actuator.rs b/kernel/src/actuator.rs index 1c79d5b12f0..5b3204f6342 100644 --- a/kernel/src/actuator.rs +++ b/kernel/src/actuator.rs @@ -429,21 +429,6 @@ actuators! { /// Log the monotonic time and which CPUs are alive every 250ms. heartbeat = "heartbeat"; - /// Have every CPU emit patterned log records at once from spawned kernel threads. - log_storm = "log-storm"; - - /// Remove the IF/TF bracket around shard selection through publication — the negative control on the log's interrupt-atomicity claim. - log_unbracketed_reserve = "log-unbracketed-reserve"; - - /// Send this CPU an IPI mid record-copy and emit one shard generation from the handler. - log_nested_emit = "log-nested-emit"; - - /// The same IPI, sent between the shard-pointer read and the unlocked `xadd` — stages order damage the log gate detects, unlike the row above's invisible corruption. - log_nested_reserve = "log-nested-reserve"; - - /// Turn the reservation's `xadd` into a load, an open interrupt window, and a store. - log_shared_reservation = "log-shared-reservation"; - /// Let a handle close cancel every poll on the log's watch in the machine. log_close_cancels_any_syscap = "log-close-cancels-any-syscap"; diff --git a/kernel/src/arch/aarch64/mod.rs b/kernel/src/arch/aarch64/mod.rs index 1ac0e061e99..e70a447a5fd 100644 --- a/kernel/src/arch/aarch64/mod.rs +++ b/kernel/src/arch/aarch64/mod.rs @@ -77,18 +77,6 @@ impl IrqGuard { } Self { daif, _not_send_sync: core::marker::PhantomData } } - - /// The mask captured and interrupts left as they are: what the - /// `log-unbracketed-reserve` actuator stages a log reservation with. - #[cfg(feature = "boot-actuators")] - pub fn unclosed() -> Self { - let daif: u64; - // SAFETY: reads `DAIF` and writes nothing. - unsafe { - core::arch::asm!("mrs {saved}, daif", saved = out(reg) daif); - } - Self { daif, _not_send_sync: core::marker::PhantomData } - } } impl Drop for IrqGuard { @@ -109,18 +97,6 @@ pub unsafe fn percpu_fetch_add( _guard: &IrqGuard, ) -> u64 { let previous = counter.load(core::sync::atomic::Ordering::Relaxed); - // Under `log-shared-reservation`, open the window the guard closes, so a - // nested record can land between the load and the store. - if crate::actuator::log_shared_reservation() && crate::log::nested::inject() { - // SAFETY: each writes `DAIF.I` and touches no memory. - unsafe { - core::arch::asm!("msr daifclr, #2"); - for _ in 0..256 { - core::hint::spin_loop(); - } - core::arch::asm!("msr daifset, #2"); - } - } // A load and a store, not an atomic add: the guard masks the only other // writer this CPU has, and no other CPU writes the counter. counter.store(previous + 1, core::sync::atomic::Ordering::Relaxed); diff --git a/kernel/src/arch/aarch64/trap.rs b/kernel/src/arch/aarch64/trap.rs index 4747673475d..399e8292e41 100644 --- a/kernel/src/arch/aarch64/trap.rs +++ b/kernel/src/arch/aarch64/trap.rs @@ -161,14 +161,12 @@ pub fn install() { /// ([`super::msi_message`], [`super::irqchip::send_self`]) is owed. #[repr(u8)] enum Vector { - LogNest = 1, Hda, VirtioSound, } pub const HDA_VECTOR: u8 = Vector::Hda as u8; pub const VIRTIO_SOUND_VECTOR: u8 = Vector::VirtioSound as u8; -pub const LOG_NEST_VECTOR: u8 = Vector::LogNest as u8; /// The crash report for a panic, from the frame pointer the panic handler stood on. pub(crate) fn report_panic(message: &core::panic::PanicInfo, frame: u64) { diff --git a/kernel/src/arch/x86_64/idt/log_nest.rs b/kernel/src/arch/x86_64/idt/log_nest.rs deleted file mode 100644 index b853a965923..00000000000 --- a/kernel/src/arch/x86_64/idt/log_nest.rs +++ /dev/null @@ -1,13 +0,0 @@ - -use super::device_irq::device_irq_entry; - -extern "sysv64" fn log_nest_handler() { - crate::log::nested::deliver(); - crate::arch::apic::eoi(); -} - -// Reuses `device_irq_entry!`'s stub: it saves scratch registers and aligns the stack for entry from either ring. -device_irq_entry! { - /// The self-IPI `log::nested` sends from inside `emit`. - pub(super) fn log_nest_entry => log_nest_handler -} diff --git a/kernel/src/arch/x86_64/idt/mod.rs b/kernel/src/arch/x86_64/idt/mod.rs index 3c7d56d78a2..646705c59b4 100644 --- a/kernel/src/arch/x86_64/idt/mod.rs +++ b/kernel/src/arch/x86_64/idt/mod.rs @@ -3,8 +3,6 @@ mod device_irq; mod dma_fault; mod hda; mod i8042; -#[cfg(feature = "boot-actuators")] -mod log_nest; mod nmi; pub(crate) mod spurious; mod timer; @@ -41,10 +39,6 @@ pub const HDA_VECTOR: u8 = Vector::Hda as u8; /// The vector the virtio-sound device's MSI-X entry carries. pub const VIRTIO_SOUND_VECTOR: u8 = Vector::VirtioSound as u8; -/// The vector `log-nested-emit` sends itself; installed only in a kernel built with `boot-actuators`. -#[cfg(feature = "boot-actuators")] -pub const LOG_NEST_VECTOR: u8 = 0x27; - const PF_PRESENT: u64 = 1 << 0; const PF_WRITE: u64 = 1 << 1; const PF_INSTRUCTION_FETCH: u64 = 1 << 4; @@ -261,8 +255,7 @@ idt_vectors! { ring3 I8042 = 0x24, i8042::i8042_entry; ring3 DmaFault = 0x25, dma_fault::dma_fault_entry; ring3 Hda = 0x26, hda::hda_entry; - // 0x27 is the actuator gate's (`log_nest`), which is why these start at - // 0x28. One per `pcidev` claim slot: the vector is how the kernel knows + // One per `pcidev` claim slot: the vector is how the kernel knows // which claim a message belongs to. ring3 UserDev0 = 0x28, user_dev::user_dev0_entry; ring3 UserDev1 = 0x29, user_dev::user_dev1_entry; @@ -464,8 +457,6 @@ pub fn init() { disable_pic(); install_gates(&mut IDT.lock()); - #[cfg(feature = "boot-actuators")] - install_actuator_gates(&mut IDT.lock()); // Every slot no row filled: delivery through a P = 0 gate is a // contributory fault, and the machine would halt as #DF with no name. let mut unclaimed = 0u32; @@ -508,13 +499,6 @@ pub fn init() { ); } -/// The one gate outside the table: only an actuator raises [`LOG_NEST_VECTOR`], so a shipping kernel never installs it. -#[cfg(feature = "boot-actuators")] -fn install_actuator_gates(idt: &mut Idt) { - idt.entries[LOG_NEST_VECTOR as usize] = - IdtEntry::ring3(Ring3Entry::new(log_nest::log_nest_entry)); -} - /// Take IF=1 on this CPU; split from `init` so `ioapic::init` can mask firmware-left entries before interrupts are live. pub fn enable_interrupts() { cpu::enable_interrupts(); diff --git a/kernel/src/arch/x86_64/mod.rs b/kernel/src/arch/x86_64/mod.rs index e44661ba2fb..91ee631cfea 100644 --- a/kernel/src/arch/x86_64/mod.rs +++ b/kernel/src/arch/x86_64/mod.rs @@ -76,18 +76,6 @@ impl IrqGuard { } Self { rflags, _not_send_sync: core::marker::PhantomData } } - - /// The flags captured and interrupts left as they are: what the - /// `log-unbracketed-reserve` actuator stages a log reservation with. - #[cfg(feature = "boot-actuators")] - pub fn unclosed() -> Self { - let rflags: u64; - // SAFETY: pushfq/pop is balanced and writes no RFLAGS bit. - unsafe { - core::arch::asm!("pushfq", "pop {saved}", saved = out(reg) rflags); - } - Self { rflags, _not_send_sync: core::marker::PhantomData } - } } impl Drop for IrqGuard { @@ -107,23 +95,6 @@ pub unsafe fn percpu_fetch_add( counter: &core::sync::atomic::AtomicU64, _guard: &IrqGuard, ) -> u64 { - // Under `log-shared-reservation`, stage a load/store race instead of the `xadd` below. - if crate::actuator::log_shared_reservation() { - let previous = counter.load(core::sync::atomic::Ordering::Relaxed); - if crate::log::nested::inject() { - // SAFETY: `sti`/`cli` each write one `RFLAGS` bit and touch no memory. - unsafe { - core::arch::asm!("sti"); - for _ in 0..256 { - core::hint::spin_loop(); - } - core::arch::asm!("cli"); - } - } - counter.store(previous + 1, core::sync::atomic::Ordering::Relaxed); - return previous; - } - let previous: u64; // Not `AtomicU64::fetch_add`: its locked xadd is costly under QEMU TCG emulation. // SAFETY: `counter.as_ptr()` is live; unlocked `xadd` retires whole, atomic against an interrupt here. diff --git a/kernel/src/arch/x86_64/percpu.rs b/kernel/src/arch/x86_64/percpu.rs index f70b189345e..4b4186487d5 100644 --- a/kernel/src/arch/x86_64/percpu.rs +++ b/kernel/src/arch/x86_64/percpu.rs @@ -432,8 +432,6 @@ pub fn reserve_log_slot( pid_off = const OFF_CURRENT_PID, options(preserves_flags), ); - // `log-nested-reserve`'s injection point: must sit between the shard-pointer read and the `xadd`, the only place ordering is decided (no-op outside tests). - crate::log::nested::reserve_window(); seq = (&*(shard as *const log::Shard)).reserve(guard); } (shard as *const log::Shard, seq, cpu, tid, pid) diff --git a/kernel/src/log/mod.rs b/kernel/src/log/mod.rs index 5d4208f7258..d0eb753c480 100644 --- a/kernel/src/log/mod.rs +++ b/kernel/src/log/mod.rs @@ -6,13 +6,10 @@ #![warn(clippy::undocumented_unsafe_blocks)] pub mod console; -pub mod nested; pub mod read; pub mod recovery; pub mod registry; pub mod shard; -#[cfg(feature = "boot-actuators")] -pub mod storm; pub mod user; use core::sync::atomic::{AtomicBool, Ordering}; @@ -178,14 +175,6 @@ pub fn emit(severity: Severity, args: core::fmt::Arguments) { record.len = message.len as u16; record.elided = message.elided.min(u16::MAX as usize) as u16; - // `log-unbracketed-reserve` stages a reservation made with interrupts open. - #[cfg(feature = "boot-actuators")] - let guard = if crate::actuator::log_unbracketed_reserve() { - crate::arch::IrqGuard::unclosed() - } else { - crate::arch::IrqGuard::close() - }; - #[cfg(not(feature = "boot-actuators"))] let guard = crate::arch::IrqGuard::close(); // Stamped inside the bracket: outside it, ordering by seq and by at_ns // could disagree. The NMI handler never logs and #MC halts rather than diff --git a/kernel/src/log/nested.rs b/kernel/src/log/nested.rs deleted file mode 100644 index fb5b423bb55..00000000000 --- a/kernel/src/log/nested.rs +++ /dev/null @@ -1,143 +0,0 @@ -//! Injects a self-IPI from inside `emit`, landing at one of two windows -//! depending on which actuator is armed. -//! -//! `log-nested-emit`: mid body-copy — overwrites an already-published slot, -//! indistinguishable from drop-oldest. -//! `log-nested-reserve`: between the shard-pointer read and the `xadd` — -//! produces a shard whose `at_ns` descends, which `Descent::advance` and the -//! log gate assume cannot happen. - -/// Producer id the burst's records use — outside the range any real storm thread can have. -#[cfg(feature = "boot-actuators")] -pub const NEST_PRODUCER: u64 = u64::MAX; - -#[cfg(feature = "boot-actuators")] -mod armed { - use core::sync::atomic::{AtomicBool, Ordering}; - - use crate::log::shard::SHARD_RECORDS; - use crate::sched::kthread; - - /// One-shot for the body-copy injection point, consumed by `mid_body` or, under `log-shared-reservation`, by the outer `inject`. - static ARMED: AtomicBool = AtomicBool::new(false); - - /// One-shot for the reservation-window injection point, consumed by [`reserve_window`]; kept separate from `ARMED` so it can't starve the body window. - static ARMED_RESERVE: AtomicBool = AtomicBool::new(false); - - /// Set by the injection and cleared by the handler, so a delivery for any other reason emits nothing. - static OWED: AtomicBool = AtomicBool::new(false); - - static STARTED: AtomicBool = AtomicBool::new(false); - - /// Spin count after sending the IPI, so delivery lands inside the window rather than after it. - const WINDOW: usize = 256; - - pub fn start_once() { - // Both actuators name the same injection; arming both would inject into one record twice. - assert!( - !(crate::actuator::log_nested_emit() && crate::actuator::log_nested_reserve()), - "log-nested-emit and log-nested-reserve both name the one injection this thread arms" - ); - if STARTED.swap(true, Ordering::Relaxed) { - return; - } - crate::log!("lognest start records={SHARD_RECORDS}"); - // A kernel thread, not the syscall that arms it: `IF` is clear for a whole syscall, so injecting there would never test the guard. - kthread::spawn("lognest", body, 0); - } - - extern "C" fn body(_arg: u64) -> ! { - if crate::actuator::log_nested_reserve() { - ARMED_RESERVE.store(true, Ordering::Relaxed); - crate::log!( - "lognest outer, and an interrupt is due between this record's shard read and its \ - xadd" - ); - ARMED_RESERVE.store(false, Ordering::Relaxed); - } else { - ARMED.store(true, Ordering::Relaxed); - crate::log!("lognest outer, and an interrupt is due inside this record's body"); - // Reset unconditionally: the one-shot must not outlive this record, or a later injection would land in an unrelated log line. - ARMED.store(false, Ordering::Relaxed); - } - crate::log!("lognest done emitted={SHARD_RECORDS}"); - - crate::watch::park_forever(); - } - - /// Consumes the one-shot and sends this CPU its own IPI; `true` if this call sent it. - pub fn inject() -> bool { - if !ARMED.swap(false, Ordering::Relaxed) { - return false; - } - OWED.store(true, Ordering::Relaxed); - crate::arch::irqchip::send_self(crate::arch::trap::LOG_NEST_VECTOR); - true - } - - /// Injection point inside the body copy; spins after sending so delivery lands inside it. - pub fn mid_body() { - if !inject() { - return; - } - for _ in 0..WINDOW { - core::hint::spin_loop(); - } - } - - /// Injection point between the shard-pointer read and the `xadd`; consumes `ARMED_RESERVE` directly, not via `inject`. - pub fn reserve_window() { - if !ARMED_RESERVE.swap(false, Ordering::Relaxed) { - return; - } - OWED.store(true, Ordering::Relaxed); - crate::arch::irqchip::send_self(crate::arch::trap::LOG_NEST_VECTOR); - for _ in 0..WINDOW { - core::hint::spin_loop(); - } - } - - /// Emits exactly one shard generation — the count that reads the outer record's disappearance as drop-oldest, not corruption. - pub fn deliver() { - if !OWED.swap(false, Ordering::Relaxed) { - return; - } - for index in 0..SHARD_RECORDS as u64 { - crate::log::storm::emit_patterned(super::NEST_PRODUCER, index); - } - } -} - -/// Arms the injection on a dedicated kernel thread, once; compiled only under `boot-actuators`. -#[cfg(feature = "boot-actuators")] -pub fn start_once() { - #[cfg(feature = "boot-actuators")] - armed::start_once(); -} - -/// Consumes the one-shot at the reservation, for `log-shared-reservation`; `true` if an IPI went out. -pub fn inject() -> bool { - #[cfg(feature = "boot-actuators")] - return armed::inject(); - #[cfg(not(feature = "boot-actuators"))] - false -} - -/// Injection point halfway through a record's body copy; always compiled so `kernel-loom`'s separate copy of `log::shard` names one path. -pub fn mid_body() { - #[cfg(feature = "boot-actuators")] - armed::mid_body(); -} - -/// Injection point between a record's shard-pointer read and its `xadd`; called only from `arch::percpu::reserve_log_slot`. -pub fn reserve_window() { - #[cfg(feature = "boot-actuators")] - armed::reserve_window(); -} - -/// The `log_nest` interrupt handler's body; no shipping kernel installs that handler. -#[cfg(feature = "boot-actuators")] -pub fn deliver() { - #[cfg(feature = "boot-actuators")] - armed::deliver(); -} diff --git a/kernel/src/log/shard.rs b/kernel/src/log/shard.rs index 140f2ef8441..4d800c58890 100644 --- a/kernel/src/log/shard.rs +++ b/kernel/src/log/shard.rs @@ -181,10 +181,6 @@ impl Shard { } let words = msg_words(len); for i in 0..words { - // Injection point for `log-nested-emit`'s test IPI; folds away outside `kernel-loom`'s shim. - if i * 2 == words && crate::actuator::log_nested_emit() { - super::nested::mid_body(); - } let mut bytes = [0u8; 8]; bytes.copy_from_slice(&record.msg[i * 8..i * 8 + 8]); slot.body[HEADER_WORDS + i].store(u64::from_le_bytes(bytes), Ordering::Relaxed); diff --git a/kernel/src/log/storm.rs b/kernel/src/log/storm.rs deleted file mode 100644 index a237a19de9e..00000000000 --- a/kernel/src/log/storm.rs +++ /dev/null @@ -1,62 +0,0 @@ -//! Generates patterned records so the log gate's reader can check a conservation law over them. - -use core::sync::atomic::{AtomicBool, Ordering}; - -use crate::sched::kthread; - -// Exceeds a shard's capacity, so the drop path under test is reached at every `--smp` count. -const STORM_RECORDS: u64 = 1024; - -// Must exceed one machine word: a single-store payload couldn't reveal a torn write. -const PAYLOAD: usize = 96; - -/// Deterministic checksum of `thread` and `index`, embedded in a record's `k=` field. -pub fn checksum(thread: u64, index: u64) -> u64 { - (thread.wrapping_mul(0x9E37_79B9_7F4A_7C15) ^ index.wrapping_mul(0xC2B2_AE3D_27D4_EB4F)) - .rotate_left(17) -} - -/// One payload byte at `offset`, deterministic in `checksum`; always lowercase ASCII. -pub fn payload_byte(checksum: u64, offset: usize) -> u8 { - b'a' + (checksum.wrapping_add(offset as u64) % 26) as u8 -} - -/// One patterned record for `thread`/`index`; also called by `log-nested-reserve` from an interrupt handler. -/// The reader regenerates this text independently from `t=`/`i=`, so the format here must stay in sync with it. -pub fn emit_patterned(thread: u64, index: u64) { - let checksum = checksum(thread, index); - let mut payload = [0u8; PAYLOAD]; - for (offset, byte) in payload.iter_mut().enumerate() { - *byte = payload_byte(checksum, offset); - } - // Fallback rather than `expect`: a panic here would halt the machine over the producer's own formatting. - let payload = core::str::from_utf8(&payload).unwrap_or(""); - crate::log!("logstorm t={thread} i={index} k={checksum:016x} {payload}"); -} - -static STARTED: AtomicBool = AtomicBool::new(false); - -/// Spawns one storm thread per shard, once for the life of the machine. -/// Called from `SYS_LOG_READ`, which is what makes the storm concurrent with a reader by construction. -pub fn start_once() { - if STARTED.swap(true, Ordering::Relaxed) { - return; - } - let threads = super::shard_count(); - // The reader parses this line to learn the storm's shape. - crate::log!("logstorm start threads={threads} records={STORM_RECORDS}"); - for thread in 0..threads { - kthread::spawn("logstorm", body, thread as u64); - } -} - -extern "C" fn body(thread: u64) -> ! { - for index in 0..STORM_RECORDS { - emit_patterned(thread, index); - } - // The reader decides from its own cursor rather than waiting on this record: a barrier here was tried and hung at scale. - crate::log!("logstorm done t={thread} emitted={STORM_RECORDS}"); - - // Parks rather than exits: kthread rows are never removed, and spinning here would compete with the reader for the rest of the boot. - crate::watch::park_forever(); -} diff --git a/kernel/src/log/user.rs b/kernel/src/log/user.rs index 67f6cb6e8db..0d0c0a6ac5f 100644 --- a/kernel/src/log/user.rs +++ b/kernel/src/log/user.rs @@ -46,17 +46,6 @@ pub fn read( out: &mut UserBytesMut, capacity: usize, ) -> Result { - // Started on first read, not at boot: an unread storm has already spent itself before a cursor exists to notice it. - #[cfg(feature = "boot-actuators")] - if crate::actuator::log_storm() { - super::storm::start_once(); - } - // Armed here too, once: one thread serves both injection windows; `log::nested` picks the target from whichever actuators are armed. - #[cfg(feature = "boot-actuators")] - if crate::actuator::log_nested_emit() || crate::actuator::log_nested_reserve() { - super::nested::start_once(); - } - let shards = super::shard_count(); // Refused, not truncated: a capacity below one record per shard cannot hold what a single call may have to merge. if capacity == 0 || capacity < shards as usize { diff --git a/kernel/src/sched/kthread.rs b/kernel/src/sched/kthread.rs index decb64376a3..baa4c07fd61 100644 --- a/kernel/src/sched/kthread.rs +++ b/kernel/src/sched/kthread.rs @@ -18,11 +18,8 @@ use crate::sync::Lock; use super::payload::ThreadSched; -/// `klogd` and `iod`, plus one `log-storm` thread per shard in the actuator build. -#[cfg(not(feature = "boot-actuators"))] +/// `klogd` and `iod`. const MAX_KERNEL_TASKS: usize = 2; -#[cfg(feature = "boot-actuators")] -const MAX_KERNEL_TASKS: usize = 2 + toyos_abi::log::MAX_LOG_SHARDS; /// Collides with no packed id: neither id map issues `u32::MAX`. const NO_TASK: u64 = u64::MAX; diff --git a/kernel/src/watch.rs b/kernel/src/watch.rs index 718a8c6a5ce..f8bf0aee262 100644 --- a/kernel/src/watch.rs +++ b/kernel/src/watch.rs @@ -266,18 +266,6 @@ pub fn wait_uncancellable_until(p: &Parkable, watch: &Watch, token: u64, ready: } } -/// Parks forever rather than exiting: exiting frees a stack a producer may still write to. -#[cfg(feature = "boot-actuators")] -#[track_caller] -pub fn park_forever() -> ! { - let parkable = crate::scheduler::Parkable::at_entry(); - let handle = crate::sched::driver::current_handle().expect("a kernel thread is a task"); - let armed = arm(handle.watch(), 0, WaitClass::Other).expect("a task can arm"); - loop { - let _ = wait(&parkable, &armed, Deadline::never()); - } -} - #[track_caller] fn wait_inner( _p: &Parkable, diff --git a/src/build.rs b/src/build.rs index c5b98186a8b..20447e09511 100644 --- a/src/build.rs +++ b/src/build.rs @@ -2534,7 +2534,7 @@ mod tests { fn the_pre_flash_gate_clears_a_valued_parameter_and_refuses_an_actuator() { let root = Path::new(env!("CARGO_MANIFEST_DIR")); assert_eq!(flashable_params(root, &[format!("{}0x1000", toyos_blackbox::PARAM)]), Ok(())); - assert!(flashable_params(root, &["log-storm".to_string()]).is_err()); + assert!(flashable_params(root, &["wedge-before-reset".to_string()]).is_err()); } #[test] diff --git a/tests/common/logread.rs b/tests/common/logread.rs index e438887b250..3085c10a548 100644 --- a/tests/common/logread.rs +++ b/tests/common/logread.rs @@ -1,284 +1,15 @@ -//! `SYS_LOG_READ`, read from inside `test-runner` under a storm. -//! -//! **The verdict is computed in the guest and asserted here.** What the host -//! can see of a conservation law is a line saying it held; what it can check is -//! that the line is there, that the run was not vacuous, and that the numbers -//! the guest printed describe the machine the host booted. So the guest prints -//! its ledger and this file reads it — `log-gate: OK` is the verdict, and every -//! number beside it is evidence a reviewer can weigh. -//! -//! The gate runs *inside* `test-runner` rather than in a binary it spawns: -//! `logread` is a `SysCap` dup and not a namespace entry, so it is not part of -//! what the runner hands its children. +//! `SYS_LOG_READ`'s readiness source, probed against a handle close. -use std::collections::BTreeMap; use std::path::Path; use std::time::Duration; use super::qemu::{BootOptions, QemuInstance}; -/// The in-guest gate's name in the `run ` protocol. It is a `test-runner` -/// builtin rather than a `/system/bin` entry, and the marker protocol is the same -/// either way. -const GATE: &str = "log-gate"; - /// The whole run's ceiling. A liveness guard and never a verdict: the guest has /// a ceiling of its own and reports what it had when it gave up, so this only /// catches a guest that stopped answering at all. const CEILING: Duration = Duration::from_secs(60); -/// One boot's storm, as the guest reported it. -struct Report { - stdout: String, - fields: BTreeMap, -} - -impl Report { - fn get(&self, key: &str) -> Result { - self.fields - .get(key) - .copied() - .ok_or_else(|| format!("the guest's report has no `{key}=`:\n{}", self.stdout)) - } -} - -/// A name two of the guest's lines both defined. -/// -/// **Not a merge, because the two lines are different subjects.** The guest -/// prints its ledger over several `log-gate:` lines and this file reads them -/// into one map, so a name appearing twice means the number a test asserts on -/// came from whichever line was printed last — silently, and with the other -/// line still on screen looking like the evidence. The nest and storm lines -/// already share `read=` and `dropped=`, and every gate here reads exactly one -/// of the two. -struct Contaminated { - key: String, - first: u64, - second: u64, -} - -/// The conservation law, at one width. -fn conservation( - test_config: &Path, - c_bins: &[(String, Vec)], - rust_bins: &[(String, Vec)], - smp: u32, -) -> Result<(), String> { - let report = storm(test_config, c_bins, rust_bins, smp, &["log-storm"])?; - let shards = report.get("shards")?; - if shards != smp as u64 { - return Err(format!( - "--smp {smp} answered {shards} shard(s); the cursor's shard count is the machine's \ - CPU count\n{}", - report.stdout - )); - } - // Non-vacuity, and it is the half a green law cannot supply: a reader that - // took every record after the storm had ended has proved nothing about - // concurrent producers. - let concurrent = report.get("concurrent")?; - let dropped = report.get("dropped")?; - let read = report.get("read")?; - if concurrent == 0 || read == 0 { - return Err(format!( - "--smp {smp} read {read} record(s), {concurrent} of them while the storm ran\n{}", - report.stdout - )); - } - eprintln!( - " [log] smp={smp}: emitted={} read={read} dropped={dropped} concurrent={concurrent} \ - lost={} wakes={}", - report.get("emitted")?, - report.get("lost")?, - report.get("wakes")?, - ); - Ok(()) -} - -pub fn log_conservation_smp1( - test_config: &Path, - c_bins: &[(String, Vec)], - rust_bins: &[(String, Vec)], -) -> Result<(), String> { - conservation(test_config, c_bins, rust_bins, 1) -} - -/// The nested-`emit` gate: an interrupt that logs, inside another `emit`, on one CPU. -/// -/// **The one case loom cannot express and the host cannot stage.** The -/// stimulus is a self-IPI sent from inside a record's own body copy, on a -/// kernel thread — where `IF` is set and `emit`'s IF-off bracket is the only thing -/// holding the interrupt off. The handler emits exactly one shard generation of -/// patterned records; the outer record is then dropped by the ring's own -/// drop-oldest policy, which is what makes "the burst laps the shard" a -/// statement with an arithmetic behind it. -/// -/// What is asserted is the conservation ledger over a workload of that shape: every -/// sequence number read or counted lost, every burst record's text regenerated -/// byte for byte from the two numbers it declares, and the burst's own `done` -/// read — so a run in which nothing was injected cannot pass quietly. -/// -/// **`--smp 1`, and that is the test's own claim.** Nesting is a property of -/// one CPU: a second CPU adds records to the merge and takes nothing away from -/// what this asks, while at one the interrupted writer and its interrupting -/// handler are provably the same CPU. -pub fn log_nested_emit( - test_config: &Path, - c_bins: &[(String, Vec)], - rust_bins: &[(String, Vec)], -) -> Result<(), String> { - let report = storm(test_config, c_bins, rust_bins, 1, &["log-nested-emit"])?; - let declared = report.get("declared")?; - let read = report.get("read")?; - if read == 0 { - return Err(format!("the burst was declared and none of it read\n{}", report.stdout)); - } - eprintln!( - " [log] nested: burst declared={declared} read={read} dropped={}", - report.get("dropped")? - ); - Ok(()) -} - -/// The reserve bracket at the window it names first: an interrupt that logs, -/// landing between a record's shard-pointer read and its unlocked `xadd`. -/// -/// **The property is that a shard has one order and not two.** `emit` reads the -/// clock and takes its sequence number inside one IF-off bracket, and every -/// reader in the tree rests on the two being the same order — `read.rs`'s -/// `Descent::advance` stops a shard's descent on the first record older than the -/// window it was asked for, which is only sound while a lower sequence number -/// cannot carry a later timestamp. `log-nested-reserve` puts an interrupt that -/// logs into exactly that window: with the bracket the IPI is pending until the -/// guard drops and the handler's whole burst is reserved *after* the record it -/// interrupted, and without it the burst is reserved *before*. -/// -/// **`--smp 8`, and no storm beside it.** Eight shards is where the merge across -/// shards has to keep each shard's own order while interleaving eight of them; -/// a storm on the injected CPU would lap the interrupted record before the -/// reader reached it, which is the one record the verdict is about. -pub fn log_reserve_window( - test_config: &Path, - c_bins: &[(String, Vec)], - rust_bins: &[(String, Vec)], -) -> Result<(), String> { - let report = storm(test_config, c_bins, rust_bins, 8, &["log-nested-reserve"])?; - let declared = report.get("declared")?; - let read = report.get("read")?; - let dropped = report.get("dropped")?; - let shards = report.get("shards")?; - if shards != 8 { - return Err(format!( - "--smp 8 answered {shards} shard(s); the cursor's shard count is the machine's CPU \ - count\n{}", - report.stdout - )); - } - if read == 0 { - return Err(format!( - "the reservation-window burst was declared and none of it read, so nothing was \ - injected into anything\n{}", - report.stdout - )); - } - // **The derivation, and it is exact rather than a bound.** With the bracket - // the IPI is pending across the whole publication, so the interrupted - // producer's own record takes `S` and the handler's burst takes - // `S+1 ..= S+BURST` after it, with `lognest done` at `S+BURST+1`. `head` is - // then `S+BURST+2` and `oldest_readable` is `head - BURST`, which is `S+2` — - // so the reader can never answer for the outer record or for the burst's - // first, and can answer for every one of the other `BURST-1`. Measured - // `read=511 dropped=1` in eight of eight boots on the dev host, 2026-08-22. - if declared != BURST || read != BURST - 1 || dropped != 1 { - return Err(format!( - "the burst declared {declared} record(s), this reader took {read} and lost \ - {dropped}: one shard generation is {BURST}, and the ring's own drop-oldest policy \ - puts exactly the burst's first record below `oldest_readable` and nothing else\n{}", - report.stdout - )); - } - eprintln!( - " [log] reserve window: burst declared={declared} read={read} dropped={dropped} \ - shards={shards}" - ); - Ok(()) -} - -/// `kernel/src/log/shard.rs`'s `SHARD_RECORDS`, which is how many records -/// `log::nested`'s handler emits: exactly one shard generation. -const BURST: u64 = 512; - -/// The negative control on [`log_reserve_window`], and on `arch::IrqGuard` -/// itself: the same boot with the reserve bracket removed. -/// -/// **The one thing that can make the log's correctness claim fail on purpose.** -/// `log-unbracketed-reserve` leaves the guard constructed and dropped exactly as -/// it is and masks nothing, so the self-IPI is delivered where it was sent — -/// inside the reservation window — and the handler's `SHARD_RECORDS` records -/// take the sequence numbers below the one the interrupted producer goes on to -/// take, while carrying timestamps above all of its. The gate must then refuse -/// the shard, by name, and the assertion here is that refusal and not merely a -/// non-zero exit: a boot that failed for any other reason has not read this -/// actuator. -/// -/// **The failure is derived, not sampled.** The burst is exactly [`BURST`] -/// records reserved back to back on one shard, so the interrupted record's own -/// number is exactly [`BURST`] above the burst's first while its `at_ns` was -/// stamped before any of them; the reader walks a shard in sequence order, so it -/// meets the inversion at that record on its first pass over the shard, on every -/// boot. Measured on the dev host 2026-08-22, eight of eight: the refusal names -/// `seq 517` in six boots, 518 in one and 665 in one — 517 is 5 + 512, cpu7's -/// shard having held four boot records before the injection. -pub fn log_reserve_window_negative( - test_config: &Path, - c_bins: &[(String, Vec)], - rust_bins: &[(String, Vec)], -) -> Result<(), String> { - let mut qemu = QemuInstance::boot_with_options( - test_config, - c_bins, - rust_bins, - BootOptions { - smp: 8, - kernel_params: &["log-nested-reserve", "log-unbracketed-reserve"], - ..Default::default() - }, - ); - let result = qemu.run_test(GATE, CEILING); - if let Some(err) = &result.error { - return Err(format!( - "the unbracketed boot never reported: {err}\nstdout:\n{}\nserial tail:\n{}", - result.stdout, - tail(&result.serial) - )); - } - if result.exit_code == Some(0) || result.stdout.contains("log-gate: OK") { - return Err(format!( - "the bracket was removed and the log gate passed anyway ({:?}), so the guard's `cli` \ - is still measured by nothing\n{}", - result.exit_code, result.stdout - )); - } - let refusal = result - .stdout - .lines() - .find(|l| l.contains(INVERSION)) - .ok_or_else(|| { - format!( - "the unbracketed boot failed for some other reason than the one this control \ - stages — no line said `{INVERSION}`\n{}", - result.stdout - ) - })?; - eprintln!(" [log] unbracketed: {}", refusal.trim()); - Ok(()) -} - -/// The clause `userland/test-runner/src/log_gate.rs` refuses a descending -/// `at_ns` with. Two copies of one sentence, and this file is the one that -/// would notice if the other changed. -const INVERSION: &str = "within a shard the sequence order is the timestamp order"; - /// A pending poll on the machine's log is not something a handle closing /// can cancel. /// @@ -334,114 +65,3 @@ fn close_probe( eprintln!(" [log] {}", survived.trim()); Ok(()) } - -/// Boot one machine with the storm armed and read the gate's verdict off it. -fn storm( - test_config: &Path, - c_bins: &[(String, Vec)], - rust_bins: &[(String, Vec)], - smp: u32, - params: &'static [&'static str], -) -> Result { - let mut qemu = QemuInstance::boot_with_options( - test_config, - c_bins, - rust_bins, - BootOptions { smp, kernel_params: params, ..Default::default() }, - ); - let result = qemu.run_test(GATE, CEILING); - if let Some(err) = &result.error { - return Err(format!( - "--smp {smp} {params:?}: {err}\nstdout:\n{}\nserial tail:\n{}", - result.stdout, - tail(&result.serial) - )); - } - match result.exit_code { - Some(0) => {} - Some(code) => { - return Err(format!( - "--smp {smp} {params:?}: the log gate exited {code}\n{}", - result.stdout - )) - } - None => { - return Err(format!("--smp {smp} {params:?}: no exit code\n{}", result.stdout)) - } - } - if !result.stdout.contains("log-gate: OK") { - return Err(format!( - "--smp {smp} {params:?}: the gate exited 0 without saying so\n{}", - result.stdout - )); - } - let fields = fields(&result.stdout).map_err(|c| { - format!( - "--smp {smp} {params:?}: two of the guest's `log-gate:` lines define `{}` ({} and \ - {}), so every number read out of this report is whichever line came last\n{}", - c.key, c.first, c.second, result.stdout - ) - })?; - Ok(Report { fields, stdout: result.stdout }) -} - -/// Every `key=` the guest printed, and the two counts it prints as -/// prose. One parse, so a test asserts on a name rather than on a column. -/// -/// **A name defined twice is refused rather than merged.** The guest's report is -/// several lines about different subjects, and flattening them means a repeated -/// name silently resolves to the last line printed — with the other line still -/// in the failure message, looking like the evidence. Refusing is what makes the -/// flattening safe: it holds exactly while the names really are unique. -fn fields(stdout: &str) -> Result, Contaminated> { - fn put( - out: &mut BTreeMap, - key: &str, - value: u64, - ) -> Result<(), Contaminated> { - match out.insert(key.to_string(), value) { - None => Ok(()), - Some(first) => Err(Contaminated { key: key.to_string(), first, second: value }), - } - } - - let mut out: BTreeMap = BTreeMap::new(); - for line in stdout.lines() { - let Some(rest) = line.split_once("log-gate: ").map(|(_, r)| r) else { continue }; - for word in rest.split_whitespace() { - let Some((key, value)) = word.split_once('=') else { continue }; - // `migrated=3/8` is two numbers: the second is the producer count, - // which the migration gate reports beside it. - let (value, producers) = match value.split_once('/') { - Some((a, b)) => (a, b.trim_end_matches(&[',', ';'][..]).parse::().ok()), - None => (value, None), - }; - if let Ok(n) = value.trim_end_matches(&[',', ';'][..]).parse::() { - put(&mut out, key, n)?; - } - if let Some(n) = producers { - put(&mut out, "producers", n)?; - } - } - // "N record(s) over M read(s) from S shard(s)" — the shape of the line - // rather than a key, because those three are what the sentence is. - let words: Vec<&str> = rest.split_whitespace().collect(); - for pair in words.windows(2) { - let Ok(n) = pair[0].parse::() else { continue }; - match pair[1] { - "record(s)" => put(&mut out, "records", n)?, - "read(s)" => put(&mut out, "reads", n)?, - "shard(s);" | "shard(s)" => put(&mut out, "shards", n)?, - _ => {} - } - } - } - Ok(out) -} - -/// The last of a capture, for a failure message. A storm puts thousands of -/// lines on the console and the interesting end is the recent one. -fn tail(serial: &str) -> String { - let lines: Vec<&str> = serial.lines().collect(); - lines[lines.len().saturating_sub(40)..].join("\n") -} diff --git a/tests/test-durations b/tests/test-durations index c32248eab77..af9755f3ce1 100644 --- a/tests/test-durations +++ b/tests/test-durations @@ -255,14 +255,10 @@ loader_watchdog_arms 10064 locale_detect 9959 locale_detect_unrecognized 160 log_backing_read_error 4887 -log_conservation_smp1 4686 log_flush_retry 20526 -log_nested_emit 5008 log_partition_identity 9516 log_partition_layout 477 log_poll_outlives_a_close 4738 -log_reserve_window 7022 -log_reserve_window_negative 6791 log_stream 24865 log_stream_e1000e 25219 log_stream_no_listener 25182 diff --git a/tests/toyos.rs b/tests/toyos.rs index ff90ef5aae8..7cfde4e6b22 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -1169,23 +1169,6 @@ const MACHINE_TESTS: &[(&str, Sched, Tier)] = &[ // never classified. Same boot shape as its two neighbours — dies inside the // boot phases at the marker, no userland — so Parallel. ("nested_fault_is_recursive", Sched::Parallel, Tier::Weekly), - // The conservation law across `SYS_LOG_READ`, and the nesting gate at one - // CPU. Parallel: every verdict is a ledger the - // guest computes over its own records — every sequence number read or - // counted lost, every payload regenerated byte for byte — and not one of - // them reads a clock. A loaded host makes the producers outrun the reader - // further, which moves records from `read` into `lost` and leaves the law - // exactly where it was. - ("log_conservation_smp1", Sched::Parallel, Tier::Weekly), - ("log_nested_emit", Sched::Parallel, Tier::Weekly), - // The same interrupt one window earlier — between a record's shard-pointer - // read and its `xadd` — and its negative control, which is the only reader - // `log-unbracketed-reserve` has ever had. Parallel for - // `log_nested_emit`'s reasons: both verdicts are the guest's ledger over its - // own records, one saying the shard kept a single order and the other that - // it lost it by name, and no clock is in either. - ("log_reserve_window", Sched::Parallel, Tier::Weekly), - ("log_reserve_window_negative", Sched::Parallel, Tier::Weekly), // A guest writes a daemon-shaped line into a real capture window on purpose // and the real comparison ignores it, with the filter turned off as the // control. One boot, two `echo`s, and every verdict is a string comparison @@ -11664,16 +11647,6 @@ fn run_machine_test( // Body in `tests/common/iommu.rs`, same reason. "iommu_discovery" => common::iommu::iommu_discovery(test_config, c_bins, rust_bins), // Body in `tests/common/logread.rs`, so the hunk here stays one line. - "log_conservation_smp1" => { - common::logread::log_conservation_smp1(test_config, c_bins, rust_bins) - } - "log_nested_emit" => common::logread::log_nested_emit(test_config, c_bins, rust_bins), - "log_reserve_window" => { - common::logread::log_reserve_window(test_config, c_bins, rust_bins) - } - "log_reserve_window_negative" => { - common::logread::log_reserve_window_negative(test_config, c_bins, rust_bins) - } "log_poll_outlives_a_close" => { common::logread::log_poll_outlives_a_close(test_config, c_bins, rust_bins) } diff --git a/userland/test-runner/src/log_close.rs b/userland/test-runner/src/log_close.rs index 3bebf8ce14b..939113d3a31 100644 --- a/userland/test-runner/src/log_close.rs +++ b/userland/test-runner/src/log_close.rs @@ -17,8 +17,8 @@ //! `cancel_by_source` acted on. What it proves is that the *handle* is not what the //! source's lifetime is tied to. //! -//! It runs inside `test-runner` for `log-gate`'s reason — a `SysCap` dup is not -//! a namespace entry, so a spawned binary has none — and it needs `dup` in its +//! It runs inside `test-runner` because a `SysCap` dup is not a namespace +//! entry, so a spawned binary has none — and it needs `dup` in its //! manifest row on top of `logread`, which `tests/testcases/system.toml` has. use std::process::Command; diff --git a/userland/test-runner/src/log_gate.rs b/userland/test-runner/src/log_gate.rs deleted file mode 100644 index 3f6145111c5..00000000000 --- a/userland/test-runner/src/log_gate.rs +++ /dev/null @@ -1,777 +0,0 @@ -//! The conservation law, read through `SYS_LOG_READ` from inside `test-runner`. -//! -//! **It runs here rather than in a binary of its own, and that is capability -//! doctrine rather than convenience.** `test-runner` passes its whole -//! *namespace* to every binary it spawns, and `logread` is not a namespace -//! entry — it is a `SysCap` dup, exactly like `realtime`, which the estate does -//! not hand down either. So the gate that reads the machine's log is the one -//! process in a test image that holds the right from its own manifest row. -//! -//! **The verdict is exact, not statistical.** Every sequence number a shard -//! ever issued is either a record this reader took or one the kernel counted as -//! lost; no number is taken twice; and every storm record's text regenerates -//! byte for byte from the two numbers it declares. A torn record fails the -//! text, a lost record that is not counted fails the ledger, and a duplicated -//! one fails it the other way. -//! -//! **Nothing this reader waits for is a record the ring may drop.** It used to -//! read until every producer had said `logstorm done`, and that record is the -//! last thing one producer writes rather than the last thing written to its -//! shard: two producers placed on one CPU means the second's records lap the -//! first's `done`, and the loop then waited for something that was never -//! coming — twice in seven suites on the dev host, each time the whole 30 s -//! ceiling in the fast tier. So the termination condition is the *cursor*: the -//! log has been drained and nothing new has arrived for [`QUIET_READS`] reads -//! and [`STORM_SETTLE`] of guest time. A `done` is a cross-check where it -//! survived and is never waited on, and the same holds of `logstorm start` and -//! of the nesting burst's own `done`. **The rule this shape exists to keep is -//! general**: a workload whose liveness depends on a record the ring is allowed -//! to drop is the same mistake wherever it appears. - -use std::collections::BTreeMap; -use std::time::{Duration, Instant}; - -use toyos::log::{LogTail, Record, MAX_LOG_SHARDS}; -use toyos::poller::{Poller, READABLE}; -use toyos::syscap::SysCap; - -/// The first sequence number any shard issues — one, so a slot nothing has ever -/// written cannot read as record 0 of every shard on every boot. -/// `kernel/src/log/shard.rs`'s `FIRST_SEQ` is the other half of this constant. -const FIRST_SEQ: u64 = 1; - -/// Records per `SYS_LOG_READ`. Above the shard count, which the call refuses -/// below, and far under a storm's rate — so the reader really is outrun and the -/// loss path is reached rather than assumed. -const BATCH: usize = 64; - -/// How long the whole gate may take before it gives up on a workload that never -/// finished, and it reports what it had when it did. -/// -/// **A liveness guard and never a verdict**, and it is what a shard stalled on -/// an uncommitted slot looks like from here: `drain_ordered` blocks a shard at -/// its first uncommitted record, so a writer that never publishes takes that -/// shard out of the merge for good. A green run is under a second of guest -/// time at every width this gate is booted at. -/// -/// **It is the guest's own ceiling and it is the smaller of the two**: the host -/// gives the whole boot 60 s (`tests/common/logread.rs`), so what a hung gate -/// reports is this one's message and this one's elapsed time. Nothing in the -/// loop below waits on a record any more, so reaching it now means the kernel -/// stopped answering rather than that a record went missing. -const CEILING: Duration = Duration::from_secs(30); - -/// Empty reads in a row before the log is called quiet. -/// -/// **Eight, each after a bounded park on the readiness source**, because a -/// single empty read can land while a producer is inside its publication -/// bracket: `drain_ordered` stops that shard and says nothing about it, so a -/// ledger closed on the first empty read can be short by what was in flight. -/// -/// **It is the whole termination condition now**, so what it costs when it is -/// wrong is worth stating: a quiet run that lands mid-storm ends the read early -/// and the verdict is computed over less of the workload. It cannot make the -/// verdict *wrong* — the conservation law is over the sequence numbers this -/// reader took and the loss the kernel counted for the same cursor, and both -/// are a consistent snapshot at any point — and the non-vacuity clauses in -/// [`verdict`] are what refuse a run that raced nothing. [`STORM_SETTLE`] is -/// what makes an early end implausible rather than merely unlikely. -const QUIET_READS: u32 = 8; - -/// How long after the last producer record the log must stay quiet before a -/// storm counts as finished. -/// -/// Eight empty reads are sixteen milliseconds of parks, and a producer stalled -/// inside its publication bracket for that long — a vCPU that the host has not -/// scheduled, which is the twelve-wide suite's ordinary state — takes its shard -/// out of the merge and can leave every other shard drained. A hundred -/// milliseconds of *guest* time on top costs one tenth of a second on three -/// boots and buys an order of magnitude on that window. It is armed only once a -/// producer's record has been seen, so an ordinary boot's gate ends on the -/// quiet reads alone. -const STORM_SETTLE: Duration = Duration::from_millis(100); - -/// How long a park on the log's readiness source waits before giving up on it. -/// -/// It is the gate's pacing as much as its wait: with nothing left to say the -/// kernel posts nothing, and eight of these is the whole tail of the run. -const IDLE_NANOS: u64 = 2_000_000; - -/// How long the deterministic readiness round waits for its own record. -/// -/// Generous, because what it bounds is a scheduler getting round to a child's -/// exit on a machine that has just run a storm on every CPU — not the post, -/// which is one function call after the drain. A gate that timed out here would -/// be reporting the host's load and not the kernel's. -const READINESS_WAIT_NANOS: u64 = 2_000_000_000; - -/// The poll's token. One handle is watched, so it identifies the round rather -/// than the source. -const LOG_TOKEN: u64 = 1; - -/// `kernel/src/log/storm.rs`'s `PAYLOAD`. -const PAYLOAD: usize = 96; - -/// `kernel/src/log/nested.rs`'s `NEST_PRODUCER`: the burst an interrupt handler -/// emits declares itself as this, so it goes through the same per-producer -/// ledger and the same byte-for-byte regeneration as a storm's records. -const NEST_PRODUCER: u64 = u64::MAX; - - -/// One storm producer's ledger. -#[derive(Default)] -struct Producer { - /// The next index expected from this thread, and `None` before its first - /// record. - next: Option, - read: u64, - /// What its own `done` record declared, once seen. - emitted: Option, - /// Shards this producer's records were found on. **More than one is a - /// producer that migrated mid-storm**, and on this kernel that is zero of - /// them and always will be: nothing switches a Ring 0 context out between - /// two instructions, so a producer cannot be moved off its CPU inside the - /// reservation window - /// (`kernel/src/log/storm.rs`'s header carries the measurement). It is - /// reported and asserted on by nothing, which is the honest shape for a - /// count whose only interesting value is unreachable. - shards: u32, - shard_mask: u32, -} - -impl Producer { - fn mark_shard(&mut self, cpu: u16) { - let bit = 1u32 << (cpu as u32 % 32); - if self.shard_mask & bit == 0 { - self.shard_mask |= bit; - self.shards += 1; - } - } -} - -/// One shard's ledger: the sequence numbers the kernel issued on that CPU. -#[derive(Default, Clone, Copy)] -struct ShardLedger { - first: Option, - next: u64, - read: u64, - /// Sequence numbers this reader never saw, derived from the gaps between - /// the ones it did. - gaps: u64, - last_at_ns: u64, -} - -pub fn run(cap: Option<&SysCap>) -> i32 { - let Some(cap) = cap else { - println!("log-gate: this program holds no system capability, so it holds no `logread`"); - return 1; - }; - match gate(cap) { - Ok(()) => 0, - Err(e) => { - println!("log-gate: FAILED: {e}"); - 1 - } - } -} - -struct Run { - shards: [ShardLedger; MAX_LOG_SHARDS], - producers: BTreeMap, - /// Producers this machine's storm has, once one of its records has been - /// seen. **Derived from the shard count rather than from an announcement**: - /// the storm starts inside the reader's own first `SYS_LOG_READ` and can - /// lap a shard before that call returns, so its opening line is a record - /// like any other and may be dropped. One thread per shard is what - /// `log::storm::start_once` spawns, and the cursor is what says how many - /// shards there are. - storm: Option, - /// What `logstorm start` or a producer's `done` declared, where one of - /// those records survived. They must agree. **A cross-check and never a - /// requirement**: both kinds are records like any other and the ring is - /// allowed to drop either, so [`verdict`] derives the count from the - /// highest index any producer reached when neither arrives. - declared: Option, - /// The nesting gate's declared burst, once its `done` has been read. Read - /// the same way, for the same reason. - nest: Option, - records: u64, - reads: u64, - /// Producer records — a storm's or the nesting burst's — this reader took. - producer_records: u64, - /// Producer records read **strictly before the last batch that carried - /// one**, which is exactly "records this reader took while the producers - /// were still emitting": a later batch carrying a producer record proves - /// the workload had not finished when this one was read. **Zero would mean - /// this reader raced nothing**, which is the one way a green conservation - /// law says nothing at all. - /// - /// It needs no `done` and no clock, only the order of the batches. - concurrent: u64, - /// When the last batch carrying a producer record was read. `None` until - /// one is, which is what leaves an ordinary boot's gate on the quiet reads - /// alone. - last_producer_at: Option, - /// Times the log's readiness source completed a poll. - completions: u64, -} - -fn gate(cap: &SysCap) -> Result<(), String> { - let mut tail = LogTail::new(); - let mut buf = [Record::EMPTY; BATCH]; - let mut run = Run { - shards: [ShardLedger::default(); MAX_LOG_SHARDS], - producers: BTreeMap::new(), - storm: None, - declared: None, - nest: None, - records: 0, - reads: 0, - producer_records: 0, - concurrent: 0, - last_producer_at: None, - completions: 0, - }; - - // **Armed before the first read and kept armed**, which is what makes a - // completion deterministic rather than lucky: the first read is what starts - // the storm, so the records that answer this poll are committed after it was - // registered, and re-arming after every harvest means a post landing *during* - // the storm finds a pending poll rather than a gap. - // - // **It used to arm only on an empty read, and that made the assertion - // depend on the shape of the boot.** During a storm no read is empty, so the - // only poll in flight was the one from before the first read; whether it was - // ever completed came down to when `klogd` happened to get a turn. At - // `--smp 4` that measured `wakes=1`, and at `--smp 8` with `/system/bin/logd` also - // reading the cursor it measured **zero** — a red about scheduling rather - // than about the readiness source. `min_complete` 0 with no timeout submits - // and harvests without blocking, so this costs one syscall a round. - let poller = Poller::new(1); - let mut armed = false; - - let mut quiet = 0u32; - let started = Instant::now(); - loop { - if !armed { - poller.watch(cap, READABLE, LOG_TOKEN); - armed = true; - } - poller.wait(0, 0, |token| { - assert_eq!(token, LOG_TOKEN, "the log poll completed with another token"); - run.completions += 1; - armed = false; - }); - - let batch = tail - .read(cap, &mut buf) - .map_err(|e| format!("SYS_LOG_READ refused a {BATCH}-record buffer: {e:?}"))?; - run.reads += 1; - if batch.is_empty() { - quiet += 1; - } else { - quiet = 0; - run.records += batch.len() as u64; - } - - // **The concurrency evidence, from the order of the batches alone.** - // Taken across the whole batch rather than per record: if this batch - // carried a producer record, then everything this reader had taken from - // a producer *before* it was taken while that producer was still - // emitting. The last such batch is what fixes the number, so it is - // assigned and not accumulated. - let producer_records_before = run.producer_records; - let shards = tail.shards(); - for record in batch { - account(record, &mut run, shards)?; - } - if run.producer_records > producer_records_before { - run.concurrent = producer_records_before; - run.last_producer_at = Some(Instant::now()); - } - - // **The cursor decides, not a record.** Caught up, quiet for - // `QUIET_READS` reads, and — once a producer has been seen — quiet for - // `STORM_SETTLE` of guest time as well. - let settled = run - .last_producer_at - .is_none_or(|at| at.elapsed() >= STORM_SETTLE); - if quiet >= QUIET_READS && settled { - break; - } - if started.elapsed() > CEILING { - return Err(format!( - "gave up after {:?}: {} records over {} reads, storm {:?}, {} producer record(s), \ - {} producer(s) done", - started.elapsed(), - run.records, - run.reads, - run.storm, - run.producer_records, - run.producers.values().filter(|p| p.emitted.is_some()).count(), - )); - } - if batch.is_empty() { - // **Nothing new, so park on the readiness source rather than spin.** - // `SYS_LOG_READ` never blocks by design; this is the other half of - // that design, and the timeout is what bounds a machine that has - // nothing left to say. The poll is already armed by the top of the - // loop, so this parks on it rather than adding a second. - poller.wait(1, IDLE_NANOS, |token| { - assert_eq!(token, LOG_TOKEN, "the log poll completed with another token"); - run.completions += 1; - armed = false; - }); - } - } - - // **The readiness source, observed deterministically rather than raced.** - // Every completion above is a `klogd` post landing while this poll happened - // to be pending, and during a storm that is a race against eight producers: - // it measured `wakes=1` at `--smp 4` and **zero** at `--smp 8` once - // `/system/bin/logd` was reading the cursor too, which is a red about - // scheduling. So if the storm produced none, make one — the shape - // `log_poll_outlives_a_close` already proves on this tree: a child that - // runs and exits commits `process.rs`'s `exit:` line, which is one kernel - // record from userland with no actuator and no privilege behind it. - if run.completions == 0 { - let mut child = std::process::Command::new("/system/bin/echo") - .arg("log-gate") - .spawn() - .map_err(|e| format!("the record-making child would not start: {e}"))?; - let _ = child.wait(); - if !armed { - poller.watch(cap, READABLE, LOG_TOKEN); - } - poller.wait(1, READINESS_WAIT_NANOS, |token| { - assert_eq!(token, LOG_TOKEN, "the log poll completed with another token"); - run.completions += 1; - }); - } - - verdict(&tail, &run) -} - -/// Put one record through both ledgers. -fn account(record: &Record, run: &mut Run, shards: u32) -> Result<(), String> { - let cpu = record.cpu as usize; - let ledger = run.shards.get_mut(cpu).ok_or_else(|| { - format!("a record claims cpu{cpu}, past the ABI's {MAX_LOG_SHARDS} shards") - })?; - - match ledger.first { - None => ledger.first = Some(record.seq), - Some(_) => { - if record.seq < ledger.next { - return Err(format!( - "cpu{cpu} answered seq {} after seq {}: a sequence number was read twice, \ - or out of order, within one shard", - record.seq, - ledger.next - 1 - )); - } - ledger.gaps += record.seq - ledger.next; - } - } - if record.at_ns < ledger.last_at_ns { - return Err(format!( - "cpu{cpu} seq {} is stamped {} ns, behind the {} ns of the record before it — within \ - a shard the sequence order is the timestamp order, and `emit` stamps inside the \ - same bracket it reserves in", - record.seq, record.at_ns, ledger.last_at_ns - )); - } - ledger.last_at_ns = record.at_ns; - ledger.next = record.seq + 1; - ledger.read += 1; - - let message = record.message(); - if message.len() != record.len as usize { - return Err(format!( - "cpu{cpu} seq {} declares {} message bytes and decodes to {}", - record.seq, - record.len, - message.len() - )); - } - - // **What the batch-boundary concurrency evidence counts.** Every record - // either of this machine's two workloads wrote, `start` and `done` records - // included: the question it answers is "had the producers finished when - // this batch was read", and a `done` is a producer still working as much as - // a patterned record is. - if message.starts_with("logstorm ") || message.starts_with("lognest ") { - run.producer_records += 1; - } - - if let Some(rest) = message.strip_prefix("lognest done ") { - let emitted = rest - .split_whitespace() - .find_map(|w| w.strip_prefix("emitted=")) - .and_then(|v| v.parse::().ok()) - .ok_or_else(|| format!("`lognest done` is unreadable: {rest}"))?; - if run.nest.replace(emitted).is_some() { - return Err("the nesting gate said `done` twice".into()); - } - return Ok(()); - } - if message.starts_with("lognest ") { - // `start` and `outer`. Both are records like any other and the burst - // laps the shard they are in, so both are *expected* to be dropped — - // which is the ring's declared policy and not a loss of evidence. - return Ok(()); - } - if let Some(rest) = message.strip_prefix("logstorm start ") { - // Informative and cross-checked where it survives; never depended on. - let (threads, records) = parse_start(rest)?; - if threads != shards { - return Err(format!( - "the storm declared {threads} producer(s) on a machine of {shards} shard(s)" - )); - } - run.storm = Some(shards); - run.declared.get_or_insert(records); - return Ok(()); - } - if let Some(rest) = message.strip_prefix("logstorm done ") { - let (thread, emitted) = parse_done(rest)?; - run.storm = Some(shards); - match run.declared { - None => run.declared = Some(emitted), - Some(declared) if declared != emitted => { - return Err(format!( - "producer t={thread} emitted {emitted} records where another \ - declared {declared}" - )) - } - Some(_) => {} - } - let producer = run.producers.entry(thread).or_default(); - producer.mark_shard(record.cpu); - if producer.emitted.replace(emitted).is_some() { - return Err(format!("producer t={thread} said `done` twice")); - } - return Ok(()); - } - let Some(rest) = message.strip_prefix("logstorm t=") else { - // An ordinary kernel record. It is in the shard ledger above, which is - // where the conservation law is computed; it declares nothing this gate - // could regenerate. - return Ok(()); - }; - - let (thread, index) = parse_record(rest)?; - let expected = storm_message(thread, index); - if message != expected { - return Err(format!( - "cpu{cpu} seq {} is a torn or mixed storm record\n read: {message}\n expected: {expected}", - record.seq - )); - } - // The nesting burst declares itself past every shard, so it is a producer - // for the ledger's purposes and never one the storm is waiting on. - if thread != NEST_PRODUCER { - run.storm = Some(shards); - } - let producer = run.producers.entry(thread).or_default(); - producer.mark_shard(record.cpu); - if let Some(next) = producer.next { - if index < next { - return Err(format!( - "producer t={thread} answered index {index} after {}: one record's body was \ - published under another record's sequence number", - next - 1 - )); - } - } - producer.next = Some(index + 1); - producer.read += 1; - Ok(()) -} - -/// The line a storm record carries, from the two numbers that identify it. -/// -/// **The kernel builds this and the reader rebuilds it**, so a body half -/// overwritten by another generation fails on the byte that differs rather than -/// on a checksum that might not have covered it. `kernel/src/log/storm.rs` is -/// the other half; a disagreement between the two formulas reds loudly rather -/// than passing quietly. -fn storm_message(thread: u64, index: u64) -> String { - let checksum = (thread.wrapping_mul(0x9E37_79B9_7F4A_7C15) - ^ index.wrapping_mul(0xC2B2_AE3D_27D4_EB4F)) - .rotate_left(17); - let payload: String = (0..PAYLOAD) - .map(|offset| (b'a' + (checksum.wrapping_add(offset as u64) % 26) as u8) as char) - .collect(); - format!("logstorm t={thread} i={index} k={checksum:016x} {payload}") -} - -fn parse_start(rest: &str) -> Result<(u32, u64), String> { - let mut threads = None; - let mut records = None; - for word in rest.split_whitespace() { - if let Some(v) = word.strip_prefix("threads=") { - threads = v.parse::().ok(); - } - if let Some(v) = word.strip_prefix("records=") { - records = v.parse::().ok(); - } - } - match (threads, records) { - (Some(t), Some(r)) => Ok((t, r)), - _ => Err(format!("`logstorm start` is unreadable: {rest}")), - } -} - -fn parse_done(rest: &str) -> Result<(u64, u64), String> { - let mut thread = None; - let mut emitted = None; - for word in rest.split_whitespace() { - if let Some(v) = word.strip_prefix("t=") { - thread = v.parse::().ok(); - } - if let Some(v) = word.strip_prefix("emitted=") { - emitted = v.parse::().ok(); - } - } - match (thread, emitted) { - (Some(t), Some(e)) => Ok((t, e)), - _ => Err(format!("`logstorm done` is unreadable: {rest}")), - } -} - -fn parse_record(rest: &str) -> Result<(u64, u64), String> { - let mut words = rest.split_whitespace(); - let thread = words - .next() - .and_then(|w| w.parse::().ok()) - .ok_or_else(|| format!("a storm record names no thread: {rest}"))?; - let index = words - .next() - .and_then(|w| w.strip_prefix("i=")) - .and_then(|w| w.parse::().ok()) - .ok_or_else(|| format!("a storm record names no index: {rest}"))?; - Ok((thread, index)) -} - -/// The conservation law, and everything the gate prints for a reader of its -/// output. -fn verdict(tail: &LogTail, run: &Run) -> Result<(), String> { - let seen: Vec = - (0..MAX_LOG_SHARDS).filter(|&i| run.shards[i].first.is_some()).collect(); - if seen.is_empty() { - return Err("no shard answered a single record".into()); - } - if tail.shards() as usize != seen.len() { - return Err(format!( - "the kernel says this machine has {} shard(s) and {} answered a record", - tail.shards(), - seen.len() - )); - } - - // **`records_emitted == records_read + lost`, with the sequence numbers as - // the ledger.** Every number a shard issued is either a record this reader - // took or one it never saw, and the second is what the kernel derives - // `lost` from — out of `head` and `next`, two numbers that have to be right - // anyway, rather than out of a producer-side counter that could drift from - // the ring. - let mut computed = 0u64; - for &i in &seen { - let first = run.shards[i].first.expect("`seen` is the shards with a first record"); - computed += first - FIRST_SEQ + run.shards[i].gaps; - } - let reported = tail.lost(); - if computed != reported { - let per_shard: Vec = seen - .iter() - .map(|&i| { - format!( - "cpu{i}: first={} last={} read={} gaps={}", - run.shards[i].first.unwrap_or(0), - run.shards[i].next.saturating_sub(1), - run.shards[i].read, - run.shards[i].gaps - ) - }) - .collect(); - return Err(format!( - "conservation failed: the sequence numbers say {computed} record(s) were never read \ - and the kernel counted {reported}\n {}", - per_shard.join("\n ") - )); - } - - let mut emitted_total = 0u64; - let mut read_total = 0u64; - let mut migrated = 0u64; - let mut said_done = 0u64; - let mut unseen = 0u64; - if let Some(threads) = run.storm { - // **What every producer emitted, from a record where one survived and - // from the ledger where none did.** `logstorm start` is written before - // the first producer runs and each `done` after that producer's last - // record; the storm laps every shard twice, so the ring is allowed to - // drop any of them and this gate may not wait for one. The floor is the - // highest index any producer reached — a producer emits `0..count`, so - // the highest index seen plus one is a count no producer exceeded, and - // the producer that finished last on a shard has its final records at - // the newest end of it. - let derived = run - .producers - .iter() - .filter(|(&t, _)| t != NEST_PRODUCER) - .filter_map(|(_, p)| p.next) - .max(); - let declared = match (run.declared, derived) { - (Some(declared), _) => declared, - (None, Some(derived)) => derived, - (None, None) => { - return Err("storm records were read and none of them named an index".into()) - } - }; - for thread in 0..threads as u64 { - let Some(producer) = run.producers.get(&thread) else { - // **A producer this reader never saw at all is the ring's - // declared policy and not a failure**, and this used to be a - // hard error. Two producers placed on one CPU write one shard, - // and 1,024 records from the second lap all 1,024 of the first: - // measured 2 of 7 full suites on the dev host, 2026-08-15, with - // 2,582 records overwritten in a shard on the run that produced - // it. Refusing it would be refusing the behaviour under test. - // - // It is not free either — see the ledger check below, which is - // what stops "the reader saw nothing of it" from covering a - // producer that never ran. - unseen += 1; - emitted_total += declared; - continue; - }; - // **A cross-check where the record survived, never a requirement.** - // A producer whose `done` was lapped is a producer the ring - // dropped a record of, which is the behaviour under test. - if let Some(emitted) = producer.emitted { - said_done += 1; - if emitted != declared { - return Err(format!( - "producer t={thread} emitted {emitted} records against a declared \ - {declared}" - )); - } - } - if producer.read > declared { - return Err(format!( - "producer t={thread} emitted {declared} records and this reader took {}", - producer.read - )); - } - if producer.next.is_some_and(|next| next > declared) { - return Err(format!( - "producer t={thread} answered index {} of a declared {declared}", - producer.next.unwrap_or(0) - 1 - )); - } - emitted_total += declared; - read_total += producer.read; - if producer.shards > 1 { - migrated += 1; - } - } - // **A producer nobody saw has to be one the ring dropped, and the - // ledger is what says so.** `unseen` producers emitted `declared` - // records each and none of them was read, so at least that many - // sequence numbers must be among the ones the kernel counted lost. It - // is a necessary condition rather than an attribution — the cursor's - // `lost` is per shard and does not name producers — and it is what - // separates "the ring lapped its whole run", which is the behaviour - // under test, from "that thread never ran", which is a kernel that did - // not spawn what it said it did. - if unseen > 0 { - let owed = unseen * declared; - if reported < owed { - return Err(format!( - "{unseen} producer(s) emitted {declared} record(s) each and this reader took none of them, while the kernel counted {reported} lost in all — a producer can only be invisible because its records were dropped, and the ledger does not account for the {owed} that would take" - )); - } - } - if read_total == 0 { - return Err("the storm ran and this reader read none of it".into()); - } - if run.concurrent == 0 { - return Err( - "every record was read after the storm had finished, so this reader raced nothing" - .into(), - ); - } - // The readiness source, asserted where it is reachable: the poll was - // armed before the read that starts the storm, so the records that - // answer it were committed after it was registered. - if run.completions == 0 { - return Err( - "the log's readiness source completed no poll — not across the storm, and not on \ - the record a child's exit commits afterwards either" - .into(), - ); - } - } - - if let Some(burst) = run.producers.get(&NEST_PRODUCER) { - // The burst's own `done` is read the same way a storm's is: a - // cross-check where it survived, and the ledger's own floor where it - // did not. The burst laps its shard by construction, so a reader - // that required that record would be requiring one the design says may - // go. - let declared = match (run.nest, burst.next) { - (Some(declared), _) => declared, - (None, Some(next)) => next, - (None, None) => { - return Err("the nesting burst was seen and named no index".into()) - } - }; - if burst.read == 0 { - return Err("the nesting burst was injected and none of it was read".into()); - } - if burst.next.is_some_and(|next| next > declared) { - return Err(format!( - "the nesting burst answered index {} of a declared {declared}", - burst.next.unwrap_or(0) - 1 - )); - } - println!( - // `nest_shards` and not `shards`: the line below reports the - // machine's shard count under that name, and two lines defining one - // name is a host-side reader that silently takes whichever came - // last (`tests/common/logread.rs`). - "log-gate: nest declared={declared} read={} dropped={} nest_shards={}", - burst.read, - declared - burst.read, - burst.shards, - ); - } - - println!( - "log-gate: {} record(s) over {} read(s) from {} shard(s); lost={reported}, and the \ - sequence numbers say the same", - run.records, - run.reads, - seen.len() - ); - if run.storm.is_some() { - // `done=` is the count of producers whose own `done` record survived - // the ring, and it is evidence rather than an assertion — the gate no - // longer waits for one and the number is what says how often the ring - // ate one. Bare, not `k/n`: the host's reader takes the denominator of - // an `a/b` field as the producer count and two of those would collide - // (`tests/common/logread.rs`). - println!( - "log-gate: storm emitted={emitted_total} read={read_total} dropped={} \ - concurrent={} migrated={migrated}/{} done={said_done} unseen={unseen} wakes={}", - emitted_total - read_total, - run.concurrent, - run.producers.len(), - run.completions, - ); - } - println!("log-gate: OK"); - Ok(()) -} diff --git a/userland/test-runner/src/main.rs b/userland/test-runner/src/main.rs index 85407cdcdf0..c90160701a4 100644 --- a/userland/test-runner/src/main.rs +++ b/userland/test-runner/src/main.rs @@ -1,6 +1,5 @@ mod kbd_close; mod log_close; -mod log_gate; use std::io::{self, BufRead, Write}; use std::os::toyos::process::{ChildExt, CommandExt}; @@ -28,7 +27,6 @@ use toyos::syscap::SysCap; /// binary's stdin is a pipe (see the `Stdio::piped()` below), so the object the /// collision is about does not exist in one. const BUILTINS: &[(&str, fn(Option<&SysCap>) -> i32)] = &[ - ("log-gate", log_gate::run), ("log-close", log_close::run), ("kbd-close", kbd_close::run), ]; From 8910046bb29b56c53fce5c23bcd1f369f94b3b29 Mon Sep 17 00:00:00 2001 From: japabu Date: Mon, 28 Sep 2026 23:19:59 +0200 Subject: [PATCH 2/4] K3 round 2: the log checks return on syscall-context producers MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Round 1 deleted the logstorm and lognest kernel threads together with the four guest tests they drove. The threads stay deleted; the checks come back, with producers that are not kernel threads. The nesting gate (log_nested_emit, log_reserve_window and the negative control log_reserve_window_negative) is restored unchanged except for where its body runs: log::nested::start_once now runs it inline in the first SYS_LOG_READ, between enable_interrupts() and disable_interrupts(). That is the kthread's context: Ring 0, IF=1, not preempted (the Ring 0 timer only sets need_resched), as the page-fault arm and deadline.rs already run. The log_nest gate, LOG_NEST_VECTOR, aarch64 Vector::LogNest (so Hda and VirtioSound keep 2 and 3), IrqGuard::unclosed, both injection points, the kernel-loom shims and the three actuators return with it. nested::inject is private now: its only outside caller was log-shared-reservation. The conservation law returns as log_conservation_smp2. Its producer is a std::thread of test-runner's new `log-storm` builtin, calling a new test-only SYS_DEBUG action, LOG_PATTERNED (21, under test-actuators), 1024 times; each call emits one `logstorm t=0 i=` record through log::storm::emit_patterned, which the reader regenerates byte for byte. `concurrent` counts storm records taken by a read after which the producer's own counter was still below 1024, not batch order; the loop ends once that counter is 1024 and QUIET_READS reads were empty, so STORM_SETTLE and the logstorm start/done parsers go. --smp 2 rather than 1: a Ring 3 producer on the reader's only CPU interleaves only at 10 ms quantum ends, and one whose 1024 calls fit in one quantum would make every run vacuous. Deleted and not restored: the log-storm and log-shared-reservation actuators (the second was read by no test), storm::start_once/body, watch::park_forever, the boot-actuators kthread row budget, the Producer.shards/migrated= ledger nothing asserted, the host's a/b field parse that only migrated= used, and close_probe's always-empty params. test-durations drops log_conservation_smp1's number, measured for a different producer; the renamed test is unpriced until measured. issues/diagnostics/a-shards-timestamps-run-backwards-at-seq-517.md is deleted: its only evidence is the line `[log] unbracketed: log-gate: FAILED: cpu6 seq 517 ...`, which is log_reserve_window_negative's own eprintln on a pass — the designed refusal. 517 is 5 + 512: the burst is 512 records reserved ahead of the interrupted one on a shard holding four boot records, and one more boot record moved it to 518, which is the "fixed position" the issue read as a defect. The sched_stress red it names shared a run with that line and nothing more. issues/kernel/deleting-logstorm-and-lognest-left-two-log-claims-unverified.md is deleted: both claims are checked again. The K3 stage is deleted from the-kernel-still-creates-threads.md: the logstorm and lognest threads are gone and the checks moved to syscall-context producers. K6 is blocked on K2, K4 and K5. Eight test manifests justified test-runner's logread by the log gate, which none of those boots runs; the comments go and the grants are filed as issues/isolation/test-runner-holds-logread-where-no-log-builtin-runs.md. The echo-spawn and negative-control-timeout issues' exits name the restored sites. Co-Authored-By: Claude Opus 5.5 --- ...-negative-times-out-beside-other-guests.md | 4 +- ...rds-timestamps-run-backwards-at-seq-517.md | 49 -- ...holds-logread-where-no-log-builtin-runs.md | 27 + ...was-refused-with-an-error-nothing-names.md | 3 +- ...-lognest-left-two-log-claims-unverified.md | 41 -- .../the-kernel-still-creates-threads.md | 6 +- kernel-loom/src/lib.rs | 20 + kernel/src/actuator.rs | 9 + kernel/src/arch/aarch64/mod.rs | 12 + kernel/src/arch/aarch64/trap.rs | 2 + kernel/src/arch/x86_64/idt/log_nest.rs | 13 + kernel/src/arch/x86_64/idt/mod.rs | 18 +- kernel/src/arch/x86_64/mod.rs | 12 + kernel/src/arch/x86_64/percpu.rs | 2 + kernel/src/log/mod.rs | 11 + kernel/src/log/nested.rs | 133 ++++ kernel/src/log/shard.rs | 4 + kernel/src/log/storm.rs | 28 + kernel/src/log/user.rs | 6 + kernel/src/syscall/dispatch.rs | 6 + tests/blockdcase/system.toml | 3 - tests/common/logread.rs | 397 +++++++++++- tests/doomcase/system.toml | 3 - tests/doommusiccase/system.toml | 3 - tests/logrotatecase/system.toml | 3 - tests/metalcase/system.toml | 3 - tests/netcase/system.toml | 3 - tests/partclaimcase/system.toml | 3 - tests/sshdcase/system.toml | 3 - tests/test-durations | 3 + tests/toyos.rs | 27 + toyos-abi/src/syscall.rs | 3 + userland/test-runner/src/log_close.rs | 4 +- userland/test-runner/src/log_gate.rs | 569 ++++++++++++++++++ userland/test-runner/src/main.rs | 3 + 35 files changed, 1295 insertions(+), 141 deletions(-) delete mode 100644 issues/diagnostics/a-shards-timestamps-run-backwards-at-seq-517.md create mode 100644 issues/isolation/test-runner-holds-logread-where-no-log-builtin-runs.md delete mode 100644 issues/kernel/deleting-logstorm-and-lognest-left-two-log-claims-unverified.md create mode 100644 kernel/src/arch/x86_64/idt/log_nest.rs create mode 100644 kernel/src/log/nested.rs create mode 100644 kernel/src/log/storm.rs create mode 100644 userland/test-runner/src/log_gate.rs diff --git a/issues/build/log-reserve-window-negative-times-out-beside-other-guests.md b/issues/build/log-reserve-window-negative-times-out-beside-other-guests.md index de18c528061..45834839b21 100644 --- a/issues/build/log-reserve-window-negative-times-out-beside-other-guests.md +++ b/issues/build/log-reserve-window-negative-times-out-beside-other-guests.md @@ -23,5 +23,5 @@ hypothesis, and one red at 18x its price is not a rate. Exit: a rate — the same suite run repeatedly with and without a second worktree's build on the host — that says whether this is contention the harness -should schedule around or a defect in the guest's own boot, and the name is -either re-tiered or fixed at the cause. +should schedule around or a defect in the guest's own boot, and the name's +`tests/toyos.rs` `MACHINE_TESTS` row is either re-tiered or the cause fixed. diff --git a/issues/diagnostics/a-shards-timestamps-run-backwards-at-seq-517.md b/issues/diagnostics/a-shards-timestamps-run-backwards-at-seq-517.md deleted file mode 100644 index 8e560986f01..00000000000 --- a/issues/diagnostics/a-shards-timestamps-run-backwards-at-seq-517.md +++ /dev/null @@ -1,49 +0,0 @@ ---- -status: open -kind: defect -opened: 2026-09-06 ---- - -# A shard's timestamps run backwards at seq 517, and sometimes reds `sched_stress` - -The log gate reports one record per full-tier run whose timestamp is behind the -record before it *in its own shard*, which the gate states is impossible: - -``` -[log] unbracketed: log-gate: FAILED: cpu6 seq 517 is stamped 736451308 ns, -behind the 739564366 ns of the record before it — within a shard the sequence -order is the timestamp order, and `emit` stamps inside the same bracket it -reserves in -``` - -Four full-tier runs on this host, one of them on `origin/metal` (`b3c314cf`) -with no working-tree diff at all: - -| run | tree | shard | seq | inversion | outcome | -|---|---|---|---|---|---| -| 1 | `t14-run4` | cpu5 | 517 | 650224011 behind 651750439 ns (1.5 ms) | `FAIL sched_stress`, 324/325 | -| 2 | `b3c314cf` (base) | cpu6 | 517 | 742053639 behind 743716169 ns (1.7 ms) | 325/325 green | -| 3 | `t14-run4` | cpu6 | 517 | 736451308 behind 739564366 ns (3.1 ms) | 325/325 green | -| 4 | `t14-run4`, one more boot record | cpu6 | 518 | 736406061 behind 737807237 ns (1.4 ms) | 325/325 green | - -So it is **not** the `t14-run4` diff — it fires on the untouched base. The only -reason it is not a permanent red is that the boot it lands in is usually not one -a test is judging. - -It is always an AP's shard, never cpu0's, and always **one fixed position** in -that shard. Run 4 is what shows that: this branch added one boot record ahead of -it and the inversion moved 517 -> 518 with it. So what selects the record is its -index in the shard, not its sequence number, not the wall time, and not the CPU -— which is a much narrower thing to look for than a race that happens to recur. - -The gate's own sentence names the invariant that is broken: `emit` stamps -`record.at_ns` and reserves the shard slot inside one `LogCommitGuard` bracket, -so a later `seq` in a shard cannot carry an earlier stamp unless either the -stamp or the reservation escapes that bracket, or `clock::nanos_since_boot` -reads backwards on that CPU. The last of those is the cheapest to check first -and overlaps `issues/kernel/ap-tsc-trail-is-assumed-and-never-checked.md`. - -**Exit condition**: the inversion explained and gone — either a `seq 517` that -holds its bracket, or a demonstration that the AP's TSC is what moved, priced -against that issue. Until then a `sched_stress` red carrying this line is this -defect and not the author's diff. diff --git a/issues/isolation/test-runner-holds-logread-where-no-log-builtin-runs.md b/issues/isolation/test-runner-holds-logread-where-no-log-builtin-runs.md new file mode 100644 index 00000000000..042464e8b6c --- /dev/null +++ b/issues/isolation/test-runner-holds-logread-where-no-log-builtin-runs.md @@ -0,0 +1,27 @@ +--- +status: open +kind: defect +opened: 2026-09-28 +--- + +# test-runner holds `logread` where no log builtin runs + +`logread` in a `[programs.test-runner]` row is authority for the builtins that +read the log inside test-runner (`log-gate`, `log-storm`, `log-close`, +`userland/test-runner/src/main.rs`'s `BUILTINS`). Every boot that runs one is a +`tests/testcases` boot (`tests/common/logread.rs` boots the machine tests' config; +`tests/toyos.rs`'s one job list naming `log-close` is `tests/testcases`). Eight +other manifests grant it anyway: `tests/partclaimcase`, `tests/blockdcase`, +`tests/doomcase`, `tests/doommusiccase`, `tests/logrotatecase`, +`tests/metalcase`, `tests/netcase` and `tests/sshdcase`. Their comments gave the +log gate as the reason, which none of those boots runs; the comments are gone +and the grants are not. + +`partclaimcase` and `blockdcase` also grant `dup`, so there every child +test-runner spawns receives a `SysCap` duplicate carrying `LOG` as well. + +**Evidence:** `rg -n '"log-gate"|"log-storm"|"log-close"' tests userland`, and +`rg -n logread -g system.toml tests`. + +**Exit:** every `logread` in a test manifest is one a program on that boot +uses, or the row says which use it is for. diff --git a/issues/kernel/a-spawn-of-echo-was-refused-with-an-error-nothing-names.md b/issues/kernel/a-spawn-of-echo-was-refused-with-an-error-nothing-names.md index e5b85565832..a9680ea1d88 100644 --- a/issues/kernel/a-spawn-of-echo-was-refused-with-an-error-nothing-names.md +++ b/issues/kernel/a-spawn-of-echo-was-refused-with-an-error-nothing-names.md @@ -39,7 +39,8 @@ onto `cf715c49` as a checked patch, four more sessions of the same suite had it green 4/4. The branch touches nothing on the spawn path. Neither arm reproduced it, so neither arm explains it. -**Exit.** The refusal named. The cheapest step is that the message carry +**Exit.** The refusal named. The cheapest step is that the message at +`userland/test-runner/src/log_gate.rs`'s `/system/bin/echo` spawn carry `e.raw_os_error()` — `other error` is a message that costs a whole run to learn nothing from — and the next sighting then says which refusal it was. Until then the rate is one guest in one shard of one run, and its `ALONE` diff --git a/issues/kernel/deleting-logstorm-and-lognest-left-two-log-claims-unverified.md b/issues/kernel/deleting-logstorm-and-lognest-left-two-log-claims-unverified.md deleted file mode 100644 index 00bee2a9e90..00000000000 --- a/issues/kernel/deleting-logstorm-and-lognest-left-two-log-claims-unverified.md +++ /dev/null @@ -1,41 +0,0 @@ ---- -status: open -kind: finding -opened: 2026-09-28 ---- - -# Deleting `logstorm`/`lognest` left two log claims unverified - -`issues/kernel/the-kernel-still-creates-threads.md`'s K3 deletes -`kernel/src/log/storm.rs` and `kernel/src/log/nested.rs` — the kernel threads -that generated log-write load for four guest tests -(`log_conservation_smp1`, `log_nested_emit`, `log_reserve_window`, -`log_reserve_window_negative`) — and, with them, every test that used those -producers. Two real kernel claims were checked by nothing else, and are now -checked by nothing at all. - -**Same-CPU interrupt reentrancy inside `emit`'s IF/TF-off bracket.** -`log_nested_emit` and `log_reserve_window` (plus its negative control -`log_reserve_window_negative`, the only test that ever exercised -`arch::IrqGuard`'s bracket by removing it) staged a self-IPI from a kernel -thread — with `IF` set, unlike inside a syscall — landing inside another -`emit`'s own reservation/publication window. `kernel/src/log/nested.rs`'s own -header called this "the one case loom cannot express and the host cannot -stage": `kernel-loom/tests/log_record.rs` models cross-CPU memory ordering -only, since loom has no interrupts and no CPU flags to reenter. Nothing -else in the tree drives this case: `read.rs`'s `Descent::advance` (a shard's -sequence order is its timestamp order) rests on `emit`'s bracket alone, and -that rests on nothing now. - -**`SYS_LOG_READ`'s conservation law under concurrent multi-shard write -load.** `log_conservation_smp1` was the only guest test that read the log -while it was being written fast enough to exercise the ring's drop-oldest -path and the reader's lost/read accounting concurrently — ordinary kernel -log traffic is far too sparse to reach it. No other test replaces this. - -Reintroducing either check needs a producer that raises the load without a -kernel thread — for instance a syscall that a userland test binary calls in -a tight loop, one bound per CPU, rather than a persistent kthread — which is -a redesign outside K3's scope (delete only). Recorded here rather than -silently, per the owner's ruling that a tracked weakness stays "known, -tracked, still true," never unmentioned. diff --git a/issues/kernel/the-kernel-still-creates-threads.md b/issues/kernel/the-kernel-still-creates-threads.md index 5f045fc738f..a263a8df7e8 100644 --- a/issues/kernel/the-kernel-still-creates-threads.md +++ b/issues/kernel/the-kernel-still-creates-threads.md @@ -25,12 +25,8 @@ code creates a schedulable task other than the per-CPU idle loop. last thread tears down its own process on its way out of the kernel, and the scheduler frees that thread's kernel stack after switching away. Blocked on #549 landing. -- **K3:** done — `kernel/src/log/storm.rs` and `kernel/src/log/nested.rs` are - deleted along with the tests that existed only to exercise them; the two - properties they alone checked are unverified now, recorded in - `issues/kernel/deleting-logstorm-and-lognest-left-two-log-claims-unverified.md`. - **K4:** `klogd` goes: the owner-approved driver-model design moves the console to logd, and this track owns that move. - **K5:** `iod` goes with the kernel's write-back queue; met only when #536 lands with no new `kthread::spawn`. -- **K6:** delete the machinery named above. Blocked on K2–K5. +- **K6:** delete the machinery named above. Blocked on K2, K4 and K5. diff --git a/kernel-loom/src/lib.rs b/kernel-loom/src/lib.rs index 4204f8a1e18..594fd0faa2a 100644 --- a/kernel-loom/src/lib.rs +++ b/kernel-loom/src/lib.rs @@ -134,6 +134,26 @@ pub mod arch { } } +/// What the kernel has been told to break, and the models never are. +/// +/// A shim rather than a `cfg` at the call site, so `commit` is one statement in +/// every build and the model drives the same line the kernel does. +pub mod actuator { + /// The one `shard.rs` names: the nesting gate's mid-body injection point. + /// Loom has no CPU flags and no interrupts, which is exactly why that gate + /// exists on a machine instead — so the models drive the loop with nothing + /// in it. + pub const fn log_nested_emit() -> bool { + false + } +} + +/// `shard.rs` calls into this from the mid-body point; in the kernel it is +/// `crate::log::nested`, and here `super` is the crate root. +pub mod nested { + pub fn mid_body() {} +} + /// The contention and deadlock reports are unreachable in these models — the /// spin they fire from is what loom cannot explore — but the arguments are /// consumed so the kernel file's bindings are still live code here. diff --git a/kernel/src/actuator.rs b/kernel/src/actuator.rs index 5b3204f6342..8e9dd38680b 100644 --- a/kernel/src/actuator.rs +++ b/kernel/src/actuator.rs @@ -429,6 +429,15 @@ actuators! { /// Log the monotonic time and which CPUs are alive every 250ms. heartbeat = "heartbeat"; + /// Remove the IF/TF bracket around shard selection through publication — the negative control on the log's interrupt-atomicity claim. + log_unbracketed_reserve = "log-unbracketed-reserve"; + + /// Send this CPU an IPI mid record-copy and emit one shard generation from the handler. + log_nested_emit = "log-nested-emit"; + + /// The same IPI, sent between the shard-pointer read and the unlocked `xadd` — stages order damage the log gate detects, unlike the row above's invisible corruption. + log_nested_reserve = "log-nested-reserve"; + /// Let a handle close cancel every poll on the log's watch in the machine. log_close_cancels_any_syscap = "log-close-cancels-any-syscap"; diff --git a/kernel/src/arch/aarch64/mod.rs b/kernel/src/arch/aarch64/mod.rs index e70a447a5fd..5c9e00e144a 100644 --- a/kernel/src/arch/aarch64/mod.rs +++ b/kernel/src/arch/aarch64/mod.rs @@ -77,6 +77,18 @@ impl IrqGuard { } Self { daif, _not_send_sync: core::marker::PhantomData } } + + /// The mask captured and interrupts left as they are: what the + /// `log-unbracketed-reserve` actuator stages a log reservation with. + #[cfg(feature = "boot-actuators")] + pub fn unclosed() -> Self { + let daif: u64; + // SAFETY: reads `DAIF` and writes nothing. + unsafe { + core::arch::asm!("mrs {saved}, daif", saved = out(reg) daif); + } + Self { daif, _not_send_sync: core::marker::PhantomData } + } } impl Drop for IrqGuard { diff --git a/kernel/src/arch/aarch64/trap.rs b/kernel/src/arch/aarch64/trap.rs index 399e8292e41..4747673475d 100644 --- a/kernel/src/arch/aarch64/trap.rs +++ b/kernel/src/arch/aarch64/trap.rs @@ -161,12 +161,14 @@ pub fn install() { /// ([`super::msi_message`], [`super::irqchip::send_self`]) is owed. #[repr(u8)] enum Vector { + LogNest = 1, Hda, VirtioSound, } pub const HDA_VECTOR: u8 = Vector::Hda as u8; pub const VIRTIO_SOUND_VECTOR: u8 = Vector::VirtioSound as u8; +pub const LOG_NEST_VECTOR: u8 = Vector::LogNest as u8; /// The crash report for a panic, from the frame pointer the panic handler stood on. pub(crate) fn report_panic(message: &core::panic::PanicInfo, frame: u64) { diff --git a/kernel/src/arch/x86_64/idt/log_nest.rs b/kernel/src/arch/x86_64/idt/log_nest.rs new file mode 100644 index 00000000000..b853a965923 --- /dev/null +++ b/kernel/src/arch/x86_64/idt/log_nest.rs @@ -0,0 +1,13 @@ + +use super::device_irq::device_irq_entry; + +extern "sysv64" fn log_nest_handler() { + crate::log::nested::deliver(); + crate::arch::apic::eoi(); +} + +// Reuses `device_irq_entry!`'s stub: it saves scratch registers and aligns the stack for entry from either ring. +device_irq_entry! { + /// The self-IPI `log::nested` sends from inside `emit`. + pub(super) fn log_nest_entry => log_nest_handler +} diff --git a/kernel/src/arch/x86_64/idt/mod.rs b/kernel/src/arch/x86_64/idt/mod.rs index 646705c59b4..3c7d56d78a2 100644 --- a/kernel/src/arch/x86_64/idt/mod.rs +++ b/kernel/src/arch/x86_64/idt/mod.rs @@ -3,6 +3,8 @@ mod device_irq; mod dma_fault; mod hda; mod i8042; +#[cfg(feature = "boot-actuators")] +mod log_nest; mod nmi; pub(crate) mod spurious; mod timer; @@ -39,6 +41,10 @@ pub const HDA_VECTOR: u8 = Vector::Hda as u8; /// The vector the virtio-sound device's MSI-X entry carries. pub const VIRTIO_SOUND_VECTOR: u8 = Vector::VirtioSound as u8; +/// The vector `log-nested-emit` sends itself; installed only in a kernel built with `boot-actuators`. +#[cfg(feature = "boot-actuators")] +pub const LOG_NEST_VECTOR: u8 = 0x27; + const PF_PRESENT: u64 = 1 << 0; const PF_WRITE: u64 = 1 << 1; const PF_INSTRUCTION_FETCH: u64 = 1 << 4; @@ -255,7 +261,8 @@ idt_vectors! { ring3 I8042 = 0x24, i8042::i8042_entry; ring3 DmaFault = 0x25, dma_fault::dma_fault_entry; ring3 Hda = 0x26, hda::hda_entry; - // One per `pcidev` claim slot: the vector is how the kernel knows + // 0x27 is the actuator gate's (`log_nest`), which is why these start at + // 0x28. One per `pcidev` claim slot: the vector is how the kernel knows // which claim a message belongs to. ring3 UserDev0 = 0x28, user_dev::user_dev0_entry; ring3 UserDev1 = 0x29, user_dev::user_dev1_entry; @@ -457,6 +464,8 @@ pub fn init() { disable_pic(); install_gates(&mut IDT.lock()); + #[cfg(feature = "boot-actuators")] + install_actuator_gates(&mut IDT.lock()); // Every slot no row filled: delivery through a P = 0 gate is a // contributory fault, and the machine would halt as #DF with no name. let mut unclaimed = 0u32; @@ -499,6 +508,13 @@ pub fn init() { ); } +/// The one gate outside the table: only an actuator raises [`LOG_NEST_VECTOR`], so a shipping kernel never installs it. +#[cfg(feature = "boot-actuators")] +fn install_actuator_gates(idt: &mut Idt) { + idt.entries[LOG_NEST_VECTOR as usize] = + IdtEntry::ring3(Ring3Entry::new(log_nest::log_nest_entry)); +} + /// Take IF=1 on this CPU; split from `init` so `ioapic::init` can mask firmware-left entries before interrupts are live. pub fn enable_interrupts() { cpu::enable_interrupts(); diff --git a/kernel/src/arch/x86_64/mod.rs b/kernel/src/arch/x86_64/mod.rs index 91ee631cfea..41ec8a0f805 100644 --- a/kernel/src/arch/x86_64/mod.rs +++ b/kernel/src/arch/x86_64/mod.rs @@ -76,6 +76,18 @@ impl IrqGuard { } Self { rflags, _not_send_sync: core::marker::PhantomData } } + + /// The flags captured and interrupts left as they are: what the + /// `log-unbracketed-reserve` actuator stages a log reservation with. + #[cfg(feature = "boot-actuators")] + pub fn unclosed() -> Self { + let rflags: u64; + // SAFETY: pushfq/pop is balanced and writes no RFLAGS bit. + unsafe { + core::arch::asm!("pushfq", "pop {saved}", saved = out(reg) rflags); + } + Self { rflags, _not_send_sync: core::marker::PhantomData } + } } impl Drop for IrqGuard { diff --git a/kernel/src/arch/x86_64/percpu.rs b/kernel/src/arch/x86_64/percpu.rs index 4b4186487d5..f70b189345e 100644 --- a/kernel/src/arch/x86_64/percpu.rs +++ b/kernel/src/arch/x86_64/percpu.rs @@ -432,6 +432,8 @@ pub fn reserve_log_slot( pid_off = const OFF_CURRENT_PID, options(preserves_flags), ); + // `log-nested-reserve`'s injection point: must sit between the shard-pointer read and the `xadd`, the only place ordering is decided (no-op outside tests). + crate::log::nested::reserve_window(); seq = (&*(shard as *const log::Shard)).reserve(guard); } (shard as *const log::Shard, seq, cpu, tid, pid) diff --git a/kernel/src/log/mod.rs b/kernel/src/log/mod.rs index d0eb753c480..07dceac9db2 100644 --- a/kernel/src/log/mod.rs +++ b/kernel/src/log/mod.rs @@ -6,10 +6,13 @@ #![warn(clippy::undocumented_unsafe_blocks)] pub mod console; +pub mod nested; pub mod read; pub mod recovery; pub mod registry; pub mod shard; +#[cfg(any(feature = "boot-actuators", feature = "test-actuators"))] +pub mod storm; pub mod user; use core::sync::atomic::{AtomicBool, Ordering}; @@ -175,6 +178,14 @@ pub fn emit(severity: Severity, args: core::fmt::Arguments) { record.len = message.len as u16; record.elided = message.elided.min(u16::MAX as usize) as u16; + // `log-unbracketed-reserve` stages a reservation made with interrupts open. + #[cfg(feature = "boot-actuators")] + let guard = if crate::actuator::log_unbracketed_reserve() { + crate::arch::IrqGuard::unclosed() + } else { + crate::arch::IrqGuard::close() + }; + #[cfg(not(feature = "boot-actuators"))] let guard = crate::arch::IrqGuard::close(); // Stamped inside the bracket: outside it, ordering by seq and by at_ns // could disagree. The NMI handler never logs and #MC halts rather than diff --git a/kernel/src/log/nested.rs b/kernel/src/log/nested.rs new file mode 100644 index 00000000000..d3a61271c44 --- /dev/null +++ b/kernel/src/log/nested.rs @@ -0,0 +1,133 @@ +//! Injects a self-IPI from inside `emit`, landing at one of two windows +//! depending on which actuator is armed. +//! +//! `log-nested-emit`: mid body-copy — overwrites an already-published slot, +//! indistinguishable from drop-oldest. +//! `log-nested-reserve`: between the shard-pointer read and the `xadd` — +//! produces a shard whose `at_ns` descends, which `Descent::advance` and the +//! log gate assume cannot happen. + +/// Producer id the burst's records use — one the log gate's own producer never takes. +#[cfg(feature = "boot-actuators")] +pub const NEST_PRODUCER: u64 = u64::MAX; + +#[cfg(feature = "boot-actuators")] +mod armed { + use core::sync::atomic::{AtomicBool, Ordering}; + + use crate::log::shard::SHARD_RECORDS; + + /// One-shot for the body-copy injection point, consumed by `mid_body`. + static ARMED: AtomicBool = AtomicBool::new(false); + + /// One-shot for the reservation-window injection point, consumed by [`reserve_window`]; kept separate from `ARMED` so it can't starve the body window. + static ARMED_RESERVE: AtomicBool = AtomicBool::new(false); + + /// Set by the injection and cleared by the handler, so a delivery for any other reason emits nothing. + static OWED: AtomicBool = AtomicBool::new(false); + + static STARTED: AtomicBool = AtomicBool::new(false); + + /// Spin count after sending the IPI, so delivery lands inside the window rather than after it. + const WINDOW: usize = 256; + + pub fn start_once() { + // Both actuators name the same injection; arming both would inject into one record twice. + assert!( + !(crate::actuator::log_nested_emit() && crate::actuator::log_nested_reserve()), + "log-nested-emit and log-nested-reserve both name the one injection this read arms" + ); + if STARTED.swap(true, Ordering::Relaxed) { + return; + } + crate::log!("lognest start records={SHARD_RECORDS}"); + // `IF` is clear for a whole syscall, so injecting with it clear would never test the guard; Ring 0 is not preempted, so the body runs whole on this CPU. + crate::arch::cpu::enable_interrupts(); + body(); + crate::arch::cpu::disable_interrupts(); + } + + fn body() { + if crate::actuator::log_nested_reserve() { + ARMED_RESERVE.store(true, Ordering::Relaxed); + crate::log!( + "lognest outer, and an interrupt is due between this record's shard read and its \ + xadd" + ); + ARMED_RESERVE.store(false, Ordering::Relaxed); + } else { + ARMED.store(true, Ordering::Relaxed); + crate::log!("lognest outer, and an interrupt is due inside this record's body"); + // Reset unconditionally: the one-shot must not outlive this record, or a later injection would land in an unrelated log line. + ARMED.store(false, Ordering::Relaxed); + } + crate::log!("lognest done emitted={SHARD_RECORDS}"); + } + + /// Consumes the one-shot and sends this CPU its own IPI; `true` if this call sent it. + fn inject() -> bool { + if !ARMED.swap(false, Ordering::Relaxed) { + return false; + } + OWED.store(true, Ordering::Relaxed); + crate::arch::irqchip::send_self(crate::arch::trap::LOG_NEST_VECTOR); + true + } + + /// Injection point inside the body copy; spins after sending so delivery lands inside it. + pub fn mid_body() { + if !inject() { + return; + } + for _ in 0..WINDOW { + core::hint::spin_loop(); + } + } + + /// Injection point between the shard-pointer read and the `xadd`; consumes `ARMED_RESERVE` directly, not via `inject`. + pub fn reserve_window() { + if !ARMED_RESERVE.swap(false, Ordering::Relaxed) { + return; + } + OWED.store(true, Ordering::Relaxed); + crate::arch::irqchip::send_self(crate::arch::trap::LOG_NEST_VECTOR); + for _ in 0..WINDOW { + core::hint::spin_loop(); + } + } + + /// Emits exactly one shard generation — the count that reads the outer record's disappearance as drop-oldest, not corruption. + pub fn deliver() { + if !OWED.swap(false, Ordering::Relaxed) { + return; + } + for index in 0..SHARD_RECORDS as u64 { + crate::log::storm::emit_patterned(super::NEST_PRODUCER, index); + } + } +} + +/// Arms the injection and emits the record it lands in, inline in the calling `SYS_LOG_READ`, once; compiled only under `boot-actuators`. +#[cfg(feature = "boot-actuators")] +pub fn start_once() { + armed::start_once(); +} + +/// Injection point halfway through a record's body copy; always compiled so `kernel-loom`'s separate copy of `log::shard` names one path. +pub fn mid_body() { + #[cfg(feature = "boot-actuators")] + armed::mid_body(); +} + +/// Injection point between a record's shard-pointer read and its `xadd`; called only from `arch::percpu::reserve_log_slot`. +pub fn reserve_window() { + #[cfg(feature = "boot-actuators")] + armed::reserve_window(); +} + +/// The `log_nest` interrupt handler's body; no shipping kernel installs that handler. +#[cfg(feature = "boot-actuators")] +pub fn deliver() { + #[cfg(feature = "boot-actuators")] + armed::deliver(); +} diff --git a/kernel/src/log/shard.rs b/kernel/src/log/shard.rs index 4d800c58890..140f2ef8441 100644 --- a/kernel/src/log/shard.rs +++ b/kernel/src/log/shard.rs @@ -181,6 +181,10 @@ impl Shard { } let words = msg_words(len); for i in 0..words { + // Injection point for `log-nested-emit`'s test IPI; folds away outside `kernel-loom`'s shim. + if i * 2 == words && crate::actuator::log_nested_emit() { + super::nested::mid_body(); + } let mut bytes = [0u8; 8]; bytes.copy_from_slice(&record.msg[i * 8..i * 8 + 8]); slot.body[HEADER_WORDS + i].store(u64::from_le_bytes(bytes), Ordering::Relaxed); diff --git a/kernel/src/log/storm.rs b/kernel/src/log/storm.rs new file mode 100644 index 00000000000..2de2b6f8090 --- /dev/null +++ b/kernel/src/log/storm.rs @@ -0,0 +1,28 @@ +//! Generates patterned records so the log gate's reader can check a conservation law over them. + +// Must exceed one machine word: a single-store payload couldn't reveal a torn write. +const PAYLOAD: usize = 96; + +/// Deterministic checksum of `thread` and `index`, embedded in a record's `k=` field. +pub fn checksum(thread: u64, index: u64) -> u64 { + (thread.wrapping_mul(0x9E37_79B9_7F4A_7C15) ^ index.wrapping_mul(0xC2B2_AE3D_27D4_EB4F)) + .rotate_left(17) +} + +/// One payload byte at `offset`, deterministic in `checksum`; always lowercase ASCII. +pub fn payload_byte(checksum: u64, offset: usize) -> u8 { + b'a' + (checksum.wrapping_add(offset as u64) % 26) as u8 +} + +/// One patterned record for `thread`/`index`; called by `SYS_DEBUG`'s `LOG_PATTERNED` and by `log-nested-reserve` from an interrupt handler. +/// The reader regenerates this text independently from `t=`/`i=`, so the format here must stay in sync with it. +pub fn emit_patterned(thread: u64, index: u64) { + let checksum = checksum(thread, index); + let mut payload = [0u8; PAYLOAD]; + for (offset, byte) in payload.iter_mut().enumerate() { + *byte = payload_byte(checksum, offset); + } + // Fallback rather than `expect`: a panic here would halt the machine over the producer's own formatting. + let payload = core::str::from_utf8(&payload).unwrap_or(""); + crate::log!("logstorm t={thread} i={index} k={checksum:016x} {payload}"); +} diff --git a/kernel/src/log/user.rs b/kernel/src/log/user.rs index 0d0c0a6ac5f..c848e166f24 100644 --- a/kernel/src/log/user.rs +++ b/kernel/src/log/user.rs @@ -46,6 +46,12 @@ pub fn read( out: &mut UserBytesMut, capacity: usize, ) -> Result { + // Run once, inside the first read's own syscall rather than on a kernel thread; `log::nested` picks the window from whichever actuator is armed. + #[cfg(feature = "boot-actuators")] + if crate::actuator::log_nested_emit() || crate::actuator::log_nested_reserve() { + super::nested::start_once(); + } + let shards = super::shard_count(); // Refused, not truncated: a capacity below one record per shard cannot hold what a single call may have to merge. if capacity == 0 || capacity < shards as usize { diff --git a/kernel/src/syscall/dispatch.rs b/kernel/src/syscall/dispatch.rs index e0f8a33e842..c582a56c9cf 100644 --- a/kernel/src/syscall/dispatch.rs +++ b/kernel/src/syscall/dispatch.rs @@ -602,6 +602,12 @@ pub(crate) fn syscall_dispatch(num: u64, a1: u64, a2: u64, a3: u64, a4: u64) -> None => SyscallError::InvalidArgument.to_u64(), } } + // Kernel records at the rate a tight loop makes them, from a preemptible userland + // thread beside the reader: the load the log gate's conservation law is read under. + DA::LOG_PATTERNED => { + crate::log::storm::emit_patterned(0, a2); + 0 + } _ => SyscallError::InvalidArgument.to_u64(), }, SYS_SCHED_INFO => match ctx.copy_out(UserAddr::new(a1), &sys_sched_info()) { diff --git a/tests/blockdcase/system.toml b/tests/blockdcase/system.toml index 623c5130aa2..fd9a95d4916 100644 --- a/tests/blockdcase/system.toml +++ b/tests/blockdcase/system.toml @@ -22,9 +22,6 @@ syscap = ["logread"] # `device` because five of the guest binaries claim the keyboard or the mouse # and no manifest row can name them — they are not `[programs]` keys — and `dup` # because a claim moves and one boot runs several of them. -# `logread` because the log gate reads the kernel's own records and cannot be -# a spawned binary: a `SysCap` dup is not part of the namespace test-runner -# hands down. # `power` because `run shutdown` is how a dozen host-side gates end their guest # and read what reached the volume, and test-runner spawns `/system/bin/shutdown` # directly — it holds no `launcher` connector, so the applet's authority is the diff --git a/tests/common/logread.rs b/tests/common/logread.rs index 3085c10a548..c78d83acbd8 100644 --- a/tests/common/logread.rs +++ b/tests/common/logread.rs @@ -1,15 +1,295 @@ -//! `SYS_LOG_READ`'s readiness source, probed against a handle close. +//! `SYS_LOG_READ`, read from inside `test-runner` under a storm. +//! +//! **The verdict is computed in the guest and asserted here.** What the host +//! can see of a conservation law is a line saying it held; what it can check is +//! that the line is there, that the run was not vacuous, and that the numbers +//! the guest printed describe the machine the host booted. So the guest prints +//! its ledger and this file reads it — `log-gate: OK` is the verdict, and every +//! number beside it is evidence a reviewer can weigh. +//! +//! The gate runs *inside* `test-runner` rather than in a binary it spawns: +//! `logread` is a `SysCap` dup and not a namespace entry, so it is not part of +//! what the runner hands its children. +use std::collections::BTreeMap; use std::path::Path; use std::time::Duration; use super::qemu::{BootOptions, QemuInstance}; +/// The in-guest gate's name in the `run ` protocol. It is a `test-runner` +/// builtin rather than a `/system/bin` entry, and the marker protocol is the same +/// either way. +const GATE: &str = "log-gate"; + +/// The same gate with its own producer thread storming the log beside it. +const STORM_GATE: &str = "log-storm"; + /// The whole run's ceiling. A liveness guard and never a verdict: the guest has /// a ceiling of its own and reports what it had when it gave up, so this only /// catches a guest that stopped answering at all. const CEILING: Duration = Duration::from_secs(60); +/// One boot's storm, as the guest reported it. +struct Report { + stdout: String, + fields: BTreeMap, +} + +impl Report { + fn get(&self, key: &str) -> Result { + self.fields + .get(key) + .copied() + .ok_or_else(|| format!("the guest's report has no `{key}=`:\n{}", self.stdout)) + } +} + +/// A name two of the guest's lines both defined. +/// +/// **Not a merge, because the two lines are different subjects.** The guest +/// prints its ledger over several `log-gate:` lines and this file reads them +/// into one map, so a name appearing twice means the number a test asserts on +/// came from whichever line was printed last — silently, and with the other +/// line still on screen looking like the evidence. The nest and storm lines +/// already share `read=` and `dropped=`, and every gate here reads exactly one +/// of the two. +struct Contaminated { + key: String, + first: u64, + second: u64, +} + +/// The conservation law, at one width. +fn conservation( + test_config: &Path, + c_bins: &[(String, Vec)], + rust_bins: &[(String, Vec)], + smp: u32, +) -> Result<(), String> { + // The test kernel by build rather than by actuator: the producer's + // `SYS_DEBUG` is what needs it, and nothing is armed. + let options = + BootOptions { smp, kernel_features: toyos_build::build::TEST_KERNEL, ..Default::default() }; + let report = storm(test_config, c_bins, rust_bins, STORM_GATE, options)?; + let shards = report.get("shards")?; + if shards != smp as u64 { + return Err(format!( + "--smp {smp} answered {shards} shard(s); the cursor's shard count is the machine's \ + CPU count\n{}", + report.stdout + )); + } + // Non-vacuity, and it is the half a green law cannot supply: a reader that + // took every record after the storm had ended has proved nothing about + // concurrent producers. + let concurrent = report.get("concurrent")?; + let dropped = report.get("dropped")?; + let read = report.get("read")?; + if concurrent == 0 || read == 0 { + return Err(format!( + "--smp {smp} read {read} record(s), {concurrent} of them while the storm ran\n{}", + report.stdout + )); + } + eprintln!( + " [log] smp={smp}: emitted={} read={read} dropped={dropped} concurrent={concurrent} \ + lost={} wakes={}", + report.get("emitted")?, + report.get("lost")?, + report.get("wakes")?, + ); + Ok(()) +} + +/// **`--smp 2`**, so the producer thread has a CPU the reader is not on and +/// runs beside it rather than only between its quanta. +pub fn log_conservation_smp2( + test_config: &Path, + c_bins: &[(String, Vec)], + rust_bins: &[(String, Vec)], +) -> Result<(), String> { + conservation(test_config, c_bins, rust_bins, 2) +} + +/// The nested-`emit` gate: an interrupt that logs, inside another `emit`, on one CPU. +/// +/// **The one case loom cannot express and the host cannot stage.** The +/// stimulus is a self-IPI sent from inside a record's own body copy, inside +/// `SYS_LOG_READ` with `IF` opened for it — where `emit`'s IF-off bracket is the +/// only thing holding the interrupt off. The handler emits exactly one shard generation of +/// patterned records; the outer record is then dropped by the ring's own +/// drop-oldest policy, which is what makes "the burst laps the shard" a +/// statement with an arithmetic behind it. +/// +/// What is asserted is the conservation ledger over a workload of that shape: every +/// sequence number read or counted lost, every burst record's text regenerated +/// byte for byte from the two numbers it declares, and the burst's own `done` +/// read — so a run in which nothing was injected cannot pass quietly. +/// +/// **`--smp 1`, and that is the test's own claim.** Nesting is a property of +/// one CPU: a second CPU adds records to the merge and takes nothing away from +/// what this asks, while at one the interrupted writer and its interrupting +/// handler are provably the same CPU. +pub fn log_nested_emit( + test_config: &Path, + c_bins: &[(String, Vec)], + rust_bins: &[(String, Vec)], +) -> Result<(), String> { + let options = BootOptions { smp: 1, kernel_params: &["log-nested-emit"], ..Default::default() }; + let report = storm(test_config, c_bins, rust_bins, GATE, options)?; + let declared = report.get("declared")?; + let read = report.get("read")?; + if read == 0 { + return Err(format!("the burst was declared and none of it read\n{}", report.stdout)); + } + eprintln!( + " [log] nested: burst declared={declared} read={read} dropped={}", + report.get("dropped")? + ); + Ok(()) +} + +/// The reserve bracket at the window it names first: an interrupt that logs, +/// landing between a record's shard-pointer read and its unlocked `xadd`. +/// +/// **The property is that a shard has one order and not two.** `emit` reads the +/// clock and takes its sequence number inside one IF-off bracket, and every +/// reader in the tree rests on the two being the same order — `read.rs`'s +/// `Descent::advance` stops a shard's descent on the first record older than the +/// window it was asked for, which is only sound while a lower sequence number +/// cannot carry a later timestamp. `log-nested-reserve` puts an interrupt that +/// logs into exactly that window: with the bracket the IPI is pending until the +/// guard drops and the handler's whole burst is reserved *after* the record it +/// interrupted, and without it the burst is reserved *before*. +/// +/// **`--smp 8`, and no storm beside it.** Eight shards is where the merge across +/// shards has to keep each shard's own order while interleaving eight of them; +/// a storm on the injected CPU would lap the interrupted record before the +/// reader reached it, which is the one record the verdict is about. +pub fn log_reserve_window( + test_config: &Path, + c_bins: &[(String, Vec)], + rust_bins: &[(String, Vec)], +) -> Result<(), String> { + let options = BootOptions { smp: 8, kernel_params: &["log-nested-reserve"], ..Default::default() }; + let report = storm(test_config, c_bins, rust_bins, GATE, options)?; + let declared = report.get("declared")?; + let read = report.get("read")?; + let dropped = report.get("dropped")?; + let shards = report.get("shards")?; + if shards != 8 { + return Err(format!( + "--smp 8 answered {shards} shard(s); the cursor's shard count is the machine's CPU \ + count\n{}", + report.stdout + )); + } + if read == 0 { + return Err(format!( + "the reservation-window burst was declared and none of it read, so nothing was \ + injected into anything\n{}", + report.stdout + )); + } + // **The derivation, and it is exact rather than a bound.** With the bracket + // the IPI is pending across the whole publication, so the interrupted + // producer's own record takes `S` and the handler's burst takes + // `S+1 ..= S+BURST` after it, with `lognest done` at `S+BURST+1`. `head` is + // then `S+BURST+2` and `oldest_readable` is `head - BURST`, which is `S+2` — + // so the reader can never answer for the outer record or for the burst's + // first, and can answer for every one of the other `BURST-1`. Measured + // `read=511 dropped=1` in eight of eight boots on the dev host, 2026-08-22. + if declared != BURST || read != BURST - 1 || dropped != 1 { + return Err(format!( + "the burst declared {declared} record(s), this reader took {read} and lost \ + {dropped}: one shard generation is {BURST}, and the ring's own drop-oldest policy \ + puts exactly the burst's first record below `oldest_readable` and nothing else\n{}", + report.stdout + )); + } + eprintln!( + " [log] reserve window: burst declared={declared} read={read} dropped={dropped} \ + shards={shards}" + ); + Ok(()) +} + +/// `kernel/src/log/shard.rs`'s `SHARD_RECORDS`, which is how many records +/// `log::nested`'s handler emits: exactly one shard generation. +const BURST: u64 = 512; + +/// The negative control on [`log_reserve_window`], and on `arch::IrqGuard` +/// itself: the same boot with the reserve bracket removed. +/// +/// **The one thing that can make the log's correctness claim fail on purpose.** +/// `log-unbracketed-reserve` leaves the guard constructed and dropped exactly as +/// it is and masks nothing, so the self-IPI is delivered where it was sent — +/// inside the reservation window — and the handler's `SHARD_RECORDS` records +/// take the sequence numbers below the one the interrupted producer goes on to +/// take, while carrying timestamps above all of its. The gate must then refuse +/// the shard, by name, and the assertion here is that refusal and not merely a +/// non-zero exit: a boot that failed for any other reason has not read this +/// actuator. +/// +/// **The failure is derived, not sampled.** The burst is exactly [`BURST`] +/// records reserved back to back on one shard, so the interrupted record's own +/// number is exactly [`BURST`] above the burst's first while its `at_ns` was +/// stamped before any of them; the reader walks a shard in sequence order, so it +/// meets the inversion at that record on its first pass over the shard, on every +/// boot. Measured on the dev host 2026-08-22, eight of eight: the refusal names +/// `seq 517` in six boots, 518 in one and 665 in one — 517 is 5 + 512, cpu7's +/// shard having held four boot records before the injection. +pub fn log_reserve_window_negative( + test_config: &Path, + c_bins: &[(String, Vec)], + rust_bins: &[(String, Vec)], +) -> Result<(), String> { + let mut qemu = QemuInstance::boot_with_options( + test_config, + c_bins, + rust_bins, + BootOptions { + smp: 8, + kernel_params: &["log-nested-reserve", "log-unbracketed-reserve"], + ..Default::default() + }, + ); + let result = qemu.run_test(GATE, CEILING); + if let Some(err) = &result.error { + return Err(format!( + "the unbracketed boot never reported: {err}\nstdout:\n{}\nserial tail:\n{}", + result.stdout, + tail(&result.serial) + )); + } + if result.exit_code == Some(0) || result.stdout.contains("log-gate: OK") { + return Err(format!( + "the bracket was removed and the log gate passed anyway ({:?}), so the guard's `cli` \ + is still measured by nothing\n{}", + result.exit_code, result.stdout + )); + } + let refusal = result + .stdout + .lines() + .find(|l| l.contains(INVERSION)) + .ok_or_else(|| { + format!( + "the unbracketed boot failed for some other reason than the one this control \ + stages — no line said `{INVERSION}`\n{}", + result.stdout + ) + })?; + eprintln!(" [log] unbracketed: {}", refusal.trim()); + Ok(()) +} + +/// The clause `userland/test-runner/src/log_gate.rs` refuses a descending +/// `at_ns` with. Two copies of one sentence, and this file is the one that +/// would notice if the other changed. +const INVERSION: &str = "within a shard the sequence order is the timestamp order"; + /// A pending poll on the machine's log is not something a handle closing /// can cancel. /// @@ -32,21 +312,8 @@ pub fn log_poll_outlives_a_close( c_bins: &[(String, Vec)], rust_bins: &[(String, Vec)], ) -> Result<(), String> { - close_probe(test_config, c_bins, rust_bins, &[]) -} - -fn close_probe( - test_config: &Path, - c_bins: &[(String, Vec)], - rust_bins: &[(String, Vec)], - params: &'static [&'static str], -) -> Result<(), String> { - let mut qemu = QemuInstance::boot_with_options( - test_config, - c_bins, - rust_bins, - BootOptions { kernel_params: params, ..Default::default() }, - ); + let mut qemu = + QemuInstance::boot_with_options(test_config, c_bins, rust_bins, BootOptions::default()); let result = qemu.run_test("log-close", CEILING); if let Some(err) = &result.error { return Err(format!("{err}\nstdout:\n{}", result.stdout)); @@ -65,3 +332,101 @@ fn close_probe( eprintln!(" [log] {}", survived.trim()); Ok(()) } + +/// Boot one machine as `options` says, run `gate` on it and read its verdict off it. +fn storm( + test_config: &Path, + c_bins: &[(String, Vec)], + rust_bins: &[(String, Vec)], + gate: &str, + options: BootOptions, +) -> Result { + let (smp, params) = (options.smp, options.kernel_params); + let mut qemu = QemuInstance::boot_with_options(test_config, c_bins, rust_bins, options); + let result = qemu.run_test(gate, CEILING); + if let Some(err) = &result.error { + return Err(format!( + "--smp {smp} {params:?}: {err}\nstdout:\n{}\nserial tail:\n{}", + result.stdout, + tail(&result.serial) + )); + } + match result.exit_code { + Some(0) => {} + Some(code) => { + return Err(format!( + "--smp {smp} {params:?}: the log gate exited {code}\n{}", + result.stdout + )) + } + None => { + return Err(format!("--smp {smp} {params:?}: no exit code\n{}", result.stdout)) + } + } + if !result.stdout.contains("log-gate: OK") { + return Err(format!( + "--smp {smp} {params:?}: the gate exited 0 without saying so\n{}", + result.stdout + )); + } + let fields = fields(&result.stdout).map_err(|c| { + format!( + "--smp {smp} {params:?}: two of the guest's `log-gate:` lines define `{}` ({} and \ + {}), so every number read out of this report is whichever line came last\n{}", + c.key, c.first, c.second, result.stdout + ) + })?; + Ok(Report { fields, stdout: result.stdout }) +} + +/// Every `key=` the guest printed, and the two counts it prints as +/// prose. One parse, so a test asserts on a name rather than on a column. +/// +/// **A name defined twice is refused rather than merged.** The guest's report is +/// several lines about different subjects, and flattening them means a repeated +/// name silently resolves to the last line printed — with the other line still +/// in the failure message, looking like the evidence. Refusing is what makes the +/// flattening safe: it holds exactly while the names really are unique. +fn fields(stdout: &str) -> Result, Contaminated> { + fn put( + out: &mut BTreeMap, + key: &str, + value: u64, + ) -> Result<(), Contaminated> { + match out.insert(key.to_string(), value) { + None => Ok(()), + Some(first) => Err(Contaminated { key: key.to_string(), first, second: value }), + } + } + + let mut out: BTreeMap = BTreeMap::new(); + for line in stdout.lines() { + let Some(rest) = line.split_once("log-gate: ").map(|(_, r)| r) else { continue }; + for word in rest.split_whitespace() { + let Some((key, value)) = word.split_once('=') else { continue }; + if let Ok(n) = value.trim_end_matches(&[',', ';'][..]).parse::() { + put(&mut out, key, n)?; + } + } + // "N record(s) over M read(s) from S shard(s)" — the shape of the line + // rather than a key, because those three are what the sentence is. + let words: Vec<&str> = rest.split_whitespace().collect(); + for pair in words.windows(2) { + let Ok(n) = pair[0].parse::() else { continue }; + match pair[1] { + "record(s)" => put(&mut out, "records", n)?, + "read(s)" => put(&mut out, "reads", n)?, + "shard(s);" | "shard(s)" => put(&mut out, "shards", n)?, + _ => {} + } + } + } + Ok(out) +} + +/// The last of a capture, for a failure message. A storm puts thousands of +/// lines on the console and the interesting end is the recent one. +fn tail(serial: &str) -> String { + let lines: Vec<&str> = serial.lines().collect(); + lines[lines.len().saturating_sub(40)..].join("\n") +} diff --git a/tests/doomcase/system.toml b/tests/doomcase/system.toml index f9b7b2411c6..2f36a22f957 100644 --- a/tests/doomcase/system.toml +++ b/tests/doomcase/system.toml @@ -32,9 +32,6 @@ syscap = ["rt"] # test-runner passes its whole namespace to the binaries it spawns, so # it holds what doom needs. No compositor here — doom's `--sound-stress` opens # no window. -# `logread` is the log gate's own: a spawned test binary does not inherit a -# `SysCap` dup, so the gate that reads the kernel's records runs inside -# `test-runner` itself. [programs.test-runner] receives = ["soundd"] syscap = ["logread"] diff --git a/tests/doommusiccase/system.toml b/tests/doommusiccase/system.toml index c2e5ecfe924..f5b47cfb734 100644 --- a/tests/doommusiccase/system.toml +++ b/tests/doommusiccase/system.toml @@ -34,9 +34,6 @@ syscap = ["rt"] # No compositor: `/system/bin/doom --music-check` opens no window. test-runner passes # its namespace to doom. -# `logread` is the log gate's own: a spawned test binary does not inherit a -# `SysCap` dup, so the gate that reads the kernel's records runs inside -# `test-runner` itself. [programs.test-runner] receives = ["soundd"] syscap = ["logread"] diff --git a/tests/logrotatecase/system.toml b/tests/logrotatecase/system.toml index 9938b47c3d7..48a8e4b2a6a 100644 --- a/tests/logrotatecase/system.toml +++ b/tests/logrotatecase/system.toml @@ -61,9 +61,6 @@ service = true receives = ["netd", "launcher"] # The union its guest binaries need on this machine shape. -# `logread` is the log gate's own: a spawned test binary does not inherit a -# `SysCap` dup, so the gate that reads the kernel's records runs inside -# `test-runner` itself. # `power` is the connector `run shutdown` below asks init through. [programs.test-runner] receives = ["compositor", "soundd", "netd", "power"] diff --git a/tests/metalcase/system.toml b/tests/metalcase/system.toml index eeca4fe25ed..606871bf0dc 100644 --- a/tests/metalcase/system.toml +++ b/tests/metalcase/system.toml @@ -54,9 +54,6 @@ service = true receives = ["netd", "launcher"] # The union its guest binaries need on this machine shape. -# `logread` is the log gate's own: a spawned test binary does not inherit a -# `SysCap` dup, so the gate that reads the kernel's records runs inside -# `test-runner` itself. [programs.test-runner] receives = ["compositor", "soundd", "netd"] syscap = ["logread"] diff --git a/tests/netcase/system.toml b/tests/netcase/system.toml index 1ae7dc9ddde..211a3e55df2 100644 --- a/tests/netcase/system.toml +++ b/tests/netcase/system.toml @@ -34,9 +34,6 @@ devices = ["pci:1af4:1041"] # This is also the only config whose test binaries take the launcher path to # `Command::spawn` at all: everywhere else test-runner holds no connector and # every spawn is direct. -# `logread` is the log gate's own: a spawned test binary does not inherit a -# `SysCap` dup, so the gate that reads the kernel's records runs inside -# `test-runner` itself. [programs.test-runner] receives = ["netd", "launcher"] syscap = ["logread"] diff --git a/tests/partclaimcase/system.toml b/tests/partclaimcase/system.toml index 329040673ef..aec72307e05 100644 --- a/tests/partclaimcase/system.toml +++ b/tests/partclaimcase/system.toml @@ -29,9 +29,6 @@ syscap = ["rt"] # `device` because five of the guest binaries claim the keyboard or the mouse # and no manifest row can name them — they are not `[programs]` keys — and `dup` # because a claim moves and one boot runs several of them. -# `logread` because the log gate reads the kernel's own records and cannot be -# a spawned binary: a `SysCap` dup is not part of the namespace test-runner -# hands down. # `power` because `endowment_denied` narrows it *away* to prove the two power # syscalls refuse a capability without it, which a capability that never # carried it would make vacuous. `run shutdown` does not use it: the applet asks diff --git a/tests/sshdcase/system.toml b/tests/sshdcase/system.toml index 09320cddb9b..81b55ede0bc 100644 --- a/tests/sshdcase/system.toml +++ b/tests/sshdcase/system.toml @@ -35,9 +35,6 @@ devices = ["pci:1af4:1041"] service = true receives = ["netd", "launcher"] -# `logread` is the log gate's own: a spawned test binary does not inherit a -# `SysCap` dup, so the gate that reads the kernel's records runs inside -# `test-runner` itself. [programs.test-runner] receives = ["netd"] syscap = ["logread"] diff --git a/tests/test-durations b/tests/test-durations index af9755f3ce1..9bdd4f2e56c 100644 --- a/tests/test-durations +++ b/tests/test-durations @@ -256,9 +256,12 @@ locale_detect 9959 locale_detect_unrecognized 160 log_backing_read_error 4887 log_flush_retry 20526 +log_nested_emit 5008 log_partition_identity 9516 log_partition_layout 477 log_poll_outlives_a_close 4738 +log_reserve_window 7022 +log_reserve_window_negative 6791 log_stream 24865 log_stream_e1000e 25219 log_stream_no_listener 25182 diff --git a/tests/toyos.rs b/tests/toyos.rs index 7cfde4e6b22..34e0227f160 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -1169,6 +1169,23 @@ const MACHINE_TESTS: &[(&str, Sched, Tier)] = &[ // never classified. Same boot shape as its two neighbours — dies inside the // boot phases at the marker, no userland — so Parallel. ("nested_fault_is_recursive", Sched::Parallel, Tier::Weekly), + // The conservation law across `SYS_LOG_READ`, and the nesting gate at one + // CPU. Parallel: every verdict is a ledger the + // guest computes over its own records — every sequence number read or + // counted lost, every payload regenerated byte for byte — and not one of + // them reads a clock. A loaded host makes the producers outrun the reader + // further, which moves records from `read` into `lost` and leaves the law + // exactly where it was. + ("log_conservation_smp2", Sched::Parallel, Tier::Weekly), + ("log_nested_emit", Sched::Parallel, Tier::Weekly), + // The same interrupt one window earlier — between a record's shard-pointer + // read and its `xadd` — and its negative control, which is the only reader + // `log-unbracketed-reserve` has ever had. Parallel for + // `log_nested_emit`'s reasons: both verdicts are the guest's ledger over its + // own records, one saying the shard kept a single order and the other that + // it lost it by name, and no clock is in either. + ("log_reserve_window", Sched::Parallel, Tier::Weekly), + ("log_reserve_window_negative", Sched::Parallel, Tier::Weekly), // A guest writes a daemon-shaped line into a real capture window on purpose // and the real comparison ignores it, with the filter turned off as the // control. One boot, two `echo`s, and every verdict is a string comparison @@ -11647,6 +11664,16 @@ fn run_machine_test( // Body in `tests/common/iommu.rs`, same reason. "iommu_discovery" => common::iommu::iommu_discovery(test_config, c_bins, rust_bins), // Body in `tests/common/logread.rs`, so the hunk here stays one line. + "log_conservation_smp2" => { + common::logread::log_conservation_smp2(test_config, c_bins, rust_bins) + } + "log_nested_emit" => common::logread::log_nested_emit(test_config, c_bins, rust_bins), + "log_reserve_window" => { + common::logread::log_reserve_window(test_config, c_bins, rust_bins) + } + "log_reserve_window_negative" => { + common::logread::log_reserve_window_negative(test_config, c_bins, rust_bins) + } "log_poll_outlives_a_close" => { common::logread::log_poll_outlives_a_close(test_config, c_bins, rust_bins) } diff --git a/toyos-abi/src/syscall.rs b/toyos-abi/src/syscall.rs index f471ce741fe..42c89cc2edf 100644 --- a/toyos-abi/src/syscall.rs +++ b/toyos-abi/src/syscall.rs @@ -855,6 +855,9 @@ pub mod debug_action { /// shipped field, and the install and the close that follow are the shipped /// paths making the shipped decision (`kernel::object::handle`). pub const SLOT_TO_LAST_GENERATION: u64 = 20; + /// Emit one patterned kernel log record, `logstorm t=0 i= …`, whose + /// text the reader regenerates from its two numbers. + pub const LOG_PATTERNED: u64 = 21; } /// Every kind of kernel object, in the order the kernel's own `kobject!` diff --git a/userland/test-runner/src/log_close.rs b/userland/test-runner/src/log_close.rs index 939113d3a31..3bebf8ce14b 100644 --- a/userland/test-runner/src/log_close.rs +++ b/userland/test-runner/src/log_close.rs @@ -17,8 +17,8 @@ //! `cancel_by_source` acted on. What it proves is that the *handle* is not what the //! source's lifetime is tied to. //! -//! It runs inside `test-runner` because a `SysCap` dup is not a namespace -//! entry, so a spawned binary has none — and it needs `dup` in its +//! It runs inside `test-runner` for `log-gate`'s reason — a `SysCap` dup is not +//! a namespace entry, so a spawned binary has none — and it needs `dup` in its //! manifest row on top of `logread`, which `tests/testcases/system.toml` has. use std::process::Command; diff --git a/userland/test-runner/src/log_gate.rs b/userland/test-runner/src/log_gate.rs new file mode 100644 index 00000000000..89b4c33893b --- /dev/null +++ b/userland/test-runner/src/log_gate.rs @@ -0,0 +1,569 @@ +//! The conservation law, read through `SYS_LOG_READ` from inside `test-runner`. +//! +//! **It runs here rather than in a binary of its own, and that is capability +//! doctrine rather than convenience.** `test-runner` passes its whole +//! *namespace* to every binary it spawns, and `logread` is not a namespace +//! entry — it is a `SysCap` dup, exactly like `realtime`, which the estate does +//! not hand down either. So the gate that reads the machine's log is the one +//! process in a test image that holds the right from its own manifest row. +//! +//! **The verdict is exact, not statistical.** Every sequence number a shard +//! ever issued is either a record this reader took or one the kernel counted as +//! lost; no number is taken twice; and every storm record's text regenerates +//! byte for byte from the two numbers it declares. A torn record fails the +//! text, a lost record that is not counted fails the ledger, and a duplicated +//! one fails it the other way. +//! +//! **The storm is a thread of this process**, calling `SYS_DEBUG`'s +//! `LOG_PATTERNED` once per record and counting each call after it returns. +//! That counter, not any record, is what says the storm is over and which +//! records were read while it ran. +//! +//! **Nothing this reader waits for is a record the ring may drop.** The +//! termination condition is the *cursor*: the log has been drained and nothing +//! new has arrived for [`QUIET_READS`] reads, once the producer has returned +//! from its last call. The nesting burst's own `done` is a cross-check where it +//! survived and is never waited on. **The rule this shape exists to keep is +//! general**: a workload whose liveness depends on a record the ring is allowed +//! to drop is the same mistake wherever it appears. + +use std::collections::BTreeMap; +use std::sync::atomic::{AtomicU64, Ordering}; +use std::sync::Arc; +use std::thread::JoinHandle; +use std::time::{Duration, Instant}; + +use toyos::log::{LogTail, Record, MAX_LOG_SHARDS}; +use toyos::poller::{Poller, READABLE}; +use toyos::syscap::SysCap; +use toyos_abi::syscall::debug_action::LOG_PATTERNED; + +/// The first sequence number any shard issues — one, so a slot nothing has ever +/// written cannot read as record 0 of every shard on every boot. +/// `kernel/src/log/shard.rs`'s `FIRST_SEQ` is the other half of this constant. +const FIRST_SEQ: u64 = 1; + +/// Records per `SYS_LOG_READ`. Above the shard count, which the call refuses +/// below. +const BATCH: usize = 64; + +/// How long the whole gate may take before it gives up on a workload that never +/// finished, and it reports what it had when it did. +/// +/// **A liveness guard and never a verdict**, and it is what a shard stalled on +/// an uncommitted slot looks like from here: `drain_ordered` blocks a shard at +/// its first uncommitted record, so a writer that never publishes takes that +/// shard out of the merge for good. +/// +/// **It is the guest's own ceiling and it is the smaller of the two**: the host +/// gives the whole boot 60 s (`tests/common/logread.rs`), so what a hung gate +/// reports is this one's message and this one's elapsed time. +const CEILING: Duration = Duration::from_secs(30); + +/// Empty reads in a row before the log is called quiet. +/// +/// **Eight, each after a bounded park on the readiness source**, because a +/// single empty read can land while a producer is inside its publication +/// bracket: `drain_ordered` stops that shard and says nothing about it, so a +/// ledger closed on the first empty read can be short by what was in flight. +const QUIET_READS: u32 = 8; + +/// How long a park on the log's readiness source waits before giving up on it. +/// +/// It is the gate's pacing as much as its wait: with nothing left to say the +/// kernel posts nothing, and eight of these is the whole tail of the run. +const IDLE_NANOS: u64 = 2_000_000; + +/// How long the deterministic readiness round waits for its own record. +/// +/// Generous, because what it bounds is a scheduler getting round to a child's +/// exit — not the post, which is one function call after the drain. A gate +/// that timed out here would be reporting the host's load and not the kernel's. +const READINESS_WAIT_NANOS: u64 = 2_000_000_000; + +/// The poll's token. One handle is watched, so it identifies the round rather +/// than the source. +const LOG_TOKEN: u64 = 1; + +/// `kernel/src/log/storm.rs`'s `PAYLOAD`. +const PAYLOAD: usize = 96; + +/// The producer id `LOG_PATTERNED`'s records declare. +const STORM_PRODUCER: u64 = 0; + +/// Records the storm emits: past a shard's 512, so the ring's drop-oldest path +/// is reachable. +const STORM_RECORDS: u64 = 1024; + +/// `kernel/src/log/nested.rs`'s `NEST_PRODUCER`: the burst an interrupt handler +/// emits declares itself as this, so it goes through the same per-producer +/// ledger and the same byte-for-byte regeneration as a storm's records. +const NEST_PRODUCER: u64 = u64::MAX; + +/// One producer's ledger. +#[derive(Default)] +struct Producer { + /// The next index expected from this producer, and `None` before its first + /// record. + next: Option, + read: u64, +} + +/// One shard's ledger: the sequence numbers the kernel issued on that CPU. +#[derive(Default, Clone, Copy)] +struct ShardLedger { + first: Option, + next: u64, + read: u64, + /// Sequence numbers this reader never saw, derived from the gaps between + /// the ones it did. + gaps: u64, + last_at_ns: u64, +} + +/// The gate over whatever the boot's actuators write. +pub fn run(cap: Option<&SysCap>) -> i32 { + report(cap, false) +} + +/// The gate with a storm beside it. +pub fn run_storm(cap: Option<&SysCap>) -> i32 { + report(cap, true) +} + +fn report(cap: Option<&SysCap>, storm: bool) -> i32 { + let Some(cap) = cap else { + println!("log-gate: this program holds no system capability, so it holds no `logread`"); + return 1; + }; + match gate(cap, storm) { + Ok(()) => 0, + Err(e) => { + println!("log-gate: FAILED: {e}"); + 1 + } + } +} + +struct Run { + shards: [ShardLedger; MAX_LOG_SHARDS], + producers: BTreeMap, + /// The nesting gate's declared burst, once its `done` has been read. A + /// cross-check and never a requirement: the burst laps its shard, so the + /// ring is allowed to drop it. + nest: Option, + records: u64, + reads: u64, + /// Storm records taken by a read after which the producer had not yet + /// returned from its last call. **Zero would mean this reader raced + /// nothing**, which is the one way a green conservation law says nothing + /// at all. + concurrent: u64, + /// Times the log's readiness source completed a poll. + completions: u64, +} + +fn gate(cap: &SysCap, storm: bool) -> Result<(), String> { + let mut tail = LogTail::new(); + let mut buf = [Record::EMPTY; BATCH]; + let mut run = Run { + shards: [ShardLedger::default(); MAX_LOG_SHARDS], + producers: BTreeMap::new(), + nest: None, + records: 0, + reads: 0, + concurrent: 0, + completions: 0, + }; + + // **Armed before the storm starts and kept armed**, which is what makes a + // completion deterministic rather than lucky: the storm's records are + // committed after this poll was registered, and re-arming after every + // harvest means a post landing *during* the storm finds a pending poll + // rather than a gap. + // + // **It used to arm only on an empty read, and that made the assertion + // depend on the shape of the boot.** During a storm no read is empty, so the + // only poll in flight was the one from before the first read; whether it was + // ever completed came down to when `klogd` happened to get a turn. At + // `--smp 4` that measured `wakes=1`, and at `--smp 8` with `/system/bin/logd` also + // reading the cursor it measured **zero** — a red about scheduling rather + // than about the readiness source. `min_complete` 0 with no timeout submits + // and harvests without blocking, so this costs one syscall a round. + let poller = Poller::new(1); + poller.watch(cap, READABLE, LOG_TOKEN); + let mut armed = true; + + let produced = Arc::new(AtomicU64::new(0)); + let mut producer = storm.then(|| spawn_producer(Arc::clone(&produced))); + let target = if storm { STORM_RECORDS } else { 0 }; + + let mut quiet = 0u32; + let started = Instant::now(); + loop { + if !armed { + poller.watch(cap, READABLE, LOG_TOKEN); + armed = true; + } + poller.wait(0, 0, |token| { + assert_eq!(token, LOG_TOKEN, "the log poll completed with another token"); + run.completions += 1; + armed = false; + }); + + let batch = tail + .read(cap, &mut buf) + .map_err(|e| format!("SYS_LOG_READ refused a {BATCH}-record buffer: {e:?}"))?; + // Loaded after the read returned: below `target` here is below it for the whole read. + let during = produced.load(Ordering::Acquire); + run.reads += 1; + if batch.is_empty() { + quiet += 1; + } else { + quiet = 0; + run.records += batch.len() as u64; + } + + let storm_before = storm_read(&run); + for record in batch { + account(record, &mut run)?; + } + if during < target { + run.concurrent += storm_read(&run) - storm_before; + } + + let finished = produced.load(Ordering::Acquire) == target; + if quiet >= QUIET_READS && finished { + break; + } + // A producer that returned short of `target` said why; waiting out the ceiling would lose it. + if !finished && producer.as_ref().is_some_and(JoinHandle::is_finished) { + join(producer.take())?; + } + if started.elapsed() > CEILING { + return Err(format!( + "gave up after {:?}: {} records over {} reads, the producer at {} of {target}", + started.elapsed(), + run.records, + run.reads, + produced.load(Ordering::Acquire), + )); + } + if batch.is_empty() { + // **Nothing new, so park on the readiness source rather than spin.** + // `SYS_LOG_READ` never blocks by design; this is the other half of + // that design, and the timeout is what bounds a machine that has + // nothing left to say. The poll is already armed by the top of the + // loop, so this parks on it rather than adding a second. + poller.wait(1, IDLE_NANOS, |token| { + assert_eq!(token, LOG_TOKEN, "the log poll completed with another token"); + run.completions += 1; + armed = false; + }); + } + } + join(producer.take())?; + + // **The readiness source, observed deterministically rather than raced.** + // If the reads above completed no poll, make one: a child that runs and + // exits commits `process.rs`'s `exit:` line, which is one kernel record + // from userland with no actuator and no privilege behind it. + if run.completions == 0 { + let mut child = std::process::Command::new("/system/bin/echo") + .arg("log-gate") + .spawn() + .map_err(|e| format!("the record-making child would not start: {e}"))?; + let _ = child.wait(); + if !armed { + poller.watch(cap, READABLE, LOG_TOKEN); + } + poller.wait(1, READINESS_WAIT_NANOS, |token| { + assert_eq!(token, LOG_TOKEN, "the log poll completed with another token"); + run.completions += 1; + }); + } + + verdict(&tail, &run, storm) +} + +/// The storm: one kernel record per call, counted after each call returns. +fn spawn_producer(produced: Arc) -> JoinHandle> { + std::thread::spawn(move || { + for index in 0..STORM_RECORDS { + let answer = toyos_abi::syscall::debug_with(LOG_PATTERNED, index); + if answer != 0 { + return Err(format!( + "SYS_DEBUG LOG_PATTERNED answered {answer:#x} at index {index}" + )); + } + produced.fetch_add(1, Ordering::Release); + } + Ok(()) + }) +} + +fn join(producer: Option>>) -> Result<(), String> { + match producer.map(JoinHandle::join) { + None | Some(Ok(Ok(()))) => Ok(()), + Some(Ok(Err(e))) => Err(e), + Some(Err(_)) => Err("the producer thread panicked".into()), + } +} + +fn storm_read(run: &Run) -> u64 { + run.producers.get(&STORM_PRODUCER).map_or(0, |p| p.read) +} + +/// Put one record through both ledgers. +fn account(record: &Record, run: &mut Run) -> Result<(), String> { + let cpu = record.cpu as usize; + let ledger = run.shards.get_mut(cpu).ok_or_else(|| { + format!("a record claims cpu{cpu}, past the ABI's {MAX_LOG_SHARDS} shards") + })?; + + match ledger.first { + None => ledger.first = Some(record.seq), + Some(_) => { + if record.seq < ledger.next { + return Err(format!( + "cpu{cpu} answered seq {} after seq {}: a sequence number was read twice, \ + or out of order, within one shard", + record.seq, + ledger.next - 1 + )); + } + ledger.gaps += record.seq - ledger.next; + } + } + if record.at_ns < ledger.last_at_ns { + return Err(format!( + "cpu{cpu} seq {} is stamped {} ns, behind the {} ns of the record before it — within \ + a shard the sequence order is the timestamp order, and `emit` stamps inside the \ + same bracket it reserves in", + record.seq, record.at_ns, ledger.last_at_ns + )); + } + ledger.last_at_ns = record.at_ns; + ledger.next = record.seq + 1; + ledger.read += 1; + + let message = record.message(); + if message.len() != record.len as usize { + return Err(format!( + "cpu{cpu} seq {} declares {} message bytes and decodes to {}", + record.seq, + record.len, + message.len() + )); + } + + if let Some(rest) = message.strip_prefix("lognest done ") { + let emitted = rest + .split_whitespace() + .find_map(|w| w.strip_prefix("emitted=")) + .and_then(|v| v.parse::().ok()) + .ok_or_else(|| format!("`lognest done` is unreadable: {rest}"))?; + if run.nest.replace(emitted).is_some() { + return Err("the nesting gate said `done` twice".into()); + } + return Ok(()); + } + if message.starts_with("lognest ") { + // `start` and `outer`. Both are records like any other and the burst + // laps the shard they are in, so both are *expected* to be dropped — + // which is the ring's declared policy and not a loss of evidence. + return Ok(()); + } + let Some(rest) = message.strip_prefix("logstorm t=") else { + // An ordinary kernel record. It is in the shard ledger above, which is + // where the conservation law is computed; it declares nothing this gate + // could regenerate. + return Ok(()); + }; + + let (thread, index) = parse_record(rest)?; + if thread != STORM_PRODUCER && thread != NEST_PRODUCER { + return Err(format!( + "cpu{cpu} seq {} names producer t={thread}, which no gate runs", + record.seq + )); + } + let expected = storm_message(thread, index); + if message != expected { + return Err(format!( + "cpu{cpu} seq {} is a torn or mixed storm record\n read: {message}\n expected: {expected}", + record.seq + )); + } + let producer = run.producers.entry(thread).or_default(); + if let Some(next) = producer.next { + if index < next { + return Err(format!( + "producer t={thread} answered index {index} after {}: one record's body was \ + published under another record's sequence number", + next - 1 + )); + } + } + producer.next = Some(index + 1); + producer.read += 1; + Ok(()) +} + +/// The line a storm record carries, from the two numbers that identify it. +/// +/// **The kernel builds this and the reader rebuilds it**, so a body half +/// overwritten by another generation fails on the byte that differs rather than +/// on a checksum that might not have covered it. `kernel/src/log/storm.rs` is +/// the other half; a disagreement between the two formulas reds loudly rather +/// than passing quietly. +fn storm_message(thread: u64, index: u64) -> String { + let checksum = (thread.wrapping_mul(0x9E37_79B9_7F4A_7C15) + ^ index.wrapping_mul(0xC2B2_AE3D_27D4_EB4F)) + .rotate_left(17); + let payload: String = (0..PAYLOAD) + .map(|offset| (b'a' + (checksum.wrapping_add(offset as u64) % 26) as u8) as char) + .collect(); + format!("logstorm t={thread} i={index} k={checksum:016x} {payload}") +} + +fn parse_record(rest: &str) -> Result<(u64, u64), String> { + let mut words = rest.split_whitespace(); + let thread = words + .next() + .and_then(|w| w.parse::().ok()) + .ok_or_else(|| format!("a storm record names no thread: {rest}"))?; + let index = words + .next() + .and_then(|w| w.strip_prefix("i=")) + .and_then(|w| w.parse::().ok()) + .ok_or_else(|| format!("a storm record names no index: {rest}"))?; + Ok((thread, index)) +} + +/// The conservation law, and everything the gate prints for a reader of its +/// output. +fn verdict(tail: &LogTail, run: &Run, storm: bool) -> Result<(), String> { + let seen: Vec = + (0..MAX_LOG_SHARDS).filter(|&i| run.shards[i].first.is_some()).collect(); + if seen.is_empty() { + return Err("no shard answered a single record".into()); + } + if tail.shards() as usize != seen.len() { + return Err(format!( + "the kernel says this machine has {} shard(s) and {} answered a record", + tail.shards(), + seen.len() + )); + } + + // **`records_emitted == records_read + lost`, with the sequence numbers as + // the ledger.** Every number a shard issued is either a record this reader + // took or one it never saw, and the second is what the kernel derives + // `lost` from — out of `head` and `next`, two numbers that have to be right + // anyway, rather than out of a producer-side counter that could drift from + // the ring. + let mut computed = 0u64; + for &i in &seen { + let first = run.shards[i].first.expect("`seen` is the shards with a first record"); + computed += first - FIRST_SEQ + run.shards[i].gaps; + } + let reported = tail.lost(); + if computed != reported { + let per_shard: Vec = seen + .iter() + .map(|&i| { + format!( + "cpu{i}: first={} last={} read={} gaps={}", + run.shards[i].first.unwrap_or(0), + run.shards[i].next.saturating_sub(1), + run.shards[i].read, + run.shards[i].gaps + ) + }) + .collect(); + return Err(format!( + "conservation failed: the sequence numbers say {computed} record(s) were never read \ + and the kernel counted {reported}\n {}", + per_shard.join("\n ") + )); + } + + let read_total = storm_read(run); + if storm { + if read_total == 0 { + return Err("the storm ran and this reader read none of it".into()); + } + let next = run.producers.get(&STORM_PRODUCER).and_then(|p| p.next).unwrap_or(0); + if next > STORM_RECORDS { + return Err(format!( + "the storm answered index {} of {STORM_RECORDS} emitted", + next - 1 + )); + } + if run.concurrent == 0 { + return Err( + "every storm record was read after the producer had finished, so this reader \ + raced nothing" + .into(), + ); + } + // The readiness source, asserted where it is reachable: the poll was + // armed before the storm started, so the records that answer it were + // committed after it was registered. + if run.completions == 0 { + return Err( + "the log's readiness source completed no poll — not across the storm, and not on \ + the record a child's exit commits afterwards either" + .into(), + ); + } + } + + if let Some(burst) = run.producers.get(&NEST_PRODUCER) { + // The burst's own `done` is a cross-check where it survived, and the + // ledger's own floor where it did not. The burst laps its shard by + // construction, so a reader that required that record would be + // requiring one the design says may go. + let declared = match (run.nest, burst.next) { + (Some(declared), _) => declared, + (None, Some(next)) => next, + (None, None) => { + return Err("the nesting burst was seen and named no index".into()) + } + }; + if burst.read == 0 { + return Err("the nesting burst was injected and none of it was read".into()); + } + if burst.next.is_some_and(|next| next > declared) { + return Err(format!( + "the nesting burst answered index {} of a declared {declared}", + burst.next.unwrap_or(0) - 1 + )); + } + println!( + "log-gate: nest declared={declared} read={} dropped={}", + burst.read, + declared - burst.read, + ); + } + + println!( + "log-gate: {} record(s) over {} read(s) from {} shard(s); lost={reported}, and the \ + sequence numbers say the same", + run.records, + run.reads, + seen.len() + ); + if storm { + println!( + "log-gate: storm emitted={STORM_RECORDS} read={read_total} dropped={} \ + concurrent={} wakes={}", + STORM_RECORDS - read_total, + run.concurrent, + run.completions, + ); + } + println!("log-gate: OK"); + Ok(()) +} diff --git a/userland/test-runner/src/main.rs b/userland/test-runner/src/main.rs index c90160701a4..69c328db6cb 100644 --- a/userland/test-runner/src/main.rs +++ b/userland/test-runner/src/main.rs @@ -1,5 +1,6 @@ mod kbd_close; mod log_close; +mod log_gate; use std::io::{self, BufRead, Write}; use std::os::toyos::process::{ChildExt, CommandExt}; @@ -27,6 +28,8 @@ use toyos::syscap::SysCap; /// binary's stdin is a pipe (see the `Stdio::piped()` below), so the object the /// collision is about does not exist in one. const BUILTINS: &[(&str, fn(Option<&SysCap>) -> i32)] = &[ + ("log-gate", log_gate::run), + ("log-storm", log_gate::run_storm), ("log-close", log_close::run), ("kbd-close", kbd_close::run), ]; From daca0395cc6729ee12c02f6d6de7c103eab6c282 Mon Sep 17 00:00:00 2001 From: japabu Date: Tue, 29 Sep 2026 02:35:09 +0200 Subject: [PATCH 3/4] log_conservation_smp2: the storm hands over to the reader, so a read lands inside it on every run At 8910046b the gate's non-vacuity check ("concurrent", storm records taken by a read while the producer had not finished) held only when the scheduler happened to interleave the reader and the producer. One TCG run at --smp 2 had the producer finish all 1024 calls before the reader reached a storm record, and the gate refused: a timing verdict, which main's #562 rules out of QEMU tests. The producer now stops after HANDOVER (64) records and waits on a channel until the reader has taken a storm record, then emits the rest. The reader sends only after it has loaded the producer's counter for that read, so that read counts as concurrent on every run: 64 is below the target, and the producer cannot move until the send. The wait is bounded by HANDOVER_WAIT (30 s, inside the host's 60 s) and fails loudly, naming the reader that never arrived. Controls, deterministic both: - join the producer before the first read: the producer times out at the handover and the gate reports it; - the same with the handover deleted: the producer finishes before any read and the concurrent check refuses, as at 8910046b. Co-Authored-By: Claude Opus 5.5 --- userland/test-runner/src/log_gate.rs | 43 ++++++++++++++++++++++++---- 1 file changed, 38 insertions(+), 5 deletions(-) diff --git a/userland/test-runner/src/log_gate.rs b/userland/test-runner/src/log_gate.rs index bafd4a24007..60fa9d3b1bb 100644 --- a/userland/test-runner/src/log_gate.rs +++ b/userland/test-runner/src/log_gate.rs @@ -17,7 +17,9 @@ //! **The storm is a thread of this process**, calling `SYS_DEBUG`'s //! `LOG_PATTERNED` once per record and counting each call after it returns. //! That counter, not any record, is what says the storm is over and which -//! records were read while it ran. +//! records were read while it ran. **The interleave is an event, not a +//! schedule**: the producer stops after [`HANDOVER`] records until this reader +//! has taken one of them, so a read lands inside the storm on every run. //! //! **Nothing this reader waits for is a record the ring may drop.** The //! termination condition is the *cursor*: the log has been drained and nothing @@ -29,8 +31,10 @@ use std::collections::BTreeMap; use std::sync::atomic::{AtomicU64, Ordering}; +use std::sync::mpsc::{self, Receiver, RecvTimeoutError}; use std::sync::Arc; use std::thread::JoinHandle; +use std::time::Duration; use toyos::log::{LogTail, Record, MAX_LOG_SHARDS}; use toyos::poller::{Poller, READABLE}; @@ -81,6 +85,14 @@ const STORM_PRODUCER: u64 = 0; /// is reachable. const STORM_RECORDS: u64 = 1024; +/// Storm records emitted before the producer waits for this reader to take +/// one: far under a shard's 512, so the ring still holds them when it arrives. +const HANDOVER: u64 = 64; + +/// How long the producer waits at [`HANDOVER`]. A liveness bound that names +/// the reader which never arrived, inside the host's 60 s for the whole boot. +const HANDOVER_WAIT: Duration = Duration::from_secs(30); + /// `kernel/src/log/nested.rs`'s `NEST_PRODUCER`: the burst an interrupt handler /// emits declares itself as this, so it goes through the same per-producer /// ledger and the same byte-for-byte regeneration as a storm's records. @@ -143,7 +155,7 @@ struct Run { /// Storm records taken by a read after which the producer had not yet /// returned from its last call. **Zero would mean this reader raced /// nothing**, which is the one way a green conservation law says nothing - /// at all. + /// at all; the handover makes it the first batch at least. concurrent: u64, /// Times the log's readiness source completed a poll. completions: u64, @@ -181,7 +193,9 @@ fn gate(cap: &SysCap, storm: bool) -> Result<(), String> { let mut armed = true; let produced = Arc::new(AtomicU64::new(0)); - let mut producer = storm.then(|| spawn_producer(Arc::clone(&produced))); + let (handover, taken) = mpsc::sync_channel(1); + let mut handover = storm.then_some(handover); + let mut producer = storm.then(|| spawn_producer(Arc::clone(&produced), taken)); let target = if storm { STORM_RECORDS } else { 0 }; let mut quiet = 0u32; @@ -216,6 +230,13 @@ fn gate(cap: &SysCap, storm: bool) -> Result<(), String> { if during < target { run.concurrent += storm_read(&run) - storm_before; } + // Sent only after `during` was loaded, so the read that took this record counts as concurrent. + if let Some(handover) = handover.take_if(|_| storm_read(&run) > 0) { + // Refused only once the producer has returned, and its join says why. + if handover.send(()).is_err() { + join(producer.take())?; + } + } let finished = produced.load(Ordering::Acquire) == target; if quiet >= QUIET_READS && finished { @@ -262,10 +283,22 @@ fn gate(cap: &SysCap, storm: bool) -> Result<(), String> { verdict(&tail, &run, storm) } -/// The storm: one kernel record per call, counted after each call returns. -fn spawn_producer(produced: Arc) -> JoinHandle> { +/// The storm: one kernel record per call, counted after each call returns, +/// paused at [`HANDOVER`] until the reader has taken one. +fn spawn_producer(produced: Arc, taken: Receiver<()>) -> JoinHandle> { std::thread::spawn(move || { for index in 0..STORM_RECORDS { + if index == HANDOVER { + taken.recv_timeout(HANDOVER_WAIT).map_err(|e| match e { + RecvTimeoutError::Timeout => format!( + "the reader took none of the storm's first {HANDOVER} records within \ + {HANDOVER_WAIT:?}" + ), + RecvTimeoutError::Disconnected => { + "the reader ended before it took a storm record".into() + } + })?; + } let answer = toyos_abi::syscall::debug_with(LOG_PATTERNED, index); if answer != 0 { return Err(format!( From 32d179268f7af6d688a70546af997b49be7a5a07 Mon Sep 17 00:00:00 2001 From: japabu Date: Tue, 29 Sep 2026 05:34:05 +0200 Subject: [PATCH 4/4] log_conservation_smp2: the lap and the overlap are events, and no guest clock decides a verdict Round 3's review of #586 found three holes in the storm gate. - The producer's 30 s `recv_timeout` at the handover was an in-guest deadline deciding a verdict, which #562 rules out. It is `recv` now: only a disconnect is an error, and the host's `CEILING` reds a reader that never arrives. - `concurrent` was at least one batch by construction: the handover read counted even while the producer was parked. A read now counts only if the producer's counter moved across it, and only after the lap. The producer emits until such a read has happened and the reader sets `stop`, so the overlap is waited on rather than sampled. The guest's "raced nothing" refusal could no longer fire and is deleted; the host still refuses `concurrent=0`. - `lost` was zero on two of three runs, so read.rs's `lost +=` was measured by nothing. After the handover the reader now blocks until the producer has emitted `shards * 512 + 1` more records, which puts more than a shard's worth into one shard whichever CPUs the producer ran on, and the host asserts `lost > 0`. `STORM_RECORDS` goes: the emitted count is the producer's counter. REMOVEs: the `LOG_PATTERNED` arm's comment, the "rather than on a kernel thread" clause in `log::user::read`, the unchecked "runs beside it" and "a read lands inside the storm" claims, `STORM_SETTLE` in the timing-verdicts issue, and the narration in the logread-grants issue. The echo-spawn and negative-control-timeout issues are back to main's text. Co-Authored-By: Claude Opus 5.5 --- ...-negative-times-out-beside-other-guests.md | 4 +- ...rdicts-ruled-off-qemu-have-no-metal-arm.md | 2 +- ...holds-logread-where-no-log-builtin-runs.md | 4 +- ...was-refused-with-an-error-nothing-names.md | 3 +- kernel/src/log/user.rs | 2 +- kernel/src/syscall/dispatch.rs | 2 - tests/common/logread.rs | 15 +- userland/test-runner/src/log_gate.rs | 136 +++++++++--------- 8 files changed, 85 insertions(+), 83 deletions(-) diff --git a/issues/build/log-reserve-window-negative-times-out-beside-other-guests.md b/issues/build/log-reserve-window-negative-times-out-beside-other-guests.md index 45834839b21..de18c528061 100644 --- a/issues/build/log-reserve-window-negative-times-out-beside-other-guests.md +++ b/issues/build/log-reserve-window-negative-times-out-beside-other-guests.md @@ -23,5 +23,5 @@ hypothesis, and one red at 18x its price is not a rate. Exit: a rate — the same suite run repeatedly with and without a second worktree's build on the host — that says whether this is contention the harness -should schedule around or a defect in the guest's own boot, and the name's -`tests/toyos.rs` `MACHINE_TESTS` row is either re-tiered or the cause fixed. +should schedule around or a defect in the guest's own boot, and the name is +either re-tiered or fixed at the cause. diff --git a/issues/build/timing-verdicts-ruled-off-qemu-have-no-metal-arm.md b/issues/build/timing-verdicts-ruled-off-qemu-have-no-metal-arm.md index 41e7c2d7def..3d912143db2 100644 --- a/issues/build/timing-verdicts-ruled-off-qemu-have-no-metal-arm.md +++ b/issues/build/timing-verdicts-ruled-off-qemu-have-no-metal-arm.md @@ -73,7 +73,7 @@ the event it stands for has no word a test can read: `INTO_WINDOW`, and `redirty_mid_flush`'s swept delay. - Drains of work handed to another thread: the 200 ms `iod` drains in `writeback_durability` and `home_backing_revoked`, `fat_backing_revoked`'s - drain, and `log_gate`'s `STORM_SETTLE` and `QUIET_READS`. + drain, and `log_gate`'s `QUIET_READS`. - Product clocks a QEMU boot races: `boot_deadline_ends_a_wedge`'s 15 s deadline against the job list reaching its shutdown, `hard_lockup_ends_a_deaf_cpu`'s 30 s, `loader_watchdog_arms` reading diff --git a/issues/isolation/test-runner-holds-logread-where-no-log-builtin-runs.md b/issues/isolation/test-runner-holds-logread-where-no-log-builtin-runs.md index 2e267a87c17..7d551f411f6 100644 --- a/issues/isolation/test-runner-holds-logread-where-no-log-builtin-runs.md +++ b/issues/isolation/test-runner-holds-logread-where-no-log-builtin-runs.md @@ -13,9 +13,7 @@ read the log inside test-runner (`log-gate`, `log-storm`, `log-close`, `tests/toyos.rs`'s one job list naming `log-close` is `tests/testcases`). Seven other manifests grant it anyway: `tests/partclaimcase`, `tests/blockdcase`, `tests/doommusiccase`, `tests/logrotatecase`, `tests/metalcase`, `tests/netcase` -and `tests/sshdcase`. Their comments gave the -log gate as the reason, which none of those boots runs; the comments are gone -and the grants are not. +and `tests/sshdcase`. `partclaimcase` and `blockdcase` also grant `dup`, so there every child test-runner spawns receives a `SysCap` duplicate carrying `LOG` as well. diff --git a/issues/kernel/a-spawn-of-echo-was-refused-with-an-error-nothing-names.md b/issues/kernel/a-spawn-of-echo-was-refused-with-an-error-nothing-names.md index a9680ea1d88..e5b85565832 100644 --- a/issues/kernel/a-spawn-of-echo-was-refused-with-an-error-nothing-names.md +++ b/issues/kernel/a-spawn-of-echo-was-refused-with-an-error-nothing-names.md @@ -39,8 +39,7 @@ onto `cf715c49` as a checked patch, four more sessions of the same suite had it green 4/4. The branch touches nothing on the spawn path. Neither arm reproduced it, so neither arm explains it. -**Exit.** The refusal named. The cheapest step is that the message at -`userland/test-runner/src/log_gate.rs`'s `/system/bin/echo` spawn carry +**Exit.** The refusal named. The cheapest step is that the message carry `e.raw_os_error()` — `other error` is a message that costs a whole run to learn nothing from — and the next sighting then says which refusal it was. Until then the rate is one guest in one shard of one run, and its `ALONE` diff --git a/kernel/src/log/user.rs b/kernel/src/log/user.rs index c848e166f24..eb76c13c2a9 100644 --- a/kernel/src/log/user.rs +++ b/kernel/src/log/user.rs @@ -46,7 +46,7 @@ pub fn read( out: &mut UserBytesMut, capacity: usize, ) -> Result { - // Run once, inside the first read's own syscall rather than on a kernel thread; `log::nested` picks the window from whichever actuator is armed. + // Run once, inside the first read's own syscall; `log::nested` picks the window from whichever actuator is armed. #[cfg(feature = "boot-actuators")] if crate::actuator::log_nested_emit() || crate::actuator::log_nested_reserve() { super::nested::start_once(); diff --git a/kernel/src/syscall/dispatch.rs b/kernel/src/syscall/dispatch.rs index c582a56c9cf..313f23aed2c 100644 --- a/kernel/src/syscall/dispatch.rs +++ b/kernel/src/syscall/dispatch.rs @@ -602,8 +602,6 @@ pub(crate) fn syscall_dispatch(num: u64, a1: u64, a2: u64, a3: u64, a4: u64) -> None => SyscallError::InvalidArgument.to_u64(), } } - // Kernel records at the rate a tight loop makes them, from a preemptible userland - // thread beside the reader: the load the log gate's conservation law is read under. DA::LOG_PATTERNED => { crate::log::storm::emit_patterned(0, a2); 0 diff --git a/tests/common/logread.rs b/tests/common/logread.rs index 410a53c0df0..ba10d353240 100644 --- a/tests/common/logread.rs +++ b/tests/common/logread.rs @@ -80,28 +80,29 @@ fn conservation( } // Non-vacuity, and it is the half a green law cannot supply: a reader that // took every record after the storm had ended has proved nothing about - // concurrent producers. + // concurrent producers, and one the ring never lapped has proved nothing + // about `lost`. let concurrent = report.get("concurrent")?; let dropped = report.get("dropped")?; let read = report.get("read")?; - if concurrent == 0 || read == 0 { + let lost = report.get("lost")?; + if concurrent == 0 || read == 0 || lost == 0 { return Err(format!( - "--smp {smp} read {read} record(s), {concurrent} of them while the storm ran\n{}", + "--smp {smp} read {read} record(s), {concurrent} of them while the storm ran, and \ + lost {lost}\n{}", report.stdout )); } eprintln!( " [log] smp={smp}: emitted={} read={read} dropped={dropped} concurrent={concurrent} \ - lost={} wakes={}", + lost={lost} wakes={}", report.get("emitted")?, - report.get("lost")?, report.get("wakes")?, ); Ok(()) } -/// **`--smp 2`**, so the producer thread has a CPU the reader is not on and -/// runs beside it rather than only between its quanta. +/// **`--smp 2`**, so the producer thread has a CPU the reader is not on. pub fn log_conservation_smp2( test_config: &Path, c_bins: &[(String, Vec)], diff --git a/userland/test-runner/src/log_gate.rs b/userland/test-runner/src/log_gate.rs index 60fa9d3b1bb..b8723d90d1e 100644 --- a/userland/test-runner/src/log_gate.rs +++ b/userland/test-runner/src/log_gate.rs @@ -16,10 +16,11 @@ //! //! **The storm is a thread of this process**, calling `SYS_DEBUG`'s //! `LOG_PATTERNED` once per record and counting each call after it returns. -//! That counter, not any record, is what says the storm is over and which -//! records were read while it ran. **The interleave is an event, not a -//! schedule**: the producer stops after [`HANDOVER`] records until this reader -//! has taken one of them, so a read lands inside the storm on every run. +//! **Every interleave the verdict rests on is an event, not a schedule**: the +//! producer stops after [`HANDOVER`] records until this reader has taken one; +//! this reader then reads nothing until the producer has emitted enough more to +//! lap its cursor on some shard, so `lost` is never zero; and the producer then +//! emits until a read has taken storm records while its counter moved. //! //! **Nothing this reader waits for is a record the ring may drop.** The //! termination condition is the *cursor*: the log has been drained and nothing @@ -30,11 +31,10 @@ //! to drop is the same mistake wherever it appears. use std::collections::BTreeMap; -use std::sync::atomic::{AtomicU64, Ordering}; -use std::sync::mpsc::{self, Receiver, RecvTimeoutError}; +use std::sync::atomic::{AtomicBool, AtomicU64, Ordering}; +use std::sync::mpsc::{self, Receiver, SyncSender}; use std::sync::Arc; use std::thread::JoinHandle; -use std::time::Duration; use toyos::log::{LogTail, Record, MAX_LOG_SHARDS}; use toyos::poller::{Poller, READABLE}; @@ -81,17 +81,14 @@ const PAYLOAD: usize = 96; /// The producer id `LOG_PATTERNED`'s records declare. const STORM_PRODUCER: u64 = 0; -/// Records the storm emits: past a shard's 512, so the ring's drop-oldest path -/// is reachable. -const STORM_RECORDS: u64 = 1024; - /// Storm records emitted before the producer waits for this reader to take /// one: far under a shard's 512, so the ring still holds them when it arrives. const HANDOVER: u64 = 64; -/// How long the producer waits at [`HANDOVER`]. A liveness bound that names -/// the reader which never arrived, inside the host's 60 s for the whole boot. -const HANDOVER_WAIT: Duration = Duration::from_secs(30); +/// `kernel/src/log/shard.rs`'s `SHARD_RECORDS`: one more than `shards` times +/// this, emitted between two reads, puts more than a shard's worth into one +/// shard, whichever CPUs the producer ran on. +const SHARD_RECORDS: u64 = 512; /// `kernel/src/log/nested.rs`'s `NEST_PRODUCER`: the burst an interrupt handler /// emits declares itself as this, so it goes through the same per-producer @@ -152,10 +149,8 @@ struct Run { nest: Option, records: u64, reads: u64, - /// Storm records taken by a read after which the producer had not yet - /// returned from its last call. **Zero would mean this reader raced - /// nothing**, which is the one way a green conservation law says nothing - /// at all; the handover makes it the first batch at least. + /// Storm records taken, after the lap, by a read across which the + /// producer's counter moved. concurrent: u64, /// Times the log's readiness source completed a poll. completions: u64, @@ -193,10 +188,13 @@ fn gate(cap: &SysCap, storm: bool) -> Result<(), String> { let mut armed = true; let produced = Arc::new(AtomicU64::new(0)); + let stop = Arc::new(AtomicBool::new(false)); let (handover, taken) = mpsc::sync_channel(1); + let (lap, lapped) = mpsc::sync_channel(1); let mut handover = storm.then_some(handover); - let mut producer = storm.then(|| spawn_producer(Arc::clone(&produced), taken)); - let target = if storm { STORM_RECORDS } else { 0 }; + let mut producer = storm + .then(|| spawn_producer(Arc::clone(&produced), Arc::clone(&stop), taken, lap)); + let mut after_lap = false; let mut quiet = 0u32; loop { @@ -210,11 +208,11 @@ fn gate(cap: &SysCap, storm: bool) -> Result<(), String> { armed = false; }); + let before = produced.load(Ordering::Acquire); let batch = tail .read(cap, &mut buf) .map_err(|e| format!("SYS_LOG_READ refused a {BATCH}-record buffer: {e:?}"))?; - // Loaded after the read returned: below `target` here is below it for the whole read. - let during = produced.load(Ordering::Acquire); + let moved = produced.load(Ordering::Acquire) != before; run.reads += 1; if batch.is_empty() { quiet += 1; @@ -227,25 +225,24 @@ fn gate(cap: &SysCap, storm: bool) -> Result<(), String> { for record in batch { account(record, &mut run)?; } - if during < target { - run.concurrent += storm_read(&run) - storm_before; + let took = storm_read(&run) - storm_before; + if after_lap && moved && took > 0 { + run.concurrent += took; + stop.store(true, Ordering::Release); } - // Sent only after `during` was loaded, so the read that took this record counts as concurrent. if let Some(handover) = handover.take_if(|_| storm_read(&run) > 0) { - // Refused only once the producer has returned, and its join says why. - if handover.send(()).is_err() { - join(producer.take())?; - } + let records = u64::from(tail.shards()) * SHARD_RECORDS + 1; + handover.send(records).map_err(|_| ended(producer.take()))?; + lapped.recv().map_err(|_| ended(producer.take()))?; + after_lap = true; } - let finished = produced.load(Ordering::Acquire) == target; - if quiet >= QUIET_READS && finished { - break; - } - // A producer that returned short of `target` said why; waiting out the host's ceiling would lose it. - if !finished && producer.as_ref().is_some_and(JoinHandle::is_finished) { + if producer.as_ref().is_some_and(JoinHandle::is_finished) { join(producer.take())?; } + if quiet >= QUIET_READS && producer.is_none() { + break; + } if batch.is_empty() { // **Nothing new, so park on the readiness source rather than spin.** // `SYS_LOG_READ` never blocks by design; this is the other half of @@ -259,7 +256,7 @@ fn gate(cap: &SysCap, storm: bool) -> Result<(), String> { }); } } - join(producer.take())?; + let emitted = produced.load(Ordering::Acquire); // **The readiness source, observed deterministically rather than raced.** // If the reads above completed no poll, make one: a child that runs and @@ -280,37 +277,53 @@ fn gate(cap: &SysCap, storm: bool) -> Result<(), String> { }); } - verdict(&tail, &run, storm) + verdict(&tail, &run, storm, emitted) } -/// The storm: one kernel record per call, counted after each call returns, -/// paused at [`HANDOVER`] until the reader has taken one. -fn spawn_producer(produced: Arc, taken: Receiver<()>) -> JoinHandle> { +/// The storm: one kernel record per call, counted after each call returns. +/// [`HANDOVER`] records, then the lap the reader names once it has taken one, +/// then records until the reader sets `stop`. +fn spawn_producer( + produced: Arc, + stop: Arc, + taken: Receiver, + lapped: SyncSender<()>, +) -> JoinHandle> { std::thread::spawn(move || { - for index in 0..STORM_RECORDS { - if index == HANDOVER { - taken.recv_timeout(HANDOVER_WAIT).map_err(|e| match e { - RecvTimeoutError::Timeout => format!( - "the reader took none of the storm's first {HANDOVER} records within \ - {HANDOVER_WAIT:?}" - ), - RecvTimeoutError::Disconnected => { - "the reader ended before it took a storm record".into() - } - })?; - } + let emit = || { + let index = produced.load(Ordering::Relaxed); let answer = toyos_abi::syscall::debug_with(LOG_PATTERNED, index); if answer != 0 { return Err(format!( "SYS_DEBUG LOG_PATTERNED answered {answer:#x} at index {index}" )); } - produced.fetch_add(1, Ordering::Release); + produced.store(index + 1, Ordering::Release); + Ok(()) + }; + for _ in 0..HANDOVER { + emit()?; + } + let lap = taken.recv().map_err(|_| "the reader ended before it took a storm record")?; + for _ in 0..lap { + emit()?; + } + lapped.send(()).map_err(|_| "the reader ended before the storm lapped it")?; + while !stop.load(Ordering::Acquire) { + emit()?; } Ok(()) }) } +/// Why the producer's end of a channel closed: it returned, and its join says why. +fn ended(producer: Option>>) -> String { + match join(producer) { + Err(e) => e, + Ok(()) => "the producer returned before the storm lapped this reader".into(), + } +} + fn join(producer: Option>>) -> Result<(), String> { match producer.map(JoinHandle::join) { None | Some(Ok(Ok(()))) => Ok(()), @@ -452,7 +465,7 @@ fn parse_record(rest: &str) -> Result<(u64, u64), String> { /// The conservation law, and everything the gate prints for a reader of its /// output. -fn verdict(tail: &LogTail, run: &Run, storm: bool) -> Result<(), String> { +fn verdict(tail: &LogTail, run: &Run, storm: bool, emitted: u64) -> Result<(), String> { let seen: Vec = (0..MAX_LOG_SHARDS).filter(|&i| run.shards[i].first.is_some()).collect(); if seen.is_empty() { @@ -504,19 +517,12 @@ fn verdict(tail: &LogTail, run: &Run, storm: bool) -> Result<(), String> { return Err("the storm ran and this reader read none of it".into()); } let next = run.producers.get(&STORM_PRODUCER).and_then(|p| p.next).unwrap_or(0); - if next > STORM_RECORDS { + if next > emitted { return Err(format!( - "the storm answered index {} of {STORM_RECORDS} emitted", + "the storm answered index {} of {emitted} emitted", next - 1 )); } - if run.concurrent == 0 { - return Err( - "every storm record was read after the producer had finished, so this reader \ - raced nothing" - .into(), - ); - } // The readiness source, asserted where it is reachable: the poll was // armed before the storm started, so the records that answer it were // committed after it was registered. @@ -566,9 +572,9 @@ fn verdict(tail: &LogTail, run: &Run, storm: bool) -> Result<(), String> { ); if storm { println!( - "log-gate: storm emitted={STORM_RECORDS} read={read_total} dropped={} \ + "log-gate: storm emitted={emitted} read={read_total} dropped={} \ concurrent={} wakes={}", - STORM_RECORDS - read_total, + emitted - read_total, run.concurrent, run.completions, );