From c7540c31d45dac68fa1852f5d25645d569b2da9d Mon Sep 17 00:00:00 2001 From: salmonik Date: Sat, 1 Aug 2026 14:09:14 +0200 Subject: klog: kernel log ring + /dev/klog + klog shell command - rsnix/src/klog.rs: RAM ring of the last 128 serial log lines (128 chars each), fed by serial_println! so every boot/low-level message is captured for free. Sequence numbers per line, wrap/drop accounting; the ring never allocates (const-constructible static). - /dev/klog char device; shell 'klog' is a thin alias for cat /dev/klog with the same filters/redirection, so 'klog -t 5', 'klog -g fat' and 'klog WRITING /disk/.../boot.log' all work. klog rejects positional args (usage) and input keywords. - Shell user-facing output (banner, prompt, term_print/term_println, pipeline sink, halt/poweroff) now writes to serial directly instead of through serial_println!, keeping echo/cat output out of the boot log (a streaming cat /dev/mem would otherwise wrap the ring). - serial_println! macro hooks klog::append_fmt via format_args! (no alloc at call sites); klog::dump formats the log for the device. Verified in QEMU: 28 boot lines captured (seq 0..27), shell output absent from the ring, klog WRITING persists a boot log (mtype-checked), wrap verified with a temporary 140-line boot loop (128 kept / 40 dropped, seq 40..167, oldest-live correct; loop reverted); full test-disk round trip still fsck-clean. --- CONTEXT.md | 36 +++++++++++---- rsnix/src/fs.rs | 8 ++++ rsnix/src/klog.rs | 130 ++++++++++++++++++++++++++++++++++++++++++++++++++++ rsnix/src/lib.rs | 1 + rsnix/src/serial.rs | 11 ++++- shell/src/lib.rs | 64 ++++++++++++++++++++------ 6 files changed, 226 insertions(+), 24 deletions(-) create mode 100644 rsnix/src/klog.rs diff --git a/CONTEXT.md b/CONTEXT.md index c6bd5f9..86822d1 100644 --- a/CONTEXT.md +++ b/CONTEXT.md @@ -255,6 +255,34 @@ Workspace of four crates, all built for the `x86_64-unknown-uefi` target: monitor (`--sock`, US layout, named keys for punctuation; bare `-`/`.`/`/` are not valid sendkey names) +✅ **`klog` kernel log ring** — a RAM ring of the last 128 serial log + lines (128 chars each, ~16 KB), fed by `serial_println!` (one choke + point — every boot/low-level message captured for free). Sequence + numbers per line + wrap/drop accounting; a dump header reports how + many lines were lost to wrap. Exposed as the `/dev/klog` char + device; the shell `klog` command is a thin alias for `cat + /dev/klog` (same filters/redirection), so `klog -t 5`, `klog -g + fat`, and `klog WRITING /disk/…/boot.log` (persists the boot log) + all work. The ring never allocates (const-constructible static); + only the dump allocates, at shell time. `klog` rejects positional + args (usage) and input keywords ("does not accept input"). + + **Design consequence: shell output must not feed the ring.** The + plan's "hook `serial_println!`" only works if that macro is + kernel-logging-only — but the shell printed prompts/errors/results + through it, which would have flooded the boot log with echo/cat + output (a `cat /dev/mem` would wrap the ring). The shell now + writes user-facing output (banner, prompt, `term_print`/ + `term_println`, pipeline sink, halt/poweroff) directly to the + serial port via `serial::write_str`; tty echo already did. Only + kernel messages (rsnix modules + `rsdos/main.rs`) go through + `serial_println!` now. Verified in QEMU: 28 boot lines captured + (seq 0..27, first `=== rsnix boot ===`, last `boot: entering + shell`), `echo hello` output absent from the ring, `klog WRITING` + persists a boot log (mtype-verified), wrap behavior verified with a + temporary 140-line boot loop (128 kept / 40 dropped, seq 40..167, + oldest live line correct — loop reverted after the test). + ## Known issues / perf notes - **Scroll cost** — scrolling still shifts the whole framebuffer (a @@ -289,14 +317,6 @@ Workspace of four crates, all built for the `x86_64-unknown-uefi` target: ## Pending decisions (agreed, not yet implemented) -- **`klog` kernel log ring**: capture all boot/low-level messages by - appending to a RAM ring buffer inside `serial_println!` (one choke - point, every existing message captured for free). Ring: 128 lines × - 128 chars ≈ 16 KB, sequence numbers, wrap/drop accounting. -- **`klog` command** = thin alias for `cat /dev/klog` plus filters - `-h` (head) and `-t` (tail); no log levels, no timestamps, nothing - fancier. `/dev/klog` is a char device so `klog WRITING /disk/…/boot.log` - persists a boot log via the existing redirection. - **Disk recognition scope — keep simple for now**: no pre-EBS UEFI block-device census, no GPT/MBR partition parsing, no NVMe driver. (Revisit later: Linux-style recognition = PCI scan → ahci/nvme → diff --git a/rsnix/src/fs.rs b/rsnix/src/fs.rs index a71e51a..063560a 100644 --- a/rsnix/src/fs.rs +++ b/rsnix/src/fs.rs @@ -41,6 +41,7 @@ enum CharDevice { Pci, Version, Meminfo, + Klog, Null, Zero, Console, @@ -140,6 +141,12 @@ pub fn init() -> (usize, usize) { FileType::Char, NodeData::Char(CharDevice::Meminfo), ); + add( + "klog", + Some(dev), + FileType::Char, + NodeData::Char(CharDevice::Klog), + ); add( "null", Some(dev), @@ -650,6 +657,7 @@ fn dev_text(dev: CharDevice, _pos: u64) -> String { CharDevice::Pci => pci_listing(), CharDevice::Version => version_text(), CharDevice::Meminfo => meminfo_text(), + CharDevice::Klog => crate::klog::dump(), CharDevice::Null | CharDevice::Console | CharDevice::Serial => String::new(), CharDevice::Zero => String::new(), } diff --git a/rsnix/src/klog.rs b/rsnix/src/klog.rs new file mode 100644 index 0000000..1e23460 --- /dev/null +++ b/rsnix/src/klog.rs @@ -0,0 +1,130 @@ +// --------------------------------------------------------------------------- +// klog — kernel log ring buffer. +// +// A RAM ring of the last MAX_LINES serial log lines, fed by +// `serial_println!` (one choke point, so every boot/low-level message is +// captured for free). Exposed to the shell as the `/dev/klog` char +// device, so `klog` (alias for `cat /dev/klog`) shows the boot sequence +// and `klog WRITING /disk/.../boot.log` persists it via normal +// redirection. +// +// Line-based: the ring stores whole lines up to MAX_LINE bytes; longer +// lines are truncated. Each line gets a sequence number; when the ring +// wraps it drops the oldest line and counts it, so a dump can report how +// much history was lost. The ring never allocates (const-constructible +// static), so it works from the very first log line; only `dump()` +// allocates, and that is called at shell time. +// --------------------------------------------------------------------------- + +extern crate alloc; + +use alloc::string::String; + +pub const MAX_LINES: usize = 128; +pub const MAX_LINE: usize = 128; + +struct Ring { + /// Sequence counter for the next line to be appended (total ever). + seq: u64, + /// Lines dropped because the ring was full (wrap overwrites). + dropped: u64, + /// Live lines currently in the ring (0..=MAX_LINES). + count: usize, + /// Slot the next line will be written to (oldest once full). + next: usize, + lens: [u8; MAX_LINES], + bytes: [[u8; MAX_LINE]; MAX_LINES], +} + +static mut RING: Ring = Ring { + seq: 0, + dropped: 0, + count: 0, + next: 0, + lens: [0; MAX_LINES], + bytes: [[0; MAX_LINE]; MAX_LINES], +}; + +fn ring() -> &'static mut Ring { + unsafe { &mut *core::ptr::addr_of_mut!(RING) } +} + +/// Append one line to the ring (line-oriented; newlines are stripped). +/// Truncated at MAX_LINE bytes. Never allocates, never logs. +pub fn append(line: &str) { + let r = ring(); + let b = line.as_bytes(); + let n = b.len().min(MAX_LINE); + if r.count == MAX_LINES { + r.dropped += 1; // overwrite the oldest line + } else { + r.count += 1; + } + r.bytes[r.next][..n].copy_from_slice(&b[..n]); + r.lens[r.next] = n as u8; + r.next = (r.next + 1) % MAX_LINES; + r.seq += 1; +} + +/// Append the formatted output of a `serial_println!` — the macro hook. +/// `fmt::Write` may deliver the line in several chunks, so accumulate +/// into one line buffer first, then append the whole line. +pub fn append_fmt(args: core::fmt::Arguments<'_>) { + let mut line = LineBuf::new(); + let _ = core::fmt::write(&mut line, args); + append(line.as_str()); +} + +struct LineBuf { + bytes: [u8; MAX_LINE], + len: usize, +} + +impl LineBuf { + fn new() -> Self { + LineBuf { + bytes: [0; MAX_LINE], + len: 0, + } + } + fn as_str(&self) -> &str { + core::str::from_utf8(&self.bytes[..self.len]).unwrap_or("") + } +} + +impl core::fmt::Write for LineBuf { + fn write_str(&mut self, s: &str) -> core::fmt::Result { + let n = s.len().min(MAX_LINE - self.len); + self.bytes[self.len..self.len + n].copy_from_slice(&s.as_bytes()[..n]); + self.len += n; + Ok(()) + } +} + +/// The whole log as text: a header with the wrap/drop accounting, then +/// one line per entry, each prefixed with its sequence number. +pub fn dump() -> String { + let r = ring(); + let mut out = String::new(); + if r.count == 0 { + out += "klog: no messages logged yet\n"; + return out; + } + let first = r.seq - r.count as u64; + let last = r.seq - 1; + out += &alloc::format!( + "klog: {} line(s) kept, {} dropped on wrap, seq {}..{}\n", + r.count, + r.dropped, + first, + last + ); + let start = (r.next + MAX_LINES - r.count) % MAX_LINES; + for i in 0..r.count { + let idx = (start + i) % MAX_LINES; + let n = r.lens[idx] as usize; + let text = core::str::from_utf8(&r.bytes[idx][..n]).unwrap_or(""); + out += &alloc::format!("{:06} {}\n", first + i as u64, text); + } + out +} diff --git a/rsnix/src/lib.rs b/rsnix/src/lib.rs index fc823ea..a2d41da 100644 --- a/rsnix/src/lib.rs +++ b/rsnix/src/lib.rs @@ -8,6 +8,7 @@ pub mod font; pub mod fs; pub mod gop; pub mod interrupts; +pub mod klog; pub mod memory; pub mod paging; pub mod pci; diff --git a/rsnix/src/serial.rs b/rsnix/src/serial.rs index 03fa570..484a114 100644 --- a/rsnix/src/serial.rs +++ b/rsnix/src/serial.rs @@ -91,12 +91,21 @@ macro_rules! serial_print { }}; } +/// Prints a line to serial and appends it to the kernel log ring +/// (klog — see /dev/klog). Every kernel-side message funnels through +/// here, so the ring captures the whole boot sequence for free. +/// User-facing shell output must NOT use this macro (shell output would +/// pollute the boot log); it writes to the serial port directly. #[macro_export] macro_rules! serial_println { - () => { $crate::serial::write_str("\r\n"); }; + () => { + $crate::serial::write_str("\r\n"); + $crate::klog::append_fmt(core::format_args!("")); + }; ($($arg:tt)*) => {{ $crate::serial_print!($($arg)*); $crate::serial::write_str("\r\n"); + $crate::klog::append_fmt(core::format_args!($($arg)*)); }}; } diff --git a/shell/src/lib.rs b/shell/src/lib.rs index cf46cb0..ddd8688 100644 --- a/shell/src/lib.rs +++ b/shell/src/lib.rs @@ -28,7 +28,7 @@ use alloc::collections::VecDeque; use alloc::string::{String, ToString}; use alloc::vec::Vec; use rsnix::tty::{self, LineInput}; -use rsnix::{gop_print, gop_println, serial_print, serial_println}; +use rsnix::{gop_print, gop_println}; /// Run the shell forever. pub fn run() -> ! { @@ -36,18 +36,17 @@ pub fn run() -> ! { "rs-dos v{} — type 'help' for commands", env!("CARGO_PKG_VERSION") ); - serial_println!( + term_println(&alloc::format!( "========== rs-dos v{} ==========", env!("CARGO_PKG_VERSION") - ); + )); loop { // Push any deferred scrolls so the prompt renders on a current // framebuffer (e.g. after a streaming command's batch of output). rsnix::vt::sync_scroll(); // Print prompt - gop_print!("> "); - serial_print!("> "); + term_print("> "); // Read one line from keyboard (tty canonical mode) match tty::read_line() { @@ -65,13 +64,26 @@ pub fn run() -> ! { } // --------------------------------------------------------------------------- -// Diagnostics go straight to terminal + serial, never through the filter -// pipeline and never into a file sink. +// Diagnostics and command output go straight to terminal + serial, never +// through the filter pipeline and never into a file sink. These helpers +// write to the serial port directly — NOT via `serial_println!`, which +// feeds the klog ring — so user-facing shell output (prompts, echoes, +// command results) never lands in the boot log. // --------------------------------------------------------------------------- +fn term_print(s: &str) { + gop_print!("{}", s); + rsnix::serial::write_str(s); +} + +fn term_println(s: &str) { + term_print(s); + gop_println!(); + rsnix::serial::write_str("\r\n"); +} + fn term_err(msg: &str) { - gop_println!("{}", msg); - serial_println!("{}", msg); + term_println(msg); } // --------------------------------------------------------------------------- @@ -541,8 +553,7 @@ impl Pipeline { fn emit(&mut self, l: &str) { match &self.sink { OutSink::Term => { - gop_println!("{}", l); - serial_println!("{}", l); + term_println(l); } OutSink::File { .. } => {} } @@ -672,6 +683,7 @@ write `{} TIL `", "pci" => cmd_pci(&parsed), "ls" => cmd_ls(&parsed), "cat" => cmd_cat(&parsed), + "klog" => cmd_klog(&parsed), "hexdump" => cmd_hexdump(&parsed), "mkdir" => cmd_mkdir(&parsed), "touch" => cmd_touch(&parsed), @@ -700,6 +712,7 @@ fn cmd_help(_p: &Parsed) { pci — list PCI devices ls — list a directory cat — print files (cat USE a TO b copies a→b; cat TIL END is a heredoc) + klog — kernel boot log (cat /dev/klog; WRITING persists it) hexdump — hex-dump a file or input stream mkdir — create a directory touch — create an empty file @@ -788,6 +801,29 @@ fn cmd_ls(p: &Parsed) { pipe.end(); } +// --------------------------------------------------------------------------- +// klog — kernel log (thin alias for `cat /dev/klog`) +// --------------------------------------------------------------------------- + +fn cmd_klog(p: &Parsed) { + if !p.args.is_empty() { + term_err("klog: usage: klog [-h N] [-t N] [-g PAT] [-p] [WRITING | TO ]"); + return; + } + // Alias for `cat /dev/klog` — same filters and redirection, so + // `klog -t 5` shows the last 5 log lines and `klog WRITING + // /disk/.../boot.log` persists the boot log. Input keywords were + // already rejected (klog does not accept input). + let q = Parsed { + cmd: alloc::string::String::from("klog"), + args: alloc::vec!["/dev/klog".into()], + input: Input::None, + filters: p.filters.clone(), + output: p.output.clone(), + }; + cmd_cat(&q); +} + // --------------------------------------------------------------------------- // cat — file and stream consumers // --------------------------------------------------------------------------- @@ -1471,8 +1507,7 @@ fn cmd_stress(p: &Parsed) { } fn cmd_halt() -> ! { - gop_println!("halting..."); - serial_println!("halting..."); + term_println("halting..."); rsnix::power::halt() } @@ -1515,7 +1550,6 @@ fn cmd_pci(p: &Parsed) { } fn cmd_poweroff() -> ! { - gop_println!("shutting down..."); - serial_println!("shutting down..."); + term_println("shutting down..."); rsnix::power::poweroff() } -- cgit v1.2.3