From ccde3868c93f99ed4903ead8b7fb7964263dfd03 Mon Sep 17 00:00:00 2001 From: Karel Moravec Date: Thu, 4 Jul 2024 20:15:27 +0200 Subject: [PATCH 01/33] feat: introduce metrics crate --- Cargo.lock | 10 +++ Cargo.toml | 2 +- fendermint/app/Cargo.toml | 2 + fendermint/ipc-metrics/Cargo.toml | 12 ++++ fendermint/ipc-metrics/src/lib.rs | 38 ++++++++++ fendermint/ipc-metrics/src/register.rs | 96 ++++++++++++++++++++++++++ 6 files changed, 159 insertions(+), 1 deletion(-) create mode 100644 fendermint/ipc-metrics/Cargo.toml create mode 100644 fendermint/ipc-metrics/src/lib.rs create mode 100644 fendermint/ipc-metrics/src/register.rs diff --git a/Cargo.lock b/Cargo.lock index fa154cfc0..2ad6fa0ad 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2886,6 +2886,7 @@ dependencies = [ "fvm_shared", "hex", "ipc-api", + "ipc-metrics", "ipc-observability", "ipc-provider", "ipc_ipld_resolver", @@ -5062,6 +5063,15 @@ dependencies = [ "zeroize", ] +[[package]] +name = "ipc-metrics" +version = "0.1.0" +dependencies = [ + "tracing", + "tracing-appender", + "tracing-subscriber", +] + [[package]] name = "ipc-observability" version = "0.1.0" diff --git a/Cargo.toml b/Cargo.toml index bb28ffb43..ff7cc3ed0 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -34,7 +34,7 @@ members = [ "fendermint/tracing", "fendermint/vm/*", "fendermint/actors", - "fendermint/actors/chainmetadata", + "fendermint/actors/chainmetadata", "fendermint/ipc-metrics", ] [workspace.package] diff --git a/fendermint/app/Cargo.toml b/fendermint/app/Cargo.toml index b524d15b8..1bc91ff17 100644 --- a/fendermint/app/Cargo.toml +++ b/fendermint/app/Cargo.toml @@ -63,6 +63,8 @@ fendermint_vm_message = { path = "../vm/message" } fendermint_vm_resolver = { path = "../vm/resolver" } fendermint_vm_snapshot = { path = "../vm/snapshot" } fendermint_vm_topdown = { path = "../vm/topdown" } +ipc-metrics = { path = "../ipc-metrics" } + fvm = { workspace = true } diff --git a/fendermint/ipc-metrics/Cargo.toml b/fendermint/ipc-metrics/Cargo.toml new file mode 100644 index 000000000..df239490b --- /dev/null +++ b/fendermint/ipc-metrics/Cargo.toml @@ -0,0 +1,12 @@ +[package] +name = "ipc-metrics" +version = "0.1.0" +authors.workspace = true +edition.workspace = true +license.workspace = true +license-file.workspace = true + +[dependencies] +tracing = { workspace = true } +tracing-subscriber = { workspace = true } +tracing-appender = { workspace = true } diff --git a/fendermint/ipc-metrics/src/lib.rs b/fendermint/ipc-metrics/src/lib.rs new file mode 100644 index 000000000..d2329d0da --- /dev/null +++ b/fendermint/ipc-metrics/src/lib.rs @@ -0,0 +1,38 @@ +// Copyright 2022-2024 Protocol Labs +// SPDX-License-Identifier: Apache-2.0, MIT + +pub mod register; + +use std::fmt::Display; +use tracing::{debug, error, info, trace, warn}; + +pub trait Recordable { + fn record_metrics(&self); +} + +pub enum Level { + Trace, + Debug, + Info, + Warn, + Error, +} + +pub trait Traceable { + fn level(&self) -> Level; +} + +pub fn emit(trace: T) +where + T: Recordable + Traceable + Display, +{ + match trace.level() { + Level::Trace => trace!(event = %trace), + Level::Debug => debug!(event = %trace), + Level::Info => info!(event = %trace), + Level::Warn => warn!(event = %trace), + Level::Error => error!(event = %trace), + } + + trace.record_metrics(); +} diff --git a/fendermint/ipc-metrics/src/register.rs b/fendermint/ipc-metrics/src/register.rs new file mode 100644 index 000000000..f4334ad21 --- /dev/null +++ b/fendermint/ipc-metrics/src/register.rs @@ -0,0 +1,96 @@ +// Copyright 2022-2024 Protocol Labs +// SPDX-License-Identifier: Apache-2.0, MIT + +use std::num::NonZeroUsize; +pub use tracing_appender::non_blocking::WorkerGuard; +use tracing_appender::rolling::{RollingFileAppender, Rotation}; +use tracing_subscriber::{fmt, layer::SubscriberExt, EnvFilter, Layer}; + +#[derive(Default)] +pub struct JournalOpts<'a> { + pub enabled: bool, + pub directory: Option<&'a str>, + pub max_log_files: Option, + pub rotation: Option<&'a str>, + pub filters: Option>, +} + +fn appender_from_opts(opts: &JournalOpts<'_>) -> RollingFileAppender { + let directory = opts.directory.expect("journal directory must be set"); + let mut appender = RollingFileAppender::builder().filename_suffix("journal"); + + if let Some(max_log_files) = opts.max_log_files { + appender = appender.max_log_files( + NonZeroUsize::new(max_log_files) + .expect("max_log_files must be greater than 0") + .into(), + ); + }; + + if let Some(rotation_str) = opts.rotation { + let rotation = match rotation_str { + "minutely" => Rotation::DAILY, + "hourly" => Rotation::HOURLY, + "daily" => Rotation::DAILY, + "never" => Rotation::NEVER, + _ => panic!("invalid rotation: {}", rotation_str), + }; + + appender = appender.rotation(rotation); + }; + + appender + .build(directory) + .expect("failed to create journal appender") +} + +// 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_filter: EnvFilter, + opts: &JournalOpts<'_>, +) -> Option { + // log all traces to stderr (reserving stdout for any actual output such as from the CLI commands) + // TODO Karel - do we want to always allow it or should we make it configurable? + let console_layer = fmt::layer() + .with_writer(std::io::stderr) + .with_target(false) + .with_file(true) + .with_line_number(true) + .with_filter(console_filter); + + // add a file layer if log_dir is set + let (file_layer, file_guard) = if opts.enabled { + let (non_blocking, file_guard) = tracing_appender::non_blocking(appender_from_opts(opts)); + + let mut file_filter = EnvFilter::from_default_env(); + + if let Some(domain_filter) = &opts.filters { + for domain in domain_filter { + file_filter = file_filter.add_directive(domain.parse().unwrap()); + } + } + + let file_layer = fmt::layer() + .json() + .with_writer(non_blocking) + .with_span_events(fmt::format::FmtSpan::CLOSE) + .with_target(false) + .with_file(true) + .with_line_number(true) + .with_filter(file_filter); + + (Some(file_layer), Some(file_guard)) + } else { + (None, None) + }; + + let registry = tracing_subscriber::registry() + .with(console_layer) + .with(file_layer); + + tracing::subscriber::set_global_default(registry) + .expect("Unable to set a global tracing subscriber"); + + file_guard +} From 6facf63dc2c9abe20e83ebdb2b2349fb2603c3ed Mon Sep 17 00:00:00 2001 From: Karel Moravec Date: Fri, 5 Jul 2024 17:08:12 +0200 Subject: [PATCH 02/33] feat: improve library with macros, add top down events --- Cargo.lock | 4 +- Cargo.toml | 4 +- fendermint/app/Cargo.toml | 1 - fendermint/ipc-metrics/Cargo.toml | 12 ---- fendermint/ipc-metrics/src/lib.rs | 38 ---------- fendermint/ipc-metrics/src/register.rs | 96 -------------------------- 6 files changed, 5 insertions(+), 150 deletions(-) delete mode 100644 fendermint/ipc-metrics/Cargo.toml delete mode 100644 fendermint/ipc-metrics/src/lib.rs delete mode 100644 fendermint/ipc-metrics/src/register.rs diff --git a/Cargo.lock b/Cargo.lock index 2ad6fa0ad..cbc2f3f1b 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -5064,9 +5064,11 @@ dependencies = [ ] [[package]] -name = "ipc-metrics" +name = "ipc-observability" version = "0.1.0" dependencies = [ + "lazy_static", + "prometheus", "tracing", "tracing-appender", "tracing-subscriber", diff --git a/Cargo.toml b/Cargo.toml index ff7cc3ed0..154dd5700 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -1,5 +1,4 @@ [workspace] -resolver = "2" members = [ # contracts "contracts/binding", @@ -34,7 +33,7 @@ members = [ "fendermint/tracing", "fendermint/vm/*", "fendermint/actors", - "fendermint/actors/chainmetadata", "fendermint/ipc-metrics", + "fendermint/actors/chainmetadata", ] [workspace.package] @@ -248,3 +247,4 @@ opt-level = "z" strip = true codegen-units = 1 incremental = false +resolver = "2" diff --git a/fendermint/app/Cargo.toml b/fendermint/app/Cargo.toml index 1bc91ff17..8e884e69f 100644 --- a/fendermint/app/Cargo.toml +++ b/fendermint/app/Cargo.toml @@ -63,7 +63,6 @@ fendermint_vm_message = { path = "../vm/message" } fendermint_vm_resolver = { path = "../vm/resolver" } fendermint_vm_snapshot = { path = "../vm/snapshot" } fendermint_vm_topdown = { path = "../vm/topdown" } -ipc-metrics = { path = "../ipc-metrics" } diff --git a/fendermint/ipc-metrics/Cargo.toml b/fendermint/ipc-metrics/Cargo.toml deleted file mode 100644 index df239490b..000000000 --- a/fendermint/ipc-metrics/Cargo.toml +++ /dev/null @@ -1,12 +0,0 @@ -[package] -name = "ipc-metrics" -version = "0.1.0" -authors.workspace = true -edition.workspace = true -license.workspace = true -license-file.workspace = true - -[dependencies] -tracing = { workspace = true } -tracing-subscriber = { workspace = true } -tracing-appender = { workspace = true } diff --git a/fendermint/ipc-metrics/src/lib.rs b/fendermint/ipc-metrics/src/lib.rs deleted file mode 100644 index d2329d0da..000000000 --- a/fendermint/ipc-metrics/src/lib.rs +++ /dev/null @@ -1,38 +0,0 @@ -// Copyright 2022-2024 Protocol Labs -// SPDX-License-Identifier: Apache-2.0, MIT - -pub mod register; - -use std::fmt::Display; -use tracing::{debug, error, info, trace, warn}; - -pub trait Recordable { - fn record_metrics(&self); -} - -pub enum Level { - Trace, - Debug, - Info, - Warn, - Error, -} - -pub trait Traceable { - fn level(&self) -> Level; -} - -pub fn emit(trace: T) -where - T: Recordable + Traceable + Display, -{ - match trace.level() { - Level::Trace => trace!(event = %trace), - Level::Debug => debug!(event = %trace), - Level::Info => info!(event = %trace), - Level::Warn => warn!(event = %trace), - Level::Error => error!(event = %trace), - } - - trace.record_metrics(); -} diff --git a/fendermint/ipc-metrics/src/register.rs b/fendermint/ipc-metrics/src/register.rs deleted file mode 100644 index f4334ad21..000000000 --- a/fendermint/ipc-metrics/src/register.rs +++ /dev/null @@ -1,96 +0,0 @@ -// Copyright 2022-2024 Protocol Labs -// SPDX-License-Identifier: Apache-2.0, MIT - -use std::num::NonZeroUsize; -pub use tracing_appender::non_blocking::WorkerGuard; -use tracing_appender::rolling::{RollingFileAppender, Rotation}; -use tracing_subscriber::{fmt, layer::SubscriberExt, EnvFilter, Layer}; - -#[derive(Default)] -pub struct JournalOpts<'a> { - pub enabled: bool, - pub directory: Option<&'a str>, - pub max_log_files: Option, - pub rotation: Option<&'a str>, - pub filters: Option>, -} - -fn appender_from_opts(opts: &JournalOpts<'_>) -> RollingFileAppender { - let directory = opts.directory.expect("journal directory must be set"); - let mut appender = RollingFileAppender::builder().filename_suffix("journal"); - - if let Some(max_log_files) = opts.max_log_files { - appender = appender.max_log_files( - NonZeroUsize::new(max_log_files) - .expect("max_log_files must be greater than 0") - .into(), - ); - }; - - if let Some(rotation_str) = opts.rotation { - let rotation = match rotation_str { - "minutely" => Rotation::DAILY, - "hourly" => Rotation::HOURLY, - "daily" => Rotation::DAILY, - "never" => Rotation::NEVER, - _ => panic!("invalid rotation: {}", rotation_str), - }; - - appender = appender.rotation(rotation); - }; - - appender - .build(directory) - .expect("failed to create journal appender") -} - -// 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_filter: EnvFilter, - opts: &JournalOpts<'_>, -) -> Option { - // log all traces to stderr (reserving stdout for any actual output such as from the CLI commands) - // TODO Karel - do we want to always allow it or should we make it configurable? - let console_layer = fmt::layer() - .with_writer(std::io::stderr) - .with_target(false) - .with_file(true) - .with_line_number(true) - .with_filter(console_filter); - - // add a file layer if log_dir is set - let (file_layer, file_guard) = if opts.enabled { - let (non_blocking, file_guard) = tracing_appender::non_blocking(appender_from_opts(opts)); - - let mut file_filter = EnvFilter::from_default_env(); - - if let Some(domain_filter) = &opts.filters { - for domain in domain_filter { - file_filter = file_filter.add_directive(domain.parse().unwrap()); - } - } - - let file_layer = fmt::layer() - .json() - .with_writer(non_blocking) - .with_span_events(fmt::format::FmtSpan::CLOSE) - .with_target(false) - .with_file(true) - .with_line_number(true) - .with_filter(file_filter); - - (Some(file_layer), Some(file_guard)) - } else { - (None, None) - }; - - let registry = tracing_subscriber::registry() - .with(console_layer) - .with(file_layer); - - tracing::subscriber::set_global_default(registry) - .expect("Unable to set a global tracing subscriber"); - - file_guard -} From 1dcf5176b9b37964abdc0c89134ca76920e6c387 Mon Sep 17 00:00:00 2001 From: Karel Moravec Date: Mon, 8 Jul 2024 15:53:27 +0200 Subject: [PATCH 03/33] feat: emit metrics --- fendermint/vm/topdown/src/proxy.rs | 75 ++++++++++++++++++++---------- 1 file changed, 51 insertions(+), 24 deletions(-) diff --git a/fendermint/vm/topdown/src/proxy.rs b/fendermint/vm/topdown/src/proxy.rs index 94a8e3177..86f6cb7b0 100644 --- a/fendermint/vm/topdown/src/proxy.rs +++ b/fendermint/vm/topdown/src/proxy.rs @@ -68,22 +68,35 @@ impl IPCProviderProxy { #[async_trait] impl ParentQueryProxy for IPCProviderProxy { async fn get_chain_head_height(&self) -> anyhow::Result { - let height = self.ipc_provider.chain_head(&self.parent_subnet).await?; - Ok(height as BlockHeight) + emit_event_with_latency(&self.parent_subnet.to_string(), "chain_head", || async { + let height = self.ipc_provider.chain_head(&self.parent_subnet).await?; + Ok(height as BlockHeight) + }) + .await } /// Get the genesis epoch of the child subnet, i.e. the epoch that the subnet was created in /// the parent subnet. async fn get_genesis_epoch(&self) -> anyhow::Result { - let height = self.ipc_provider.genesis_epoch(&self.child_subnet).await?; - Ok(height as BlockHeight) + emit_event_with_latency(&self.parent_subnet.to_string(), "genesis_epoch", || async { + let height = self.ipc_provider.genesis_epoch(&self.child_subnet).await?; + Ok(height as BlockHeight) + }) + .await } /// Getting the block hash at the target height. async fn get_block_hash(&self, height: BlockHeight) -> anyhow::Result { - self.ipc_provider - .get_block_hash(&self.parent_subnet, height as ChainEpoch) - .await + emit_event_with_latency( + &self.parent_subnet.to_string(), + "get_block_hash", + || async { + self.ipc_provider + .get_block_hash(&self.parent_subnet, height as ChainEpoch) + .await + }, + ) + .await } /// Get the top down messages from the starting to the ending height. @@ -91,14 +104,21 @@ impl ParentQueryProxy for IPCProviderProxy { &self, height: BlockHeight, ) -> anyhow::Result>> { - self.ipc_provider - .get_top_down_msgs(&self.child_subnet, height as ChainEpoch) - .await - .map(|mut v| { - // sort ascending, we dont assume the changes are ordered - v.value.sort_by(|a, b| a.nonce.cmp(&b.nonce)); - v - }) + emit_event_with_latency( + &self.parent_subnet.to_string(), + "get_top_down_msgs", + || async { + self.ipc_provider + .get_top_down_msgs(&self.child_subnet, height as ChainEpoch) + .await + .map(|mut v| { + // sort ascending, we dont assume the changes are ordered + v.value.sort_by(|a, b| a.nonce.cmp(&b.nonce)); + v + }) + }, + ) + .await } /// Get the validator set at the specified height. @@ -106,15 +126,22 @@ impl ParentQueryProxy for IPCProviderProxy { &self, height: BlockHeight, ) -> anyhow::Result>> { - self.ipc_provider - .get_validator_changeset(&self.child_subnet, height as ChainEpoch) - .await - .map(|mut v| { - // sort ascending, we dont assume the changes are ordered - v.value - .sort_by(|a, b| a.configuration_number.cmp(&b.configuration_number)); - v - }) + emit_event_with_latency( + &self.parent_subnet.to_string(), + "get_validator_changeset", + || async { + self.ipc_provider + .get_validator_changeset(&self.child_subnet, height as ChainEpoch) + .await + .map(|mut v| { + // sort ascending, we dont assume the changes are ordered + v.value + .sort_by(|a, b| a.configuration_number.cmp(&b.configuration_number)); + v + }) + }, + ) + .await } } From d34590d9c6d5800fb35f928989d0441681851f35 Mon Sep 17 00:00:00 2001 From: Karel Moravec Date: Tue, 9 Jul 2024 13:04:24 +0200 Subject: [PATCH 04/33] feat: add remaining top down events --- fendermint/vm/topdown/src/observe.rs | 2 ++ 1 file changed, 2 insertions(+) diff --git a/fendermint/vm/topdown/src/observe.rs b/fendermint/vm/topdown/src/observe.rs index 5a0caa66e..e2d9582fb 100644 --- a/fendermint/vm/topdown/src/observe.rs +++ b/fendermint/vm/topdown/src/observe.rs @@ -1,10 +1,12 @@ // Copyright 2022-2024 Protocol Labs // SPDX-License-Identifier: Apache-2.0, MIT +use ethers::core::k256::elliptic_curve::rand_core::block; use ipc_observability::{ impl_traceable, impl_traceables, lazy_static, register_metrics, serde::HexEncodableBlockHash, Recordable, TraceLevel, Traceable, }; +use ipc_provider::lotus::message::chain::Block; use prometheus::{ register_histogram_vec, register_int_counter_vec, register_int_gauge, register_int_gauge_vec, HistogramVec, IntCounterVec, IntGauge, IntGaugeVec, Registry, From 75e45e430390be2a4c5022ea90fd013e05434ec8 Mon Sep 17 00:00:00 2001 From: Karel Moravec Date: Tue, 9 Jul 2024 16:41:29 +0200 Subject: [PATCH 05/33] feat: remove unused code & fix build --- Cargo.toml | 2 +- fendermint/app/src/cmd/run.rs | 4 +- fendermint/app/src/events.rs | 26 ++++ fendermint/app/src/metrics/tracing.rs | 208 ++++++++++++++++++++++++++ fendermint/vm/topdown/src/observe.rs | 2 - 5 files changed, 237 insertions(+), 5 deletions(-) create mode 100644 fendermint/app/src/events.rs create mode 100644 fendermint/app/src/metrics/tracing.rs diff --git a/Cargo.toml b/Cargo.toml index 154dd5700..bb28ffb43 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -1,4 +1,5 @@ [workspace] +resolver = "2" members = [ # contracts "contracts/binding", @@ -247,4 +248,3 @@ opt-level = "z" strip = true codegen-units = 1 incremental = false -resolver = "2" diff --git a/fendermint/app/src/cmd/run.rs b/fendermint/app/src/cmd/run.rs index 2dac3ef6a..c3ae39ec7 100644 --- a/fendermint/app/src/cmd/run.rs +++ b/fendermint/app/src/cmd/run.rs @@ -24,7 +24,7 @@ use fendermint_vm_snapshot::{SnapshotManager, SnapshotParams}; use fendermint_vm_topdown::observe::register_metrics as register_topdown_metrics; use fendermint_vm_topdown::proxy::{IPCProviderProxy, IPCProviderProxyWithLatency}; use fendermint_vm_topdown::sync::launch_polling_syncer; -use fendermint_vm_topdown::voting::{publish_vote_loop, Error as VoteError, VoteTally}; +use fendermint_vm_topdown::voting::{publish_vote_loop, VoteTally}; use fendermint_vm_topdown::{CachedFinalityProvider, IPCParentFinality, Toggle}; use fvm_shared::address::{current_network, Address, Network}; use ipc_ipld_resolver::{Event as ResolverEvent, VoteRecord}; @@ -543,7 +543,7 @@ async fn dispatch_vote( tracing::debug!("ignoring vote; topdown disabled"); return; } - let res = atomically_or_err(|| { + let _res = atomically_or_err(|| { parent_finality_votes.add_vote( vote.public_key.clone(), f.height, diff --git a/fendermint/app/src/events.rs b/fendermint/app/src/events.rs new file mode 100644 index 000000000..84fc2c8cd --- /dev/null +++ b/fendermint/app/src/events.rs @@ -0,0 +1,26 @@ +// Copyright 2022-2024 Protocol Labs +// SPDX-License-Identifier: Apache-2.0, MIT + +use crate::BlockHeight; + +/// Re-export other events, just to provide the visibility of where they are. +pub use fendermint_vm_event::{ + NewBottomUpCheckpoint, ParentFinalityCommitted, ParentFinalityMissingQuorum, +}; + +/// Hex encoded block hash. +pub type BlockHashHex<'a> = &'a str; + +#[derive(Debug, Default)] +pub struct ProposalProcessed<'a> { + pub is_accepted: bool, + pub block_height: BlockHeight, + pub block_hash: BlockHashHex<'a>, + pub num_txs: usize, + pub proposer: &'a str, +} + +#[derive(Debug, Default)] +pub struct NewBlock { + pub block_height: BlockHeight, +} diff --git a/fendermint/app/src/metrics/tracing.rs b/fendermint/app/src/metrics/tracing.rs new file mode 100644 index 000000000..3dfca6949 --- /dev/null +++ b/fendermint/app/src/metrics/tracing.rs @@ -0,0 +1,208 @@ +// Copyright 2022-2024 Protocol Labs +// SPDX-License-Identifier: Apache-2.0, MIT +//! Subscribing to tracing events and turning them into metrics. + +use std::marker::PhantomData; + +use tracing::{Event, Subscriber}; +use tracing_subscriber::{filter, layer, registry::LookupSpan, Layer}; + +use super::prometheus::app as am; +use crate::events::*; + +/// Create a layer that handles events by incrementing metrics. +pub fn layer() -> impl Layer +where + S: Subscriber, + for<'a> S: LookupSpan<'a>, +{ + MetricsLayer::new().with_filter(filter::filter_fn(|md| md.name().starts_with("event::"))) +} + +struct MetricsLayer { + _subscriber: PhantomData, +} + +impl MetricsLayer { + pub fn new() -> Self { + Self { + _subscriber: PhantomData, + } + } +} + +/// Check that the field exist on a type; if it doesn't this won't compile. +/// This ensures that we're mapping fields with the correct name. +macro_rules! check_field { + ($event_ty:ident :: $field:ident) => {{ + if false { + #[allow(clippy::needless_update)] + let _event = $event_ty { + $field: Default::default(), + ..Default::default() + }; + } + }}; +} + +/// Set a gague to an absolute value based on a field in an event. +macro_rules! set_gauge { + ($event:ident, $event_ty:ident :: $field:ident, $gauge:expr) => { + check_field!($event_ty::$field); + let mut fld = visitors::FindU64::new(stringify!($field)); + $event.record(&mut fld); + $gauge.set(fld.value as i64); + }; +} + +/// Increment a counter by the value of a field in the event. +macro_rules! inc_counter { + ($event:ident, $event_ty:ident :: $field:ident, $counter:expr) => { + check_field!($event_ty::$field); + let mut fld = visitors::FindU64::new(stringify!($field)); + $event.record(&mut fld); + $counter.inc_by(fld.value); + }; +} + +/// Increment a counter by 1. +/// +/// The field is ignored, it's only here because of how the macros look like. +macro_rules! inc1_counter { + ($event:ident, $event_ty:ident :: $field:ident, $counter:expr) => { + check_field!($event_ty::$field); + $counter.inc(); + }; +} + +/// Produce the prefixed event name from the type name. +macro_rules! event_name { + ($event_ty:ident) => { + concat!("event::", stringify!($event_ty)) + }; +} + +/// Call one of the macros that set values on a metric. +macro_rules! event_mapping { + ($op:ident, $event:ident, $event_ty:ident :: $field:ident, $metric:expr) => { + $op!($event, $event_ty::$field, $metric); + }; +} + +/// Match the event name to event DTO types and within the map fields to metrics. +macro_rules! event_match { + ($event:ident { $( $event_ty:ident { $( $field:ident => $op:ident ! $metric:expr ),* $(,)? } ),* } ) => { + match $event.metadata().name() { + $( + event_name!($event_ty) => { + $( + event_mapping!($op, $event, $event_ty :: $field, $metric); + )* + } + )* + _ => {} + } + }; +} + +impl Layer for MetricsLayer { + fn on_event(&self, event: &Event<'_>, _ctx: layer::Context<'_, S>) { + event_match!(event { + ParentFinalityCommitted { + block_height => set_gauge ! &am::TOPDOWN_FINALIZED_BLOCK_HEIGHT, + }, + ParentFinalityMissingQuorum { + block_hash => inc1_counter ! &am::TOPDOWN_FINALITY_MISSING_QUORUM, + }, + NewBottomUpCheckpoint { + block_height => set_gauge ! &am::BOTTOMUP_CKPT_BLOCK_HEIGHT, + next_configuration_number => set_gauge ! &am::BOTTOMUP_CKPT_CONFIG_NUM, + num_msgs => inc_counter ! &am::BOTTOMUP_CKPT_NUM_MSGS, + }, + NewBlock { + block_height => set_gauge ! &am::ABCI_COMMITTED_BLOCK_HEIGHT + } + }); + } +} + +mod visitors { + use tracing::field::{Field, Visit}; + + pub struct FindU64<'a> { + pub name: &'a str, + pub value: u64, + } + + impl<'a> FindU64<'a> { + pub fn new(name: &'a str) -> Self { + Self { name, value: 0 } + } + } + + // Looking for multiple values because the callsite might be passed as a literal which turns into an i64 for example. + impl<'a> Visit for FindU64<'a> { + fn record_u64(&mut self, field: &Field, value: u64) { + if field.name() == self.name { + self.value = value; + } + } + + fn record_i64(&mut self, field: &Field, value: i64) { + if field.name() == self.name { + self.value = value as u64; + } + } + + fn record_i128(&mut self, field: &Field, value: i128) { + if field.name() == self.name { + self.value = value as u64; + } + } + + fn record_u128(&mut self, field: &Field, value: u128) { + if field.name() == self.name { + self.value = value as u64; + } + } + + fn record_debug(&mut self, _field: &Field, _value: &dyn std::fmt::Debug) {} + } +} + +#[cfg(test)] +mod tests { + use fendermint_tracing::emit; + use fendermint_vm_event::ParentFinalityCommitted; + use prometheus::IntGauge; + use tracing_subscriber::layer::SubscriberExt; + + #[test] + fn test_metrics_layer() { + let gauge: &IntGauge = &super::super::prometheus::app::TOPDOWN_FINALIZED_BLOCK_HEIGHT; + + let v0 = gauge.get(); + gauge.inc(); + let v1 = gauge.get(); + assert!(v1 > v0, "gague should change without being registered"); + + let block_height = std::time::SystemTime::now() + .duration_since(std::time::UNIX_EPOCH) + .unwrap() + .as_secs(); + + let subscriber = tracing_subscriber::registry().with(super::layer()); + + tracing::subscriber::with_default(subscriber, || { + emit! { + ParentFinalityCommitted { block_height, block_hash: "metrics-test-block" } + } + }); + + assert_eq!( + gauge.get() as u64, + block_height, + "metrics should be captured" + ); + } +} diff --git a/fendermint/vm/topdown/src/observe.rs b/fendermint/vm/topdown/src/observe.rs index e2d9582fb..5a0caa66e 100644 --- a/fendermint/vm/topdown/src/observe.rs +++ b/fendermint/vm/topdown/src/observe.rs @@ -1,12 +1,10 @@ // Copyright 2022-2024 Protocol Labs // SPDX-License-Identifier: Apache-2.0, MIT -use ethers::core::k256::elliptic_curve::rand_core::block; use ipc_observability::{ impl_traceable, impl_traceables, lazy_static, register_metrics, serde::HexEncodableBlockHash, Recordable, TraceLevel, Traceable, }; -use ipc_provider::lotus::message::chain::Block; use prometheus::{ register_histogram_vec, register_int_counter_vec, register_int_gauge, register_int_gauge_vec, HistogramVec, IntCounterVec, IntGauge, IntGaugeVec, Registry, From c2465bce2d3185a2861f05331cda7914644c146c Mon Sep 17 00:00:00 2001 From: Karel Moravec Date: Wed, 10 Jul 2024 13:44:36 +0200 Subject: [PATCH 06/33] feat: address comments --- fendermint/vm/topdown/src/observe.rs | 3 +++ fendermint/vm/topdown/src/voting.rs | 4 ++-- 2 files changed, 5 insertions(+), 2 deletions(-) diff --git a/fendermint/vm/topdown/src/observe.rs b/fendermint/vm/topdown/src/observe.rs index 5a0caa66e..cce0b3b2e 100644 --- a/fendermint/vm/topdown/src/observe.rs +++ b/fendermint/vm/topdown/src/observe.rs @@ -1,6 +1,9 @@ // Copyright 2022-2024 Protocol Labs // SPDX-License-Identifier: Apache-2.0, MIT +use hex; +use std::fmt; + use ipc_observability::{ impl_traceable, impl_traceables, lazy_static, register_metrics, serde::HexEncodableBlockHash, Recordable, TraceLevel, Traceable, diff --git a/fendermint/vm/topdown/src/voting.rs b/fendermint/vm/topdown/src/voting.rs index 793c2ab24..f8e0a6522 100644 --- a/fendermint/vm/topdown/src/voting.rs +++ b/fendermint/vm/topdown/src/voting.rs @@ -8,8 +8,8 @@ use std::hash::Hash; use std::{fmt::Debug, time::Duration}; use crate::observe::{ - ParentFinalityCommitted, ParentFinalityPeerQuorumReached, ParentFinalityPeerVoteReceived, - ParentFinalityPeerVoteSent, + HexEncodableBlockHash, ParentFinalityCommitted, ParentFinalityPeerQuorumReached, + ParentFinalityPeerVoteReceived, ParentFinalityPeerVoteSent, }; use crate::{BlockHash, BlockHeight}; use ipc_observability::{emit, serde::HexEncodableBlockHash}; From 599bcc33d3912260cdce73ea2cfe282f72a7a349 Mon Sep 17 00:00:00 2001 From: Karel Moravec Date: Wed, 10 Jul 2024 16:04:42 +0200 Subject: [PATCH 07/33] feat: use latency wrapper instead --- fendermint/app/src/cmd/run.rs | 2 +- fendermint/vm/topdown/src/proxy.rs | 120 +++++++++++++++++++---------- 2 files changed, 82 insertions(+), 40 deletions(-) diff --git a/fendermint/app/src/cmd/run.rs b/fendermint/app/src/cmd/run.rs index c3ae39ec7..d9463729f 100644 --- a/fendermint/app/src/cmd/run.rs +++ b/fendermint/app/src/cmd/run.rs @@ -263,7 +263,7 @@ async fn run(settings: Settings) -> anyhow::Result<()> { CachedFinalityProvider::uninitialized(config.clone(), ipc_provider.clone()).await?; let p = Arc::new(Toggle::enabled(finality_provider)); - (p, Some((ipc_provider, config))) + (p, Some((ipc_provider_with_latency, config))) } else { info!("topdown finality disabled"); (Arc::new(Toggle::disabled()), None) diff --git a/fendermint/vm/topdown/src/proxy.rs b/fendermint/vm/topdown/src/proxy.rs index 86f6cb7b0..abbd3812f 100644 --- a/fendermint/vm/topdown/src/proxy.rs +++ b/fendermint/vm/topdown/src/proxy.rs @@ -68,33 +68,94 @@ impl IPCProviderProxy { #[async_trait] impl ParentQueryProxy for IPCProviderProxy { async fn get_chain_head_height(&self) -> anyhow::Result { - emit_event_with_latency(&self.parent_subnet.to_string(), "chain_head", || async { - let height = self.ipc_provider.chain_head(&self.parent_subnet).await?; - Ok(height as BlockHeight) - }) - .await + let height = self.ipc_provider.chain_head(&self.parent_subnet).await?; + Ok(height as BlockHeight) } /// Get the genesis epoch of the child subnet, i.e. the epoch that the subnet was created in /// the parent subnet. async fn get_genesis_epoch(&self) -> anyhow::Result { - emit_event_with_latency(&self.parent_subnet.to_string(), "genesis_epoch", || async { - let height = self.ipc_provider.genesis_epoch(&self.child_subnet).await?; - Ok(height as BlockHeight) - }) - .await + let height = self.ipc_provider.genesis_epoch(&self.child_subnet).await?; + Ok(height as BlockHeight) } /// Getting the block hash at the target height. + async fn get_block_hash(&self, height: BlockHeight) -> anyhow::Result { + self.ipc_provider + .get_block_hash(&self.parent_subnet, height as ChainEpoch) + .await + } + + /// Get the top down messages from the starting to the ending height. + async fn get_top_down_msgs( + &self, + height: BlockHeight, + ) -> anyhow::Result>> { + self.ipc_provider + .get_top_down_msgs(&self.child_subnet, height as ChainEpoch) + .await + .map(|mut v| { + // sort ascending, we dont assume the changes are ordered + v.value.sort_by(|a, b| a.nonce.cmp(&b.nonce)); + v + }) + } + + /// Get the validator set at the specified height. + async fn get_validator_changes( + &self, + height: BlockHeight, + ) -> anyhow::Result>> { + self.ipc_provider + .get_validator_changeset(&self.child_subnet, height as ChainEpoch) + .await + .map(|mut v| { + // sort ascending, we dont assume the changes are ordered + v.value + .sort_by(|a, b| a.configuration_number.cmp(&b.configuration_number)); + v + }) + } +} + +pub struct IPCProviderProxyWithLatency { + inner: IPCProviderProxy, +} + +impl IPCProviderProxyWithLatency { + pub fn new(inner: IPCProviderProxy) -> Self { + Self { inner } + } +} + +#[async_trait] +impl ParentQueryProxy for IPCProviderProxyWithLatency { + #[instrument(skip(self))] + async fn get_chain_head_height(&self) -> anyhow::Result { + emit_event_with_latency( + &self.inner.parent_subnet.to_string(), + "chain_head", + || async { self.inner.get_chain_head_height().await }, + ) + .await + } + + #[instrument(skip(self))] + async fn get_genesis_epoch(&self) -> anyhow::Result { + emit_event_with_latency( + &self.inner.parent_subnet.to_string(), + "genesis_epoch", + || async { self.inner.get_genesis_epoch().await }, + ) + .await + } + + #[instrument(skip(self))] async fn get_block_hash(&self, height: BlockHeight) -> anyhow::Result { emit_event_with_latency( - &self.parent_subnet.to_string(), + &self.inner.parent_subnet.to_string(), "get_block_hash", - || async { - self.ipc_provider - .get_block_hash(&self.parent_subnet, height as ChainEpoch) - .await - }, + || async { self.inner.get_block_hash(height).await }, ) .await } @@ -105,18 +166,9 @@ impl ParentQueryProxy for IPCProviderProxy { height: BlockHeight, ) -> anyhow::Result>> { emit_event_with_latency( - &self.parent_subnet.to_string(), + &self.inner.parent_subnet.to_string(), "get_top_down_msgs", - || async { - self.ipc_provider - .get_top_down_msgs(&self.child_subnet, height as ChainEpoch) - .await - .map(|mut v| { - // sort ascending, we dont assume the changes are ordered - v.value.sort_by(|a, b| a.nonce.cmp(&b.nonce)); - v - }) - }, + || async { self.inner.get_top_down_msgs(height).await }, ) .await } @@ -127,19 +179,9 @@ impl ParentQueryProxy for IPCProviderProxy { height: BlockHeight, ) -> anyhow::Result>> { emit_event_with_latency( - &self.parent_subnet.to_string(), + &self.inner.parent_subnet.to_string(), "get_validator_changeset", - || async { - self.ipc_provider - .get_validator_changeset(&self.child_subnet, height as ChainEpoch) - .await - .map(|mut v| { - // sort ascending, we dont assume the changes are ordered - v.value - .sort_by(|a, b| a.configuration_number.cmp(&b.configuration_number)); - v - }) - }, + || async { self.inner.get_validator_changes(height).await }, ) .await } From e80f3dfb05353b84c07768c8d147367675d28973 Mon Sep 17 00:00:00 2001 From: Karel Moravec Date: Thu, 11 Jul 2024 22:22:43 +0200 Subject: [PATCH 08/33] feat: add config filters --- fendermint/app/src/main.rs | 3 ++ fendermint/app/src/metrics/tracing.rs | 53 --------------------------- fendermint/vm/topdown/src/observe.rs | 53 +++++++++++++++++++++++++++ 3 files changed, 56 insertions(+), 53 deletions(-) diff --git a/fendermint/app/src/main.rs b/fendermint/app/src/main.rs index 117fa3121..13a86b74b 100644 --- a/fendermint/app/src/main.rs +++ b/fendermint/app/src/main.rs @@ -48,6 +48,9 @@ async fn main() { init_panic_handler(); + use fendermint_vm_topdown::observe::emit_all; + emit_all(); + if let Err(e) = cmd::exec(&opts).await { tracing::error!("failed to execute {:?}: {e:?}", opts); std::process::exit(fendermint_app::AppExitCode::UnknownError as i32); diff --git a/fendermint/app/src/metrics/tracing.rs b/fendermint/app/src/metrics/tracing.rs index 3dfca6949..397092396 100644 --- a/fendermint/app/src/metrics/tracing.rs +++ b/fendermint/app/src/metrics/tracing.rs @@ -65,16 +65,6 @@ macro_rules! inc_counter { }; } -/// Increment a counter by 1. -/// -/// The field is ignored, it's only here because of how the macros look like. -macro_rules! inc1_counter { - ($event:ident, $event_ty:ident :: $field:ident, $counter:expr) => { - check_field!($event_ty::$field); - $counter.inc(); - }; -} - /// Produce the prefixed event name from the type name. macro_rules! event_name { ($event_ty:ident) => { @@ -108,12 +98,6 @@ macro_rules! event_match { impl Layer for MetricsLayer { fn on_event(&self, event: &Event<'_>, _ctx: layer::Context<'_, S>) { event_match!(event { - ParentFinalityCommitted { - block_height => set_gauge ! &am::TOPDOWN_FINALIZED_BLOCK_HEIGHT, - }, - ParentFinalityMissingQuorum { - block_hash => inc1_counter ! &am::TOPDOWN_FINALITY_MISSING_QUORUM, - }, NewBottomUpCheckpoint { block_height => set_gauge ! &am::BOTTOMUP_CKPT_BLOCK_HEIGHT, next_configuration_number => set_gauge ! &am::BOTTOMUP_CKPT_CONFIG_NUM, @@ -169,40 +153,3 @@ mod visitors { fn record_debug(&mut self, _field: &Field, _value: &dyn std::fmt::Debug) {} } } - -#[cfg(test)] -mod tests { - use fendermint_tracing::emit; - use fendermint_vm_event::ParentFinalityCommitted; - use prometheus::IntGauge; - use tracing_subscriber::layer::SubscriberExt; - - #[test] - fn test_metrics_layer() { - let gauge: &IntGauge = &super::super::prometheus::app::TOPDOWN_FINALIZED_BLOCK_HEIGHT; - - let v0 = gauge.get(); - gauge.inc(); - let v1 = gauge.get(); - assert!(v1 > v0, "gague should change without being registered"); - - let block_height = std::time::SystemTime::now() - .duration_since(std::time::UNIX_EPOCH) - .unwrap() - .as_secs(); - - let subscriber = tracing_subscriber::registry().with(super::layer()); - - tracing::subscriber::with_default(subscriber, || { - emit! { - ParentFinalityCommitted { block_height, block_hash: "metrics-test-block" } - } - }); - - assert_eq!( - gauge.get() as u64, - block_height, - "metrics should be captured" - ); - } -} diff --git a/fendermint/vm/topdown/src/observe.rs b/fendermint/vm/topdown/src/observe.rs index cce0b3b2e..613864f26 100644 --- a/fendermint/vm/topdown/src/observe.rs +++ b/fendermint/vm/topdown/src/observe.rs @@ -151,6 +151,59 @@ impl Recordable for ParentFinalityCommitted<'_> { } } +pub fn emit_all() { + use ipc_observability::emit; + + emit(ParentRpcCalled { + source: "source", + json_rpc: "json_rpc", + method: "method", + status: "status", + latency: 1.0, + }); + + let hash = vec![0u8; 32]; + + emit(ParentFinalityAcquired { + source: "parent-finality", + is_null: false, + block_height: 10, + block_hash: Some(HexEncodableBlockHash(hash.clone())), + commitment_hash: Some(HexEncodableBlockHash(hash.clone())), + num_msgs: 5, + num_validator_changes: 6, + }); + + emit(ParentFinalityPeerVoteReceived { + validator: "abcd", + block_height: 10, + block_hash: HexEncodableBlockHash(hash.clone()), + commitment_hash: HexEncodableBlockHash(hash.clone()), + }); + + emit(ParentFinalityPeerVoteSent { + block_height: 10, + block_hash: HexEncodableBlockHash(hash.clone()), + commitment_hash: HexEncodableBlockHash(hash.clone()), + }); + + emit(ParentFinalityPeerQuorumReached { + block_height: 10, + block_hash: HexEncodableBlockHash(hash.clone()), + commitment_hash: HexEncodableBlockHash(hash.clone()), + weight: 5, + }); + + emit(ParentFinalityCommitted { + parent_height: 10, + block_hash: HexEncodableBlockHash(hash.clone()), + local_height: Some(3), + proposer: Some("proposer-validator"), + }); + + println!("Emitted all events"); +} + #[cfg(test)] mod tests { use super::*; From 79de523d2e51737186738a890eb70efc2c55ac92 Mon Sep 17 00:00:00 2001 From: Karel Moravec Date: Fri, 12 Jul 2024 13:49:43 +0200 Subject: [PATCH 09/33] feat: add config as a cmd flags --- fendermint/app/src/main.rs | 3 -- fendermint/vm/topdown/src/observe.rs | 53 ------------------------- ipc/observability/src/tracing_layers.rs | 8 ++++ 3 files changed, 8 insertions(+), 56 deletions(-) diff --git a/fendermint/app/src/main.rs b/fendermint/app/src/main.rs index 13a86b74b..117fa3121 100644 --- a/fendermint/app/src/main.rs +++ b/fendermint/app/src/main.rs @@ -48,9 +48,6 @@ async fn main() { init_panic_handler(); - use fendermint_vm_topdown::observe::emit_all; - emit_all(); - if let Err(e) = cmd::exec(&opts).await { tracing::error!("failed to execute {:?}: {e:?}", opts); std::process::exit(fendermint_app::AppExitCode::UnknownError as i32); diff --git a/fendermint/vm/topdown/src/observe.rs b/fendermint/vm/topdown/src/observe.rs index 613864f26..cce0b3b2e 100644 --- a/fendermint/vm/topdown/src/observe.rs +++ b/fendermint/vm/topdown/src/observe.rs @@ -151,59 +151,6 @@ impl Recordable for ParentFinalityCommitted<'_> { } } -pub fn emit_all() { - use ipc_observability::emit; - - emit(ParentRpcCalled { - source: "source", - json_rpc: "json_rpc", - method: "method", - status: "status", - latency: 1.0, - }); - - let hash = vec![0u8; 32]; - - emit(ParentFinalityAcquired { - source: "parent-finality", - is_null: false, - block_height: 10, - block_hash: Some(HexEncodableBlockHash(hash.clone())), - commitment_hash: Some(HexEncodableBlockHash(hash.clone())), - num_msgs: 5, - num_validator_changes: 6, - }); - - emit(ParentFinalityPeerVoteReceived { - validator: "abcd", - block_height: 10, - block_hash: HexEncodableBlockHash(hash.clone()), - commitment_hash: HexEncodableBlockHash(hash.clone()), - }); - - emit(ParentFinalityPeerVoteSent { - block_height: 10, - block_hash: HexEncodableBlockHash(hash.clone()), - commitment_hash: HexEncodableBlockHash(hash.clone()), - }); - - emit(ParentFinalityPeerQuorumReached { - block_height: 10, - block_hash: HexEncodableBlockHash(hash.clone()), - commitment_hash: HexEncodableBlockHash(hash.clone()), - weight: 5, - }); - - emit(ParentFinalityCommitted { - parent_height: 10, - block_hash: HexEncodableBlockHash(hash.clone()), - local_height: Some(3), - proposer: Some("proposer-validator"), - }); - - println!("Emitted all events"); -} - #[cfg(test)] mod tests { use super::*; diff --git a/ipc/observability/src/tracing_layers.rs b/ipc/observability/src/tracing_layers.rs index f680fbdcb..15ab07e97 100644 --- a/ipc/observability/src/tracing_layers.rs +++ b/ipc/observability/src/tracing_layers.rs @@ -13,6 +13,14 @@ pub struct DomainEventFilterLayer { inner: L, } +impl Deref for DomainEventFilterLayer { + type Target = Registry; + + fn deref(&self) -> &Self::Target { + &self.inner + } +} + impl DomainEventFilterLayer { pub fn new(domains: Option>, events: Option>, inner: L) -> Self { DomainEventFilterLayer { From 2f40eefcbd06274e74efc092c2ba7a6bd086f503 Mon Sep 17 00:00:00 2001 From: Karel Moravec Date: Mon, 15 Jul 2024 11:59:42 +0200 Subject: [PATCH 10/33] feat: fix comments --- ipc/observability/src/tracing_layers.rs | 8 -------- 1 file changed, 8 deletions(-) diff --git a/ipc/observability/src/tracing_layers.rs b/ipc/observability/src/tracing_layers.rs index 15ab07e97..f680fbdcb 100644 --- a/ipc/observability/src/tracing_layers.rs +++ b/ipc/observability/src/tracing_layers.rs @@ -13,14 +13,6 @@ pub struct DomainEventFilterLayer { inner: L, } -impl Deref for DomainEventFilterLayer { - type Target = Registry; - - fn deref(&self) -> &Self::Target { - &self.inner - } -} - impl DomainEventFilterLayer { pub fn new(domains: Option>, events: Option>, inner: L) -> Self { DomainEventFilterLayer { From a97b16d9726c320e19d94be0d4e66ea34366afdf Mon Sep 17 00:00:00 2001 From: Karel Moravec Date: Fri, 12 Jul 2024 17:30:43 +0200 Subject: [PATCH 11/33] feat: add consensus traces --- fendermint/app/src/app.rs | 14 +++ fendermint/app/src/events.rs | 26 ----- fendermint/app/src/metrics/tracing.rs | 155 -------------------------- test-network/genesis.json | 97 ++++++++++++++++ test-network/keys/alice.pk | 1 + test-network/keys/alice.sk | 1 + test-network/keys/bob.pk | 1 + test-network/keys/bob.sk | 1 + test-network/keys/charlie.pk | 1 + test-network/keys/charlie.sk | 1 + test-network/keys/dave.pk | 1 + test-network/keys/dave.sk | 1 + test-network/traces/2024-07-12.traces | 2 + 13 files changed, 121 insertions(+), 181 deletions(-) delete mode 100644 fendermint/app/src/events.rs delete mode 100644 fendermint/app/src/metrics/tracing.rs create mode 100644 test-network/genesis.json create mode 100644 test-network/keys/alice.pk create mode 100644 test-network/keys/alice.sk create mode 100644 test-network/keys/bob.pk create mode 100644 test-network/keys/bob.sk create mode 100644 test-network/keys/charlie.pk create mode 100644 test-network/keys/charlie.sk create mode 100644 test-network/keys/dave.pk create mode 100644 test-network/keys/dave.sk create mode 100644 test-network/traces/2024-07-12.traces diff --git a/fendermint/app/src/app.rs b/fendermint/app/src/app.rs index e87677483..e01733fc0 100644 --- a/fendermint/app/src/app.rs +++ b/fendermint/app/src/app.rs @@ -715,8 +715,22 @@ where }); if accept { + emit(BlockProposalAccepted { + height: request.height.value(), + hash: HexEncodableBlockHash(request.hash.into()), + size: size_txs, + tx_count: num_txs, + validator: request.proposer_address.to_string().as_str(), + }); Ok(response::ProcessProposal::Accept) } else { + emit(BlockProposalRejected { + height: request.height.value(), + size: size_txs, + tx_count: num_txs, + validator: request.proposer_address.to_string().as_str(), + reason: "rejected", + }); Ok(response::ProcessProposal::Reject) } } diff --git a/fendermint/app/src/events.rs b/fendermint/app/src/events.rs deleted file mode 100644 index 84fc2c8cd..000000000 --- a/fendermint/app/src/events.rs +++ /dev/null @@ -1,26 +0,0 @@ -// Copyright 2022-2024 Protocol Labs -// SPDX-License-Identifier: Apache-2.0, MIT - -use crate::BlockHeight; - -/// Re-export other events, just to provide the visibility of where they are. -pub use fendermint_vm_event::{ - NewBottomUpCheckpoint, ParentFinalityCommitted, ParentFinalityMissingQuorum, -}; - -/// Hex encoded block hash. -pub type BlockHashHex<'a> = &'a str; - -#[derive(Debug, Default)] -pub struct ProposalProcessed<'a> { - pub is_accepted: bool, - pub block_height: BlockHeight, - pub block_hash: BlockHashHex<'a>, - pub num_txs: usize, - pub proposer: &'a str, -} - -#[derive(Debug, Default)] -pub struct NewBlock { - pub block_height: BlockHeight, -} diff --git a/fendermint/app/src/metrics/tracing.rs b/fendermint/app/src/metrics/tracing.rs deleted file mode 100644 index 397092396..000000000 --- a/fendermint/app/src/metrics/tracing.rs +++ /dev/null @@ -1,155 +0,0 @@ -// Copyright 2022-2024 Protocol Labs -// SPDX-License-Identifier: Apache-2.0, MIT -//! Subscribing to tracing events and turning them into metrics. - -use std::marker::PhantomData; - -use tracing::{Event, Subscriber}; -use tracing_subscriber::{filter, layer, registry::LookupSpan, Layer}; - -use super::prometheus::app as am; -use crate::events::*; - -/// Create a layer that handles events by incrementing metrics. -pub fn layer() -> impl Layer -where - S: Subscriber, - for<'a> S: LookupSpan<'a>, -{ - MetricsLayer::new().with_filter(filter::filter_fn(|md| md.name().starts_with("event::"))) -} - -struct MetricsLayer { - _subscriber: PhantomData, -} - -impl MetricsLayer { - pub fn new() -> Self { - Self { - _subscriber: PhantomData, - } - } -} - -/// Check that the field exist on a type; if it doesn't this won't compile. -/// This ensures that we're mapping fields with the correct name. -macro_rules! check_field { - ($event_ty:ident :: $field:ident) => {{ - if false { - #[allow(clippy::needless_update)] - let _event = $event_ty { - $field: Default::default(), - ..Default::default() - }; - } - }}; -} - -/// Set a gague to an absolute value based on a field in an event. -macro_rules! set_gauge { - ($event:ident, $event_ty:ident :: $field:ident, $gauge:expr) => { - check_field!($event_ty::$field); - let mut fld = visitors::FindU64::new(stringify!($field)); - $event.record(&mut fld); - $gauge.set(fld.value as i64); - }; -} - -/// Increment a counter by the value of a field in the event. -macro_rules! inc_counter { - ($event:ident, $event_ty:ident :: $field:ident, $counter:expr) => { - check_field!($event_ty::$field); - let mut fld = visitors::FindU64::new(stringify!($field)); - $event.record(&mut fld); - $counter.inc_by(fld.value); - }; -} - -/// Produce the prefixed event name from the type name. -macro_rules! event_name { - ($event_ty:ident) => { - concat!("event::", stringify!($event_ty)) - }; -} - -/// Call one of the macros that set values on a metric. -macro_rules! event_mapping { - ($op:ident, $event:ident, $event_ty:ident :: $field:ident, $metric:expr) => { - $op!($event, $event_ty::$field, $metric); - }; -} - -/// Match the event name to event DTO types and within the map fields to metrics. -macro_rules! event_match { - ($event:ident { $( $event_ty:ident { $( $field:ident => $op:ident ! $metric:expr ),* $(,)? } ),* } ) => { - match $event.metadata().name() { - $( - event_name!($event_ty) => { - $( - event_mapping!($op, $event, $event_ty :: $field, $metric); - )* - } - )* - _ => {} - } - }; -} - -impl Layer for MetricsLayer { - fn on_event(&self, event: &Event<'_>, _ctx: layer::Context<'_, S>) { - event_match!(event { - NewBottomUpCheckpoint { - block_height => set_gauge ! &am::BOTTOMUP_CKPT_BLOCK_HEIGHT, - next_configuration_number => set_gauge ! &am::BOTTOMUP_CKPT_CONFIG_NUM, - num_msgs => inc_counter ! &am::BOTTOMUP_CKPT_NUM_MSGS, - }, - NewBlock { - block_height => set_gauge ! &am::ABCI_COMMITTED_BLOCK_HEIGHT - } - }); - } -} - -mod visitors { - use tracing::field::{Field, Visit}; - - pub struct FindU64<'a> { - pub name: &'a str, - pub value: u64, - } - - impl<'a> FindU64<'a> { - pub fn new(name: &'a str) -> Self { - Self { name, value: 0 } - } - } - - // Looking for multiple values because the callsite might be passed as a literal which turns into an i64 for example. - impl<'a> Visit for FindU64<'a> { - fn record_u64(&mut self, field: &Field, value: u64) { - if field.name() == self.name { - self.value = value; - } - } - - fn record_i64(&mut self, field: &Field, value: i64) { - if field.name() == self.name { - self.value = value as u64; - } - } - - fn record_i128(&mut self, field: &Field, value: i128) { - if field.name() == self.name { - self.value = value as u64; - } - } - - fn record_u128(&mut self, field: &Field, value: u128) { - if field.name() == self.name { - self.value = value as u64; - } - } - - fn record_debug(&mut self, _field: &Field, _value: &dyn std::fmt::Debug) {} - } -} diff --git a/test-network/genesis.json b/test-network/genesis.json new file mode 100644 index 000000000..b2f5501ae --- /dev/null +++ b/test-network/genesis.json @@ -0,0 +1,97 @@ +{ + "chain_name": "test", + "timestamp": 1680101412, + "network_version": 21, + "base_fee": "1000", + "power_scale": 0, + "validators": [ + { + "public_key": "BPMMj79Dc5slgNl1v29V0mn/ixHt7CO/MbsNLQP0ZpSEd5FuW2UQ5hzNsKhauI97UZ9jQN3t+kRJQaWlcRjcJdI=", + "power": "1000000000000000000" + } + ], + "accounts": [ + { + "meta": { + "Account": { + "owner": "t1vfs6z4k6cyoevukvhqomsgwqrb75i2jodwa4jxa" + } + }, + "balance": "10000000000000000000" + }, + { + "meta": { + "Account": { + "owner": "t410frr6xjymicyh4iltk5v27c4y4misr73mcqjzh45a" + } + }, + "balance": "10000000000000000000" + }, + { + "meta": { + "Account": { + "owner": "t1zrk7jjngc3uzobjkmlzjynjfgpxvxctxbxuvs5a" + } + }, + "balance": "10000000000000000000" + }, + { + "meta": { + "Account": { + "owner": "t410f5qlw62wdgzwdwfb3rjoheibxrhke3vmzxtcdzrq" + } + }, + "balance": "10000000000000000000" + }, + { + "meta": { + "Account": { + "owner": "t1kwdghtw7j72qb5dwf4gskyp4be4cter73nlojuy" + } + }, + "balance": "10000000000000000000" + }, + { + "meta": { + "Account": { + "owner": "t410flcjfiuotgwadabcoftuuo26ooaxrovjvwdccoji" + } + }, + "balance": "10000000000000000000" + }, + { + "meta": { + "Account": { + "owner": "t1e3acffdre4egtul5kp3c2hamm522dg6aqfgzioy" + } + }, + "balance": "10000000000000000000" + }, + { + "meta": { + "Account": { + "owner": "t410fst6awyokeeevmqiwcnlzwt3g2uazcsavr2u2iwi" + } + }, + "balance": "10000000000000000000" + }, + { + "meta": { + "Multisig": { + "signers": [ + "t1zrk7jjngc3uzobjkmlzjynjfgpxvxctxbxuvs5a", + "t1kwdghtw7j72qb5dwf4gskyp4be4cter73nlojuy", + "t1e3acffdre4egtul5kp3c2hamm522dg6aqfgzioy" + ], + "threshold": 2, + "vesting_duration": 1000000, + "vesting_start": 0 + } + }, + "balance": "30000000000000000000" + } + ], + "eam_permission_mode": { + "mode": "unrestricted" + } +} \ No newline at end of file diff --git a/test-network/keys/alice.pk b/test-network/keys/alice.pk new file mode 100644 index 000000000..794dee8f6 --- /dev/null +++ b/test-network/keys/alice.pk @@ -0,0 +1 @@ +AhIQ+C+xL8C9v45KcdczZj5H4sPxROx08lT+seQCEM6c \ No newline at end of file diff --git a/test-network/keys/alice.sk b/test-network/keys/alice.sk new file mode 100644 index 000000000..a8c648503 --- /dev/null +++ b/test-network/keys/alice.sk @@ -0,0 +1 @@ +UWJv1Gj1tmnxlKUQizJTxobyJuB7u4PbkO3J2pfd+PI= \ No newline at end of file diff --git a/test-network/keys/bob.pk b/test-network/keys/bob.pk new file mode 100644 index 000000000..20aed1d21 --- /dev/null +++ b/test-network/keys/bob.pk @@ -0,0 +1 @@ +AvMMj79Dc5slgNl1v29V0mn/ixHt7CO/MbsNLQP0ZpSE \ No newline at end of file diff --git a/test-network/keys/bob.sk b/test-network/keys/bob.sk new file mode 100644 index 000000000..3c63da5b8 --- /dev/null +++ b/test-network/keys/bob.sk @@ -0,0 +1 @@ +EWYQ7LHh7eLty4OUv1IL3Yjyke/P0fyqOUNv4TBqJaM= \ No newline at end of file diff --git a/test-network/keys/charlie.pk b/test-network/keys/charlie.pk new file mode 100644 index 000000000..087aae502 --- /dev/null +++ b/test-network/keys/charlie.pk @@ -0,0 +1 @@ +AhgmflhhhFLNq+xZ1BGY9b0v8o/D3VEcSkPtGdhpv/vR \ No newline at end of file diff --git a/test-network/keys/charlie.sk b/test-network/keys/charlie.sk new file mode 100644 index 000000000..67f08daca --- /dev/null +++ b/test-network/keys/charlie.sk @@ -0,0 +1 @@ +P2qcIpdwNblXYIeakFAnsNkRQKl+JpmAX4mmmPJvluI= \ No newline at end of file diff --git a/test-network/keys/dave.pk b/test-network/keys/dave.pk new file mode 100644 index 000000000..630dc08b0 --- /dev/null +++ b/test-network/keys/dave.pk @@ -0,0 +1 @@ +AsmyG+kLuoplF8iv4A8xD2VaR86tgVyWh7t0aqbRfpmg \ No newline at end of file diff --git a/test-network/keys/dave.sk b/test-network/keys/dave.sk new file mode 100644 index 000000000..5efce2ac0 --- /dev/null +++ b/test-network/keys/dave.sk @@ -0,0 +1 @@ +u/8eCA7tnRFriVCsWm9qpVktOrSr0t2gPgBJtszdC4M= \ No newline at end of file diff --git a/test-network/traces/2024-07-12.traces b/test-network/traces/2024-07-12.traces new file mode 100644 index 000000000..7efff3021 --- /dev/null +++ b/test-network/traces/2024-07-12.traces @@ -0,0 +1,2 @@ +{"timestamp":"2024-07-12T11:47:57.300184Z","level":"INFO","fields":{"domain":"Topdown","event":"ParentFinalityAcquired { source: \"parent-finality\", is_null: false, block_height: 10, block_hash: Some(0000000000000000000000000000000000000000000000000000000000000000), commitment_hash: Some(0000000000000000000000000000000000000000000000000000000000000000), num_msgs: 5, num_validator_changes: 6 }"},"filename":"ipc/observability/src/lib.rs","line_number":36} +{"timestamp":"2024-07-12T11:47:57.300423Z","level":"INFO","fields":{"domain":"Topdown","event":"ParentFinalityPeerVoteSent { block_height: 10, block_hash: 0000000000000000000000000000000000000000000000000000000000000000, commitment_hash: 0000000000000000000000000000000000000000000000000000000000000000 }"},"filename":"ipc/observability/src/lib.rs","line_number":36} From f16f8c5d7d9b3d9357f98810ba60204435afb5ca Mon Sep 17 00:00:00 2001 From: Karel Moravec Date: Fri, 12 Jul 2024 22:35:47 +0200 Subject: [PATCH 12/33] feat: add execution metrics --- fendermint/vm/interpreter/src/fvm/check.rs | 2 ++ fendermint/vm/interpreter/src/fvm/exec.rs | 2 ++ 2 files changed, 4 insertions(+) diff --git a/fendermint/vm/interpreter/src/fvm/check.rs b/fendermint/vm/interpreter/src/fvm/check.rs index 5e627007c..89c70a617 100644 --- a/fendermint/vm/interpreter/src/fvm/check.rs +++ b/fendermint/vm/interpreter/src/fvm/check.rs @@ -1,6 +1,8 @@ // Copyright 2022-2024 Protocol Labs // SPDX-License-Identifier: Apache-2.0, MIT +use std::time::Instant; + use async_trait::async_trait; use fvm_ipld_blockstore::Blockstore; diff --git a/fendermint/vm/interpreter/src/fvm/exec.rs b/fendermint/vm/interpreter/src/fvm/exec.rs index f53e630a9..d83f6fafd 100644 --- a/fendermint/vm/interpreter/src/fvm/exec.rs +++ b/fendermint/vm/interpreter/src/fvm/exec.rs @@ -1,6 +1,8 @@ // Copyright 2022-2024 Protocol Labs // SPDX-License-Identifier: Apache-2.0, MIT +use std::time::Instant; + use anyhow::Context; use async_trait::async_trait; use std::collections::HashMap; From a1644724eb162f346e6ea89c9e2b2b6178f15eca Mon Sep 17 00:00:00 2001 From: Karel Moravec Date: Mon, 15 Jul 2024 16:37:23 +0200 Subject: [PATCH 13/33] feat: add proposals metrics & reason --- fendermint/app/src/app.rs | 4 ++-- fendermint/vm/interpreter/src/bytes.rs | 16 +++++++++++++--- fendermint/vm/interpreter/src/chain.rs | 12 ++++++++---- fendermint/vm/interpreter/src/lib.rs | 6 +++++- 4 files changed, 28 insertions(+), 10 deletions(-) diff --git a/fendermint/app/src/app.rs b/fendermint/app/src/app.rs index e01733fc0..dcf0d6e47 100644 --- a/fendermint/app/src/app.rs +++ b/fendermint/app/src/app.rs @@ -690,7 +690,7 @@ where let size_txs = txs.iter().map(|tx| tx.len()).sum::(); let num_txs = txs.len(); - let accept = self + let (accept, reason) = self .interpreter .process(self.chain_env.clone(), txs) .await @@ -729,7 +729,7 @@ where size: size_txs, tx_count: num_txs, validator: request.proposer_address.to_string().as_str(), - reason: "rejected", + reason: reason.unwrap_or_default().as_str(), }); Ok(response::ProcessProposal::Reject) } diff --git a/fendermint/vm/interpreter/src/bytes.rs b/fendermint/vm/interpreter/src/bytes.rs index 1af84dd85..59ad88b41 100644 --- a/fendermint/vm/interpreter/src/bytes.rs +++ b/fendermint/vm/interpreter/src/bytes.rs @@ -125,13 +125,17 @@ where } /// Parse messages in the block, reject if unknown format. Pass the rest to the inner `ChainMessage` interpreter. - async fn process(&self, state: Self::State, msgs: Vec) -> anyhow::Result { + async fn process( + &self, + state: Self::State, + msgs: Vec, + ) -> anyhow::Result<(bool, Option)> { if msgs.len() > self.max_msgs { tracing::warn!( block_msgs = msgs.len(), "rejecting block: too many messages" ); - return Ok(false); + return Ok((false, Some(format!("too many messages: {}", msgs.len())))); } let mut chain_msgs = Vec::new(); @@ -152,7 +156,13 @@ where "failed to decode message in proposal as ChainMessage" ); if self.reject_malformed_proposal { - return Ok(false); + return Ok(( + false, + Some(format!( + "failed to decode message in proposal as ChainMessage: {}", + e + )), + )); } } Ok(msg) => chain_msgs.push(msg), diff --git a/fendermint/vm/interpreter/src/chain.rs b/fendermint/vm/interpreter/src/chain.rs index 79136138f..5c0fe8489 100644 --- a/fendermint/vm/interpreter/src/chain.rs +++ b/fendermint/vm/interpreter/src/chain.rs @@ -175,7 +175,11 @@ where } /// Perform finality checks on top-down transactions and availability checks on bottom-up transactions. - async fn process(&self, env: Self::State, msgs: Vec) -> anyhow::Result { + async fn process( + &self, + env: Self::State, + msgs: Vec, + ) -> anyhow::Result<(bool, Option)> { for msg in msgs { match msg { ChainMessage::Ipc(IpcMessage::BottomUpExec(msg)) => { @@ -194,7 +198,7 @@ where .await; if !is_resolved { - return Ok(false); + return Ok((false, Some("checkpoint not resolved".to_string()))); } } ChainMessage::Ipc(IpcMessage::TopDownExec(ParentFinality { @@ -208,13 +212,13 @@ where let is_final = atomically(|| env.parent_finality_provider.check_proposal(&prop)).await; if !is_final { - return Ok(false); + return Ok((false, Some("parent finality not available".to_string()))); } } _ => {} }; } - Ok(true) + Ok((true, None)) } } diff --git a/fendermint/vm/interpreter/src/lib.rs b/fendermint/vm/interpreter/src/lib.rs index 42dab76b8..a12ccfcc0 100644 --- a/fendermint/vm/interpreter/src/lib.rs +++ b/fendermint/vm/interpreter/src/lib.rs @@ -54,7 +54,11 @@ pub trait ProposalInterpreter: Sync + Send { /// This is our chance check whether CIDs proposed for execution are available. /// /// Return `true` if we can accept this block, `false` to reject it. - async fn process(&self, state: Self::State, msgs: Vec) -> anyhow::Result; + async fn process( + &self, + state: Self::State, + msgs: Vec, + ) -> anyhow::Result<(bool, Option)>; } /// The `ExecInterpreter` applies messages on some state, which is From 1f5a38a27952be508f79698aa2070c12adc8f83d Mon Sep 17 00:00:00 2001 From: Karel Moravec Date: Tue, 16 Jul 2024 10:40:41 +0200 Subject: [PATCH 14/33] feat: add mempool event --- fendermint/app/src/app.rs | 8 +++++++- 1 file changed, 7 insertions(+), 1 deletion(-) diff --git a/fendermint/app/src/app.rs b/fendermint/app/src/app.rs index dcf0d6e47..d9958cd72 100644 --- a/fendermint/app/src/app.rs +++ b/fendermint/app/src/app.rs @@ -625,7 +625,13 @@ where let mut mpool_received_trace = MpoolReceived::default(); let response = match result { - Err(e) => invalid_check_tx(AppError::InvalidEncoding, e.description), + Err(e) => { + emit(MpoolReceivedInvalidMessage { + reason: "InvalidEncoding", + description: e.description.as_ref(), + }); + invalid_check_tx(AppError::InvalidEncoding, e.description) + } Ok(result) => match result { Err(IllegalMessage) => invalid_check_tx(AppError::IllegalMessage, "".to_owned()), Ok(Err(InvalidSignature(d))) => invalid_check_tx(AppError::InvalidSignature, d), From da8448510e9633e80f170096b72b9139ff8ff2f9 Mon Sep 17 00:00:00 2001 From: Karel Moravec Date: Tue, 16 Jul 2024 10:44:19 +0200 Subject: [PATCH 15/33] feat: remove --- test-network/genesis.json | 97 --------------------------- test-network/keys/alice.pk | 1 - test-network/keys/alice.sk | 1 - test-network/keys/bob.pk | 1 - test-network/keys/bob.sk | 1 - test-network/keys/charlie.pk | 1 - test-network/keys/charlie.sk | 1 - test-network/keys/dave.pk | 1 - test-network/keys/dave.sk | 1 - test-network/traces/2024-07-12.traces | 2 - 10 files changed, 107 deletions(-) delete mode 100644 test-network/genesis.json delete mode 100644 test-network/keys/alice.pk delete mode 100644 test-network/keys/alice.sk delete mode 100644 test-network/keys/bob.pk delete mode 100644 test-network/keys/bob.sk delete mode 100644 test-network/keys/charlie.pk delete mode 100644 test-network/keys/charlie.sk delete mode 100644 test-network/keys/dave.pk delete mode 100644 test-network/keys/dave.sk delete mode 100644 test-network/traces/2024-07-12.traces diff --git a/test-network/genesis.json b/test-network/genesis.json deleted file mode 100644 index b2f5501ae..000000000 --- a/test-network/genesis.json +++ /dev/null @@ -1,97 +0,0 @@ -{ - "chain_name": "test", - "timestamp": 1680101412, - "network_version": 21, - "base_fee": "1000", - "power_scale": 0, - "validators": [ - { - "public_key": "BPMMj79Dc5slgNl1v29V0mn/ixHt7CO/MbsNLQP0ZpSEd5FuW2UQ5hzNsKhauI97UZ9jQN3t+kRJQaWlcRjcJdI=", - "power": "1000000000000000000" - } - ], - "accounts": [ - { - "meta": { - "Account": { - "owner": "t1vfs6z4k6cyoevukvhqomsgwqrb75i2jodwa4jxa" - } - }, - "balance": "10000000000000000000" - }, - { - "meta": { - "Account": { - "owner": "t410frr6xjymicyh4iltk5v27c4y4misr73mcqjzh45a" - } - }, - "balance": "10000000000000000000" - }, - { - "meta": { - "Account": { - "owner": "t1zrk7jjngc3uzobjkmlzjynjfgpxvxctxbxuvs5a" - } - }, - "balance": "10000000000000000000" - }, - { - "meta": { - "Account": { - "owner": "t410f5qlw62wdgzwdwfb3rjoheibxrhke3vmzxtcdzrq" - } - }, - "balance": "10000000000000000000" - }, - { - "meta": { - "Account": { - "owner": "t1kwdghtw7j72qb5dwf4gskyp4be4cter73nlojuy" - } - }, - "balance": "10000000000000000000" - }, - { - "meta": { - "Account": { - "owner": "t410flcjfiuotgwadabcoftuuo26ooaxrovjvwdccoji" - } - }, - "balance": "10000000000000000000" - }, - { - "meta": { - "Account": { - "owner": "t1e3acffdre4egtul5kp3c2hamm522dg6aqfgzioy" - } - }, - "balance": "10000000000000000000" - }, - { - "meta": { - "Account": { - "owner": "t410fst6awyokeeevmqiwcnlzwt3g2uazcsavr2u2iwi" - } - }, - "balance": "10000000000000000000" - }, - { - "meta": { - "Multisig": { - "signers": [ - "t1zrk7jjngc3uzobjkmlzjynjfgpxvxctxbxuvs5a", - "t1kwdghtw7j72qb5dwf4gskyp4be4cter73nlojuy", - "t1e3acffdre4egtul5kp3c2hamm522dg6aqfgzioy" - ], - "threshold": 2, - "vesting_duration": 1000000, - "vesting_start": 0 - } - }, - "balance": "30000000000000000000" - } - ], - "eam_permission_mode": { - "mode": "unrestricted" - } -} \ No newline at end of file diff --git a/test-network/keys/alice.pk b/test-network/keys/alice.pk deleted file mode 100644 index 794dee8f6..000000000 --- a/test-network/keys/alice.pk +++ /dev/null @@ -1 +0,0 @@ -AhIQ+C+xL8C9v45KcdczZj5H4sPxROx08lT+seQCEM6c \ No newline at end of file diff --git a/test-network/keys/alice.sk b/test-network/keys/alice.sk deleted file mode 100644 index a8c648503..000000000 --- a/test-network/keys/alice.sk +++ /dev/null @@ -1 +0,0 @@ -UWJv1Gj1tmnxlKUQizJTxobyJuB7u4PbkO3J2pfd+PI= \ No newline at end of file diff --git a/test-network/keys/bob.pk b/test-network/keys/bob.pk deleted file mode 100644 index 20aed1d21..000000000 --- a/test-network/keys/bob.pk +++ /dev/null @@ -1 +0,0 @@ -AvMMj79Dc5slgNl1v29V0mn/ixHt7CO/MbsNLQP0ZpSE \ No newline at end of file diff --git a/test-network/keys/bob.sk b/test-network/keys/bob.sk deleted file mode 100644 index 3c63da5b8..000000000 --- a/test-network/keys/bob.sk +++ /dev/null @@ -1 +0,0 @@ -EWYQ7LHh7eLty4OUv1IL3Yjyke/P0fyqOUNv4TBqJaM= \ No newline at end of file diff --git a/test-network/keys/charlie.pk b/test-network/keys/charlie.pk deleted file mode 100644 index 087aae502..000000000 --- a/test-network/keys/charlie.pk +++ /dev/null @@ -1 +0,0 @@ -AhgmflhhhFLNq+xZ1BGY9b0v8o/D3VEcSkPtGdhpv/vR \ No newline at end of file diff --git a/test-network/keys/charlie.sk b/test-network/keys/charlie.sk deleted file mode 100644 index 67f08daca..000000000 --- a/test-network/keys/charlie.sk +++ /dev/null @@ -1 +0,0 @@ -P2qcIpdwNblXYIeakFAnsNkRQKl+JpmAX4mmmPJvluI= \ No newline at end of file diff --git a/test-network/keys/dave.pk b/test-network/keys/dave.pk deleted file mode 100644 index 630dc08b0..000000000 --- a/test-network/keys/dave.pk +++ /dev/null @@ -1 +0,0 @@ -AsmyG+kLuoplF8iv4A8xD2VaR86tgVyWh7t0aqbRfpmg \ No newline at end of file diff --git a/test-network/keys/dave.sk b/test-network/keys/dave.sk deleted file mode 100644 index 5efce2ac0..000000000 --- a/test-network/keys/dave.sk +++ /dev/null @@ -1 +0,0 @@ -u/8eCA7tnRFriVCsWm9qpVktOrSr0t2gPgBJtszdC4M= \ No newline at end of file diff --git a/test-network/traces/2024-07-12.traces b/test-network/traces/2024-07-12.traces deleted file mode 100644 index 7efff3021..000000000 --- a/test-network/traces/2024-07-12.traces +++ /dev/null @@ -1,2 +0,0 @@ -{"timestamp":"2024-07-12T11:47:57.300184Z","level":"INFO","fields":{"domain":"Topdown","event":"ParentFinalityAcquired { source: \"parent-finality\", is_null: false, block_height: 10, block_hash: Some(0000000000000000000000000000000000000000000000000000000000000000), commitment_hash: Some(0000000000000000000000000000000000000000000000000000000000000000), num_msgs: 5, num_validator_changes: 6 }"},"filename":"ipc/observability/src/lib.rs","line_number":36} -{"timestamp":"2024-07-12T11:47:57.300423Z","level":"INFO","fields":{"domain":"Topdown","event":"ParentFinalityPeerVoteSent { block_height: 10, block_hash: 0000000000000000000000000000000000000000000000000000000000000000, commitment_hash: 0000000000000000000000000000000000000000000000000000000000000000 }"},"filename":"ipc/observability/src/lib.rs","line_number":36} From c1ded52f02e49bb3788eef857fc020bb6b7cc734 Mon Sep 17 00:00:00 2001 From: Karel Moravec Date: Tue, 16 Jul 2024 14:49:56 +0200 Subject: [PATCH 16/33] feat: address comments --- fendermint/app/src/app.rs | 45 +++++++++---------- fendermint/vm/interpreter/src/bytes.rs | 13 +++--- fendermint/vm/interpreter/src/chain.rs | 8 ++-- fendermint/vm/interpreter/src/fvm/check.rs | 2 - fendermint/vm/interpreter/src/fvm/exec.rs | 2 - .../vm/interpreter/src/fvm/state/exec.rs | 37 +++++++++++++++ .../vm/interpreter/src/fvm/state/mod.rs | 2 +- fendermint/vm/interpreter/src/lib.rs | 2 +- 8 files changed, 70 insertions(+), 41 deletions(-) diff --git a/fendermint/app/src/app.rs b/fendermint/app/src/app.rs index d9958cd72..be2190799 100644 --- a/fendermint/app/src/app.rs +++ b/fendermint/app/src/app.rs @@ -696,11 +696,7 @@ where let size_txs = txs.iter().map(|tx| tx.len()).sum::(); let num_txs = txs.len(); - let (accept, reason) = self - .interpreter - .process(self.chain_env.clone(), txs) - .await - .context("failed to process proposal")?; + let process_result = self.interpreter.process(self.chain_env.clone(), txs).await; emit(BlockProposalReceived { height: request.height.value(), @@ -720,24 +716,27 @@ where reason: None, }); - if accept { - emit(BlockProposalAccepted { - height: request.height.value(), - hash: HexEncodableBlockHash(request.hash.into()), - size: size_txs, - tx_count: num_txs, - validator: request.proposer_address.to_string().as_str(), - }); - Ok(response::ProcessProposal::Accept) - } else { - emit(BlockProposalRejected { - height: request.height.value(), - size: size_txs, - tx_count: num_txs, - validator: request.proposer_address.to_string().as_str(), - reason: reason.unwrap_or_default().as_str(), - }); - Ok(response::ProcessProposal::Reject) + match process_result { + Ok(_) => { + emit(BlockProposalAccepted { + height: request.height.value(), + hash: HexEncodableBlockHash(request.hash.into()), + size: size_txs, + tx_count: num_txs, + validator: request.proposer_address.to_string().as_str(), + }); + Ok(response::ProcessProposal::Accept) + } + Err(e) => { + emit(BlockProposalRejected { + height: request.height.value(), + size: size_txs, + tx_count: num_txs, + validator: request.proposer_address.to_string().as_str(), + reason: e.as_str(), + }); + Ok(response::ProcessProposal::Reject) + } } } diff --git a/fendermint/vm/interpreter/src/bytes.rs b/fendermint/vm/interpreter/src/bytes.rs index 59ad88b41..b1afaad66 100644 --- a/fendermint/vm/interpreter/src/bytes.rs +++ b/fendermint/vm/interpreter/src/bytes.rs @@ -129,13 +129,13 @@ where &self, state: Self::State, msgs: Vec, - ) -> anyhow::Result<(bool, Option)> { + ) -> anyhow::Result { if msgs.len() > self.max_msgs { tracing::warn!( block_msgs = msgs.len(), "rejecting block: too many messages" ); - return Ok((false, Some(format!("too many messages: {}", msgs.len())))); + return Err(format!("too many messages: {}", msgs.len())); } let mut chain_msgs = Vec::new(); @@ -156,12 +156,9 @@ where "failed to decode message in proposal as ChainMessage" ); if self.reject_malformed_proposal { - return Ok(( - false, - Some(format!( - "failed to decode message in proposal as ChainMessage: {}", - e - )), + return Err(format!( + "failed to decode message in proposal as ChainMessage: {}", + e )); } } diff --git a/fendermint/vm/interpreter/src/chain.rs b/fendermint/vm/interpreter/src/chain.rs index 5c0fe8489..05860bfec 100644 --- a/fendermint/vm/interpreter/src/chain.rs +++ b/fendermint/vm/interpreter/src/chain.rs @@ -179,7 +179,7 @@ where &self, env: Self::State, msgs: Vec, - ) -> anyhow::Result<(bool, Option)> { + ) -> anyhow::Result { for msg in msgs { match msg { ChainMessage::Ipc(IpcMessage::BottomUpExec(msg)) => { @@ -198,7 +198,7 @@ where .await; if !is_resolved { - return Ok((false, Some("checkpoint not resolved".to_string()))); + return Err("checkpoint not resolved".to_string()); } } ChainMessage::Ipc(IpcMessage::TopDownExec(ParentFinality { @@ -212,13 +212,13 @@ where let is_final = atomically(|| env.parent_finality_provider.check_proposal(&prop)).await; if !is_final { - return Ok((false, Some("parent finality not available".to_string()))); + return Err("parent finality not available".to_string()); } } _ => {} }; } - Ok((true, None)) + Ok(true) } } diff --git a/fendermint/vm/interpreter/src/fvm/check.rs b/fendermint/vm/interpreter/src/fvm/check.rs index 89c70a617..5e627007c 100644 --- a/fendermint/vm/interpreter/src/fvm/check.rs +++ b/fendermint/vm/interpreter/src/fvm/check.rs @@ -1,8 +1,6 @@ // Copyright 2022-2024 Protocol Labs // SPDX-License-Identifier: Apache-2.0, MIT -use std::time::Instant; - use async_trait::async_trait; use fvm_ipld_blockstore::Blockstore; diff --git a/fendermint/vm/interpreter/src/fvm/exec.rs b/fendermint/vm/interpreter/src/fvm/exec.rs index d83f6fafd..f53e630a9 100644 --- a/fendermint/vm/interpreter/src/fvm/exec.rs +++ b/fendermint/vm/interpreter/src/fvm/exec.rs @@ -1,8 +1,6 @@ // Copyright 2022-2024 Protocol Labs // SPDX-License-Identifier: Apache-2.0, MIT -use std::time::Instant; - use anyhow::Context; use async_trait::async_trait; use std::collections::HashMap; diff --git a/fendermint/vm/interpreter/src/fvm/state/exec.rs b/fendermint/vm/interpreter/src/fvm/state/exec.rs index 7d5f10dda..46e291eae 100644 --- a/fendermint/vm/interpreter/src/fvm/state/exec.rs +++ b/fendermint/vm/interpreter/src/fvm/state/exec.rs @@ -2,6 +2,7 @@ // SPDX-License-Identifier: Apache-2.0, MIT use std::collections::{HashMap, HashSet}; +use std::time::{Duration, Instant}; use anyhow::Ok; use cid::Cid; @@ -350,3 +351,39 @@ fn check_error(e: anyhow::Error) -> (ApplyRet, ActorAddressMap) { }; (ret, Default::default()) } + +pub struct ElapsedExecution<'a, DB> +where + DB: Blockstore + Clone + 'static, +{ + state: &'a mut FvmExecState, +} + +impl<'a, DB> ElapsedExecution<'a, DB> +where + DB: Blockstore + Clone + 'static, +{ + pub fn new(state: &'a mut FvmExecState) -> Self { + Self { state } + } + + pub fn execute_implicit( + &mut self, + msg: Message, + ) -> anyhow::Result<(ApplyRet, ActorAddressMap, Duration)> { + let start = Instant::now(); + let result = self.state.execute_implicit(msg)?; + let duration = start.elapsed(); + Ok((result.0, result.1, duration)) + } + + pub fn execute_explicit( + &mut self, + msg: Message, + ) -> anyhow::Result<(ApplyRet, ActorAddressMap, Duration)> { + let start = Instant::now(); + let result = self.state.execute_explicit(msg)?; + let duration = start.elapsed(); + Ok((result.0, result.1, duration)) + } +} diff --git a/fendermint/vm/interpreter/src/fvm/state/mod.rs b/fendermint/vm/interpreter/src/fvm/state/mod.rs index 22a1504e4..0547ce9d8 100644 --- a/fendermint/vm/interpreter/src/fvm/state/mod.rs +++ b/fendermint/vm/interpreter/src/fvm/state/mod.rs @@ -12,7 +12,7 @@ pub mod snapshot; use std::sync::Arc; pub use check::FvmCheckState; -pub use exec::{BlockHash, FvmExecState, FvmStateParams, FvmUpdatableParams}; +pub use exec::{BlockHash, ElapsedExecution, FvmExecState, FvmStateParams, FvmUpdatableParams}; pub use genesis::{empty_state_tree, FvmGenesisState}; pub use query::FvmQueryState; diff --git a/fendermint/vm/interpreter/src/lib.rs b/fendermint/vm/interpreter/src/lib.rs index a12ccfcc0..f8a40e6d0 100644 --- a/fendermint/vm/interpreter/src/lib.rs +++ b/fendermint/vm/interpreter/src/lib.rs @@ -58,7 +58,7 @@ pub trait ProposalInterpreter: Sync + Send { &self, state: Self::State, msgs: Vec, - ) -> anyhow::Result<(bool, Option)>; + ) -> anyhow::Result; } /// The `ExecInterpreter` applies messages on some state, which is From 59f3ea75c6157702bd648a5408bf4797de6d17ef Mon Sep 17 00:00:00 2001 From: Karel Moravec Date: Tue, 16 Jul 2024 15:59:21 +0200 Subject: [PATCH 17/33] feat: address comments --- fendermint/app/src/app.rs | 2 +- fendermint/vm/interpreter/src/bytes.rs | 10 ++++------ fendermint/vm/interpreter/src/chain.rs | 7 ++++--- fendermint/vm/interpreter/src/errors.rs | 16 ++++++++++++++++ fendermint/vm/interpreter/src/fvm/state/exec.rs | 2 ++ fendermint/vm/interpreter/src/lib.rs | 3 ++- 6 files changed, 29 insertions(+), 11 deletions(-) create mode 100644 fendermint/vm/interpreter/src/errors.rs diff --git a/fendermint/app/src/app.rs b/fendermint/app/src/app.rs index be2190799..61ebadb68 100644 --- a/fendermint/app/src/app.rs +++ b/fendermint/app/src/app.rs @@ -733,7 +733,7 @@ where size: size_txs, tx_count: num_txs, validator: request.proposer_address.to_string().as_str(), - reason: e.as_str(), + reason: e.to_string().as_str(), }); Ok(response::ProcessProposal::Reject) } diff --git a/fendermint/vm/interpreter/src/bytes.rs b/fendermint/vm/interpreter/src/bytes.rs index b1afaad66..e3a45ca3e 100644 --- a/fendermint/vm/interpreter/src/bytes.rs +++ b/fendermint/vm/interpreter/src/bytes.rs @@ -9,6 +9,7 @@ use fvm_ipld_encoding::Error as IpldError; use crate::{ chain::{ChainMessageApplyRet, ChainMessageCheckRes}, + errors::ProcessError, fvm::{FvmQuery, FvmQueryRet}, CheckInterpreter, ExecInterpreter, GenesisInterpreter, ProposalInterpreter, QueryInterpreter, }; @@ -129,13 +130,13 @@ where &self, state: Self::State, msgs: Vec, - ) -> anyhow::Result { + ) -> anyhow::Result { if msgs.len() > self.max_msgs { tracing::warn!( block_msgs = msgs.len(), "rejecting block: too many messages" ); - return Err(format!("too many messages: {}", msgs.len())); + return Err(ProcessError::TooManyMessages(msgs.len())); } let mut chain_msgs = Vec::new(); @@ -156,10 +157,7 @@ where "failed to decode message in proposal as ChainMessage" ); if self.reject_malformed_proposal { - return Err(format!( - "failed to decode message in proposal as ChainMessage: {}", - e - )); + return Err(ProcessError::FailedToDecodeMessage(e.to_string())); } } Ok(msg) => chain_msgs.push(msg), diff --git a/fendermint/vm/interpreter/src/chain.rs b/fendermint/vm/interpreter/src/chain.rs index 05860bfec..dae3dc951 100644 --- a/fendermint/vm/interpreter/src/chain.rs +++ b/fendermint/vm/interpreter/src/chain.rs @@ -1,5 +1,6 @@ // Copyright 2022-2024 Protocol Labs // SPDX-License-Identifier: Apache-2.0, MIT +use crate::errors::ProcessError; use crate::fvm::state::ipc::GatewayCaller; use crate::fvm::{topdown, FvmApplyRet, PowerUpdates}; use crate::{ @@ -179,7 +180,7 @@ where &self, env: Self::State, msgs: Vec, - ) -> anyhow::Result { + ) -> anyhow::Result { for msg in msgs { match msg { ChainMessage::Ipc(IpcMessage::BottomUpExec(msg)) => { @@ -198,7 +199,7 @@ where .await; if !is_resolved { - return Err("checkpoint not resolved".to_string()); + return Err(ProcessError::CheckpointNotResolved); } } ChainMessage::Ipc(IpcMessage::TopDownExec(ParentFinality { @@ -212,7 +213,7 @@ where let is_final = atomically(|| env.parent_finality_provider.check_proposal(&prop)).await; if !is_final { - return Err("parent finality not available".to_string()); + return Err(ProcessError::ParentFinalityNotAvailable); } } _ => {} diff --git a/fendermint/vm/interpreter/src/errors.rs b/fendermint/vm/interpreter/src/errors.rs new file mode 100644 index 000000000..62e736395 --- /dev/null +++ b/fendermint/vm/interpreter/src/errors.rs @@ -0,0 +1,16 @@ +// Copyright 2022-2024 Protocol Labs +// SPDX-License-Identifier: Apache-2.0, MIT + +use thiserror::Error; + +#[derive(Error, Debug)] +pub enum ProcessError { + #[error("checkpoint not resolved")] + CheckpointNotResolved, + #[error("parent finality not available")] + ParentFinalityNotAvailable, + #[error("too many messages: {0}")] + TooManyMessages(usize), + #[error("failed to decode message in proposal as ChainMessage: {0}")] + FailedToDecodeMessage(String), +} diff --git a/fendermint/vm/interpreter/src/fvm/state/exec.rs b/fendermint/vm/interpreter/src/fvm/state/exec.rs index 46e291eae..3ab8b4fe0 100644 --- a/fendermint/vm/interpreter/src/fvm/state/exec.rs +++ b/fendermint/vm/interpreter/src/fvm/state/exec.rs @@ -38,6 +38,8 @@ pub type ActorAddressMap = HashMap; /// The result of the message application bundled with any delegated addresses of event emitters. pub type ExecResult = anyhow::Result<(ApplyRet, ActorAddressMap)>; +use crate::fvm::observe::MsgExecCheck; + /// Parts of the state which evolve during the lifetime of the chain. #[serde_as] #[derive(Serialize, Deserialize, Debug, Clone, Eq, PartialEq)] diff --git a/fendermint/vm/interpreter/src/lib.rs b/fendermint/vm/interpreter/src/lib.rs index f8a40e6d0..49ac252ca 100644 --- a/fendermint/vm/interpreter/src/lib.rs +++ b/fendermint/vm/interpreter/src/lib.rs @@ -4,6 +4,7 @@ use async_trait::async_trait; pub mod bytes; pub mod chain; +pub mod errors; pub mod fvm; pub mod signed; @@ -58,7 +59,7 @@ pub trait ProposalInterpreter: Sync + Send { &self, state: Self::State, msgs: Vec, - ) -> anyhow::Result; + ) -> anyhow::Result; } /// The `ExecInterpreter` applies messages on some state, which is From 13bb9c64317401529e56da6f3c7d91b608d4ae76 Mon Sep 17 00:00:00 2001 From: Karel Moravec Date: Tue, 16 Jul 2024 16:11:24 +0200 Subject: [PATCH 18/33] feat: fix clippy --- fendermint/vm/interpreter/src/fvm/state/exec.rs | 2 -- 1 file changed, 2 deletions(-) diff --git a/fendermint/vm/interpreter/src/fvm/state/exec.rs b/fendermint/vm/interpreter/src/fvm/state/exec.rs index 3ab8b4fe0..46e291eae 100644 --- a/fendermint/vm/interpreter/src/fvm/state/exec.rs +++ b/fendermint/vm/interpreter/src/fvm/state/exec.rs @@ -38,8 +38,6 @@ pub type ActorAddressMap = HashMap; /// The result of the message application bundled with any delegated addresses of event emitters. pub type ExecResult = anyhow::Result<(ApplyRet, ActorAddressMap)>; -use crate::fvm::observe::MsgExecCheck; - /// Parts of the state which evolve during the lifetime of the chain. #[serde_as] #[derive(Serialize, Deserialize, Debug, Clone, Eq, PartialEq)] From d3b22d696b6051c55aa27cf9137fd60511f825a2 Mon Sep 17 00:00:00 2001 From: raulk Date: Tue, 16 Jul 2024 17:42:49 +0100 Subject: [PATCH 19/33] minor cleanup. --- fendermint/app/src/cmd/run.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/fendermint/app/src/cmd/run.rs b/fendermint/app/src/cmd/run.rs index d9463729f..c3ae39ec7 100644 --- a/fendermint/app/src/cmd/run.rs +++ b/fendermint/app/src/cmd/run.rs @@ -263,7 +263,7 @@ async fn run(settings: Settings) -> anyhow::Result<()> { CachedFinalityProvider::uninitialized(config.clone(), ipc_provider.clone()).await?; let p = Arc::new(Toggle::enabled(finality_provider)); - (p, Some((ipc_provider_with_latency, config))) + (p, Some((ipc_provider, config))) } else { info!("topdown finality disabled"); (Arc::new(Toggle::disabled()), None) From 094e9b68c6db39db7a24aa5d66c1d82fcdf36799 Mon Sep 17 00:00:00 2001 From: Karel Moravec Date: Tue, 16 Jul 2024 20:38:52 +0200 Subject: [PATCH 20/33] feat: fix typo --- Cargo.lock | 1 + fendermint/app/src/app.rs | 39 ++++++++++++++-------------- fendermint/app/src/observe.rs | 2 ++ fendermint/vm/topdown/src/observe.rs | 3 --- fendermint/vm/topdown/src/voting.rs | 4 +-- 5 files changed, 24 insertions(+), 25 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index cbc2f3f1b..c482f4abc 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -5067,6 +5067,7 @@ dependencies = [ name = "ipc-observability" version = "0.1.0" dependencies = [ + "hex", "lazy_static", "prometheus", "tracing", diff --git a/fendermint/app/src/app.rs b/fendermint/app/src/app.rs index 61ebadb68..5c402969b 100644 --- a/fendermint/app/src/app.rs +++ b/fendermint/app/src/app.rs @@ -716,28 +716,27 @@ where reason: None, }); - match process_result { - Ok(_) => { - emit(BlockProposalAccepted { - height: request.height.value(), - hash: HexEncodableBlockHash(request.hash.into()), - size: size_txs, - tx_count: num_txs, - validator: request.proposer_address.to_string().as_str(), - }); - Ok(response::ProcessProposal::Accept) - } + let mut proposal_evaluated = BlockProposalEvaluated { + height: request.height.value(), + hash: HexEncodableBlockHash(request.hash.into()), + size: size_txs, + tx_count: num_txs, + validator: &request.proposer_address, + accept: true, + reason: None, + }; + + let process_proposal = match process_result { + Ok(_) => response::ProcessProposal::Accept, Err(e) => { - emit(BlockProposalRejected { - height: request.height.value(), - size: size_txs, - tx_count: num_txs, - validator: request.proposer_address.to_string().as_str(), - reason: e.to_string().as_str(), - }); - Ok(response::ProcessProposal::Reject) + proposal_evaluated.accept = false; + proposal_evaluated.reason = Some(e); + response::ProcessProposal::Reject } - } + }; + + emit(proposal_evaluated); + Ok(process_proposal) } /// Signals the beginning of a new block, prior to any `DeliverTx` calls. diff --git a/fendermint/app/src/observe.rs b/fendermint/app/src/observe.rs index 793abe2fa..7f434827c 100644 --- a/fendermint/app/src/observe.rs +++ b/fendermint/app/src/observe.rs @@ -170,6 +170,8 @@ mod tests { validator: &id, }); + let id = Id::new([0x01; 20]); + emit(BlockProposalSent { height: 1, size: 100, diff --git a/fendermint/vm/topdown/src/observe.rs b/fendermint/vm/topdown/src/observe.rs index cce0b3b2e..5a0caa66e 100644 --- a/fendermint/vm/topdown/src/observe.rs +++ b/fendermint/vm/topdown/src/observe.rs @@ -1,9 +1,6 @@ // Copyright 2022-2024 Protocol Labs // SPDX-License-Identifier: Apache-2.0, MIT -use hex; -use std::fmt; - use ipc_observability::{ impl_traceable, impl_traceables, lazy_static, register_metrics, serde::HexEncodableBlockHash, Recordable, TraceLevel, Traceable, diff --git a/fendermint/vm/topdown/src/voting.rs b/fendermint/vm/topdown/src/voting.rs index f8e0a6522..793c2ab24 100644 --- a/fendermint/vm/topdown/src/voting.rs +++ b/fendermint/vm/topdown/src/voting.rs @@ -8,8 +8,8 @@ use std::hash::Hash; use std::{fmt::Debug, time::Duration}; use crate::observe::{ - HexEncodableBlockHash, ParentFinalityCommitted, ParentFinalityPeerQuorumReached, - ParentFinalityPeerVoteReceived, ParentFinalityPeerVoteSent, + ParentFinalityCommitted, ParentFinalityPeerQuorumReached, ParentFinalityPeerVoteReceived, + ParentFinalityPeerVoteSent, }; use crate::{BlockHash, BlockHeight}; use ipc_observability::{emit, serde::HexEncodableBlockHash}; From 27e7e36ff740027883aaf6890ac84b102ed4825e Mon Sep 17 00:00:00 2001 From: Karel Moravec Date: Tue, 16 Jul 2024 21:36:08 +0200 Subject: [PATCH 21/33] feat: standartize mpool trace --- fendermint/app/src/observe.rs | 2 -- 1 file changed, 2 deletions(-) diff --git a/fendermint/app/src/observe.rs b/fendermint/app/src/observe.rs index 7f434827c..793abe2fa 100644 --- a/fendermint/app/src/observe.rs +++ b/fendermint/app/src/observe.rs @@ -170,8 +170,6 @@ mod tests { validator: &id, }); - let id = Id::new([0x01; 20]); - emit(BlockProposalSent { height: 1, size: 100, From e6e79f3902b1307d813b367a01ae32cb0bf1f642 Mon Sep 17 00:00:00 2001 From: Karel Moravec Date: Fri, 19 Jul 2024 00:08:46 +0200 Subject: [PATCH 22/33] feat: address comments --- fendermint/app/src/app.rs | 14 ++++--- fendermint/app/src/cmd/run.rs | 4 +- fendermint/app/src/observe.rs | 7 ++++ fendermint/vm/interpreter/src/bytes.rs | 13 +++++-- fendermint/vm/interpreter/src/chain.rs | 13 ++++--- fendermint/vm/interpreter/src/errors.rs | 2 + fendermint/vm/interpreter/src/fvm/observe.rs | 3 +- .../vm/interpreter/src/fvm/state/exec.rs | 38 +------------------ .../vm/interpreter/src/fvm/state/mod.rs | 2 +- fendermint/vm/interpreter/src/lib.rs | 13 ++++++- fendermint/vm/topdown/src/proxy.rs | 1 + 11 files changed, 55 insertions(+), 55 deletions(-) diff --git a/fendermint/app/src/app.rs b/fendermint/app/src/app.rs index 5c402969b..897df8b97 100644 --- a/fendermint/app/src/app.rs +++ b/fendermint/app/src/app.rs @@ -26,7 +26,8 @@ use fendermint_vm_interpreter::fvm::store::ReadOnlyBlockstore; use fendermint_vm_interpreter::fvm::{FvmApplyRet, FvmGenesisOutput, PowerUpdates}; use fendermint_vm_interpreter::signed::InvalidSignature; use fendermint_vm_interpreter::{ - CheckInterpreter, ExecInterpreter, GenesisInterpreter, ProposalInterpreter, QueryInterpreter, + CheckInterpreter, ExecInterpreter, GenesisInterpreter, ProcessResult, ProposalInterpreter, + QueryInterpreter, }; use fendermint_vm_message::query::FvmQueryHeight; use fendermint_vm_snapshot::{SnapshotClient, SnapshotError}; @@ -696,7 +697,10 @@ where let size_txs = txs.iter().map(|tx| tx.len()).sum::(); let num_txs = txs.len(); - let process_result = self.interpreter.process(self.chain_env.clone(), txs).await; + let process_result = self + .interpreter + .process(self.chain_env.clone(), txs) + .await?; emit(BlockProposalReceived { height: request.height.value(), @@ -727,10 +731,10 @@ where }; let process_proposal = match process_result { - Ok(_) => response::ProcessProposal::Accept, - Err(e) => { + ProcessResult::Accepted => response::ProcessProposal::Accept, + ProcessResult::Rejected(reason) => { proposal_evaluated.accept = false; - proposal_evaluated.reason = Some(e); + proposal_evaluated.reason = Some(reason); response::ProcessProposal::Reject } }; diff --git a/fendermint/app/src/cmd/run.rs b/fendermint/app/src/cmd/run.rs index c3ae39ec7..2dac3ef6a 100644 --- a/fendermint/app/src/cmd/run.rs +++ b/fendermint/app/src/cmd/run.rs @@ -24,7 +24,7 @@ use fendermint_vm_snapshot::{SnapshotManager, SnapshotParams}; use fendermint_vm_topdown::observe::register_metrics as register_topdown_metrics; use fendermint_vm_topdown::proxy::{IPCProviderProxy, IPCProviderProxyWithLatency}; use fendermint_vm_topdown::sync::launch_polling_syncer; -use fendermint_vm_topdown::voting::{publish_vote_loop, VoteTally}; +use fendermint_vm_topdown::voting::{publish_vote_loop, Error as VoteError, VoteTally}; use fendermint_vm_topdown::{CachedFinalityProvider, IPCParentFinality, Toggle}; use fvm_shared::address::{current_network, Address, Network}; use ipc_ipld_resolver::{Event as ResolverEvent, VoteRecord}; @@ -543,7 +543,7 @@ async fn dispatch_vote( tracing::debug!("ignoring vote; topdown disabled"); return; } - let _res = atomically_or_err(|| { + let res = atomically_or_err(|| { parent_finality_votes.add_vote( vote.public_key.clone(), f.height, diff --git a/fendermint/app/src/observe.rs b/fendermint/app/src/observe.rs index 793abe2fa..37bbfd28d 100644 --- a/fendermint/app/src/observe.rs +++ b/fendermint/app/src/observe.rs @@ -1,6 +1,7 @@ // Copyright 2022-2024 Protocol Labs // SPDX-License-Identifier: Apache-2.0, MIT +use fendermint_vm_message::conv::from_eth; use fvm_shared::address::Address; use fvm_shared::econ::TokenAmount; @@ -147,6 +148,12 @@ pub struct MpoolReceived { impl Recordable for MpoolReceived { fn record_metrics(&self) { + let from = self + .message + .as_ref() + .map(|m| m.from.to_string()) + .unwrap_or("".to_string()); + MPOOL_RECEIVED .with_label_values(&[&self.accept.to_string()]) .inc(); diff --git a/fendermint/vm/interpreter/src/bytes.rs b/fendermint/vm/interpreter/src/bytes.rs index e3a45ca3e..af8273fb7 100644 --- a/fendermint/vm/interpreter/src/bytes.rs +++ b/fendermint/vm/interpreter/src/bytes.rs @@ -11,7 +11,8 @@ use crate::{ chain::{ChainMessageApplyRet, ChainMessageCheckRes}, errors::ProcessError, fvm::{FvmQuery, FvmQueryRet}, - CheckInterpreter, ExecInterpreter, GenesisInterpreter, ProposalInterpreter, QueryInterpreter, + CheckInterpreter, ExecInterpreter, GenesisInterpreter, ProcessResult, ProposalInterpreter, + QueryInterpreter, }; pub type BytesMessageApplyRes = Result; @@ -130,13 +131,15 @@ where &self, state: Self::State, msgs: Vec, - ) -> anyhow::Result { + ) -> anyhow::Result { if msgs.len() > self.max_msgs { tracing::warn!( block_msgs = msgs.len(), "rejecting block: too many messages" ); - return Err(ProcessError::TooManyMessages(msgs.len())); + return Ok(ProcessResult::Rejected(ProcessError::TooManyMessages( + msgs.len(), + ))); } let mut chain_msgs = Vec::new(); @@ -157,7 +160,9 @@ where "failed to decode message in proposal as ChainMessage" ); if self.reject_malformed_proposal { - return Err(ProcessError::FailedToDecodeMessage(e.to_string())); + return Ok(ProcessResult::Rejected( + ProcessError::FailedToDecodeMessage(e.to_string()), + )); } } Ok(msg) => chain_msgs.push(msg), diff --git a/fendermint/vm/interpreter/src/chain.rs b/fendermint/vm/interpreter/src/chain.rs index dae3dc951..00a3ccbdb 100644 --- a/fendermint/vm/interpreter/src/chain.rs +++ b/fendermint/vm/interpreter/src/chain.rs @@ -7,7 +7,8 @@ use crate::{ fvm::state::FvmExecState, fvm::FvmMessage, signed::{SignedMessageApplyRes, SignedMessageCheckRes, SyntheticMessage, VerifiableMessage}, - CheckInterpreter, ExecInterpreter, GenesisInterpreter, ProposalInterpreter, QueryInterpreter, + CheckInterpreter, ExecInterpreter, GenesisInterpreter, ProcessResult, ProposalInterpreter, + QueryInterpreter, }; use anyhow::{bail, Context}; use async_stm::atomically; @@ -180,7 +181,7 @@ where &self, env: Self::State, msgs: Vec, - ) -> anyhow::Result { + ) -> anyhow::Result { for msg in msgs { match msg { ChainMessage::Ipc(IpcMessage::BottomUpExec(msg)) => { @@ -199,7 +200,7 @@ where .await; if !is_resolved { - return Err(ProcessError::CheckpointNotResolved); + return Ok(ProcessResult::Rejected(ProcessError::CheckpointNotResolved)); } } ChainMessage::Ipc(IpcMessage::TopDownExec(ParentFinality { @@ -213,13 +214,15 @@ where let is_final = atomically(|| env.parent_finality_provider.check_proposal(&prop)).await; if !is_final { - return Err(ProcessError::ParentFinalityNotAvailable); + return Ok(ProcessResult::Rejected( + ProcessError::ParentFinalityNotAvailable, + )); } } _ => {} }; } - Ok(true) + Ok(ProcessResult::Accepted) } } diff --git a/fendermint/vm/interpreter/src/errors.rs b/fendermint/vm/interpreter/src/errors.rs index 62e736395..8cdf28a40 100644 --- a/fendermint/vm/interpreter/src/errors.rs +++ b/fendermint/vm/interpreter/src/errors.rs @@ -13,4 +13,6 @@ pub enum ProcessError { TooManyMessages(usize), #[error("failed to decode message in proposal as ChainMessage: {0}")] FailedToDecodeMessage(String), + #[error("")] + Empty, } diff --git a/fendermint/vm/interpreter/src/fvm/observe.rs b/fendermint/vm/interpreter/src/fvm/observe.rs index d0304b879..fd8b0ead9 100644 --- a/fendermint/vm/interpreter/src/fvm/observe.rs +++ b/fendermint/vm/interpreter/src/fvm/observe.rs @@ -14,6 +14,8 @@ use prometheus::{ use fendermint_crypto::PublicKey; use fvm_shared::message::Message; +use fvm_shared::message::Message; + register_metrics! { EXEC_FVM_CHECK_EXECUTION_TIME_SECS: Histogram = register_histogram!("exec_fvm_check_execution_time_secs", "Execution time of FVM check in seconds"); @@ -181,7 +183,6 @@ mod tests { config_number: 3, }); - let mut r = thread_rng(); let secret_key = SecretKey::random(&mut r); emit(CheckpointSigned { diff --git a/fendermint/vm/interpreter/src/fvm/state/exec.rs b/fendermint/vm/interpreter/src/fvm/state/exec.rs index 46e291eae..def96ce14 100644 --- a/fendermint/vm/interpreter/src/fvm/state/exec.rs +++ b/fendermint/vm/interpreter/src/fvm/state/exec.rs @@ -177,11 +177,13 @@ where /// Execute message implicitly. pub fn execute_implicit(&mut self, msg: Message) -> ExecResult { + // TODO Karel - measure here self.execute_message(msg, ApplyKind::Implicit) } /// Execute message explicitly. pub fn execute_explicit(&mut self, msg: Message) -> ExecResult { + // TODO Karel - measure here self.execute_message(msg, ApplyKind::Explicit) } @@ -351,39 +353,3 @@ fn check_error(e: anyhow::Error) -> (ApplyRet, ActorAddressMap) { }; (ret, Default::default()) } - -pub struct ElapsedExecution<'a, DB> -where - DB: Blockstore + Clone + 'static, -{ - state: &'a mut FvmExecState, -} - -impl<'a, DB> ElapsedExecution<'a, DB> -where - DB: Blockstore + Clone + 'static, -{ - pub fn new(state: &'a mut FvmExecState) -> Self { - Self { state } - } - - pub fn execute_implicit( - &mut self, - msg: Message, - ) -> anyhow::Result<(ApplyRet, ActorAddressMap, Duration)> { - let start = Instant::now(); - let result = self.state.execute_implicit(msg)?; - let duration = start.elapsed(); - Ok((result.0, result.1, duration)) - } - - pub fn execute_explicit( - &mut self, - msg: Message, - ) -> anyhow::Result<(ApplyRet, ActorAddressMap, Duration)> { - let start = Instant::now(); - let result = self.state.execute_explicit(msg)?; - let duration = start.elapsed(); - Ok((result.0, result.1, duration)) - } -} diff --git a/fendermint/vm/interpreter/src/fvm/state/mod.rs b/fendermint/vm/interpreter/src/fvm/state/mod.rs index 0547ce9d8..22a1504e4 100644 --- a/fendermint/vm/interpreter/src/fvm/state/mod.rs +++ b/fendermint/vm/interpreter/src/fvm/state/mod.rs @@ -12,7 +12,7 @@ pub mod snapshot; use std::sync::Arc; pub use check::FvmCheckState; -pub use exec::{BlockHash, ElapsedExecution, FvmExecState, FvmStateParams, FvmUpdatableParams}; +pub use exec::{BlockHash, FvmExecState, FvmStateParams, FvmUpdatableParams}; pub use genesis::{empty_state_tree, FvmGenesisState}; pub use query::FvmQueryState; diff --git a/fendermint/vm/interpreter/src/lib.rs b/fendermint/vm/interpreter/src/lib.rs index 49ac252ca..011249b02 100644 --- a/fendermint/vm/interpreter/src/lib.rs +++ b/fendermint/vm/interpreter/src/lib.rs @@ -28,6 +28,17 @@ pub trait GenesisInterpreter: Sync + Send { ) -> anyhow::Result<(Self::State, Self::Output)>; } +pub enum ProcessResult { + Accepted, + Rejected(errors::ProcessError), +} + +impl ProcessResult { + pub fn is_accepted(&self) -> bool { + matches!(self, ProcessResult::Accepted) + } +} + /// Prepare and process transaction proposals. #[async_trait] pub trait ProposalInterpreter: Sync + Send { @@ -59,7 +70,7 @@ pub trait ProposalInterpreter: Sync + Send { &self, state: Self::State, msgs: Vec, - ) -> anyhow::Result; + ) -> anyhow::Result; } /// The `ExecInterpreter` applies messages on some state, which is diff --git a/fendermint/vm/topdown/src/proxy.rs b/fendermint/vm/topdown/src/proxy.rs index abbd3812f..d52c3b70d 100644 --- a/fendermint/vm/topdown/src/proxy.rs +++ b/fendermint/vm/topdown/src/proxy.rs @@ -118,6 +118,7 @@ impl ParentQueryProxy for IPCProviderProxy { } } +// TODO - create a macro for this pub struct IPCProviderProxyWithLatency { inner: IPCProviderProxy, } From 01843f083579d4839e18c78b9b3d2233731ce552 Mon Sep 17 00:00:00 2001 From: Karel Moravec Date: Fri, 19 Jul 2024 00:15:10 +0200 Subject: [PATCH 23/33] lint: clippy --- fendermint/app/src/observe.rs | 1 - fendermint/vm/interpreter/src/fvm/state/exec.rs | 1 - 2 files changed, 2 deletions(-) diff --git a/fendermint/app/src/observe.rs b/fendermint/app/src/observe.rs index 37bbfd28d..2521d20f5 100644 --- a/fendermint/app/src/observe.rs +++ b/fendermint/app/src/observe.rs @@ -1,7 +1,6 @@ // Copyright 2022-2024 Protocol Labs // SPDX-License-Identifier: Apache-2.0, MIT -use fendermint_vm_message::conv::from_eth; use fvm_shared::address::Address; use fvm_shared::econ::TokenAmount; diff --git a/fendermint/vm/interpreter/src/fvm/state/exec.rs b/fendermint/vm/interpreter/src/fvm/state/exec.rs index def96ce14..34c4dc765 100644 --- a/fendermint/vm/interpreter/src/fvm/state/exec.rs +++ b/fendermint/vm/interpreter/src/fvm/state/exec.rs @@ -2,7 +2,6 @@ // SPDX-License-Identifier: Apache-2.0, MIT use std::collections::{HashMap, HashSet}; -use std::time::{Duration, Instant}; use anyhow::Ok; use cid::Cid; From 6f67fe181b6c5b1b85137c62f4abf75b20c785e2 Mon Sep 17 00:00:00 2001 From: Karel Moravec Date: Fri, 19 Jul 2024 14:45:30 +0200 Subject: [PATCH 24/33] feat: revert risky changes & small cleanup --- fendermint/app/src/app.rs | 28 ++++++++----------- fendermint/app/src/observe.rs | 6 ---- fendermint/vm/interpreter/src/bytes.rs | 18 +++--------- fendermint/vm/interpreter/src/chain.rs | 18 ++++-------- fendermint/vm/interpreter/src/errors.rs | 18 ------------ .../vm/interpreter/src/fvm/state/exec.rs | 2 -- fendermint/vm/interpreter/src/lib.rs | 18 +----------- 7 files changed, 21 insertions(+), 87 deletions(-) delete mode 100644 fendermint/vm/interpreter/src/errors.rs diff --git a/fendermint/app/src/app.rs b/fendermint/app/src/app.rs index 897df8b97..61e709a17 100644 --- a/fendermint/app/src/app.rs +++ b/fendermint/app/src/app.rs @@ -26,8 +26,7 @@ use fendermint_vm_interpreter::fvm::store::ReadOnlyBlockstore; use fendermint_vm_interpreter::fvm::{FvmApplyRet, FvmGenesisOutput, PowerUpdates}; use fendermint_vm_interpreter::signed::InvalidSignature; use fendermint_vm_interpreter::{ - CheckInterpreter, ExecInterpreter, GenesisInterpreter, ProcessResult, ProposalInterpreter, - QueryInterpreter, + CheckInterpreter, ExecInterpreter, GenesisInterpreter, ProposalInterpreter, QueryInterpreter, }; use fendermint_vm_message::query::FvmQueryHeight; use fendermint_vm_snapshot::{SnapshotClient, SnapshotError}; @@ -697,10 +696,11 @@ where let size_txs = txs.iter().map(|tx| tx.len()).sum::(); let num_txs = txs.len(); - let process_result = self + let accept = self .interpreter .process(self.chain_env.clone(), txs) - .await?; + .await + .context("failed to process proposal")?; emit(BlockProposalReceived { height: request.height.value(), @@ -726,21 +726,15 @@ where size: size_txs, tx_count: num_txs, validator: &request.proposer_address, - accept: true, + accept, reason: None, - }; - - let process_proposal = match process_result { - ProcessResult::Accepted => response::ProcessProposal::Accept, - ProcessResult::Rejected(reason) => { - proposal_evaluated.accept = false; - proposal_evaluated.reason = Some(reason); - response::ProcessProposal::Reject - } - }; + }); - emit(proposal_evaluated); - Ok(process_proposal) + if accept { + Ok(response::ProcessProposal::Accept) + } else { + Ok(response::ProcessProposal::Reject) + } } /// Signals the beginning of a new block, prior to any `DeliverTx` calls. diff --git a/fendermint/app/src/observe.rs b/fendermint/app/src/observe.rs index 2521d20f5..793abe2fa 100644 --- a/fendermint/app/src/observe.rs +++ b/fendermint/app/src/observe.rs @@ -147,12 +147,6 @@ pub struct MpoolReceived { impl Recordable for MpoolReceived { fn record_metrics(&self) { - let from = self - .message - .as_ref() - .map(|m| m.from.to_string()) - .unwrap_or("".to_string()); - MPOOL_RECEIVED .with_label_values(&[&self.accept.to_string()]) .inc(); diff --git a/fendermint/vm/interpreter/src/bytes.rs b/fendermint/vm/interpreter/src/bytes.rs index af8273fb7..1af84dd85 100644 --- a/fendermint/vm/interpreter/src/bytes.rs +++ b/fendermint/vm/interpreter/src/bytes.rs @@ -9,10 +9,8 @@ use fvm_ipld_encoding::Error as IpldError; use crate::{ chain::{ChainMessageApplyRet, ChainMessageCheckRes}, - errors::ProcessError, fvm::{FvmQuery, FvmQueryRet}, - CheckInterpreter, ExecInterpreter, GenesisInterpreter, ProcessResult, ProposalInterpreter, - QueryInterpreter, + CheckInterpreter, ExecInterpreter, GenesisInterpreter, ProposalInterpreter, QueryInterpreter, }; pub type BytesMessageApplyRes = Result; @@ -127,19 +125,13 @@ where } /// Parse messages in the block, reject if unknown format. Pass the rest to the inner `ChainMessage` interpreter. - async fn process( - &self, - state: Self::State, - msgs: Vec, - ) -> anyhow::Result { + async fn process(&self, state: Self::State, msgs: Vec) -> anyhow::Result { if msgs.len() > self.max_msgs { tracing::warn!( block_msgs = msgs.len(), "rejecting block: too many messages" ); - return Ok(ProcessResult::Rejected(ProcessError::TooManyMessages( - msgs.len(), - ))); + return Ok(false); } let mut chain_msgs = Vec::new(); @@ -160,9 +152,7 @@ where "failed to decode message in proposal as ChainMessage" ); if self.reject_malformed_proposal { - return Ok(ProcessResult::Rejected( - ProcessError::FailedToDecodeMessage(e.to_string()), - )); + return Ok(false); } } Ok(msg) => chain_msgs.push(msg), diff --git a/fendermint/vm/interpreter/src/chain.rs b/fendermint/vm/interpreter/src/chain.rs index 00a3ccbdb..79136138f 100644 --- a/fendermint/vm/interpreter/src/chain.rs +++ b/fendermint/vm/interpreter/src/chain.rs @@ -1,14 +1,12 @@ // Copyright 2022-2024 Protocol Labs // SPDX-License-Identifier: Apache-2.0, MIT -use crate::errors::ProcessError; use crate::fvm::state::ipc::GatewayCaller; use crate::fvm::{topdown, FvmApplyRet, PowerUpdates}; use crate::{ fvm::state::FvmExecState, fvm::FvmMessage, signed::{SignedMessageApplyRes, SignedMessageCheckRes, SyntheticMessage, VerifiableMessage}, - CheckInterpreter, ExecInterpreter, GenesisInterpreter, ProcessResult, ProposalInterpreter, - QueryInterpreter, + CheckInterpreter, ExecInterpreter, GenesisInterpreter, ProposalInterpreter, QueryInterpreter, }; use anyhow::{bail, Context}; use async_stm::atomically; @@ -177,11 +175,7 @@ where } /// Perform finality checks on top-down transactions and availability checks on bottom-up transactions. - async fn process( - &self, - env: Self::State, - msgs: Vec, - ) -> anyhow::Result { + async fn process(&self, env: Self::State, msgs: Vec) -> anyhow::Result { for msg in msgs { match msg { ChainMessage::Ipc(IpcMessage::BottomUpExec(msg)) => { @@ -200,7 +194,7 @@ where .await; if !is_resolved { - return Ok(ProcessResult::Rejected(ProcessError::CheckpointNotResolved)); + return Ok(false); } } ChainMessage::Ipc(IpcMessage::TopDownExec(ParentFinality { @@ -214,15 +208,13 @@ where let is_final = atomically(|| env.parent_finality_provider.check_proposal(&prop)).await; if !is_final { - return Ok(ProcessResult::Rejected( - ProcessError::ParentFinalityNotAvailable, - )); + return Ok(false); } } _ => {} }; } - Ok(ProcessResult::Accepted) + Ok(true) } } diff --git a/fendermint/vm/interpreter/src/errors.rs b/fendermint/vm/interpreter/src/errors.rs deleted file mode 100644 index 8cdf28a40..000000000 --- a/fendermint/vm/interpreter/src/errors.rs +++ /dev/null @@ -1,18 +0,0 @@ -// Copyright 2022-2024 Protocol Labs -// SPDX-License-Identifier: Apache-2.0, MIT - -use thiserror::Error; - -#[derive(Error, Debug)] -pub enum ProcessError { - #[error("checkpoint not resolved")] - CheckpointNotResolved, - #[error("parent finality not available")] - ParentFinalityNotAvailable, - #[error("too many messages: {0}")] - TooManyMessages(usize), - #[error("failed to decode message in proposal as ChainMessage: {0}")] - FailedToDecodeMessage(String), - #[error("")] - Empty, -} diff --git a/fendermint/vm/interpreter/src/fvm/state/exec.rs b/fendermint/vm/interpreter/src/fvm/state/exec.rs index 34c4dc765..7d5f10dda 100644 --- a/fendermint/vm/interpreter/src/fvm/state/exec.rs +++ b/fendermint/vm/interpreter/src/fvm/state/exec.rs @@ -176,13 +176,11 @@ where /// Execute message implicitly. pub fn execute_implicit(&mut self, msg: Message) -> ExecResult { - // TODO Karel - measure here self.execute_message(msg, ApplyKind::Implicit) } /// Execute message explicitly. pub fn execute_explicit(&mut self, msg: Message) -> ExecResult { - // TODO Karel - measure here self.execute_message(msg, ApplyKind::Explicit) } diff --git a/fendermint/vm/interpreter/src/lib.rs b/fendermint/vm/interpreter/src/lib.rs index 011249b02..42dab76b8 100644 --- a/fendermint/vm/interpreter/src/lib.rs +++ b/fendermint/vm/interpreter/src/lib.rs @@ -4,7 +4,6 @@ use async_trait::async_trait; pub mod bytes; pub mod chain; -pub mod errors; pub mod fvm; pub mod signed; @@ -28,17 +27,6 @@ pub trait GenesisInterpreter: Sync + Send { ) -> anyhow::Result<(Self::State, Self::Output)>; } -pub enum ProcessResult { - Accepted, - Rejected(errors::ProcessError), -} - -impl ProcessResult { - pub fn is_accepted(&self) -> bool { - matches!(self, ProcessResult::Accepted) - } -} - /// Prepare and process transaction proposals. #[async_trait] pub trait ProposalInterpreter: Sync + Send { @@ -66,11 +54,7 @@ pub trait ProposalInterpreter: Sync + Send { /// This is our chance check whether CIDs proposed for execution are available. /// /// Return `true` if we can accept this block, `false` to reject it. - async fn process( - &self, - state: Self::State, - msgs: Vec, - ) -> anyhow::Result; + async fn process(&self, state: Self::State, msgs: Vec) -> anyhow::Result; } /// The `ExecInterpreter` applies messages on some state, which is From 42950278860e56f779cd3fd0f606fe925bafeda0 Mon Sep 17 00:00:00 2001 From: Karel Moravec Date: Wed, 17 Jul 2024 23:17:07 +0200 Subject: [PATCH 25/33] feat: use tracing config --- Cargo.lock | 4 + fendermint/app/options/src/lib.rs | 115 ----------------------- fendermint/app/options/src/log.rs | 93 ------------------ fendermint/app/settings/src/eth.rs | 3 + fendermint/app/settings/src/lib.rs | 2 + fendermint/app/src/cmd/eth.rs | 3 + fendermint/app/src/cmd/mod.rs | 14 ++- fendermint/app/src/cmd/run.rs | 4 + fendermint/app/src/main.rs | 32 +++---- ipc/observability/src/lib.rs | 1 + ipc/observability/src/traces.rs | 94 ++++++------------ ipc/observability/src/traces_settings.rs | 111 ++++++++++++++++++++++ 12 files changed, 181 insertions(+), 295 deletions(-) delete mode 100644 fendermint/app/options/src/log.rs create mode 100644 ipc/observability/src/traces_settings.rs diff --git a/Cargo.lock b/Cargo.lock index c482f4abc..c84467976 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2959,6 +2959,7 @@ dependencies = [ "fvm_ipld_encoding", "fvm_shared", "ipc-api", + "ipc-observability", "ipc-provider", "lazy_static", "multiaddr", @@ -5067,9 +5068,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/src/eth.rs b/fendermint/app/settings/src/eth.rs index 877f61bac..edb409add 100644 --- a/fendermint/app/settings/src/eth.rs +++ b/fendermint/app/settings/src/eth.rs @@ -10,6 +10,8 @@ use serde_with::{serde_as, DurationSeconds}; use std::time::Duration; use tower_http::cors::{AllowHeaders, AllowMethods, AllowOrigin}; +use ipc_observability::traces_settings::TracesSettings; + use crate::{IsHumanReadable, MetricsSettings, SocketAddress}; /// Ethereum API facade settings. @@ -24,6 +26,7 @@ pub struct EthSettings { pub max_nonce_gap: u64, pub metrics: MetricsSettings, pub cors: CorsOpt, + pub tracing: TracesSettings, } #[serde_as] diff --git a/fendermint/app/settings/src/lib.rs b/fendermint/app/settings/src/lib.rs index 2e3d46df6..168a82887 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 f95a60e50..b6c8ec4e2 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 2dac3ef6a..5ceccf600 100644 --- a/fendermint/app/src/cmd/run.rs +++ b/fendermint/app/src/cmd/run.rs @@ -42,6 +42,8 @@ use crate::cmd::key::read_secret_key; use crate::{cmd, options::run::RunArgs, settings::Settings}; use fendermint_app::observe::register_metrics as register_consensus_metrics; +use ipc_observability::traces::set_global_tracing_subscriber; + cmd! { RunArgs(self, settings) { run(settings).await @@ -62,6 +64,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/src/lib.rs b/ipc/observability/src/lib.rs index 57fe44d7a..918e8da55 100644 --- a/ipc/observability/src/lib.rs +++ b/ipc/observability/src/lib.rs @@ -7,6 +7,7 @@ mod tracing_layers; pub use lazy_static::lazy_static; pub mod observe; 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>, +} From b77bc360190c08cf132912dc04284a31a8179d7b Mon Sep 17 00:00:00 2001 From: Karel Moravec Date: Thu, 18 Jul 2024 16:56:48 +0200 Subject: [PATCH 26/33] feat: add tracing to each command --- fendermint/app/config/default.toml | 16 ++++++++++++++++ fendermint/app/src/cmd/debug.rs | 7 ++++++- fendermint/app/src/cmd/eth.rs | 5 ++--- fendermint/app/src/cmd/genesis.rs | 4 ++++ fendermint/app/src/cmd/key.rs | 4 ++++ fendermint/app/src/cmd/materializer.rs | 4 ++++ fendermint/app/src/cmd/rpc.rs | 4 ++++ fendermint/app/src/cmd/run.rs | 4 ++-- ipc/observability/src/traces.rs | 20 +++++++++++++++++--- ipc/observability/src/traces_settings.rs | 9 ++++----- 10 files changed, 63 insertions(+), 14 deletions(-) diff --git a/fendermint/app/config/default.toml b/fendermint/app/config/default.toml index 88e72e7da..54e4716c4 100644 --- a/fendermint/app/config/default.toml +++ b/fendermint/app/config/default.toml @@ -63,6 +63,14 @@ host = "127.0.0.1" # The default port where the Prometheus exporter makes the metrics available. port = 9184 +[tracing] + +[tracing.console] +enabled = true + +[tracing.file] +enabled = false + [snapshots] # Enable the export and import of snapshots. enabled = false @@ -160,6 +168,14 @@ allowed_methods = [] # Suggested headers if allowing origins: "Accept", "Authorization", "Content-Type", "Origin" allowed_headers = [] +[eth.tracing] + +[eth.tracing.console] +enabled = true + +[eth.tracing.file] +enabled = false + # IPLD Resolver Configuration [resolver] # Time to wait between attempts to resolve a CID after an error. diff --git a/fendermint/app/src/cmd/debug.rs b/fendermint/app/src/cmd/debug.rs index 364fd36c1..015db3ead 100644 --- a/fendermint/app/src/cmd/debug.rs +++ b/fendermint/app/src/cmd/debug.rs @@ -6,6 +6,8 @@ use fendermint_app_options::debug::{ DebugArgs, DebugCommands, DebugExportTopDownEventsArgs, DebugIpcCommands, }; use fendermint_vm_topdown::proxy::IPCProviderProxy; +use ipc_observability::traces::set_global_tracing_subscriber; +use ipc_observability::traces_settings::TracesSettings; use ipc_provider::{ config::subnet::{EVMSubnet, SubnetConfig}, IpcProvider, @@ -23,9 +25,12 @@ cmd! { cmd! { DebugIpcCommands(self) { + let _trace_file_guard = set_global_tracing_subscriber(&TracesSettings::default())?; + match self { - DebugIpcCommands::ExportTopDownEvents(args) => + DebugIpcCommands::ExportTopDownEvents(args) => { export_topdown_events(args).await + } } } } diff --git a/fendermint/app/src/cmd/eth.rs b/fendermint/app/src/cmd/eth.rs index b6c8ec4e2..16231dd1b 100644 --- a/fendermint/app/src/cmd/eth.rs +++ b/fendermint/app/src/cmd/eth.rs @@ -16,9 +16,10 @@ use crate::{ cmd! { EthArgs(self, settings: EthSettings) { + let _trace_file_guard = set_global_tracing_subscriber(&settings.tracing)?; + match self.command.clone() { EthCommands::Run { ws_url, http_url, connect_retry_delay } => { - let (client, driver) = HybridClient::new(http_url, ws_url, Duration::from_secs(connect_retry_delay)).context("failed to create HybridClient")?; let driver_handle = tokio::spawn(async move { driver.run().await }); @@ -35,8 +36,6 @@ 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/genesis.rs b/fendermint/app/src/cmd/genesis.rs index 183a89cb7..37e1bdea8 100644 --- a/fendermint/app/src/cmd/genesis.rs +++ b/fendermint/app/src/cmd/genesis.rs @@ -14,6 +14,8 @@ use fendermint_vm_genesis::{ ipc, Account, Actor, ActorMeta, Collateral, Genesis, Multisig, PermissionMode, SignerAddr, Validator, ValidatorKey, }; +use ipc_observability::traces::set_global_tracing_subscriber; +use ipc_observability::traces_settings::TracesSettings; use crate::cmd; use crate::options::genesis::*; @@ -22,7 +24,9 @@ use super::key::read_public_key; cmd! { GenesisArgs(self) { + let _trace_file_guard = set_global_tracing_subscriber(&TracesSettings::default())?; let genesis_file = self.genesis_file.clone(); + match &self.command { GenesisCommands::New(args) => args.exec(genesis_file).await, GenesisCommands::AddAccount(args) => args.exec(genesis_file).await, diff --git a/fendermint/app/src/cmd/key.rs b/fendermint/app/src/cmd/key.rs index e5891ae0f..757426862 100644 --- a/fendermint/app/src/cmd/key.rs +++ b/fendermint/app/src/cmd/key.rs @@ -6,6 +6,8 @@ use fendermint_app_options::key::KeyShowPeerIdArgs; use fendermint_crypto::{from_b64, to_b64, PublicKey, SecretKey}; use fendermint_vm_actor_interface::eam::EthAddress; use fvm_shared::address::Address; +use ipc_observability::traces::set_global_tracing_subscriber; +use ipc_observability::traces_settings::TracesSettings; use rand_chacha::{rand_core::SeedableRng, ChaCha20Rng}; use serde_json::json; use std::path::Path; @@ -21,6 +23,8 @@ use crate::{ cmd! { KeyArgs(self) { + let _trace_file_guard = set_global_tracing_subscriber(&TracesSettings::default())?; + match &self.command { KeyCommands::Gen(args) => args.exec(()).await, KeyCommands::IntoTendermint(args) => args.exec(()).await, diff --git a/fendermint/app/src/cmd/materializer.rs b/fendermint/app/src/cmd/materializer.rs index f55797d5d..5c236bc89 100644 --- a/fendermint/app/src/cmd/materializer.rs +++ b/fendermint/app/src/cmd/materializer.rs @@ -14,6 +14,8 @@ use fendermint_materializer::{ testnet::Testnet, AccountId, TestnetId, TestnetName, }; +use ipc_observability::traces::set_global_tracing_subscriber; +use ipc_observability::traces_settings::TracesSettings; use crate::cmd; @@ -21,6 +23,8 @@ use super::key::{read_secret_key, read_secret_key_hex}; cmd! { MaterializerArgs(self) { + let _trace_file_guard = set_global_tracing_subscriber(&TracesSettings::default())?; + let data_dir = expand_tilde(&self.data_dir); let dm = || DockerMaterializer::new(&data_dir, self.seed).map(|m| m.with_policy(DropPolicy::PERSISTENT)); let lm = || dm().map(|m| LoggingMaterializer::new(m, "cli".to_string())); diff --git a/fendermint/app/src/cmd/rpc.rs b/fendermint/app/src/cmd/rpc.rs index a4012555b..a35256bfd 100644 --- a/fendermint/app/src/cmd/rpc.rs +++ b/fendermint/app/src/cmd/rpc.rs @@ -31,6 +31,8 @@ use tendermint_rpc::HttpClient; use fendermint_rpc::message::{GasParams, SignedMessageFactory}; use fendermint_rpc::{client::FendermintClient, query::QueryClient}; use fendermint_vm_actor_interface::eam::{self, CreateReturn, EthAddress}; +use ipc_observability::traces::set_global_tracing_subscriber; +use ipc_observability::traces_settings::TracesSettings; use crate::cmd; use crate::options::rpc::{BroadcastMode, FevmArgs, RpcFevmCommands, TransArgs}; @@ -40,6 +42,8 @@ use super::key::read_secret_key; cmd! { RpcArgs(self) { + let _trace_file_guard = set_global_tracing_subscriber(&TracesSettings::default())?; + let client = FendermintClient::new_http(self.url.clone(), self.proxy_url.clone())?; match self.command.clone() { RpcCommands::Query { height, command } => { diff --git a/fendermint/app/src/cmd/run.rs b/fendermint/app/src/cmd/run.rs index 5ceccf600..3988498c5 100644 --- a/fendermint/app/src/cmd/run.rs +++ b/fendermint/app/src/cmd/run.rs @@ -46,6 +46,8 @@ use ipc_observability::traces::set_global_tracing_subscriber; cmd! { RunArgs(self, settings) { + let _trace_file_guard = set_global_tracing_subscriber(&settings.tracing)?; + run(settings).await } } @@ -64,8 +66,6 @@ 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/ipc/observability/src/traces.rs b/ipc/observability/src/traces.rs index 6ba306c65..495db66ee 100644 --- a/ipc/observability/src/traces.rs +++ b/ipc/observability/src/traces.rs @@ -8,7 +8,7 @@ pub use tracing_appender::non_blocking::WorkerGuard; use tracing_appender::rolling::RollingFileAppender; use tracing_subscriber::{fmt, fmt::Subscriber, layer::SubscriberExt, Layer}; -use crate::traces_settings::{FileLayerSettings, TracesSettings}; +use crate::traces_settings::{FileLayerSettings, LogLevel, TracesSettings}; use crate::tracing_layers::DomainEventFilterLayer; use anyhow::Result; @@ -29,7 +29,14 @@ pub fn set_global_tracing_subscriber(config: &TracesSettings) -> Result Result, } impl Default for ConsoleLayerSettings { fn default() -> Self { ConsoleLayerSettings { enabled: true, - level: LogLevel::default(), + level: Some(LogLevel::default()), } } } #[serde_as] #[derive(Debug, Deserialize, Clone, Default)] - pub struct FileLayerSettings { pub enabled: bool, - pub level: LogLevel, + pub level: Option, pub directory: Option, pub max_log_files: Option, pub rotation: Option, From edb7dc227d0fdf0970d6550df701fcf3a3819e10 Mon Sep 17 00:00:00 2001 From: Karel Moravec Date: Fri, 19 Jul 2024 15:41:07 +0200 Subject: [PATCH 27/33] feat: introduce cleanups --- fendermint/app/src/cmd/debug.rs | 2 +- fendermint/app/src/cmd/eth.rs | 2 +- fendermint/app/src/cmd/genesis.rs | 2 +- fendermint/app/src/cmd/key.rs | 2 +- fendermint/app/src/cmd/materializer.rs | 2 +- fendermint/app/src/cmd/mod.rs | 4 +- fendermint/app/src/cmd/rpc.rs | 2 +- fendermint/app/src/cmd/run.rs | 2 +- fendermint/app/src/main.rs | 14 ++-- ipc/observability/src/traces.rs | 89 +++++++++++------------- ipc/observability/src/traces_settings.rs | 25 +++++-- 11 files changed, 76 insertions(+), 70 deletions(-) diff --git a/fendermint/app/src/cmd/debug.rs b/fendermint/app/src/cmd/debug.rs index 015db3ead..f3f0e1413 100644 --- a/fendermint/app/src/cmd/debug.rs +++ b/fendermint/app/src/cmd/debug.rs @@ -25,7 +25,7 @@ cmd! { cmd! { DebugIpcCommands(self) { - let _trace_file_guard = set_global_tracing_subscriber(&TracesSettings::default())?; + let _trace_file_guard = set_global_tracing_subscriber(&TracesSettings::default()); match self { DebugIpcCommands::ExportTopDownEvents(args) => { diff --git a/fendermint/app/src/cmd/eth.rs b/fendermint/app/src/cmd/eth.rs index 16231dd1b..953a88d7c 100644 --- a/fendermint/app/src/cmd/eth.rs +++ b/fendermint/app/src/cmd/eth.rs @@ -16,7 +16,7 @@ use crate::{ cmd! { EthArgs(self, settings: EthSettings) { - let _trace_file_guard = set_global_tracing_subscriber(&settings.tracing)?; + let _trace_file_guard = set_global_tracing_subscriber(&settings.tracing); match self.command.clone() { EthCommands::Run { ws_url, http_url, connect_retry_delay } => { diff --git a/fendermint/app/src/cmd/genesis.rs b/fendermint/app/src/cmd/genesis.rs index 37e1bdea8..7c0270242 100644 --- a/fendermint/app/src/cmd/genesis.rs +++ b/fendermint/app/src/cmd/genesis.rs @@ -24,7 +24,7 @@ use super::key::read_public_key; cmd! { GenesisArgs(self) { - let _trace_file_guard = set_global_tracing_subscriber(&TracesSettings::default())?; + let _trace_file_guard = set_global_tracing_subscriber(&TracesSettings::default()); let genesis_file = self.genesis_file.clone(); match &self.command { diff --git a/fendermint/app/src/cmd/key.rs b/fendermint/app/src/cmd/key.rs index 757426862..8d96be680 100644 --- a/fendermint/app/src/cmd/key.rs +++ b/fendermint/app/src/cmd/key.rs @@ -23,7 +23,7 @@ use crate::{ cmd! { KeyArgs(self) { - let _trace_file_guard = set_global_tracing_subscriber(&TracesSettings::default())?; + let _trace_file_guard = set_global_tracing_subscriber(&TracesSettings::default()); match &self.command { KeyCommands::Gen(args) => args.exec(()).await, diff --git a/fendermint/app/src/cmd/materializer.rs b/fendermint/app/src/cmd/materializer.rs index 5c236bc89..fec50f762 100644 --- a/fendermint/app/src/cmd/materializer.rs +++ b/fendermint/app/src/cmd/materializer.rs @@ -23,7 +23,7 @@ use super::key::{read_secret_key, read_secret_key_hex}; cmd! { MaterializerArgs(self) { - let _trace_file_guard = set_global_tracing_subscriber(&TracesSettings::default())?; + let _trace_file_guard = set_global_tracing_subscriber(&TracesSettings::default()); let data_dir = expand_tilde(&self.data_dir); let dm = || DockerMaterializer::new(&data_dir, self.seed).map(|m| m.with_policy(DropPolicy::PERSISTENT)); diff --git a/fendermint/app/src/cmd/mod.rs b/fendermint/app/src/cmd/mod.rs index fbc756f5d..12758a493 100644 --- a/fendermint/app/src/cmd/mod.rs +++ b/fendermint/app/src/cmd/mod.rs @@ -10,7 +10,7 @@ use crate::{ use anyhow::{anyhow, Context}; use async_trait::async_trait; -use ipc_observability::traces::create_subscriber; +use ipc_observability::traces::create_temporary_subscriber; use tracing::subscriber; pub mod config; @@ -84,7 +84,7 @@ fn settings(opts: &Options) -> anyhow::Result { d => d, }; - subscriber::with_default(create_subscriber(), || { + subscriber::with_default(create_temporary_subscriber(), || { tracing::info!( path = config_dir.to_string_lossy().into_owned(), "reading configuration" diff --git a/fendermint/app/src/cmd/rpc.rs b/fendermint/app/src/cmd/rpc.rs index a35256bfd..9c477dc21 100644 --- a/fendermint/app/src/cmd/rpc.rs +++ b/fendermint/app/src/cmd/rpc.rs @@ -42,7 +42,7 @@ use super::key::read_secret_key; cmd! { RpcArgs(self) { - let _trace_file_guard = set_global_tracing_subscriber(&TracesSettings::default())?; + let _trace_file_guard = set_global_tracing_subscriber(&TracesSettings::default()); let client = FendermintClient::new_http(self.url.clone(), self.proxy_url.clone())?; match self.command.clone() { diff --git a/fendermint/app/src/cmd/run.rs b/fendermint/app/src/cmd/run.rs index 3988498c5..3b0a897ac 100644 --- a/fendermint/app/src/cmd/run.rs +++ b/fendermint/app/src/cmd/run.rs @@ -46,7 +46,7 @@ use ipc_observability::traces::set_global_tracing_subscriber; cmd! { RunArgs(self, settings) { - let _trace_file_guard = set_global_tracing_subscriber(&settings.tracing)?; + let _trace_file_guard = set_global_tracing_subscriber(&settings.tracing); run(settings).await } diff --git a/fendermint/app/src/main.rs b/fendermint/app/src/main.rs index 81af83988..408899da5 100644 --- a/fendermint/app/src/main.rs +++ b/fendermint/app/src/main.rs @@ -4,7 +4,7 @@ pub use fendermint_app_options as options; pub use fendermint_app_settings as settings; -use ipc_observability::traces::create_subscriber; +use ipc_observability::traces::create_temporary_subscriber; use tracing::subscriber; mod cmd; @@ -20,12 +20,12 @@ fn init_panic_handler() { // let stacktrace = std::backtrace::Backtrace::capture(); let stacktrace = std::backtrace::Backtrace::force_capture(); - subscriber::with_default(create_subscriber(), || { + subscriber::with_default(create_temporary_subscriber(), || { tracing::error!( - "panic occurred: {error:?}\n{stacktrace}", - error = info, - stacktrace = stacktrace - ) + stacktrace = stacktrace.to_string(), + info = info.to_string(), + "panicking" + ); }); // We could exit the application if any of the background tokio tasks panic. @@ -41,7 +41,7 @@ async fn main() { init_panic_handler(); if let Err(e) = cmd::exec(&opts).await { - subscriber::with_default(create_subscriber(), || { + subscriber::with_default(create_temporary_subscriber(), || { tracing::error!("failed to execute {:?}: {e:?}", opts) }); std::process::exit(fendermint_app::AppExitCode::UnknownError as i32); diff --git a/ipc/observability/src/traces.rs b/ipc/observability/src/traces.rs index 495db66ee..affb96832 100644 --- a/ipc/observability/src/traces.rs +++ b/ipc/observability/src/traces.rs @@ -6,74 +6,63 @@ use tracing::Level; pub use tracing_appender::non_blocking; pub use tracing_appender::non_blocking::WorkerGuard; use tracing_appender::rolling::RollingFileAppender; -use tracing_subscriber::{fmt, fmt::Subscriber, layer::SubscriberExt, Layer}; +use tracing_subscriber::{fmt, fmt::Subscriber, layer::SubscriberExt, Layer, LogLevel}; -use crate::traces_settings::{FileLayerSettings, LogLevel, TracesSettings}; +use crate::traces_settings::{FileLayerSettings, TracesSettings}; use crate::tracing_layers::DomainEventFilterLayer; -use anyhow::Result; -pub fn create_subscriber() -> Subscriber { +// +pub fn create_temporary_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() } -pub fn set_global_tracing_subscriber(config: &TracesSettings) -> Result { +pub fn set_global_tracing_subscriber(config: &TracesSettings) -> Option { + let console_filter = match config.console { + Some(console_settings) => console_settings.level_to_filter(), + None => LogLevel::default().to_filter(), + }; + // 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( - config - .console - .level + .with_filter(console_filter); + + let (file_layer, file_guard) = match config.file { + Some(file_settings) if file_settings.enabled => { + let (non_blocking, file_guard) = non_blocking(create_file_appender(&file_settings)); + + let file_layer = fmt::layer() + .json() + .with_writer(non_blocking) + .with_span_events(fmt::format::FmtSpan::CLOSE) + .with_target(false) + .with_file(true) + .with_line_number(true) + .with_filter(file_settings.level_to_filter()); + + let domains = file_settings + .domain_filter .as_ref() - .unwrap_or(&LogLevel::default()) - .to_filter()?, - ); + .map(|v| v.iter().map(|s| s.to_string()).collect()); + + let events = file_settings + .events_filter + .as_ref() + .map(|v| v.iter().map(|s| s.to_string()).collect()); + + let file_layer = DomainEventFilterLayer::new(domains, events, file_layer); - 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() - .with_writer(non_blocking) - .with_span_events(fmt::format::FmtSpan::CLOSE) - .with_target(false) - .with_file(true) - .with_line_number(true) - .with_filter( - config - .file - .level - .as_ref() - .unwrap_or(&LogLevel::default()) - .to_filter()?, - ); - - let domains = config - .file - .domain_filter - .as_ref() - .map(|v| v.iter().map(|s| s.to_string()).collect()); - - 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); - - (Some(file_layer), Some(file_guard)) - } else { - (None, None) + (Some(file_layer), Some(file_guard)) + } + _ => (None, None), }; let registry = tracing_subscriber::registry() @@ -83,7 +72,7 @@ pub fn set_global_tracing_subscriber(config: &TracesSettings) -> Result RollingFileAppender { diff --git a/ipc/observability/src/traces_settings.rs b/ipc/observability/src/traces_settings.rs index c4f2f7cee..2ac85749e 100644 --- a/ipc/observability/src/traces_settings.rs +++ b/ipc/observability/src/traces_settings.rs @@ -77,21 +77,25 @@ impl FromStr for RotationKind { #[serde_as] #[derive(Debug, Deserialize, Clone, Default)] pub struct TracesSettings { - pub console: ConsoleLayerSettings, - pub file: FileLayerSettings, + pub console: Option, + pub file: Option, } #[serde_as] #[derive(Debug, Deserialize, Clone)] pub struct ConsoleLayerSettings { - pub enabled: bool, pub level: Option, } +impl ConsoleLayerSettings { + pub fn level_to_filter(&self) -> EnvFilter { + level_to_filter(&self.level) + } +} + impl Default for ConsoleLayerSettings { fn default() -> Self { ConsoleLayerSettings { - enabled: true, level: Some(LogLevel::default()), } } @@ -108,3 +112,16 @@ pub struct FileLayerSettings { pub domain_filter: Option>, pub events_filter: Option>, } + +impl FileLayerSettings { + pub fn level_to_filter(&self) -> EnvFilter { + level_to_filter(&self.level) + } +} + +fn level_to_filter(level: &Option) -> EnvFilter { + match level { + Some(level) => level.to_filter().unwrap_or_default(), + None => EnvFilter::default(), + } +} From 4e7d1c6c751e1a7f1befaa026007e0056e41b3a1 Mon Sep 17 00:00:00 2001 From: Karel Moravec Date: Fri, 19 Jul 2024 19:59:59 +0200 Subject: [PATCH 28/33] feat: adress comments --- fendermint/app/settings/src/eth.rs | 4 +- fendermint/app/settings/src/lib.rs | 4 +- fendermint/app/src/cmd/debug.rs | 4 +- fendermint/app/src/cmd/genesis.rs | 4 +- fendermint/app/src/cmd/key.rs | 4 +- fendermint/app/src/cmd/materializer.rs | 4 +- fendermint/app/src/cmd/rpc.rs | 4 +- ipc/observability/src/lib.rs | 2 +- ipc/observability/src/traces.rs | 17 +-- ipc/observability/src/traces_settings.rs | 127 ----------------------- 10 files changed, 24 insertions(+), 150 deletions(-) delete mode 100644 ipc/observability/src/traces_settings.rs diff --git a/fendermint/app/settings/src/eth.rs b/fendermint/app/settings/src/eth.rs index edb409add..954a59a90 100644 --- a/fendermint/app/settings/src/eth.rs +++ b/fendermint/app/settings/src/eth.rs @@ -10,7 +10,7 @@ use serde_with::{serde_as, DurationSeconds}; use std::time::Duration; use tower_http::cors::{AllowHeaders, AllowMethods, AllowOrigin}; -use ipc_observability::traces_settings::TracesSettings; +use ipc_observability::config::TracingSettings; use crate::{IsHumanReadable, MetricsSettings, SocketAddress}; @@ -26,7 +26,7 @@ pub struct EthSettings { pub max_nonce_gap: u64, pub metrics: MetricsSettings, pub cors: CorsOpt, - pub tracing: TracesSettings, + pub tracing: TracingSettings, } #[serde_as] diff --git a/fendermint/app/settings/src/lib.rs b/fendermint/app/settings/src/lib.rs index 168a82887..695014b20 100644 --- a/fendermint/app/settings/src/lib.rs +++ b/fendermint/app/settings/src/lib.rs @@ -22,7 +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_observability::config::TracingSettings; use ipc_provider::config::deserialize::deserialize_eth_address_from_str; pub mod eth; @@ -287,7 +287,7 @@ pub struct Settings { pub broadcast: BroadcastSettings, pub ipc: IpcSettings, pub testing: Option, - pub tracing: TracesSettings, + pub tracing: TracingSettings, } impl Settings { diff --git a/fendermint/app/src/cmd/debug.rs b/fendermint/app/src/cmd/debug.rs index f3f0e1413..8b1c9f1ea 100644 --- a/fendermint/app/src/cmd/debug.rs +++ b/fendermint/app/src/cmd/debug.rs @@ -6,8 +6,8 @@ use fendermint_app_options::debug::{ DebugArgs, DebugCommands, DebugExportTopDownEventsArgs, DebugIpcCommands, }; use fendermint_vm_topdown::proxy::IPCProviderProxy; +use ipc_observability::config::TracingSettings; use ipc_observability::traces::set_global_tracing_subscriber; -use ipc_observability::traces_settings::TracesSettings; use ipc_provider::{ config::subnet::{EVMSubnet, SubnetConfig}, IpcProvider, @@ -25,7 +25,7 @@ cmd! { cmd! { DebugIpcCommands(self) { - let _trace_file_guard = set_global_tracing_subscriber(&TracesSettings::default()); + let _trace_file_guard = set_global_tracing_subscriber(&TracingSettings::default()); match self { DebugIpcCommands::ExportTopDownEvents(args) => { diff --git a/fendermint/app/src/cmd/genesis.rs b/fendermint/app/src/cmd/genesis.rs index 7c0270242..c811a4622 100644 --- a/fendermint/app/src/cmd/genesis.rs +++ b/fendermint/app/src/cmd/genesis.rs @@ -14,8 +14,8 @@ use fendermint_vm_genesis::{ ipc, Account, Actor, ActorMeta, Collateral, Genesis, Multisig, PermissionMode, SignerAddr, Validator, ValidatorKey, }; +use ipc_observability::config::TracingSettings; use ipc_observability::traces::set_global_tracing_subscriber; -use ipc_observability::traces_settings::TracesSettings; use crate::cmd; use crate::options::genesis::*; @@ -24,7 +24,7 @@ use super::key::read_public_key; cmd! { GenesisArgs(self) { - let _trace_file_guard = set_global_tracing_subscriber(&TracesSettings::default()); + let _trace_file_guard = set_global_tracing_subscriber(&TracingSettings::default()); let genesis_file = self.genesis_file.clone(); match &self.command { diff --git a/fendermint/app/src/cmd/key.rs b/fendermint/app/src/cmd/key.rs index 8d96be680..b534add42 100644 --- a/fendermint/app/src/cmd/key.rs +++ b/fendermint/app/src/cmd/key.rs @@ -6,8 +6,8 @@ use fendermint_app_options::key::KeyShowPeerIdArgs; use fendermint_crypto::{from_b64, to_b64, PublicKey, SecretKey}; use fendermint_vm_actor_interface::eam::EthAddress; use fvm_shared::address::Address; +use ipc_observability::config::TracingSettings; use ipc_observability::traces::set_global_tracing_subscriber; -use ipc_observability::traces_settings::TracesSettings; use rand_chacha::{rand_core::SeedableRng, ChaCha20Rng}; use serde_json::json; use std::path::Path; @@ -23,7 +23,7 @@ use crate::{ cmd! { KeyArgs(self) { - let _trace_file_guard = set_global_tracing_subscriber(&TracesSettings::default()); + let _trace_file_guard = set_global_tracing_subscriber(&TracingSettings::default()); match &self.command { KeyCommands::Gen(args) => args.exec(()).await, diff --git a/fendermint/app/src/cmd/materializer.rs b/fendermint/app/src/cmd/materializer.rs index fec50f762..9971cc044 100644 --- a/fendermint/app/src/cmd/materializer.rs +++ b/fendermint/app/src/cmd/materializer.rs @@ -14,8 +14,8 @@ use fendermint_materializer::{ testnet::Testnet, AccountId, TestnetId, TestnetName, }; +use ipc_observability::config::TracingSettings; use ipc_observability::traces::set_global_tracing_subscriber; -use ipc_observability::traces_settings::TracesSettings; use crate::cmd; @@ -23,7 +23,7 @@ use super::key::{read_secret_key, read_secret_key_hex}; cmd! { MaterializerArgs(self) { - let _trace_file_guard = set_global_tracing_subscriber(&TracesSettings::default()); + let _trace_file_guard = set_global_tracing_subscriber(&TracingSettings::default()); let data_dir = expand_tilde(&self.data_dir); let dm = || DockerMaterializer::new(&data_dir, self.seed).map(|m| m.with_policy(DropPolicy::PERSISTENT)); diff --git a/fendermint/app/src/cmd/rpc.rs b/fendermint/app/src/cmd/rpc.rs index 9c477dc21..2861a6286 100644 --- a/fendermint/app/src/cmd/rpc.rs +++ b/fendermint/app/src/cmd/rpc.rs @@ -31,8 +31,8 @@ use tendermint_rpc::HttpClient; use fendermint_rpc::message::{GasParams, SignedMessageFactory}; use fendermint_rpc::{client::FendermintClient, query::QueryClient}; use fendermint_vm_actor_interface::eam::{self, CreateReturn, EthAddress}; +use ipc_observability::config::TracingSettings; use ipc_observability::traces::set_global_tracing_subscriber; -use ipc_observability::traces_settings::TracesSettings; use crate::cmd; use crate::options::rpc::{BroadcastMode, FevmArgs, RpcFevmCommands, TransArgs}; @@ -42,7 +42,7 @@ use super::key::read_secret_key; cmd! { RpcArgs(self) { - let _trace_file_guard = set_global_tracing_subscriber(&TracesSettings::default()); + let _trace_file_guard = set_global_tracing_subscriber(&TracingSettings::default()); let client = FendermintClient::new_http(self.url.clone(), self.proxy_url.clone())?; match self.command.clone() { diff --git a/ipc/observability/src/lib.rs b/ipc/observability/src/lib.rs index 918e8da55..c1c4d3cbc 100644 --- a/ipc/observability/src/lib.rs +++ b/ipc/observability/src/lib.rs @@ -5,9 +5,9 @@ pub mod macros; pub mod traces; mod tracing_layers; pub use lazy_static::lazy_static; +pub mod config; pub mod observe; 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 affb96832..00a8c1ae8 100644 --- a/ipc/observability/src/traces.rs +++ b/ipc/observability/src/traces.rs @@ -6,10 +6,11 @@ use tracing::Level; pub use tracing_appender::non_blocking; pub use tracing_appender::non_blocking::WorkerGuard; use tracing_appender::rolling::RollingFileAppender; -use tracing_subscriber::{fmt, fmt::Subscriber, layer::SubscriberExt, Layer, LogLevel}; +use tracing_subscriber::{fmt, fmt::Subscriber, layer::SubscriberExt, Layer}; -use crate::traces_settings::{FileLayerSettings, TracesSettings}; +use crate::config::{FileLayerSettings, LogLevel, TracingSettings}; use crate::tracing_layers::DomainEventFilterLayer; +use tracing_subscriber::filter::EnvFilter; // pub fn create_temporary_subscriber() -> Subscriber { @@ -21,10 +22,10 @@ pub fn create_temporary_subscriber() -> Subscriber { .finish() } -pub fn set_global_tracing_subscriber(config: &TracesSettings) -> Option { - let console_filter = match config.console { +pub fn set_global_tracing_subscriber(config: &TracingSettings) -> Option { + let console_filter = match &config.console { Some(console_settings) => console_settings.level_to_filter(), - None => LogLevel::default().to_filter(), + None => EnvFilter::default(), }; // log all traces to stderr (reserving stdout for any actual output such as from the CLI commands) @@ -35,9 +36,9 @@ pub fn set_global_tracing_subscriber(config: &TracesSettings) -> Option { - let (non_blocking, file_guard) = non_blocking(create_file_appender(&file_settings)); + let (non_blocking, file_guard) = non_blocking(create_file_appender(file_settings)); let file_layer = fmt::layer() .json() @@ -94,7 +95,7 @@ fn create_file_appender(settings: &FileLayerSettings) -> RollingFileAppender { if let Some(rotation_kind) = &settings.rotation { println!("rotation kind: {:?}", rotation_kind); - appender = appender.rotation(rotation_kind.to_tracing_rotation()); + appender = appender.rotation(rotation_kind.into()); }; appender diff --git a/ipc/observability/src/traces_settings.rs b/ipc/observability/src/traces_settings.rs deleted file mode 100644 index 2ac85749e..000000000 --- a/ipc/observability/src/traces_settings.rs +++ /dev/null @@ -1,127 +0,0 @@ -// 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, Default)] -pub struct TracesSettings { - pub console: Option, - pub file: Option, -} - -#[serde_as] -#[derive(Debug, Deserialize, Clone)] -pub struct ConsoleLayerSettings { - pub level: Option, -} - -impl ConsoleLayerSettings { - pub fn level_to_filter(&self) -> EnvFilter { - level_to_filter(&self.level) - } -} - -impl Default for ConsoleLayerSettings { - fn default() -> Self { - ConsoleLayerSettings { - level: Some(LogLevel::default()), - } - } -} - -#[serde_as] -#[derive(Debug, Deserialize, Clone, Default)] -pub struct FileLayerSettings { - pub enabled: bool, - pub level: Option, - pub directory: Option, - pub max_log_files: Option, - pub rotation: Option, - pub domain_filter: Option>, - pub events_filter: Option>, -} - -impl FileLayerSettings { - pub fn level_to_filter(&self) -> EnvFilter { - level_to_filter(&self.level) - } -} - -fn level_to_filter(level: &Option) -> EnvFilter { - match level { - Some(level) => level.to_filter().unwrap_or_default(), - None => EnvFilter::default(), - } -} From ad1bd14e378f613a19061a8dea0ffb9869f73980 Mon Sep 17 00:00:00 2001 From: Karel Moravec Date: Mon, 22 Jul 2024 16:25:30 +0200 Subject: [PATCH 29/33] feat: fix after rebase --- fendermint/app/src/app.rs | 18 +---- fendermint/vm/interpreter/src/fvm/observe.rs | 1 + fendermint/vm/topdown/src/proxy.rs | 71 -------------------- ipc/observability/src/lib.rs | 1 - 4 files changed, 2 insertions(+), 89 deletions(-) diff --git a/fendermint/app/src/app.rs b/fendermint/app/src/app.rs index 61e709a17..e87677483 100644 --- a/fendermint/app/src/app.rs +++ b/fendermint/app/src/app.rs @@ -625,13 +625,7 @@ where let mut mpool_received_trace = MpoolReceived::default(); let response = match result { - Err(e) => { - emit(MpoolReceivedInvalidMessage { - reason: "InvalidEncoding", - description: e.description.as_ref(), - }); - invalid_check_tx(AppError::InvalidEncoding, e.description) - } + Err(e) => invalid_check_tx(AppError::InvalidEncoding, e.description), Ok(result) => match result { Err(IllegalMessage) => invalid_check_tx(AppError::IllegalMessage, "".to_owned()), Ok(Err(InvalidSignature(d))) => invalid_check_tx(AppError::InvalidSignature, d), @@ -720,16 +714,6 @@ where reason: None, }); - let mut proposal_evaluated = BlockProposalEvaluated { - height: request.height.value(), - hash: HexEncodableBlockHash(request.hash.into()), - size: size_txs, - tx_count: num_txs, - validator: &request.proposer_address, - accept, - reason: None, - }); - if accept { Ok(response::ProcessProposal::Accept) } else { diff --git a/fendermint/vm/interpreter/src/fvm/observe.rs b/fendermint/vm/interpreter/src/fvm/observe.rs index fd8b0ead9..3b96271ec 100644 --- a/fendermint/vm/interpreter/src/fvm/observe.rs +++ b/fendermint/vm/interpreter/src/fvm/observe.rs @@ -183,6 +183,7 @@ mod tests { config_number: 3, }); + let mut r = thread_rng(); let secret_key = SecretKey::random(&mut r); emit(CheckpointSigned { diff --git a/fendermint/vm/topdown/src/proxy.rs b/fendermint/vm/topdown/src/proxy.rs index d52c3b70d..7fe47cb5d 100644 --- a/fendermint/vm/topdown/src/proxy.rs +++ b/fendermint/vm/topdown/src/proxy.rs @@ -128,77 +128,6 @@ impl IPCProviderProxyWithLatency { Self { inner } } } - -#[async_trait] -impl ParentQueryProxy for IPCProviderProxyWithLatency { - #[instrument(skip(self))] - async fn get_chain_head_height(&self) -> anyhow::Result { - emit_event_with_latency( - &self.inner.parent_subnet.to_string(), - "chain_head", - || async { self.inner.get_chain_head_height().await }, - ) - .await - } - - #[instrument(skip(self))] - async fn get_genesis_epoch(&self) -> anyhow::Result { - emit_event_with_latency( - &self.inner.parent_subnet.to_string(), - "genesis_epoch", - || async { self.inner.get_genesis_epoch().await }, - ) - .await - } - - #[instrument(skip(self))] - async fn get_block_hash(&self, height: BlockHeight) -> anyhow::Result { - emit_event_with_latency( - &self.inner.parent_subnet.to_string(), - "get_block_hash", - || async { self.inner.get_block_hash(height).await }, - ) - .await - } - - /// Get the top down messages from the starting to the ending height. - async fn get_top_down_msgs( - &self, - height: BlockHeight, - ) -> anyhow::Result>> { - emit_event_with_latency( - &self.inner.parent_subnet.to_string(), - "get_top_down_msgs", - || async { self.inner.get_top_down_msgs(height).await }, - ) - .await - } - - /// Get the validator set at the specified height. - async fn get_validator_changes( - &self, - height: BlockHeight, - ) -> anyhow::Result>> { - emit_event_with_latency( - &self.inner.parent_subnet.to_string(), - "get_validator_changeset", - || async { self.inner.get_validator_changes(height).await }, - ) - .await - } -} - -// TODO - create a macro for this -pub struct IPCProviderProxyWithLatency { - inner: IPCProviderProxy, -} - -impl IPCProviderProxyWithLatency { - pub fn new(inner: IPCProviderProxy) -> Self { - Self { inner } - } -} - #[async_trait] impl ParentQueryProxy for IPCProviderProxyWithLatency { #[instrument(skip(self))] diff --git a/ipc/observability/src/lib.rs b/ipc/observability/src/lib.rs index c1c4d3cbc..57fe44d7a 100644 --- a/ipc/observability/src/lib.rs +++ b/ipc/observability/src/lib.rs @@ -5,7 +5,6 @@ pub mod macros; pub mod traces; mod tracing_layers; pub use lazy_static::lazy_static; -pub mod config; pub mod observe; pub mod serde; From c544c46f164065705288d80c114827d1d66feaad Mon Sep 17 00:00:00 2001 From: Karel Moravec Date: Mon, 22 Jul 2024 17:58:32 +0200 Subject: [PATCH 30/33] fix: rebase && comments --- Cargo.lock | 15 +-- fendermint/app/settings/Cargo.toml | 1 + fendermint/vm/interpreter/src/fvm/observe.rs | 2 - ipc/observability/Cargo.toml | 3 + ipc/observability/src/config.rs | 116 +++++++++++++++++++ ipc/observability/src/lib.rs | 1 + ipc/observability/src/traces.rs | 8 +- 7 files changed, 127 insertions(+), 19 deletions(-) create mode 100644 ipc/observability/src/config.rs diff --git a/Cargo.lock b/Cargo.lock index c84467976..7f7cfecb4 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2886,7 +2886,6 @@ dependencies = [ "fvm_shared", "hex", "ipc-api", - "ipc-metrics", "ipc-observability", "ipc-provider", "ipc_ipld_resolver", @@ -5074,19 +5073,7 @@ dependencies = [ "prometheus", "serde", "serde_with 2.3.3", - "tracing", - "tracing-appender", - "tracing-subscriber", -] - -[[package]] -name = "ipc-observability" -version = "0.1.0" -dependencies = [ - "anyhow", - "hex", - "lazy_static", - "prometheus", + "strum 0.26.1", "tracing", "tracing-appender", "tracing-subscriber", diff --git a/fendermint/app/settings/Cargo.toml b/fendermint/app/settings/Cargo.toml index ba66ec4fa..e72a27e1f 100644 --- a/fendermint/app/settings/Cargo.toml +++ b/fendermint/app/settings/Cargo.toml @@ -28,6 +28,7 @@ fvm_shared = { workspace = true } fvm_ipld_encoding = { workspace = true } ipc-api = { workspace = true } ipc-provider = { workspace = true } +ipc-observability = { workspace = true } fendermint_vm_encoding = { path = "../../vm/encoding" } fendermint_vm_topdown = { path = "../../vm/topdown" } diff --git a/fendermint/vm/interpreter/src/fvm/observe.rs b/fendermint/vm/interpreter/src/fvm/observe.rs index 3b96271ec..d0304b879 100644 --- a/fendermint/vm/interpreter/src/fvm/observe.rs +++ b/fendermint/vm/interpreter/src/fvm/observe.rs @@ -14,8 +14,6 @@ use prometheus::{ use fendermint_crypto::PublicKey; use fvm_shared::message::Message; -use fvm_shared::message::Message; - register_metrics! { EXEC_FVM_CHECK_EXECUTION_TIME_SECS: Histogram = register_histogram!("exec_fvm_check_execution_time_secs", "Execution time of FVM check in seconds"); diff --git a/ipc/observability/Cargo.toml b/ipc/observability/Cargo.toml index 67679a858..41a445d08 100644 --- a/ipc/observability/Cargo.toml +++ b/ipc/observability/Cargo.toml @@ -14,3 +14,6 @@ tracing-subscriber = { workspace = true } tracing-appender = { workspace = true } hex = { workspace = true } anyhow = { workspace = true } +serde = { workspace = true } +serde_with = { workspace = true } +strum = { workspace = true } diff --git a/ipc/observability/src/config.rs b/ipc/observability/src/config.rs new file mode 100644 index 000000000..877da5329 --- /dev/null +++ b/ipc/observability/src/config.rs @@ -0,0 +1,116 @@ +// 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 strum; +use tracing_appender; +use tracing_appender::rolling::Rotation; +use tracing_subscriber::filter::EnvFilter; + +#[serde_as] +#[derive(Debug, Deserialize, Clone, Default, strum::EnumString, strum::Display)] +#[strum(serialize_all = "snake_case")] +pub enum LogLevel { + Off, + Error, + Warn, + Info, + Debug, + #[default] + Trace, +} + +impl LogLevel { + 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.to_string())?) + } +} + +#[serde_as] +#[derive(Debug, Deserialize, Clone, strum::EnumString, strum::Display)] +#[strum(serialize_all = "snake_case")] +pub enum RotationKind { + Minutely, + Hourly, + Daily, + Never, +} + +impl From for tracing_appender::rolling::Rotation { + fn from(kind: RotationKind) -> tracing_appender::rolling::Rotation { + match kind { + RotationKind::Minutely => tracing_appender::rolling::Rotation::MINUTELY, + RotationKind::Hourly => tracing_appender::rolling::Rotation::HOURLY, + RotationKind::Daily => tracing_appender::rolling::Rotation::DAILY, + RotationKind::Never => tracing_appender::rolling::Rotation::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, + } + } +} + +#[serde_as] +#[derive(Debug, Deserialize, Clone, Default)] +pub struct TracingSettings { + pub console: Option, + pub file: Option, +} + +#[serde_as] +#[derive(Debug, Deserialize, Clone)] +pub struct ConsoleLayerSettings { + pub level: Option, +} + +impl ConsoleLayerSettings { + pub fn level_to_filter(&self) -> EnvFilter { + level_to_filter(&self.level) + } +} + +impl Default for ConsoleLayerSettings { + fn default() -> Self { + ConsoleLayerSettings { + level: Some(LogLevel::default()), + } + } +} + +#[serde_as] +#[derive(Debug, Deserialize, Clone, Default)] +pub struct FileLayerSettings { + pub enabled: bool, + pub level: Option, + pub directory: Option, + pub max_log_files: Option, + pub rotation: Option, + pub domain_filter: Option>, + pub events_filter: Option>, +} + +impl FileLayerSettings { + pub fn level_to_filter(&self) -> EnvFilter { + level_to_filter(&self.level) + } +} + +fn level_to_filter(level: &Option) -> EnvFilter { + match level { + Some(level) => level.to_filter().unwrap_or_default(), + None => EnvFilter::default(), + } +} diff --git a/ipc/observability/src/lib.rs b/ipc/observability/src/lib.rs index 57fe44d7a..c1c4d3cbc 100644 --- a/ipc/observability/src/lib.rs +++ b/ipc/observability/src/lib.rs @@ -5,6 +5,7 @@ pub mod macros; pub mod traces; mod tracing_layers; pub use lazy_static::lazy_static; +pub mod config; pub mod observe; pub mod serde; diff --git a/ipc/observability/src/traces.rs b/ipc/observability/src/traces.rs index 00a8c1ae8..f9f746251 100644 --- a/ipc/observability/src/traces.rs +++ b/ipc/observability/src/traces.rs @@ -8,11 +8,11 @@ pub use tracing_appender::non_blocking::WorkerGuard; use tracing_appender::rolling::RollingFileAppender; use tracing_subscriber::{fmt, fmt::Subscriber, layer::SubscriberExt, Layer}; -use crate::config::{FileLayerSettings, LogLevel, TracingSettings}; +use crate::config::{FileLayerSettings, TracingSettings}; use crate::tracing_layers::DomainEventFilterLayer; use tracing_subscriber::filter::EnvFilter; -// +// Creates a temporary subscriber that logs all traces to stderr. Useful when global tracing is not set yet. pub fn create_temporary_subscriber() -> Subscriber { tracing_subscriber::FmtSubscriber::builder() .with_max_level(Level::TRACE) @@ -22,6 +22,7 @@ pub fn create_temporary_subscriber() -> Subscriber { .finish() } +// Sets a global tracing subscriber with the given configuration. Returns a guard that can be used to drop the subscriber. pub fn set_global_tracing_subscriber(config: &TracingSettings) -> Option { let console_filter = match &config.console { Some(console_settings) => console_settings.level_to_filter(), @@ -95,7 +96,8 @@ fn create_file_appender(settings: &FileLayerSettings) -> RollingFileAppender { if let Some(rotation_kind) = &settings.rotation { println!("rotation kind: {:?}", rotation_kind); - appender = appender.rotation(rotation_kind.into()); + let rotation: tracing_appender::rolling::Rotation = rotation_kind.clone().into(); + appender = appender.rotation(rotation); }; appender From 22a065adb69c550654e737c032c0d3e3d7264e97 Mon Sep 17 00:00:00 2001 From: Karel Moravec Date: Mon, 22 Jul 2024 18:29:03 +0200 Subject: [PATCH 31/33] fix: select proper default --- fendermint/vm/topdown/src/proxy.rs | 1 + ipc/observability/src/config.rs | 4 ++-- ipc/observability/src/traces.rs | 5 ++--- 3 files changed, 5 insertions(+), 5 deletions(-) diff --git a/fendermint/vm/topdown/src/proxy.rs b/fendermint/vm/topdown/src/proxy.rs index 7fe47cb5d..94a8e3177 100644 --- a/fendermint/vm/topdown/src/proxy.rs +++ b/fendermint/vm/topdown/src/proxy.rs @@ -128,6 +128,7 @@ impl IPCProviderProxyWithLatency { Self { inner } } } + #[async_trait] impl ParentQueryProxy for IPCProviderProxyWithLatency { #[instrument(skip(self))] diff --git a/ipc/observability/src/config.rs b/ipc/observability/src/config.rs index 877da5329..956cc6f03 100644 --- a/ipc/observability/src/config.rs +++ b/ipc/observability/src/config.rs @@ -108,9 +108,9 @@ impl FileLayerSettings { } } -fn level_to_filter(level: &Option) -> EnvFilter { +pub fn level_to_filter(level: &Option) -> EnvFilter { match level { Some(level) => level.to_filter().unwrap_or_default(), - None => EnvFilter::default(), + None => LogLevel::Trace.to_filter().unwrap_or_default(), } } diff --git a/ipc/observability/src/traces.rs b/ipc/observability/src/traces.rs index f9f746251..dceeb3767 100644 --- a/ipc/observability/src/traces.rs +++ b/ipc/observability/src/traces.rs @@ -8,9 +8,8 @@ pub use tracing_appender::non_blocking::WorkerGuard; use tracing_appender::rolling::RollingFileAppender; use tracing_subscriber::{fmt, fmt::Subscriber, layer::SubscriberExt, Layer}; -use crate::config::{FileLayerSettings, TracingSettings}; +use crate::config::{level_to_filter, FileLayerSettings, TracingSettings}; use crate::tracing_layers::DomainEventFilterLayer; -use tracing_subscriber::filter::EnvFilter; // Creates a temporary subscriber that logs all traces to stderr. Useful when global tracing is not set yet. pub fn create_temporary_subscriber() -> Subscriber { @@ -26,7 +25,7 @@ pub fn create_temporary_subscriber() -> Subscriber { pub fn set_global_tracing_subscriber(config: &TracingSettings) -> Option { let console_filter = match &config.console { Some(console_settings) => console_settings.level_to_filter(), - None => EnvFilter::default(), + None => level_to_filter(&None), }; // log all traces to stderr (reserving stdout for any actual output such as from the CLI commands) From 68b2dbcfe2fcf4d41514ee33aa9f6a000c1914c8 Mon Sep 17 00:00:00 2001 From: Karel Moravec Date: Mon, 22 Jul 2024 18:45:43 +0200 Subject: [PATCH 32/33] feat: setup tracing in single place --- fendermint/app/src/cmd/debug.rs | 3 --- fendermint/app/src/cmd/genesis.rs | 3 --- fendermint/app/src/cmd/key.rs | 4 ---- fendermint/app/src/cmd/mod.rs | 39 +++++++++++++++++++++++++------ fendermint/app/src/cmd/rpc.rs | 11 +++------ fendermint/app/src/cmd/run.rs | 4 ---- 6 files changed, 35 insertions(+), 29 deletions(-) diff --git a/fendermint/app/src/cmd/debug.rs b/fendermint/app/src/cmd/debug.rs index 8b1c9f1ea..391f767b5 100644 --- a/fendermint/app/src/cmd/debug.rs +++ b/fendermint/app/src/cmd/debug.rs @@ -6,8 +6,6 @@ use fendermint_app_options::debug::{ DebugArgs, DebugCommands, DebugExportTopDownEventsArgs, DebugIpcCommands, }; use fendermint_vm_topdown::proxy::IPCProviderProxy; -use ipc_observability::config::TracingSettings; -use ipc_observability::traces::set_global_tracing_subscriber; use ipc_provider::{ config::subnet::{EVMSubnet, SubnetConfig}, IpcProvider, @@ -25,7 +23,6 @@ cmd! { cmd! { DebugIpcCommands(self) { - let _trace_file_guard = set_global_tracing_subscriber(&TracingSettings::default()); match self { DebugIpcCommands::ExportTopDownEvents(args) => { diff --git a/fendermint/app/src/cmd/genesis.rs b/fendermint/app/src/cmd/genesis.rs index c811a4622..c7d1c6a21 100644 --- a/fendermint/app/src/cmd/genesis.rs +++ b/fendermint/app/src/cmd/genesis.rs @@ -14,8 +14,6 @@ use fendermint_vm_genesis::{ ipc, Account, Actor, ActorMeta, Collateral, Genesis, Multisig, PermissionMode, SignerAddr, Validator, ValidatorKey, }; -use ipc_observability::config::TracingSettings; -use ipc_observability::traces::set_global_tracing_subscriber; use crate::cmd; use crate::options::genesis::*; @@ -24,7 +22,6 @@ use super::key::read_public_key; cmd! { GenesisArgs(self) { - let _trace_file_guard = set_global_tracing_subscriber(&TracingSettings::default()); let genesis_file = self.genesis_file.clone(); match &self.command { diff --git a/fendermint/app/src/cmd/key.rs b/fendermint/app/src/cmd/key.rs index b534add42..e5891ae0f 100644 --- a/fendermint/app/src/cmd/key.rs +++ b/fendermint/app/src/cmd/key.rs @@ -6,8 +6,6 @@ use fendermint_app_options::key::KeyShowPeerIdArgs; use fendermint_crypto::{from_b64, to_b64, PublicKey, SecretKey}; use fendermint_vm_actor_interface::eam::EthAddress; use fvm_shared::address::Address; -use ipc_observability::config::TracingSettings; -use ipc_observability::traces::set_global_tracing_subscriber; use rand_chacha::{rand_core::SeedableRng, ChaCha20Rng}; use serde_json::json; use std::path::Path; @@ -23,8 +21,6 @@ use crate::{ cmd! { KeyArgs(self) { - let _trace_file_guard = set_global_tracing_subscriber(&TracingSettings::default()); - match &self.command { KeyCommands::Gen(args) => args.exec(()).await, KeyCommands::IntoTendermint(args) => args.exec(()).await, diff --git a/fendermint/app/src/cmd/mod.rs b/fendermint/app/src/cmd/mod.rs index 12758a493..8854c0d7d 100644 --- a/fendermint/app/src/cmd/mod.rs +++ b/fendermint/app/src/cmd/mod.rs @@ -10,7 +10,9 @@ use crate::{ use anyhow::{anyhow, Context}; use async_trait::async_trait; +use ipc_observability::config::TracingSettings; use ipc_observability::traces::create_temporary_subscriber; +use ipc_observability::traces::set_global_tracing_subscriber; use tracing::subscriber; pub mod config; @@ -66,13 +68,36 @@ macro_rules! cmd { pub async fn exec(opts: &Options) -> anyhow::Result<()> { match &opts.command { Commands::Config(args) => args.exec(settings(opts)?).await, - Commands::Debug(args) => args.exec(()).await, - Commands::Run(args) => args.exec(settings(opts)?).await, - Commands::Key(args) => args.exec(()).await, - Commands::Genesis(args) => args.exec(()).await, - Commands::Rpc(args) => args.exec(()).await, - Commands::Eth(args) => args.exec(settings(opts)?.eth).await, - Commands::Materializer(args) => args.exec(()).await, + Commands::Debug(args) => { + let _trace_file_guard = set_global_tracing_subscriber(&TracingSettings::default()); + args.exec(()).await + } + Commands::Run(args) => { + let settings = settings(opts)?; + let _trace_file_guard = set_global_tracing_subscriber(&settings.tracing); + args.exec(settings).await + } + Commands::Key(args) => { + let _trace_file_guard = set_global_tracing_subscriber(&TracingSettings::default()); + args.exec(()).await + } + Commands::Genesis(args) => { + let _trace_file_guard = set_global_tracing_subscriber(&TracingSettings::default()); + args.exec(()).await + } + Commands::Rpc(args) => { + let _trace_file_guard = set_global_tracing_subscriber(&TracingSettings::default()); + args.exec(()).await + } + Commands::Eth(args) => { + let settings = settings(opts)?.eth; + let _trace_file_guard = set_global_tracing_subscriber(&settings.tracing); + args.exec(settings).await + } + Commands::Materializer(args) => { + let _trace_file_guard = set_global_tracing_subscriber(&TracingSettings::default()); + args.exec(()).await + } } } diff --git a/fendermint/app/src/cmd/rpc.rs b/fendermint/app/src/cmd/rpc.rs index 2861a6286..fc85ca24d 100644 --- a/fendermint/app/src/cmd/rpc.rs +++ b/fendermint/app/src/cmd/rpc.rs @@ -28,22 +28,17 @@ use tendermint::abci::response::DeliverTx; use tendermint::block::Height; use tendermint_rpc::HttpClient; -use fendermint_rpc::message::{GasParams, SignedMessageFactory}; -use fendermint_rpc::{client::FendermintClient, query::QueryClient}; -use fendermint_vm_actor_interface::eam::{self, CreateReturn, EthAddress}; -use ipc_observability::config::TracingSettings; -use ipc_observability::traces::set_global_tracing_subscriber; - use crate::cmd; use crate::options::rpc::{BroadcastMode, FevmArgs, RpcFevmCommands, TransArgs}; use crate::options::rpc::{RpcArgs, RpcCommands, RpcQueryCommands}; +use fendermint_rpc::message::{GasParams, SignedMessageFactory}; +use fendermint_rpc::{client::FendermintClient, query::QueryClient}; +use fendermint_vm_actor_interface::eam::{self, CreateReturn, EthAddress}; use super::key::read_secret_key; cmd! { RpcArgs(self) { - let _trace_file_guard = set_global_tracing_subscriber(&TracingSettings::default()); - let client = FendermintClient::new_http(self.url.clone(), self.proxy_url.clone())?; match self.command.clone() { RpcCommands::Query { height, command } => { diff --git a/fendermint/app/src/cmd/run.rs b/fendermint/app/src/cmd/run.rs index 3b0a897ac..2dac3ef6a 100644 --- a/fendermint/app/src/cmd/run.rs +++ b/fendermint/app/src/cmd/run.rs @@ -42,12 +42,8 @@ use crate::cmd::key::read_secret_key; use crate::{cmd, options::run::RunArgs, settings::Settings}; use fendermint_app::observe::register_metrics as register_consensus_metrics; -use ipc_observability::traces::set_global_tracing_subscriber; - cmd! { RunArgs(self, settings) { - let _trace_file_guard = set_global_tracing_subscriber(&settings.tracing); - run(settings).await } } From 73a4f4d7ba11ee2b2cc9640be6bd6da9a0252646 Mon Sep 17 00:00:00 2001 From: Karel Moravec Date: Mon, 22 Jul 2024 20:17:12 +0200 Subject: [PATCH 33/33] fix: do no register tracing twice in eth --- fendermint/app/src/cmd/eth.rs | 3 --- 1 file changed, 3 deletions(-) diff --git a/fendermint/app/src/cmd/eth.rs b/fendermint/app/src/cmd/eth.rs index 953a88d7c..defcd4f8a 100644 --- a/fendermint/app/src/cmd/eth.rs +++ b/fendermint/app/src/cmd/eth.rs @@ -5,7 +5,6 @@ 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::{ @@ -16,8 +15,6 @@ use crate::{ cmd! { EthArgs(self, settings: EthSettings) { - let _trace_file_guard = set_global_tracing_subscriber(&settings.tracing); - match self.command.clone() { EthCommands::Run { ws_url, http_url, connect_retry_delay } => { let (client, driver) = HybridClient::new(http_url, ws_url, Duration::from_secs(connect_retry_delay)).context("failed to create HybridClient")?;