diff --git a/bootloader/src/loaderlog.rs b/bootloader/src/loaderlog.rs index 175fb03ead4..34554a50e8d 100644 --- a/bootloader/src/loaderlog.rs +++ b/bootloader/src/loaderlog.rs @@ -224,5 +224,5 @@ fn unique_guid(bs: &BootServices, handle: Handle) -> Option<[u8; 16]> { /// Why there is no log, and that the boot goes on without one. fn refused(why: fmt::Arguments) { // The console directly: there is no file, and this says why. - uefi_services::println!("{}Loader log: {why}. This boot's loader lines are on the screen only", crate::stamp::now()); + uefi_services::println!("{} Loader log: {why}. This boot's loader lines are on the screen only", crate::stamp::now()); } diff --git a/bootloader/src/main.rs b/bootloader/src/main.rs index e800acfdf55..9849a95a9eb 100644 --- a/bootloader/src/main.rs +++ b/bootloader/src/main.rs @@ -743,7 +743,7 @@ fn end_this_pass(system_table: &SystemTable, exit_event: Option) -> fn main(handle: Handle, mut system_table: SystemTable) -> Status { // First, so this reading is firmware's time and none of the loader's. let entry_counter = arch::counter(); - let counter_hz = stamp::start(entry_counter); + let counter_hz = stamp::start(); let exit_event = uefi_services::init(&mut system_table).unwrap(); // First, because it covers everything below it: firmware starts a // five-minute countdown when it loads an image and resets the machine if @@ -813,7 +813,7 @@ fn main(handle: Handle, mut system_table: SystemTable) -> Status { loaderlog::open(&system_table, &log_guid, finding.is_none() && !retry); println!("{}", loaderlog::BEGINS_AT); match counter_hz { - Some(hz) => println!("Loader clock: each line opens with the ms since this loader's entry, at the counter's stated {hz} Hz"), + Some(hz) => println!("Loader clock: each line opens with the seconds since the counter's zero, at the counter's stated {hz} Hz"), None => println!("Loader clock: this CPU states no counter rate, so no line carries the time it was said"), } if let Err(e) = cleared { diff --git a/bootloader/src/stamp.rs b/bootloader/src/stamp.rs index de5695259d9..803d53b291d 100644 --- a/bootloader/src/stamp.rs +++ b/bootloader/src/stamp.rs @@ -1,50 +1,40 @@ -//! The head of every line the loader says: how far into the loader it was -//! said, in milliseconds since `main`'s first statement, by the CPU's counter -//! at the rate the CPU states ([`crate::arch::counter_hz`]). No wall clock: a -//! line is placed against the loader's own start and nothing else. +//! The head of every line the loader says: the log's one head +//! (`toyos_abi::log::Head`), whose time is the seconds since the CPU's counter +//! last started — power-on, or the reset since — at the rate the CPU states +//! ([`crate::arch::counter_hz`]). The kernel's records and every program's +//! line count from the same zero, so a loader line and the kernel's first +//! record are placed against each other. No wall clock. //! -//! A CPU that states no rate gets lines with no head, and [`start`]'s caller -//! says so once. +//! A CPU that states no rate gets lines whose time is `toyos_abi::log::UNTIMED`, +//! and [`start`]'s caller says so once. use core::fmt; use core::sync::atomic::{AtomicU64, Ordering}; -/// The counter at the loader's entry, and its rate; zero until [`start`]. -static ENTRY: AtomicU64 = AtomicU64::new(0); +use toyos_abi::log::{Head, Severity, LOADER}; + +/// The counter's rate; zero until [`start`], and for a CPU that states none. static HZ: AtomicU64 = AtomicU64::new(0); -/// Take `entry` as every stamp's zero, and return the rate stamps are -/// converted at, or `None` where the CPU states none. -pub fn start(entry: u64) -> Option { +/// Read the rate stamps are converted at, and return it, or `None` where the +/// CPU states none. +pub fn start() -> Option { let hz = crate::arch::counter_hz(); - ENTRY.store(entry, Ordering::Relaxed); HZ.store(hz.unwrap_or(0), Ordering::Relaxed); hz } -/// Now, as a line's head. -pub fn now() -> Stamp { +/// Now, as a line's head. The loader runs on the boot CPU alone, the kernel's +/// `cpu0`. +pub fn now() -> Head<'static> { let hz = HZ.load(Ordering::Relaxed); - let ticks = crate::arch::counter() - .checked_sub(ENTRY.load(Ordering::Relaxed)) - .expect("the counter ran backwards since the loader's entry"); - Stamp((hz != 0).then(|| (u128::from(ticks) * 1_000 / u128::from(hz)) as u64)) + let at_ns = (hz != 0).then(|| (u128::from(crate::arch::counter()) * 1_000_000_000 / u128::from(hz)) as u64); + Head { wall: "", at_ns, cpu: Some(0), who: LOADER, severity: Severity::Info, tid: 0, pid: None } } /// One line, stamped, to the console and then to `loader.log`. pub fn say(args: fmt::Arguments) { - let stamp = now(); - uefi_services::println!("{stamp}{args}"); - crate::loaderlog::line(format_args!("{stamp}{args}")); -} - -pub struct Stamp(Option); - -impl fmt::Display for Stamp { - fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { - match self.0 { - Some(ms) => write!(f, "{ms:>5} ms "), - None => Ok(()), - } - } + let head = now(); + uefi_services::println!("{head} {args}"); + crate::loaderlog::line(format_args!("{head} {args}")); } diff --git a/issues/a-programs-line-on-a-screen-names-no-cpu.md b/issues/a-programs-line-on-a-screen-names-no-cpu.md index 4f84397c2d6..8e9a1e2e9ac 100644 --- a/issues/a-programs-line-on-a-screen-names-no-cpu.md +++ b/issues/a-programs-line-on-a-screen-names-no-cpu.md @@ -7,10 +7,10 @@ opened: 2026-10-04 # A program's line on a screen names no CPU The owner asked for the seconds since boot and the CPU in front of every -line a screen shows. A kernel record's line carries both: `[kernel 1.193 cpu0 +line a screen shows. A kernel record's line carries both: `[ 1.193 cpu0 kernel alert tid=3]`. A program's line carries only the time: -`{1.234 warn soundserver}` on `/system/bin/console` and on `cargo run`'s -terminal. The reason is the record. `toyos::log::region::Body`, the record a +`[ 1.234 soundserver warn]` on `/system/bin/console`, on `cargo run`'s +terminal and in `/log`. The reason is the record. `toyos::log::region::Body`, the record a program writes into its ring, has `at_ns`, `pid`, `tid` and a severity and no CPU, so `logkeeper` has no CPU to give `toyos_logstream::ProgramLine`. diff --git a/issues/the-kernel-console-split-does-not-re-arm-across-a-guest-reset.md b/issues/the-kernel-console-split-does-not-re-arm-across-a-guest-reset.md index bbbc3d7dbb9..5462d979883 100644 --- a/issues/the-kernel-console-split-does-not-re-arm-across-a-guest-reset.md +++ b/issues/the-kernel-console-split-does-not-re-arm-across-a-guest-reset.md @@ -7,7 +7,8 @@ opened: 2026-09-28 # The kernel console split does not re-arm across a guest reset `src/kernelconsole.rs`'s `KernelConsole` withholds the virtio port's bytes -until the first `[kernel ` head and passes every byte after it: `held` is +until the kernel's first record (`toyos_logstream::kernel_opening`) and +passes every byte after it: `held` is `None` from then on. A guest reset inside one QEMU process does not re-arm it. `tests/common/update.rs`'s `Rig::boot` boots the Headless profile, whose stdio is that port, with `takes_the_reset`, and each `reboot` resets that @@ -27,7 +28,8 @@ Nothing reds on it. The update tests look for a needle past an offset in the console (`owed`, `reboot_until`), and firmware lines beside the needle do not stop it matching. Every update test passed in #572's round-2 and round-3 nightlies. If the firmware does write its handoff line there, -`Loader log: … so [kernel …` is a line `Serial::interleaved` reports as a torn +`Loader log: … so [ 1.234 cpu0 kernel] …` is a line `Serial::interleaved` +reports as a torn kernel line. ## Exit condition diff --git a/issues/the-loaders-lines-carry-no-time-on-an-x86-cpu-that-states-no-tsc-rate.md b/issues/the-loaders-lines-carry-no-time-on-an-x86-cpu-that-states-no-tsc-rate.md index f360d617de4..753d01f0e87 100644 --- a/issues/the-loaders-lines-carry-no-time-on-an-x86-cpu-that-states-no-tsc-rate.md +++ b/issues/the-loaders-lines-carry-no-time-on-an-x86-cpu-that-states-no-tsc-rate.md @@ -6,9 +6,16 @@ opened: 2026-10-04 # The loader's lines carry no time on an x86 CPU that states no TSC rate -`bootloader/src/stamp.rs` converts the cycle counter at the rate CPUID leaves -15H/16H state (`toyos_tsc::stated_hz`), and a CPU that states neither gets -unstamped lines and one `Loader clock: this CPU states no counter rate` line. +Every line of the log opens with its time since the CPU's counter last started +(`toyos_abi::log::Head`). The loader converts the counter at the rate CPUID +leaves 15H/16H state (`bootloader/src/stamp.rs`, `toyos_tsc::stated_hz`), and +the kernel does the same for its records until it has measured the TSC against +the HPET (`kernel/src/clock.rs`'s `stamp`). A CPU that states neither leaf gets +`--.---` (`toyos_abi::log::UNTIMED`) in place of the time on every loader line, +one `Loader clock: this CPU states no counter rate` line, and `--.---` on every +kernel record before `clock: HPET at …` — `boot:`, `ACPI:`, the interrupt +controller's and the per-CPU area's among them. The records after it carry +their time from the same zero. Every AMD part is one. InstLatx64's recorded CPUID dumps (`github.com/InstLatx64/InstLatx64`, `AuthenticAMD/`) read leaf 0's EAX, the @@ -17,17 +24,18 @@ Zen 3+ (`0A40F41_K19_Rembrandt_01_CPUID`), Zen 4 (`0A60F12_K19_Raphael_01_CPUID` and Zen 5 (`0B00F21_K20_Turin_01_CPUID`, `0B20F40_K20_StrixPoint_06_CPUID`, `0B40F40_K20_GraniteRidge_02_CPUID`): neither leaf exists there. QEMU's `qemu64` states neither either, and under the `guest / suite` check's -`-cpu host` whether a line is stamped is the runner's CPU's to decide. +`-cpu host` whether a line is timed is the runner's CPU's to decide. A second rate source is the fix, and the choice of one is open: the `EFI_TIMESTAMP_PROTOCOL`'s stated frequency, the ACPI PM timer or the HPET, each -a calibration the loader then pays for before its first stamped line. +a calibration the loader then pays for before its first timed line. -Until then no guest test sees the stamp on the screen: `screen_loader_clears` -(`tests/toyos.rs`) matches the screen's first line with or without its head, -because no x86 guest stamps one. The fix is where that test starts asserting -the head on the screen. +Until then no guest test asserts a time on the screen: `screen_loader_clears` +(`tests/toyos.rs`) measures the screen's first line, head and all, whose head +reads `--.---` under `qemu64` and whatever the runner's CPU states under +`-cpu host`. The fix is where that test starts asserting a time in it. -Exit: a loader line carries its milliseconds on an x86-64 CPU that states -neither leaf 15H's ratio nor leaf 16H's base frequency, and `screen_loader_clears` -asserts that line's head on the screen. +Exit: a loader line and a kernel record written before `clock: HPET at …` carry +their time on an x86-64 CPU that states neither leaf 15H's ratio nor leaf 16H's +base frequency, and `screen_loader_clears` asserts that line's time on the +screen. diff --git a/kernel/loom/src/lib.rs b/kernel/loom/src/lib.rs index f3e3b305aa6..9dd8a9b0cf3 100644 --- a/kernel/loom/src/lib.rs +++ b/kernel/loom/src/lib.rs @@ -193,6 +193,12 @@ pub mod log_registry; #[path = "../../src/log/read.rs"] pub mod log_read; +/// What `read.rs` names as `super::stamp`, which in the kernel is +/// `crate::log::stamp`. +#[cfg(not(feature = "loom"))] +#[path = "../../src/log/stamp.rs"] +pub mod stamp; + /// What `read.rs`'s log-only walks name as `super::shards()`: none, since no /// test here drives them; the walks a test drives take their shards. #[cfg(not(feature = "loom"))] diff --git a/kernel/loom/tests/log_body_words.rs b/kernel/loom/tests/log_body_words.rs index 3d5a0dac500..e2e1ff8a414 100644 --- a/kernel/loom/tests/log_body_words.rs +++ b/kernel/loom/tests/log_body_words.rs @@ -18,7 +18,7 @@ #![cfg(not(feature = "loom"))] use kernel_loom::log_shard::Shard; -use toyos_abi::log::{LogRecord, Severity, FLAG_EARLY, MAX_RECORD_MESSAGE}; +use toyos_abi::log::{LogRecord, Severity, FLAG_UNTIMED, MAX_RECORD_MESSAGE}; /// A record whose every field is distinct, so a swap between two of them fails /// rather than being absorbed. @@ -32,7 +32,7 @@ fn record(seq: u64, len: usize) -> LogRecord { r.len = len as u16; r.elided = 0x5678; r.severity = Severity::Alert as u8; - r.flags = FLAG_EARLY; + r.flags = FLAG_UNTIMED; for (i, b) in r.msg[..len].iter_mut().enumerate() { *b = b'a' + (i % 26) as u8; } diff --git a/kernel/src/clock.rs b/kernel/src/clock.rs index 2adf21ddd57..df0aef555ac 100644 --- a/kernel/src/clock.rs +++ b/kernel/src/clock.rs @@ -1,24 +1,63 @@ //! The machine's clocks: monotonic since boot, read off the CPU's free-running //! counter at the period the architecture's boot gives [`set_counter`] (on -//! x86-64, measured against the HPET); and wall-clock, read from the +//! x86-64, measured against the HPET); wall-clock, read from the //! architecture's RTC exactly once — a CMOS read can block for up to a //! second — in [`init_wall`], and answered after as that reading plus -//! [`nanos_since_boot`]. +//! [`nanos_since_boot`]; and the log's stamp ([`stamp`]), the same clock +//! counted from the counter's zero, which is where every line of the log — +//! the loader's, the kernel's and every program's — counts from. use core::sync::atomic::{AtomicBool, AtomicU64, Ordering::{Acquire, Relaxed, Release}}; use crate::arch::cpu; +use crate::log::LogStamp; use crate::time::Instant; static TSC_BOOT: AtomicU64 = AtomicU64::new(0); static TSC_PERIOD_FS: AtomicU64 = AtomicU64::new(0); +/// The counter's zero to `TSC_BOOT`, in nanoseconds. +static STAMP_AT_BOOT: AtomicU64 = AtomicU64::new(0); +/// One counter tick at the rate the CPU states, in femtoseconds; zero where it +/// states none, or before [`state`]. +static STATED_FS: AtomicU64 = AtomicU64::new(0); + +/// Take the rate the CPU states, the loader's, for the stamps the log carries +/// before [`set_counter`]. The kernel's entry calls this before its first record. +pub fn state() { + let stated = cpu::stated_counter_hz().map_or(0, |hz| 1_000_000_000_000_000 / hz); + STATED_FS.store(stated, Relaxed); +} /// Start the clock on the counter: its reading at boot and its measured period. /// The architecture's boot calls this once, after it has the period. +/// +/// **The stamps go on from where the stated rate left them**: a record before +/// this read the counter at that rate, so the stamp at `boot` is that reading, +/// and no record after this one is stamped earlier than one before it. pub fn set_counter(boot: u64, period_fs: u64) { + let stated = STATED_FS.load(Relaxed); + let at_boot = ticks_to_nanos(boot, if stated != 0 { stated } else { period_fs }); + STAMP_AT_BOOT.store(at_boot, Relaxed); TSC_BOOT.store(boot, Relaxed); TSC_PERIOD_FS.store(period_fs, Relaxed); - publish_page(boot, period_fs); + publish_page(boot, period_fs, at_boot); +} + +fn ticks_to_nanos(ticks: u64, period_fs: u64) -> u64 { + ((ticks as u128 * period_fs as u128) / 1_000_000) as u64 +} + +/// Now as a log line's time: nanoseconds since the counter's zero — power-on, +/// or the reset since — at the clock's rate, and before [`set_counter`] at the +/// rate the CPU states. `None` where it states none and the clock has not +/// started: no rate reads the counter yet. Never panics, as +/// [`nanos_since_boot`]. +pub fn stamp() -> Option { + if calibrated() { + return Some(LogStamp::since_zero(STAMP_AT_BOOT.load(Relaxed).saturating_add(nanos_since_boot()))); + } + let stated = STATED_FS.load(Relaxed); + (stated != 0).then(|| LogStamp::since_zero(ticks_to_nanos(cpu::counter(), stated))) } /// The clock page's frame, or 0 before [`set_counter`]: the one every address space @@ -28,7 +67,7 @@ static PAGE_PHYS: AtomicU64 = AtomicU64::new(0); /// Lay the calibration out on a frame of its own, for every process to read /// the clock this module reads without asking it. Laid out before any address /// space can map it, and never written again. -fn publish_page(counter_at_boot: u64, period_fs: u64) { +fn publish_page(counter_at_boot: u64, period_fs: u64, stamp_at_boot: u64) { use toyos_abi::clock::{ClockPage, CLOCK_MAGIC}; let bytes = crate::mm::PAGE_2M as usize; // Held for the machine's life: every process maps it. @@ -42,7 +81,7 @@ fn publish_page(counter_at_boot: u64, period_fs: u64) { core::ptr::write_bytes(frame.ptr(), 0, bytes); core::ptr::write_volatile( frame.ptr() as *mut ClockPage, - ClockPage { magic: CLOCK_MAGIC, counter_at_boot, period_fs }, + ClockPage { magic: CLOCK_MAGIC, counter_at_boot, period_fs, stamp_at_boot }, ); } PAGE_PHYS.store(frame.phys(), Release); @@ -75,9 +114,7 @@ pub fn calibrated() -> bool { /// reads it from inside a bracket where panicking would reenter the log. /// Saturating, not wrapping: a trailing CPU reads as oldest, not lying newest after a 584-year wrap. pub fn nanos_since_boot() -> u64 { - let delta = cpu::counter().saturating_sub(TSC_BOOT.load(Relaxed)); - let period_fs = TSC_PERIOD_FS.load(Relaxed); - ((delta as u128 * period_fs as u128) / 1_000_000) as u64 + ticks_to_nanos(cpu::counter().saturating_sub(TSC_BOOT.load(Relaxed)), TSC_PERIOD_FS.load(Relaxed)) } /// The same reading as an [`Instant`], the type arithmetic on it is allowed in. @@ -109,7 +146,7 @@ pub fn counter_ticks(nanos: u64) -> u64 { /// Zero while the period is unknown, so a span taken on a machine that never /// calibrated reads as no time rather than as an invented one. pub fn nanos_of_ticks(ticks: u64) -> u64 { - ((ticks as u128 * TSC_PERIOD_FS.load(Relaxed) as u128) / 1_000_000) as u64 + ticks_to_nanos(ticks, TSC_PERIOD_FS.load(Relaxed)) } /// Polls `ready` until it holds or `nanos` pass; `false` is the deadline. diff --git a/kernel/src/deadline.rs b/kernel/src/deadline.rs index ff284ecea47..04af4cb9bfc 100644 --- a/kernel/src/deadline.rs +++ b/kernel/src/deadline.rs @@ -244,7 +244,7 @@ fn expire() -> ! { CPU's timer last found the kernel:\n{KernelPcs}The tail of the log ring follows — which \ is what nothing was draining.\n", BOUND_MS.load(Relaxed), - crate::clock::nanos_since_boot() / 1_000_000, + crate::clock::stamp().expect("the deadline polls only once the clock runs").nanos() / 1_000_000, phase(), )); // The seal first, because the USB stop `reset_now` makes before it writes diff --git a/kernel/src/drivers/panic_console/mod.rs b/kernel/src/drivers/panic_console/mod.rs index c6040253026..837761a7f55 100644 --- a/kernel/src/drivers/panic_console/mod.rs +++ b/kernel/src/drivers/panic_console/mod.rs @@ -19,6 +19,7 @@ use core::sync::atomic::{AtomicBool, AtomicU32, AtomicU64, AtomicUsize, Ordering use toyos_abi::boot::{KernelArgs, MemoryMapEntry}; use crate::log; +use crate::log::LogStamp; use crate::panic_reboot::Bound; use crate::time::{Budget, Cadence, Duration}; use crate::mm::policy::MmioPolicy; @@ -152,7 +153,7 @@ impl Rendered { Self { text: [0; SNAPSHOT_CAP], marks: [0; MARK_BYTES], len: 0, lines: 0 }; /// Render the newest records stamped in `from..=to` that fit; returns the byte count. Records older than the buffer holds are dropped. - fn render(&mut self, from: u64, to: u64) -> usize { + fn render(&mut self, from: LogStamp, to: LogStamp) -> usize { self.marks = [0; MARK_BYTES]; self.lines = 0; self.len = 0; @@ -579,7 +580,7 @@ fn capture_into(refresh: bool) { // panic path may take no lock. `SNAPSHOT` is written only here, under // `CAPTURE`, after `CAPTURE_ACCESS` admitted a writer and before publication. let into = unsafe { &mut *SNAPSHOT.0.get() }; - CAPTURE_ACCESS.publish(into.render(0, u64::MAX) > 0); + CAPTURE_ACCESS.publish(into.render(LogStamp::ZERO, LogStamp::MAX) > 0); } /// This CPU's claim on `SNAPSHOT`; tokens never collide, unclaimed-0 and `EARLY_CAPTOR` included. @@ -604,7 +605,7 @@ fn live_tail() -> View<'static> { // SAFETY: sound as `capture`'s `SNAPSHOT` write — `LIVE` is reached only // from here, every caller holds `PAINTING`; one block, not two, so render and view can't disagree. let into: &'static mut Rendered = unsafe { &mut *LIVE.0.get() }; - into.render(0, u64::MAX); + into.render(LogStamp::ZERO, LogStamp::MAX); let rendered: &'static Rendered = into; rendered.view() } @@ -761,7 +762,7 @@ fn repaint() { /// /// [`boot_checkpoint`] without the userland check — the keystroke is the /// consent. A single paint is not a report, so this arms a hold that [`hold_report`] answers. -pub fn paint_report(from: u64, to: u64) { +pub fn paint_report(from: LogStamp, to: LogStamp) { // SAFETY: sound as `capture`'s `SNAPSHOT` write — `REPORT` is reached // only from here and `report_text`; the dump reschedules every CPU, so only one is in flight. let into = unsafe { &mut *REPORT.0.get() }; diff --git a/kernel/src/log/console.rs b/kernel/src/log/console.rs index 5c819b5ab52..32450524d4f 100644 --- a/kernel/src/log/console.rs +++ b/kernel/src/log/console.rs @@ -347,11 +347,11 @@ impl core::fmt::Write for Line { } } -/// Render one record as the console line; `logkeeper`'s `/log` sink renders the same line with a different prefix. +/// Render one record as the console line; `logkeeper`'s `/log` sink renders the same line with its wall clock. pub fn write_line(record: &LogRecord, emit: impl FnMut(&[u8])) { use core::fmt::Write; let mut line = Line::new(emit); - let _ = write!(line, "{}", record.tagged("kernel")); + let _ = write!(line, "{record}"); line.finish(); } diff --git a/kernel/src/log/mod.rs b/kernel/src/log/mod.rs index 2ff8cc727c4..25b1d43aeef 100644 --- a/kernel/src/log/mod.rs +++ b/kernel/src/log/mod.rs @@ -10,13 +10,15 @@ pub mod read; pub mod recovery; pub mod registry; pub mod shard; +mod stamp; #[cfg(feature = "test-actuators")] pub mod storm; pub mod user; use core::sync::atomic::{AtomicBool, Ordering}; -use toyos_abi::log::{LogRecord, FLAG_EARLY, MAX_LOG_SHARDS, MAX_RECORD_MESSAGE}; +pub use stamp::LogStamp; +use toyos_abi::log::{LogRecord, FLAG_UNTIMED, MAX_LOG_SHARDS, MAX_RECORD_MESSAGE}; pub use shard::Shard; pub use toyos_abi::log::Severity; @@ -91,7 +93,7 @@ pub fn seal_tail() { crate::blackbox::append(|out| { let _ = writeln!(out, "{TAIL_HEAD} ({TAIL_RECORDS})"); let mut tail = Tail { out, left: TAIL_RECORDS }; - read::snapshot_committed(0, read::newest_committed_at_ns(), &mut tail); + read::snapshot_committed(LogStamp::ZERO, read::newest_committed(), &mut tail); }); } @@ -143,7 +145,6 @@ struct Origin { cpu: u16, tid: u32, pid: u32, - flags: u8, } /// The IF/TF-off bracket must span the `xadd` through publication, or a @@ -155,14 +156,14 @@ fn reserve(guard: &crate::arch::IrqGuard) -> (Origin, u64) { if !PERCPU_READY.load(Ordering::Relaxed) { // SAFETY: nothing else is running, so this CPU owns the boot shard. let seq = unsafe { BOOT_SHARD.reserve(guard) }; - let origin = Origin { shard: &BOOT_SHARD, cpu: 0, tid: 0, pid: 0, flags: FLAG_EARLY }; + let origin = Origin { shard: &BOOT_SHARD, cpu: 0, tid: 0, pid: 0 }; return (origin, seq); } let (shard, seq, cpu, tid, pid) = crate::arch::percpu::reserve_log_slot(guard); // SAFETY: this CPU's own `PerCpu` pointer, valid before the CPU takes an instruction. let shard: &'static Shard = unsafe { &*shard }; - (Origin { shard, cpu: cpu as u16, tid: on_a_thread(tid), pid: on_a_thread(pid), flags: 0 }, seq) + (Origin { shard, cpu: cpu as u16, tid: on_a_thread(tid), pid: on_a_thread(pid) }, seq) } /// `0` means "no thread"; `PerCpu`'s own sentinel is `u32::MAX`, translated at @@ -191,13 +192,15 @@ pub fn emit(severity: Severity, args: core::fmt::Arguments) { // could disagree. The NMI handler never logs and #MC halts rather than // returning, which is what closes the two paths IF/TF masking alone // cannot. - record.at_ns = crate::clock::nanos_since_boot(); + match crate::clock::stamp() { + Some(at) => record.at_ns = at.nanos(), + None => record.flags = FLAG_UNTIMED, + } let (origin, seq) = reserve(&guard); record.seq = seq; record.pid = origin.pid; record.tid = origin.tid; record.cpu = origin.cpu; - record.flags = origin.flags; // SAFETY: seq came from this shard's own reserve, committed exactly once under this guard. unsafe { origin.shard.commit(seq, &record, &guard) }; diff --git a/kernel/src/log/read.rs b/kernel/src/log/read.rs index 549d7bc0049..4034a2684a1 100644 --- a/kernel/src/log/read.rs +++ b/kernel/src/log/read.rs @@ -6,6 +6,7 @@ use toyos_abi::log::{LogRecord, MAX_LOG_SHARDS}; use super::shard::{Ring, Shard, FIRST_SEQ}; +use super::stamp::LogStamp; /// Accepts one record; `false` means it was not taken and ends the walk. pub trait RecordSink { @@ -220,9 +221,9 @@ where } } -/// The `at_ns` of the newest committed record, or zero if none: the upper bound +/// The stamp of the newest committed record, or zero if none: the upper bound /// of a snapshot that must not chase records committed while it walks. -pub fn newest_committed_at_ns() -> u64 { +pub fn newest_committed() -> LogStamp { let mut newest = 0; for shard in super::shards().iter().flatten() { let mut descent = IDLE; @@ -235,7 +236,7 @@ pub fn newest_committed_at_ns() -> u64 { newest = newest.max(at_ns); } } - newest + LogStamp::since_zero(newest) } /// Is there a committed record this cursor has not taken, without taking it? @@ -254,7 +255,8 @@ pub fn any_committed(cursor: &Cursor) -> bool { /// Every committed record stamped in `from..=to`, newest first merged by /// `at_ns` until `out` is full; returns nothing, since no caller counts. -pub fn snapshot_committed(from: u64, to: u64, out: &mut impl RecordSink) { +pub fn snapshot_committed(from: LogStamp, to: LogStamp, out: &mut impl RecordSink) { + let (from, to) = (from.nanos(), to.nanos()); let mut descents = [IDLE; MAX_LOG_SHARDS]; for (descent, shard) in descents.iter_mut().zip(super::shards()) { let Some(shard) = shard else { continue }; diff --git a/kernel/src/log/recovery.rs b/kernel/src/log/recovery.rs index f9127050af5..7ed0c704507 100644 --- a/kernel/src/log/recovery.rs +++ b/kernel/src/log/recovery.rs @@ -12,6 +12,7 @@ use toyos_abi::log::LogRecord; use toyos_blackbox::{Kept, Recovery, Report}; use super::read::{self, RecordSink}; +use super::LogStamp; /// Write the section at `report`'s end. pub fn seal_into(report: &mut Report<'_>) { @@ -31,12 +32,12 @@ pub fn seal_into(report: &mut Report<'_>) { // One upper bound for both walks: a record committed between them is // stamped past it, so the second walk places what the first measured. - let to = read::newest_committed_at_ns(); + let to = read::newest_committed(); let mut measure = Measure(Recovery::new()); - read::snapshot_committed(0, to, &mut measure); + read::snapshot_committed(LogStamp::ZERO, to, &mut measure); let mut kept = report.recovery(measure.0); if let Some(from) = kept.from() { - read::snapshot_committed(from, to, &mut Place(&mut kept)); + read::snapshot_committed(LogStamp::since_zero(from), to, &mut Place(&mut kept)); } kept.close(); } diff --git a/kernel/src/log/stamp.rs b/kernel/src/log/stamp.rs new file mode 100644 index 00000000000..1dc26556fec --- /dev/null +++ b/kernel/src/log/stamp.rs @@ -0,0 +1,23 @@ +//! A log line's time, the clock a record's `at_ns` is on: nanoseconds since +//! the counter's zero (`crate::clock::stamp`). A type of its own because +//! `clock::nanos_since_boot` counts the same nanoseconds from another zero, +//! and a window over the log taken on that clock lands that far from the +//! records it means. + +#[derive(Clone, Copy, PartialEq, Eq, PartialOrd, Ord)] +pub struct LogStamp(u64); + +impl LogStamp { + pub const ZERO: Self = Self(0); + pub const MAX: Self = Self(u64::MAX); + + /// `nanos` since the counter's zero: a record's `at_ns`, or the clock's + /// own reading of it. + pub const fn since_zero(nanos: u64) -> Self { + Self(nanos) + } + + pub const fn nanos(self) -> u64 { + self.0 + } +} diff --git a/kernel/src/main.rs b/kernel/src/main.rs index 008bd03f7c7..d9efe43ded9 100644 --- a/kernel/src/main.rs +++ b/kernel/src/main.rs @@ -230,6 +230,8 @@ fn report_log_destination() { /// # Safety /// `kernel_args` is the loader's live [`KernelArgs`], and nothing has run before this. pub(crate) unsafe extern "C" fn kernel_main(kernel_args: &KernelArgs) -> ! { + // Before the first record, which is stamped at the rate it states. + clock::state(); // Copied onto the kernel stack: the original lives on the UEFI stack, unreachable once mm::init drops the identity map. let kernel_args = *kernel_args; diff --git a/kernel/src/sched/dump.rs b/kernel/src/sched/dump.rs index 512cb3ae28e..80467d06868 100644 --- a/kernel/src/sched/dump.rs +++ b/kernel/src/sched/dump.rs @@ -214,7 +214,7 @@ fn report(_proof: &UnderNothing) { let cpus = online_cpus(); let me = percpu::cpu_id() as usize; // Two instants, not byte positions: there is no single stream across CPUs. - let from = crate::clock::nanos_since_boot(); + let from = log_stamp(); log!("=== blocked-task dump: {cpus} cpu(s), and this report takes the screen ==="); // Indexed by cpu id: `OWES` is `MAX_CPUS` long regardless of `cpus`. @@ -257,7 +257,11 @@ fn report(_proof: &UnderNothing) { let census = census(); summary(cpus, silent, census); - crate::drivers::panic_console::paint_report(from, crate::clock::nanos_since_boot()); + crate::drivers::panic_console::paint_report(from, log_stamp()); +} + +fn log_stamp() -> crate::log::LogStamp { + crate::clock::stamp().expect("the dump runs in a scheduler pass, after the clock starts") } /// Sends an NMI to each CPU that ignored its kick: unlike a kick, an NMI diff --git a/src/bootlog.rs b/src/bootlog.rs index e1dea2990c1..c5f726feb7c 100644 --- a/src/bootlog.rs +++ b/src/bootlog.rs @@ -219,14 +219,14 @@ pub fn panel_census(log: &str) -> Option { /// ended, which no program writes ([`is_program_line`]). pub const EXIT: &str = "exit: "; -/// One rendered record's message: what follows the bracket every kernel -/// record opens with. `None` for a line that is not a kernel record's first. +/// One rendered record's message: what follows its head. `None` for a line +/// that is not a kernel record's first. pub fn message(line: &str) -> Option<&str> { - line.strip_prefix('[')?.split_once("] ").map(|(_, message)| message) + toyos_logstream::parse(line).filter(|p| p.source == toyos_logstream::Source::Kernel).map(|p| p.text) } /// Whether a line of the log is a program's (`toyos_logstream::ProgramLine`): -/// `logkeeper` writes that head and no kernel record opens with it. +/// `logkeeper` writes that head, and it names no kernel. pub fn is_program_line(line: &str) -> bool { toyos_logstream::is_program_line(line) } @@ -372,11 +372,83 @@ pub fn stopping_line(log: &str) -> Option<&str> { }) } -/// The milliseconds since boot one record line carries. +/// The loader's word for its clock, in `bootloader/src/main.rs`: the head of +/// the line naming the rate the CPU states, and the line where it states none. +pub const LOADER_CLOCK_STATED: &str = + "Loader clock: each line opens with the seconds since the counter's zero, at the counter's stated "; +pub const LOADER_CLOCK_NONE: &str = + "Loader clock: this CPU states no counter rate, so no line carries the time it was said"; + +/// The kernel's record of starting `logkeeper`, which every boot does, and the +/// supervisor's line once that spawn has returned to it. +pub const LOGKEEPER_SPAWN: &str = "spawn: /system/bin/logkeeper "; +pub const LOGKEEPER_STARTED: &str = "supervisor: started logkeeper"; + +/// Whether the loader's lines, the kernel's records and a program's lines +/// count from one zero: no timed kernel record is earlier than the loader's +/// last timed line before the handoff, and the supervisor's +/// [`LOGKEEPER_STARTED`] is no earlier than the kernel's [`LOGKEEPER_SPAWN`], +/// which the same spawn call writes milliseconds before. A clock that kept +/// another zero puts one of them before what caused it. /// -/// **Found from the CPU it precedes rather than by position**: the field before -/// it is the writer's tag, and the two writers disagree about it on purpose — -/// `logkeeper` puts a wall clock there and the panel puts nothing. +/// `loader` holds the pass that handed the machine to the kernel; `log` holds +/// the kernel's records and the programs' lines, and may hold the loader's +/// too, as a console does. Nothing to compare is a refusal wherever the boot +/// owes it: a loader that states a rate owes timed lines, and a boot that +/// reached [`COMPLETE`] owes the spawn record and the supervisor's line. +pub fn one_clock(loader: &str, log: &str) -> Result<(), String> { + use toyos_logstream::{parse, Source}; + let handed = loader + .find(LOADER_LAST_LINE) + .map(|at| &loader[..at + LOADER_LAST_LINE.len()]) + .ok_or_else(|| format!("the loader never said {LOADER_LAST_LINE:?}"))?; + let stated = handed.contains(LOADER_CLOCK_STATED); + if !stated && !handed.contains(LOADER_CLOCK_NONE) { + return Err("the loader said nothing of its clock before the handoff".to_string()); + } + if stated { + let loader = handed + .lines() + .filter_map(parse) + .filter(|p| p.source == Source::Loader) + .filter_map(|p| p.ms) + .next_back() + .ok_or("the loader states its counter's rate and none of its lines carries a time")?; + let kernel = log + .lines() + .filter_map(record_millis) + .min() + .ok_or("the loader states its counter's rate and no kernel record carries a time")?; + if kernel < loader { + return Err(format!( + "the loader's last line before the handoff reads {loader} ms and the kernel's \ + earliest timed record {kernel} ms" + )); + } + } + let spawned = log.lines().find(|l| message(l).is_some_and(|m| m.starts_with(LOGKEEPER_SPAWN))).and_then(record_millis); + let said = log + .lines() + .filter_map(parse) + .find(|p| p.source == Source::Program("supervisor") && p.text == LOGKEEPER_STARTED) + .and_then(|p| p.ms); + let complete = log.lines().any(|l| message(l).is_some_and(|m| m.starts_with(COMPLETE))); + match (spawned, said) { + (Some(spawned), Some(said)) if said < spawned => Err(format!( + "the supervisor's {LOGKEEPER_STARTED:?} reads {said} ms and the kernel's record of that spawn {spawned} ms" + )), + (Some(_), Some(_)) => Ok(()), + (spawned, said) if complete => Err(format!( + "the boot reached {COMPLETE:?} with {} and {}", + if spawned.is_some() { "a timed spawn record of logkeeper" } else { "no timed spawn record of logkeeper" }, + if said.is_some() { "a timed supervisor line saying so" } else { "no timed supervisor line saying so" }, + )), + _ => Ok(()), + } +} + +/// The milliseconds since the counter's zero one record line carries, whether +/// `logkeeper` put a wall clock before them or the panel put nothing. pub fn record_millis(line: &str) -> Option { toyos_logstream::record_ms(line) } @@ -403,7 +475,8 @@ pub fn declares(source: &str, rhs: &str) -> bool { joined.lines().any(|line| line.trim_end().ends_with(&tail)) } -/// When the last record in `log` was written, in milliseconds since boot. +/// When the last record in `log` was written, in milliseconds since the +/// counter's zero. pub fn last_record_millis(log: &str) -> Option { log.lines().rev().find_map(record_millis) } @@ -437,22 +510,22 @@ mod tests { /// made the log whole before it. #[test] fn a_boot_record_without_the_supervisors_stop_is_not_a_pass() { - let booted = "[kernel 1.151 cpu0] Boot: complete (1151ms)\n"; - let stopping = format!("{{1.203 supervisor}} {STOPPING} (Reboot)\n"); + let booted = "[ 1.151 cpu0 kernel] Boot: complete (1151ms)\n"; + let stopping = format!("[ 1.203 supervisor] {STOPPING} (Reboot)\n"); let ended = format!("{booted}{stopping}"); assert_eq!(verdict(&ended), Ok(1151)); // What `logkeeper` wrote between the flush and the stop is no refusal. - assert_eq!(verdict(&format!("{ended}[kernel 1.210 cpu0] exit: reboot pid=6\n")), Ok(1151)); + assert_eq!(verdict(&format!("{ended}[ 1.210 cpu0 kernel] exit: reboot pid=6\n")), Ok(1151)); assert_eq!( verdict(booted), - Err(Unfit::Unfinished("[kernel 1.151 cpu0] Boot: complete (1151ms)".to_string())) + Err(Unfit::Unfinished("[ 1.151 cpu0 kernel] Boot: complete (1151ms)".to_string())) ); // The words, from anyone but the supervisor, and from the supervisor as anything but its // line, are not the supervisor's stop. - let forged = format!("{booted}{{1.203 test-runner}} {STOPPING}\n"); + let forged = format!("{booted}[ 1.203 test-runner] {STOPPING}\n"); assert!(matches!(verdict(&forged), Err(Unfit::Unfinished(_)))); - let quoted = format!("{booted}{{1.203 supervisor}} supervisor: said {STOPPING}\n"); + let quoted = format!("{booted}[ 1.203 supervisor] supervisor: said {STOPPING}\n"); assert!(matches!(verdict("ed), Err(Unfit::Unfinished(_)))); assert_eq!(verdict(&stopping), Err(Unfit::NoBootRecord)); assert_eq!(verdict(""), Err(Unfit::NoBootRecord)); @@ -463,11 +536,11 @@ mod tests { #[test] fn a_boot_is_handed_back_by_its_done_and_its_last_word() { let done = format!("Black box: {HANDED_BACK} at 2026-09-08-160844\n"); - let tail = format!("| {LOG_TAIL}[kernel 23.340 cpu1] {REBOOTING}\n"); + let tail = format!("| {LOG_TAIL}[23.340 cpu1 kernel] {REBOOTING}\n"); assert_eq!(handed_back(&format!("{done}{tail}")), Ok(())); assert_eq!(handed_back(&done), Err(Unfit::NotHandedBack)); assert_eq!(handed_back(&tail), Err(Unfit::NotHandedBack)); - let elsewhere = format!("{done}| [kernel 23.340 cpu1] {REBOOTING}\n"); + let elsewhere = format!("{done}| [23.340 cpu1 kernel] {REBOOTING}\n"); assert_eq!(handed_back(&elsewhere), Err(Unfit::NotHandedBack)); } @@ -511,6 +584,15 @@ mod tests { path.display() ); } + // Formats, not constants: the loader fills the rate's hole with the + // counter's. + let main = std::fs::read_to_string( + std::path::Path::new(env!("CARGO_MANIFEST_DIR")).join("bootloader/src/main.rs"), + ) + .expect("the loader's main"); + for said in [format!("{LOADER_CLOCK_STATED}{{hz}} Hz\""), format!("\"{LOADER_CLOCK_NONE}\"")] { + assert!(main.contains(&said), "bootloader/src/main.rs prints no {said:?}"); + } // A format and not a constant: the loader fills its hole with the // state's own word. let path = @@ -581,11 +663,11 @@ mod tests { /// record's continuation line is the kernel's. #[test] fn a_programs_line_is_never_the_kernels() { - let log = "[2026-09-08 16:08:23 2.100 cpu0] exit: test_rs_job pid=4 code=3 cpu=1ms\n\ - [2026-09-08 16:08:23 2.150 cpu0] PANIC: a report\n its second line\n\ - {2026-09-08 16:08:23 2.200 test-runner} [2026-09-08 16:08:23 2.200 cpu0] exit: test_rs_job pid=4 code=0 cpu=0ms\n\ - {2026-09-08 16:08:23 2.300 test-runner} {x 2.3 netstack} netstack: MAC 00:00:00:00:00:00\n\ - {2026-09-08 16:08:23 2.400 netstack} netstack: MAC 52:54:00:12:34:56\n"; + let log = "[2026-09-08 16:08:23 2.100 cpu0 kernel] exit: test_rs_job pid=4 code=3 cpu=1ms\n\ + [2026-09-08 16:08:23 2.150 cpu0 kernel] PANIC: a report\n its second line\n\ + [2026-09-08 16:08:23 2.200 test-runner] [2026-09-08 16:08:23 2.200 cpu0 kernel] exit: test_rs_job pid=4 code=0 cpu=0ms\n\ + [2026-09-08 16:08:23 2.300 test-runner] [ 2.300 netstack] netstack: MAC 00:00:00:00:00:00\n\ + [2026-09-08 16:08:23 2.400 netstack] netstack: MAC 52:54:00:12:34:56\n"; let kernel = kernel_records(log); assert!(!kernel.contains("code=0"), "{kernel}"); assert!(kernel.contains("code=3") && kernel.contains(" its second line\n"), "{kernel}"); @@ -605,8 +687,8 @@ mod tests { #[test] fn the_boot_record_is_the_kernels_own_line() { - assert_eq!(boot_millis("[kernel 1.151 cpu0] Boot: complete (1151ms)\n"), Some(1151)); - assert_eq!(boot_millis("[kernel 0.084 cpu0] Boot: storage ready (84ms)\n"), None); + assert_eq!(boot_millis("[ 1.151 cpu0 kernel] Boot: complete (1151ms)\n"), Some(1151)); + assert_eq!(boot_millis("[ 0.084 cpu0 kernel] Boot: storage ready (84ms)\n"), None); assert_eq!(boot_millis("Boot: complete (later)\n"), None); assert_eq!(boot_millis(""), None); } @@ -622,12 +704,12 @@ mod record_time_tests { #[test] fn a_records_elapsed_field_is_read_past_whatever_tag_precedes_it() { assert_eq!( - record_millis("[2026-09-07 22:57:46 3.109 cpu1] exit: a pid=7 code=0 cpu=180ms"), + record_millis("[2026-09-07 22:57:46 3.109 cpu1 kernel] exit: a pid=7 code=0 cpu=180ms"), Some(3_109) ); - assert_eq!(record_millis("[3.109 cpu1] exit: a pid=7 code=0"), Some(3_109)); + assert_eq!(record_millis("[ 3.109 cpu1 kernel] exit: a pid=7 code=0"), Some(3_109)); assert_eq!( - record_millis("[2026-09-07 22:58:03 20.071 cpu2 tid=1] exit: b tid=1 code=0"), + record_millis("[2026-09-07 22:58:03 20.071 cpu2 kernel tid=1] exit: b tid=1 code=0"), Some(20_071) ); // The `cpu=180ms` field is a record's *content*: a reader keying on the @@ -641,7 +723,7 @@ mod record_time_tests { /// with the kernel's dashes flattened to ASCII. #[test] fn the_panel_census_is_read_off_either_channel() { - let logkeeper = "[2026-09-08 06:50:53 2.5 cpu0] panel: paints=3 px=6220800 us=1500000 \ + let logkeeper = "[2026-09-08 06:50:53 2.500 cpu0 kernel] panel: paints=3 px=6220800 us=1500000 \ max_us=520000\n"; assert_eq!( panel_census(logkeeper), @@ -664,7 +746,7 @@ mod record_time_tests { | usb-quiesce: no barrier was taken, so this reset is not the shutdown's\n\ | usb-quiesce: no bulk transfer was outstan{cut}\n\ {TAIL_IN_THE_FILE} 221 record(s)\n\ - | [0.148 cpu0] iommu: unit3 scope ioapic 00:1e.7 id=2\n" + | [ 0.148 cpu0 kernel] iommu: unit3 scope ioapic 00:1e.7 id=2\n" ) }; // Run 44's own reading, with the cut two lines under the census. @@ -687,7 +769,7 @@ mod record_time_tests { #[test] fn the_last_record_is_the_last_line_that_carries_a_time() { - let log = "[1.000 cpu0] first\n[2.500 cpu1] second\nnot a record\n"; + let log = "[ 1.000 cpu0 kernel] first\n[ 2.500 cpu1 kernel] second\nnot a record\n"; assert_eq!(last_record_millis(log), Some(2_500)); assert_eq!(last_record_millis("nothing\n"), None); } diff --git a/src/kernelconsole.rs b/src/kernelconsole.rs index 731a8d53a77..12e33763bfa 100644 --- a/src/kernelconsole.rs +++ b/src/kernelconsole.rs @@ -5,28 +5,24 @@ //! loader's there first, the last of them cut off where boot services end and //! the kernel's first record written onto its tail. Every one of them is on the //! 16550 as well, and a loader line is read there. Where the kernel begins is -//! the whole rule, so a firmware that writes nothing on the port reads the same. -//! A terminal is shown that whole, and what is the kernel's in colour -//! ([`Painter`], [`relay`]); the bytes the host reads are never coloured. +//! the whole rule (`toyos_logstream::kernel_opening`), so a firmware that +//! writes nothing on the port reads the same. A terminal is shown that whole, +//! and what is the kernel's in colour ([`Painter`], [`relay`]); the bytes the +//! host reads are never coloured. use std::borrow::Cow; use std::io::{self, Read, Write}; use std::os::fd::{AsFd, AsRawFd, BorrowedFd}; -use toyos_logstream::Showing; - -/// What every kernel record's console line opens with: `write_line` in -/// `kernel/src/log/console.rs` tags each record `kernel`, and nothing before -/// the kernel writes it. -pub const HEAD: &str = "[kernel "; +use toyos_logstream::{kernel_opening, Opening, Showing}; /// A console's bytes as they arrive, withheld until the kernel's first record. /// /// Of a QEMU process's first boot only: a guest reset does not re-arm it /// (`issues/the-kernel-console-split-does-not-re-arm-across-a-guest-reset.md`). pub struct KernelConsole { - /// The withheld tail that could still begin [`HEAD`]; `None` once the - /// kernel has begun. + /// The withheld tail that could still open the kernel's first record; + /// `None` once the kernel has begun. held: Option>, } @@ -41,14 +37,21 @@ impl KernelConsole { pub fn pass<'a>(&mut self, chunk: &'a [u8]) -> Cow<'a, [u8]> { let Some(held) = &mut self.held else { return Cow::Borrowed(chunk) }; held.extend_from_slice(chunk); - let head = HEAD.as_bytes(); - if let Some(at) = held.windows(head.len()).position(|w| w == head) { - let from = held.split_off(at); - self.held = None; - return Cow::Owned(from); + match kernel_opening(held) { + Opening::At(at) => { + let from = held.split_off(at); + self.held = None; + Cow::Owned(from) + } + Opening::From(at) => { + held.drain(..at); + Cow::Borrowed(&[]) + } + Opening::Nowhere => { + held.clear(); + Cow::Borrowed(&[]) + } } - held.drain(..held.len().saturating_sub(head.len() - 1)); - Cow::Borrowed(&[]) } } @@ -56,8 +59,8 @@ impl KernelConsole { /// record as it came, and every line from it on as [`Showing`] shows it. /// /// From the kernel's first record on the console carries whole lines only, so -/// a line is held until it ends; before it, only what could still begin -/// [`HEAD`] is. +/// a line is held until it ends; before it, only what could still open that +/// record is. #[derive(Default)] pub struct Painter { begun: bool, @@ -70,16 +73,18 @@ impl Painter { pub fn pass(&mut self, chunk: &[u8]) -> Vec { let mut out = Vec::new(); self.held.extend_from_slice(chunk); - let head = HEAD.as_bytes(); if !self.begun { - match self.held.windows(head.len()).position(|w| w == head) { - Some(at) => { + match kernel_opening(&self.held) { + Opening::At(at) => { out.extend(self.held.drain(..at)); self.begun = true; } - None => { - let keep = (1..head.len()).rev().find(|&k| self.held.ends_with(&head[..k])).unwrap_or(0); - out.extend(self.held.drain(..self.held.len() - keep)); + Opening::From(at) => { + out.extend(self.held.drain(..at)); + return out; + } + Opening::Nowhere => { + out.append(&mut self.held); return out; } } @@ -94,7 +99,7 @@ impl Painter { /// What the terminal is shown of what is still held once the console has /// ended: a line a machine that stopped mid-line never finished, or the - /// bytes that could have begun [`HEAD`]. + /// bytes that could have opened the kernel's first record. pub fn finish(mut self) -> Vec { let held = std::mem::take(&mut self.held); if !self.begun || held.is_empty() { @@ -176,14 +181,14 @@ mod tests { /// off by the handoff. const FIRMWARE: &str = "\x1b[2J\x1b[01;01H\x1b[=3h\x1b[2J\x1b[01;01HBdsDxe: loading Boot0001 \ \"UEFI QEMU QEMU USB HARDDRIVE TOYOS0BOOTSTICK1\" from PciRoot(0x0)/Pci(0x1,0x0)/USB(0x0,0x0)\n\ - ToyOS Bootloader 1.0\n\ - ROOT: read into memory at 0x7c894000+0x800000 from LBA 212992+16384, 1048576 bytes a request \ + [--.--- cpu0 loader] ToyOS Bootloader 1.0\n\ + [--.--- cpu0 loader] ROOT: read into memory at 0x7c894000+0x800000 from LBA 212992+16384, 1048576 bytes a request \ (optimal granularity: not reported), in 22519000 counter ticks\n\ - Loader log: the kernel handoff begins, so "; + [--.--- cpu0 loader] Loader log: the kernel handoff begins, so "; - const KERNEL: &str = "[kernel 0.000 cpu0 boot] black box: 0x8000000 is this boot's, 16344 bytes \ + const KERNEL: &str = "[--.--- cpu0 kernel] black box: 0x8000000 is this boot's, 16344 bytes \ for the next boot's loader\n\ - [kernel 0.001 cpu0 boot] pmm: the firmware map calls 4288393216 bytes usable\n"; + [--.--- cpu0 kernel] pmm: the firmware map calls 4288393216 bytes usable\n"; /// Everything `stream` passes, fed in pieces cut at each of `cuts`. fn passed(stream: &str, cuts: &[usize]) -> String { @@ -214,7 +219,7 @@ mod tests { #[test] fn a_port_the_firmware_left_alone_passes_whole() { - let later = format!("{KERNEL}{{1.002 supervisor}} supervisor: a program's line\n"); + let later = format!("{KERNEL}[ 1.002 supervisor] supervisor: a program's line\n"); assert_eq!(passed(&later, &[3, 40]), later); } @@ -235,8 +240,8 @@ mod tests { /// and the same however the chunks fall. #[test] fn a_terminal_is_shown_the_firmware_as_it_came_and_the_kernel_in_colour() { - let alert = "[kernel 0.002 cpu1 alert tid=4] PANIC: panicked at kernel/src/main.rs:1:\n oops\n"; - let program = "{0.003 warn supervisor} supervisor: a program's line\n"; + let alert = "[ 0.002 cpu1 kernel alert tid=4] PANIC: panicked at kernel/src/main.rs:1:\n oops\n"; + let program = "[ 0.003 supervisor warn] supervisor: a program's line\n"; let stream = format!("{FIRMWARE}{KERNEL}{alert}{program}"); let mut want = String::from(FIRMWARE); let mut showing = Showing::default(); @@ -247,9 +252,9 @@ mod tests { assert_eq!(painted(&stream, &[]), want); let every_byte: Vec = (1..stream.len()).collect(); assert_eq!(painted(&stream, &every_byte), want); - // What is held before the kernel is only what could begin its head. + // What is held before the kernel is only what could still open its first record. assert_eq!(painted(&FIRMWARE[..FIRMWARE.len() - 3], &[]), FIRMWARE[..FIRMWARE.len() - 3]); - assert_eq!(painted("so [ker", &[]), "so "); + assert_eq!(painted("so [--.--- cpu0 ker", &[]), "so "); } /// A console that ends mid-line — a machine that stopped while it spoke — @@ -257,7 +262,7 @@ mod tests { /// the kernel's head still shows those bytes. #[test] fn a_console_that_ends_mid_line_shows_its_last_line() { - let cut = "[kernel 0.004 cpu0 alert tid=1] PANIC: triple fa"; + let cut = "[ 0.004 cpu0 kernel alert tid=1] PANIC: triple fa"; let mut painter = Painter::default(); let mut out = painter.pass(format!("{KERNEL}{cut}").as_bytes()); out.extend(painter.finish()); @@ -267,7 +272,7 @@ mod tests { assert!(want.ends_with("\x1b[91mPANIC: triple fa\x1b[0m"), "{want:?}"); assert_eq!(String::from_utf8(out).expect("UTF-8"), want); - for early in ["so [ker", "loading\r"] { + for early in ["so [--.--- cpu0 ker", "loading\r"] { let mut painter = Painter::default(); let mut out = painter.pass(early.as_bytes()); out.extend(painter.finish()); @@ -307,10 +312,10 @@ mod tests { fn burst() -> (Vec, Vec) { let mut stream = String::from(FIRMWARE); for n in 0..20_000 { - stream.push_str(&format!("[kernel 1.{:03} cpu{} alert tid=3] frame {n}: kernel::panic\n", n % 1000, n % 8)); + stream.push_str(&format!("[ 1.{:03} cpu{} kernel alert tid=3] frame {n}: kernel::panic\n", n % 1000, n % 8)); stream.push_str(" continued\n"); } - stream.push_str("[kernel 9.999 cpu0] cut mid-li"); + stream.push_str("[ 9.999 cpu0 kernel] cut mid-li"); let mut painter = Painter::default(); let mut want = painter.pass(stream.as_bytes()); want.extend(painter.finish()); @@ -383,6 +388,6 @@ mod tests { let mut console = KernelConsole::default(); assert!(console.pass(FIRMWARE.as_bytes()).is_empty()); let held = console.held.as_ref().expect("the kernel has not begun").len(); - assert!(held < HEAD.len(), "{held} bytes withheld, more than could begin the head"); + assert!(held < toyos_logstream::MAX_HEAD, "{held} bytes withheld, more than could open a record"); } } diff --git a/src/lan.rs b/src/lan.rs index 3808999f599..765a6a81854 100644 --- a/src/lan.rs +++ b/src/lan.rs @@ -182,7 +182,7 @@ pub fn delivered(text: &str) -> Result { mod tests { use super::*; - const LEASED: &str = "[2026-09-08 16:08:23 2.100 cpu0] netstack: DHCP: lease 10.0.2.15/24 from \ + const LEASED: &str = "[2026-09-08 16:08:23 2.100 cpu0 kernel] netstack: DHCP: lease 10.0.2.15/24 from \ 10.0.2.2, gateway 10.0.2.2, dns [10.0.2.3 10.0.2.4], 412 ms after netstack \ came up"; @@ -250,10 +250,10 @@ mod tests { fn only_netstacks_own_lines_are_netstacks() { let lease = LEASED.split_once("] ").expect("a record").1; let log = format!( - "{{2026-09-08 16:08:23 2.100 netstack}} {lease}\n\ - {{2026-09-08 16:08:23 2.200 netstack}} netstack: ready, at most 8 clients\n\ - {{2026-09-08 16:08:23 2.300 evil}} {{2026-09-08 16:08:23 2.300 netstack}} netstack: MAC 00:00:00:00:00:00\n\ - [2026-09-08 16:08:23 2.400 cpu0] netstack: MAC 00:00:00:00:00:01\n\ + "[2026-09-08 16:08:23 2.100 netstack] {lease}\n\ + [2026-09-08 16:08:23 2.200 netstack] netstack: ready, at most 8 clients\n\ + [2026-09-08 16:08:23 2.300 evil] [2026-09-08 16:08:23 2.300 netstack] netstack: MAC 00:00:00:00:00:00\n\ + [2026-09-08 16:08:23 2.400 cpu0 kernel] netstack: MAC 00:00:00:00:00:01\n\ netstack: MAC 52:54:00:12:34:56\n" ); let netstack = netstack_records(&log); @@ -274,23 +274,23 @@ mod tests { /// Metal run 57's `lanicscase` kernel log, verbatim, from the I219's /// hand-over to the record of its first message. const RUN_57: &str = "\ -[2026-09-16 15:01:20 1.333 cpu0] pcidev: PCI 00:1f.6 [8086:15fc] handed over on slot 0, vector 0x28 -[2026-09-16 15:01:20 1.360 cpu0] ELF: 3417 relocations indexed (RELATIVE + GLOB_DAT + TPOFF) -[2026-09-16 15:01:20 1.360 cpu0] spawn: TLS 1 modules, total_memsz=144 -[2026-09-16 15:01:20 1.518 cpu0] spawn: /system/bin/netstack pid=5 tid=0 dst=5 base=0x10000000000 entry=0x1000004e5c0 cr3=0x1cc1000 symbols=2048KiB (layout=25ms relocs=0ms deps=0ms tls=1ms total=184ms) -[2026-09-16 15:01:20 1.552 cpu0] ELF: 2833 relocations indexed (RELATIVE + GLOB_DAT + TPOFF) -[2026-09-16 15:01:20 1.552 cpu0] spawn: TLS 1 modules, total_memsz=144 -[2026-09-16 15:01:20 1.739 cpu0] spawn: /system/bin/test-runner pid=6 tid=0 dst=6 base=0x10000000000 entry=0x1000001fff0 cr3=0x1cbf000 symbols=2048KiB (layout=32ms relocs=0ms deps=0ms tls=2ms total=221ms) -[2026-09-16 15:01:20 1.958 cpu4] usb-storage: disk 0 does not implement SYNCHRONIZE CACHE (sense 0x05/0x20/0x00); its writes are durable once they complete -[2026-09-16 15:01:21 2.239 cpu5] shm: 0xa0800000 mapped Uncacheable into pid 5 -[2026-09-16 15:01:21 2.239 cpu5] iommu: domain6 maps 0x6800000..0x6a00000 at 0x2000000000 -[2026-09-16 15:01:21 2.239 cpu0] pcidev: slot 0 took its first message on vector 0x28 +[2026-09-16 15:01:20 1.333 cpu0 kernel] pcidev: PCI 00:1f.6 [8086:15fc] handed over on slot 0, vector 0x28 +[2026-09-16 15:01:20 1.360 cpu0 kernel] ELF: 3417 relocations indexed (RELATIVE + GLOB_DAT + TPOFF) +[2026-09-16 15:01:20 1.360 cpu0 kernel] spawn: TLS 1 modules, total_memsz=144 +[2026-09-16 15:01:20 1.518 cpu0 kernel] spawn: /system/bin/netstack pid=5 tid=0 dst=5 base=0x10000000000 entry=0x1000004e5c0 cr3=0x1cc1000 symbols=2048KiB (layout=25ms relocs=0ms deps=0ms tls=1ms total=184ms) +[2026-09-16 15:01:20 1.552 cpu0 kernel] ELF: 2833 relocations indexed (RELATIVE + GLOB_DAT + TPOFF) +[2026-09-16 15:01:20 1.552 cpu0 kernel] spawn: TLS 1 modules, total_memsz=144 +[2026-09-16 15:01:20 1.739 cpu0 kernel] spawn: /system/bin/test-runner pid=6 tid=0 dst=6 base=0x10000000000 entry=0x1000001fff0 cr3=0x1cbf000 symbols=2048KiB (layout=32ms relocs=0ms deps=0ms tls=2ms total=221ms) +[2026-09-16 15:01:20 1.958 cpu4 kernel] usb-storage: disk 0 does not implement SYNCHRONIZE CACHE (sense 0x05/0x20/0x00); its writes are durable once they complete +[2026-09-16 15:01:21 2.239 cpu5 kernel] shm: 0xa0800000 mapped Uncacheable into pid 5 +[2026-09-16 15:01:21 2.239 cpu5 kernel] iommu: domain6 maps 0x6800000..0x6a00000 at 0x2000000000 +[2026-09-16 15:01:21 2.239 cpu0 kernel] pcidev: slot 0 took its first message on vector 0x28 "; - const HANDED: &str = "[2026-09-16 15:01:20 1.333 cpu0] pcidev: PCI 00:1f.6 [8086:15fc] \ + const HANDED: &str = "[2026-09-16 15:01:20 1.333 cpu0 kernel] pcidev: PCI 00:1f.6 [8086:15fc] \ handed over on slot 0, vector 0x28\n"; const TOOK: &str = - "[2026-09-16 15:01:21 2.239 cpu0] pcidev: slot 0 took its first message on vector 0x28\n"; + "[2026-09-16 15:01:21 2.239 cpu0 kernel] pcidev: slot 0 took its first message on vector 0x28\n"; /// Run 57 with one of its lines replaced, refusing a fixture the edit did /// not change. @@ -319,7 +319,7 @@ mod tests { /// Another writer's line carrying the words is not the kernel's record. #[test] fn a_line_that_is_not_the_kernels_record_is_refused_and_named() { - let stray = "[2026-09-16 15:01:21 2.240 cpu3] test-runner: waiting until netstack took its \ + let stray = "[2026-09-16 15:01:21 2.240 cpu3 kernel] test-runner: waiting until netstack took its \ first message\n"; let log = edited(TOOK, "").replacen( "total=184ms)\n", @@ -337,7 +337,7 @@ mod tests { fn another_slots_record_is_refused_as_another_claims() { let why = delivered(&edited( TOOK, - "[2026-09-16 15:01:21 2.239 cpu0] pcidev: slot 1 took its first message on vector \ + "[2026-09-16 15:01:21 2.239 cpu0 kernel] pcidev: slot 1 took its first message on vector \ 0x30\n", )) .expect_err("slot 1 is not the I219's"); @@ -354,12 +354,12 @@ mod tests { fn a_boot_where_the_i219_was_not_handed_over_is_refused_whatever_else_took_a_message() { let log = edited( HANDED, - "[2026-09-16 15:01:20 1.333 cpu0] pcidev: PCI 00:1f.6 [8086:15fc] NOT HANDED OVER: \ + "[2026-09-16 15:01:20 1.333 cpu0 kernel] pcidev: PCI 00:1f.6 [8086:15fc] NOT HANDED OVER: \ refused\n", ) .replacen( TOOK, - "[2026-09-16 15:01:21 2.239 cpu0] pcidev: slot 3 took its first message on vector \ + "[2026-09-16 15:01:21 2.239 cpu0 kernel] pcidev: slot 3 took its first message on vector \ 0x2a\n", 1, ); @@ -381,7 +381,7 @@ mod tests { #[test] fn a_record_after_the_slot_is_handed_over_again_is_refused() { let again = - "[2026-09-16 15:01:21 2.200 cpu0] pcidev: PCI 00:1f.7 [8086:a0f0] handed over on \ + "[2026-09-16 15:01:21 2.200 cpu0 kernel] pcidev: PCI 00:1f.7 [8086:a0f0] handed over on \ slot 0, vector 0x28\n"; let log = edited(TOOK, &format!("{again}{TOOK}")); let why = delivered(&log).expect_err("the record answers the later claim"); @@ -397,7 +397,7 @@ mod tests { /// hand-over. #[test] fn a_hand_over_not_in_the_kernels_spelling_is_refused() { - let stray = "[2026-09-16 15:01:20 1.333 cpu0] netstack: [8086:15fc] handed over on slot 0, \ + let stray = "[2026-09-16 15:01:20 1.333 cpu0 kernel] netstack: [8086:15fc] handed over on slot 0, \ vector 0x28\n"; let why = delivered(&edited(HANDED, stray)).expect_err("a userland line"); assert!(why.contains("no `[8086:15fc] handed over on slot ` record"), "{why}"); diff --git a/src/metal.rs b/src/metal.rs index e36a0b46af9..fee39041d79 100644 --- a/src/metal.rs +++ b/src/metal.rs @@ -2677,7 +2677,7 @@ mod tests { let booted = format!("{stale}{}\n", bootlog::LOADER_LAST_LINE); assert_eq!(reported_and_booted_nothing(&booted, ""), None); assert_eq!( - reported_and_booted_nothing(stale, "[kernel 1.2 cpu0] Boot: complete (1220ms)\n"), + reported_and_booted_nothing(stale, "[ 1.200 cpu0 kernel] Boot: complete (1220ms)\n"), None ); assert_eq!( @@ -2745,7 +2745,7 @@ mod tests { let loader = format!( "{}\n{}\n{}\n{}\nBlack box: {}, so it handed the machine back on purpose and this \ - chain ends here\n| {} (16)\n| {}[1.516 cpu0] {}\n{}\n", + chain ends here\n| {} (16)\n| {}[ 1.516 cpu0 kernel] {}\n{}\n", bootlog::LOADER_FIRST_LINE, bootlog::LOADER_LAST_LINE, bootlog::SEPARATOR, @@ -2757,7 +2757,7 @@ mod tests { bootlog::CHAIN_ENDS_LINE, ); let log = format!( - "[kernel 1.151 cpu0] Boot: complete (1151ms)\n{{1.203 supervisor}} {} (Reboot)\n", + "[ 1.151 cpu0 kernel] Boot: complete (1151ms)\n[ 1.203 supervisor] {} (Reboot)\n", bootlog::STOPPING ); assert_eq!( @@ -3271,7 +3271,7 @@ mod tests { bootlog::DEADLINE_EXPIRED ); let log = format!( - "[2026-09-29 18:22:39 0.060 cpu0] {}120000 ms, after which this kernel seals a \ + "[2026-09-29 18:22:39 0.060 cpu0 kernel] {}120000 ms, after which this kernel seals a \ WEDGED record and writes the reset register itself\n", bootlog::DEADLINE_ARMED ); @@ -3295,11 +3295,11 @@ mod tests { reached at 120153 ms, with this machine in `complete`.\n", bootlog::DEADLINE_EXPIRED ); - let booted = "[kernel 1.198 cpu0] Boot: complete (1198ms)\n"; + let booted = "[ 1.198 cpu0 kernel] Boot: complete (1198ms)\n"; assert_eq!(wedged_boot(&sealed, booted), Ok(1198)); let done = format!( - "Black box: {}\n| {}[kernel 1.3 cpu0] {}\n", + "Black box: {}\n| {}[ 1.300 cpu0 kernel] {}\n", bootlog::HANDED_BACK, bootlog::LOG_TAIL, bootlog::REBOOTING @@ -3320,7 +3320,7 @@ mod tests { /// which the detector ended exactly as designed — as a failure. #[test] fn either_bounds_record_is_a_wedged_boots_pass() { - let booted = "[kernel 1.200 cpu0] Boot: complete (1200ms)\n"; + let booted = "[ 1.200 cpu0 kernel] Boot: complete (1200ms)\n"; let locked = format!( "Previous boot's panic: the last boot read WEDGED\n| {}: cpu7 has taken no interrupt \ for 60004 ms, with `IF` clear at every sample in that span. Its bound is 60000 ms.\n\ @@ -3361,8 +3361,8 @@ mod tests { Loader log: the last boot is accounted for, so this pass resets the machine\n", bootlog::SEPARATOR ); - let log = "[2026-09-29 10:36:53 1.171 cpu0] Boot: complete (1171ms)\n\ - {2026-09-29 10:36:53 1.186 supervisor} supervisor: power: the machine stops, and logkeeper makes \ + let log = "[2026-09-29 10:36:53 1.171 cpu0 kernel] Boot: complete (1171ms)\n\ + [2026-09-29 10:36:53 1.186 supervisor] supervisor: power: the machine stops, and logkeeper makes \ the log whole first (Reboot)\n"; let armed = |names: &[&str]| -> Vec { names.iter().map(|n| (*n).to_string()).collect() }; assert_eq!( diff --git a/src/metaldevices.rs b/src/metaldevices.rs index f8321467060..9c9e85cf4c5 100644 --- a/src/metaldevices.rs +++ b/src/metaldevices.rs @@ -104,8 +104,8 @@ mod tests { Black box: the last boot read DONE, so it handed the machine back on purpose and this \ chain ends here\n\ | log: this boot's newest records follow, newest first (16)\n\ - | log-tail: [kernel 3.960 cpu0] Rebooting.\n\ - | log-tail: [kernel 3.955 cpu0] usb-quiesce: disk 0 SYNCHRONIZE CACHE ok\n\ + | log-tail: [ 3.960 cpu0 kernel] Rebooting.\n\ + | log-tail: [ 3.955 cpu0 kernel] usb-quiesce: disk 0 SYNCHRONIZE CACHE ok\n\ | usb-quiesce: no Bulk-Only command was open, so this reset cuts none\n\ | usb-quiesce: xHCI 00:14.0 halted=true USBSTS=0x00000009\n\ | usb-quiesce: 2/2 disk cache(s) flushed, 1 with no cache to flush, \ diff --git a/src/metaltalk.rs b/src/metaltalk.rs index a398349f197..191e39355d6 100644 --- a/src/metaltalk.rs +++ b/src/metaltalk.rs @@ -1256,8 +1256,8 @@ mod tests { #[test] fn the_judge_reads_what_the_stream_carried_and_what_the_peer_answered() { let stream = vec![ - "[---------- -------- 0.011 cpu0] SMP: AP cpu1 online\n".to_string(), - "[---------- -------- 1.216 cpu0] Boot: complete (1216ms)\n".to_string(), + "[---------- -------- 0.011 cpu0 kernel] SMP: AP cpu1 online\n".to_string(), + "[---------- -------- 1.216 cpu0 kernel] Boot: complete (1216ms)\n".to_string(), ]; let good = heard(Ok(Exec { stdout: owed(), status: Some(0) }), Ok("accepted".into())); let said = judge(&good, &stream).expect("every fact is there"); @@ -1301,7 +1301,7 @@ mod tests { let cut = Conversation::parse(&said.render()).unwrap().unwrap(); let bad = judge(&cut, &[]).unwrap_err(); assert!(bad.iter().any(|b| b.contains("before a byte arrived")), "{bad:?}"); - let lines = vec!["[---------- -------- 1.216 cpu0] Boot: complete (1216ms)\n".to_string()]; + let lines = vec!["[---------- -------- 1.216 cpu0 kernel] Boot: complete (1216ms)\n".to_string()]; assert!(judge(&cut, &lines).is_ok()); } @@ -1330,7 +1330,7 @@ mod tests { let stream = Stream::connect(peer, &file, false, Duration::from_secs(10)).unwrap(); let (mut conn, _) = server.accept().unwrap(); for i in 0..100 { - writeln!(conn, "[kernel 0.{i:03} cpu0] line {i}").unwrap(); + writeln!(conn, "[ 0.{i:03} cpu0 kernel] line {i}").unwrap(); } drop(conn); let peer = stream.wait_connected(Duration::from_secs(5)).expect("the peer"); @@ -1339,7 +1339,7 @@ mod tests { let lines = stream.lines(); assert_eq!(lines.len(), 100); for (i, line) in lines.iter().enumerate() { - assert_eq!(*line, format!("[kernel 0.{i:03} cpu0] line {i}\n")); + assert_eq!(*line, format!("[ 0.{i:03} cpu0 kernel] line {i}\n")); } assert_eq!(std::fs::read_to_string(&file).unwrap(), lines.concat()); } @@ -1436,7 +1436,7 @@ mod tests { let reach: Arc = net.clone(); let stream = Stream::through(reach, peer, &dir.join("s.log"), false, Duration::from_secs(5)).unwrap(); let mut conn = accepted(&server, "the dial after the name answered"); - writeln!(conn, "[kernel 1.216 cpu0] Boot: complete (1216ms)").unwrap(); + writeln!(conn, "[ 1.216 cpu0 kernel] Boot: complete (1216ms)").unwrap(); assert_eq!(stream.wait_connected(Duration::from_secs(5)), Some(at), "{:?}", stream.unopened()); assert!(stream.wait_for("Boot: complete", Duration::from_secs(5))); assert_eq!(stream.turned_away(), 1, "the one dial before the machine answered"); @@ -1457,16 +1457,16 @@ mod tests { let stream = Stream::connect(Peer::At(at), &dir.join("s.log"), false, Duration::from_secs(5)) .expect("a loopback reader"); let (mut conn, _) = server.accept().unwrap(); - writeln!(conn, "[kernel 1.216 cpu0] Boot: complete (1216ms)").unwrap(); + writeln!(conn, "[ 1.216 cpu0 kernel] Boot: complete (1216ms)").unwrap(); stream.wait_connected(Duration::from_secs(5)).expect("the peer"); assert!(stream.wait_for("Boot: complete", Duration::from_secs(5)), "the first line was not read"); assert!(!stream.wait_ended(Duration::ZERO), "a quiet peer was read as a closed one"); - writeln!(conn, "[kernel 1.217 cpu0] supervisor: started logkeeper").unwrap(); + writeln!(conn, "[ 1.217 cpu0 kernel] supervisor: started logkeeper").unwrap(); drop(conn); assert!(stream.wait_ended(Duration::from_secs(5))); assert_eq!( stream.lines(), - vec!["[kernel 1.216 cpu0] Boot: complete (1216ms)\n", "[kernel 1.217 cpu0] supervisor: started logkeeper\n"] + vec!["[ 1.216 cpu0 kernel] Boot: complete (1216ms)\n", "[ 1.217 cpu0 kernel] supervisor: started logkeeper\n"] ); } @@ -1476,10 +1476,10 @@ mod tests { #[test] fn the_hand_back_waits_for_the_boot_record_the_judge_reads() { const STALLED_AT: [&str; 2] = [ - "[2026-09-29 14:01:34 0.493 cpu0] xHCI: mass storage iface=0 in=0x81/512 out=0x2/512", - "[2026-09-29 14:01:34 0.493 cpu0] xHCI: configuration set", + "[2026-09-29 14:01:34 0.493 cpu0 kernel] xHCI: mass storage iface=0 in=0x81/512 out=0x2/512", + "[2026-09-29 14:01:34 0.493 cpu0 kernel] xHCI: configuration set", ]; - const RECORD: &str = "[2026-09-29 14:01:35 1.166 cpu0] Boot: complete (1166ms)"; + const RECORD: &str = "[2026-09-29 14:01:35 1.166 cpu0 kernel] Boot: complete (1166ms)"; let dir = toyos_tmpdir::TempDir::new("metaltalk-carried"); let server = TcpListener::bind("127.0.0.1:0").unwrap(); let at = server.local_addr().unwrap(); @@ -1536,19 +1536,19 @@ mod tests { let stream = Stream::connect(Peer::At(at), &dir.join("s.log"), false, Duration::from_secs(5)) .expect("a loopback reader"); let mut first = accepted(&server, "the first dial"); - writeln!(first, "[kernel 0.001 cpu0] before the swap").unwrap(); + writeln!(first, "[ 0.001 cpu0 kernel] before the swap").unwrap(); assert!(stream.wait_for("before the swap", Duration::from_secs(5))); stream.redial(Duration::from_secs(5)); close(accepted(&server, "the redial")); let mut third = accepted(&server, "the dial after a connection turned away"); - writeln!(third, "[kernel 0.001 cpu0] before the swap").unwrap(); - writeln!(third, "[kernel 9.000 cpu0] after the swap").unwrap(); + writeln!(third, "[ 0.001 cpu0 kernel] before the swap").unwrap(); + writeln!(third, "[ 9.000 cpu0 kernel] after the swap").unwrap(); assert!(stream.wait_for("after the swap", Duration::from_secs(5))); assert_eq!(stream.connections(), 2, "the connection turned away was counted as admitted"); assert_eq!(stream.turned_away(), 1, "the connection closed before a line"); assert_eq!( stream.lines(), - vec!["[kernel 0.001 cpu0] before the swap\n", "[kernel 9.000 cpu0] after the swap\n"] + vec!["[ 0.001 cpu0 kernel] before the swap\n", "[ 9.000 cpu0 kernel] after the swap\n"] ); let mut rest = [0u8; 1]; assert_eq!( @@ -1598,7 +1598,7 @@ mod tests { let stream = Stream::through(reach, peer, &dir.join("s.log"), false, Duration::from_secs(5)).expect("a loopback reader"); let mut first = accepted(server, "the first dial"); - writeln!(first, "[kernel 0.001 cpu0] before the swap").unwrap(); + writeln!(first, "[ 0.001 cpu0 kernel] before the swap").unwrap(); assert!(stream.wait_for("before the swap", Duration::from_secs(5))); (stream, first) } @@ -1613,8 +1613,8 @@ mod tests { close(server.accept().unwrap().0); } let (mut conn, _) = server.accept().unwrap(); - writeln!(conn, "[kernel 0.001 cpu0] before the swap").unwrap(); - writeln!(conn, "[kernel 9.000 cpu0] after the swap").unwrap(); + writeln!(conn, "[ 0.001 cpu0 kernel] before the swap").unwrap(); + writeln!(conn, "[ 9.000 cpu0 kernel] after the swap").unwrap(); }); } diff --git a/tests/checks.rs b/tests/checks.rs index 1713391032b..319d1e8aaba 100644 --- a/tests/checks.rs +++ b/tests/checks.rs @@ -92,7 +92,7 @@ mod checks { } else if line.contains(\"KERNEL PANIC\") {\n\ if line.starts_with(\"SEGFAULT\") {\n\ // ends on `PANIC:` and nothing else, which is the defect\n\ - const KERNEL: &str = \"[kernel 1.450 cpu3] PANIC: panicked at reserve.rs:812:9:\";\n"; + const KERNEL: &str = \"[ 1.450 cpu3 kernel] PANIC: panicked at reserve.rs:812:9:\";\n"; let named = hand_rolled_deaths(staged); if named.len() != 2 { return Err(format!( @@ -289,19 +289,19 @@ mod checks { /// words, which nothing links this crate to. #[test] fn nested_nmi_verdict() -> Result<(), String> { - const WHOLE: &str = "[kernel 0.385 cpu1] CPU 1: jo\n\ + const WHOLE: &str = "[ 0.385 cpu1 kernel] CPU 1: jo\n\ [nmi] NESTED NMI on cpu 0: a second NMI entered while IST2 was still in use.\n\ [nmi] rip=0xffffffff8012d3a0 rsp=0xffff80000017df50\n\ [nmi] the outer handler's frame is gone; the machine stops here.\n\ ining scheduler\n\ - [kernel 0.390 cpu0] panic: rebooting in 60 s, timed by the calibrated clock\n"; + [ 0.390 cpu0 kernel] panic: rebooting in 60 s, timed by the calibrated clock\n"; const SPLICED: &str = "[[kenrnmel i0.38]5 cpNu1E] CSPUT 1E: Djo inNiMngI s choednule r\n\ c[pkeurn el0 0:.3 85a cp u1s] sechcedo: ncpud=1 rNeaMdyI=0 deyinngt=0e srtoeppded= 0 wpahrkield=0e c urrIentS=NTon2e trwipas=s1\n \ stil[lke rnieln 0 .3u87s cep.u1\n\ ] [i8n04m2:i ar]me d a t r37i2mps,= i0dlex fatf 38f7mfs,8 0 0in0te0r7rubpt3s 9\u{2014} 1th6e cp5in hras snevper= as0sxerftefd f(kbfd 8GSI0 10, a0ux0 G0SI 612)0\n\ df50\n\ [nmi] the outer handler's frame is gone; the machine stops here.\n\ - [kernel 0.390 cpu0] panic: rebooting in 60 s unless a key is pressed\n"; + [ 0.390 cpu0 kernel] panic: rebooting in 60 s unless a key is pressed\n"; if faults::report(WHOLE)? != WHOLE.lines().nth(1).unwrap_or_default() { return Err("a whole report's first line was not the one answered".into()); } @@ -315,7 +315,7 @@ mod checks { let lines: Vec<&str> = WHOLE.lines().collect(); for at in 1..=3 { let (head, tail) = lines[at].split_at(lines[at].len() / 2); - let cut = format!("{head}[kernel 0.386 cp{tail}"); + let cut = format!("{head}[ 0.386 cpu1 ker{tail}"); let mut spliced = lines.clone(); spliced[at] = &cut; if faults::report(&spliced.join("\n")).is_ok() { @@ -349,7 +349,7 @@ mod checks { cpus.iter() .enumerate() .map(|(i, (cr0, cr4))| { - format!("[kernel 0.1 cpu{i}] control_regs: cpu{i} cr0={cr0:#010x} cr4={cr4:#010x}\n") + format!("[ 0.100 cpu{i} kernel] control_regs: cpu{i} cr0={cr0:#010x} cr4={cr4:#010x}\n") }) .collect() } @@ -412,17 +412,17 @@ mod checks { use common::irqcensus::{windows_under, Measured}; let census = |cpu: u32| { format!( - "[kernel 0.1 cpu0] irq: cpu{cpu} timer=0 kick=0 xhci=0 userdev=0 sound=0 i8042=0 \ + "[ 0.100 cpu0 kernel] irq: cpu{cpu} timer=0 kick=0 xhci=0 userdev=0 sound=0 i8042=0 \ dmafault=0 hda=0 tlb=0 nmi=0 spurious=0 unclaimed=0\n" ) }; let windows = |cpu: u32, (irqs, preempt): (u64, u64)| { - format!("[kernel 0.1 cpu0] windows: cpu{cpu} irqs_off_ns={irqs} preempt_off_ns={preempt}\n") + format!("[ 0.100 cpu0 kernel] windows: cpu{cpu} irqs_off_ns={irqs} preempt_off_ns={preempt}\n") }; let report = |cpu0: (u64, u64), cpu1: (u64, u64)| [census(0), windows(0, cpu0), census(1), windows(1, cpu1)].concat(); - let exit = |name: &str| format!("[kernel 0.1 cpu0] exit: {name} pid=9 code=0 cpu=1ms\n"); + let exit = |name: &str| format!("[ 0.100 cpu0 kernel] exit: {name} pid=9 code=0 cpu=1ms\n"); let held_ns = kernel::sched::windows::HELD_NS; - let hold = format!("[kernel 0.1 cpu1] windows: held cpu1 ns={}\n", held_ns + 7); + let hold = format!("[ 0.100 cpu1 kernel] windows: held cpu1 ns={}\n", held_ns + 7); // Since each CPU joined: longer on cpu0 than anything under the load. let first = [report((6_500_000, 6_400_000), (900, 800)), exit("test_rs_idle_span")].concat(); let read_back = (held_ns + 400, held_ns + 300); @@ -456,7 +456,7 @@ mod checks { refused("a load that never ended", &good.replace(&exit(WINDOWS_LOAD), ""), "never ended")?; refused("no hold", &good.replace(&hold, ""), "held no window of known length")?; refused("a second hold", &[hold.as_str(), &good].concat(), "a second hold")?; - refused("a hold cut short", &good.replace(&hold, "[kernel 0.1 cpu1] windows: held cpu1 ns=1000\n"), "the kernel owes")?; + refused("a hold cut short", &good.replace(&hold, "[ 0.100 cpu1 kernel] windows: held cpu1 ns=1000\n"), "the kernel owes")?; refused( "an interrupts-off window read back at half", &good.replace(&windows(1, read_back), &windows(1, (read_back.0 / 2, read_back.1))), @@ -857,6 +857,11 @@ mod checks { metal_checks::a_cleared_page_owes_no_panel(); } + #[test] + fn metal_loader_kernel_and_program_count_from_one_zero() { + metal_checks::the_loader_the_kernel_and_a_program_count_from_one_zero(); + } + #[test] fn metal_list_from_parse_reaches_run_without_the_machine() -> Result<(), String> { let args: Vec = ["--metal", "--list"].iter().map(ToString::to_string).collect(); @@ -911,13 +916,13 @@ mod checks { bootlog::SEPARATOR ) }; - let rebooted = "| log-tail: [1.516 cpu0] Rebooting.\n"; - let stopped = "| log-tail: [1.209 cpu0] stop: 13 of 13 userland thread(s) stopped across 8 \ + let rebooted = "| log-tail: [ 1.516 cpu0 kernel] Rebooting.\n"; + let stopped = "| log-tail: [ 1.209 cpu0 kernel] stop: 13 of 13 userland thread(s) stopped across 8 \ cpu(s) in 0 ms of a 2010 ms budget over 1 sweep(s), 0 of 38 userland block \ operation(s) still open\n"; let jobcase = - "[2026-09-29 10:40:36 0.000 cpu0 boot] ACPI: reset register SystemIO 0xcf9 <- 0x06\n"; + "[2026-09-29 10:40:36 0.000 cpu0 kernel] ACPI: reset register SystemIO 0xcf9 <- 0x06\n"; let judge = metal_judge("machine_reboot"); assert_eq!(judge(&[&readback("jobcase", &done(rebooted), jobcase)]), Ok(())); assert!(judge(&[&readback("jobcase", &done(stopped), jobcase)]).is_err()); @@ -935,12 +940,12 @@ mod checks { bootlog::SEPARATOR ) }; - let kernel = "[2026-09-29 10:33:28 0.000 cpu0 boot] panic console: armed 1920x1080 \ + let kernel = "[2026-09-29 10:33:28 0.000 cpu0 kernel] panic console: armed 1920x1080 \ stride=1920 format=1 at 0x4000000000, write-combining\n"; - let staged = "| [1.509 cpu1] wedge: staged, and only the boot deadline ends this machine: \ + let staged = "| [ 1.509 cpu1 kernel] wedge: staged, and only the boot deadline ends this machine: \ every CPU stops taking scheduler passes from here\n"; - let awake = |cpu: u32| format!("| [1.509 cpu{cpu}] wedge: cpu{cpu} arrived with interrupts on\n"); - let deaf = "| [1.509 cpu1] wedge: cpu1 arrived with interrupts off, through the syscall \ + let awake = |cpu: u32| format!("| [ 1.509 cpu{cpu} kernel] wedge: cpu{cpu} arrived with interrupts on\n"); + let deaf = "| [ 1.509 cpu1 kernel] wedge: cpu1 arrived with interrupts off, through the syscall \ gate, and takes them again here\n"; let judge = metal_judge("boot_deadline_ends_a_wedge"); // The seal's line for each CPU, cpu1's being `staging`. @@ -967,7 +972,7 @@ mod checks { let unnamed = format!("{staged}{}{}| cpu0 pc=0xffff80006051b0b2 {spin}\n", awake(1), awake(0)); assert!(judge(&[&readback("deadlinewedge", &wedged(&unnamed), kernel)]).is_err()); - let sweep = "| [1.526 cpu0] usb-load: sweeping disk 0 from block 6569336 to 7507812, \ + let sweep = "| [ 1.526 cpu0 kernel] usb-load: sweeping disk 0 from block 6569336 to 7507812, \ rewriting each run with the bytes just read from it, until this machine is \ reset out from under it\n"; let judge = metal_judge("usb_reset_records_the_phase_it_cut"); @@ -991,7 +996,7 @@ mod checks { bootlog::SEPARATOR, bootlog::HUNG_WITHOUT_A_RECORD ); - let kernel = "[2026-09-29 13:13:43 1.171 cpu0] Boot: complete (1171ms)\n"; + let kernel = "[2026-09-29 13:13:43 1.171 cpu0 kernel] Boot: complete (1171ms)\n"; let judge = metal_judge("blackbox_foreign_record"); assert_eq!(judge(&[&readback("foreignrecord", &loader, kernel)]), Ok(())); for state in ["PANIC", "WEDGED"] { @@ -1010,13 +1015,13 @@ mod checks { /// firmware never claimed it. The T14 has two, and each is judged. #[test] fn the_xecp_judge_reads_the_t14s_handoff() { - let t14 = "[2026-09-29 11:05:25 0.253 cpu0] xHCI: xecp selftest 8/8 malformed lists refused\n\ - [2026-09-29 11:05:25 0.253 cpu0] xHCI: firmware did not claim the controller \ + let t14 = "[2026-09-29 11:05:25 0.253 cpu0 kernel] xHCI: xecp selftest 8/8 malformed lists refused\n\ + [2026-09-29 11:05:25 0.253 cpu0 kernel] xHCI: firmware did not claim the controller \ (USBLEGSUP 0x01002201)\n\ - [2026-09-29 11:05:25 0.253 cpu0] xHCI: USBLEGCTLSTS 0xe0000000 -> 0x00000000 \ + [2026-09-29 11:05:25 0.253 cpu0 kernel] xHCI: USBLEGCTLSTS 0xe0000000 -> 0x00000000 \ (SMI generation off)\n\ - [2026-09-29 11:05:25 0.253 cpu0] xHCI: controller reset\n\ - [2026-09-29 11:05:25 0.254 cpu0] xHCI: controller started\n"; + [2026-09-29 11:05:25 0.253 cpu0 kernel] xHCI: controller reset\n\ + [2026-09-29 11:05:25 0.254 cpu0 kernel] xHCI: controller started\n"; assert_eq!(xhci_xecp(t14), Ok(())); assert_eq!(xhci_xecp(&format!("{t14}{t14}")), Ok(())); // Firmware that kept the controller handed nothing over. diff --git a/tests/checks/audio.rs b/tests/checks/audio.rs index f1f504b1224..e9b816f2529 100644 --- a/tests/checks/audio.rs +++ b/tests/checks/audio.rs @@ -12,25 +12,25 @@ pub fn judges_verdict() -> Result<(), String> { }; let stats = |underruns: u32, clients: u32, deferred: u32| { format!( - "{{2.000 soundserver}} soundserver: wakes=9 completions=9 submitted=9 underruns={underruns} \ + "[ 2.000 soundserver] soundserver: wakes=9 completions=9 submitted=9 underruns={underruns} \ drains=0 max_wake_lat_us=9 max_batch=1 clients={clients} deferred={deferred} \ starve_max=0 worst_irq_late_us=0 worst_pickup_us=0 worst_empty=0 worst_batch=1 \ late_wakes=0\n" ) }; - let spawn = |job: &str| format!("[kernel 1.000 cpu0] spawn: /system/bin/{job} pid=7\n"); + let spawn = |job: &str| format!("[ 1.000 cpu0 kernel] spawn: /system/bin/{job} pid=7\n"); // One stream through soundserver: `playing` is the stats line while it plays, // and `ended` the flush once it has left. let session = |playing: String, how: &str, ended: String| { format!( - "{{1.000 soundserver}} soundserver: client 0 connected (id=1)\n{{1.000 soundserver}} soundserver: \ - resumed\n{playing}{{3.000 soundserver}} soundserver: client 1 removed ({how})\n{ended}\ - {{3.000 soundserver}} soundserver: suspended\n" + "[ 1.000 soundserver] soundserver: client 0 connected (id=1)\n[ 1.000 soundserver] soundserver: \ + resumed\n{playing}[ 3.000 soundserver] soundserver: client 1 removed ({how})\n{ended}\ + [ 3.000 soundserver] soundserver: suspended\n" ) }; let next = spawn("test_rs_next"); - let configured = "{0.500 soundserver} soundserver: hda path configured in 3 ms\n"; + let configured = "[ 0.500 soundserver] soundserver: hda path configured in 3 ms\n"; let tone = |ended: String| { format!("{configured}{}{}", spawn("test_rs_audio_tone"), session(stats(0, 1, 0), "closed", ended)) }; @@ -45,7 +45,7 @@ pub fn judges_verdict() -> Result<(), String> { judged( "a tone on the null sink", tone_on_metal, - &format!("{}{{0.600 soundserver}} {NULL_SINK}\n{next}", tone(stats(0, 0, 0))), + &format!("{}[ 0.600 soundserver] {NULL_SINK}\n{next}", tone(stats(0, 0, 0))), false, )?; // The next job's stream connected before soundserver let the tone's go, so the @@ -54,10 +54,10 @@ pub fn judges_verdict() -> Result<(), String> { "a tone another job's stream joined", tone_on_metal, &format!( - "{configured}{}{{1.000 soundserver}} soundserver: client 0 connected (id=1)\n{}{next}\ - {{3.000 soundserver}} soundserver: client 1 connected (id=2)\n\ - {{3.000 soundserver}} soundserver: client 1 removed (closed)\n{}\ - {{4.000 soundserver}} soundserver: client 2 removed (closed)\n{}", + "{configured}{}[ 1.000 soundserver] soundserver: client 0 connected (id=1)\n{}{next}\ + [ 3.000 soundserver] soundserver: client 1 connected (id=2)\n\ + [ 3.000 soundserver] soundserver: client 1 removed (closed)\n{}\ + [ 4.000 soundserver] soundserver: client 2 removed (closed)\n{}", spawn("test_rs_audio_tone"), stats(0, 1, 0), stats(0, 1, 0), @@ -69,7 +69,7 @@ pub fn judges_verdict() -> Result<(), String> { "a tone whose window ended before its stream connected", tone_on_metal, &format!( - "{configured}{}{{0.900 soundserver}} soundserver: client 0 removed (closed)\n{}{}{next}", + "{configured}{}[ 0.900 soundserver] soundserver: client 0 removed (closed)\n{}{}{next}", spawn("test_rs_audio_tone"), stats(0, 0, 0), session(stats(0, 1, 0), "closed", stats(0, 0, 0)) @@ -82,10 +82,10 @@ pub fn judges_verdict() -> Result<(), String> { "a tone beside a stream soundserver held at its spawn", tone_on_metal, &format!( - "{configured}{{0.900 soundserver}} soundserver: client 0 connected (id=0)\n{}\ - {{1.000 soundserver}} soundserver: client 1 connected (id=1)\n{}\ - {{2.500 soundserver}} soundserver: client 0 removed (closed)\n\ - {{3.000 soundserver}} soundserver: client 1 removed (closed)\n{}{next}", + "{configured}[ 0.900 soundserver] soundserver: client 0 connected (id=0)\n{}\ + [ 1.000 soundserver] soundserver: client 1 connected (id=1)\n{}\ + [ 2.500 soundserver] soundserver: client 0 removed (closed)\n\ + [ 3.000 soundserver] soundserver: client 1 removed (closed)\n{}{next}", spawn("test_rs_audio_tone"), stats(0, 2, 0), stats(0, 0, 0), @@ -115,7 +115,7 @@ pub fn judges_verdict() -> Result<(), String> { false, )?; // The next job spawned ahead of soundserver's last word on the second stream. - let (playing, tail) = second.split_at(second.find("{3.000 soundserver} soundserver: client 1 removed").expect("staged")); + let (playing, tail) = second.split_at(second.find("[ 3.000 soundserver] soundserver: client 1 removed").expect("staged")); judged( "a stalled client soundserver deferred for after the next job began", client_stall_on_metal, @@ -125,7 +125,7 @@ pub fn judges_verdict() -> Result<(), String> { judged( "a stalled client over a repeated completion", client_stall_on_metal, - &stall(second.clone(), &format!("{{2.500 soundserver}} soundserver: repeated completion for free buffer\n{next}")), + &stall(second.clone(), &format!("[ 2.500 soundserver] soundserver: repeated completion for free buffer\n{next}")), false, )?; judged("the T14's stalled client", client_stall_on_metal, T14_STALL, true)?; @@ -133,8 +133,8 @@ pub fn judges_verdict() -> Result<(), String> { "the T14's stalled client, its second stream opened on a running soundserver", client_stall_on_metal, &T14_STALL - .replace("{2026-10-03 07:05:06 7.865 soundserver} soundserver: suspended\n", "") - .replace("{2026-10-03 07:05:07 8.143 soundserver} soundserver: resumed\n", ""), + .replace("[2026-10-03 07:05:06 7.865 soundserver] soundserver: suspended\n", "") + .replace("[2026-10-03 07:05:07 8.143 soundserver] soundserver: resumed\n", ""), false, )?; @@ -152,8 +152,8 @@ pub fn judges_verdict() -> Result<(), String> { "a death soundserver claimed beside a departure it established", departures_on_metal, &departures("closed").replacen( - "{3.000 soundserver} soundserver: client 1 removed", - "{3.000 soundserver} soundserver: client 1 died\n{3.000 soundserver} soundserver: client 1 removed", + "[ 3.000 soundserver] soundserver: client 1 removed", + "[ 3.000 soundserver] soundserver: client 1 died\n[ 3.000 soundserver] soundserver: client 1 removed", 1, ), false, @@ -161,7 +161,7 @@ pub fn judges_verdict() -> Result<(), String> { judged( "a departure soundserver never reported", departures_on_metal, - &departures("closed").replacen("{3.000 soundserver} soundserver: client 1 removed (closed)\n", "", 1), + &departures("closed").replacen("[ 3.000 soundserver] soundserver: client 1 removed (closed)\n", "", 1), false, )?; judged( @@ -176,11 +176,11 @@ pub fn judges_verdict() -> Result<(), String> { )?; let idle = |said: &str| format!("{}{said}{next}", spawn("test_rs_audio_idle_suspend")); - judged("an idle soundserver", idle_suspend_on_metal, &idle("{1.000 soundserver} soundserver: suspended\n"), true)?; + judged("an idle soundserver", idle_suspend_on_metal, &idle("[ 1.000 soundserver] soundserver: suspended\n"), true)?; judged( "an idle soundserver that started the device", idle_suspend_on_metal, - &idle(&format!("{{1.000 soundserver}} {DEVICE_STARTED}\n")), + &idle(&format!("[ 1.000 soundserver] {DEVICE_STARTED}\n")), false, )?; @@ -188,14 +188,14 @@ pub fn judges_verdict() -> Result<(), String> { // both others in `/log`, and five counted unwritten. let stalled = |held: u32, unwritten: u32, refusals: usize| { format!( - "{{1.000 test_rs_soundserver_log_stall}} flooded soundserver with 10 refusals\n\ - {{1.000 test_rs_soundserver_log_stall}} soundserver refused 1 probe\n\ - {}{{1.100 soundserver}} soundserver: protocol violation (msg 7)\n\ - {{1.200 soundserver}} soundserver: opening stream: 48000 Hz\n\ - {{2.000 logkeeper}} logkeeper: reading soundserver again, as `--stall-until` asked, with {held} of \ + "[ 1.000 test_rs_soundserver_log_stall] flooded soundserver with 10 refusals\n\ + [ 1.000 test_rs_soundserver_log_stall] soundserver refused 1 probe\n\ + {}[ 1.100 soundserver] soundserver: protocol violation (msg 7)\n\ + [ 1.200 soundserver] soundserver: opening stream: 48000 Hz\n\ + [ 2.000 logkeeper] logkeeper: reading soundserver again, as `--stall-until` asked, with {held} of \ its ring's 64 slots waiting\n\ - {{2.100 logkeeper}} logkeeper: {unwritten} record(s) of soundserver's found its ring full\n", - "{1.050 soundserver} soundserver: refusing connection, too many\n".repeat(refusals) + [ 2.100 logkeeper] logkeeper: {unwritten} record(s) of soundserver's found its ring full\n", + "[ 1.050 soundserver] soundserver: refusing connection, too many\n".repeat(refusals) ) }; judged("the stalled log", log_stall_on_metal, &stalled(64, 5, 6), true)?; @@ -208,25 +208,25 @@ pub fn judges_verdict() -> Result<(), String> { /// The T14's `testcases` boot, verbatim: the tone's last records, and the /// stalled client's from its spawn to its exit. Its first stream opens 3 ms /// after the tone's left, on a soundserver that has not suspended. -const T14_STALL: &str = r"{2026-10-03 07:05:04 5.681 soundserver} soundserver: client 0 removed (closed) -{2026-10-03 07:05:04 5.681 soundserver} soundserver: wakes=573 completions=415 submitted=415 underruns=0 drains=0 max_wake_lat_us=2307 max_batch=2 clients=0 deferred=0 starve_max=0 worst_irq_late_us=2288 worst_pickup_us=18 worst_empty=0 worst_batch=2 late_wakes=0 -[2026-10-03 07:05:04 5.682 cpu4] exit: test_rs_audio_tone pid=11 code=0 cpu=2ms -[2026-10-03 07:05:04 5.683 cpu7] spawn: /system/bin/test_rs_hda_client_stall pid=12 tid=0 dst=6 base=0x10000000000 entry=0x1000003df40 root=0x83d6000 symbols=2048KiB (layout=0ms relocs=0ms deps=0ms tls=0ms total=1ms) -{2026-10-03 07:05:04 5.684 tid=1 soundserver} soundserver: opening stream: 44100Hz 2ch fmt=0 -{2026-10-03 07:05:04 5.684 soundserver} soundserver: client 0 connected (id=1) -{2026-10-03 07:05:06 7.685 soundserver} soundserver: wakes=842 completions=690 submitted=690 underruns=104 drains=0 max_wake_lat_us=1746 max_batch=2 clients=1 deferred=0 starve_max=13 worst_irq_late_us=1724 worst_pickup_us=22 worst_empty=0 worst_batch=2 late_wakes=0 -{2026-10-03 07:05:06 7.842 soundserver} soundserver: client 1 removed (closed) -{2026-10-03 07:05:06 7.842 soundserver} soundserver: wakes=85 completions=54 submitted=54 underruns=0 drains=0 max_wake_lat_us=70 max_batch=1 clients=0 deferred=0 starve_max=0 worst_irq_late_us=17 worst_pickup_us=53 worst_empty=1 worst_batch=1 late_wakes=0 -[2026-10-03 07:05:06 7.842 cpu7 tid=1] exit: test_rs_hda_client_stall tid=1 code=0 cpu=15ms -{2026-10-03 07:05:06 7.865 soundserver} soundserver: suspended -{2026-10-03 07:05:07 8.142 tid=1 soundserver} soundserver: opening stream: 44100Hz 2ch fmt=0 -{2026-10-03 07:05:07 8.142 soundserver} soundserver: client 0 connected (id=2) -{2026-10-03 07:05:07 8.143 soundserver} soundserver: resumed -{2026-10-03 07:05:08 9.051 soundserver} soundserver: client 2 removed (closed) -{2026-10-03 07:05:08 9.051 soundserver} soundserver: wakes=425 completions=313 submitted=321 underruns=26 drains=0 max_wake_lat_us=88 max_batch=1 clients=0 deferred=0 starve_max=13 worst_irq_late_us=53 worst_pickup_us=34 worst_empty=1 worst_batch=1 late_wakes=0 -[2026-10-03 07:05:08 9.051 cpu0 tid=2] exit: test_rs_hda_client_stall tid=2 code=0 cpu=3ms -{2026-10-03 07:05:08 9.079 soundserver} soundserver: suspended -{2026-10-03 07:05:08 9.079 soundserver} soundserver: idle wake 1 (1 records) -{2026-10-03 07:05:08 9.351 pid=12 test-runner} stalled 8 then 2 times, soundserver survived -[2026-10-03 07:05:08 9.352 cpu6] exit: test_rs_hda_client_stall pid=12 code=0 cpu=2ms +const T14_STALL: &str = r"[2026-10-03 07:05:04 5.681 soundserver] soundserver: client 0 removed (closed) +[2026-10-03 07:05:04 5.681 soundserver] soundserver: wakes=573 completions=415 submitted=415 underruns=0 drains=0 max_wake_lat_us=2307 max_batch=2 clients=0 deferred=0 starve_max=0 worst_irq_late_us=2288 worst_pickup_us=18 worst_empty=0 worst_batch=2 late_wakes=0 +[2026-10-03 07:05:04 5.682 cpu4 kernel] exit: test_rs_audio_tone pid=11 code=0 cpu=2ms +[2026-10-03 07:05:04 5.683 cpu7 kernel] spawn: /system/bin/test_rs_hda_client_stall pid=12 tid=0 dst=6 base=0x10000000000 entry=0x1000003df40 root=0x83d6000 symbols=2048KiB (layout=0ms relocs=0ms deps=0ms tls=0ms total=1ms) +[2026-10-03 07:05:04 5.684 soundserver tid=1] soundserver: opening stream: 44100Hz 2ch fmt=0 +[2026-10-03 07:05:04 5.684 soundserver] soundserver: client 0 connected (id=1) +[2026-10-03 07:05:06 7.685 soundserver] soundserver: wakes=842 completions=690 submitted=690 underruns=104 drains=0 max_wake_lat_us=1746 max_batch=2 clients=1 deferred=0 starve_max=13 worst_irq_late_us=1724 worst_pickup_us=22 worst_empty=0 worst_batch=2 late_wakes=0 +[2026-10-03 07:05:06 7.842 soundserver] soundserver: client 1 removed (closed) +[2026-10-03 07:05:06 7.842 soundserver] soundserver: wakes=85 completions=54 submitted=54 underruns=0 drains=0 max_wake_lat_us=70 max_batch=1 clients=0 deferred=0 starve_max=0 worst_irq_late_us=17 worst_pickup_us=53 worst_empty=1 worst_batch=1 late_wakes=0 +[2026-10-03 07:05:06 7.842 cpu7 kernel tid=1] exit: test_rs_hda_client_stall tid=1 code=0 cpu=15ms +[2026-10-03 07:05:06 7.865 soundserver] soundserver: suspended +[2026-10-03 07:05:07 8.142 soundserver tid=1] soundserver: opening stream: 44100Hz 2ch fmt=0 +[2026-10-03 07:05:07 8.142 soundserver] soundserver: client 0 connected (id=2) +[2026-10-03 07:05:07 8.143 soundserver] soundserver: resumed +[2026-10-03 07:05:08 9.051 soundserver] soundserver: client 2 removed (closed) +[2026-10-03 07:05:08 9.051 soundserver] soundserver: wakes=425 completions=313 submitted=321 underruns=26 drains=0 max_wake_lat_us=88 max_batch=1 clients=0 deferred=0 starve_max=13 worst_irq_late_us=53 worst_pickup_us=34 worst_empty=1 worst_batch=1 late_wakes=0 +[2026-10-03 07:05:08 9.051 cpu0 kernel tid=2] exit: test_rs_hda_client_stall tid=2 code=0 cpu=3ms +[2026-10-03 07:05:08 9.079 soundserver] soundserver: suspended +[2026-10-03 07:05:08 9.079 soundserver] soundserver: idle wake 1 (1 records) +[2026-10-03 07:05:08 9.351 test-runner pid=12] stalled 8 then 2 times, soundserver survived +[2026-10-03 07:05:08 9.352 cpu6 kernel] exit: test_rs_hda_client_stall pid=12 code=0 cpu=2ms "; diff --git a/tests/checks/claims.rs b/tests/checks/claims.rs index 040be76be02..999c9983cf5 100644 --- a/tests/checks/claims.rs +++ b/tests/checks/claims.rs @@ -8,18 +8,18 @@ use super::*; /// The T14's records of one boot, verbatim but for the readback's `stream|` /// prefix: the I219 enumerated, firmware's root-bridge windows, a domain, and /// the I219 claimed, released and claimed again. -const RECORDED: &str = r"[2026-09-29 11:54:39 0.065 cpu0] PCI 00:1f.6 [0200] vendor=8086 device=15fc prog_if=00 bars=[bar0=0xbcf00000] -[2026-09-29 11:54:39 0.149 cpu0] pcidev: firmware declared root bridge memory: mem 0xa2000000..0xbd000000, mem 0x4000000000..0x603dc00000, mem 0xa0800000..0xa2000000, mem 0xbd000000..0xc0000000, mem 0xff000000..0xffb80000, mem 0xffd3a070..0x100000000, mem 0x603dc00000..0x8000000000 -[2026-09-29 11:54:39 0.250 cpu0] iommu: domain2 root=0xa31000 aw=48 mgaw=39 addresses from 0x2000000000 to 0x8000000000 -[2026-09-29 12:10:34 1.191 cpu0] iommu: irte5 source=00:1f.6 p=1 sid=0x00fe svt=1 sq=0 vector=0x28 apic=0x0 dst=0x0 trigger=edge -[2026-09-29 12:10:34 1.192 cpu0] pcidev: PCI 00:1f.6 [8086:15fc] handed over on slot 0, vector 0x28 -[2026-09-29 12:10:53 20.233 cpu1] pcidev: PCI 00:1f.6 [8086:15fc] released from slot 0; reset by nothing (Express: no capability; AF: no capability; PM: No_Soft_Reset set), so where it may still be aimed is kept for its next claim -[2026-09-29 12:10:53 20.238 cpu0] iommu: irte6 source=00:1f.6 p=1 sid=0x00fe svt=1 sq=0 vector=0x28 apic=0x0 dst=0x0 trigger=edge -[2026-09-29 12:10:53 20.239 cpu0] pcidev: PCI 00:1f.6 [8086:15fc] handed over on slot 0, vector 0x28 +const RECORDED: &str = r"[2026-09-29 11:54:39 0.065 cpu0 kernel] PCI 00:1f.6 [0200] vendor=8086 device=15fc prog_if=00 bars=[bar0=0xbcf00000] +[2026-09-29 11:54:39 0.149 cpu0 kernel] pcidev: firmware declared root bridge memory: mem 0xa2000000..0xbd000000, mem 0x4000000000..0x603dc00000, mem 0xa0800000..0xa2000000, mem 0xbd000000..0xc0000000, mem 0xff000000..0xffb80000, mem 0xffd3a070..0x100000000, mem 0x603dc00000..0x8000000000 +[2026-09-29 11:54:39 0.250 cpu0 kernel] iommu: domain2 root=0xa31000 aw=48 mgaw=39 addresses from 0x2000000000 to 0x8000000000 +[2026-09-29 12:10:34 1.191 cpu0 kernel] iommu: irte5 source=00:1f.6 p=1 sid=0x00fe svt=1 sq=0 vector=0x28 apic=0x0 dst=0x0 trigger=edge +[2026-09-29 12:10:34 1.192 cpu0 kernel] pcidev: PCI 00:1f.6 [8086:15fc] handed over on slot 0, vector 0x28 +[2026-09-29 12:10:53 20.233 cpu1 kernel] pcidev: PCI 00:1f.6 [8086:15fc] released from slot 0; reset by nothing (Express: no capability; AF: no capability; PM: No_Soft_Reset set), so where it may still be aimed is kept for its next claim +[2026-09-29 12:10:53 20.238 cpu0 kernel] iommu: irte6 source=00:1f.6 p=1 sid=0x00fe svt=1 sq=0 vector=0x28 apic=0x0 dst=0x0 trigger=edge +[2026-09-29 12:10:53 20.239 cpu0 kernel] pcidev: PCI 00:1f.6 [8086:15fc] handed over on slot 0, vector 0x28 "; /// The second release, which that boot never reached. -const RELEASED: &str = "[2026-09-29 12:10:55 22.000 cpu1] pcidev: PCI 00:1f.6 [8086:15fc] released from slot 0; reset by nothing\n"; +const RELEASED: &str = "[2026-09-29 12:10:55 22.000 cpu1 kernel] pcidev: PCI 00:1f.6 [8086:15fc] released from slot 0; reset by nothing\n"; fn log(text: &str) -> serial::Serial { serial::Serial::named("T14 log", text) @@ -28,7 +28,7 @@ fn log(text: &str) -> serial::Serial { /// One entry for both claims, not present after each release; the recorded /// second entry, and a release that leaves its entry present, red. pub fn one_entry_per_slot() { - let cleared = "[2026-09-29 12:10:53 20.234 cpu1] iommu: irte0 source=00:1f.6 p=0 released\n"; + let cleared = "[2026-09-29 12:10:53 20.234 cpu1 kernel] iommu: irte0 source=00:1f.6 p=0 released\n"; let green = format!("{RECORDED}{cleared}{RELEASED}{cleared}") .replace("irte5 ", "irte0 ") .replace("irte6 ", "irte0 "); diff --git a/tests/checks/lan.rs b/tests/checks/lan.rs index 80ada23391f..203a4f49ea9 100644 --- a/tests/checks/lan.rs +++ b/tests/checks/lan.rs @@ -7,13 +7,13 @@ use toyos_build::metal::{READBACK_BOOT, READBACK_STREAM, READBACK_TALK}; /// The T14's `lantalkcase` boot: the card's hand-over, what netstack said of its /// MAC, its link and its lease, and the supervisor's stop. The MAC and the two resolvers /// are stand-ins that name nobody; every other byte is the machine's. -const LOG: &str = r"[2026-10-03 10:20:01 1.192 cpu0] pcidev: PCI 00:1f.6 [8086:15fc] handed over on slot 0, vector 0x28 -{2026-10-03 10:20:05 5.727 netstack} netstack: MAC 02:00:00:00:00:01 -[2026-10-03 10:20:08 8.499 cpu4] pcidev: slot 0 took its first message on vector 0x28 -{2026-10-03 10:20:08 8.499 netstack} netstack: I219: link up at 1000 Mb/s full duplex, 2772 ms after the driver came up -{2026-10-03 10:20:19 19.053 netstack} netstack: DHCP: lease 192.168.1.48/24 from 192.168.1.1, gateway 192.168.1.1, dns [192.0.2.53 198.51.100.53], 13326 ms after netstack came up -{2026-10-03 10:20:19 19.053 netstack} netstack: ready, at most 103 piped connections (4 MiB each of 16022 MiB total) -{2026-10-03 10:20:20 20.249 supervisor} supervisor: power: the machine stops, and logkeeper makes the log whole first (Reboot) +const LOG: &str = r"[2026-10-03 10:20:01 1.192 cpu0 kernel] pcidev: PCI 00:1f.6 [8086:15fc] handed over on slot 0, vector 0x28 +[2026-10-03 10:20:05 5.727 netstack] netstack: MAC 02:00:00:00:00:01 +[2026-10-03 10:20:08 8.499 cpu4 kernel] pcidev: slot 0 took its first message on vector 0x28 +[2026-10-03 10:20:08 8.499 netstack] netstack: I219: link up at 1000 Mb/s full duplex, 2772 ms after the driver came up +[2026-10-03 10:20:19 19.053 netstack] netstack: DHCP: lease 192.168.1.48/24 from 192.168.1.1, gateway 192.168.1.1, dns [192.0.2.53 198.51.100.53], 13326 ms after netstack came up +[2026-10-03 10:20:19 19.053 netstack] netstack: ready, at most 103 piped connections (4 MiB each of 16022 MiB total) +[2026-10-03 10:20:20 20.249 supervisor] supervisor: power: the machine stops, and logkeeper makes the log whole first (Reboot) "; /// That boot's `boot.txt`, under the same stand-in. diff --git a/tests/checks/metal.rs b/tests/checks/metal.rs index 8ccfcf79fc9..2bbd38de727 100644 --- a/tests/checks/metal.rs +++ b/tests/checks/metal.rs @@ -10,7 +10,7 @@ use toyos_build::metal::{ use toyos_build::metaltimings::{Machine, Record}; const PANEL: &str = "| panel: paints=10 px=8741248 us=21751 max_us=3851\n"; -const BOOTED: &str = "[2026-09-29 18:22:39 1.165 cpu0] Boot: complete (1165ms)\n"; +const BOOTED: &str = "[2026-09-29 18:22:39 1.165 cpu0 kernel] Boot: complete (1165ms)\n"; fn t14() -> Machine { Machine { @@ -23,8 +23,9 @@ fn t14() -> Machine { /// A `loader.log` whose pass after the reset reads `page`. fn loader(page: &str) -> String { format!( - "{}\n{}\n{}\n{}\n{page}", + "{}\n{}\n{}\n{}\n{}\n{page}", bootlog::LOADER_FIRST_LINE, + bootlog::LOADER_CLOCK_NONE, bootlog::LOADER_LAST_LINE, bootlog::SEPARATOR, bootlog::LOADER_FIRST_LINE @@ -34,7 +35,7 @@ fn loader(page: &str) -> String { /// The record of arming the deadline, at the 60 ms the T14 arms it. fn armed() -> String { format!( - "[2026-09-29 18:22:39 0.060 cpu0] {}120000 ms, after which this kernel seals a WEDGED \ + "[2026-09-29 18:22:39 0.060 cpu0 kernel] {}120000 ms, after which this kernel seals a WEDGED \ record and writes the reset register itself\n{BOOTED}", bootlog::DEADLINE_ARMED ) @@ -48,6 +49,10 @@ fn expired_at(reached: i64) -> String { ) } +/// What every boot that reaches `Boot: complete` owes `one_clock`. +const STARTED: &str = "[2026-09-29 18:22:38 0.050 cpu0 kernel] spawn: /system/bin/logkeeper pid=6\n\ + [2026-09-29 18:22:38 0.050 supervisor] supervisor: started logkeeper\n"; + /// One boot's readback as the loop writes it. pub(super) fn plant( dir: &Path, @@ -64,7 +69,7 @@ pub(super) fn plant( ); for (name, text) in [ (READBACK_LOADER, loader(page)), - (READBACK_KERNEL, kernel.to_string()), + (READBACK_KERNEL, format!("{STARTED}{kernel}")), (READBACK_BOOT, boot), (READBACK_VERDICT, verdict_file(verdict)), ] { @@ -292,8 +297,8 @@ pub fn a_failing_shared_member_fails_its_boot() { let jobs = ["test_rs_std_tls", "test_rs_fs_large_file"]; let exits = |code: i32| { format!( - "{BOOTED}[2026-09-29 18:22:41 2.310 cpu3] exit: {} pid=12 code=0 cpu=4ms\n\ - [2026-09-29 18:22:42 3.120 cpu5] exit: {} pid=13 code={code} cpu=9ms\n", + "{BOOTED}[2026-09-29 18:22:41 2.310 cpu3 kernel] exit: {} pid=12 code=0 cpu=4ms\n\ + [2026-09-29 18:22:42 3.120 cpu5 kernel] exit: {} pid=13 code={code} cpu=9ms\n", jobs[0], jobs[1] ) }; @@ -360,3 +365,48 @@ pub fn a_cleared_page_owes_no_panel() { ); assert_eq!(judged(&cleared, &hung), (true, None)); } + +/// **The loader's lines, the kernel's records and a program's lines count +/// from one zero**: a kernel record stamped before the loader's handoff, or the +/// supervisor's line after a spawn before that spawn's record, is a clock that kept another +/// zero; and a boot that owes something to compare and lacks it is refused. +pub fn the_loader_the_kernel_and_a_program_count_from_one_zero() { + const STATED: &str = "Loader clock: each line opens with the seconds since the counter's zero, at \ + the counter's stated 2419200000 Hz"; + let read = |clock: &str, loader_ms: &str, kernel_ms: &str, said: &str| { + let dir = toyos_tmpdir::TempDir::new("metal-one-clock"); + let kernel = format!( + "[2026-10-04 09:30:00 {kernel_ms} cpu0 kernel] panic console: armed\n\ + [2026-10-04 09:30:00 12.000 cpu0 kernel] spawn: /system/bin/logkeeper pid=6\n\ + {said}\ + [2026-10-04 09:30:00 15.000 cpu0 kernel] Boot: complete (3335ms)\n" + ); + plant(&dir, "planted", PANEL, &kernel, None); + let loader = format!( + "[{loader_ms} cpu0 loader] {}\n[{loader_ms} cpu0 loader] {clock}\n[{loader_ms} cpu0 loader] {}\n{}\n{}\n{PANEL}", + bootlog::LOADER_FIRST_LINE, + bootlog::LOADER_LAST_LINE, + bootlog::SEPARATOR, + bootlog::LOADER_FIRST_LINE + ); + let home = metal::at(&dir, "planted"); + fs::write(home.join(READBACK_LOADER), loader).expect("a planted loader.log"); + fs::write(home.join(READBACK_KERNEL), kernel).expect("a planted log"); + metal::read_readback(&dir, "planted").expect("a planted readback").one_clock() + }; + let (stated, none) = (STATED, bootlog::LOADER_CLOCK_NONE); + let said = |ms: &str| format!("[2026-10-04 09:30:00 {ms} supervisor] {}\n", bootlog::LOGKEEPER_STARTED); + assert_eq!(read(stated, " 9.876", "11.665", &said("13.064")), Ok(())); + assert_eq!(read(none, "--.---", " 0.050", &said("13.064")), Ok(())); + let why = read(stated, " 9.876", " 0.050", &said("13.064")).expect_err("a kernel that counts from its own start"); + assert!(why.contains("the kernel's earliest timed record 50 ms"), "{why}"); + let why = read(stated, " 9.876", "11.665", &said(" 1.064")).expect_err("a program that counts from the kernel's clock"); + assert!(why.contains("reads 1064 ms and the kernel's record of that spawn 12000 ms"), "{why}"); + // Nothing to compare, where the boot owes it. + let why = read(stated, "--.---", "11.665", &said("13.064")).expect_err("a loader that lost its time"); + assert!(why.contains("none of its lines carries a time"), "{why}"); + let why = read("Loader log: opened", " 9.876", "11.665", &said("13.064")).expect_err("a loader silent on its clock"); + assert!(why.contains("said nothing of its clock"), "{why}"); + let why = read(stated, " 9.876", "11.665", "").expect_err("a complete boot with no supervisor line"); + assert!(why.contains("no timed supervisor line saying so"), "{why}"); +} diff --git a/tests/checks/qemu.rs b/tests/checks/qemu.rs index 7a3dadfd246..0096b197cee 100644 --- a/tests/checks/qemu.rs +++ b/tests/checks/qemu.rs @@ -59,7 +59,7 @@ pub fn host_scale_self_check() -> Result<(), String> { pub fn ceiling_self_check() -> Result<(), String> { const CEILING: Duration = Duration::from_secs(380); const KERNEL: &str = - "[kernel 1.450 cpu3] PANIC: panicked at kernel/src/sched/reserve.rs:812:9:"; + "[ 1.450 cpu3 kernel] PANIC: panicked at kernel/src/sched/reserve.rs:812:9:"; let quiet = GUEST_QUIET + Duration::from_secs(1); let talking = Duration::from_millis(200); @@ -80,7 +80,7 @@ pub fn ceiling_self_check() -> Result<(), String> { if early >= CEILING { return Err(String::from("staged the panic after the ceiling, so it proves nothing")); } - let again = "[kernel 1.503 cpu7] PANIC: panicked at kernel/src/sched/reserve.rs:812:9:"; + let again = "[ 1.503 cpu7 kernel] PANIC: panicked at kernel/src/sched/reserve.rs:812:9:"; if ceiling_verdict(Some(again), early, CEILING, quiet, 40).as_deref() != Some(panic.as_str()) { return Err(format!( "one panic on two boots gives two sentences:\n\ @@ -107,7 +107,7 @@ pub fn ceiling_self_check() -> Result<(), String> { // 2b. The same two cases for the wait that holds a whole capture rather // than a line at a time — `await_guest`, whose `it went quiet` is the // wording #156's signature is stated in. - let halted = format!("[kernel 0.400 cpu0] compositor: frames=120\n{KERNEL}\n"); + let halted = format!("[ 0.400 cpu0 kernel] compositor: frames=120\n{KERNEL}\n"); let Some(found) = super::serial::kernel_death(&halted) else { return Err(String::from("a capture ending in a kernel panic reads as a guest that merely \ stopped, which is the verdict that threw the cause away")); @@ -115,7 +115,7 @@ pub fn ceiling_self_check() -> Result<(), String> { if kernel_died_here(found) != panic { return Err(String::from("the two waits word one panic differently")); } - let program_died = format!("[kernel 0.400 cpu0] compositor: frames=120\n{USER}\n"); + let program_died = format!("[ 0.400 cpu0 kernel] compositor: frames=120\n{USER}\n"); if super::serial::kernel_death(&program_died).is_some() { return Err(format!( "a capture whose only panic is a program's reads as a halted machine:\n{program_died}" @@ -221,12 +221,12 @@ pub fn ceiling_self_check() -> Result<(), String> { // went into the record with its report — written, on IST1, 6688 bytes of // it — never printed. Both directions, because the second is what keeps a // stall or a slow test from pasting a boot's console at somebody. - const DF: &str = "[kernel 6.204 cpu1] DOUBLE FAULT on CPU 1 (pid=Some(Pid(2)) tid=Some(Tid(0)))"; - let window_before = "[kernel 6.201 cpu0] spawn: /system/bin/test_rs_console_line_atomicity pid=41\n"; + const DF: &str = "[ 6.204 cpu1 kernel] DOUBLE FAULT on CPU 1 (pid=Some(Pid(2)) tid=Some(Tid(0)))"; + let window_before = "[ 6.201 cpu0 kernel] spawn: /system/bin/test_rs_console_line_atomicity pid=41\n"; let window_serial = format!( "AAAAAAAA\n{DF}\n\ - [kernel 6.204 cpu1] cr2=0xffff800002672ff8 (address that caused the fault chain)\n\ - [kernel 6.204 cpu1] rip=0xffffffff80121a40 rsp=0xffff800002673000 rbp=0x0\n" + [ 6.204 cpu1 kernel] cr2=0xffff800002672ff8 (address that caused the fault chain)\n\ + [ 6.204 cpu1 kernel] rip=0xffffffff80121a40 rsp=0xffff800002673000 rbp=0x0\n" ); let died_verdict = ceiling_verdict(Some(DF), early, CEILING, quiet, 40) .ok_or("a staged double fault reached no verdict at all")?; @@ -249,7 +249,7 @@ pub fn ceiling_self_check() -> Result<(), String> { // The other direction. A guest still talking at its ceiling has nothing to // account for, and a verdict that grew a serial log would be a second defect // dressed as a fix. - let quiet_capture = WaitVerdict::new(slow.clone(), &["[kernel 0.377 cpu0] NVMe: found\n"]); + let quiet_capture = WaitVerdict::new(slow.clone(), &["[ 0.377 cpu0 kernel] NVMe: found\n"]); if quiet_capture.to_string() != slow { return Err(format!( "a verdict on a capture nothing died in grew a report:\n{quiet_capture}" diff --git a/tests/checks/serial.rs b/tests/checks/serial.rs index 3185b69a0e3..cba7757dcbc 100644 --- a/tests/checks/serial.rs +++ b/tests/checks/serial.rs @@ -18,7 +18,7 @@ pub fn spellings() -> impl Iterator { /// here is one this type must *fail*, because the failures are the point: a /// `must_not_say` that returns `Ok` on an empty capture is the whole hazard. pub fn self_check() -> Result<(), String> { - let live = Serial::named("test capture", "[kernel 0.001 cpu0] NVMe: found\nhello from userland\n"); + let live = Serial::named("test capture", "[ 0.001 cpu0 kernel] NVMe: found\nhello from userland\n"); let dead = Serial::named("test capture", ""); // Userland said things; the kernel said nothing. This is what a broken // capture looks like when it is not simply empty, and the case a @@ -27,15 +27,15 @@ pub fn self_check() -> Result<(), String> { // A readback of `/log`, whose kernel records open with a date. let readback = Serial::named( "test capture", - "[2026-09-29 11:11:20 0.000 cpu0 boot] panic console: armed 1920x1080 stride=1920 \ + "[2026-09-29 11:11:20 0.000 cpu0 kernel] panic console: armed 1920x1080 stride=1920 \ format=1 at 0x4000000000, write-combining\n\ - {2026-09-29 11:11:21 1.170 supervisor} supervisor: started logkeeper\n", + [2026-09-29 11:11:21 1.170 supervisor] supervisor: started logkeeper\n", ); let readback_mute = - Serial::named("test capture", "{2026-09-29 11:11:21 1.170 supervisor} supervisor: started logkeeper\n"); + Serial::named("test capture", "[2026-09-29 11:11:21 1.170 supervisor] supervisor: started logkeeper\n"); let panicking = Serial::named( "test capture", - "[kernel 0.001 cpu0] NVMe: found\n[kernel 0.002 cpu0] PANIC: nope\n", + "[ 0.001 cpu0 kernel] NVMe: found\n[ 0.002 cpu0 kernel] PANIC: nope\n", ); /// One row: what it is called, whether it must pass, and the call itself. @@ -66,7 +66,7 @@ pub fn self_check() -> Result<(), String> { ("must_be_clean on a user-owned DMA fault", false, &|| { Serial::named( "test capture", - "[kernel 0.001 cpu0] NVMe: found\n[kernel 4.100 cpu0] iommu: DMA FAULT \ + "[ 0.001 cpu0 kernel] NVMe: found\n[ 4.100 cpu0 kernel] iommu: DMA FAULT \ owner=slot0 unit0 stream=00:03.0 addr=0x1000 access=read reason=0x06 \ read-permission\n", ) @@ -96,9 +96,9 @@ pub fn self_check() -> Result<(), String> { // first case is the defect and is asserted in both directions — the plain // scan reads the stranger. const READY: &str = "===I8042_READY==="; - let stranger = "[kernel 0.418 cpu1] i8042: 1 interrupts and 0 bytes, nothing decoded — first \ + let stranger = "[ 0.418 cpu1 kernel] i8042: 1 interrupts and 0 bytes, nothing decoded — first \ seen at 418ms"; - let mine = "[kernel 2.816 cpu0] i8042: 2 interrupts and 6 bytes, nothing decoded — no event \ + let mine = "[ 2.816 cpu0 kernel] i8042: 2 interrupts and 6 bytes, nothing decoded — no event \ from [0xe1, 0x1d, 0x45, 0xe1, 0x9d, 0xc5], first seen at 2816ms"; let staged = Serial::named("test capture", format!("{stranger}\n{READY}\n{mine}\n")); if staged.must_say("nothing decoded")? != stranger { @@ -122,7 +122,7 @@ pub fn self_check() -> Result<(), String> { } // Interleaving is detected and named, and a clean capture reports none. - let split = Serial::named("test capture", "[kernel 0.001 cpu0] a\nBoot: comp[kernel 0.002 cpu0] lete\n"); + let split = Serial::named("test capture", "[ 0.001 cpu0 kernel] a\nBoot: comp[ 0.002 cpu0 kernel] lete\n"); if split.interleaved().is_none() { return Err(String::from("a kernel prefix spliced mid-line was not detected")); } @@ -141,21 +141,21 @@ pub fn self_check() -> Result<(), String> { // prefix is the whole discriminator, so it is asserted from both sides: // the same words, once from the kernel and once from somebody else. const KERNEL_PANIC_LINE: &str = - "[kernel 1.450 cpu3] PANIC: panicked at kernel/src/sched/reserve.rs:812:9:"; + "[ 1.450 cpu3 kernel] PANIC: panicked at kernel/src/sched/reserve.rs:812:9:"; const USER_PANIC_LINE: &str = "thread 'main' (1) panicked at sshserver/src/main.rs:359:23:"; let whose: &[(&str, Option)] = &[ // The kernel, about itself. (KERNEL_PANIC_LINE, Some(Died::Kernel)), - ("[kernel 0.068 cpu0] KERNEL PANIC: read unmapped address at 0x0", Some(Died::Kernel)), + ("[ 0.068 cpu0 kernel] KERNEL PANIC: read unmapped address at 0x0", Some(Died::Kernel)), // The three that write none of the words beside them. The first is // verbatim what a staged `#DF` put on the console. ( - "[kernel 0.443 cpu0] DOUBLE FAULT on CPU 0 (pid=Some(Pid(5)) tid=Some(Tid(0)))", + "[ 0.443 cpu0 kernel] DOUBLE FAULT on CPU 0 (pid=Some(Pid(5)) tid=Some(Tid(0)))", Some(Died::Kernel), ), - ("[kernel 0.443 cpu0] MACHINE CHECK on CPU 3", Some(Died::Kernel)), + ("[ 0.443 cpu0 kernel] MACHINE CHECK on CPU 3", Some(Died::Kernel)), ( - "[kernel 4.100 cpu0] iommu: DMA FAULT owner=kernel unit0 stream=00:1f.2 \ + "[ 4.100 cpu0 kernel] iommu: DMA FAULT owner=kernel unit0 stream=00:1f.2 \ addr=0x1000 access=read reason=0x06 unknown", Some(Died::Kernel), ), @@ -164,13 +164,13 @@ pub fn self_check() -> Result<(), String> { // two lines differ in one field, which is what makes the case worth // stating rather than assuming. ( - "[kernel 4.100 cpu0] iommu: DMA FAULT owner=slot0 unit0 stream=00:03.0 \ + "[ 4.100 cpu0 kernel] iommu: DMA FAULT owner=slot0 unit0 stream=00:03.0 \ addr=0x1000 access=read reason=0x06 read-permission", None, ), - ("[kernel 0.001 cpu0] EARLY PANIC: nothing is up yet", Some(Died::Kernel)), + ("[ 0.001 cpu0 kernel] EARLY PANIC: nothing is up yet", Some(Died::Kernel)), ( - "[kernel 2.000 cpu1] DOUBLE PANIC: the cpu was already in Fatal; first: invalid \ + "[ 2.000 cpu1 kernel] DOUBLE PANIC: the cpu was already in Fatal; first: invalid \ opcode rip=0x0000000000401234 cr2=0x0000000000000000 err=0x0000000000000000; \ second: panic at src/mm/paging.rs:41:5: the page is not there", Some(Died::Kernel), @@ -180,19 +180,19 @@ pub fn self_check() -> Result<(), String> { ("\n!!! PANIC REENTRY: CPU halted !!! (apic 3)", Some(Died::Kernel)), ("KERNEL PANIC: spliced onto somebody's unterminated write", Some(Died::Kernel)), // The kernel, about a process. Its line, somebody else's death. - ("[kernel 0.412 cpu0] SEGFAULT tid=7: read unmapped address at 0x0", Some(Died::Faulted)), - ("[kernel 0.412 cpu0] SIGILL tid=7: illegal instruction", Some(Died::Faulted)), - ("[kernel 0.412 cpu0] FATAL tid=7: machine check", Some(Died::Faulted)), + ("[ 0.412 cpu0 kernel] SEGFAULT tid=7: read unmapped address at 0x0", Some(Died::Faulted)), + ("[ 0.412 cpu0 kernel] SIGILL tid=7: illegal instruction", Some(Died::Faulted)), + ("[ 0.412 cpu0 kernel] FATAL tid=7: machine check", Some(Died::Faulted)), // A process, about itself. Neither of these ends anybody's run. (USER_PANIC_LINE, Some(Died::Panicked)), ("libc panic: panicked at src/main.rs:9:1:", Some(Died::Panicked)), // The one the naive fix cannot tell from the kernel's, and must. ("PANIC: printed by a program that felt like printing it", Some(Died::Panicked)), // A `/log` readback's heads: the kernel's panic, and a program's. - ("[2026-09-29 11:11:22 2.000 cpu1] PANIC: nope", Some(Died::Kernel)), - ("{2026-09-29 11:11:22 2.000 supervisor} PANIC: printed by the supervisor", Some(Died::Panicked)), + ("[2026-09-29 11:11:22 2.000 cpu1 kernel] PANIC: nope", Some(Died::Kernel)), + ("[2026-09-29 11:11:22 2.000 supervisor] PANIC: printed by the supervisor", Some(Died::Panicked)), // Nothing died. - ("[kernel 0.377 cpu0] NVMe: found", None), + ("[ 0.377 cpu0 kernel] NVMe: found", None), ("hello from userland", None), ("", None), ]; @@ -206,7 +206,7 @@ pub fn self_check() -> Result<(), String> { // as its own case because the table above would still pass if `died` // ignored the prefix and every kernel-written line simply came first. for word in ["PANIC:", "panicked at"] { - let kernel = format!("[kernel 1.450 cpu3] {word} whatever follows"); + let kernel = format!("[ 1.450 cpu3 kernel] {word} whatever follows"); let program = format!("some program says {word} whatever follows"); if died(&kernel) != Some(Died::Kernel) || died(&program) != Some(Died::Panicked) { return Err(format!( @@ -219,7 +219,7 @@ pub fn self_check() -> Result<(), String> { // And `must_be_clean` still refuses both of them, because a boot that // carries either is not a clean boot whoever wrote it. for line in [KERNEL_PANIC_LINE, USER_PANIC_LINE] { - let capture = Serial::named("test capture", format!("[kernel 0.001 cpu0] up\n{line}\n")); + let capture = Serial::named("test capture", format!("[ 0.001 cpu0 kernel] up\n{line}\n")); if capture.must_be_clean().is_ok() { return Err(format!("must_be_clean passed a capture carrying {line:?}")); } @@ -231,16 +231,16 @@ pub fn self_check() -> Result<(), String> { // it and a daemon still talking after the header — a capture that begins at // the death would be a capture nobody has. const DF_HEADER: &str = - "[kernel 6.204 cpu1] DOUBLE FAULT on CPU 1 (pid=Some(Pid(2)) tid=Some(Tid(0)))"; + "[ 6.204 cpu1 kernel] DOUBLE FAULT on CPU 1 (pid=Some(Pid(2)) tid=Some(Tid(0)))"; let staged_df = format!( - "[kernel 6.201 cpu0] spawn: /system/bin/test_rs_console_line_atomicity pid=41\n\ + "[ 6.201 cpu0 kernel] spawn: /system/bin/test_rs_console_line_atomicity pid=41\n\ AAAAAAAA\n\ {DF_HEADER}\n\ - [kernel 6.204 cpu1] cr2=0xffff800002672ff8 (address that caused the fault chain)\n\ - [kernel 6.204 cpu1] rip=0xffffffff80121a40 rsp=0xffff800002673000 rbp=0x0\n\ - [kernel 6.204 cpu1] Kernel backtrace:\n\ + [ 6.204 cpu1 kernel] cr2=0xffff800002672ff8 (address that caused the fault chain)\n\ + [ 6.204 cpu1 kernel] rip=0xffffffff80121a40 rsp=0xffff800002673000 rbp=0x0\n\ + [ 6.204 cpu1 kernel] Kernel backtrace:\n\ soundserver: suspended\n\ - [kernel 6.205 cpu1] Found interrupt frame at stack offset +0x18:\n" + [ 6.205 cpu1 kernel] Found interrupt frame at stack offset +0x18:\n" ); let Some(report) = death_report(&staged_df) else { return Err(String::from( @@ -271,20 +271,20 @@ pub fn self_check() -> Result<(), String> { } // The other direction, and the one that keeps this out of everybody's // terminal: a capture nothing died in has no report at all. - let healthy = "[kernel 0.377 cpu0] NVMe: found\nBoot: complete\n"; + let healthy = "[ 0.377 cpu0 kernel] NVMe: found\nBoot: complete\n"; if death_report(healthy).is_some() { return Err(String::from("a clean capture produced a death report")); } // A *program* dying is not the machine's account either — the same // discrimination `died` makes, asked of the thing that quotes a capture. - let program = format!("[kernel 0.001 cpu0] up\n{USER_PANIC_LINE}\nmore output\n"); + let program = format!("[ 0.001 cpu0 kernel] up\n{USER_PANIC_LINE}\nmore output\n"); if death_report(&program).is_some() { return Err(format!("a program's own panic reads as the kernel's death:\n{program}")); } // Bounded, and it says by how much rather than trailing off. 400 lines of // report is four times what the deepest one in this tree writes. let flood: String = std::iter::once(DF_HEADER.to_string()) - .chain((0..400).map(|i| format!("[kernel 6.204 cpu1] line {i}"))) + .chain((0..400).map(|i| format!("[ 6.204 cpu1 kernel] line {i}"))) .collect::>() .join("\n"); let bounded = death_report(&flood).ok_or("a 401-line report vanished")?; diff --git a/tests/checks/usb.rs b/tests/checks/usb.rs index 1bb77708561..e7139b5cab4 100644 --- a/tests/checks/usb.rs +++ b/tests/checks/usb.rs @@ -13,52 +13,52 @@ pub fn transport_break_verdict() -> Result<(), String> { } }; const STAGED: &str = "\ - [kernel 1.174 cpu3] usb-storage: 00:14.0 slot 1 transport broke on SCSI 0x2a: a staged \ + [ 1.174 cpu3 kernel] usb-storage: 00:14.0 slot 1 transport broke on SCSI 0x2a: a staged \ break skipped the data phase wait; break 1 of 3 running\n"; const OWED: &str = "\ - [kernel 1.174 cpu3] usb-storage: 00:14.0 slot 1 is owed the data of the command that \ + [ 1.174 cpu3 kernel] usb-storage: 00:14.0 slot 1 is owed the data of the command that \ broke, so nothing can be asked of it on the Bulk-Out: its port is reset with no class \ reset before it\n"; const RESET: &str = "\ - [kernel 1.229 cpu3] xHCI: 00:14.0 slot 1 port 1 reset while recovering (hot on a USB2 \ + [ 1.229 cpu3 kernel] xHCI: 00:14.0 slot 1 port 1 reset while recovering (hot on a USB2 \ port): PORTSC 0x00000e03 then 0x00200e03, link Active, speed 3: reset, and the port is \ enabled\n"; const UNANSWERED: &str = "\ - [kernel 1.279 cpu3] xHCI: Address Device (after the port reset) failed: code 4 (USB \ + [ 1.279 cpu3 kernel] xHCI: Address Device (after the port reset) failed: code 4 (USB \ Transaction Error)\n"; const CLIMBED_ON: &str = "\ - [kernel 1.279 cpu3] usb-storage: 00:14.0 slot 1 the port reset was not answered; break 2 \ + [ 1.279 cpu3 kernel] usb-storage: 00:14.0 slot 1 the port reset was not answered; break 2 \ of 3 running\n\ - [kernel 1.279 cpu3] usb-storage: 00:14.0 slot 1 broke 2 times running; its port reset did \ + [ 1.279 cpu3 kernel] usb-storage: 00:14.0 slot 1 broke 2 times running; its port reset did \ not bring the transport back\n\ - [kernel 1.279 cpu3] xHCI: 00:14.0 slot 1 port 1 reset while taking it offline (hot on a \ + [ 1.279 cpu3 kernel] xHCI: 00:14.0 slot 1 port 1 reset while taking it offline (hot on a \ USB2 port): PORTSC 0x000202a0 then 0x000202a0, link RxDetect, speed 0: nothing is \ connected, so its port's teardown takes it from here\n\ - [kernel 1.279 cpu3] usb-storage: 00:14.0 slot 1 is offline: both bulk endpoints \ + [ 1.279 cpu3 kernel] usb-storage: 00:14.0 slot 1 is offline: both bulk endpoints \ Stopped=true, port 1 reset=false and nothing sent after it, Reset Device=false, its slot \ goes back to the controller; every operation on it is refused from here\n"; const LEFT: &str = "\ - [kernel 1.279 cpu3] usb-storage: 00:14.0 slot 1 the port reset was not answered, and port \ + [ 1.279 cpu3 kernel] usb-storage: 00:14.0 slot 1 the port reset was not answered, and port \ 1 no longer holds the device (PORTSC 0x000202a0): its port's teardown takes it from here\n"; const BACK: &str = "\ - [kernel 1.279 cpu3] usb-storage: disk 0 left port 1 (its port read empty) after this \ + [ 1.279 cpu3 kernel] usb-storage: disk 0 left port 1 (its port read empty) after this \ driver reset it; it is held 1894 ms for the same device to come back\n\ - [kernel 2.211 cpu0] usb-storage: disk 0 came back on port 13 slot 6 as the same device \ + [ 2.211 cpu0 kernel] usb-storage: disk 0 came back on port 13 slot 6 as the same device \ (USB 0781:5581, serial number \"FEDCBA98765432FEDCBA\", 7507812 blocks of 512 B), \ msc_block +0x30000; its volume carries on\n\ - [kernel 2.259 cpu3] usb-storage: disk 0 is back, and the operation it was asked went out \ + [ 2.259 cpu3 kernel] usb-storage: disk 0 is back, and the operation it was asked went out \ again on it: it completed\n"; const TOOK: &str = "\ - [kernel 1.330 cpu3] usb-storage: 00:14.0 slot 1 the port reset took: addressed and \ + [ 1.330 cpu3 kernel] usb-storage: 00:14.0 slot 1 the port reset took: addressed and \ configured again, the device answered TEST UNIT READY under its own tag 0x5a2\n"; const COMPLETED: &str = "\ - [kernel 1.331 cpu3] usb-storage: 00:14.0 slot 1 SCSI 0x2a completed after 1 break(s) \ + [ 1.331 cpu3 kernel] usb-storage: 00:14.0 slot 1 SCSI 0x2a completed after 1 break(s) \ running; the transport came back and the count is cleared\n"; const CLASS_RESET_TOOK: &str = "\ - [kernel 1.175 cpu3] usb-storage: 00:14.0 slot 1 Reset Recovery took: the device answered \ + [ 1.175 cpu3 kernel] usb-storage: 00:14.0 slot 1 Reset Recovery took: the device answered \ TEST UNIT READY under its own tag 0x5a2\n"; const CLASS_RESET_UNANSWERED: &str = "\ - [kernel 1.175 cpu3] usb-storage: 00:14.0 slot 1 the class reset was not answered; break 2 \ + [ 1.175 cpu3 kernel] usb-storage: 00:14.0 slot 1 the class reset was not answered; break 2 \ of 3 running\n"; judged("the break as the T14 read it", &format!("{STAGED}{OWED}{RESET}{UNANSWERED}{CLIMBED_ON}{BACK}"), false)?; diff --git a/tests/common/irqcensus.rs b/tests/common/irqcensus.rs index a4bfb247699..2b676fdbd71 100644 --- a/tests/common/irqcensus.rs +++ b/tests/common/irqcensus.rs @@ -47,7 +47,7 @@ impl Census { /// Parse one line, or say why it is not one. /// /// Anything before `irq: cpu` is ignored, so the same parser reads a raw - /// guest line, a `[kernel …]` log line and a `[serial N]` echo of either. + /// guest line, a kernel record's line and a `[serial N]` echo of either. pub fn parse(line: &str) -> Option> { let rest = line.split("irq: cpu").nth(1)?; Some(Self::parse_body(rest)) diff --git a/tests/common/metal.rs b/tests/common/metal.rs index ea887072ccf..08752b18c62 100644 --- a/tests/common/metal.rs +++ b/tests/common/metal.rs @@ -280,12 +280,22 @@ impl Readback { Serial::named(&format!("{}'s loader.log", self.label), self.loader.as_str()) } - /// When the last record this boot left was written, in milliseconds since - /// boot. `None` on a log with no record at all. + /// When the last record this boot left was written, on the log's clock. + /// `None` on a log with no record at all. pub fn last_record_ms(&self) -> Option { bootlog::last_record_millis(&self.kernel) } + /// [`bootlog::one_clock`] of this boot. + pub fn one_clock(&self) -> Result<(), String> { + bootlog::one_clock(&self.loader, &self.log).map_err(|why| format!("{}: {why}", self.label)) + } + + /// When `Boot: complete` was written, on the same clock. + pub fn complete_record_ms(&self) -> Option { + self.kernel.lines().find(|line| line.contains(bootlog::COMPLETE)).and_then(bootlog::record_millis) + } + /// Whether this boot's log is whole to its stop, and the stop's own tail /// is on the page. /// @@ -1075,6 +1085,7 @@ pub fn judge_readbacks( findings.extend(back.stop_completed().err()); findings.extend(back.deadline_on_time().err()); findings.extend(back.lockup_on_time().err()); + findings.extend(back.one_clock().err()); for why in &findings { eprintln!(" FAIL {why}"); } @@ -1138,7 +1149,7 @@ pub fn judge_readbacks( } } if let (Ok(back), true) = (back, ran > 0) { - if let (Some(complete), Some(last)) = (back.boot_ms, back.last_record_ms()) { + if let (Some(complete), Some(last)) = (back.complete_record_ms(), back.last_record_ms()) { let each = last.saturating_sub(complete) / ran as u64; eprintln!(" {} ms per member over the {ran} that ran", each); } diff --git a/tests/common/qemu.rs b/tests/common/qemu.rs index d7c0ce1b2cc..95a630f373b 100644 --- a/tests/common/qemu.rs +++ b/tests/common/qemu.rs @@ -375,12 +375,9 @@ pub const GUEST_QUIET: Duration = Duration::from_secs(15); /// through [`await_guest`]. pub const GUEST_WEDGED: Duration = Duration::from_secs(141); -/// A kernel line without its `[kernel cpu] ` stamp. +/// A kernel line without its head. fn without_stamp(line: &str) -> &str { - if !is_kernel_line(line) { - return line; - } - line.split_once("] ").map_or(line, |(_, rest)| rest) + toyos_logstream::parse(line).filter(|p| p.source == toyos_logstream::Source::Kernel).map_or(line, |p| p.text) } /// The sentence a wait gives when what stopped the guest is on the console. @@ -1134,11 +1131,10 @@ pub fn build_toyos_bin(arch: Arch, crate_path: &Path, name: &str) -> Vec { } /// A kernel record's line, whichever writer spelled its head: `klogd`'s console -/// `[kernel …]` and a `/log` file's `[