alnyan/yggdrasil
1
0
Fork 0
Code Issues 33 Pull Requests Packages Projects Releases Wiki Activity

debug: better kernel ring logger

Browse Source
This commit is contained in:
Mark Poliakov 2025-02-09 14:30:39 +02:00
parent a08fe6ab1b
commit 5edb26a757
8 changed files with 759 additions and 535 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

2
kernel/libk/src/config/general.rs
View File

@ -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,
}

533
kernel/libk/src/debug.rs
View File

@ -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<DebugSinkWrapper, MAX_DEBUG_SINKS>>,
}
struct RingLoggerInner {
data: RingBuffer<u8>,
}
/// Logger sink which collects output to an internal ring buffer
pub struct RingLoggerSink {
inner: IrqSafeSpinlock<RingLoggerInner>,
}
/// 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<dyn DebugSink>),
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<log::Level> 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<StaticVector<DebugSinkWrapper, MAX_DEBUG_SINKS>> =
IrqSafeRwLock::new(StaticVector::new());
/// See [RingLoggerSink]
pub static RING_LOGGER_SINK: RingLoggerSink = RingLoggerSink::new();
fn make_sysfs_sink_object(index: usize) -> Arc<KObject<usize>> {
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<String, Error> {
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<dyn DebugSink>, level: LogLevel) {
add_sink_inner(DebugSinkWrapper::Arc(level, sink.clone()));
}
pub fn add_serial_sink(sink: Arc<dyn DebugSink>, 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<Self, Self::Err> {
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),
}
}
}

240
kernel/libk/src/debug/mod.rs Normal file
View File

@ -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<log::Level> 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<KObject<usize>> {
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<String, Error> {
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<Self, Self::Err> {
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),
}
}
}

54
kernel/libk/src/debug/panic.rs Normal file
View File

@ -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<DebugSinkWrapper, MAX_DEBUG_SINKS>>,
}
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)+))
}

270
kernel/libk/src/debug/ring.rs Normal file
View File

@ -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<LogBuffer> = 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<usize>,
}
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<Metadata, Error> {
unreachable!()
}
fn size(&self, _node: &NodeRef) -> Result<u64, Error> {
Ok(0)
}
fn as_any(&self) -> &dyn Any {
self
}
}
impl RegularImpl for LogFile {
fn open(
&self,
_node: &NodeRef,
opts: OpenOptions,
) -> Result<(u64, Option<InstanceData>), 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<usize, Error> {
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))
}

186
kernel/libk/src/debug/sink.rs Normal file
View File

@ -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<dyn DebugSink>),
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<StaticVector<DebugSinkWrapper, MAX_DEBUG_SINKS>> =
IrqSafeRwLock::new(StaticVector::new());
static SERIAL_SINK_SET_UP: AtomicBool = AtomicBool::new(false);
/// Adds a debugging output sink
pub fn add_sink(sink: Arc<dyn DebugSink>, 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<dyn DebugSink>, 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();
}
}

6
kernel/libk/src/fs/sysfs/object.rs
View File

@ -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<D> KObject<D> {
self.node.add_child(filename, child.node.clone())
}
pub fn node(&self) -> &NodeRef {
&self.node
}
pub(super) fn data(&self) -> &D {
&self.data
}

3
kernel/src/main.rs
View File

@ -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.