user: rework userspace tracing

This commit is contained in:
Mark Poliakov 2025-02-19 22:06:29 +02:00
parent 0105be8fea
commit dcc5d56750
57 changed files with 289 additions and 128 deletions

View File

@ -180,9 +180,10 @@ fn make_sysfs_sink_object(index: usize) -> Arc<KObject<usize>> {
}
/// 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,

View File

@ -1,6 +1,7 @@
use core::mem::MaybeUninit;
pub(crate) use abi::{
debug::TraceLevel,
error::Error,
io::{
AccessMode, DirectoryEntry, FileAttr, FileMode, FileSync, MountOptions, OpenOptions,

View File

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

View File

@ -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<ProcessId>;
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<()>;

View File

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

View File

@ -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);
}
}
}

View File

@ -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))) };
}

View File

@ -165,7 +165,7 @@ impl<R> Thread<R> {
// 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();
}
}

View File

@ -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<Item = &'a AuxValue>>(
/// 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),

View File

@ -21,11 +21,18 @@ pub fn clone_tls(image: &TlsImage) -> Result<TlsInfo, Error> {
const TCB_SIZE: usize = size_of::<usize>() * 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<TlsInfo, Error> {
// Zero the TCB after the self-pointer
tcb[size_of::<usize>()..].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,

View File

@ -71,7 +71,7 @@ pub fn clone_tls(image: &TlsImage) -> Result<TlsInfo, Error> {
// Zero the TCB after the self-pointer
tcb[size_of::<usize>()..].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,

View File

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

10
userspace/Cargo.lock generated
View File

@ -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",
]

View File

@ -83,7 +83,7 @@ fn run() -> Result<ExitCode, Error> {
}
fn main() -> ExitCode {
logsink::setup_logging();
logsink::setup_logging(true);
log::info!("colors-bar starting");
match run() {
Ok(code) => code,

View File

@ -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();

View File

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

View File

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

View File

@ -73,7 +73,7 @@ fn run(binary: &str, args: &[String]) -> Result<!, Error> {
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<!, Error> {
// 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<String> = std::env::args().skip(1).collect();
if args.is_empty() {

View File

@ -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();
}

View File

@ -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!(

View File

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

View File

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

View File

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

View File

@ -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<usize> {
let segment = self.segments.iter().find(|seg| seg.object_id == object_id)?;
pub fn offset(&self, module_id: u32, offset: usize) -> Option<usize> {
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;

View File

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

View File

@ -65,7 +65,7 @@ impl TlsLayoutBuilder for TlsLayoutImpl {
.map(|(object_id, offset, size)| TlsSegment {
offset,
size,
object_id,
module_id: object_id + 1,
})
.collect();

View File

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

View File

@ -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::<InitMsg>(&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
}

View File

@ -39,7 +39,7 @@ impl FromStr for Mode {
fn exec_script<P: AsRef<Path>>(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()?;

View File

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

View File

@ -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();
}

View File

@ -1,6 +1,7 @@
use std::io::stdout;
use log::LevelFilter;
use yggdrasil_rt::debug::TraceLevel;
struct LogSink;
@ -10,12 +11,22 @@ 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) };
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();
}

View File

@ -591,6 +591,7 @@ dependencies = [
"cbindgen",
"chrono",
"libyalloc",
"log",
"yggdrasil-abi",
"yggdrasil-rt",
]

View File

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

View File

@ -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();
}

View File

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

View File

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

View File

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

View File

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

View File

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

View File

@ -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);

View File

@ -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)?;

View File

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

View File

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

View File

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

View File

@ -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::<usize>();
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();
}

View File

@ -136,7 +136,7 @@ pub fn realpath<P: AsRef<Path>>(path: P) -> EResult<PathBuf> {
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<P: AsRef<Path>>(path: P) -> EResult<PathBuf> {
}
let (head, tail) = path.split_left();
yggdrasil_rt::debug_trace!("* {head:?}");
log::debug!("* {head:?}");
match head {
".." => {
@ -160,7 +160,7 @@ pub fn realpath<P: AsRef<Path>>(path: P) -> EResult<PathBuf> {
path = tail;
}
yggdrasil_rt::debug_trace!("-> {buffer:?}");
log::debug!("-> {buffer:?}");
EResult::Ok(buffer)
}

View File

@ -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();

View File

@ -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 !!!");
}
_ => {}
}

View File

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

View File

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

View File

@ -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();

View File

@ -7,13 +7,16 @@ authors = ["Mark Poliakov <mark@alnyan.me>"]
# 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

View File

@ -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();

View File

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

View File

@ -7,6 +7,8 @@ authors = ["Mark Poliakov <mark@alnyan.me>"]
[dependencies]
libpsf.workspace = true
libcolors.workspace = true
logsink.workspace = true
log.workspace = true
thiserror.workspace = true
clap.workspace = true

View File

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