From dcc5d56750e9da8a1504f766f7ad9624e31978d0 Mon Sep 17 00:00:00 2001 From: Mark Poliakov Date: Wed, 19 Feb 2025 22:06:29 +0200 Subject: [PATCH] user: rework userspace tracing --- kernel/libk/src/debug/mod.rs | 5 +- kernel/src/syscall/imp/mod.rs | 1 + kernel/src/syscall/imp/sys_debug.rs | 16 ++++- lib/abi/def/yggdrasil.abi | 9 ++- lib/abi/src/debug.rs | 2 + lib/runtime/src/debug.rs | 14 ++-- lib/runtime/src/process/signal.rs | 2 +- lib/runtime/src/process/thread.rs | 8 ++- lib/runtime/src/process/thread_local/mod.rs | 19 ++++-- .../src/process/thread_local/variant1.rs | 13 +++- .../src/process/thread_local/variant2.rs | 2 +- lib/runtime/src/sys/mod.rs | 1 + userspace/Cargo.lock | 10 +++ userspace/colors/src/bin/colors-bar.rs | 2 +- userspace/colors/src/main.rs | 2 +- userspace/dyn-loader/Cargo.toml | 5 +- userspace/dyn-loader/src/error.rs | 2 +- userspace/dyn-loader/src/main.rs | 5 +- userspace/dyn-loader/src/object.rs | 12 ++-- .../dyn-loader/src/relocation/aarch64.rs | 4 +- userspace/dyn-loader/src/relocation/i686.rs | 2 +- userspace/dyn-loader/src/relocation/x86_64.rs | 5 +- userspace/dyn-loader/src/state.rs | 6 +- userspace/dyn-loader/src/thread_local/mod.rs | 17 ++--- .../dyn-loader/src/thread_local/variant1.rs | 4 +- .../dyn-loader/src/thread_local/variant2.rs | 2 +- userspace/init/Cargo.toml | 5 +- userspace/init/src/main.rs | 16 ++--- userspace/init/src/rc.rs | 2 +- userspace/lib/logsink/Cargo.toml | 4 ++ userspace/lib/logsink/src/lib.rs | 2 +- userspace/lib/logsink/src/yggdrasil.rs | 23 +++++-- userspace/lib/ygglibc/Cargo.lock | 1 + userspace/lib/ygglibc/Cargo.toml | 1 + userspace/lib/ygglibc/src/debug.rs | 66 +++++++++++++++++++ .../lib/ygglibc/src/headers/pthread/attr.rs | 10 +-- .../ygglibc/src/headers/pthread/barrier.rs | 8 +-- .../lib/ygglibc/src/headers/pthread/cond.rs | 4 +- .../lib/ygglibc/src/headers/pthread/mutex.rs | 22 +++---- .../lib/ygglibc/src/headers/pthread/tls.rs | 2 +- .../lib/ygglibc/src/headers/signal/mod.rs | 4 +- .../lib/ygglibc/src/headers/stdio/file.rs | 3 +- .../ygglibc/src/headers/sys_socket/socket.rs | 2 +- .../lib/ygglibc/src/headers/unistd/io.rs | 10 +-- .../lib/ygglibc/src/headers/unistd/process.rs | 4 +- userspace/lib/ygglibc/src/init.rs | 4 +- userspace/lib/ygglibc/src/io/mod.rs | 6 +- userspace/lib/ygglibc/src/lib.rs | 3 + userspace/lib/ygglibc/src/panic.rs | 8 ++- userspace/netutils/Cargo.toml | 4 +- userspace/netutils/src/dnsq.rs | 9 +-- userspace/netutils/src/ncap.rs | 3 +- userspace/sysutils/Cargo.toml | 7 +- userspace/sysutils/src/login.rs | 7 +- userspace/sysutils/src/view.rs | 3 +- userspace/term/Cargo.toml | 2 + userspace/term/src/main.rs | 2 +- 57 files changed, 289 insertions(+), 128 deletions(-) create mode 100644 userspace/lib/ygglibc/src/debug.rs diff --git a/kernel/libk/src/debug/mod.rs b/kernel/libk/src/debug/mod.rs index 462c92d6..8ee5ccc9 100644 --- a/kernel/libk/src/debug/mod.rs +++ b/kernel/libk/src/debug/mod.rs @@ -180,9 +180,10 @@ fn make_sysfs_sink_object(index: usize) -> Arc> { } /// Print a trace message coming from a process -pub fn program_trace(process: &Process, _thread: &Thread, message: &str) { - log::debug!( +pub fn program_trace(process: &Process, _thread: &Thread, level: log::Level, message: &str) { + log::log!( target: ":program", + level, "{} ({}) {message}\n", process.name, process.id, diff --git a/kernel/src/syscall/imp/mod.rs b/kernel/src/syscall/imp/mod.rs index bc47be72..ce6985cb 100644 --- a/kernel/src/syscall/imp/mod.rs +++ b/kernel/src/syscall/imp/mod.rs @@ -1,6 +1,7 @@ use core::mem::MaybeUninit; pub(crate) use abi::{ + debug::TraceLevel, error::Error, io::{ AccessMode, DirectoryEntry, FileAttr, FileMode, FileSync, MountOptions, OpenOptions, diff --git a/kernel/src/syscall/imp/sys_debug.rs b/kernel/src/syscall/imp/sys_debug.rs index a91dda34..00a48830 100644 --- a/kernel/src/syscall/imp/sys_debug.rs +++ b/kernel/src/syscall/imp/sys_debug.rs @@ -1,14 +1,24 @@ -use abi::{debug::DebugOperation, error::Error, process::ProcessId}; +use abi::{ + debug::{DebugOperation, TraceLevel}, + error::Error, + process::ProcessId, +}; use libk::{ debug, task::{process::Process, thread::Thread}, }; -pub(crate) fn debug_trace(message: &str) { +pub(crate) fn debug_trace(level: TraceLevel, message: &str) { let thread = Thread::current(); let process = thread.process(); + let level = match level { + TraceLevel::Debug => log::Level::Debug, + TraceLevel::Info => log::Level::Info, + TraceLevel::Warn => log::Level::Warn, + TraceLevel::Error => log::Level::Error, + }; - debug::program_trace(&process, &thread, message); + debug::program_trace(&process, &thread, level, message); } pub(crate) fn debug_control(pid: ProcessId, op: &mut DebugOperation) -> Result<(), Error> { diff --git a/lib/abi/def/yggdrasil.abi b/lib/abi/def/yggdrasil.abi index 889b7847..a1b475e8 100644 --- a/lib/abi/def/yggdrasil.abi +++ b/lib/abi/def/yggdrasil.abi @@ -61,6 +61,13 @@ bitfield MappingFlags(u32) { EXEC: 1, } +enum TraceLevel(u32) { + Debug = 0, + Info = 1, + Warn = 2, + Error = 3, +} + // TODO allow splitting types into separate modules syscall get_random(buffer: &mut [u8]); @@ -174,5 +181,5 @@ syscall fork() -> Result; syscall execve(options: &ExecveOptions<'_>) -> Result<()>; // Debugging -syscall debug_trace(message: &str); +syscall debug_trace(level: TraceLevel, message: &str); syscall debug_control(pid: ProcessId, op: &mut DebugOperation<'_>) -> Result<()>; diff --git a/lib/abi/src/debug.rs b/lib/abi/src/debug.rs index 9ea41c17..e76fa1bb 100644 --- a/lib/abi/src/debug.rs +++ b/lib/abi/src/debug.rs @@ -1,6 +1,8 @@ //! Debugging functionality use crate::{arch::SavedFrame, io::RawFd}; +pub use crate::generated::TraceLevel; + /// Describes a debugger operation #[derive(Debug)] pub enum DebugOperation<'a> { diff --git a/lib/runtime/src/debug.rs b/lib/runtime/src/debug.rs index 081addf8..62abb585 100644 --- a/lib/runtime/src/debug.rs +++ b/lib/runtime/src/debug.rs @@ -2,13 +2,13 @@ use core::fmt; -pub use abi::debug::{DebugFrame, DebugOperation}; +pub use abi::debug::{DebugFrame, DebugOperation, TraceLevel}; /// Prints a debug message using DebugTrace syscall #[macro_export] macro_rules! debug_trace { - ($($args:tt)+) => { - $crate::debug::_debug_trace(format_args!($($args)+)) + ($level:ident, $($args:tt)+) => { + $crate::debug::_debug_trace($crate::debug::TraceLevel::$level, format_args!($($args)+)) }; } @@ -29,16 +29,16 @@ impl fmt::Write for TracePrinter { /// Trace raw message into the kernel's log. If the message is not a valid unicode string, it will /// get discarded. -pub fn trace_raw(data: &[u8]) { +pub fn trace_raw(level: TraceLevel, data: &[u8]) { if let Ok(str) = core::str::from_utf8(data) { unsafe { - crate::sys::debug_trace(str); + crate::sys::debug_trace(level, str); } } } #[doc(hidden)] -pub fn _debug_trace(a: core::fmt::Arguments<'_>) { +pub fn _debug_trace(level: TraceLevel, a: core::fmt::Arguments<'_>) { use fmt::Write; let mut printer = TracePrinter { @@ -50,7 +50,7 @@ pub fn _debug_trace(a: core::fmt::Arguments<'_>) { if printer.len != 0 { unsafe { let s = core::str::from_utf8_unchecked(&printer.buf[..printer.len]); - crate::sys::debug_trace(s); + crate::sys::debug_trace(level, s); } } } diff --git a/lib/runtime/src/process/signal.rs b/lib/runtime/src/process/signal.rs index 1346b5a7..2df3afed 100644 --- a/lib/runtime/src/process/signal.rs +++ b/lib/runtime/src/process/signal.rs @@ -55,7 +55,7 @@ unsafe extern "C" fn common_signal_entry(data: &SignalEntryData) -> ! { // TODO add signal print hook function to dump signal info here fn terminate_by_signal(signal: Signal) -> ! { - crate::debug_trace!("runtime: terminated by signal: {signal:?}"); + crate::debug_trace!(Warn, "runtime: terminated by signal: {signal:?}"); unsafe { crate::sys::exit_process(ExitCode::BySignal(Ok(signal))) }; } diff --git a/lib/runtime/src/process/thread.rs b/lib/runtime/src/process/thread.rs index c63eaaa0..0028ec8f 100644 --- a/lib/runtime/src/process/thread.rs +++ b/lib/runtime/src/process/thread.rs @@ -165,7 +165,7 @@ impl Thread { // Setup TLS as soon as possible if let Err(err) = thread_local::init_tls(argument.tls_image, true) { - crate::debug_trace!("thread_entry failed: TLS init error: {err:?}"); + crate::debug_trace!(Warn, "thread_entry failed: TLS init error: {err:?}"); // TODO result is uninit unsafe { crate::sys::exit_thread() }; } @@ -261,7 +261,11 @@ impl OwnedStack { impl Drop for OwnedStack { fn drop(&mut self) { - crate::debug_trace!("Drop OwnedStack {:#x?}", self.base..self.base + self.size); + crate::debug_trace!( + Debug, + "Drop OwnedStack {:#x?}", + self.base..self.base + self.size + ); unsafe { crate::sys::unmap_memory(self.base, self.size) }.ok(); } } diff --git a/lib/runtime/src/process/thread_local/mod.rs b/lib/runtime/src/process/thread_local/mod.rs index 5232c9db..2851a0bc 100644 --- a/lib/runtime/src/process/thread_local/mod.rs +++ b/lib/runtime/src/process/thread_local/mod.rs @@ -178,7 +178,7 @@ impl Dtv { /// Will panic if key is longer than the DTV itself. pub fn set_specific(&mut self, key: usize, value: *mut c_void, grow: bool) { if self.try_set_specific(key, value, grow).is_err() { - crate::debug_trace!("Dtv::set_specific(): invalid key {key}, grow={grow}"); + crate::debug_trace!(Debug, "Dtv::set_specific(): invalid key {key}, grow={grow}"); panic!("Dtv::set_specific(): invalid key {key})") } } @@ -215,7 +215,7 @@ impl Dtv { match Self::get_key(&self.entries, key) { Some(value) => value, None => { - crate::debug_trace!("Dtv::get(): out-of-bounds DTV key: {key}"); + crate::debug_trace!(Debug, "Dtv::get(): out-of-bounds DTV key: {key}"); panic!("Dtv::get(): out-of-bounds DTV key: {key}"); } } @@ -227,11 +227,12 @@ impl Dtv { /// /// Will panic if key == 0. pub fn set(&mut self, key: usize, value: *mut c_void) { + crate::debug_trace!(Debug, "Dtv::set({key}, {value:p})"); if key > self.entries.len() { self.entries.resize(key, null_mut()); } if !Self::set_key(&mut self.entries, key, value) { - crate::debug_trace!("Dtv::set(): invalid key {key}"); + crate::debug_trace!(Debug, "Dtv::set(): invalid key {key}"); panic!("Dtv::set(): invalid key {key}"); } } @@ -259,7 +260,7 @@ pub fn init_tls_from_auxv<'a, I: Iterator>( /// a dummy (platform-specific) TLS copy will be created. pub fn init_tls(image: Option<&TlsImage>, force: bool) -> Result<(), Error> { let Some(image) = image else { - crate::debug_trace!("TODO: handle executables with no TLS"); + crate::debug_trace!(Debug, "TODO: handle executables with no TLS"); return Err(Error::NotImplemented); }; @@ -292,6 +293,11 @@ fn setup_dtv(image: &TlsImage, tls_info: &TlsInfo) -> Result<(), Error> { // NOTE if module 1 is specified again by the dynamic loader, it will be overriden with // what dynamic loader says if let Some(module0_offset) = tls_info.module0_offset { + crate::debug_trace!( + Info, + "DTV[1] = {:#x}", + tls_info.base + module0_offset + DTV_OFFSET + ); dtv.set( 1, core::ptr::without_provenance_mut(tls_info.base + module0_offset + DTV_OFFSET), @@ -303,6 +309,11 @@ fn setup_dtv(image: &TlsImage, tls_info: &TlsInfo) -> Result<(), Error> { } for &(module_id, module_offset) in image.module_offsets.iter() { assert!(module_offset < image.full_size); + crate::debug_trace!( + Info, + "DTV[{module_id}] = {:#x}", + tls_info.base + module_offset + DTV_OFFSET + ); dtv.set( module_id, core::ptr::with_exposed_provenance_mut(tls_info.base + module_offset + DTV_OFFSET), diff --git a/lib/runtime/src/process/thread_local/variant1.rs b/lib/runtime/src/process/thread_local/variant1.rs index e380d7a0..7ad5a381 100644 --- a/lib/runtime/src/process/thread_local/variant1.rs +++ b/lib/runtime/src/process/thread_local/variant1.rs @@ -21,11 +21,18 @@ pub fn clone_tls(image: &TlsImage) -> Result { const TCB_SIZE: usize = size_of::() * 2; if !image.align.is_power_of_two() { - crate::debug_trace!("TLS layout not aligned to a power of two: {}", image.align); + crate::debug_trace!( + Debug, + "TLS layout not aligned to a power of two: {}", + image.align + ); unsafe { crate::sys::exit_process(ExitCode::Exited(1)) }; } if image.align > 0x1000 { - crate::debug_trace!("TODO: TLS alignment larger than a page size is not supported"); + crate::debug_trace!( + Warn, + "TODO: TLS alignment larger than a page size is not supported" + ); unsafe { crate::sys::exit_process(ExitCode::Exited(1)) }; } @@ -73,7 +80,7 @@ pub fn clone_tls(image: &TlsImage) -> Result { // Zero the TCB after the self-pointer tcb[size_of::()..].fill(0); - crate::debug_trace!("TLS: base={:#x}, tp={:#x}", base, tp); + crate::debug_trace!(Debug, "TLS: base={:#x}, tp={:#x}", base, tp); Ok(TlsInfo { base, diff --git a/lib/runtime/src/process/thread_local/variant2.rs b/lib/runtime/src/process/thread_local/variant2.rs index 4f5463de..e2c37afe 100644 --- a/lib/runtime/src/process/thread_local/variant2.rs +++ b/lib/runtime/src/process/thread_local/variant2.rs @@ -71,7 +71,7 @@ pub fn clone_tls(image: &TlsImage) -> Result { // Zero the TCB after the self-pointer tcb[size_of::()..].fill(0); - crate::debug_trace!("TLS: base={:#x}, tp={:#x}", base, tp); + crate::debug_trace!(Debug, "TLS: base={:#x}, tp={:#x}", base, tp); Ok(TlsInfo { base, diff --git a/lib/runtime/src/sys/mod.rs b/lib/runtime/src/sys/mod.rs index e1756710..201357f5 100644 --- a/lib/runtime/src/sys/mod.rs +++ b/lib/runtime/src/sys/mod.rs @@ -17,6 +17,7 @@ mod riscv64; mod generated { // Import all the necessary types from generated ABI use abi::{ + debug::TraceLevel, error::Error, io::{ AccessMode, DirectoryEntry, FileAttr, FileMode, FileSync, MountOptions, OpenOptions, diff --git a/userspace/Cargo.lock b/userspace/Cargo.lock index 988b8a4b..944bc7eb 100644 --- a/userspace/Cargo.lock +++ b/userspace/Cargo.lock @@ -740,6 +740,8 @@ dependencies = [ "bytemuck", "cfg-if", "elf", + "log", + "logsink", "rustc-demangle", "thiserror", "yggdrasil-rt", @@ -1229,6 +1231,8 @@ name = "init" version = "0.1.0" dependencies = [ "cross", + "log", + "logsink", "serde", "serde_json", "yggdrasil-rt", @@ -1407,6 +1411,7 @@ version = "0.1.0" dependencies = [ "env_logger", "log", + "yggdrasil-rt", ] [[package]] @@ -1498,6 +1503,7 @@ dependencies = [ "clap-num", "http", "log", + "logsink", "rand 0.9.0-alpha.1", "runtime", "serde", @@ -2651,6 +2657,8 @@ dependencies = [ "humansize", "init", "libterm", + "log", + "logsink", "pci-ids", "rand 0.9.0-alpha.1", "serde", @@ -2682,6 +2690,8 @@ dependencies = [ "clap", "libcolors", "libpsf", + "log", + "logsink", "thiserror", ] diff --git a/userspace/colors/src/bin/colors-bar.rs b/userspace/colors/src/bin/colors-bar.rs index c995df1a..98a7549b 100644 --- a/userspace/colors/src/bin/colors-bar.rs +++ b/userspace/colors/src/bin/colors-bar.rs @@ -83,7 +83,7 @@ fn run() -> Result { } fn main() -> ExitCode { - logsink::setup_logging(); + logsink::setup_logging(true); log::info!("colors-bar starting"); match run() { Ok(code) => code, diff --git a/userspace/colors/src/main.rs b/userspace/colors/src/main.rs index a4a1c130..fe805354 100644 --- a/userspace/colors/src/main.rs +++ b/userspace/colors/src/main.rs @@ -365,7 +365,7 @@ impl WindowServer for Server<'_> { } fn main() -> ExitCode { - logsink::setup_logging(); + logsink::setup_logging(false); log::info!("Colors starting"); let server = Server::new().unwrap(); diff --git a/userspace/dyn-loader/Cargo.toml b/userspace/dyn-loader/Cargo.toml index 7bce0f0f..4a0264f1 100644 --- a/userspace/dyn-loader/Cargo.toml +++ b/userspace/dyn-loader/Cargo.toml @@ -5,10 +5,13 @@ edition = "2021" [dependencies] yggdrasil-rt.workspace = true +logsink.workspace = true + thiserror.workspace = true +bytemuck.workspace = true +log.workspace = true elf = "0.7.4" -bytemuck = "1.19.0" cfg-if = "1.0.0" rustc-demangle = { version = "0.1.24" } diff --git a/userspace/dyn-loader/src/error.rs b/userspace/dyn-loader/src/error.rs index d835f286..65a72bb9 100644 --- a/userspace/dyn-loader/src/error.rs +++ b/userspace/dyn-loader/src/error.rs @@ -2,7 +2,7 @@ use std::io; #[derive(Debug, thiserror::Error)] pub enum Error { - #[error("I/O error")] + #[error("{0}")] Io(#[from] io::Error), #[error("ELF parse error")] ElfParse(#[from] elf::ParseError), diff --git a/userspace/dyn-loader/src/main.rs b/userspace/dyn-loader/src/main.rs index 7397c514..b279d581 100644 --- a/userspace/dyn-loader/src/main.rs +++ b/userspace/dyn-loader/src/main.rs @@ -73,7 +73,7 @@ fn run(binary: &str, args: &[String]) -> Result { for module in layout.segments.iter() { auxv.push(AuxValue { tag: auxv::TLS_MODULE_ID, - val: module.object_id as u64 + 1, + val: module.module_id as u64, }); auxv.push(AuxValue { tag: auxv::TLS_MODULE_OFFSET, @@ -98,7 +98,7 @@ fn run(binary: &str, args: &[String]) -> Result { // Setup arguments and enter the main object let entry = objects.root.entry().ok_or(Error::NoEntrypoint)?; - debug_trace!("entry = {:p}", entry); + log::info!("entry = {:p}", entry); let argument = env::build_argument(args, &auxv)?; unsafe { enter(entry, argument) }; @@ -134,6 +134,7 @@ unsafe fn enter(entry: extern "C" fn(usize), argument: usize) -> ! { } fn main() -> ExitCode { + logsink::setup_logging(false); let args: Vec = std::env::args().skip(1).collect(); if args.is_empty() { diff --git a/userspace/dyn-loader/src/object.rs b/userspace/dyn-loader/src/object.rs index 2eb2313f..66a80b31 100644 --- a/userspace/dyn-loader/src/object.rs +++ b/userspace/dyn-loader/src/object.rs @@ -187,8 +187,8 @@ impl Object { return Ok(()); } - debug_trace!("Load {:?}", self.path); - debug_trace!("Image range: {:#x?}", self.vma_start..self.vma_end); + log::info!("Load {:?}", self.path); + log::info!("Image range: {:#x?}", self.vma_start..self.vma_end); // TODO segment granularity mappings let mapping_size = self.vma_end - self.vma_start; @@ -200,7 +200,7 @@ impl Object { ElfType::Static => todo!(), }; - debug_trace!( + log::info!( "Actual range: {:#x?} ({:+#x})", mapping.range(), mapping.base() as i64 - self.vma_start as i64 @@ -228,14 +228,14 @@ impl Object { } if let (Some(ptr), Some(size)) = (dt_preinit_array, dt_preinit_array_sz) { - debug_trace!("{:?}: DT_PREINIT_ARRAY: {:#x?}", self.path, ptr..ptr + size); + log::debug!("{:?}: DT_PREINIT_ARRAY: {:#x?}", self.path, ptr..ptr + size); let ptr = ptr as i64 + mapping.base() as i64 - self.vma_start as i64; let ptr = ptr as usize; self.pre_init_array = Some(ptr..ptr + size as usize); } if let (Some(ptr), Some(size)) = (dt_init_array, dt_init_array_sz) { // This address is subject to relocation - debug_trace!("{:?}: DT_INIT_ARRAY: {:#x?}", self.path, ptr..ptr + size); + log::debug!("{:?}: DT_INIT_ARRAY: {:#x?}", self.path, ptr..ptr + size); let ptr = ptr as i64 + mapping.base() as i64 - self.vma_start as i64; let ptr = ptr as usize; self.init_array = Some(ptr..ptr + size as usize); @@ -324,7 +324,7 @@ impl Object { } let func = mem::transmute::<_, Constructor>(func); - debug_trace!("ld: call constructor {func:p}"); + log::debug!("ld: call constructor {func:p}"); func(); } diff --git a/userspace/dyn-loader/src/relocation/aarch64.rs b/userspace/dyn-loader/src/relocation/aarch64.rs index c68defeb..d2e27541 100644 --- a/userspace/dyn-loader/src/relocation/aarch64.rs +++ b/userspace/dyn-loader/src/relocation/aarch64.rs @@ -72,14 +72,14 @@ impl Relocation for Rela { R_AARCH64_TLS_TPREL => { let layout = state.tls_layout.as_ref().unwrap(); let offset = layout.offset(tls.module_id, tls.offset).unwrap(); - debug_trace!("{}@tprel -> {}", name, offset); + log::debug!("{}@tprel -> {}", name, offset); Ok(Some(RelaValue::QWord(offset as _))) } _ => todo!("Unsupported relocation against TLS symbol: {}", self.r_type), }, ResolvedSymbol::Null(object_id) => match self.r_type { // See make_tlsdesc_relocation() - R_AARCH64_TLSDESC => Ok(Some(make_tlsdesc_relocation(false, state, object_id, 0))), + R_AARCH64_TLSDESC => Ok(Some(make_tlsdesc_relocation(false, state, object_id + 1, 0))), // B + A R_AARCH64_RELATIVE => Ok(Some(RelaValue::QWord(load_base as i64 + self.r_addend))), _ => todo!( diff --git a/userspace/dyn-loader/src/relocation/i686.rs b/userspace/dyn-loader/src/relocation/i686.rs index 23c18529..6eaa40a7 100644 --- a/userspace/dyn-loader/src/relocation/i686.rs +++ b/userspace/dyn-loader/src/relocation/i686.rs @@ -41,7 +41,7 @@ impl Relocation for Rel { // Offset from TLS start let offset = tls_layout.offset(tls.module_id, tls.offset).unwrap(); let offset_from_tp = -((tls_layout.tp_offset - offset) as i32); - debug_trace!("{}@tpoff -> {}", name, offset_from_tp); + log::debug!("{}@tpoff -> {}", name, offset_from_tp); Ok(Some(RelValue::DWordNoAddend(offset_from_tp))) } diff --git a/userspace/dyn-loader/src/relocation/x86_64.rs b/userspace/dyn-loader/src/relocation/x86_64.rs index 49fa17bb..29b1bf67 100644 --- a/userspace/dyn-loader/src/relocation/x86_64.rs +++ b/userspace/dyn-loader/src/relocation/x86_64.rs @@ -42,10 +42,11 @@ impl Relocation for Rela { R_X86_64_TPOFF64 => { // Need to extract fixed global offset let tls_layout = state.tls_layout.as_ref().unwrap(); + log::info!("TPOFF64: module_id={}", tls.module_id); // Offset from TLS start let offset = tls_layout.offset(tls.module_id, tls.offset).unwrap(); let offset_from_tp = -((tls_layout.tp_offset - offset) as i64); - debug_trace!("{}@tpoff -> {}", name, offset_from_tp); + log::debug!("{}@tpoff -> {}", name, offset_from_tp); Ok(Some(RelaValue::QWord(offset_from_tp))) } @@ -54,7 +55,7 @@ impl Relocation for Rela { }, &ResolvedSymbol::Null(object_id) => match self.r_type { // TLS module ID - R_X86_64_DTPMOD64 => Ok(Some(RelaValue::QWord(object_id as _))), + R_X86_64_DTPMOD64 => Ok(Some(RelaValue::QWord((object_id + 1) as _))), // B + A R_X86_64_RELATIVE => Ok(Some(RelaValue::QWord(load_base as i64 + self.r_addend))), diff --git a/userspace/dyn-loader/src/state.rs b/userspace/dyn-loader/src/state.rs index 7fefa917..7a7c2c18 100644 --- a/userspace/dyn-loader/src/state.rs +++ b/userspace/dyn-loader/src/state.rs @@ -107,19 +107,19 @@ impl State { *export = ExportedTlsSymbol { source, offset, - module_id: object_id, + module_id: object_id + 1, weak, }; } Some(_) => (), None => { - debug_trace!("{:?}: TLS {:?} -> {}:{:#x}", source, sym.name, object_id, offset); + log::debug!("{:?}: TLS {:?} -> {}:{:#x}", source, sym.name, object_id + 1, offset); self.tls_symbol_table.insert( sym.name.clone(), ExportedTlsSymbol { source, offset, - module_id: object_id, + module_id: object_id + 1, weak, }, ); diff --git a/userspace/dyn-loader/src/thread_local/mod.rs b/userspace/dyn-loader/src/thread_local/mod.rs index 119d43f4..4a8a306e 100644 --- a/userspace/dyn-loader/src/thread_local/mod.rs +++ b/userspace/dyn-loader/src/thread_local/mod.rs @@ -35,7 +35,7 @@ pub struct TlsLayout { pub struct TlsSegment { pub offset: usize, pub size: usize, - pub object_id: u32, + pub module_id: u32, } pub struct TlsImage { @@ -47,8 +47,8 @@ pub struct TlsImage { } impl TlsLayout { - pub fn offset(&self, object_id: u32, offset: usize) -> Option { - let segment = self.segments.iter().find(|seg| seg.object_id == object_id)?; + pub fn offset(&self, module_id: u32, offset: usize) -> Option { + let segment = self.segments.iter().find(|seg| seg.module_id == module_id)?; Some(segment.offset + offset) } } @@ -67,16 +67,17 @@ pub fn build_tls_image( let tp_offset = layout.tp_offset; for segment in layout.segments.iter() { - debug_trace!( + log::info!( "Load TLS segment: tlsoffset_i={:#x?} (-{:#x}), module_id={}", segment.offset..segment.offset + segment.size, layout.prefix_len, - segment.object_id + segment.module_id ); - let object = match segment.object_id { - 0 => &mut *root, - _ => libraries.get_mut(&segment.object_id).unwrap(), + let object = match segment.module_id { + 0 => unreachable!(), + 1 => &mut *root, + _ => libraries.get_mut(&(segment.module_id - 1)).unwrap(), }; object.tls_offset = Some(segment.offset); let load_offset = segment.offset - layout.prefix_len; diff --git a/userspace/dyn-loader/src/thread_local/variant1.rs b/userspace/dyn-loader/src/thread_local/variant1.rs index 9dc8f8c5..faf8cc98 100644 --- a/userspace/dyn-loader/src/thread_local/variant1.rs +++ b/userspace/dyn-loader/src/thread_local/variant1.rs @@ -30,7 +30,7 @@ impl TlsLayoutBuilder for TlsLayoutImpl { segments.push(TlsSegment { offset: total_size, size: tls.p_memsz as _, - object_id: 0, + module_id: 1, }); total_size += tls.p_memsz as usize; @@ -52,7 +52,7 @@ impl TlsLayoutBuilder for TlsLayoutImpl { segments.push(TlsSegment { offset: total_size, size: tls.p_memsz as _, - object_id, + module_id: object_id + 1, }); total_size += tls.p_memsz as usize; diff --git a/userspace/dyn-loader/src/thread_local/variant2.rs b/userspace/dyn-loader/src/thread_local/variant2.rs index ef15caa1..bf68a986 100644 --- a/userspace/dyn-loader/src/thread_local/variant2.rs +++ b/userspace/dyn-loader/src/thread_local/variant2.rs @@ -65,7 +65,7 @@ impl TlsLayoutBuilder for TlsLayoutImpl { .map(|(object_id, offset, size)| TlsSegment { offset, size, - object_id, + module_id: object_id + 1, }) .collect(); diff --git a/userspace/init/Cargo.toml b/userspace/init/Cargo.toml index 1f49cec2..84dcd0d4 100644 --- a/userspace/init/Cargo.toml +++ b/userspace/init/Cargo.toml @@ -16,6 +16,9 @@ path = "src/rc.rs" [dependencies] cross.workspace = true +yggdrasil-rt.workspace = true +logsink.workspace = true + +log.workspace = true serde.workspace = true serde_json.workspace = true -yggdrasil-rt.workspace = true diff --git a/userspace/init/src/main.rs b/userspace/init/src/main.rs index 826b17f3..3ff9b6a3 100644 --- a/userspace/init/src/main.rs +++ b/userspace/init/src/main.rs @@ -11,7 +11,6 @@ use std::{ use cross::net::LocalPacketSocket; use init::InitMsg; -use yggdrasil_rt::debug_trace; const INITTAB_PATH: &str = "/etc/inittab"; @@ -162,19 +161,20 @@ fn main_loop(socket: LocalPacketSocket) -> io::Result { let len = socket.receive(&mut buf)?; if let Ok(msg) = serde_json::from_slice::(&buf[..len]) { if let Err(err) = handle_message(msg) { - debug_trace!("init::handle_message: {err}"); + log::warn!("init::handle_message: {err}"); } } } } fn main() -> ExitCode { - debug_trace!("Userspace init starting"); + logsink::setup_logging(false); + log::info!("Userspace init starting"); let rules = match load_rules(INITTAB_PATH) { Ok(s) => s, Err(e) => { - debug_trace!("init: failed to load rules: {:?}", e); + log::error!("init: failed to load rules: {:?}", e); return ExitCode::FAILURE; } }; @@ -182,16 +182,16 @@ fn main() -> ExitCode { //let channel = MessageChannel::open("service-control", true).unwrap(); let control_socket = LocalPacketSocket::bind("/init.sock").unwrap(); - debug_trace!("Rules loaded"); + log::info!("Rules loaded"); for rule in rules { - debug_trace!("rc: {:?}", rule); + log::info!("rc: {:?}", rule); if let Err(err) = rule.run() { - debug_trace!("rc: failed to execute rule {:?}: {:?}", rule, err); + log::error!("rc: failed to execute rule {:?}: {:?}", rule, err); } } let Err(error) = main_loop(control_socket); - debug_trace!("init: main_loop returned {error}"); + log::error!("init: main_loop returned {error}"); ExitCode::FAILURE } diff --git a/userspace/init/src/rc.rs b/userspace/init/src/rc.rs index 41b224a2..e3a35626 100644 --- a/userspace/init/src/rc.rs +++ b/userspace/init/src/rc.rs @@ -39,7 +39,7 @@ impl FromStr for Mode { fn exec_script>(path: P, arg: &str) -> Result<(), Error> { let path = path.as_ref(); - yggdrasil_rt::debug_trace!("rc: {:?} {}", path, arg); + log::info!("rc: {:?} {}", path, arg); // TODO run those in parallel, if allowed let mut process = Command::new(path).arg(arg).spawn()?; diff --git a/userspace/lib/logsink/Cargo.toml b/userspace/lib/logsink/Cargo.toml index b8618b53..776bba74 100644 --- a/userspace/lib/logsink/Cargo.toml +++ b/userspace/lib/logsink/Cargo.toml @@ -6,10 +6,14 @@ edition = "2021" [dependencies] log.workspace = true +[target.'cfg(target_os = "yggdrasil")'.dependencies] +yggdrasil-rt.workspace = true + [target.'cfg(unix)'.dependencies] env_logger.workspace = true [dev-dependencies] +yggdrasil-rt.workspace = true env_logger.workspace = true [lints] diff --git a/userspace/lib/logsink/src/lib.rs b/userspace/lib/logsink/src/lib.rs index 2f194b6d..1c33d0c0 100644 --- a/userspace/lib/logsink/src/lib.rs +++ b/userspace/lib/logsink/src/lib.rs @@ -6,6 +6,6 @@ pub mod yggdrasil; pub use yggdrasil::*; #[cfg(any(rust_analyzer, unix))] -pub fn setup_logging() { +pub fn setup_logging(_stdout: bool) { env_logger::init(); } diff --git a/userspace/lib/logsink/src/yggdrasil.rs b/userspace/lib/logsink/src/yggdrasil.rs index 8c0ed46c..5dd5961f 100644 --- a/userspace/lib/logsink/src/yggdrasil.rs +++ b/userspace/lib/logsink/src/yggdrasil.rs @@ -1,6 +1,7 @@ use std::io::stdout; use log::LevelFilter; +use yggdrasil_rt::debug::TraceLevel; struct LogSink; @@ -10,11 +11,21 @@ impl log::Log for LogSink { } fn log(&self, record: &log::Record) { - debug_trace!("[{}] {}", record.level(), record.args()); + // debug_trace!("[{}] {}", record.level(), record.args()); + let trace_level = match record.level() { + log::Level::Trace | log::Level::Debug => TraceLevel::Debug, + log::Level::Info => TraceLevel::Info, + log::Level::Warn => TraceLevel::Warn, + log::Level::Error => TraceLevel::Error, + }; + let message = format!("{}", record.args()); + unsafe { yggdrasil_rt::sys::debug_trace(trace_level, &message) }; - use std::io::Write; - let mut stdout = stdout(); - writeln!(stdout, "[{}] {}", record.level(), record.args()).ok(); + if unsafe { TO_STDOUT } { + use std::io::Write; + let mut stdout = stdout(); + writeln!(stdout, "[{}] {}", record.level(), record.args()).ok(); + } } fn flush(&self) { @@ -23,8 +34,10 @@ impl log::Log for LogSink { } static SINK: LogSink = LogSink; +static mut TO_STDOUT: bool = true; -pub fn setup_logging() { +pub fn setup_logging(stdout: bool) { + unsafe { TO_STDOUT = stdout }; log::set_max_level(LevelFilter::Debug); log::set_logger(&SINK).unwrap(); } diff --git a/userspace/lib/ygglibc/Cargo.lock b/userspace/lib/ygglibc/Cargo.lock index 2f35fd93..9363667c 100644 --- a/userspace/lib/ygglibc/Cargo.lock +++ b/userspace/lib/ygglibc/Cargo.lock @@ -591,6 +591,7 @@ dependencies = [ "cbindgen", "chrono", "libyalloc", + "log", "yggdrasil-abi", "yggdrasil-rt", ] diff --git a/userspace/lib/ygglibc/Cargo.toml b/userspace/lib/ygglibc/Cargo.toml index dfeab444..87c7c991 100644 --- a/userspace/lib/ygglibc/Cargo.toml +++ b/userspace/lib/ygglibc/Cargo.toml @@ -11,6 +11,7 @@ yggdrasil-rt = { path = "../../../lib/runtime", features = ["__tls_get_addr"] } yggdrasil-abi = { path = "../../../lib/abi", features = ["alloc", "bytemuck"] } libyalloc = { path = "../../../lib/libyalloc" } +log = "0.4.22" bitflags = "2.6.0" chrono = { version = "0.4.31", default-features = false } diff --git a/userspace/lib/ygglibc/src/debug.rs b/userspace/lib/ygglibc/src/debug.rs new file mode 100644 index 00000000..537014bb --- /dev/null +++ b/userspace/lib/ygglibc/src/debug.rs @@ -0,0 +1,66 @@ +use core::fmt; + +use yggdrasil_rt::debug::TraceLevel; + +struct LogSink; +struct MessageBuffer { + buffer: [u8; 256], + len: usize, +} + +impl MessageBuffer { + pub const fn new() -> Self { + Self { + buffer: [0; 256], + len: 0, + } + } +} + +impl fmt::Write for MessageBuffer { + fn write_str(&mut self, s: &str) -> fmt::Result { + let len = (self.buffer.len() - self.len).min(s.len()); + self.buffer[self.len..self.len + len].copy_from_slice(&s.as_bytes()[..len]); + self.len += len; + Ok(()) + } +} + +impl log::Log for LogSink { + fn flush(&self) {} + + fn log(&self, record: &log::Record) { + use fmt::Write; + let level = match record.level() { + log::Level::Trace | log::Level::Debug => TraceLevel::Debug, + log::Level::Info => TraceLevel::Info, + log::Level::Warn => TraceLevel::Warn, + log::Level::Error => TraceLevel::Error, + }; + let mut buffer = MessageBuffer::new(); + write!(buffer, "{}", record.args()).ok(); + let text = match core::str::from_utf8(&buffer.buffer[..buffer.len]) { + Ok(text) => text, + Err(error) => { + let valid = unsafe { + core::str::from_utf8_unchecked(&buffer.buffer[..error.valid_up_to()]) + }; + valid + } + }; + unsafe { + yggdrasil_rt::sys::debug_trace(level, text); + } + } + + fn enabled(&self, _metadata: &log::Metadata) -> bool { + true + } +} + +static LOG: LogSink = LogSink; + +pub(crate) fn init_log_sink() { + log::set_max_level(log::LevelFilter::Debug); + log::set_logger(&LOG).ok(); +} diff --git a/userspace/lib/ygglibc/src/headers/pthread/attr.rs b/userspace/lib/ygglibc/src/headers/pthread/attr.rs index c6fa9641..a5a459cd 100644 --- a/userspace/lib/ygglibc/src/headers/pthread/attr.rs +++ b/userspace/lib/ygglibc/src/headers/pthread/attr.rs @@ -144,7 +144,7 @@ unsafe extern "C" fn pthread_attr_setdetachstate( #[no_mangle] unsafe extern "C" fn pthread_attr_setguardsize(_attr: *mut pthread_attr_t, _size: usize) -> c_int { - yggdrasil_rt::debug_trace!("TODO: pthread_attr_setguardsize()"); + log::error!("TODO: pthread_attr_setguardsize()"); 0 } @@ -153,7 +153,7 @@ unsafe extern "C" fn pthread_attr_setinheritsched( _attr: *mut pthread_attr_t, _inherit: c_int, ) -> c_int { - yggdrasil_rt::debug_trace!("TODO: pthread_attr_setinheritsched()"); + log::error!("TODO: pthread_attr_setinheritsched()"); 0 } @@ -162,7 +162,7 @@ unsafe extern "C" fn pthread_attr_setschedparam( _attr: *mut pthread_attr_t, _param: *const __ygg_sched_param_t, ) -> c_int { - yggdrasil_rt::debug_trace!("TODO: pthread_attr_setschedparam()"); + log::error!("TODO: pthread_attr_setschedparam()"); 0 } @@ -171,13 +171,13 @@ unsafe extern "C" fn pthread_attr_setschedpolicy( _attr: *mut pthread_attr_t, _policy: c_int, ) -> c_int { - yggdrasil_rt::debug_trace!("TODO: pthread_attr_setschedpolicy()"); + log::error!("TODO: pthread_attr_setschedpolicy()"); 0 } #[no_mangle] unsafe extern "C" fn pthread_attr_setscope(_attr: *mut pthread_attr_t, _scope: c_int) -> c_int { - yggdrasil_rt::debug_trace!("TODO: pthread_attr_setscope()"); + log::error!("TODO: pthread_attr_setscope()"); 0 } diff --git a/userspace/lib/ygglibc/src/headers/pthread/barrier.rs b/userspace/lib/ygglibc/src/headers/pthread/barrier.rs index dc360af4..2fd0018a 100644 --- a/userspace/lib/ygglibc/src/headers/pthread/barrier.rs +++ b/userspace/lib/ygglibc/src/headers/pthread/barrier.rs @@ -57,7 +57,7 @@ impl pthread_barrier_t { #[no_mangle] unsafe extern "C" fn pthread_barrier_destroy(_barrier: *mut pthread_barrier_t) -> c_int { - yggdrasil_rt::debug_trace!("TODO: pthread_barrier_destroy()"); + log::error!("TODO: pthread_barrier_destroy()"); 0 } @@ -83,7 +83,7 @@ unsafe extern "C" fn pthread_barrier_wait(barrier: *mut pthread_barrier_t) -> c_ #[no_mangle] unsafe extern "C" fn pthread_barrierattr_destroy(_attr: *mut pthread_barrierattr_t) -> c_int { - yggdrasil_rt::debug_trace!("TODO: pthread_barrierattr_destroy()"); + log::error!("TODO: pthread_barrierattr_destroy()"); 0 } @@ -100,7 +100,7 @@ unsafe extern "C" fn pthread_barrierattr_getpshared( #[no_mangle] unsafe extern "C" fn pthread_barrierattr_init(_attr: *mut pthread_barrierattr_t) -> c_int { - yggdrasil_rt::debug_trace!("TODO: pthread_barrierattr_init()"); + log::error!("TODO: pthread_barrierattr_init()"); 0 } @@ -112,7 +112,7 @@ unsafe extern "C" fn pthread_barrierattr_setpshared( if shared == PTHREAD_PROCESS_PRIVATE { CIntZeroResult::SUCCESS } else { - yggdrasil_rt::debug_trace!("TODO: pthread_barrierattr_setpshared()"); + log::error!("TODO: pthread_barrierattr_setpshared()"); error::errno = Errno::EINVAL; CIntZeroResult::ERROR } diff --git a/userspace/lib/ygglibc/src/headers/pthread/cond.rs b/userspace/lib/ygglibc/src/headers/pthread/cond.rs index 1c1c7d3a..b1503457 100644 --- a/userspace/lib/ygglibc/src/headers/pthread/cond.rs +++ b/userspace/lib/ygglibc/src/headers/pthread/cond.rs @@ -150,7 +150,7 @@ unsafe extern "C" fn pthread_condattr_setclock( if clockid == CLOCK_MONOTONIC { CIntZeroResult::SUCCESS } else { - yggdrasil_rt::debug_trace!("TODO: pthread_condattr_setclock()"); + log::error!("TODO: pthread_condattr_setclock()"); error::errno = Errno::EINVAL; CIntZeroResult::ERROR } @@ -164,7 +164,7 @@ unsafe extern "C" fn pthread_condattr_setpshared( if shared == PTHREAD_PROCESS_PRIVATE { CIntZeroResult::SUCCESS } else { - yggdrasil_rt::debug_trace!("TODO: pthread_condattr_setpshared()"); + log::error!("TODO: pthread_condattr_setpshared()"); error::errno = Errno::EINVAL; CIntZeroResult::ERROR } diff --git a/userspace/lib/ygglibc/src/headers/pthread/mutex.rs b/userspace/lib/ygglibc/src/headers/pthread/mutex.rs index dd2ae7d0..adfd0e21 100644 --- a/userspace/lib/ygglibc/src/headers/pthread/mutex.rs +++ b/userspace/lib/ygglibc/src/headers/pthread/mutex.rs @@ -113,13 +113,13 @@ impl Default for pthread_mutexattr_t { #[no_mangle] unsafe extern "C" fn pthread_mutex_consistent(_mutex: *mut pthread_mutex_t) -> c_int { - yggdrasil_rt::debug_trace!("TODO: pthread_mutex_consistent()"); + log::error!("TODO: pthread_mutex_consistent()"); 0 } #[no_mangle] unsafe extern "C" fn pthread_mutex_destroy(_mutex: *mut pthread_mutex_t) -> c_int { - yggdrasil_rt::debug_trace!("TODO: pthread_mutex_destroy()"); + log::error!("TODO: pthread_mutex_destroy()"); 0 } @@ -128,7 +128,7 @@ unsafe extern "C" fn pthread_mutex_getprioceiling( _mutex: *const pthread_mutex_t, maxprio: *mut c_int, ) -> c_int { - yggdrasil_rt::debug_trace!("TODO: pthread_mutex_getprioceiling()"); + log::error!("TODO: pthread_mutex_getprioceiling()"); if let Some(maxprio) = NonNull::new(maxprio) { maxprio.write(10); } @@ -168,7 +168,7 @@ unsafe extern "C" fn pthread_mutex_setprioceiling( new: c_int, old: *mut c_int, ) -> c_int { - yggdrasil_rt::debug_trace!("TODO: pthread_mutex_setprioceiling()"); + log::error!("TODO: pthread_mutex_setprioceiling()"); if let Some(old) = NonNull::new(old) { old.write(new); } @@ -207,7 +207,7 @@ unsafe extern "C" fn pthread_mutexattr_getprioceiling( _attr: *const pthread_mutexattr_t, maxprio: *mut c_int, ) -> c_int { - yggdrasil_rt::debug_trace!("TODO: pthread_mutexattr_getprioceiling()"); + log::error!("TODO: pthread_mutexattr_getprioceiling()"); if let Some(maxprio) = NonNull::new(maxprio) { maxprio.write(10); } @@ -219,7 +219,7 @@ unsafe extern "C" fn pthread_mutexattr_getprotocol( _attr: *const pthread_mutexattr_t, protocol: *mut c_int, ) -> c_int { - yggdrasil_rt::debug_trace!("TODO: pthread_mutexattr_getprotocol()"); + log::error!("TODO: pthread_mutexattr_getprotocol()"); if let Some(protocol) = NonNull::new(protocol) { protocol.write(PTHREAD_PRIO_NONE); } @@ -242,7 +242,7 @@ unsafe extern "C" fn pthread_mutexattr_getrobust( _attr: *const pthread_mutexattr_t, robust: *mut c_int, ) -> c_int { - yggdrasil_rt::debug_trace!("TODO: pthread_mutexattr_getrobust()"); + log::error!("TODO: pthread_mutexattr_getrobust()"); if let Some(robust) = NonNull::new(robust) { robust.write(PTHREAD_MUTEX_STALLED); } @@ -273,7 +273,7 @@ unsafe extern "C" fn pthread_mutexattr_setprioceiling( _attr: *mut pthread_mutexattr_t, _maxprio: c_int, ) -> c_int { - yggdrasil_rt::debug_trace!("TODO: pthread_mutexattr_setprioceiling()"); + log::error!("TODO: pthread_mutexattr_setprioceiling()"); 0 } @@ -285,7 +285,7 @@ unsafe extern "C" fn pthread_mutexattr_setprotocol( if protocol == PTHREAD_PRIO_NONE { CIntZeroResult::SUCCESS } else { - yggdrasil_rt::debug_trace!("TODO: pthread_mutexattr_setprotocol()"); + log::error!("TODO: pthread_mutexattr_setprotocol()"); error::errno = Errno::EINVAL; CIntZeroResult::ERROR } @@ -299,7 +299,7 @@ unsafe extern "C" fn pthread_mutexattr_setpshared( if shared == PTHREAD_PROCESS_PRIVATE { CIntZeroResult::SUCCESS } else { - yggdrasil_rt::debug_trace!("TODO: pthread_mutexattr_setpshared()"); + log::error!("TODO: pthread_mutexattr_setpshared()"); error::errno = Errno::EINVAL; CIntZeroResult::ERROR } @@ -313,7 +313,7 @@ unsafe extern "C" fn pthread_mutexattr_setrobust( if robust == PTHREAD_MUTEX_STALLED { CIntZeroResult::SUCCESS } else { - yggdrasil_rt::debug_trace!("TODO: pthread_mutexattr_setrobust()"); + log::error!("TODO: pthread_mutexattr_setrobust()"); error::errno = Errno::EINVAL; CIntZeroResult::ERROR } diff --git a/userspace/lib/ygglibc/src/headers/pthread/tls.rs b/userspace/lib/ygglibc/src/headers/pthread/tls.rs index 64d159db..6b0a6061 100644 --- a/userspace/lib/ygglibc/src/headers/pthread/tls.rs +++ b/userspace/lib/ygglibc/src/headers/pthread/tls.rs @@ -21,7 +21,7 @@ unsafe extern "C" fn pthread_key_create( #[no_mangle] unsafe extern "C" fn pthread_key_delete(_key: pthread_key_t) -> CIntZeroResult { - yggdrasil_rt::debug_trace!("TODO: pthread_key_delete()"); + log::error!("TODO: pthread_key_delete()"); CIntZeroResult::SUCCESS } diff --git a/userspace/lib/ygglibc/src/headers/signal/mod.rs b/userspace/lib/ygglibc/src/headers/signal/mod.rs index 7bdd96f1..241a451a 100644 --- a/userspace/lib/ygglibc/src/headers/signal/mod.rs +++ b/userspace/lib/ygglibc/src/headers/signal/mod.rs @@ -209,7 +209,7 @@ unsafe extern "C" fn sigaction( _new: *const sigaction, _old: *mut sigaction, ) -> CIntZeroResult { - yggdrasil_rt::debug_trace!("TODO: sigaction({:?})", signum); + log::error!("TODO: sigaction({:?})", signum); CIntZeroResult::SUCCESS } @@ -282,7 +282,7 @@ unsafe extern "C" fn signal(handler: sig_handler_t, signum: SigNumber) -> sig_ha let address = handler as usize; // NULL or SIG_ERR if address == 0 || address == 1 { - yggdrasil_rt::debug_trace!("libc: signal() was passed an invalid handler"); + log::error!("libc: signal() was passed an invalid handler"); error::errno = Errno::EINVAL; // SIG_ERR return core::mem::transmute(1usize); diff --git a/userspace/lib/ygglibc/src/headers/stdio/file.rs b/userspace/lib/ygglibc/src/headers/stdio/file.rs index a3f0c3ba..320c5819 100644 --- a/userspace/lib/ygglibc/src/headers/stdio/file.rs +++ b/userspace/lib/ygglibc/src/headers/stdio/file.rs @@ -5,7 +5,6 @@ use core::{ use alloc::boxed::Box; use yggdrasil_rt::{ - debug_trace, io::{OpenOptions, RawFd, SeekFrom}, path::Path, }; @@ -61,7 +60,7 @@ unsafe extern "C" fn fclose(fp: *mut FILE) -> CEofResult { let fp = NonNull::new(fp).expect("fclose(): fp == NULL"); if !io::managed::deregister_file(fp) { - debug_trace!("fclose() on non-registered file: {fp:p}"); + log::error!("fclose() on non-registered file: {fp:p}"); } FILE::close(fp)?; diff --git a/userspace/lib/ygglibc/src/headers/sys_socket/socket.rs b/userspace/lib/ygglibc/src/headers/sys_socket/socket.rs index 92a85e8f..0be39a5d 100644 --- a/userspace/lib/ygglibc/src/headers/sys_socket/socket.rs +++ b/userspace/lib/ygglibc/src/headers/sys_socket/socket.rs @@ -96,7 +96,7 @@ unsafe extern "C" fn socket(domain: c_int, ty: c_int, proto: c_int) -> CFdResult (AF_INET, SOCK_STREAM, 0) => rt::SocketType::TcpStream, (AF_INET, SOCK_DGRAM, 0) => rt::SocketType::UdpPacket, (_, _, _) => { - yggdrasil_rt::debug_trace!("Unsupported socket({domain}, {ty}, {proto})"); + log::error!("Unsupported socket({domain}, {ty}, {proto})"); error::errno = Errno::ENOTSUPP; return CFdResult::ERROR; } diff --git a/userspace/lib/ygglibc/src/headers/unistd/io.rs b/userspace/lib/ygglibc/src/headers/unistd/io.rs index c70f99fb..db0dde34 100644 --- a/userspace/lib/ygglibc/src/headers/unistd/io.rs +++ b/userspace/lib/ygglibc/src/headers/unistd/io.rs @@ -1,6 +1,6 @@ use core::{ffi::{c_char, c_int, c_void}, mem::MaybeUninit}; -use yggdrasil_rt::{debug_trace, io::{RawFd, SeekFrom}}; +use yggdrasil_rt::{io::{RawFd, SeekFrom}}; use crate::{ error::{CFdResult, CIntZeroResult, CIsizeResult, COffsetResult, ResultExt, TryFromExt}, @@ -32,19 +32,19 @@ unsafe extern "C" fn dup2(oldfd: c_int, newfd: c_int) -> CFdResult { #[no_mangle] unsafe extern "C" fn fdatasync(fd: c_int) -> CIntZeroResult { - debug_trace!("TODO: fdatasync()"); + log::error!("TODO: fdatasync()"); CIntZeroResult::SUCCESS } #[no_mangle] unsafe extern "C" fn fsync(fd: c_int) -> CIntZeroResult { - debug_trace!("TODO: fsync()"); + log::error!("TODO: fsync()"); CIntZeroResult::SUCCESS } #[no_mangle] unsafe extern "C" fn isatty(fd: c_int) -> c_int { - debug_trace!("TODO: isatty()"); + log::error!("TODO: isatty()"); 1 } @@ -85,7 +85,7 @@ unsafe extern "C" fn pwrite(fd: c_int, buf: *const c_void, len: usize, pos: off_ #[no_mangle] unsafe extern "C" fn sync() { - debug_trace!("TODO: sync()"); + log::error!("TODO: sync()"); } #[no_mangle] diff --git a/userspace/lib/ygglibc/src/headers/unistd/process.rs b/userspace/lib/ygglibc/src/headers/unistd/process.rs index b955902d..b4e358bb 100644 --- a/userspace/lib/ygglibc/src/headers/unistd/process.rs +++ b/userspace/lib/ygglibc/src/headers/unistd/process.rs @@ -3,8 +3,6 @@ use core::{ time::Duration, }; -use yggdrasil_rt::debug_trace; - use crate::{ error::{self, CIntCountResult, CIntZeroResult, ResultExt}, headers::{ @@ -76,7 +74,7 @@ unsafe extern "C" fn getuid() -> uid_t { #[no_mangle] unsafe extern "C" fn nice(incr: c_int) -> CIntCountResult { - debug_trace!("TODO: nice()"); + log::error!("TODO: nice()"); CIntCountResult::success(0) } diff --git a/userspace/lib/ygglibc/src/init.rs b/userspace/lib/ygglibc/src/init.rs index 41840840..f70ff7da 100644 --- a/userspace/lib/ygglibc/src/init.rs +++ b/userspace/lib/ygglibc/src/init.rs @@ -21,7 +21,7 @@ pub extern "C" fn init() { } unsafe fn call_constructor_list(start: usize, end: usize) { - yggdrasil_rt::debug_trace!("call_constructor_list {:#x?}", start..end); + log::debug!("call_constructor_list {:#x?}", start..end); let base = start as *const usize; let len = (end - start) / size_of::(); for i in 0..len { @@ -29,7 +29,7 @@ unsafe fn call_constructor_list(start: usize, end: usize) { if addr == 0 { continue; } - yggdrasil_rt::debug_trace!("call constructor: {:#x}", addr); + log::debug!("call constructor: {:#x}", addr); let func = core::mem::transmute::<_, extern "C" fn()>(addr); func(); } diff --git a/userspace/lib/ygglibc/src/io/mod.rs b/userspace/lib/ygglibc/src/io/mod.rs index 7ede193d..4f93c06d 100644 --- a/userspace/lib/ygglibc/src/io/mod.rs +++ b/userspace/lib/ygglibc/src/io/mod.rs @@ -136,7 +136,7 @@ pub fn realpath>(path: P) -> EResult { let mut path = path.as_ref(); let mut buffer = PathBuf::from("/"); - yggdrasil_rt::debug_trace!("realpath({path:?})"); + log::debug!("realpath({path:?})"); loop { if path.is_empty() { @@ -144,7 +144,7 @@ pub fn realpath>(path: P) -> EResult { } let (head, tail) = path.split_left(); - yggdrasil_rt::debug_trace!("* {head:?}"); + log::debug!("* {head:?}"); match head { ".." => { @@ -160,7 +160,7 @@ pub fn realpath>(path: P) -> EResult { path = tail; } - yggdrasil_rt::debug_trace!("-> {buffer:?}"); + log::debug!("-> {buffer:?}"); EResult::Ok(buffer) } diff --git a/userspace/lib/ygglibc/src/lib.rs b/userspace/lib/ygglibc/src/lib.rs index 94a32f9b..2e87b0cc 100644 --- a/userspace/lib/ygglibc/src/lib.rs +++ b/userspace/lib/ygglibc/src/lib.rs @@ -42,6 +42,7 @@ extern crate compiler_builtins; #[cfg(test)] extern crate std; +mod debug; mod allocator; mod cxxabi; mod env; @@ -64,6 +65,8 @@ unsafe extern "C" fn __ygglibc_entry( main: extern "C" fn(c_int, *const *const c_char, *const *const c_char) -> c_int, arg: usize, ) { + // Setup a logging sink + debug::init_log_sink(); init::call_constructors(); signal::init(true); init::init(); diff --git a/userspace/lib/ygglibc/src/panic.rs b/userspace/lib/ygglibc/src/panic.rs index eb9f887a..a1ab2d33 100644 --- a/userspace/lib/ygglibc/src/panic.rs +++ b/userspace/lib/ygglibc/src/panic.rs @@ -36,7 +36,9 @@ impl PanicPrinter { let text = &self.buffer[..self.pos]; if !text.is_empty() { // Print to debug trace - yggdrasil_rt::debug::trace_raw(text); + if let Ok(text) = core::str::from_utf8(text) { + log::error!("{text}"); + } // Print to stderr if let Some(print) = self.print.as_mut() { @@ -94,8 +96,8 @@ fn panic_handler(pi: &core::panic::PanicInfo) -> ! { printer.flush(); } 1 => { - yggdrasil_rt::debug_trace!("{pi:?}"); - yggdrasil_rt::debug_trace!("!!! ygglibc panicked while panicking !!!"); + log::error!("{pi:?}"); + log::error!("!!! ygglibc panicked while panicking !!!"); } _ => {} } diff --git a/userspace/netutils/Cargo.toml b/userspace/netutils/Cargo.toml index da362a9e..3f539a74 100644 --- a/userspace/netutils/Cargo.toml +++ b/userspace/netutils/Cargo.toml @@ -4,9 +4,11 @@ version = "0.1.0" edition = "2021" [dependencies] -log.workspace = true yggdrasil-abi.workspace = true runtime.workspace = true +logsink.workspace = true + +log.workspace = true bytemuck.workspace = true serde_json.workspace = true serde.workspace = true diff --git a/userspace/netutils/src/dnsq.rs b/userspace/netutils/src/dnsq.rs index 7eb2de81..8e0833ae 100644 --- a/userspace/netutils/src/dnsq.rs +++ b/userspace/netutils/src/dnsq.rs @@ -63,11 +63,11 @@ fn handle_query( match (ty, class) { (DnsType::A, DnsClass::IN) => { if let Some(ip) = a_cache.get(name) { - debug_trace!("Cache hit: {} -> {}", name, ip); + log::debug!("Cache hit: {} -> {}", name, ip); return Ok(IpAddr::V4(*ip)); } - debug_trace!("Cache miss: {}", name); + log::debug!("Cache miss: {}", name); let result = perform_query(nameservers, name, ty)?; for answer in result.answers { @@ -78,7 +78,7 @@ fn handle_query( #[allow(clippy::single_match)] match (answer.ty, answer.class, answer.rdata) { (DnsType::A, DnsClass::IN, DnsRecordData::A(ip)) => { - debug_trace!("Resolved: {} -> {}", name, ip); + log::debug!("Resolved: {} -> {}", name, ip); a_cache.insert(name, ip); } _ => (), @@ -131,7 +131,7 @@ fn run_server(addr: SocketAddr, nameservers: &[SocketAddr]) -> Result<(), Error> let reply = DnsMessage::reply(reply_code, message.questions, answers, message.xid); reply.serialize(&mut packet); if let Err(error) = socket.send_to(&packet, remote) { - debug_trace!("sendto: {}", error); + log::error!("sendto: {}", error); } } } @@ -192,6 +192,7 @@ fn perform_query(nameservers: &[SocketAddr], name: &str, ty: DnsType) -> Result< } fn main() -> ExitCode { + logsink::setup_logging(true); let mut args: Arguments = Arguments::parse(); if let Some(server) = args.server { diff --git a/userspace/netutils/src/ncap.rs b/userspace/netutils/src/ncap.rs index ef68a74c..26864ddd 100644 --- a/userspace/netutils/src/ncap.rs +++ b/userspace/netutils/src/ncap.rs @@ -159,10 +159,11 @@ fn run(args: &Args) -> io::Result<()> { } fn sigint_handler(_: Signal) { - debug_trace!("SIGINT handler!") + log::debug!("SIGINT handler!") } fn main() -> ExitCode { + logsink::setup_logging(true); let _ = set_signal_handler(Signal::Interrupted, SignalHandler::Function(sigint_handler)); let args = Args::parse(); diff --git a/userspace/sysutils/Cargo.toml b/userspace/sysutils/Cargo.toml index dc61d768..e9b42404 100644 --- a/userspace/sysutils/Cargo.toml +++ b/userspace/sysutils/Cargo.toml @@ -7,13 +7,16 @@ authors = ["Mark Poliakov "] # See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html [dependencies] -rand.workspace = true libterm.workspace = true yggdrasil-abi.workspace = true yggdrasil-rt.workspace = true +cross.workspace = true +logsink.workspace = true + +log.workspace = true +rand.workspace = true thiserror.workspace = true clap.workspace = true -cross.workspace = true serde.workspace = true serde_json.workspace = true sha2.workspace = true diff --git a/userspace/sysutils/src/login.rs b/userspace/sysutils/src/login.rs index 0a6b7f6d..facdd3ab 100644 --- a/userspace/sysutils/src/login.rs +++ b/userspace/sysutils/src/login.rs @@ -46,6 +46,7 @@ fn login_attempt(erase: bool) -> Result<(), io::Error> { } fn main() -> ExitCode { + logsink::setup_logging(false); let args: Vec<_> = env::args().skip(1).collect(); if args.len() != 1 { eprintln!("Usage: /sbin/login TTY"); @@ -54,16 +55,16 @@ fn main() -> ExitCode { let terminal = args[0].as_str(); // TODO check that `terminal` is a terminal - debug_trace!("Starting a session at {}", terminal); + log::info!("Starting a session at {}", terminal); if let Err(err) = unsafe { start_terminal_session(terminal) } { - debug_trace!("Error: {:?}", err); + log::error!("Error: {:?}", err); eprintln!("Could not setup a session at {}: {:?}", terminal, err); return ExitCode::FAILURE; } let mut attempt_number = 0; loop { - debug_trace!("Login attempt {}", attempt_number); + log::debug!("Login attempt {}", attempt_number); // "Attach" the terminal let group_id = std::os::yggdrasil::process::group_id(); diff --git a/userspace/sysutils/src/view.rs b/userspace/sysutils/src/view.rs index 3e82fa90..764b60ad 100644 --- a/userspace/sysutils/src/view.rs +++ b/userspace/sysutils/src/view.rs @@ -162,13 +162,14 @@ struct Args { } fn main() -> ExitCode { + logsink::setup_logging(true); // TODO check if running in a terminal let args = Args::parse(); let view = View::open(&args.filename, !args.no_bar).unwrap(); match view.run() { Ok(()) => ExitCode::SUCCESS, Err(error) => { - yggdrasil_rt::debug_trace!("view: {error}"); + log::error!("view: {error}"); ExitCode::FAILURE } } diff --git a/userspace/term/Cargo.toml b/userspace/term/Cargo.toml index 146b09aa..fb940a98 100644 --- a/userspace/term/Cargo.toml +++ b/userspace/term/Cargo.toml @@ -7,6 +7,8 @@ authors = ["Mark Poliakov "] [dependencies] libpsf.workspace = true libcolors.workspace = true +logsink.workspace = true +log.workspace = true thiserror.workspace = true clap.workspace = true diff --git a/userspace/term/src/main.rs b/userspace/term/src/main.rs index 536e98a7..611e1563 100644 --- a/userspace/term/src/main.rs +++ b/userspace/term/src/main.rs @@ -278,7 +278,7 @@ impl Terminal<'_> { let pty_slave_stdout = fd::clone_fd(pty_slave_stdin)?; let pty_slave_stderr = fd::clone_fd(pty_slave_stdin)?; - debug_trace!("stdin = {pty_slave_stdin:?}, stdout = {pty_slave_stdout:?}, stderr = {pty_slave_stderr:?}"); + log::debug!("stdin = {pty_slave_stdin:?}, stdout = {pty_slave_stdout:?}, stderr = {pty_slave_stderr:?}"); let group_id = yggdrasil::process::create_process_group(); let shell = unsafe {