From 68af3b14777337af0b02cad18ef05b672b735d0f Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 4 Oct 2026 22:11:32 +0200 Subject: [PATCH 1/8] Every line of the log opens with one head, time first, from the counter's zero The owner's rulings of 2026-10-04: kernel and program lines take one shape, "seconds, then where it ran, then who said it, the same brackets for both"; and every line, the loader's, the kernel's and every program's, counts from one zero, the moment the CPU's counter started, with the wall clock in /log alone. - toyos_abi::log::Head is the one formatter: [ . cpu tid= pid=]. The seconds are right aligned in two columns; a line said before its sayer knew a counter rate reads --.--- there. A kernel record's who is `kernel`, the loader's `loader`, a program's its tag. LogRecord's Display, LogRecord::dated (the wall clock, for /log), ProgramLine and the loader's stamp all write it. - toyos_logstream::parse is the one reader: the console app, the host relay, the harness and the metal judges read every head through it. A Tag refuses `kernel`, `loader` and `cpu`, so the sayer in a head is logkeeper's word and never a program's, now that both open with `[`. kernel_opening finds the kernel's first record on a console after the firmware's bytes and the loader's lines, for the relay and the split. - The stamp counts from the counter's zero. The loader converts the raw counter at the rate the CPU states. The kernel's records carry clock::stamp: before the clock is calibrated, the counter at the rate the CPU states (taken at the kernel's entry), and after it the calibrated clock offset by the stamp at its start, so no record is stamped earlier than one before it. Where the CPU states no rate, a record before the calibration carries FLAG_UNTIMED (which replaces FLAG_EARLY, whose `boot` word the ruling's shape drops) and its line reads --.---. - The clock page carries stamp_at_boot, so a program's records (toyos_abi::clock::stamp_ns) and logkeeper's comparisons against them read the same clock as the kernel's. nanos_since_boot keeps its zero: every bound and deadline measured from boot is unchanged, Boot: complete included. - The wedge's "reached at" is quoted on the log's clock, since the metal judge subtracts the arming record's stamp from it; the metal loop's per-member figure takes both its instants from record stamps. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01WcU2Dsw6mDYtwYfzVHPzM8 --- bootloader/src/loaderlog.rs | 2 +- bootloader/src/main.rs | 4 +- bootloader/src/stamp.rs | 54 +- ...-programs-line-on-a-screen-names-no-cpu.md | 6 +- ...it-does-not-re-arm-across-a-guest-reset.md | 6 +- ...e-on-an-x86-cpu-that-states-no-tsc-rate.md | 32 +- kernel/loom/tests/log_body_words.rs | 4 +- kernel/src/clock.rs | 54 +- kernel/src/deadline.rs | 2 +- kernel/src/log/console.rs | 4 +- kernel/src/log/mod.rs | 13 +- kernel/src/main.rs | 2 + src/bootlog.rs | 60 +- src/kernelconsole.rs | 89 +-- src/lan.rs | 48 +- src/metal.rs | 18 +- src/metaldevices.rs | 4 +- src/metaltalk.rs | 38 +- tests/checks.rs | 48 +- tests/checks/audio.rs | 106 ++-- tests/checks/claims.rs | 20 +- tests/checks/lan.rs | 14 +- tests/checks/metal.rs | 8 +- tests/checks/qemu.rs | 18 +- tests/checks/serial.rs | 68 +-- tests/checks/usb.rs | 32 +- tests/common/irqcensus.rs | 2 +- tests/common/metal.rs | 11 +- tests/common/qemu.rs | 14 +- tests/common/serial.rs | 7 +- tests/toyos.rs | 6 +- toyos-abi/src/clock.rs | 25 +- toyos-abi/src/log.rs | 204 ++++--- toyos-blackbox/src/lib.rs | 20 +- toyos-logstream/src/lib.rs | 522 ++++++++++++------ toyos-quiesce/src/lib.rs | 2 +- toyos-swap/src/lib.rs | 2 +- toyos-symbols/tests/frame.rs | 2 +- toyos-trace/src/lib.rs | 3 +- toyos/src/log/stdio.rs | 2 +- userland/console/src/main.rs | 10 +- userland/logkeeper/src/main.rs | 33 +- userland/logkeeper/src/origin.rs | 4 +- userland/logkeeper/src/serve.rs | 4 +- 44 files changed, 956 insertions(+), 671 deletions(-) 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..50ca183dfa4 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 sees a time on the screen: `screen_loader_clears` +(`tests/toyos.rs`) measures the screen's first line, head and all, and on every +x86 guest that head reads `--.---`. 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/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 ee7795c7dc1..bd64b602cfa 100644 --- a/kernel/src/clock.rs +++ b/kernel/src/clock.rs @@ -1,9 +1,11 @@ //! 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}}; @@ -12,13 +14,49 @@ 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(STAMP_AT_BOOT.load(Relaxed).saturating_add(nanos_since_boot())); + } + let stated = STATED_FS.load(Relaxed); + (stated != 0).then(|| ticks_to_nanos(cpu::counter(), stated)) } /// The clock page's frame, or 0 before [`set_counter`]: the one every address space @@ -28,7 +66,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 +80,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 +113,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 +145,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..246be433cfb 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") / 1_000_000, phase(), )); // The seal first, because the USB stop `reset_now` makes before it writes 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..a3a6a1ca0e8 100644 --- a/kernel/src/log/mod.rs +++ b/kernel/src/log/mod.rs @@ -16,7 +16,7 @@ pub mod user; use core::sync::atomic::{AtomicBool, Ordering}; -use toyos_abi::log::{LogRecord, FLAG_EARLY, MAX_LOG_SHARDS, MAX_RECORD_MESSAGE}; +use toyos_abi::log::{LogRecord, FLAG_UNTIMED, MAX_LOG_SHARDS, MAX_RECORD_MESSAGE}; pub use shard::Shard; pub use toyos_abi::log::Severity; @@ -143,7 +143,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 +154,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 +190,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_ns) => record.at_ns = at_ns, + 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/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/src/bootlog.rs b/src/bootlog.rs index e1dea2990c1..7712cc8b3f5 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,8 @@ pub fn stopping_line(log: &str) -> Option<&str> { }) } -/// The milliseconds since boot one record line carries. -/// -/// **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. +/// 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 +400,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 +435,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 +461,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)); } @@ -581,11 +579,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 +603,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 +620,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 +639,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 +662,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 +685,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 04f50c4bd14..379afd6ff5b 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} total=0 timer=0 kick=0 xhci=0 userdev=0 sound=0 i8042=0 \ + "[ 0.100 cpu0 kernel] irq: cpu{cpu} total=0 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))), @@ -911,13 +911,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 +935,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 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 +967,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 +991,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 +1010,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..c74b308c548 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 { @@ -34,7 +34,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 ) @@ -292,8 +292,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] ) }; 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 656bc7d50a0..878a06e1896 100644 --- a/tests/common/irqcensus.rs +++ b/tests/common/irqcensus.rs @@ -48,7 +48,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..f2706c0c70d 100644 --- a/tests/common/metal.rs +++ b/tests/common/metal.rs @@ -280,12 +280,17 @@ 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) } + /// 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. /// @@ -1138,7 +1143,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 `[