From de66e56b6c951192bcb47987b34ac21e2bcea43a Mon Sep 17 00:00:00 2001 From: Timshel Date: Wed, 24 Jul 2024 16:49:03 +0200 Subject: [PATCH] Allow to override log level for specific target (#4305) --- .env.template | 5 ++- src/config.rs | 5 ++- src/main.rs | 122 +++++++++++++++++++++++++++++++++----------------- 3 files changed, 88 insertions(+), 44 deletions(-) diff --git a/.env.template b/.env.template index c4e391e4..9e36a51a 100644 --- a/.env.template +++ b/.env.template @@ -362,8 +362,9 @@ ## Log level ## Change the verbosity of the log output ## Valid values are "trace", "debug", "info", "warn", "error" and "off" -## Setting it to "trace" or "debug" would also show logs for mounted -## routes and static file, websocket and alive requests +## Setting it to "trace" or "debug" would also show logs for mounted routes and static file, websocket and alive requests +## For a specific module append a comma separated `path::to::module=log_level` +## For example, to only see debug logs for icons use: LOG_LEVEL="info,vaultwarden::api::icons=debug" # LOG_LEVEL=info ## Token for the admin interface, preferably an Argon2 PCH string diff --git a/src/config.rs b/src/config.rs index 1a41c9e8..5579918e 100644 --- a/src/config.rs +++ b/src/config.rs @@ -576,8 +576,9 @@ make_config! { use_syslog: bool, false, def, false; /// Log file path log_file: String, false, option; - /// Log level - log_level: String, false, def, "Info".to_string(); + /// Log level |> Valid values are "trace", "debug", "info", "warn", "error" and "off" + /// For a specific module append it as a comma separated value "info,path::to::module=debug" + log_level: String, false, def, "info".to_string(); /// Enable DB WAL |> Turning this off might lead to worse performance, but might help if using vaultwarden on some exotic filesystems, /// that do not support WAL. Please make sure you read project wiki on the topic before changing this setting. diff --git a/src/main.rs b/src/main.rs index 8a3f0eb8..ca39c502 100644 --- a/src/main.rs +++ b/src/main.rs @@ -26,6 +26,7 @@ extern crate diesel; extern crate diesel_migrations; use std::{ + collections::HashMap, fs::{canonicalize, create_dir_all}, panic, path::Path, @@ -65,13 +66,7 @@ async fn main() -> Result<(), Error> { parse_args(); launch_info(); - use log::LevelFilter as LF; - let level = LF::from_str(&CONFIG.log_level()).unwrap_or_else(|_| { - let valid_log_levels = LF::iter().map(|lvl| lvl.as_str().to_lowercase()).collect::>().join(", "); - println!("Log level must be one of the following: {valid_log_levels}"); - exit(1); - }); - init_logging(level).ok(); + let level = init_logging()?; check_data_folder().await; auth::initialize_keys().unwrap_or_else(|e| { @@ -89,7 +84,7 @@ async fn main() -> Result<(), Error> { schedule_jobs(pool.clone()); crate::db::models::TwoFactor::migrate_u2f_to_webauthn(&mut pool.get().await.unwrap()).await.unwrap(); - let extra_debug = matches!(level, LF::Trace | LF::Debug); + let extra_debug = matches!(level, log::LevelFilter::Trace | log::LevelFilter::Debug); launch_rocket(pool, extra_debug).await // Blocks until program termination. } @@ -210,7 +205,38 @@ fn launch_info() { ); } -fn init_logging(level: log::LevelFilter) -> Result<(), fern::InitError> { +fn init_logging() -> Result { + let levels = log::LevelFilter::iter().map(|lvl| lvl.as_str().to_lowercase()).collect::>().join("|"); + let log_level_rgx_str = format!("^({levels})((,[^,=]+=({levels}))*)$"); + let log_level_rgx = regex::Regex::new(&log_level_rgx_str)?; + let config_str = CONFIG.log_level().to_lowercase(); + + let (level, levels_override) = if let Some(caps) = log_level_rgx.captures(&config_str) { + let level = caps + .get(1) + .and_then(|m| log::LevelFilter::from_str(m.as_str()).ok()) + .ok_or(Error::new("Failed to parse global log level".to_string(), ""))?; + + let levels_override: Vec<(&str, log::LevelFilter)> = caps + .get(2) + .map(|m| { + m.as_str() + .split(',') + .collect::>() + .into_iter() + .flat_map(|s| match s.split('=').collect::>()[..] { + [log, lvl_str] => log::LevelFilter::from_str(lvl_str).ok().map(|lvl| (log, lvl)), + _ => None, + }) + .collect() + }) + .ok_or(Error::new("Failed to parse overrides".to_string(), ""))?; + + (level, levels_override) + } else { + err!(format!("LOG_LEVEL should follow the format info,vaultwarden::api::icons=debug, invalid: {config_str}")) + }; + // Depending on the main log level we either want to disable or enable logging for hickory. // Else if there are timeouts it will clutter the logs since hickory uses warn for this. let hickory_level = if level >= log::LevelFilter::Debug { @@ -241,47 +267,61 @@ fn init_logging(level: log::LevelFilter) -> Result<(), fern::InitError> { log::LevelFilter::Warn }; - let mut logger = fern::Dispatch::new() - .level(level) + // Enable smtp debug logging only specifically for smtp when need. + // This can contain sensitive information we do not want in the default debug/trace logging. + let smtp_log_level = if CONFIG.smtp_debug() { + log::LevelFilter::Debug + } else { + log::LevelFilter::Off + }; + + let mut default_levels = HashMap::from([ // Hide unknown certificate errors if using self-signed - .level_for("rustls::session", log::LevelFilter::Off) + ("rustls::session", log::LevelFilter::Off), // Hide failed to close stream messages - .level_for("hyper::server", log::LevelFilter::Warn) + ("hyper::server", log::LevelFilter::Warn), // Silence Rocket `_` logs - .level_for("_", rocket_underscore_level) - .level_for("rocket::response::responder::_", rocket_underscore_level) - .level_for("rocket::server::_", rocket_underscore_level) - .level_for("vaultwarden::api::admin::_", rocket_underscore_level) - .level_for("vaultwarden::api::notifications::_", rocket_underscore_level) + ("_", rocket_underscore_level), + ("rocket::response::responder::_", rocket_underscore_level), + ("rocket::server::_", rocket_underscore_level), + ("vaultwarden::api::admin::_", rocket_underscore_level), + ("vaultwarden::api::notifications::_", rocket_underscore_level), // Silence Rocket logs - .level_for("rocket::launch", log::LevelFilter::Error) - .level_for("rocket::launch_", log::LevelFilter::Error) - .level_for("rocket::rocket", log::LevelFilter::Warn) - .level_for("rocket::server", log::LevelFilter::Warn) - .level_for("rocket::fairing::fairings", log::LevelFilter::Warn) - .level_for("rocket::shield::shield", log::LevelFilter::Warn) - .level_for("hyper::proto", log::LevelFilter::Off) - .level_for("hyper::client", log::LevelFilter::Off) + ("rocket::launch", log::LevelFilter::Error), + ("rocket::launch_", log::LevelFilter::Error), + ("rocket::rocket", log::LevelFilter::Warn), + ("rocket::server", log::LevelFilter::Warn), + ("rocket::fairing::fairings", log::LevelFilter::Warn), + ("rocket::shield::shield", log::LevelFilter::Warn), + ("hyper::proto", log::LevelFilter::Off), + ("hyper::client", log::LevelFilter::Off), // Filter handlebars logs - .level_for("handlebars::render", handlebars_level) + ("handlebars::render", handlebars_level), // Prevent cookie_store logs - .level_for("cookie_store", log::LevelFilter::Off) + ("cookie_store", log::LevelFilter::Off), // Variable level for hickory used by reqwest - .level_for("hickory_resolver::name_server::name_server", hickory_level) - .level_for("hickory_proto::xfer", hickory_level) - .level_for("diesel_logger", diesel_logger_level) - .chain(std::io::stdout()); + ("hickory_resolver::name_server::name_server", hickory_level), + ("hickory_proto::xfer", hickory_level), + ("diesel_logger", diesel_logger_level), + // SMTP + ("lettre::transport::smtp", smtp_log_level), + ]); + + for (path, level) in levels_override.into_iter() { + let _ = default_levels.insert(path, level); + } - // Enable smtp debug logging only specifically for smtp when need. - // This can contain sensitive information we do not want in the default debug/trace logging. - if CONFIG.smtp_debug() { + if Some(&log::LevelFilter::Debug) == default_levels.get("lettre::transport::smtp") { println!( "[WARNING] SMTP Debugging is enabled (SMTP_DEBUG=true). Sensitive information could be disclosed via logs!\n\ [WARNING] Only enable SMTP_DEBUG during troubleshooting!\n" ); - logger = logger.level_for("lettre::transport::smtp", log::LevelFilter::Debug) - } else { - logger = logger.level_for("lettre::transport::smtp", log::LevelFilter::Off) + } + + let mut logger = fern::Dispatch::new().level(level).chain(std::io::stdout()); + + for (path, level) in default_levels { + logger = logger.level_for(path.to_string(), level); } if CONFIG.extended_logging() { @@ -318,7 +358,9 @@ fn init_logging(level: log::LevelFilter) -> Result<(), fern::InitError> { } } - logger.apply()?; + if let Err(err) = logger.apply() { + err!(format!("Failed to activate logger: {err}")) + } // Catch panics and log them instead of default output to StdErr panic::set_hook(Box::new(|info| { @@ -356,7 +398,7 @@ fn init_logging(level: log::LevelFilter) -> Result<(), fern::InitError> { } })); - Ok(()) + Ok(level) } #[cfg(not(windows))]