From 4461d1ea3f494778f07041164f6b8a252bd26ea2 Mon Sep 17 00:00:00 2001 From: notgne2 Date: Sun, 27 Dec 2020 10:48:18 -0700 Subject: Replace logger, add more logging options including files --- Cargo.lock | 108 +++++++++++++++++++++++++++++++++------------------- Cargo.toml | 2 +- src/activate.rs | 16 ++++---- src/main.rs | 25 ++++++++---- src/utils/deploy.rs | 20 +++++++++- src/utils/mod.rs | 95 +++++++++++++++++++++++++++++++++++++++++++-- 6 files changed, 206 insertions(+), 60 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index edf39a8..b2ec71c 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -65,6 +65,19 @@ version = "1.0.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "baf1de4339761588bc0619e3cbc0120ee582ebb74b53b4efbf79117bd2da40fd" +[[package]] +name = "chrono" +version = "0.4.19" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "670ad68c9088c2a963aaa298cb369688cf3f9465ce5e2d4ca10e6e0098a1ce73" +dependencies = [ + "libc", + "num-integer", + "num-traits", + "time", + "winapi 0.3.9", +] + [[package]] name = "clap" version = "3.0.0-beta.2" @@ -123,12 +136,12 @@ name = "deploy-rs" version = "0.1.0" dependencies = [ "clap", + "flexi_logger", "fork", "futures-util", "log", "merge", "notify", - "pretty_env_logger", "rnix", "serde", "serde_derive", @@ -141,19 +154,6 @@ dependencies = [ "yn", ] -[[package]] -name = "env_logger" -version = "0.7.1" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "44533bbbb3bb3c1fa17d9f2e4e38bbbaf8396ba82193c4cb1b6445d711445d36" -dependencies = [ - "atty", - "humantime", - "log", - "regex", - "termcolor", -] - [[package]] name = "filetime" version = "0.2.13" @@ -166,6 +166,22 @@ dependencies = [ "winapi 0.3.9", ] +[[package]] +name = "flexi_logger" +version = "0.16.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "c37586928c27a25ff5fce49ff3f8e071b3beeef48b4f004fe7d40d75a26e3db5" +dependencies = [ + "atty", + "chrono", + "glob", + "lazy_static", + "log", + "regex", + "thiserror", + "yansi", +] + [[package]] name = "fork" version = "0.1.18" @@ -253,6 +269,12 @@ dependencies = [ "slab", ] +[[package]] +name = "glob" +version = "0.3.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "9b919933a397b79c37e33b77bb2aa3dc8eb6e165ad809e58ff75bc7db2e34574" + [[package]] name = "hashbrown" version = "0.9.1" @@ -277,15 +299,6 @@ dependencies = [ "libc", ] -[[package]] -name = "humantime" -version = "1.3.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "df004cfca50ef23c36850aaaa59ad52cc70d0e90243c3c7737a4dd32dc7a3c4f" -dependencies = [ - "quick-error", -] - [[package]] name = "indexmap" version = "1.6.0" @@ -526,6 +539,16 @@ dependencies = [ "winapi 0.3.9", ] +[[package]] +name = "num-integer" +version = "0.1.44" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d2cc698a63b549a70bc047073d2949cce27cd1c7b0a4a862d08a8031bc2801db" +dependencies = [ + "autocfg", + "num-traits", +] + [[package]] name = "num-traits" version = "0.2.14" @@ -614,16 +637,6 @@ version = "0.1.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "8b870d8c151b6f2fb93e84a13146138f05d02ed11c7e7c54f8826aaaf7c9f184" -[[package]] -name = "pretty_env_logger" -version = "0.4.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "926d36b9553851b8b0005f1275891b392ee4d2d833852c417ed025477350fb9d" -dependencies = [ - "env_logger", - "log", -] - [[package]] name = "proc-macro-error" version = "1.0.4" @@ -669,12 +682,6 @@ dependencies = [ "unicode-xid", ] -[[package]] -name = "quick-error" -version = "1.2.3" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "a1d01941d82fa2ab50be1e79e6714289dd7cde78eba4c074bc5a4374f650dfe0" - [[package]] name = "quote" version = "1.0.7" @@ -900,6 +907,17 @@ dependencies = [ "lazy_static", ] +[[package]] +name = "time" +version = "0.1.44" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "6db9e6914ab8b1ae1c260a4ae7a49b6c5611b40328a735b21862567685e73255" +dependencies = [ + "libc", + "wasi", + "winapi 0.3.9", +] + [[package]] name = "tokio" version = "0.3.5" @@ -983,6 +1001,12 @@ dependencies = [ "winapi-util", ] +[[package]] +name = "wasi" +version = "0.10.0+wasi-snapshot-preview1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "1a143597ca7c7793eff794def352d41792a93c481eb1042423ff7ff72ba2c31f" + [[package]] name = "whoami" version = "0.9.0" @@ -1042,6 +1066,12 @@ dependencies = [ "winapi-build", ] +[[package]] +name = "yansi" +version = "0.5.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "9fc79f4a1e39857fc00c3f662cbf2651c771f00e9c15fe2abc341806bd46bd71" + [[package]] name = "yn" version = "0.1.1" diff --git a/Cargo.toml b/Cargo.toml index 335dcc8..f276453 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -19,7 +19,7 @@ serde = "1.0.104" merge = "0.1.0" whoami = "0.9.0" log = "0.4" -pretty_env_logger = "0.4" +flexi_logger = "0.16" notify = "5.0.0-pre.3" futures-util = "0.3.6" fork = "0.1" diff --git a/src/activate.rs b/src/activate.rs index 84d4b12..b982d72 100644 --- a/src/activate.rs +++ b/src/activate.rs @@ -18,7 +18,6 @@ use notify::{RecommendedWatcher, RecursiveMode, Watcher}; use thiserror::Error; -extern crate pretty_env_logger; #[macro_use] extern crate log; @@ -35,6 +34,13 @@ struct Opts { profile_path: String, closure: String, + /// Print debug logs to output + #[clap(short, long)] + debug_logs: bool, + /// File to print logs to (including the background activation process) + #[clap(long)] + log_dir: Option, + /// Temp path for any temporary files that may be needed during activation #[clap(long)] temp_path: String, @@ -347,14 +353,10 @@ pub async fn activate( #[tokio::main] async fn main() -> Result<(), Box> { - if std::env::var("DEPLOY_LOG").is_err() { - std::env::set_var("DEPLOY_LOG", "info"); - } - - pretty_env_logger::init_custom_env("DEPLOY_LOG"); - let opts: Opts = Opts::parse(); + utils::init_logger(opts.debug_logs, opts.log_dir.as_deref(), true)?; + match activate( opts.profile_path, opts.closure, diff --git a/src/main.rs b/src/main.rs index be7ad40..c003da7 100644 --- a/src/main.rs +++ b/src/main.rs @@ -12,8 +12,6 @@ use tokio::process::Command; use thiserror::Error; -extern crate pretty_env_logger; - #[macro_use] extern crate log; @@ -39,6 +37,13 @@ struct Opts { /// Extra arguments to be passed to nix build extra_build_args: Vec, + /// Print debug logs to output + #[clap(short, long)] + debug_logs: bool, + /// Directory to print logs to (including the background activation process) + #[clap(long)] + log_dir: Option, + /// Keep the build outputs of each built profile #[clap(short, long)] keep_result: bool, @@ -336,6 +341,8 @@ async fn run_deploy( keep_result: bool, result_path: Option<&str>, extra_build_args: &[String], + debug_logs: bool, + log_dir: Option, ) -> Result<(), RunDeployError> { let to_deploy: Vec<((&str, &utils::data::Node), (&str, &utils::data::Profile))> = match (&deploy_flake.node, &deploy_flake.profile) { @@ -432,6 +439,8 @@ async fn run_deploy( profile, profile_name, &cmd_overrides, + debug_logs, + log_dir.as_deref(), ); let deploy_defs = deploy_data.defs()?; @@ -480,19 +489,17 @@ enum RunError { GetDeploymentDataError(#[from] GetDeploymentDataError), #[error("Error parsing flake: {0}")] ParseFlakeError(#[from] utils::ParseFlakeError), + #[error("Error initiating logger: {0}")] + LoggerError(#[from] flexi_logger::FlexiLoggerError), #[error("{0}")] RunDeployError(#[from] RunDeployError), } async fn run() -> Result<(), RunError> { - if std::env::var("DEPLOY_LOG").is_err() { - std::env::set_var("DEPLOY_LOG", "info"); - } - - pretty_env_logger::init_custom_env("DEPLOY_LOG"); - let opts: Opts = Opts::parse(); + utils::init_logger(opts.debug_logs, opts.log_dir.as_deref(), false)?; + let deploy_flake = utils::parse_flake(opts.flake.as_str())?; let cmd_overrides = utils::CmdOverrides { @@ -534,6 +541,8 @@ async fn run() -> Result<(), RunError> { opts.keep_result, result_path, &opts.extra_build_args, + opts.debug_logs, + opts.log_dir, ) .await?; diff --git a/src/utils/deploy.rs b/src/utils/deploy.rs index 14a44a0..3aced6c 100644 --- a/src/utils/deploy.rs +++ b/src/utils/deploy.rs @@ -16,6 +16,8 @@ fn build_activate_command( temp_path: &Cow, confirm_timeout: u16, magic_rollback: bool, + debug_logs: bool, + log_dir: Option<&str>, ) -> String { let mut self_activate_command = format!( "{}/activate-rs '{}' '{}' --temp-path {} --confirm-timeout {}", @@ -30,6 +32,14 @@ fn build_activate_command( self_activate_command = format!("{} --auto-rollback", self_activate_command); } + if debug_logs { + self_activate_command = format!("{} --debug-logs", self_activate_command); + } + + if let Some(log_dir) = log_dir { + self_activate_command = format!("{} --log-file {}", self_activate_command, log_dir); + } + if let Some(sudo_cmd) = &sudo { self_activate_command = format!("{} {}", sudo_cmd, self_activate_command); } @@ -47,6 +57,8 @@ fn test_activation_command_builder() { let temp_path = &"/tmp".into(); let confirm_timeout = 30; let magic_rollback = true; + let debug_logs = true; + let log_dir = Some("/tmp/something.txt"); assert_eq!( build_activate_command( @@ -56,9 +68,11 @@ fn test_activation_command_builder() { auto_rollback, temp_path, confirm_timeout, - magic_rollback + magic_rollback, + debug_logs, + log_dir ), - "sudo -u test /nix/store/blah/etc/activate-rs '/blah/profiles/test' '/nix/store/blah/etc' --temp-path /tmp --confirm-timeout 30 --magic-rollback --auto-rollback" + "sudo -u test /nix/store/blah/etc/activate-rs '/blah/profiles/test' '/nix/store/blah/etc' --temp-path /tmp --confirm-timeout 30 --magic-rollback --auto-rollback --debug-logs --log-file /tmp/something.txt" .to_string(), ); } @@ -107,6 +121,8 @@ pub async fn deploy_profile( &temp_path, confirm_timeout, magic_rollback, + deploy_data.debug_logs, + deploy_data.log_dir, ); debug!("Constructed activation command: {}", self_activate_command); diff --git a/src/utils/mod.rs b/src/utils/mod.rs index 5770f98..42c81f7 100644 --- a/src/utils/mod.rs +++ b/src/utils/mod.rs @@ -3,14 +3,14 @@ // // SPDX-License-Identifier: MPL-2.0 -use rnix::{types::*, NodeOrToken, SyntaxKind::*, SyntaxNode}; - -use std::path::PathBuf; +use rnix::{types::*, SyntaxKind::*}; use merge::Merge; use thiserror::Error; +use flexi_logger::*; + #[macro_export] macro_rules! good_panic { ($($tts:tt)*) => {{ @@ -19,6 +19,87 @@ macro_rules! good_panic { }} } +pub fn logger_formatter_activate( + w: &mut dyn std::io::Write, + _now: &mut DeferredNow, + record: &Record, +) -> Result<(), std::io::Error> { + let level = record.level(); + + write!( + w, + "⭐ REMOTE ⭐ {0} {1} {0} {2}", + match level { + log::Level::Error => "❌", + log::Level::Warn => "⚠️", + log::Level::Info => "ℹ️", + log::Level::Debug => "❓", + log::Level::Trace => "🖊️", + }, + style(level, level.to_string()), + record.args() + ) +} + +pub fn logger_formatter_deploy( + w: &mut dyn std::io::Write, + _now: &mut DeferredNow, + record: &Record, +) -> Result<(), std::io::Error> { + let level = record.level(); + + write!( + w, + "🚀 {0} {1} {0} {2}", + match level { + log::Level::Error => "❌", + log::Level::Warn => "⚠️", + log::Level::Info => "ℹ️", + log::Level::Debug => "❓", + log::Level::Trace => "🖊️", + }, + style(level, level.to_string()), + record.args() + ) +} + +pub fn init_logger( + debug_logs: bool, + log_dir: Option<&str>, + activate: bool, +) -> Result<(), FlexiLoggerError> { + let logger_formatter = match activate { + true => logger_formatter_activate, + false => logger_formatter_deploy, + }; + + if let Some(log_dir) = log_dir { + Logger::with_env_or_str("debug") + .log_to_file() + .format_for_stderr(logger_formatter) + .set_palette("196;208;51;7;8".to_string()) + .directory(log_dir) + .discriminant(if activate { "activate" } else { "deploy" }) + .duplicate_to_stderr(match debug_logs { + true => Duplicate::Debug, + false => Duplicate::Info, + }) + .print_message() + .start()?; + } else { + Logger::with_env_or_str(match debug_logs { + true => "debug", + false => "info", + }) + .log_target(LogTarget::StdErr) + .format(logger_formatter_deploy) + .set_palette("196;208;51;7;8".to_string()) + .start()?; + } + + Ok(()) +} + pub mod data; pub mod deploy; pub mod push; @@ -191,6 +272,9 @@ pub struct DeployData<'a> { pub cmd_overrides: &'a CmdOverrides, pub merged_settings: data::GenericSettings, + + pub debug_logs: bool, + pub log_dir: Option<&'a str>, } #[derive(Debug)] @@ -259,6 +343,8 @@ pub fn make_deploy_data<'a, 's>( profile: &'a data::Profile, profile_name: &'a str, cmd_overrides: &'a CmdOverrides, + debug_logs: bool, + log_dir: Option<&'a str>, ) -> DeployData<'a> { let mut merged_settings = top_settings.clone(); merged_settings.merge(node.generic_settings.clone()); @@ -292,6 +378,9 @@ pub fn make_deploy_data<'a, 's>( cmd_overrides, merged_settings, + + debug_logs, + log_dir, } } -- cgit v1.2.3 From bbc2a2d984fc5ce3da0cbb74c4482f3953fb734e Mon Sep 17 00:00:00 2001 From: notgne2 Date: Sun, 27 Dec 2020 10:58:20 -0700 Subject: Use error log macro more in activate.rs --- src/activate.rs | 10 +++------- 1 file changed, 3 insertions(+), 7 deletions(-) diff --git a/src/activate.rs b/src/activate.rs index b982d72..f64e069 100644 --- a/src/activate.rs +++ b/src/activate.rs @@ -225,11 +225,7 @@ pub async fn activation_confirmation( Err(e) => deleted.blocking_send(Err(e)), }; if let Err(e) = send_result { - // We can't communicate our error, but panic-ing would - // be bad; let's write an error and trust that the - // activate function will realize we aren't sending - // data. - eprintln!("Could not send file system event to watcher: {}", e); + error!("Could not send file system event to watcher: {}", e); } })?; watcher.watch(lock_path, RecursiveMode::Recursive)?; @@ -243,10 +239,10 @@ pub async fn activation_confirmation( rt.block_on(async move { if let Err(err) = danger_zone(done, confirm_timeout).await { if let Err(err) = deactivate(&profile_path).await { - good_panic!("Error de-activating due to another error in confirmation thread, oh no...: {}", err); + error!("Error de-activating due to another error in confirmation thread, oh no...: {}", err); } - good_panic!("Error in confirmation thread: {}", err); + error!("Error in confirmation thread: {}", err); } }); }) -- cgit v1.2.3 From 72b04b0ae84f68a3314de32da87381097a54fbe5 Mon Sep 17 00:00:00 2001 From: notgne2 Date: Sun, 27 Dec 2020 10:59:32 -0700 Subject: Fix log dir/file mismatch --- src/activate.rs | 2 +- src/utils/deploy.rs | 4 ++-- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/src/activate.rs b/src/activate.rs index f64e069..9c23068 100644 --- a/src/activate.rs +++ b/src/activate.rs @@ -37,7 +37,7 @@ struct Opts { /// Print debug logs to output #[clap(short, long)] debug_logs: bool, - /// File to print logs to (including the background activation process) + /// Directory to print logs to (including the background activation process) #[clap(long)] log_dir: Option, diff --git a/src/utils/deploy.rs b/src/utils/deploy.rs index 3aced6c..93cebee 100644 --- a/src/utils/deploy.rs +++ b/src/utils/deploy.rs @@ -37,7 +37,7 @@ fn build_activate_command( } if let Some(log_dir) = log_dir { - self_activate_command = format!("{} --log-file {}", self_activate_command, log_dir); + self_activate_command = format!("{} --log-dir {}", self_activate_command, log_dir); } if let Some(sudo_cmd) = &sudo { @@ -72,7 +72,7 @@ fn test_activation_command_builder() { debug_logs, log_dir ), - "sudo -u test /nix/store/blah/etc/activate-rs '/blah/profiles/test' '/nix/store/blah/etc' --temp-path /tmp --confirm-timeout 30 --magic-rollback --auto-rollback --debug-logs --log-file /tmp/something.txt" + "sudo -u test /nix/store/blah/etc/activate-rs '/blah/profiles/test' '/nix/store/blah/etc' --temp-path /tmp --confirm-timeout 30 --magic-rollback --auto-rollback --debug-logs --log-dir /tmp/something.txt" .to_string(), ); } -- cgit v1.2.3 From 01ea759cf653750694201522a1b7e0d86f89a177 Mon Sep 17 00:00:00 2001 From: notgne2 Date: Sun, 27 Dec 2020 11:05:37 -0700 Subject: Deduplicate level to emoji pattern into make_emoji() --- src/utils/mod.rs | 26 ++++++++++++-------------- 1 file changed, 12 insertions(+), 14 deletions(-) diff --git a/src/utils/mod.rs b/src/utils/mod.rs index 42c81f7..00277c8 100644 --- a/src/utils/mod.rs +++ b/src/utils/mod.rs @@ -19,6 +19,16 @@ macro_rules! good_panic { }} } +fn make_emoji(level: log::Level) -> &'static str { + match level { + log::Level::Error => "❌", + log::Level::Warn => "⚠️", + log::Level::Info => "ℹ️", + log::Level::Debug => "❓", + log::Level::Trace => "🖊️", + } +} + pub fn logger_formatter_activate( w: &mut dyn std::io::Write, _now: &mut DeferredNow, @@ -29,13 +39,7 @@ pub fn logger_formatter_activate( write!( w, "⭐ REMOTE ⭐ {0} {1} {0} {2}", - match level { - log::Level::Error => "❌", - log::Level::Warn => "⚠️", - log::Level::Info => "ℹ️", - log::Level::Debug => "❓", - log::Level::Trace => "🖊️", - }, + make_emoji(level), style(level, level.to_string()), record.args() ) @@ -51,13 +55,7 @@ pub fn logger_formatter_deploy( write!( w, "🚀 {0} {1} {0} {2}", - match level { - log::Level::Error => "❌", - log::Level::Warn => "⚠️", - log::Level::Info => "ℹ️", - log::Level::Debug => "❓", - log::Level::Trace => "🖊️", - }, + make_emoji(level), style(level, level.to_string()), record.args() ) -- cgit v1.2.3 From 48548d1b1564861a63603814d62bb008e4e3edae Mon Sep 17 00:00:00 2001 From: notgne2 Date: Sun, 27 Dec 2020 11:33:55 -0700 Subject: Remove discriminant (they are already differenciated by binary name) --- src/utils/mod.rs | 1 - 1 file changed, 1 deletion(-) diff --git a/src/utils/mod.rs b/src/utils/mod.rs index 00277c8..9557aab 100644 --- a/src/utils/mod.rs +++ b/src/utils/mod.rs @@ -77,7 +77,6 @@ pub fn init_logger( .format_for_stderr(logger_formatter) .set_palette("196;208;51;7;8".to_string()) .directory(log_dir) - .discriminant(if activate { "activate" } else { "deploy" }) .duplicate_to_stderr(match debug_logs { true => Duplicate::Debug, false => Duplicate::Info, -- cgit v1.2.3 From 40d71ccdd715c6008de1a0bb97ed11282a8fe61c Mon Sep 17 00:00:00 2001 From: notgne2 Date: Sun, 27 Dec 2020 13:04:54 -0700 Subject: Make printed deployment information be info level instead of warn --- src/main.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/main.rs b/src/main.rs index c003da7..6783c40 100644 --- a/src/main.rs +++ b/src/main.rs @@ -247,7 +247,7 @@ fn print_deployment( let toml = toml::to_string(&part_map)?; - warn!("The following profiles are going to be deployed:\n{}", toml); + info!("The following profiles are going to be deployed:\n{}", toml); Ok(()) } -- cgit v1.2.3 From b6a6abe104d348ba696054c930a3dafe0edf8d00 Mon Sep 17 00:00:00 2001 From: notgne2 Date: Wed, 30 Dec 2020 20:25:59 -0700 Subject: Modify activation logic to keep SSH connection alive for magic-rollback and avoid forking or disconnecting std{out,err} --- Cargo.lock | 15 ++++- Cargo.toml | 1 + src/activate.rs | 182 ++++++++++++++++++++++++++++++++++++++++------------ src/main.rs | 6 +- src/utils/deploy.rs | 167 +++++++++++++++++++++++++++++++++++++---------- src/utils/mod.rs | 54 +++++++++++++--- 6 files changed, 339 insertions(+), 86 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index b2ec71c..8a96a33 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -146,6 +146,7 @@ dependencies = [ "serde", "serde_derive", "serde_json", + "signal-hook", "smol_str", "thiserror", "tokio", @@ -792,11 +793,21 @@ dependencies = [ "serde", ] +[[package]] +name = "signal-hook" +version = "0.3.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "6b3799fa361789a685db59e3986fb5f6f949e478728b9913c6759f7b014d0372" +dependencies = [ + "libc", + "signal-hook-registry", +] + [[package]] name = "signal-hook-registry" -version = "1.2.2" +version = "1.3.0" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "ce32ea0c6c56d5eacaeb814fbed9960547021d3edd010ded1425f180536b20ab" +checksum = "16f1d0fef1604ba8f7a073c7e701f213e056707210e9020af4528e0101ce11a6" dependencies = [ "libc", ] diff --git a/Cargo.toml b/Cargo.toml index f276453..b48eea3 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -27,6 +27,7 @@ thiserror = "1.0" toml = "0.5" yn = "0.1" rnix = "0.8" +signal-hook = "0.3" # smol_str is required by rnix, but 0.1.17 doesn't build on rustc # 1.45.2 (shipped in nixos-20.09); it requires rustc 1.46.0. See diff --git a/src/activate.rs b/src/activate.rs index 9c23068..49d16af 100644 --- a/src/activate.rs +++ b/src/activate.rs @@ -3,6 +3,8 @@ // // SPDX-License-Identifier: MPL-2.0 +use signal_hook::{consts::signal::SIGHUP, iterator::Signals}; + use clap::Clap; use tokio::fs; @@ -27,24 +29,39 @@ extern crate serde_derive; #[macro_use] mod utils; -/// Activation portion of the simple Rust Nix deploy tool +/// Remote activation utility for deploy-rs #[derive(Clap, Debug)] #[clap(version = "1.0", author = "Serokell ")] struct Opts { - profile_path: String, - closure: String, - /// Print debug logs to output #[clap(short, long)] debug_logs: bool, - /// Directory to print logs to (including the background activation process) + /// Directory to print logs to #[clap(long)] log_dir: Option, - /// Temp path for any temporary files that may be needed during activation + /// Path for any temporary files that may be needed during activation #[clap(long)] temp_path: String, + #[clap(subcommand)] + subcmd: SubCommand, +} + +#[derive(Clap, Debug)] +enum SubCommand { + Activate(ActivateOpts), + Wait(WaitOpts), +} + +/// Activate a profile +#[derive(Clap, Debug)] +struct ActivateOpts { + /// The closure to activate + closure: String, + /// The profile path to install into + profile_path: String, + /// Maximum time to wait for confirmation after activation #[clap(long)] confirm_timeout: u16, @@ -58,6 +75,13 @@ struct Opts { auto_rollback: bool, } +/// Activate a profile +#[derive(Clap, Debug)] +struct WaitOpts { + /// The closure to wait for + closure: String, +} + #[derive(Error, Debug)] pub enum DeactivateError { #[error("Failed to execute the rollback command: {0}")] @@ -201,8 +225,9 @@ pub async fn activation_confirmation( confirm_timeout: u16, closure: String, ) -> Result<(), ActivationConfirmationError> { - let lock_hash = &closure["/nix/store/".len()..]; - let lock_path = format!("{}/deploy-rs-canary-{}", temp_path, lock_hash); + let lock_path = utils::make_lock_path(&temp_path, &closure); + + debug!("Ensuring parent directory exists for canary file"); if let Some(parent) = Path::new(&lock_path).parent() { fs::create_dir_all(parent) @@ -210,49 +235,98 @@ pub async fn activation_confirmation( .map_err(ActivationConfirmationError::CreateConfirmDirError)?; } + debug!("Creating canary file"); + fs::File::create(&lock_path) .await - .map_err(ActivationConfirmationError::CreateConfirmDirError)?; + .map_err(ActivationConfirmationError::CreateConfirmFileError)?; + + debug!("Creating notify watcher"); let (deleted, done) = mpsc::channel(1); + let mut watcher: RecommendedWatcher = Watcher::new_immediate(move |res: Result| { let send_result = match res { Ok(e) if e.kind == notify::EventKind::Remove(notify::event::RemoveKind::File) => { - deleted.blocking_send(Ok(())) + debug!("Got worthy removal event, sending on channel"); + deleted.try_send(Ok(())) + } + Err(e) => { + debug!("Got error waiting for removal event, sending on channel"); + deleted.try_send(Err(e)) } Ok(_) => Ok(()), // ignore non-removal events - Err(e) => deleted.blocking_send(Err(e)), }; + if let Err(e) = send_result { error!("Could not send file system event to watcher: {}", e); } })?; - watcher.watch(lock_path, RecursiveMode::Recursive)?; - if let fork::Fork::Child = - fork::daemon(false, false).map_err(ActivationConfirmationError::ForkError)? - { - std::thread::spawn(move || { - let rt = tokio::runtime::Runtime::new().unwrap(); + watcher.watch(&lock_path, RecursiveMode::NonRecursive)?; + + if let Err(err) = danger_zone(done, confirm_timeout).await { + error!("Error waiting for confirmation event: {}", err); - rt.block_on(async move { - if let Err(err) = danger_zone(done, confirm_timeout).await { - if let Err(err) = deactivate(&profile_path).await { - error!("Error de-activating due to another error in confirmation thread, oh no...: {}", err); - } + if let Err(err) = deactivate(&profile_path).await { + error!( + "Error de-activating due to another error waiting for confirmation, oh no...: {}", + err + ); + } + } + + Ok(()) +} - error!("Error in confirmation thread: {}", err); +#[derive(Error, Debug)] +pub enum WaitError { + #[error("Error creating watcher for activation: {0}")] + Watcher(#[from] notify::Error), + #[error("Error waiting for activation: {0}")] + Waiting(#[from] DangerZoneError), +} +pub async fn wait(temp_path: String, closure: String) -> Result<(), WaitError> { + let lock_path = utils::make_lock_path(&temp_path, &closure); + + let (created, done) = mpsc::channel(1); + + let mut watcher: RecommendedWatcher = { + // TODO: fix wasteful clone + let lock_path = lock_path.clone(); + + Watcher::new_immediate(move |res: Result| { + let send_result = match res { + Ok(e) if e.kind == notify::EventKind::Create(notify::event::CreateKind::File) => { + match &e.paths[..] { + [x] if x == Path::new(&lock_path) => created.try_send(Ok(())), + _ => Ok(()), } - }); - }) - .join() - .unwrap(); + } + Err(e) => created.try_send(Err(e)), + Ok(_) => Ok(()), // ignore non-removal events + }; + + if let Err(e) = send_result { + error!("Could not send file system event to watcher: {}", e); + } + })? + }; - info!("Confirmation successful!"); + watcher.watch(&temp_path, RecursiveMode::NonRecursive)?; + + // Avoid a potential race condition by checking for existence after watcher creation + if fs::metadata(&lock_path).await.is_ok() { + watcher.unwatch(&temp_path)?; + return Ok(()); } - std::process::exit(0); + danger_zone(done, 60).await?; + + info!("Found canary file, done waiting!"); + + Ok(()) } #[derive(Error, Debug)] @@ -303,6 +377,8 @@ pub async fn activate( } }; + debug!("Running activation script"); + let activate_status = match Command::new(format!("{}/deploy-rs-activate", profile_path)) .env("PROFILE", &profile_path) .current_dir(&profile_path) @@ -333,6 +409,7 @@ pub async fn activate( if magic_rollback { info!("Magic rollback is enabled, setting up confirmation hook..."); + match activation_confirmation(profile_path.clone(), temp_path, confirm_timeout, closure) .await { @@ -349,20 +426,43 @@ pub async fn activate( #[tokio::main] async fn main() -> Result<(), Box> { + // Ensure that this process stays alive after the SSH connection dies + let mut signals = Signals::new(&[SIGHUP])?; + std::thread::spawn(move || { + for sig in signals.forever() { + println!("Received NOHUP - ignoring..."); + } + }); + let opts: Opts = Opts::parse(); - utils::init_logger(opts.debug_logs, opts.log_dir.as_deref(), true)?; - - match activate( - opts.profile_path, - opts.closure, - opts.auto_rollback, - opts.temp_path, - opts.confirm_timeout, - opts.magic_rollback, - ) - .await - { + utils::init_logger( + opts.debug_logs, + opts.log_dir.as_deref(), + match opts.subcmd { + SubCommand::Activate(_) => utils::LoggerType::Activate, + SubCommand::Wait(_) => utils::LoggerType::Wait, + }, + )?; + + let r = match opts.subcmd { + SubCommand::Activate(activate_opts) => activate( + activate_opts.profile_path, + activate_opts.closure, + activate_opts.auto_rollback, + opts.temp_path, + activate_opts.confirm_timeout, + activate_opts.magic_rollback, + ) + .await + .map_err(|x| Box::new(x) as Box), + + SubCommand::Wait(wait_opts) => wait(opts.temp_path, wait_opts.closure) + .await + .map_err(|x| Box::new(x) as Box), + }; + + match r { Ok(()) => (), Err(err) => good_panic!("{}", err), } diff --git a/src/main.rs b/src/main.rs index 6783c40..1544fed 100644 --- a/src/main.rs +++ b/src/main.rs @@ -498,7 +498,11 @@ enum RunError { async fn run() -> Result<(), RunError> { let opts: Opts = Opts::parse(); - utils::init_logger(opts.debug_logs, opts.log_dir.as_deref(), false)?; + utils::init_logger( + opts.debug_logs, + opts.log_dir.as_deref(), + utils::LoggerType::Deploy, + )?; let deploy_flake = utils::parse_flake(opts.flake.as_str())?; diff --git a/src/utils/deploy.rs b/src/utils/deploy.rs index 93cebee..3371160 100644 --- a/src/utils/deploy.rs +++ b/src/utils/deploy.rs @@ -19,9 +19,24 @@ fn build_activate_command( debug_logs: bool, log_dir: Option<&str>, ) -> String { - let mut self_activate_command = format!( - "{}/activate-rs '{}' '{}' --temp-path {} --confirm-timeout {}", - closure, profile_path, closure, temp_path, confirm_timeout + let mut self_activate_command = format!("{}/activate-rs", closure); + + if debug_logs { + self_activate_command = format!("{} --debug-logs", self_activate_command); + } + + if let Some(log_dir) = log_dir { + self_activate_command = format!("{} --log-dir {}", self_activate_command, log_dir); + } + + self_activate_command = format!( + "{} --temp-path '{}' activate '{}' '{}'", + self_activate_command, temp_path, closure, profile_path + ); + + self_activate_command = format!( + "{} --confirm-timeout {}", + self_activate_command, confirm_timeout ); if magic_rollback { @@ -32,14 +47,6 @@ fn build_activate_command( self_activate_command = format!("{} --auto-rollback", self_activate_command); } - if debug_logs { - self_activate_command = format!("{} --debug-logs", self_activate_command); - } - - if let Some(log_dir) = log_dir { - self_activate_command = format!("{} --log-dir {}", self_activate_command, log_dir); - } - if let Some(sudo_cmd) = &sudo { self_activate_command = format!("{} {}", sudo_cmd, self_activate_command); } @@ -49,7 +56,6 @@ fn build_activate_command( #[test] fn test_activation_command_builder() { - let activate_path_str = "/blah/bin/activate".to_string(); let sudo = Some("sudo -u test".to_string()); let profile_path = "/blah/profiles/test"; let closure = "/nix/store/blah/etc"; @@ -72,7 +78,57 @@ fn test_activation_command_builder() { debug_logs, log_dir ), - "sudo -u test /nix/store/blah/etc/activate-rs '/blah/profiles/test' '/nix/store/blah/etc' --temp-path /tmp --confirm-timeout 30 --magic-rollback --auto-rollback --debug-logs --log-dir /tmp/something.txt" + "sudo -u test /nix/store/blah/etc/activate-rs --debug-logs --log-dir /tmp/something.txt --temp-path '/tmp' activate '/nix/store/blah/etc' '/blah/profiles/test' --confirm-timeout 30 --magic-rollback --auto-rollback" + .to_string(), + ); +} + +fn build_wait_command( + sudo: &Option, + closure: &str, + temp_path: &Cow, + debug_logs: bool, + log_dir: Option<&str>, +) -> String { + let mut self_activate_command = format!("{}/activate-rs", closure); + + if debug_logs { + self_activate_command = format!("{} --debug-logs", self_activate_command); + } + + if let Some(log_dir) = log_dir { + self_activate_command = format!("{} --log-dir {}", self_activate_command, log_dir); + } + + self_activate_command = format!( + "{} --temp-path '{}' wait '{}'", + self_activate_command, temp_path, closure + ); + + if let Some(sudo_cmd) = &sudo { + self_activate_command = format!("{} {}", sudo_cmd, self_activate_command); + } + + self_activate_command +} + +#[test] +fn test_wait_command_builder() { + let sudo = Some("sudo -u test".to_string()); + let closure = "/nix/store/blah/etc"; + let temp_path = &"/tmp".into(); + let debug_logs = true; + let log_dir = Some("/tmp/something.txt"); + + assert_eq!( + build_wait_command( + &sudo, + closure, + temp_path, + debug_logs, + log_dir + ), + "sudo -u test /nix/store/blah/etc/activate-rs --debug-logs --log-dir /tmp/something.txt --temp-path '/tmp' wait '/nix/store/blah/etc'" .to_string(), ); } @@ -81,10 +137,20 @@ fn test_activation_command_builder() { pub enum DeployProfileError { #[error("Failed to calculate activate bin path from deploy bin path: {0}")] DeployPathToActivatePathError(#[from] super::DeployPathToActivatePathError), + + #[error("Failed to spawn activation command over SSH: {0}")] + SSHSpawnActivateError(std::io::Error), + #[error("Failed to run activation command over SSH: {0}")] SSHActivateError(std::io::Error), - #[error("Activation over SSH resulted in a bad exit code: {0:?}")] + #[error("Activating over SSH resulted in a bad exit code: {0:?}")] SSHActivateExitError(Option), + + #[error("Failed to run wait command over SSH: {0}")] + SSHWaitError(std::io::Error), + #[error("Waiting over SSH resulted in a bad exit code: {0:?}")] + SSHWaitExitError(Option), + #[error("Failed to run confirmation command over SSH (the server should roll back): {0}")] SSHConfirmError(std::io::Error), #[error( @@ -127,35 +193,70 @@ pub async fn deploy_profile( debug!("Constructed activation command: {}", self_activate_command); + let self_wait_command = build_wait_command( + &deploy_defs.sudo, + &deploy_data.profile.profile_settings.path, + &temp_path, + deploy_data.debug_logs, + deploy_data.log_dir, + ); + + debug!("Constructed wait command: {}", self_wait_command); + let hostname = match deploy_data.cmd_overrides.hostname { Some(ref x) => x, None => &deploy_data.node.node_settings.hostname, }; - let mut c = Command::new("ssh"); - let mut ssh_command = c - .arg("-t") - .arg(format!("ssh://{}@{}", deploy_defs.ssh_user, hostname)); + let ssh_addr = format!("ssh://{}@{}", deploy_defs.ssh_user, hostname); + + let mut ssh_activate_command_ = Command::new("ssh"); + let ssh_activate_command = ssh_activate_command_.arg(&ssh_addr); for ssh_opt in &deploy_data.merged_settings.ssh_opts { - ssh_command = ssh_command.arg(ssh_opt); + ssh_activate_command.arg(&ssh_opt); } - let ssh_exit_status = ssh_command - .arg(self_activate_command) - .status() - .await - .map_err(DeployProfileError::SSHActivateError)?; + if !magic_rollback { + let ssh_activate_exit_status = ssh_activate_command + .arg(self_activate_command) + .status() + .await + .map_err(DeployProfileError::SSHActivateError)?; - match ssh_exit_status.code() { - Some(0) => (), - a => return Err(DeployProfileError::SSHActivateExitError(a)), - }; + match ssh_activate_exit_status.code() { + Some(0) => (), + a => return Err(DeployProfileError::SSHActivateExitError(a)), + }; - info!("Success activating!"); + info!("Success activating, done!"); + } else { + let ssh_activate = ssh_activate_command + .arg(self_activate_command) + .spawn() + .map_err(DeployProfileError::SSHSpawnActivateError)?; - if magic_rollback { - info!("Attempting to confirm activation"); + info!("Creating activation waiter"); + + let mut ssh_wait_command_ = Command::new("ssh"); + let ssh_wait_command = ssh_wait_command_.arg(&ssh_addr); + + for ssh_opt in &deploy_data.merged_settings.ssh_opts { + ssh_wait_command.arg(ssh_opt); + } + + let ssh_wait_exit_status = ssh_wait_command + .arg(self_wait_command) + .status() + .await + .map_err(DeployProfileError::SSHWaitError)?; + + match ssh_wait_exit_status.code() { + Some(0) => (), + a => return Err(DeployProfileError::SSHWaitExitError(a)), + }; + + info!("Success activating, attempting to confirm activation"); let mut c = Command::new("ssh"); let mut ssh_confirm_command = c.arg(format!("ssh://{}@{}", deploy_defs.ssh_user, hostname)); @@ -164,8 +265,8 @@ pub async fn deploy_profile( ssh_confirm_command = ssh_confirm_command.arg(ssh_opt); } - let lock_hash = &deploy_data.profile.profile_settings.path["/nix/store/".len()..]; - let lock_path = format!("{}/deploy-rs-canary-{}", temp_path, lock_hash); + let lock_path = + super::make_lock_path(&temp_path, &deploy_data.profile.profile_settings.path); let mut confirm_command = format!("rm {}", lock_path); if let Some(sudo_cmd) = &deploy_defs.sudo { diff --git a/src/utils/mod.rs b/src/utils/mod.rs index 9557aab..b1aa3e6 100644 --- a/src/utils/mod.rs +++ b/src/utils/mod.rs @@ -19,6 +19,12 @@ macro_rules! good_panic { }} } +pub fn make_lock_path(temp_path: &str, closure: &str) -> String { + let lock_hash = + &closure["/nix/store/".len()..closure.find("-").unwrap_or_else(|| closure.len())]; + format!("{}/deploy-rs-canary-{}", temp_path, lock_hash) +} + fn make_emoji(level: log::Level) -> &'static str { match level { log::Level::Error => "❌", @@ -38,7 +44,23 @@ pub fn logger_formatter_activate( write!( w, - "⭐ REMOTE ⭐ {0} {1} {0} {2}", + "⭐ {0} {1} {0} {2}", + make_emoji(level), + style(level, level.to_string()), + record.args() + ) +} + +pub fn logger_formatter_wait( + w: &mut dyn std::io::Write, + _now: &mut DeferredNow, + record: &Record, +) -> Result<(), std::io::Error> { + let level = record.level(); + + write!( + w, + "👀 {0} {1} {0} {2}", make_emoji(level), style(level, level.to_string()), record.args() @@ -61,18 +83,25 @@ pub fn logger_formatter_deploy( ) } +pub enum LoggerType { + Deploy, + Activate, + Wait, +} + pub fn init_logger( debug_logs: bool, log_dir: Option<&str>, - activate: bool, + logger_type: LoggerType, ) -> Result<(), FlexiLoggerError> { - let logger_formatter = match activate { - true => logger_formatter_activate, - false => logger_formatter_deploy, + let logger_formatter = match logger_type { + LoggerType::Deploy => logger_formatter_deploy, + LoggerType::Activate => logger_formatter_activate, + LoggerType::Wait => logger_formatter_wait, }; if let Some(log_dir) = log_dir { - Logger::with_env_or_str("debug") + let mut logger = Logger::with_env_or_str("debug") .log_to_file() .format_for_stderr(logger_formatter) .set_palette("196;208;51;7;8".to_string()) @@ -81,15 +110,22 @@ pub fn init_logger( true => Duplicate::Debug, false => Duplicate::Info, }) - .print_message() - .start()?; + .print_message(); + + match logger_type { + LoggerType::Activate => logger = logger.discriminant("activate"), + LoggerType::Wait => logger = logger.discriminant("wait"), + LoggerType::Deploy => (), + } + + logger.start()?; } else { Logger::with_env_or_str(match debug_logs { true => "debug", false => "info", }) .log_target(LogTarget::StdErr) - .format(logger_formatter_deploy) + .format(logger_formatter) .set_palette("196;208;51;7;8".to_string()) .start()?; } -- cgit v1.2.3 From 12fee773d5a3a142a8cb9b57e57ff2be98346584 Mon Sep 17 00:00:00 2001 From: notgne2 Date: Fri, 1 Jan 2021 19:30:33 -0700 Subject: Format logs differently --- src/utils/mod.rs | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/src/utils/mod.rs b/src/utils/mod.rs index b1aa3e6..89b124f 100644 --- a/src/utils/mod.rs +++ b/src/utils/mod.rs @@ -44,7 +44,7 @@ pub fn logger_formatter_activate( write!( w, - "⭐ {0} {1} {0} {2}", + "⭐ {} [activate] [{}] {}", make_emoji(level), style(level, level.to_string()), record.args() @@ -60,7 +60,7 @@ pub fn logger_formatter_wait( write!( w, - "👀 {0} {1} {0} {2}", + "👀 {} [wait] [{}] {}", make_emoji(level), style(level, level.to_string()), record.args() @@ -76,7 +76,7 @@ pub fn logger_formatter_deploy( write!( w, - "🚀 {0} {1} {0} {2}", + "🚀 {} [deploy] [{}] {}", make_emoji(level), style(level, level.to_string()), record.args() -- cgit v1.2.3