From 5950b5971ce98885b3f11410b2fdff09a2fb0a7c Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 4 Oct 2026 11:45:22 +0200 Subject: [PATCH 1/7] Logs on screen are coloured by severity and source, with a compact stamp The owner asked for colours in the logs that appear on screen, and then for a compact stamp in front of each line: the seconds since boot and the CPU, with the wall clock only in the saved log. Colour is the record's, applied where a line is drawn; no record, no line of /log and no byte of the console wire carries one. - The panel (boot checkpoints, Ctrl+Alt+D's report, the fatal report) marks each rendered line with its record's ink and whether it opens the record. The head of a record's first line - `[1.193 cpu0 tid=3]` - is drawn in a dim grey, the text white for Info, amber for Warn, red for Error and Alert. The alert red moves from FF5050 to FF6E6E: on the fatal ground 600000 the old one read 4.35:1, under WCAG's 4.5:1; every ink now reads 5.15:1 or better on both grounds. A cell carries its ink, so the glass diff still repaints only what changed. - A kernel record's line names its severity above Info in its head, as a program's line already did (`[kernel 1.193 cpu0 alert tid=3]`), so a reader of the text - /log, the console - can tell an alert from an info line. - toyos-logstream's `Shown` is how a terminal shows a line of the log: the console's form with no wall clock, the head dim, `kernel` or the program's tag in its own colour, the text by severity and with no byte that acts. /system/bin/console draws the log it seeds above its prompt through it, and a continuation wears the severity of the record above it. - `cargo run` relays QEMU's console through `kernelconsole::Painter` when its stdout is a terminal: the firmware's bytes as they came, every line from the kernel's first record on through `Shown`. A file or pipe still gets the bytes. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01WcU2Dsw6mDYtwYfzVHPzM8 --- kernel/src/drivers/panic_console/mod.rs | 154 +++++++++++++---- src/kernelconsole.rs | 92 ++++++++++ src/qemu.rs | 28 ++- tests/common/screen.rs | 26 ++- tests/toyos.rs | 39 +++-- toyos-abi/src/log.rs | 20 ++- toyos-logstream/src/lib.rs | 221 ++++++++++++++++++++++-- userland/console/src/main.rs | 49 ++++-- 8 files changed, 537 insertions(+), 92 deletions(-) diff --git a/kernel/src/drivers/panic_console/mod.rs b/kernel/src/drivers/panic_console/mod.rs index 720d92c7697..8786cba83e3 100644 --- a/kernel/src/drivers/panic_console/mod.rs +++ b/kernel/src/drivers/panic_console/mod.rs @@ -39,8 +39,8 @@ const MAX_ROWS: usize = 96; const SNAPSHOT_CAP: usize = 32 * 1024; const _: () = assert!(SNAPSHOT_CAP >= MAX_ROWS * MAX_COLS); -/// One bit per byte `text` can hold — worst case is a message of nothing but newlines, one line per byte. -const ALERT_WORDS: usize = SNAPSHOT_CAP.div_ceil(64); +/// One [`Mark`] a nibble per byte `text` can hold — worst case is a message of nothing but newlines, one line per byte. +const MARK_BYTES: usize = SNAPSHOT_CAP.div_ceil(2); /// How long Ctrl+Alt+D's report keeps the panel. const REPORT_HOLD: Budget = Budget::of( @@ -103,11 +103,63 @@ struct FbCell(UnsafeCell); // SAFETY: the panic path may take no lock; `PENDING` has one writer at a time. unsafe impl Sync for FbCell {} -/// A screenful-and-then-some of rendered log; which lines are red is the record's [`log::Severity`], never inferred from the text. +/// What a line's text is drawn in. +#[derive(Clone, Copy, PartialEq, Eq)] +enum Ink { + Plain = 0, + Warn = 1, + Alert = 2, + /// The head a record's first line opens with: its time, CPU and thread. + Stamp = 3, +} + +impl Ink { + /// A record's text: by its severity, and plain for a byte no severity is. + fn of(severity: Option) -> Self { + match severity { + None | Some(log::Severity::Info) => Ink::Plain, + Some(log::Severity::Warn) => Ink::Warn, + Some(log::Severity::Error | log::Severity::Alert) => Ink::Alert, + } + } + + fn from_bits(bits: u8) -> Self { + match bits & 3 { + 0 => Ink::Plain, + 1 => Ink::Warn, + 2 => Ink::Alert, + _ => Ink::Stamp, + } + } +} + +/// One line of a rendered log as its record made it: the ink of its text, and +/// whether it opens the record and so carries the head. Read from the record, +/// never inferred from the text. +#[derive(Clone, Copy)] +struct Mark(u8); + +impl Mark { + const OPENS: u8 = 1 << 2; + + fn new(ink: Ink, opens: bool) -> Self { + Self(ink as u8 | if opens { Self::OPENS } else { 0 }) + } + + fn ink(self) -> Ink { + Ink::from_bits(self.0) + } + + fn opens(self) -> bool { + self.0 & Self::OPENS != 0 + } +} + +/// A screenful-and-then-some of rendered log, and each line's [`Mark`]. struct Rendered { text: [u8; SNAPSHOT_CAP], - /// One bit per line, counted back from the last — the buffer fills from its end. - alert: [u64; ALERT_WORDS], + /// One nibble per line, counted back from the last — the buffer fills from its end. + marks: [u8; MARK_BYTES], /// Bytes of `text` in use, at its end. len: usize, lines: usize, @@ -115,11 +167,11 @@ struct Rendered { impl Rendered { const EMPTY: Self = - Self { text: [0; SNAPSHOT_CAP], alert: [0; ALERT_WORDS], len: 0, lines: 0 }; + Self { text: [0; SNAPSHOT_CAP], marks: [0; MARK_BYTES], len: 0, lines: 0 }; /// Render the newest records stamped in `from..=to` that fit; returns the byte count. Records older than the buffer holds are dropped. fn render(&mut self, from: u64, to: u64) -> usize { - self.alert = [0; ALERT_WORDS]; + self.marks = [0; MARK_BYTES]; self.lines = 0; self.len = 0; let mut fill = Backfill { at: SNAPSHOT_CAP, into: self }; @@ -132,7 +184,7 @@ impl Rendered { fn view(&self) -> View<'_> { View { text: self.text.get(SNAPSHOT_CAP - self.len..).unwrap_or(&[]), - alert: &self.alert, + marks: &self.marks, lines: self.lines, } } @@ -142,15 +194,16 @@ impl Rendered { #[derive(Clone, Copy)] struct View<'a> { text: &'a [u8], - alert: &'a [u64; ALERT_WORDS], + marks: &'a [u8; MARK_BYTES], lines: usize, } impl View<'_> { - /// Whether line `n`, counted from the first, came from an `alert!`. - fn is_alert(&self, n: usize) -> bool { - let Some(from_end) = self.lines.checked_sub(n + 1) else { return false }; - self.alert.get(from_end / 64).is_some_and(|word| word & (1 << (from_end % 64)) != 0) + /// Line `n`'s mark, counted from the first. + fn mark(&self, n: usize) -> Mark { + let Some(from_end) = self.lines.checked_sub(n + 1) else { return Mark::new(Ink::Plain, false) }; + let byte = self.marks.get(from_end / 2).copied().unwrap_or(0); + Mark(byte >> (from_end % 2 * 4) & 0xF) } } @@ -172,11 +225,12 @@ impl log::read::RecordSink for Backfill<'_> { // Counted in newlines, not records: `paint` counts newlines, and a multi-line record (every panic) is more than one row. let lines = out.iter().filter(|&&byte| byte == b'\n').count(); - if record.severity().is_some_and(|s| s >= log::Severity::Error) { - for line in self.into.lines..self.into.lines + lines { - if let Some(word) = self.into.alert.get_mut(line / 64) { - *word |= 1 << (line % 64); - } + let ink = Ink::of(record.severity()); + for line in self.into.lines..self.into.lines + lines { + // Counted from the end, so the record's first line is its last here. + let mark = Mark::new(ink, line + 1 == self.into.lines + lines); + if let Some(byte) = self.into.marks.get_mut(line / 2) { + *byte |= mark.0 << (line % 2 * 4); } } self.into.lines += lines; @@ -900,8 +954,8 @@ static PROBE_AT: [AtomicU32; PROBES] = [const { AtomicU32::new(0) }; PROBES]; static PROBE_PX: [AtomicU32; PROBES] = [const { AtomicU32::new(0) }; PROBES]; static PROBE_N: AtomicUsize = AtomicUsize::new(0); -/// One grid position as the panel left it: the character drawn there and -/// whether it was drawn in the alert colour. +/// One grid position as the panel left it: the character drawn there and its +/// [`Ink`]. /// /// Zero is ground and no character — an unpainted panel, and what a row is /// padded with past the end of its text — so the grid is `.bss` and costs the @@ -912,10 +966,9 @@ struct Cell(u16); impl Cell { const GROUND: Cell = Cell(0); - const ALERT: u16 = 1 << 8; - fn of(byte: u8, alert: bool) -> Self { - Self(glyph_char(byte) as u16 | if alert { Self::ALERT } else { 0 }) + fn of(byte: u8, ink: Ink) -> Self { + Self(glyph_char(byte) as u16 | (ink as u16) << 8) } /// The character on the glass here, or `None` where the cell is ground. @@ -924,8 +977,39 @@ impl Cell { (ch != 0).then_some(ch) } - fn alert(self) -> bool { - self.0 & Self::ALERT != 0 + fn ink(self) -> Ink { + Ink::from_bits((self.0 >> 8) as u8) + } +} + +/// Each [`Ink`] as this framebuffer's pixel. Every one reads at 4.5:1 or +/// better against both grounds [`paint`] fills with (WCAG 2.x's contrast +/// ratio), and every one is at or above `tests/common/screen.rs`'s +/// foreground threshold on its brightest channel. +struct Palette { + plain: u32, + warn: u32, + alert: u32, + stamp: u32, +} + +impl Palette { + fn of(fb: &Fb) -> Self { + Self { + plain: rgb(fb, 0xFF, 0xFF, 0xFF), + warn: rgb(fb, 0xFF, 0xC8, 0x40), + alert: rgb(fb, 0xFF, 0x6E, 0x6E), + stamp: rgb(fb, 0x9E, 0x9E, 0x9E), + } + } + + fn pixel(&self, ink: Ink) -> u32 { + match ink { + Ink::Plain => self.plain, + Ink::Warn => self.warn, + Ink::Alert => self.alert, + Ink::Stamp => self.stamp, + } } } @@ -1053,8 +1137,7 @@ fn paint(fill: Fill, view: View, watch: Watch, stop: impl Fn() -> bool) { Fill::Fatal => rgb(&fb, 0x60, 0x00, 0x00), Fill::Boot => 0, }; - let white = rgb(&fb, 0xFF, 0xFF, 0xFF); - let alert = rgb(&fb, 0xFF, 0x50, 0x50); + let palette = Palette::of(&fb); // SAFETY: every painter holds `PAINTING` for the whole of its paint, so // this is the only reference to the grid while it exists. @@ -1090,14 +1173,18 @@ fn paint(fill: Fill, view: View, watch: Watch, stop: impl Fn() -> bool) { want.fill(Cell::GROUND); let text_row = if r < draw { row_start.get(r).copied() } else { None }; if let Some(row) = text_row { - // Colour comes from the record's severity, so it holds for every display row a wrapped line occupies. - let alerted = view.is_alert(row.line as usize); - for (off, cell) in (row.at as usize..).zip(want.iter_mut()) { + // Colour comes from the record, so it holds for every display row a wrapped line occupies. + let mark = view.mark(row.line as usize); + let at = row.at as usize; + // The head is the record's first line up to its first `]`, which no head holds before its own. + let mut head = mark.opens() && (at == 0 || text.get(at - 1) == Some(&b'\n')); + for (off, cell) in (at..).zip(want.iter_mut()) { let Some(&byte) = text.get(off) else { break }; if byte == b'\n' { break; } - *cell = Cell::of(byte, alerted); + *cell = Cell::of(byte, if head { Ink::Stamp } else { mark.ink() }); + head &= byte != b']'; } } if pages > 1 && r == grid_rows - 1 { @@ -1107,8 +1194,7 @@ fn paint(fill: Fill, view: View, watch: Watch, stop: impl Fn() -> bool) { let glassed = glass.row(r, cols); for (c, (&cell, was)) in want.iter().zip(glassed.iter_mut()).enumerate() { if cell != *was { - let color = if cell.alert() { alert } else { white }; - pixels += draw_cell(&fb, c, r, cell, ground, color); + pixels += draw_cell(&fb, c, r, cell, ground, palette.pixel(cell.ink())); *was = cell; } if watch == Watch::Yes && text_row.is_some() { @@ -1181,7 +1267,7 @@ fn footer_cells(pages: usize, row: &mut [Cell]) { buf[n] = b']'; n += 1; for (cell, &byte) in row.iter_mut().zip(buf[..n].iter()) { - *cell = Cell::of(byte, false); + *cell = Cell::of(byte, Ink::Plain); } } diff --git a/src/kernelconsole.rs b/src/kernelconsole.rs index f90197e1f23..5f033b26291 100644 --- a/src/kernelconsole.rs +++ b/src/kernelconsole.rs @@ -6,9 +6,13 @@ //! 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`]); the bytes the host reads are never coloured. use std::borrow::Cow; +use toyos_logstream::{Severity, Shown}; + /// 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. @@ -46,6 +50,58 @@ impl KernelConsole { } } +/// The console as a terminal shows it: what comes before the kernel's first +/// record as it came, and every line from it on as `toyos_logstream::Shown` +/// draws it — the kernel's records and programs' lines by their heads, and a +/// record's continuation in the severity of the record above 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. +pub struct Painter { + begun: bool, + held: Vec, + severity: Severity, +} + +impl Default for Painter { + fn default() -> Self { + Self { begun: false, held: Vec::new(), severity: Severity::Info } + } +} + +impl Painter { + /// What of the next `chunk` the terminal is shown now. + 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) => { + 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)); + return out; + } + } + } + while let Some(end) = self.held.iter().position(|&b| b == b'\n') { + let line: Vec = self.held.drain(..=end).collect(); + let line = String::from_utf8_lossy(&line[..end]); + let line = line.strip_suffix('\r').unwrap_or(&line); + let shown = + toyos_logstream::shown(line).unwrap_or(Shown { head: None, severity: self.severity, text: line }); + self.severity = shown.severity; + out.extend_from_slice(format!("{shown}\n").as_bytes()); + } + out + } +} + #[cfg(test)] mod tests { use super::*; @@ -97,6 +153,42 @@ mod tests { assert_eq!(passed(&later, &[3, 40]), later); } + /// What the terminal is shown of `stream` fed in pieces cut at each of `cuts`. + fn painted(stream: &str, cuts: &[usize]) -> String { + let mut painter = Painter::default(); + let mut out = Vec::new(); + let mut from = 0; + for &to in cuts.iter().chain([stream.len()].iter()) { + out.extend_from_slice(&painter.pass(&stream.as_bytes()[from..to])); + from = to; + } + String::from_utf8(out).expect("the painter writes UTF-8") + } + + /// The firmware's bytes reach the terminal as they came, the kernel's + /// lines as a screen shows them, a continuation in its record's severity — + /// 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 stream = format!("{FIRMWARE}{KERNEL}{alert}{program}"); + let mut want = String::from(FIRMWARE); + let mut severity = Severity::Info; + for line in format!("{KERNEL}{alert}{program}").lines() { + let shown = toyos_logstream::shown(line).unwrap_or(Shown { head: None, severity, text: line }); + severity = shown.severity; + want.push_str(&format!("{shown}\n")); + } + assert!(want.contains("\x1b[91m oops\x1b[0m\n"), "{want:?}"); + 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. + assert_eq!(painted(&FIRMWARE[..FIRMWARE.len() - 3], &[]), FIRMWARE[..FIRMWARE.len() - 3]); + assert_eq!(painted("so [ker", &[]), "so "); + } + #[test] fn nothing_before_the_kernel_passes() { assert_eq!(passed(FIRMWARE, &[5, 200]), ""); diff --git a/src/qemu.rs b/src/qemu.rs index 100b509b05f..a8cdbaa1b94 100644 --- a/src/qemu.rs +++ b/src/qemu.rs @@ -47,10 +47,12 @@ //! slow is the clock, RTF well below 1.0 is synthesis not keeping up. use std::fs::File; +use std::io::{IsTerminal, Read, Write}; use std::path::PathBuf; -use std::process::Command; +use std::process::{Command, Stdio}; use toyos_build::arch::Arch; +use toyos_build::kernelconsole::Painter; /// The hardware shape QEMU presents to the guest. /// @@ -278,13 +280,33 @@ pub fn launch(opts: &Options) { eprintln!("QEMU interrupt log: /tmp/toyos-qemu-debug.log"); } - // Serial output goes to stdout (stdio), so keep stdout attached to terminal. // Capture QEMU's own stderr to a file for post-mortem analysis. let stderr_file = File::create("/tmp/toyos-qemu-stderr.log").expect("create stderr log"); qemu.stderr(stderr_file); eprintln!("QEMU stderr log: /tmp/toyos-qemu-stderr.log"); - qemu.status().expect("failed to execute QEMU"); + // A terminal is shown the console in colour; a file or a pipe gets its bytes. + if !std::io::stdout().is_terminal() { + qemu.status().expect("failed to execute QEMU"); + return; + } + let mut child = qemu.stdout(Stdio::piped()).spawn().expect("failed to execute QEMU"); + let mut console = child.stdout.take().expect("QEMU's stdout is piped"); + let relay = std::thread::spawn(move || { + let mut painter = Painter::default(); + let mut buf = [0u8; 4096]; + let mut out = std::io::stdout(); + loop { + let n = console.read(&mut buf).expect("QEMU's console refused a read"); + if n == 0 { + return; + } + out.write_all(&painter.pass(&buf[..n])).expect("the terminal refused the console"); + out.flush().expect("the terminal refused the console"); + } + }); + child.wait().expect("failed to wait for QEMU"); + relay.join().expect("the console relay"); } /// The machine a profile runs on, with its IOMMU where the machine carries one diff --git a/tests/common/screen.rs b/tests/common/screen.rs index f8d46326df1..9ffdc044a9e 100644 --- a/tests/common/screen.rs +++ b/tests/common/screen.rs @@ -22,10 +22,10 @@ const GLYPHS: usize = 95; /// assertion can never accidentally pass on undecodable pixels. pub const UNKNOWN: char = '\u{fffd}'; -/// Foreground threshold on the brightest channel. The renderer draws white -/// (0xFF) or alert red (0xFF,0x50,0x50) over a dark red (0x60,0,0) or black +/// Foreground threshold on the brightest channel. The renderer draws every +/// ink with a channel at 0x9E or above over a dark red (0x60,0,0) or black /// fill, so anything at or above this is text and anything below is -/// background, with 0x30 of margin on both sides. +/// background, with 0x0E and 0x30 of margin. const FG_THRESHOLD: u8 = 0x90; pub struct Ppm { @@ -143,6 +143,26 @@ impl Ppm { None } + /// The colour of the first foreground pixel of `needle`'s own cells, on + /// the first cell row carrying it; `None` where no row does or its cells + /// are blank. A row's head and its text are drawn apart, so this — and not + /// [`Ppm::row_fg`] — is the colour of the text. + pub fn fg_of(&self, needle: &str) -> Option<[u8; 3]> { + let rows = self.rows(); + let (cy, at) = rows.iter().enumerate().find_map(|(cy, row)| Some((cy, row.find(needle)?)))?; + let cx = rows[cy][..at].chars().count(); + let cells = cx..cx + needle.chars().count(); + for y in cy * GLYPH_H..(cy + 1) * GLYPH_H { + for x in cells.start * GLYPH_W..cells.end * GLYPH_W { + let p = self.pixels[y * self.width + x]; + if p[0].max(p[1]).max(p[2]) >= FG_THRESHOLD { + return Some(p); + } + } + } + None + } + /// The fill colour, read from the bottom-right pixel. The renderer paints /// at most `MAX_ROWS` rows and never the last column of a glyph cell, so /// this corner carries the fill and nothing else. diff --git a/tests/toyos.rs b/tests/toyos.rs index 7fac3b67117..09e95188f4b 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -985,9 +985,11 @@ fn c_corpus_metal( /// The comparator's own staged name. It is a `RUST_SKIP` helper, so discovery /// never makes a job of it and [`shared_metal`] stages it as one. const CCHECK: &str = "test_rs_ccheck"; -/// The renderer's two text colours, as the screendump reports them. +/// The renderer's inks for `Info` text, `Alert` text and a record's head, as +/// the screendump reports them. const WHITE: [u8; 3] = [0xFF, 0xFF, 0xFF]; -const ALERT: [u8; 3] = [0xFF, 0x50, 0x50]; +const ALERT: [u8; 3] = [0xFF, 0x6E, 0x6E]; +const STAMP: [u8; 3] = [0x9E, 0x9E, 0x9E]; /// And the fill a halted machine leaves behind. const FILL_FATAL: [u8; 3] = [0x60, 0x00, 0x00]; /// The fill a boot checkpoint leaves behind. It is the only thing that tells a @@ -1404,8 +1406,9 @@ fn print_screen(name: &str, text: &str) { } } -/// Assert the colour decisions `text()` cannot see: the fill, every row an -/// `alert!` produced, and one row it did not. +/// Assert the colour decisions `text()` cannot see: the fill, the text of +/// every row an `alert!` produced and of one row it did not, and the head the +/// record's first row opens with. /// /// **Both rows are named by their text, and that is the whole assertion.** /// Nothing in the message says "alert" any more — the colour is the record's @@ -1428,34 +1431,38 @@ fn check_colors( if dump.fill() != fill { return Err(format!("fill is {:?}, want {fill:?}", dump.fill())); } - let rows = dump.rows(); for alert_line in alert_lines { - let Some(cy) = dump.row_index(alert_line) else { + let Some(fg) = dump.fg_of(alert_line) else { return Err(format!("{alert_line:?} not on screen\n{}", dump.text())); }; - if dump.row_fg(cy) != Some(ALERT) { + if fg != ALERT { return Err(format!( - "{alert_line:?} drawn in {:?}, want alert {ALERT:?} — every row of an \ + "{alert_line:?} drawn in {fg:?}, want alert {ALERT:?} — every row of an \ `alert!` record wears its level, including the ones its message wrapped \ or newlined onto\n{}", - dump.row_fg(cy), dump.text() )); } } - let Some(plain) = dump.row_index(plain_line) else { + // The record's first row opens with its head, drawn dim and apart from its text. + let opens = alert_lines.first().and_then(|line| dump.row_index(line)); + if let Some(cy) = opens.filter(|&cy| dump.row_fg(cy) != Some(STAMP)) { + return Err(format!( + "the head of {:?} drawn in {:?}, want the stamp's {STAMP:?}\n{}", + dump.rows()[cy], + dump.row_fg(cy), + dump.text() + )); + } + let Some(fg) = dump.fg_of(plain_line) else { return Err(format!( "{plain_line:?} is not on screen, so there is no ordinary row to compare the \ highlight against\n{}", dump.text() )); }; - if dump.row_fg(plain) != Some(WHITE) { - return Err(format!( - "ordinary row {:?} drawn in {:?}, want white {WHITE:?}", - rows[plain], - dump.row_fg(plain) - )); + if fg != WHITE { + return Err(format!("ordinary text {plain_line:?} drawn in {fg:?}, want white {WHITE:?}")); } Ok(()) } diff --git a/toyos-abi/src/log.rs b/toyos-abi/src/log.rs index 4a9d6efa914..56456749f6c 100644 --- a/toyos-abi/src/log.rs +++ b/toyos-abi/src/log.rs @@ -37,9 +37,10 @@ pub const MAX_LOG_SHARDS: usize = 8; /// /// **Four because four have writers and readers.** The kernel writes `Info` /// (`log!`) and `Alert` (`alert!`); a program's stdout is `Info` and its stderr -/// `Error`, and its own lines choose. The panel paints `Error` and above red; -/// `/system/bin/logkeeper` names every one above `Info` in the line, and makes the -/// volume durable at `Alert` rather than on its interval. +/// `Error`, and its own lines choose. Every rendered line names one above +/// `Info` by its [`word`](Self::word), a screen colours the line by it, and +/// `/system/bin/logkeeper` makes the volume durable at `Alert` rather than on +/// its interval. #[derive(Debug, Clone, Copy, PartialEq, Eq, PartialOrd, Ord)] #[repr(u8)] pub enum Severity { @@ -207,6 +208,9 @@ impl LogRecord { if self.is_early() { f.write_str(" boot")?; } + if let Some(word) = self.severity().and_then(Severity::word) { + write!(f, " {word}")?; + } if self.tid != 0 { write!(f, " tid={}", self.tid)?; } @@ -360,14 +364,20 @@ mod tests { assert_eq!(early.tagged("kernel").to_string(), "[kernel 1.234 cpu2 boot] x"); } - /// The two decorations, each of which a consumer would otherwise invent. + /// The three decorations, each of which a consumer would otherwise invent. #[test] - fn early_and_elided_are_in_the_line_rather_than_in_a_convention() { + fn early_severity_and_elided_are_in_the_line_rather_than_in_a_convention() { let mut r = record("x"); r.flags = FLAG_EARLY; r.tid = 0; assert_eq!(r.to_string(), "[1.234 cpu2 boot] x"); + let mut r = record("x"); + r.severity = Severity::Alert as u8; + assert_eq!(r.tagged("kernel").to_string(), "[kernel 1.234 cpu2 alert tid=4] x"); + r.flags = FLAG_EARLY; + assert_eq!(r.to_string(), "[1.234 cpu2 boot alert tid=4] x"); + let mut r = record("x"); r.elided = 900; assert_eq!(r.to_string(), "[1.234 cpu2 tid=4] x …[900 bytes elided]"); diff --git a/toyos-logstream/src/lib.rs b/toyos-logstream/src/lib.rs index 7abd58aee23..ef3c62257ca 100644 --- a/toyos-logstream/src/lib.rs +++ b/toyos-logstream/src/lib.rs @@ -18,7 +18,9 @@ //! [`Text`] writes every control byte as text. //! //! The same form goes to the console, where `logkeeper` is the one writer of -//! program lines, without the wall-clock stamp. +//! program lines, without the wall-clock stamp. A terminal shows either in +//! the console's form and in colour ([`Shown`]); no line of the log carries a +//! colour. //! //! Pure: `core` and `alloc`, no `unsafe`, no I/O. @@ -257,38 +259,135 @@ pub fn program_line(line: &str) -> Option> { let rest = line.strip_prefix(OPEN)?; let (head, text) = rest.split_once(CLOSE)?; let text = text.strip_prefix(' ')?; - let mut words = head.rsplit(' '); - let tag = words.next()?; + let (words, tag) = head.rsplit_once(' ').unwrap_or(("", head)); Tag::new(tag)?; - let severity = words + Some(Said { tag, severity: severity_in(words), text }) +} + +/// The severity a head's words name, `Info` where none does. +fn severity_in(words: &str) -> Severity { + words + .split(' ') .find_map(|word| { [Severity::Warn, Severity::Error, Severity::Alert] .into_iter() .find(|s| s.word() == Some(word)) }) - .unwrap_or(Severity::Info); - Some(Said { tag, severity, text }) + .unwrap_or(Severity::Info) } -/// The milliseconds since boot a kernel record's line carries, or `None` for -/// any other line. +/// A kernel record's line as its head and text: the head inside the bracket, +/// from the word before the CPU on — the time — and the text after it. /// /// **Found from the CPU it precedes rather than by position**: the field before -/// it is the writer's tag, and the writers disagree about it on purpose — -/// `logkeeper` puts a wall clock there and the panel puts nothing. -/// -/// Read inside the record's bracket and nowhere else, so no text after it — a -/// program's included — can answer for the time. -pub fn record_ms(line: &str) -> Option { - let (head, _) = line.strip_prefix('[')?.split_once("] ")?; +/// the time is the writer's tag, and the writers disagree about it on purpose — +/// `logkeeper` puts a wall clock there, the console `kernel` and the panel +/// nothing. Read inside the record's bracket and nowhere else, so no text after +/// it — a program's included — can answer for the time. +fn record_head(line: &str) -> Option<(&str, &str)> { + let (head, text) = line.strip_prefix('[')?.split_once("] ")?; let (before, _) = head.split_once(" cpu")?; - let field = before.split_whitespace().next_back()?; + let stamp = &head[before.rfind(' ').map_or(0, |at| at + 1)..]; + millis(stamp.split(' ').next()?)?; + Some((stamp, text)) +} + +/// `.` as milliseconds. +fn millis(field: &str) -> Option { let (secs, millis) = field.split_once('.')?; let secs: u64 = secs.parse().ok()?; let millis: u64 = millis.parse().ok()?; secs.checked_mul(1_000)?.checked_add(millis) } +/// The milliseconds since boot a kernel record's line carries, or `None` for +/// any other line. +pub fn record_ms(line: &str) -> Option { + millis(record_head(line)?.0.split(' ').next()?) +} + +/// Whose a line on a screen is. +#[derive(Clone, Copy, Debug, PartialEq, Eq)] +pub enum Source<'a> { + Kernel, + /// A program, by its [`Tag`]. + Program(&'a str), +} + +/// What opens a line on a screen: whose it is, and its stamp — the head's +/// words from the time since boot on, so the CPU where the record carries one, +/// and never the wall clock, which only `/log` keeps. +#[derive(Clone, Copy, Debug, PartialEq, Eq)] +pub struct Head<'a> { + pub source: Source<'a>, + /// `1.193 cpu0 alert tid=3` for the kernel's, `1.234 warn tid=2` for a program's. + pub stamp: &'a str, +} + +/// A line of the log as a terminal shows it: the console's form, with no wall +/// clock, coloured by the line's severity and whose it is, and its text with +/// no byte that acts ([`Text`]). The colour is this rendering's and never in +/// the line it was read from. +/// +/// `head` is `None` for a kernel record's continuation, which wears the +/// severity of the record above it. +#[derive(Clone, Copy, Debug, PartialEq, Eq)] +pub struct Shown<'a> { + pub head: Option>, + pub severity: Severity, + pub text: &'a str, +} + +/// Read a kernel record's line or a program's — in `/log`'s form or the +/// console's, its newline optional — as a screen shows it; `None` for any +/// other line, a record's continuation included. +pub fn shown(line: &str) -> Option> { + let line = line.strip_suffix('\n').unwrap_or(line); + if let Some(said) = program_line(line) { + let head = line[OPEN.len_utf8()..].split_once(CLOSE)?.0; + let words = head.strip_suffix(said.tag)?.trim_end(); + // The time is the first word that is one: `/log`'s wall clock is none. + let from: usize = + words.split(' ').take_while(|word| millis(word).is_none()).map(|word| word.len() + 1).sum(); + let stamp = words.get(from..).filter(|stamp| !stamp.is_empty())?; + let head = Head { source: Source::Program(said.tag), stamp }; + return Some(Shown { head: Some(head), severity: said.severity, text: said.text }); + } + let (stamp, text) = record_head(line)?; + let head = Head { source: Source::Kernel, stamp }; + Some(Shown { head: Some(head), severity: severity_in(stamp), text }) +} + +/// The SGR words a [`Shown`] is drawn in. The stamp is a grey and not SGR 2, +/// which `/system/bin/terminal` does not draw; the rest are the sixteen colours +/// a host terminal's theme keeps legible on its own ground. +const STAMP: &str = "\x1b[38;5;245m"; +const KERNEL: &str = "\x1b[94m"; +const PROGRAM: &str = "\x1b[36m"; +const WARN: &str = "\x1b[33m"; +const ERROR: &str = "\x1b[91m"; +const RESET: &str = "\x1b[0m"; + +impl Display for Shown<'_> { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + match self.head { + Some(Head { source: Source::Kernel, stamp }) => { + write!(f, "{STAMP}[{KERNEL}kernel{STAMP} {stamp}]{RESET} ")? + } + Some(Head { source: Source::Program(tag), stamp }) => { + write!(f, "{STAMP}{OPEN}{stamp} {PROGRAM}{tag}{STAMP}{CLOSE}{RESET} ")? + } + None => {} + } + let ink = match self.severity { + Severity::Info => "", + Severity::Warn => WARN, + Severity::Error | Severity::Alert => ERROR, + }; + write!(f, "{ink}{}{RESET}", Text(self.text.as_bytes())) + } +} + /// Whether `line` opens as a program's line: what a judge of the kernel's /// records leaves out. pub fn is_program_line(line: &str) -> bool { @@ -554,6 +653,96 @@ mod tests { assert_eq!(record_ms(""), None); } + /// What a terminal shows of a line, with its colours taken out. + fn plain(shown: Shown<'_>) -> String { + let painted = format!("{shown}"); + let mut out = String::new(); + let mut rest = painted.as_str(); + while let Some((before, after)) = rest.split_once('\x1b') { + out.push_str(before); + rest = &after[after.find('m').expect("an SGR ends in m") + 1..]; + } + out.push_str(rest); + out + } + + fn kernel_record(severity: Severity, flags: u8, msg: &str) -> toyos_abi::log::LogRecord { + let mut r = toyos_abi::log::LogRecord { + seq: 1, + at_ns: 1_193_000_000, + cpu: 3, + tid: 7, + severity: severity as u8, + flags, + len: msg.len() as u16, + ..toyos_abi::log::LogRecord::EMPTY + }; + r.msg[..msg.len()].copy_from_slice(msg.as_bytes()); + r + } + + /// **A screen shows the console's line, whichever form it read**: `/log`'s + /// line and the console's, each made by its own writer's formatter, show + /// as the console's line, with the time since boot and the CPU and no wall + /// clock — for every severity, the kernel's records and a program's both. + #[test] + fn a_screen_shows_the_consoles_line_from_either_form() { + let wall = "2026-10-04 09:30:00"; + for severity in [Severity::Info, Severity::Warn, Severity::Error, Severity::Alert] { + for flags in [0, toyos_abi::log::FLAG_EARLY] { + let record = kernel_record(severity, flags, "spawn: /system/bin/netstack pid=5"); + let console = format!("{}", record.tagged("kernel")); + for line in [format!("{}", record.tagged(wall)), console.clone()] { + let shown = shown(&line).expect("a kernel record"); + assert_eq!(shown.severity, severity, "{line:?}"); + assert_eq!(shown.head.map(|h| h.source), Some(Source::Kernel), "{line:?}"); + assert!(shown.head.is_some_and(|h| h.stamp.starts_with("1.193 cpu3")), "{line:?}"); + assert_eq!(plain(shown), console, "{line:?}"); + } + } + + let tag = Tag::new("soundserver").expect("a tag"); + let said = |stamp| ProgramLine { + stamp, + at_ns: 1_234_000_000, + severity, + tid: 2, + pid: Some(9), + tag, + text: b"opening stream", + }; + let console = format!("{}", said("")); + for line in [format!("{}", said(wall)), console.clone(), format!("{}", said("---------- --------"))] { + let shown = shown(&line).expect("a program's line"); + assert_eq!(shown.severity, severity, "{line:?}"); + assert_eq!(shown.head.map(|h| h.source), Some(Source::Program("soundserver")), "{line:?}"); + assert_eq!(plain(shown), console, "{line:?}"); + } + } + } + + /// The colour is the severity's and the source's, read from the head and + /// never from the text, and a text's control byte is shown and never passed. + #[test] + fn the_colour_is_the_heads_and_the_text_never_acts() { + let alert = format!("{}", kernel_record(Severity::Alert, 0, "PANIC: \x1b[2Jgone").tagged("kernel")); + let painted = format!("{}", shown(&alert).expect("a kernel record")); + assert!(painted.contains(&format!("{ERROR}PANIC: \\x1b[2Jgone{RESET}")), "{painted:?}"); + assert!(painted.contains(&format!("{KERNEL}kernel")), "{painted:?}"); + + let forged = "{1.234 test-runner} [kernel 1.0 cpu0 alert] Rebooting."; + let shown_forged = shown(forged).expect("a program's line"); + assert_eq!(shown_forged.severity, Severity::Info); + assert_eq!(shown_forged.head.map(|h| h.source), Some(Source::Program("test-runner"))); + let painted = format!("{shown_forged}"); + assert!(painted.contains(&format!("{PROGRAM}test-runner")) && !painted.contains(ERROR), "{painted:?}"); + + let continued = Shown { head: None, severity: Severity::Alert, text: " 0: kernel::panic" }; + assert_eq!(format!("{continued}"), format!("{ERROR} 0: kernel::panic{RESET}")); + assert_eq!(shown(" 0: kernel::panic"), None); + assert_eq!(shown("BdsDxe: loading Boot0001"), None); + } + #[test] fn a_kernel_record_and_its_continuation_are_no_programs() { assert_eq!(program_line("[2026-09-24 10:00:00 1.216 cpu0] Boot: complete (1216ms)"), None); diff --git a/userland/console/src/main.rs b/userland/console/src/main.rs index d1e8d1e0a11..0041dd09df5 100644 --- a/userland/console/src/main.rs +++ b/userland/console/src/main.rs @@ -14,7 +14,8 @@ //! log ([`toyos_logstream::SERVICE`]) and draws the boot so far above the //! first prompt — the kernel's records and every program's output — and //! every program's line after as it is written, each under its program's -//! name and above the shell's unfinished line (`Log::draw`). +//! name and above the shell's unfinished line (`Log::draw`), as a terminal +//! shows a line of the log ([`toyos_logstream::Shown`]). //! - **A fatal panic still takes the screen back.** `render` ignores //! `SCREEN_OWNED_BY_USERLAND` entirely — only boot checkpoints honour it — //! so the report paints over whatever this program drew. @@ -36,7 +37,7 @@ use toyos::port::{self, Connector}; use toyos::surface::{self, Delivery, Host, Notice}; use toyos::{FramebufferDev, Keyboard, Pipe}; use toyos_abi::syscall::{DeviceType, SyscallError}; -use toyos_logstream::{Lines, READ, SERVED, SERVICE}; +use toyos_logstream::{Lines, Severity, Shown, Source, READ, SERVED, SERVICE}; use window::Screen; const FONT: &str = "/system/share/fonts/JetBrainsMono-Regular-8x16.font"; @@ -70,6 +71,8 @@ struct Log { /// Whether the last kernel record was kept, which its continuation lines /// follow. drawing: bool, + /// The last kernel record's severity, which its continuation lines wear. + severity: Severity, /// Lines kept and not yet drawn. held: Vec, } @@ -90,7 +93,15 @@ impl Log { // SAFETY: the kernel moved this handle into this table with the frame // that names it, and nothing else answers for it. let pipe = unsafe { Pipe::from_raw(raw) }; - Ok(Self { pipe, lines: Lines::new(), handed, asked_ms, drawing: true, held: Vec::new() }) + Ok(Self { + pipe, + lines: Lines::new(), + handed, + asked_ms, + drawing: true, + severity: Severity::Info, + held: Vec::new(), + }) } /// Take every whole line in `bytes` that goes on the screen. @@ -100,22 +111,30 @@ impl Log { /// asked** — the boot so far, as the panel it took over would have shown /// it. A record after that is not drawn: it would put a `spawn:` and an /// `exit:` beside every command typed. + /// + /// Each is drawn as [`toyos_logstream::Shown`] draws it; a continuation + /// wears the severity of the kernel record above it. fn take(&mut self, bytes: &[u8]) { - let (asked_ms, drawing, held) = (self.asked_ms, &mut self.drawing, &mut self.held); + let (asked_ms, drawing, severity, held) = + (self.asked_ms, &mut self.drawing, &mut self.severity, &mut self.held); self.lines.push(bytes, |line, _| { - let text = std::str::from_utf8(line).ok(); - let keep = match text.and_then(toyos_logstream::program_line) { - Some(said) => said.tag != OWN_TAG, - None => { - if let Some(ms) = text.and_then(toyos_logstream::record_ms) { - *drawing = ms < asked_ms; - } - *drawing + let line = String::from_utf8_lossy(line); + let shown = match toyos_logstream::shown(&line) { + Some(shown) => { + let keep = match shown.head.map(|head| head.source) { + Some(Source::Program(tag)) => tag != OWN_TAG, + _ => { + *drawing = toyos_logstream::record_ms(&line).is_some_and(|ms| ms < asked_ms); + *severity = shown.severity; + *drawing + } + }; + keep.then_some(shown) } + None => (*drawing).then_some(Shown { head: None, severity: *severity, text: &line }), }; - if keep { - held.extend_from_slice(line); - held.push(b'\n'); + if let Some(shown) = shown { + held.extend_from_slice(format!("{shown}\n").as_bytes()); } }); } From ff6735dd1a3247bf07669e85ab9d9d5975c6dd0e Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 4 Oct 2026 13:17:02 +0200 Subject: [PATCH 2/7] Answer review round 1: one reader for a line's severity, a relay that waits out the terminal, two-bit marks - toyos-logstream's `Showing` is the one stateful reader of the log's lines as a screen shows them: a line that is no kernel record's and no program's continues the last kernel record and wears its severity, whatever program lines came between. `/system/bin/console` and `kernelconsole::Painter` both read through it, where each had its own copy and the two disagreed about a program line in between. `shown` is private to it. - `Painter::finish` gives back what the painter still holds once the console ends: a line cut by a machine that stopped mid-line, or bytes that could have begun `[kernel `. Before, the relay dropped them at EOF. - `kernelconsole::relay` is the relay, in the library where a host test reaches it, and `cargo run` writes through an unbuffered duplicate of its stdout. A write refused as `WouldBlock` waits on `poll(POLLOUT)` and goes on. QEMU 11.1.1's stdio chardev makes fd 0 non-blocking (`chardev/char-stdio.c`, `stdio_chr_open`: `qemu_set_blocking(0, false, errp)`), and a terminal's fd 0 and this process's stdout are usually one open file description, so the flag is on the relay's stdout too. - The panel's Warn ink and its amber go: the panel reads kernel records, and the kernel writes only Info and Alert. A mark is two bits (alert, opens), 8 KiB per `Rendered` rather than 16 KiB. - `check_colors` checks the named text on every row carrying it, so a wrapped row of an ordinary record's first line must be white, not stamp grey. - issues/diagnostics/a-programs-line-on-a-screen-names-no-cpu.md records that a program's line carries no CPU. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01WcU2Dsw6mDYtwYfzVHPzM8 --- ...-programs-line-on-a-screen-names-no-cpu.md | 22 +++ kernel/src/drivers/panic_console/mod.rs | 73 +++---- src/kernelconsole.rs | 185 +++++++++++++++--- src/qemu.rs | 21 +- tests/common/screen.rs | 29 ++- tests/toyos.rs | 53 ++--- toyos-logstream/src/lib.rs | 54 ++++- userland/console/src/main.rs | 38 ++-- 8 files changed, 331 insertions(+), 144 deletions(-) create mode 100644 issues/diagnostics/a-programs-line-on-a-screen-names-no-cpu.md diff --git a/issues/diagnostics/a-programs-line-on-a-screen-names-no-cpu.md b/issues/diagnostics/a-programs-line-on-a-screen-names-no-cpu.md new file mode 100644 index 00000000000..4f84397c2d6 --- /dev/null +++ b/issues/diagnostics/a-programs-line-on-a-screen-names-no-cpu.md @@ -0,0 +1,22 @@ +--- +status: open +kind: defect +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 +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 +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`. + +Owner: orchestrator. Exit condition: one of two. Either a program's record +carries the CPU its writer stamped it on, every program line `logkeeper` writes +names it as `cpu` after the time, and `toyos-logstream`'s +`a_screen_shows_the_consoles_line_from_either_form` requires it of a +program's line. Or the owner rules that a program's line needs no CPU, and +this file is deleted with that ruling in its commit message. diff --git a/kernel/src/drivers/panic_console/mod.rs b/kernel/src/drivers/panic_console/mod.rs index 8786cba83e3..c6040253026 100644 --- a/kernel/src/drivers/panic_console/mod.rs +++ b/kernel/src/drivers/panic_console/mod.rs @@ -39,8 +39,8 @@ const MAX_ROWS: usize = 96; const SNAPSHOT_CAP: usize = 32 * 1024; const _: () = assert!(SNAPSHOT_CAP >= MAX_ROWS * MAX_COLS); -/// One [`Mark`] a nibble per byte `text` can hold — worst case is a message of nothing but newlines, one line per byte. -const MARK_BYTES: usize = SNAPSHOT_CAP.div_ceil(2); +/// One two-bit [`Mark`] per byte `text` can hold — worst case is a message of nothing but newlines, one line per byte. +const MARK_BYTES: usize = SNAPSHOT_CAP.div_ceil(4); /// How long Ctrl+Alt+D's report keeps the panel. const REPORT_HOLD: Budget = Budget::of( @@ -103,51 +103,33 @@ struct FbCell(UnsafeCell); // SAFETY: the panic path may take no lock; `PENDING` has one writer at a time. unsafe impl Sync for FbCell {} -/// What a line's text is drawn in. +/// What a cell is drawn in. #[derive(Clone, Copy, PartialEq, Eq)] enum Ink { + /// A record's text below `Error`. Plain = 0, - Warn = 1, - Alert = 2, + /// An `Error` or `Alert` record's text. + Alert = 1, /// The head a record's first line opens with: its time, CPU and thread. - Stamp = 3, + Stamp = 2, } -impl Ink { - /// A record's text: by its severity, and plain for a byte no severity is. - fn of(severity: Option) -> Self { - match severity { - None | Some(log::Severity::Info) => Ink::Plain, - Some(log::Severity::Warn) => Ink::Warn, - Some(log::Severity::Error | log::Severity::Alert) => Ink::Alert, - } - } - - fn from_bits(bits: u8) -> Self { - match bits & 3 { - 0 => Ink::Plain, - 1 => Ink::Warn, - 2 => Ink::Alert, - _ => Ink::Stamp, - } - } -} - -/// One line of a rendered log as its record made it: the ink of its text, and -/// whether it opens the record and so carries the head. Read from the record, -/// never inferred from the text. +/// One line of a rendered log as its record made it: whether its text is in +/// the alert ink, and whether it opens the record and so carries the head. +/// Read from the record, never inferred from the text. #[derive(Clone, Copy)] struct Mark(u8); impl Mark { - const OPENS: u8 = 1 << 2; + const ALERT: u8 = 1; + const OPENS: u8 = 2; - fn new(ink: Ink, opens: bool) -> Self { - Self(ink as u8 | if opens { Self::OPENS } else { 0 }) + fn new(alert: bool, opens: bool) -> Self { + Self(if alert { Self::ALERT } else { 0 } | if opens { Self::OPENS } else { 0 }) } fn ink(self) -> Ink { - Ink::from_bits(self.0) + if self.0 & Self::ALERT != 0 { Ink::Alert } else { Ink::Plain } } fn opens(self) -> bool { @@ -158,7 +140,7 @@ impl Mark { /// A screenful-and-then-some of rendered log, and each line's [`Mark`]. struct Rendered { text: [u8; SNAPSHOT_CAP], - /// One nibble per line, counted back from the last — the buffer fills from its end. + /// Four marks a byte, one per line, counted back from the last — the buffer fills from its end. marks: [u8; MARK_BYTES], /// Bytes of `text` in use, at its end. len: usize, @@ -201,9 +183,9 @@ struct View<'a> { impl View<'_> { /// Line `n`'s mark, counted from the first. fn mark(&self, n: usize) -> Mark { - let Some(from_end) = self.lines.checked_sub(n + 1) else { return Mark::new(Ink::Plain, false) }; - let byte = self.marks.get(from_end / 2).copied().unwrap_or(0); - Mark(byte >> (from_end % 2 * 4) & 0xF) + let Some(from_end) = self.lines.checked_sub(n + 1) else { return Mark::new(false, false) }; + let byte = self.marks.get(from_end / 4).copied().unwrap_or(0); + Mark(byte >> (from_end % 4 * 2) & 3) } } @@ -225,12 +207,12 @@ impl log::read::RecordSink for Backfill<'_> { // Counted in newlines, not records: `paint` counts newlines, and a multi-line record (every panic) is more than one row. let lines = out.iter().filter(|&&byte| byte == b'\n').count(); - let ink = Ink::of(record.severity()); + let alert = record.severity().is_some_and(|s| s >= log::Severity::Error); for line in self.into.lines..self.into.lines + lines { // Counted from the end, so the record's first line is its last here. - let mark = Mark::new(ink, line + 1 == self.into.lines + lines); - if let Some(byte) = self.into.marks.get_mut(line / 2) { - *byte |= mark.0 << (line % 2 * 4); + let mark = Mark::new(alert, line + 1 == self.into.lines + lines); + if let Some(byte) = self.into.marks.get_mut(line / 4) { + *byte |= mark.0 << (line % 4 * 2); } } self.into.lines += lines; @@ -978,7 +960,11 @@ impl Cell { } fn ink(self) -> Ink { - Ink::from_bits((self.0 >> 8) as u8) + match self.0 >> 8 { + 0 => Ink::Plain, + 1 => Ink::Alert, + _ => Ink::Stamp, + } } } @@ -988,7 +974,6 @@ impl Cell { /// foreground threshold on its brightest channel. struct Palette { plain: u32, - warn: u32, alert: u32, stamp: u32, } @@ -997,7 +982,6 @@ impl Palette { fn of(fb: &Fb) -> Self { Self { plain: rgb(fb, 0xFF, 0xFF, 0xFF), - warn: rgb(fb, 0xFF, 0xC8, 0x40), alert: rgb(fb, 0xFF, 0x6E, 0x6E), stamp: rgb(fb, 0x9E, 0x9E, 0x9E), } @@ -1006,7 +990,6 @@ impl Palette { fn pixel(&self, ink: Ink) -> u32 { match ink { Ink::Plain => self.plain, - Ink::Warn => self.warn, Ink::Alert => self.alert, Ink::Stamp => self.stamp, } diff --git a/src/kernelconsole.rs b/src/kernelconsole.rs index 5f033b26291..d40f04fa7db 100644 --- a/src/kernelconsole.rs +++ b/src/kernelconsole.rs @@ -7,11 +7,13 @@ //! 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`]); the bytes the host reads are never coloured. +//! ([`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::{Severity, Shown}; +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 @@ -51,23 +53,16 @@ impl KernelConsole { } /// The console as a terminal shows it: what comes before the kernel's first -/// record as it came, and every line from it on as `toyos_logstream::Shown` -/// draws it — the kernel's records and programs' lines by their heads, and a -/// record's continuation in the severity of the record above it. +/// 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. +#[derive(Default)] pub struct Painter { begun: bool, held: Vec, - severity: Severity, -} - -impl Default for Painter { - fn default() -> Self { - Self { begun: false, held: Vec::new(), severity: Severity::Info } - } + showing: Showing, } impl Painter { @@ -91,15 +86,80 @@ impl Painter { } while let Some(end) = self.held.iter().position(|&b| b == b'\n') { let line: Vec = self.held.drain(..=end).collect(); - let line = String::from_utf8_lossy(&line[..end]); - let line = line.strip_suffix('\r').unwrap_or(&line); - let shown = - toyos_logstream::shown(line).unwrap_or(Shown { head: None, severity: self.severity, text: line }); - self.severity = shown.severity; - out.extend_from_slice(format!("{shown}\n").as_bytes()); + self.show(&line[..end], &mut out); + out.push(b'\n'); + } + out + } + + /// 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`]. + pub fn finish(mut self) -> Vec { + let held = std::mem::take(&mut self.held); + if !self.begun || held.is_empty() { + return held; } + let mut out = Vec::new(); + self.show(&held, &mut out); out } + + fn show(&mut self, line: &[u8], out: &mut Vec) { + let line = String::from_utf8_lossy(line); + let line = line.strip_suffix('\r').unwrap_or(&line); + out.extend_from_slice(self.showing.line(line).to_string().as_bytes()); + } +} + +/// Relay `console` to `terminal` as a [`Painter`] shows it, until `console` +/// ends and what the painter held is written. +/// +/// **A write the terminal refuses as `WouldBlock` waits for it and goes on.** +/// QEMU's stdio chardev makes its fd 0 non-blocking (`stdio_chr_open`, +/// `chardev/char-stdio.c`), and a terminal's fd 0 and this process's stdout +/// are one open file description, which is what holds the flag. +pub fn relay(mut console: impl Read, terminal: &mut (impl Write + AsFd)) -> io::Result<()> { + let mut painter = Painter::default(); + let mut buf = [0u8; 4096]; + loop { + let n = match console.read(&mut buf) { + Ok(n) => n, + Err(e) if e.kind() == io::ErrorKind::Interrupted => continue, + Err(e) => return Err(e), + }; + if n == 0 { + return write_all(terminal, &painter.finish()); + } + write_all(terminal, &painter.pass(&buf[..n]))?; + } +} + +fn write_all(out: &mut (impl Write + AsFd), mut bytes: &[u8]) -> io::Result<()> { + while !bytes.is_empty() { + match out.write(bytes) { + Ok(0) => return Err(io::ErrorKind::WriteZero.into()), + Ok(n) => bytes = &bytes[n..], + Err(e) if e.kind() == io::ErrorKind::Interrupted => {} + Err(e) if e.kind() == io::ErrorKind::WouldBlock => writable(out.as_fd())?, + Err(e) => return Err(e), + } + } + Ok(()) +} + +/// Wait until `fd` takes a write. Unbounded, as a blocking write is: a +/// terminal its user has stopped takes one when the user lets it. +fn writable(fd: BorrowedFd<'_>) -> io::Result<()> { + let mut ready = libc::pollfd { fd: fd.as_raw_fd(), events: libc::POLLOUT, revents: 0 }; + // SAFETY: one `pollfd`, which lives across the call. + if unsafe { libc::poll(&mut ready, 1, -1) } < 0 { + let e = io::Error::last_os_error(); + if e.kind() != io::ErrorKind::Interrupted { + return Err(e); + } + } + Ok(()) } #[cfg(test)] @@ -174,11 +234,9 @@ mod tests { let program = "{0.003 warn supervisor} supervisor: a program's line\n"; let stream = format!("{FIRMWARE}{KERNEL}{alert}{program}"); let mut want = String::from(FIRMWARE); - let mut severity = Severity::Info; + let mut showing = Showing::default(); for line in format!("{KERNEL}{alert}{program}").lines() { - let shown = toyos_logstream::shown(line).unwrap_or(Shown { head: None, severity, text: line }); - severity = shown.severity; - want.push_str(&format!("{shown}\n")); + want.push_str(&format!("{}\n", showing.line(line))); } assert!(want.contains("\x1b[91m oops\x1b[0m\n"), "{want:?}"); assert_eq!(painted(&stream, &[]), want); @@ -189,6 +247,89 @@ mod tests { assert_eq!(painted("so [ker", &[]), "so "); } + /// A console that ends mid-line — a machine that stopped while it spoke — + /// still shows its last line, and one that ends on what could have begun + /// 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 mut painter = Painter::default(); + let mut out = painter.pass(format!("{KERNEL}{cut}").as_bytes()); + out.extend(painter.finish()); + let mut showing = Showing::default(); + let want: String = KERNEL.lines().map(|line| format!("{}\n", showing.line(line))).collect(); + let want = format!("{want}{}", showing.line(cut)); + 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"] { + let mut painter = Painter::default(); + let mut out = painter.pass(early.as_bytes()); + out.extend(painter.finish()); + assert_eq!(out, early.as_bytes()); + } + } + + /// A pipe that refuses a write as `WouldBlock` once it is full, and says so + /// the first time it does. + struct Refusing { + pipe: std::io::PipeWriter, + refused: Option>, + } + + impl Write for Refusing { + fn write(&mut self, bytes: &[u8]) -> io::Result { + let wrote = self.pipe.write(bytes); + if wrote.as_ref().is_err_and(|e| e.kind() == io::ErrorKind::WouldBlock) { + self.refused.take().map(|said| said.send(())); + } + wrote + } + + fn flush(&mut self) -> io::Result<()> { + self.pipe.flush() + } + } + + impl AsFd for Refusing { + fn as_fd(&self) -> BorrowedFd<'_> { + self.pipe.as_fd() + } + } + + /// **A terminal that refuses a write as `WouldBlock` is waited for, and + /// shown every byte in order**: a burst far past a pipe's capacity into a + /// non-blocking pipe nobody reads until it has refused one. + #[test] + fn a_relay_waits_out_a_terminal_that_would_block() { + 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(" continued\n"); + } + stream.push_str("[kernel 9.999 cpu0] cut mid-li"); + let mut painter = Painter::default(); + let mut want = painter.pass(stream.as_bytes()); + want.extend(painter.finish()); + + let (mut reader, pipe) = std::io::pipe().expect("a pipe"); + // SAFETY: `pipe` is an open descriptor this test owns. + let flags = unsafe { libc::fcntl(pipe.as_raw_fd(), libc::F_GETFL) }; + // SAFETY: as above; the flags are its own and `O_NONBLOCK`. + assert!(flags >= 0 && unsafe { libc::fcntl(pipe.as_raw_fd(), libc::F_SETFL, flags | libc::O_NONBLOCK) } == 0); + let (said, refused) = std::sync::mpsc::channel(); + let mut terminal = Refusing { pipe, refused: Some(said) }; + let console = stream.into_bytes(); + let relay = std::thread::spawn(move || relay(console.as_slice(), &mut terminal)); + + refused.recv_timeout(std::time::Duration::from_secs(60)).expect("the pipe never refused a write"); + let mut shown = Vec::new(); + reader.read_to_end(&mut shown).expect("the relay's output"); + relay.join().expect("the relay").expect("the relay wrote everything"); + assert!(shown.len() > 1 << 20, "{} bytes is no burst", shown.len()); + assert!(shown == want, "the terminal was shown {} bytes, not the {} painted", shown.len(), want.len()); + } + #[test] fn nothing_before_the_kernel_passes() { assert_eq!(passed(FIRMWARE, &[5, 200]), ""); diff --git a/src/qemu.rs b/src/qemu.rs index a8cdbaa1b94..bf9dd5f2e6e 100644 --- a/src/qemu.rs +++ b/src/qemu.rs @@ -47,12 +47,13 @@ //! slow is the clock, RTF well below 1.0 is synthesis not keeping up. use std::fs::File; -use std::io::{IsTerminal, Read, Write}; +use std::io::IsTerminal; +use std::os::fd::AsFd; use std::path::PathBuf; use std::process::{Command, Stdio}; use toyos_build::arch::Arch; -use toyos_build::kernelconsole::Painter; +use toyos_build::kernelconsole; /// The hardware shape QEMU presents to the guest. /// @@ -290,20 +291,12 @@ pub fn launch(opts: &Options) { qemu.status().expect("failed to execute QEMU"); return; } + // Unbuffered, so a write the terminal refuses is the relay's to wait out. + let mut terminal = File::from(std::io::stdout().as_fd().try_clone_to_owned().expect("this process's stdout")); let mut child = qemu.stdout(Stdio::piped()).spawn().expect("failed to execute QEMU"); - let mut console = child.stdout.take().expect("QEMU's stdout is piped"); + let console = child.stdout.take().expect("QEMU's stdout is piped"); let relay = std::thread::spawn(move || { - let mut painter = Painter::default(); - let mut buf = [0u8; 4096]; - let mut out = std::io::stdout(); - loop { - let n = console.read(&mut buf).expect("QEMU's console refused a read"); - if n == 0 { - return; - } - out.write_all(&painter.pass(&buf[..n])).expect("the terminal refused the console"); - out.flush().expect("the terminal refused the console"); - } + kernelconsole::relay(console, &mut terminal).expect("the console's relay to the terminal") }); child.wait().expect("failed to wait for QEMU"); relay.join().expect("the console relay"); diff --git a/tests/common/screen.rs b/tests/common/screen.rs index 9ffdc044a9e..6fe371826fa 100644 --- a/tests/common/screen.rs +++ b/tests/common/screen.rs @@ -143,24 +143,23 @@ impl Ppm { None } - /// The colour of the first foreground pixel of `needle`'s own cells, on - /// the first cell row carrying it; `None` where no row does or its cells + /// For every cell row carrying `needle`, that row and the colour of the + /// first foreground pixel of `needle`'s own cells on it, `None` where they /// are blank. A row's head and its text are drawn apart, so this — and not /// [`Ppm::row_fg`] — is the colour of the text. - pub fn fg_of(&self, needle: &str) -> Option<[u8; 3]> { - let rows = self.rows(); - let (cy, at) = rows.iter().enumerate().find_map(|(cy, row)| Some((cy, row.find(needle)?)))?; - let cx = rows[cy][..at].chars().count(); - let cells = cx..cx + needle.chars().count(); - for y in cy * GLYPH_H..(cy + 1) * GLYPH_H { - for x in cells.start * GLYPH_W..cells.end * GLYPH_W { - let p = self.pixels[y * self.width + x]; - if p[0].max(p[1]).max(p[2]) >= FG_THRESHOLD { - return Some(p); - } - } + pub fn fg_of(&self, needle: &str) -> Vec<(String, Option<[u8; 3]>)> { + let mut found = Vec::new(); + for (cy, row) in self.rows().into_iter().enumerate() { + let Some(at) = row.find(needle) else { continue }; + let cx = row[..at].chars().count(); + let cells = cx..cx + needle.chars().count(); + let fg = (cy * GLYPH_H..(cy + 1) * GLYPH_H) + .flat_map(|y| (cells.start * GLYPH_W..cells.end * GLYPH_W).map(move |x| (x, y))) + .map(|(x, y)| self.pixels[y * self.width + x]) + .find(|p| p[0].max(p[1]).max(p[2]) >= FG_THRESHOLD); + found.push((row, fg)); } - None + found } /// The fill colour, read from the bottom-right pixel. The renderer paints diff --git a/tests/toyos.rs b/tests/toyos.rs index 06e0a3f7284..5c0bd41da7a 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -1465,8 +1465,8 @@ fn print_screen(name: &str, text: &str) { } /// Assert the colour decisions `text()` cannot see: the fill, the text of -/// every row an `alert!` produced and of one row it did not, and the head the -/// record's first row opens with. +/// every row an `alert!` produced and of every row carrying a text it did not, +/// and the head the record's first row opens with. /// /// **Both rows are named by their text, and that is the whole assertion.** /// Nothing in the message says "alert" any more — the colour is the record's @@ -1490,17 +1490,13 @@ fn check_colors( return Err(format!("fill is {:?}, want {fill:?}", dump.fill())); } for alert_line in alert_lines { - let Some(fg) = dump.fg_of(alert_line) else { - return Err(format!("{alert_line:?} not on screen\n{}", dump.text())); - }; - if fg != ALERT { - return Err(format!( - "{alert_line:?} drawn in {fg:?}, want alert {ALERT:?} — every row of an \ - `alert!` record wears its level, including the ones its message wrapped \ - or newlined onto\n{}", - dump.text() - )); - } + inked( + dump, + alert_line, + ALERT, + "every row of an `alert!` record wears its level, including the ones its message \ + wrapped or newlined onto", + )?; } // The record's first row opens with its head, drawn dim and apart from its text. let opens = alert_lines.first().and_then(|line| dump.row_index(line)); @@ -1512,17 +1508,28 @@ fn check_colors( dump.text() )); } - let Some(fg) = dump.fg_of(plain_line) else { - return Err(format!( - "{plain_line:?} is not on screen, so there is no ordinary row to compare the \ - highlight against\n{}", - dump.text() - )); - }; - if fg != WHITE { - return Err(format!("ordinary text {plain_line:?} drawn in {fg:?}, want white {WHITE:?}")); + inked( + dump, + plain_line, + WHITE, + "an ordinary record's text is white on every row it fills, a row its first line \ + wrapped onto included, which carries no head", + ) +} + +/// `needle`'s own cells are drawn in `want` on every row carrying it, and +/// some row does. +fn inked(dump: &screen::Ppm, needle: &str, want: [u8; 3], why: &str) -> Result<(), String> { + let rows = dump.fg_of(needle); + if rows.is_empty() { + return Err(format!("{needle:?} not on screen\n{}", dump.text())); + } + match rows.iter().find(|(_, fg)| *fg != Some(want)) { + Some((row, fg)) => { + Err(format!("{needle:?} drawn in {fg:?} on {row:?}, want {want:?} — {why}\n{}", dump.text())) + } + None => Ok(()), } - Ok(()) } /// `tests/toyos-rust-tests`' binary that `tests/virtjobcase` runs as its job diff --git a/toyos-logstream/src/lib.rs b/toyos-logstream/src/lib.rs index ef3c62257ca..7cc6b919f9f 100644 --- a/toyos-logstream/src/lib.rs +++ b/toyos-logstream/src/lib.rs @@ -329,8 +329,8 @@ pub struct Head<'a> { /// no byte that acts ([`Text`]). The colour is this rendering's and never in /// the line it was read from. /// -/// `head` is `None` for a kernel record's continuation, which wears the -/// severity of the record above it. +/// `head` is `None` for a kernel record's continuation, which [`Showing`] +/// gives the severity of the record above it. #[derive(Clone, Copy, Debug, PartialEq, Eq)] pub struct Shown<'a> { pub head: Option>, @@ -338,10 +338,39 @@ pub struct Shown<'a> { pub text: &'a str, } +/// The log's lines, in the order they came, as a screen shows each: a line +/// that is no kernel record's and no program's continues the last kernel +/// record and wears its severity, whatever program lines came between. +#[derive(Clone, Copy, Debug)] +pub struct Showing { + /// The last kernel record's severity. + severity: Severity, +} + +impl Default for Showing { + fn default() -> Self { + Self { severity: Severity::Info } + } +} + +impl Showing { + /// `line`, its newline optional, as a screen shows it. + pub fn line<'a>(&mut self, line: &'a str) -> Shown<'a> { + let line = line.strip_suffix('\n').unwrap_or(line); + let Some(shown) = shown(line) else { + return Shown { head: None, severity: self.severity, text: line }; + }; + if shown.head.is_some_and(|head| head.source == Source::Kernel) { + self.severity = shown.severity; + } + shown + } +} + /// Read a kernel record's line or a program's — in `/log`'s form or the /// console's, its newline optional — as a screen shows it; `None` for any /// other line, a record's continuation included. -pub fn shown(line: &str) -> Option> { +fn shown(line: &str) -> Option> { let line = line.strip_suffix('\n').unwrap_or(line); if let Some(said) = program_line(line) { let head = line[OPEN.len_utf8()..].split_once(CLOSE)?.0; @@ -743,6 +772,25 @@ mod tests { assert_eq!(shown("BdsDxe: loading Boot0001"), None); } + /// A continuation wears the severity of the kernel record above it, and a + /// program's line in between — of another severity — changes nothing. + #[test] + fn a_continuation_wears_its_kernel_records_severity_across_a_programs_line() { + let alert = format!("{}", kernel_record(Severity::Alert, 0, "PANIC: oops").tagged("kernel")); + let info = format!("{}", kernel_record(Severity::Info, 0, "spawn: x").tagged("kernel")); + let mut showing = Showing::default(); + assert_eq!(showing.line(" before any record").severity, Severity::Info); + assert_eq!(showing.line(&alert).severity, Severity::Alert); + let program = showing.line("{1.234 warn soundserver} underrun\n"); + assert_eq!((program.severity, program.head.map(|h| h.source)), (Severity::Warn, Some(Source::Program("soundserver")))); + let continued = showing.line(" 0: kernel::panic\n"); + assert_eq!(continued, Shown { head: None, severity: Severity::Alert, text: " 0: kernel::panic" }); + assert_eq!(showing.line("{1.300 soundserver} resumed").severity, Severity::Info); + assert_eq!(showing.line(" 1: kernel::main").severity, Severity::Alert); + showing.line(&info); + assert_eq!(showing.line(" more").severity, Severity::Info); + } + #[test] fn a_kernel_record_and_its_continuation_are_no_programs() { assert_eq!(program_line("[2026-09-24 10:00:00 1.216 cpu0] Boot: complete (1216ms)"), None); diff --git a/userland/console/src/main.rs b/userland/console/src/main.rs index 0041dd09df5..39351eeaf22 100644 --- a/userland/console/src/main.rs +++ b/userland/console/src/main.rs @@ -15,7 +15,7 @@ //! first prompt — the kernel's records and every program's output — and //! every program's line after as it is written, each under its program's //! name and above the shell's unfinished line (`Log::draw`), as a terminal -//! shows a line of the log ([`toyos_logstream::Shown`]). +//! shows a line of the log ([`toyos_logstream::Showing`]). //! - **A fatal panic still takes the screen back.** `render` ignores //! `SCREEN_OWNED_BY_USERLAND` entirely — only boot checkpoints honour it — //! so the report paints over whatever this program drew. @@ -37,7 +37,7 @@ use toyos::port::{self, Connector}; use toyos::surface::{self, Delivery, Host, Notice}; use toyos::{FramebufferDev, Keyboard, Pipe}; use toyos_abi::syscall::{DeviceType, SyscallError}; -use toyos_logstream::{Lines, Severity, Shown, Source, READ, SERVED, SERVICE}; +use toyos_logstream::{Lines, Showing, Source, READ, SERVED, SERVICE}; use window::Screen; const FONT: &str = "/system/share/fonts/JetBrainsMono-Regular-8x16.font"; @@ -71,8 +71,8 @@ struct Log { /// Whether the last kernel record was kept, which its continuation lines /// follow. drawing: bool, - /// The last kernel record's severity, which its continuation lines wear. - severity: Severity, + /// How each line is shown. + showing: Showing, /// Lines kept and not yet drawn. held: Vec, } @@ -99,7 +99,7 @@ impl Log { handed, asked_ms, drawing: true, - severity: Severity::Info, + showing: Showing::default(), held: Vec::new(), }) } @@ -112,28 +112,22 @@ impl Log { /// it. A record after that is not drawn: it would put a `spawn:` and an /// `exit:` beside every command typed. /// - /// Each is drawn as [`toyos_logstream::Shown`] draws it; a continuation - /// wears the severity of the kernel record above it. + /// Each is drawn as [`Showing`] shows it. fn take(&mut self, bytes: &[u8]) { - let (asked_ms, drawing, severity, held) = - (self.asked_ms, &mut self.drawing, &mut self.severity, &mut self.held); + let (asked_ms, drawing, showing, held) = + (self.asked_ms, &mut self.drawing, &mut self.showing, &mut self.held); self.lines.push(bytes, |line, _| { let line = String::from_utf8_lossy(line); - let shown = match toyos_logstream::shown(&line) { - Some(shown) => { - let keep = match shown.head.map(|head| head.source) { - Some(Source::Program(tag)) => tag != OWN_TAG, - _ => { - *drawing = toyos_logstream::record_ms(&line).is_some_and(|ms| ms < asked_ms); - *severity = shown.severity; - *drawing - } - }; - keep.then_some(shown) + let shown = showing.line(&line); + let keep = match shown.head.map(|head| head.source) { + Some(Source::Program(tag)) => tag != OWN_TAG, + Some(Source::Kernel) => { + *drawing = toyos_logstream::record_ms(&line).is_some_and(|ms| ms < asked_ms); + *drawing } - None => (*drawing).then_some(Shown { head: None, severity: *severity, text: &line }), + None => *drawing, }; - if let Some(shown) = shown { + if keep { held.extend_from_slice(format!("{shown}\n").as_bytes()); } }); From f6b14fa80b04bc338a6cf45f40b45dc0b15e0c11 Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 4 Oct 2026 13:57:37 +0200 Subject: [PATCH 3/7] The relay's wait on a terminal refuses any poll answer but POLLOUT, and is measured on a pty Review round 2: `writable` ignored `revents`, so a POLLNVAL or POLLERR, which poll returns at once, would have turned the wait into a spin, and the only test of it wrote to a pipe, which poll supports on every host. macOS's poll(2) says it "does not support devices", and a tty is one. `writable` now errs on any answer but POLLOUT. A new host test relays a burst into a raw, non-blocking pty slave nobody reads until a write was refused. It passes on macOS 27.0, where every poll answered POLLOUT (0x4) for the pty, so the deletion path (the relay opening its own blocking description of `ttyname(1)`) is not needed. The test keeps the slave open until the master has read every byte: closed as soon as the relay returned, 32 of 200 runs lost its queued tail (UnexpectedEof on the master); kept open, 0 of 200. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01WcU2Dsw6mDYtwYfzVHPzM8 --- src/kernelconsole.rs | 93 +++++++++++++++++++++++++++++++++++--------- 1 file changed, 75 insertions(+), 18 deletions(-) diff --git a/src/kernelconsole.rs b/src/kernelconsole.rs index d40f04fa7db..144502bde9f 100644 --- a/src/kernelconsole.rs +++ b/src/kernelconsole.rs @@ -150,14 +150,18 @@ fn write_all(out: &mut (impl Write + AsFd), mut bytes: &[u8]) -> io::Result<()> /// Wait until `fd` takes a write. Unbounded, as a blocking write is: a /// terminal its user has stopped takes one when the user lets it. +/// +/// Any answer but `POLLOUT` is an error, never a retry: a `POLLNVAL` or +/// `POLLERR` comes back at once, and retrying it would spin. fn writable(fd: BorrowedFd<'_>) -> io::Result<()> { let mut ready = libc::pollfd { fd: fd.as_raw_fd(), events: libc::POLLOUT, revents: 0 }; // SAFETY: one `pollfd`, which lives across the call. if unsafe { libc::poll(&mut ready, 1, -1) } < 0 { let e = io::Error::last_os_error(); - if e.kind() != io::ErrorKind::Interrupted { - return Err(e); - } + return if e.kind() == io::ErrorKind::Interrupted { Ok(()) } else { Err(e) }; + } + if ready.revents != libc::POLLOUT { + return Err(io::Error::other(format!("poll answered {:#x} for a terminal, not POLLOUT", ready.revents))); } Ok(()) } @@ -165,6 +169,7 @@ fn writable(fd: BorrowedFd<'_>) -> io::Result<()> { #[cfg(test)] mod tests { use super::*; + use std::os::fd::FromRawFd; /// QEMU 11.1.1's own edk2 on the virtio port, as a boot put it there: the /// screen clears, `BdsDxe` and the loader, and the loader's last line cut @@ -270,14 +275,14 @@ mod tests { } } - /// A pipe that refuses a write as `WouldBlock` once it is full, and says so + /// A descriptor that refuses a write as `WouldBlock` once it is full, and says so /// the first time it does. - struct Refusing { - pipe: std::io::PipeWriter, + struct Refusing { + pipe: W, refused: Option>, } - impl Write for Refusing { + impl Write for Refusing { fn write(&mut self, bytes: &[u8]) -> io::Result { let wrote = self.pipe.write(bytes); if wrote.as_ref().is_err_and(|e| e.kind() == io::ErrorKind::WouldBlock) { @@ -291,17 +296,15 @@ mod tests { } } - impl AsFd for Refusing { + impl AsFd for Refusing { fn as_fd(&self) -> BorrowedFd<'_> { self.pipe.as_fd() } } - /// **A terminal that refuses a write as `WouldBlock` is waited for, and - /// shown every byte in order**: a burst far past a pipe's capacity into a - /// non-blocking pipe nobody reads until it has refused one. - #[test] - fn a_relay_waits_out_a_terminal_that_would_block() { + /// A burst of kernel lines far past any terminal's capacity, and what a + /// [`Painter`] shows of it. + 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)); @@ -311,15 +314,26 @@ mod tests { let mut painter = Painter::default(); let mut want = painter.pass(stream.as_bytes()); want.extend(painter.finish()); + (stream.into_bytes(), want) + } - let (mut reader, pipe) = std::io::pipe().expect("a pipe"); - // SAFETY: `pipe` is an open descriptor this test owns. - let flags = unsafe { libc::fcntl(pipe.as_raw_fd(), libc::F_GETFL) }; + fn non_blocking(fd: BorrowedFd<'_>) { + // SAFETY: `fd` is open for the call. + let flags = unsafe { libc::fcntl(fd.as_raw_fd(), libc::F_GETFL) }; // SAFETY: as above; the flags are its own and `O_NONBLOCK`. - assert!(flags >= 0 && unsafe { libc::fcntl(pipe.as_raw_fd(), libc::F_SETFL, flags | libc::O_NONBLOCK) } == 0); + assert!(flags >= 0 && unsafe { libc::fcntl(fd.as_raw_fd(), libc::F_SETFL, flags | libc::O_NONBLOCK) } == 0); + } + + /// **A terminal that refuses a write as `WouldBlock` is waited for, and + /// shown every byte in order**: a burst far past a pipe's capacity into a + /// non-blocking pipe nobody reads until it has refused one. + #[test] + fn a_relay_waits_out_a_pipe_that_would_block() { + let (console, want) = burst(); + let (mut reader, pipe) = std::io::pipe().expect("a pipe"); + non_blocking(pipe.as_fd()); let (said, refused) = std::sync::mpsc::channel(); let mut terminal = Refusing { pipe, refused: Some(said) }; - let console = stream.into_bytes(); let relay = std::thread::spawn(move || relay(console.as_slice(), &mut terminal)); refused.recv_timeout(std::time::Duration::from_secs(60)).expect("the pipe never refused a write"); @@ -330,6 +344,49 @@ mod tests { assert!(shown == want, "the terminal was shown {} bytes, not the {} painted", shown.len(), want.len()); } + /// **The same on a terminal device**, which is what the relay writes to in + /// use: a pty whose raw, non-blocking slave nobody reads until it has + /// refused a write. `writable` errs on any `poll` answer but `POLLOUT`, so + /// the relay's success is `poll` waiting on the device. + #[test] + fn a_relay_waits_out_a_pty_that_would_block() { + let (console, want) = burst(); + let (mut master, mut slave) = (-1, -1); + // SAFETY: two out-pointers to live ints; no name, termios or size asked for. + let opened = unsafe { + libc::openpty(&mut master, &mut slave, std::ptr::null_mut(), std::ptr::null_mut(), std::ptr::null_mut()) + }; + assert_eq!(opened, 0, "openpty: {}", io::Error::last_os_error()); + // SAFETY: `openpty` returned both descriptors open and ours alone. + let (mut master, slave) = + unsafe { (std::fs::File::from_raw_fd(master), std::fs::File::from_raw_fd(slave)) }; + // SAFETY: a zeroed termios is only a buffer `tcgetattr` fills. + let mut raw: libc::termios = unsafe { std::mem::zeroed() }; + // SAFETY: `slave` is an open terminal and `raw` lives across both calls. + assert!(unsafe { libc::tcgetattr(slave.as_raw_fd(), &mut raw) } == 0); + // SAFETY: as above. + unsafe { libc::cfmakeraw(&mut raw) }; + // SAFETY: as above. + assert!(unsafe { libc::tcsetattr(slave.as_raw_fd(), libc::TCSANOW, &raw) } == 0); + non_blocking(slave.as_fd()); + let (said, refused) = std::sync::mpsc::channel(); + let mut terminal = Refusing { pipe: slave, refused: Some(said) }; + // The slave stays open until the master has read it all: the last close + // of a non-blocking slave discards what it still queues. + let relay = std::thread::spawn(move || (relay(console.as_slice(), &mut terminal), terminal)); + let length = want.len(); + let reader = std::thread::spawn(move || { + refused.recv_timeout(std::time::Duration::from_secs(60)).expect("the pty never refused a write"); + let mut shown = vec![0; length]; + master.read_exact(&mut shown).map(|()| shown) + }); + + let (wrote, _slave) = relay.join().expect("the relay"); + wrote.expect("the relay wrote everything"); + let shown = reader.join().expect("the reader").expect("the relay's output"); + assert!(shown == want, "the terminal was shown other bytes than the {} painted", want.len()); + } + #[test] fn nothing_before_the_kernel_passes() { assert_eq!(passed(FIRMWARE, &[5, 200]), ""); From 5b012ffae4abdce0da03b07a598aa9ed24814ddf Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 4 Oct 2026 14:12:20 +0200 Subject: [PATCH 4/7] File: the compositor says its routine lines as errors Found in this branch's `cargo run` capture: the compositor writes its status with `eprintln!`, stderr is recorded at Error, and the terminal now draws Error text red, so 22 routine lines of one boot read as failures. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01WcU2Dsw6mDYtwYfzVHPzM8 --- ...ositor-says-its-routine-lines-as-errors.md | 19 +++++++++++++++++++ 1 file changed, 19 insertions(+) create mode 100644 issues/diagnostics/the-compositor-says-its-routine-lines-as-errors.md diff --git a/issues/diagnostics/the-compositor-says-its-routine-lines-as-errors.md b/issues/diagnostics/the-compositor-says-its-routine-lines-as-errors.md new file mode 100644 index 00000000000..2d477a392b4 --- /dev/null +++ b/issues/diagnostics/the-compositor-says-its-routine-lines-as-errors.md @@ -0,0 +1,19 @@ +--- +status: open +kind: defect +opened: 2026-10-04 +--- + +# The compositor says its routine lines as errors + +The compositor writes its status with `eprintln!` (`userland/compositor/src`), +and `toyos::log::stdio` records a line written to stderr at `Severity::Error`. +So `compositor: ready`, its wallpaper size and its periodic `frames=…` census +are Error records. Since the console and `cargo run`'s terminal draw an Error +record's text in bright red, every one of them reads as a failure: a +`cargo run` boot on macOS under TCG drew 22 compositor lines, all +`{… error compositor}` in red, and none of them was one. + +Owner: orchestrator. Exit condition: the compositor's routine lines are +recorded at Info (`toyos::log`'s `say!` or stdout), a boot's console carries +no `error compositor` line that reports no failure, and this file is deleted. From 05546dff601779b7c8f58dc95e5206081f29538a Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 4 Oct 2026 14:36:06 +0200 Subject: [PATCH 5/7] The relay runs on cargo run's thread and ends QEMU when it fails A relay that failed on its own thread panicked there while the main thread waited on QEMU, which ran on writing into a pipe nobody read until its user quit it blind. The relay now runs where QEMU is owned: the console ends when QEMU does, and a relay error kills QEMU before the error ends the run. The pipe test held nothing the pty test does not: the same burst through the same relay into a non-blocking descriptor, every byte compared, and the no-wait mutation reddened both alike. It goes, and Refusing wraps the pty's slave alone. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01WcU2Dsw6mDYtwYfzVHPzM8 --- src/kernelconsole.rs | 45 +++++++++++++------------------------------- src/qemu.rs | 11 +++++++---- 2 files changed, 20 insertions(+), 36 deletions(-) diff --git a/src/kernelconsole.rs b/src/kernelconsole.rs index 992354bcbaf..d9cadcff864 100644 --- a/src/kernelconsole.rs +++ b/src/kernelconsole.rs @@ -277,14 +277,14 @@ mod tests { /// A descriptor that refuses a write as `WouldBlock` once it is full, and says so /// the first time it does. - struct Refusing { - pipe: W, + struct Refusing { + slave: std::fs::File, refused: Option>, } - impl Write for Refusing { + impl Write for Refusing { fn write(&mut self, bytes: &[u8]) -> io::Result { - let wrote = self.pipe.write(bytes); + let wrote = self.slave.write(bytes); if wrote.as_ref().is_err_and(|e| e.kind() == io::ErrorKind::WouldBlock) { self.refused.take().map(|said| said.send(())); } @@ -292,17 +292,17 @@ mod tests { } fn flush(&mut self) -> io::Result<()> { - self.pipe.flush() + self.slave.flush() } } - impl AsFd for Refusing { + impl AsFd for Refusing { fn as_fd(&self) -> BorrowedFd<'_> { - self.pipe.as_fd() + self.slave.as_fd() } } - /// A burst of kernel lines far past any terminal's capacity, and what a + /// A burst of kernel lines far past a terminal's capacity, and what a /// [`Painter`] shows of it. fn burst() -> (Vec, Vec) { let mut stream = String::from(FIRMWARE); @@ -325,29 +325,10 @@ mod tests { } /// **A terminal that refuses a write as `WouldBlock` is waited for, and - /// shown every byte in order**: a burst far past a pipe's capacity into a - /// non-blocking pipe nobody reads until it has refused one. - #[test] - fn a_relay_waits_out_a_pipe_that_would_block() { - let (console, want) = burst(); - let (mut reader, pipe) = std::io::pipe().expect("a pipe"); - non_blocking(pipe.as_fd()); - let (said, refused) = std::sync::mpsc::channel(); - let mut terminal = Refusing { pipe, refused: Some(said) }; - let relay = std::thread::spawn(move || relay(console.as_slice(), &mut terminal)); - - refused.recv_timeout(std::time::Duration::from_secs(60)).expect("the pipe never refused a write"); - let mut shown = Vec::new(); - reader.read_to_end(&mut shown).expect("the relay's output"); - relay.join().expect("the relay").expect("the relay wrote everything"); - assert!(shown.len() > 1 << 20, "{} bytes is no burst", shown.len()); - assert!(shown == want, "the terminal was shown {} bytes, not the {} painted", shown.len(), want.len()); - } - - /// **The same on a terminal device**, which is what the relay writes to in - /// use: a pty whose raw, non-blocking slave nobody reads until it has - /// refused a write. `writable` errs on any `poll` answer but `POLLOUT`, so - /// the relay's success is `poll` waiting on the device. + /// shown every byte in order**: a burst far past its capacity into a pty + /// whose raw, non-blocking slave nobody reads until it has refused a + /// write. `writable` errs on any `poll` answer but `POLLOUT`, so the + /// relay's success is `poll` waiting on the device. #[test] fn a_relay_waits_out_a_pty_that_would_block() { let (console, want) = burst(); @@ -370,7 +351,7 @@ mod tests { assert!(unsafe { libc::tcsetattr(slave.as_raw_fd(), libc::TCSANOW, &raw) } == 0); non_blocking(slave.as_fd()); let (said, refused) = std::sync::mpsc::channel(); - let mut terminal = Refusing { pipe: slave, refused: Some(said) }; + let mut terminal = Refusing { slave, refused: Some(said) }; // The slave stays open until the master has read it all: the last close // of a non-blocking slave discards what it still queues. let relay = std::thread::spawn(move || (relay(console.as_slice(), &mut terminal), terminal)); diff --git a/src/qemu.rs b/src/qemu.rs index bf9dd5f2e6e..0d543a5f520 100644 --- a/src/qemu.rs +++ b/src/qemu.rs @@ -295,11 +295,14 @@ pub fn launch(opts: &Options) { let mut terminal = File::from(std::io::stdout().as_fd().try_clone_to_owned().expect("this process's stdout")); let mut child = qemu.stdout(Stdio::piped()).spawn().expect("failed to execute QEMU"); let console = child.stdout.take().expect("QEMU's stdout is piped"); - let relay = std::thread::spawn(move || { - kernelconsole::relay(console, &mut terminal).expect("the console's relay to the terminal") - }); + // The console ends when QEMU does; a relay that fails first ends QEMU, which + // would otherwise run on into a pipe nobody reads. + let relayed = kernelconsole::relay(console, &mut terminal); + if relayed.is_err() { + child.kill().expect("failed to kill QEMU"); + } child.wait().expect("failed to wait for QEMU"); - relay.join().expect("the console relay"); + relayed.expect("the console's relay to the terminal"); } /// The machine a profile runs on, with its IOMMU where the machine carries one From 3a0e4528ff765afdd999876b9b285732b023e797 Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 4 Oct 2026 14:55:13 +0200 Subject: [PATCH 6/7] The pty relay test fails on a lost byte instead of hanging With the pipe test gone, the pty test is the one that sees a relay drop bytes, and it hung on it: the reader blocks in read_exact on a slave the test holds open, and the test joined it unbounded. Under m-drop and m-relay-noflush it ran until killed. The reader now hands its bytes over a channel the test waits on for 60 s, and a short delivery is a red naming the byte count. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01WcU2Dsw6mDYtwYfzVHPzM8 --- src/kernelconsole.rs | 13 +++++++++---- 1 file changed, 9 insertions(+), 4 deletions(-) diff --git a/src/kernelconsole.rs b/src/kernelconsole.rs index d9cadcff864..6b7d25561b1 100644 --- a/src/kernelconsole.rs +++ b/src/kernelconsole.rs @@ -356,16 +356,21 @@ mod tests { // of a non-blocking slave discards what it still queues. let relay = std::thread::spawn(move || (relay(console.as_slice(), &mut terminal), terminal)); let length = want.len(); - let reader = std::thread::spawn(move || { + let (read, all_read) = std::sync::mpsc::channel(); + std::thread::spawn(move || { refused.recv_timeout(std::time::Duration::from_secs(60)).expect("the pty never refused a write"); let mut shown = vec![0; length]; - master.read_exact(&mut shown).map(|()| shown) + read.send(master.read_exact(&mut shown).map(|()| shown)) }); let (wrote, _slave) = relay.join().expect("the relay"); wrote.expect("the relay wrote everything"); - let shown = reader.join().expect("the reader").expect("the relay's output"); - assert!(shown == want, "the terminal was shown other bytes than the {} painted", want.len()); + // A relay that lost bytes leaves the reader blocked on an open slave. + let shown = all_read + .recv_timeout(std::time::Duration::from_secs(60)) + .unwrap_or_else(|e| panic!("the terminal was not shown the {length} bytes painted: {e}")) + .expect("the relay's output"); + assert!(shown == want, "the terminal was shown other bytes than the {length} painted"); } #[test] From e7e98c4d49bc08626c7416c62af2f60f70c1a5b0 Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 4 Oct 2026 15:07:49 +0200 Subject: [PATCH 7/7] The relay's test is bounded, and a failed relay ends QEMU with SIGTERM The pty test joined its relay thread without a bound, so a relay whose poll never wakes for a pty hung the suite instead of reddening it. The relay now hands its result and the terminal back over a channel that the test waits on for at most 60 s. With `writable` polling for POLLIN instead of POLLOUT, the test ran past 150 s and was killed at the previous head, and now fails within the bound. On a relay error `cargo run` ended QEMU with `Child::kill`, a SIGKILL: QEMU restores the terminal's termios and fd flags only on its own exit path, so a terminal still there was left raw and non-blocking. It now sends SIGTERM and waits, and the relay's error is reported whatever the kill or the wait answers, rather than lost to a panic on a failed kill. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01WcU2Dsw6mDYtwYfzVHPzM8 --- src/kernelconsole.rs | 8 ++++++-- src/qemu.rs | 15 +++++++++++---- 2 files changed, 17 insertions(+), 6 deletions(-) diff --git a/src/kernelconsole.rs b/src/kernelconsole.rs index 6b7d25561b1..731a8d53a77 100644 --- a/src/kernelconsole.rs +++ b/src/kernelconsole.rs @@ -354,7 +354,8 @@ mod tests { let mut terminal = Refusing { slave, refused: Some(said) }; // The slave stays open until the master has read it all: the last close // of a non-blocking slave discards what it still queues. - let relay = std::thread::spawn(move || (relay(console.as_slice(), &mut terminal), terminal)); + let (relayed, done) = std::sync::mpsc::channel(); + std::thread::spawn(move || relayed.send((relay(console.as_slice(), &mut terminal), terminal))); let length = want.len(); let (read, all_read) = std::sync::mpsc::channel(); std::thread::spawn(move || { @@ -363,7 +364,10 @@ mod tests { read.send(master.read_exact(&mut shown).map(|()| shown)) }); - let (wrote, _slave) = relay.join().expect("the relay"); + // A relay whose wait never ends reds here rather than hanging the suite. + let (wrote, _slave) = done + .recv_timeout(std::time::Duration::from_secs(60)) + .unwrap_or_else(|e| panic!("the relay did not finish: {e}")); wrote.expect("the relay wrote everything"); // A relay that lost bytes leaves the reader blocked on an open slave. let shown = all_read diff --git a/src/qemu.rs b/src/qemu.rs index 0d543a5f520..32800acce2a 100644 --- a/src/qemu.rs +++ b/src/qemu.rs @@ -297,12 +297,19 @@ pub fn launch(opts: &Options) { let console = child.stdout.take().expect("QEMU's stdout is piped"); // The console ends when QEMU does; a relay that fails first ends QEMU, which // would otherwise run on into a pipe nobody reads. - let relayed = kernelconsole::relay(console, &mut terminal); - if relayed.is_err() { - child.kill().expect("failed to kill QEMU"); + if let Err(relay) = kernelconsole::relay(console, &mut terminal) { + // SIGTERM, not `Child::kill`'s SIGKILL: QEMU gives the terminal back its + // modes only on its own exit path. + let pid = libc::pid_t::try_from(child.id()).expect("a pid is a pid_t"); + // SAFETY: `child` is not yet waited for, so `pid` is still QEMU's. + let ended = if unsafe { libc::kill(pid, libc::SIGTERM) } == 0 { + child.wait().map(drop) + } else { + Err(std::io::Error::last_os_error()) + }; + panic!("the console's relay to the terminal: {relay}; ending QEMU: {ended:?}"); } child.wait().expect("failed to wait for QEMU"); - relayed.expect("the console's relay to the terminal"); } /// The machine a profile runs on, with its IOMMU where the machine carries one