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