From 30a01bd5c1bd686a786084696f910cbaf9423a53 Mon Sep 17 00:00:00 2001 From: Claude Date: Mon, 5 Oct 2026 09:36:36 +0000 Subject: [PATCH 1/8] irq_census judges each CPU by its largest counts, not its last line The judge compared lines from different process exits as if the capture listed them in the order their counters were read. It does not: an exit reads the counters before log::emit stamps its line, two exits on two CPUs run side by side, and log::read::drain_ordered merges the shards by stamp. So a line stamped later can carry the earlier read, and two checks redded with no kernel defect: - the per-source monotonic check, when exit X reads cpu1's census, exit Y reads it with one more kick, and Y is stamped first; - the issuer checks on `tlb: shootdowns=`, when Y loads ISSUED (T1), X loads T2 > T1 and logs it, and Y's swap of REPORTED returns T2, so Y logs T1 after X's T2: "went backwards", and the last tlb line (T1) under a newer irq line's tlb count, "shoots down without being counted". No line says when it was read: a line's read has an upper bound, its stamp, and no lower bound, since the exit can be held between the read and the stamp. With no lower bound no pair of lines from two exits has a known read order, so any comparison between them can red a correct kernel. The judge therefore compares none: a CPU's census is the largest count each of its sources reached on any line, and the issuer's is the largest shootdowns=. Both are what the newest read would have shown, whatever order the lines were stamped in. The monotonic check and the issuer's went-backwards check are deleted; the device-delivery and conservation checks run on the largest counts. The bound on tlb deliveries stays sound: an exit reads its deliveries before the issuer's total, and the exit that first swaps a total into REPORTED logs it, so every total an exit read is on some tlb: line. The doc comment of control_regs had been left above irq_census, which rustdoc read as the census judge's; it moves back above control_regs. tests/checks.rs's irq_census_verdict feeds the judge two exits stamped in the other order from their reads, the issue's two cases in one capture, and holds it green; it also holds the judge red on an AP device delivery on a line that is not that AP's last, on a delivery past the largest issued count, and on a capture with no tlb: line. Found off this fence and filed: the suite's summary reader, common::irqcensus::observe, keeps a CPU's last stamped line the same way (issues/the-irq-census-summary-takes-a-cpus-last-stamped-line-as-its-newest-read.md). Closes issues/the-irq-census-judge-reds-on-two-exits-stamped-in-the-other-order.md. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_015tYBoMwh9xUcBBLG35wTFr --- ...on-two-exits-stamped-in-the-other-order.md | 37 ------ ...us-last-stamped-line-as-its-newest-read.md | 22 ++++ tests/checks.rs | 58 +++++++++ tests/toyos.rs | 110 ++++++++---------- 4 files changed, 131 insertions(+), 96 deletions(-) delete mode 100644 issues/the-irq-census-judge-reds-on-two-exits-stamped-in-the-other-order.md create mode 100644 issues/the-irq-census-summary-takes-a-cpus-last-stamped-line-as-its-newest-read.md diff --git a/issues/the-irq-census-judge-reds-on-two-exits-stamped-in-the-other-order.md b/issues/the-irq-census-judge-reds-on-two-exits-stamped-in-the-other-order.md deleted file mode 100644 index 7f654801a41..00000000000 --- a/issues/the-irq-census-judge-reds-on-two-exits-stamped-in-the-other-order.md +++ /dev/null @@ -1,37 +0,0 @@ ---- -status: open -kind: defect -opened: 2026-10-04 ---- - -# The `irq_census` judge reds on two exits' lines stamped in the other order from their reads - -The judge `irq_census` (`tests/toyos.rs`) compares lines from different process -exits as if the capture listed them in the order their counters were read. It -does not. Each exit prints `irq_census::log_census` and then -`tlb::log_census` (`kernel/src/process.rs`), and nothing serialises two exits on -two CPUs. `log::emit` reads its arguments and formats them before it stamps the -record (`kernel/src/log/mod.rs`), each CPU writes its own shard, and -`log::read::drain_ordered` merges the shards by stamp. So exit X can read a -counter before exit Y and still be stamped after Y. - -Two of the judge's checks then red with no kernel defect: - -- **The per-source monotonic check.** X reads cpu1's census, then Y reads it - with one more `kick`. Y is stamped first. The capture shows cpu1's `kick` - going backwards. -- **The issuer checks on `tlb: shootdowns=`.** Y loads `ISSUED` and gets T1. - X then loads T2 > T1, swaps `REPORTED` to T2 and logs. Y's swap returns T2, - which is not T1, so Y logs `shootdowns=T1` after X's T2. The capture shows - `T2` then `T1`, which reds "the issuer census went backwards". The last - `tlb:` line is then T1, and a newer `irq:` line's `tlb` count can exceed it, - which reds "some path shoots down without being counted". - -Neither has been seen red. The recorded red the same window produced was the -deleted total/sources check (#734), where the reads were within one line. - -Owner: the harness, `irq_census` in `tests/toyos.rs`. - -**Exit:** a host test feeds the judge two exits' `irq:` and `tlb:` lines in -stamp order, with the later stamp carrying the earlier read as above, and the -judge stays green. diff --git a/issues/the-irq-census-summary-takes-a-cpus-last-stamped-line-as-its-newest-read.md b/issues/the-irq-census-summary-takes-a-cpus-last-stamped-line-as-its-newest-read.md new file mode 100644 index 00000000000..c3a7b5ed204 --- /dev/null +++ b/issues/the-irq-census-summary-takes-a-cpus-last-stamped-line-as-its-newest-read.md @@ -0,0 +1,22 @@ +--- +status: open +kind: defect +opened: 2026-10-05 +--- + +# The irq census summary takes a CPU's last stamped line as its newest read + +`common::irqcensus::observe` (`tests/common/irqcensus.rs`) keeps, per guest +and CPU, the last `irq: cpuN` line the console carried, and the module's +header says the last line a capture holds for a CPU is that boot's whole +census. It is not. A process exit reads the counters before `log::emit` +stamps its line, two exits on two CPUs run side by side, and the shards are +merged by stamp, so the line stamped last can carry the older read. The +suite's summary then counts that CPU short by what it took between the two +reads. The judge `irq_census` (`tests/toyos.rs`) takes each source's largest +count for this reason. + +Owner: the harness, `observe` in `tests/common/irqcensus.rs`. + +**Exit:** the summary keeps each source's largest count per guest and CPU, +and the module's header no longer says the last line is the whole census. diff --git a/tests/checks.rs b/tests/checks.rs index 319d1e8aaba..19efd357599 100644 --- a/tests/checks.rs +++ b/tests/checks.rs @@ -486,6 +486,64 @@ mod checks { Ok(()) } + /// [`irq_census`] over two exits stamped in the other order from their + /// reads. X, on cpu2, reads cpu1 and is held before it stamps; Y, on cpu3, + /// reads every CPU with one more `kick` on cpu1, stamps, loads the + /// issuer's 7 and is held before its swap. Two shootdowns later X stamps + /// cpu1, reads cpu2 and cpu3 at 9 deliveries and logs 9; Y's swap then + /// returns 9, so Y logs 7. + #[test] + fn irq_census_verdict() -> Result<(), String> { + let census = |at: &str, on: u32, cpu: u32, kick: u64, tlb: u64| { + let xhci = if cpu == 0 { 40 } else { 0 }; + format!( + "[ {at} cpu{on} kernel] irq: cpu{cpu} timer=100 kick={kick} xhci={xhci} userdev=0 \ + sound=0 i8042=0 dmafault=0 hda=0 tlb={tlb} nmi=0 spurious=0 unclaimed=0\n" + ) + }; + let issued = |at: &str, on: u32, total: u64| { + format!( + "[ {at} cpu{on} kernel] tlb: shootdowns={total} wait=12us max=3us dlopen=0 pcid=0 \ + mmio=0 unmap={total} pipe=0 staged=0 bench=0\n" + ) + }; + let y_cpu2 = census("2.001", 3, 2, 2, 7); + let x_cpu3 = census("2.004", 2, 3, 2, 9); + let (x_issued, y_issued) = (issued("2.005", 2, 9), issued("2.006", 3, 7)); + let good = [ + census("2.000", 2, 0, 3, 0), + census("2.001", 3, 0, 3, 0), + census("2.001", 3, 1, 6, 7), + y_cpu2.clone(), + census("2.001", 3, 3, 2, 7), + census("2.004", 2, 1, 5, 7), + census("2.004", 2, 2, 2, 9), + x_cpu3.clone(), + x_issued.clone(), + y_issued.clone(), + ] + .concat(); + irq_census(&good).map_err(|e| format!("two exits stamped out of read order were refused: {e}"))?; + + let refused = |what: &str, capture: &str, says: &str| match irq_census(capture) { + Ok(()) => Err(format!("{what} was accepted")), + Err(e) if e.contains(says) => Ok(()), + Err(e) => Err(format!("{what} was refused for the wrong reason: {e}")), + }; + refused( + "an AP's device delivery on a line that is not that AP's last", + &good.replace(&y_cpu2, &y_cpu2.replace("xhci=0", "xhci=1")), + "addressed to physical destination 0", + )?; + refused( + "a delivery past the largest issued count", + &good.replace(&x_cpu3, &census("2.004", 2, 3, 2, 10)), + "without being counted", + )?; + refused("no issuer line", &good.replace(&x_issued, "").replace(&y_issued, ""), "said nothing")?; + Ok(()) + } + /// What the declaration itself has to be, before any of it means anything. /// Which shared-boot binaries need `SYS_DEBUG`, asked of their source. /// diff --git a/tests/toyos.rs b/tests/toyos.rs index 781e5bdec42..0c3cbc6c4c1 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -2678,66 +2678,39 @@ fn run_machine_test(name: &str, test_config: &Path) -> Result<(), String> { } } -/// Every CPU's `CR0` and `CR4`, against what a CPU running this kernel must -/// hold. -/// -/// **Not the same question the kernel's own self-check asks.** That one compares -/// each CPU against the declaration, so it catches a CPU that missed it and -/// nothing else; a declaration that is wrong satisfies it on every core. The -/// bits below are spelled out here, away from the constants that produce them, -/// so the two have to agree independently — and the ones that matter are the -/// ones an AP used to arrive with: `CD`/`NW` set is caching off, `WP` clear is -/// the kernel's own read-only mappings not binding supervisor writes, `NE` -/// clear routes an unmasked x87 exception to a pin nothing listens on. +/// Every device delivery is still cpu0's, and no CPU took a shootdown IPI the +/// issuer did not count. /// -/// `OSXSAVE` is asserted *clear*: with it set the CPU would permit `XCR0` to -/// name components `FXSAVE64` does not save, and this kernel saves user FP -/// state with `FXSAVE64`. -/// -/// Both halves, because the kernel writes both registers whole: every bit named -/// below must hold its named value, **and a bit named nowhere below may not be -/// set at all**. Silence about a bit is a hole rather than a permission. -/// The interrupt census adds up, is monotonic, and every device delivery is -/// still cpu0's. +/// **The capture is in stamp order, not read order.** A process exit reads the +/// counters before `log::emit` stamps its line, and two exits on two CPUs run +/// side by side, so a line stamped later can carry the earlier read, of a +/// CPU's census or of the issuer's total, and no line says when it was read. +/// No two lines are compared by their place in the capture: a CPU's census is +/// the largest count each of its sources reached on any line, and the issuer's +/// is the largest `shootdowns=`. fn irq_census(capture: &str) -> Result<(), String> { - use common::irqcensus::{Census, DEVICE_SOURCES, SOURCES}; - // Every line, in order, so a later census can be compared with an - // earlier one on the same CPU. - let mut lines: Vec = Vec::new(); + use common::irqcensus::{Census, DEVICE_SOURCES}; + let mut newest: BTreeMap = BTreeMap::new(); for line in capture.lines() { - match Census::parse(line) { + let census = match Census::parse(line) { None => continue, - Some(Ok(census)) => lines.push(census), + Some(Ok(census)) => census, Some(Err(why)) => return Err(format!("{why}\nline: {line}")), + }; + let most = newest.entry(census.cpu).or_insert_with(|| census.clone()); + for (most, read) in most.by_source.iter_mut().zip(census.by_source) { + *most = (*most).max(read); } } - if lines.is_empty() { + if newest.is_empty() { return Err(format!( "no `irq: cpu` census in the capture — a process exited and the kernel \ said nothing:\n{capture}" )); } - // 1. Monotonic: a counter that went backwards is a torn read or a - // word two CPUs are writing, which is what the no-`lock` argument - // in `kernel/src/irq_census.rs` rests on being impossible. - let mut newest: std::collections::BTreeMap = std::collections::BTreeMap::new(); - for census in &lines { - if let Some(prev) = newest.get(&census.cpu) { - if let Some(name) = SOURCES.iter().zip(prev.by_source.iter().zip(census.by_source)).find_map( - |(name, (&was, now))| (now < was).then_some(name), - ) { - return Err(format!( - "cpu{}'s `{name}` count went backwards: {prev:?} then {census:?}", - census.cpu, - )); - } - } - newest.insert(census.cpu, census.clone()); - } - - // 2. The machine is real: the boot CPU took interrupts, and so did - // at least one AP — otherwise (3) says nothing. + // 1. The machine is real: the boot CPU took interrupts, and so did + // at least one AP — otherwise (2) says nothing. let cpu0 = newest .get(&0) .ok_or_else(|| format!("no cpu0 in the census: {newest:?}"))?; @@ -2755,7 +2728,7 @@ fn irq_census(capture: &str) -> Result<(), String> { return Err(format!("no AP took a single interrupt: {newest:?}")); } - // 3. **The present-state fact this whole track is about.** Every + // 2. **The present-state fact this whole track is about.** Every // message-signalled interrupt is addressed to physical // destination 0 (`drivers::pci`'s `MSG_ADDR`) and the one I/O // APIC pin goes to the BSP, so no AP may have a device count at @@ -2793,11 +2766,14 @@ fn irq_census(capture: &str) -> Result<(), String> { newest.values().map(Census::total).sum::(), ); - // 4. The issuer side: every `tlb` delivery a CPU's census carries - // must be within the issues the `tlb:` line counted — an excess + // 3. The issuer side: every `tlb` delivery a CPU's census carries + // must be within the issues a `tlb:` line counted — an excess // is a path shooting down uncounted. The lower bound is not // asserted: an issued IPI can be pending on an IF-clear target. - let mut issued: Vec = Vec::new(); + // The bound is the largest count: an exit reads its deliveries + // before the issuer's total, and whichever exit first swaps a + // total into `tlb::REPORTED` logs it. + let mut issued: Option = None; for line in capture.lines() { let Some(rest) = line.split("tlb: shootdowns=").nth(1) else { continue }; let n: u64 = rest @@ -2805,22 +2781,19 @@ fn irq_census(capture: &str) -> Result<(), String> { .next() .and_then(|v| v.parse().ok()) .ok_or_else(|| format!("unreadable issuer census: {line}"))?; - issued.push(n); + issued = issued.max(Some(n)); eprintln!(" [tlb] {}", line.trim()); } - let Some(&last_issued) = issued.last() else { + let Some(issued) = issued else { return Err(format!( "no `tlb: shootdowns=` census in the capture — two process exits on a \ 4-CPU guest and the issuer side said nothing:\n{capture}" )); }; - if issued.windows(2).any(|w| w[1] < w[0]) { - return Err(format!("the issuer census went backwards: {issued:?}")); - } for census in newest.values() { - if census.source("tlb") > last_issued { + if census.source("tlb") > issued { return Err(format!( - "cpu{} took {} tlb IPI(s) against {last_issued} counted issue(s) — \ + "cpu{} took {} tlb IPI(s) against {issued} counted issue(s) — \ some path shoots down without being counted: {census:?}", census.cpu, census.source("tlb"), @@ -2828,7 +2801,7 @@ fn irq_census(capture: &str) -> Result<(), String> { } } eprintln!( - " [tlb] {last_issued} shootdown(s) issued, deliveries per CPU {:?} — every \ + " [tlb] {issued} shootdown(s) issued, deliveries per CPU {:?} — every \ delivery accounted for", newest.values().map(|c| c.source("tlb")).collect::>(), ); @@ -3363,6 +3336,25 @@ fn ioapic_topology(log: &str) -> Result<(), String> { Ok(()) } +/// Every CPU's `CR0` and `CR4`, against what a CPU running this kernel must +/// hold. +/// +/// **Not the same question the kernel's own self-check asks.** That one compares +/// each CPU against the declaration, so it catches a CPU that missed it and +/// nothing else; a declaration that is wrong satisfies it on every core. The +/// bits below are spelled out here, away from the constants that produce them, +/// so the two have to agree independently — and the ones that matter are the +/// ones an AP used to arrive with: `CD`/`NW` set is caching off, `WP` clear is +/// the kernel's own read-only mappings not binding supervisor writes, `NE` +/// clear routes an unmasked x87 exception to a pin nothing listens on. +/// +/// `OSXSAVE` is asserted *clear*: with it set the CPU would permit `XCR0` to +/// name components `FXSAVE64` does not save, and this kernel saves user FP +/// state with `FXSAVE64`. +/// +/// Both halves, because the kernel writes both registers whole: every bit named +/// below must hold its named value, **and a bit named nowhere below may not be +/// set at all**. Silence about a bit is a hole rather than a permission. fn control_regs(log: &str, cpus: u32) -> Result<(), String> { /// `(bit, name, must_be_set)`. Every bit `CR0` defines, so a value with any /// other bit set is reserved state the kernel put there. From 86244ac8dc5b86cae9d354cdc0642684a7a7a1ea Mon Sep 17 00:00:00 2001 From: Claude Date: Mon, 5 Oct 2026 09:37:42 +0000 Subject: [PATCH 2/8] The LAPIC selftests read the total after the probe, and arm the one-shot spurious::selftest and unclaimed::selftest each claim the CPU still takes interrupts after the probe vector, and neither check could fail. Both read taken_before = deliveries_total(cpu) before apic::send_self, and the probe's own delivery is counted in that total, so once `delivered` held, deliveries_total(cpu) > taken_before was already true at the first poll. A CPU the probe's handler left deaf printed 3/3, "and the CPU took interrupts after it". Each now reads the total once the handler has returned (the selftest polls on the CPU the self-IPI interrupts, so `delivered` holding means the handler has run to its iretq), and waits for an interrupt past it. Waiting is not enough on its own: nothing else promises this CPU an interrupt inside the 50 ms budget. The selftests run on the BSP in the device phase, before any scheduler pass has armed its one-shot, and apic::init_timer leaves the timer stopped; the old check never found out, because it passed on the probe alone. So each arms the one-shot with arm_within(QUANTUM_NS), as usb_gate and the deadline's wedge do for a CPU that has to take a timer interrupt. Its Ring 0 fire re-arms one quantum on, so the BSP ticks from there to its first pass, the state an executing CPU is in; any source still counts, since only a deaf CPU is ruled out. boot.rs's note on interrupt_selftests said the timer was already ticking; it now says what the selftests need, interrupts on and the timer calibrated. Closes issues/the-spurious-and-unclaimed-selftests-took-interrupts-after-check-cannot-fail.md. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_015tYBoMwh9xUcBBLG35wTFr --- ...took-interrupts-after-check-cannot-fail.md | 23 ------------------- kernel/src/arch/x86_64/boot.rs | 2 +- kernel/src/arch/x86_64/idt/spurious.rs | 7 ++++-- kernel/src/arch/x86_64/idt/unclaimed.rs | 7 ++++-- 4 files changed, 11 insertions(+), 28 deletions(-) delete mode 100644 issues/the-spurious-and-unclaimed-selftests-took-interrupts-after-check-cannot-fail.md diff --git a/issues/the-spurious-and-unclaimed-selftests-took-interrupts-after-check-cannot-fail.md b/issues/the-spurious-and-unclaimed-selftests-took-interrupts-after-check-cannot-fail.md deleted file mode 100644 index 31b9a5899c0..00000000000 --- a/issues/the-spurious-and-unclaimed-selftests-took-interrupts-after-check-cannot-fail.md +++ /dev/null @@ -1,23 +0,0 @@ ---- -status: open -kind: defect -opened: 2026-10-04 ---- - -# The spurious and unclaimed selftests' "took interrupts after it" check cannot fail - -`spurious::selftest` (`kernel/src/arch/x86_64/idt/spurious.rs`) and -`unclaimed::selftest` (`kernel/src/arch/x86_64/idt/unclaimed.rs`) each claim to -confirm the CPU still takes interrupts after the probe vector. They read -`taken_before = deliveries_total(cpu)` before `apic::send_self`. The probe's -own delivery is counted in that total. Once `delivered` has held, the probe's -source count is past `before`, so `deliveries_total(cpu) > taken_before` is -already true at the first poll. A CPU left deaf by the probe's handler passes -the check, and the `3/3` line says "the CPU took interrupts after it" either -way. - -Owner: the LAPIC selftests, `kernel/src/arch/x86_64/idt/`. - -**Exit:** a mutation that leaves the CPU taking no interrupt once the probe's -handler returns makes each selftest print `FAILED`, and the `selftests` row in -`tests/toyos.rs` that boots both actuators reds on it. diff --git a/kernel/src/arch/x86_64/boot.rs b/kernel/src/arch/x86_64/boot.rs index b58d961a7f5..474e8247949 100644 --- a/kernel/src/arch/x86_64/boot.rs +++ b/kernel/src/arch/x86_64/boot.rs @@ -144,7 +144,7 @@ pub fn start_other_cpus(platform: &Platform, args: &KernelArgs) { /// The interrupt-controller selftests an actuator asks for, once the timer ticks. #[cfg(feature = "boot-actuators")] pub fn interrupt_selftests() { - // Needs interrupts on and the timer already ticking: its last assertion is that the interrupt after the spurious one arrives. + // Needs interrupts on and the timer calibrated: each arms the one-shot and asserts an interrupt arrives after its probe. if crate::actuator::lapic_spurious_selftest() { idt::spurious::selftest(); } diff --git a/kernel/src/arch/x86_64/idt/spurious.rs b/kernel/src/arch/x86_64/idt/spurious.rs index c26a827da7f..f52a8e47a82 100644 --- a/kernel/src/arch/x86_64/idt/spurious.rs +++ b/kernel/src/arch/x86_64/idt/spurious.rs @@ -80,7 +80,6 @@ pub fn selftest() { crate::log!("LAPIC: spurious selftest FAILED — this CPU publishes no census block"); return; }; - let taken_before = crate::irq_census::deliveries_total(cpu).unwrap_or(0); // This platform's devices are all MSI/MSI-X and `TPR` is never written, so // nothing here raises a spurious interrupt without this call. @@ -109,8 +108,12 @@ pub fn selftest() { } // Confirms the CPU still takes interrupts afterward; any source works, since only a deaf CPU is ruled out. + // Read now the handler has returned, so the probe's own delivery is already in it, + // and the one-shot armed so an interrupt comes. + let taken = crate::irq_census::deliveries_total(cpu).unwrap_or(0); + apic::arm_within(kernel::sched::fair::QUANTUM_NS); let ran_on = crate::clock::settles(ARRIVES.nanos(), || { - crate::irq_census::deliveries_total(cpu).unwrap_or(taken_before) > taken_before + crate::irq_census::deliveries_total(cpu).unwrap_or(taken) > taken }); if !ran_on { crate::log!( diff --git a/kernel/src/arch/x86_64/idt/unclaimed.rs b/kernel/src/arch/x86_64/idt/unclaimed.rs index 76d17222611..2bb20d79339 100644 --- a/kernel/src/arch/x86_64/idt/unclaimed.rs +++ b/kernel/src/arch/x86_64/idt/unclaimed.rs @@ -127,7 +127,6 @@ pub fn selftest() { crate::log!("LAPIC: unclaimed selftest FAILED — this CPU publishes no census block"); return; }; - let taken_before = crate::irq_census::deliveries_total(cpu).unwrap_or(0); apic::send_self(PROBE_VECTOR); @@ -161,8 +160,12 @@ pub fn selftest() { return; } + // Read now the handler has returned, so the probe's own delivery is already in it, + // and the one-shot armed so an interrupt comes. + let taken = crate::irq_census::deliveries_total(cpu).unwrap_or(0); + apic::arm_within(kernel::sched::fair::QUANTUM_NS); let ran_on = crate::clock::settles(ARRIVES.nanos(), || { - crate::irq_census::deliveries_total(cpu).unwrap_or(taken_before) > taken_before + crate::irq_census::deliveries_total(cpu).unwrap_or(taken) > taken }); if !ran_on { crate::log!( From 71fb985c84c54eaca98a2b184bbc7af135a2733d Mon Sep 17 00:00:00 2001 From: Claude Date: Mon, 5 Oct 2026 09:37:59 +0000 Subject: [PATCH 3/8] The console's routine lines go on stdout, so only a failure is drawn as an error MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A line a program writes to stderr is an Error record (toyos::log::stdio::Stream::severity), drawn in red. /system/bin/console, the surface of the console/system.toml boot, wrote its four routine lines with eprintln!: `console: ready …`, `keyboard layout is now …`, `client N has the keyboard until it exits` and `client N gave the keyboard back`. They now go to stdout, an Info record, as the compositor's and the terminal's identical lines did in 6e6a8f71. `no framebuffer, exiting` and `dropping client` stay on stderr: each reports a failure. Closes issues/the-console-says-its-routine-lines-as-errors.md. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_015tYBoMwh9xUcBBLG35wTFr --- ...console-says-its-routine-lines-as-errors.md | 18 ------------------ userland/console/src/main.rs | 8 ++++---- 2 files changed, 4 insertions(+), 22 deletions(-) delete mode 100644 issues/the-console-says-its-routine-lines-as-errors.md diff --git a/issues/the-console-says-its-routine-lines-as-errors.md b/issues/the-console-says-its-routine-lines-as-errors.md deleted file mode 100644 index bdc8f564cd3..00000000000 --- a/issues/the-console-says-its-routine-lines-as-errors.md +++ /dev/null @@ -1,18 +0,0 @@ ---- -status: open -kind: defect -opened: 2026-10-04 ---- - -# The console says its routine lines as errors - -`/system/bin/console` (`userland/console/src/main.rs`), the surface of the -`console/system.toml` boot, writes `console: ready …`, `keyboard layout is -now …`, `client N has the keyboard until it exits` and `client N gave the -keyboard back` with `eprintln!`, and a line on stderr is an Error record -(`toyos::log::stdio::Stream::severity`). So every one of them is drawn in red -on the console and reads as a failure, as the terminal's identical lines did -until they moved to stdout. - -Owner: orchestrator. Exit condition: those four lines are written to stdout, -and this file is deleted. diff --git a/userland/console/src/main.rs b/userland/console/src/main.rs index d27b558b652..d6866dc4740 100644 --- a/userland/console/src/main.rs +++ b/userland/console/src/main.rs @@ -202,7 +202,7 @@ fn main() { // The seed is the heaviest thing this program ever draws — a screenful of // log per scrolled row — so a boot that felt slow says so here. let (panel_bytes, blits) = console.screen_traffic(); - eprintln!( + println!( "console: ready {}x{} ({cols}x{rows} cells), log {seeded} bytes, \ panel {panel_bytes} bytes in {blits} blits", info.width, info.height @@ -304,13 +304,13 @@ fn main() { Notice::LayoutChanged => { window::load_layout(&mut translator); host.notify_layout(); - eprintln!("console: keyboard layout is now {}", translator.layout()); + println!("console: keyboard layout is now {}", translator.layout()); } Notice::Grabbed { client } => { - eprintln!("console: client {client} has the keyboard until it exits") + println!("console: client {client} has the keyboard until it exits") } Notice::Released { client } => { - eprintln!("console: client {client} gave the keyboard back") + println!("console: client {client} gave the keyboard back") } Notice::Dropped { client, why } => { eprintln!("console: dropping client {client} — {why}") From 0cfedce29be64ba90a21faf64d4137d2447b0415 Mon Sep 17 00:00:00 2001 From: Claude Date: Mon, 5 Oct 2026 11:03:02 +0000 Subject: [PATCH 4/8] The census's largest-count fold is Census::raise, in common::irqcensus irq_census folded each CPU's lines into the largest count per source inline. common::irqcensus is the module that exists for the census's two readers, and observe, the summary's reader, needs the same fold (issues/the-irq-census-summary-takes-a-cpus-last-stamped-line-as-its-newest-read.md), so the fold is one method on Census, and the judge calls it. Why the largest count is the newest read, stamp order not being read order, is the method's doc; the judge's doc points at it. The module header said the last line a capture holds for a CPU is that boot's whole census, which is false for the reason raise exists; it now says the largest count per source is. The filed issue's exit is narrowed to what is left: observe folding with raise, and SEEN's doc. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_015tYBoMwh9xUcBBLG35wTFr --- ...us-last-stamped-line-as-its-newest-read.md | 19 +++++++++---------- tests/common/irqcensus.rs | 16 +++++++++++++++- tests/toyos.rs | 17 ++++++----------- 3 files changed, 30 insertions(+), 22 deletions(-) diff --git a/issues/the-irq-census-summary-takes-a-cpus-last-stamped-line-as-its-newest-read.md b/issues/the-irq-census-summary-takes-a-cpus-last-stamped-line-as-its-newest-read.md index c3a7b5ed204..ce042317847 100644 --- a/issues/the-irq-census-summary-takes-a-cpus-last-stamped-line-as-its-newest-read.md +++ b/issues/the-irq-census-summary-takes-a-cpus-last-stamped-line-as-its-newest-read.md @@ -7,16 +7,15 @@ opened: 2026-10-05 # The irq census summary takes a CPU's last stamped line as its newest read `common::irqcensus::observe` (`tests/common/irqcensus.rs`) keeps, per guest -and CPU, the last `irq: cpuN` line the console carried, and the module's -header says the last line a capture holds for a CPU is that boot's whole -census. It is not. A process exit reads the counters before `log::emit` -stamps its line, two exits on two CPUs run side by side, and the shards are -merged by stamp, so the line stamped last can carry the older read. The -suite's summary then counts that CPU short by what it took between the two -reads. The judge `irq_census` (`tests/toyos.rs`) takes each source's largest -count for this reason. +and CPU, the last `irq: cpuN` line the console carried, as if that line were +the CPU's newest read. It is not. A process exit reads the counters before +`log::emit` stamps its line, two exits on two CPUs run side by side, and the +shards are merged by stamp, so the line stamped last can carry the older +read. The suite's summary then counts that CPU short by what it took between +the two reads. The judge `irq_census` (`tests/toyos.rs`) folds each CPU's +lines with `Census::raise`, the largest count per source, for this reason. Owner: the harness, `observe` in `tests/common/irqcensus.rs`. -**Exit:** the summary keeps each source's largest count per guest and CPU, -and the module's header no longer says the last line is the whole census. +**Exit:** `observe` folds each guest's CPU lines with `Census::raise`, and +`SEEN`'s doc no longer says the last line is the whole boot. diff --git a/tests/common/irqcensus.rs b/tests/common/irqcensus.rs index 2b676fdbd71..f3148de4955 100644 --- a/tests/common/irqcensus.rs +++ b/tests/common/irqcensus.rs @@ -4,7 +4,8 @@ //! The guest prints `irq: cpuN timer=… kick=… …` per online CPU whenever a //! process exits, on `SYS_SHUTDOWN` and on the blocked-task dump //! (`kernel/src/irq_census.rs`). The counters are cumulative since boot, so the -//! **last** line a capture holds for a CPU is that boot's whole census. +//! largest count each source reaches on a CPU's lines is that boot's whole +//! census ([`Census::raise`]). //! //! Two readers, and they are why this is a module rather than a closure: //! `irq_census_conservation` asks whether one boot's census is internally @@ -89,6 +90,19 @@ impl Census { self.by_source[i] } + /// Raise each source to its count in `read`, another line of this CPU. + /// + /// **Lines are in stamp order, not read order.** A process exit reads the + /// counters before `log::emit` stamps its line, and two exits on two CPUs + /// run side by side, so a line stamped later can carry the earlier read. + /// The counters are monotonic, so the largest count per source is the + /// newest read whatever the order of the lines. + pub fn raise(&mut self, read: &Self) { + for (most, count) in self.by_source.iter_mut().zip(read.by_source) { + *most = (*most).max(count); + } + } + /// Every interrupt this CPU took: the kernel keeps no total apart from its sources. pub fn total(&self) -> u64 { self.by_source.iter().sum() diff --git a/tests/toyos.rs b/tests/toyos.rs index 0c3cbc6c4c1..2a6a86bbbe8 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -2681,13 +2681,11 @@ fn run_machine_test(name: &str, test_config: &Path) -> Result<(), String> { /// Every device delivery is still cpu0's, and no CPU took a shootdown IPI the /// issuer did not count. /// -/// **The capture is in stamp order, not read order.** A process exit reads the -/// counters before `log::emit` stamps its line, and two exits on two CPUs run -/// side by side, so a line stamped later can carry the earlier read, of a -/// CPU's census or of the issuer's total, and no line says when it was read. -/// No two lines are compared by their place in the capture: a CPU's census is -/// the largest count each of its sources reached on any line, and the issuer's -/// is the largest `shootdowns=`. +/// **The capture is in stamp order, not read order** (`Census::raise`), of a +/// CPU's census and of the issuer's total alike, and no line says when it was +/// read. No two lines are compared by their place in the capture: a CPU's +/// census is the largest count each of its sources reached on any line, and the +/// issuer's is the largest `shootdowns=`. fn irq_census(capture: &str) -> Result<(), String> { use common::irqcensus::{Census, DEVICE_SOURCES}; let mut newest: BTreeMap = BTreeMap::new(); @@ -2697,10 +2695,7 @@ fn irq_census(capture: &str) -> Result<(), String> { Some(Ok(census)) => census, Some(Err(why)) => return Err(format!("{why}\nline: {line}")), }; - let most = newest.entry(census.cpu).or_insert_with(|| census.clone()); - for (most, read) in most.by_source.iter_mut().zip(census.by_source) { - *most = (*most).max(read); - } + newest.entry(census.cpu).or_insert_with(|| census.clone()).raise(&census); } if newest.is_empty() { return Err(format!( From c5cc9cf5ebf61026eb2e3a6a168a49c7ae3e042e Mon Sep 17 00:00:00 2001 From: Claude Date: Mon, 5 Oct 2026 11:03:02 +0000 Subject: [PATCH 5/8] The selftests' after-check issue stays open until the T14 reads its exit 86244ac8 deleted the issue with the code fix, but its exit, the selftests row reddening on a deaf-after-probe mutation, has not been read: no QEMU guest test arms either selftest, and the T14 row lapic_spurious_vector, the only reader, has not booted the fix. A close whose exit is unmet does not land, so the issue is restored, open, with its owner. It now records that the fix is in, and names the exit as the three lapic_spurious_vector runs and the two mutation patches posted on #741. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_015tYBoMwh9xUcBBLG35wTFr --- ...took-interrupts-after-check-cannot-fail.md | 36 +++++++++++++++++++ 1 file changed, 36 insertions(+) create mode 100644 issues/the-spurious-and-unclaimed-selftests-took-interrupts-after-check-cannot-fail.md diff --git a/issues/the-spurious-and-unclaimed-selftests-took-interrupts-after-check-cannot-fail.md b/issues/the-spurious-and-unclaimed-selftests-took-interrupts-after-check-cannot-fail.md new file mode 100644 index 00000000000..b04dc6b63e2 --- /dev/null +++ b/issues/the-spurious-and-unclaimed-selftests-took-interrupts-after-check-cannot-fail.md @@ -0,0 +1,36 @@ +--- +status: open +kind: defect +opened: 2026-10-04 +--- + +# The spurious and unclaimed selftests' "took interrupts after it" check cannot fail + +`spurious::selftest` (`kernel/src/arch/x86_64/idt/spurious.rs`) and +`unclaimed::selftest` (`kernel/src/arch/x86_64/idt/unclaimed.rs`) each claim to +confirm the CPU still takes interrupts after the probe vector. They read +`taken_before = deliveries_total(cpu)` before `apic::send_self`. The probe's +own delivery is counted in that total. Once `delivered` has held, the probe's +source count is past `before`, so `deliveries_total(cpu) > taken_before` is +already true at the first poll. A CPU left deaf by the probe's handler passes +the check, and the `3/3` line says "the CPU took interrupts after it" either +way. + +The code fix is in `main`: each selftest reads the total once the probe's +handler has returned, and arms the BSP's one-shot with `arm_within` so an +interrupt past it is due inside the budget. The exit is unread: no QEMU guest +test arms either selftest, and the T14 row `lapic_spurious_vector` has not +booted the fix. The mutation is `selftests-deaf-after-probe-on-head.patch` +(both gates `iretq` with IF cleared), and its negative control +`selftests-deaf-after-probe-on-base.patch`, both posted on the pull request +that landed the fix (#741). Until the row is read, the check that this claims +can fail is still a reading of the code. + +Owner: the LAPIC selftests, `kernel/src/arch/x86_64/idt/`. + +**Exit:** three T14 runs of `lapic_spurious_vector` are read. The fixed head +is green, both selftests `3/3` with `(0 -> 1)`; the head with +`selftests-deaf-after-probe-on-head.patch` is red, on both `… took no +interrupt at all after …` lines; the head with +`selftests-deaf-after-probe-on-base.patch`, the fix reverted under the same +mutation, is green, the defect the fix removes. From 3103522e32855bacb29f5d11d4d9fafb4d1c0ad6 Mon Sep 17 00:00:00 2001 From: japabu Date: Wed, 7 Oct 2026 14:29:28 +0200 Subject: [PATCH 6/8] The LAPIC selftests' after-check reads the timer it armed, not a total Each selftest armed the one-shot and then accepted any rise of `irq_census::deliveries_total(cpu)`, and that total counts `Source::Nmi`. Every metal image carries a boot deadline (`tests/common/metal.rs`), so `deadline::start` has armed the hard-lockup sampler's performance-counter NMI on the BSP before `interrupt_selftests` runs, and an NMI is delivered whatever `IF` holds. One landing inside the 50 ms budget moved the total on a CPU the probe's handler had left with `IF` clear, and the check passed. The check now waits for `Source::Timer`, the interrupt it armed: maskable, so a count that moves is a CPU that takes interrupts. The failure line says that. `deliveries_total` has no caller left and goes, and `sum_except`'s parameter, left with one value, with it. The issue's record of the fix and its exit's quoted line follow. Co-Authored-By: Claude Opus 5.5 --- ...took-interrupts-after-check-cannot-fail.md | 23 +++++++++++-------- kernel/src/arch/x86_64/idt/spurious.rs | 13 +++++------ kernel/src/arch/x86_64/idt/unclaimed.rs | 11 ++++----- kernel/src/irq_census.rs | 22 +++++++----------- 4 files changed, 32 insertions(+), 37 deletions(-) diff --git a/issues/the-spurious-and-unclaimed-selftests-took-interrupts-after-check-cannot-fail.md b/issues/the-spurious-and-unclaimed-selftests-took-interrupts-after-check-cannot-fail.md index b04dc6b63e2..9dc28959dbc 100644 --- a/issues/the-spurious-and-unclaimed-selftests-took-interrupts-after-check-cannot-fail.md +++ b/issues/the-spurious-and-unclaimed-selftests-took-interrupts-after-check-cannot-fail.md @@ -16,21 +16,24 @@ already true at the first poll. A CPU left deaf by the probe's handler passes the check, and the `3/3` line says "the CPU took interrupts after it" either way. -The code fix is in `main`: each selftest reads the total once the probe's -handler has returned, and arms the BSP's one-shot with `arm_within` so an -interrupt past it is due inside the budget. The exit is unread: no QEMU guest -test arms either selftest, and the T14 row `lapic_spurious_vector` has not -booted the fix. The mutation is `selftests-deaf-after-probe-on-head.patch` -(both gates `iretq` with IF cleared), and its negative control +The code fix is in `main`: each selftest arms the BSP's one-shot with +`arm_within` once the probe's handler has returned, and waits for the timer's +own count (`Source::Timer`) to move. Never a total: every metal image carries +a boot deadline, so the hard-lockup sampler's performance-counter NMI is armed +on the BSP before the selftests run, and an NMI is counted whatever `IF` +holds. The exit is unread on hardware: no QEMU guest test arms either +selftest, and the T14 row `lapic_spurious_vector` has not booted the fix. The +mutation is `selftests-deaf-after-probe-on-head.patch` (both gates `iretq` +with IF cleared), and its negative control `selftests-deaf-after-probe-on-base.patch`, both posted on the pull request -that landed the fix (#741). Until the row is read, the check that this claims -can fail is still a reading of the code. +that landed the fix (#741). Until the row is read, that the check can fail on +the T14 is still a reading of the code. Owner: the LAPIC selftests, `kernel/src/arch/x86_64/idt/`. **Exit:** three T14 runs of `lapic_spurious_vector` are read. The fixed head is green, both selftests `3/3` with `(0 -> 1)`; the head with -`selftests-deaf-after-probe-on-head.patch` is red, on both `… took no -interrupt at all after …` lines; the head with +`selftests-deaf-after-probe-on-head.patch` is red, on both `… did not take +the timer interrupt armed after …` lines; the head with `selftests-deaf-after-probe-on-base.patch`, the fix reverted under the same mutation, is green, the defect the fix removes. diff --git a/kernel/src/arch/x86_64/idt/spurious.rs b/kernel/src/arch/x86_64/idt/spurious.rs index f52a8e47a82..87033cd496d 100644 --- a/kernel/src/arch/x86_64/idt/spurious.rs +++ b/kernel/src/arch/x86_64/idt/spurious.rs @@ -107,18 +107,17 @@ pub fn selftest() { return; } - // Confirms the CPU still takes interrupts afterward; any source works, since only a deaf CPU is ruled out. - // Read now the handler has returned, so the probe's own delivery is already in it, - // and the one-shot armed so an interrupt comes. - let taken = crate::irq_census::deliveries_total(cpu).unwrap_or(0); + // Confirms the CPU still takes interrupts afterward, by the one it arms here. + // The timer's own count and never a total: the hard-lockup sampler's NMI lands whatever `IF` holds. + let taken = crate::irq_census::deliveries(cpu, Source::Timer).unwrap_or(0); apic::arm_within(kernel::sched::fair::QUANTUM_NS); let ran_on = crate::clock::settles(ARRIVES.nanos(), || { - crate::irq_census::deliveries_total(cpu).unwrap_or(taken) > taken + crate::irq_census::deliveries(cpu, Source::Timer).unwrap_or(taken) > taken }); if !ran_on { crate::log!( - "LAPIC: spurious selftest FAILED — cpu{cpu} took no interrupt at all after the \ - spurious one" + "LAPIC: spurious selftest FAILED — cpu{cpu} did not take the timer interrupt armed \ + after the spurious one" ); return; } diff --git a/kernel/src/arch/x86_64/idt/unclaimed.rs b/kernel/src/arch/x86_64/idt/unclaimed.rs index 2bb20d79339..e88871ea50e 100644 --- a/kernel/src/arch/x86_64/idt/unclaimed.rs +++ b/kernel/src/arch/x86_64/idt/unclaimed.rs @@ -160,17 +160,16 @@ pub fn selftest() { return; } - // Read now the handler has returned, so the probe's own delivery is already in it, - // and the one-shot armed so an interrupt comes. - let taken = crate::irq_census::deliveries_total(cpu).unwrap_or(0); + // The timer's own count and never a total: the hard-lockup sampler's NMI lands whatever `IF` holds. + let taken = crate::irq_census::deliveries(cpu, Source::Timer).unwrap_or(0); apic::arm_within(kernel::sched::fair::QUANTUM_NS); let ran_on = crate::clock::settles(ARRIVES.nanos(), || { - crate::irq_census::deliveries_total(cpu).unwrap_or(taken) > taken + crate::irq_census::deliveries(cpu, Source::Timer).unwrap_or(taken) > taken }); if !ran_on { crate::log!( - "LAPIC: unclaimed selftest FAILED — cpu{cpu} took no interrupt at all after the \ - unclaimed one" + "LAPIC: unclaimed selftest FAILED — cpu{cpu} did not take the timer interrupt armed \ + after the unclaimed one" ); return; } diff --git a/kernel/src/irq_census.rs b/kernel/src/irq_census.rs index 196ed8ee04a..41b6cc13449 100644 --- a/kernel/src/irq_census.rs +++ b/kernel/src/irq_census.rs @@ -56,9 +56,9 @@ impl Source { ]; } -/// Every source's count summed, bar `except`'s. -fn sum_except(counts: &[u64; Source::COUNT], except: Option) -> u64 { - counts.iter().sum::() - except.map_or(0, |source| counts[source as usize]) +/// Every source's count summed, bar the NMI's. +fn sum_bar_nmi(counts: &[u64; Source::COUNT]) -> u64 { + counts.iter().sum::() - counts[Source::Nmi as usize] } // Counted where each is taken, by the architecture's handlers @@ -106,30 +106,24 @@ pub fn deliveries(cpu: u32, source: Source) -> Option { read(cpu).map(|counts| counts[source as usize]) } -/// Every CPU's total delivery count, or `None` if that CPU has never been built. -#[cfg(feature = "boot-actuators")] -pub fn deliveries_total(cpu: u32) -> Option { - read(cpu).map(|counts| sum_except(&counts, None)) -} - /// **One CPU's progress: every interrupt it has taken except the NMI.** /// /// What `crate::hardlockup` compares one sample to the next, and the exclusion -/// is the whole of why this is not [`deliveries_total`]: that sample arrives -/// *as* an NMI and has already counted itself by the time it reads this, so a -/// total including it moves on every sample and no CPU is ever stuck. +/// is load-bearing: that sample arrives *as* an NMI and has already counted +/// itself by the time it reads this, so a total including it moves on every +/// sample and no CPU is ever stuck. /// /// One published pointer and relaxed loads: no lock, so the CPU sealing a /// record about a sibling can read this about it. pub fn taken_by(cpu: u32) -> Option { - read(cpu).map(|counts| sum_except(&counts, Some(Source::Nmi))) + read(cpu).map(|counts| sum_bar_nmi(&counts)) } /// [`taken_by`] for the CPU asking, read straight off its own block — the one /// form a CPU inside an NMI may use, since it needs neither the published /// pointer array nor a bounds check on a `cpu_id` it is standing on. pub fn taken_here() -> u64 { - sum_except(&percpu::irq_counts_here(), Some(Source::Nmi)) + sum_bar_nmi(&percpu::irq_counts_here()) } /// Logs one `irq: cpuN =…` line per online CPU; counts are cumulative since boot. From 45b0402b7dc3a96292fbafb98c8423ee05083b18 Mon Sep 17 00:00:00 2001 From: japabu Date: Wed, 7 Oct 2026 15:19:28 +0200 Subject: [PATCH 7/8] The after-check issue says what the selftests read before the fix in the past tense Its first paragraph still said, in the present tense, that the selftests read `deliveries_total(cpu)`: the branch deletes that function, and the selftests at this head read the timer's count. The paragraph now says what the defect was. Review round 2 of #741, NOTE 3. Co-Authored-By: Claude Opus 5.5 --- ...tests-took-interrupts-after-check-cannot-fail.md | 13 ++++++------- 1 file changed, 6 insertions(+), 7 deletions(-) diff --git a/issues/the-spurious-and-unclaimed-selftests-took-interrupts-after-check-cannot-fail.md b/issues/the-spurious-and-unclaimed-selftests-took-interrupts-after-check-cannot-fail.md index 9dc28959dbc..6be5faf754a 100644 --- a/issues/the-spurious-and-unclaimed-selftests-took-interrupts-after-check-cannot-fail.md +++ b/issues/the-spurious-and-unclaimed-selftests-took-interrupts-after-check-cannot-fail.md @@ -8,13 +8,12 @@ opened: 2026-10-04 `spurious::selftest` (`kernel/src/arch/x86_64/idt/spurious.rs`) and `unclaimed::selftest` (`kernel/src/arch/x86_64/idt/unclaimed.rs`) each claim to -confirm the CPU still takes interrupts after the probe vector. They read -`taken_before = deliveries_total(cpu)` before `apic::send_self`. The probe's -own delivery is counted in that total. Once `delivered` has held, the probe's -source count is past `before`, so `deliveries_total(cpu) > taken_before` is -already true at the first poll. A CPU left deaf by the probe's handler passes -the check, and the `3/3` line says "the CPU took interrupts after it" either -way. +confirm the CPU still takes interrupts after the probe vector. Before the fix +they read a total of the CPU's deliveries before `apic::send_self` and passed +once it had risen. The probe's own delivery was counted in that total, so the +check was already true at the first poll after `delivered` held: a CPU left +deaf by the probe's handler passed, and the `3/3` line said "the CPU took +interrupts after it" either way. The code fix is in `main`: each selftest arms the BSP's one-shot with `arm_within` once the probe's handler has returned, and waits for the timer's From a0ecc30b9dd6fd10de57ef8e550370f229a183b2 Mon Sep 17 00:00:00 2001 From: japabu Date: Wed, 7 Oct 2026 16:20:09 +0200 Subject: [PATCH 8/8] The T14 read the after-check's exit, so its issue closes MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit issues/the-spurious-and-unclaimed-selftests-took-interrupts-after-check-cannot-fail.md asked for three T14 runs of lapic_spurious_vector. All three were run on the images staged at 45b0402b7, each one boot, judged by the row's own judge: - the head (image 2d2bd892...73772a): judge exit 0, both selftests "3/3 ... (0 -> 1) ... and the CPU took interrupts after it", and the nine other rows of that boot exit 0 each. - the head with selftests-deaf-after-probe-on-head.patch (image b470abbb...aab35f, built from f73a47f29): judge exit 1, on "LAPIC: spurious selftest FAILED — cpu0 did not take the timer interrupt armed after the spurious one"; the boot log carries the unclaimed selftest's same line 50 ms later, and then goes on to "Boot: complete", the supervisor, test-runner's reboot test and a reboot the next loader pass read as DONE. No WEDGED record, no panic, no "never arrived", no 3/3 line. - the head with selftests-deaf-after-probe-on-base.patch, the branch's whole kernel diff reverted under the same mutation (image d6932e7b...6fcb5f, built from 798288fb6): judge exit 0, both 3/3 lines. A deaf CPU passed the base's total: the defect. So the check fails on the hardware on a CPU the probe's handler left deaf, and the base's did not. The rule the issue carried is already at each selftest's read: the timer's own count and never a total. No citation of the file is left in the tree: git grep of the slug, of "check cannot fail" and of the two patch names finds only the file. Co-Authored-By: Claude Opus 5.5 --- ...took-interrupts-after-check-cannot-fail.md | 38 ------------------- 1 file changed, 38 deletions(-) delete mode 100644 issues/the-spurious-and-unclaimed-selftests-took-interrupts-after-check-cannot-fail.md diff --git a/issues/the-spurious-and-unclaimed-selftests-took-interrupts-after-check-cannot-fail.md b/issues/the-spurious-and-unclaimed-selftests-took-interrupts-after-check-cannot-fail.md deleted file mode 100644 index 6be5faf754a..00000000000 --- a/issues/the-spurious-and-unclaimed-selftests-took-interrupts-after-check-cannot-fail.md +++ /dev/null @@ -1,38 +0,0 @@ ---- -status: open -kind: defect -opened: 2026-10-04 ---- - -# The spurious and unclaimed selftests' "took interrupts after it" check cannot fail - -`spurious::selftest` (`kernel/src/arch/x86_64/idt/spurious.rs`) and -`unclaimed::selftest` (`kernel/src/arch/x86_64/idt/unclaimed.rs`) each claim to -confirm the CPU still takes interrupts after the probe vector. Before the fix -they read a total of the CPU's deliveries before `apic::send_self` and passed -once it had risen. The probe's own delivery was counted in that total, so the -check was already true at the first poll after `delivered` held: a CPU left -deaf by the probe's handler passed, and the `3/3` line said "the CPU took -interrupts after it" either way. - -The code fix is in `main`: each selftest arms the BSP's one-shot with -`arm_within` once the probe's handler has returned, and waits for the timer's -own count (`Source::Timer`) to move. Never a total: every metal image carries -a boot deadline, so the hard-lockup sampler's performance-counter NMI is armed -on the BSP before the selftests run, and an NMI is counted whatever `IF` -holds. The exit is unread on hardware: no QEMU guest test arms either -selftest, and the T14 row `lapic_spurious_vector` has not booted the fix. The -mutation is `selftests-deaf-after-probe-on-head.patch` (both gates `iretq` -with IF cleared), and its negative control -`selftests-deaf-after-probe-on-base.patch`, both posted on the pull request -that landed the fix (#741). Until the row is read, that the check can fail on -the T14 is still a reading of the code. - -Owner: the LAPIC selftests, `kernel/src/arch/x86_64/idt/`. - -**Exit:** three T14 runs of `lapic_spurious_vector` are read. The fixed head -is green, both selftests `3/3` with `(0 -> 1)`; the head with -`selftests-deaf-after-probe-on-head.patch` is red, on both `… did not take -the timer interrupt armed after …` lines; the head with -`selftests-deaf-after-probe-on-base.patch`, the fix reverted under the same -mutation, is green, the defect the fix removes.