From a8c29fd1a237157e7ebb948064961a33df72a7a1 Mon Sep 17 00:00:00 2001 From: SteveLauC Date: Tue, 17 Oct 2023 11:19:47 +0800 Subject: [PATCH] fix: make logger work while loading config file (#581) --- src/command.rs | 8 +++--- src/config.rs | 62 +++++++++++++++++++++++++++++++------------- src/ctrlc/windows.rs | 3 ++- src/main.rs | 54 ++++++++++++-------------------------- src/utils.rs | 54 ++++++++++++++++++++++++++++++++++++++ 5 files changed, 122 insertions(+), 59 deletions(-) diff --git a/src/command.rs b/src/command.rs index d8a87e25..5c8bb804 100644 --- a/src/command.rs +++ b/src/command.rs @@ -10,6 +10,8 @@ use color_eyre::eyre::Context; use crate::error::TopgradeError; +use tracing::debug; + /// Like [`Output`], but UTF-8 decoded. #[derive(Clone, Debug, PartialEq, Eq)] pub struct Utf8Output { @@ -183,7 +185,7 @@ impl CommandExt for Command { let err = TopgradeError::ProcessFailedWithOutput(program, output.status, stderr.into_owned()); let ret = Err(err).with_context(|| message); - tracing::debug!("Command failed: {ret:?}"); + debug!("Command failed: {ret:?}"); ret } } @@ -203,7 +205,7 @@ impl CommandExt for Command { let (program, _) = get_program_and_args(self); let err = TopgradeError::ProcessFailed(program, status); let ret = Err(err).with_context(|| format!("Command failed: `{command}`")); - tracing::debug!("Command failed: {ret:?}"); + debug!("Command failed: {ret:?}"); ret } } @@ -239,6 +241,6 @@ fn format_program_and_args(cmd: &Command) -> String { fn log(cmd: &Command) -> String { let command = format_program_and_args(cmd); - tracing::debug!("Executing command `{command}`"); + debug!("Executing command `{command}`"); command } diff --git a/src/config.rs b/src/config.rs index c8e59f3f..cc176f7b 100644 --- a/src/config.rs +++ b/src/config.rs @@ -17,17 +17,19 @@ use regex::Regex; use regex_split::RegexSplit; use serde::Deserialize; use strum::{EnumIter, EnumString, EnumVariantNames, IntoEnumIterator}; -use tracing::debug; use which_crate::which; +use super::utils::{editor, hostname}; use crate::command::CommandExt; use crate::sudo::SudoKind; use crate::utils::string_prepend_str; - -use super::utils::{editor, hostname}; +use tracing::{debug, error}; pub static EXAMPLE_CONFIG: &str = include_str!("../config.example.toml"); +/// Topgrade's default log level. +pub const DEFAULT_LOG_LEVEL: &str = "warn"; + #[allow(unused_macros)] macro_rules! str_value { ($section:ident, $value:ident) => { @@ -607,11 +609,11 @@ impl ConfigFile { */ for include in dir_include { let include_contents = fs::read_to_string(&include).map_err(|e| { - tracing::error!("Unable to read {}", include.display()); + error!("Unable to read {}", include.display()); e })?; let include_contents_parsed = toml::from_str(include_contents.as_str()).map_err(|e| { - tracing::error!("Failed to deserialize {}", include.display()); + error!("Failed to deserialize {}", include.display()); e })?; @@ -628,7 +630,7 @@ impl ConfigFile { } let mut contents_non_split = fs::read_to_string(&config_path).map_err(|e| { - tracing::error!("Unable to read {}", config_path.display()); + error!("Unable to read {}", config_path.display()); e })?; @@ -641,7 +643,7 @@ impl ConfigFile { for contents in contents_split { let config_file_include_only: ConfigFileIncludeOnly = toml::from_str(contents).map_err(|e| { - tracing::error!("Failed to deserialize an include section of {}", config_path.display()); + error!("Failed to deserialize an include section of {}", config_path.display()); e })?; @@ -654,28 +656,24 @@ impl ConfigFile { let include_contents = match fs::read_to_string(&include_path) { Ok(c) => c, Err(e) => { - tracing::error!("Unable to read {}: {}", include_path.display(), e); + error!("Unable to read {}: {}", include_path.display(), e); continue; } }; match toml::from_str::(&include_contents) { Ok(include_parsed) => result.merge(include_parsed), Err(e) => { - tracing::error!("Failed to deserialize {}: {}", include_path.display(), e); + error!("Failed to deserialize {}: {}", include_path.display(), e); continue; } }; - - debug!("Configuration include found: {}", include_path.display()); } - } else { - debug!("No include paths found in {}", config_path.display()); } } match toml::from_str::(contents) { Ok(contents) => result.merge(contents), - Err(e) => tracing::error!("Failed to deserialize {}: {}", config_path.display(), e), + Err(e) => error!("Failed to deserialize {}: {}", config_path.display(), e), } } @@ -713,8 +711,6 @@ impl ConfigFile { } } - debug!("Loaded configuration: {:?}", result); - Ok(result) } @@ -832,7 +828,7 @@ pub struct CommandLineArgs { /// Tracing filter directives. /// /// See: https://docs.rs/tracing-subscriber/latest/tracing_subscriber/struct.EnvFilter.html - #[clap(long, default_value = "warn")] + #[clap(long, default_value = DEFAULT_LOG_LEVEL)] pub log_filter: String, /// Print completion script for the given shell and exit @@ -860,6 +856,27 @@ impl CommandLineArgs { pub fn env_variables(&self) -> &Vec { &self.env } + + /// In Topgrade, filter directives come from 3 places: + /// 1. CLI option `--log-filter` + /// 2. Config file + /// 3. `debug` if the `--verbose` option is present + /// + /// Before loading the configuration file, we need our logger to work, so this + /// function will return directives coming from part 1 and 2. + /// + /// + /// When the configuration file is loaded, `Config::tracing_filter_directives()` + /// will return all the 3 parts. + pub fn tracing_filter_directives(&self) -> String { + let mut ret = self.log_filter.clone(); + if self.verbose { + ret.push(','); + ret.push_str("debug"); + } + + ret + } } /// Represents the application configuration @@ -867,6 +884,7 @@ impl CommandLineArgs { /// The struct holds the loaded configuration file, as well as the arguments parsed from the command line. /// Its provided methods decide the appropriate options based on combining the configuration file and the /// command line arguments. +#[derive(Debug)] pub struct Config { opt: CommandLineArgs, config_file: ConfigFile, @@ -883,7 +901,7 @@ impl Config { ConfigFile::read(opt.config.clone()).unwrap_or_else(|e| { // Inform the user about errors when loading the configuration, // but fallback to the default config to at least attempt to do something - tracing::error!("failed to load configuration: {}", e); + error!("failed to load configuration: {}", e); ConfigFile::default() }) } else { @@ -1442,6 +1460,14 @@ impl Config { self.opt.verbose } + /// After loading the config file, filter directives consist of 3 parts: + /// + /// 1. directives from the configuration file + /// 2. directives from the CLI options `--log-filter` + /// 3. `debug`, which would be enabled if the `--verbose` option is present + /// + /// Previous directive will be overwritten if a directive with the same target + /// appear later. pub fn tracing_filter_directives(&self) -> String { let mut ret = String::new(); if let Some(directives) = self.config_file.misc.as_ref().and_then(|m| m.log_filters.as_ref()) { diff --git a/src/ctrlc/windows.rs b/src/ctrlc/windows.rs index b2cf9e15..5519cfb0 100644 --- a/src/ctrlc/windows.rs +++ b/src/ctrlc/windows.rs @@ -1,5 +1,6 @@ //! A stub for Ctrl + C handling. use crate::ctrlc::interrupted::set_interrupted; +use tracing::error; use winapi::shared::minwindef::{BOOL, DWORD, FALSE, TRUE}; use winapi::um::consoleapi::SetConsoleCtrlHandler; use winapi::um::wincon::CTRL_C_EVENT; @@ -16,6 +17,6 @@ extern "system" fn handler(ctrl_type: DWORD) -> BOOL { pub fn set_handler() { if 0 == unsafe { SetConsoleCtrlHandler(Some(handler), TRUE) } { - tracing::error!("Cannot set a control C handler") + error!("Cannot set a control C handler") } } diff --git a/src/main.rs b/src/main.rs index 7ae916b5..c9c5f391 100644 --- a/src/main.rs +++ b/src/main.rs @@ -26,6 +26,8 @@ use self::error::Upgraded; use self::steps::{remote::*, *}; use self::terminal::*; +use self::utils::{install_color_eyre, install_tracing, update_tracing}; + mod command; mod config; mod ctrlc; @@ -53,6 +55,18 @@ fn run() -> Result<()> { ctrlc::set_handler(); let opt = CommandLineArgs::parse(); + // Set up the logger with the filter directives from: + // 1. CLI option `--log-filter` + // 2. `debug` if the `--verbose` option is present + // We do this because we need our logger to work while loading the + // configuration file. + // + // When the configuration file is loaded, update the logger with the full + // filter directives. + // + // For more info, see the comments in `CommandLineArgs::tracing_filter_directives()` + // and `Config::tracing_filter_directives()`. + let reload_handle = install_tracing(&opt.tracing_filter_directives())?; if let Some(shell) = opt.gen_completion { let cmd = &mut CommandLineArgs::command(); @@ -84,7 +98,8 @@ fn run() -> Result<()> { } let config = Config::load(opt)?; - install_tracing(&config.tracing_filter_directives())?; + // Update the logger with the full filter directives. + update_tracing(&reload_handle, &config.tracing_filter_directives())?; set_title(config.set_title()); display_time(config.display_time()); set_desktop_notifications(config.notify_each_step()); @@ -94,6 +109,7 @@ fn run() -> Result<()> { debug!("{:?}", std::env::args()); debug!("Binary path: {:?}", std::env::current_exe()); debug!("Self Update: {:?}", cfg!(feature = "self-update")); + debug!("Configuration: {:?}", config); if config.run_in_tmux() && env::var("TOPGRADE_INSIDE_TMUX").is_err() { #[cfg(unix)] @@ -565,39 +581,3 @@ fn main() { } } } - -fn install_tracing(filter_directives: &str) -> Result<()> { - use tracing_subscriber::fmt; - use tracing_subscriber::fmt::format::FmtSpan; - use tracing_subscriber::layer::SubscriberExt; - use tracing_subscriber::util::SubscriberInitExt; - use tracing_subscriber::EnvFilter; - - let env_filter = EnvFilter::try_new(filter_directives) - .or_else(|_| EnvFilter::try_from_default_env()) - .or_else(|_| EnvFilter::try_new("info"))?; - - let fmt_layer = fmt::layer() - .with_target(false) - .with_span_events(FmtSpan::NEW | FmtSpan::CLOSE) - .without_time(); - - let registry = tracing_subscriber::registry(); - - registry.with(env_filter).with(fmt_layer).init(); - - Ok(()) -} - -fn install_color_eyre() -> Result<()> { - color_eyre::config::HookBuilder::new() - // Don't display the backtrace reminder by default: - // Backtrace omitted. Run with RUST_BACKTRACE=1 environment variable to display it. - // Run with RUST_BACKTRACE=full to include source snippets. - .display_env_section(false) - // Display location information by default: - // Location: - // src/steps.rs:92 - .display_location_section(true) - .install() -} diff --git a/src/utils.rs b/src/utils.rs index ee9cc0f8..0e8e77c2 100644 --- a/src/utils.rs +++ b/src/utils.rs @@ -5,9 +5,17 @@ use std::path::{Path, PathBuf}; use std::process::Command; use color_eyre::eyre::Result; + use tracing::{debug, error}; +use tracing_subscriber::fmt::format::FmtSpan; +use tracing_subscriber::layer::SubscriberExt; +use tracing_subscriber::reload::{Handle, Layer}; +use tracing_subscriber::util::SubscriberInitExt; +use tracing_subscriber::{fmt, Registry}; +use tracing_subscriber::{registry, EnvFilter}; use crate::command::CommandExt; +use crate::config::DEFAULT_LOG_LEVEL; use crate::error::SkipStep; pub trait PathExt @@ -251,3 +259,49 @@ pub fn check_is_python_2_or_shim(python: PathBuf) -> Result { Ok(python) } + +/// Set up the tracing logger +/// +/// # Return value +/// A reload handle will be returned so that we can change the log level at +/// runtime. +pub fn install_tracing(filter_directives: &str) -> Result> { + let env_filter = EnvFilter::try_new(filter_directives) + .or_else(|_| EnvFilter::try_from_default_env()) + .or_else(|_| EnvFilter::try_new(DEFAULT_LOG_LEVEL))?; + + let fmt_layer = fmt::layer() + .with_target(false) + .with_span_events(FmtSpan::NEW | FmtSpan::CLOSE) + .without_time(); + + let (filter, reload_handle) = Layer::new(env_filter); + + registry().with(filter).with(fmt_layer).init(); + + Ok(reload_handle) +} + +/// Update the tracing logger with new `filter_directives`. +pub fn update_tracing(reload_handle: &Handle, filter_directives: &str) -> Result<()> { + let new = EnvFilter::try_new(filter_directives) + .or_else(|_| EnvFilter::try_from_default_env()) + .or_else(|_| EnvFilter::try_new(DEFAULT_LOG_LEVEL))?; + reload_handle.modify(|old| *old = new)?; + + Ok(()) +} + +/// Set up the error handler crate +pub fn install_color_eyre() -> Result<()> { + color_eyre::config::HookBuilder::new() + // Don't display the backtrace reminder by default: + // Backtrace omitted. Run with RUST_BACKTRACE=1 environment variable to display it. + // Run with RUST_BACKTRACE=full to include source snippets. + .display_env_section(false) + // Display location information by default: + // Location: + // src/steps.rs:92 + .display_location_section(true) + .install() +}