fix: make logger work while loading config file (#581)

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
 }

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 tracing::{debug, error};
-use super::utils::{editor, hostname};
 
 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::<Self>(&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::<Self>(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<String> {
         &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()) {

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")
     }
 }

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()
-}

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<PathBuf> {
 
     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<Handle<EnvFilter, Registry>> {
+    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<EnvFilter, Registry>, 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()
+}