From b51acaf3605c7b09398889c8135119f4f00f1b28 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?J=C3=B6rg=20Herbel?= Date: Tue, 19 Nov 2024 16:45:44 +0100 Subject: [PATCH] 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 | 28 +++++-- src/bin/scheduler/setup/steps/directories.rs | 32 +++++-- src/bin/scheduler/setup/steps/rcc.rs | 54 ++++++------ src/bin/scheduler/setup/steps/run.rs | 84 ++++++++++++++----- .../scheduler/setup/steps/unpack_managed.rs | 8 ++ 5 files changed, 146 insertions(+), 60 deletions(-) diff --git a/src/bin/scheduler/setup/steps/api.rs b/src/bin/scheduler/setup/steps/api.rs index c58e3b11..eb0892ab 100644 --- a/src/bin/scheduler/setup/steps/api.rs +++ b/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, Vec); -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) -> 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::>() + .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(), diff --git a/src/bin/scheduler/setup/steps/directories.rs b/src/bin/scheduler/setup/steps/directories.rs index 35ca5f7f..7f97b5a9 100644 --- a/src/bin/scheduler/setup/steps/directories.rs +++ b/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(), diff --git a/src/bin/scheduler/setup/steps/rcc.rs b/src/bin/scheduler/setup/steps/rcc.rs index 893680ad..4ad2d887 100644 --- a/src/bin/scheduler/setup/steps/rcc.rs +++ b/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,6 +30,15 @@ struct StepFilePermissions { #[cfg(windows)] impl SetupStep for StepFilePermissions { + fn label(&self) -> String { + format!( + "Grant SID {sid} permissions `{permissions}` for {target}", + sid = self.sid, + permissions = &self.icacls_permissions, + target = &self.target, + ) + } + fn setup(&self) -> Result<(), api::Error> { run_icacls_command([ self.target.as_str(), @@ -81,6 +90,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, @@ -100,7 +117,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 @@ -114,14 +130,12 @@ 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"), @@ -129,16 +143,8 @@ impl SetupStep for StepRCCCommand { } }; 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!( @@ -171,6 +177,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, @@ -179,7 +189,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()), @@ -193,13 +202,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.", @@ -218,13 +221,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 `{}`", diff --git a/src/bin/scheduler/setup/steps/run.rs b/src/bin/scheduler/setup/steps/run.rs index 6bba1997..0c7539b2 100644 --- a/src/bin/scheduler/setup/steps/run.rs +++ b/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, ) -> Result<(Vec, Vec), 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) -> Vec; #[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"), ]; diff --git a/src/bin/scheduler/setup/steps/unpack_managed.rs b/src/bin/scheduler/setup/steps/unpack_managed.rs index 4a1a4c77..838b2056 100644 --- a/src/bin/scheduler/setup/steps/unpack_managed.rs +++ b/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))