diff --git a/Cargo.lock b/Cargo.lock index 74157e1a73..8cf7b74bb2 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -270,9 +270,9 @@ dependencies = [ [[package]] name = "anyhow" -version = "1.0.75" +version = "1.0.81" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "a4668cab20f66d8d020e1fbc0ebe47217433c1b6c8f2040faf858554e394ace6" +checksum = "0952808a6c2afd1aa8947271f3a60f1a6763c7b912d210184c5149b5cf147247" [[package]] name = "arc-swap" @@ -481,7 +481,7 @@ checksum = "a66537f1bb974b254c98ed142ff995236e81b9d0fe4db0575f46612cb15eb0f9" dependencies = [ "proc-macro2", "quote", - "syn 2.0.38", + "syn 2.0.58", ] [[package]] @@ -1000,7 +1000,7 @@ dependencies = [ "heck 0.4.1", "proc-macro2", "quote", - "syn 2.0.38", + "syn 2.0.58", ] [[package]] @@ -1325,7 +1325,7 @@ checksum = "83fdaf97f4804dcebfa5862639bc9ce4121e82140bec2a987ac5140294865b5b" dependencies = [ "proc-macro2", "quote", - "syn 2.0.38", + "syn 2.0.58", ] [[package]] @@ -1397,7 +1397,7 @@ dependencies = [ "proc-macro2", "quote", "strsim 0.10.0", - "syn 2.0.38", + "syn 2.0.58", ] [[package]] @@ -1430,7 +1430,7 @@ checksum = "c5a91391accf613803c2a9bf9abccdbaa07c54b4244a5b64883f9c3c137c86be" dependencies = [ "darling_core 0.20.6", "quote", - "syn 2.0.38", + "syn 2.0.58", ] [[package]] @@ -1628,7 +1628,7 @@ checksum = "487585f4d0c6655fe74905e2504d8ad6908e4db67f744eb140876906c2f3175d" dependencies = [ "proc-macro2", "quote", - "syn 2.0.38", + "syn 2.0.58", ] [[package]] @@ -1647,7 +1647,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "f87ab5c4c35c1d2fc7928e96d1cee3786a9bc9571ebaf4bf8f4207e6271165fa" dependencies = [ "quote", - "syn 2.0.38", + "syn 2.0.58", ] [[package]] @@ -1763,7 +1763,7 @@ dependencies = [ "heck 0.4.1", "proc-macro2", "quote", - "syn 2.0.38", + "syn 2.0.58", ] [[package]] @@ -1775,7 +1775,7 @@ dependencies = [ "once_cell", "proc-macro2", "quote", - "syn 2.0.38", + "syn 2.0.58", ] [[package]] @@ -2008,7 +2008,7 @@ checksum = "89ca545a94061b6365f2c7355b4b32bd20df3ff95f02da9329b34ccc3bd6ee72" dependencies = [ "proc-macro2", "quote", - "syn 2.0.38", + "syn 2.0.58", ] [[package]] @@ -3197,7 +3197,7 @@ dependencies = [ "proc-macro-warning", "proc-macro2", "quote", - "syn 2.0.38", + "syn 2.0.58", ] [[package]] @@ -4012,7 +4012,7 @@ dependencies = [ "proc-macro-crate", "proc-macro2", "quote", - "syn 2.0.38", + "syn 2.0.58", ] [[package]] @@ -4150,6 +4150,7 @@ dependencies = [ "mina-hasher", "mina-p2p-messages", "multihash 0.18.1", + "openmina-macros", "redux", "serde", "serde_json", @@ -4160,6 +4161,19 @@ dependencies = [ "tracing", ] +[[package]] +name = "openmina-macros" +version = "0.0.1" +dependencies = [ + "anyhow", + "openmina-core", + "proc-macro2", + "quote", + "rust-format", + "syn 2.0.58", + "tracing", +] + [[package]] name = "openmina-node-invariants" version = "0.3.0" @@ -4270,7 +4284,7 @@ checksum = "a948666b637a0f465e8564c73e89d4dde00d72d4d473cc972f390fc3dcee7d9c" dependencies = [ "proc-macro2", "quote", - "syn 2.0.38", + "syn 2.0.58", ] [[package]] @@ -4349,6 +4363,7 @@ dependencies = [ "multiaddr", "multihash 0.18.1", "openmina-core", + "openmina-macros", "quick-protobuf", "rand 0.8.5", "redux", @@ -4511,7 +4526,7 @@ dependencies = [ "pest_meta", "proc-macro2", "quote", - "syn 2.0.38", + "syn 2.0.58", ] [[package]] @@ -4542,7 +4557,7 @@ checksum = "4359fd9c9171ec6e8c62926d6faaf553a8dc3f64e1507e76da7911b4f6a04405" dependencies = [ "proc-macro2", "quote", - "syn 2.0.38", + "syn 2.0.58", ] [[package]] @@ -4739,14 +4754,14 @@ checksum = "9b698b0b09d40e9b7c1a47b132d66a8b54bcd20583d9b6d06e4535e383b4405c" dependencies = [ "proc-macro2", "quote", - "syn 2.0.38", + "syn 2.0.58", ] [[package]] name = "proc-macro2" -version = "1.0.69" +version = "1.0.79" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "134c189feb4956b20f6f547d2cf727d4c0fe06722b20a0eec87ed445a97f92da" +checksum = "e835ff2298f5721608eb1a980ecaee1aef2c132bf95ecc026a11b7bf3c01c02e" dependencies = [ "unicode-ident", ] @@ -4771,7 +4786,7 @@ checksum = "440f724eba9f6996b75d63681b0a92b06947f1457076d503a4d2e2c8f56442b8" dependencies = [ "proc-macro2", "quote", - "syn 2.0.38", + "syn 2.0.58", ] [[package]] @@ -4851,9 +4866,9 @@ dependencies = [ [[package]] name = "quote" -version = "1.0.33" +version = "1.0.35" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "5267fca4496028628a95160fc423a33e8b2e6af8a5302579e322e4b520293cae" +checksum = "291ec9ab5efd934aaf503a6466c5d5251535d108ee747472c3977cc5acc868ef" dependencies = [ "proc-macro2", ] @@ -5259,6 +5274,9 @@ name = "rust-format" version = "0.3.4" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "60e7c00b6c3bf5e38a880eec01d7e829d12ca682079f8238a464def3c4b31627" +dependencies = [ + "proc-macro2", +] [[package]] name = "rustc-demangle" @@ -5532,7 +5550,7 @@ checksum = "67c5609f394e5c2bd7fc51efda478004ea80ef42fee983d5c67a65e34f32c0e3" dependencies = [ "proc-macro2", "quote", - "syn 2.0.38", + "syn 2.0.58", ] [[package]] @@ -5618,7 +5636,7 @@ dependencies = [ "darling 0.20.6", "proc-macro2", "quote", - "syn 2.0.38", + "syn 2.0.58", ] [[package]] @@ -5795,6 +5813,7 @@ dependencies = [ "serde_json", "sha2 0.10.8", "strum_macros", + "thiserror", "wasm-bindgen-test", ] @@ -5969,9 +5988,9 @@ dependencies = [ [[package]] name = "syn" -version = "2.0.38" +version = "2.0.58" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "e96b79aaa137db8f61e26363a0c9b47d8b4ec75da28b7d1d614c2303e232408b" +checksum = "44cfb93f38070beee36b3fef7d4f5a16f27751d94b187b666a5cc5e9b0d30687" dependencies = [ "proc-macro2", "quote", @@ -6068,7 +6087,7 @@ checksum = "266b2e40bc00e5a6c09c3584011e08b06f123c00362c92b975ba9843aaaa14b8" dependencies = [ "proc-macro2", "quote", - "syn 2.0.38", + "syn 2.0.58", ] [[package]] @@ -6154,7 +6173,7 @@ checksum = "5b8a1e28f2deaa14e508979454cb3a223b10b938b45af148bc0986de36f1923b" dependencies = [ "proc-macro2", "quote", - "syn 2.0.38", + "syn 2.0.58", ] [[package]] @@ -6296,7 +6315,7 @@ checksum = "34704c8d6ebcbc939824180af020566b01a7c01f80641264eba0999f6c2b6be7" dependencies = [ "proc-macro2", "quote", - "syn 2.0.38", + "syn 2.0.58", ] [[package]] @@ -6790,7 +6809,7 @@ dependencies = [ "once_cell", "proc-macro2", "quote", - "syn 2.0.38", + "syn 2.0.58", "wasm-bindgen-shared", ] @@ -6824,7 +6843,7 @@ checksum = "54681b18a46765f095758388f2d0cf16eb8d4169b639ab575a8f5693af210c7b" dependencies = [ "proc-macro2", "quote", - "syn 2.0.38", + "syn 2.0.58", "wasm-bindgen-backend", "wasm-bindgen-shared", ] @@ -7450,7 +7469,7 @@ checksum = "9ce1b18ccd8e73a9321186f97e46f9f04b778851177567b1975109d26a08d2a6" dependencies = [ "proc-macro2", "quote", - "syn 2.0.38", + "syn 2.0.58", ] [[package]] @@ -7470,7 +7489,7 @@ checksum = "ce36e65b0d2999d2aafac989fb249189a141aee1f53c612c1f37d72631959f69" dependencies = [ "proc-macro2", "quote", - "syn 2.0.38", + "syn 2.0.58", ] [[package]] diff --git a/Cargo.toml b/Cargo.toml index ad7c0542f9..23d56b9afc 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -3,6 +3,7 @@ cargo-features = ["named-profiles"] [workspace] members = [ "core", + "macros", "ledger", "snark", "p2p", diff --git a/core/Cargo.toml b/core/Cargo.toml index 5345bab6a6..a037db32d7 100644 --- a/core/Cargo.toml +++ b/core/Cargo.toml @@ -16,6 +16,7 @@ redux = { workspace = true } tokio = { version = "1.26", features = ["sync"] } time = { version = "0.3", features = ["formatting"] } multihash = { version = "0.18.1", features = ["blake2b"] } +openmina-macros = { path = "../macros" } mina-hasher = { workspace = true } mina-p2p-messages = { workspace = true } diff --git a/core/src/lib.rs b/core/src/lib.rs index 1053fcb302..5c96fc0001 100644 --- a/core/src/lib.rs +++ b/core/src/lib.rs @@ -26,3 +26,6 @@ pub fn preshared_key(chain_id: &str) -> [u8; 32] { psk_fixed.copy_from_slice(hash.as_ref()); psk_fixed } + +pub use log::ActionEvent; +pub use openmina_macros::*; diff --git a/core/src/log.rs b/core/src/log.rs index cb1db0d83c..15ec293491 100644 --- a/core/src/log.rs +++ b/core/src/log.rs @@ -73,4 +73,71 @@ macro_rules! error { }; } +pub const ACTION_TRACE_TARGET: &str = "openmina_core::log::action"; + +#[macro_export] +macro_rules! action_event { + ($level:expr, $context:expr, $($tts:tt)*) => { + $crate::log::inner::event!(target: { $crate::log::ACTION_TRACE_TARGET }, $level, time = $context.time(), kind = $context.kind(), node_id = $context.node_id(), $($tts)*) + }; + ($level:expr, $context:expr) => { + $crate::log::inner::event!(target: { $crate::log::ACTION_TRACE_TARGET }, $level, time = $context.time(), kind = $context.kind(), node_id = $context.node_id()) + }; + } + +#[macro_export] +macro_rules! action_warn { + ($context:expr, $($tts:tt)*) => { + $crate::action_event!($crate::log::inner::Level::WARN, $context, $($tts)*) + }; + ($context:expr) => { + $crate::action_event!($crate::log::inner::Level::WARN, $context) + }; +} + +#[macro_export] +macro_rules! action_info { + ($context:expr, $($tts:tt)*) => { + $crate::action_event!($crate::log::inner::Level::INFO, $context, $($tts)*) + }; + ($context:expr) => { + $crate::action_event!($crate::log::inner::Level::INFO, $context) + }; +} + +#[macro_export] +macro_rules! action_debug { + ($context:expr, $($tts:tt)*) => { + $crate::action_event!($crate::log::inner::Level::DEBUG, $context, $($tts)*) + }; + ($context:expr) => { + $crate::action_event!($crate::log::inner::Level::DEBUG, $context) + }; +} + +#[macro_export] +macro_rules! action_trace { + ($context:expr, $($tts:tt)*) => { + $crate::action_event!($crate::log::inner::Level::TRACE, $context, $($tts)*) + }; + ($context:expr) => { + $crate::action_event!($crate::log::inner::Level::TRACE, $context) + }; +} + +pub trait EventContext { + fn timestamp(&self) -> redux::Timestamp; + fn time(&self) -> &'_ dyn Value; + fn node_id(&self) -> &'_ dyn Value; + fn kind(&self) -> &'_ dyn Value; +} + +pub trait ActionEvent { + fn action_event(&self, context: &T) + where + T: EventContext; +} + +use tracing::Value; + pub use crate::{debug, error, info, trace, warn}; diff --git a/core/src/snark/snark_job_commitment.rs b/core/src/snark/snark_job_commitment.rs index b071e1d346..ab02ee1154 100644 --- a/core/src/snark/snark_job_commitment.rs +++ b/core/src/snark/snark_job_commitment.rs @@ -10,9 +10,7 @@ use super::SnarkJobId; #[derive(BinProtWrite, BinProtRead, Serialize, Deserialize, Debug, Clone)] pub struct SnarkJobCommitment { - /// Timestamp in milliseconds. - /// TODO(binier): have to use i64, because binprot doesn't support u64. - timestamp: i64, + timestamp: u64, pub job_id: SnarkJobId, pub fee: CurrencyFeeStableV1, pub snarker: NonZeroCurvePoint, @@ -27,7 +25,7 @@ impl SnarkJobCommitment { snarker: NonZeroCurvePoint, ) -> Self { Self { - timestamp: timestamp as i64, + timestamp, job_id, fee, snarker, diff --git a/macros/Cargo.toml b/macros/Cargo.toml new file mode 100644 index 0000000000..2cb7db1a32 --- /dev/null +++ b/macros/Cargo.toml @@ -0,0 +1,20 @@ +[package] +name = "openmina-macros" +version = "0.0.1" +edition = "2021" +license = "Apache-2.0" +authors = [ "Alexander Koptelov " ] + +[lib] +proc-macro = true + +[dependencies] +proc-macro2 = "1.0.79" +quote = "1.0.35" +syn = "2.0.53" + +[dev-dependencies] +openmina-core = { path = "../core" } +tracing = "0.1.40" +rust-format = { version = "0.3", features = ["token_stream"] } +anyhow = "1.0.81" diff --git a/macros/src/action_event.md b/macros/src/action_event.md new file mode 100644 index 0000000000..6267af32b8 --- /dev/null +++ b/macros/src/action_event.md @@ -0,0 +1,182 @@ +Derives `[openmina_core::ActionEvent]` trait implementation for action. + +### Action containers + +For action containers, it simply delegates to inner actions. + + +```rust +# use openmina_core::ActionEvent; +# +#[derive(ActionEvent)] +enum ActionContainer { + SubAction1(Action1), +} +#[derive(ActionEvent)] +enum Action1 { + Init, + Done, +} + +ActionContainer::SubAction1(Action1::Init).action_event(context); +``` + +```rust +impl ActionEvent for ActionContainer { + fn action_event(&self, context: &T) + where T: ActionContext + { + match self { + ActionContainer(action) => action.action_event(context), + } + } +} + +impl ActionEvent for Action1 { + fn action_event(&self, context: &T) + where T: ActionContext + { + match self { + Action1::Init => openmina_core::action_debug!(context), + Action1::Done => openmina_core::action_debug!(context), + } + } +} +``` + +### Tracing level + +By default, tracing event of level `debug` is generated for an action. It can be +overriden by using `#[action_event(level = ...)]` attribute. Also, actions that +names ends with `Error` or `Warn` will be traced with `warn` level. + +```rust +#[derive(openmina_core::ActionEvent)] +#[action_event(level = trace)] +pub enum Action { + ActionDefaultLevel, + #[action_event(level = warn)] + ActionOverrideLevel, + ActionWithError, + ActionWithWarn, +} +``` + +```rust +impl openmina_core::ActionEvent for Action { + fn action_event(&self, context: &T) + where + T: openmina_core::log::EventContext, + { + #[allow(unused_variables)] + match self { + Action::ActionDefaultLevel => openmina_core::action_trace!(context), + Action::ActionOverrideLevel => openmina_core::action_warn!(context), + Action::ActionWithError => openmina_core::action_warn!(context), + Action::ActionWithWarn => openmina_core::action_warn!(context), + } + } +} +``` + +### Summary field + + +If an action has doc-comment, its first line will be used for `summary` field of +tracing events for the action. + +```rust +#[derive(openmina_core::ActionEvent)] +pub enum Action { + Unit, + /// documentation + UnitWithDoc, + /// Multiline documentation. + /// Another line. + /// + /// And another. + UnitWithMultilineDoc, +} +``` + +```rust +impl openmina_core::ActionEvent for Action { + fn action_event(&self, context: &T) + where + T: openmina_core::log::EventContext, + { + match self { + Action::Unit => openmina_core::action_debug!(context), + Action::UnitWithDoc => openmina_core::action_debug!(context, summary = "documentation"), + Action::UnitWithMultilineDoc => openmina_core::action_debug!(context, summary = "Multiline documentation"), + } + } +} +``` + +### Fields + +Certain fields can be added to the tracing event, using `#[action_event(fields(...))]` attribute. + +```rust +#[derive(openmina_core::ActionEvent)] +pub enum Action { + NoFields { f1: bool }, + #[action_event(fields(f1))] + Field { f1: bool }, + #[action_event(fields(f = f1))] + FieldWithName { f1: bool }, + #[action_event(fields(debug(f1)))] + DebugField { f1: bool }, + #[action_event(fields(display(f1)))] + DisplayField { f1: bool }, +} +``` + +```rust +impl openmina_core::ActionEvent for Action { + fn action_event(&self, context: &T) + where + T: openmina_core::log::EventContext, + { + match self { + Action::NoFields { f1 } => openmina_core::action_debug!(context), + Action::Field { f1 } => openmina_core::action_debug!(context, f1 = f1), + Action::FieldWithName { f1 } => openmina_core::action_debug!(context, f = f1), + Action::DebugField { f1 } => openmina_core::action_debug!(context, f1 = debug(f1)), + Action::DisplayField { f1 } => openmina_core::action_debug!(context, f1 = display(f1)), + } + } +} +``` + +### Logging using custom expression. + +When an action needs some custom logic to log (e.g. different logging basing on +a field's enum variant), logging can be delegated to a function implementing +that logic. + +```rust +#[derive(openmina_core::ActionEvent)] +pub enum Action { + #[action_event(expr(foo(context)))] + Unit, + #[action_event(expr(bar(context, f1)))] + Named { f1: bool }, +} +``` + +```rust +impl openmina_core::ActionEvent for Action { + fn action_event(&self, context: &T) + where + T: openmina_core::log::EventContext, + { + #[allow(unused_variables)] + match self { + Action::Unit => foo(context), + Action::Named { f1 } => bar(context, f1), + } + } +} +``` diff --git a/macros/src/action_event.rs b/macros/src/action_event.rs new file mode 100644 index 0000000000..12908e17df --- /dev/null +++ b/macros/src/action_event.rs @@ -0,0 +1,487 @@ +use std::convert::TryInto; + +use proc_macro2::*; +use quote::*; +use syn::*; + +#[derive(Clone, Debug)] +enum Level { + Error, + Warn, + Info, + Debug, + Trace, +} + +impl TryFrom for Level { + type Error = Error; + + fn try_from(value: Expr) -> Result { + let Expr::Path(ExprPath { path, .. }) = value else { + return Err(Error::new_spanned(value, "ident is expected")); + }; + let level = match path.require_ident()?.to_string().to_lowercase().as_str() { + "error" => Level::Error, + "warn" => Level::Warn, + "info" => Level::Info, + "debug" => Level::Debug, + "trace" => Level::Trace, + _ => return Err(Error::new_spanned(path, "incorrect value")), + }; + Ok(level) + } +} + +impl ToTokens for Level { + fn to_tokens(&self, tokens: &mut TokenStream) { + let ident = match self { + Level::Error => format_ident!("action_error"), + Level::Warn => format_ident!("action_warn"), + Level::Info => format_ident!("action_info"), + Level::Debug => format_ident!("action_debug"), + Level::Trace => format_ident!("action_trace"), + }; + tokens.extend(quote!(#ident)); + } +} + +#[derive(Clone, Debug)] +enum FieldsSpec { + /// List of expressions for fields to be added to the tracing, with + /// optional ident for filtering. + Some(Vec<(Option, TokenStream)>), +} + +#[derive(Clone, Debug, Default)] +struct ActionEventAttrs { + level: Option, + fields: Option, + expr: Option, +} + +pub fn expand(input: DeriveInput) -> Result { + let Data::Enum(enum_data) = &input.data else { + return Err(Error::new_spanned(input, "should be enum")); + }; + let type_name = &input.ident; + let trait_name = quote!(openmina_core::ActionEvent); // TODO + let input_attrs = action_event_attrs(&input.attrs)?; + let variants = enum_data + .variants + .iter() + .map(|v| { + let variant_name = &v.ident; + let mut args = vec![quote!(context)]; + let variant_attrs = action_event_attrs(&v.attrs)?; + match &v.fields { + Fields::Unnamed(fields) => { + if fields.unnamed.len() != 1 { + return Err(Error::new_spanned( + fields, + "only single-item variant supported", + )); + } + if fields.unnamed.len() != 1 { + return Err(Error::new_spanned( + fields, + "only single-item variant supported", + )); + } + Ok(quote! { + #type_name :: #variant_name (action) => action.action_event(#(#args),*), + }) + } + Fields::Named(fields_named) => { + let field_names = fields_named.named.iter().map(|named| &named.ident); + if let Some(expr) = variant_attrs.expr { + return Ok(quote! { + #type_name :: #variant_name { #(#field_names),* } => #expr, + }); + } + args.extend(summary_field(&v.attrs)?); + args.extend(fields(&variant_attrs.fields, &input_attrs.fields, fields_named)?); + let level = level(&variant_attrs.level, &v.ident, &input_attrs.level); + Ok(quote! { + #type_name :: #variant_name { #(#field_names),* } => openmina_core::#level!(#(#args),*), + }) + } + Fields::Unit => { + if let Some(expr) = variant_attrs.expr { + return Ok(quote! { + #type_name :: #variant_name => #expr, + }); + } + args.extend(summary_field(&v.attrs)?); + let level = level(&variant_attrs.level, &v.ident, &input_attrs.level); + Ok(quote! { + #type_name :: #variant_name => openmina_core::#level!(#(#args),*), + }) + } + } + }) + .collect::>>()?; + + Ok(quote! { + impl #trait_name for #type_name { + fn action_event(&self, context: &T) + where T: openmina_core::log::EventContext, + { + #[allow(unused_variables)] + match self { + #(#variants)* + } + } + } + }) +} + +fn level(variant_level: &Option, variant_name: &Ident, enum_level: &Option) -> Level { + variant_level + .as_ref() + .cloned() + .or_else(|| { + let s = variant_name.to_string(); + (s.ends_with("Error") || s.ends_with("Warn")).then_some(Level::Warn) + }) + .or_else(|| enum_level.as_ref().cloned()) + .unwrap_or(Level::Debug) +} + +fn fields( + variant_fields: &Option, + enum_fields: &Option, + fields: &FieldsNamed, +) -> Result> { + variant_fields + .as_ref() + .or(enum_fields.as_ref()) + .map_or_else(|| Ok(Vec::new()), |f| filter_fields(f, fields)) +} + +fn filter_fields(field_spec: &FieldsSpec, fields: &FieldsNamed) -> Result> { + match field_spec { + FieldsSpec::Some(f) => f + .iter() + .filter(|(name, _)| { + name.as_ref().map_or(true, |name| { + fields.named.iter().any(|n| Some(name) == n.ident.as_ref()) + }) + }) + .map(|(_, expr)| Ok(expr.clone())) + .collect(), + } +} + +fn action_event_attrs(attrs: &Vec) -> Result { + attrs + .iter() + .filter(|attr| attr.path().is_ident("action_event")) + .try_fold(ActionEventAttrs::default(), |mut attrs, attr| { + let nested = + attr.parse_args_with(punctuated::Punctuated::::parse_terminated)?; + nested.into_iter().try_for_each(|meta| { + match meta { + // #[level = ...] + Meta::NameValue(name_value) if name_value.path.is_ident("level") => { + let _ = attrs.level.insert(name_value.value.try_into()?); + } + // #[expr(...)] + Meta::List(list) if list.path.is_ident("expr") => { + let _ = attrs.expr.insert(list.parse_args::()?); + } + // #[fields(...)] + Meta::List(list) if list.path.is_ident("fields") => { + let nested = list.parse_args_with( + punctuated::Punctuated::::parse_terminated, + )?; + let fields = nested + .iter() + .map(|meta| { + match meta { + // field + Meta::Path(path) => { + let ident = path.require_ident()?; + Ok((Some(ident.clone()), quote!(#ident = #ident))) + } + // field = expr + Meta::NameValue(name_value) => { + let event_field = name_value.path.require_ident()?; + let expr = &name_value.value; + let maybe_field = get_field_name(expr); + Ok((maybe_field.cloned(), quote!(#event_field = #expr))) + } + // debug(field) + // display(field) + Meta::List(list) + if list.path.is_ident("debug") + || list.path.is_ident("display") => + { + let conv = list.path.require_ident()?; + let Expr::Path(field) = list.parse_args::()? else { + return Err(Error::new_spanned( + list, + "identifier is expected", + )); + }; + let field = field.path.require_ident()?; + Ok((Some(field.clone()), quote!(#field = #conv(#field)))) + } + _ => Err(Error::new_spanned(meta, "unrecognized repr")), + } + }) + .collect::>>()?; + let _ = attrs.fields.insert(FieldsSpec::Some(fields)); + } + _ => return Err(Error::new_spanned(meta, "unrecognized repr")), + } + Ok(()) + })?; + Ok(attrs) + }) +} + +fn get_field_name(expr: &Expr) -> Option<&Ident> { + match expr { + Expr::Path(path) => path.path.require_ident().ok(), + Expr::Field(field) => get_field_name(&field.base), + Expr::Reference(reference) => get_field_name(&reference.expr), + Expr::Unary(ExprUnary { expr, .. }) => get_field_name(expr), + Expr::Call(call) => match call.func.as_ref() { + Expr::Path(path) if path.path.is_ident("display") || path.path.is_ident("debug") => { + call.args.first().and_then(|arg| get_field_name(arg)) + } + Expr::Field(field) => get_field_name(&field.base), + _ => None, + }, + _ => None, + } +} + +fn summary_field(attrs: &Vec) -> Result> { + let Some(doc_attr) = attrs.iter().find(|attr| attr.path().is_ident("doc")) else { + return Ok(None); + }; + let name_value = doc_attr.meta.require_name_value()?; + let Expr::Lit(ExprLit { + lit: Lit::Str(lit), .. + }) = &name_value.value + else { + return Ok(None); + }; + let value = lit.value(); + let trimmed = value.trim(); + let stripped = trimmed.strip_suffix('.').unwrap_or(trimmed); + Ok(Some(quote!(summary = #stripped))) +} + +#[cfg(test)] +mod tests { + use rust_format::{Formatter, RustFmt}; + + fn test(input: &str, expected: &str) -> anyhow::Result<()> { + let fmt = RustFmt::default(); + + let expected = fmt.format_str(expected)?; + let input = syn::parse_str::(input)?; + let output = super::expand(input)?; + let output = fmt.format_tokens(output)?; + assert_eq!( + output, expected, + "\n<<<<<<\n{}======\n{}>>>>>>", + output, expected + ); + Ok(()) + } + + #[test] + fn test_delegate() -> anyhow::Result<()> { + let input = r#" +#[derive(openmina_core::ActionEvent)] +pub enum SuperAction { + Sub1(SubAction1), + Sub2(SubAction2), +} +"#; + let expected = r#" +impl openmina_core::ActionEvent for SuperAction { + fn action_event(&self, context: &T) + where + T: openmina_core::log::EventContext, + { + #[allow(unused_variables)] + match self { + SuperAction::Sub1(action) => action.action_event(context), + SuperAction::Sub2(action) => action.action_event(context), + } + } +} +"#; + test(input, expected) + } + + #[test] + fn test_unit() -> anyhow::Result<()> { + let input = r#" +#[derive(openmina_core::ActionEvent)] +pub enum Action { + Unit, + /// documentation + UnitWithDoc, + /// Multiline documentation. + /// Another line. + /// + /// And another. + UnitWithMultilineDoc, +} +"#; + let expected = r#" +impl openmina_core::ActionEvent for Action { + fn action_event(&self, context: &T) + where + T: openmina_core::log::EventContext, + { + #[allow(unused_variables)] + match self { + Action::Unit => openmina_core::action_debug!(context), + Action::UnitWithDoc => openmina_core::action_debug!(context, summary = "documentation"), + Action::UnitWithMultilineDoc => openmina_core::action_debug!(context, summary = "Multiline documentation"), + } + } +} +"#; + test(input, expected) + } + + #[test] + fn test_level() -> anyhow::Result<()> { + let input = r#" +#[derive(openmina_core::ActionEvent)] +#[action_event(level = trace)] +pub enum Action { + ActionDefaultLevel, + #[action_event(level = warn)] + ActionOverrideLevel, + ActionWithError, + ActionWithWarn, +} +"#; + let expected = r#" +impl openmina_core::ActionEvent for Action { + fn action_event(&self, context: &T) + where + T: openmina_core::log::EventContext, + { + #[allow(unused_variables)] + match self { + Action::ActionDefaultLevel => openmina_core::action_trace!(context), + Action::ActionOverrideLevel => openmina_core::action_warn!(context), + Action::ActionWithError => openmina_core::action_warn!(context), + Action::ActionWithWarn => openmina_core::action_warn!(context), + } + } +} +"#; + test(input, expected) + } + + #[test] + fn test_fields() -> anyhow::Result<()> { + let input = r#" +#[derive(openmina_core::ActionEvent)] +pub enum Action { + NoFields { f1: bool }, + #[action_event(fields(f1))] + Field { f1: bool }, + #[action_event(fields(f = f1))] + FieldWithName { f1: bool }, + #[action_event(fields(f = f.subfield))] + FieldExpr { f: WithSubfield }, + #[action_event(fields(f = display(f.subfield)))] + FieldDisplayExpr { f: WithSubfield }, + #[action_event(fields(debug(f1)))] + DebugField { f1: bool }, + #[action_event(fields(display(f1)))] + DisplayField { f1: bool }, +} +"#; + let expected = r#" +impl openmina_core::ActionEvent for Action { + fn action_event(&self, context: &T) + where + T: openmina_core::log::EventContext, + { + #[allow(unused_variables)] + match self { + Action::NoFields { f1 } => openmina_core::action_debug!(context), + Action::Field { f1 } => openmina_core::action_debug!(context, f1 = f1), + Action::FieldWithName { f1 } => openmina_core::action_debug!(context, f = f1), + Action::FieldExpr { f } => openmina_core::action_debug!(context, f = f.subfield), + Action::FieldDisplayExpr { f } => openmina_core::action_debug!(context, f = display(f.subfield)), + Action::DebugField { f1 } => openmina_core::action_debug!(context, f1 = debug(f1)), + Action::DisplayField { f1 } => openmina_core::action_debug!(context, f1 = display(f1)), + } + } +} +"#; + test(input, expected) + } + + #[test] + fn test_filtered_fields() -> anyhow::Result<()> { + let input = r#" +#[derive(openmina_core::ActionEvent)] +#[action_event(fields(f1, f2 = f2.sub, f3 = display(f3.sub), f4 = foo()))] +pub enum Action { + Unit, + AllFields { f1: bool, f2: WithSub, f3: WithSub }, + OnlyF1 { f1: bool }, + WithF3 { f1: bool, f3: WithSub }, +} +"#; + let expected = r#" +impl openmina_core::ActionEvent for Action { + fn action_event(&self, context: &T) + where + T: openmina_core::log::EventContext, + { + #[allow(unused_variables)] + match self { + Action::Unit => openmina_core::action_debug!(context), + Action::AllFields { f1, f2, f3 } => openmina_core::action_debug!(context, f1 = f1, f2 = f2.sub, f3 = display(f3.sub), f4 = foo()), + Action::OnlyF1 { f1 } => openmina_core::action_debug!(context, f1 = f1, f4 = foo()), + Action::WithF3 { f1, f3 } => openmina_core::action_debug!(context, f1 = f1, f3 = display(f3.sub), f4 = foo()), + } + } +} +"#; + test(input, expected) + } + + #[test] + fn test_call() -> anyhow::Result<()> { + let input = r#" +#[derive(openmina_core::ActionEvent)] +pub enum Action { + #[action_event(expr(foo(context)))] + Unit, + #[action_event(expr(foo(context, f1)))] + Named { f1: bool }, +} +"#; + let expected = r#" +impl openmina_core::ActionEvent for Action { + fn action_event(&self, context: &T) + where + T: openmina_core::log::EventContext, + { + #[allow(unused_variables)] + match self { + Action::Unit => foo(context), + Action::Named { f1 } => foo(context, f1), + } + } +} +"#; + test(input, expected) + } +} diff --git a/macros/src/lib.rs b/macros/src/lib.rs new file mode 100644 index 0000000000..7181354e2d --- /dev/null +++ b/macros/src/lib.rs @@ -0,0 +1,11 @@ +#[doc = include_str!("action_event.md")] +#[proc_macro_derive(ActionEvent, attributes(action_event))] +pub fn action_event(input: proc_macro::TokenStream) -> proc_macro::TokenStream { + let input = syn::parse_macro_input!(input as syn::DeriveInput); + match action_event::expand(input) { + Ok(tokens) => tokens.into(), + Err(err) => err.to_compile_error().into(), + } +} + +mod action_event; diff --git a/node/src/action_kind.rs b/node/src/action_kind.rs index 4bad67b933..a9d8eeaf2a 100644 --- a/node/src/action_kind.rs +++ b/node/src/action_kind.rs @@ -1117,7 +1117,7 @@ impl ActionKindGet for P2pNetworkKademliaAction { ActionKind::P2pNetworkKademliaUpdateFindNodeRequest } Self::StartBootstrap { .. } => ActionKind::P2pNetworkKademliaStartBootstrap, - Self::BootstrapFinished { .. } => ActionKind::P2pNetworkKademliaBootstrapFinished, + Self::BootstrapFinished => ActionKind::P2pNetworkKademliaBootstrapFinished, } } } diff --git a/node/src/block_producer/block_producer_actions.rs b/node/src/block_producer/block_producer_actions.rs index 9a04133b04..328cda6108 100644 --- a/node/src/block_producer/block_producer_actions.rs +++ b/node/src/block_producer/block_producer_actions.rs @@ -1,5 +1,6 @@ use mina_p2p_messages::v2::MinaBaseProofStableV2; use openmina_core::block::ArcBlockWithHash; +use openmina_core::ActionEvent; use serde::{Deserialize, Serialize}; use super::vrf_evaluator::BlockProducerVrfEvaluatorAction; @@ -11,13 +12,24 @@ use super::{ pub type BlockProducerActionWithMeta = redux::ActionWithMeta; pub type BlockProducerActionWithMetaRef<'a> = redux::ActionWithMeta<&'a BlockProducerAction>; -#[derive(Serialize, Deserialize, Debug, Clone)] +#[derive(Serialize, Deserialize, Debug, Clone, ActionEvent)] +#[action_event(level = trace)] pub enum BlockProducerAction { VrfEvaluator(BlockProducerVrfEvaluatorAction), BestTipUpdate { best_tip: ArcBlockWithHash, }, WonSlotSearch, + #[action_event( + level = info, + fields( + slot = won_slot.global_slot.slot_number.as_u32(), + slot_time = openmina_core::log::to_rfc_3339(won_slot.slot_time) + .unwrap_or_else(|_| "".to_owned()), + current_time = openmina_core::log::to_rfc_3339(context.timestamp()) + .unwrap_or_else(|_| "".to_owned()), + ) + )] WonSlot { won_slot: BlockProducerWonSlot, }, diff --git a/node/src/block_producer/vrf_evaluator/block_producer_vrf_evaluator_actions.rs b/node/src/block_producer/vrf_evaluator/block_producer_vrf_evaluator_actions.rs index 58c48e77dd..c2e15e5dfd 100644 --- a/node/src/block_producer/vrf_evaluator/block_producer_vrf_evaluator_actions.rs +++ b/node/src/block_producer/vrf_evaluator/block_producer_vrf_evaluator_actions.rs @@ -5,9 +5,12 @@ use mina_p2p_messages::v2::{ ConsensusProofOfStakeDataEpochDataNextValueVersionedValueStableV1, ConsensusProofOfStakeDataEpochDataStakingValueVersionedValueStableV1, LedgerHash, }; +use openmina_core::action_info; use openmina_core::block::ArcBlockWithHash; +use openmina_core::ActionEvent; use serde::{Deserialize, Serialize}; use vrf::VrfEvaluationOutput; +use vrf::VrfWonSlot; use super::{EpochData, VrfEvaluatorInput}; @@ -16,21 +19,26 @@ pub type BlockProducerVrfEvaluatorActionWithMeta = pub type BlockProducerVrfEvaluatorActionWithMetaRef<'a> = redux::ActionWithMeta<&'a BlockProducerVrfEvaluatorAction>; -#[derive(Serialize, Deserialize, Debug, Clone)] +#[derive(Serialize, Deserialize, Debug, Clone, ActionEvent)] +#[action_event(level = info)] pub enum BlockProducerVrfEvaluatorAction { - EvaluateSlot { - vrf_input: VrfEvaluatorInput, - }, + /// Vrf Evaluation requested. + #[action_event(fields(debug(vrp_input)))] + EvaluateSlot { vrf_input: VrfEvaluatorInput }, + /// Evaluation successful. + #[action_event(expr(log_vrf_output(context, vrf_output)))] ProcessSlotEvaluationSuccess { vrf_output: VrfEvaluationOutput, staking_ledger_hash: LedgerHash, }, - InitializeEvaluator { - best_tip: ArcBlockWithHash, - }, + #[action_event(level = trace)] + InitializeEvaluator { best_tip: ArcBlockWithHash }, + /// Checking possible Vrf evaluations. FinalizeEvaluatorInitialization { previous_epoch_and_height: Option<(u32, u32)>, }, + /// Checking possible Vrf evaluations. + #[action_event(level = info, fields(current_epoch_number, current_best_tip_slot, current_best_tip_global_slot))] CheckEpochEvaluability { current_epoch_number: u32, current_best_tip_height: u32, @@ -41,6 +49,8 @@ pub enum BlockProducerVrfEvaluatorAction { next_epoch_data: ConsensusProofOfStakeDataEpochDataNextValueVersionedValueStableV1, transition_frontier_size: u32, }, + /// Initalize epoch vrf evaluation. + #[action_event(level = info, fields(current_epoch_number, current_best_tip_slot, current_best_tip_global_slot))] InitializeEpochEvaluation { current_epoch_number: u32, current_best_tip_slot: u32, @@ -51,6 +61,8 @@ pub enum BlockProducerVrfEvaluatorAction { producer: AccountPublicKey, transition_frontier_size: u32, }, + /// Constructing delegator table. + #[action_event(level = info, fields(current_epoch_number, current_best_tip_slot, current_best_tip_global_slot))] BeginDelegatorTableConstruction { staking_epoch_data: EpochData, producer: AccountPublicKey, @@ -61,6 +73,8 @@ pub enum BlockProducerVrfEvaluatorAction { next_epoch_first_slot: u32, transition_frontier_size: u32, }, + /// Delegator table constructed. + #[action_event(level = info, fields(current_epoch_number, current_best_tip_slot, current_best_tip_global_slot))] FinalizeDelegatorTableConstruction { staking_epoch_data: EpochData, producer: AccountPublicKey, @@ -71,6 +85,8 @@ pub enum BlockProducerVrfEvaluatorAction { next_epoch_first_slot: u32, transition_frontier_size: u32, }, + /// Selecting starting slot. + #[action_event(level = info, fields(current_global_slot, current_best_tip_height))] SelectInitialSlot { current_global_slot: u32, current_best_tip_height: u32, @@ -80,6 +96,8 @@ pub enum BlockProducerVrfEvaluatorAction { staking_epoch_data: EpochData, next_epoch_first_slot: u32, }, + /// Starting epoch evaluation. + #[action_event(level = info, fields(current_epoch_number, current_best_tip_slot, current_best_tip_global_slot))] BeginEpochEvaluation { current_best_tip_height: u32, current_best_tip_slot: u32, @@ -88,18 +106,25 @@ pub enum BlockProducerVrfEvaluatorAction { staking_epoch_data: EpochData, latest_evaluated_global_slot: u32, }, + /// Saving last block height in epoch. + #[action_event(level = info, fields(epoch_number, last_block_height))] RecordLastBlockHeightInEpoch { epoch_number: u32, last_block_height: u32, }, + #[action_event(level = trace)] ContinueEpochEvaluation { latest_evaluated_global_slot: u32, epoch_number: u32, }, + /// Epoch evaluation finished. + #[action_event(level = info, fields(epoch_number, latest_evaluated_global_slot))] FinishEpochEvaluation { epoch_number: u32, latest_evaluated_global_slot: u32, }, + /// Waiting for epoch to evaluate. + #[action_event(level = info, fields(current_epoch_number, current_best_tip_height))] WaitForNextEvaluation { current_epoch_number: u32, current_best_tip_height: u32, @@ -108,13 +133,15 @@ pub enum BlockProducerVrfEvaluatorAction { last_epoch_block_height: Option, transition_frontier_size: u32, }, + /// Checking epoch bounds. + #[action_event(level = trace)] CheckEpochBounds { epoch_number: u32, latest_evaluated_global_slot: u32, }, - CleanupOldSlots { - current_epoch_number: u32, - }, + /// Cleaning up old won slots. + #[action_event(level = trace)] + CleanupOldSlots { current_epoch_number: u32 }, } impl redux::EnablingCondition for BlockProducerVrfEvaluatorAction { @@ -217,3 +244,24 @@ impl From for crate::Action { Self::BlockProducer(crate::BlockProducerAction::VrfEvaluator(value)) } } + +fn log_vrf_output(context: &T, vrf_output: &VrfEvaluationOutput) +where + T: openmina_core::log::EventContext, +{ + match vrf_output { + VrfEvaluationOutput::SlotWon(VrfWonSlot { + global_slot, + vrf_output, + .. + }) => action_info!( + context, + summary = "Slot evaluation result - won slot", + global_slot, + vrf_output = display(vrf_output) + ), + VrfEvaluationOutput::SlotLost(_) => { + action_info!(context, summary = "Slot evaluation result - lost slot") + } + } +} diff --git a/node/src/external_snark_worker/external_snark_worker_actions.rs b/node/src/external_snark_worker/external_snark_worker_actions.rs index cca543aa5a..776b231e41 100644 --- a/node/src/external_snark_worker/external_snark_worker_actions.rs +++ b/node/src/external_snark_worker/external_snark_worker_actions.rs @@ -1,6 +1,6 @@ use std::time::Duration; -use openmina_core::snark::SnarkJobId; +use openmina_core::{snark::SnarkJobId, ActionEvent}; use redux::{EnablingCondition, Timestamp}; use serde::{Deserialize, Serialize}; @@ -11,7 +11,8 @@ use super::{ SnarkWorkResult, }; -#[derive(Debug, Clone, Serialize, Deserialize)] +#[derive(Debug, Clone, Serialize, Deserialize, ActionEvent)] +#[action_event(fields(display(job_id), display(error)))] pub enum ExternalSnarkWorkerAction { Start, Started, diff --git a/node/src/logger/logger_effects.rs b/node/src/logger/logger_effects.rs index 15d93b5109..03a158c9ce 100644 --- a/node/src/logger/logger_effects.rs +++ b/node/src/logger/logger_effects.rs @@ -1,1448 +1,89 @@ -use p2p::P2pNetworkConnectionCloseReason; +use openmina_core::log::inner::field::{display, DisplayValue}; +use openmina_core::log::inner::Value; +use openmina_core::log::{time_to_str, ActionEvent, EventContext}; +use p2p::PeerId; -use crate::block_producer::vrf_evaluator::BlockProducerVrfEvaluatorAction; -use crate::p2p::channels::best_tip::P2pChannelsBestTipAction; -use crate::p2p::channels::rpc::P2pChannelsRpcAction; -use crate::p2p::channels::snark::P2pChannelsSnarkAction; -use crate::p2p::channels::snark_job_commitment::P2pChannelsSnarkJobCommitmentAction; use crate::p2p::channels::P2pChannelsAction; -use crate::p2p::connection::incoming::P2pConnectionIncomingAction; -use crate::p2p::connection::outgoing::P2pConnectionOutgoingAction; use crate::p2p::connection::P2pConnectionAction; -use crate::p2p::disconnection::P2pDisconnectionAction; -use crate::p2p::discovery::P2pDiscoveryAction; -use crate::p2p::network::{ - noise::P2pNetworkNoiseAction, pnet::P2pNetworkPnetAction, rpc::P2pNetworkRpcAction, - scheduler::P2pNetworkSchedulerAction, select::P2pNetworkSelectAction, - yamux::P2pNetworkYamuxAction, P2pNetworkAction, SelectKind, -}; +use crate::p2p::network::P2pNetworkAction; use crate::p2p::P2pAction; -use crate::snark::work_verify::SnarkWorkVerifyAction; use crate::snark::SnarkAction; -use crate::transition_frontier::genesis::TransitionFrontierGenesisAction; -use crate::transition_frontier::sync::TransitionFrontierSyncAction; -use crate::transition_frontier::TransitionFrontierAction; -use crate::{Action, ActionWithMetaRef, BlockProducerAction, Service, Store}; +use crate::{Action, ActionKind, ActionWithMetaRef, Service, Store}; + +struct ActionLoggerContext { + time: redux::Timestamp, + time_str: String, + node_id: DisplayValue, + kind: DisplayValue, +} + +impl ActionLoggerContext { + fn new(time: redux::Timestamp, node_id: PeerId, kind: ActionKind) -> Self { + ActionLoggerContext { + time, + time_str: time_to_str(time), + node_id: display(node_id), + kind: display(kind), + } + } +} + +impl EventContext for ActionLoggerContext { + fn timestamp(&self) -> redux::Timestamp { + self.time + } + + fn time(&self) -> &'_ dyn Value { + &self.time_str + } + + fn node_id(&self) -> &'_ dyn Value { + &self.node_id + } + + fn kind(&self) -> &'_ dyn Value { + &self.kind + } +} pub fn logger_effects(store: &Store, action: ActionWithMetaRef<'_>) { let (action, meta) = action.split(); - let kind = action.kind(); - - let node_id = store.state().p2p.my_id().to_string(); - // let _guard = openmina_core::log::create_span(&peer_id).entered(); + let context = ActionLoggerContext::new(meta.time(), store.state().p2p.my_id(), action.kind()); match action { Action::P2p(action) => match action { - P2pAction::Listen(action) => match action { - p2p::listen::P2pListenAction::New { listener_id, addr } => { - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("addr: {addr}"), - addr = addr.to_string(), - listener_id = listener_id.to_string(), - ); - } - p2p::listen::P2pListenAction::Expired { listener_id, addr } => { - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("addr: {addr}"), - addr = addr.to_string(), - listener_id = listener_id.to_string(), - ); - } - p2p::listen::P2pListenAction::Error { listener_id, error } => { - openmina_core::log::warn!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("id: {listener_id}, error: {error}"), - error = error, - listener_id = listener_id.to_string(), - ); - } - p2p::listen::P2pListenAction::Closed { listener_id, error } => { - if let Some(error) = error { - openmina_core::log::warn!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("id: {listener_id}, error: {error}"), - error = error, - listener_id = listener_id.to_string(), - ); - } else { - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("id: {listener_id},"), - listener_id = listener_id.to_string(), - ); - } - } - }, + P2pAction::Listen(action) => action.action_event(&context), P2pAction::Connection(action) => match action { - P2pConnectionAction::Outgoing(action) => match action { - P2pConnectionOutgoingAction::RandomInit => {} - P2pConnectionOutgoingAction::Init { opts, .. } => { - let peer_id = opts.peer_id(); - openmina_core::log::info!( - meta.time(); - kind = kind.to_string(), - summary = format!("peer_id: {peer_id}"), - peer_id = peer_id.to_string(), - transport = opts.kind(), - ); - } - P2pConnectionOutgoingAction::Reconnect { opts, .. } => { - let peer_id = opts.peer_id(); - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("peer_id: {peer_id}"), - peer_id = peer_id.to_string(), - transport = opts.kind(), - ); - } - P2pConnectionOutgoingAction::OfferSdpCreatePending { .. } => {} - P2pConnectionOutgoingAction::OfferSdpCreateError { peer_id, error } => { - openmina_core::log::warn!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("peer_id: {peer_id}"), - peer_id = peer_id.to_string(), - error = error.clone(), - ); - } - P2pConnectionOutgoingAction::OfferSdpCreateSuccess { peer_id, sdp } => { - openmina_core::log::debug!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("peer_id: {peer_id}"), - peer_id = peer_id.to_string(), - sdp = sdp.clone(), - ); - } - P2pConnectionOutgoingAction::OfferReady { peer_id, offer } => { - openmina_core::log::debug!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("peer_id: {peer_id}"), - peer_id = peer_id.to_string(), - offer = serde_json::to_string(offer).ok() - ); - } - P2pConnectionOutgoingAction::OfferSendSuccess { peer_id } => { - openmina_core::log::debug!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("peer_id: {peer_id}"), - peer_id = peer_id.to_string(), - ); - } - P2pConnectionOutgoingAction::AnswerRecvPending { .. } => {} - P2pConnectionOutgoingAction::AnswerRecvError { peer_id, error } => { - openmina_core::log::warn!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("peer_id: {peer_id}"), - peer_id = peer_id.to_string(), - error = format!("{:?}", error), - ); - } - P2pConnectionOutgoingAction::AnswerRecvSuccess { peer_id, answer } => { - openmina_core::log::debug!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("peer_id: {peer_id}"), - peer_id = peer_id.to_string(), - trace_answer = serde_json::to_string(answer).ok() - ); - } - P2pConnectionOutgoingAction::FinalizePending { .. } => {} - P2pConnectionOutgoingAction::FinalizeError { peer_id, error } => { - openmina_core::log::warn!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("peer_id: {peer_id}"), - peer_id = peer_id.to_string(), - error = error.clone(), - ); - } - P2pConnectionOutgoingAction::FinalizeSuccess { peer_id } => { - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("peer_id: {peer_id}"), - peer_id = peer_id.to_string() - ); - } - P2pConnectionOutgoingAction::Timeout { peer_id } => { - openmina_core::log::warn!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("peer_id: {peer_id}"), - peer_id = peer_id.to_string() - ); - } - P2pConnectionOutgoingAction::Error { peer_id, error } => { - openmina_core::log::warn!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("peer_id: {peer_id}"), - peer_id = peer_id.to_string(), - error = format!("{:?}", error), - ); - } - P2pConnectionOutgoingAction::Success { peer_id } => { - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("peer_id: {peer_id}"), - peer_id = peer_id.to_string() - ); - } - }, - P2pConnectionAction::Incoming(action) => match action { - P2pConnectionIncomingAction::Init { opts, .. } => { - let peer_id = opts.peer_id; - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("peer_id: {peer_id}"), - peer_id = peer_id.to_string(), - trace_signaling = format!("{:?}", opts.signaling), - ); - } - P2pConnectionIncomingAction::AnswerSdpCreatePending { .. } => {} - P2pConnectionIncomingAction::AnswerSdpCreateError { peer_id, error } => { - openmina_core::log::warn!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("peer_id: {peer_id}"), - peer_id = peer_id.to_string(), - error = format!("{:?}", error), - ); - } - P2pConnectionIncomingAction::AnswerSdpCreateSuccess { peer_id, sdp } => { - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("peer_id: {peer_id}"), - peer_id = peer_id.to_string(), - trace_sdp = sdp.clone(), - ); - } - P2pConnectionIncomingAction::AnswerReady { peer_id, answer } => { - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("peer_id: {peer_id}"), - peer_id = peer_id.to_string(), - trace_answer = serde_json::to_string(answer).ok() - ); - } - P2pConnectionIncomingAction::AnswerSendSuccess { peer_id } => { - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("peer_id: {peer_id}"), - peer_id = peer_id.to_string(), - ); - } - P2pConnectionIncomingAction::FinalizePending { .. } => {} - P2pConnectionIncomingAction::FinalizeError { peer_id, error } => { - openmina_core::log::warn!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("peer_id: {peer_id}"), - peer_id = peer_id.to_string(), - error = format!("{:?}", error), - ); - } - P2pConnectionIncomingAction::FinalizeSuccess { peer_id } => { - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("peer_id: {peer_id}"), - peer_id = peer_id.to_string(), - ); - } - P2pConnectionIncomingAction::Timeout { peer_id } => { - openmina_core::log::warn!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("peer_id: {peer_id}"), - peer_id = peer_id.to_string(), - ); - } - P2pConnectionIncomingAction::Error { peer_id, error } => { - openmina_core::log::warn!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("peer_id: {peer_id}"), - peer_id = peer_id.to_string(), - error = format!("{:?}", error), - ); - } - P2pConnectionIncomingAction::Success { peer_id } => { - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("peer_id: {peer_id}"), - peer_id = peer_id.to_string(), - ); - } - P2pConnectionIncomingAction::Libp2pReceived { peer_id } => { - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("peer_id: {peer_id}"), - peer_id = peer_id.to_string(), - ); - } - }, - }, - P2pAction::Disconnection(action) => match action { - P2pDisconnectionAction::Init { peer_id, reason } => { - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("peer_id: {peer_id}"), - peer_id = peer_id.to_string(), - reason = format!("{:?}", reason) - ); - } - P2pDisconnectionAction::Finish { peer_id } => { - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("peer_id: {peer_id}"), - peer_id = peer_id.to_string() - ); - } - }, - P2pAction::Discovery(action) => match action { - P2pDiscoveryAction::Init { peer_id } => { - openmina_core::log::debug!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("peer_id: {peer_id}"), - peer_id = peer_id.to_string() - ); - } - P2pDiscoveryAction::Success { peer_id, .. } => { - openmina_core::log::debug!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("peer_id: {peer_id}"), - peer_id = peer_id.to_string() - ); - } - P2pDiscoveryAction::KademliaBootstrap => { - openmina_core::log::debug!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("bootstrap kademlia"), - ); - } - P2pDiscoveryAction::KademliaInit => { - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("find node"), - ); - } - P2pDiscoveryAction::KademliaAddRoute { peer_id, addresses } => { - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("add route {peer_id} {:?}", addresses.first()), - ); - } - P2pDiscoveryAction::KademliaSuccess { peers } => { - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("peers: {:?}", peers), - ); - } - P2pDiscoveryAction::KademliaFailure { description } => { - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("{:?}", description), - ); - } + P2pConnectionAction::Outgoing(action) => action.action_event(&context), + P2pConnectionAction::Incoming(action) => action.action_event(&context), }, + P2pAction::Disconnection(action) => action.action_event(&context), + P2pAction::Discovery(action) => action.action_event(&context), P2pAction::Channels(action) => match action { - P2pChannelsAction::MessageReceived(_) => {} - P2pChannelsAction::BestTip(action) => match action { - P2pChannelsBestTipAction::Init { peer_id } => { - openmina_core::log::debug!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("peer_id: {peer_id}"), - peer_id = peer_id.to_string() - ); - } - P2pChannelsBestTipAction::Ready { peer_id } => { - openmina_core::log::debug!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("peer_id: {peer_id}"), - peer_id = peer_id.to_string() - ); - } - _ => {} - }, - P2pChannelsAction::Snark(action) => match action { - P2pChannelsSnarkAction::Init { peer_id } => { - openmina_core::log::debug!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("peer_id: {peer_id}"), - peer_id = peer_id.to_string() - ); - } - P2pChannelsSnarkAction::Ready { peer_id } => { - openmina_core::log::debug!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("peer_id: {peer_id}"), - peer_id = peer_id.to_string() - ); - } - _ => {} - }, - P2pChannelsAction::SnarkJobCommitment(action) => match action { - P2pChannelsSnarkJobCommitmentAction::Init { peer_id } => { - openmina_core::log::debug!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("peer_id: {}", peer_id), - peer_id = peer_id.to_string() - ); - } - P2pChannelsSnarkJobCommitmentAction::Ready { peer_id } => { - openmina_core::log::debug!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("peer_id: {}", peer_id), - peer_id = peer_id.to_string() - ); - } - _ => {} - }, - P2pChannelsAction::Rpc(action) => match action { - P2pChannelsRpcAction::Init { peer_id } => { - openmina_core::log::debug!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("peer_id: {peer_id}"), - peer_id = peer_id.to_string() - ); - } - P2pChannelsRpcAction::Ready { peer_id } => { - openmina_core::log::debug!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("peer_id: {peer_id}"), - peer_id = peer_id.to_string() - ); - } - P2pChannelsRpcAction::RequestSend { - peer_id, - id, - request, - } => { - openmina_core::log::debug!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("peer_id: {peer_id}, rpc_id: {id}, kind: {:?}", request.kind()), - peer_id = peer_id.to_string(), - rpc_id = id.to_string(), - trace_request = serde_json::to_string(request).ok() - ); - } - P2pChannelsRpcAction::ResponseReceived { - peer_id, - id, - response, - } => { - openmina_core::log::debug!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("peer_id: {peer_id}, rpc_id: {id}"), - peer_id = peer_id.to_string(), - rpc_id = id.to_string(), - trace_response = serde_json::to_string(response).ok() - ); - } - _ => {} - }, + P2pChannelsAction::MessageReceived(action) => action.action_event(&context), + P2pChannelsAction::BestTip(action) => action.action_event(&context), + P2pChannelsAction::Snark(action) => action.action_event(&context), + P2pChannelsAction::SnarkJobCommitment(action) => action.action_event(&context), + P2pChannelsAction::Rpc(action) => action.action_event(&context), }, - P2pAction::Peer(_) => {} - // TODO: + P2pAction::Peer(action) => action.action_event(&context), P2pAction::Network(action) => match action { - P2pNetworkAction::Scheduler(action) => match action { - P2pNetworkSchedulerAction::InterfaceDetected { ip } => { - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("ip: {}", ip), - ); - } - P2pNetworkSchedulerAction::InterfaceExpired { ip } => { - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("ip: {}", ip), - ); - } - P2pNetworkSchedulerAction::IncomingDidAccept { addr, result } => match result { - Ok(()) => openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - addr = addr.as_ref().unwrap().to_string(), - ), - Err(err) => openmina_core::log::error!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - err = err, - ), - }, - P2pNetworkSchedulerAction::OutgoingDidConnect { addr, result } => { - match result { - Ok(()) => openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - addr = addr.to_string(), - ), - Err(err) => openmina_core::log::warn!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - err = err, - ), - } - } - P2pNetworkSchedulerAction::SelectDone { - addr, - kind: select_kind, - protocol, - incoming, - } if protocol.is_some() => match select_kind { - SelectKind::Authentication => { - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("authentication on addr: {}", addr), - negotiated = format!("{:?}", protocol), - incoming = incoming, - ) - } - SelectKind::MultiplexingNoPeerId => { - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("multiplexing on addr: {}", addr), - negotiated = format!("{:?}", protocol), - incoming = incoming, - ) - } - SelectKind::Multiplexing(peer_id) => { - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("multiplexing on addr: {}", addr), - peer_id = peer_id.to_string(), - negotiated = format!("{:?}", protocol), - incoming = incoming, - ) - } - SelectKind::Stream(peer_id, stream_id) => { - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("stream on addr: {}", addr), - peer_id = peer_id.to_string(), - stream_id = stream_id, - negotiated = format!("{:?}", protocol), - incoming = incoming, - ) - } - }, - P2pNetworkSchedulerAction::SelectError { - addr, - kind: select_kind, - error, - } => match select_kind { - SelectKind::Authentication => { - openmina_core::log::warn!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - error = error, - summary = format!("failed select authentication on addr {}: {}", addr, error), - ) - } - SelectKind::MultiplexingNoPeerId => { - openmina_core::log::warn!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - error = error, - summary = format!("failed select multiplexing on addr {}: {}", addr, error), - ) - } - SelectKind::Multiplexing(peer_id) => { - openmina_core::log::warn!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - error = error, - summary = format!("failed select multiplexing on addr {}: {}", addr, error), - peer_id = peer_id.to_string(), - ) - } - SelectKind::Stream(peer_id, stream_id) => { - openmina_core::log::warn!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - error = error, - summary = format!("failed select stream on addr {}: {}", addr, error), - peer_id = peer_id.to_string(), - stream_id = stream_id, - ) - } - }, - P2pNetworkSchedulerAction::Disconnect { addr, reason } => { - openmina_core::log::warn!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("disconnecting peer {addr}: {reason}"), - addr = openmina_core::log::inner::field::display(addr), - reason = openmina_core::log::inner::field::display(reason), - ) - } - P2pNetworkSchedulerAction::Error { addr, error } => { - openmina_core::log::warn!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("disconnecting peer {addr}: {error}"), - addr = openmina_core::log::inner::field::display(addr), - error = openmina_core::log::inner::field::display(error), - ) - } - P2pNetworkSchedulerAction::Disconnected { addr, reason } => match reason { - P2pNetworkConnectionCloseReason::Disconnect(reason) => { - openmina_core::log::warn!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("disconnected peer {addr}: {reason}"), - addr = openmina_core::log::inner::field::display(addr), - reason = openmina_core::log::inner::field::display(reason), - ) - } - P2pNetworkConnectionCloseReason::Error(error) => { - openmina_core::log::warn!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("disconnected peer {addr}: {error}"), - addr = openmina_core::log::inner::field::display(addr), - error = openmina_core::log::inner::field::display(error), - ) - } - }, - _ => {} - }, - P2pNetworkAction::Pnet(action) => match action { - P2pNetworkPnetAction::SetupNonce { addr, incoming, .. } => { - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - addr = addr.to_string(), - incoming = incoming, - ) - } - _ => {} - }, - P2pNetworkAction::Select(action) => match action { - P2pNetworkSelectAction::Init { - addr, - kind: select_kind, - incoming, - .. - } => match select_kind { - SelectKind::Authentication => { - openmina_core::log::debug!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("authentication on addr: {}", addr), - incoming = incoming, - ) - } - SelectKind::MultiplexingNoPeerId => { - openmina_core::log::debug!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("multiplexing on addr: {}", addr), - incoming = incoming, - ) - } - SelectKind::Multiplexing(peer_id) => { - openmina_core::log::debug!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("multiplexing on addr: {}", addr), - peer_id = peer_id.to_string(), - incoming = incoming, - ) - } - SelectKind::Stream(peer_id, stream_id) => { - openmina_core::log::debug!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("stream on addr: {}", addr), - peer_id = peer_id.to_string(), - stream_id = stream_id, - incoming = incoming, - ) - } - }, - P2pNetworkSelectAction::IncomingToken { - addr, - kind: stream_kind, - token, - } => match stream_kind { - SelectKind::Authentication => { - openmina_core::log::debug!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("authentication on addr: {}", addr), - token = format!("{:?}", token), - ) - } - SelectKind::MultiplexingNoPeerId => { - openmina_core::log::debug!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("multiplexing on addr: {}", addr), - token = format!("{:?}", token), - ) - } - SelectKind::Multiplexing(peer_id) => { - openmina_core::log::debug!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("multiplexing on addr: {}", addr), - peer_id = peer_id.to_string(), - token = format!("{:?}", token), - ) - } - SelectKind::Stream(peer_id, stream_id) => { - openmina_core::log::debug!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("stream on addr: {}", addr), - peer_id = peer_id.to_string(), - stream_id = stream_id, - token = format!("{:?}", token), - ) - } - }, - P2pNetworkSelectAction::OutgoingTokens { - addr, - kind: select_kind, - tokens, - } => match select_kind { - SelectKind::Authentication => { - openmina_core::log::debug!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("authentication on addr: {}", addr), - tokens = format!("{:?}", tokens), - ) - } - SelectKind::MultiplexingNoPeerId => { - openmina_core::log::debug!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("multiplexing on addr: {}", addr), - tokens = format!("{:?}", tokens), - ) - } - SelectKind::Multiplexing(peer_id) => { - openmina_core::log::debug!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("multiplexing on addr: {}", addr), - peer_id = peer_id.to_string(), - tokens = format!("{:?}", tokens), - ) - } - SelectKind::Stream(peer_id, stream_id) => { - openmina_core::log::debug!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("stream on addr: {}", addr), - peer_id = peer_id.to_string(), - stream_id = stream_id, - tokens = format!("{:?}", tokens), - ) - } - }, - _ => {} - }, - P2pNetworkAction::Noise(action) => match action { - P2pNetworkNoiseAction::Init { addr, incoming, .. } => { - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - addr = addr.to_string(), - incoming = incoming, - ) - } - P2pNetworkNoiseAction::HandshakeDone { - addr, - peer_id, - incoming, - } => { - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - addr = addr.to_string(), - incoming = incoming, - peer_id = peer_id.to_string(), - ) - } - P2pNetworkNoiseAction::IncomingChunk { addr, data } => { - openmina_core::log::debug!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - addr = addr.to_string(), - data = format!("{:?}", data), - ) - } - P2pNetworkNoiseAction::OutgoingChunk { addr, data } => { - openmina_core::log::debug!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - addr = addr.to_string(), - data = format!("{:?}", data), - ) - } - P2pNetworkNoiseAction::DecryptedData { addr, data, .. } => { - openmina_core::log::debug!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - addr = addr.to_string(), - data = format!("{:?}", data), - ) - } - _ => {} - }, - P2pNetworkAction::Yamux(action) => match action { - P2pNetworkYamuxAction::IncomingData { addr, data } => { - openmina_core::log::debug!( - meta.time(); - kind = kind.to_string(), - addr = addr.to_string(), - data = format!("{:?}", data), - ) - } - P2pNetworkYamuxAction::IncomingFrame { addr, frame } => { - openmina_core::log::debug!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - addr = addr.to_string(), - frame = format!("{:?}", frame), - ) - } - P2pNetworkYamuxAction::OutgoingFrame { addr, frame } => { - openmina_core::log::debug!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - addr = addr.to_string(), - frame = format!("{:?}", frame), - ) - } - _ => {} - }, - P2pNetworkAction::Rpc(action) => match action { - P2pNetworkRpcAction::Init { - addr, - peer_id, - stream_id, - incoming, - } => { - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - addr = addr.to_string(), - peer_id = peer_id.to_string(), - stream_id = stream_id, - incoming = incoming, - ) - } - P2pNetworkRpcAction::IncomingMessage { - addr, - peer_id, - stream_id, - message, - } => { - let msg = match &message { - p2p::RpcMessage::Handshake => "handshake".to_owned(), - p2p::RpcMessage::Heartbeat => "heartbeat".to_owned(), - p2p::RpcMessage::Query { header, .. } => format!("{header:?}"), - p2p::RpcMessage::Response { header, .. } => format!("{header:?}"), - }; - openmina_core::log::debug!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - addr = addr.to_string(), - peer_id = peer_id.to_string(), - stream_id = stream_id, - msg = msg, - ) - } - _ => {} - }, - P2pNetworkAction::Kad(_) => {} + P2pNetworkAction::Scheduler(action) => action.action_event(&context), + P2pNetworkAction::Pnet(action) => action.action_event(&context), + P2pNetworkAction::Select(action) => action.action_event(&context), + P2pNetworkAction::Noise(action) => action.action_event(&context), + P2pNetworkAction::Yamux(action) => action.action_event(&context), + P2pNetworkAction::Rpc(action) => action.action_event(&context), + P2pNetworkAction::Kad(action) => action.action_event(&context), }, }, - Action::ExternalSnarkWorker(a) => { - use crate::external_snark_worker::ExternalSnarkWorkerAction; - match a { - ExternalSnarkWorkerAction::Start - | ExternalSnarkWorkerAction::Started - | ExternalSnarkWorkerAction::Kill - | ExternalSnarkWorkerAction::Killed - | ExternalSnarkWorkerAction::WorkCancelled - | ExternalSnarkWorkerAction::PruneWork => { - openmina_core::log::debug!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - trace_action = serde_json::to_string(&a).ok() - ) - } - ExternalSnarkWorkerAction::SubmitWork { job_id, .. } => { - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - work_id = job_id.to_string(), - ) - } - ExternalSnarkWorkerAction::WorkResult { .. } => { - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - ) - } - ExternalSnarkWorkerAction::CancelWork => { - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - ) - } - ExternalSnarkWorkerAction::WorkError { error, .. } => { - openmina_core::log::warn!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - error = error.to_string(), - ) - } - ExternalSnarkWorkerAction::Error { error, .. } => { - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - error = error.to_string(), - ) - } - ExternalSnarkWorkerAction::StartTimeout { .. } => { - openmina_core::log::warn!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - ) - } - ExternalSnarkWorkerAction::WorkTimeout { .. } => { - openmina_core::log::warn!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - ) - } - } - } + Action::ExternalSnarkWorker(action) => action.action_event(&context), Action::Snark(a) => match a { - SnarkAction::WorkVerify(a) => match a { - SnarkWorkVerifyAction::Init { - req_id, - batch, - sender, - } => { - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("id: {}, batch size: {}", req_id, batch.len()), - peer_id = sender, - rpc_id = req_id.to_string(), - trace_batch = serde_json::to_string(&batch.iter().map(|v| v.job_id()).collect::>()).ok() - ); - } - SnarkWorkVerifyAction::Error { req_id, .. } => { - let Some(req) = store.state().snark.work_verify.jobs.get(*req_id) else { - return; - }; - openmina_core::log::warn!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("id: {}, batch size: {}", req_id, req.batch().len()), - peer_id = req.sender(), - rpc_id = req_id.to_string(), - trace_batch = serde_json::to_string(&req.batch().iter().map(|v| v.job_id()).collect::>()).ok() - ); - } - SnarkWorkVerifyAction::Success { req_id } => { - let Some(req) = store.state().snark.work_verify.jobs.get(*req_id) else { - return; - }; - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("id: {}, batch size: {}", req_id, req.batch().len()), - peer_id = req.sender(), - rpc_id = req_id.to_string(), - trace_batch = serde_json::to_string(&req.batch().iter().map(|v| v.job_id()).collect::>()).ok() - ); - } - _ => {} - }, - _ => {} - }, - Action::TransitionFrontier(a) => match a { - TransitionFrontierAction::Genesis(a) => match a { - TransitionFrontierGenesisAction::ProvePending => { - openmina_core::log::info!( - meta.time(); - kind = kind.to_string(), - summary = format!("Proving genesis block"), - ); - } - TransitionFrontierGenesisAction::ProveSuccess { .. } => { - openmina_core::log::info!( - meta.time(); - kind = kind.to_string(), - summary = format!("Genesis block proved"), - ); - } - _ => {} - }, - TransitionFrontierAction::GenesisInject => { - let Some(genesis) = store - .state() - .transition_frontier - .genesis - .block_with_real_or_dummy_proof() - else { - return; - }; - openmina_core::log::info!( - meta.time(); - kind = kind.to_string(), - summary = format!("Transition frontier reconstructed genesis ledger({}) and block({})", genesis.snarked_ledger_hash(), genesis.hash()), - genesis_block_hash = genesis.hash().to_string(), - genesis_ledger_hash = genesis.snarked_ledger_hash().to_string(), - ); - } - TransitionFrontierAction::Sync(action) => match action { - TransitionFrontierSyncAction::Init { - best_tip, - root_block, - .. - } => openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = "Transition frontier sync init".to_string(), - block_hash = best_tip.hash.to_string(), - root_block_hash = root_block.hash.to_string(), - ), - TransitionFrontierSyncAction::BestTipUpdate { - best_tip, - root_block, - .. - } => openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = "New best tip received".to_string(), - block_hash = best_tip.hash.to_string(), - root_block_hash = root_block.hash.to_string(), - ), - TransitionFrontierSyncAction::LedgerStakingPending => openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = "Staking ledger sync pending".to_string(), - ), - TransitionFrontierSyncAction::LedgerStakingSuccess => openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = "Staking ledger sync success".to_string(), - ), - TransitionFrontierSyncAction::LedgerNextEpochPending => { - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = "Next epoch ledger sync pending".to_string(), - ) - } - TransitionFrontierSyncAction::LedgerNextEpochSuccess => { - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = "Next epoch ledger sync pending".to_string(), - ) - } - TransitionFrontierSyncAction::LedgerRootPending => openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = "Transition frontier root ledger sync pending".to_string(), - ), - TransitionFrontierSyncAction::LedgerRootSuccess => openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = "Transition frontier root ledger sync success".to_string(), - ), - _other => openmina_core::log::debug!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - ), - }, - TransitionFrontierAction::Synced { .. } => openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = "Transition frontier synced".to_string(), - ), - }, - Action::BlockProducer(a) => match a { - BlockProducerAction::VrfEvaluator(a) => match a { - BlockProducerVrfEvaluatorAction::ProcessSlotEvaluationSuccess { - vrf_output, - .. - } => match vrf_output { - vrf::VrfEvaluationOutput::SlotWon(won_slot) => { - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("Slot evaluation result - won slot"), - global_slot = won_slot.global_slot, - vrf_output = won_slot.vrf_output.to_string(), - ) - } - vrf::VrfEvaluationOutput::SlotLost(_) => { - openmina_core::log::debug!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("Slot evaluation result - lost slot: {:?}", vrf_output), - ) - } - }, - BlockProducerVrfEvaluatorAction::EvaluateSlot { vrf_input } => { - openmina_core::log::debug!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("Vrf Evaluation requested: {:?}", vrf_input), - ) - } - BlockProducerVrfEvaluatorAction::CheckEpochEvaluability { - current_epoch_number, - current_best_tip_global_slot, - current_best_tip_slot, - .. - } => { - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("Checking possible Vrf evaluations"), - status = store.state().block_producer.vrf_evaluator().unwrap().status.to_string(), // TODO: keep? if yes, no unwrap - status_details = format!("{:?}", store.state().block_producer.vrf_evaluator().unwrap().status), - current_epoch = current_epoch_number, - current_best_tip_global_slot = current_best_tip_global_slot, - current_best_tip_slot = current_best_tip_slot, - ) - } - BlockProducerVrfEvaluatorAction::InitializeEpochEvaluation { - current_epoch_number, - current_best_tip_global_slot, - current_best_tip_slot, - .. - } => { - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("Constructing delegator table"), - status = store.state().block_producer.vrf_evaluator().unwrap().status.to_string(), // TODO: keep? if yes, no unwrap - current_epoch = current_epoch_number, - current_best_tip_global_slot = current_best_tip_global_slot, - current_best_tip_slot = current_best_tip_slot, - ) - } - BlockProducerVrfEvaluatorAction::BeginDelegatorTableConstruction { - current_epoch_number, - current_best_tip_global_slot, - current_best_tip_slot, - .. - } => { - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("Constructing delegator table"), - status = store.state().block_producer.vrf_evaluator().unwrap().status.to_string(), // TODO: keep? if yes, no unwrap - current_epoch = current_epoch_number, - current_best_tip_global_slot = current_best_tip_global_slot, - current_best_tip_slot = current_best_tip_slot, - ) - } - BlockProducerVrfEvaluatorAction::BeginEpochEvaluation { - current_epoch_number, - current_best_tip_global_slot, - current_best_tip_slot, - .. - } => { - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("Starting epoch evaluation"), - status = store.state().block_producer.vrf_evaluator().unwrap().status.to_string(), // TODO: keep? if yes, no unwrap - current_epoch = current_epoch_number, - current_best_tip_global_slot = current_best_tip_global_slot, - current_best_tip_slot = current_best_tip_slot, - ) - } - BlockProducerVrfEvaluatorAction::FinalizeDelegatorTableConstruction { - current_epoch_number, - current_best_tip_global_slot, - current_best_tip_slot, - .. - } => { - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("Delegator table constructed"), - status = store.state().block_producer.vrf_evaluator().unwrap().status.to_string(), // TODO: keep? if yes, no unwrap - current_epoch = current_epoch_number, - current_best_tip_global_slot = current_best_tip_global_slot, - current_best_tip_slot = current_best_tip_slot, - ) - } - BlockProducerVrfEvaluatorAction::RecordLastBlockHeightInEpoch { - epoch_number, - last_block_height, - .. - } => { - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("Saving last block height in epoch"), - status = store.state().block_producer.vrf_evaluator().unwrap().status.to_string(), // TODO: keep? if yes, no unwrap - epoch = epoch_number, - last_block_height = last_block_height, - ) - } - BlockProducerVrfEvaluatorAction::InitializeEvaluator { .. } => {} - BlockProducerVrfEvaluatorAction::FinalizeEvaluatorInitialization { .. } => { - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("Vrf evaluator initilaized"), - ) - } - BlockProducerVrfEvaluatorAction::FinishEpochEvaluation { - epoch_number, - latest_evaluated_global_slot, - } => { - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("Epoch evaluation finished"), - epoch_number = epoch_number, - latest_evaluated_global_slot = latest_evaluated_global_slot, - ) - } - BlockProducerVrfEvaluatorAction::WaitForNextEvaluation { - current_epoch_number, - current_best_tip_height, - .. - } => { - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("Waiting for epoch to evaluate"), - epoch_number = current_epoch_number, - current_best_tip_height = current_best_tip_height, - ) - } - BlockProducerVrfEvaluatorAction::SelectInitialSlot { - current_epoch_number, - current_best_tip_height, - .. - } => { - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("Selecting starting slot"), - epoch_number = current_epoch_number, - current_best_tip_height = current_best_tip_height, - ) - } - BlockProducerVrfEvaluatorAction::CheckEpochBounds { .. } => { - openmina_core::log::trace!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("Checking epoch bounds"), - status = format!("{:?}", store.state().block_producer.vrf_evaluator().unwrap().status), - ) - } - BlockProducerVrfEvaluatorAction::CleanupOldSlots { .. } => { - openmina_core::log::trace!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("Cleaning up old won slots"), - ) - } - _ => {} - }, - BlockProducerAction::BestTipUpdate { .. } => {} - BlockProducerAction::WonSlot { won_slot } => { - openmina_core::log::info!( - meta.time(); - node_id = node_id, - kind = kind.to_string(), - summary = format!("Won slot"), - slot = won_slot.global_slot.slot_number.as_u32(), - slot_time = openmina_core::log::to_rfc_3339(won_slot.slot_time).unwrap(), - current_time = openmina_core::log::to_rfc_3339(meta.time()).unwrap(), - ) - } + SnarkAction::WorkVerify(a) => a.action_event(&context), _ => {} }, + Action::TransitionFrontier(a) => a.action_event(&context), + Action::BlockProducer(a) => a.action_event(&context), _ => {} } } diff --git a/node/src/transition_frontier/genesis/transition_frontier_genesis_actions.rs b/node/src/transition_frontier/genesis/transition_frontier_genesis_actions.rs index dedba3702e..ab42b7c1e1 100644 --- a/node/src/transition_frontier/genesis/transition_frontier_genesis_actions.rs +++ b/node/src/transition_frontier/genesis/transition_frontier_genesis_actions.rs @@ -1,4 +1,5 @@ use mina_p2p_messages::v2; +use openmina_core::ActionEvent; use serde::{Deserialize, Serialize}; use super::{GenesisConfigLoaded, TransitionFrontierGenesisState}; @@ -8,7 +9,8 @@ pub type TransitionFrontierGenesisActionWithMeta = pub type TransitionFrontierGenesisActionWithMetaRef<'a> = redux::ActionWithMeta<&'a TransitionFrontierGenesisAction>; -#[derive(derive_more::From, Serialize, Deserialize, Debug, Clone)] +#[derive(derive_more::From, Serialize, Deserialize, Debug, Clone, ActionEvent)] +#[action_event(level = trace)] pub enum TransitionFrontierGenesisAction { LedgerLoadInit, LedgerLoadPending, @@ -17,7 +19,11 @@ pub enum TransitionFrontierGenesisAction { }, Produce, ProveInit, + /// Proving genesis block. + #[action_event(level = info)] ProvePending, + /// Genesis block proved. + #[action_event(level = info)] ProveSuccess { proof: Box, }, diff --git a/node/src/transition_frontier/sync/ledger/snarked/transition_frontier_sync_ledger_snarked_actions.rs b/node/src/transition_frontier/sync/ledger/snarked/transition_frontier_sync_ledger_snarked_actions.rs index 8e3ad275d1..9d2fe9ba13 100644 --- a/node/src/transition_frontier/sync/ledger/snarked/transition_frontier_sync_ledger_snarked_actions.rs +++ b/node/src/transition_frontier/sync/ledger/snarked/transition_frontier_sync_ledger_snarked_actions.rs @@ -1,4 +1,5 @@ use mina_p2p_messages::v2::{LedgerHash, MinaBaseAccountBinableArgStableV2}; +use openmina_core::ActionEvent; use serde::{Deserialize, Serialize}; use crate::ledger::{LedgerAddress, LEDGER_DEPTH}; @@ -21,7 +22,8 @@ pub type TransitionFrontierSyncLedgerSnarkedActionWithMeta = pub type TransitionFrontierSyncLedgerSnarkedActionWithMetaRef<'a> = redux::ActionWithMeta<&'a TransitionFrontierSyncLedgerSnarkedAction>; -#[derive(Serialize, Deserialize, Debug, Clone)] +#[derive(Serialize, Deserialize, Debug, Clone, ActionEvent)] +#[action_event(level = trace)] pub enum TransitionFrontierSyncLedgerSnarkedAction { Pending, PeersQuery, diff --git a/node/src/transition_frontier/sync/ledger/staged/transition_frontier_sync_ledger_staged_actions.rs b/node/src/transition_frontier/sync/ledger/staged/transition_frontier_sync_ledger_staged_actions.rs index 05b2fdc397..7d89f31a5e 100644 --- a/node/src/transition_frontier/sync/ledger/staged/transition_frontier_sync_ledger_staged_actions.rs +++ b/node/src/transition_frontier/sync/ledger/staged/transition_frontier_sync_ledger_staged_actions.rs @@ -1,6 +1,7 @@ use std::sync::Arc; use mina_p2p_messages::v2::{self, LedgerHash}; +use openmina_core::ActionEvent; use serde::{Deserialize, Serialize}; use crate::p2p::channels::rpc::{P2pRpcId, StagedLedgerAuxAndPendingCoinbases}; @@ -17,7 +18,8 @@ pub type TransitionFrontierSyncLedgerStagedActionWithMeta = pub type TransitionFrontierSyncLedgerStagedActionWithMetaRef<'a> = redux::ActionWithMeta<&'a TransitionFrontierSyncLedgerStagedAction>; -#[derive(Serialize, Deserialize, Debug, Clone)] +#[derive(Serialize, Deserialize, Debug, Clone, ActionEvent)] +#[action_event(level = trace)] pub enum TransitionFrontierSyncLedgerStagedAction { PartsFetchPending, PartsPeerFetchInit, diff --git a/node/src/transition_frontier/sync/ledger/transition_frontier_sync_ledger_actions.rs b/node/src/transition_frontier/sync/ledger/transition_frontier_sync_ledger_actions.rs index 6133232c6c..2566be57c5 100644 --- a/node/src/transition_frontier/sync/ledger/transition_frontier_sync_ledger_actions.rs +++ b/node/src/transition_frontier/sync/ledger/transition_frontier_sync_ledger_actions.rs @@ -1,3 +1,4 @@ +use openmina_core::ActionEvent; use serde::{Deserialize, Serialize}; use crate::transition_frontier::sync::TransitionFrontierSyncAction; @@ -12,7 +13,7 @@ pub type TransitionFrontierSyncLedgerActionWithMeta = pub type TransitionFrontierSyncLedgerActionWithMetaRef<'a> = redux::ActionWithMeta<&'a TransitionFrontierSyncLedgerAction>; -#[derive(derive_more::From, Serialize, Deserialize, Debug, Clone)] +#[derive(derive_more::From, Serialize, Deserialize, Debug, Clone, ActionEvent)] pub enum TransitionFrontierSyncLedgerAction { Init, Snarked(TransitionFrontierSyncLedgerSnarkedAction), diff --git a/node/src/transition_frontier/sync/transition_frontier_sync_actions.rs b/node/src/transition_frontier/sync/transition_frontier_sync_actions.rs index 6e8764dfc2..15ddd34468 100644 --- a/node/src/transition_frontier/sync/transition_frontier_sync_actions.rs +++ b/node/src/transition_frontier/sync/transition_frontier_sync_actions.rs @@ -1,6 +1,7 @@ use mina_p2p_messages::v2::StateHash; use openmina_core::block::ArcBlockWithHash; use openmina_core::consensus::consensus_take; +use openmina_core::ActionEvent; use serde::{Deserialize, Serialize}; use crate::p2p::channels::rpc::P2pRpcId; @@ -17,31 +18,42 @@ pub type TransitionFrontierSyncActionWithMeta = redux::ActionWithMeta = redux::ActionWithMeta<&'a TransitionFrontierSyncAction>; -#[derive(Serialize, Deserialize, Debug, Clone)] +#[derive(Serialize, Deserialize, Debug, Clone, ActionEvent)] pub enum TransitionFrontierSyncAction { /// Set transition frontier target to new best tip (for still unsynced frontiers) + #[action_event(level = info, fields( + block_hash = display(&best_tip.hash), + root_block_hash = display(&root_block.hash), + ))] Init { best_tip: ArcBlockWithHash, root_block: ArcBlockWithHash, blocks_inbetween: Vec, }, /// Set sync target to a new best tip (for already synced frontiers) + #[action_event(level = info)] BestTipUpdate { best_tip: ArcBlockWithHash, root_block: ArcBlockWithHash, blocks_inbetween: Vec, }, /// Staking Ledger sync is pending + #[action_event(level = info)] LedgerStakingPending, /// Staking Ledger sync was successful + #[action_event(level = info)] LedgerStakingSuccess, /// Next Epoch Ledger sync is pending + #[action_event(level = info)] LedgerNextEpochPending, /// Next Epoch Ledger sync was successful + #[action_event(level = info)] LedgerNextEpochSuccess, /// Transition frontier Root Ledger sync is pending + #[action_event(level = info)] LedgerRootPending, /// Transition frontier Root Ledger sync was successful + #[action_event(level = info)] LedgerRootSuccess, BlocksPending, BlocksPeersQuery, diff --git a/node/src/transition_frontier/transition_frontier_actions.rs b/node/src/transition_frontier/transition_frontier_actions.rs index 34bb81634b..63f466362e 100644 --- a/node/src/transition_frontier/transition_frontier_actions.rs +++ b/node/src/transition_frontier/transition_frontier_actions.rs @@ -1,6 +1,7 @@ use std::collections::BTreeSet; use mina_p2p_messages::v2::StateHash; +use openmina_core::ActionEvent; use serde::{Deserialize, Serialize}; use super::genesis::TransitionFrontierGenesisAction; @@ -10,17 +11,21 @@ pub type TransitionFrontierActionWithMeta = redux::ActionWithMeta = redux::ActionWithMeta<&'a TransitionFrontierAction>; -#[derive(derive_more::From, Serialize, Deserialize, Debug, Clone)] +#[derive(derive_more::From, Serialize, Deserialize, Debug, Clone, ActionEvent)] pub enum TransitionFrontierAction { Genesis(TransitionFrontierGenesisAction), - /// Inject genesis block into the transition frontier, unless we already - /// have a better block there. + /// Inject genesis block into the transition frontier. + /// + /// Unless we already have a better block there. /// /// If this node is block producer, we produce proof for the genesis /// block, otherwise we don't need it so we use dummy proof instead. + #[action_event(level = info)] GenesisInject, Sync(TransitionFrontierSyncAction), + /// Transition frontier synced. + #[action_event(level = info)] Synced { /// Required protocol states for root block. needed_protocol_states: BTreeSet, diff --git a/p2p/Cargo.toml b/p2p/Cargo.toml index e7b98421fc..98b441485b 100644 --- a/p2p/Cargo.toml +++ b/p2p/Cargo.toml @@ -42,6 +42,7 @@ mina-p2p-messages = { workspace = true } salsa-simple = { path = "../tools/salsa-simple" } openmina-core = { path = "../core" } +openmina-macros = { path = "../macros" } quick-protobuf = "0.8.1" crypto-bigint = { version = "0.5.5", features = ["generic-array", "serde", "alloc"] } diff --git a/p2p/src/channels/best_tip/p2p_channels_best_tip_actions.rs b/p2p/src/channels/best_tip/p2p_channels_best_tip_actions.rs index a6fa853a5a..dc13fd93b1 100644 --- a/p2p/src/channels/best_tip/p2p_channels_best_tip_actions.rs +++ b/p2p/src/channels/best_tip/p2p_channels_best_tip_actions.rs @@ -1,4 +1,4 @@ -use openmina_core::block::ArcBlockWithHash; +use openmina_core::{block::ArcBlockWithHash, ActionEvent}; use serde::{Deserialize, Serialize}; use crate::{ @@ -11,27 +11,34 @@ use super::BestTipPropagationState; pub type P2pChannelsBestTipActionWithMetaRef<'a> = redux::ActionWithMeta<&'a P2pChannelsBestTipAction>; -#[derive(Debug, Clone, Serialize, Deserialize)] +#[derive(Debug, Clone, Serialize, Deserialize, ActionEvent)] +#[action_event(fields(display(peer_id), best_tip = display(&best_tip.hash)))] pub enum P2pChannelsBestTipAction { + /// Initialize best tip channel. Init { peer_id: PeerId, }, Pending { peer_id: PeerId, }, + /// Best tip channel is ready. Ready { peer_id: PeerId, }, + /// Send best tip request. RequestSend { peer_id: PeerId, }, + /// Best tip response is received. Received { peer_id: PeerId, best_tip: ArcBlockWithHash, }, + /// Best tip request is received. RequestReceived { peer_id: PeerId, }, + /// Best tip response is sent. ResponseSend { peer_id: PeerId, best_tip: ArcBlockWithHash, diff --git a/p2p/src/channels/p2p_channels_actions.rs b/p2p/src/channels/p2p_channels_actions.rs index 7f436a7135..3f5fa5b206 100644 --- a/p2p/src/channels/p2p_channels_actions.rs +++ b/p2p/src/channels/p2p_channels_actions.rs @@ -1,3 +1,4 @@ +use openmina_core::log::ActionEvent; use serde::{Deserialize, Serialize}; use crate::{P2pState, PeerId}; @@ -50,3 +51,11 @@ impl From for crate::P2pAction { Self::Channels(P2pChannelsAction::MessageReceived(a)) } } + +impl ActionEvent for P2pChannelsMessageReceivedAction { + fn action_event(&self, _context: &T) + where + T: openmina_core::log::EventContext, + { + } +} diff --git a/p2p/src/channels/rpc/p2p_channels_rpc_actions.rs b/p2p/src/channels/rpc/p2p_channels_rpc_actions.rs index e3767aba1b..6c170d6ef8 100644 --- a/p2p/src/channels/rpc/p2p_channels_rpc_actions.rs +++ b/p2p/src/channels/rpc/p2p_channels_rpc_actions.rs @@ -1,3 +1,4 @@ +use openmina_core::ActionEvent; use redux::Timestamp; use serde::{Deserialize, Serialize}; @@ -9,7 +10,8 @@ pub type P2pChannelsRpcActionWithMetaRef<'a> = redux::ActionWithMeta<&'a P2pChan pub const MAX_P2P_RPC_REMOTE_CONCURRENT_REQUESTS: usize = 5; -#[derive(Serialize, Deserialize, Debug, Clone)] +#[derive(Serialize, Deserialize, Debug, Clone, ActionEvent)] +#[action_event(fields(display(peer_id)))] pub enum P2pChannelsRpcAction { Init { peer_id: PeerId, diff --git a/p2p/src/channels/snark/p2p_channels_snark_actions.rs b/p2p/src/channels/snark/p2p_channels_snark_actions.rs index 641f49de67..520fe085f0 100644 --- a/p2p/src/channels/snark/p2p_channels_snark_actions.rs +++ b/p2p/src/channels/snark/p2p_channels_snark_actions.rs @@ -1,12 +1,13 @@ use crate::{channels::P2pChannelsAction, P2pState, PeerId}; -use openmina_core::snark::Snark; +use openmina_core::{snark::Snark, ActionEvent}; use serde::{Deserialize, Serialize}; use super::{P2pChannelsSnarkState, SnarkInfo, SnarkPropagationState}; pub type P2pChannelsSnarkActionWithMetaRef<'a> = redux::ActionWithMeta<&'a P2pChannelsSnarkAction>; -#[derive(Serialize, Deserialize, Debug, Clone)] +#[derive(Serialize, Deserialize, Debug, Clone, ActionEvent)] +#[action_event(fields(display(peer_id)))] pub enum P2pChannelsSnarkAction { Init { peer_id: PeerId, diff --git a/p2p/src/channels/snark_job_commitment/p2p_channels_snark_job_commitment_actions.rs b/p2p/src/channels/snark_job_commitment/p2p_channels_snark_job_commitment_actions.rs index ad51f894c5..02ca96cb74 100644 --- a/p2p/src/channels/snark_job_commitment/p2p_channels_snark_job_commitment_actions.rs +++ b/p2p/src/channels/snark_job_commitment/p2p_channels_snark_job_commitment_actions.rs @@ -1,3 +1,4 @@ +use openmina_core::ActionEvent; use serde::{Deserialize, Serialize}; use crate::{P2pState, PeerId}; @@ -9,7 +10,8 @@ use super::{ pub type P2pChannelsSnarkJobCommitmentActionWithMetaRef<'a> = redux::ActionWithMeta<&'a P2pChannelsSnarkJobCommitmentAction>; -#[derive(Debug, Clone, Serialize, Deserialize)] +#[derive(Debug, Clone, Serialize, Deserialize, ActionEvent)] +#[action_event(fields(display(peer_id)))] pub enum P2pChannelsSnarkJobCommitmentAction { Init { peer_id: PeerId, diff --git a/p2p/src/connection/incoming/p2p_connection_incoming_actions.rs b/p2p/src/connection/incoming/p2p_connection_incoming_actions.rs index 198380a360..f2db4d8dbf 100644 --- a/p2p/src/connection/incoming/p2p_connection_incoming_actions.rs +++ b/p2p/src/connection/incoming/p2p_connection_incoming_actions.rs @@ -1,6 +1,6 @@ use serde::{Deserialize, Serialize}; -use openmina_core::requests::RpcId; +use openmina_core::{requests::RpcId, ActionEvent}; use crate::{webrtc, P2pAction, P2pState, PeerId}; @@ -9,12 +9,15 @@ use super::P2pConnectionIncomingInitOpts; pub type P2pConnectionIncomingActionWithMetaRef<'a> = redux::ActionWithMeta<&'a P2pConnectionIncomingAction>; -#[derive(Serialize, Deserialize, Debug, Clone)] +#[derive(Serialize, Deserialize, Debug, Clone, ActionEvent)] +#[action_event(fields(debug(opts), display(peer_id), display(error)))] pub enum P2pConnectionIncomingAction { + /// Incoming connection is initialized. Init { opts: P2pConnectionIncomingInitOpts, rpc_id: Option, }, + #[action_event(level = trace)] AnswerSdpCreatePending { peer_id: PeerId, }, @@ -33,26 +36,35 @@ pub enum P2pConnectionIncomingAction { AnswerSendSuccess { peer_id: PeerId, }, + /// Pending incoming connection finalization. + #[action_event(level = trace)] FinalizePending { peer_id: PeerId, }, + /// Error finalizing incoming connection. FinalizeError { peer_id: PeerId, error: String, }, + /// Incoming connection finalized. FinalizeSuccess { peer_id: PeerId, }, + /// Timeout establishing incoming connection. Timeout { peer_id: PeerId, }, + /// Error establishing incoming connection. Error { peer_id: PeerId, error: P2pConnectionIncomingError, }, + /// Incoming connection is succesful. + #[action_event(level = info)] Success { peer_id: PeerId, }, + /// Incoming libp2p connection is succesful. Libp2pReceived { peer_id: PeerId, }, diff --git a/p2p/src/connection/incoming/p2p_connection_incoming_state.rs b/p2p/src/connection/incoming/p2p_connection_incoming_state.rs index 14ae5c3454..52dac1f982 100644 --- a/p2p/src/connection/incoming/p2p_connection_incoming_state.rs +++ b/p2p/src/connection/incoming/p2p_connection_incoming_state.rs @@ -113,9 +113,12 @@ impl P2pConnectionIncomingState { } } -#[derive(Serialize, Deserialize, Debug, Clone)] +#[derive(Serialize, Deserialize, Debug, Clone, thiserror::Error)] pub enum P2pConnectionIncomingError { + #[error("error creating SDP: {0}")] SdpCreateError(String), + #[error("finalization error: {0}")] FinalizeError(String), + #[error("timeout error")] Timeout, } diff --git a/p2p/src/connection/mod.rs b/p2p/src/connection/mod.rs index 939ceef05a..c94c2f5462 100644 --- a/p2p/src/connection/mod.rs +++ b/p2p/src/connection/mod.rs @@ -43,9 +43,11 @@ impl RejectionReason { } } -#[derive(Serialize, Deserialize, Debug, Clone)] +#[derive(Serialize, Deserialize, Debug, Clone, thiserror::Error)] pub enum P2pConnectionErrorResponse { + #[error("connection rejected: {0}")] Rejected(RejectionReason), + #[error("internal error")] InternalError, } diff --git a/p2p/src/connection/outgoing/p2p_connection_outgoing_actions.rs b/p2p/src/connection/outgoing/p2p_connection_outgoing_actions.rs index 0525c567ba..893019b605 100644 --- a/p2p/src/connection/outgoing/p2p_connection_outgoing_actions.rs +++ b/p2p/src/connection/outgoing/p2p_connection_outgoing_actions.rs @@ -1,3 +1,4 @@ +use openmina_core::ActionEvent; use serde::{Deserialize, Serialize}; use openmina_core::requests::RpcId; @@ -10,17 +11,25 @@ use super::{P2pConnectionOutgoingError, P2pConnectionOutgoingInitOpts}; pub type P2pConnectionOutgoingActionWithMetaRef<'a> = redux::ActionWithMeta<&'a P2pConnectionOutgoingAction>; -#[derive(Serialize, Deserialize, Debug, Clone)] +#[derive(Serialize, Deserialize, Debug, Clone, ActionEvent)] +#[action_event(fields(display(opts), display(peer_id), display(error)))] pub enum P2pConnectionOutgoingAction { + /// Initialize connection to a random peer. + #[action_event(level = trace)] RandomInit, + /// Initialize connection to a new peer. + #[action_event(level = info)] Init { opts: P2pConnectionOutgoingInitOpts, rpc_id: Option, }, + /// Reconnect to an existing peer. + #[action_event(level = info)] Reconnect { opts: P2pConnectionOutgoingInitOpts, rpc_id: Option, }, + #[action_event(level = trace)] OfferSdpCreatePending { peer_id: PeerId, }, @@ -39,6 +48,7 @@ pub enum P2pConnectionOutgoingAction { OfferSendSuccess { peer_id: PeerId, }, + #[action_event(level = trace)] AnswerRecvPending { peer_id: PeerId, }, @@ -50,23 +60,31 @@ pub enum P2pConnectionOutgoingAction { peer_id: PeerId, answer: webrtc::Answer, }, + #[action_event(level = trace)] FinalizePending { peer_id: PeerId, }, + /// Error finalizing outgoing connection. FinalizeError { peer_id: PeerId, error: String, }, + /// Outgoing connection succsessfully finalized. + #[action_event(level = info)] FinalizeSuccess { peer_id: PeerId, }, + /// Timeout establishing connection to a peer. Timeout { peer_id: PeerId, }, + /// Error connecting to a peer. Error { peer_id: PeerId, error: P2pConnectionOutgoingError, }, + /// Outgoing connection is successful. + #[action_event(level = info)] Success { peer_id: PeerId, }, diff --git a/p2p/src/connection/outgoing/p2p_connection_outgoing_state.rs b/p2p/src/connection/outgoing/p2p_connection_outgoing_state.rs index 670551b5f8..a89e840e8a 100644 --- a/p2p/src/connection/outgoing/p2p_connection_outgoing_state.rs +++ b/p2p/src/connection/outgoing/p2p_connection_outgoing_state.rs @@ -119,11 +119,16 @@ impl P2pConnectionOutgoingState { } } -#[derive(Serialize, Deserialize, Debug, Clone)] +#[derive(Serialize, Deserialize, Debug, Clone, thiserror::Error)] pub enum P2pConnectionOutgoingError { + #[error("error creating SDP: {0}")] SdpCreateError(String), + #[error("rejected: {0}")] Rejected(RejectionReason), + #[error("remote internal error")] RemoteInternalError, + #[error("finalization error: {0}")] FinalizeError(String), + #[error("timeout error")] Timeout, } diff --git a/p2p/src/disconnection/p2p_disconnection_actions.rs b/p2p/src/disconnection/p2p_disconnection_actions.rs index 36f03cfe57..b941881438 100644 --- a/p2p/src/disconnection/p2p_disconnection_actions.rs +++ b/p2p/src/disconnection/p2p_disconnection_actions.rs @@ -1,3 +1,4 @@ +use openmina_core::ActionEvent; use serde::{Deserialize, Serialize}; use super::P2pDisconnectionReason; @@ -5,15 +6,16 @@ use crate::{P2pPeerStatus, P2pState, PeerId}; pub type P2pDisconnectionActionWithMetaRef<'a> = redux::ActionWithMeta<&'a P2pDisconnectionAction>; -#[derive(Serialize, Deserialize, Debug, Clone)] +#[derive(Serialize, Deserialize, Debug, Clone, ActionEvent)] +#[action_event(fields(display(peer_id), display(reason)), level = info)] pub enum P2pDisconnectionAction { + /// Initialize disconnection. Init { peer_id: PeerId, reason: P2pDisconnectionReason, }, - Finish { - peer_id: PeerId, - }, + /// Finish disconnecting from a peer. + Finish { peer_id: PeerId }, } impl redux::EnablingCondition for P2pDisconnectionAction { diff --git a/p2p/src/discovery/p2p_discovery_actions.rs b/p2p/src/discovery/p2p_discovery_actions.rs index d1841630e3..51ab8f5626 100644 --- a/p2p/src/discovery/p2p_discovery_actions.rs +++ b/p2p/src/discovery/p2p_discovery_actions.rs @@ -1,3 +1,4 @@ +use openmina_core::ActionEvent; use serde::{Deserialize, Serialize}; use crate::{connection::outgoing::P2pConnectionOutgoingInitOpts, P2pState, PeerId}; @@ -6,7 +7,8 @@ use crate::{connection::outgoing::P2pConnectionOutgoingInitOpts, P2pState, PeerI pub type P2pDiscoveryActionWithMetaRef<'a> = redux::ActionWithMeta<&'a P2pDiscoveryAction>; -#[derive(Serialize, Deserialize, Debug, Clone)] +#[derive(Serialize, Deserialize, Debug, Clone, ActionEvent)] +#[action_event(fields(display(peer_id), debug(peers), debug(addresses), description))] pub enum P2pDiscoveryAction { Init { peer_id: PeerId, diff --git a/p2p/src/listen/p2p_listen_actions.rs b/p2p/src/listen/p2p_listen_actions.rs index 43aac301d5..7fd4774b1f 100644 --- a/p2p/src/listen/p2p_listen_actions.rs +++ b/p2p/src/listen/p2p_listen_actions.rs @@ -1,3 +1,4 @@ +use openmina_core::ActionEvent; use redux::EnablingCondition; use serde::{Deserialize, Serialize}; @@ -5,7 +6,8 @@ use crate::{P2pListenerId, P2pState}; pub type P2pListenActionWithMetaRef<'a> = redux::ActionWithMeta<&'a P2pListenAction>; -#[derive(Serialize, Deserialize, Debug, Clone)] +#[derive(Serialize, Deserialize, Debug, Clone, ActionEvent)] +#[action_event(fields(display(listener_id), display(addr), error))] pub enum P2pListenAction { New { listener_id: P2pListenerId, diff --git a/p2p/src/network/kad/bootstrap/p2p_network_kad_bootstrap_actions.rs b/p2p/src/network/kad/bootstrap/p2p_network_kad_bootstrap_actions.rs index b8191b015a..9fae385fc3 100644 --- a/p2p/src/network/kad/bootstrap/p2p_network_kad_bootstrap_actions.rs +++ b/p2p/src/network/kad/bootstrap/p2p_network_kad_bootstrap_actions.rs @@ -1,19 +1,21 @@ +use openmina_core::ActionEvent; use redux::EnablingCondition; use serde::{Deserialize, Serialize}; use crate::{P2pAction, P2pNetworkKadAction, P2pNetworkKadLatestRequestPeers, P2pState, PeerId}; -#[derive(Clone, Debug, Serialize, Deserialize)] +#[derive(Clone, Debug, Serialize, Deserialize, ActionEvent)] +#[action_event(fields(display(peer_id), debug(closest_peers), error))] pub enum P2pNetworkKadBootstrapAction { + /// Create `FIND_NODE` request. CreateRequests, + /// `FIND_NODE` request successful. RequestDone { peer_id: PeerId, closest_peers: P2pNetworkKadLatestRequestPeers, }, - RequestError { - peer_id: PeerId, - error: String, - }, + /// `FIND_NODE` request failed. + RequestError { peer_id: PeerId, error: String }, } impl EnablingCondition for P2pNetworkKadBootstrapAction { diff --git a/p2p/src/network/kad/p2p_network_kad_actions.rs b/p2p/src/network/kad/p2p_network_kad_actions.rs index cf14af9ddf..d9de6c6031 100644 --- a/p2p/src/network/kad/p2p_network_kad_actions.rs +++ b/p2p/src/network/kad/p2p_network_kad_actions.rs @@ -1,5 +1,6 @@ use std::net::SocketAddr; +use openmina_core::ActionEvent; use redux::EnablingCondition; use serde::{Deserialize, Serialize}; @@ -11,7 +12,7 @@ use crate::{ use super::bootstrap::P2pNetworkKadBootstrapAction; /// Kademlia actions. -#[derive(Debug, Clone, Serialize, Deserialize, derive_more::From)] +#[derive(Debug, Clone, Serialize, Deserialize, derive_more::From, ActionEvent)] pub enum P2pNetworkKadAction { System(P2pNetworkKademliaAction), Bootstrap(P2pNetworkKadBootstrapAction), @@ -37,8 +38,17 @@ impl From for P2pAction { } /// Kademlia system actions -#[derive(Debug, Clone, Serialize, Deserialize)] +#[derive(Debug, Clone, Serialize, Deserialize, ActionEvent)] +#[action_event(fields( + display(addr), + display(peer_id), + stream_id, + display(key), + debug(closest_peers) +))] pub enum P2pNetworkKademliaAction { + /// Answer `FIND_NODE` request. + /// /// Answers peer's `FIND_NODE` request by querying routing table for closest nodes. AnswerFindNodeRequest { addr: SocketAddr, @@ -46,6 +56,8 @@ pub enum P2pNetworkKademliaAction { stream_id: StreamId, key: PeerId, }, + /// Udate result of scheduled outgoing `FIND_NODE`. + /// /// Udates result of scheduled outgoing `FIND_NODE` request to a peer. UpdateFindNodeRequest { addr: SocketAddr, @@ -53,10 +65,12 @@ pub enum P2pNetworkKademliaAction { stream_id: StreamId, closest_peers: Vec, }, - /// Performs local node's Kademlia bootstrap. + /// Perform local node's Kademlia bootstrap. + #[action_event(level = info)] StartBootstrap { key: PeerId }, /// Bootstrap is finished. - BootstrapFinished {}, + #[action_event(level = info)] + BootstrapFinished, } impl EnablingCondition for P2pNetworkKademliaAction { diff --git a/p2p/src/network/kad/request/p2p_network_kad_request_actions.rs b/p2p/src/network/kad/request/p2p_network_kad_request_actions.rs index c2dc6ccd82..c971eeab13 100644 --- a/p2p/src/network/kad/request/p2p_network_kad_request_actions.rs +++ b/p2p/src/network/kad/request/p2p_network_kad_request_actions.rs @@ -1,11 +1,13 @@ use std::net::SocketAddr; +use openmina_core::ActionEvent; use redux::EnablingCondition; use serde::{Deserialize, Serialize}; use crate::{P2pAction, P2pNetworkKadEntry, P2pState, PeerId, StreamId}; -#[derive(Clone, Debug, Serialize, Deserialize)] +#[derive(Clone, Debug, Serialize, Deserialize, ActionEvent)] +#[action_event(fields(display(peer_id), display(addr), display(key), stream_id, error))] pub enum P2pNetworkKadRequestAction { New { peer_id: PeerId, @@ -36,6 +38,7 @@ pub enum P2pNetworkKadRequestAction { stream_id: StreamId, data: Vec, }, + #[action_event(level = trace)] Prune { peer_id: PeerId, }, diff --git a/p2p/src/network/kad/request/p2p_network_kad_request_effects.rs b/p2p/src/network/kad/request/p2p_network_kad_request_effects.rs index 2a1b7cfd11..510e66f4ce 100644 --- a/p2p/src/network/kad/request/p2p_network_kad_request_effects.rs +++ b/p2p/src/network/kad/request/p2p_network_kad_request_effects.rs @@ -1,6 +1,5 @@ use std::net::SocketAddr; -use openmina_core::warn; use redux::ActionMeta; use crate::{ @@ -18,7 +17,7 @@ use crate::{ use super::{super::stream::P2pNetworkKademliaStreamAction, P2pNetworkKadRequestAction}; impl P2pNetworkKadRequestAction { - pub fn effects(self, meta: &ActionMeta, store: &mut Store) -> Result<(), String> + pub fn effects(self, _meta: &ActionMeta, store: &mut Store) -> Result<(), String> where Store: crate::P2pStore, { @@ -186,7 +185,6 @@ impl P2pNetworkKadRequestAction { store.dispatch(P2pNetworkKadRequestAction::Prune { peer_id }); } A::Error { peer_id, error } => { - warn!(meta.time(); "error requesting FIND_NODE: {error}"); let bootstrap_request = discovery_state .bootstrap_state() .and_then(|bootstrap_state| bootstrap_state.request(&peer_id)) diff --git a/p2p/src/network/kad/stream/p2p_network_kad_stream_actions.rs b/p2p/src/network/kad/stream/p2p_network_kad_stream_actions.rs index 7a2b310828..bed2cad2ca 100644 --- a/p2p/src/network/kad/stream/p2p_network_kad_stream_actions.rs +++ b/p2p/src/network/kad/stream/p2p_network_kad_stream_actions.rs @@ -1,5 +1,6 @@ use std::net::SocketAddr; +use openmina_core::ActionEvent; use redux::EnablingCondition; use serde::{Deserialize, Serialize}; @@ -9,7 +10,8 @@ use crate::{ }; /// Kademlia stream related actions. -#[derive(Debug, Clone, Serialize, Deserialize)] +#[derive(Debug, Clone, Serialize, Deserialize, ActionEvent)] +#[action_event(fields(display(addr), display(peer_id), stream_id, incoming, debug(data)))] pub enum P2pNetworkKademliaStreamAction { /// Creates a new stream state. New { @@ -75,6 +77,7 @@ pub enum P2pNetworkKademliaStreamAction { }, /// Removes the closed stream from the state. + #[action_event(level = trace)] Prune { addr: SocketAddr, peer_id: PeerId, diff --git a/p2p/src/network/noise/p2p_network_noise_actions.rs b/p2p/src/network/noise/p2p_network_noise_actions.rs index 284a67d9a7..5433913de7 100644 --- a/p2p/src/network/noise/p2p_network_noise_actions.rs +++ b/p2p/src/network/noise/p2p_network_noise_actions.rs @@ -1,12 +1,14 @@ use std::net::SocketAddr; +use openmina_core::ActionEvent; use serde::{Deserialize, Serialize}; use crate::{Data, P2pNetworkAction, P2pState, PeerId}; use super::p2p_network_noise_state::{Pk, Sk}; -#[derive(Serialize, Deserialize, Debug, Clone)] +#[derive(Serialize, Deserialize, Debug, Clone, ActionEvent)] +#[action_event(level = trace, fields(display(addr), incoming, debug(data), display(peer_id)))] pub enum P2pNetworkNoiseAction { Init { addr: SocketAddr, @@ -36,6 +38,7 @@ pub enum P2pNetworkNoiseAction { data: Data, }, // the remote peer sends the data to internals thru noise + #[action_event(fields(display(addr), debug(data), debug(peer_id)))] DecryptedData { addr: SocketAddr, peer_id: Option, diff --git a/p2p/src/network/pnet/p2p_network_pnet_actions.rs b/p2p/src/network/pnet/p2p_network_pnet_actions.rs index f2b80f0c77..213f6ea6f7 100644 --- a/p2p/src/network/pnet/p2p_network_pnet_actions.rs +++ b/p2p/src/network/pnet/p2p_network_pnet_actions.rs @@ -1,10 +1,12 @@ use std::net::SocketAddr; +use openmina_core::ActionEvent; use serde::{Deserialize, Serialize}; use crate::{Data, P2pState}; -#[derive(Serialize, Deserialize, Debug, Clone)] +#[derive(Serialize, Deserialize, Debug, Clone, ActionEvent)] +#[action_event(fields(display(addr), debug(data), incoming), level = trace)] pub enum P2pNetworkPnetAction { IncomingData { addr: SocketAddr, @@ -14,6 +16,7 @@ pub enum P2pNetworkPnetAction { addr: SocketAddr, data: Data, }, + #[action_event(level = debug)] SetupNonce { addr: SocketAddr, nonce: Data, diff --git a/p2p/src/network/rpc/p2p_network_rpc_actions.rs b/p2p/src/network/rpc/p2p_network_rpc_actions.rs index 9392462f87..e15a0ad2a6 100644 --- a/p2p/src/network/rpc/p2p_network_rpc_actions.rs +++ b/p2p/src/network/rpc/p2p_network_rpc_actions.rs @@ -1,12 +1,14 @@ use std::net::SocketAddr; use mina_p2p_messages::rpc_kernel::{QueryHeader, ResponseHeader}; +use openmina_core::{action_debug, action_trace, ActionEvent}; use serde::{Deserialize, Serialize}; use super::{super::*, *}; use crate::{P2pState, PeerId}; -#[derive(Serialize, Deserialize, Debug, Clone)] +#[derive(Serialize, Deserialize, Debug, Clone, ActionEvent)] +#[action_event(fields(display(addr), display(peer_id), incoming, stream_id, debug(data), fin))] pub enum P2pNetworkRpcAction { Init { addr: SocketAddr, @@ -14,12 +16,14 @@ pub enum P2pNetworkRpcAction { stream_id: StreamId, incoming: bool, }, + #[action_event(level = trace)] IncomingData { addr: SocketAddr, peer_id: PeerId, stream_id: StreamId, data: Data, }, + #[action_event(expr(log_message(context, message, addr, peer_id, stream_id)))] IncomingMessage { addr: SocketAddr, peer_id: PeerId, @@ -129,3 +133,46 @@ impl redux::EnablingCondition for P2pNetworkRpcAction { } } } + +fn log_message( + context: &T, + message: &RpcMessage, + addr: &SocketAddr, + peer_id: &PeerId, + stream_id: &u32, +) where + T: openmina_core::log::EventContext, +{ + match message { + RpcMessage::Handshake => action_trace!( + context, + addr = display(addr), + peer_id = display(peer_id), + stream_id, + message_kind = "handshake" + ), + RpcMessage::Heartbeat => action_trace!( + context, + addr = display(addr), + peer_id = display(peer_id), + stream_id, + message_kind = "heartbeat" + ), + RpcMessage::Query { header, .. } => action_debug!( + context, + addr = display(addr), + peer_id = display(peer_id), + stream_id, + message_kind = "query", + message_header = debug(header) + ), + RpcMessage::Response { header, .. } => action_debug!( + context, + addr = display(addr), + peer_id = display(peer_id), + stream_id, + message_kind = "response", + message_header = debug(header) + ), + } +} diff --git a/p2p/src/network/scheduler/p2p_network_scheduler_actions.rs b/p2p/src/network/scheduler/p2p_network_scheduler_actions.rs index c3fd79f828..0d718cd95f 100644 --- a/p2p/src/network/scheduler/p2p_network_scheduler_actions.rs +++ b/p2p/src/network/scheduler/p2p_network_scheduler_actions.rs @@ -1,5 +1,6 @@ use std::net::{IpAddr, SocketAddr}; +use openmina_core::ActionEvent; use serde::{Deserialize, Serialize}; use super::{ @@ -12,7 +13,8 @@ use super::{ use crate::{disconnection::P2pDisconnectionReason, P2pState, PeerId}; -#[derive(Serialize, Deserialize, Debug, Clone)] +#[derive(Serialize, Deserialize, Debug, Clone, ActionEvent)] +#[action_event(fields(display(ip), display(listener), display(addr), debug(result), select_kind = debug(kind)))] pub enum P2pNetworkSchedulerAction { InterfaceDetected { ip: IpAddr, @@ -23,6 +25,7 @@ pub enum P2pNetworkSchedulerAction { IncomingConnectionIsReady { listener: SocketAddr, }, + #[action_event(fields(debug(addr), debug(result)))] IncomingDidAccept { addr: Option, result: Result<(), String>, diff --git a/p2p/src/network/scheduler/p2p_network_scheduler_state.rs b/p2p/src/network/scheduler/p2p_network_scheduler_state.rs index 7506615209..cdaa4ebadb 100644 --- a/p2p/src/network/scheduler/p2p_network_scheduler_state.rs +++ b/p2p/src/network/scheduler/p2p_network_scheduler_state.rs @@ -55,10 +55,12 @@ impl P2pNetworkConnectionState { } } -#[derive(Serialize, Deserialize, Debug, Clone, PartialEq, Eq, derive_more::From)] +#[derive(Serialize, Deserialize, Debug, Clone, PartialEq, Eq, thiserror::Error)] pub enum P2pNetworkConnectionCloseReason { - Disconnect(P2pDisconnectionReason), - Error(P2pNetworkConnectionError), + #[error("peer is disconnected: {0}")] + Disconnect(#[from] P2pDisconnectionReason), + #[error("connection error: {0}")] + Error(#[from] P2pNetworkConnectionError), } /// P2p connection error. diff --git a/p2p/src/network/select/p2p_network_select_actions.rs b/p2p/src/network/select/p2p_network_select_actions.rs index c8cb524e2a..7a672280f5 100644 --- a/p2p/src/network/select/p2p_network_select_actions.rs +++ b/p2p/src/network/select/p2p_network_select_actions.rs @@ -1,13 +1,17 @@ use std::net::SocketAddr; +use openmina_core::ActionEvent; use serde::{Deserialize, Serialize}; use crate::{Data, P2pState, PeerId}; use super::{super::*, *}; -#[derive(derive_more::From, Serialize, Deserialize, Debug, Clone)] +#[derive(derive_more::From, Serialize, Deserialize, Debug, Clone, ActionEvent)] +#[action_event(fields(display(addr), select_kind = debug(kind), debug(data), send_handshake, fin, debug(token), debug(tokens)))] pub enum P2pNetworkSelectAction { + /// Initialize protocol selection. + /// /// Multistream Select protocol is running multiple times: /// When Pnet protocol is done for newly established TCP connection. We don't have `peer_id` yet. /// When Noise protocol is done and we have a `peer_id`. @@ -18,6 +22,7 @@ pub enum P2pNetworkSelectAction { incoming: bool, send_handshake: bool, }, + #[action_event(level = trace)] IncomingData { addr: SocketAddr, kind: SelectKind, diff --git a/p2p/src/network/yamux/p2p_network_yamux_actions.rs b/p2p/src/network/yamux/p2p_network_yamux_actions.rs index 1ed9027489..0a1dc68642 100644 --- a/p2p/src/network/yamux/p2p_network_yamux_actions.rs +++ b/p2p/src/network/yamux/p2p_network_yamux_actions.rs @@ -1,11 +1,13 @@ use std::net::SocketAddr; +use openmina_core::ActionEvent; use serde::{Deserialize, Serialize}; use super::p2p_network_yamux_state::{StreamId, YamuxFrame, YamuxPing}; use crate::{token, Data, P2pState}; -#[derive(Serialize, Deserialize, Debug, Clone)] +#[derive(Serialize, Deserialize, Debug, Clone, ActionEvent)] +#[action_event(fields(display(addr), stream_id, debug(data), fin, debug(stream_kind)))] pub enum P2pNetworkYamuxAction { IncomingData { addr: SocketAddr, @@ -17,10 +19,12 @@ pub enum P2pNetworkYamuxAction { data: Data, fin: bool, }, + #[action_event(level = trace)] IncomingFrame { addr: SocketAddr, frame: YamuxFrame, }, + #[action_event(level = trace)] OutgoingFrame { addr: SocketAddr, frame: YamuxFrame, diff --git a/p2p/src/peer/p2p_peer_actions.rs b/p2p/src/peer/p2p_peer_actions.rs index f27d7fbb82..cb111d7344 100644 --- a/p2p/src/peer/p2p_peer_actions.rs +++ b/p2p/src/peer/p2p_peer_actions.rs @@ -1,4 +1,4 @@ -use openmina_core::block::ArcBlockWithHash; +use openmina_core::{block::ArcBlockWithHash, ActionEvent}; use serde::{Deserialize, Serialize}; use crate::{P2pState, PeerId}; @@ -6,12 +6,12 @@ use crate::{P2pState, PeerId}; pub type P2pPeerActionWithMeta = redux::ActionWithMeta; pub type P2pPeerActionWithMetaRef<'a> = redux::ActionWithMeta<&'a P2pPeerAction>; -#[derive(Serialize, Deserialize, Debug, Clone)] +#[derive(Serialize, Deserialize, Debug, Clone, ActionEvent)] +#[action_event(level = info, fields(display(peer_id), best_tip = display(&best_tip.hash), incoming))] pub enum P2pPeerAction { - Ready { - peer_id: PeerId, - incoming: bool, - }, + /// Peer is ready. + Ready { peer_id: PeerId, incoming: bool }, + /// Peer's best tip is updated. BestTipUpdate { peer_id: PeerId, best_tip: ArcBlockWithHash, diff --git a/snark/Cargo.toml b/snark/Cargo.toml index 82794f3478..67a6a154ce 100644 --- a/snark/Cargo.toml +++ b/snark/Cargo.toml @@ -28,6 +28,7 @@ mina-p2p-messages = { workspace = true } sha2 = "0.10" num-bigint = "0.4" bincode = "1.3.3" +thiserror = "1.0.50" rand = "0.8" rayon = "1.5" diff --git a/snark/src/work_verify/mod.rs b/snark/src/work_verify/mod.rs index 0401b123b7..158106534d 100644 --- a/snark/src/work_verify/mod.rs +++ b/snark/src/work_verify/mod.rs @@ -22,8 +22,10 @@ impl openmina_core::requests::RequestIdType for SnarkWorkVerifyIdType { pub type SnarkWorkVerifyId = openmina_core::requests::RequestId; -#[derive(Serialize, Deserialize, Debug, Clone)] +#[derive(Serialize, Deserialize, Debug, Clone, thiserror::Error)] pub enum SnarkWorkVerifyError { + #[error("verification failed")] VerificationFailed, + #[error("validator thread crashed")] ValidatorThreadCrashed, } diff --git a/snark/src/work_verify/snark_work_verify_actions.rs b/snark/src/work_verify/snark_work_verify_actions.rs index f204bfebeb..a0bd6155f8 100644 --- a/snark/src/work_verify/snark_work_verify_actions.rs +++ b/snark/src/work_verify/snark_work_verify_actions.rs @@ -1,14 +1,16 @@ use serde::{Deserialize, Serialize}; -use openmina_core::snark::Snark; +use openmina_core::{snark::Snark, ActionEvent}; use super::{SnarkWorkVerifyError, SnarkWorkVerifyId}; pub type SnarkWorkVerifyActionWithMeta = redux::ActionWithMeta; pub type SnarkWorkVerifyActionWithMetaRef<'a> = redux::ActionWithMeta<&'a SnarkWorkVerifyAction>; -#[derive(Serialize, Deserialize, Debug, Clone)] +#[derive(Serialize, Deserialize, Debug, Clone, ActionEvent)] +#[action_event(level = trace, fields(display(req_id), display(error)))] pub enum SnarkWorkVerifyAction { + #[action_event(level = info)] Init { req_id: SnarkWorkVerifyId, batch: Vec, @@ -21,6 +23,7 @@ pub enum SnarkWorkVerifyAction { req_id: SnarkWorkVerifyId, error: SnarkWorkVerifyError, }, + #[action_event(level = info)] Success { req_id: SnarkWorkVerifyId, },