From 5657a135f1436ef6bd34e954895af96cbbb2ddeb Mon Sep 17 00:00:00 2001 From: Marcel Guzik Date: Thu, 24 Oct 2024 16:42:45 +0200 Subject: [PATCH 1/3] Make --debug flag override RUST_LOG Flags should always take precedence over environment variables because are often used by users to override the environment which they usually have little control over. To implement this change it was necessary to refactor the code a little bit as previously set_log_level function was not aware if desired log level was specifically requested by the user (--debug flag) or just the default (INFO level). As such, the new log_init function takes into account all sources that decide what log level we should select: CLI options, RUST_LOG env variable, and tedge configuration file. Signed-off-by: Marcel Guzik --- Cargo.lock | 1 + crates/common/tedge_config/Cargo.toml | 1 + .../src/system_services/log_config.rs | 46 +++++++++++++++++++ crates/core/tedge_agent/src/lib.rs | 26 ++++------- crates/core/tedge_mapper/src/lib.rs | 26 ++++------- crates/core/tedge_watchdog/src/lib.rs | 23 +++------- plugins/c8y_firmware_plugin/src/lib.rs | 23 ++++------ 7 files changed, 82 insertions(+), 64 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index f0280882af9..bead0138642 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -3945,6 +3945,7 @@ dependencies = [ "assert_matches", "camino", "certificate", + "clap", "doku", "figment", "humantime", diff --git a/crates/common/tedge_config/Cargo.toml b/crates/common/tedge_config/Cargo.toml index 71d7f3eb8cb..7072f804cdb 100644 --- a/crates/common/tedge_config/Cargo.toml +++ b/crates/common/tedge_config/Cargo.toml @@ -16,6 +16,7 @@ test = [] anyhow = { workspace = true } camino = { workspace = true, features = ["serde", "serde1"] } certificate = { workspace = true, features = ["reqwest"] } +clap = { workspace = true } doku = { workspace = true } figment = { workspace = true, features = ["env", "toml"] } humantime = { workspace = true } diff --git a/crates/common/tedge_config/src/system_services/log_config.rs b/crates/common/tedge_config/src/system_services/log_config.rs index f93b59307f4..c9e8e331289 100644 --- a/crates/common/tedge_config/src/system_services/log_config.rs +++ b/crates/common/tedge_config/src/system_services/log_config.rs @@ -1,10 +1,56 @@ use camino::Utf8Path; +use clap::Args; use crate::system_services::SystemConfig; use crate::system_services::SystemServiceError; use std::io::IsTerminal; use std::str::FromStr; +#[derive(Args, Debug, PartialEq, Eq, Clone)] +pub struct LogConfigArgs { + /// Turn-on the DEBUG log level. + /// + /// If off only reports ERROR, WARN, and INFO, if on also reports DEBUG + #[clap(long, global = true)] + pub debug: bool, +} + +/// Configures and enables logging taking into account flags, env variables and file config. +/// +/// 1. Log config is taken from the file configuration first +/// 2. If `RUST_LOG` variable is set, it overrides file-based configuration +/// 3. If `--debug` or `--log-level` flags are set, they override previous steps +/// +/// Reports all the log events sent either with the `log` crate or the `tracing` +/// crate. +pub fn log_init( + sname: &str, + flags: &LogConfigArgs, + config_dir: &Utf8Path, +) -> Result<(), SystemServiceError> { + let subscriber = tracing_subscriber::fmt() + .with_writer(std::io::stderr) + .with_ansi(std::io::stderr().is_terminal()) + .with_timer(tracing_subscriber::fmt::time::UtcTime::rfc_3339()); + + if flags.debug { + subscriber.with_max_level(tracing::Level::DEBUG).init(); + return Ok(()); + } + + if std::env::var("RUST_LOG").is_ok() { + subscriber + .with_env_filter(tracing_subscriber::EnvFilter::from_default_env()) + .init(); + return Ok(()); + } + + let log_level = get_log_level(sname, config_dir)?; + subscriber.with_max_level(log_level).init(); + + Ok(()) +} + pub fn get_log_level( sname: &str, config_dir: &Utf8Path, diff --git a/crates/core/tedge_agent/src/lib.rs b/crates/core/tedge_agent/src/lib.rs index f14e2643670..5c83a90d5e5 100644 --- a/crates/core/tedge_agent/src/lib.rs +++ b/crates/core/tedge_agent/src/lib.rs @@ -16,8 +16,8 @@ use std::sync::Arc; use agent::AgentConfig; use camino::Utf8PathBuf; use tedge_config::get_config_dir; -use tedge_config::system_services::get_log_level; -use tedge_config::system_services::set_log_level; +use tedge_config::system_services::log_init; +use tedge_config::system_services::LogConfigArgs; use tracing::log::warn; mod agent; @@ -37,12 +37,8 @@ version = clap::crate_version!(), about = clap::crate_description!() )] pub struct AgentOpt { - /// Turn-on the debug log level. - /// - /// If off only reports ERROR, WARN, and INFO - /// If on also reports DEBUG - #[clap(long)] - pub debug: bool, + #[command(flatten)] + pub log_args: LogConfigArgs, /// Start the agent with clean session off, subscribe to the topics, so that no messages are lost #[clap(short, long)] @@ -72,15 +68,11 @@ pub async fn run(agent_opt: AgentOpt) -> Result<(), anyhow::Error> { let tedge_config_location = tedge_config::TEdgeConfigLocation::from_custom_root(agent_opt.config_dir.clone()); - // If `debug` is `false` then only `error!`, `warn!` and `info!` are reported. - // If `debug` is `true` then also `debug!` is reported. - let log_level = if agent_opt.debug { - tracing::Level::DEBUG - } else { - get_log_level("tedge-agent", &tedge_config_location.tedge_config_root_path)? - }; - - set_log_level(log_level); + log_init( + "tedge-agent", + &agent_opt.log_args, + &tedge_config_location.tedge_config_root_path, + )?; let init = agent_opt.init; diff --git a/crates/core/tedge_mapper/src/lib.rs b/crates/core/tedge_mapper/src/lib.rs index c2b9eb4a674..55e74b78035 100644 --- a/crates/core/tedge_mapper/src/lib.rs +++ b/crates/core/tedge_mapper/src/lib.rs @@ -8,8 +8,8 @@ use clap::Parser; use flockfile::check_another_instance_is_not_running; use std::fmt; use tedge_config::get_config_dir; -use tedge_config::system_services::get_log_level; -use tedge_config::system_services::set_log_level; +use tedge_config::system_services::log_init; +use tedge_config::system_services::LogConfigArgs; use tedge_config::PathBuf; use tedge_config::ProfileName; use tracing::log::warn; @@ -64,12 +64,8 @@ pub struct MapperOpt { #[clap(subcommand)] pub name: MapperName, - /// Turn-on the debug log level. - /// - /// If off only reports ERROR, WARN, and INFO - /// If on also reports DEBUG - #[clap(long, global = true)] - pub debug: bool, + #[command(flatten)] + pub log_args: LogConfigArgs, /// Start the mapper with clean session off, subscribe to the topics, so that no messages are lost #[clap(short, long)] @@ -122,15 +118,11 @@ pub async fn run(mapper_opt: MapperOpt) -> anyhow::Result<()> { tedge_config::TEdgeConfigLocation::from_custom_root(&mapper_opt.config_dir); let config = tedge_config::TEdgeConfig::try_new(tedge_config_location.clone())?; - let log_level = if mapper_opt.debug { - tracing::Level::DEBUG - } else { - get_log_level( - "tedge-mapper", - &tedge_config_location.tedge_config_root_path, - )? - }; - set_log_level(log_level); + log_init( + "tedge-mapper", + &mapper_opt.log_args, + &tedge_config_location.tedge_config_root_path, + )?; // Run only one instance of a mapper (if enabled) let mut _flock = None; diff --git a/crates/core/tedge_watchdog/src/lib.rs b/crates/core/tedge_watchdog/src/lib.rs index ff0ba9ea77a..79607e466fd 100644 --- a/crates/core/tedge_watchdog/src/lib.rs +++ b/crates/core/tedge_watchdog/src/lib.rs @@ -23,12 +23,8 @@ version = clap::crate_version!(), about = clap::crate_description!() )] pub struct WatchdogOpt { - /// Turn-on the debug log level. - /// - /// If off only reports ERROR, WARN, and INFO - /// If on also reports DEBUG - #[clap(long)] - pub debug: bool, + #[command(flatten)] + pub log_args: LogConfigArgs, /// Start the watchdog from custom path /// @@ -46,16 +42,11 @@ pub async fn run(watchdog_opt: WatchdogOpt) -> Result<(), anyhow::Error> { let tedge_config_location = tedge_config::TEdgeConfigLocation::from_custom_root(watchdog_opt.config_dir.clone()); - let log_level = if watchdog_opt.debug { - tracing::Level::DEBUG - } else { - get_log_level( - "tedge-watchdog", - &tedge_config_location.tedge_config_root_path, - )? - }; - - set_log_level(log_level); + log_init( + "tedge-watchdog", + &watchdog_opt.log_args, + &tedge_config_location.tedge_config_root_path, + )?; watchdog::start_watchdog(watchdog_opt.config_dir).await } diff --git a/plugins/c8y_firmware_plugin/src/lib.rs b/plugins/c8y_firmware_plugin/src/lib.rs index 1b19579acc3..0841fd41936 100644 --- a/plugins/c8y_firmware_plugin/src/lib.rs +++ b/plugins/c8y_firmware_plugin/src/lib.rs @@ -9,8 +9,8 @@ use tedge_api::mqtt_topics::EntityTopicId; use tedge_api::mqtt_topics::MqttSchema; use tedge_api::mqtt_topics::Service; use tedge_config::get_config_dir; -use tedge_config::system_services::get_log_level; -use tedge_config::system_services::set_log_level; +use tedge_config::system_services::log_init; +use tedge_config::system_services::LogConfigArgs; use tedge_config::ProfileName; use tedge_config::TEdgeConfig; use tedge_downloader_ext::DownloaderActor; @@ -39,12 +39,8 @@ about = clap::crate_description!(), after_help = AFTER_HELP_TEXT )] pub struct FirmwarePluginOpt { - /// Turn-on the debug log level. - /// - /// If off only reports ERROR, WARN, and INFO - /// If on also reports DEBUG - #[clap(long)] - pub debug: bool, + #[command(flatten)] + pub log_args: LogConfigArgs, /// Create required directories #[clap(short, long)] @@ -67,13 +63,12 @@ pub async fn run(firmware_plugin_opt: FirmwarePluginOpt) -> Result<(), anyhow::E // Load tedge config from the provided location let tedge_config_location = tedge_config::TEdgeConfigLocation::from_custom_root(&firmware_plugin_opt.config_dir); - let log_level = if firmware_plugin_opt.debug { - tracing::Level::DEBUG - } else { - get_log_level(PLUGIN_NAME, &tedge_config_location.tedge_config_root_path)? - }; - set_log_level(log_level); + log_init( + "c8y-firmware-plugin", + &firmware_plugin_opt.log_args, + &tedge_config_location.tedge_config_root_path, + )?; let tedge_config = tedge_config::TEdgeConfig::try_new(tedge_config_location)?; let c8y_profile = firmware_plugin_opt.profile.as_deref(); From 537e02df15c47109416adbda90003ae92e388dea Mon Sep 17 00:00:00 2001 From: Marcel Guzik Date: Mon, 28 Oct 2024 11:49:54 +0100 Subject: [PATCH 2/3] Remove all calls to set_log_level in tests Signed-off-by: Marcel Guzik --- crates/extensions/c8y_mapper_ext/src/operations/handler.rs | 1 - crates/extensions/c8y_mapper_ext/src/tests.rs | 1 - 2 files changed, 2 deletions(-) diff --git a/crates/extensions/c8y_mapper_ext/src/operations/handler.rs b/crates/extensions/c8y_mapper_ext/src/operations/handler.rs index 6b8ddad579c..1f19908cfc8 100644 --- a/crates/extensions/c8y_mapper_ext/src/operations/handler.rs +++ b/crates/extensions/c8y_mapper_ext/src/operations/handler.rs @@ -671,7 +671,6 @@ mod tests { #[tokio::test] async fn shouldnt_process_invalid_status_transitions() { - tedge_config::system_services::set_log_level(tracing::Level::DEBUG); let TestHandle { operation_handler: mut sut, ttd: _ttd, diff --git a/crates/extensions/c8y_mapper_ext/src/tests.rs b/crates/extensions/c8y_mapper_ext/src/tests.rs index b298be87c7f..ed5fa8db3c1 100644 --- a/crates/extensions/c8y_mapper_ext/src/tests.rs +++ b/crates/extensions/c8y_mapper_ext/src/tests.rs @@ -2628,7 +2628,6 @@ async fn mapper_doesnt_update_status_of_subworkflow_commands_3048() { #[tokio::test] async fn mapper_doesnt_send_duplicate_operation_status() { - tedge_config::system_services::set_log_level(tracing::Level::DEBUG); let ttd = TempTedgeDir::new(); let test_handle = spawn_c8y_mapper_actor(&ttd, true).await; let TestHandle { From cc410972f2ca0430cc9ac82bdac2de5c4d4bf1ea Mon Sep 17 00:00:00 2001 From: Marcel Guzik Date: Mon, 28 Oct 2024 12:37:05 +0100 Subject: [PATCH 3/3] Add --log-level flag Add a --log-level flag that sets the verbosity of reported logs. In contrast to --debug, which enables debug logs in addition to the default error, warn, and info logs, --log-level sets the maximum verbosity, i.e. when set to error print only errors, if set to warn print warnings and errors, etc. and when set to trace, print all the logs. If --log-level is selected, this value is used and takes precedence over --debug. RUST_LOG env variable still overrides the flag. Signed-off-by: Marcel Guzik --- .../src/system_services/log_config.rs | 17 +++++++++++++++-- 1 file changed, 15 insertions(+), 2 deletions(-) diff --git a/crates/common/tedge_config/src/system_services/log_config.rs b/crates/common/tedge_config/src/system_services/log_config.rs index c9e8e331289..63b44bf8273 100644 --- a/crates/common/tedge_config/src/system_services/log_config.rs +++ b/crates/common/tedge_config/src/system_services/log_config.rs @@ -13,6 +13,15 @@ pub struct LogConfigArgs { /// If off only reports ERROR, WARN, and INFO, if on also reports DEBUG #[clap(long, global = true)] pub debug: bool, + + /// Configures the logging level. + /// + /// One of error/warn/info/debug/trace. Logs with verbosity lower or equal to the selected level + /// will be printed, i.e. warn prints ERROR and WARN logs and trace prints logs of all levels. + /// + /// Overrides `--debug` + #[clap(long, global = true)] + pub log_level: Option, } /// Configures and enables logging taking into account flags, env variables and file config. @@ -33,8 +42,12 @@ pub fn log_init( .with_ansi(std::io::stderr().is_terminal()) .with_timer(tracing_subscriber::fmt::time::UtcTime::rfc_3339()); - if flags.debug { - subscriber.with_max_level(tracing::Level::DEBUG).init(); + let log_level = flags + .log_level + .or(flags.debug.then_some(tracing::Level::DEBUG)); + + if let Some(log_level) = log_level { + subscriber.with_max_level(log_level).init(); return Ok(()); }