Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
6 changes: 6 additions & 0 deletions Cargo.lock

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

4 changes: 4 additions & 0 deletions Cargo.toml
Original file line number Diff line number Diff line change
Expand Up @@ -70,6 +70,7 @@ members = [
"toyos-xhci",
"toyos-xhci/sim",
"userland/acpiserver",
"userland/acpiserver-api",
"userland/acpiserver/aml",
"userland/calc",
"userland/compositor",
Expand Down Expand Up @@ -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" }
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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
`<boot>'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
Expand Down Expand Up @@ -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

Expand All @@ -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

Expand All @@ -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.
Original file line number Diff line number Diff line change
Expand Up @@ -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.
30 changes: 30 additions & 0 deletions issues/acpiserver-lines-are-spelled-again-by-their-readers.md
Original file line number Diff line number Diff line change
@@ -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.
Original file line number Diff line number Diff line change
Expand Up @@ -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 |
|---|---|---|---|---|
Expand Down Expand Up @@ -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'
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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.
105 changes: 105 additions & 0 deletions src/bootlog.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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<'_>> {
Part::parse(path.rsplit('/').next()?).map(|(_, part)| part)
}
let mut newest: Option<Part> = 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 (";
Expand Down Expand Up @@ -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<u32>) -> 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(&quoted), 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.
Expand Down
10 changes: 10 additions & 0 deletions tests/checks.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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();
Expand All @@ -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();
Expand Down
Loading
Loading