Improve and unify logging during setup steps

Each step now produces a label that is used for logging. Also, before gathering
and running the steps a stage, we log the name of this stage.

src/bin/scheduler/setup/steps/api.rs

@@ -1,4 +1,5 @@
 use crate::internal_config::Plan;
+use log::{debug, error};
 use robotmk::results::SetupFailure;
 use robotmk::termination::Cancelled;
 use tokio_util::sync::CancellationToken;
@@ -16,21 +17,26 @@ impl Error {
 }
 
 pub trait SetupStep {
+    fn label(&self) -> String;
     fn setup(&self) -> Result<(), Error>;
 }
 
 pub type StepWithPlans = (Box<dyn SetupStep>, Vec<Plan>);
 
-struct SetupStepSuccess {}
+struct SetupStepNoOp {}
+
+impl SetupStep for SetupStepNoOp {
+    fn label(&self) -> String {
+        "No-op".into()
+    }
 
-impl SetupStep for SetupStepSuccess {
     fn setup(&self) -> Result<(), Error> {
         Ok(())
     }
 }
 
 pub fn skip(plans: Vec<Plan>) -> StepWithPlans {
-    (Box::new(SetupStepSuccess {}), plans)
+    (Box::new(SetupStepNoOp {}), plans)
 }
 
 pub fn run_steps(
@@ -44,19 +50,27 @@ pub fn run_steps(
             return Err(Cancelled);
         }
         if affected_plans.is_empty() {
+            debug!("Setup step `{}` affects no plans, skipping", step.label());
             continue;
         }
+        debug!(
+            "Plan(s) {plan_ids}: {label}",
+            label = step.label(),
+            plan_ids = affected_plans
+                .iter()
+                .map(|plan| plan.id.as_str())
+                .collect::<Vec<&str>>()
+                .join(", ")
+        );
         match step.setup() {
             Ok(()) => {
                 plans.extend(affected_plans);
             }
             Err(err) => {
                 for plan in &plans {
-                    log::error!(
+                    error!(
                         "Plan {}: {}. Plan won't be scheduled.\nCaused by: {:?}",
-                        plan.id,
-                        err.summary,
-                        err.cause,
+                        plan.id, err.summary, err.cause,
                     );
                     errors.push(SetupFailure {
                         plan_id: plan.id.clone(),

src/bin/scheduler/setup/steps/directories.rs

@@ -19,6 +19,10 @@ struct StepCreate {
 }
 
 impl SetupStep for StepCreate {
+    fn label(&self) -> String {
+        format!("Create directory {}", self.target)
+    }
+
     fn setup(&self) -> Result<(), api::Error> {
         create_dir_all(&self.target)
             .map_err(|err| api::Error::new(format!("Failed to create {}", self.target), err))
@@ -31,18 +35,27 @@ struct StepCreateWithAccess {
 }
 
 impl SetupStep for StepCreateWithAccess {
+    fn label(&self) -> String {
+        let mut label = StepCreate {
+            target: self.target.clone(),
+        }
+        .label();
+        if let Session::User(user_session) = &self.session {
+            label = format!(
+                "{label} and grant user {user} full access",
+                user = user_session.user_name
+            );
+        }
+        label
+    }
+
     fn setup(&self) -> Result<(), api::Error> {
         StepCreate {
             target: self.target.clone(),
         }
         .setup()?;
+        #[cfg(windows)]
         if let Session::User(user_session) = &self.session {
-            log::info!(
-                "Granting full access for {} to user `{}`.",
-                &self.target,
-                &user_session.user_name
-            );
-            #[cfg(windows)]
             grant_full_access(&user_session.user_name, &self.target).map_err(|err| {
                 api::Error::new(
                     format!("Failed to set permissions for {}", self.target),
@@ -61,6 +74,13 @@ struct StepRobocorpHomeBase {
 
 #[cfg(windows)]
 impl SetupStep for StepRobocorpHomeBase {
+    fn label(&self) -> String {
+        format!(
+            "Create ROBOCORP_HOME base directory {} and restrict to Administrator group only",
+            self.target
+        )
+    }
+
     fn setup(&self) -> Result<(), api::Error> {
         StepCreate {
             target: self.target.clone(),

src/bin/scheduler/setup/steps/rcc.rs

@@ -17,7 +17,7 @@ use robotmk::termination::Outcome;
 
 use anyhow::{anyhow, Context};
 use camino::Utf8PathBuf;
-use log::{debug, error};
+use log::debug;
 use std::vec;
 use tokio_util::sync::CancellationToken;
 
@@ -30,14 +30,23 @@ struct StepFilePermissions {
 
 #[cfg(windows)]
 impl SetupStep for StepFilePermissions {
-    fn setup(&self) -> Result<(), api::Error> {
-        if let Session::User(user_session) = &self.session {
-            log::info!(
-                "Granting user `{user}` {permissions} access to {target}.",
-                user = &user_session.user_name,
+    fn label(&self) -> String {
+        match &self.session {
+            Session::Current(_) => format!(
+                "Not changing permissions of {} since current user is assumed to have access",
+                &self.target,
+            ),
+            Session::User(user_session) => format!(
+                "Grant user {user} permissions `{permissions}` for {target}",
+                user = user_session.user_name,
                 permissions = &self.icacls_permissions,
                 target = &self.target,
-            );
+            ),
+        }
+    }
+
+    fn setup(&self) -> Result<(), api::Error> {
+        if let Session::User(user_session) = &self.session {
             run_icacls_command([
                 self.target.as_str(),
                 "/grant",
@@ -90,6 +99,14 @@ impl StepRCCCommand {
 }
 
 impl SetupStep for StepRCCCommand {
+    fn label(&self) -> String {
+        format!(
+            "Execute RCC with arguments `{arguments:?}` in session `{session}`",
+            arguments = &self.arguments,
+            session = &self.session,
+        )
+    }
+
     fn setup(&self) -> Result<(), api::Error> {
         let mut command_spec = RCCEnvironment::bundled_command_spec(
             &self.binary_path,
@@ -109,7 +126,6 @@ impl SetupStep for StepRCCCommand {
             timeout: 120,
             cancellation_token: &self.cancellation_token,
         };
-        debug!("Running {} for `{}`", command_spec, &self.session);
         let run_outcome = match self.session.run(&run_spec).context(format!(
             "Failed to run {} for `{}`",
             run_spec.command_spec, self.session
@@ -123,31 +139,21 @@ impl SetupStep for StepRCCCommand {
         let exit_code = match run_outcome {
             Outcome::Completed(exit_code) => exit_code,
             Outcome::Timeout => {
-                error!("{} for `{}` timed out", run_spec.command_spec, self.session);
                 return Err(api::Error::new(
                     self.summary_if_failure.clone(),
                     anyhow!("Timeout"),
                 ));
             }
             Outcome::Cancel => {
-                error!("{} for `{}` cancelled", run_spec.command_spec, self.session);
                 return Err(api::Error::new(
                     self.summary_if_failure.clone(),
                     anyhow!("Cancelled"),
                 ));
             }
         };
         if exit_code == 0 {
-            debug!(
-                "{} for `{}` successful",
-                run_spec.command_spec, self.session
-            );
             Ok(())
         } else {
-            error!(
-                "{} for `{}` exited non-successfully",
-                run_spec.command_spec, self.session
-            );
             Err(api::Error::new(
                 self.summary_if_failure.clone(),
                 anyhow!(
@@ -180,6 +186,10 @@ impl StepDisableSharedHolotree {
 }
 
 impl SetupStep for StepDisableSharedHolotree {
+    fn label(&self) -> String {
+        format!("Disable shared holotree in session `{}`", &self.session)
+    }
+
     fn setup(&self) -> Result<(), api::Error> {
         let mut command_spec = RCCEnvironment::bundled_command_spec(
             &self.binary_path,
@@ -188,7 +198,6 @@ impl SetupStep for StepDisableSharedHolotree {
                 .to_string(),
         );
         command_spec.add_arguments(["holotree", "init", "--revoke"]);
-        debug!("Running {} for `{}`", command_spec, self.session);
         let name = "holotree_disabling_sharing";
         let run_spec = &RunSpec {
             id: &format!("robotmk_{name}_{}", self.session.id()),
@@ -202,13 +211,7 @@ impl SetupStep for StepDisableSharedHolotree {
             cancellation_token: &self.cancellation_token,
         };
         match self.session.run(run_spec) {
-            Ok(Outcome::Completed(0)) => {
-                debug!(
-                    "{} for `{}` successful",
-                    run_spec.command_spec, self.session
-                );
-                Ok(())
-            }
+            Ok(Outcome::Completed(0)) => Ok(()),
             Ok(Outcome::Completed(5)) => {
                 debug!(
                     "`{}` not using shared holotree. Don't need to disable.",
@@ -227,13 +230,10 @@ impl SetupStep for StepDisableSharedHolotree {
                 "Disabling shared holotree timed out".into(),
                 anyhow!("Timeout"),
             )),
-            Ok(Outcome::Cancel) => {
-                error!("{} for `{}` cancelled", run_spec.command_spec, self.session);
-                Err(api::Error::new(
-                    "Disabling shared holotree cancelled".into(),
-                    anyhow!("Cancelled"),
-                ))
-            }
+            Ok(Outcome::Cancel) => Err(api::Error::new(
+                "Disabling shared holotree cancelled".into(),
+                anyhow!("Cancelled"),
+            )),
             Err(error) => {
                 let error = error.context(format!(
                     "Failed to run {} for `{}`",

src/bin/scheduler/setup/steps/run.rs

@@ -1,6 +1,7 @@
 use super::api::{run_steps, StepWithPlans};
 use super::{directories, rcc, unpack_managed};
 use crate::internal_config::{sort_plans_by_grouping, GlobalConfig, Plan};
+use log::info;
 use robotmk::results::SetupFailure;
 use robotmk::termination::Cancelled;
 
@@ -9,7 +10,8 @@ pub fn run(
     mut plans: Vec<Plan>,
 ) -> Result<(Vec<Plan>, Vec<SetupFailure>), Cancelled> {
     let mut failures = Vec::new();
-    for gatherer in STEPS {
+    for (gatherer, stage) in STEPS {
+        info!("Running setup stage: {stage}");
         plans = {
             let plan_count = plans.len();
             let setup_steps = gatherer(config, plans);
@@ -29,32 +31,74 @@ pub fn run(
 
 type Gatherer = fn(&GlobalConfig, Vec<Plan>) -> Vec<StepWithPlans>;
 #[cfg(unix)]
-type Steps = [Gatherer; 11];
+type Steps = [(Gatherer, &'static str); 11];
 #[cfg(windows)]
-type Steps = [Gatherer; 17];
+type Steps = [(Gatherer, &'static str); 17];
 
 const STEPS: Steps = [
-    directories::gather_managed_directories,
+    (
+        directories::gather_managed_directories,
+        "Managed directories",
+    ),
     #[cfg(windows)]
-    directories::gather_robocorp_home_base,
+    (
+        directories::gather_robocorp_home_base,
+        "ROBOCORP_HOME base directory",
+    ),
     #[cfg(windows)]
-    directories::gather_robocorp_home_per_user,
-    directories::gather_plan_working_directories,
-    directories::gather_environment_building_directories,
-    directories::gather_rcc_working_base,
+    (
+        directories::gather_robocorp_home_per_user,
+        "User-specific ROBOCORP_HOME directories",
+    ),
+    (
+        directories::gather_plan_working_directories,
+        "Plan working directories",
+    ),
+    (
+        directories::gather_environment_building_directories,
+        "Environment building directories",
+    ),
+    (
+        directories::gather_rcc_working_base,
+        "Base working directory for RCC setup steps",
+    ),
     #[cfg(windows)]
-    directories::gather_rcc_longpath_directory,
-    directories::gather_rcc_working_per_user,
+    (
+        directories::gather_rcc_longpath_directory,
+        "Working directory for enabling RCC long path support",
+    ),
+    (
+        directories::gather_rcc_working_per_user,
+        "User-specififc working directories for RCC setup steps",
+    ),
     #[cfg(windows)]
-    rcc::gather_rcc_binary_permissions,
+    (rcc::gather_rcc_binary_permissions, "RCC binary permissions"),
     #[cfg(windows)]
-    rcc::gather_rcc_profile_permissions,
-    rcc::gather_disable_rcc_telemetry,
-    rcc::gather_configure_default_rcc_profile,
-    rcc::gather_import_custom_rcc_profile,
-    rcc::gather_switch_to_custom_rcc_profile,
+    (
+        rcc::gather_rcc_profile_permissions,
+        "RCC profile permissions",
+    ),
+    (rcc::gather_disable_rcc_telemetry, "Disable RCC telemetry"),
+    (
+        rcc::gather_configure_default_rcc_profile,
+        "Configure default RCC profile",
+    ),
+    (
+        rcc::gather_import_custom_rcc_profile,
+        "Import custom RCC profile",
+    ),
+    (
+        rcc::gather_switch_to_custom_rcc_profile,
+        "Switch to custom RCC profile",
+    ),
     #[cfg(windows)]
-    rcc::gather_enable_rcc_long_path_support,
-    rcc::gather_disable_rcc_shared_holotree,
-    unpack_managed::gather,
+    (
+        rcc::gather_enable_rcc_long_path_support,
+        "Enable RCC long path support",
+    ),
+    (
+        rcc::gather_disable_rcc_shared_holotree,
+        "Disable RCC shared holotrees",
+    ),
+    (unpack_managed::gather, "Unpack managed robots"),
 ];

src/bin/scheduler/setup/steps/unpack_managed.rs

@@ -42,6 +42,14 @@ struct StepUnpackManaged {
 }
 
 impl SetupStep for StepUnpackManaged {
+    fn label(&self) -> String {
+        format!(
+            "Unpack managed robot {archive_path} to {target_dir}",
+            archive_path = self.tar_gz_path,
+            target_dir = self.target_dir
+        )
+    }
+
     fn setup(&self) -> Result<(), api::Error> {
         unpack_into(&self.tar_gz_path, &self.target_dir, self.size_limit)
             .map_err(|err| api::Error::new("Failed to unpack managed robot archive".into(), err))