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 new file mode 100644 index 00000000000..4f84397c2d6 --- /dev/null +++ b/issues/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/issues/the-compositor-says-its-routine-lines-as-errors.md b/issues/the-compositor-says-its-routine-lines-as-errors.md new file mode 100644 index 00000000000..2d477a392b4 --- /dev/null +++ b/issues/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. diff --git a/kernel/src/drivers/panic_console/mod.rs b/kernel/src/drivers/panic_console/mod.rs index 720d92c7697..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 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 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,11 +103,45 @@ 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 cell is drawn in. +#[derive(Clone, Copy, PartialEq, Eq)] +enum Ink { + /// A record's text below `Error`. + Plain = 0, + /// An `Error` or `Alert` record's text. + Alert = 1, + /// The head a record's first line opens with: its time, CPU and thread. + Stamp = 2, +} + +/// 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 ALERT: u8 = 1; + const OPENS: u8 = 2; + + fn new(alert: bool, opens: bool) -> Self { + Self(if alert { Self::ALERT } else { 0 } | if opens { Self::OPENS } else { 0 }) + } + + fn ink(self) -> Ink { + if self.0 & Self::ALERT != 0 { Ink::Alert } else { Ink::Plain } + } + + 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], + /// 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, lines: usize, @@ -115,11 +149,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 +166,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 +176,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(false, false) }; + let byte = self.marks.get(from_end / 4).copied().unwrap_or(0); + Mark(byte >> (from_end % 4 * 2) & 3) } } @@ -172,11 +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(); - 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 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(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; @@ -900,8 +936,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 +948,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 +959,40 @@ impl Cell { (ch != 0).then_some(ch) } - fn alert(self) -> bool { - self.0 & Self::ALERT != 0 + fn ink(self) -> Ink { + match self.0 >> 8 { + 0 => Ink::Plain, + 1 => Ink::Alert, + _ => Ink::Stamp, + } + } +} + +/// 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, + alert: u32, + stamp: u32, +} + +impl Palette { + fn of(fb: &Fb) -> Self { + Self { + plain: rgb(fb, 0xFF, 0xFF, 0xFF), + 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::Alert => self.alert, + Ink::Stamp => self.stamp, + } } } @@ -1053,8 +1120,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 +1156,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 +1177,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 +1250,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 73b30fe4b4e..731a8d53a77 100644 --- a/src/kernelconsole.rs +++ b/src/kernelconsole.rs @@ -6,8 +6,14 @@ //! 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. 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 @@ -46,9 +52,124 @@ 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 [`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, + showing: Showing, +} + +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(); + 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. +/// +/// 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(); + 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(()) +} + #[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 @@ -97,6 +218,165 @@ 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 showing = Showing::default(); + for line in format!("{KERNEL}{alert}{program}").lines() { + want.push_str(&format!("{}\n", showing.line(line))); + } + 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 "); + } + + /// 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 descriptor that refuses a write as `WouldBlock` once it is full, and says so + /// the first time it does. + struct Refusing { + slave: std::fs::File, + refused: Option>, + } + + impl Write for Refusing { + fn write(&mut self, bytes: &[u8]) -> io::Result { + 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(())); + } + wrote + } + + fn flush(&mut self) -> io::Result<()> { + self.slave.flush() + } + } + + impl AsFd for Refusing { + fn as_fd(&self) -> BorrowedFd<'_> { + self.slave.as_fd() + } + } + + /// 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); + 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()); + (stream.into_bytes(), want) + } + + 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(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 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(); + 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 { 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 (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 || { + refused.recv_timeout(std::time::Duration::from_secs(60)).expect("the pty never refused a write"); + let mut shown = vec![0; length]; + read.send(master.read_exact(&mut shown).map(|()| shown)) + }); + + // 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 + .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] fn nothing_before_the_kernel_passes() { assert_eq!(passed(FIRMWARE, &[5, 200]), ""); diff --git a/src/qemu.rs b/src/qemu.rs index 100b509b05f..32800acce2a 100644 --- a/src/qemu.rs +++ b/src/qemu.rs @@ -47,10 +47,13 @@ //! slow is the clock, RTF well below 1.0 is synthesis not keeping up. use std::fs::File; +use std::io::IsTerminal; +use std::os::fd::AsFd; use std::path::PathBuf; -use std::process::Command; +use std::process::{Command, Stdio}; use toyos_build::arch::Arch; +use toyos_build::kernelconsole; /// The hardware shape QEMU presents to the guest. /// @@ -278,13 +281,35 @@ 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; + } + // 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 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. + 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"); } /// 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..6fe371826fa 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,25 @@ impl Ppm { None } + /// 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) -> 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)); + } + found + } + /// 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 ba3aac3a3c2..30ee51f7380 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -1075,9 +1075,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 @@ -1494,8 +1496,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 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 @@ -1518,36 +1521,47 @@ 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 { - return Err(format!("{alert_line:?} not on screen\n{}", dump.text())); - }; - if dump.row_fg(cy) != Some(ALERT) { - return Err(format!( - "{alert_line:?} drawn in {:?}, 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() - )); - } + inked( + dump, + alert_line, + ALERT, + "every row of an `alert!` record wears its level, including the ones its message \ + wrapped or newlined onto", + )?; } - 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!( - "{plain_line:?} is not on screen, so there is no ordinary row to compare the \ - highlight against\n{}", + "the head of {:?} drawn in {:?}, want the stamp's {STAMP:?}\n{}", + dump.rows()[cy], + dump.row_fg(cy), 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) - )); } - Ok(()) + 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(()), + } } /// `tests/toyos-rust-tests`' binary that `tests/virtjobcase` runs as its job 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..7cc6b919f9f 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,164 @@ 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 [`Showing`] +/// gives 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, +} + +/// 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. +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 +682,115 @@ 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); + } + + /// 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 d1e8d1e0a11..39351eeaf22 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::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. @@ -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, Showing, 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, + /// How each line is shown. + showing: Showing, /// 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, + showing: Showing::default(), + held: Vec::new(), + }) } /// Take every whole line in `bytes` that goes on the screen. @@ -100,22 +111,24 @@ 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 [`Showing`] shows 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, showing, held) = + (self.asked_ms, &mut self.drawing, &mut self.showing, &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; - } + let line = String::from_utf8_lossy(line); + 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, }; if keep { - held.extend_from_slice(line); - held.push(b'\n'); + held.extend_from_slice(format!("{shown}\n").as_bytes()); } }); }