init: add serial debug output for scheduler tracing

Add dbg_init/dbgprintln macros that write directly to /scheme/debug/no-preserve,
bypassing logd output redirection after switch_stdio. This enables scheduler
tracing (INIT_RUN, INIT_DEFER, INIT_BLOCK, INIT_DONE, INIT_SCHEME) to remain
visible on the serial console throughout all boot phases.

Also add INIT_SPIN counter to detect infinite polling loops in step().

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<fs::File> = 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 {

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<String, usize> = 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,14 +78,33 @@ 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 {
+                                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 {
+            match &service.type_ {
-                eprintln!(
+                crate::service::ServiceType::Oneshot
-                    "Starting {} ({})",
+                | crate::service::ServiceType::Notify
-                    unit.info.description.as_ref().unwrap_or(&unit.id.0),
+                | crate::service::ServiceType::Scheme(_) => {
-                    service.cmd,
+                    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),
                 );

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

init/src/unit.rs

@@ -131,6 +131,7 @@ fn true_bool() -> bool {
     true
 }
 
+#[derive(Debug)]
 pub enum UnitKind {
     LegacyScript { script: Vec<Command> },
     Service { service: Service },