From 185ef76145ebaa3d35ea8936c319d6726d6e05de Mon Sep 17 00:00:00 2001 From: Shanin Roman <40040452+Erigara@users.noreply.github.com> Date: Fri, 12 Jul 2024 13:43:31 +0300 Subject: [PATCH] feat(logger): use RUST_LOG-like EnvFilter for logging (#4837) Signed-off-by: Shanin Roman --- cli/src/lib.rs | 4 +- client/benches/torii.rs | 2 +- client/src/client.rs | 2 +- config/Cargo.toml | 2 +- config/src/client_api.rs | 22 ++++-- config/src/logger.rs | 79 ++++++++++++++++--- config/src/parameters/user.rs | 8 +- config/tests/fixtures.rs | 2 +- core/src/kiso.rs | 21 ++--- genesis/src/lib.rs | 2 +- logger/Cargo.toml | 2 +- logger/src/actor.rs | 17 ++-- logger/src/lib.rs | 12 +-- logger/tests/setting_logger.rs | 2 +- schema/gen/src/lib.rs | 3 - .../get_configuration_response_schema.json | 2 +- .../configuration/test_get_configuration.py | 2 +- .../configuration/test_post_configuration.py | 4 +- 18 files changed, 125 insertions(+), 63 deletions(-) diff --git a/cli/src/lib.rs b/cli/src/lib.rs index 8c61027bcba..63e00eeddb1 100644 --- a/cli/src/lib.rs +++ b/cli/src/lib.rs @@ -520,7 +520,7 @@ impl Iroha { loop { tokio::select! { Ok(()) = log_level_update.changed() => { - let value = *log_level_update.borrow_and_update(); + let value = log_level_update.borrow_and_update().clone(); if let Err(error) = logger.reload_level(value).await { iroha_logger::error!("Failed to reload log level: {error}"); }; @@ -615,7 +615,7 @@ pub fn read_config_and_genesis( validate_config(&config)?; - let logger_config = LoggerInitConfig::new(config.logger, args.terminal_colors); + let logger_config = LoggerInitConfig::new(config.logger.clone(), args.terminal_colors); Ok((config, logger_config, genesis)) } diff --git a/client/benches/torii.rs b/client/benches/torii.rs index 07f673b3105..2a9b0114275 100644 --- a/client/benches/torii.rs +++ b/client/benches/torii.rs @@ -45,7 +45,7 @@ fn query_requests(criterion: &mut Criterion) { rt.block_on(builder.start_with_peer(&mut peer)); rt.block_on(async { iroha_logger::test_logger() - .reload_level(iroha::data_model::Level::ERROR) + .reload_level(iroha::data_model::Level::ERROR.into()) .await .unwrap() }); diff --git a/client/src/client.rs b/client/src/client.rs index d7729127604..6902b054f0a 100644 --- a/client/src/client.rs +++ b/client/src/client.rs @@ -1030,7 +1030,7 @@ impl Client { /// /// # Errors /// If sending request or decoding fails - pub fn set_config(&self, dto: ConfigDTO) -> Result<()> { + pub fn set_config(&self, dto: &ConfigDTO) -> Result<()> { let body = serde_json::to_vec(&dto).wrap_err(format!("Failed to serialize {dto:?}"))?; let url = self .torii_url diff --git a/config/Cargo.toml b/config/Cargo.toml index 556b9f1bfa5..0269103636c 100644 --- a/config/Cargo.toml +++ b/config/Cargo.toml @@ -19,7 +19,7 @@ iroha_genesis = { workspace = true } error-stack = { workspace = true } tracing = { workspace = true } -tracing-subscriber = { workspace = true, features = ["fmt", "ansi"] } +tracing-subscriber = { workspace = true, features = ["fmt", "ansi", "env-filter"] } url = { workspace = true, features = ["serde"] } serde = { workspace = true, features = ["derive"] } diff --git a/config/src/client_api.rs b/config/src/client_api.rs index f87bc5b7a41..9bd4fa2a8e5 100644 --- a/config/src/client_api.rs +++ b/config/src/client_api.rs @@ -9,13 +9,15 @@ // configuration-related crate, this part should be re-written in a clean way. // Track configuration refactoring here: https://github.com/hyperledger/iroha/issues/2585 -use iroha_data_model::Level; use serde::{Deserialize, Serialize}; -use crate::parameters::actual::{Logger as BaseLogger, Root as BaseConfig}; +use crate::{ + logger::Directives, + parameters::actual::{Logger as BaseLogger, Root as BaseConfig}, +}; /// Subset of [`super::iroha`] configuration. -#[derive(Debug, Serialize, Deserialize, Clone, Copy)] +#[derive(Debug, Serialize, Deserialize, Clone)] pub struct ConfigDTO { #[allow(missing_docs)] pub logger: Logger, @@ -30,27 +32,31 @@ impl From<&'_ BaseConfig> for ConfigDTO { } /// Subset of [`super::logger`] configuration. -#[derive(Debug, Serialize, Deserialize, Clone, Copy)] +#[derive(Debug, Serialize, Deserialize, Clone)] pub struct Logger { #[allow(missing_docs)] - pub level: Level, + pub level: Directives, } impl From<&'_ BaseLogger> for Logger { fn from(value: &'_ BaseLogger) -> Self { - Self { level: value.level } + Self { + level: value.level.clone(), + } } } #[cfg(test)] mod test { + use iroha_data_model::Level; + use super::*; #[test] fn snapshot_serialized_form() { let value = ConfigDTO { logger: Logger { - level: Level::TRACE, + level: Level::TRACE.into(), }, }; @@ -62,7 +68,7 @@ mod test { let expected = expect_test::expect![[r#" { "logger": { - "level": "TRACE" + "level": "trace" } }"#]]; expected.assert_eq(&actual); diff --git a/config/src/logger.rs b/config/src/logger.rs index e5038337396..8b56b34048c 100644 --- a/config/src/logger.rs +++ b/config/src/logger.rs @@ -1,18 +1,13 @@ //! Configuration utils related to Logger specifically. +use std::{ + fmt::{Debug, Display}, + str::FromStr, +}; + pub use iroha_data_model::Level; use serde_with::{DeserializeFromStr, SerializeDisplay}; - -/// Convert [`Level`] into [`tracing::Level`] -pub fn into_tracing_level(level: Level) -> tracing::Level { - match level { - Level::TRACE => tracing::Level::TRACE, - Level::DEBUG => tracing::Level::DEBUG, - Level::INFO => tracing::Level::INFO, - Level::WARN => tracing::Level::WARN, - Level::ERROR => tracing::Level::ERROR, - } -} +use tracing_subscriber::filter::Directive; /// Reflects formatters in [`tracing_subscriber::fmt::format`] #[derive( @@ -40,6 +35,68 @@ pub enum Format { Json, } +/// List of directives +#[derive(Clone, DeserializeFromStr, SerializeDisplay, PartialEq, Eq)] +pub struct Directives(Vec); + +impl FromStr for Directives { + type Err = tracing_subscriber::filter::ParseError; + + fn from_str(dirs: &str) -> std::result::Result { + if dirs.is_empty() { + return Ok(Self(Vec::new())); + } + let directives = dirs + .split(',') + .filter(|s| !s.is_empty()) + .map(Directive::from_str) + .collect::, _>>()?; + Ok(Self(directives)) + } +} + +impl Display for Directives { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + let mut directives_iter = self.0.iter(); + if let Some(directive) = directives_iter.next() { + write!(f, "{directive}")?; + } + for directive in directives_iter { + write!(f, ",{directive}")?; + } + Ok(()) + } +} + +impl Debug for Directives { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + Display::fmt(&self, f) + } +} + +impl From for Directives { + fn from(level: Level) -> Self { + Directives(Vec::from([into_tracing_level(level).into()])) + } +} + +impl Default for Directives { + fn default() -> Self { + Self::from(Level::INFO) + } +} + +/// Convert [`Level`] into [`tracing::Level`] +fn into_tracing_level(level: Level) -> tracing::Level { + match level { + Level::TRACE => tracing::Level::TRACE, + Level::DEBUG => tracing::Level::DEBUG, + Level::INFO => tracing::Level::INFO, + Level::WARN => tracing::Level::WARN, + Level::ERROR => tracing::Level::ERROR, + } +} + #[cfg(test)] pub mod tests { use crate::logger::Format; diff --git a/config/src/parameters/user.rs b/config/src/parameters/user.rs index a8bbdd38cbe..04d42ea56e3 100644 --- a/config/src/parameters/user.rs +++ b/config/src/parameters/user.rs @@ -25,14 +25,14 @@ use iroha_config_base::{ ReadConfig, WithOrigin, }; use iroha_crypto::{PrivateKey, PublicKey}; -use iroha_data_model::{peer::PeerId, ChainId, Level}; +use iroha_data_model::{peer::PeerId, ChainId}; use iroha_primitives::{addr::SocketAddr, unique_vec::UniqueVec}; use serde::Deserialize; use url::Url; use crate::{ kura::InitMode as KuraInitMode, - logger::Format as LoggerFormat, + logger::{Directives, Format as LoggerFormat}, parameters::{actual, defaults}, snapshot::Mode as SnapshotMode, }; @@ -346,14 +346,14 @@ impl Queue { } } -#[derive(Debug, Clone, Copy, Default, ReadConfig)] +#[derive(Debug, Clone, Default, ReadConfig)] pub struct Logger { /// Level of logging verbosity // TODO: parse user provided value in a case insensitive way, // because `format` is set in lowercase, and `LOG_LEVEL=INFO` + `LOG_FORMAT=pretty` // looks inconsistent #[config(env = "LOG_LEVEL", default)] - pub level: Level, + pub level: Directives, /// Output format #[config(env = "LOG_FORMAT", default)] pub format: LoggerFormat, diff --git a/config/tests/fixtures.rs b/config/tests/fixtures.rs index c4d4e7375b3..0b09a9e3114 100644 --- a/config/tests/fixtures.rs +++ b/config/tests/fixtures.rs @@ -172,7 +172,7 @@ fn minimal_config_snapshot() { idle_time: 30s, }, logger: Logger { - level: INFO, + level: info, format: Full, }, queue: Queue { diff --git a/core/src/kiso.rs b/core/src/kiso.rs index 67837c12816..19982bc1949 100644 --- a/core/src/kiso.rs +++ b/core/src/kiso.rs @@ -10,9 +10,9 @@ use eyre::Result; use iroha_config::{ client_api::{ConfigDTO, Logger as LoggerDTO}, + logger::Directives, parameters::actual::Root as Config, }; -use iroha_logger::Level; use tokio::sync::{mpsc, oneshot, watch}; const DEFAULT_CHANNEL_SIZE: usize = 32; @@ -29,7 +29,7 @@ impl KisoHandle { /// Spawn a new actor pub fn new(state: Config) -> Self { let (actor_sender, actor_receiver) = mpsc::channel(DEFAULT_CHANNEL_SIZE); - let (log_level_update, _) = watch::channel(state.logger.level); + let (log_level_update, _) = watch::channel(state.logger.level.clone()); let mut actor = Actor { handle: actor_receiver, state, @@ -75,7 +75,7 @@ impl KisoHandle { /// /// # Errors /// If communication with actor fails. - pub async fn subscribe_on_log_level(&self) -> Result, Error> { + pub async fn subscribe_on_log_level(&self) -> Result, Error> { let (tx, rx) = oneshot::channel(); let msg = Message::SubscribeOnLogLevel { respond_to: tx }; let _ = self.actor.send(msg).await; @@ -93,7 +93,7 @@ enum Message { respond_to: oneshot::Sender>, }, SubscribeOnLogLevel { - respond_to: oneshot::Sender>, + respond_to: oneshot::Sender>, }, } @@ -111,7 +111,7 @@ struct Actor { // future dynamic parameter, it will require its own `subscribe_on_` function in [`KisoHandle`], // new channel here, and new [`Message`] variant. If boilerplate expands, a more general solution will be // required. However, as of now a single manually written implementation seems optimal. - log_level_update: watch::Sender, + log_level_update: watch::Sender, } impl Actor { @@ -134,7 +134,7 @@ impl Actor { }, respond_to, } => { - let _ = self.log_level_update.send(new_level); + let _ = self.log_level_update.send(new_level.clone()); self.state.logger.level = new_level; let _ = respond_to.send(Ok(())); @@ -155,6 +155,7 @@ mod tests { client_api::{ConfigDTO, Logger as LoggerDTO}, parameters::{actual::Root, user::Root as UserConfig}, }; + use iroha_logger::Level; use super::*; @@ -175,7 +176,7 @@ mod tests { const WATCH_LAG_MILLIS: u64 = 30; let mut config = test_config(); - config.logger.level = INIT_LOG_LEVEL; + config.logger.level = INIT_LOG_LEVEL.into(); let kiso = KisoHandle::new(config); let mut recv = kiso @@ -189,7 +190,7 @@ mod tests { kiso.update_with_dto(ConfigDTO { logger: LoggerDTO { - level: NEW_LOG_LEVEL, + level: NEW_LOG_LEVEL.into(), }, }) .await @@ -200,7 +201,7 @@ mod tests { .expect("Watcher should resolve within timeout") .expect("Watcher should not be closed"); - let value = *recv.borrow_and_update(); - assert_eq!(value, NEW_LOG_LEVEL); + let value = recv.borrow_and_update().clone(); + assert_eq!(value, NEW_LOG_LEVEL.into()); } } diff --git a/genesis/src/lib.rs b/genesis/src/lib.rs index 078ba4bc2f1..49c9526deff 100644 --- a/genesis/src/lib.rs +++ b/genesis/src/lib.rs @@ -148,7 +148,7 @@ fn build_transactions( let parameters = build_transaction( parameters .into_iter() - .map(SetParameter) + .map(SetParameter::new) .map(InstructionBox::from) .collect(), chain_id.clone(), diff --git a/logger/Cargo.toml b/logger/Cargo.toml index 38c5cf90409..b5bfd82d3d1 100644 --- a/logger/Cargo.toml +++ b/logger/Cargo.toml @@ -19,7 +19,7 @@ serde_json = { workspace = true } tracing = { workspace = true } tracing-core = "0.1.32" tracing-futures = { version = "0.2.5", default-features = false, features = ["std-future", "std"] } -tracing-subscriber = { workspace = true, features = ["fmt", "ansi", "json"] } +tracing-subscriber = { workspace = true, features = ["fmt", "ansi", "json", "env-filter"] } tokio = { workspace = true, features = ["sync", "rt", "macros"] } console-subscriber = { version = "0.3.0", optional = true } once_cell = { workspace = true } diff --git a/logger/src/actor.rs b/logger/src/actor.rs index e9e2d91280e..42f75fa8b95 100644 --- a/logger/src/actor.rs +++ b/logger/src/actor.rs @@ -1,10 +1,9 @@ //! Actor encapsulating interaction with logger & telemetry subsystems. -use iroha_config::logger::into_tracing_level; -use iroha_data_model::Level; +use iroha_config::logger::Directives; use tokio::sync::{broadcast, mpsc, oneshot}; use tracing_core::Subscriber; -use tracing_subscriber::{reload, reload::Error as ReloadError}; +use tracing_subscriber::reload::{self, Error as ReloadError}; use crate::telemetry; @@ -16,7 +15,7 @@ pub struct LoggerHandle { impl LoggerHandle { pub(crate) fn new( - handle: reload::Handle, + handle: reload::Handle, telemetry_receiver: mpsc::Receiver, ) -> Self { let (tx, rx) = mpsc::channel(32); @@ -39,7 +38,7 @@ impl LoggerHandle { /// # Errors /// - If reloading on the side of [`reload::Handle`] fails /// - If actor communication fails - pub async fn reload_level(&self, new_value: Level) -> color_eyre::Result<(), Error> { + pub async fn reload_level(&self, new_value: Directives) -> color_eyre::Result<(), Error> { let (tx, rx) = oneshot::channel(); let _ = self .sender @@ -73,7 +72,7 @@ impl LoggerHandle { enum Message { ReloadLevel { - value: Level, + value: Directives, respond_to: oneshot::Sender>, }, SubscribeOnTelemetry { @@ -98,7 +97,7 @@ struct LoggerActor { telemetry_receiver: mpsc::Receiver, telemetry_forwarder_regular: broadcast::Sender, telemetry_forwarder_future: broadcast::Sender, - level_handle: reload::Handle, + level_handle: reload::Handle, } impl LoggerActor { @@ -125,8 +124,8 @@ impl LoggerActor { fn handle_message(&mut self, msg: Message) { match msg { Message::ReloadLevel { value, respond_to } => { - let level = into_tracing_level(value); - let filter = tracing_subscriber::filter::LevelFilter::from_level(level); + let filter = tracing_subscriber::filter::EnvFilter::try_new(value.to_string()) + .expect("INTERNAL BUG: Directives is not valid"); let result = self.level_handle.reload(filter); let _ = respond_to.send(result); } diff --git a/logger/src/lib.rs b/logger/src/lib.rs index 35fd022889d..1378ea9cc1f 100644 --- a/logger/src/lib.rs +++ b/logger/src/lib.rs @@ -13,7 +13,6 @@ use std::{ use actor::LoggerHandle; use color_eyre::{eyre::eyre, Report, Result}; -use iroha_config::logger::into_tracing_level; pub use iroha_config::{ logger::{Format, Level}, parameters::actual::{DevTelemetry as DevTelemetryConfig, Logger as Config}, @@ -42,7 +41,7 @@ fn try_set_logger() -> Result<()> { } /// Configuration needed for [`init_global`]. It is a little extension of [`Config`]. -#[derive(Copy, Clone, Debug)] +#[derive(Clone, Debug)] pub struct InitConfig { base: Config, terminal_colors: bool, @@ -100,7 +99,7 @@ pub fn test_logger() -> LoggerHandle { // `test_logger` simple and also will emphasise isolation which is necessary anyway in // case of singleton mocking (where the logger is the singleton). let config = Config { - level: Level::DEBUG, + level: Level::DEBUG.into(), format: Format::Pretty, }; @@ -121,12 +120,15 @@ pub fn disable_global() -> Result<()> { try_set_logger() } +#[allow(clippy::needless_pass_by_value)] fn step2(config: InitConfig, layer: L) -> Result where L: tracing_subscriber::Layer + Debug + Send + Sync + 'static, { - let level: tracing::Level = into_tracing_level(config.base.level); - let level_filter = tracing_subscriber::filter::LevelFilter::from_level(level); + // NOTE: unfortunately constructing EnvFilter from vector of Directive is not part of public api + let level_filter = + tracing_subscriber::filter::EnvFilter::try_new(config.base.level.to_string()) + .expect("INTERNAL BUG: Directives not valid"); let (level_filter, level_filter_handle) = reload::Layer::new(level_filter); let subscriber = Registry::default() .with(layer) diff --git a/logger/tests/setting_logger.rs b/logger/tests/setting_logger.rs index 2df0de5f548..b933797294e 100644 --- a/logger/tests/setting_logger.rs +++ b/logger/tests/setting_logger.rs @@ -4,7 +4,7 @@ use iroha_logger::{init_global, Config, InitConfig}; async fn setting_logger_twice_fails() { let cfg = Config::default(); - let first = init_global(InitConfig::new(cfg, false)); + let first = init_global(InitConfig::new(cfg.clone(), false)); assert!(first.is_ok()); let second = init_global(InitConfig::new(cfg, false)); diff --git a/schema/gen/src/lib.rs b/schema/gen/src/lib.rs index 0b8fb381f22..4de30ede387 100644 --- a/schema/gen/src/lib.rs +++ b/schema/gen/src/lib.rs @@ -124,9 +124,6 @@ types!( AssetType, AssetValue, AtIndex, - BTreeMap, - BTreeMap, - BTreeMap, BTreeMap, BTreeMap, BTreeSet, diff --git a/torii/pytests/common/schemas/get_configuration_response_schema.json b/torii/pytests/common/schemas/get_configuration_response_schema.json index 3e7ef8e95e5..bcd1bcfa8c9 100644 --- a/torii/pytests/common/schemas/get_configuration_response_schema.json +++ b/torii/pytests/common/schemas/get_configuration_response_schema.json @@ -7,7 +7,7 @@ "properties": { "level": { "type": "string", - "enum": ["TRACE", "DEBUG", "INFO", "WARN", "ERROR"] + "enum": ["trace", "debug", "info", "warn", "error"] } }, "required": ["level"] diff --git a/torii/pytests/test/configuration/test_get_configuration.py b/torii/pytests/test/configuration/test_get_configuration.py index 173c43471ff..9e4eaef2fca 100644 --- a/torii/pytests/test/configuration/test_get_configuration.py +++ b/torii/pytests/test/configuration/test_get_configuration.py @@ -10,7 +10,7 @@ from common.settings import BASE_URL -valid_log_levels = ["TRACE", "DEBUG", "INFO", "WARN", "ERROR"] +valid_log_levels = ["trace", "debug", "info", "warn", "error"] @pytest.fixture(scope="function", autouse=True) diff --git a/torii/pytests/test/configuration/test_post_configuration.py b/torii/pytests/test/configuration/test_post_configuration.py index 6c74c9ed216..06f917d05df 100644 --- a/torii/pytests/test/configuration/test_post_configuration.py +++ b/torii/pytests/test/configuration/test_post_configuration.py @@ -7,7 +7,7 @@ from common.settings import BASE_URL -valid_log_levels = ["TRACE", "DEBUG", "INFO", "WARN", "ERROR"] +valid_log_levels = ["trace", "debug", "info", "warn", "error"] @pytest.fixture(scope="function", autouse=True) @@ -24,7 +24,7 @@ def test_post_configuration_invalid_data(): ): response = requests.post( f"{BASE_URL}/configuration", - json={"logger": {"level": "invalid"}}, + json={"logger": {"level": "iroha_core=invalid"}}, ) with allure.step("THEN the response status code should be a client error"):