From 9e70cd2e3ff8b785bd146bcefd79c6918f480351 Mon Sep 17 00:00:00 2001 From: japabu Date: Thu, 8 Oct 2026 22:57:49 +0200 Subject: [PATCH 1/2] A hole in a T14 boot's log reds that boot by name, and the two ACPI rows ride testcases again: 26 boots to 25 A metal judge reads what the stick came back with. A boot that outlogs logkeeper's retention deletes its own middle, by design, and a judge then reports a deleted line missing while a judge that asserts an absence passes over the hole. Nothing said the readback had one. bootlog::lost_parts reads logkeeper's own deletion lines for the stem the boot's opening line names, and read_readback refuses such a readback before any row or member is judged: the refused-boot path, no new type, no guess at which rows' lines sat in the hole. A program's line carrying the same words, a kernel record carrying them, and an earlier boot's file deleted to make room are none of them this boot's hole. Both of logkeeper's spellings are held to its source, since nothing links the build system to that program. Each boot's line in "the boots" now gives its log's bytes. acpi_hold slept to 54 s after boot so that acpiserver's count line, written thirty seconds after it arms, was in the log before the reboot. It now waits for that line on the `log` port, bounded by the same 54 s, and exits non-zero without it. The reader it shares with counters_metal moves to src/served_log.rs. With that, acpi_server_events and acpi_tables_loaded name TESTCASES and testcases-hold goes, with its three rows of the T14's record. The hold is the boot's last job: counters_metal and fault_gates join the constant so the order is the constant's and not the table's. Step A tried this ride once and the row went red because the count line fell in the deleted middle; #776 cut the kernel's records per process, the boot's log is about 7.6 MB and whole, and a hole would now red the boot by name. Issues: the retention issue says which legs of its exit are met and which are left; the elide issue loses a reason #773's landing spent; the thread-ended issue's exit legs are in the order they can be met in. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01RvnWQFcMuGqTHYhvSnTe8A --- ...ddle-and-the-rows-whose-lines-sat-there.md | 36 ++++-- ...-last-word-and-no-record-can-say-so-now.md | 10 +- ...as-one-user-and-lives-in-a-shared-crate.md | 5 +- src/bootlog.rs | 118 ++++++++++++++++++ tests/checks.rs | 5 + tests/checks/metal.rs | 40 ++++++ tests/common/metal.rs | 14 ++- tests/metal/lenovo-20w0003amz.toml | 3 - tests/toyos-rust-tests/src/bin/acpi_hold.rs | 30 +++-- .../src/bin/counters_metal.rs | 51 +------- tests/toyos-rust-tests/src/served_log.rs | 49 ++++++++ tests/toyos.rs | 18 ++- 12 files changed, 295 insertions(+), 84 deletions(-) create mode 100644 tests/toyos-rust-tests/src/served_log.rs diff --git a/issues/a-t14-boot-that-outlogs-its-retention-loses-its-middle-and-the-rows-whose-lines-sat-there.md b/issues/a-t14-boot-that-outlogs-its-retention-loses-its-middle-and-the-rows-whose-lines-sat-there.md index 1c9bb775b02..d7650680901 100644 --- a/issues/a-t14-boot-that-outlogs-its-retention-loses-its-middle-and-the-rows-whose-lines-sat-there.md +++ b/issues/a-t14-boot-that-outlogs-its-retention-loses-its-middle-and-the-rows-whose-lines-sat-there.md @@ -10,8 +10,15 @@ opened: 2026-10-08 `userland/logkeeper/src/store.rs`) and deletes the writing boot's own middle past that, by design: one boot's flood costs its own middle and nobody's start. A metal judge reads what came back, so a line a flooding boot wrote in -its middle is a line the judge reports missing, and nothing in the harness -says the readback has a hole. +its middle is a line the judge reports missing, and a judge that asserts an +absence passes over the hole. + +**A hole is red by name now, and it is the whole boot's.** `bootlog::lost_parts` +reads `logkeeper`'s own deletion lines for the boot's own stem, and +`read_readback` (`tests/common/metal.rs`) refuses such a readback before any +row or member is judged on it: every rider of that boot is red with +`'s own log lost parts 2 to N to retention; no row is judged on it`. +The harness does not guess which rows' lines sat in the hole. `testcases` is such a boot, and the flood was the kernel's, not the job's: `test_rs_counters_metal`'s `loaded` phase spawns a child per CPU in a loop for @@ -42,9 +49,8 @@ that head and takes in no longer. megabytes kept, 98.5% of it still that one job's `spawn:` and `exit:` records, and the phase spawns a child per CPU for twenty seconds: about 2.2 times the children, a sixteen-CPU machine or a faster one, outlogs the retention again. -**The harness is as silent about a hole as it was**: nothing reds a readback -whose own boot deleted a part of its log. How many parts this boot wrote was -not read. +That boot would then red whole, by name, with every row that rides it. The +readback of `c6269f885` rotated seven times and deleted nothing. ## Measured @@ -69,8 +75,12 @@ count line is there at 42.579 s (`28 SCIs; embedded controller queries taken: 0x4f x14`). `testcases`' readback of 2026-10-07 has the same hole: no record in seconds 36 to 47. -So `acpi_server_events` and `acpi_tables_loaded` keep `testcases-hold`, a boot -whose log is whole. +`acpi_server_events` and `acpi_tables_loaded` ride `testcases` again, with +`test_rs_acpi_hold` its last job, and `testcases-hold` is deleted. The job +waits on the `log` port for the server's count line, bounded by the runner's +bound less a tenth, and exits non-zero without it. That readback judged +offline by this harness reds by name: `testcases's own log lost parts 2 to 26 +to retention; no row is judged on it`. ## Owner @@ -80,6 +90,12 @@ fuller: a boot that carries every shipping-kernel member logs more than ## Exit condition -No boot of the metal profile writes past `logkeeper`'s retention, or a -readback whose own boot deleted a part of its log reds by name before any row -is judged on it; and `acpi_server_events` passes on `testcases` on the T14. +Three legs. Met: a readback whose own boot deleted a part of its log reds by +name before any row is judged on it. Left: + +- `acpi_server_events` and `acpi_tables_loaded` pass on `testcases` on the + T14, on a log no part of which was deleted. +- No boot of the metal profile can write past `logkeeper`'s retention on a + machine with more CPUs or faster ones: what `testcases` logs is bounded by + a count, where today it is twenty seconds of however many children the + machine spawns. diff --git a/issues/a-thread-ended-after-the-boots-last-word-and-no-record-can-say-so-now.md b/issues/a-thread-ended-after-the-boots-last-word-and-no-record-can-say-so-now.md index d92da660a0d..3bd94bf798e 100644 --- a/issues/a-thread-ended-after-the-boots-last-word-and-no-record-can-say-so-now.md +++ b/issues/a-thread-ended-after-the-boots-last-word-and-no-record-can-say-so-now.md @@ -34,10 +34,10 @@ Owner: the stop path, `kernel/src/quiesce.rs`. ## Exit condition -- The stop says how many threads ended between its `stop:` record and the - reset, in a record the next loader pass prints, and `stopped_boot` reds on - one that is not zero. - `quiesce_wakes_on_the_last_park`, deleted with the commits `issues/quiesce-wakes-on-the-last-park-gave-up-on-one-thread-beside-the-held-one.md` - names, is back and green beside other guests on a loaded host with that - check in it. + names, is back, and with it `stopped_boot`, which the tree no longer has. +- The stop says how many threads ended between its `stop:` record and the + reset, in a record the next loader pass prints; `stopped_boot` reds on one + that is not zero, and the test is green beside other guests on a loaded + host with that check in it. diff --git a/issues/toyos-elides-limit-has-one-user-and-lives-in-a-shared-crate.md b/issues/toyos-elides-limit-has-one-user-and-lives-in-a-shared-crate.md index bd1761cb2d2..7f4e3ffb167 100644 --- a/issues/toyos-elides-limit-has-one-user-and-lives-in-a-shared-crate.md +++ b/issues/toyos-elides-limit-has-one-user-and-lives-in-a-shared-crate.md @@ -13,13 +13,10 @@ limited. The crate is shared for `Elided`, which `toyos-symbols` uses; what one program alone uses belongs in that program's package (`.claude/agents/reviewer.md`, "Fit"). -Not moved where it was found: PR #773 is open over `userland/logkeeper/src`, -and the module moves into the tree that leaves. - Owner: `userland/logkeeper`. ## Exit condition -Once #773 has landed: `limit.rs` is a module of `userland/logkeeper` with its +`limit.rs` is a module of `userland/logkeeper` with its host tests, `toyos-elide` holds `Elided` and what serves it, its header and `description` say so, and `rg 'toyos_elide::limit'` finds nothing. diff --git a/src/bootlog.rs b/src/bootlog.rs index e50042b5c52..e1219162969 100644 --- a/src/bootlog.rs +++ b/src/bootlog.rs @@ -293,6 +293,59 @@ pub fn split_listing(listing: &str) -> (Option<&str>, Vec<&str>) { (loader, logkeeper) } +/// What `logkeeper` says as it opens a boot's file, before that file's path, in +/// `userland/logkeeper/src/main.rs`. +pub const LOG_OPENED: &str = "logkeeper: this boot's kernel log is "; + +/// What `logkeeper` says either side of the path of a file retention deleted, +/// in `userland/logkeeper/src/store.rs`'s `sweep`. +pub const LOG_RETIRED: [&str; 2] = [" logs, so ", " was deleted"]; + +/// One of `logkeeper`'s paths as its boot's stem and its part, as +/// `userland/logkeeper/src/store.rs` names a part: the first is the bare stem. +fn stem_and_part(path: &str) -> Option<(&str, u32)> { + let name = path.rsplit('/').next()?; + let bare = name.strip_suffix(".log").filter(|_| is_logkeeper_file(name))?; + match bare.split_once('_') { + Some((stem, part)) => Some((stem, part.parse().ok()?)), + None => Some((bare, 1)), + } +} + +/// The parts of its own log the boot `log` ends in deleted to retention, first +/// and last, or `None` for a log that is whole. +/// +/// **Read off `logkeeper`'s own lines, and off their paths**: a program's line +/// can carry the same words, and a boot deletes earlier boots' files without +/// losing a line of its own. Retention takes a boot's continuations oldest +/// first, and the lines naming the oldest go with the parts that held them, so +/// the hole opens at the boot's first continuation and the newest line, which +/// is written into the newest part, closes it. +pub fn lost_parts(log: &str) -> Option<(u32, u32)> { + let mut own: Option<(&str, u32)> = None; + let mut last: Option = None; + for said in log.lines().filter_map(toyos_logstream::program_line) { + if said.tag != toyos_logstream::LOGKEEPER { + continue; + } + if let Some(opened) = said.text.strip_prefix(LOG_OPENED) { + own = opened.split_whitespace().next().and_then(stem_and_part); + last = None; + } + let retired = said + .text + .strip_suffix(LOG_RETIRED[1]) + .and_then(|head| head.split_once(LOG_RETIRED[0])) + .and_then(|(_, path)| stem_and_part(path)); + if let (Some((stem, part)), Some((mine, _))) = (retired, own) { + if stem == mine { + last = last.max(Some(part)); + } + } + } + Some((own?.1 + 1, last?)) +} + /// The kernel's boot-phase record for the end of boot, in /// `kernel/src/log/mod.rs`'s `boot_phase!`. pub const COMPLETE: &str = "Boot: complete ("; @@ -682,6 +735,71 @@ mod tests { } } + /// A boot's own middle, deleted to retention: `logkeeper`'s lines naming + /// this boot's stem, and nobody else's words and no other boot's files. + #[test] + fn a_boot_that_deleted_parts_of_its_own_log_is_told_from_one_that_is_whole() { + let opened = |stem: &str| { + format!("[2026-10-08 14:06:46 12.841 logkeeper] {LOG_OPENED}/log/{stem}.log (2026-10-08 14:06:46 UTC)\n") + }; + let retired = |tag: &str, file: &str| { + format!( + "[2026-10-08 14:07:21 47.238 {tag}] logkeeper: /log holds more than 16{}/log/{file}{}\n", + LOG_RETIRED[0], LOG_RETIRED[1] + ) + }; + let continued = "[2026-10-08 14:07:21 47.242 logkeeper] logkeeper: /log/2026-10-08-140646_0026.log reached \ + 1067282 bytes and this boot continues in /log/2026-10-08-140646_0027.log\n"; + let own = opened("2026-10-08-140646"); + // What came back of a boot that wrote forty-one parts: the lines naming + // parts 2 to 11 went with those parts. + let holed = format!( + "{own}{}{continued}{}", + retired("logkeeper", "2026-10-08-140646_0012.log"), + retired("logkeeper", "2026-10-08-140646_0026.log") + ); + assert_eq!(lost_parts(&holed), Some((2, 26))); + assert_eq!(lost_parts(&format!("{own}{}", retired("logkeeper", "2026-10-08-140646_0002.log"))), Some((2, 2))); + + // A boot that rotated and deleted nothing. + assert_eq!(lost_parts(&format!("{own}{continued}")), None); + assert_eq!(lost_parts(""), None); + // An earlier boot's files, whole or a continuation, are not this boot's lines. + let earlier = format!( + "{own}{}{}", + retired("logkeeper", "2026-10-07-091500.log"), + retired("logkeeper", "2026-10-07-091500_0003.log") + ); + assert_eq!(lost_parts(&earlier), None); + // The same words from another program, from the kernel, and about a + // file that is not one of logkeeper's. + let quoted = format!( + "{own}{}[2026-10-08 14:07:21 47.238 cpu2 kernel] tmpfs: read through a backing whose file was deleted\n{}", + retired("test-runner pid=31", "2026-10-08-140646_0012.log"), + retired("logkeeper", "loader.log") + ); + assert_eq!(lost_parts("ed), None); + // The boot the log ends in: an earlier boot's hole on the same volume + // is that boot's. + assert_eq!(lost_parts(&format!("{holed}{}", opened("2026-10-08-141929"))), None); + } + + /// Nothing links this crate to `logkeeper` either: both lines are held to + /// its source. + #[test] + fn logkeeper_writes_the_lines_the_host_reads() { + let root = std::path::Path::new(env!("CARGO_MANIFEST_DIR")).join("userland/logkeeper/src"); + for (file, needle) in [ + ("main.rs", format!("say!(\"{LOG_OPENED}{{}} ({{dated}})\", v.path())")), + ("store.rs", format!("{{MAX_LOG_FILES}}{}{{path}}{}\"", LOG_RETIRED[0], LOG_RETIRED[1])), + ("store.rs", "1 => format!(\"{DIR}/{stem}.log\")".to_string()), + ("store.rs", "n => format!(\"{DIR}/{stem}_{n:04}.log\")".to_string()), + ] { + let source = std::fs::read_to_string(root.join(file)).expect("a logkeeper module"); + assert!(source.contains(&needle), "userland/logkeeper/src/{file} does not write {needle:?}"); + } + } + /// A program writing a kernel verdict's words, or another program's head, /// is left out of the kernel's records and read as its own; a kernel /// record's continuation line is the kernel's. diff --git a/tests/checks.rs b/tests/checks.rs index 72348f36250..9bfda5bbde7 100644 --- a/tests/checks.rs +++ b/tests/checks.rs @@ -876,6 +876,11 @@ mod checks { metal_checks::a_boot_with_a_failure_of_its_own_adds_no_row(); } + #[test] + fn metal_boot_that_lost_parts_of_its_log_judges_no_row() { + metal_checks::a_boot_that_lost_parts_of_its_log_judges_no_row(); + } + #[test] fn metal_name_two_boots_measured_is_refused() { metal_checks::a_name_two_boots_measured_is_refused(); diff --git a/tests/checks/metal.rs b/tests/checks/metal.rs index 1a90b554af5..acbc69c5140 100644 --- a/tests/checks/metal.rs +++ b/tests/checks/metal.rs @@ -213,6 +213,46 @@ pub fn a_boot_with_a_failure_of_its_own_adds_no_row() { ); } +static HOLED: Metal = + Metal { arms: &[metal::once("holed", "tests/jobcase", &[], &[])], judge: span }; + +/// **A boot that deleted parts of its own log is refused by name, and no row +/// is judged on what is left**: `span` asserts no line, so it would pass over +/// the hole. The same boot having rotated and deleted nothing is read. +pub fn a_boot_that_lost_parts_of_its_log_judges_no_row() { + const OPENED: &str = "[2026-09-29 18:22:39 1.170 logkeeper] logkeeper: this boot's kernel log is \ + /log/2026-09-29-182239.log (2026-09-29 18:22:39 UTC)\n"; + const CONTINUED: &str = "[2026-09-29 18:23:14 36.901 logkeeper] logkeeper: /log/2026-09-29-182239_0017.log \ + reached 1048816 bytes and this boot continues in /log/2026-09-29-182239_0018.log\n"; + let retired = |file: &str| { + format!( + "[2026-09-29 18:23:14 36.899 logkeeper] logkeeper: /log holds more than 16 logs, so /log/{file} \ + was deleted\n" + ) + }; + let dir = toyos_tmpdir::TempDir::new("metal-readbacks"); + let root = toyos_tmpdir::TempDir::new("metal-records"); + let holed = format!( + "{BOOTED}{OPENED}{}{}{CONTINUED}", + retired("2026-09-29-182239_0002.log"), + retired("2026-09-29-182239_0003.log") + ); + plant(&dir, "holed", PANEL, &holed, None); + plant(&dir, "passing", PANEL, &format!("{BOOTED}{OPENED}{CONTINUED}"), None); + let readbacks = read(&dir, &["holed", "passing"]); + assert_eq!( + readbacks["holed"].as_ref().err().map(String::as_str), + Some("holed's own log lost parts 2 to 3 to retention; no row is judged on it") + ); + + let tests = [("holed", &HOLED), ("passes", &PASSING)]; + let runs: Vec<&(&str, &'static Metal)> = tests.iter().collect(); + assert!(metal::judge_readbacks(&root, &readbacks, &runs, &[]), "a boot with a hole in its log judged green"); + let record = Record::load(&root, &t14()).expect("a readable record").expect("a record"); + assert!(record.measured.contains_key("span.passing.us"), "{:?}", record.measured); + assert!(!record.measured.keys().any(|name| name.contains("holed")), "{:?}", record.measured); +} + /// Two boots under one name are judged on the first reading and recorded off /// neither. pub fn a_name_two_boots_measured_is_refused() { diff --git a/tests/common/metal.rs b/tests/common/metal.rs index 71e1c247f94..41cb6306f90 100644 --- a/tests/common/metal.rs +++ b/tests/common/metal.rs @@ -814,6 +814,13 @@ pub fn read_readback(dir: &Path, label: &str) -> Result { .map_err(|why| format!("toyos-metal refused {label}: {why}"))?; let loader = read(toyos_build::metal::READBACK_LOADER)?; let log = read(toyos_build::metal::READBACK_KERNEL)?; + // Before any row: a judge that reads a line reports a deleted one missing, + // and a judge that asserts an absence passes over it. + if let Some((first, last)) = bootlog::lost_parts(&log) { + return Err(format!( + "{label}'s own log lost parts {first} to {last} to retention; no row is judged on it" + )); + } let boot = read(toyos_build::metal::READBACK_BOOT)?; Readback::new(label, loader, log, &boot) } @@ -999,8 +1006,11 @@ pub fn judge_readbacks( }; let ms = back.boot_ms.map_or_else(|| "-".to_string(), |ms| ms.to_string()); eprintln!( - " {label}: Boot: complete {ms} ms, back in {} s, the stick enumerated {} s after that", - back.back_secs, back.stick_secs + " {label}: Boot: complete {ms} ms, a log of {} bytes, back in {} s, the stick enumerated {} s \ + after that", + back.log.len(), + back.back_secs, + back.stick_secs ); let panel = back.panel(); if let Some(panel) = panel { diff --git a/tests/metal/lenovo-20w0003amz.toml b/tests/metal/lenovo-20w0003amz.toml index 86823aa9c4f..c33ec82e17b 100644 --- a/tests/metal/lenovo-20w0003amz.toml +++ b/tests/metal/lenovo-20w0003amz.toml @@ -55,9 +55,6 @@ bios = "N34ET71W (1.71 )" "boot.testcases-debug.complete_ms" = 1165 "boot.testcases-debug.panel_max_us" = 3824 "boot.testcases-debug.panel_us" = 22032 -"boot.testcases-hold.complete_ms" = 1212 -"boot.testcases-hold.panel_max_us" = 2477 -"boot.testcases-hold.panel_us" = 13240 "boot.testcases-mkdir.complete_ms" = 1166 "boot.testcases-mkdir.panel_max_us" = 3839 "boot.testcases-mkdir.panel_us" = 22100 diff --git a/tests/toyos-rust-tests/src/bin/acpi_hold.rs b/tests/toyos-rust-tests/src/bin/acpi_hold.rs index 0aec0573ec5..97ba7fa5c0c 100644 --- a/tests/toyos-rust-tests/src/bin/acpi_hold.rs +++ b/tests/toyos-rust-tests/src/bin/acpi_hold.rs @@ -1,18 +1,30 @@ -//! Hold the boot open with `/system/bin/acpiserver` serving it, and exit when -//! the runner's own bound is near. It asserts nothing. +//! Hold the boot open until `/system/bin/acpiserver` has logged a count of the +//! embedded controller's queries, and exit non-zero where the runner's own +//! bound comes near first. //! -//! The `acpi_server_events` metal row runs it: its judge reads a count line the -//! server writes only once one of its count intervals has passed, which a boot -//! that ends with the shared block's jobs does not reach. +//! The `acpi_server_events` metal row runs it, last in its boot: its judge +//! reads that line, which the server writes only once one of its count +//! intervals has passed, and a boot whose other jobs end sooner does not reach +//! it. -use std::thread::sleep; use std::time::Duration; +use toyos_logstream::program_line; + +#[path = "../served_log.rs"] +mod served_log; + +/// How long after boot the wait gives up: the runner's bound less a tenth. const UNTIL_MS: u64 = toyos_tco::JOB_BOUND_MS - toyos_tco::JOB_BOUND_MS / 10; +/// The server's count line, after its count of SCIs. +const COUNTS: &str = "embedded controller queries taken: "; + fn main() { let since_boot = toyos_abi::clock::nanos_since_boot() / 1_000_000; - println!("acpi_hold: holding the boot open to {UNTIL_MS} ms, {since_boot} ms in"); - sleep(Duration::from_millis(UNTIL_MS.saturating_sub(since_boot))); - println!("acpi_hold: held to {UNTIL_MS} ms, and nothing stopped the machine"); + let bound = Duration::from_millis(UNTIL_MS.saturating_sub(since_boot)); + served_log::Log::open().until("the ACPI server's count of its controller's queries", bound, |line| { + program_line(line).is_some_and(|said| said.tag == "acpiserver" && said.text.contains(COUNTS)) + }); + println!("acpi_hold: the ACPI server's count is in the log, and nothing stopped the machine"); } diff --git a/tests/toyos-rust-tests/src/bin/counters_metal.rs b/tests/toyos-rust-tests/src/bin/counters_metal.rs index 5fac26e4f39..fc58389d0c0 100644 --- a/tests/toyos-rust-tests/src/bin/counters_metal.rs +++ b/tests/toyos-rust-tests/src/bin/counters_metal.rs @@ -35,13 +35,15 @@ use std::sync::atomic::{AtomicBool, Ordering}; use std::time::{Duration, Instant}; use toyos::endow::{Endowments, SYSCAP_LABEL}; -use toyos::poller::{Poller, READABLE}; use toyos::syscap::SysCap; -use toyos::Pipe; use toyos_abi::clock::stamp_ns; use toyos_abi::counters::{Counter, RawRecord, Record}; -use toyos_abi::syscall::{self, SyscallError}; -use toyos_logstream::{parse, program_line, Lines, Source}; +use toyos_abi::syscall; +use toyos_logstream::{parse, program_line, Source}; + +#[path = "../served_log.rs"] +mod served_log; +use served_log::Log; /// The idle span: long enough that a CPU's busy fraction is its idle one and /// not the reads'. @@ -166,47 +168,6 @@ fn print(phase: &str, read: &Read) { } } -/// This boot's log as logkeeper serves it, from its first line. A reader of -/// the `log` port is handed each round only after it is on the stick. -struct Log { - pipe: Pipe, - poller: Poller, - lines: Lines, - chunk: Vec, -} - -impl Log { - fn open() -> Log { - let pipe = logkeeper_api::read().unwrap_or_else(|why| panic!("test-runner's `log` port: {why}")).pipe; - Log { pipe, poller: Poller::new(1), lines: Lines::new(), chunk: vec![0u8; 64 * 1024] } - } - - /// Hand `seen` each line in turn until it has answered `true`, for at most - /// `bound`; `what` names what it waits for. - fn until(&mut self, what: &str, bound: Duration, mut seen: impl FnMut(&str) -> bool) { - let by = Instant::now() + bound; - let mut done = false; - while !done { - let left = by - .checked_duration_since(Instant::now()) - .unwrap_or_else(|| panic!("the log did not show {what} within {bound:?}")); - match self.pipe.read_nonblock(&mut self.chunk) { - Ok(0) => panic!("logkeeper closed the log before it showed {what}"), - Ok(n) => self.lines.push(&self.chunk[..n], |line, _| { - let line = std::str::from_utf8(line) - .unwrap_or_else(|e| panic!("logkeeper served a line that is not UTF-8 ({e}): {line:?}")); - done |= seen(line); - }), - Err(SyscallError::WouldBlock) => { - self.poller.watch(&self.pipe, READABLE, 0); - self.poller.wait(1, left.as_nanos() as u64, |_| {}); - } - Err(e) => panic!("the log's pipe refused a read: {e:?}"), - } - } - } -} - /// Wait until `acpiserver` has armed and, where it serves an embedded /// controller, the kernel has logged the claim's first interrupt and the server /// its first query. diff --git a/tests/toyos-rust-tests/src/served_log.rs b/tests/toyos-rust-tests/src/served_log.rs new file mode 100644 index 00000000000..1dbf050e1da --- /dev/null +++ b/tests/toyos-rust-tests/src/served_log.rs @@ -0,0 +1,49 @@ +//! This boot's log as logkeeper serves it on test-runner's `log` port, from +//! its first line. A reader is handed each round only after it is on the +//! stick. + +use std::time::{Duration, Instant}; + +use toyos::poller::{Poller, READABLE}; +use toyos::Pipe; +use toyos_abi::syscall::SyscallError; +use toyos_logstream::Lines; + +pub struct Log { + pipe: Pipe, + poller: Poller, + lines: Lines, + chunk: Vec, +} + +impl Log { + pub fn open() -> Log { + let pipe = logkeeper_api::read().unwrap_or_else(|why| panic!("test-runner's `log` port: {why}")).pipe; + Log { pipe, poller: Poller::new(1), lines: Lines::new(), chunk: vec![0u8; 64 * 1024] } + } + + /// Hand `seen` each line in turn until it has answered `true`, for at most + /// `bound`; `what` names what it waits for. + pub fn until(&mut self, what: &str, bound: Duration, mut seen: impl FnMut(&str) -> bool) { + let by = Instant::now() + bound; + let mut done = false; + while !done { + let left = by + .checked_duration_since(Instant::now()) + .unwrap_or_else(|| panic!("the log did not show {what} within {bound:?}")); + match self.pipe.read_nonblock(&mut self.chunk) { + Ok(0) => panic!("logkeeper closed the log before it showed {what}"), + Ok(n) => self.lines.push(&self.chunk[..n], |line, _| { + let line = std::str::from_utf8(line) + .unwrap_or_else(|e| panic!("logkeeper served a line that is not UTF-8 ({e}): {line:?}")); + done |= seen(line); + }), + Err(SyscallError::WouldBlock) => { + self.poller.watch(&self.pipe, READABLE, 0); + self.poller.wait(1, left.as_nanos() as u64, |_| {}); + } + Err(e) => panic!("the log's pipe refused a read: {e:?}"), + } + } + } +} diff --git a/tests/toyos.rs b/tests/toyos.rs index 95cb23ad433..44c1bb9ebbb 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -161,8 +161,9 @@ const RUST_SKIP: &[&str] = &[ // a boot that starts none: the `acpi_server_death` metal row runs it on // tests/acpicase. "acpi_release", - // It holds the boot open to near the runner's bound, and asserts nothing: - // the `acpi_server_events` metal row runs it. + // It waits for the ACPI server's count of its embedded controller's + // queries, and no guest's machine has that controller: the + // `acpi_server_events` metal row runs it. "acpi_hold", // It claims the fixed hardware itself, which needs a boot that starts no // server, and stages the firmware's side of the Global Lock and finds the @@ -461,7 +462,7 @@ const METAL: &[(&str, metal::Metal)] = &[ // is held and what is read beside Linux's. "counters", metal::Metal { - arms: &[metal::once("testcases", "tests/testcases", &[], &["test_rs_counters_metal"])], + arms: TESTCASES, judge: |b| counters_on_metal(b[0]), }, ), @@ -472,7 +473,7 @@ const METAL: &[(&str, metal::Metal)] = &[ // past the server's count interval. "acpi_server_events", metal::Metal { - arms: &[metal::once("testcases-hold", "tests/testcases", &[], &["test_rs_acpi_hold"])], + arms: TESTCASES, judge: |b| acpi_events_on_metal(b[0]), }, ), @@ -482,7 +483,7 @@ const METAL: &[(&str, metal::Metal)] = &[ // The same boot as `acpi_server_events`. "acpi_tables_loaded", metal::Metal { - arms: &[metal::once("testcases-hold", "tests/testcases", &[], &["test_rs_acpi_hold"])], + arms: TESTCASES, judge: |b| acpi_tables_on_metal(b[0]), }, ), @@ -884,7 +885,7 @@ const METAL: &[(&str, metal::Metal)] = &[ ( "crash_report_reads_no_kernel_memory", metal::Metal { - arms: &[metal::once("testcases", "tests/testcases", &[], &["test_rs_fault_gates"])], + arms: TESTCASES, judge: |b| { b[0].job_passed("test_rs_fault_gates")?; faults::crash_report_reads_no_kernel_memory(&b[0].kernel()) @@ -917,6 +918,11 @@ const TESTCASES: &[metal::Arm] = &[metal::once( "test_rs_syscall_cost", "test_rs_null_sink_client_exits", claims::RECLAIM, + "test_rs_counters_metal", + "test_rs_fault_gates", + // Last: the count it waits for comes thirty seconds after the server + // arms, and a job after it would wait that out behind it. + "test_rs_acpi_hold", ], )]; From 473efea22d3fb17a303b75efa190c60c5cce41d2 Mon Sep 17 00:00:00 2001 From: japabu Date: Thu, 8 Oct 2026 23:29:13 +0200 Subject: [PATCH 2/2] The hole is read from the parts a log names, not from a line that can be lost; logkeeper's words and its part names have one declaration each Review round 1 of #785. The detector read logkeeper's `was deleted` lines, and logkeeper does not write that line with the deletion: `sweep` says it into logkeeper's own ring and a later round writes it. A rotation in the terminal round of the stop's flush has the line held back from the file, and a boot can die between the removal and the next sync. Where that deletion was the boot's first, the readback was parts 1 and 3 to 17 with no deletion line, and it passed as whole. lost_parts now reads the sequence of parts the file itself holds. logkeeper rotates once a round, after that round's write, and the next round writes the rotation's line into the part it opened; so each continuation carries the line that opened it, the parts step by one from the part the opening line names, and a longer step is the parts that are gone. The deletion lines add nothing to that and are no longer read: one way to know. The review's case (parts 1 and 3, nothing said of a deletion) was red at 9e70cd2e3 and is a test, beside the boot that died after the removal and the stop that held the newest rotation's line back. One declaration each. The part-naming grammar is toyos_wallclock::Part, beside classify, which is now its parse; logkeeper names its files through it and bootlog reads them through it. logkeeper's opening line and its rotation line are toyos_logstream::LOG_OPENED and LOG_CONTINUES, as STOPPING already is. bootlog's stem_and_part, its two spelled-again lines and the test that grepped logkeeper's source are gone; logkeeper's part test moves to toyos-wallclock, and its retention tests use stems of the real shape. The server's count line is acpiserver_api::QUERIES_COUNTED, a crate the server, acpi_hold and the judge all read. The hold is the boot's last job by construction: an arm names the job its boot ends on (`last`), batches puts it behind every job any arm on that boot names and refuses two arms that end one boot differently. The two ACPI rows name TESTCASES_HELD; TESTCASES and the counters and crash-report arms are as they were on main. Issues: the retention issue has two of three legs met, the T14's reading at 9e70cd2e3 among them; the press issue's exit names what holds its boots open now that acpi_hold ends at the count line; the server's other lines, still spelled again by their readers, are filed. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01RvnWQFcMuGqTHYhvSnTe8A --- Cargo.lock | 6 + Cargo.toml | 4 + ...ddle-and-the-rows-whose-lines-sat-there.md | 28 ++- ...ines-are-spelled-again-by-their-readers.md | 30 +++ ...erts-a-program-line-it-never-waited-for.md | 35 ++++ ...ent-came-up-to-17-s-after-ec-query-0x28.md | 13 +- src/bootlog.rs | 185 ++++++++---------- tests/checks.rs | 5 + tests/checks/metal.rs | 53 +++-- tests/common/metal.rs | 35 +++- tests/toyos-rust-tests/Cargo.lock | 5 + tests/toyos-rust-tests/Cargo.toml | 2 + tests/toyos-rust-tests/src/bin/acpi_hold.rs | 5 +- tests/toyos.rs | 22 ++- toyos-logstream/src/lib.rs | 10 + toyos-wallclock/src/lib.rs | 94 +++++++-- userland/acpiserver-api/Cargo.toml | 12 ++ userland/acpiserver-api/src/lib.rs | 9 + userland/acpiserver/Cargo.toml | 2 + userland/acpiserver/src/main.rs | 2 +- userland/logkeeper/src/main.rs | 4 +- userland/logkeeper/src/store.rs | 79 +++----- 22 files changed, 417 insertions(+), 223 deletions(-) create mode 100644 issues/acpiserver-lines-are-spelled-again-by-their-readers.md create mode 100644 issues/machine-shutdown-short-stop-asserts-a-program-line-it-never-waited-for.md create mode 100644 userland/acpiserver-api/Cargo.toml create mode 100644 userland/acpiserver-api/src/lib.rs diff --git a/Cargo.lock b/Cargo.lock index b4cee0fa902..8fb2327948d 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -6,12 +6,17 @@ version = 4 name = "acpiserver" version = "0.1.0" dependencies = [ + "acpiserver-api", "toyos", "toyos-abi", "toyos-acpi", "toyos-aml", ] +[[package]] +name = "acpiserver-api" +version = "0.1.0" + [[package]] name = "adler2" version = "2.0.1" @@ -5743,6 +5748,7 @@ dependencies = [ name = "toyos-build" version = "0.1.0" dependencies = [ + "acpiserver-api", "bcachefs", "fatfs", "flate2", diff --git a/Cargo.toml b/Cargo.toml index 0b87c7af659..788315a9e7a 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -70,6 +70,7 @@ members = [ "toyos-xhci", "toyos-xhci/sim", "userland/acpiserver", + "userland/acpiserver-api", "userland/acpiserver/aml", "userland/calc", "userland/compositor", @@ -222,6 +223,9 @@ kernel = { path = "kernel" } # The Bulk-Only phases, so the harness judging a wedge reads the word # `toyos_xhci::bot::Phase` declares instead of spelling it a second time. toyos-xhci = { path = "toyos-xhci" } +# The ACPI server's count line, so the judge reads the words the server writes +# and the job that waits for them matches. +acpiserver-api = { path = "userland/acpiserver-api" } [patch.crates-io] loom = { git = "https://github.com/ToyOSOrg/loom", branch = "toyos" } diff --git a/issues/a-t14-boot-that-outlogs-its-retention-loses-its-middle-and-the-rows-whose-lines-sat-there.md b/issues/a-t14-boot-that-outlogs-its-retention-loses-its-middle-and-the-rows-whose-lines-sat-there.md index d7650680901..ccfe2c6fdbf 100644 --- a/issues/a-t14-boot-that-outlogs-its-retention-loses-its-middle-and-the-rows-whose-lines-sat-there.md +++ b/issues/a-t14-boot-that-outlogs-its-retention-loses-its-middle-and-the-rows-whose-lines-sat-there.md @@ -14,10 +14,14 @@ its middle is a line the judge reports missing, and a judge that asserts an absence passes over the hole. **A hole is red by name now, and it is the whole boot's.** `bootlog::lost_parts` -reads `logkeeper`'s own deletion lines for the boot's own stem, and -`read_readback` (`tests/common/metal.rs`) refuses such a readback before any -row or member is judged on it: every rider of that boot is red with -`'s own log lost parts 2 to N to retention; no row is judged on it`. +reads the sequence of parts the file itself holds: each continuation carries +the line of the rotation that opened it, so the parts a boot's log names step +by one from the part its opening line names, and a longer step is the parts +that are gone. No deletion line is read: the stop's flush can hold one back, +and a boot can die before the round that would write it. `read_readback` +(`tests/common/metal.rs`) refuses such a readback before any row or member is +judged on it: every rider of that boot is red with +`'s own log is missing its parts 2 to N; no row is judged on it`. The harness does not guess which rows' lines sat in the hole. `testcases` is such a boot, and the flood was the kernel's, not the job's: @@ -79,8 +83,12 @@ in seconds 36 to 47. `test_rs_acpi_hold` its last job, and `testcases-hold` is deleted. The job waits on the `log` port for the server's count line, bounded by the runner's bound less a tenth, and exits non-zero without it. That readback judged -offline by this harness reds by name: `testcases's own log lost parts 2 to 26 -to retention; no row is judged on it`. +offline by this harness reds by name: `testcases's own log is missing its +parts 2 to 26; no row is judged on it`. + +On the T14 at `9e70cd2e3` both rows passed on `testcases`: a log of 7,547,522 +bytes, seven rotations and no deletion, the server's count at 43.093 s on the +log's clock and the hold, started at 54.920 s, ended on it without waiting. ## Owner @@ -90,11 +98,11 @@ fuller: a boot that carries every shipping-kernel member logs more than ## Exit condition -Three legs. Met: a readback whose own boot deleted a part of its log reds by -name before any row is judged on it. Left: +Three legs, two met. A readback whose own log is missing a part reds by name +before any row is judged on it; and `acpi_server_events` and +`acpi_tables_loaded` pass on `testcases` on the T14, on a log no part of which +was deleted. Left: -- `acpi_server_events` and `acpi_tables_loaded` pass on `testcases` on the - T14, on a log no part of which was deleted. - No boot of the metal profile can write past `logkeeper`'s retention on a machine with more CPUs or faster ones: what `testcases` logs is bounded by a count, where today it is twenty seconds of however many children the diff --git a/issues/acpiserver-lines-are-spelled-again-by-their-readers.md b/issues/acpiserver-lines-are-spelled-again-by-their-readers.md new file mode 100644 index 00000000000..b3d5c81b609 --- /dev/null +++ b/issues/acpiserver-lines-are-spelled-again-by-their-readers.md @@ -0,0 +1,30 @@ +--- +status: open +kind: tooling +opened: 2026-10-08 +--- + +# `acpiserver`'s lines are spelled again by their readers + +`userland/acpiserver-api` holds one of the server's lines, its count of the +embedded controller's queries, and the server, `acpi_hold` and the +`acpi_server_events` judge read it there. Every other line of the server's +that a reader matches is still a second spelling, held to the server's by +nothing: a change of wording in `userland/acpiserver/src` is found as a red +guest test, or on the T14 as a wait that runs to its bound. + +- `tests/common/power.rs`: `ACPI_ARMED`, `ACPI_PRESSED`, `ACPI_TABLE`, + `ACPI_S5_HANDED`. +- `tests/toyos.rs`, `acpi_events_on_metal` and `acpi_tables_on_metal`: the + armed line, `taken for the first time`, `tables loaded in`, the tables' + read counts, `refused`. +- `tests/toyos-rust-tests/src/bin/counters_metal.rs`, `acpi_said`: + `acpiserver: armed: `, `embedded controller none`, the first-query line. + +Owner: `userland/acpiserver`. + +## Exit condition + +Each of those lines is a constant or a format of `acpiserver-api` that the +server writes through and its readers match on, and `rg '"acpiserver: ' +tests/` finds no literal. diff --git a/issues/machine-shutdown-short-stop-asserts-a-program-line-it-never-waited-for.md b/issues/machine-shutdown-short-stop-asserts-a-program-line-it-never-waited-for.md new file mode 100644 index 00000000000..020a0ca5629 --- /dev/null +++ b/issues/machine-shutdown-short-stop-asserts-a-program-line-it-never-waited-for.md @@ -0,0 +1,35 @@ +--- +status: open +kind: tooling +opened: 2026-10-08 +--- + +# `machine_shutdown_short_stop` asserts a program's line it never waited for + +`machine_shutdown_short_stop` (`tests/common/power.rs`) waits for the +kernel's record `Q35_S5_SUPPLIED` and then asserts, on the console captured +to there, `acpiserver`'s `ACPI_ARMED`. The server says the armed line first, +but the two reach the console by different roads: the kernel writes its own +record, and a program's line arrives when `logkeeper` has read the server's +ring and relayed it. A capture that ends at the kernel's record does not +have to hold the server's line. + +Seen once, beside `machine_shutdown` and `acpi_power_button` in one filtered +run, on a host at load 51 (1 min) running other worktrees' builds: + +``` +FAIL machine_shutdown_short_stop: "acpiserver: armed: power button served, embedded controller none" never reached the boot: +``` + +The capture holds the kernel's record, stamped 15.521 s, and no program's +line stamped after 15.175 s. Alone, two +minutes later at load 45 on the same tree, it passed in 12 s. The branch it +was seen on changed no line of `tests/common/power.rs`, and of `acpiserver` +only the spelling of its count line. + +Owner: the harness, `tests/common/power.rs`. + +## Exit condition + +The test waits for `ACPI_ARMED` itself, as `acpi_power_button` does, before +it asserts it, and passes beside other guests on a loaded host. diff --git a/issues/the-t14s-power-button-event-came-up-to-17-s-after-ec-query-0x28.md b/issues/the-t14s-power-button-event-came-up-to-17-s-after-ec-query-0x28.md index a7070e790ea..c10de93da9e 100644 --- a/issues/the-t14s-power-button-event-came-up-to-17-s-after-ec-query-0x28.md +++ b/issues/the-t14s-power-button-event-came-up-to-17-s-after-ec-query-0x28.md @@ -10,8 +10,9 @@ On the T14 in ACPI mode, a press of the power button is sometimes lost: the machine stops only on a later press. On every boot that served a press, `/system/bin/acpiserver` took embedded-controller query 0x28 first, and the fixed power-button event, `PWRBTN_STS`, which is what powers the machine off, -arrived after it. The boots that served one, each held open by `acpi_hold`, -as `logkeeper` wrote them to the stick: +arrived after it. The boots that served one, each held open by `acpi_hold` +as it then was, a sleep to 54 s after boot, as `logkeeper` wrote them to the +stick: | head | query 0x28 first taken | power button pressed | gap | owner's presses | |---|---|---|---|---| @@ -303,8 +304,12 @@ One boot decides neither a fix nor this issue's close. **Exit**: an on-demand check by the owner, which the orchestrator asks him for at the head that claims the fix and which no test or CI job waits on. On -ten boots of that head held open by `acpi_hold` he presses the power button -once, briefly; every boot's log carries the server's press line and the +ten boots of that head he presses the power button once, briefly. Each is +held open by a job of this check's own, which waits, bounded, for the press +the boot is about; that job is owed with the check, built with the ACPI +track's later slice on the owner's go. `acpi_hold` no longer holds a boot +for a press: it ends at the server's first count line. Then every boot's +log carries the server's press line and the supervisor's power-off, and he reports one press for each. Each boot ends in S5 and leaves no readback, so each log is read off the stick's log partition, copied before the next flash, as at `ee6aadecb`. The head, the ten logs' diff --git a/src/bootlog.rs b/src/bootlog.rs index e1219162969..1f3e550e1b1 100644 --- a/src/bootlog.rs +++ b/src/bootlog.rs @@ -293,57 +293,43 @@ pub fn split_listing(listing: &str) -> (Option<&str>, Vec<&str>) { (loader, logkeeper) } -/// What `logkeeper` says as it opens a boot's file, before that file's path, in -/// `userland/logkeeper/src/main.rs`. -pub const LOG_OPENED: &str = "logkeeper: this boot's kernel log is "; - -/// What `logkeeper` says either side of the path of a file retention deleted, -/// in `userland/logkeeper/src/store.rs`'s `sweep`. -pub const LOG_RETIRED: [&str; 2] = [" logs, so ", " was deleted"]; - -/// One of `logkeeper`'s paths as its boot's stem and its part, as -/// `userland/logkeeper/src/store.rs` names a part: the first is the bare stem. -fn stem_and_part(path: &str) -> Option<(&str, u32)> { - let name = path.rsplit('/').next()?; - let bare = name.strip_suffix(".log").filter(|_| is_logkeeper_file(name))?; - match bare.split_once('_') { - Some((stem, part)) => Some((stem, part.parse().ok()?)), - None => Some((bare, 1)), - } -} - -/// The parts of its own log the boot `log` ends in deleted to retention, first -/// and last, or `None` for a log that is whole. +/// The parts of its own log the boot `log` ends in no longer has, first and +/// last, or `None` for a log that is whole. /// -/// **Read off `logkeeper`'s own lines, and off their paths**: a program's line -/// can carry the same words, and a boot deletes earlier boots' files without -/// losing a line of its own. Retention takes a boot's continuations oldest -/// first, and the lines naming the oldest go with the parts that held them, so -/// the hole opens at the boot's first continuation and the newest line, which -/// is written into the newest part, closes it. +/// **Read off the sequence of parts the file itself holds**, which no flush +/// and no death can take without taking the part: `logkeeper` rotates once a +/// round, after that round's write, and the line saying so +/// ([`toyos_logstream::LOG_CONTINUES`]) is written by the next round into the +/// part it opened. So the parts a boot's log names, from the one its opening +/// line names, step by one, and a step that is longer is the parts that are +/// gone. The newest rotation's line may not have reached the file; the part it +/// opened is no hole. A program's line can carry the same words, so only +/// `logkeeper`'s are read, and only for this boot's stem. pub fn lost_parts(log: &str) -> Option<(u32, u32)> { - let mut own: Option<(&str, u32)> = None; - let mut last: Option = None; - for said in log.lines().filter_map(toyos_logstream::program_line) { - if said.tag != toyos_logstream::LOGKEEPER { + use toyos_logstream::{LOGKEEPER, LOG_CONTINUES, LOG_OPENED}; + use toyos_wallclock::Part; + fn named(path: &str) -> Option> { + Part::parse(path.rsplit('/').next()?).map(|(_, part)| part) + } + let mut newest: Option = None; + let mut lost: Option<(u32, u32)> = None; + for said in log.lines().filter_map(toyos_logstream::program_line).filter(|said| said.tag == LOGKEEPER) { + if let Some(opened) = said.text.strip_prefix(LOG_OPENED) { + newest = opened.split_whitespace().next().and_then(named); + lost = None; continue; } - if let Some(opened) = said.text.strip_prefix(LOG_OPENED) { - own = opened.split_whitespace().next().and_then(stem_and_part); - last = None; + let Some((_, path)) = said.text.split_once(LOG_CONTINUES) else { continue }; + let (Some(next), Some(was)) = (named(path), newest) else { continue }; + if next.stem != was.stem { + continue; } - let retired = said - .text - .strip_suffix(LOG_RETIRED[1]) - .and_then(|head| head.split_once(LOG_RETIRED[0])) - .and_then(|(_, path)| stem_and_part(path)); - if let (Some((stem, part)), Some((mine, _))) = (retired, own) { - if stem == mine { - last = last.max(Some(part)); - } + if next.part > was.part + 1 { + lost = Some((lost.map_or(was.part + 1, |(first, _)| first), next.part - 1)); } + newest = Some(next); } - Some((own?.1 + 1, last?)) + lost } /// The kernel's boot-phase record for the end of boot, in @@ -735,69 +721,70 @@ mod tests { } } - /// A boot's own middle, deleted to retention: `logkeeper`'s lines naming - /// this boot's stem, and nobody else's words and no other boot's files. + use toyos_logstream::{LOG_CONTINUES, LOG_OPENED}; + + const STEM: &str = "2026-10-08-140646"; + + fn opened(stem: &str) -> String { + format!("[2026-10-08 14:06:46 12.841 logkeeper] {LOG_OPENED}/log/{stem}.log (2026-10-08 14:06:46 UTC)\n") + } + + /// `logkeeper`'s line for the rotation that opened part `to` of `stem`. + fn continued(tag: &str, stem: &str, to: u32) -> String { + let part = |part| toyos_wallclock::Part { stem, part }; + format!( + "[2026-10-08 14:07:21 47.242 {tag}] logkeeper: /log/{} reached 1067282{LOG_CONTINUES}/log/{}\n", + part(to - 1), + part(to) + ) + } + + fn parts(stem: &str, to: std::ops::RangeInclusive) -> String { + to.map(|to| continued("logkeeper", stem, to)).collect() + } + + /// **The hole no deletion line names**: a boot's file holds the rotation + /// that opened each part it has, so parts 1 and 3 with nothing said of a + /// deletion is part 2 gone — whether the line saying so was held back by + /// the stop's flush or the boot died before the round that would write it. #[test] - fn a_boot_that_deleted_parts_of_its_own_log_is_told_from_one_that_is_whole() { - let opened = |stem: &str| { - format!("[2026-10-08 14:06:46 12.841 logkeeper] {LOG_OPENED}/log/{stem}.log (2026-10-08 14:06:46 UTC)\n") - }; - let retired = |tag: &str, file: &str| { - format!( - "[2026-10-08 14:07:21 47.238 {tag}] logkeeper: /log holds more than 16{}/log/{file}{}\n", - LOG_RETIRED[0], LOG_RETIRED[1] - ) - }; - let continued = "[2026-10-08 14:07:21 47.242 logkeeper] logkeeper: /log/2026-10-08-140646_0026.log reached \ - 1067282 bytes and this boot continues in /log/2026-10-08-140646_0027.log\n"; - let own = opened("2026-10-08-140646"); - // What came back of a boot that wrote forty-one parts: the lines naming - // parts 2 to 11 went with those parts. - let holed = format!( - "{own}{}{continued}{}", - retired("logkeeper", "2026-10-08-140646_0012.log"), - retired("logkeeper", "2026-10-08-140646_0026.log") - ); - assert_eq!(lost_parts(&holed), Some((2, 26))); - assert_eq!(lost_parts(&format!("{own}{}", retired("logkeeper", "2026-10-08-140646_0002.log"))), Some((2, 2))); + fn a_part_whose_rotation_the_log_does_not_hold_is_a_hole() { + assert_eq!(lost_parts(&format!("{}{}", opened(STEM), continued("logkeeper", STEM, 3))), Some((2, 2))); + // Died between the removal of part 2 and the next sync: parts 1 and 3 + // to 16 came back, and part 17 was never opened. + assert_eq!(lost_parts(&format!("{}{}", opened(STEM), parts(STEM, 3..=16))), Some((2, 2))); + // The stop's flush held back the newest rotation's line: part 17 is on + // the volume and nothing in the file says so. + assert_eq!(lost_parts(&format!("{}{}", opened(STEM), parts(STEM, 4..=16))), Some((2, 3))); + } - // A boot that rotated and deleted nothing. - assert_eq!(lost_parts(&format!("{own}{continued}")), None); + /// What came back of the T14 boot that wrote forty-one parts, a boot that + /// rotated and lost nothing, and the lines that are not this boot's. + #[test] + fn a_boot_that_lost_parts_of_its_own_log_is_told_from_one_that_is_whole() { + let own = opened(STEM); + assert_eq!(lost_parts(&format!("{own}{}", parts(STEM, 27..=41))), Some((2, 26))); + // Two holes are reported from the first lost part to the last. + assert_eq!(lost_parts(&format!("{own}{}{}", parts(STEM, 3..=4), parts(STEM, 9..=10))), Some((2, 8))); + + assert_eq!(lost_parts(&format!("{own}{}", parts(STEM, 2..=8))), None); + assert_eq!(lost_parts(&own), None); assert_eq!(lost_parts(""), None); - // An earlier boot's files, whole or a continuation, are not this boot's lines. - let earlier = format!( - "{own}{}{}", - retired("logkeeper", "2026-10-07-091500.log"), - retired("logkeeper", "2026-10-07-091500_0003.log") - ); - assert_eq!(lost_parts(&earlier), None); - // The same words from another program, from the kernel, and about a - // file that is not one of logkeeper's. + // The same words from another program, and about another boot's file. let quoted = format!( - "{own}{}[2026-10-08 14:07:21 47.238 cpu2 kernel] tmpfs: read through a backing whose file was deleted\n{}", - retired("test-runner pid=31", "2026-10-08-140646_0012.log"), - retired("logkeeper", "loader.log") + "{own}{}{}", + continued("test-runner pid=31", STEM, 12), + continued("logkeeper", "2026-10-07-091500", 5) ); assert_eq!(lost_parts("ed), None); // The boot the log ends in: an earlier boot's hole on the same volume // is that boot's. - assert_eq!(lost_parts(&format!("{holed}{}", opened("2026-10-08-141929"))), None); - } - - /// Nothing links this crate to `logkeeper` either: both lines are held to - /// its source. - #[test] - fn logkeeper_writes_the_lines_the_host_reads() { - let root = std::path::Path::new(env!("CARGO_MANIFEST_DIR")).join("userland/logkeeper/src"); - for (file, needle) in [ - ("main.rs", format!("say!(\"{LOG_OPENED}{{}} ({{dated}})\", v.path())")), - ("store.rs", format!("{{MAX_LOG_FILES}}{}{{path}}{}\"", LOG_RETIRED[0], LOG_RETIRED[1])), - ("store.rs", "1 => format!(\"{DIR}/{stem}.log\")".to_string()), - ("store.rs", "n => format!(\"{DIR}/{stem}_{n:04}.log\")".to_string()), - ] { - let source = std::fs::read_to_string(root.join(file)).expect("a logkeeper module"); - assert!(source.contains(&needle), "userland/logkeeper/src/{file} does not write {needle:?}"); - } + let next = "2026-10-08-141929"; + assert_eq!(lost_parts(&format!("{own}{}{}", parts(STEM, 27..=41), opened(next))), None); + assert_eq!( + lost_parts(&format!("{own}{}{}{}", parts(STEM, 2..=3), opened(next), continued("logkeeper", next, 4))), + Some((2, 3)) + ); } /// A program writing a kernel verdict's words, or another program's head, diff --git a/tests/checks.rs b/tests/checks.rs index 9bfda5bbde7..f9535023c6a 100644 --- a/tests/checks.rs +++ b/tests/checks.rs @@ -901,6 +901,11 @@ mod checks { metal_checks::a_failing_shared_member_fails_its_boot(); } + #[test] + fn metal_boots_last_job_is_behind_every_other() { + metal_checks::a_boots_last_job_is_behind_every_other(); + } + #[test] fn metal_words_take_rows_members_and_whole_boots() { metal_checks::words_take_rows_members_and_whole_boots(); diff --git a/tests/checks/metal.rs b/tests/checks/metal.rs index acbc69c5140..e8454463d16 100644 --- a/tests/checks/metal.rs +++ b/tests/checks/metal.rs @@ -216,33 +216,30 @@ pub fn a_boot_with_a_failure_of_its_own_adds_no_row() { static HOLED: Metal = Metal { arms: &[metal::once("holed", "tests/jobcase", &[], &[])], judge: span }; -/// **A boot that deleted parts of its own log is refused by name, and no row -/// is judged on what is left**: `span` asserts no line, so it would pass over -/// the hole. The same boot having rotated and deleted nothing is read. +/// **A boot whose log is missing parts of itself is refused by name, and no +/// row is judged on what is left**: `span` asserts no line, so it would pass +/// over the hole. The same boot having rotated and lost nothing is read. pub fn a_boot_that_lost_parts_of_its_log_judges_no_row() { - const OPENED: &str = "[2026-09-29 18:22:39 1.170 logkeeper] logkeeper: this boot's kernel log is \ - /log/2026-09-29-182239.log (2026-09-29 18:22:39 UTC)\n"; - const CONTINUED: &str = "[2026-09-29 18:23:14 36.901 logkeeper] logkeeper: /log/2026-09-29-182239_0017.log \ - reached 1048816 bytes and this boot continues in /log/2026-09-29-182239_0018.log\n"; - let retired = |file: &str| { + use toyos_logstream::{LOG_CONTINUES, LOG_OPENED}; + const STEM: &str = "2026-09-29-182239"; + let part = |part| toyos_wallclock::Part { stem: STEM, part }; + let opened = format!("[2026-09-29 18:22:39 1.170 logkeeper] {LOG_OPENED}/log/{} (2026-09-29 18:22:39 UTC)\n", part(1)); + let continued = |to: u32| { format!( - "[2026-09-29 18:23:14 36.899 logkeeper] logkeeper: /log holds more than 16 logs, so /log/{file} \ - was deleted\n" + "[2026-09-29 18:23:14 36.901 logkeeper] logkeeper: /log/{} reached 1048816{LOG_CONTINUES}/log/{}\n", + part(to - 1), + part(to) ) }; let dir = toyos_tmpdir::TempDir::new("metal-readbacks"); let root = toyos_tmpdir::TempDir::new("metal-records"); - let holed = format!( - "{BOOTED}{OPENED}{}{}{CONTINUED}", - retired("2026-09-29-182239_0002.log"), - retired("2026-09-29-182239_0003.log") - ); - plant(&dir, "holed", PANEL, &holed, None); - plant(&dir, "passing", PANEL, &format!("{BOOTED}{OPENED}{CONTINUED}"), None); + // Parts 1, 4 and 5 came back, and no line says where 2 and 3 went. + plant(&dir, "holed", PANEL, &format!("{BOOTED}{opened}{}{}", continued(4), continued(5)), None); + plant(&dir, "passing", PANEL, &format!("{BOOTED}{opened}{}{}", continued(2), continued(3)), None); let readbacks = read(&dir, &["holed", "passing"]); assert_eq!( readbacks["holed"].as_ref().err().map(String::as_str), - Some("holed's own log lost parts 2 to 3 to retention; no row is judged on it") + Some("holed's own log is missing its parts 2 to 3; no row is judged on it") ); let tests = [("holed", &HOLED), ("passes", &PASSING)]; @@ -367,6 +364,26 @@ pub fn a_failing_shared_member_fails_its_boot() { ); } +/// **A boot's last job is behind every other, whichever row names it first**: +/// a row after the one that ends the boot adds its job before the last, and +/// two rows ending one boot on different jobs are refused by both names. +pub fn a_boots_last_job_is_behind_every_other() { + const HELD: metal::Arm = metal::Arm { last: Some("hold"), ..metal::once("own", "tests/testcases", &[], &["early"]) }; + static ENDS: Metal = Metal { arms: &[HELD], judge: |_| Ok(()) }; + static LATER: Metal = + Metal { arms: &[metal::once("own", "tests/testcases", &[], &["hold", "later"])], judge: |_| Ok(()) }; + static OTHER: Metal = Metal { + arms: &[metal::Arm { last: Some("later"), ..metal::once("own", "tests/testcases", &[], &[]) }], + judge: |_| Ok(()), + }; + let boots = metal::batches(&[("ends", &ENDS), ("later", &LATER)], &[]).expect("one last job"); + assert_eq!(boots["own"].jobs, ["early", "later", "hold"]); + let Err(refused) = metal::batches(&[("ends", &ENDS), ("other", &OTHER)], &[]) else { + panic!("two last jobs on one boot were batched"); + }; + assert!(refused.contains("other ends the boot \"own\" on later and another row ends it on hold"), "{refused}"); +} + /// **What a run's words take**: no word the whole profile; a name word every /// row and member it is part of, chunked as they come; a boot word that boot /// as the whole profile chunks it, with every row that rides it; and a word diff --git a/tests/common/metal.rs b/tests/common/metal.rs index 41cb6306f90..21190c3bce2 100644 --- a/tests/common/metal.rs +++ b/tests/common/metal.rs @@ -57,6 +57,10 @@ pub struct Arm { /// kernel, and that is what most of the suite wants: it is the artifact the /// owner flashes. pub features: &'static [&'static str], + /// The job this boot ends on, before `reboot`: [`batches`] puts it after + /// every job any arm on the boot names, so none can land behind it, and + /// refuses two arms that name different ones. + pub last: Option<&'static str>, } /// The ordinary arm: one boot, and the fields a caller must still say. @@ -70,7 +74,7 @@ pub const fn once( params: &'static [&'static str], jobs: &'static [&'static str], ) -> Arm { - Arm { boot, config, params, jobs, features: &[] } + Arm { boot, config, params, jobs, features: &[], last: None } } /// One boot carrying members that are **discovered rather than registered**. @@ -524,11 +528,13 @@ fn within_one_period(late_ms: i64, period_ns: u64) -> Result<(), String> { } /// One image, and every test that rides it. -struct Batch { +pub struct Batch { config: &'static str, params: Vec<&'static str>, features: &'static [&'static str], - jobs: Vec, + /// What the runner spawns, in order. + pub jobs: Vec, + last: Option<&'static str>, files: Vec<(String, Vec)>, links: Vec<(String, String)>, } @@ -553,7 +559,7 @@ pub fn at(dir: &Path, label: &str) -> PathBuf { /// **Two arms naming one boot are refused where they disagree about it**: an /// image is one config armed one way, and a silent winner would give one of the /// two tests a machine it did not ask for. -fn batches( +pub fn batches( tests: &[(&str, &'static Metal)], shared: &[SharedBoot], ) -> Result, String> { @@ -568,6 +574,7 @@ fn batches( params: boot.params.to_vec(), features: boot.features, jobs: boot.jobs.clone(), + last: None, files: boot.files.clone(), links: boot.links.clone(), }, @@ -584,6 +591,7 @@ fn batches( params: arm.params.to_vec(), features: arm.features, jobs: Vec::new(), + last: None, files: Vec::new(), links: Vec::new(), }); @@ -604,6 +612,23 @@ fn batches( )); } batch.add(arm.jobs.iter().map(|j| (*j).to_string())); + match (batch.last, arm.last) { + (Some(was), Some(now)) if was != now => { + return Err(format!( + "{name} ends the boot {:?} on {now} and another row ends it on {was}; one boot \ + has one last job", + arm.boot + )); + } + (None, now) => batch.last = now, + (Some(_), _) => {} + } + } + } + for batch in out.values_mut() { + if let Some(last) = batch.last { + batch.jobs.retain(|job| job != last); + batch.jobs.push(last.to_string()); } } Ok(out) @@ -818,7 +843,7 @@ pub fn read_readback(dir: &Path, label: &str) -> Result { // and a judge that asserts an absence passes over it. if let Some((first, last)) = bootlog::lost_parts(&log) { return Err(format!( - "{label}'s own log lost parts {first} to {last} to retention; no row is judged on it" + "{label}'s own log is missing its parts {first} to {last}; no row is judged on it" )); } let boot = read(toyos_build::metal::READBACK_BOOT)?; diff --git a/tests/toyos-rust-tests/Cargo.lock b/tests/toyos-rust-tests/Cargo.lock index e1d6d0cabd3..d7afd1b6254 100644 --- a/tests/toyos-rust-tests/Cargo.lock +++ b/tests/toyos-rust-tests/Cargo.lock @@ -2,6 +2,10 @@ # It is not intended for manual editing. version = 4 +[[package]] +name = "acpiserver-api" +version = "0.1.0" + [[package]] name = "alsa" version = "0.11.0" @@ -715,6 +719,7 @@ dependencies = [ name = "toyos-rust-tests" version = "0.1.0" dependencies = [ + "acpiserver-api", "cpal", "inspect", "libloading", diff --git a/tests/toyos-rust-tests/Cargo.toml b/tests/toyos-rust-tests/Cargo.toml index e8054018036..c4e1f7285d4 100644 --- a/tests/toyos-rust-tests/Cargo.toml +++ b/tests/toyos-rust-tests/Cargo.toml @@ -15,6 +15,8 @@ toyos-inspect = { path = "../../toyos-inspect" } # wait on the log being quiet. toyos-logstream = { path = "../../toyos-logstream" } logkeeper-api = { path = "../../userland/logkeeper-api" } +# The ACPI server's count line, for `acpi_hold`'s wait on it. +acpiserver-api = { path = "../../userland/acpiserver-api" } # The diary's decoder, for `trace_read` and `trace_flood`. toyos-trace = { path = "../../toyos-trace" } # The reader's asker, for `hda_client_stall`. diff --git a/tests/toyos-rust-tests/src/bin/acpi_hold.rs b/tests/toyos-rust-tests/src/bin/acpi_hold.rs index 97ba7fa5c0c..f0f0634e9b1 100644 --- a/tests/toyos-rust-tests/src/bin/acpi_hold.rs +++ b/tests/toyos-rust-tests/src/bin/acpi_hold.rs @@ -17,14 +17,11 @@ mod served_log; /// How long after boot the wait gives up: the runner's bound less a tenth. const UNTIL_MS: u64 = toyos_tco::JOB_BOUND_MS - toyos_tco::JOB_BOUND_MS / 10; -/// The server's count line, after its count of SCIs. -const COUNTS: &str = "embedded controller queries taken: "; - fn main() { let since_boot = toyos_abi::clock::nanos_since_boot() / 1_000_000; let bound = Duration::from_millis(UNTIL_MS.saturating_sub(since_boot)); served_log::Log::open().until("the ACPI server's count of its controller's queries", bound, |line| { - program_line(line).is_some_and(|said| said.tag == "acpiserver" && said.text.contains(COUNTS)) + program_line(line).is_some_and(|said| said.tag == "acpiserver" && said.text.contains(acpiserver_api::QUERIES_COUNTED)) }); println!("acpi_hold: the ACPI server's count is in the log, and nothing stopped the machine"); } diff --git a/tests/toyos.rs b/tests/toyos.rs index 44c1bb9ebbb..f46551115e1 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -462,7 +462,7 @@ const METAL: &[(&str, metal::Metal)] = &[ // is held and what is read beside Linux's. "counters", metal::Metal { - arms: TESTCASES, + arms: &[metal::once("testcases", "tests/testcases", &[], &["test_rs_counters_metal"])], judge: |b| counters_on_metal(b[0]), }, ), @@ -473,7 +473,7 @@ const METAL: &[(&str, metal::Metal)] = &[ // past the server's count interval. "acpi_server_events", metal::Metal { - arms: TESTCASES, + arms: TESTCASES_HELD, judge: |b| acpi_events_on_metal(b[0]), }, ), @@ -483,7 +483,7 @@ const METAL: &[(&str, metal::Metal)] = &[ // The same boot as `acpi_server_events`. "acpi_tables_loaded", metal::Metal { - arms: TESTCASES, + arms: TESTCASES_HELD, judge: |b| acpi_tables_on_metal(b[0]), }, ), @@ -885,7 +885,7 @@ const METAL: &[(&str, metal::Metal)] = &[ ( "crash_report_reads_no_kernel_memory", metal::Metal { - arms: TESTCASES, + arms: &[metal::once("testcases", "tests/testcases", &[], &["test_rs_fault_gates"])], judge: |b| { b[0].job_passed("test_rs_fault_gates")?; faults::crash_report_reads_no_kernel_memory(&b[0].kernel()) @@ -918,14 +918,16 @@ const TESTCASES: &[metal::Arm] = &[metal::once( "test_rs_syscall_cost", "test_rs_null_sink_client_exits", claims::RECLAIM, - "test_rs_counters_metal", - "test_rs_fault_gates", - // Last: the count it waits for comes thirty seconds after the server - // arms, and a job after it would wait that out behind it. - "test_rs_acpi_hold", ], )]; +/// The same boot, ended on the hold: the count it waits for comes thirty +/// seconds after the server arms, and a job behind it would wait that out too. +const TESTCASES_HELD: &[metal::Arm] = &[metal::Arm { + last: Some("test_rs_acpi_hold"), + ..metal::once("testcases", "tests/testcases", &[], &[]) +}]; + /// **Two boots of one config, because these two cannot share one.** Each fills /// a machine-wide cap and leaves it filled: `mkdir_cap` fills the directory cap, /// and `readdir_bound`'s own `create_dir("/tmp/empty")` is then refused with @@ -3992,7 +3994,7 @@ fn acpi_events_on_metal(back: &metal::Readback) -> Result<(), String> { return Err(format!("the server died: {fired}")); } let firsts: Vec<&&str> = lines.iter().filter(|l| l.contains("taken for the first time")).collect(); - let counts = lines.iter().rfind(|l| l.contains("embedded controller queries taken: ")); + let counts = lines.iter().rfind(|l| l.contains(acpiserver_api::QUERIES_COUNTED)); let (true, Some(counts)) = (!firsts.is_empty(), counts) else { return Err(format!("the server logged {} first sighting(s) and {counts:?} for counts", firsts.len())); }; diff --git a/toyos-logstream/src/lib.rs b/toyos-logstream/src/lib.rs index a4d74332aeb..a3add819e13 100644 --- a/toyos-logstream/src/lib.rs +++ b/toyos-logstream/src/lib.rs @@ -93,6 +93,16 @@ pub const RESUME: u32 = 7; /// boot `/log` is owed, since `logkeeper` answers only once it is durable. pub const STOPPING: &str = "supervisor: power: the machine stops, and logkeeper makes the log whole first"; +/// What `logkeeper` says as it opens a boot's file, before that file's path: +/// the first of its own lines in the file it names. +pub const LOG_OPENED: &str = "logkeeper: this boot's kernel log is "; + +/// What `logkeeper` says of a part that reached its bound, between the bytes it +/// reached and the path of the part the boot continues in, which ends the +/// line. Said once the next part is open and written by the next round, so +/// each continuation holds the line of the rotation that opened it. +pub const LOG_CONTINUES: &str = " bytes and this boot continues in "; + /// What a [`REGISTER`] frame says: the pid the supervisor started, and its name. #[derive(Clone, Copy, Debug, PartialEq, Eq)] pub struct Registration<'a> { diff --git a/toyos-wallclock/src/lib.rs b/toyos-wallclock/src/lib.rs index 47bea3b2646..e2b92d93c42 100644 --- a/toyos-wallclock/src/lib.rs +++ b/toyos-wallclock/src/lib.rs @@ -163,29 +163,63 @@ pub enum Class { Dated, } -/// Whether `name` on the log volume is one of `logkeeper`'s files, and which kind. +/// One file of a boot's log as its name says it: the boot's stem, and which +/// part of that boot's sequence the file is, from 1. /// -/// An allow-list, and the strictness is the safety property in both -/// directions: `logkeeper` deletes nothing this does not recognise, and a host -/// reading the volume for a boot's log reads nothing else — the bootloader's -/// own `loader.log` is not one of these. -pub fn classify(name: &str) -> Option { - let stem = name.strip_suffix(".log")?; - let stem = match stem.split_once('_') { - Some((head, part)) => { - if part.len() != 4 || !part.bytes().all(|b| b.is_ascii_digit()) { - return None; - } - head +/// The first part carries the bare stem, because that is what nearly every +/// boot ever writes and a `_0001` on it would be noise on every stick. A +/// continuation takes `_` rather than any other separator for one reason: it +/// is the only legal character that sorts *after* `.`, so `.log` still +/// comes before `_0002.log` and the names sort in the order the parts +/// were written. The part is four digits wide: a fifth would sort before the +/// fourth. +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +pub struct Part<'a> { + pub stem: &'a str, + pub part: u32, +} + +impl fmt::Display for Part<'_> { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + match self.part { + 1 => write!(f, "{}.log", self.stem), + n => write!(f, "{}_{n:04}.log", self.stem), } - None => stem, - }; + } +} - if let Some(index) = stem.strip_prefix(UNDATED_STEM).and_then(|s| s.strip_prefix('-')) { - let ours = index.len() == 2 && index.bytes().all(|b| b.is_ascii_digit()); - return ours.then_some(Class::Undated); +impl<'a> Part<'a> { + /// `name` on the log volume read back, where it is one of `logkeeper`'s + /// files, with which kind its boot is. + /// + /// An allow-list, and the strictness is the safety property in both + /// directions: `logkeeper` deletes nothing this does not recognise, and a host + /// reading the volume for a boot's log reads nothing else — the bootloader's + /// own `loader.log` is not one of these. + pub fn parse(name: &'a str) -> Option<(Class, Self)> { + let bare = name.strip_suffix(".log")?; + let (stem, part) = match bare.split_once('_') { + Some((stem, part)) => { + if part.len() != 4 || !part.bytes().all(|b| b.is_ascii_digit()) { + return None; + } + (stem, part.parse().ok()?) + } + None => (bare, 1), + }; + let class = match stem.strip_prefix(UNDATED_STEM).and_then(|s| s.strip_prefix('-')) { + Some(index) => { + (index.len() == 2 && index.bytes().all(|b| b.is_ascii_digit())).then_some(Class::Undated) + } + None => is_stem(stem).then_some(Class::Dated), + }; + Some((class?, Part { stem, part })) } - is_stem(stem).then_some(Class::Dated) +} + +/// Whether `name` on the log volume is one of `logkeeper`'s files, and which kind. +pub fn classify(name: &str) -> Option { + Part::parse(name).map(|(class, _)| class) } fn is_leap(year: u64) -> bool { @@ -232,6 +266,8 @@ mod tests { extern crate alloc; use super::*; use alloc::format; + use alloc::string::ToString; + use alloc::vec::Vec; /// The round trip, over the dates a calendar gets wrong: a leap day, a /// century that is not a leap year, and the epoch itself. @@ -310,6 +346,26 @@ mod tests { } } + /// A part's name is read back as the stem and part it was written from, + /// and the names of one boot sort in the order its parts were written. + #[test] + fn a_part_is_its_stem_and_number() { + let named = |stem, part| Part { stem, part }.to_string(); + assert_eq!(named("2026-09-26-100000", 1), "2026-09-26-100000.log"); + assert_eq!(named("unknown-03", 7), "unknown-03_0007.log"); + for stem in ["2026-09-26-100000", "unknown-03"] { + let mut names = Vec::new(); + for part in [1, 2, 10, 9999] { + let name = named(stem, part); + assert_eq!(Part::parse(&name).map(|(_, part)| part), Some(Part { stem, part }), "{name}"); + names.push(name); + } + assert!(names.is_sorted(), "{names:?}"); + } + assert_eq!(Part::parse("loader.log"), None); + assert_eq!(Part::parse("2026-09-26-100000_0002.txt"), None); + } + #[test] fn an_impossible_instant_is_refused_and_a_leap_day_is_not() { assert!(Civil { year: 2000, month: 2, day: 29, hour: 0, min: 0, sec: 0 }.is_valid()); diff --git a/userland/acpiserver-api/Cargo.toml b/userland/acpiserver-api/Cargo.toml new file mode 100644 index 00000000000..0ba7a89c9ee --- /dev/null +++ b/userland/acpiserver-api/Cargo.toml @@ -0,0 +1,12 @@ +[package] +name = "acpiserver-api" +description = "What acpiserver says in the boot's log, as the programs that wait on its lines and the judges that read them spell it." +version = "0.1.0" +edition = "2024" +license = "MIT OR Apache-2.0" + +[lib] +doctest = false + +[lints.rust] +unsafe_code = "forbid" diff --git a/userland/acpiserver-api/src/lib.rs b/userland/acpiserver-api/src/lib.rs new file mode 100644 index 00000000000..ebad342baed --- /dev/null +++ b/userland/acpiserver-api/src/lib.rs @@ -0,0 +1,9 @@ +//! `/system/bin/acpiserver`'s lines in the boot's log, for whoever reads one: +//! the server writes each through the constant its readers match on. + +#![no_std] + +/// The server's count of the embedded controller's queries, written once a +/// count interval where a count moved: after its count of SCIs, and before +/// each query number with how often it was taken. +pub const QUERIES_COUNTED: &str = "embedded controller queries taken: "; diff --git a/userland/acpiserver/Cargo.toml b/userland/acpiserver/Cargo.toml index faa28e18881..5f0f93208c8 100644 --- a/userland/acpiserver/Cargo.toml +++ b/userland/acpiserver/Cargo.toml @@ -11,6 +11,8 @@ toyos-abi = { path = "../../toyos-abi" } # The tables' decode, which the kernel reads its own of by. toyos-acpi = { path = "../../toyos-acpi" } toyos-aml = { path = "aml" } +# Its own lines, as their readers spell them. +acpiserver-api = { path = "../acpiserver-api" } [package.metadata.toyos.host] exempt.owns = "ToyOS's ACPI fixed hardware, claimed from the kernel with the SCI it raises" diff --git a/userland/acpiserver/src/main.rs b/userland/acpiserver/src/main.rs index 720b9dba827..958f777578c 100644 --- a/userland/acpiserver/src/main.rs +++ b/userland/acpiserver/src/main.rs @@ -330,6 +330,6 @@ impl Server { } self.logged = self.counted; let counts: Vec = self.counts.iter().map(|(q, n)| format!("{q:#04x} x{n}")).collect(); - println!("acpiserver: {} SCIs; embedded controller queries taken: {}", self.scis, counts.join(", ")); + println!("acpiserver: {} SCIs; {}{}", self.scis, acpiserver_api::QUERIES_COUNTED, counts.join(", ")); } } diff --git a/userland/logkeeper/src/main.rs b/userland/logkeeper/src/main.rs index 89fea058157..d1bfcbdbb2f 100644 --- a/userland/logkeeper/src/main.rs +++ b/userland/logkeeper/src/main.rs @@ -90,7 +90,7 @@ use toyos::syscap::SysCap; use toyos::{Console, Pipe}; use toyos_abi::syscall::SyscallError; use toyos_logstream::{ - ProgramLine, Registration, Tag, CONSOLE, FLUSH, FLUSHED, MAX_TAG, ORIGINS, REGISTER, RESUME, + ProgramLine, Registration, Tag, CONSOLE, FLUSH, FLUSHED, LOG_OPENED, MAX_TAG, ORIGINS, REGISTER, RESUME, SERVICE, }; use toyos_wallclock::Civil; @@ -153,7 +153,7 @@ fn main() { // This program's half of the startup report, in one line: the kernel // says whether it has a console, this program whether it has a volume // and what the name it chose was decided by. - Some(v) => say!("logkeeper: this boot's kernel log is {} ({dated})", v.path()), + Some(v) => say!("{LOG_OPENED}{} ({dated})", v.path()), None => say!( "logkeeper: no {DIR} on this machine - this boot's kernel log is on the console only \ ({dated})" diff --git a/userland/logkeeper/src/store.rs b/userland/logkeeper/src/store.rs index 9dcfb083157..835b36642e0 100644 --- a/userland/logkeeper/src/store.rs +++ b/userland/logkeeper/src/store.rs @@ -21,7 +21,8 @@ use std::fs::{self, File, OpenOptions}; use std::io::Write; use std::path::PathBuf; -use toyos_wallclock::{classify, Class, UNDATED_STEM}; +use toyos_logstream::LOG_CONTINUES; +use toyos_wallclock::{classify, Class, Part, UNDATED_STEM}; /// Where the logs go. /// @@ -44,8 +45,7 @@ pub const EARLIER_BOOTS: usize = MAX_LOG_FILES / 2; /// How many continuation files one boot may produce before this gives up. /// -/// The part number is four digits wide and a fifth would sort *before* the -/// fourth, putting retention in the wrong order. +/// The part number is four digits wide (`toyos_wallclock::Part`). pub const MAX_LOG_PARTS: u32 = 9999; /// How large one file may get before the next part starts. @@ -55,28 +55,16 @@ pub const MAX_LOG_PARTS: u32 = 9999; /// what `/system/bin/console` reads off USB before it paints anything. pub const MAX_LOG_BYTES: u64 = 1024 * 1024; -/// The name of one file in this boot's sequence. -/// -/// The first part carries the bare stem, because that is what nearly every boot -/// ever writes and a `_0001` on it would be noise on every stick. A -/// continuation takes `_` rather than any other separator for one reason: it is -/// the only legal character that sorts *after* `.`, so `.log` still comes -/// before `_0002.log` and retention deletes a boot's parts in the order -/// they were written. +/// Where one file of this boot's sequence is: `toyos_wallclock::Part` is its +/// name. pub fn path(stem: &str, part: u32) -> String { - match part { - 1 => format!("{DIR}/{stem}.log"), - n => format!("{DIR}/{stem}_{n:04}.log"), - } + format!("{DIR}/{}", Part { stem, part }) } /// A path of this program's as its boot's stem and its part number. fn stem_and_part(path: &str) -> Option<(&str, u32)> { - let name = path.rsplit('/').next()?.strip_suffix(".log")?; - match name.split_once('_') { - Some((stem, part)) => Some((stem, part.parse().ok()?)), - None => Some((name, 1)), - } + let (_, Part { stem, part }) = Part::parse(path.rsplit('/').next()?)?; + Some((stem, part)) } /// Every file on `/log` that this program wrote, oldest first. @@ -270,7 +258,7 @@ impl Volume { self.size = 0; let next = self.path(); self.file = create(&next)?; - say(format!("logkeeper: {full} reached {bytes} bytes and this boot continues in {next}")); + say(format!("logkeeper: {full} reached {bytes}{LOG_CONTINUES}{next}")); Ok(()) } } @@ -294,8 +282,8 @@ mod tests { /// A volume under the bound loses nothing. #[test] fn nothing_goes_while_there_is_room() { - let existing: Vec = (0..10).flat_map(|b| boot(&format!("2026-09-0{b}"), 1)).collect(); - assert!(retire(&existing, "2026-09-26").is_empty()); + let existing: Vec = (0..10).flat_map(|b| boot(&format!("2026-09-0{b}-000000"), 1)).collect(); + assert!(retire(&existing, "2026-09-26-000000").is_empty()); } /// **The flood this floor exists for.** A boot that has written eight @@ -304,13 +292,13 @@ mod tests { #[test] fn a_flooding_boot_costs_its_own_middle_and_nobody_elses_start() { let mut existing: Vec = - (0..8).flat_map(|b| boot(&format!("2026-09-1{b}"), 1)).collect(); - existing.extend(boot("2026-09-26", 8)); + (0..8).flat_map(|b| boot(&format!("2026-09-1{b}-000000"), 1)).collect(); + existing.extend(boot("2026-09-26-000000", 8)); assert_eq!(existing.len(), 16); - let going = retire(&existing, "2026-09-26"); - assert_eq!(going, [path("2026-09-26", 2)]); + let going = retire(&existing, "2026-09-26-000000"); + assert_eq!(going, [path("2026-09-26-000000", 2)]); for earlier in 0..8 { - assert!(!going.contains(&path(&format!("2026-09-1{earlier}"), 1))); + assert!(!going.contains(&path(&format!("2026-09-1{earlier}-000000"), 1))); } } @@ -320,39 +308,28 @@ mod tests { fn whole_old_boots_go_first_then_earlier_continuations() { let mut existing: Vec = Vec::new(); for b in 0..10 { - existing.extend(boot(&format!("2026-08-{:02}", 10 + b), 1)); + existing.extend(boot(&format!("2026-08-{:02}-000000", 10 + b), 1)); } - existing.extend(boot("2026-09-01", 3)); - existing.extend(boot("2026-09-26", 3)); + existing.extend(boot("2026-09-01-000000", 3)); + existing.extend(boot("2026-09-26-000000", 3)); assert_eq!(existing.len(), 16); // Eleven earlier boots, eight kept: the three oldest may go whole, and // the oldest alone makes the room one new part needs. - assert_eq!(retire(&existing, "2026-09-26"), [path("2026-08-10", 1)]); + assert_eq!(retire(&existing, "2026-09-26-000000"), [path("2026-08-10-000000", 1)]); let mut existing: Vec = - (0..8).flat_map(|b| boot(&format!("2026-08-{:02}", 10 + b), 1)).collect(); - existing.extend(boot("2026-09-01", 5)); - existing.extend(boot("2026-09-26", 3)); + (0..8).flat_map(|b| boot(&format!("2026-08-{:02}-000000", 10 + b), 1)).collect(); + existing.extend(boot("2026-09-01-000000", 5)); + existing.extend(boot("2026-09-26-000000", 3)); assert_eq!(existing.len(), 16); - assert_eq!(retire(&existing, "2026-09-26"), [path("2026-08-10", 1)]); + assert_eq!(retire(&existing, "2026-09-26-000000"), [path("2026-08-10-000000", 1)]); let mut existing: Vec = - (0..7).flat_map(|b| boot(&format!("2026-08-{:02}", 10 + b), 1)).collect(); - existing.extend(boot("2026-09-01", 6)); - existing.extend(boot("2026-09-26", 3)); + (0..7).flat_map(|b| boot(&format!("2026-08-{:02}-000000", 10 + b), 1)).collect(); + existing.extend(boot("2026-09-01-000000", 6)); + existing.extend(boot("2026-09-26-000000", 3)); assert_eq!(existing.len(), 16); - assert_eq!(retire(&existing, "2026-09-26"), [path("2026-09-01", 2)]); + assert_eq!(retire(&existing, "2026-09-26-000000"), [path("2026-09-01-000000", 2)]); } - /// Names that are not this program's are none of its business; a name - /// that parses carries its stem and part. - #[test] - fn a_part_is_its_stem_and_number() { - assert_eq!(stem_and_part("/log/2026-09-26-10-00-00.log"), Some(("2026-09-26-10-00-00", 1))); - assert_eq!( - stem_and_part("/log/2026-09-26-10-00-00_0007.log"), - Some(("2026-09-26-10-00-00", 7)) - ); - assert_eq!(stem_and_part("/log/loader.txt"), None); - } }