From 03bc0ea18b8646a4b146e918902ab172768c0ec8 Mon Sep 17 00:00:00 2001 From: Timshel Date: Tue, 21 May 2024 15:34:01 +0200 Subject: [PATCH] Allow to set and override module log_level --- .env.template | 6 +-- src/config.rs | 2 +- src/main.rs | 138 +++++++++++++++++++++++++++++++++----------------- 3 files changed, 96 insertions(+), 50 deletions(-) diff --git a/.env.template b/.env.template index 07d7dbc0..09141ab1 100644 --- a/.env.template +++ b/.env.template @@ -362,9 +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 -# LOG_LEVEL=info +## 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` +# LOG_LEVEL=info,path::to::module=debug ## Token for the admin interface, preferably an Argon2 PCH string ## Vaultwarden has a built-in generator by calling `vaultwarden hash` diff --git a/src/config.rs b/src/config.rs index 489a229d..df933811 100644 --- a/src/config.rs +++ b/src/config.rs @@ -564,7 +564,7 @@ make_config! { use_syslog: bool, false, def, false; /// Log file path log_file: String, false, option; - /// Log level + /// Log level: `info,path::to::module=warn` 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, diff --git a/src/main.rs b/src/main.rs index c7726a87..499aa36c 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, @@ -64,15 +65,9 @@ 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()?; - let extra_debug = matches!(level, LF::Trace | LF::Debug); + let extra_debug = matches!(level, log::LevelFilter::Trace | log::LevelFilter::Debug); check_data_folder().await; auth::initialize_keys().unwrap_or_else(|_| { @@ -210,7 +205,39 @@ 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 { + println!("[WARNING] Log level set to info, LOG_LEVEL should match {log_level_rgx_str}"); + (log::LevelFilter::Info, Vec::new()) + }; + // 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 +268,64 @@ fn init_logging(level: log::LevelFilter) -> Result<(), fern::InitError> { log::LevelFilter::Warn }; - let mut logger = fern::Dispatch::new() - .level(level) - // Hide unknown certificate errors if using self-signed - .level_for("rustls::session", log::LevelFilter::Off) - // Hide failed to close stream messages - .level_for("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) - // 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) - // Filter handlebars logs - .level_for("handlebars::render", handlebars_level) - // Prevent cookie_store logs - .level_for("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()); - // 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() { + 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 + ("rustls::session", log::LevelFilter::Off), + // Hide failed to close stream messages + ("hyper::server", log::LevelFilter::Warn), + // Silence Rocket `_` logs + ("_", 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 + ("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 + ("handlebars::render", handlebars_level), + // Prevent cookie_store logs + ("cookie_store", log::LevelFilter::Off), + // Variable level for hickory used by reqwest + ("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); + } + + 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()); + + let mut sorted_levels = default_levels.into_iter().collect::>(); + sorted_levels.sort_by_key(|a| a.0); + + for (path, level) in sorted_levels { + logger = logger.level_for(path.to_string(), level); } if CONFIG.extended_logging() { @@ -318,7 +362,9 @@ fn init_logging(level: log::LevelFilter) -> Result<(), fern::InitError> { } } - logger.apply()?; + if let Err(err) = logger.apply() { + error!("Failed to activate logger: {err}") + } // Catch panics and log them instead of default output to StdErr panic::set_hook(Box::new(|info| { @@ -356,7 +402,7 @@ fn init_logging(level: log::LevelFilter) -> Result<(), fern::InitError> { } })); - Ok(()) + Ok(level) } #[cfg(not(windows))]