From f2d902d7752a20830edea43a5f1f0474406c4f29 Mon Sep 17 00:00:00 2001 From: Mykhailo Kremniov Date: Fri, 20 Dec 2024 20:27:23 +0200 Subject: [PATCH] Logging initialization improvements --- logging/src/lib.rs | 250 +++++++++++++++++++++++++++++++-------- logging/src/log_style.rs | 76 +++++------- logging/src/utils.rs | 38 ++++++ node-lib/src/runner.rs | 16 ++- utils/tests/log_error.rs | 16 ++- 5 files changed, 295 insertions(+), 101 deletions(-) create mode 100644 logging/src/utils.rs diff --git a/logging/src/lib.rs b/logging/src/lib.rs index ebc640a6dd..bbc6f668b7 100644 --- a/logging/src/lib.rs +++ b/logging/src/lib.rs @@ -15,99 +15,249 @@ mod log_style; mod tracing_utils; +mod utils; use std::{ io::{IsTerminal, Write}, sync::Mutex, }; +use tracing::{level_filters::LevelFilter, Subscriber}; use tracing_subscriber::{ fmt::MakeWriter, layer::SubscriberExt, util::SubscriberInitExt, EnvFilter, Layer, Registry, }; -use log_style::{get_log_style_from_env, LogStyle, TextColoring}; +use log_style::{get_log_style_from_env, LogStyleParseError}; pub use log; - +pub use log_style::{LogStyle, TextColoring}; pub use tracing_utils::{spawn_in_current_span, spawn_in_span}; +pub use utils::{get_from_env, GetFromEnvError, ValueOrEnvVar}; /// Send log output to the terminal. pub fn init_logging() { - init_logging_impl( - // Write to stderr to mimic the behavior of env_logger. - std::io::stderr, - // This will be true if stderr is the actual terminal (i.e. it wasn't redirected - // to a file etc). - std::io::stderr().is_terminal(), - // Use the default env var for filtering. - None, - ); + init_logging_generic(default_writer_settings(), no_writer_settings()); } /// Send log output to the specified [Write] instance, log lines are separated by '\n' /// /// `is_terminal` will determine text coloring in the `TextColoring::Auto` case. pub fn init_logging_to(file: impl Write + Send + 'static, is_terminal: bool) { - init_logging_impl(Mutex::new(Box::new(file)), is_terminal, None); + init_logging_generic( + WriterSettings { + make_writer: write_to_make_writer(file), + is_terminal, + filter: ValueOrEnvVar::EnvVar("RUST_LOG".into()), + log_style: ValueOrEnvVar::EnvVar(LOG_STYLE_ENV_VAR_NAME.into()), + }, + no_writer_settings(), + ); } -/// Same as init_logging_to, but here we use the specified custom env var for filtering -/// instead of RUST_LOG. -pub fn init_logging_with_env_var( - file: impl Write + Send + 'static, - is_terminal: bool, - filter_env_var_name: &str, -) { - init_logging_impl( - Mutex::new(Box::new(file)), - is_terminal, - Some(filter_env_var_name), - ); +pub fn default_writer_settings() -> WriterSettings std::io::Stderr> { + WriterSettings { + // Write to stderr to mimic the behavior of env_logger. + make_writer: std::io::stderr, + // This will be true if stderr is the actual terminal (i.e. it wasn't redirected + // to a file etc). + is_terminal: std::io::stderr().is_terminal(), + // Use the default env var for filtering. + filter: ValueOrEnvVar::EnvVar("RUST_LOG".into()), + // Use the default env var style. + log_style: ValueOrEnvVar::EnvVar(LOG_STYLE_ENV_VAR_NAME.into()), + } +} + +/// Convert a `Write` instance to `MakeWriter`. +pub fn write_to_make_writer( + writer: impl Write + Send + 'static, +) -> impl for<'a> MakeWriter<'a> + Send + Sync + 'static { + Mutex::new(Box::new(writer)) } static LOG_STYLE_ENV_VAR_NAME: &str = "ML_LOG_STYLE"; +static DEFAULT_LOG_STYLE: LogStyle = LogStyle::Text(TextColoring::Auto); static INITIALIZE_LOGGER_ONCE_FLAG: std::sync::Once = std::sync::Once::new(); -/// `filter_env_var_name` specifies a custom env var to use instead of RUST_LOG; -/// if not specified, RUST_LOG will be used. -fn init_logging_impl(make_writer: MW, is_terminal: bool, filter_env_var_name: Option<&str>) -where - MW: for<'a> MakeWriter<'a> + Send + Sync + 'static, +pub struct WriterSettings { + pub make_writer: MW, + pub is_terminal: bool, + pub filter: ValueOrEnvVar, + pub log_style: ValueOrEnvVar, +} + +/// Generic version of init_logging that allows to have an auxiliary writer with its own settings +/// for filtering and log style. +pub fn init_logging_generic( + main_writer_settings: WriterSettings, + aux_writer_settings: Option>, +) where + MW1: for<'a> MakeWriter<'a> + Send + Sync + 'static, + MW2: for<'a> MakeWriter<'a> + Send + Sync + 'static, { INITIALIZE_LOGGER_ONCE_FLAG.call_once(move || { - let (log_style, log_style_parse_err) = get_log_style_from_env(LOG_STYLE_ENV_VAR_NAME); - - let logging_layer: Box + Send + Sync> = match log_style { - LogStyle::Json => { - Box::new(tracing_subscriber::fmt::Layer::new().json().with_writer(make_writer)) - } - LogStyle::Text(preferred_coloring) => Box::new( - tracing_subscriber::fmt::Layer::new() - .with_writer(make_writer) - .with_ansi(should_use_coloring(preferred_coloring, is_terminal)), - ), - }; + let mut errors = Vec::new(); + let main_layer = make_layer(main_writer_settings, &mut errors); + let aux_layer = aux_writer_settings.map(|settings| make_layer(settings, &mut errors)); Registry::default() - .with(logging_layer) - // This will construct EnvFilter using the specified env variable. - .with(EnvFilter::from_env( - filter_env_var_name.unwrap_or("RUST_LOG"), - )) + .with(main_layer) + .with(aux_layer) // This basically calls tracing::subscriber::set_global_default on self and then // initializes a 'log' compatibility layer, so that 'log' macros continue to work // (this requires the "tracing-log" feature to be enabled, but it is enabled by default). .init(); - // Now that we've initialized logging somehow, we can complain about the env var parsing error, - // if any. - if let Some(err) = log_style_parse_err { - log::error!("Couldn't get log style from {LOG_STYLE_ENV_VAR_NAME} - {err}"); + // Now that we've initialized logging somehow, we can complain about errors, if any. + for error in errors { + log::error!("Log initialization error: {error}"); } }); } +pub fn no_writer_settings() -> Option> { + None +} + +fn make_layer( + writer_settings: WriterSettings, + errors: &mut Vec, +) -> Box + Send + Sync> +where + MW: for<'a> MakeWriter<'a> + Send + Sync + 'static, + S: Subscriber + for<'a> tracing_subscriber::registry::LookupSpan<'a>, +{ + let filter = make_env_filter(writer_settings.filter, errors); + let log_style = get_log_style(&writer_settings.log_style, errors); + + make_layer_impl( + writer_settings.make_writer, + writer_settings.is_terminal, + filter, + log_style, + ) +} + +fn make_layer_impl( + make_writer: MW, + is_terminal: bool, + filter: EnvFilter, + log_style: LogStyle, +) -> Box + Send + Sync> +where + MW: for<'a> MakeWriter<'a> + Send + Sync + 'static, + S: Subscriber + for<'a> tracing_subscriber::registry::LookupSpan<'a>, +{ + match log_style { + LogStyle::Json => tracing_subscriber::fmt::Layer::new() + .json() + .with_writer(make_writer) + .with_filter(filter) + .boxed(), + LogStyle::Text(preferred_coloring) => tracing_subscriber::fmt::Layer::new() + .with_writer(make_writer) + .with_ansi(should_use_coloring(preferred_coloring, is_terminal)) + .with_filter(filter) + .boxed(), + } +} + +fn get_log_style( + log_style: &ValueOrEnvVar, + errors: &mut Vec, +) -> LogStyle { + let result_opt = match get_log_style_impl(log_style) { + Ok(opt_val) => opt_val, + Err(err) => { + errors.push(err); + None + } + }; + result_opt.unwrap_or(DEFAULT_LOG_STYLE) +} + +fn get_log_style_impl( + log_style: &ValueOrEnvVar, +) -> Result, InternalLogInitError> { + match log_style { + ValueOrEnvVar::Value(val) => Ok(Some(*val)), + ValueOrEnvVar::EnvVar(var_name) => get_log_style_from_env(var_name).map_err(|err| { + InternalLogInitError::LogStyleFromEnvRetrievalError { + env_var_name: var_name.to_string(), + error: err, + } + }), + } +} + +fn make_env_filter( + filter_str: ValueOrEnvVar, + errors: &mut Vec, +) -> EnvFilter { + let result_opt = match make_env_filter_impl(filter_str) { + Ok(filter) => Some(filter), + Err(err) => { + errors.push(err); + None + } + }; + + result_opt.unwrap_or_else(|| { + EnvFilter::builder() + .with_default_directive(default_filter_directive()) + .parse_lossy("") + }) +} + +fn make_env_filter_impl(filter: ValueOrEnvVar) -> Result { + let filter_directives = match filter { + ValueOrEnvVar::Value(val) => Some(val), + ValueOrEnvVar::EnvVar(var_name) => get_from_env(var_name.as_ref())?, + }; + let filter_directives = filter_directives.unwrap_or_default(); + + // Note: here we try to catch errors to later print them to the log with the "error" severity, so that + // typos in the filter string can be noticed. But not all errors will be caught. E.g. if you set the filter + // to "debugg" instead of "debug", `parse` will treat it as a target and not as a log level, and nothing will + // be printed to the log. + let filter = EnvFilter::builder() + // Default filter to use if the passed directives are empty (i.e. if the whole string is empty or it contains + // a list of empty directives, e.g. something like ",,,"). + .with_default_directive(default_filter_directive()) + .parse(&filter_directives) + .map_err(|err| InternalLogInitError::FilterDirectivesParseError { + directives: filter_directives, + error: err, + })?; + + Ok(filter) +} + +// Note: EnvFilter::from_env also uses ERROR as the default. +fn default_filter_directive() -> tracing_subscriber::filter::Directive { + LevelFilter::ERROR.into() +} + +#[allow(clippy::enum_variant_names)] +#[derive(Debug, thiserror::Error)] +enum InternalLogInitError { + #[error("Error retrieving log style from env var {env_var_name}: {error}")] + LogStyleFromEnvRetrievalError { + env_var_name: String, + error: LogStyleParseError, + }, + + #[error("Env var error: {0:?}")] + GetFromEnvError(#[from] GetFromEnvError), + + #[error("Error parsing filter directives '{directives}': {error}")] + FilterDirectivesParseError { + directives: String, + error: tracing_subscriber::filter::ParseError, + }, +} + fn can_use_coloring() -> bool { if cfg!(windows) { // Allow using colors if run in an MSYS console, which includes Git Bash diff --git a/logging/src/log_style.rs b/logging/src/log_style.rs index c6acc70116..25d32f393d 100644 --- a/logging/src/log_style.rs +++ b/logging/src/log_style.rs @@ -13,11 +13,9 @@ // See the License for the specific language governing permissions and // limitations under the License. -use std::ffi::OsString; - use thiserror::Error; -static DEFAULT_LOG_STYLE: LogStyle = LogStyle::Text(TextColoring::Auto); +use crate::utils::{get_from_env, GetFromEnvError}; #[derive(Copy, Clone, Debug, PartialEq, Eq)] pub enum TextColoring { @@ -45,26 +43,16 @@ impl LogStyle { } } -pub fn get_log_style_from_env(env_var_name: &str) -> (LogStyle, Option) { - let (style, parse_err) = match std::env::var(env_var_name) { - Ok(str) => match LogStyle::parse(&str) { - Ok(style) => (Some(style), None), - Err(err) => (None, Some(err)), - }, - Err(std::env::VarError::NotPresent) => (None, None), - Err(std::env::VarError::NotUnicode(os_str)) => { - (None, Some(LogStyleParseError::BadData(os_str))) - } - }; - (style.unwrap_or(DEFAULT_LOG_STYLE), parse_err) +pub fn get_log_style_from_env(env_var_name: &str) -> Result, LogStyleParseError> { + get_from_env(env_var_name)?.map(|val| LogStyle::parse(&val)).transpose() } #[derive(Debug, Error, PartialEq, Eq)] pub enum LogStyleParseError { #[error("Unrecognized format: {0}")] UnrecognizedFormat(String), - #[error("Bad data: {0:?}")] - BadData(OsString), + #[error("Env var error: {0:?}")] + GetFromEnvError(#[from] GetFromEnvError), } #[cfg(test)] @@ -83,59 +71,57 @@ mod tests { // Basic tests { std::env::set_var(TEST_ENV_VAR, "text"); - let (style, error) = get_log_style_from_env(TEST_ENV_VAR); - assert_eq!(style, LogStyle::Text(TextColoring::Auto)); - assert_eq!(error, None); + let result = get_log_style_from_env(TEST_ENV_VAR); + assert_eq!(result, Ok(Some(LogStyle::Text(TextColoring::Auto)))); std::env::set_var(TEST_ENV_VAR, "text-colored"); - let (style, error) = get_log_style_from_env(TEST_ENV_VAR); - assert_eq!(style, LogStyle::Text(TextColoring::On)); - assert_eq!(error, None); + let result = get_log_style_from_env(TEST_ENV_VAR); + assert_eq!(result, Ok(Some(LogStyle::Text(TextColoring::On)))); std::env::set_var(TEST_ENV_VAR, "text-uncolored"); - let (style, error) = get_log_style_from_env(TEST_ENV_VAR); - assert_eq!(style, LogStyle::Text(TextColoring::Off)); - assert_eq!(error, None); + let result = get_log_style_from_env(TEST_ENV_VAR); + assert_eq!(result, Ok(Some(LogStyle::Text(TextColoring::Off)))); std::env::set_var(TEST_ENV_VAR, "json"); - let (style, error) = get_log_style_from_env(TEST_ENV_VAR); - assert_eq!(style, LogStyle::Json); - assert_eq!(error, None); + let result = get_log_style_from_env(TEST_ENV_VAR); + assert_eq!(result, Ok(Some(LogStyle::Json))); } // Case-insensitivity tests { std::env::set_var(TEST_ENV_VAR, "tEXt"); - let (style, error) = get_log_style_from_env(TEST_ENV_VAR); - assert_eq!(style, LogStyle::Text(TextColoring::Auto)); - assert_eq!(error, None); + let result = get_log_style_from_env(TEST_ENV_VAR); + assert_eq!(result, Ok(Some(LogStyle::Text(TextColoring::Auto)))); std::env::set_var(TEST_ENV_VAR, "tEXt-coLoRed"); - let (style, error) = get_log_style_from_env(TEST_ENV_VAR); - assert_eq!(style, LogStyle::Text(TextColoring::On)); - assert_eq!(error, None); + let result = get_log_style_from_env(TEST_ENV_VAR); + assert_eq!(result, Ok(Some(LogStyle::Text(TextColoring::On)))); std::env::set_var(TEST_ENV_VAR, "tEXt-uncoLoRed"); - let (style, error) = get_log_style_from_env(TEST_ENV_VAR); - assert_eq!(style, LogStyle::Text(TextColoring::Off)); - assert_eq!(error, None); + let result = get_log_style_from_env(TEST_ENV_VAR); + assert_eq!(result, Ok(Some(LogStyle::Text(TextColoring::Off)))); std::env::set_var(TEST_ENV_VAR, "jSoN"); - let (style, error) = get_log_style_from_env(TEST_ENV_VAR); - assert_eq!(style, LogStyle::Json); - assert_eq!(error, None); + let result = get_log_style_from_env(TEST_ENV_VAR); + assert_eq!(result, Ok(Some(LogStyle::Json))); } // Bad value test { let str = "foo"; std::env::set_var(TEST_ENV_VAR, str); - let (style, error) = get_log_style_from_env(TEST_ENV_VAR); - assert_eq!(style, DEFAULT_LOG_STYLE); + let result = get_log_style_from_env(TEST_ENV_VAR); assert_eq!( - error, - Some(LogStyleParseError::UnrecognizedFormat(str.to_owned())) + result, + Err(LogStyleParseError::UnrecognizedFormat(str.to_owned())) ); } + + // Missing value test + { + std::env::remove_var(TEST_ENV_VAR); + let result = get_log_style_from_env(TEST_ENV_VAR); + assert_eq!(result, Ok(None)); + } } } diff --git a/logging/src/utils.rs b/logging/src/utils.rs new file mode 100644 index 0000000000..a086716efe --- /dev/null +++ b/logging/src/utils.rs @@ -0,0 +1,38 @@ +// Copyright (c) 2021-2024 RBB S.r.l +// opensource@mintlayer.org +// SPDX-License-Identifier: MIT +// Licensed under the MIT License; +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// https://github.com/mintlayer/mintlayer-core/blob/master/LICENSE +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +use std::{borrow::Cow, ffi::OsString}; + +#[derive(Debug, thiserror::Error, PartialEq, Eq)] +pub enum GetFromEnvError { + #[error("Env var {var_name}'s contents are not valid unicode: {data:?}")] + NotUnicode { var_name: String, data: OsString }, +} + +pub fn get_from_env(var_name: &str) -> Result, GetFromEnvError> { + match std::env::var(var_name) { + Ok(str) => Ok(Some(str)), + Err(std::env::VarError::NotPresent) => Ok(None), + Err(std::env::VarError::NotUnicode(data)) => Err(GetFromEnvError::NotUnicode { + var_name: var_name.to_owned(), + data, + }), + } +} + +pub enum ValueOrEnvVar { + Value(T), + EnvVar(Cow<'static, str>), +} diff --git a/node-lib/src/runner.rs b/node-lib/src/runner.rs index cbc4c08804..51d6a41cb3 100644 --- a/node-lib/src/runner.rs +++ b/node-lib/src/runner.rs @@ -264,6 +264,8 @@ pub async fn setup(options: Options) -> Result { return Ok(NodeSetupResult::DataDirCleanedUp); } + let main_log_writer_settings = logging::default_writer_settings(); + // Init logging if run_options.log_to_file.is_some_and(|log_to_file| log_to_file) { let log_file = FileRotate::new( @@ -274,9 +276,19 @@ pub async fn setup(options: Options) -> Result { #[cfg(unix)] None, ); - logging::init_logging_to(log_file, false); + logging::init_logging_generic( + main_log_writer_settings, + Some(logging::WriterSettings { + make_writer: logging::write_to_make_writer(log_file), + is_terminal: false, + filter: logging::ValueOrEnvVar::Value("info".into()), + log_style: logging::ValueOrEnvVar::Value(logging::LogStyle::Text( + logging::TextColoring::Off, + )), + }), + ); } else { - logging::init_logging(); + logging::init_logging_generic(main_log_writer_settings, logging::no_writer_settings()); } logging::log::info!("Command line options: {options:?}"); diff --git a/utils/tests/log_error.rs b/utils/tests/log_error.rs index d8f046dcb8..8c9bca1cf6 100644 --- a/utils/tests/log_error.rs +++ b/utils/tests/log_error.rs @@ -852,7 +852,9 @@ mod log_output { sync::{Arc, Mutex}, }; - use logging::init_logging_with_env_var; + use logging::{ + init_logging_generic, write_to_make_writer, LogStyle, ValueOrEnvVar, WriterSettings, + }; #[derive(Clone)] pub struct LogOutput(Arc>>); @@ -863,9 +865,15 @@ mod log_output { } pub fn init_logging(&self) { - let env_var_name = "LOGGING_TEST_RUST_LOG_VAR"; - std::env::set_var(env_var_name, "trace"); - init_logging_with_env_var(self.clone(), false, env_var_name); + init_logging_generic( + WriterSettings { + make_writer: write_to_make_writer(self.clone()), + is_terminal: false, + filter: ValueOrEnvVar::Value("trace".to_owned()), + log_style: ValueOrEnvVar::Value(LogStyle::Text(logging::TextColoring::Off)), + }, + logging::no_writer_settings(), + ); } pub fn take(&self) -> String {