diff --git a/Cargo.lock b/Cargo.lock index 07f591bd0..fc9c81eed 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2958,6 +2958,7 @@ dependencies = [ "fvm_ipld_encoding", "fvm_shared", "ipc-api", + "ipc-observability", "ipc-provider", "lazy_static", "multiaddr", @@ -5056,9 +5057,12 @@ dependencies = [ name = "ipc-observability" version = "0.1.0" dependencies = [ + "anyhow", "hex", "lazy_static", "prometheus", + "serde", + "serde_with 2.3.3", "tracing", "tracing-appender", "tracing-subscriber", diff --git a/fendermint/app/options/src/lib.rs b/fendermint/app/options/src/lib.rs index 64d7c2b77..08c50fbbb 100644 --- a/fendermint/app/options/src/lib.rs +++ b/fendermint/app/options/src/lib.rs @@ -7,9 +7,7 @@ use clap::{Args, Parser, Subcommand}; use config::ConfigArgs; use debug::DebugArgs; use fvm_shared::address::Network; -use ipc_observability::traces::FileLayerConfig; use lazy_static::lazy_static; -use tracing_subscriber::EnvFilter; use self::{ eth::EthArgs, genesis::GenesisArgs, key::KeyArgs, materializer::MaterializerArgs, rpc::RpcArgs, @@ -25,10 +23,8 @@ pub mod materializer; pub mod rpc; pub mod run; -mod log; mod parse; -use log::{parse_log_level, parse_rotation_kind, LogLevel, RotationKind}; use parse::parse_network; lazy_static! { @@ -103,70 +99,10 @@ pub struct Options { #[arg(long, env = "FM_CONFIG_DIR")] config_dir: Option, - // TODO Karel - move all FM_LOG_FILE* flags to a configuration file instead - - // Enable logging to a file. - #[arg(long, env = "FM_LOG_FILE_ENABLED")] - pub log_file_enabled: Option, - - /// Set a custom directory for ipc log files. - #[arg(long, env = "FM_LOG_FILE_DIR")] - pub log_dir: Option, - - #[arg(long, env = "FM_LOG_FILE_MAX_FILES")] - pub max_log_files: Option, - - #[arg( - long, - default_value = "daily", - value_enum, - env = "FM_LOG_FILE_ROTATION", - help = "The kind of rotation to use for log files. Options: minutely, hourly, daily, never.", - value_parser = parse_rotation_kind, - )] - pub log_files_rotation: Option, - - #[arg( - long, - env = "FM_LOG_FILE_DOMAINS_FILTER", - help = "Filter log events by domains. Only events from the specified domains will be logged. Comma separated.", - value_delimiter = ',' - )] - pub domains_filter: Option>, - - #[arg( - long, - env = "FM_LOG_FILE_EVENTS_FILTER", - help = "Filter log events by name. Only events with the specified names will be logged. Comma separated.", - value_delimiter = ',' - )] - pub events_filter: Option>, - /// Optionally override the default configuration. #[arg(short, long, default_value = "dev")] pub mode: String, - /// Set the logging level of the console. - #[arg( - short = 'l', - long, - default_value = "info", - value_enum, - env = "FM_LOG_LEVEL", - help = "Standard log levels, or a comma separated list of filters, e.g. 'debug,tower_abci=warn,libp2p::gossipsub=info'", - value_parser = parse_log_level, - )] - log_level: LogLevel, - - /// Set the logging level of the log file. If missing, it defaults to the same level as the console. - #[arg( - long, - value_enum, - env = "FM_LOG_FILE_LEVEL", - value_parser = parse_log_level, - )] - log_file_level: Option, - /// Global options repeated here for discoverability, so they show up in `--help` among the others. #[command(flatten)] pub global: GlobalArgs, @@ -176,35 +112,6 @@ pub struct Options { } impl Options { - /// Tracing filter for the console. - /// - /// Coalescing everything into a filter instead of either a level or a filter - /// because the `tracing_subscriber` setup methods like `with_filter` and `with_level` - /// produce different static types and it's not obvious how to use them as alternatives. - pub fn log_console_filter(&self) -> anyhow::Result { - self.log_level.to_filter() - } - - /// Tracing filter for the log file. - pub fn log_file_filter(&self) -> anyhow::Result { - if let Some(ref level) = self.log_file_level { - level.to_filter() - } else { - self.log_console_filter() - } - } - - pub fn log_file_config(&self) -> FileLayerConfig { - FileLayerConfig { - enabled: self.log_file_enabled.unwrap_or(false), - directory: self.log_dir.clone(), - max_log_files: self.max_log_files, - rotation: self.log_files_rotation.clone(), - domain_filter: self.domains_filter.clone(), - events_filter: self.events_filter.clone(), - } - } - /// Path to the configuration directories. /// /// If not specified then returns the default under the home directory. @@ -248,7 +155,6 @@ mod tests { use crate::*; use clap::Parser; use fvm_shared::address::Network; - use tracing::level_filters::LevelFilter; /// Set some env vars, run a fallible piece of code, then unset the variables otherwise they would affect the next test. pub fn with_env_vars(vars: &[(&str, &str)], f: F) -> T @@ -318,27 +224,6 @@ mod tests { assert!(e.to_string().contains("Usage:"), "unexpected help: {e}"); } - #[test] - fn parse_log_level() { - let parse_filter = |cmd: &str| { - let opts: Options = Options::parse_from(cmd.split_ascii_whitespace()); - opts.log_console_filter().expect("filter should parse") - }; - - let assert_level = |cmd: &str, level: LevelFilter| { - let filter = parse_filter(cmd); - assert_eq!(filter.max_level_hint(), Some(level)) - }; - - assert_level("fendermint --log-level debug run", LevelFilter::DEBUG); - assert_level("fendermint --log-level off run", LevelFilter::OFF); - assert_level( - "fendermint --log-level libp2p=warn,error run", - LevelFilter::WARN, - ); - assert_level("fendermint --log-level info run", LevelFilter::INFO); - } - #[test] fn parse_invalid_log_level() { // NOTE: `nonsense` in itself is interpreted as a target. Maybe we should mandate at least `=` in it? diff --git a/fendermint/app/options/src/log.rs b/fendermint/app/options/src/log.rs deleted file mode 100644 index bf2ae5f53..000000000 --- a/fendermint/app/options/src/log.rs +++ /dev/null @@ -1,93 +0,0 @@ -// Copyright 2022-2024 Protocol Labs -// SPDX-License-Identifier: Apache-2.0, MIT - -use clap::{builder::PossibleValue, ValueEnum}; - -use lazy_static::lazy_static; -use tracing_subscriber::EnvFilter; - -pub use ipc_observability::traces::RotationKind; - -/// Standard log levels, or something we can pass to -/// -/// To be fair all of these could be handled by the `EnvFilter`, even `off`, -/// however I also wanted to leave it here as an example of implementing `ValueEnum` manually, -/// and perhaps we have simpler usecases where we only want to simply match levels. -#[derive(Debug, Clone)] -pub enum LogLevel { - Off, - Error, - Warn, - Info, - Debug, - Trace, - Filter(String), -} - -impl LogLevel { - pub fn as_str(&self) -> &str { - match self { - LogLevel::Off => "off", - LogLevel::Error => "error", - LogLevel::Warn => "warn", - LogLevel::Info => "info", - LogLevel::Debug => "debug", - LogLevel::Trace => "trace", - LogLevel::Filter(s) => s.as_str(), - } - } - - pub fn to_filter(&self) -> anyhow::Result { - // At this point the filter should have been parsed before, - // but if we created a log level directly, it can fail. - // We fail if it doesn't parse because presumably we _want_ to see those things. - Ok(EnvFilter::try_new(self.as_str())?) - } -} - -impl ValueEnum for LogLevel { - fn value_variants<'a>() -> &'a [Self] { - lazy_static! { - static ref VARIANTS: Vec = vec![ - LogLevel::Off, - LogLevel::Error, - LogLevel::Warn, - LogLevel::Info, - LogLevel::Debug, - LogLevel::Trace, - ]; - } - - &VARIANTS - } - - fn to_possible_value(&self) -> Option { - if let LogLevel::Filter(_) = self { - None - } else { - Some(PossibleValue::new(self.as_str().to_string())) - } - } -} - -pub fn parse_log_level(s: &str) -> Result { - if let Ok(lvl) = ValueEnum::from_str(s, true) { - return Ok(lvl); - } - // `EnvFilter` is not `Clone`, so we can't store it, but we can use it to validate early. - if let Err(e) = EnvFilter::try_new(s) { - Err(e.to_string()) - } else { - Ok(LogLevel::Filter(s.to_string())) - } -} - -pub fn parse_rotation_kind(s: &str) -> Result { - match s { - "minutely" => Ok(RotationKind::Minutely), - "hourly" => Ok(RotationKind::Hourly), - "daily" => Ok(RotationKind::Daily), - "never" => Ok(RotationKind::Never), - _ => Err(format!("invalid rotation kind: {}", s)), - } -} diff --git a/fendermint/app/settings/Cargo.toml b/fendermint/app/settings/Cargo.toml index e4f2680de..0b012a440 100644 --- a/fendermint/app/settings/Cargo.toml +++ b/fendermint/app/settings/Cargo.toml @@ -26,6 +26,7 @@ fvm_shared = { workspace = true } fvm_ipld_encoding = { workspace = true } ipc-api = { workspace = true } ipc-provider = { workspace = true } +ipc-observability = { workspace = true } tracing = { workspace = true } fendermint_vm_encoding = { path = "../../vm/encoding" } diff --git a/fendermint/app/settings/src/eth.rs b/fendermint/app/settings/src/eth.rs index d004296fe..ead251077 100644 --- a/fendermint/app/settings/src/eth.rs +++ b/fendermint/app/settings/src/eth.rs @@ -6,6 +6,8 @@ use serde::Deserialize; use serde_with::{serde_as, DurationSeconds}; use std::time::Duration; +use ipc_observability::traces_settings::TracesSettings; + use crate::{IsHumanReadable, MetricsSettings, SocketAddress}; /// Ethereum API facade settings. @@ -19,6 +21,7 @@ pub struct EthSettings { pub gas: GasOpt, pub max_nonce_gap: u64, pub metrics: MetricsSettings, + pub tracing: TracesSettings, } #[serde_as] diff --git a/fendermint/app/settings/src/lib.rs b/fendermint/app/settings/src/lib.rs index e83f53c05..6eb5c2f76 100644 --- a/fendermint/app/settings/src/lib.rs +++ b/fendermint/app/settings/src/lib.rs @@ -22,6 +22,7 @@ use fendermint_vm_topdown::BlockHeight; use self::eth::EthSettings; use self::fvm::FvmSettings; use self::resolver::ResolverSettings; +use ipc_observability::traces_settings::TracesSettings; use ipc_provider::config::deserialize::deserialize_eth_address_from_str; pub mod eth; @@ -286,6 +287,7 @@ pub struct Settings { pub broadcast: BroadcastSettings, pub ipc: IpcSettings, pub testing: Option, + pub tracing: TracesSettings, } impl Settings { diff --git a/fendermint/app/src/cmd/eth.rs b/fendermint/app/src/cmd/eth.rs index 2f67aea18..b479c2dc8 100644 --- a/fendermint/app/src/cmd/eth.rs +++ b/fendermint/app/src/cmd/eth.rs @@ -5,6 +5,7 @@ use std::time::Duration; use anyhow::Context; use fendermint_eth_api::HybridClient; +use ipc_observability::traces::set_global_tracing_subscriber; use tracing::info; use crate::{ @@ -34,6 +35,8 @@ cmd! { /// Run the Ethereum API facade. async fn run(settings: EthSettings, client: HybridClient) -> anyhow::Result<()> { + // TOOO kare - set up tracing + if settings.metrics.enabled { info!("metrics enabled"); diff --git a/fendermint/app/src/cmd/mod.rs b/fendermint/app/src/cmd/mod.rs index e32592459..fbc756f5d 100644 --- a/fendermint/app/src/cmd/mod.rs +++ b/fendermint/app/src/cmd/mod.rs @@ -10,6 +10,9 @@ use crate::{ use anyhow::{anyhow, Context}; use async_trait::async_trait; +use ipc_observability::traces::create_subscriber; +use tracing::subscriber; + pub mod config; pub mod debug; pub mod eth; @@ -81,10 +84,13 @@ fn settings(opts: &Options) -> anyhow::Result { d => d, }; - tracing::info!( - path = config_dir.to_string_lossy().into_owned(), - "reading configuration" - ); + subscriber::with_default(create_subscriber(), || { + tracing::info!( + path = config_dir.to_string_lossy().into_owned(), + "reading configuration" + ) + }); + let settings = Settings::new(&config_dir, &opts.home_dir, &opts.mode).context("error parsing settings")?; diff --git a/fendermint/app/src/cmd/run.rs b/fendermint/app/src/cmd/run.rs index 87c1e11cd..38f220c5f 100644 --- a/fendermint/app/src/cmd/run.rs +++ b/fendermint/app/src/cmd/run.rs @@ -39,6 +39,8 @@ use tracing::info; use crate::cmd::key::read_secret_key; use crate::{cmd, options::run::RunArgs, settings::Settings}; +use ipc_observability::traces::set_global_tracing_subscriber; + cmd! { RunArgs(self, settings) { run(settings).await @@ -59,6 +61,8 @@ namespaces! { /// /// This method acts as our composition root. async fn run(settings: Settings) -> anyhow::Result<()> { + let _work_guard = set_global_tracing_subscriber(&settings.tracing)?; + let tendermint_rpc_url = settings.tendermint_rpc_url()?; tracing::info!("Connecting to Tendermint at {tendermint_rpc_url}"); diff --git a/fendermint/app/src/main.rs b/fendermint/app/src/main.rs index 117fa3121..81af83988 100644 --- a/fendermint/app/src/main.rs +++ b/fendermint/app/src/main.rs @@ -3,19 +3,11 @@ pub use fendermint_app_options as options; pub use fendermint_app_settings as settings; -use ipc_observability::traces::{register_tracing_subscriber, WorkerGuard}; -mod cmd; - -fn init_tracing(opts: &options::Options) -> Option { - let console_filter = opts - .log_console_filter() - .expect("invalid console level filter"); - let file_filter = opts.log_file_filter().expect("invalid file level filter"); - let file_config = opts.log_file_config(); +use ipc_observability::traces::create_subscriber; +use tracing::subscriber; - register_tracing_subscriber(console_filter, file_filter, file_config) -} +mod cmd; /// Install a panic handler that prints stuff to the logs, otherwise it only shows up in the console. fn init_panic_handler() { @@ -28,11 +20,13 @@ fn init_panic_handler() { // let stacktrace = std::backtrace::Backtrace::capture(); let stacktrace = std::backtrace::Backtrace::force_capture(); - tracing::error!( - stacktrace = stacktrace.to_string(), - info = info.to_string(), - "panicking" - ); + subscriber::with_default(create_subscriber(), || { + tracing::error!( + "panic occurred: {error:?}\n{stacktrace}", + error = info, + stacktrace = stacktrace + ) + }); // We could exit the application if any of the background tokio tasks panic. // However, they are not necessarily critical processes, the chain might still make progress. @@ -44,12 +38,12 @@ fn init_panic_handler() { async fn main() { let opts = options::parse(); - let _guard = init_tracing(&opts); - init_panic_handler(); if let Err(e) = cmd::exec(&opts).await { - tracing::error!("failed to execute {:?}: {e:?}", opts); + subscriber::with_default(create_subscriber(), || { + tracing::error!("failed to execute {:?}: {e:?}", opts) + }); std::process::exit(fendermint_app::AppExitCode::UnknownError as i32); } } diff --git a/ipc/observability/Cargo.toml b/ipc/observability/Cargo.toml index de39eba22..086bcb22b 100644 --- a/ipc/observability/Cargo.toml +++ b/ipc/observability/Cargo.toml @@ -13,3 +13,6 @@ tracing = { workspace = true } tracing-subscriber = { workspace = true } tracing-appender = { workspace = true } hex = { workspace = true } +serde = { workspace = true } +serde_with = { workspace = true } +anyhow = { workspace = true } diff --git a/ipc/observability/src/lib.rs b/ipc/observability/src/lib.rs index 504c256a9..16871739b 100644 --- a/ipc/observability/src/lib.rs +++ b/ipc/observability/src/lib.rs @@ -6,6 +6,7 @@ pub mod traces; mod tracing_layers; pub use lazy_static::lazy_static; pub mod serde; +pub mod traces_settings; use std::fmt::Debug; use tracing::{debug, error, info, trace, warn}; diff --git a/ipc/observability/src/traces.rs b/ipc/observability/src/traces.rs index ae14ad90f..6ba306c65 100644 --- a/ipc/observability/src/traces.rs +++ b/ipc/observability/src/traces.rs @@ -2,76 +2,37 @@ // SPDX-License-Identifier: Apache-2.0, MIT use std::num::NonZeroUsize; -use std::path::PathBuf; -use std::str::FromStr; +use tracing::Level; pub use tracing_appender::non_blocking; pub use tracing_appender::non_blocking::WorkerGuard; -use tracing_appender::rolling::{RollingFileAppender, Rotation}; -use tracing_subscriber::filter::EnvFilter; -use tracing_subscriber::{fmt, layer::SubscriberExt, Layer}; +use tracing_appender::rolling::RollingFileAppender; +use tracing_subscriber::{fmt, fmt::Subscriber, layer::SubscriberExt, Layer}; +use crate::traces_settings::{FileLayerSettings, TracesSettings}; use crate::tracing_layers::DomainEventFilterLayer; +use anyhow::Result; -#[derive(Debug, Clone)] -pub enum RotationKind { - Minutely, - Hourly, - Daily, - Never, -} - -impl RotationKind { - fn to_tracing_rotation(&self) -> Rotation { - match self { - RotationKind::Minutely => Rotation::DAILY, - RotationKind::Hourly => Rotation::HOURLY, - RotationKind::Daily => Rotation::DAILY, - RotationKind::Never => Rotation::NEVER, - } - } -} - -impl FromStr for RotationKind { - type Err = String; - - fn from_str(s: &str) -> Result { - match s { - "minutely" => Ok(RotationKind::Minutely), - "hourly" => Ok(RotationKind::Hourly), - "daily" => Ok(RotationKind::Daily), - "never" => Ok(RotationKind::Never), - _ => Err(format!("invalid rotation kind: {}", s)), - } - } -} - -#[derive(Default)] -pub struct FileLayerConfig { - pub enabled: bool, - pub directory: Option, - pub max_log_files: Option, - pub rotation: Option, - pub domain_filter: Option>, - pub events_filter: Option>, +pub fn create_subscriber() -> Subscriber { + tracing_subscriber::FmtSubscriber::builder() + .with_max_level(Level::TRACE) + .with_target(false) + .with_file(true) + .with_line_number(true) + // builds the subscriber. + .finish() } -// Register a tracing subscriber with the given options -// Returns a guard that must be kept alive for the duration of the program (because it's non-blocking and needs to flush) -pub fn register_tracing_subscriber( - console_level_filter: EnvFilter, - file_level_filter: EnvFilter, - file_opts: FileLayerConfig, -) -> Option { +pub fn set_global_tracing_subscriber(config: &TracesSettings) -> Result { // log all traces to stderr (reserving stdout for any actual output such as from the CLI commands) let console_layer = fmt::layer() .with_writer(std::io::stderr) .with_target(false) .with_file(true) .with_line_number(true) - .with_filter(console_level_filter); + .with_filter(config.console.level.to_filter()?); - let (file_layer, file_guard) = if file_opts.enabled { - let (non_blocking, file_guard) = non_blocking(file_appender_from_opts(&file_opts)); + let (file_layer, file_guard) = if config.file.enabled { + let (non_blocking, file_guard) = non_blocking(create_file_appender(&config.file)); let file_layer = fmt::layer() .json() @@ -80,13 +41,18 @@ pub fn register_tracing_subscriber( .with_target(false) .with_file(true) .with_line_number(true) - .with_filter(file_level_filter); + .with_filter(config.file.level.to_filter()?); - let domains = file_opts + let domains = config + .file .domain_filter + .as_ref() .map(|v| v.iter().map(|s| s.to_string()).collect()); - let events = file_opts + + let events = config + .file .events_filter + .as_ref() .map(|v| v.iter().map(|s| s.to_string()).collect()); let file_layer = DomainEventFilterLayer::new(domains, events, file_layer); @@ -103,17 +69,17 @@ pub fn register_tracing_subscriber( tracing::subscriber::set_global_default(registry) .expect("Unable to set a global tracing subscriber"); - file_guard + file_guard.ok_or_else(|| anyhow::anyhow!("file guard not created")) } -fn file_appender_from_opts(opts: &FileLayerConfig) -> RollingFileAppender { - let directory = opts +fn create_file_appender(settings: &FileLayerSettings) -> RollingFileAppender { + let directory = settings .directory .as_deref() .expect("missing file log directory"); let mut appender = RollingFileAppender::builder().filename_suffix("traces"); - if let Some(max_log_files) = opts.max_log_files { + if let Some(max_log_files) = settings.max_log_files { println!("max log files: {}", max_log_files); appender = appender.max_log_files( @@ -123,7 +89,7 @@ fn file_appender_from_opts(opts: &FileLayerConfig) -> RollingFileAppender { ); }; - if let Some(rotation_kind) = &opts.rotation { + if let Some(rotation_kind) = &settings.rotation { println!("rotation kind: {:?}", rotation_kind); appender = appender.rotation(rotation_kind.to_tracing_rotation()); }; diff --git a/ipc/observability/src/traces_settings.rs b/ipc/observability/src/traces_settings.rs new file mode 100644 index 000000000..854499e1c --- /dev/null +++ b/ipc/observability/src/traces_settings.rs @@ -0,0 +1,111 @@ +// Copyright 2022-2024 Protocol Labs +// SPDX-License-Identifier: Apache-2.0, MIT + +use serde::Deserialize; +use serde_with::serde_as; +use std::path::PathBuf; +use std::str::FromStr; +use tracing_appender::rolling::Rotation; +use tracing_subscriber::filter::EnvFilter; + +#[serde_as] +#[derive(Debug, Deserialize, Clone, Default)] +pub enum LogLevel { + Off, + Error, + Warn, + Info, + Debug, + #[default] + Trace, +} + +impl LogLevel { + pub fn as_str(&self) -> &str { + match self { + LogLevel::Off => "off", + LogLevel::Error => "error", + LogLevel::Warn => "warn", + LogLevel::Info => "info", + LogLevel::Debug => "debug", + LogLevel::Trace => "trace", + } + } + + pub fn to_filter(&self) -> anyhow::Result { + // At this point the filter should have been parsed before, + // but if we created a log level directly, it can fail. + // We fail if it doesn't parse because presumably we _want_ to see those things. + Ok(EnvFilter::try_new(self.as_str())?) + } +} + +#[serde_as] +#[derive(Debug, Deserialize, Clone)] +pub enum RotationKind { + Minutely, + Hourly, + Daily, + Never, +} + +impl RotationKind { + pub fn to_tracing_rotation(&self) -> Rotation { + match self { + RotationKind::Minutely => Rotation::DAILY, + RotationKind::Hourly => Rotation::HOURLY, + RotationKind::Daily => Rotation::DAILY, + RotationKind::Never => Rotation::NEVER, + } + } +} + +impl FromStr for RotationKind { + type Err = String; + + fn from_str(s: &str) -> Result { + match s { + "minutely" => Ok(RotationKind::Minutely), + "hourly" => Ok(RotationKind::Hourly), + "daily" => Ok(RotationKind::Daily), + "never" => Ok(RotationKind::Never), + _ => Err(format!("invalid rotation kind: {}", s)), + } + } +} + +#[serde_as] +#[derive(Debug, Deserialize, Clone)] +pub struct TracesSettings { + pub console: ConsoleLayerSettings, + pub file: FileLayerSettings, +} + +#[serde_as] +#[derive(Debug, Deserialize, Clone)] +pub struct ConsoleLayerSettings { + pub enabled: bool, + pub level: LogLevel, +} + +impl Default for ConsoleLayerSettings { + fn default() -> Self { + ConsoleLayerSettings { + enabled: true, + level: LogLevel::default(), + } + } +} + +#[serde_as] +#[derive(Debug, Deserialize, Clone, Default)] + +pub struct FileLayerSettings { + pub enabled: bool, + pub level: LogLevel, + pub directory: Option, + pub max_log_files: Option, + pub rotation: Option, + pub domain_filter: Option>, + pub events_filter: Option>, +}