switch-to-configuration-ng: add more logging

Adds more logging to the non-systemd related parts of
switch-to-configuration.

nixos/doc/manual/development/what-happens-during-a-system-switch.chapter.md

@@ -46,7 +46,9 @@ of actions is always the same:
 
 By default, some units are filtered from the outputs to make it less spammy.
 This can be disabled for development or testing by setting the environment variable
-`STC_DISPLAY_ALL_UNITS=1`
+`STC_DISPLAY_ALL_UNITS=1`.
+
+More detailed output can be displayed by setting `STC_DEBUG=1`.
 
 Most of these actions are either self-explaining but some of them have to do
 with our units or the activation script. For this reason, these topics are

pkgs/by-name/sw/switch-to-configuration-ng/src/src/main.rs

@@ -909,6 +909,10 @@ fn block_on_jobs(
     submitted_jobs: &Rc<RefCell<HashMap<dbus::Path<'static>, Job>>>,
 ) {
     while !submitted_jobs.borrow().is_empty() {
+        log::debug!(
+            "waiting for submitted jobs to finish, still have {} job(s)",
+            submitted_jobs.borrow().len()
+        );
         _ = conn.process(Duration::from_millis(500));
     }
 }
@@ -961,6 +965,7 @@ fn do_user_switch(parent_exe: String) -> anyhow::Result<()> {
         .restart_unit("nixos-activation.service", "replace")
         .context("Failed to restart nixos-activation.service")?;
 
+    log::debug!("waiting for nixos activation to finish");
     while !*nixos_activation_done.borrow() {
         _ = dbus_conn
             .process(Duration::from_secs(500))
@@ -989,6 +994,8 @@ dry-activate: show what would be done if this configuration were activated
 
 /// Performs switch-to-configuration functionality for the entire system
 fn do_system_switch(action: Action) -> anyhow::Result<()> {
+    log::debug!("Performing system switch");
+
     let out = PathBuf::from(required_env("OUT")?);
     let toplevel = PathBuf::from(required_env("TOPLEVEL")?);
     let distro_id = required_env("DISTRO_ID")?;
@@ -996,8 +1003,14 @@ fn do_system_switch(action: Action) -> anyhow::Result<()> {
     let install_bootloader = required_env("INSTALL_BOOTLOADER")?;
     let locale_archive = required_env("LOCALE_ARCHIVE")?;
     let new_systemd = PathBuf::from(required_env("SYSTEMD")?);
+    let log_level = if std::env::var("STC_DEBUG").is_ok() {
+        LevelFilter::Debug
+    } else {
+        LevelFilter::Info
+    };
 
     let action = ACTION.get_or_init(|| action);
+    log::debug!("Using action {:?}", action);
 
     // The action that is to be performed (like switch, boot, test, dry-activate) Also exposed via
     // environment variable from now on
@@ -1029,6 +1042,7 @@ fn do_system_switch(action: Action) -> anyhow::Result<()> {
     std::fs::set_permissions("/run/nixos", perms)
         .context("Failed to set permissions on /run/nixos directory")?;
 
+    log::debug!("Creating lock file /run/nixos/switch-to-configuration.lock");
     let Ok(lock) = std::fs::OpenOptions::new()
         .append(true)
         .create(true)
@@ -1038,12 +1052,13 @@ fn do_system_switch(action: Action) -> anyhow::Result<()> {
         die();
     };
 
+    log::debug!("Acquiring lock on file /run/nixos/switch-to-configuration.lock");
     let Ok(_lock) = Flock::lock(lock, FlockArg::LockExclusiveNonblock) else {
         eprintln!("Could not acquire lock");
         die();
     };
 
-    if syslog::init(Facility::LOG_USER, LevelFilter::Debug, Some("nixos")).is_err() {
+    if syslog::init(Facility::LOG_USER, log_level, Some("nixos")).is_err() {
         bail!("Failed to initialize logger");
     }
 
@@ -1053,6 +1068,7 @@ fn do_system_switch(action: Action) -> anyhow::Result<()> {
         != "1"
     {
         do_pre_switch_check(&pre_switch_check, &toplevel, action)?;
+        log::debug!("Done performing pre-switch checks");
     }
 
     if *action == Action::Check {
@@ -1062,6 +1078,7 @@ fn do_system_switch(action: Action) -> anyhow::Result<()> {
     // Install or update the bootloader.
     if matches!(action, Action::Switch | Action::Boot) {
         do_install_bootloader(&install_bootloader, &toplevel)?;
+        log::debug!("Done performing bootloader installation");
     }
 
     // Just in case the new configuration hangs the system, do a sync now.
@@ -1642,6 +1659,7 @@ won't take effect until you reboot the system.
         eprintln!("restarting systemd...");
         _ = systemd.reexecute(); // we don't get a dbus reply here
 
+        log::debug!("waiting for systemd restart to finish");
         while !*systemd_reload_status.borrow() {
             _ = dbus_conn
                 .process(Duration::from_millis(500))
@@ -1656,6 +1674,7 @@ won't take effect until you reboot the system.
 
     // Make systemd reload its units.
     _ = systemd.reload(); // we don't get a dbus reply here
+    log::debug!("waiting for systemd reload to finish");
     while !*systemd_reload_status.borrow() {
         _ = dbus_conn
             .process(Duration::from_millis(500))
@@ -1692,6 +1711,7 @@ won't take effect until you reboot the system.
                     .canonicalize()
                     .context("Failed to get full path to /proc/self/exe")?;
 
+                log::debug!("Performing user switch for {name}");
                 std::process::Command::new(&myself)
                     .uid(uid)
                     .gid(gid)