From 41b482378310a05fa7ebb0949c795329c162b11e Mon Sep 17 00:00:00 2001 From: japabu Date: Thu, 8 Oct 2026 12:49:08 +0200 Subject: [PATCH 1/2] The power-off's lost Global Lock line is an issue on main `acpi_mediated_access` reds main's nightly `tcg / suite` (run 37758546165 at b6bcb9691) and was seen once more locally under load. The text is the one written on wt/toyos-pcislot (5d1469615), carried here unchanged so that the fix that follows closes a record main has. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01RvnWQFcMuGqTHYhvSnTe8A --- ...-is-logged-after-the-last-console-drain.md | 57 +++++++++++++++++++ 1 file changed, 57 insertions(+) create mode 100644 issues/the-power-offs-global-lock-line-is-logged-after-the-last-console-drain.md diff --git a/issues/the-power-offs-global-lock-line-is-logged-after-the-last-console-drain.md b/issues/the-power-offs-global-lock-line-is-logged-after-the-last-console-drain.md new file mode 100644 index 00000000000..e23d06a9a25 --- /dev/null +++ b/issues/the-power-offs-global-lock-line-is-logged-after-the-last-console-drain.md @@ -0,0 +1,57 @@ +--- +status: open +kind: defect +opened: 2026-10-08 +--- + +# The power-off logs the Global Lock's give-back after the console's last drain, and `acpi_mediated_access` waits for that line + +`acpi_mediated_access` (`tests/toyos.rs`) ends its wait on the kernel's line +`acpi: the Global Lock given back for a holder that left it taken (the machine +is stopping)`. Twice it never arrived, and the harness ended the guest after +`GUEST_QUIET` (15 s) of silence: + +``` +FAIL acpi_mediated_access: STALLED: waiting for the probe's power-off to give the lock back — it went quiet +``` + +| where | head | instrument | load | result | +|---|---|---|---|---| +| `main`'s nightly, run 37758546165, `tcg / suite` | `b6bcb9691` | TCG on a hosted 4-core x86-64 runner, 31 tests one wide | the suite alone | STALL after 18 s | +| the development machine, a whole-suite run of #763 | `252d19247` | TCG, x86-64 guest on an AArch64 host, 14 cores, 12 wide | load average 45 to 67: five agents compiling beside the suite | STALL after 35 s | +| `main`'s merge queue, six runs, #749 to #746 (37753990562, 37755528529, 37757410477, 37758981663, 37759626406, 37760845496), `guest / suite` | `6f87cdb9c` to `1084ddc9a` | KVM on hosted 4-core runners, 31 tests one wide | the suite alone | PASS, 3 s each | +| the development machine, `acpi_` by name | `252d19247` | TCG, 2 tests | run alone | PASS, 4 s | + +The nightly's head has #749, which added the test, and nothing of #763: the +red is `main`'s. KVM on a hosted runner is not TCG on a loaded host, so the +six green runs say only that the test passes where the guest is fast. + +## What was read + +`power::shutdown` (`kernel/src/power.rs`) calls `serial::flush_final()` under +the comment "Last chance: nothing drains the log ring after this point", and +then `arch::power::off`. `off` (`kernel/src/arch/x86_64/power.rs`) calls +`acpi_mode::settle`, whose `give_back` logs the line the test waits for, then +`acpi_mode::quiet`, then writes `SLP_TYP` and `SLP_EN`. So the line is +committed after the stop's last drain. Past boot the console's one writer is +`klogd` (`kernel/src/log/console.rs`, `Drain::Thread`), woken at the commit: the +line reaches the host only if `klogd`, on the other CPU, puts it on the wire +before this CPU has made one port read, `quiet`'s writes and the two writes +that end the machine. Nothing waits for it. + +That is a reading, and no run confirms it: neither red kept what the guest +said after boot. The test passes `await_guest`'s error up without its capture, +and the `uart-*.log` the nightly kept (artifact `serial-suite`, `uart-6.log`, +the `i8042-withheld` boot) ends where every boot's does, at the hand-over to +the virtio console. It fits both reds: the nightly's 18 s is the 3 s the test +takes under KVM and the 15 s of `GUEST_QUIET`. A probe whose arm failed would +have ended the wait by `===TEST_END`, and a kernel panic by its own line. + +The branch that saw it locally moves nothing here: `settle`, `give_back`, +`off`, `shutdown` and the console are `main`'s bytes in #763. + +Owner: the `acpi` claim's author (#749). + +**Exit**: `acpi_mediated_access` green in the nightly's `tcg / suite`, with the +give-back's line on the wire before `SLP_EN` by construction and not by +`klogd` winning; and a stall of this test carrying what the guest said. From e3a2022d14462fccb34d48000c5372495d316f34 Mon Sep 17 00:00:00 2001 From: japabu Date: Thu, 8 Oct 2026 13:10:19 +0200 Subject: [PATCH 2/2] The power-off says what it has to say above the log's last drain `power::shutdown` drained the log ring (`serial::flush_final`), stopped USB, and only then called `arch::power::off`, whose `acpi_mode::settle` gives back a Global Lock its holder was stopped holding and logs that it did. The record was committed after the ring's last reader had gone, so it reached the console only if `klogd`, on the other CPU, put it on the wire before this CPU had made one port read, `quiet`'s writes and the two writes of `SLP_TYP` and `SLP_EN`. `acpi_mediated_access` waits for that line. Under KVM the merge queue's six runs won the race in 3 s each; under TCG main's nightly lost it (run 37758546165 at b6bcb9691, `tcg / suite`: STALLED after 18 s, which is the test's 3 s and the 15 s of GUEST_QUIET), and so did a whole-suite run on the development machine at a load average of 45 to 67 on 14 cores. The architecture's power-off is now two calls. `arch::power::settle` takes the hardware back and settles it, which is everything that path logs, and answers a `Settled`; `arch::power::off` takes that value and nothing else, so it cannot be reached before the settle, and `power::shutdown` puts the flush between the two. x86-64's `off` is the PM1 reads and writes and its panic, which drains for itself. AArch64 hands out nothing a power-off takes back, so its `settle` is empty; its `off` already wrote every line straight to the UART. The reboot and the fatal paths were read for the same shape and do not have it: `reboot` flushes and then asserts and resets, x86-64's `reset` is one port write, AArch64's writes its refusal raw, and `stop::before_reset` writes the black box and no record. What moved besides the log: the take-back's TLB shootdown, the wait for an `SMI_CMD` write in flight and the lock's give-back now come before the flush and the USB stop instead of after them, and a machine with no soft-off settles before it halts where it halted first. The test's stall now carries what the guest said since its boot: neither red kept a line of it, which is why the cause was a reading and no run. `acpi_lock_given_back_on_one_cpu` is `acpi_mediated_access`'s boot on one CPU. There the power-off's CPU is the only one, the stop runs with preemption off, and no `klogd` runs beside it: a record committed below the last drain reaches no wire. With the kernel's change reverted that boot stalled on the give-back's line three times of three on the development machine, its capture ending at `Shutting down.`; with it the line arrived three of three. On two CPUs the same revert is green there, which is how the order got in. The two-CPU row stays for what one CPU cannot say: the second CPU's range registers beside the unlisted read. The issue stays, assigned: its exit names a green nightly `tcg / suite`, which only a nightly on a main that carries this can show, and the read is the orchestrator's at landing. The file is the bytes #763 and #764 add, with its status changed and a closing section appended. The header's rule is the console's. The black box's tail is sealed in `quiesce`, before either end is entered, so the settle's line is in no page: issues/the-power-offs-give-back-line-is-in-no-black-box-tail.md. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01RvnWQFcMuGqTHYhvSnTe8A --- ...-give-back-line-is-in-no-black-box-tail.md | 42 +++++++++++++++++++ ...-is-logged-after-the-last-console-drain.md | 25 ++++++++++- kernel/src/arch/aarch64/power.rs | 10 ++++- kernel/src/arch/x86_64/power.rs | 23 +++++++--- kernel/src/power.rs | 16 ++++++- tests/toyos.rs | 20 ++++++--- 6 files changed, 122 insertions(+), 14 deletions(-) create mode 100644 issues/the-power-offs-give-back-line-is-in-no-black-box-tail.md diff --git a/issues/the-power-offs-give-back-line-is-in-no-black-box-tail.md b/issues/the-power-offs-give-back-line-is-in-no-black-box-tail.md new file mode 100644 index 00000000000..8c75f9660fa --- /dev/null +++ b/issues/the-power-offs-give-back-line-is-in-no-black-box-tail.md @@ -0,0 +1,42 @@ +--- +status: open +kind: defect +opened: 2026-10-08 +--- + +# What the power-off's settle logs is committed after the black box's tail is sealed + +`quiesce` (`kernel/src/syscall/machine.rs`) says the boot's last word, drains +the console and seals the newest records onto the black box's page +(`log::seal_tail`) before `power::shutdown` is entered. `shutdown` then calls +`arch::power::settle`, whose `acpi_mode::settle` logs `acpi: the Global Lock +given back for a holder that left it taken (the machine is stopping)` where a +holder was stopped holding the lock. That record is committed below the seal: +it is on the console, which `shutdown` drains after it, and in no page tail. +On the console it follows `Shutting down.`, which `quiesce` calls the boot's +last word. + +So on a machine with no serial port no reader keeps the line: `/log`'s writer +was stopped with the rest of userland, `flush_final` has no wire to drain to, +and the page was sealed without it. The T14 is such a machine, and one where +the kernel writes `ACPI_ENABLE` itself and a holder can be stopped holding +the lock. + +What that costs today is narrow. A power-off that takes leaves nothing for a +next loader to read: S5 keeps no memory context by ACPI's definition (the +specification's, not a reading of the T14's DIMMs), and the page is DRAM. The +tail is read after a power-off only where the write did not take: `S5 did not +take`, a panic and then a reset. + +Not moved in #767, which put the settle above the console's drain: the seal +is `quiesce`'s, shared by the reboot, which settles nothing; it stands above +`xhci::seal_shut`, which must be the last thing `quiesce` does, and the +settle needs the `Stopping` and runs below it. Sealing after the settle, or +settling above the last word, is a second change of the stop's order. + +Owner: the `acpi` claim's author (#749). + +**Exit**: no record is committed to the ring below `log::seal_tail` on either +end, read in `quiesce`, `power::shutdown` and `power::reboot`; and +`kernel/src/power.rs`'s header sentence then names the page beside the +console. diff --git a/issues/the-power-offs-global-lock-line-is-logged-after-the-last-console-drain.md b/issues/the-power-offs-global-lock-line-is-logged-after-the-last-console-drain.md index e23d06a9a25..f7344e74d77 100644 --- a/issues/the-power-offs-global-lock-line-is-logged-after-the-last-console-drain.md +++ b/issues/the-power-offs-global-lock-line-is-logged-after-the-last-console-drain.md @@ -1,5 +1,5 @@ --- -status: open +status: assigned kind: defect opened: 2026-10-08 --- @@ -55,3 +55,26 @@ Owner: the `acpi` claim's author (#749). **Exit**: `acpi_mediated_access` green in the nightly's `tcg / suite`, with the give-back's line on the wire before `SLP_EN` by construction and not by `klogd` winning; and a stall of this test carrying what the guest said. + +## What landed, and what is still owed + +Everything above is `main` before #767 and is kept as it was written. #767 +split the architecture's power-off in two: `arch::power::settle` says the +give-back's line, `power::shutdown` drains the console after it, and +`arch::power::off` takes the value only `settle` makes and logs nothing. The +exit's second and third clauses are met by that pull request: the order is +`kernel/src/power.rs`'s `shutdown`, and the test's stall appends what the +guest said since its boot. + +The reading above has since been run. On one CPU no other CPU runs `klogd` +beside the power-off, and the line never arrived with the split reverted, +three boots of three, each capture ending at `Shutting down.`; with it the +line arrived, three of three. `acpi_lock_given_back_on_one_cpu` +(`tests/toyos.rs`) is that boot. + +Its first clause is not met: no nightly has run `tcg / suite` on a `main` +that carries #767. + +Assigned: the orchestrator, at #767's landing. He reads `acpi_mediated_access` +in the first nightly `tcg / suite` on a `main` that carries it, and deletes +this file on a green; a stall there prints the guest's words, and goes here. diff --git a/kernel/src/arch/aarch64/power.rs b/kernel/src/arch/aarch64/power.rs index 477042084df..a400f9fe728 100644 --- a/kernel/src/arch/aarch64/power.rs +++ b/kernel/src/arch/aarch64/power.rs @@ -35,12 +35,20 @@ pub fn reset() -> ! { cpu::halt() } +/// What [`off`] takes: this machine hands out nothing a power-off takes back. +pub struct Settled(()); + +/// Nothing to settle, and so nothing said. +pub fn settle(_stopping: crate::quiesce::Stopping) -> Settled { + Settled(()) +} + /// `SYSTEM_OFF`, once every other CPU the roster holds has turned itself off /// with `CPU_OFF` and PSCI answers it off: the caller puts every core in a /// known state first, and this is DEN0022 §5.10.3's own way to. The budget /// for all of them is [`DEAF_CPU`]'s span from the SGI: a CPU PSCI still /// answers on at its end is named, and the machine powers off regardless. -pub fn off(_stopping: crate::quiesce::Stopping) -> ! { +pub fn off(_settled: Settled) -> ! { cpu::disable_interrupts(); let Some(psci) = psci::conduit() else { cpu::halt() }; irqchip::off_all_but_self(); diff --git a/kernel/src/arch/x86_64/power.rs b/kernel/src/arch/x86_64/power.rs index 0eed43f9429..55585056afb 100644 --- a/kernel/src/arch/x86_64/power.rs +++ b/kernel/src/arch/x86_64/power.rs @@ -13,7 +13,7 @@ use toyos_acpi::{Reset, Table, TableError, S5, SDT_HEADER_LEN, SDT_REVISION}; use toyos_userbound::{Mediated, Ports}; use super::cpu; -use super::pio::{self, Declared, Slot}; +use super::pio::{self, Declared, Slot, TakenBack}; use crate::drivers::acpi::direct_phys; use crate::log; use crate::time::{Deadline, Duration, Tripwire}; @@ -153,8 +153,24 @@ const S5_TAKES: Tripwire = Tripwire::absurd( this kernel two seconds later never entered it", ); +/// The hardware taken back for the power-off, with everything [`settle`] +/// says said: what [`off`] takes, so the log's last drain stands between. +pub struct Settled(TakenBack); + +/// Take the hardware back from whoever was handed it, waiting out a write to +/// `SMI_CMD` and an act for the `acpi` claim's holder in flight, and give +/// back a Global Lock that holder was stopped holding. +pub fn settle(stopping: crate::quiesce::Stopping) -> Settled { + let taken = pio::take_back(&stopping); + super::smi_cmd::settle(&taken); + super::acpi_mode::settle(&taken); + Settled(taken) +} + /// Enter S5, or halt on a machine whose tables named no soft-off. /// +/// **Nothing here logs**: the log's last drain is behind it (`power::shutdown`). +/// /// ACPI 6.5 §16.1.6's order: on a machine in ACPI mode, which is the OS's /// to put to sleep, every event is disabled and every status cleared first /// (`acpi_mode::quiet`), so no event pending at the write wakes it again; @@ -166,12 +182,9 @@ const S5_TAKES: Tripwire = Tripwire::absurd( /// the panel shows it, and the black box carries it through the panic's reset, /// where a halt would leave a machine that is on, silent, and indistinguishable /// from one the power left. -pub fn off(stopping: crate::quiesce::Stopping) -> ! { +pub fn off(Settled(taken): Settled) -> ! { let (Some(control), true) = (PM1A_CNT.get(), SOFT_OFF.load(Ordering::Acquire)) else { cpu::halt() }; let control = control.port(0); - let taken = pio::take_back(&stopping); - super::smi_cmd::settle(&taken); - super::acpi_mode::settle(&taken); let held = cpu::inw(control); if held & SCI_EN != 0 { super::acpi_mode::quiet(&taken); diff --git a/kernel/src/power.rs b/kernel/src/power.rs index cfca578edf2..e6c67dac829 100644 --- a/kernel/src/power.rs +++ b/kernel/src/power.rs @@ -8,6 +8,16 @@ //! than of whoever asked for one, and what a third caller gets without knowing //! it is owed. Resets this kernel does not perform — a TCO or firmware //! watchdog, a triple fault, power loss — are outside it and always will be. +//! +//! **Nothing an end says is logged after the console's last drain.** +//! `serial::flush_final` is the log ring's last reader for the console: a +//! record committed past it reaches the wire only if `klogd`, on another CPU, +//! beats the register write. What an end says through the ring it says above +//! the flush (`arch::power::settle`); `arch::power::off` and +//! `arch::power::reset` log nothing, and a panic in either drains for itself. +//! The black box's page is another reader and an earlier one: its tail is +//! sealed before either end is entered (`log::seal_tail`), so what `settle` +//! says is on the console and in no page. use crate::drivers::{serial, xhci::stop}; @@ -49,11 +59,13 @@ pub fn reset_now() -> ! { /// Power the machine off, or halt on one that offers no power-off. pub fn shutdown(stopping: crate::quiesce::Stopping) -> ! { - // Last chance: nothing drains the log ring after this point. + // Above the flush, because it logs. + let settled = crate::arch::power::settle(stopping); + // Nothing drains the log ring after this point, and nothing below logs. serial::flush_final(); // A power-off takes VBUS with it on a machine whose ports are not // always-on and takes nothing on one whose are, so the devices are handed // back here for the same reason as at a reboot. stop::before_reset(); - crate::arch::power::off(stopping) + crate::arch::power::off(settled) } diff --git a/tests/toyos.rs b/tests/toyos.rs index b0ebf22de57..fd73a124219 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -271,6 +271,10 @@ const MACHINE_TESTS: &[&str] = &[ // that owes `GBL_RLS` need the FACS's word staged as only an idle firmware // allows: neither is done to the T14, which nothing powers on again. "acpi_mediated_access", + // The same boot on one CPU, where the power-off's CPU is the only one + // there is: what it logs reaches the console by the stop's own drain or + // not at all, since no other CPU runs `klogd` beside it. + "acpi_lock_given_back_on_one_cpu", // The power-off after a stop that left a thread running, in ACPI mode: it // ends the machine, so only one QEMU reports stopping can be asked, and // the T14 hands over in legacy mode, where no holder means no quieting. @@ -1719,8 +1723,9 @@ const ACPI_MEDIATED_SAID: [&str; 8] = [ /// given back for the probe itself, which asks for the power-off holding it /// once every arm has passed. The probe does not come back from that, so its /// verdict is its last line and the kernel's; a probe that ends instead is -/// one whose arm failed. -fn acpi_mediated_access() -> Result<(), String> { +/// one whose arm failed. On `cpus` CPUs: the second one's range registers are +/// read where there is one. +fn acpi_mediated_access(cpus: u32) -> Result<(), String> { const JOB: &str = "test_rs_acpi_mediated"; const HELD_INTO_THE_STOP: &str = "acpi: holding the Global Lock, and asking for the power-off with it"; const GIVEN_BACK_AT_THE_STOP: &str = "acpi: the Global Lock given back for a holder that left it taken (the machine is stopping)"; @@ -1733,6 +1738,7 @@ fn acpi_mediated_access() -> Result<(), String> { // The test kernel, for the Global Lock's actuator too. kernel_params: &["i8042-withheld"], ready_marker: "acpi: the ACPI row: ", + smp: cpus, extra_root_files: vec![suite_bin(toyos_build::arch::Arch::X86_64, "acpi_mediated")], ..Default::default() }, @@ -1741,7 +1747,9 @@ fn acpi_mediated_access() -> Result<(), String> { let ended = format!("===TEST_END {JOB} "); await_guest(&mut qemu, &mut console, "the probe's power-off to give the lock back", |said| { said.contains(GIVEN_BACK_AT_THE_STOP) || said.contains(&ended) - })?; + }) + // The probe's whole run: a wait that ends on neither line has no other account of it. + .map_err(|why| format!("{why}\nsince its boot the guest said:\n{}", &console[qemu.boot_log().len()..]))?; let said = serial::Serial::named("the probe's boot", console); said.must_be_clean()?; said.must_say(isa::WITHHELD)?; @@ -1749,7 +1757,8 @@ fn acpi_mediated_access() -> Result<(), String> { said.must_say("acpi: the Global Lock given back for a holder that left it taken (its claim is gone)")?; // Whose range registers passed the unlisted read, and how this // hypervisor's second CPU holds its own beside them. - for line in ["mtrr: the boot processor's range registers: ", "mtrr: cpu1's range registers are "] { + let mtrr = ["mtrr: the boot processor's range registers: ", "mtrr: cpu1's range registers are "]; + for line in mtrr.iter().take(cpus as usize) { eprintln!(" [acpi] {}", said.must_say(line)?.trim()); } for line in ACPI_MEDIATED_SAID { @@ -2794,7 +2803,8 @@ fn run_machine_test(name: &str, test_config: &Path) -> Result<(), String> { "nested_nmi_is_loud" => faults::nested_nmi_is_loud(test_config), "machine_shutdown" => power::machine_shutdown(test_config), "acpi_power_button" => power::acpi_power_button(test_config), - "acpi_mediated_access" => acpi_mediated_access(), + "acpi_mediated_access" => acpi_mediated_access(2), + "acpi_lock_given_back_on_one_cpu" => acpi_mediated_access(1), "machine_shutdown_short_stop" => power::machine_shutdown_short_stop(test_config), other => Err(format!("unknown machine test {other}")), }