init: add scheduler completion counter with direct serial output

Write DONE/LIVE diagnostics to /scheme/debug/no-preserve to
confirm step() completion. Revert all verbose tracing to clean
state.

init/src/main.rs

@@ -1,8 +1,6 @@
 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};
@@ -15,43 +13,6 @@ 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)?;
@@ -93,7 +54,6 @@ 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
@@ -153,7 +113,6 @@ 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();
@@ -214,11 +173,8 @@ 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

@@ -1,4 +1,5 @@
 use std::collections::VecDeque;
+use std::io::Write;
 
 use crate::InitConfig;
 use crate::unit::{Unit, UnitId, UnitKind, UnitStore};
@@ -55,58 +56,35 @@ 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 count: usize = 0;
-        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 {
+                if let Ok(mut f) = std::fs::OpenOptions::new().write(true).open("/scheme/debug/no-preserve") {
+                    let _ = writeln!(f, "DONE: {} units", count);
+                }
                 return;
             };
+            count += 1;
 
             match job.kind {
                 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());
+                                self.pending.push_back(job);
-                                break;
+                                continue 'a;
                             }
                         }
                     }
 
-                    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);
+                    if count % 50 == 0 {
+                        if let Ok(mut f) = std::fs::OpenOptions::new().write(true).open("/scheme/debug/no-preserve") {
+                            let _ = writeln!(f, "LIVE: {} units processed", count);
+                        }
+                    }
                 }
             }
         }
@@ -114,48 +92,32 @@ 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 {
-                    crate::dbgprintln!("init: running: {cmd:?}");
+                    eprintln!("init: running: {cmd:?}");
                 }
                 cmd.run(config);
             }
         }
         UnitKind::Service { service } => {
             if config.skip_cmd.contains(&service.cmd) {
-                crate::dbgprintln!("Skipping '{} {}'", service.cmd, service.args.join(" "));
+                eprintln!("Skipping '{} {}'", service.cmd, service.args.join(" "));
                 return;
             }
-            match &service.type_ {
+            if config.log_debug {
-                crate::service::ServiceType::Oneshot
+                eprintln!(
-                | crate::service::ServiceType::Notify
+                    "Starting {} ({})",
-                | crate::service::ServiceType::Scheme(_) => {
+                    unit.info.description.as_ref().unwrap_or(&unit.id.0),
-                    crate::dbgprintln!(
+                    service.cmd,
-                        "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 {
-                crate::dbgprintln!(
+                eprintln!(
                     "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) => {
-                crate::dbgprintln!("init: failed to execute {:?}: {}", command, err);
+                eprintln!("init: failed to execute {:?}: {}", command, err);
                 return;
             }
         };
@@ -61,17 +61,13 @@ impl Service {
             ServiceType::Notify => match read_pipe.read_exact(&mut [0]) {
                 Ok(()) => {}
                 Err(err) if err.kind() == io::ErrorKind::UnexpectedEof => {
-                    crate::dbgprintln!("init: {command:?} exited without notifying readiness");
+                    eprintln!("init: {command:?} exited without notifying readiness");
                 }
                 Err(err) => {
-                    crate::dbgprintln!("init: failed to wait for {command:?}: {err}");
+                    eprintln!("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(
@@ -84,43 +80,35 @@ impl Service {
                             errno: syscall::EINTR,
                         }) => continue,
                         Ok(0) => {
-                            crate::dbgprintln!("INIT_SCHEME: call_ro returned Ok(0) for {:?} - writer closed", command);
+                            eprintln!("init: {command:?} exited without notifying readiness");
-                            crate::dbgprintln!("init: {command:?} exited without notifying readiness");
                             return;
                         }
-                        Ok(1) => {
+                        Ok(1) => break,
-                            crate::dbgprintln!("INIT_SCHEME: call_ro returned Ok(1) for {:?} - got fd={}", command, new_fd);
-                            break;
-                        }
                         Ok(n) => {
-                            crate::dbgprintln!("INIT_SCHEME: call_ro returned Ok({}) for {:?}", n, command);
+                            eprintln!("init: incorrect amount of fds {n} returned");
-                            crate::dbgprintln!("init: incorrect amount of fds {n} returned");
                             return;
                         }
                         Err(err) => {
-                            crate::dbgprintln!("INIT_SCHEME: call_ro returned Err({}) for {:?}", err, command);
+                            eprintln!("init: failed to wait for {command:?}: {err}");
-                            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() {
-                            crate::dbgprintln!("init: {command:?} failed with {exit_status}");
+                            eprintln!("init: {command:?} failed with {exit_status}");
                         }
                     }
                     Err(err) => {
-                        crate::dbgprintln!("init: failed to wait for {:?}: {}", command, err)
+                        eprintln!("init: failed to wait for {:?}: {}", command, err)
                     }
                 }
             }

init/src/unit.rs

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