diff --git a/Cargo.lock b/Cargo.lock index 3f6e0d899c1..9a7e782a8b5 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 1c9bb775b02..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 @@ -10,8 +10,19 @@ 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 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: `test_rs_counters_metal`'s `loaded` phase spawns a child per CPU in a loop for @@ -42,9 +53,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 +79,16 @@ 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 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 @@ -80,6 +98,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, 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: + +- 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/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/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/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..1f3e550e1b1 100644 --- a/src/bootlog.rs +++ b/src/bootlog.rs @@ -293,6 +293,45 @@ pub fn split_listing(listing: &str) -> (Option<&str>, Vec<&str>) { (loader, logkeeper) } +/// 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 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)> { + 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; + } + 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; + } + if next.part > was.part + 1 { + lost = Some((lost.map_or(was.part + 1, |(first, _)| first), next.part - 1)); + } + newest = Some(next); + } + lost +} + /// 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 +721,72 @@ mod tests { } } + 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_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))); + } + + /// 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); + // The same words from another program, and about another boot's file. + let quoted = format!( + "{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. + 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, /// 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..f9535023c6a 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(); @@ -896,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 1a90b554af5..e8454463d16 100644 --- a/tests/checks/metal.rs +++ b/tests/checks/metal.rs @@ -213,6 +213,43 @@ 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 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() { + 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.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"); + // 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 is missing its parts 2 to 3; 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() { @@ -327,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 71e1c247f94..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) @@ -814,6 +839,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 is missing its parts {first} to {last}; no row is judged on it" + )); + } let boot = read(toyos_build::metal::READBACK_BOOT)?; Readback::new(label, loader, log, &boot) } @@ -999,8 +1031,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/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 0aec0573ec5..f0f0634e9b1 100644 --- a/tests/toyos-rust-tests/src/bin/acpi_hold.rs +++ b/tests/toyos-rust-tests/src/bin/acpi_hold.rs @@ -1,18 +1,27 @@ -//! 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; 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(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-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 138b88cdae2..f0fccd0e971 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 @@ -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_HELD, 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_HELD, judge: |b| acpi_tables_on_metal(b[0]), }, ), @@ -920,6 +921,13 @@ const TESTCASES: &[metal::Arm] = &[metal::once( ], )]; +/// 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 @@ -4038,7 +4046,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); - } }