From 6e6a8f713c0ccb1fd67cd0aaf1ed0442f700f4cf Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 4 Oct 2026 21:36:14 +0200 Subject: [PATCH 1/3] Routine lines go on stdout, so only a failure is drawn as an error A line a program writes to stderr becomes a Severity::Error record (toyos::log::stdio::Stream::severity), and since #720 the console and `cargo run`'s terminal draw an Error record in bright red. The compositor wrote all its status with eprintln!, so `compositor: ready`, the wallpaper and window-budget lines, every window opened and closed, and the periodic `frames=` census were red on every boot without one of them reporting a failure. Owner ruling (2026-10-04): #720's colours are right; the compositor is using the wrong output, and an agent moves its routine lines to normal output. The rule is one: a routine line is not an error. - compositor: wallpaper, window budget, ready, window opened/closed and the frame census go to stdout. A dropped client goes to stdout when its connection is gone (the routine way a client ends) and stays on stderr for every other reason, each of which is the client failing the protocol; DropReason::failed says which, by an exhaustive match. - terminal: `ready`, and a client taking and giving back the keyboard. - doom: the periodic `[music] rt_factor=` telemetry. - toybox: tone's start and done lines, and stats's report. Every other program in system.toml was read: what it writes on stderr is a failure, a refusal or a usage message, or it already speaks through toyos's say!/warn!/error!. /system/bin/console, of console/system.toml, carries the terminal's identical lines and is filed as issues/the-console-says-its-routine-lines-as-errors.md. Closes issues/the-compositor-says-its-routine-lines-as-errors.md; its rule moves to Stream::severity's doc. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01WcU2Dsw6mDYtwYfzVHPzM8 --- ...ositor-says-its-routine-lines-as-errors.md | 19 ---------- ...onsole-says-its-routine-lines-as-errors.md | 18 ++++++++++ toyos/src/log/stdio.rs | 3 +- userland/compositor/src/client.rs | 24 +++++++++++-- userland/compositor/src/session.rs | 6 ++-- userland/compositor/src/stats.rs | 2 +- userland/doom/src/sound.rs | 2 +- userland/terminal/src/main.rs | 6 ++-- userland/toybox/src/stats.rs | 36 +++++++++---------- userland/toybox/src/tone.rs | 4 +-- 10 files changed, 69 insertions(+), 51 deletions(-) delete mode 100644 issues/the-compositor-says-its-routine-lines-as-errors.md create mode 100644 issues/the-console-says-its-routine-lines-as-errors.md diff --git a/issues/the-compositor-says-its-routine-lines-as-errors.md b/issues/the-compositor-says-its-routine-lines-as-errors.md deleted file mode 100644 index 2d477a392b4..00000000000 --- a/issues/the-compositor-says-its-routine-lines-as-errors.md +++ /dev/null @@ -1,19 +0,0 @@ ---- -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/issues/the-console-says-its-routine-lines-as-errors.md b/issues/the-console-says-its-routine-lines-as-errors.md new file mode 100644 index 00000000000..bdc8f564cd3 --- /dev/null +++ b/issues/the-console-says-its-routine-lines-as-errors.md @@ -0,0 +1,18 @@ +--- +status: open +kind: defect +opened: 2026-10-04 +--- + +# The console says its routine lines as errors + +`/system/bin/console` (`userland/console/src/main.rs`), the surface of the +`console/system.toml` boot, writes `console: ready …`, `keyboard layout is +now …`, `client N has the keyboard until it exits` and `client N gave the +keyboard back` with `eprintln!`, and a line on stderr is an Error record +(`toyos::log::stdio::Stream::severity`). So every one of them is drawn in red +on the console and reads as a failure, as the terminal's identical lines did +until they moved to stdout. + +Owner: orchestrator. Exit condition: those four lines are written to stdout, +and this file is deleted. diff --git a/toyos/src/log/stdio.rs b/toyos/src/log/stdio.rs index cf12527f38d..6d80bf70347 100644 --- a/toyos/src/log/stdio.rs +++ b/toyos/src/log/stdio.rs @@ -34,7 +34,8 @@ pub enum Stream { } impl Stream { - /// What a line on this stream is, when it becomes a record. + /// What a line on this stream is, when it becomes a record: every line on + /// stderr is an error, so a routine line goes on stdout. pub const fn severity(self) -> Severity { match self { Self::Out => Severity::Info, diff --git a/userland/compositor/src/client.rs b/userland/compositor/src/client.rs index b2504f30f7b..4429494d34c 100644 --- a/userland/compositor/src/client.rs +++ b/userland/compositor/src/client.rs @@ -178,6 +178,19 @@ impl DropReason { Self::CopyTimeout => "it began a copy and never committed it", } } + + /// Whether the going is a failure, said on stderr, rather than a client's + /// routine end, said on stdout. + pub fn failed(self) -> bool { + match self { + Self::Gone => false, + Self::OutOfProtocol + | Self::Retired + | Self::NotReading + | Self::HandshakeTimeout + | Self::CopyTimeout => true, + } + } } impl From for DropReason { @@ -200,7 +213,12 @@ pub fn mark_dead(dead: &mut Vec, handle: RawHandle, reason: DropReason) { pub fn announce(dead: &[Dead]) { for (handle, reason) in dead { - eprintln!("compositor: dropping client {} — {}", handle.0, reason.why()); + let (client, why) = (handle.0, reason.why()); + if reason.failed() { + eprintln!("compositor: dropping client {client} — {why}"); + } else { + println!("compositor: dropping client {client} — {why}"); + } } } @@ -216,7 +234,7 @@ pub fn announce(dead: &[Dead]) { /// asks of the log — and a caller that re-sends a close because it could not /// tell whether the first one landed closes the next window down. pub fn note_closed(by: &str, win: &Win, remaining: usize) { - eprintln!( + println!( "compositor: window closed client={} by {by}, {remaining} left, presents={} frames={}", win.client.conn.as_handle().0, win.client.presents, @@ -227,7 +245,7 @@ pub fn note_closed(by: &str, win: &Win, remaining: usize) { /// The open's own line, and where the client's pixels are on the panel: the one /// fact about a window that nobody reading the screen can recover from it. pub fn note_opened(client: RawHandle, content: toyos_desktop::Rect, live: usize) { - eprintln!( + println!( "compositor: window opened client={} content={},{} {}x{}, {live} live", client.0, content.x0, diff --git a/userland/compositor/src/session.rs b/userland/compositor/src/session.rs index bc64d560d9d..98b151162d3 100644 --- a/userland/compositor/src/session.rs +++ b/userland/compositor/src/session.rs @@ -195,7 +195,7 @@ impl Session { raw, scaled: Vec::new(), }; - eprintln!( + println!( "compositor: wallpaper {}x{}, scaling to {}x{}", wallpaper.w, wallpaper.h, @@ -215,7 +215,7 @@ impl Session { let total_mem = total_memory(); let max_windows = toyos_desktop::max_windows(total_mem, desk.screen, MAX_WINDOW_SLOTS as usize); - eprintln!( + println!( "compositor: at most {max_windows} windows ({} MiB each of {} MiB total)", toyos_desktop::window_bytes(desk.screen) / (1024 * 1024), total_mem / (1024 * 1024), @@ -239,7 +239,7 @@ impl Session { let mut damage = Damage::default(); damage.add(desk.screen); - eprintln!("compositor: ready"); + println!("compositor: ready"); let now = Instant::now(); Self { diff --git a/userland/compositor/src/stats.rs b/userland/compositor/src/stats.rs index fb3a203939c..4228668522c 100644 --- a/userland/compositor/src/stats.rs +++ b/userland/compositor/src/stats.rs @@ -52,7 +52,7 @@ impl FrameStats { /// mean is a division, and the total is the share of the window that /// compositing cost, which the mean is not. pub fn report(&self, moved: (u64, u64), composed: Traffic, windows: usize) { - eprintln!( + println!( "compositor: frames={} rects={} damage_px={} damage_px_max={} \ composite_us_min={} composite_us_max={} composite_us_total={} \ scanout_wr_bytes={} scanout_blits={} back_rd_bytes={} cursor={} windows={}", diff --git a/userland/doom/src/sound.rs b/userland/doom/src/sound.rs index 9ef120a7d1f..f622dde2d30 100644 --- a/userland/doom/src/sound.rs +++ b/userland/doom/src/sound.rs @@ -672,7 +672,7 @@ fn music_telemetry(ring: &MusicRing, render_cost: std::time::Duration) { let audio_s = t.chunks as f64 * RENDER_CHUNK as f64 / OUTPUT_RATE as f64; let rt = t.cpu.as_secs_f64() / audio_s; let fill = 100 * (RING_FRAMES - ring.free_space()) / RING_FRAMES; - eprintln!("[music] rt_factor={rt:.2} rendered={audio_s:.1}s/{:.1}s ring={fill}%", wall.as_secs_f64()); + println!("[music] rt_factor={rt:.2} rendered={audio_s:.1}s/{:.1}s ring={fill}%", wall.as_secs_f64()); *t = Tel { window_start: Instant::now(), cpu: Default::default(), chunks: 0 }; } } diff --git a/userland/terminal/src/main.rs b/userland/terminal/src/main.rs index 95405c471d4..a25fd3ad16c 100644 --- a/userland/terminal/src/main.rs +++ b/userland/terminal/src/main.rs @@ -75,7 +75,7 @@ fn main() { // from here a keystroke the compositor forwards has somewhere to land even // if the shell has not reached its first read. Before it, one is dropped // with no trace. - eprintln!("terminal: ready"); + println!("terminal: ready"); loop { poller.watch_raw(RawHandle(shell_stdout.as_raw_fd() as u32), READABLE, TOKEN_STDOUT); @@ -132,10 +132,10 @@ fn main() { // re-read arrives back through `Event::LayoutChanged`. Notice::LayoutChanged => window.notify_layout_changed(), Notice::Grabbed { client } => { - eprintln!("terminal: client {client} has the keyboard until it exits") + println!("terminal: client {client} has the keyboard until it exits") } Notice::Released { client } => { - eprintln!("terminal: client {client} gave the keyboard back") + println!("terminal: client {client} gave the keyboard back") } Notice::Dropped { client, why } => { eprintln!("terminal: dropping client {client} — {why}") diff --git a/userland/toybox/src/stats.rs b/userland/toybox/src/stats.rs index b2d11cc3032..63d816351b4 100644 --- a/userland/toybox/src/stats.rs +++ b/userland/toybox/src/stats.rs @@ -31,30 +31,30 @@ pub fn main(args: Vec) { } let code = status.code().unwrap_or(-1); - eprintln!(); - eprintln!("── process stats (pid {}, exit {code}) ──────────", s.pid); - eprintln!(" wall {}", fmt_ns(s.wall_ns)); - eprintln!(" cpu {}", fmt_ns(s.cpu_ns)); - eprintln!(); + println!(); + println!("── process stats (pid {}, exit {code}) ──────────", s.pid); + println!(" wall {}", fmt_ns(s.wall_ns)); + println!(" cpu {}", fmt_ns(s.cpu_ns)); + println!(); let fault_total = s.fault_demand_count + s.fault_zero_count; if fault_total > 0 || s.fault_ns > 0 { - eprintln!(" faults {:>6} ({} demand, {} zero)", + println!(" faults {:>6} ({} demand, {} zero)", fault_total, s.fault_demand_count, s.fault_zero_count); - eprintln!(" fault time {}", fmt_ns(s.fault_ns)); - eprintln!(); + println!(" fault time {}", fmt_ns(s.fault_ns)); + println!(); } if s.io_read_ops > 0 { - eprintln!(" io ops {:>6}", s.io_read_ops); - eprintln!(" io bytes {}", fmt_bytes(s.io_read_bytes)); - eprintln!(); + println!(" io ops {:>6}", s.io_read_ops); + println!(" io bytes {}", fmt_bytes(s.io_read_bytes)); + println!(); } let blocked_total = s.blocked_io_ns + s.blocked_futex_ns + s.blocked_pipe_ns + s.blocked_ipc_ns + s.blocked_other_ns; if blocked_total > 0 { - eprint!(" blocked {}", fmt_ns(blocked_total)); + print!(" blocked {}", fmt_ns(blocked_total)); let mut parts = Vec::new(); if s.blocked_io_ns > 0 { parts.push(format!("io {}", fmt_ns(s.blocked_io_ns))); } if s.blocked_futex_ns > 0 { parts.push(format!("futex {}", fmt_ns(s.blocked_futex_ns))); } @@ -62,21 +62,21 @@ pub fn main(args: Vec) { if s.blocked_ipc_ns > 0 { parts.push(format!("ipc {}", fmt_ns(s.blocked_ipc_ns))); } if s.blocked_other_ns > 0 { parts.push(format!("other {}", fmt_ns(s.blocked_other_ns))); } if !parts.is_empty() { - eprint!(" ({})", parts.join(", ")); + print!(" ({})", parts.join(", ")); } - eprintln!(); + println!(); } if s.runqueue_wait_ns > 0 { - eprintln!(" runqueue {}", fmt_ns(s.runqueue_wait_ns)); + println!(" runqueue {}", fmt_ns(s.runqueue_wait_ns)); } if blocked_total > 0 || s.runqueue_wait_ns > 0 { - eprintln!(); + println!(); } - eprintln!(" syscalls {:>6} (wall {})", s.syscall_total, fmt_ns(s.syscall_total_ns)); - eprintln!(" peak mem {} ({} allocs)", fmt_bytes(s.peak_memory), s.alloc_count); + println!(" syscalls {:>6} (wall {})", s.syscall_total, fmt_ns(s.syscall_total_ns)); + println!(" peak mem {} ({} allocs)", fmt_bytes(s.peak_memory), s.alloc_count); } fn fmt_ns(ns: u64) -> String { diff --git a/userland/toybox/src/tone.rs b/userland/toybox/src/tone.rs index f1b39582615..ff0c82d63b4 100644 --- a/userland/toybox/src/tone.rs +++ b/userland/toybox/src/tone.rs @@ -25,7 +25,7 @@ pub fn main(args: Vec) { }, }; - eprintln!( + println!( "tone: {freq}Hz for {duration_secs}s at amplitude {}", amplitude as i32 ); @@ -100,5 +100,5 @@ pub fn main(args: Vec) { // Let the last buffer drain std::thread::sleep(std::time::Duration::from_millis(100)); - eprintln!("tone: done"); + println!("tone: done"); } From ba85257af3ebb48df0ad6faa04c0c81d7f1a1678 Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 4 Oct 2026 22:05:35 +0200 Subject: [PATCH 2/3] A dropped client is routine only when its other end closed DropReason::Gone, said on stdout since the previous commit, stood for more than a closed peer. From folded TooLarge and every Syscall error into it, and the copy path marked any handle_send refusal Gone. handle_send answers ResourceExhausted to a peer that leaves MAX_QUEUED_BATCHES batches unreceived (kernel/src/object/service.rs), so a client that never calls handle_recv was dropped with an Info line saying its connection is gone. Gone now comes only from SyscallError::Gone (and a read's Eof). Any other kernel refusal is Refused(e), naming the error, and TooLarge is its own reason; both are failures and stay on stderr. Both send producers, deliver*'s From and the copy path's handle_send, go through From, with exhaustive matches. The reason is now Display, since Refused carries the kernel's word. The compositor's first host test walks every error the ABI can encode through both conversions; it was red on the previous mapping (Unknown -> Gone). Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01WcU2Dsw6mDYtwYfzVHPzM8 --- userland/compositor/src/client.rs | 76 +++++++++++++++++++++++++----- userland/compositor/src/session.rs | 6 +-- 2 files changed, 66 insertions(+), 16 deletions(-) diff --git a/userland/compositor/src/client.rs b/userland/compositor/src/client.rs index 4429494d34c..4c404081a2e 100644 --- a/userland/compositor/src/client.rs +++ b/userland/compositor/src/client.rs @@ -13,12 +13,14 @@ //! used it — so every region a client writes is one the compositor made, and a //! handle a client sends stays queued until its connection closes. +use std::fmt; use std::sync::atomic::Ordering; use std::time::{Duration, Instant}; use toyos::shm::SharedMemory; use toyos::AsHandle; use toyos::{ipc, Connection}; +use toyos_abi::syscall::SyscallError; use toyos_abi::RawHandle; use toyos_desktop::Window; @@ -159,26 +161,40 @@ pub enum DropReason { /// Its pipe would not take a whole frame — an entire pipe of messages it /// has not read. NotReading, - /// The connection is gone. + /// Its other end closed: the one send error that is a client's routine end. Gone, + /// The kernel refused a send to it for any other reason — a handle send + /// to a peer that leaves `MAX_QUEUED_BATCHES` unreceived is + /// `ResourceExhausted`. + Refused(SyscallError), + /// A message to it that this end will not frame. + TooLarge, /// Accepted, and never completed a first frame. HandshakeTimeout, /// Given a region to copy into, and never committed it. CopyTimeout, } -impl DropReason { - pub fn why(self) -> &'static str { +impl fmt::Display for DropReason { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { match self { - Self::OutOfProtocol => "it sent a frame this protocol cannot describe", - Self::Retired => "it sent the retired clipboard region, whose handle is never taken", - Self::NotReading => "its pipe will not take another message and it is not reading", - Self::Gone => "its connection is gone", - Self::HandshakeTimeout => "it never finished its first message", - Self::CopyTimeout => "it began a copy and never committed it", + Self::OutOfProtocol => f.write_str("it sent a frame this protocol cannot describe"), + Self::Retired => { + f.write_str("it sent the retired clipboard region, whose handle is never taken") + } + Self::NotReading => { + f.write_str("its pipe will not take another message and it is not reading") + } + Self::Gone => f.write_str("its connection is gone"), + Self::Refused(e) => write!(f, "the kernel refused a send to it: {e}"), + Self::TooLarge => f.write_str("a message to it is too large to frame"), + Self::HandshakeTimeout => f.write_str("it never finished its first message"), + Self::CopyTimeout => f.write_str("it began a copy and never committed it"), } } +} +impl DropReason { /// Whether the going is a failure, said on stderr, rather than a client's /// routine end, said on stdout. pub fn failed(self) -> bool { @@ -187,17 +203,29 @@ impl DropReason { Self::OutOfProtocol | Self::Retired | Self::NotReading + | Self::Refused(_) + | Self::TooLarge | Self::HandshakeTimeout | Self::CopyTimeout => true, } } } +impl From for DropReason { + fn from(e: SyscallError) -> Self { + match e { + SyscallError::Gone => Self::Gone, + e => Self::Refused(e), + } + } +} + impl From for DropReason { fn from(e: ipc::TrySendError) -> Self { match e { ipc::TrySendError::Full => Self::NotReading, - _ => Self::Gone, + ipc::TrySendError::TooLarge => Self::TooLarge, + ipc::TrySendError::Syscall(e) => e.into(), } } } @@ -213,11 +241,11 @@ pub fn mark_dead(dead: &mut Vec, handle: RawHandle, reason: DropReason) { pub fn announce(dead: &[Dead]) { for (handle, reason) in dead { - let (client, why) = (handle.0, reason.why()); + let client = handle.0; if reason.failed() { - eprintln!("compositor: dropping client {client} — {why}"); + eprintln!("compositor: dropping client {client} — {reason}"); } else { - println!("compositor: dropping client {client} — {why}"); + println!("compositor: dropping client {client} — {reason}"); } } } @@ -285,3 +313,25 @@ pub fn deliver_signal(dead: &mut Vec, win: &Win, msg_type: u32) { mark_dead(dead, win.client.conn.as_handle(), e.into()); } } + +#[cfg(test)] +mod tests { + use super::*; + + /// Every error the ABI can encode. + fn every_syscall_error() -> impl Iterator { + (0..=255).filter_map(|n| SyscallError::from_u64(u64::MAX - n)) + } + + #[test] + fn only_a_closed_peer_ends_a_send_without_a_failure() { + for e in every_syscall_error() { + let closed = e == SyscallError::Gone; + assert_eq!(DropReason::from(e).failed(), !closed, "a handle send's {e:?}"); + let reason = DropReason::from(ipc::TrySendError::Syscall(e)); + assert_eq!(reason.failed(), !closed, "a frame's {e:?}"); + } + assert!(DropReason::from(ipc::TrySendError::Full).failed()); + assert!(DropReason::from(ipc::TrySendError::TooLarge).failed()); + } +} diff --git a/userland/compositor/src/session.rs b/userland/compositor/src/session.rs index 98b151162d3..d03dc0a1c1b 100644 --- a/userland/compositor/src/session.rs +++ b/userland/compositor/src/session.rs @@ -336,7 +336,7 @@ impl Session { Some(_) => DropReason::CopyTimeout, None => DropReason::HandshakeTimeout, }; - eprintln!("compositor: dropping client {} — {}", p.conn.as_handle().0, reason.why()); + eprintln!("compositor: dropping client {} — {}", p.conn.as_handle().0, reason); } self.pending.retain(|p| now.duration_since(p.since) < HANDSHAKE_TIMEOUT); @@ -990,9 +990,9 @@ impl Session { }; // Moved on its own, so that a refused move leaves `theirs` here to // close: once moved, its number is no longer this process's to close. - if syscall::handle_send(conn.as_handle(), &[theirs]).is_err() { + if let Err(e) = syscall::handle_send(conn.as_handle(), &[theirs]) { syscall::close(theirs); - mark_dead(&mut self.dead, handle, DropReason::Gone); + mark_dead(&mut self.dead, handle, e.into()); return; } if let Err(e) = conn.try_signal(window::MSG_COPY_REGION) { From e4cf4b5a88f61e26e759da4fbaa651c22d021e68 Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 4 Oct 2026 22:25:58 +0200 Subject: [PATCH 3/3] The compositor's drop-reason test goes: its exhaustive matches are read, not tested Both conversions into DropReason are exhaustive matches beside the predicate they feed, and the test's oracle restated From's two arms; deleting it also takes the exempt compositor back out of src/userlandhost.rs's gated crates. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01WcU2Dsw6mDYtwYfzVHPzM8 --- userland/compositor/src/client.rs | 22 ---------------------- 1 file changed, 22 deletions(-) diff --git a/userland/compositor/src/client.rs b/userland/compositor/src/client.rs index 4c404081a2e..32d9a37ada3 100644 --- a/userland/compositor/src/client.rs +++ b/userland/compositor/src/client.rs @@ -313,25 +313,3 @@ pub fn deliver_signal(dead: &mut Vec, win: &Win, msg_type: u32) { mark_dead(dead, win.client.conn.as_handle(), e.into()); } } - -#[cfg(test)] -mod tests { - use super::*; - - /// Every error the ABI can encode. - fn every_syscall_error() -> impl Iterator { - (0..=255).filter_map(|n| SyscallError::from_u64(u64::MAX - n)) - } - - #[test] - fn only_a_closed_peer_ends_a_send_without_a_failure() { - for e in every_syscall_error() { - let closed = e == SyscallError::Gone; - assert_eq!(DropReason::from(e).failed(), !closed, "a handle send's {e:?}"); - let reason = DropReason::from(ipc::TrySendError::Syscall(e)); - assert_eq!(reason.failed(), !closed, "a frame's {e:?}"); - } - assert!(DropReason::from(ipc::TrySendError::Full).failed()); - assert!(DropReason::from(ipc::TrySendError::TooLarge).failed()); - } -}