diff --git a/bin/network-monitor/Cargo.toml b/bin/network-monitor/Cargo.toml index 88a41507f4..84601900f1 100644 --- a/bin/network-monitor/Cargo.toml +++ b/bin/network-monitor/Cargo.toml @@ -14,6 +14,10 @@ version.workspace = true [lints] workspace = true +[package.metadata.cargo-shear] +# Required by expansions of the Miden tracing macros. +ignored = ["tracing"] + [dependencies] anyhow = { workspace = true } axum = { workspace = true } diff --git a/bin/network-monitor/src/commands/start.rs b/bin/network-monitor/src/commands/start.rs index fd08e8972b..5ff74d1a5e 100644 --- a/bin/network-monitor/src/commands/start.rs +++ b/bin/network-monitor/src/commands/start.rs @@ -4,8 +4,7 @@ use anyhow::Result; use miden_node_utils::logging::OpenTelemetry; -use miden_node_utils::tracing::miden_instrument; -use tracing::info; +use miden_node_utils::tracing::{info, miden_instrument}; use crate::config::MonitorConfig; use crate::frontend::ServerState; @@ -28,7 +27,7 @@ use crate::{COMPONENT, LOG_TARGET}; err, )] pub async fn start_monitor(config: MonitorConfig) -> Result<()> { - info!(target: LOG_TARGET, config = ?config, "Loaded configuration"); + info!(target: LOG_TARGET, "Loaded configuration", port = config.port); let _otel_guard = miden_node_utils::logging::setup_tracing(OpenTelemetry::from_env().with_name("monitor"))?; diff --git a/bin/network-monitor/src/counter.rs b/bin/network-monitor/src/counter.rs index a137b41622..a2af9755c5 100644 --- a/bin/network-monitor/src/counter.rs +++ b/bin/network-monitor/src/counter.rs @@ -10,7 +10,7 @@ use std::time::{Duration, Instant}; use anyhow::{Context, Result}; use miden_node_proto::clients::RpcClient; use miden_node_utils::spawn::spawn_blocking_in_current_span; -use miden_node_utils::tracing::miden_instrument; +use miden_node_utils::tracing::{debug, error, info, miden_instrument, warn}; use miden_protocol::account::auth::AuthSecretKey; use miden_protocol::account::{Account, AccountCode, AccountId, AccountPatch}; use miden_protocol::asset::AssetVault; @@ -38,7 +38,6 @@ use miden_standards::note::{NetworkAccountTarget, NoteExecutionHint}; use miden_tx::auth::BasicAuthenticator; use miden_tx::{LocalTransactionProver, TransactionExecutor}; use tokio::sync::{Mutex, watch}; -use tracing::{debug, error, info, warn}; use crate::config::MonitorConfig; use crate::deploy::counter::COUNTER_SLOT_NAME; @@ -271,30 +270,26 @@ impl IncrementService { .await .inspect_err(|e| { error!( + e, target: LOG_TARGET, - { - account.id = %self.tx.wallet_account.id(), - error = ?e, - }, - "Failed to re-sync wallet account from RPC" + "Failed to re-sync wallet account from RPC", + account.id = self.tx.wallet_account.id() ); })? .context("wallet account not found on-chain during re-sync") .inspect_err(|e| { error!( + e, target: LOG_TARGET, - { - account.id = %self.tx.wallet_account.id(), - error = ?e, - }, - "Wallet account not found on-chain during re-sync" + "Wallet account not found on-chain during re-sync", + account.id = self.tx.wallet_account.id() ); })?; debug!( target: LOG_TARGET, - { account.id = %self.tx.wallet_account.id() }, - "Wallet account re-synced from RPC" + "Wallet account re-synced from RPC", + account.id = self.tx.wallet_account.id() ); self.tx.wallet_account = fresh_account; Ok(()) @@ -406,9 +401,12 @@ impl IncrementService { let block_height = self.submission_client.submit(&proven_tx, &tx_inputs).await?; - info!(target: LOG_TARGET, "Submitted proven transaction to RPC"); - let tx_id = proven_tx.id().to_hex(); + info!( + target: LOG_TARGET, + "Submitted proven transaction to RPC", + transaction.id = tx_id.as_str() + ); Ok((tx_id, account_patch, block_height)) } @@ -445,7 +443,7 @@ impl Service for IncrementService { guard.pending_started = Some(Instant::now()); }, Err(e) => { - error!(target: LOG_TARGET, error = ?e, "Failed to create and submit network note"); + error!(&e, target: LOG_TARGET, "Failed to create and submit network note"); self.details.failure_count += 1; self.failures.record_failure(); last_error = Some(format!("create/submit note failed: {e}")); @@ -459,15 +457,15 @@ impl Service for IncrementService { if !resynced_now && self.failures.should_regenerate() { warn!( target: LOG_TARGET, - consecutive_failures = self.failures.consecutive_failures, - "re-sync ineffective, regenerating accounts from scratch" + "re-sync ineffective, regenerating accounts from scratch", + counter.failures.consecutive = self.failures.consecutive_failures ); self.failures.mark_regeneration_attempt(); match self.try_regenerate_accounts().await { Ok(()) => self.failures.reset(), Err(regen_err) => { self.failures.mark_regeneration_failed(); - error!(target: LOG_TARGET, error = ?regen_err, "Account regeneration failed"); + error!(®en_err, target: LOG_TARGET, "Account regeneration failed"); }, } } @@ -552,13 +550,11 @@ impl CounterTrackingService { info!( target: LOG_TARGET, - { - old.counter.id = %self.counter_account.id(), - new.counter.id = %reloaded.counter.id(), - old.wallet.id = %self.wallet_account.id(), - new.wallet.id = %reloaded.wallet.id(), - }, "monitor accounts changed, resetting tracking state", + counter.account.id.old = self.counter_account.id(), + counter.account.id.new = reloaded.counter.id(), + wallet.account.id.old = self.wallet_account.id(), + wallet.account.id.new = reloaded.wallet.id() ); self.wallet_account = reloaded.wallet; self.counter_account = reloaded.counter; @@ -592,7 +588,7 @@ impl CounterTrackingService { // Counter value not available yet, but not an error. Ok(None) => return None, Err(e) => { - error!(target: LOG_TARGET, error = ?e, "Failed to fetch counter value"); + error!(&e, target: LOG_TARGET, "Failed to fetch counter value"); return Some(format!("fetch counter value failed: {e}")); }, }; @@ -614,8 +610,8 @@ impl CounterTrackingService { Ok(None) => {}, Err(e) => { error!( + &e, target: LOG_TARGET, - error = ?e, "Failed to fetch expected wallet counter value" ); last_error = Some(format!("fetch expected value failed: {e}")); @@ -664,9 +660,10 @@ impl CounterTrackingService { { warn!( target: LOG_TARGET, - timeout = ?self.config.counter_latency_timeout, - target_value = pending.target_value, - "Latency measurement timed out" + "Latency measurement timed out", + counter.latency.timeout_ms = + self.config.counter_latency_timeout.as_millis() as u64, + counter.value.target = pending.target_value ); let mut guard = self.latency_state.lock().await; if guard.pending.as_ref().map(|p| p.target_value) == Some(pending.target_value) { @@ -767,10 +764,14 @@ async fn initialize_tracking_state( Ok(Some(observed)) => { details.current_value = Some(observed); details.last_updated = Some(current_unix_timestamp_secs()); - info!(target: LOG_TARGET, observed_value = observed, "Initialized counter tracking"); + info!( + target: LOG_TARGET, + "Initialized counter tracking", + counter.value.observed = observed + ); }, Ok(None) => warn!(target: LOG_TARGET, "Counter account not found at init"), - Err(e) => error!(target: LOG_TARGET, error = ?e, "Failed to fetch initial counter value"), + Err(e) => error!(&e, target: LOG_TARGET, "Failed to fetch initial counter value"), } match fetch_slot_value(rpc_client, wallet_account.id(), WALLET_COUNTER_SLOT_NAME.as_str()).await @@ -778,7 +779,7 @@ async fn initialize_tracking_state( Ok(Some(expected)) => details.expected_value = Some(expected), Ok(None) => {}, Err(e) => { - error!(target: LOG_TARGET, error = ?e, "Failed to fetch initial expected wallet value"); + error!(&e, target: LOG_TARGET, "Failed to fetch initial expected wallet value"); }, } @@ -858,9 +859,9 @@ fn update_expected_and_pending( } else { warn!( target: LOG_TARGET, - expected_value = expected, - observed_value = observed_value, - "Expected counter value is less than current value, setting pending to 0" + "Expected counter value is less than current value, setting pending to 0", + counter.value.expected = expected, + counter.value.observed = observed_value ); details.pending_increments = Some(0); } @@ -968,12 +969,10 @@ async fn fetch_wallet_account( Ok(response) => response.into_inner(), Err(e) => { warn!( + &e, target: LOG_TARGET, - { - account.id = %account_id, - error = %e, - }, - "Failed to fetch wallet account via RPC" + "Failed to fetch wallet account via RPC", + account.id = account_id ); return Ok(None); }, @@ -983,8 +982,8 @@ async fn fetch_wallet_account( if response.witness.is_some() { info!( target: LOG_TARGET, - { account.id = %account_id }, - "account found on-chain but cannot reconstruct full account from RPC response" + "account found on-chain but cannot reconstruct full account from RPC response", + account.id = account_id ); } return Ok(None); @@ -1058,7 +1057,7 @@ async fn fetch_wallet_account( expected_storage_commitment ); - info!(target: LOG_TARGET, { account.id = %account_id }, "Fetched wallet account from RPC"); + info!(target: LOG_TARGET, "Fetched wallet account from RPC", account.id = account_id); Ok(Some(account)) } diff --git a/bin/network-monitor/src/deploy/mod.rs b/bin/network-monitor/src/deploy/mod.rs index 89881e35cd..a4180db158 100644 --- a/bin/network-monitor/src/deploy/mod.rs +++ b/bin/network-monitor/src/deploy/mod.rs @@ -25,7 +25,7 @@ use miden_node_proto::generated::rpc::{ use miden_node_proto::generated::transaction::ProvenTransaction as ProtoProvenTransaction; use miden_node_utils::retry; use miden_node_utils::spawn::spawn_blocking_in_current_span; -use miden_node_utils::tracing::miden_instrument; +use miden_node_utils::tracing::{debug, info, miden_instrument, warn}; use miden_protocol::Word; use miden_protocol::account::{ Account, @@ -183,11 +183,11 @@ impl TransactionSubmissionClient { }) .notify(|status: &anyhow::Error, _| { stale_key.store(true, Ordering::Relaxed); - tracing::warn!( + warn!( + status, target: COMPONENT, - %tx_id, - err = %status, "Transaction inputs rejected as stale, refreshing the encryption key and retrying", + transaction.id = tx_id ); }) .await; @@ -277,11 +277,11 @@ pub async fn create_genesis_aware_rpc_client( }) .retry(genesis_discovery_backoff()) .notify(|err: &anyhow::Error, sleep: Duration| { - tracing::warn!( + warn!( + err, target: COMPONENT, - err = ?err, - sleep_ms = sleep.as_millis() as u64, "RPC genesis discovery failed; retrying after backoff", + retry.delay_ms = sleep.as_millis() as u64 ); }) .await @@ -296,7 +296,7 @@ pub async fn create_and_deploy_accounts( submission_client: &TransactionSubmissionClient, prover: &LocalTransactionProver, ) -> Result { - tracing::info!(target: LOG_TARGET, "Creating fresh monitor accounts"); + info!(target: LOG_TARGET, "Creating fresh monitor accounts"); let mut rpc_client = submission_client.rpc_client(); @@ -314,7 +314,10 @@ pub async fn create_and_deploy_accounts( let counter_anchor = resolve_counter_anchor(&mut rpc_client, &genesis_header, &committed_counter).await?; - tracing::info!(target: LOG_TARGET, "Successfully created and deployed accounts"); + info!( + target: LOG_TARGET, + "Successfully created and deployed accounts" + ); Ok(DeployedMonitorAccounts { wallet: wallet_account, @@ -397,26 +400,27 @@ async fn resolve_counter_anchor( .await { Ok(Some(anchor)) => { - tracing::info!( + info!( target: LOG_TARGET, - { - account.id = %committed_counter.id(), - block.number = %anchor.block_header.block_num(), - }, - "Resolved counter FPI anchor" + "Resolved counter FPI anchor", + account.id = committed_counter.id(), + block.number = anchor.block_header.block_num() ); return Ok(anchor); }, - Ok(None) => tracing::debug!( + Ok(None) => debug!( target: LOG_TARGET, - { account.id = %committed_counter.id(), attempt }, - "Counter account not yet committed in the expected state; retrying" + "Counter account not yet committed in the expected state; retrying", + account.id = committed_counter.id(), + retry.attempt = attempt ), Err(err) => { - tracing::debug!( + debug!( + &err, target: LOG_TARGET, - { account.id = %committed_counter.id(), attempt, error = ?err }, - "Counter anchor resolution attempt failed; retrying" + "Counter anchor resolution attempt failed; retrying", + account.id = committed_counter.id(), + retry.attempt = attempt ); last_error = Some(err); }, diff --git a/bin/network-monitor/src/faucet.rs b/bin/network-monitor/src/faucet.rs index ff0cb94edb..7c47835a77 100644 --- a/bin/network-monitor/src/faucet.rs +++ b/bin/network-monitor/src/faucet.rs @@ -8,11 +8,10 @@ use std::time::{Duration, Instant}; use anyhow::Context; use hex; use miden_node_utils::spawn::spawn_blocking_in_current_span; -use miden_node_utils::tracing::miden_instrument; +use miden_node_utils::tracing::{debug, info, miden_instrument, trace, warn}; use reqwest::Client; use serde::{Deserialize, Serialize}; use sha2::{Digest, Sha256}; -use tracing::{debug, info, trace, warn}; use url::Url; use crate::deploy::wallet::create_wallet_account; @@ -156,8 +155,8 @@ impl Service for FaucetService { match fetch_faucet_metadata(&self.client, &self.url).await { Ok(metadata) => self.faucet_metadata = Some(metadata), Err(e) => warn!( + &e, target: LOG_TARGET, - error = %format!("{e:#}"), "Failed to fetch faucet metadata" ), } @@ -171,14 +170,18 @@ impl Service for FaucetService { self.last_tx_id = Some(minted_tokens.tx_id.clone()); info!( target: LOG_TARGET, - { transaction.id = %minted_tokens.tx_id }, - "Faucet test successful" + "Faucet test successful", + transaction.id = minted_tokens.tx_id.as_str() ); None }, Err(e) => { self.failure_count += 1; - warn!(target: LOG_TARGET, error = %e, "Faucet test failed"); + warn!( + &e, + target: LOG_TARGET, + "Faucet test failed" + ); Some(format!("{e:#}")) }, }; @@ -249,11 +252,9 @@ async fn perform_mint_test( ) -> anyhow::Result { debug!( target: LOG_TARGET, - { - account.id = %account_id, - account.id.len = account_id.len(), - }, - "Using recipient account ID" + "Using recipient account ID", + account.id = account_id, + account.id.length = account_id.len() ); // Step 1: Request PoW challenge @@ -266,16 +267,17 @@ async fn perform_mint_test( let response = client.get(pow_url).send().await?; let response_text = read_success_body(response).await.context("/pow request failed")?; - debug!(target: LOG_TARGET, response = %response_text, "Faucet PoW response"); + debug!(target: LOG_TARGET, "Faucet PoW response received"); let challenge_response: PowChallengeResponse = parse_faucet_response(&response_text).context("unexpected response from /pow")?; debug!( target: LOG_TARGET, - target = challenge_response.target, - challenge.prefix = %&challenge_response.challenge[..16.min(challenge_response.challenge.len())], - "Received PoW challenge" + "Received PoW challenge", + pow.target = challenge_response.target, + pow.challenge.prefix = + &challenge_response.challenge[..16.min(challenge_response.challenge.len())] ); // Step 2: Solve the PoW challenge off the async runtime; hashing is CPU-bound and would @@ -289,7 +291,7 @@ async fn perform_mint_test( .context("PoW solver task panicked")? .context("Failed to solve PoW challenge")?; - debug!(target: LOG_TARGET, nonce = nonce, "Solved PoW challenge"); + debug!(target: LOG_TARGET, "Solved PoW challenge", pow.nonce = nonce); // Step 3: Request tokens with the solution let mut tokens_url = faucet_url.join("/get_tokens")?; @@ -304,7 +306,7 @@ async fn perform_mint_test( let response = client.get(tokens_url).send().await?; let response_text = read_success_body(response).await.context("/get_tokens request failed")?; - debug!(target: LOG_TARGET, response = %response_text, "Faucet /get_tokens response"); + debug!(target: LOG_TARGET, "Faucet token response received"); let tokens_response: GetTokensResponse = parse_faucet_response(&response_text).context("unexpected response from /get_tokens")?; @@ -374,11 +376,11 @@ fn solve_pow_challenge(challenge: &str, target: u64, timeout: Duration) -> anyho if hash_as_u64 < target { trace!( target: LOG_TARGET, - nonce = nonce, - hash = hash_as_u64, - target = target, - target.leading_zero_bits = target.leading_zeros(), - "PoW solution found" + "PoW solution found", + pow.nonce = nonce, + pow.hash = hash_as_u64, + pow.target = target, + pow.target.leading_zero_bits = target.leading_zeros() ); return Ok(nonce); } @@ -394,11 +396,11 @@ fn solve_pow_challenge(challenge: &str, target: u64, timeout: Duration) -> anyho } trace!( target: LOG_TARGET, - nonce = nonce, - current_hash = hash_as_u64, - target = target, - target.leading_zero_bits = target.leading_zeros(), - "PoW solve progress" + "PoW solve progress", + pow.nonce = nonce, + pow.hash = hash_as_u64, + pow.target = target, + pow.target.leading_zero_bits = target.leading_zeros() ); } } diff --git a/bin/network-monitor/src/frontend.rs b/bin/network-monitor/src/frontend.rs index db44f079c1..f331a0c2df 100644 --- a/bin/network-monitor/src/frontend.rs +++ b/bin/network-monitor/src/frontend.rs @@ -12,9 +12,8 @@ use axum::http::header; use axum::response::{IntoResponse, Response}; use axum::routing::get; use maud::Markup; -use miden_node_utils::tracing::miden_instrument; +use miden_node_utils::tracing::{info, miden_instrument}; use tokio::sync::watch; -use tracing::info; use crate::config::MonitorConfig; use crate::status::{NetworkStatus, ServiceStatus}; @@ -48,8 +47,12 @@ pub async fn serve(server_state: ServerState, config: MonitorConfig) { .with_state(server_state); let bind_address = format!("0.0.0.0:{}", config.port); - info!(target: LOG_TARGET, %bind_address, "Starting web server"); - info!(target: LOG_TARGET, "Dashboard available at: http://localhost:{}/", config.port); + info!( + target: LOG_TARGET, + "Starting web server", + network_monitor.listen = bind_address.as_str() + ); + info!(target: LOG_TARGET, "Dashboard available", port = config.port); let listener = tokio::net::TcpListener::bind(&bind_address) .await .expect("Failed to bind to address"); diff --git a/bin/network-monitor/src/monitor/tasks.rs b/bin/network-monitor/src/monitor/tasks.rs index 9e8a3b692d..2bb576ba78 100644 --- a/bin/network-monitor/src/monitor/tasks.rs +++ b/bin/network-monitor/src/monitor/tasks.rs @@ -7,10 +7,10 @@ use anyhow::Result; use backon::{ExponentialBuilder, Retryable}; use miden_node_proto::clients::RemoteProverClient; use miden_node_utils::tasks::Tasks as SupervisedTasks; +use miden_node_utils::tracing::{debug, warn}; use miden_tx::LocalTransactionProver; use tokio::sync::watch::Receiver; use tokio::sync::{Mutex, watch}; -use tracing::{debug, warn}; use crate::LOG_TARGET; use crate::config::MonitorConfig; @@ -147,7 +147,7 @@ impl Tasks { let config = config.clone(); self.handles.spawn_infallible("ntx", run_ntx(config, increment_tx, tracking_tx)); - debug!(target: LOG_TARGET, service = "ntx", "Spawned service"); + debug!(target: LOG_TARGET, "Spawned service", service.name = "ntx"); (increment_rx, tracking_rx) } @@ -161,7 +161,7 @@ impl Tasks { let service_name = svc.name().to_string(); self.handles .spawn_infallible(service_name.clone(), async move { svc.run(tx).await }); - debug!(target: LOG_TARGET, service = %service_name, "Spawned service"); + debug!(target: LOG_TARGET, "Spawned service", service.name = service_name); rx } @@ -214,10 +214,10 @@ async fn run_ntx( .retry(backoff) .notify(|err: &anyhow::Error, sleep: Duration| { warn!( + err, target: LOG_TARGET, - err = ?err, - sleep_ms = sleep.as_millis() as u64, "NTX bootstrap failed; retrying after backoff", + retry.delay_ms = sleep.as_millis() as u64 ); let msg = format!("deploying monitor accounts failed: {err:#}"); increment_tx.send_replace(ServiceStatus::unhealthy( diff --git a/bin/network-monitor/src/remote_prover.rs b/bin/network-monitor/src/remote_prover.rs index 5822af9a5f..71863a2325 100644 --- a/bin/network-monitor/src/remote_prover.rs +++ b/bin/network-monitor/src/remote_prover.rs @@ -13,14 +13,13 @@ use std::time::{Duration, Instant}; use miden_node_proto::clients::{RemoteProverClient, RemoteProverProxyStatusClient}; use miden_node_proto::generated as proto; -use miden_node_utils::tracing::miden_instrument; +use miden_node_utils::tracing::{debug, miden_instrument, warn}; use miden_protocol::utils::serde::Serializable; use serde::{Deserialize, Serialize}; use tokio::sync::watch; use tokio::task::JoinHandle; use tokio::time::MissedTickBehavior; use tonic::Request; -use tracing::{debug, warn}; use url::Url; use crate::COMPONENT; @@ -175,14 +174,14 @@ impl ProverStatusService { } match &self.probe_handle { None => { - debug!(target: COMPONENT, prover = %self.name, "spawning probe task"); + debug!(target: COMPONENT, "spawning probe task", prover = self.name); self.probe_handle = Some(self.probe_spawner.spawn()); }, Some(handle) if handle.is_finished() => { warn!( target: COMPONENT, - prover = %self.name, - "probe task terminated unexpectedly; respawning" + "probe task terminated unexpectedly; respawning", + prover = self.name ); self.probe_spawner.probe_tx.send_modify(|snapshot| { snapshot.failure_count += 1; @@ -290,7 +289,12 @@ impl Service for ProverStatusService { self.last_status_err = None; }, Err(e) => { - debug!(target: COMPONENT, prover = %self.name, error = %e, "Remote prover status check failed"); + debug!( + &e, + target: COMPONENT, + "Remote prover status check failed", + prover = self.name + ); self.last_status_err = Some(e.to_string()); }, } @@ -369,17 +373,21 @@ async fn run_prover_test( ) { let payload = loop { if probe_tx.is_closed() { - debug!(target: COMPONENT, prover = %name, "probe channel closed, exiting probe task"); + debug!( + target: COMPONENT, + "probe channel closed, exiting probe task", + prover = name + ); return; } match generate_prover_test_payload(&rpc_url).await { Ok(payload) => break payload, Err(e) => { warn!( + &e, target: COMPONENT, - prover = %name, - error = ?e, - "failed to build remote-prover probe payload; retrying" + "failed to build remote-prover probe payload; retrying", + prover = name ); probe_tx.send_modify(|snapshot| { snapshot.latest = Some(ProverTestOutcome { @@ -441,7 +449,11 @@ async fn run_prover_test( } if probe_tx.send(state.clone()).is_err() { - debug!(target: COMPONENT, prover = %name, "probe channel closed, exiting probe task"); + debug!( + target: COMPONENT, + "probe channel closed, exiting probe task", + prover = name + ); return; } } diff --git a/bin/network-monitor/src/service.rs b/bin/network-monitor/src/service.rs index 11e7c972f8..0fc3672ed8 100644 --- a/bin/network-monitor/src/service.rs +++ b/bin/network-monitor/src/service.rs @@ -10,9 +10,9 @@ use std::time::Duration; use miden_node_proto::clients::{Builder as ClientBuilder, GrpcClient}; +use miden_node_utils::tracing::debug; use tokio::sync::watch; use tokio::time::MissedTickBehavior; -use tracing::debug; use url::Url; use crate::LOG_TARGET; @@ -62,7 +62,11 @@ pub trait Service: Send + 'static { interval.tick().await; let status = self.check().await; if tx.send(status).is_err() { - debug!(target: LOG_TARGET, "No receivers for {}, shutting down", self.name()); + debug!( + target: LOG_TARGET, + "No receivers; shutting down service", + service.name = self.name() + ); return; } } diff --git a/bin/network-monitor/src/service_status.rs b/bin/network-monitor/src/service_status.rs index 15c023e7af..2e2c09d623 100644 --- a/bin/network-monitor/src/service_status.rs +++ b/bin/network-monitor/src/service_status.rs @@ -8,8 +8,8 @@ use std::time::{Duration, SystemTime, UNIX_EPOCH}; use miden_node_proto::generated as proto; use miden_node_proto::generated::rpc::{BlockProducerStatus, RpcStatus}; +use miden_node_utils::tracing::warn; use serde::{Deserialize, Serialize}; -use tracing::warn; use crate::LOG_TARGET; use crate::faucet::FaucetTestDetails; @@ -336,9 +336,9 @@ impl From for WorkerStatusDetails { |_| { warn!( target: LOG_TARGET, - raw = value.status, - worker = %value.name, - "Unknown worker health status discriminant" + "Unknown worker health status discriminant", + worker.status.raw = value.status, + worker.name = value.name.as_str() ); Status::Unknown }, @@ -362,8 +362,8 @@ impl RemoteProverStatusDetails { |_| { warn!( target: LOG_TARGET, - raw = status.supported_proof_type, - "Unknown supported proof type discriminant" + "Unknown supported proof type discriminant", + prover.proof_type.raw = status.supported_proof_type ); ProofType::Unknown }, diff --git a/bin/network-monitor/src/status.rs b/bin/network-monitor/src/status.rs index 8c655f5e83..422054db8f 100644 --- a/bin/network-monitor/src/status.rs +++ b/bin/network-monitor/src/status.rs @@ -8,8 +8,7 @@ use std::time::Duration; use miden_node_proto::clients::RpcClient; -use miden_node_utils::tracing::miden_instrument; -use tracing::debug; +use miden_node_utils::tracing::{debug, miden_instrument}; use url::Url; use crate::COMPONENT; @@ -136,9 +135,9 @@ impl Service for RpcService { { debug!( target: COMPONENT, - chain_tip = rpc_details.chain_tip, - stale_duration_secs = stale_duration, - "Chain tip is stale" + "Chain tip is stale", + tip.number = rpc_details.chain_tip, + tip.stale_duration_secs = stale_duration ); return ServiceStatus::unhealthy( self.name(), @@ -153,7 +152,7 @@ impl Service for RpcService { ServiceStatus::healthy(self.name(), ServiceDetails::RpcStatus(rpc_details)) }, Err(e) => { - debug!(target: COMPONENT, error = %e, "RPC status check failed"); + debug!(&e, target: COMPONENT, "RPC status check failed"); ServiceStatus::error(self.name(), e) }, } diff --git a/bin/node/Cargo.toml b/bin/node/Cargo.toml index 6b851f0c45..ac0d0ba552 100644 --- a/bin/node/Cargo.toml +++ b/bin/node/Cargo.toml @@ -14,6 +14,10 @@ version.workspace = true [lints] workspace = true +[package.metadata.cargo-shear] +# Required by expansions of the Miden tracing macros. +ignored = ["tracing"] + [features] tracing-forest = ["miden-node-block-producer/tracing-forest"] diff --git a/bin/node/src/commands/lifecycle.rs b/bin/node/src/commands/lifecycle.rs index cc5660ecb7..fc04f7eaf6 100644 --- a/bin/node/src/commands/lifecycle.rs +++ b/bin/node/src/commands/lifecycle.rs @@ -6,6 +6,7 @@ use miden_node_store::genesis::GenesisBlock; use miden_node_store::{DataDirectory, Db, State}; use miden_node_utils::fs::ensure_empty_directory; use miden_node_utils::genesis::{OfficialNetwork, fetch_genesis_block, read_genesis_block}; +use miden_node_utils::tracing::info; use super::ENV_DATA_DIRECTORY; @@ -35,36 +36,32 @@ pub struct BootstrapCommand { impl BootstrapCommand { pub async fn handle(self) -> anyhow::Result<()> { - tracing::info!( + info!( target: crate::LOG_TARGET, - { - service.name = "miden-node", - service.version = env!("CARGO_PKG_VERSION"), - genesis.source.kind = - if self.genesis_block_file.is_some() { "file" } else { "network" }, - genesis.source = %self.genesis_block_file.as_ref().map_or_else( - || self.network.map_or_else( - || "custom".to_owned(), - |network| network.to_string(), - ), - |path| path.display().to_string(), - ), - data.directory = %self.data_directory.display(), - }, "Bootstrapping node", + service.name = "miden-node", + service.version = env!("CARGO_PKG_VERSION"), + genesis.source.kind = + if self.genesis_block_file.is_some() { "file" } else { "network" }, + genesis.source = self.genesis_block_file.as_ref().map_or_else( + || self.network.map_or_else( + || "custom".to_owned(), + |network| network.to_string(), + ), + |path| path.display().to_string(), + ), + data.directory = self.data_directory.as_path() ); ensure_empty_directory(&self.data_directory)?; let genesis_block = read_bootstrap_genesis_block(self.genesis_block_file.as_deref(), self.network).await?; let genesis_commitment = genesis_block.inner().header().commitment(); State::bootstrap(genesis_block, &self.data_directory)?; - tracing::info!( + info!( target: crate::LOG_TARGET, - { - genesis.commitment = %genesis_commitment, - data.directory = %self.data_directory.display(), - }, "Node bootstrap complete", + genesis.commitment = genesis_commitment, + data.directory = self.data_directory.as_path() ); Ok(()) } diff --git a/bin/node/src/commands/modes.rs b/bin/node/src/commands/modes.rs index 1efaa3ca68..7e809ad135 100644 --- a/bin/node/src/commands/modes.rs +++ b/bin/node/src/commands/modes.rs @@ -19,6 +19,7 @@ use miden_node_utils::clap::duration_to_human_readable_string; use miden_node_utils::formatting::format_endpoint; use miden_node_utils::shutdown::CancellationToken; use miden_node_utils::tasks::Tasks; +use miden_node_utils::tracing::info; use tokio::net::TcpListener; use url::Url; @@ -140,31 +141,31 @@ impl SequencerCommand { } fn log_starting(&self) { - tracing::info!( + info!( target: crate::LOG_TARGET, - { - service.name = "miden-node", - service.version = env!("CARGO_PKG_VERSION"), - node.role = "sequencer", - rpc.listen = %self.runtime.rpc.listen, - internal.listen = %self.internal.map_or_else( - || "disabled".to_owned(), - |address| address.to_string(), - ), - data.directory = %self.runtime.data_directory.display(), - validator.endpoints = %self - .external_services - .validator_urls - .iter() - .map(format_endpoint) - .collect::>() - .join(","), - ntx_builder.endpoint = %format_endpoint(&self.external_services.ntx_builder_url), - block.interval = %humantime::Duration::from(self.block_producer.block.interval), - batch.interval = %humantime::Duration::from(self.block_producer.batch.interval), - store.sqlite.connection_pool_size = self.store.sqlite.connection_pool_size.get(), - }, "Starting node", + service.name = "miden-node", + service.version = env!("CARGO_PKG_VERSION"), + node.role = "sequencer", + rpc.listen = self.runtime.rpc.listen.to_string(), + internal.listen = self.internal.map_or_else( + || "disabled".to_owned(), + |address| address.to_string(), + ), + data.directory = self.runtime.data_directory.as_path(), + validator.endpoints = self + .external_services + .validator_urls + .iter() + .map(format_endpoint) + .collect::>() + .join(","), + ntx_builder.endpoint = format_endpoint(&self.external_services.ntx_builder_url), + block.interval = + humantime::Duration::from(self.block_producer.block.interval).to_string(), + batch.interval = + humantime::Duration::from(self.block_producer.batch.interval).to_string(), + db.sqlite.connection_pool_size = self.store.sqlite.connection_pool_size.get() ); } } @@ -372,28 +373,26 @@ impl FullNodeCommand { } fn log_starting(&self) { - tracing::info!( + info!( target: crate::LOG_TARGET, - { - service.name = "miden-node", - service.version = env!("CARGO_PKG_VERSION"), - node.role = "full", - rpc.listen = %self.runtime.rpc.listen, - data.directory = %self.runtime.data_directory.display(), - sync.block_source.endpoint = %format_endpoint(&self.sync.block_source_url), - sync.ready_threshold = self.sync.readiness_threshold, - validator.endpoints = %if self.validator_urls.is_empty() { - "disabled".to_owned() - } else { - self.validator_urls.iter().map(format_endpoint).collect::>().join(",") - }, - sequencer.endpoint = %self.sequencer_url.as_ref().map_or_else( - || "disabled".to_owned(), - format_endpoint, - ), - store.sqlite.connection_pool_size = self.store.sqlite.connection_pool_size.get(), - }, "Starting node", + service.name = "miden-node", + service.version = env!("CARGO_PKG_VERSION"), + node.role = "full", + rpc.listen = self.runtime.rpc.listen.to_string(), + data.directory = self.runtime.data_directory.as_path(), + sync.block_source.endpoint = format_endpoint(&self.sync.block_source_url), + sync.ready_threshold = self.sync.readiness_threshold, + validator.endpoints = if self.validator_urls.is_empty() { + "disabled".to_owned() + } else { + self.validator_urls.iter().map(format_endpoint).collect::>().join(",") + }, + sequencer.endpoint = self.sequencer_url.as_ref().map_or_else( + || "disabled".to_owned(), + format_endpoint, + ), + db.sqlite.connection_pool_size = self.store.sqlite.connection_pool_size.get() ); } } diff --git a/bin/node/src/commands/recover.rs b/bin/node/src/commands/recover.rs index 211f4a2db9..c07c503ce0 100644 --- a/bin/node/src/commands/recover.rs +++ b/bin/node/src/commands/recover.rs @@ -7,6 +7,7 @@ use miden_node_proto::clients::{Builder, ValidatorClient}; use miden_node_proto::generated::validator::{BlockSubscriptionRequest, BlockSubscriptionResponse}; use miden_node_store::{BlockWriter, State, WriterTask}; use miden_node_utils::shutdown::CancellationToken; +use miden_node_utils::tracing::info; use miden_protocol::Word; use miden_protocol::block::{ BlockBody, @@ -21,7 +22,6 @@ use miden_protocol::utils::serde::Deserializable; use tokio::sync::mpsc; use tokio_stream::StreamExt; use tonic::codec::Streaming; -use tracing::info; use url::Url; use super::ENV_DATA_DIRECTORY; @@ -133,9 +133,9 @@ async fn recover_from_validators( if local_tip >= recovery_tip { info!( target: LOG_TARGET, - local_tip = local_tip.as_u32(), - recovery_tip = recovery_tip.as_u32(), "Local chain is already at the validators' chain tip; nothing to recover", + block.number = local_tip, + sync.upstream_block = recovery_tip ); return Ok(()); } @@ -153,10 +153,10 @@ async fn recover_from_validators( let block_count = u64::from(recovery_tip.as_u32() - block_from) + 1; info!( target: LOG_TARGET, - block_from, - recovery_tip = recovery_tip.as_u32(), - validators = validators.len(), "Recovering blocks from validators", + block.from = block_from, + sync.upstream_block = recovery_tip, + validators.count = validators.len() ); // Run recovery as a three-stage pipeline so that receiving blocks from the validators, @@ -185,14 +185,14 @@ async fn recover_from_validators( .apply_block(block) .await .context("failed to apply recovered block")?; - info!(target: LOG_TARGET, block_number = block_num.as_u32(), "Applied recovered block"); + info!(target: LOG_TARGET, "Applied recovered block", block.number = block_num); } // The channel closes either because every block up to the recovery target was coalesced or // because the coalescer failed. coalescer.await.context("coalescer task panicked")??; - info!(target: LOG_TARGET, chain_tip = recovery_tip.as_u32(), "Block recovery complete"); + info!(target: LOG_TARGET, "Block recovery complete", tip.number = recovery_tip); Ok(()) } diff --git a/bin/ntx-builder/src/actor/execute.rs b/bin/ntx-builder/src/actor/execute.rs index 8e4818d58b..9af861f2d1 100644 --- a/bin/ntx-builder/src/actor/execute.rs +++ b/bin/ntx-builder/src/actor/execute.rs @@ -3,11 +3,10 @@ use std::sync::{Arc, Mutex}; use std::time::Duration; use backon::ExponentialBuilder; -use miden_node_utils::ErrorReport; use miden_node_utils::lru_cache::LruCache; use miden_node_utils::retry::{self, Retryable}; use miden_node_utils::spawn::spawn_blocking_in_current_span; -use miden_node_utils::tracing::{ErrorSpanExt, miden_instrument, miden_span_record}; +use miden_node_utils::tracing::{ErrorSpanExt, info, miden_instrument, miden_span_record, warn}; use miden_protocol::Word; use miden_protocol::account::{ Account, @@ -109,12 +108,12 @@ fn request_backoff(initial: Duration, max: Duration) -> ExponentialBuilder { /// Emits a structured warning for a transient NTX request failure that is about to be retried. fn log_transient_retry(operation: &'static str, err: &E, sleep: Duration) { - tracing::warn!( + warn!( + err, target: COMPONENT, - operation, - err = %err.as_report(), - sleep_ms = sleep.as_millis() as u64, "ntx transient request failure; retrying after backoff", + operation.name = operation, + retry.delay_ms = sleep.as_millis() as u64 ); } @@ -427,14 +426,12 @@ impl NtxContext { .collect::>(); for failed_note in &failed { - tracing::info!( + info!( + failed_note.error(), target: LOG_TARGET, - { - note.id = %failed_note.note().id(), - nullifier = %failed_note.note().nullifier(), - err = %failed_note.error().as_report(), - }, "note failed consumability check", + note.id = failed_note.note().id(), + note.nullifier = failed_note.note().nullifier() ); } @@ -514,13 +511,11 @@ impl NtxContext { successful.is_empty() && failed.iter().any(|f| f.num_cycles().is_some()) }, Err(err) => { - tracing::warn!( + warn!( + &err, target: LOG_TARGET, - { - note.id = %note.id(), - err = %err.as_report(), - }, "isolation re-check for a cycle-limited note failed; treating it as deferrable", + note.id = note.id() ); false }, diff --git a/bin/ntx-builder/src/actor/mod.rs b/bin/ntx-builder/src/actor/mod.rs index 81d12f738c..14f1c0111e 100644 --- a/bin/ntx-builder/src/actor/mod.rs +++ b/bin/ntx-builder/src/actor/mod.rs @@ -12,10 +12,10 @@ use anyhow::Context; use candidate::{SponsoredFeatureNote, TransactionCandidate}; use futures::FutureExt; use miden_node_utils::ErrorReport; -use miden_node_utils::formatting::{format_array, format_opt}; +use miden_node_utils::formatting::format_opt; use miden_node_utils::lru_cache::LruCache; use miden_node_utils::shutdown::CancellationToken; -use miden_node_utils::tracing::miden_instrument; +use miden_node_utils::tracing::{debug, error, info, miden_instrument, warn}; use miden_protocol::Word; use miden_protocol::account::{Account, AccountId, AccountPatch}; use miden_protocol::block::BlockNumber; @@ -400,10 +400,10 @@ impl AccountActor { } // Idle timeout: actor has been idle too long, deactivate. () = idle_timeout_sleep => { - tracing::debug!( + debug!( target: LOG_TARGET, - %account_id, - "Account actor deactivated due to idle timeout" + "Account actor deactivated due to idle timeout", + account.id = account_id ); return Ok(()); } @@ -464,21 +464,21 @@ impl AccountActor { Arc::make_mut(account) .apply_patch(&pending_patch) .context("failed to apply landed transaction patch to in-memory account")?; - tracing::info!( + info!( target: LOG_TARGET, - account_id = %self.account_id, - tx_id = %submitted_tx_id, "submitted transaction landed; advanced in-memory account by its patch", + account.id = self.account_id, + transaction.id = submitted_tx_id ); ActorMode::NotesAvailable } else if elapsed.as_u32() >= u32::from(self.config.tx_expiration_delta.get()) { - tracing::info!( + info!( target: LOG_TARGET, - account_id = %self.account_id, - %submitted_at, - current_tip = %view.chain_tip, - delta = self.config.tx_expiration_delta, "submitted transaction expired", + account.id = self.account_id, + transaction.submitted_at = submitted_at, + tip.number = view.chain_tip, + transaction.expiration_delta = self.config.tx_expiration_delta.get() ); // The submission did not land. Reload the authoritative account in case a // different transaction changed it while we waited, then resume selection. @@ -546,11 +546,11 @@ impl AccountActor { (nullifier, error) }) .collect::>(); - tracing::info!( + info!( target: LOG_TARGET, - %account_id, - rejected_count = failed_notes.len(), "dropping network notes whose script roots are not allowlisted", + account.id = account_id, + note.rejected.count = failed_notes.len() ); self.mark_notes_failed(&failed_notes, block_num).await; } @@ -673,12 +673,12 @@ impl AccountActor { .chain(sponsored.sponsorships.iter().map(Note::id)) }) .collect(); - tracing::info!( + info!( target: LOG_TARGET, - %account_id, - note_ids = %format_array(¬e_ids), - num_notes = note_ids.len(), "executing network transaction", + account.id = account_id, + note.ids = note_ids.as_slice(), + note.count = note_ids.len() ); let execution_result = context.execute_transaction(tx_candidate).await; @@ -699,14 +699,14 @@ impl AccountActor { // - `oversized_notes` exceed the per-tx cycle budget on their own and can never be // consumed. They are discarded immediately so they stop being re-selected. // - `failed_notes` are genuine consumability failures and are penalized as usual. - tracing::info!( + info!( target: LOG_TARGET, - %account_id, - %tx_id, - num_genuine_failed = failed_notes.len(), - num_deferred = deferred_notes.len(), - num_oversized = oversized_notes.len(), "network transaction executed", + account.id = account_id, + transaction.id = tx_id, + note.failed.count = failed_notes.len(), + note.deferred.count = deferred_notes.len(), + note.oversized.count = oversized_notes.len() ); self.cache_note_scripts(fetched_scripts).await; @@ -740,13 +740,12 @@ impl AccountActor { }, // Transaction execution failed. Err(err) => { - let error_msg = err.as_report(); - tracing::error!( + error!( + &err, target: LOG_TARGET, - %account_id, - note_ids = %format_array(¬e_ids), - err = %error_msg, "network transaction failed", + account.id = account_id, + note.ids = note_ids.as_slice() ); // A rejected submission (e.g. an account-commitment mismatch) means our in-memory @@ -770,14 +769,12 @@ impl AccountActor { .iter() .map(|sponsored| { let feature = sponsored.feature.as_note(); - tracing::info!( + info!( + error.as_ref(), target: LOG_TARGET, - { - note.id = %feature.id(), - nullifier = %feature.nullifier(), - err = %error_msg, - }, "note failed: transaction execution error", + note.id = feature.id(), + note.nullifier = feature.nullifier() ); (feature.nullifier(), error.clone()) }) @@ -794,10 +791,10 @@ impl AccountActor { .await .context("failed to reload account after a rejected submission")? { - tracing::info!( + info!( target: LOG_TARGET, - %account_id, "reloaded account from the database after a rejected submission", + account.id = account_id ); *account = Arc::new(latest); } @@ -889,14 +886,12 @@ fn log_oversized_notes(oversized: Vec) -> Vec { oversized .into_iter() .map(|note| { - tracing::warn!( + warn!( target: LOG_TARGET, - { - note.id = %note.note().id(), - nullifier = %note.note().nullifier(), - num_cycles = %format_opt(note.num_cycles().as_ref()), - }, "note discarded: exceeds the per-tx cycle budget on its own and can never be consumed", + note.id = note.note().id(), + note.nullifier = note.note().nullifier(), + note.execution_cycles = format_opt(note.num_cycles().as_ref()) ); note.note().nullifier() }) @@ -910,14 +905,12 @@ fn log_oversized_notes(oversized: Vec) -> Vec { /// round with their `attempt_count` untouched. fn log_deferred_notes(deferred: Vec) { for note in deferred { - tracing::info!( + info!( target: LOG_TARGET, - { - note.id = %note.note().id(), - nullifier = %note.note().nullifier(), - num_cycles = %format_opt(note.num_cycles().as_ref()), - }, "note deferred: exceeded per-tx cycle budget, will retry next round", + note.id = note.note().id(), + note.nullifier = note.note().nullifier(), + note.execution_cycles = format_opt(note.num_cycles().as_ref()) ); } } @@ -935,14 +928,12 @@ fn attribute_failed_notes( let mut attributed = Vec::new(); for f in failed { let error_msg = f.error().as_report(); - tracing::info!( + info!( + f.error(), target: LOG_TARGET, - { - note.id = %f.note().id(), - nullifier = %f.note().nullifier(), - err = %error_msg, - }, "note failed: consumability check", + note.id = f.note().id(), + note.nullifier = f.note().nullifier() ); let nullifier = sponsor_to_feature .get(&f.note().id()) diff --git a/bin/ntx-builder/src/builder.rs b/bin/ntx-builder/src/builder.rs index 0af18fe191..a6e2a8ff01 100644 --- a/bin/ntx-builder/src/builder.rs +++ b/bin/ntx-builder/src/builder.rs @@ -5,7 +5,7 @@ use anyhow::Context; use futures::Stream; use miden_node_utils::shutdown::CancellationToken; use miden_node_utils::tasks::Tasks; -use miden_node_utils::tracing::miden_instrument; +use miden_node_utils::tracing::{info, miden_instrument}; use miden_protocol::account::AccountId; use miden_protocol::block::{BlockNumber, SignedBlock}; use tokio::net::TcpListener; @@ -140,10 +140,10 @@ impl NetworkTransactionBuilder { if local_tip == committed_tip { self.is_synced = true; - tracing::info!( + info!( target: LOG_TARGET, - { block.number = %committed_tip }, - "ntx-builder is now in sync" + "ntx-builder is now in sync", + block.number = committed_tip ); break; } @@ -157,10 +157,10 @@ impl NetworkTransactionBuilder { .accounts_with_pending_notes(max_note_attempts) .await .context("failed to load accounts with pending notes at catch-up")?; - tracing::info!( + info!( target: LOG_TARGET, - num_accounts = pending_accounts.len(), "spawning actors for accounts with carry-over pending notes", + account.ids.count = pending_accounts.len() ); for account_id in pending_accounts { self.coordinator.spawn_actor_when_committed(account_id).await?; @@ -200,10 +200,10 @@ impl NetworkTransactionBuilder { }, SteadyStateAction::Respawn(respawn) => { if let Some(account_id) = respawn { - tracing::info!( + info!( target: LOG_TARGET, - { account.id = %account_id }, "respawning actor that shut down with a pending notification", + account.id = account_id ); self.coordinator.spawn_actor(account_id); } diff --git a/bin/ntx-builder/src/chain_state.rs b/bin/ntx-builder/src/chain_state.rs index f27cd88307..7cb996e55c 100644 --- a/bin/ntx-builder/src/chain_state.rs +++ b/bin/ntx-builder/src/chain_state.rs @@ -1,5 +1,6 @@ use std::sync::{Arc, RwLock}; +use miden_node_utils::tracing::debug; use miden_protocol::block::{BlockHeader, BlockNumber}; use miden_protocol::crypto::merkle::mmr::PartialMmr; use miden_protocol::transaction::PartialBlockchain; @@ -59,11 +60,11 @@ impl ChainState { // Skip blocks already reflected in the chain state. The builder may load state during // startup before receiving the same block from the committed-block subscription. if tip.block_num() <= self.chain_tip_header.block_num() { - tracing::debug!( + debug!( target: LOG_TARGET, - event_block = %tip.block_num(), - current_tip = %self.chain_tip_header.block_num(), "Skipping committed block already reflected in chain state", + block.number = tip.block_num(), + tip.number = self.chain_tip_header.block_num() ); return; } diff --git a/bin/ntx-builder/src/clients/rpc.rs b/bin/ntx-builder/src/clients/rpc.rs index a79c259278..3b214e1c9c 100644 --- a/bin/ntx-builder/src/clients/rpc.rs +++ b/bin/ntx-builder/src/clients/rpc.rs @@ -24,7 +24,7 @@ use miden_node_proto::generated::rpc::{BlockSubscriptionRequest, BlockSubscripti use miden_node_proto::generated::{self as proto}; use miden_node_utils::ErrorReport; use miden_node_utils::retry::{self, Retryable}; -use miden_node_utils::tracing::miden_instrument; +use miden_node_utils::tracing::{debug, info, miden_instrument, warn}; use miden_protocol::Word; use miden_protocol::account::{ AccountCode, @@ -44,7 +44,6 @@ use miden_protocol::utils::serde::{Deserializable, Serializable}; use thiserror::Error; use tonic::Status; use tonic::metadata::AsciiMetadataValue; -use tracing::{info}; use url::Url; use crate::COMPONENT; @@ -122,7 +121,12 @@ impl RpcClient { backoff_initial: Duration, backoff_max: Duration, ) -> anyhow::Result { - info!(target: COMPONENT, rpc_endpoint = %rpc_url, "Initializing RPC client"); + info!( + target: COMPONENT, + "Initializing RPC client", + dependency.name = "rpc", + dependency.endpoint = rpc_url.to_string() + ); let builder = Builder::new(rpc_url) .with_tls()? @@ -215,11 +219,11 @@ impl RpcClient { }) .retry(self.backoff) .notify(|err: &RpcError, dur| { - tracing::warn!( + warn!( + err, target: COMPONENT, - sleep_ms = dur.as_millis() as u64, - err = %err.as_report(), "RPC connection failed while opening block subscription, retrying", + retry.delay_ms = dur.as_millis() as u64 ); }) .await @@ -247,9 +251,10 @@ impl RpcClient { Some(stream) => stream, None => match client.block_subscription_with_retry(next_from).await { Ok(stream) => { - tracing::info!( - target: COMPONENT, %next_from, + info!( + target: COMPONENT, "block subscription connected", + block.from = next_from ); // Reset the stall clock so time spent (re)connecting is not counted // against the next block's arrival. @@ -257,9 +262,11 @@ impl RpcClient { inner.insert(stream) }, Err(err) => { - tracing::warn!( - target: COMPONENT, err = %err.as_report(), %next_from, + warn!( + &err, + target: COMPONENT, "failed to open block subscription, retrying", + block.from = next_from ); tokio::time::sleep(RECONNECT_DELAY).await; continue; @@ -279,31 +286,36 @@ impl RpcClient { (client, next_from, inner, last_block), )); }, - Ok(Some(Err(err))) => tracing::warn!( - target: COMPONENT, err = %err.as_report(), %next_from, + Ok(Some(Err(err))) => warn!( + &err, + target: COMPONENT, "block subscription failed, reconnecting", + block.from = next_from ), - Ok(None) => tracing::warn!( - target: COMPONENT, %next_from, + Ok(None) => warn!( + target: COMPONENT, "block subscription closed by node, reconnecting", + block.from = next_from ), Err(_elapsed) => { let idle = last_block.elapsed(); if idle < STALL_TIMEOUT { // Quiet but not yet stalled: emit a liveness signal and keep // polling the same stream instead of reconnecting. - tracing::debug!( - target: COMPONENT, %next_from, - idle = %humantime::format_duration(Duration::from_secs(idle.as_secs())), + debug!( + target: COMPONENT, "no block received recently; subscription still open", + block.from = next_from, + subscription.idle_ms = idle.as_millis() as u64 ); continue; } - tracing::warn!( - target: COMPONENT, %next_from, - idle = %humantime::format_duration(Duration::from_secs(idle.as_secs())), - stall_timeout = %humantime::format_duration(STALL_TIMEOUT), + warn!( + target: COMPONENT, "no block received within stall timeout; treating subscription as stalled, reconnecting", + block.from = next_from, + subscription.idle_ms = idle.as_millis() as u64, + subscription.stall_timeout_ms = STALL_TIMEOUT.as_millis() as u64 ); }, } @@ -361,11 +373,11 @@ impl RpcClient { .when(|status: &Status| status.code() == tonic::Code::FailedPrecondition) .notify(|status: &Status, _| { stale_key.store(true, Ordering::Relaxed); - tracing::warn!( + warn!( + status, target: COMPONENT, - %tx_id, - err = %status.message(), "Transaction inputs rejected as stale, refreshing the encryption key and retrying", + transaction.id = tx_id ); }) .await diff --git a/bin/ntx-builder/src/commands/mod.rs b/bin/ntx-builder/src/commands/mod.rs index e2275db0c9..12cc52104e 100644 --- a/bin/ntx-builder/src/commands/mod.rs +++ b/bin/ntx-builder/src/commands/mod.rs @@ -12,6 +12,7 @@ use miden_node_utils::fs::ensure_empty_directory; use miden_node_utils::genesis::{OfficialNetwork, fetch_genesis_block, read_genesis_block}; use miden_node_utils::logging::OpenTelemetry; use miden_node_utils::shutdown::CancellationToken; +use miden_node_utils::tracing::info; use tokio::net::TcpListener; use tonic::metadata::AsciiMetadataValue; use url::Url; @@ -168,23 +169,21 @@ impl NtxBuilderCommand { genesis_block_file, network, } => { - tracing::info!( + info!( target: miden_ntx_builder::LOG_TARGET, - { - service.name = "miden-ntx-builder", - service.version = env!("CARGO_PKG_VERSION"), - genesis.source.kind = - if genesis_block_file.is_some() { "file" } else { "network" }, - genesis.source = %genesis_block_file.as_ref().map_or_else( - || network.map_or_else( - || "custom".to_owned(), - |network| network.to_string(), - ), - |path| path.display().to_string(), - ), - data.directory = %data_directory.display(), - }, "Bootstrapping NTX builder", + service.name = "miden-ntx-builder", + service.version = env!("CARGO_PKG_VERSION"), + genesis.source.kind = + if genesis_block_file.is_some() { "file" } else { "network" }, + genesis.source = genesis_block_file.as_ref().map_or_else( + || network.map_or_else( + || "custom".to_owned(), + |network| network.to_string(), + ), + |path| path.display().to_string(), + ), + data.directory = data_directory.as_path() ); ensure_empty_directory(&data_directory)?; let database_filepath = data_directory.join("ntx-builder.sqlite3"); @@ -194,13 +193,11 @@ impl NtxBuilderCommand { miden_ntx_builder::bootstrap(database_filepath, &genesis) .await .context("failed to bootstrap ntx-builder database")?; - tracing::info!( + info!( target: miden_ntx_builder::LOG_TARGET, - { - genesis.commitment = %genesis_commitment, - data.directory = %data_directory.display(), - }, "NTX builder bootstrap complete", + genesis.commitment = genesis_commitment, + data.directory = data_directory.as_path() ); Ok(()) }, @@ -229,22 +226,20 @@ impl NtxBuilderCommand { unreachable!("start is only called for the Start variant") }; - tracing::info!( + info!( target: miden_ntx_builder::LOG_TARGET, - { - service.name = "miden-ntx-builder", - service.version = env!("CARGO_PKG_VERSION"), - ntx_builder.listen = %listen, - data.directory = %data_directory.display(), - rpc.endpoint = %format_endpoint(&rpc_url), - tx_prover.endpoint = %format_endpoint(&tx_prover_url), - rpc.authentication.configured = rpc_auth_header_value.is_some(), - ntx_builder.idle_timeout = %humantime::Duration::from(idle_timeout), - ntx_builder.max_cycles = max_tx_cycles, - ntx_builder.tx_expiration_delta = tx_expiration_delta.get(), - sqlite.connection_pool_size = sqlite_connection_pool_size.get(), - }, "Starting NTX builder", + service.name = "miden-ntx-builder", + service.version = env!("CARGO_PKG_VERSION"), + ntx_builder.listen = listen.to_string(), + data.directory = data_directory.as_path(), + rpc.endpoint = format_endpoint(&rpc_url), + tx_prover.endpoint = format_endpoint(&tx_prover_url), + rpc.authentication.configured = rpc_auth_header_value.is_some(), + ntx_builder.idle_timeout = humantime::Duration::from(idle_timeout).to_string(), + ntx_builder.max_cycles = max_tx_cycles, + ntx_builder.tx_expiration_delta = tx_expiration_delta.get(), + db.sqlite.connection_pool_size = sqlite_connection_pool_size.get() ); let listener = TcpListener::bind(listen) diff --git a/bin/ntx-builder/src/coordinator.rs b/bin/ntx-builder/src/coordinator.rs index 3916942b73..e55144daaf 100644 --- a/bin/ntx-builder/src/coordinator.rs +++ b/bin/ntx-builder/src/coordinator.rs @@ -3,7 +3,7 @@ use std::sync::Arc; use anyhow::Context; use miden_node_utils::shutdown::CancellationToken; -use miden_node_utils::tracing::miden_instrument; +use miden_node_utils::tracing::{debug, error, info, miden_instrument, warn}; use miden_protocol::account::AccountId; use miden_protocol::block::BlockNumber; use miden_protocol::transaction::TransactionId; @@ -149,22 +149,21 @@ impl Coordinator { if let Some(&count) = self.crash_counts.get(&account_id) && count >= self.max_account_crashes { - tracing::warn!( + warn!( target: LOG_TARGET, - { - account.id = %account_id, - crash_count = count, - }, - "Account deactivated due to repeated crashes, skipping actor spawn" + "Account deactivated due to repeated crashes, skipping actor spawn", + account.id = account_id, + account.crashes.count = count ); return; } if self.actor_registry.contains_key(&account_id) { - tracing::error!( + error!( + anyhow::anyhow!("account actor already exists"), target: LOG_TARGET, - { account.id = %account_id }, "Account actor already exists", + account.id = account_id ); return; } @@ -185,10 +184,10 @@ impl Coordinator { })); self.actor_registry.insert(account_id, handle); - tracing::debug!( + debug!( target: LOG_TARGET, - { account.id = %account_id }, - "Created actor for account" + "Created actor for account", + account.id = account_id ); } @@ -216,10 +215,10 @@ impl Coordinator { if committed { self.spawn_actor(account_id); } else { - tracing::info!( + info!( target: LOG_TARGET, - { account.id = %account_id }, "deferring actor spawn until the account's creation is committed", + account.id = account_id ); self.pending_spawns.insert(account_id); } @@ -307,19 +306,17 @@ impl Coordinator { Some(Ok((account_id, Err(err)))) => { let count = self.crash_counts.entry(account_id).or_insert(0); *count += 1; - tracing::error!( + error!( + &err, target: LOG_TARGET, - { - account.id = %account_id, - error = %format!("{err:#}"), - }, - "Account actor crashed" + "Account actor crashed", + account.id = account_id ); self.actor_registry.remove(&account_id); Ok(None) }, Some(Err(err)) => { - tracing::error!(target: LOG_TARGET, error = %err, "Actor task failed"); + error!(&err, target: LOG_TARGET, "Actor task failed"); Ok(None) }, None => { diff --git a/bin/ntx-builder/src/db/migrations.rs b/bin/ntx-builder/src/db/migrations.rs index a5ed38f39d..c8227543c0 100644 --- a/bin/ntx-builder/src/db/migrations.rs +++ b/bin/ntx-builder/src/db/migrations.rs @@ -1,7 +1,7 @@ use std::path::Path; use miden_node_db::DatabaseError; -use miden_node_utils::tracing::miden_instrument; +use miden_node_utils::tracing::{info, miden_instrument}; use crate::COMPONENT; @@ -14,10 +14,10 @@ include!(concat!(env!("OUT_DIR"), "/db_migrator.rs")); )] pub fn bootstrap_database(database_filepath: &Path) -> Result<(), DatabaseError> { let migrator = migrator().map_err(DatabaseError::migration)?; - tracing::info!( + info!( target: COMPONENT, - migration_count = migrator.schema_hashes().len(), - "Bootstrapping database schema" + "Bootstrapping database schema", + migration.count = migrator.schema_hashes().len() ); migrator.bootstrap(database_filepath).map_err(DatabaseError::migration)?; @@ -31,10 +31,10 @@ pub fn bootstrap_database(database_filepath: &Path) -> Result<(), DatabaseError> )] pub fn migrate_database(database_filepath: &Path) -> Result<(), DatabaseError> { let migrator = migrator().map_err(DatabaseError::migration)?; - tracing::info!( + info!( target: COMPONENT, - migration_count = migrator.schema_hashes().len(), - "Applying database migrations" + "Applying database migrations", + migration.count = migrator.schema_hashes().len() ); migrator.migrate(database_filepath).map_err(DatabaseError::migration)?; @@ -48,10 +48,10 @@ pub fn migrate_database(database_filepath: &Path) -> Result<(), DatabaseError> { )] pub fn verify_latest_schema(database_filepath: &Path) -> Result<(), DatabaseError> { let migrator = migrator().map_err(DatabaseError::migration)?; - tracing::info!( + info!( target: COMPONENT, - migration_count = migrator.schema_hashes().len(), - "Verifying database schema" + "Verifying database schema", + migration.count = migrator.schema_hashes().len() ); migrator diff --git a/bin/ntx-builder/src/db/mod.rs b/bin/ntx-builder/src/db/mod.rs index 3b8b5d1298..7fd438ed76 100644 --- a/bin/ntx-builder/src/db/mod.rs +++ b/bin/ntx-builder/src/db/mod.rs @@ -5,7 +5,7 @@ use std::path::{Path, PathBuf}; use anyhow::Context; use miden_node_db::DatabaseError; use miden_node_db::sqlite::{DbReader, DbWriter}; -use miden_node_utils::tracing::miden_instrument; +use miden_node_utils::tracing::{info, miden_instrument}; use miden_protocol::Word; use miden_protocol::account::{Account, AccountId}; use miden_protocol::block::{BlockHeader, BlockNumber, SignedBlock, ValidatorKeys}; @@ -15,7 +15,6 @@ use miden_protocol::note::{Note, NoteId, NoteScript, Nullifier}; use miden_protocol::transaction::TransactionId; #[cfg(test)] use miden_standards::note::AccountTargetNetworkNote; -use tracing::info; use crate::committed_block::CommittedBlockEffects; use crate::db::migrations::{bootstrap_database, migrate_database, verify_latest_schema}; @@ -316,9 +315,9 @@ fn open_with_pool_size( info!( target: COMPONENT, - sqlite = %database_filepath.display(), - connection_pool_size = %connection_pool_size, - "Connected to the database" + "Connected to the database", + path = database_filepath, + db.sqlite.connection_pool_size = connection_pool_size.get() ); Ok(NtxDbWriter { writer, reader: NtxDbReader { reader } }) diff --git a/bin/ntx-builder/src/lib.rs b/bin/ntx-builder/src/lib.rs index c79b8d7239..f35d877625 100644 --- a/bin/ntx-builder/src/lib.rs +++ b/bin/ntx-builder/src/lib.rs @@ -11,6 +11,7 @@ use miden_node_store::genesis::GenesisBlock; use miden_node_utils::ErrorReport; use miden_node_utils::lru_cache::LruCache; use miden_node_utils::shutdown::CancellationToken; +use miden_node_utils::tracing::debug; use tokio::sync::mpsc; use tonic::metadata::AsciiMetadataValue; use url::Url; @@ -439,10 +440,10 @@ impl NtxBuilderConfig { let block_from = last_applied_block.child(); - tracing::debug!( + debug!( target: LOG_TARGET, - %block_from, - "ntx-builder opening committed-block subscription" + "ntx-builder opening committed-block subscription", + block.from = block_from ); // The stream reconnects on its own whenever the node closes the subscription, resuming from diff --git a/bin/ntx-builder/src/server.rs b/bin/ntx-builder/src/server.rs index a84df05d22..a1f5fa1649 100644 --- a/bin/ntx-builder/src/server.rs +++ b/bin/ntx-builder/src/server.rs @@ -4,6 +4,7 @@ use miden_node_proto_build::ntx_builder_api_descriptor; use miden_node_utils::panic::{CatchPanicLayer, catch_panic_layer_fn}; use miden_node_utils::shutdown::CancellationToken; use miden_node_utils::tracing::grpc::grpc_trace_fn; +use miden_node_utils::tracing::info; use tokio::net::TcpListener; use tokio_stream::wrappers::TcpListenerStream; use tonic_reflection::server; @@ -45,14 +46,12 @@ impl NtxBuilderRpcServer { let endpoint = listener.local_addr().context("failed to read NTX builder listen address")?; - tracing::info!( + info!( target: LOG_TARGET, - { - service.name = "miden-ntx-builder", - service.version = env!("CARGO_PKG_VERSION"), - ntx_builder.listen = %endpoint, - }, "NTX builder ready", + service.name = "miden-ntx-builder", + service.version = env!("CARGO_PKG_VERSION"), + ntx_builder.listen = endpoint.to_string() ); tonic::transport::Server::builder() diff --git a/bin/ntx-builder/src/server/get_network_note_status.rs b/bin/ntx-builder/src/server/get_network_note_status.rs index cb064d8568..d6fc261986 100644 --- a/bin/ntx-builder/src/server/get_network_note_status.rs +++ b/bin/ntx-builder/src/server/get_network_note_status.rs @@ -1,4 +1,5 @@ use miden_node_proto::generated::{self as grpc, rpc}; +use miden_node_utils::tracing::error; use miden_protocol::Word; use super::NtxBuilderRpcServer; @@ -34,12 +35,14 @@ impl grpc::server::ntx_builder_api::GetNetworkNoteStatus for NtxBuilderRpcServer _metadata: &tonic::metadata::MetadataMap, _extensions: &tonic::codegen::http::Extensions, ) -> tonic::Result { - let row = self - .db.get_note_status(note_id).await - .map_err(|err| { - tracing::error!(target: LOG_TARGET, error = %err, "Failed to query note status from DB"); - tonic::Status::internal("database error") - })?; + let row = self.db.get_note_status(note_id).await.map_err(|err| { + error!( + &err, + target: LOG_TARGET, + "Failed to query note status from DB" + ); + tonic::Status::internal("database error") + })?; let Some(row) = row else { return Err(tonic::Status::not_found("note not found in ntx-builder database")); diff --git a/bin/remote-prover/src/server/mod.rs b/bin/remote-prover/src/server/mod.rs index fa4c089704..abcc27dcdb 100644 --- a/bin/remote-prover/src/server/mod.rs +++ b/bin/remote-prover/src/server/mod.rs @@ -7,6 +7,7 @@ use miden_node_utils::logging::OpenTelemetry; use miden_node_utils::panic::catch_panic_layer_fn; use miden_node_utils::shutdown::CancellationToken; use miden_node_utils::tracing::grpc::grpc_trace_fn; +use miden_node_utils::tracing::info; use proof_kind::ProofKind; use tokio::net::TcpListener; use tokio::task::JoinHandle; @@ -70,17 +71,15 @@ impl Server { .expect("local address should exist for a tcp listener") .port(); - tracing::info!( + info!( target: LOG_TARGET, - { - service.name = "miden-remote-prover", - service.version = env!("CARGO_PKG_VERSION"), - prover.timeout = %humantime::Duration::from(self.timeout), - prover.capacity = self.capacity.get(), - prover.kind = %self.kind, - prover.port = port, - }, "Remote prover ready", + service.name = "miden-remote-prover", + service.version = env!("CARGO_PKG_VERSION"), + prover.timeout = humantime::Duration::from(self.timeout).to_string(), + prover.capacity = self.capacity.get(), + prover.kind = self.kind, + prover.port = port ); let status_service = diff --git a/bin/validator/src/commands/bootstrap.rs b/bin/validator/src/commands/bootstrap.rs index 5a858b1e14..5af9825742 100644 --- a/bin/validator/src/commands/bootstrap.rs +++ b/bin/validator/src/commands/bootstrap.rs @@ -6,6 +6,7 @@ use miden_node_store::BlockStore; use miden_node_store::genesis::GenesisBlock; use miden_node_utils::fs::ensure_empty_directory; use miden_node_utils::genesis::read_genesis_block; +use miden_node_utils::tracing::info; use miden_validator::DataDirectory; /// Runs the `bootstrap` command: seeds this validator's database from the genesis block file @@ -19,15 +20,13 @@ pub async fn bootstrap( sqlite_connection_pool_size: NonZeroUsize, genesis_block_file: &Path, ) -> anyhow::Result<()> { - tracing::info!( + info!( target: miden_validator::LOG_TARGET, - { - service.name = "miden-validator", - service.version = env!("CARGO_PKG_VERSION"), - genesis.file = %genesis_block_file.display(), - data.directory = %data_directory.display(), - }, "Bootstrapping validator", + service.name = "miden-validator", + service.version = env!("CARGO_PKG_VERSION"), + genesis.file = genesis_block_file, + data.directory = data_directory ); ensure_empty_directory(data_directory)?; @@ -51,13 +50,11 @@ pub async fn bootstrap( .await .context("failed to bootstrap the validator database")?; - tracing::info!( + info!( target: miden_validator::LOG_TARGET, - { - genesis.commitment = %genesis_commitment, - data.directory = %data_directory.display(), - }, "Validator bootstrap complete", + genesis.commitment = genesis_commitment, + data.directory = data_directory ); Ok(()) diff --git a/bin/validator/src/commands/mod.rs b/bin/validator/src/commands/mod.rs index 687135989e..5c36e9be73 100644 --- a/bin/validator/src/commands/mod.rs +++ b/bin/validator/src/commands/mod.rs @@ -15,6 +15,7 @@ use clap::Parser; use miden_node_utils::clap::GrpcOptions; use miden_node_utils::logging::OpenTelemetry; use miden_node_utils::shutdown::CancellationToken; +use miden_node_utils::tracing::info; use miden_protocol::crypto::dsa::ecdsa_k256_keccak::{PublicKey, SigningKey}; use miden_protocol::crypto::dsa::eddsa_25519_sha512::KeyExchangeKey; use miden_protocol::utils::serde::{Deserializable, Serializable}; @@ -292,21 +293,20 @@ impl ValidatorCommand { } => { let address = listen; let operator_key = storage_key.load()?; - tracing::info!( + info!( target: miden_validator::LOG_TARGET, - { - service.name = "miden-validator", - service.version = env!("CARGO_PKG_VERSION"), - validator.listen = %address, - validator.admin_listen = admin_listen.map_or_else( - || "disabled".to_owned(), - |address| address.to_string(), - ), - data.directory = %data_directory.display(), - validator.signer = if signing_key.signing_key_kms_id.is_some() { "kms" } else { "local" }, - sqlite.connection_pool_size = sqlite_connection_pool_size.get(), - }, "Starting validator", + service.name = "miden-validator", + service.version = env!("CARGO_PKG_VERSION"), + validator.listen = address.to_string(), + validator.admin_listen = admin_listen.map_or_else( + || "disabled".to_owned(), + |address| address.to_string(), + ), + data.directory = data_directory.as_path(), + validator.signer = + if signing_key.signing_key_kms_id.is_some() { "kms" } else { "local" }, + db.sqlite.connection_pool_size = sqlite_connection_pool_size.get() ); let decrypter = encryption_key.into_decrypter().await?; diff --git a/bin/validator/src/db/migrations.rs b/bin/validator/src/db/migrations.rs index 42ef9fad47..8ecfc5745f 100644 --- a/bin/validator/src/db/migrations.rs +++ b/bin/validator/src/db/migrations.rs @@ -1,7 +1,7 @@ use std::path::Path; use miden_node_db::DatabaseError; -use miden_node_utils::tracing::miden_instrument; +use miden_node_utils::tracing::{info, miden_instrument}; use crate::{COMPONENT, LOG_TARGET}; @@ -14,10 +14,10 @@ include!(concat!(env!("OUT_DIR"), "/db_migrator.rs")); )] pub fn bootstrap_database(database_filepath: &Path) -> std::result::Result<(), DatabaseError> { let migrator = migrator().map_err(DatabaseError::migration)?; - tracing::info!( + info!( target: LOG_TARGET, - migration_count = migrator.schema_hashes().len(), - "Bootstrapping database schema" + "Bootstrapping database schema", + migration.count = migrator.schema_hashes().len() ); migrator.bootstrap(database_filepath).map_err(DatabaseError::migration)?; @@ -31,10 +31,10 @@ pub fn bootstrap_database(database_filepath: &Path) -> std::result::Result<(), D )] pub fn migrate_database(database_filepath: &Path) -> std::result::Result<(), DatabaseError> { let migrator = migrator().map_err(DatabaseError::migration)?; - tracing::info!( + info!( target: LOG_TARGET, - migration_count = migrator.schema_hashes().len(), - "Applying database migrations" + "Applying database migrations", + migration.count = migrator.schema_hashes().len() ); migrator.migrate(database_filepath).map_err(DatabaseError::migration)?; @@ -48,10 +48,10 @@ pub fn migrate_database(database_filepath: &Path) -> std::result::Result<(), Dat )] pub fn verify_latest_schema(database_filepath: &Path) -> std::result::Result<(), DatabaseError> { let migrator = migrator().map_err(DatabaseError::migration)?; - tracing::info!( + info!( target: LOG_TARGET, - migration_count = migrator.schema_hashes().len(), - "Verifying database schema" + "Verifying database schema", + migration.count = migrator.schema_hashes().len() ); migrator diff --git a/bin/validator/src/db/mod.rs b/bin/validator/src/db/mod.rs index bca4d598bd..4b9a89dac9 100644 --- a/bin/validator/src/db/mod.rs +++ b/bin/validator/src/db/mod.rs @@ -3,7 +3,7 @@ use std::path::{Path, PathBuf}; use miden_node_db::DatabaseError; use miden_node_db::sqlite::{DbReader, DbWriter}; -use miden_node_utils::tracing::miden_instrument; +use miden_node_utils::tracing::{info, miden_instrument}; use miden_protocol::block::{BlockHeader, BlockNumber}; use miden_protocol::transaction::TransactionId; @@ -280,11 +280,11 @@ fn open_with_pool_size( ) -> Result { let (writer, reader) = miden_node_db::sqlite::open_with_pool_size(database_filepath, connection_pool_size)?; - tracing::info!( + info!( target: LOG_TARGET, - sqlite= %database_filepath.display(), - connection_pool_size = %connection_pool_size, - "Connected to the database" + "Connected to the database", + path = database_filepath, + db.sqlite.connection_pool_size = connection_pool_size.get() ); Ok(ValidatorDbWriter { writer, diff --git a/bin/validator/src/server/mod.rs b/bin/validator/src/server/mod.rs index ac7954342a..eb5264b0ea 100644 --- a/bin/validator/src/server/mod.rs +++ b/bin/validator/src/server/mod.rs @@ -8,6 +8,7 @@ use miden_node_utils::clap::GrpcOptions; use miden_node_utils::panic::catch_panic_layer_fn; use miden_node_utils::shutdown::CancellationToken; use miden_node_utils::tracing::grpc::grpc_trace_fn; +use miden_node_utils::tracing::info; use tokio::net::TcpListener; use tokio_stream::wrappers::TcpListenerStream; use tower_http::catch_panic::CatchPanicLayer; @@ -86,13 +87,11 @@ impl ValidatorAdminServer { ) -> anyhow::Result<()> { let endpoint = listener.local_addr().context("failed to read validator admin listen address")?; - tracing::info!( + info!( target: LOG_TARGET, - { - service.name = "miden-validator-admin", - validator.admin_listen = %endpoint, - }, "Validator admin server ready", + service.name = "miden-validator-admin", + validator.admin_listen = endpoint.to_string() ); axum::serve(listener, admin_service::router(self.operator_key, self.reader)) @@ -139,15 +138,13 @@ impl ValidatorServer { .await .context("failed to initialize validator server")?; let endpoint = listener.local_addr().context("failed to read validator listen address")?; - tracing::info!( + info!( target: LOG_TARGET, - { - service.name = "miden-validator", - service.version = env!("CARGO_PKG_VERSION"), - validator.listen = %endpoint, - block.number = metrics.chain_tip, - }, "Validator ready", + service.name = "miden-validator", + service.version = env!("CARGO_PKG_VERSION"), + validator.listen = endpoint.to_string(), + block.number = metrics.chain_tip ); // Build the gRPC server with the API service and trace layer. diff --git a/bin/validator/src/server/validator_service/block_subscription.rs b/bin/validator/src/server/validator_service/block_subscription.rs index 2747b87549..d740c5f83a 100644 --- a/bin/validator/src/server/validator_service/block_subscription.rs +++ b/bin/validator/src/server/validator_service/block_subscription.rs @@ -5,7 +5,7 @@ use std::task::{Context, Poll}; use miden_node_proto::generated as grpc; use miden_node_proto::generated::validator::BlockSubscriptionResponse; use miden_node_utils::ErrorReport; -use miden_node_utils::tracing::{miden_instrument, miden_span_record}; +use miden_node_utils::tracing::{error, info, miden_instrument, miden_span_record}; use miden_protocol::block::BlockNumber; use tokio::sync::OwnedRwLockWriteGuard; use tokio_stream::wrappers::ReceiverStream; @@ -89,12 +89,17 @@ impl grpc::server::validator_api::BlockSubscription for ValidatorService { }), Ok(None) => { Err(tonic::Status::not_found(format!("block {block} not found"))) - } + }, Err(err) => Err(tonic::Status::internal( err.as_report_context("failed to load block"), )), - }.inspect_err(|err| { - tracing::error!(block.number = %block, message = %err.message(), "failed to load block in validator recovery stream"); + } + .inspect_err(|err| { + error!( + &err, + "failed to load block in validator recovery stream", + block.number = block + ); }); // Errors are not recoverable so we abort the stream after informing the client. @@ -105,7 +110,7 @@ impl grpc::server::validator_api::BlockSubscription for ValidatorService { // and prevent the sending of the error response. let is_err = response.is_err(); if tx.send(response).await.is_err() || is_err { - tracing::info!("validator recovery stream closing"); + info!("validator recovery stream closing"); return; } } diff --git a/crates/block-producer/src/batch_builder/mod.rs b/crates/block-producer/src/batch_builder/mod.rs index c43e9cfb68..3092389f94 100644 --- a/crates/block-producer/src/batch_builder/mod.rs +++ b/crates/block-producer/src/batch_builder/mod.rs @@ -8,7 +8,7 @@ use miden_node_proto::domain::batch::BatchInputs; use miden_node_store::state::State; use miden_node_utils::shutdown::CancellationToken; use miden_node_utils::spawn::spawn_blocking_in_current_span; -use miden_node_utils::tracing::{ErrorSpanExt, miden_instrument, miden_span_record}; +use miden_node_utils::tracing::{ErrorSpanExt, error, miden_instrument, miden_span_record}; use miden_protocol::MIN_PROOF_SECURITY_LEVEL; use miden_protocol::batch::{BatchId, ProposedBatch, ProvenBatch}; use miden_protocol::transaction::TransactionId; @@ -220,7 +220,11 @@ impl BatchBuilder { Ok(Ok(())) => Ok(()), Ok(Err(err)) => Err(err), Err(crash) => { - tracing::error!(target: LOG_TARGET, message=%crash, "Batch worker pool panic'd"); + error!( + &crash, + target: LOG_TARGET, + "Batch worker pool panic'd" + ); panic!("Batch worker pool panic: {crash}"); }, } diff --git a/crates/block-producer/src/block_builder/mod.rs b/crates/block-producer/src/block_builder/mod.rs index 2ac4565815..dcb166a26a 100644 --- a/crates/block-producer/src/block_builder/mod.rs +++ b/crates/block-producer/src/block_builder/mod.rs @@ -3,10 +3,9 @@ use std::sync::Arc; use anyhow::Context; use miden_node_store::state::{BlockWriter, State}; -use miden_node_utils::formatting::format_array; use miden_node_utils::shutdown::CancellationToken; use miden_node_utils::spawn::spawn_blocking_in_current_span; -use miden_node_utils::tracing::{ErrorSpanExt, miden_instrument, miden_span_record}; +use miden_node_utils::tracing::{ErrorSpanExt, debug, miden_instrument, miden_span_record}; use miden_protocol::batch::{OrderedBatches, ProvenBatch}; use miden_protocol::block::{ BlockInputs, @@ -380,9 +379,11 @@ impl BlockBuilder { ); if num_transactions > 0 { - let transaction_ids = - signed_block.body().transactions().as_slice().iter().map(TransactionHeader::id); - tracing::debug!(target: LOG_TARGET, transactions = %format_array(transaction_ids), "Included transactions"); + debug!( + target: LOG_TARGET, + "Included transactions", + block.transaction.count = num_transactions + ); } self.block_writer diff --git a/crates/block-producer/src/mempool/mod.rs b/crates/block-producer/src/mempool/mod.rs index 6c0171c7a6..a85b2aeeb5 100644 --- a/crates/block-producer/src/mempool/mod.rs +++ b/crates/block-producer/src/mempool/mod.rs @@ -55,7 +55,7 @@ use std::num::NonZeroUsize; use std::sync::{Arc, LockResult, Mutex, MutexGuard}; use miden_node_utils::ErrorReport; -use miden_node_utils::tracing::{miden_instrument, miden_span_record}; +use miden_node_utils::tracing::{debug, miden_instrument, miden_span_record}; use miden_protocol::batch::{BatchId, ProvenBatch}; use miden_protocol::block::{BlockHeader, BlockNumber}; use miden_protocol::transaction::TransactionHeader; @@ -724,14 +724,12 @@ fn emit_transaction_added(tx: &AuthenticatedTransaction) { return; } - tracing::debug!( + debug!( target: LOG_TARGET, - { - transaction.id = %tx.id(), - account.id = %tx.account_id(), - transaction.expires_at = %tx.expires_at(), - }, "Transaction added to mempool", + transaction.id = tx.id(), + account.id = tx.account_id(), + transaction.expires_at = tx.expires_at() ); } @@ -741,13 +739,11 @@ fn emit_transaction_expirations(removal: &graph::TransactionRemoval, chain_tip: } for transaction_id in removal.direct() { - tracing::debug!( + debug!( target: LOG_TARGET, - { - transaction.id = %transaction_id, - block.number = %chain_tip, - }, "Transaction expired from mempool", + transaction.id = transaction_id, + block.number = chain_tip ); } @@ -764,13 +760,11 @@ fn emit_transaction_evictions( } for transaction_id in removal.direct() { - tracing::debug!( + debug!( target: LOG_TARGET, - { - transaction.id = %transaction_id, - mempool.removal.reason = direct_reason, - }, "Transaction evicted from mempool", + transaction.id = transaction_id, + mempool.removal.reason = direct_reason ); } @@ -779,13 +773,11 @@ fn emit_transaction_evictions( fn emit_dependent_transaction_evictions(removal: &graph::TransactionRemoval, reason: &'static str) { for transaction_id in removal.dependents() { - tracing::debug!( + debug!( target: LOG_TARGET, - { - transaction.id = %transaction_id, - mempool.removal.reason = reason, - }, "Transaction evicted from mempool", + transaction.id = transaction_id, + mempool.removal.reason = reason ); } } diff --git a/crates/block-producer/src/proof_scheduler.rs b/crates/block-producer/src/proof_scheduler.rs index 803b2290f3..d283fc54fb 100644 --- a/crates/block-producer/src/proof_scheduler.rs +++ b/crates/block-producer/src/proof_scheduler.rs @@ -21,13 +21,13 @@ use miden_node_proto::BlockProofRequest; use miden_node_store::state::{ProofWriter, State}; use miden_node_utils::retry::{self, Retryable}; use miden_node_utils::shutdown::CancellationToken; -use miden_node_utils::tracing::miden_instrument; +use miden_node_utils::tracing::{debug, info, miden_instrument}; use miden_protocol::block::{BlockNumber, BlockProof}; use miden_protocol::utils::serde::{Deserializable, Serializable}; use thiserror::Error; use tokio::sync::watch; use tokio::task::JoinSet; -use tracing::{Instrument, debug, info}; +use tracing::Instrument; use crate::block_prover::{BlockProver, ProverError}; use crate::errors::ProofSchedulerError; diff --git a/crates/block-producer/src/rpc_sync.rs b/crates/block-producer/src/rpc_sync.rs index 210ef0ae0c..2fdb604cf6 100644 --- a/crates/block-producer/src/rpc_sync.rs +++ b/crates/block-producer/src/rpc_sync.rs @@ -9,13 +9,13 @@ use miden_node_store::state::{BlockWriter, ProofWriter, State}; use miden_node_utils::retry::{self, RetryableWithContext}; use miden_node_utils::shutdown::CancellationToken; use miden_node_utils::tasks::Tasks; -use miden_node_utils::tracing::miden_instrument; +use miden_node_utils::tracing::{debug, info, miden_instrument, warn}; use miden_protocol::block::{BlockNumber, SignedBlock}; use miden_protocol::utils::serde::Deserializable; use tokio_stream::StreamExt; use tonic_health::ServingStatus; use tonic_health::server::HealthReporter; -use tracing::{Instrument, info, info_span, warn}; +use tracing::{Instrument, info_span}; use crate::{COMPONENT, LOG_TARGET}; @@ -72,40 +72,34 @@ impl RpcReadiness { ReadinessTransition::BecameReady => { info!( target: LOG_TARGET, - { - service.name = "miden-node", - service.version = env!("CARGO_PKG_VERSION"), - node.role = "full", - block.number = %local_tip, - sync.upstream_block = %upstream_tip, - sync.block_gap = gap, - sync.ready_threshold = self.threshold, - }, "Node ready", + service.name = "miden-node", + service.version = env!("CARGO_PKG_VERSION"), + node.role = "full", + block.number = local_tip, + sync.upstream_block = upstream_tip, + sync.block_gap = gap, + sync.ready_threshold = self.threshold ); }, ReadinessTransition::BecameNotReady => { warn!( target: LOG_TARGET, - { - block.number = %local_tip, - sync.upstream_block = %upstream_tip, - sync.block_gap = gap, - sync.ready_threshold = self.threshold, - }, "Node no longer ready", + block.number = local_tip, + sync.upstream_block = upstream_tip, + sync.block_gap = gap, + sync.ready_threshold = self.threshold ); }, ReadinessTransition::InitialNotReady => { - tracing::debug!( + debug!( target: LOG_TARGET, - { - block.number = %local_tip, - sync.upstream_block = %upstream_tip, - sync.block_gap = gap, - sync.ready_threshold = self.threshold, - }, "Node synchronizing", + block.number = local_tip, + sync.upstream_block = upstream_tip, + sync.block_gap = gap, + sync.ready_threshold = self.threshold ); }, ReadinessTransition::Unchanged => {}, @@ -192,10 +186,10 @@ impl BlockSync { .context(self) .notify(|err, _| { warn!( + err, target: LOG_TARGET, - err = %format!("{err:#}"), - retry.delay = %RECONNECT_DELAY.as_secs(), "Block sync failed, retrying", + retry.delay_ms = RECONNECT_DELAY.as_millis() as u64 ); }); @@ -217,7 +211,11 @@ impl BlockSync { self.readiness.update(upstream_tip, local_tip).await; let block_from = local_tip.child().as_u32(); - info!(target: LOG_TARGET, block_from, "Connecting to upstream RPC for blocks"); + info!( + target: LOG_TARGET, + "Connecting to upstream RPC for blocks", + block.from = block_from + ); let mut stream = client .block_subscription(BlockSubscriptionRequest { block_from }) @@ -284,10 +282,10 @@ impl ProofSync { .context(self) .notify(|err, _| { warn!( + err, target: LOG_TARGET, - err = %format!("{err:#}"), - retry.delay = %RECONNECT_DELAY.as_secs(), "Proof sync failed, retrying", + retry.delay_ms = RECONNECT_DELAY.as_millis() as u64 ); }); @@ -302,8 +300,8 @@ impl ProofSync { let starting_block = self.state.proven_tip().child(); info!( target: LOG_TARGET, - block_from = %starting_block, - "Subscribing to block proof stream" + "Subscribing to block proof stream", + block.from = starting_block ); let mut client = self.source_rpc.clone(); let mut stream = client diff --git a/crates/block-producer/src/server/mod.rs b/crates/block-producer/src/server/mod.rs index bc506550e5..fbfb8096a0 100644 --- a/crates/block-producer/src/server/mod.rs +++ b/crates/block-producer/src/server/mod.rs @@ -7,7 +7,7 @@ use miden_node_store::state::{BlockWriter, ProofWriter, State}; use miden_node_utils::formatting::{format_input_notes, format_output_notes}; use miden_node_utils::shutdown::CancellationToken; use miden_node_utils::tasks::Tasks; -use miden_node_utils::tracing::miden_instrument; +use miden_node_utils::tracing::{debug, error, info, miden_instrument}; use miden_protocol::batch::ProposedBatch; use miden_protocol::block::BlockNumber; use miden_protocol::transaction::ProvenTransaction; @@ -107,13 +107,13 @@ pub struct Sequencer { impl Sequencer { /// Spawns the sequencer tasks and returns its in-process API. pub fn spawn(self, shutdown: CancellationToken) -> Result { - tracing::info!(target: LOG_TARGET, "Initializing sequencer"); + info!(target: LOG_TARGET, "Initializing sequencer"); let state = self.state; let validator = BlockProducerValidatorClient::new(self.validator_urls.clone(), self.validator_timeout)?; let chain_tip = state.committed_tip(); - tracing::info!(target: LOG_TARGET, "Sequencer initialized"); + info!(target: LOG_TARGET, "Sequencer initialized"); let block_builder = BlockBuilder::new( Arc::clone(&state), @@ -297,7 +297,8 @@ impl BlockProducerApi { let stats = { let Ok(mempool) = mempool.lock() else { - tracing::error!( + error!( + anyhow::anyhow!("mempool lock poisoned"), target: LOG_TARGET, "Mempool lock poisoned, stopping mempool stats updater" ); @@ -324,18 +325,18 @@ impl BlockProducerApi { &self, tx: ProvenTransaction, ) -> Result { - tracing::debug!( + debug!( target: LOG_TARGET, - tx_id = %tx.id().to_hex(), - account_id = %tx.account_id().to_hex(), - initial_state_commitment = %tx.account_update().initial_state_commitment(), - final_state_commitment = %tx.account_update().final_state_commitment(), - input_notes = %format_input_notes(tx.input_notes()), - output_notes = %format_output_notes(tx.output_notes()), - ref_block_commitment = %tx.ref_block_commitment(), - "Submitting transaction" + "Submitting transaction", + transaction.id = tx.id(), + account.id = tx.account_id(), + account.initial_state.commitment = tx.account_update().initial_state_commitment(), + account.final_state.commitment = tx.account_update().final_state_commitment(), + transaction.input_notes = format_input_notes(tx.input_notes()), + transaction.output_notes = format_output_notes(tx.output_notes()), + transaction.reference_block.commitment = tx.ref_block_commitment() ); - tracing::debug!(target: COMPONENT, proof = ?tx.proof()); + debug!(target: COMPONENT, "Transaction proof received"); // Authenticate against the local store, then add to the mempool. let inputs = get_tx_inputs(&self.state, &tx) diff --git a/crates/block-producer/src/store/mod.rs b/crates/block-producer/src/store/mod.rs index 1fd81f1c2d..c3af75fc07 100644 --- a/crates/block-producer/src/store/mod.rs +++ b/crates/block-producer/src/store/mod.rs @@ -9,7 +9,7 @@ use miden_node_proto::errors::ConversionError; use miden_node_proto::generated::sequencer; use miden_node_store::state::{State, TransactionInputs as StoreTransactionInputs}; use miden_node_utils::formatting::format_opt; -use miden_node_utils::tracing::miden_instrument; +use miden_node_utils::tracing::{debug, miden_instrument}; use miden_protocol::Word; use miden_protocol::account::AccountId; use miden_protocol::block::BlockNumber; @@ -211,7 +211,7 @@ pub async fn get_tx_inputs( *current_block_height, ); - tracing::debug!(target: LOG_TARGET, tx_inputs = %tx_inputs, "Transaction inputs"); + debug!(target: LOG_TARGET, "Transaction inputs loaded"); Ok(tx_inputs) } diff --git a/crates/block-producer/src/validator/mod.rs b/crates/block-producer/src/validator/mod.rs index 1fdf49498e..9889e35ef6 100644 --- a/crates/block-producer/src/validator/mod.rs +++ b/crates/block-producer/src/validator/mod.rs @@ -4,13 +4,12 @@ use miden_node_proto::clients::{Builder, ValidatorClient}; use miden_node_proto::decode::GrpcDecodeExt; use miden_node_proto::errors::ConversionError; use miden_node_proto::{decode, generated as proto}; -use miden_node_utils::tracing::miden_instrument; +use miden_node_utils::tracing::{info, miden_instrument}; use miden_protocol::Word; use miden_protocol::block::ProposedBlock; use miden_protocol::crypto::dsa::ecdsa_k256_keccak::{PublicKey, Signature}; use miden_protocol::utils::serde::Serializable; use thiserror::Error; -use tracing::info; use url::Url; use crate::{COMPONENT, LOG_TARGET}; @@ -58,7 +57,12 @@ impl BlockProducerValidatorClient { let clients = validator_urls .into_iter() .map(|validator_url| { - info!(target: LOG_TARGET, validator_endpoint = %validator_url, "Initializing validator client"); + info!( + target: LOG_TARGET, + "Initializing validator client", + dependency.name = "validator", + dependency.endpoint = validator_url.to_string() + ); Ok(Builder::new(validator_url) .with_tls()? diff --git a/crates/proto/src/clients/mod.rs b/crates/proto/src/clients/mod.rs index 8f1a0b4f2a..4ece361610 100644 --- a/crates/proto/src/clients/mod.rs +++ b/crates/proto/src/clients/mod.rs @@ -32,6 +32,7 @@ use std::time::Duration; use http::header::ACCEPT; use miden_node_utils::tracing::grpc::OtelInterceptor; +use miden_node_utils::tracing::{debug, info, warn}; use miden_protocol::Word; use miden_protocol::batch::ProposedBatch; use miden_protocol::utils::serde::Serializable; @@ -568,44 +569,44 @@ impl Builder { match result { Ok(Ok(_client)) => { - tracing::info!( - dependency.name = dependency_name, - dependency.endpoint = %endpoint, + info!( "Configured service reachable", + dependency.name = dependency_name, + dependency.endpoint = endpoint.as_str() ); shutdown.cancelled().await; return; }, Ok(Err(err)) if first_failure => { - tracing::warn!( - dependency.name = dependency_name, - dependency.endpoint = %endpoint, - %err, + warn!( + &err, "Configured service unreachable", + dependency.name = dependency_name, + dependency.endpoint = endpoint.as_str() ); }, Err(_elapsed) if first_failure => { - tracing::warn!( - dependency.name = dependency_name, - dependency.endpoint = %endpoint, - timeout = ?CONNECT_TIMEOUT, + warn!( "Configured service connection timed out", + dependency.name = dependency_name, + dependency.endpoint = endpoint.as_str(), + timeout.ms = CONNECT_TIMEOUT.as_millis() as u64 ); }, Ok(Err(err)) => { - tracing::debug!( - dependency.name = dependency_name, - dependency.endpoint = %endpoint, - %err, + debug!( + &err, "Configured service still unreachable", + dependency.name = dependency_name, + dependency.endpoint = endpoint.as_str() ); }, Err(_elapsed) => { - tracing::debug!( - dependency.name = dependency_name, - dependency.endpoint = %endpoint, - timeout = ?CONNECT_TIMEOUT, + debug!( "Configured service connection still timing out", + dependency.name = dependency_name, + dependency.endpoint = endpoint.as_str(), + timeout.ms = CONNECT_TIMEOUT.as_millis() as u64 ); }, } diff --git a/crates/rpc/src/server/api.rs b/crates/rpc/src/server/api.rs index 46d24b73cd..cdfbf72915 100644 --- a/crates/rpc/src/server/api.rs +++ b/crates/rpc/src/server/api.rs @@ -22,7 +22,7 @@ use miden_node_utils::limiter::{ }; use miden_node_utils::lru_cache::LruCache; use miden_node_utils::retry::{self, Retryable}; -use miden_node_utils::tracing::miden_instrument; +use miden_node_utils::tracing::{miden_instrument, warn}; use miden_protocol::Word; use miden_protocol::account::AccountId; use miden_protocol::block::{BlockHeader, BlockNumber}; @@ -173,11 +173,11 @@ impl RpcService { .retry(retry::exponential(Duration::from_millis(500), Duration::from_secs(30))) .when(|err| err.code() == tonic::Code::Unavailable) .notify(|err, backoff| { - tracing::warn!( + warn!( + err, target: LOG_TARGET, - ?backoff, - %err, - "connection failed while fetching genesis header, retrying" + "connection failed while fetching genesis header, retrying", + retry.delay_ms = backoff.as_millis() as u64 ); }) .await?; diff --git a/crates/rpc/src/server/api/get_account.rs b/crates/rpc/src/server/api/get_account.rs index cfbd63a183..09bd2f4297 100644 --- a/crates/rpc/src/server/api/get_account.rs +++ b/crates/rpc/src/server/api/get_account.rs @@ -9,9 +9,9 @@ use miden_node_proto::domain::account::{ use miden_node_proto::generated as proto; use miden_node_store::GetAccountError; use miden_node_utils::limiter::{QueryParamStorageMapKeyTotalLimit, QueryParamStorageMapSlotLimit}; -use miden_node_utils::tracing::{miden_instrument, miden_span_record}; +use miden_node_utils::tracing::{debug, miden_instrument, miden_span_record}; use tonic::Status; -use tracing::{debug, info_span}; +use tracing::info_span; use super::{RpcService, check}; use crate::{COMPONENT, LOG_TARGET}; @@ -41,8 +41,12 @@ impl proto::server::rpc_api::GetAccount for RpcService { _extensions: &tonic::codegen::http::Extensions, ) -> tonic::Result { miden_span_record!(account.id = request.account_id, block.number = request.block_num); - tracing::trace!(target: LOG_TARGET, ?request); - debug!(target: LOG_TARGET, "Getting account"); + debug!( + target: LOG_TARGET, + "Getting account", + account.id = request.account_id, + block.number = request.block_num + ); // Validate storage map request limits before forwarding to store. if let Some(details) = &request.details { diff --git a/crates/rpc/src/server/api/get_block_by_number.rs b/crates/rpc/src/server/api/get_block_by_number.rs index 826beed1a5..210a73c291 100644 --- a/crates/rpc/src/server/api/get_block_by_number.rs +++ b/crates/rpc/src/server/api/get_block_by_number.rs @@ -1,7 +1,6 @@ use miden_node_proto::generated as proto; -use miden_node_utils::tracing::miden_instrument; +use miden_node_utils::tracing::{debug, miden_instrument}; use miden_protocol::block::BlockNumber; -use tracing::debug; use super::{RpcService, database_error_to_status}; use crate::{COMPONENT, LOG_TARGET}; @@ -24,6 +23,7 @@ impl proto::server::rpc_api::GetBlockByNumber for RpcService { name = "get_block_by_number", fields( block.number = request.block_num, + request.include_proof = request.include_proof.unwrap_or_default(), ), err, )] @@ -33,7 +33,12 @@ impl proto::server::rpc_api::GetBlockByNumber for RpcService { _metadata: &tonic::metadata::MetadataMap, _extensions: &tonic::codegen::http::Extensions, ) -> tonic::Result { - debug!(target: LOG_TARGET, ?request, "Getting block by number"); + debug!( + target: LOG_TARGET, + "Getting block by number", + block.number = request.block_num, + request.include_proof = request.include_proof.unwrap_or_default() + ); let block_num = BlockNumber::from(request.block_num); let block = self diff --git a/crates/rpc/src/server/api/get_block_header_by_number.rs b/crates/rpc/src/server/api/get_block_header_by_number.rs index 634f2dd746..52b0a62bf5 100644 --- a/crates/rpc/src/server/api/get_block_header_by_number.rs +++ b/crates/rpc/src/server/api/get_block_header_by_number.rs @@ -1,7 +1,6 @@ use miden_node_proto::generated as proto; -use miden_node_utils::tracing::miden_instrument; +use miden_node_utils::tracing::{debug, miden_instrument}; use miden_protocol::block::BlockNumber; -use tracing::debug; use super::{COMPONENT, RpcService}; use crate::LOG_TARGET; @@ -24,6 +23,7 @@ impl proto::server::rpc_api::GetBlockHeaderByNumber for RpcService { name = "get_block_header_by_number", fields( block.number = request.block_num(), + request.include_mmr_proof = request.include_mmr_proof.unwrap_or_default(), ), err, )] @@ -33,7 +33,12 @@ impl proto::server::rpc_api::GetBlockHeaderByNumber for RpcService { _metadata: &tonic::metadata::MetadataMap, _extensions: &tonic::codegen::http::Extensions, ) -> tonic::Result { - debug!(target: LOG_TARGET, ?request, "Getting block header by number"); + debug!( + target: LOG_TARGET, + "Getting block header by number", + block.number = request.block_num(), + request.include_mmr_proof = request.include_mmr_proof.unwrap_or_default() + ); let block_num = request.block_num.map(BlockNumber::from); let (block_header, mmr_proof) = self diff --git a/crates/rpc/src/server/api/get_limits.rs b/crates/rpc/src/server/api/get_limits.rs index 5d35a86e4b..f34b3f8efd 100644 --- a/crates/rpc/src/server/api/get_limits.rs +++ b/crates/rpc/src/server/api/get_limits.rs @@ -1,6 +1,5 @@ use miden_node_proto::generated as proto; -use miden_node_utils::tracing::miden_instrument; -use tracing::debug; +use miden_node_utils::tracing::{debug, miden_instrument}; use super::{RPC_LIMITS, RpcService}; use crate::{COMPONENT, LOG_TARGET}; diff --git a/crates/rpc/src/server/api/get_network_note_status.rs b/crates/rpc/src/server/api/get_network_note_status.rs index 9bf88c8f95..be502e8787 100644 --- a/crates/rpc/src/server/api/get_network_note_status.rs +++ b/crates/rpc/src/server/api/get_network_note_status.rs @@ -1,8 +1,7 @@ use miden_node_proto::generated as proto; -use miden_node_utils::tracing::{miden_instrument, miden_span_record}; +use miden_node_utils::tracing::{debug, miden_instrument, miden_span_record}; use miden_protocol::Word; use tonic::Request; -use tracing::debug; use super::{RpcBackend, RpcService}; use crate::{COMPONENT, LOG_TARGET}; @@ -39,12 +38,14 @@ impl proto::server::rpc_api::GetNetworkNoteStatus for RpcService { ) -> tonic::Result { let original_accept_header = metadata.get(http::header::ACCEPT.as_str()).cloned(); - tracing::trace!(target: LOG_TARGET, ?request); - let note_id = request; miden_span_record!(note.id = note_id); - debug!(target: LOG_TARGET, "Getting network note status"); + debug!( + target: LOG_TARGET, + "Getting network note status", + note.id = note_id + ); let mut forwarded_request = Request::new(note_id.as_word().into()); if let Some(accept) = original_accept_header { diff --git a/crates/rpc/src/server/api/get_note_script_by_root.rs b/crates/rpc/src/server/api/get_note_script_by_root.rs index 689fbd39ab..ce7cc9cccb 100644 --- a/crates/rpc/src/server/api/get_note_script_by_root.rs +++ b/crates/rpc/src/server/api/get_note_script_by_root.rs @@ -1,9 +1,8 @@ use miden_node_proto::decode::read_root; use miden_node_proto::generated as proto; -use miden_node_utils::tracing::{miden_instrument, miden_span_record}; +use miden_node_utils::tracing::{debug, miden_instrument, miden_span_record}; use miden_protocol::note::NoteScript; use tonic::Status; -use tracing::debug; use super::{RpcService, database_error_to_status}; use crate::{COMPONENT, LOG_TARGET}; @@ -32,12 +31,14 @@ impl proto::server::rpc_api::GetNoteScriptByRoot for RpcService { _metadata: &tonic::metadata::MetadataMap, _extensions: &tonic::codegen::http::Extensions, ) -> tonic::Result { - tracing::trace!(target: LOG_TARGET, ?request); - let root = read_root::(request.root, "NoteScriptRoot")?; miden_span_record!(script.root = root); - debug!(target: LOG_TARGET, "Getting note script by root"); + debug!( + target: LOG_TARGET, + "Getting note script by root", + script.root = root + ); let script = self .state diff --git a/crates/rpc/src/server/api/get_notes_by_id.rs b/crates/rpc/src/server/api/get_notes_by_id.rs index bcbc6bcb90..8ecb751895 100644 --- a/crates/rpc/src/server/api/get_notes_by_id.rs +++ b/crates/rpc/src/server/api/get_notes_by_id.rs @@ -3,7 +3,7 @@ use miden_node_proto::generated as proto; use miden_node_proto::generated::note::CommittedNote; use miden_node_store::NoteRecord; use miden_node_utils::limiter::QueryParamNoteIdLimit; -use miden_node_utils::tracing::miden_instrument; +use miden_node_utils::tracing::{debug, miden_instrument, miden_span_record}; use miden_protocol::Word; use miden_protocol::note::NoteId; use miden_protocol::utils::serde::Serializable; @@ -36,12 +36,20 @@ impl proto::server::rpc_api::GetNotesById for RpcService { _metadata: &tonic::metadata::MetadataMap, _extensions: &tonic::codegen::http::Extensions, ) -> tonic::Result { - tracing::trace!(target: LOG_TARGET, ?request); - check::(request.ids.len())?; let note_ids: Vec = convert_digests_to_words::(request.ids)?; let note_ids: Vec = note_ids.into_iter().map(NoteId::from_raw).collect(); + miden_span_record!( + note.ids = ¬e_ids[..note_ids.len().min(10)], + note.count = note_ids.len() + ); + debug!( + target: LOG_TARGET, + "Getting notes by ID", + note.ids = ¬e_ids[..note_ids.len().min(10)], + note.count = note_ids.len() + ); let notes = self .state diff --git a/crates/rpc/src/server/api/get_transaction_encryption_key.rs b/crates/rpc/src/server/api/get_transaction_encryption_key.rs index ec1ff9c560..3406582ebb 100644 --- a/crates/rpc/src/server/api/get_transaction_encryption_key.rs +++ b/crates/rpc/src/server/api/get_transaction_encryption_key.rs @@ -1,6 +1,5 @@ use miden_node_proto::generated as proto; -use miden_node_utils::tracing::miden_instrument; -use tracing::debug; +use miden_node_utils::tracing::{debug, miden_instrument}; use super::{Request, RpcBackend, RpcService}; use crate::{COMPONENT, LOG_TARGET}; diff --git a/crates/rpc/src/server/api/status.rs b/crates/rpc/src/server/api/status.rs index d8b67a5ce7..64639e89d1 100644 --- a/crates/rpc/src/server/api/status.rs +++ b/crates/rpc/src/server/api/status.rs @@ -1,7 +1,6 @@ use miden_node_block_producer::{BlockProducerStatus, MempoolStats}; use miden_node_proto::generated as proto; -use miden_node_utils::tracing::miden_instrument; -use tracing::debug; +use miden_node_utils::tracing::{debug, miden_instrument}; use super::{ProtoMempoolStats, Request, RpcBackend, RpcService}; use crate::{COMPONENT, LOG_TARGET}; diff --git a/crates/rpc/src/server/api/submit_proven_tx.rs b/crates/rpc/src/server/api/submit_proven_tx.rs index 3f2c32d961..d102491746 100644 --- a/crates/rpc/src/server/api/submit_proven_tx.rs +++ b/crates/rpc/src/server/api/submit_proven_tx.rs @@ -4,7 +4,7 @@ use miden_node_proto::clients::{SequencerClient, ValidatorClient}; use miden_node_proto::generated as proto; use miden_node_utils::ErrorReport; use miden_node_utils::spawn::spawn_blocking_in_current_span; -use miden_node_utils::tracing::{miden_instrument, miden_span_record}; +use miden_node_utils::tracing::{debug, miden_instrument, miden_span_record, trace}; use miden_protocol::MIN_PROOF_SECURITY_LEVEL; use miden_protocol::transaction::{ OutputNote, @@ -15,7 +15,6 @@ use miden_protocol::transaction::{ }; use miden_protocol::utils::serde::{Deserializable, Serializable}; use tonic::{Request, Status}; -use tracing::debug; use super::{COMPONENT, RpcBackend, RpcService, submit_tx_to_validators}; use crate::LOG_TARGET; @@ -48,7 +47,7 @@ impl proto::server::rpc_api::SubmitProvenTx for RpcService { let is_authorized_network_tx = self.is_authorized_network_tx(metadata); let original_accept_header = metadata.get(http::header::ACCEPT.as_str()).cloned(); - tracing::trace!(target: LOG_TARGET, "Received transaction submission"); + trace!(target: LOG_TARGET, "Received transaction submission"); let tx = ProvenTransaction::read_from_bytes(&request.transaction).map_err(|err| { Status::invalid_argument(err.as_report_context("invalid transaction")) diff --git a/crates/rpc/src/server/api/submit_proven_tx_batch.rs b/crates/rpc/src/server/api/submit_proven_tx_batch.rs index 84d80dfc0f..618c9b9d24 100644 --- a/crates/rpc/src/server/api/submit_proven_tx_batch.rs +++ b/crates/rpc/src/server/api/submit_proven_tx_batch.rs @@ -3,7 +3,7 @@ use miden_node_proto::clients::{SequencerClient, ValidatorClient}; use miden_node_proto::generated as proto; use miden_node_utils::ErrorReport; use miden_node_utils::spawn::spawn_blocking_in_current_span; -use miden_node_utils::tracing::{miden_instrument, miden_span_record}; +use miden_node_utils::tracing::{debug, miden_instrument, miden_span_record, trace}; use miden_protocol::MIN_PROOF_SECURITY_LEVEL; use miden_protocol::batch::{ProposedBatch, ProvenBatch}; use miden_protocol::utils::serde::{Deserializable, Serializable}; @@ -41,10 +41,10 @@ impl proto::server::rpc_api::SubmitProvenTxBatch for RpcService { let is_authorized_network_tx = self.is_authorized_network_tx(metadata); let original_accept_header = metadata.get(http::header::ACCEPT.as_str()).cloned(); - tracing::trace!( + trace!( target: LOG_TARGET, - { batch.size = request.sealed_transaction_inputs.len() }, "Received transaction batch", + batch.size = request.sealed_transaction_inputs.len() ); let proven_batch = ProvenBatch::read_from_bytes(&request.batch_proof).map_err(|err| { @@ -68,7 +68,7 @@ impl proto::server::rpc_api::SubmitProvenTxBatch for RpcService { })? .ok_or(Status::invalid_argument("missing `proposed_batch` field"))?; - tracing::debug!(target: LOG_TARGET, "Submitting transaction batch"); + debug!(target: LOG_TARGET, "Submitting transaction batch"); // Verify the reference block is actually part of the chain. self.verify_reference_commitment( diff --git a/crates/rpc/src/server/api/subscription/block.rs b/crates/rpc/src/server/api/subscription/block.rs index a97be870d1..3c4f40f88e 100644 --- a/crates/rpc/src/server/api/subscription/block.rs +++ b/crates/rpc/src/server/api/subscription/block.rs @@ -1,8 +1,7 @@ use miden_node_proto::generated as proto; use miden_node_utils::grpc::ClientIp; -use miden_node_utils::tracing::miden_instrument; +use miden_node_utils::tracing::{debug, miden_instrument}; use miden_protocol::block::BlockNumber; -use tracing::debug; use super::super::{COMPONENT, RpcService}; use super::stream::{StreamItem, SubscriptionStream}; diff --git a/crates/rpc/src/server/api/subscription/proof.rs b/crates/rpc/src/server/api/subscription/proof.rs index c46dc49ce3..ed95c6b870 100644 --- a/crates/rpc/src/server/api/subscription/proof.rs +++ b/crates/rpc/src/server/api/subscription/proof.rs @@ -1,8 +1,7 @@ use miden_node_proto::generated as proto; use miden_node_utils::grpc::ClientIp; -use miden_node_utils::tracing::miden_instrument; +use miden_node_utils::tracing::{debug, miden_instrument}; use miden_protocol::block::BlockNumber; -use tracing::debug; use super::super::{COMPONENT, RpcService}; use super::stream::{StreamItem, SubscriptionStream}; diff --git a/crates/rpc/src/server/api/subscription/stream/mod.rs b/crates/rpc/src/server/api/subscription/stream/mod.rs index 5b88c86057..d1e0f94734 100644 --- a/crates/rpc/src/server/api/subscription/stream/mod.rs +++ b/crates/rpc/src/server/api/subscription/stream/mod.rs @@ -6,7 +6,7 @@ use std::task::{Context, Poll}; use std::time::{Duration, Instant}; use miden_node_store::DatabaseError; -use miden_node_utils::ErrorReport; +use miden_node_utils::tracing::error; use miden_protocol::block::BlockNumber; use tokio::sync::mpsc::error::SendTimeoutError; use tokio::sync::{OwnedSemaphorePermit, Semaphore, mpsc, watch}; @@ -256,16 +256,16 @@ where let data = (self.get_data)(block) .await .inspect_err(|err| { - tracing::error!( - block.number = %block, - message = %err.as_report(), - "failed to load data for stream" - ); + error!(&err, "failed to load data for stream", block.number = block); }) .map_err(|_| StreamError::Internal)?; data.ok_or_else(|| { - tracing::error!(block.number = %block, "stream data not found"); + error!( + anyhow::anyhow!("stream data not found for block {block}"), + "stream data not found", + block.number = block + ); StreamError::Internal }) } diff --git a/crates/rpc/src/server/api/sync_account_storage_maps.rs b/crates/rpc/src/server/api/sync_account_storage_maps.rs index 9312fd9f34..da12ec192e 100644 --- a/crates/rpc/src/server/api/sync_account_storage_maps.rs +++ b/crates/rpc/src/server/api/sync_account_storage_maps.rs @@ -1,6 +1,6 @@ use miden_node_proto::decode::{read_account_id, read_block_range}; use miden_node_proto::generated as proto; -use miden_node_utils::tracing::{miden_instrument, miden_span_record}; +use miden_node_utils::tracing::{debug, miden_instrument, miden_span_record}; use tonic::Status; use super::{ @@ -35,8 +35,6 @@ impl proto::server::rpc_api::SyncAccountStorageMaps for RpcService { _metadata: &tonic::metadata::MetadataMap, _extensions: &tonic::codegen::http::Extensions, ) -> tonic::Result { - tracing::trace!(target: LOG_TARGET, ?request); - let account_id = read_account_id::( request.account_id.clone(), )?; @@ -49,7 +47,13 @@ impl proto::server::rpc_api::SyncAccountStorageMaps for RpcService { block_range.to = range.block_to ); - tracing::debug!(target: LOG_TARGET, "Syncing account storage maps"); + debug!( + target: LOG_TARGET, + "Syncing account storage maps", + account.id = account_id, + block_range.from = range.block_from, + block_range.to = range.block_to + ); if !account_id.is_public() { return Err(Status::invalid_argument(format!("account {account_id} is not public"))); diff --git a/crates/rpc/src/server/api/sync_account_vault.rs b/crates/rpc/src/server/api/sync_account_vault.rs index c9800f60d8..f4b2aef5d1 100644 --- a/crates/rpc/src/server/api/sync_account_vault.rs +++ b/crates/rpc/src/server/api/sync_account_vault.rs @@ -1,6 +1,6 @@ use miden_node_proto::decode::{read_account_id, read_block_range}; use miden_node_proto::generated as proto; -use miden_node_utils::tracing::{miden_instrument, miden_span_record}; +use miden_node_utils::tracing::{debug, miden_instrument, miden_span_record}; use miden_protocol::Word; use tonic::Status; @@ -36,8 +36,6 @@ impl proto::server::rpc_api::SyncAccountVault for RpcService { _metadata: &tonic::metadata::MetadataMap, _extensions: &tonic::codegen::http::Extensions, ) -> tonic::Result { - tracing::trace!(target: LOG_TARGET, ?request); - let account_id = read_account_id::( request.account_id.clone(), )?; @@ -49,7 +47,13 @@ impl proto::server::rpc_api::SyncAccountVault for RpcService { block_range.to = range.block_to ); - tracing::debug!(target: LOG_TARGET, "Syncing account vault"); + debug!( + target: LOG_TARGET, + "Syncing account vault", + account.id = account_id, + block_range.from = range.block_from, + block_range.to = range.block_to + ); if !account_id.is_public() { return Err(Status::invalid_argument(format!("account {account_id} is not public"))); diff --git a/crates/rpc/src/server/api/sync_chain_mmr.rs b/crates/rpc/src/server/api/sync_chain_mmr.rs index 54253da013..75d3e5c62b 100644 --- a/crates/rpc/src/server/api/sync_chain_mmr.rs +++ b/crates/rpc/src/server/api/sync_chain_mmr.rs @@ -1,9 +1,8 @@ use miden_node_proto::generated as proto; use miden_node_store::StateSyncError; -use miden_node_utils::tracing::miden_instrument; +use miden_node_utils::tracing::{debug, miden_instrument}; use miden_protocol::block::BlockNumber; use tonic::Status; -use tracing::debug; use super::RpcService; use crate::{COMPONENT, LOG_TARGET}; diff --git a/crates/rpc/src/server/api/sync_notes.rs b/crates/rpc/src/server/api/sync_notes.rs index 2b7aeca7f4..8482c00d90 100644 --- a/crates/rpc/src/server/api/sync_notes.rs +++ b/crates/rpc/src/server/api/sync_notes.rs @@ -2,9 +2,8 @@ use miden_node_proto::decode::read_block_range; use miden_node_proto::generated as proto; use miden_node_store::{NoteSyncError, NoteSyncRecord}; use miden_node_utils::limiter::QueryParamNoteTagLimit; -use miden_node_utils::tracing::{miden_instrument, miden_span_record}; +use miden_node_utils::tracing::{debug, miden_instrument, miden_span_record}; use tonic::Status; -use tracing::debug; use super::{RpcInvalidBlockRange, RpcService, check, invalid_block_range_to_status}; use crate::{COMPONENT, LOG_TARGET}; @@ -33,13 +32,23 @@ impl proto::server::rpc_api::SyncNotes for RpcService { _metadata: &tonic::metadata::MetadataMap, _extensions: &tonic::codegen::http::Extensions, ) -> tonic::Result { - tracing::trace!(target: LOG_TARGET, ?request); - let range = read_block_range::(request.block_range, "SyncNotesRequest")?; - miden_span_record!(block_range.from = range.block_from, block_range.to = range.block_to); + miden_span_record!( + block_range.from = range.block_from, + block_range.to = range.block_to, + note.tags = request.note_tags.as_slice(), + note.tag.count = request.note_tags.len() + ); - debug!(target: LOG_TARGET, "Syncing notes"); + debug!( + target: LOG_TARGET, + "Syncing notes", + block_range.from = range.block_from, + block_range.to = range.block_to, + note.tags = request.note_tags.as_slice(), + note.tag.count = request.note_tags.len() + ); check::(request.note_tags.len())?; diff --git a/crates/rpc/src/server/api/sync_nullifiers.rs b/crates/rpc/src/server/api/sync_nullifiers.rs index 7f06d817e0..a0bcfe8691 100644 --- a/crates/rpc/src/server/api/sync_nullifiers.rs +++ b/crates/rpc/src/server/api/sync_nullifiers.rs @@ -1,9 +1,8 @@ use miden_node_proto::decode::read_block_range; use miden_node_proto::generated as proto; use miden_node_utils::limiter::QueryParamNullifierPrefixLimit; -use miden_node_utils::tracing::{miden_instrument, miden_span_record}; +use miden_node_utils::tracing::{debug, miden_instrument, miden_span_record}; use tonic::Status; -use tracing::debug; use super::{ RpcInvalidBlockRange, @@ -38,13 +37,23 @@ impl proto::server::rpc_api::SyncNullifiers for RpcService { _metadata: &tonic::metadata::MetadataMap, _extensions: &tonic::codegen::http::Extensions, ) -> tonic::Result { - tracing::trace!(target: LOG_TARGET, ?request); - let range = read_block_range::(request.block_range, "SyncNullifiersRequest")?; - miden_span_record!(block_range.from = range.block_from, block_range.to = range.block_to); + miden_span_record!( + block_range.from = range.block_from, + block_range.to = range.block_to, + prefix_len = request.prefix_len, + prefixes = request.nullifiers.as_slice() #[nonstandard] + ); - debug!(target: LOG_TARGET, "Syncing nullifiers"); + debug!( + target: LOG_TARGET, + "Syncing nullifiers", + block_range.from = range.block_from, + block_range.to = range.block_to, + prefix_len = request.prefix_len, + prefixes = request.nullifiers.as_slice() #[nonstandard] + ); check::(request.nullifiers.len())?; diff --git a/crates/rpc/src/server/api/sync_transactions.rs b/crates/rpc/src/server/api/sync_transactions.rs index b5dd8a86cb..c71f4f3914 100644 --- a/crates/rpc/src/server/api/sync_transactions.rs +++ b/crates/rpc/src/server/api/sync_transactions.rs @@ -2,9 +2,8 @@ use miden_node_proto::decode::{read_account_ids, read_block_range}; use miden_node_proto::generated as proto; use miden_node_store::{NoteSyncRecord, TransactionRecord}; use miden_node_utils::limiter::QueryParamAccountIdLimit; -use miden_node_utils::tracing::{miden_instrument, miden_span_record}; +use miden_node_utils::tracing::{debug, miden_instrument, miden_span_record}; use tonic::Status; -use tracing::debug; use super::{ RpcInvalidBlockRange, @@ -39,8 +38,6 @@ impl proto::server::rpc_api::SyncTransactions for RpcService { _metadata: &tonic::metadata::MetadataMap, _extensions: &tonic::codegen::http::Extensions, ) -> tonic::Result { - tracing::trace!(target: LOG_TARGET, ?request); - let range = read_block_range::(request.block_range, "SyncTransactionsRequest")?; let n_accounts = request.account_ids.len(); let account_ids = @@ -53,7 +50,14 @@ impl proto::server::rpc_api::SyncTransactions for RpcService { account.count = n_accounts ); - debug!(target: LOG_TARGET, "Syncing transactions"); + debug!( + target: LOG_TARGET, + "Syncing transactions", + block_range.from = range.block_from, + block_range.to = range.block_to, + account.ids = account_ids, + account.ids.count = n_accounts + ); check::(request.account_ids.len())?; diff --git a/crates/rpc/src/server/mod.rs b/crates/rpc/src/server/mod.rs index 25e0e33af5..89ef50ed4f 100644 --- a/crates/rpc/src/server/mod.rs +++ b/crates/rpc/src/server/mod.rs @@ -21,6 +21,8 @@ use miden_node_utils::panic::{CatchPanicLayer, catch_panic_layer_fn}; use miden_node_utils::shutdown::CancellationToken; use miden_node_utils::tasks::Tasks; use miden_node_utils::tracing::grpc::grpc_trace_fn; +use miden_node_utils::tracing::info; +use miden_protocol::block::BlockNumber; use rand::RngExt; use tokio::net::TcpListener; use tokio_stream::wrappers::TcpListenerStream; @@ -29,7 +31,6 @@ use tonic_reflection::server; use tonic_web::GrpcWebLayer; use tower_http::classify::{GrpcCode, GrpcErrorsAsFailures, SharedClassifier}; use tower_http::trace::TraceLayer; -use tracing::info; use crate::LOG_TARGET; use crate::server::api::SequencerInternalService; @@ -404,31 +405,27 @@ impl Rpc { } } -fn log_node_ready(mode: &str, endpoint: impl Display, chain_tip: impl Display) { +fn log_node_ready(mode: &str, endpoint: impl Display, chain_tip: BlockNumber) { info!( target: LOG_TARGET, - { - service.name = "miden-node", - service.version = env!("CARGO_PKG_VERSION"), - node.role = mode, - rpc.listen = %endpoint, - block.number = %chain_tip, - }, "Node ready", + service.name = "miden-node", + service.version = env!("CARGO_PKG_VERSION"), + node.role = mode, + rpc.listen = endpoint.to_string(), + block.number = chain_tip ); } fn log_node_synchronizing(mode: &str, endpoint: impl Display, readiness_threshold: u32) { info!( target: LOG_TARGET, - { - service.name = "miden-node", - service.version = env!("CARGO_PKG_VERSION"), - node.role = mode, - rpc.listen = %endpoint, - sync.ready_threshold = readiness_threshold, - }, "Node started; synchronizing", + service.name = "miden-node", + service.version = env!("CARGO_PKG_VERSION"), + node.role = mode, + rpc.listen = endpoint.to_string(), + sync.ready_threshold = readiness_threshold ); } @@ -464,8 +461,8 @@ impl SequencerInternal { .context("failed to read internal sequencer listen address")?; info!( target: LOG_TARGET, - { internal.listen = %endpoint }, "Internal sequencer server ready", + internal.listen = endpoint.to_string() ); let service = SequencerInternalService { block_producer: self.block_producer }; diff --git a/crates/store/src/account_state_forest/mod.rs b/crates/store/src/account_state_forest/mod.rs index b4680482fa..e45f40cbc7 100644 --- a/crates/store/src/account_state_forest/mod.rs +++ b/crates/store/src/account_state_forest/mod.rs @@ -12,7 +12,7 @@ use miden_node_proto::domain::account::{ }; use miden_node_utils::ErrorReport; use miden_node_utils::lru_cache::LruCache; -use miden_node_utils::tracing::miden_instrument; +use miden_node_utils::tracing::{miden_instrument, trace}; use miden_protocol::account::{ AccountId, AccountPatch, @@ -834,12 +834,12 @@ impl AccountStateForest { for patch in &account_patches { self.cache_hashed_keys_from_patch(patch); - tracing::trace!( + trace!( target: crate::LOG_TARGET, - account_id = %patch.id(), - %block_num, - is_full_state = patch.is_full_state(), - "Updated forest with account patch" + "Updated forest with account patch", + account.id = patch.id(), + block.number = block_num, + account.updated = patch.is_full_state() ); } diff --git a/crates/store/src/data_directory.rs b/crates/store/src/data_directory.rs index 44bf557988..4e1405cb0c 100644 --- a/crates/store/src/data_directory.rs +++ b/crates/store/src/data_directory.rs @@ -1,6 +1,8 @@ use std::ops::Not; use std::path::PathBuf; +use miden_node_utils::tracing::RecordAttribute; + /// Represents the store's data-directory and its content paths. /// /// Used to keep our filepath assumptions in one location. @@ -31,3 +33,11 @@ impl DataDirectory { self.0.display() } } + +impl RecordAttribute for DataDirectory { + const FIELD_NAMES: &'static [&'static str] = &["data.directory", "path"]; + + fn record_attribute(&self) -> impl tracing::Value + '_ { + tracing::field::display(self.display()) + } +} diff --git a/crates/store/src/db/migrations.rs b/crates/store/src/db/migrations.rs index 213b6df53c..f5c305ba26 100644 --- a/crates/store/src/db/migrations.rs +++ b/crates/store/src/db/migrations.rs @@ -1,7 +1,7 @@ use std::path::Path; use miden_node_db::DatabaseError; -use miden_node_utils::tracing::miden_instrument; +use miden_node_utils::tracing::{info, miden_instrument}; use crate::{COMPONENT, LOG_TARGET}; @@ -14,10 +14,10 @@ include!(concat!(env!("OUT_DIR"), "/db_migrator.rs")); )] pub fn bootstrap_database(database_filepath: &Path) -> std::result::Result<(), DatabaseError> { let migrator = migrator().map_err(DatabaseError::migration)?; - tracing::info!( + info!( target: LOG_TARGET, - migration_count = migrator.schema_hashes().len(), - "Bootstrapping database schema" + "Bootstrapping database schema", + migration.count = migrator.schema_hashes().len() ); migrator.bootstrap(database_filepath).map_err(DatabaseError::migration)?; @@ -32,10 +32,10 @@ pub fn bootstrap_database(database_filepath: &Path) -> std::result::Result<(), D )] pub fn migrate_database(database_filepath: &Path) -> std::result::Result<(), DatabaseError> { let migrator = migrator().map_err(DatabaseError::migration)?; - tracing::info!( + info!( target: LOG_TARGET, - migration_count = migrator.schema_hashes().len(), - "Applying database migrations" + "Applying database migrations", + migration.count = migrator.schema_hashes().len() ); migrator.migrate(database_filepath).map_err(DatabaseError::migration)?; @@ -50,10 +50,10 @@ pub fn migrate_database(database_filepath: &Path) -> std::result::Result<(), Dat )] pub fn verify_latest_schema(database_filepath: &Path) -> std::result::Result<(), DatabaseError> { let migrator = migrator().map_err(DatabaseError::migration)?; - tracing::info!( + info!( target: LOG_TARGET, - migration_count = migrator.schema_hashes().len(), - "Verifying database schema" + "Verifying database schema", + migration.count = migrator.schema_hashes().len() ); migrator diff --git a/crates/store/src/db/mod.rs b/crates/store/src/db/mod.rs index ff407ab4fc..3a644aabf9 100644 --- a/crates/store/src/db/mod.rs +++ b/crates/store/src/db/mod.rs @@ -13,7 +13,7 @@ use miden_node_utils::limiter::{ QueryParamLimiter, QueryParamNoteCommitmentLimit, }; -use miden_node_utils::tracing::miden_instrument; +use miden_node_utils::tracing::{info, miden_instrument, warn}; use miden_protocol::Word; use miden_protocol::account::{AccountHeader, AccountId, AccountStorageHeader, StorageMapKey}; use miden_protocol::asset::{Asset, AssetId}; @@ -36,7 +36,6 @@ use miden_protocol::note::{ }; use miden_protocol::transaction::TransactionHeader; use miden_protocol::utils::serde::Deserializable; -use tracing::info; use crate::db::migrations::{migrate_database, verify_latest_schema}; use crate::db::models::conv::SqlTypeConvert; @@ -260,9 +259,9 @@ impl Db { let db = miden_node_db::Db::new_with_pool_size(&database_filepath, connection_pool_size)?; info!( target: LOG_TARGET, - sqlite= %database_filepath.display(), - connection_pool_size = %connection_pool_size, - "Connected to the database" + "Connected to the database", + path = database_filepath, + db.sqlite.connection_pool_size = connection_pool_size.get() ); Ok(Self { db }) @@ -619,11 +618,11 @@ impl Db { match queries::select_note_ids_by_nullifier(conn, chunk) { Ok(note_ids) => resolved_note_ids.extend(note_ids), Err(err) => { - tracing::warn!( + warn!( + &err, target: COMPONENT, - %err, - nullifiers.count = chunk.len(), "Failed to resolve consumed note IDs for lifecycle events", + note.nullifier.count = chunk.len() ); break; }, diff --git a/crates/store/src/genesis/config/mod.rs b/crates/store/src/genesis/config/mod.rs index 81723b79d8..6fff2d9b97 100644 --- a/crates/store/src/genesis/config/mod.rs +++ b/crates/store/src/genesis/config/mod.rs @@ -5,6 +5,7 @@ use std::path::{Path, PathBuf}; use std::str::FromStr; use indexmap::IndexMap; +use miden_node_utils::tracing::debug; use miden_protocol::account::auth::{AuthScheme, AuthSecretKey}; use miden_protocol::account::{Account, AccountBuilder, AccountFile, AccountId, AccountType}; use miden_protocol::asset::{Asset, AssetAmount, FungibleAsset, TokenSymbol}; @@ -242,7 +243,12 @@ impl GenesisConfig { // Setup all wallet accounts, which reference the faucet's for their provided assets. for (index, WalletConfig { account_type, assets }) in wallet_configs.into_iter().enumerate() { - tracing::debug!(target: LOG_TARGET, index, assets = ?assets, "Adding wallet account"); + debug!( + target: LOG_TARGET, + "Adding wallet account", + account.index = index, + account.assets.count = assets.len() + ); let mut rng = ChaCha20Rng::from_seed(rand::random()); let secret_key = RpoSecretKey::with_rng(&mut rng); @@ -301,19 +307,19 @@ impl GenesisConfig { let updated_faucet = current_faucet.with_token_supply(new_token_supply)?; let slot = updated_faucet.token_config_slot_value(); faucet_account.storage_mut().set_item(slot.name(), slot.value())?; - tracing::debug!( + debug!( target: LOG_TARGET, - "Reducing faucet account {faucet} for {symbol} by {amount}", - faucet = faucet_id.to_hex(), - symbol = symbol, - amount = total_issuance + "Reducing faucet account issuance", + account.id = faucet_id, + asset.symbol = symbol.to_string(), + asset.amount = total_issuance ); } else { - tracing::debug!( + debug!( target: LOG_TARGET, - "No wallet is referencing {faucet} for {symbol}", - faucet = faucet_id.to_hex(), - symbol = symbol, + "No wallet references faucet asset", + account.id = faucet_id, + asset.symbol = symbol.to_string() ); } @@ -667,10 +673,12 @@ fn prepare_fungible_asset_update( let faucet_id = faucet_account.id(); let issuance: &mut u64 = faucet_issuance.entry(faucet_id).or_default(); - tracing::debug!( + debug!( target: LOG_TARGET, - "Updating faucet issuance {faucet} with {issuance} += {amount}", - faucet = faucet_id.to_hex() + "Updating faucet issuance", + account.id = faucet_id, + asset.symbol = symbol.to_string(), + asset.amount = amount ); issuance .checked_add_assign(&amount) diff --git a/crates/store/src/state/block_lifecycle.rs b/crates/store/src/state/block_lifecycle.rs index 655151341e..f2083f6cb4 100644 --- a/crates/store/src/state/block_lifecycle.rs +++ b/crates/store/src/state/block_lifecycle.rs @@ -1,6 +1,6 @@ use std::collections::{BTreeMap, BTreeSet}; -use miden_node_utils::tracing::miden_instrument; +use miden_node_utils::tracing::{debug, miden_instrument}; use miden_protocol::Word; use miden_protocol::account::{ AccountId, @@ -93,56 +93,38 @@ impl BlockLifecycle { )] pub(super) fn emit(self, resolved_note_ids: &BTreeMap) { for account in self.registered_accounts { - tracing::debug!( + debug!( target: LOG_TARGET, - { - account.id = %account.account_id, - block.number = %self.block_num, - transaction.id = %account.transaction_id, - }, "Account registered", + account.id = account.account_id, + block.number = self.block_num, + transaction.id = account.transaction_id ); } for note in self.created_notes { - tracing::debug!( + debug!( target: LOG_TARGET, - { - note.id = %note.note_id, - note.sender = %note.sender, - note.erased = note.erased, - block.number = %self.block_num, - transaction.id = %note.transaction_id, - }, "Note created", + note.id = note.note_id, + note.sender = note.sender, + note.erased = note.erased, + block.number = self.block_num, + transaction.id = note.transaction_id ); } for note in self.consumed_notes { let note_id = note.note_id.or_else(|| resolved_note_ids.get(¬e.nullifier).copied()); - if let Some(note_id) = note_id { - tracing::debug!( - target: LOG_TARGET, - { - note.id = %note_id, - note.nullifier = %note.nullifier, - block.number = %self.block_num, - transaction.id = %note.transaction_id, - }, - "Note consumed", - ); - } else { - tracing::debug!( - target: LOG_TARGET, - { - note.nullifier = %note.nullifier, - note.id_resolved = false, - block.number = %self.block_num, - transaction.id = %note.transaction_id, - }, - "Note consumed", - ); - } + debug!( + target: LOG_TARGET, + "Note consumed", + note.id = note_id, + note.id_resolved = note_id.is_some(), + note.nullifier = note.nullifier, + block.number = self.block_num, + transaction.id = note.transaction_id + ); } for change in self.storage_changes { @@ -205,17 +187,15 @@ impl StorageChange { operation, value: Some(value), } => { - tracing::debug!( + debug!( target: LOG_TARGET, - { - account.id = %account_id, - account.storage.slot = %slot_name, - account.storage.kind = "value", - account.storage.operation = storage_operation(operation), - account.storage.value = %value, - block.number = %block_num, - }, "Account storage updated", + account.id = account_id, + account.storage.slot = slot_name, + account.storage.kind = "value", + account.storage.operation = storage_operation(operation), + account.storage.value = value, + block.number = block_num ); }, StorageChange::Value { @@ -224,16 +204,14 @@ impl StorageChange { operation, value: None, } => { - tracing::debug!( + debug!( target: LOG_TARGET, - { - account.id = %account_id, - account.storage.slot = %slot_name, - account.storage.kind = "value", - account.storage.operation = storage_operation(operation), - block.number = %block_num, - }, "Account storage updated", + account.id = account_id, + account.storage.slot = slot_name, + account.storage.kind = "value", + account.storage.operation = storage_operation(operation), + block.number = block_num ); }, StorageChange::MapEntry { @@ -243,20 +221,18 @@ impl StorageChange { key, value, } => { - tracing::debug!( + debug!( target: LOG_TARGET, - { - account.id = %account_id, - account.storage.slot = %slot_name, - account.storage.kind = "map", - account.storage.operation = storage_operation(operation), - account.storage.map.key = %key, - account.storage.map.entry.operation = - if value.is_empty() { "remove" } else { "set" }, - account.storage.value = %value, - block.number = %block_num, - }, "Account storage updated", + account.id = account_id, + account.storage.slot = slot_name, + account.storage.kind = "map", + account.storage.operation = storage_operation(operation), + account.storage.map.key = key, + account.storage.map.entry.operation = + if value.is_empty() { "remove" } else { "set" }, + account.storage.value = value, + block.number = block_num ); }, StorageChange::MapSlot { @@ -265,17 +241,15 @@ impl StorageChange { operation, entries_count, } => { - tracing::debug!( + debug!( target: LOG_TARGET, - { - account.id = %account_id, - account.storage.slot = %slot_name, - account.storage.kind = "map", - account.storage.operation = storage_operation(operation), - account.storage.map.entries.count = entries_count, - block.number = %block_num, - }, "Account storage updated", + account.id = account_id, + account.storage.slot = slot_name, + account.storage.kind = "map", + account.storage.operation = storage_operation(operation), + account.storage.map.entries.count = entries_count, + block.number = block_num ); }, } diff --git a/crates/store/src/state/bootstrap.rs b/crates/store/src/state/bootstrap.rs index ae6cc65e30..f38efd2f07 100644 --- a/crates/store/src/state/bootstrap.rs +++ b/crates/store/src/state/bootstrap.rs @@ -1,7 +1,7 @@ use std::path::Path; use anyhow::Context; -use miden_node_utils::tracing::miden_instrument; +use miden_node_utils::tracing::{debug, miden_instrument}; use crate::blocks::BlockStore; use crate::db::Db; @@ -22,20 +22,32 @@ impl State { DataDirectory::load(data_directory.to_path_buf()).with_context(|| { format!("failed to load data directory at {}", data_directory.display()) })?; - tracing::debug!(target: LOG_TARGET, path=%data_directory.display(), "Data directory loaded"); + debug!( + target: LOG_TARGET, + "Data directory loaded", + path = data_directory + ); let block_store_path = data_directory.block_store_dir(); - let block_store = + let _block_store = BlockStore::bootstrap(block_store_path.clone(), &genesis).with_context(|| { format!("failed to bootstrap block store at {}", block_store_path.display()) })?; - tracing::debug!(target: LOG_TARGET, path=%block_store.display(), "Block store created"); + debug!( + target: LOG_TARGET, + "Block store created", + path = block_store_path + ); let database_filepath = data_directory.database_path(); Db::bootstrap(database_filepath.clone(), genesis).with_context(|| { format!("failed to bootstrap database at {}", database_filepath.display()) })?; - tracing::debug!(target: LOG_TARGET, path=%database_filepath.display(), "Database created"); + debug!( + target: LOG_TARGET, + "Database created", + path = database_filepath + ); Ok(()) } diff --git a/crates/store/src/state/loader.rs b/crates/store/src/state/loader.rs index 1a95452a7d..bdfbccbaa8 100644 --- a/crates/store/src/state/loader.rs +++ b/crates/store/src/state/loader.rs @@ -23,6 +23,8 @@ use miden_crypto::merkle::smt::{ }; #[cfg(feature = "rocksdb")] use miden_node_utils::clap::RocksDbOptions; +#[cfg(feature = "rocksdb")] +use miden_node_utils::tracing::info; use miden_node_utils::tracing::miden_instrument; use miden_protocol::account::{AccountId, AccountStorageHeader, StorageSlotType}; use miden_protocol::block::account_tree::{AccountIdKey, AccountTree}; @@ -32,8 +34,6 @@ use miden_protocol::block::{BlockHeader, BlockNumber, Blockchain}; use miden_protocol::crypto::merkle::smt::MemoryStorage; use miden_protocol::crypto::merkle::smt::{LargeSmt, LargeSmtError, SmtStorage}; use miden_protocol::{Felt, Word}; -#[cfg(feature = "rocksdb")] -use tracing::info; use crate::COMPONENT; #[cfg(feature = "rocksdb")] diff --git a/crates/store/src/state/view/snapshot.rs b/crates/store/src/state/view/snapshot.rs index 50ecd3f921..6211eebed1 100644 --- a/crates/store/src/state/view/snapshot.rs +++ b/crates/store/src/state/view/snapshot.rs @@ -12,6 +12,7 @@ use std::sync::atomic::{AtomicUsize, Ordering}; use std::sync::{Arc, OnceLock, Weak}; use std::time::{Duration, Instant}; +use miden_node_utils::tracing::{debug, warn}; use miden_protocol::block::nullifier_tree::NullifierTree; use miden_protocol::block::{BlockNumber, Blockchain}; use miden_protocol::crypto::merkle::smt::LargeSmt; @@ -161,21 +162,21 @@ impl Drop for SnapshotGuard { superseded_for.filter(|held| *held > SNAPSHOT_SUPERSEDED_WARN_THRESHOLD) { let superseded_for_ms = u64::try_from(superseded_for.as_millis()).unwrap_or(u64::MAX); - tracing::warn!( + warn!( target: COMPONENT, - block_num, + "State snapshot held for excessive time after supersession", + block.number = block_num, snapshot.lifetime_ms = lifetime_ms, snapshot.superseded_for_ms = superseded_for_ms, - snapshots.live = remaining, - "state snapshot held for excessive time after supersession", + snapshots.live = remaining ); } else { - tracing::debug!( + debug!( target: COMPONENT, - block_num, + "State snapshot released", + block.number = block_num, snapshot.lifetime_ms = lifetime_ms, - snapshots.live = remaining, - "state snapshot released", + snapshots.live = remaining ); } } diff --git a/crates/store/src/state/writer/worker.rs b/crates/store/src/state/writer/worker.rs index 55b01db17d..66099f0c6c 100644 --- a/crates/store/src/state/writer/worker.rs +++ b/crates/store/src/state/writer/worker.rs @@ -6,7 +6,7 @@ use std::sync::{Arc, Once}; use arc_swap::ArcSwap; use miden_node_utils::ErrorReport; use miden_node_utils::shutdown::CancellationToken; -use miden_node_utils::tracing::{miden_instrument, miden_span_record}; +use miden_node_utils::tracing::{debug, miden_instrument, miden_span_record, warn}; use miden_protocol::Word; use miden_protocol::account::AccountUpdateDetails; use miden_protocol::block::account_tree::AccountMutationSet; @@ -271,7 +271,7 @@ impl WriteWorker { if let Some(block_lifecycle) = block_lifecycle { block_lifecycle.emit(&resolved_note_ids); } - tracing::debug!(target: LOG_TARGET, "Block applied"); + debug!(target: LOG_TARGET, "Block applied"); Ok(()) } @@ -284,11 +284,11 @@ impl WriteWorker { fn check_live_snapshots(&self, block_num: BlockNumber) -> u64 { let snapshots_live = self.snapshots_live.load(Ordering::Relaxed) as u64; if snapshots_live > SNAPSHOTS_LIVE_WARN_THRESHOLD { - tracing::warn!( + warn!( target: COMPONENT, - block_num = block_num.as_u32(), - snapshots.live = snapshots_live, "too many live state snapshots; slow readers are pinning old generations", + block.number = block_num, + snapshots.live = snapshots_live ); } snapshots_live @@ -575,10 +575,10 @@ fn raise_thread_priority() { static WARN_ONCE: Once = Once::new(); if let Err(error) = set_current_thread_priority(ThreadPriority::Max) { WARN_ONCE.call_once(|| { - tracing::warn!( + warn!( + &error, target: COMPONENT, - ?error, - "failed to raise apply-block thread priority; continuing at normal priority", + "failed to raise apply-block thread priority; continuing at normal priority" ); }); } diff --git a/crates/tracing-macro/src/lib.rs b/crates/tracing-macro/src/lib.rs index a9fbdef57f..ed2277b0b0 100644 --- a/crates/tracing-macro/src/lib.rs +++ b/crates/tracing-macro/src/lib.rs @@ -13,6 +13,7 @@ use syn::{ Expr, Ident, ItemFn, + LitStr, Macro, Meta, Result, @@ -58,6 +59,324 @@ pub fn miden_instrument(attr: TokenStream, item: TokenStream) -> TokenStream { expanded.into() } +/// Emits a trace-level event. +/// +/// An optional first argument may provide an error implementing `ErrorReport`. Its display value +/// and source chain are recorded as `exception.message`; callers do not provide that attribute +/// themselves. +/// +/// The event name is required and must be a string literal. When an error is provided, optional +/// `target:` and `parent:` arguments go between the error and name, in that order. Without an +/// error, they precede the name. Attributes follow the name and must use a registered field name +/// and a value implementing `RecordAttribute`. Append `#[nonstandard]` to a field value to permit +/// an unregistered name while retaining its canonical encoding. Tracing format specifiers and +/// trailing commas are not supported. +/// +/// The name is recorded as tracing's `message` field, which the OpenTelemetry tracing layer uses +/// as the event name. +/// +/// ```rust,ignore +/// use miden_node_utils::tracing::trace; +/// +/// trace!(target: "node", "block.received", block.number = 42_u32); +/// +/// let source = std::io::Error::other("invalid block"); +/// trace!(&source, "block.rejected", block.number = 42_u32); +/// ``` +#[proc_macro] +pub fn trace(input: TokenStream) -> TokenStream { + expand_event(input, "trace", false) +} + +/// Emits a debug-level event. +/// +/// An optional first argument may provide an error implementing `ErrorReport`. Its display value +/// and source chain are recorded as `exception.message`; callers do not provide that attribute +/// themselves. +/// +/// The event name is required and must be a string literal. When an error is provided, optional +/// `target:` and `parent:` arguments go between the error and name, in that order. Without an +/// error, they precede the name. Attributes follow the name and must use a registered field name +/// and a value implementing `RecordAttribute`. Append `#[nonstandard]` to a field value to permit +/// an unregistered name while retaining its canonical encoding. Tracing format specifiers and +/// trailing commas are not supported. +/// +/// The name is recorded as tracing's `message` field, which the OpenTelemetry tracing layer uses +/// as the event name. +/// +/// ```rust,ignore +/// use miden_node_utils::tracing::debug; +/// +/// debug!("block.queued", block.number = 42_u32); +/// +/// let source = std::io::Error::other("upstream unavailable"); +/// debug!(&source, "block.retrying", block.number = 42_u32); +/// ``` +#[proc_macro] +pub fn debug(input: TokenStream) -> TokenStream { + expand_event(input, "debug", false) +} + +/// Emits an info-level event. +/// +/// An optional first argument may provide an error implementing `ErrorReport`. Its display value +/// and source chain are recorded as `exception.message`; callers do not provide that attribute +/// themselves. +/// +/// The event name is required and must be a string literal. When an error is provided, optional +/// `target:` and `parent:` arguments go between the error and name, in that order. Without an +/// error, they precede the name. Attributes follow the name and must use a registered field name +/// and a value implementing `RecordAttribute`. Append `#[nonstandard]` to a field value to permit +/// an unregistered name while retaining its canonical encoding. Tracing format specifiers and +/// trailing commas are not supported. +/// +/// The name is recorded as tracing's `message` field, which the OpenTelemetry tracing layer uses +/// as the event name. +/// +/// ```rust,ignore +/// use miden_node_utils::tracing::info; +/// +/// let parent = tracing::info_span!("block"); +/// info!(parent: &parent, "block.accepted", block.number = 42_u32); +/// +/// let source = std::io::Error::other("used fallback"); +/// info!(&source, "block.fallback_used", block.number = 42_u32); +/// ``` +#[proc_macro] +pub fn info(input: TokenStream) -> TokenStream { + expand_event(input, "info", false) +} + +/// Emits a warning-level event. +/// +/// An optional first argument may provide an error implementing `ErrorReport`. Its display value +/// and source chain are recorded as `exception.message`; callers do not provide that attribute +/// themselves. +/// +/// The event name is required and must be a string literal. When an error is provided, optional +/// `target:` and `parent:` arguments go between the error and name, in that order. Without an +/// error, they precede the name. Attributes follow the name and must use a registered field name +/// and a value implementing `RecordAttribute`. Append `#[nonstandard]` to a field value to permit +/// an unregistered name while retaining its canonical encoding. Tracing format specifiers and +/// trailing commas are not supported. +/// +/// The name is recorded as tracing's `message` field, which the OpenTelemetry tracing layer uses +/// as the event name. +/// +/// ```rust,ignore +/// use miden_node_utils::tracing::warn; +/// +/// warn!("block.delayed", block.number = 42_u32); +/// +/// let source = std::io::Error::other("upstream unavailable"); +/// warn!(&source, "block.retrying", block.number = 42_u32); +/// ``` +#[proc_macro] +pub fn warn(input: TokenStream) -> TokenStream { + expand_event(input, "warn", false) +} + +/// Emits an error-level event with a complete error report. +/// +/// The first argument is required and must implement `ErrorReport`. Its display value and source +/// chain are recorded as `exception.message`; callers do not provide that attribute themselves. +/// +/// The event name follows the error and must be a string literal. Optional `target:` and `parent:` +/// arguments go between the error and name, in that order. Additional attributes follow the name +/// and must use a registered field name and a value implementing `RecordAttribute`. Append +/// `#[nonstandard]` to a field value to permit an unregistered name while retaining its canonical +/// encoding. Tracing format specifiers and trailing commas are not supported. +/// +/// The name is recorded as tracing's `message` field, which the OpenTelemetry tracing layer uses +/// as the event name. +/// +/// ```rust,ignore +/// use miden_node_utils::tracing::error; +/// +/// let source = std::io::Error::other("database unavailable"); +/// error!(source, target: "node", "block.store_failed", block.number = 42_u32); +/// ``` +#[proc_macro] +pub fn error(input: TokenStream) -> TokenStream { + expand_event(input, "error", true) +} + +fn expand_event(input: TokenStream, level: &str, error_required: bool) -> TokenStream { + let event = if error_required { + syn::parse::(input).map(|event| event.0) + } else { + syn::parse::(input).map(|event| event.0) + }; + let event = match event { + Ok(event) => event, + Err(error) => return error.into_compile_error().into(), + }; + + event.tokens(&Ident::new(level, proc_macro2::Span::call_site())).into() +} + +struct ErrorEvent(Event); + +impl Parse for ErrorEvent { + fn parse(input: ParseStream<'_>) -> Result { + let event = parse_error_event(input)?; + event.reject_exception_message()?; + + Ok(Self(event)) + } +} + +struct OptionalErrorEvent(Event); + +impl Parse for OptionalErrorEvent { + fn parse(input: ParseStream<'_>) -> Result { + let event = if starts_without_error(input) { + Event::parse_after_error(input, None)? + } else { + parse_error_event(input)? + }; + event.reject_exception_message()?; + + Ok(Self(event)) + } +} + +fn parse_error_event(input: ParseStream<'_>) -> Result { + if input.is_empty() { + return Err(input.error("expected an error expression")); + } + + let error = input.parse()?; + if input.is_empty() { + return Err(syn::Error::new_spanned(error, "expected a static event name string literal")); + } + input.parse::()?; + + Event::parse_after_error(input, Some(error)) +} + +struct Event { + error: Option, + target: Option, + parent: Option, + name: LitStr, + fields: Vec, +} + +impl Event { + fn parse_after_error(input: ParseStream<'_>, error: Option) -> Result { + let target = if input.peek(event_kw::target) { + input.parse::()?; + input.parse::()?; + let target = input.parse()?; + input.parse::()?; + Some(target) + } else { + None + }; + + let parent = if input.peek(event_kw::parent) { + input.parse::()?; + input.parse::()?; + let parent = input.parse()?; + input.parse::()?; + Some(parent) + } else { + None + }; + + let name = input + .parse::() + .map_err(|_| input.error("expected a static event name string literal"))?; + let mut fields = Vec::new(); + + if !input.is_empty() { + let comma = input.parse::()?; + if input.is_empty() { + return Err(syn::Error::new_spanned(comma, "trailing commas are not supported")); + } + + loop { + fields.push(RecordField::parse(input, true)?); + if input.is_empty() { + break; + } + + let comma = input.parse::()?; + if input.is_empty() { + return Err(syn::Error::new_spanned( + comma, + "trailing commas are not supported", + )); + } + } + } + + Ok(Self { error, target, parent, name, fields }) + } + + fn reject_exception_message(&self) -> Result<()> { + if let Some(field) = + self.fields.iter().find(|field| field.path.name() == "exception.message") + { + Err(syn::Error::new_spanned( + &field.path, + "pass the error as the first argument instead of recording `exception.message`", + )) + } else { + Ok(()) + } + } + + fn tokens(&self, level: &Ident) -> TokenStream2 { + let target = self.target.as_ref().map(|target| quote! { target: #target, }); + let parent = self.parent.as_ref().map(|parent| quote! { parent: #parent, }); + let name = &self.name; + let error = self.error.as_ref().map(|error| { + quote! { + , exception.message = ::miden_node_utils::tracing::record_attribute( + &({ + use ::miden_node_utils::ErrorReport as _; + (#error).as_report() + }) + ) + } + }); + let fields = self.fields.iter().map(RecordField::instrument_tokens); + + quote! { + ::tracing::#level!( + #target + #parent + message = #name + #error + #(, #fields)* + ) + } + } +} + +mod event_kw { + syn::custom_keyword!(parent); + syn::custom_keyword!(target); +} + +fn starts_without_error(input: ParseStream<'_>) -> bool { + if input.peek(LitStr) { + return true; + } + + let ahead = input.fork(); + let starts_with_target = + ahead.parse::().is_ok() && ahead.parse::().is_ok(); + if starts_with_target { + return true; + } + + let ahead = input.fork(); + ahead.parse::().is_ok() && ahead.parse::().is_ok() +} + fn merge_inferred_fields(attr: TokenStream2, fields: &[FieldPath]) -> Result { let mut args = split_top_level_args(attr); reject_skip_directives(&args)?; diff --git a/crates/utils/src/lib.rs b/crates/utils/src/lib.rs index 3ece42a147..d81fd3233d 100644 --- a/crates/utils/src/lib.rs +++ b/crates/utils/src/lib.rs @@ -1,3 +1,5 @@ +extern crate self as miden_node_utils; + pub mod block_cache; pub mod clap; pub mod cors; @@ -37,7 +39,7 @@ pub trait ErrorReport: std::error::Error { } } -impl ErrorReport for T {} +impl ErrorReport for T {} /// Extends nested results types, allowing them to be flattened. /// diff --git a/crates/utils/src/logging.rs b/crates/utils/src/logging.rs index 4415f7e328..24183cabf2 100644 --- a/crates/utils/src/logging.rs +++ b/crates/utils/src/logging.rs @@ -13,7 +13,7 @@ use tracing_opentelemetry::OpenTelemetryLayer; use tracing_subscriber::layer::{Filter, SubscriberExt}; use tracing_subscriber::{EnvFilter, Layer, Registry}; -use crate::tracing::ErrorSpanExt; +use crate::tracing::{ErrorSpanExt, error}; /// Global tracer provider for flushing traces on panic. /// @@ -226,11 +226,11 @@ pub fn setup_tracing_with_config(config: TracingConfig) -> anyhow::Result