diff --git a/init/src/main.rs b/init/src/main.rs index 5682cf4455..0286273cdd 100644 --- a/init/src/main.rs +++ b/init/src/main.rs @@ -1,6 +1,8 @@ use std::collections::BTreeMap; use std::ffi::OsString; +use std::io::Write; use std::path::Path; +use std::sync::atomic::{AtomicBool, Ordering}; use std::{env, fs, io}; use libredox::flag::{O_RDONLY, O_WRONLY}; @@ -13,6 +15,43 @@ mod script; mod service; mod unit; +static SERIAL_DEBUG_FD: std::sync::OnceLock = std::sync::OnceLock::new(); +static SERIAL_DEBUG_INIT: AtomicBool = AtomicBool::new(false); + +pub fn dbg_init() { + SERIAL_DEBUG_INIT.store(true, Ordering::SeqCst); + let _ = SERIAL_DEBUG_FD.get_or_init(|| { + fs::OpenOptions::new() + .write(true) + .open("/scheme/debug/no-preserve") + .unwrap_or_else(|_| { + fs::OpenOptions::new() + .write(true) + .open("/scheme/debug") + .unwrap_or_else(|_| fs::OpenOptions::new().write(true).open("/dev/null").unwrap()) + }) + }); +} + +pub fn dbg(msg: &str) { + if !SERIAL_DEBUG_INIT.load(Ordering::SeqCst) { + eprintln!("{}", msg); + return; + } + if let Some(f) = SERIAL_DEBUG_FD.get() { + let mut f = f; + let _ = writeln!(f, "{}", msg); + let _ = f.flush(); + } +} + +#[macro_export] +macro_rules! dbgprintln { + ($($arg:tt)*) => { + $crate::dbg(&format!($($arg)*)) + }; +} + fn switch_stdio(stdio: &str) -> io::Result<()> { let stdin = libredox::Fd::open(stdio, O_RDONLY, 0)?; let stdout = libredox::Fd::open(stdio, O_WRONLY, 0)?; @@ -54,6 +93,7 @@ fn switch_root(unit_store: &mut UnitStore, config: &mut InitConfig, prefix: &Pat prefix.display(), etcdir.display() ); + crate::dbgprintln!("init: switchroot to {} {}", prefix.display(), etcdir.display()); config .envs @@ -113,6 +153,7 @@ fn switch_root(unit_store: &mut UnitStore, config: &mut InitConfig, prefix: &Pat } fn main() { + dbg_init(); let mut init_config = InitConfig::new(); let mut unit_store = UnitStore::new(); let mut scheduler = Scheduler::new(); @@ -173,8 +214,11 @@ fn main() { } }; + eprintln!("INIT: starting /usr scheduler step"); + crate::dbgprintln!("INIT: starting /usr scheduler step"); scheduler.step(&mut unit_store, &mut init_config); - + eprintln!("INIT: scheduler step complete, entering waitpid loop"); + crate::dbgprintln!("INIT: scheduler step complete, entering waitpid loop"); libredox::call::setrens(0, 0).expect("init: failed to enter null namespace"); loop { diff --git a/init/src/scheduler.rs b/init/src/scheduler.rs index d42a4e5700..1597c2db8b 100644 --- a/init/src/scheduler.rs +++ b/init/src/scheduler.rs @@ -55,7 +55,21 @@ impl Scheduler { } pub fn step(&mut self, unit_store: &mut UnitStore, init_config: &mut InitConfig) { + let mut pushback_count: std::collections::BTreeMap = std::collections::BTreeMap::new(); + let mut total_iters: usize = 0; + let mut last_logged_spin: usize = 0; 'a: loop { + total_iters += 1; + if total_iters - last_logged_spin >= 50 { + last_logged_spin = total_iters; + let pending_names: Vec<&String> = self.pending.iter().map(|j| &j.unit.0).collect(); + crate::dbgprintln!( + "INIT_SPIN: {} iterations, {} pending: {:?}", + total_iters, + self.pending.len(), + pending_names + ); + } let Some(job) = self.pending.pop_front() else { return; }; @@ -64,15 +78,34 @@ impl Scheduler { JobKind::Start => { let unit = unit_store.unit_mut(&job.unit); + let mut blocked_by = vec![]; for dep in &unit.info.requires_weak { for pending_job in &self.pending { if &pending_job.unit == dep { - self.pending.push_back(job); - continue 'a; + blocked_by.push(dep.0.clone()); + break; } } } + if !blocked_by.is_empty() { + *pushback_count.entry(job.unit.0.clone()).or_insert(0) += 1; + let count = pushback_count[&job.unit.0]; + if count <= 3 { + crate::dbgprintln!( + "INIT_DEFER: {} waiting on {:?} (attempt {})", + job.unit.0, blocked_by, count + ); + } else if count == 10 { + crate::dbgprintln!( + "INIT_DEFER: {} still waiting on {:?} after 10 attempts - POSSIBLE DEADLOCK", + job.unit.0, blocked_by + ); + } + self.pending.push_back(job); + continue 'a; + } + run(unit, init_config); } } @@ -81,32 +114,48 @@ impl Scheduler { } fn run(unit: &mut Unit, config: &mut InitConfig) { + crate::dbgprintln!("INIT_RUN: {} ({:?})", unit.id.0, unit.kind); match &unit.kind { UnitKind::LegacyScript { script } => { for cmd in script.clone() { if config.log_debug { - eprintln!("init: running: {cmd:?}"); + crate::dbgprintln!("init: running: {cmd:?}"); } cmd.run(config); } } UnitKind::Service { service } => { if config.skip_cmd.contains(&service.cmd) { - eprintln!("Skipping '{} {}'", service.cmd, service.args.join(" ")); + crate::dbgprintln!("Skipping '{} {}'", service.cmd, service.args.join(" ")); return; } - if config.log_debug { - eprintln!( - "Starting {} ({})", - unit.info.description.as_ref().unwrap_or(&unit.id.0), - service.cmd, - ); + match &service.type_ { + crate::service::ServiceType::Oneshot + | crate::service::ServiceType::Notify + | crate::service::ServiceType::Scheme(_) => { + crate::dbgprintln!( + "INIT_BLOCK: {} ({:?} {})", + unit.id.0, service.type_, service.cmd + ); + } + crate::service::ServiceType::OneshotAsync => {} } service.spawn(&config.envs); + match &service.type_ { + crate::service::ServiceType::Oneshot + | crate::service::ServiceType::Notify + | crate::service::ServiceType::Scheme(_) => { + crate::dbgprintln!( + "INIT_DONE: {} ({:?})", + unit.id.0, service.type_ + ); + } + crate::service::ServiceType::OneshotAsync => {} + } } UnitKind::Target {} => { if config.log_debug { - eprintln!( + crate::dbgprintln!( "Reached target {}", unit.info.description.as_ref().unwrap_or(&unit.id.0), ); diff --git a/init/src/service.rs b/init/src/service.rs index ed0023e921..d02821f79c 100644 --- a/init/src/service.rs +++ b/init/src/service.rs @@ -52,7 +52,7 @@ impl Service { let mut child = match command.spawn() { Ok(child) => child, Err(err) => { - eprintln!("init: failed to execute {:?}: {}", command, err); + crate::dbgprintln!("init: failed to execute {:?}: {}", command, err); return; } }; @@ -61,13 +61,17 @@ impl Service { ServiceType::Notify => match read_pipe.read_exact(&mut [0]) { Ok(()) => {} Err(err) if err.kind() == io::ErrorKind::UnexpectedEof => { - eprintln!("init: {command:?} exited without notifying readiness"); + crate::dbgprintln!("init: {command:?} exited without notifying readiness"); } Err(err) => { - eprintln!("init: failed to wait for {command:?}: {err}"); + crate::dbgprintln!("init: failed to wait for {command:?}: {err}"); } }, ServiceType::Scheme(scheme) => { + crate::dbgprintln!( + "INIT_SCHEME: entering call_ro loop for {:?} (scheme={}, pipe_fd={})", + command, scheme, read_pipe.as_raw_fd() + ); let mut new_fd = usize::MAX; loop { match syscall::call_ro( @@ -80,35 +84,43 @@ impl Service { errno: syscall::EINTR, }) => continue, Ok(0) => { - eprintln!("init: {command:?} exited without notifying readiness"); + crate::dbgprintln!("INIT_SCHEME: call_ro returned Ok(0) for {:?} - writer closed", command); + crate::dbgprintln!("init: {command:?} exited without notifying readiness"); return; } - Ok(1) => break, + Ok(1) => { + crate::dbgprintln!("INIT_SCHEME: call_ro returned Ok(1) for {:?} - got fd={}", command, new_fd); + break; + } Ok(n) => { - eprintln!("init: incorrect amount of fds {n} returned"); + crate::dbgprintln!("INIT_SCHEME: call_ro returned Ok({}) for {:?}", n, command); + crate::dbgprintln!("init: incorrect amount of fds {n} returned"); return; } Err(err) => { - eprintln!("init: failed to wait for {command:?}: {err}"); + crate::dbgprintln!("INIT_SCHEME: call_ro returned Err({}) for {:?}", err, command); + crate::dbgprintln!("init: failed to wait for {command:?}: {err}"); return; } } } + crate::dbgprintln!("INIT_SCHEME: registering scheme {} with fd {} in namespace", scheme, new_fd); let current_namespace_fd = libredox::call::getns().expect("TODO"); libredox::call::register_scheme_to_ns(current_namespace_fd, scheme, new_fd) .expect("TODO"); + crate::dbgprintln!("INIT_SCHEME: scheme {} registered successfully", scheme); } ServiceType::Oneshot => { drop(read_pipe); match child.wait() { Ok(exit_status) => { if !exit_status.success() { - eprintln!("init: {command:?} failed with {exit_status}"); + crate::dbgprintln!("init: {command:?} failed with {exit_status}"); } } Err(err) => { - eprintln!("init: failed to wait for {:?}: {}", command, err) + crate::dbgprintln!("init: failed to wait for {:?}: {}", command, err) } } } diff --git a/init/src/unit.rs b/init/src/unit.rs index 98053cb2d7..38a44182b1 100644 --- a/init/src/unit.rs +++ b/init/src/unit.rs @@ -131,6 +131,7 @@ fn true_bool() -> bool { true } +#[derive(Debug)] pub enum UnitKind { LegacyScript { script: Vec }, Service { service: Service },