From 5edb26a75773deeb29a8600a79900a97ee419a76 Mon Sep 17 00:00:00 2001 From: Mark Poliakov Date: Sun, 9 Feb 2025 14:30:39 +0200 Subject: [PATCH] debug: better kernel ring logger --- kernel/libk/src/config/general.rs | 2 +- kernel/libk/src/debug.rs | 533 ----------------------------- kernel/libk/src/debug/mod.rs | 240 +++++++++++++ kernel/libk/src/debug/panic.rs | 54 +++ kernel/libk/src/debug/ring.rs | 270 +++++++++++++++ kernel/libk/src/debug/sink.rs | 186 ++++++++++ kernel/libk/src/fs/sysfs/object.rs | 6 +- kernel/src/main.rs | 3 + 8 files changed, 759 insertions(+), 535 deletions(-) delete mode 100644 kernel/libk/src/debug.rs create mode 100644 kernel/libk/src/debug/mod.rs create mode 100644 kernel/libk/src/debug/panic.rs create mode 100644 kernel/libk/src/debug/ring.rs create mode 100644 kernel/libk/src/debug/sink.rs diff --git a/kernel/libk/src/config/general.rs b/kernel/libk/src/config/general.rs index 654b4388..5cdcafdb 100644 --- a/kernel/libk/src/config/general.rs +++ b/kernel/libk/src/config/general.rs @@ -18,7 +18,7 @@ pub struct DebugOptions { impl Default for DebugOptions { fn default() -> Self { Self { - serial_level: LogLevel::Debug, // LogLevel::Info, + serial_level: LogLevel::Info, display_level: LogLevel::Info, disable_program_trace: false, } diff --git a/kernel/libk/src/debug.rs b/kernel/libk/src/debug.rs deleted file mode 100644 index 12200e8b..00000000 --- a/kernel/libk/src/debug.rs +++ /dev/null @@ -1,533 +0,0 @@ -//! Utilities for debug information logging - -// TODO -#![allow(missing_docs)] - -use core::{ - fmt::{self, Arguments}, - str::FromStr, - sync::atomic::{AtomicBool, Ordering}, -}; - -use alloc::{ - format, - string::{String, ToString}, - sync::Arc, -}; -use libk_util::{ - ring::RingBuffer, - sync::{ - spin_rwlock::{IrqSafeRwLock, IrqSafeRwLockReadGuard}, - IrqSafeSpinlock, - }, - OneTimeInit, StaticVector, -}; -use yggdrasil_abi::error::Error; - -use crate::{ - arch::Cpu, - config, - fs::sysfs::{ - self, - attribute::{StringAttribute, StringAttributeOps}, - object::KObject, - }, - task::{process::Process, thread::Thread}, - time::monotonic_time, -}; - -const MAX_DEBUG_SINKS: usize = 8; -const RING_LOGGER_CAPACITY: usize = 65536; - -static RING_AVAILABLE: AtomicBool = AtomicBool::new(false); -static SERIAL_SINK_SET_UP: AtomicBool = AtomicBool::new(false); -static DEBUG_LOCK: IrqSafeSpinlock<()> = IrqSafeSpinlock::new(()); - -struct KernelLoggerSink; -/// Locking log sink for dumping panic info -pub struct PanicLoggerSink<'a> { - lock: IrqSafeRwLockReadGuard<'a, StaticVector>, -} - -struct RingLoggerInner { - data: RingBuffer, -} - -/// Logger sink which collects output to an internal ring buffer -pub struct RingLoggerSink { - inner: IrqSafeSpinlock, -} - -/// Defines the severity of the message -#[derive(Debug, Clone, Copy, PartialEq, Eq, PartialOrd, Ord)] -pub enum LogLevel { - /// Very verbose low-level debugging information - Trace, - /// Debugging and verbose information - Debug, - /// General information about transitions in the system state - Info, - /// Non-critical abnormalities or notices - Warning, - /// Failures of non-essential components - Error, - /// Irrecoverable errors which result in kernel panic - Fatal, -} - -/// Generic interface for debug output -pub trait DebugSink: Sync { - /// Sends a single byte to the output - fn putc(&self, c: u8) -> Result<(), Error>; - - /// Sends a string of bytes to the output - fn puts(&self, s: &str) -> Result<(), Error> { - for &byte in s.as_bytes() { - self.putc(byte)?; - } - Ok(()) - } - - /// Returns `true` if the device supports vt100-like control sequences - fn supports_control_sequences(&self) -> bool { - false - } -} - -#[derive(Clone)] -pub enum DebugSinkWrapper { - Arc(LogLevel, Arc), - Static(LogLevel, &'static dyn DebugSink), -} - -unsafe impl Send for DebugSinkWrapper {} -unsafe impl Sync for DebugSinkWrapper {} -// #[derive(Clone, Copy)] -// struct DebugSinkWrapper { -// // inner: &'static dyn DebugSink, -// level: LogLevel, -// } - -struct SinkWriter<'a> { - sink: &'a dyn DebugSink, -} - -impl fmt::Write for SinkWriter<'_> { - fn write_str(&mut self, s: &str) -> fmt::Result { - self.sink.puts(s).map_err(|_| fmt::Error) - } -} - -impl DebugSinkWrapper { - #[inline] - pub fn sink(&self) -> &dyn DebugSink { - match self { - Self::Arc(_, arc) => arc.as_ref(), - Self::Static(_, sink) => *sink, - } - } - - #[inline] - pub fn level(&self) -> LogLevel { - match self { - Self::Arc(level, _) => *level, - Self::Static(level, _) => *level, - } - } - - pub fn set_level(&mut self, target: LogLevel) { - match self { - Self::Arc(level, _) => *level = target, - Self::Static(level, _) => *level = target, - } - } -} - -impl log::Log for DebugSinkWrapper { - fn enabled(&self, metadata: &log::Metadata) -> bool { - if LogLevel::from(metadata.level()) < self.level() { - return false; - } - if metadata.target() == "program" && config::get().debug.disable_program_trace { - return false; - } - - true - } - - fn log(&self, record: &log::Record) { - use core::fmt::Write; - - let level = LogLevel::from(record.level()); - let sink = self.sink(); - let cpu = Cpu::try_local().map(|c| c.id()); - let line = record.line().unwrap_or(0); - let args = record.args(); - - let (prefix, suffix) = if sink.supports_control_sequences() { - (level.log_prefix(), level.log_suffix()) - } else { - ("", "") - }; - - let mut writer = SinkWriter { sink }; - let now = monotonic_time(); - let s = now.seconds(); - - match record.target() { - ":program" => { - write!(writer, "{prefix}{s:06}:").ok(); - if let Some(cpu) = cpu { - write!(writer, "{cpu}:").ok(); - } else { - write!(writer, "?:").ok(); - } - write!(writer, "ptrace:{args}").ok(); - } - ":raw" => { - write!(writer, "{prefix}{args}{suffix}").ok(); - } - target => { - write!(writer, "{prefix}{s:06}:").ok(); - if let Some(cpu) = cpu { - write!(writer, "{cpu}:").ok(); - } else { - write!(writer, "?:").ok(); - } - writeln!(writer, "{target}:{line}: {args}{suffix}").ok(); - } - } - } - - fn flush(&self) {} -} - -impl log::Log for RingLoggerSink { - fn enabled(&self, metadata: &log::Metadata) -> bool { - metadata.target() != "program" - } - - fn log(&self, record: &log::Record) { - use fmt::Write; - let mut lock = self.inner.lock(); - let file = record.file().unwrap_or(""); - let line = record.line().unwrap_or(0); - writeln!(lock, "{}:{}: {}", file, line, record.args()).ok(); - } - - fn flush(&self) {} -} - -impl log::Log for KernelLoggerSink { - fn enabled(&self, metadata: &log::Metadata) -> bool { - metadata.target() != "io" - } - - fn log(&self, record: &log::Record) { - if !self.enabled(record.metadata()) { - return; - } - - let _guard = DEBUG_LOCK.lock(); - if RING_AVAILABLE.load(Ordering::Acquire) { - RING_LOGGER_SINK.log(record); - } - for sink in DEBUG_SINKS.read().iter() { - if sink.enabled(record.metadata()) { - sink.log(record); - } - } - } - - fn flush(&self) {} -} - -impl LogLevel { - fn log_prefix(self) -> &'static str { - match self { - LogLevel::Trace => "", - LogLevel::Debug => "", - LogLevel::Info => "\x1b[36m\x1b[1m", - LogLevel::Warning => "\x1b[33m\x1b[1m", - LogLevel::Error => "\x1b[31m\x1b[1m", - LogLevel::Fatal => "\x1b[38;2;255;0;0m\x1b[1m", - } - } - - fn log_suffix(self) -> &'static str { - match self { - LogLevel::Trace => "", - LogLevel::Debug => "", - LogLevel::Info => "\x1b[0m", - LogLevel::Warning => "\x1b[0m", - LogLevel::Error => "\x1b[0m", - LogLevel::Fatal => "\x1b[0m", - } - } -} - -impl RingLoggerSink { - const fn new() -> Self { - Self { - inner: IrqSafeSpinlock::new(RingLoggerInner { - data: RingBuffer::with_capacity(RING_LOGGER_CAPACITY), - }), - } - } - - /// Reads data from the sink without blocking and waiting for more to arrive - pub fn read(&self, pos: usize, buffer: &mut [u8]) -> usize { - unsafe { self.inner.lock().data.read_all_static(pos, buffer) } - } - - fn init_buffer(&self) -> Result<(), Error> { - self.inner.lock().data.reserve() - } -} - -impl fmt::Write for RingLoggerInner { - fn write_str(&mut self, s: &str) -> fmt::Result { - for ch in s.bytes() { - self.data.write(ch); - } - Ok(()) - } -} - -impl From for LogLevel { - fn from(value: log::Level) -> Self { - match value { - log::Level::Trace => Self::Trace, - log::Level::Debug => Self::Debug, - log::Level::Info => Self::Info, - log::Level::Warn => Self::Warning, - log::Level::Error => Self::Error, - } - } -} - -impl PanicLoggerSink<'_> { - /// Locks the global logger, allowing the panicking CPU to dump its panic info without being - /// interrupted - pub fn lock() -> Self { - Self { - lock: DEBUG_SINKS.read(), - } - } - - /// Prints a formatted message to the panic log - pub fn log_fmt(&self, args: Arguments) { - use log::Log; - - self.log( - &log::Record::builder() - .level(log::Level::Error) - .target(":raw") - .args(args) - .build(), - ) - } -} - -impl log::Log for PanicLoggerSink<'_> { - fn enabled(&self, _metadata: &log::Metadata) -> bool { - true - } - - fn log(&self, record: &log::Record) { - for sink in self.lock.iter() { - if sink.enabled(record.metadata()) { - sink.log(record); - } - } - } - - fn flush(&self) {} -} - -/// Logs a formatted message to the panic output -pub macro panic_log($sink:expr, $($args:tt)+) { - $sink.log_fmt(format_args!($($args)+)) -} - -static LOGGER: KernelLoggerSink = KernelLoggerSink; - -static DEBUG_SINKS: IrqSafeRwLock> = - IrqSafeRwLock::new(StaticVector::new()); - -/// See [RingLoggerSink] -pub static RING_LOGGER_SINK: RingLoggerSink = RingLoggerSink::new(); - -fn make_sysfs_sink_object(index: usize) -> Arc> { - struct Level; - - impl StringAttributeOps for Level { - type Data = usize; - const NAME: &'static str = "level"; - const LIMIT: usize = 16; - const WRITEABLE: bool = true; - - fn read(state: &Self::Data) -> Result { - let sinks = DEBUG_SINKS.read(); - let sink = sinks.get(*state).ok_or(Error::InvalidFile)?; - Ok(sink.level().to_string()) - } - - fn write(state: &Self::Data, value: &str) -> Result<(), Error> { - let level = LogLevel::from_str(value)?; - let mut sinks = DEBUG_SINKS.write(); - let sink = sinks.get_mut(*state).ok_or(Error::InvalidFile)?; - sink.set_level(level); - Ok(()) - } - } - - let object = KObject::new(index); - - object.add_attribute(StringAttribute::from(Level)).ok(); - - object -} - -fn add_sink_inner(sink: DebugSinkWrapper) { - let index = { - let mut sinks = DEBUG_SINKS.write(); - let index = sinks.len(); - sinks.push(sink); - index - }; - - if let Some(debug) = sysfs::debug() { - debug - .add_object(format!("{index}"), make_sysfs_sink_object(index)) - .ok(); - } -} - -/// Adds a debugging output sink -pub fn add_sink(sink: Arc, level: LogLevel) { - add_sink_inner(DebugSinkWrapper::Arc(level, sink.clone())); -} - -pub fn add_serial_sink(sink: Arc, level: LogLevel) { - if SERIAL_SINK_SET_UP.swap(true, Ordering::Acquire) { - return; - } - - add_sink(sink, level); -} - -pub fn add_early_sink(sink: &'static dyn DebugSink, level: LogLevel) { - add_sink_inner(DebugSinkWrapper::Static(level, sink)); -} - -pub fn disable_early_sinks() { - let mut sinks = DEBUG_SINKS.write(); - // TODO proper sink storage/manipulation - for sink in sinks.iter_mut() { - if let DebugSinkWrapper::Static(level, _) = sink { - *level = LogLevel::Fatal; - } - } -} - -/// Print a trace message coming from a process -pub fn program_trace(process: &Process, _thread: &Thread, message: &str) { - log::debug!( - target: ":program", - "{} ({}) {message}\n", - process.name, - process.id, - ); -} - -pub fn init_logger() { - static LOGGER_SET_UP: OneTimeInit<()> = OneTimeInit::new(); - - LOGGER_SET_UP.or_init_with(|| { - log::set_logger(&LOGGER) - .map(|_| log::set_max_level(log::LevelFilter::Trace)) - .ok(); - }); -} - -/// Resets the debugging terminal by clearing it -pub fn init() { - if RING_LOGGER_SINK.init_buffer().is_ok() { - RING_AVAILABLE.store(true, Ordering::Release); - } - - init_logger(); -} - -pub fn hex_dump(level: log::Level, bytes: &[u8], start_address: u64, with_chars: bool) { - if bytes.is_empty() { - return; - } - - let line_width = 16; - let address_width = (start_address + bytes.len() as u64).ilog10() as usize + 1; - - for i in (0..bytes.len()).step_by(line_width) { - log::log!(target: ":raw", level, "{:0width$X}: ", start_address + i as u64, width = address_width); - - for j in 0..line_width { - if i + j < bytes.len() { - log::log!(target: ":raw", level, "{:02X}", bytes[i + j]); - } else { - log::log!(target: ":raw", level, " "); - } - - if j % 2 != 0 { - log::log!(target: ":raw", level, " "); - } - } - - if with_chars { - for j in 0..line_width { - if i + j >= bytes.len() { - break; - } - let ch = if bytes[i + j].is_ascii_graphic() { - bytes[i + j] - } else { - b'.' - }; - log::log!(target: ":raw", level, "{}", ch as char); - } - } - - log::log!(target: ":raw", level, "\n"); - } -} - -impl fmt::Display for LogLevel { - fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { - let level = match self { - Self::Trace => "trace", - Self::Debug => "debug", - Self::Info => "info", - Self::Warning => "warn", - Self::Error => "error", - Self::Fatal => "fatal", - }; - - f.write_str(level) - } -} - -impl FromStr for LogLevel { - type Err = Error; - - fn from_str(s: &str) -> Result { - match s { - "trace" | "t" => Ok(Self::Trace), - "debug" | "d" => Ok(Self::Debug), - "info" | "i" => Ok(Self::Info), - "warn" | "w" => Ok(Self::Warning), - "error" | "e" => Ok(Self::Error), - "fatal" | "f" => Ok(Self::Fatal), - _ => Err(Error::InvalidArgument), - } - } -} diff --git a/kernel/libk/src/debug/mod.rs b/kernel/libk/src/debug/mod.rs new file mode 100644 index 00000000..855f0b34 --- /dev/null +++ b/kernel/libk/src/debug/mod.rs @@ -0,0 +1,240 @@ +//! Utilities for debug information logging + +use alloc::{ + string::{String, ToString}, + sync::Arc, +}; +use core::{fmt, str::FromStr}; +use ring::RingLoggerSink; + +use libk_util::{sync::IrqSafeSpinlock, OneTimeInit}; +use sink::DEBUG_SINKS; +use yggdrasil_abi::error::Error; + +use crate::{ + fs::sysfs::{ + attribute::{StringAttribute, StringAttributeOps}, + object::KObject, + }, + task::{process::Process, thread::Thread}, +}; + +mod panic; +mod ring; +mod sink; + +pub use panic::{panic_log, PanicLoggerSink}; +pub use ring::add_kernel_log_file; +pub use sink::{add_early_sink, add_serial_sink, add_sink, DebugSink}; + +static DEBUG_LOCK: IrqSafeSpinlock<()> = IrqSafeSpinlock::new(()); + +struct KernelLoggerSink; + +/// Defines the severity of the message +#[derive(Debug, Clone, Copy, PartialEq, Eq, PartialOrd, Ord)] +pub enum LogLevel { + /// Very verbose low-level debugging information + Trace, + /// Debugging and verbose information + Debug, + /// General information about transitions in the system state + Info, + /// Non-critical abnormalities or notices + Warning, + /// Failures of non-essential components + Error, + /// Irrecoverable errors which result in kernel panic + Fatal, +} + +impl LogLevel { + fn log_prefix(self) -> &'static str { + match self { + LogLevel::Trace => "", + LogLevel::Debug => "", + LogLevel::Info => "\x1b[36m\x1b[1m", + LogLevel::Warning => "\x1b[33m\x1b[1m", + LogLevel::Error => "\x1b[31m\x1b[1m", + LogLevel::Fatal => "\x1b[38;2;255;0;0m\x1b[1m", + } + } + + fn log_suffix(self) -> &'static str { + match self { + LogLevel::Trace => "", + LogLevel::Debug => "", + LogLevel::Info => "\x1b[0m", + LogLevel::Warning => "\x1b[0m", + LogLevel::Error => "\x1b[0m", + LogLevel::Fatal => "\x1b[0m", + } + } +} + +impl From for LogLevel { + fn from(value: log::Level) -> Self { + match value { + log::Level::Trace => Self::Trace, + log::Level::Debug => Self::Debug, + log::Level::Info => Self::Info, + log::Level::Warn => Self::Warning, + log::Level::Error => Self::Error, + } + } +} + +impl log::Log for KernelLoggerSink { + fn enabled(&self, metadata: &log::Metadata) -> bool { + metadata.target() != "io" + } + + fn log(&self, record: &log::Record) { + if !self.enabled(record.metadata()) { + return; + } + + RingLoggerSink.log(record); + + let _guard = DEBUG_LOCK.lock(); + for sink in DEBUG_SINKS.read().iter() { + if sink.enabled(record.metadata()) { + sink.log(record); + } + } + } + + fn flush(&self) {} +} + +static LOGGER: KernelLoggerSink = KernelLoggerSink; + +fn make_sysfs_sink_object(index: usize) -> Arc> { + struct Level; + + impl StringAttributeOps for Level { + type Data = usize; + const NAME: &'static str = "level"; + const LIMIT: usize = 16; + const WRITEABLE: bool = true; + + fn read(state: &Self::Data) -> Result { + let sinks = DEBUG_SINKS.read(); + let sink = sinks.get(*state).ok_or(Error::InvalidFile)?; + Ok(sink.level().to_string()) + } + + fn write(state: &Self::Data, value: &str) -> Result<(), Error> { + let level = LogLevel::from_str(value)?; + let mut sinks = DEBUG_SINKS.write(); + let sink = sinks.get_mut(*state).ok_or(Error::InvalidFile)?; + sink.set_level(level); + Ok(()) + } + } + + let object = KObject::new(index); + + object.add_attribute(StringAttribute::from(Level)).ok(); + + object +} + +/// Print a trace message coming from a process +pub fn program_trace(process: &Process, _thread: &Thread, message: &str) { + log::debug!( + target: ":program", + "{} ({}) {message}\n", + process.name, + process.id, + ); +} + +/// Initializes kernel logging output. Prior to this call, no log entries are recorded. +pub fn init_logger() { + static LOGGER_SET_UP: OneTimeInit<()> = OneTimeInit::new(); + + LOGGER_SET_UP.or_init_with(|| { + log::set_logger(&LOGGER) + .map(|_| log::set_max_level(log::LevelFilter::Trace)) + .ok(); + }); +} + +/// Resets the debugging terminal by clearing it +pub fn init() { + init_logger(); +} + +/// Print a hex dump into the kernel log with given level +pub fn hex_dump(level: log::Level, bytes: &[u8], start_address: u64, with_chars: bool) { + if bytes.is_empty() { + return; + } + + let line_width = 16; + let address_width = (start_address + bytes.len() as u64).ilog10() as usize + 1; + + for i in (0..bytes.len()).step_by(line_width) { + log::log!(target: ":raw", level, "{:0width$X}: ", start_address + i as u64, width = address_width); + + for j in 0..line_width { + if i + j < bytes.len() { + log::log!(target: ":raw", level, "{:02X}", bytes[i + j]); + } else { + log::log!(target: ":raw", level, " "); + } + + if j % 2 != 0 { + log::log!(target: ":raw", level, " "); + } + } + + if with_chars { + for j in 0..line_width { + if i + j >= bytes.len() { + break; + } + let ch = if bytes[i + j].is_ascii_graphic() { + bytes[i + j] + } else { + b'.' + }; + log::log!(target: ":raw", level, "{}", ch as char); + } + } + + log::log!(target: ":raw", level, "\n"); + } +} + +impl fmt::Display for LogLevel { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + let level = match self { + Self::Trace => "trace", + Self::Debug => "debug", + Self::Info => "info", + Self::Warning => "warn", + Self::Error => "error", + Self::Fatal => "fatal", + }; + + f.write_str(level) + } +} + +impl FromStr for LogLevel { + type Err = Error; + + fn from_str(s: &str) -> Result { + match s { + "trace" | "t" => Ok(Self::Trace), + "debug" | "d" => Ok(Self::Debug), + "info" | "i" => Ok(Self::Info), + "warn" | "w" => Ok(Self::Warning), + "error" | "e" => Ok(Self::Error), + "fatal" | "f" => Ok(Self::Fatal), + _ => Err(Error::InvalidArgument), + } + } +} diff --git a/kernel/libk/src/debug/panic.rs b/kernel/libk/src/debug/panic.rs new file mode 100644 index 00000000..4e0ef2c3 --- /dev/null +++ b/kernel/libk/src/debug/panic.rs @@ -0,0 +1,54 @@ +use core::fmt::Arguments; + +use libk_util::{sync::spin_rwlock::IrqSafeRwLockReadGuard, StaticVector}; + +use super::sink::{DebugSinkWrapper, DEBUG_SINKS, MAX_DEBUG_SINKS}; + +/// Locking log sink for dumping panic info +pub struct PanicLoggerSink<'a> { + lock: IrqSafeRwLockReadGuard<'a, StaticVector>, +} + +impl PanicLoggerSink<'_> { + /// Locks the global logger, allowing the panicking CPU to dump its panic info without being + /// interrupted + pub fn lock() -> Self { + Self { + lock: DEBUG_SINKS.read(), + } + } + + /// Prints a formatted message to the panic log + pub fn log_fmt(&self, args: Arguments) { + use log::Log; + + self.log( + &log::Record::builder() + .level(log::Level::Error) + .target(":raw") + .args(args) + .build(), + ) + } +} + +impl log::Log for PanicLoggerSink<'_> { + fn enabled(&self, _metadata: &log::Metadata) -> bool { + true + } + + fn log(&self, record: &log::Record) { + for sink in self.lock.iter() { + if sink.enabled(record.metadata()) { + sink.log(record); + } + } + } + + fn flush(&self) {} +} + +/// Logs a formatted message to the panic output +pub macro panic_log($sink:expr, $($args:tt)+) { + $sink.log_fmt(format_args!($($args)+)) +} diff --git a/kernel/libk/src/debug/ring.rs b/kernel/libk/src/debug/ring.rs new file mode 100644 index 00000000..2a321fbf --- /dev/null +++ b/kernel/libk/src/debug/ring.rs @@ -0,0 +1,270 @@ +use core::{any::Any, fmt, future::poll_fn, task::Poll}; + +use alloc::sync::Arc; +use libk_util::{sync::spin_rwlock::IrqSafeRwLock, waker::QueueWaker}; +use yggdrasil_abi::{ + error::Error, + io::{FileMode, OpenOptions}, +}; + +use crate::{ + task::sync::AsyncMutex, + vfs::{CommonImpl, Filename, InstanceData, Metadata, Node, NodeFlags, NodeRef, RegularImpl}, +}; + +const RECORD_SIZE: usize = 128; +const FIXED_LOG_SIZE: usize = 256; + +struct LogFile; +pub(super) struct RingLoggerSink; + +struct WriteBuffer { + text: [u8; 255], + len: usize, +} + +struct Record { + len: usize, + level: log::Level, +} + +impl fmt::Write for WriteBuffer { + fn write_str(&mut self, s: &str) -> fmt::Result { + let bytes = s.as_bytes(); + let available = self.text.len() - self.len; + let amount = available.min(bytes.len()); + self.text[self.len..self.len + amount].copy_from_slice(&bytes[..amount]); + self.len += amount; + Ok(()) + } +} + +static mut FIXED_LOG_BUFFER: [u8; FIXED_LOG_SIZE * RECORD_SIZE] = [0; FIXED_LOG_SIZE * RECORD_SIZE]; +static mut FIXED_LOG_RECORDS: [Record; FIXED_LOG_SIZE] = [const { + Record { + len: 0, + level: log::Level::Trace, + } +}; FIXED_LOG_SIZE]; +#[allow(static_mut_refs)] +static LOG_BUFFER: IrqSafeRwLock = IrqSafeRwLock::new(unsafe { + LogBuffer::new(LogBufferStorage::Fixed { + meta: &mut FIXED_LOG_RECORDS, + data: &mut FIXED_LOG_BUFFER, + }) +}); +static LOG_NOTIFY: QueueWaker = QueueWaker::new(); + +enum LogBufferStorage { + Fixed { + meta: &'static mut [Record; FIXED_LOG_SIZE], + data: &'static mut [u8; FIXED_LOG_SIZE * RECORD_SIZE], + }, +} + +struct LogBuffer { + storage: LogBufferStorage, + head: usize, + tail: usize, + filled: bool, +} + +struct OpenLogFile { + seq: AsyncMutex, +} + +impl LogBufferStorage { + fn record_mut(&mut self, index: usize) -> (&mut Record, &mut [u8]) { + match self { + Self::Fixed { meta, data } => { + let index = index % meta.len(); + (&mut meta[index], &mut data[index * RECORD_SIZE..]) + } + } + } + + fn record(&self, index: usize) -> (&Record, &[u8]) { + match self { + Self::Fixed { meta, data } => { + let index = index % meta.len(); + (&meta[index], &data[index * RECORD_SIZE..]) + } + } + } + + fn len(&self) -> usize { + match self { + Self::Fixed { meta, .. } => meta.len(), + } + } +} + +impl LogBuffer { + const fn new(storage: LogBufferStorage) -> Self { + Self { + storage, + head: 0, + tail: 0, + filled: false, + } + } + + fn write(&mut self, level: log::Level, text: &[u8]) { + let len = text.len().min(RECORD_SIZE); + let (meta, data) = self.storage.record_mut(self.head); + meta.len = len; + meta.level = level; + data[..len].copy_from_slice(&text[..len]); + self.head = self.head.wrapping_add(1); + if self.filled { + self.tail = self.head.wrapping_sub(self.storage.len() - 1); + } else if self.head == self.storage.len() { + self.filled = true; + } + } +} + +impl CommonImpl for LogFile { + fn metadata(&self, _node: &NodeRef) -> Result { + unreachable!() + } + + fn size(&self, _node: &NodeRef) -> Result { + Ok(0) + } + + fn as_any(&self) -> &dyn Any { + self + } +} + +impl RegularImpl for LogFile { + fn open( + &self, + _node: &NodeRef, + opts: OpenOptions, + ) -> Result<(u64, Option), Error> { + if opts.contains_any(OpenOptions::WRITE | OpenOptions::APPEND | OpenOptions::TRUNCATE) { + return Err(Error::ReadOnly); + } + let instance = Arc::new(OpenLogFile { + seq: AsyncMutex::new(LOG_BUFFER.read().tail), + }); + Ok((0, Some(instance))) + } + + fn read( + &self, + _node: &NodeRef, + instance: Option<&InstanceData>, + _pos: u64, + buf: &mut [u8], + ) -> Result { + if buf.len() < 4 { + return Err(Error::InvalidArgument); + } + + let instance: &OpenLogFile = instance + .and_then(|t| t.downcast_ref()) + .ok_or(Error::InvalidFile)?; + + block! { + let mut seq = instance.seq.lock().await; + let (len, new_seq) = read_log_line(*seq, buf).await; + *seq = new_seq; + Ok(len) + }? + } + + fn close(&self, _node: &NodeRef, _instance: Option<&InstanceData>) -> Result<(), Error> { + Ok(()) + } +} + +impl log::Log for RingLoggerSink { + fn enabled(&self, metadata: &log::Metadata) -> bool { + metadata.level() != log::Level::Trace + } + + fn log(&self, record: &log::Record) { + use core::fmt::Write; + + if !self.enabled(record.metadata()) { + return; + } + + let mut write = WriteBuffer { + text: [0; 255], + len: 0, + }; + let result = if record.target() == ":raw" || record.target() == ":program" { + write!(write, "{}", record.args()) + } else { + write!(write, "{}\n", record.args()) + }; + + if let Ok(()) = result { + LOG_BUFFER + .write() + .write(record.level(), &write.text[..write.len]); + LOG_NOTIFY.wake_all(); + } + } + + fn flush(&self) {} +} + +/// Adds a kernel log file to the parent node +pub fn add_kernel_log_file(parent: &NodeRef) { + let node = Node::regular( + LogFile, + NodeFlags::IN_MEMORY_SIZE | NodeFlags::IN_MEMORY_PROPS, + Some(Metadata::now_root(FileMode::new(0o400))), + None, + ); + + let filename = unsafe { Filename::from_str_unchecked("log") }; + parent.add_child(filename, node).ok(); +} + +async fn read_log_line(seq: usize, buffer: &mut [u8]) -> (usize, usize) { + poll_fn(|cx| { + if let Some(out) = try_read_log_line(seq, buffer) { + LOG_NOTIFY.remove(cx.waker()); + Poll::Ready(out) + } else { + LOG_NOTIFY.register(cx.waker()); + Poll::Pending + } + }) + .await +} + +fn try_read_log_line(seq: usize, buffer: &mut [u8]) -> Option<(usize, usize)> { + let lock = LOG_BUFFER.read(); + if seq == lock.head { + return None; + } + let available = lock.head.wrapping_sub(seq); + let ridx = if available < lock.storage.len() { + seq + } else { + lock.tail + }; + + let (meta, data) = lock.storage.record(ridx); + let new_seq = ridx.wrapping_add(1); + let len = core::cmp::min(meta.len, buffer.len() - 2); + + buffer[0] = match meta.level { + log::Level::Trace => b't', + log::Level::Debug => b'd', + log::Level::Info => b'i', + log::Level::Warn => b'w', + log::Level::Error => b'e', + }; + buffer[1] = b':'; + buffer[2..len + 2].copy_from_slice(&data[..len]); + + Some((len + 2, new_seq)) +} diff --git a/kernel/libk/src/debug/sink.rs b/kernel/libk/src/debug/sink.rs new file mode 100644 index 00000000..383e22e0 --- /dev/null +++ b/kernel/libk/src/debug/sink.rs @@ -0,0 +1,186 @@ +use core::{ + fmt, + sync::atomic::{AtomicBool, Ordering}, +}; + +use alloc::{format, sync::Arc}; +use libk_util::{sync::spin_rwlock::IrqSafeRwLock, StaticVector}; +use yggdrasil_abi::error::Error; + +use crate::{arch::Cpu, config, fs::sysfs, time::monotonic_time}; + +use super::{make_sysfs_sink_object, LogLevel}; + +/// Generic interface for debug output +pub trait DebugSink: Sync { + /// Sends a single byte to the output + fn putc(&self, c: u8) -> Result<(), Error>; + + /// Sends a string of bytes to the output + fn puts(&self, s: &str) -> Result<(), Error> { + for &byte in s.as_bytes() { + self.putc(byte)?; + } + Ok(()) + } + + /// Returns `true` if the device supports vt100-like control sequences + fn supports_control_sequences(&self) -> bool { + false + } +} + +#[derive(Clone)] +pub enum DebugSinkWrapper { + Arc(LogLevel, Arc), + Static(LogLevel, &'static dyn DebugSink), +} + +struct SinkWriter<'a> { + sink: &'a dyn DebugSink, +} + +unsafe impl Send for DebugSinkWrapper {} +unsafe impl Sync for DebugSinkWrapper {} + +impl fmt::Write for SinkWriter<'_> { + fn write_str(&mut self, s: &str) -> fmt::Result { + self.sink.puts(s).map_err(|_| fmt::Error) + } +} + +impl DebugSinkWrapper { + #[inline] + pub fn sink(&self) -> &dyn DebugSink { + match self { + Self::Arc(_, arc) => arc.as_ref(), + Self::Static(_, sink) => *sink, + } + } + + #[inline] + pub fn level(&self) -> LogLevel { + match self { + Self::Arc(level, _) => *level, + Self::Static(level, _) => *level, + } + } + + pub fn set_level(&mut self, target: LogLevel) { + match self { + Self::Arc(level, _) => *level = target, + Self::Static(level, _) => *level = target, + } + } +} + +impl log::Log for DebugSinkWrapper { + fn enabled(&self, metadata: &log::Metadata) -> bool { + if LogLevel::from(metadata.level()) < self.level() { + return false; + } + if metadata.target() == "program" && config::get().debug.disable_program_trace { + return false; + } + + true + } + + fn log(&self, record: &log::Record) { + use core::fmt::Write; + + let level = LogLevel::from(record.level()); + let sink = self.sink(); + let cpu = Cpu::try_local().map(|c| c.id()); + let line = record.line().unwrap_or(0); + let args = record.args(); + + let (prefix, suffix) = if sink.supports_control_sequences() { + (level.log_prefix(), level.log_suffix()) + } else { + ("", "") + }; + + let mut writer = SinkWriter { sink }; + let now = monotonic_time(); + let s = now.seconds(); + + match record.target() { + ":program" => { + write!(writer, "{prefix}{s:06}:").ok(); + if let Some(cpu) = cpu { + write!(writer, "{cpu}:").ok(); + } else { + write!(writer, "?:").ok(); + } + write!(writer, "ptrace:{args}").ok(); + } + ":raw" => { + write!(writer, "{prefix}{args}{suffix}").ok(); + } + target => { + write!(writer, "{prefix}{s:06}:").ok(); + if let Some(cpu) = cpu { + write!(writer, "{cpu}:").ok(); + } else { + write!(writer, "?:").ok(); + } + writeln!(writer, "{target}:{line}: {args}{suffix}").ok(); + } + } + } + + fn flush(&self) {} +} + +pub(super) const MAX_DEBUG_SINKS: usize = 8; + +pub(super) static DEBUG_SINKS: IrqSafeRwLock> = + IrqSafeRwLock::new(StaticVector::new()); + +static SERIAL_SINK_SET_UP: AtomicBool = AtomicBool::new(false); + +/// Adds a debugging output sink +pub fn add_sink(sink: Arc, level: LogLevel) { + add_sink_inner(DebugSinkWrapper::Arc(level, sink.clone())); +} + +/// Adds a serial debug output sink. Only one will be added, rest are ignored. +pub fn add_serial_sink(sink: Arc, level: LogLevel) { + if SERIAL_SINK_SET_UP.swap(true, Ordering::Acquire) { + return; + } + + add_sink(sink, level); +} + +/// Adds an early output sink, which is disabled by a call to [disable_early_sinks]. +pub fn add_early_sink(sink: &'static dyn DebugSink, level: LogLevel) { + add_sink_inner(DebugSinkWrapper::Static(level, sink)); +} + +/// Disables eraly output sinks +pub fn disable_early_sinks() { + let mut sinks = DEBUG_SINKS.write(); + // TODO proper sink storage/manipulation + for sink in sinks.iter_mut() { + if let DebugSinkWrapper::Static(level, _) = sink { + *level = LogLevel::Fatal; + } + } +} + +fn add_sink_inner(sink: DebugSinkWrapper) { + let index = { + let mut sinks = DEBUG_SINKS.write(); + let index = sinks.len(); + sinks.push(sink); + index + }; + + if let Some(debug) = sysfs::debug() { + debug + .add_object(format!("{index}"), make_sysfs_sink_object(index)) + .ok(); + } +} diff --git a/kernel/libk/src/fs/sysfs/object.rs b/kernel/libk/src/fs/sysfs/object.rs index 0c66f69f..6fc27b53 100644 --- a/kernel/libk/src/fs/sysfs/object.rs +++ b/kernel/libk/src/fs/sysfs/object.rs @@ -4,7 +4,7 @@ use alloc::sync::Arc; use libk_util::OneTimeInit; use yggdrasil_abi::{error::Error, io::FileMode}; -use crate::vfs::{impls::MemoryDirectory, path::OwnedFilename, Metadata, Node, NodeFlags}; +use crate::vfs::{impls::MemoryDirectory, path::OwnedFilename, Metadata, Node, NodeFlags, NodeRef}; use super::attribute::Attribute; @@ -39,6 +39,10 @@ impl KObject { self.node.add_child(filename, child.node.clone()) } + pub fn node(&self) -> &NodeRef { + &self.node + } + pub(super) fn data(&self) -> &D { &self.data } diff --git a/kernel/src/main.rs b/kernel/src/main.rs index d7cbdf0c..b66ee3b5 100644 --- a/kernel/src/main.rs +++ b/kernel/src/main.rs @@ -43,6 +43,7 @@ use git_version::git_version; use kernel_arch::{Architecture, ArchitectureImpl}; use libk::{ arch::Cpu, + debug, fs::{ devfs, sysfs::{ @@ -115,9 +116,11 @@ fn register_sysfs_attributes() { } let kernel = sysfs::kernel().unwrap(); + let kernel_node = kernel.node(); kernel.add_attribute(StringAttribute::from(Version)).ok(); kernel.add_attribute(StringAttribute::from(Arch)).ok(); + debug::add_kernel_log_file(kernel_node); } /// Common kernel main function. Must be called for BSP processor only.