diff --git a/Cargo.lock b/Cargo.lock index cb96c5e3f3..33058dd899 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1852,6 +1852,16 @@ dependencies = [ "slab", ] +[[package]] +name = "fuzzy-search" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "464810ef4f0f4ce4573c9cb2584a5ed78ef0d00ca328ddfc39dc9a89d8d0bef9" +dependencies = [ + "anyhow", + "rayon", +] + [[package]] name = "generator" version = "0.8.8" @@ -3114,6 +3124,7 @@ dependencies = [ "hex", "humantime", "miden-node-proto", + "miden-node-tracing", "miden-node-utils", "miden-protocol", "miden-standards", @@ -3164,6 +3175,7 @@ dependencies = [ "miden-node-proto-build", "miden-node-store", "miden-node-test-macro", + "miden-node-tracing", "miden-node-utils", "miden-node-validator", "miden-protocol", @@ -3222,6 +3234,7 @@ dependencies = [ "miden-node-proto", "miden-node-proto-build", "miden-node-test-macro", + "miden-node-tracing", "miden-node-utils", "miden-protocol", "miden-remote-prover-client", @@ -3292,6 +3305,7 @@ dependencies = [ "miden-node-proto", "miden-node-proto-build", "miden-node-store", + "miden-node-tracing", "miden-node-utils", "miden-protocol", "miden-standards", @@ -3337,6 +3351,7 @@ dependencies = [ "miden-node-proto", "miden-node-proto-build", "miden-node-test-macro", + "miden-node-tracing", "miden-node-utils", "miden-protocol", "miden-remote-prover-client", @@ -3387,6 +3402,28 @@ dependencies = [ "syn 2.0.117", ] +[[package]] +name = "miden-node-tracing" +version = "0.14.0" +dependencies = [ + "async-trait", + "miden-node-tracing-macro", + "miden-node-utils", + "opentelemetry", + "tracing", + "trybuild", +] + +[[package]] +name = "miden-node-tracing-macro" +version = "0.14.0" +dependencies = [ + "fuzzy-search", + "proc-macro2", + "quote", + "syn 2.0.117", +] + [[package]] name = "miden-node-utils" version = "0.14.0" @@ -3433,6 +3470,7 @@ dependencies = [ "miden-node-db", "miden-node-proto", "miden-node-proto-build", + "miden-node-tracing", "miden-node-utils", "miden-protocol", "miden-tx", @@ -3538,6 +3576,7 @@ dependencies = [ "miden-block-prover", "miden-node-proto", "miden-node-proto-build", + "miden-node-tracing", "miden-node-utils", "miden-protocol", "miden-standards", diff --git a/Cargo.toml b/Cargo.toml index 1079a7f9c9..de472cf347 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -16,6 +16,8 @@ members = [ "crates/rpc", "crates/store", "crates/test-macro", + "crates/tracing", + "crates/tracing-macro", "crates/utils", "crates/validator", "proto", @@ -54,12 +56,15 @@ miden-node-proto-build = { path = "proto", version = "0.14" } miden-node-rpc = { path = "crates/rpc", version = "0.14" } miden-node-store = { path = "crates/store", version = "0.14" } miden-node-test-macro = { path = "crates/test-macro" } +miden-node-tracing = { path = "crates/tracing", version = "0.14" } miden-node-utils = { path = "crates/utils", version = "0.14" } miden-node-validator = { path = "crates/validator", version = "0.14" } miden-remote-prover-client = { path = "crates/remote-prover-client", version = "0.14" } # Temporary workaround until # is part of `rocksdb-rust` release miden-node-rocksdb-cxx-linkage-fix = { path = "crates/rocksdb-cxx-linkage-fix", version = "0.14" } +miden-node-tracing-macro = { path = "crates/tracing-macro", version = "0.14" } +trybuild = { features = ["diff"], version = "1.0" } # miden-protocol dependencies. These should be updated in sync. miden-block-prover = { version = "0.14" } diff --git a/bin/network-monitor/Cargo.toml b/bin/network-monitor/Cargo.toml index b39ce93469..a4bf9905d3 100644 --- a/bin/network-monitor/Cargo.toml +++ b/bin/network-monitor/Cargo.toml @@ -15,25 +15,26 @@ version.workspace = true workspace = true [dependencies] -anyhow = { workspace = true } -axum = { version = "0.8" } -clap = { features = ["env"], workspace = true } -hex = { version = "0.4" } -humantime = { workspace = true } -miden-node-proto = { workspace = true } -miden-node-utils = { workspace = true } -miden-protocol = { features = ["std", "testing"], workspace = true } -miden-standards = { workspace = true } -miden-testing = { workspace = true } -miden-tx = { features = ["std"], workspace = true } -rand = { workspace = true } -rand_chacha = { workspace = true } -reqwest = { features = ["json", "query"], workspace = true } -serde = { features = ["derive"], version = "1.0" } -serde_json = { version = "1.0" } -sha2 = { version = "0.10" } -tokio = { features = ["full"], workspace = true } -tonic = { features = ["codegen", "tls-native-roots", "transport"], workspace = true } -tonic-health = { workspace = true } -tracing = { workspace = true } -url = { features = ["serde"], workspace = true } +anyhow = { workspace = true } +axum = { version = "0.8" } +clap = { features = ["env"], workspace = true } +hex = { version = "0.4" } +humantime = { workspace = true } +miden-node-proto = { workspace = true } +miden-node-tracing = { workspace = true } +miden-node-utils = { workspace = true } +miden-protocol = { features = ["std", "testing"], workspace = true } +miden-standards = { workspace = true } +miden-testing = { workspace = true } +miden-tx = { features = ["std"], workspace = true } +rand = { workspace = true } +rand_chacha = { workspace = true } +reqwest = { features = ["json", "query"], workspace = true } +serde = { features = ["derive"], version = "1.0" } +serde_json = { version = "1.0" } +sha2 = { version = "0.10" } +tokio = { features = ["full"], workspace = true } +tonic = { features = ["codegen", "tls-native-roots", "transport"], workspace = true } +tonic-health = { workspace = true } +tracing = { workspace = true } +url = { features = ["serde"], workspace = true } diff --git a/bin/network-monitor/src/commands/start.rs b/bin/network-monitor/src/commands/start.rs index 75cd8f6e83..1255772c57 100644 --- a/bin/network-monitor/src/commands/start.rs +++ b/bin/network-monitor/src/commands/start.rs @@ -3,8 +3,9 @@ //! This module contains the implementation for starting the network monitoring service. use anyhow::Result; +use miden_node_tracing::{debug, info, warn}; use miden_node_utils::logging::OpenTelemetry; -use tracing::{debug, info, instrument, warn}; +use tracing::instrument; use crate::COMPONENT; use crate::config::MonitorConfig; diff --git a/bin/network-monitor/src/counter.rs b/bin/network-monitor/src/counter.rs index 47439986cf..c9ead1f886 100644 --- a/bin/network-monitor/src/counter.rs +++ b/bin/network-monitor/src/counter.rs @@ -12,6 +12,7 @@ use anyhow::{Context, Result}; use miden_node_proto::clients::RpcClient; use miden_node_proto::generated::rpc::BlockHeaderByNumberRequest; use miden_node_proto::generated::transaction::ProvenTransaction; +use miden_node_tracing::{error, info, warn}; use miden_protocol::account::auth::AuthSecretKey; use miden_protocol::account::{Account, AccountFile, AccountHeader, AccountId}; use miden_protocol::assembly::Library; @@ -38,7 +39,7 @@ use miden_tx::{LocalTransactionProver, TransactionExecutor}; use rand::{Rng, SeedableRng}; use rand_chacha::ChaCha20Rng; use tokio::sync::{Mutex, watch}; -use tracing::{error, info, instrument, warn}; +use tracing::instrument; /// Number of consecutive increment failures before re-syncing the wallet account from the RPC. const RESYNC_FAILURE_THRESHOLD: usize = 3; @@ -184,7 +185,7 @@ async fn fetch_wallet_account( let response = match rpc_client.get_account(request).await { Ok(response) => response.into_inner(), Err(e) => { - warn!(account.id = %account_id, err = %e, "failed to fetch wallet account via RPC"); + warn!(account.id = %account_id, "failed to fetch wallet account via RPC: {e}"); return Ok(None); }, }; @@ -519,11 +520,14 @@ async fn try_resync_wallet_account( let fresh_account = fetch_wallet_account(rpc_client, wallet_account.id()) .await .inspect_err(|e| { - error!(account.id = %wallet_account.id(), err = ?e, "failed to re-sync wallet account from RPC"); + error!(account.id = %wallet_account.id(), "failed to re-sync wallet account from RPC: {e:?}"); })? .context("wallet account not found on-chain during re-sync") .inspect_err(|e| { - error!(account.id = %wallet_account.id(), err = ?e, "wallet account not found on-chain during re-sync"); + error!( + account.id = %wallet_account.id(), + "wallet account not found on-chain during re-sync: {e:?}" + ); })?; info!(account.id = %wallet_account.id(), "wallet account re-synced from RPC"); diff --git a/bin/network-monitor/src/explorer.rs b/bin/network-monitor/src/explorer.rs index f912a62dff..ab302eafd7 100644 --- a/bin/network-monitor/src/explorer.rs +++ b/bin/network-monitor/src/explorer.rs @@ -4,11 +4,12 @@ use std::fmt::{self, Display}; use std::time::Duration; +use miden_node_tracing::info; use reqwest::Client; use serde::Serialize; use tokio::sync::watch; use tokio::time::MissedTickBehavior; -use tracing::{info, instrument}; +use tracing::instrument; use url::Url; use crate::status::{ExplorerStatusDetails, ServiceDetails, ServiceStatus, Status}; diff --git a/bin/network-monitor/src/faucet.rs b/bin/network-monitor/src/faucet.rs index 1e50a173d9..9df0b9eb09 100644 --- a/bin/network-monitor/src/faucet.rs +++ b/bin/network-monitor/src/faucet.rs @@ -7,6 +7,7 @@ use std::time::Duration; use anyhow::Context; use hex; +use miden_node_tracing::{debug, info, warn}; use miden_protocol::account::AccountId; use miden_protocol::testing::account_id::ACCOUNT_ID_SENDER; use reqwest::Client; @@ -14,7 +15,7 @@ use serde::{Deserialize, Serialize}; use sha2::{Digest, Sha256}; use tokio::sync::watch; use tokio::time::MissedTickBehavior; -use tracing::{debug, info, instrument, warn}; +use tracing::instrument; use url::Url; use crate::status::{ServiceDetails, ServiceStatus, Status}; diff --git a/bin/network-monitor/src/frontend.rs b/bin/network-monitor/src/frontend.rs index ecc08d26f2..a7a016605c 100644 --- a/bin/network-monitor/src/frontend.rs +++ b/bin/network-monitor/src/frontend.rs @@ -7,8 +7,9 @@ use axum::Router; use axum::http::header; use axum::response::{Html, IntoResponse, Response}; use axum::routing::get; +use miden_node_tracing::info; use tokio::sync::watch; -use tracing::{info, instrument}; +use tracing::instrument; use crate::COMPONENT; use crate::config::MonitorConfig; diff --git a/bin/network-monitor/src/monitor/tasks.rs b/bin/network-monitor/src/monitor/tasks.rs index 57f5ce3950..7c936c031d 100644 --- a/bin/network-monitor/src/monitor/tasks.rs +++ b/bin/network-monitor/src/monitor/tasks.rs @@ -11,10 +11,11 @@ use miden_node_proto::clients::{ RemoteProverProxyStatusClient, RpcClient, }; +use miden_node_tracing::debug; use tokio::sync::watch::Receiver; use tokio::sync::{Mutex, watch}; use tokio::task::{Id, JoinSet}; -use tracing::{debug, instrument}; +use tracing::instrument; use crate::COMPONENT; use crate::config::MonitorConfig; diff --git a/bin/network-monitor/src/note_transport.rs b/bin/network-monitor/src/note_transport.rs index 4556f8bf10..c5c9d14503 100644 --- a/bin/network-monitor/src/note_transport.rs +++ b/bin/network-monitor/src/note_transport.rs @@ -3,12 +3,13 @@ use std::time::Duration; +use miden_node_tracing::info; use tokio::sync::watch; use tokio::time::MissedTickBehavior; use tonic::transport::{Channel, ClientTlsConfig}; use tonic_health::pb::health_client::HealthClient; use tonic_health::pb::{HealthCheckRequest, health_check_response}; -use tracing::{info, instrument}; +use tracing::instrument; use url::Url; use crate::status::{NoteTransportStatusDetails, ServiceDetails, ServiceStatus, Status}; diff --git a/bin/network-monitor/src/remote_prover.rs b/bin/network-monitor/src/remote_prover.rs index ffa2a2724e..ce72c8b682 100644 --- a/bin/network-monitor/src/remote_prover.rs +++ b/bin/network-monitor/src/remote_prover.rs @@ -8,6 +8,7 @@ use std::time::Duration; use anyhow::Context; use miden_node_proto::clients::{Builder as ClientBuilder, RemoteProverClient}; use miden_node_proto::generated as proto; +use miden_node_tracing::info; use miden_protocol::account::auth::AuthScheme; use miden_protocol::asset::{Asset, FungibleAsset}; use miden_protocol::note::NoteType; @@ -19,7 +20,7 @@ use serde::{Deserialize, Serialize}; use tokio::sync::watch; use tokio::time::MissedTickBehavior; use tonic::Request; -use tracing::{info, instrument}; +use tracing::instrument; use url::Url; use crate::status::{ServiceDetails, ServiceStatus, Status}; diff --git a/bin/network-monitor/src/status.rs b/bin/network-monitor/src/status.rs index 419b837b0b..988c36fbd4 100644 --- a/bin/network-monitor/src/status.rs +++ b/bin/network-monitor/src/status.rs @@ -12,10 +12,11 @@ use miden_node_proto::clients::{ }; use miden_node_proto::generated as proto; use miden_node_proto::generated::rpc::{BlockProducerStatus, RpcStatus, StoreStatus}; +use miden_node_tracing::{debug, info}; use serde::{Deserialize, Serialize}; use tokio::sync::watch; use tokio::time::MissedTickBehavior; -use tracing::{debug, info, instrument}; +use tracing::instrument; use url::Url; use crate::faucet::FaucetTestDetails; diff --git a/bin/remote-prover/Cargo.toml b/bin/remote-prover/Cargo.toml index 582bdd94f4..fbe84197cc 100644 --- a/bin/remote-prover/Cargo.toml +++ b/bin/remote-prover/Cargo.toml @@ -23,6 +23,7 @@ humantime = { workspace = true } miden-block-prover = { workspace = true } miden-node-proto = { workspace = true } miden-node-proto-build = { features = ["internal"], workspace = true } +miden-node-tracing = { workspace = true } miden-node-utils = { workspace = true } miden-protocol = { features = ["std"], workspace = true } miden-tx = { features = ["concurrent", "std"], workspace = true } diff --git a/bin/remote-prover/src/main.rs b/bin/remote-prover/src/main.rs index e445d80f14..b747f1d384 100644 --- a/bin/remote-prover/src/main.rs +++ b/bin/remote-prover/src/main.rs @@ -1,7 +1,7 @@ use anyhow::Context; use clap::Parser; +use miden_node_tracing::info; use miden_node_utils::logging::{OpenTelemetry, setup_tracing}; -use tracing::info; mod generated; mod server; diff --git a/crates/block-producer/Cargo.toml b/crates/block-producer/Cargo.toml index c5c62abb3a..cb387e3990 100644 --- a/crates/block-producer/Cargo.toml +++ b/crates/block-producer/Cargo.toml @@ -24,6 +24,7 @@ futures = { workspace = true } itertools = { workspace = true } miden-node-proto = { workspace = true } miden-node-proto-build = { features = ["internal"], workspace = true } +miden-node-tracing = { workspace = true } miden-node-utils = { features = ["testing"], workspace = true } miden-protocol = { default-features = true, workspace = true } miden-remote-prover-client = { features = ["batch-prover", "block-prover"], workspace = true } diff --git a/crates/block-producer/src/batch_builder/mod.rs b/crates/block-producer/src/batch_builder/mod.rs index 34dab83a3f..7ba379c2c4 100644 --- a/crates/block-producer/src/batch_builder/mod.rs +++ b/crates/block-producer/src/batch_builder/mod.rs @@ -6,6 +6,7 @@ use std::time::Duration; use futures::never::Never; use futures::{FutureExt, TryFutureExt}; use miden_node_proto::domain::batch::BatchInputs; +use miden_node_tracing::instrument; use miden_node_utils::tracing::OpenTelemetrySpanExt; use miden_protocol::MIN_PROOF_SECURITY_LEVEL; use miden_protocol::batch::{BatchId, ProposedBatch, ProvenBatch}; @@ -14,15 +15,15 @@ use miden_tx_batch_prover::LocalBatchProver; use rand::Rng; use tokio::task::JoinSet; use tokio::time; -use tracing::{Instrument, Span, instrument}; +use tracing::{Instrument, Span}; use url::Url; +use crate::TelemetryInjectorExt; use crate::domain::batch::SelectedBatch; use crate::domain::transaction::AuthenticatedTransaction; use crate::errors::BuildBatchError; use crate::mempool::SharedMempool; use crate::store::StoreClient; -use crate::{COMPONENT, TelemetryInjectorExt}; // BATCH BUILDER // ================================================================================================ @@ -102,7 +103,7 @@ impl BatchBuilder { } } - #[instrument(parent = None, target = COMPONENT, name = "batch_builder.build_batch", skip_all)] + #[instrument(COMPONENT: root)] async fn build_batch(&mut self, mempool: SharedMempool) { Span::current().set_attribute("workers.count", self.worker_pool.len()); @@ -130,7 +131,7 @@ impl BatchBuilder { /// require the same logic as here to handle the case when the pool is at capacity. This /// design was chosen instead as it removes this branching logic by "always" having the pool /// at max capacity. Instead completed workers wait to be culled by this function. - #[instrument(target = COMPONENT, name = "batch_builder.wait_for_available_worker", skip_all)] + #[instrument(COMPONENT:)] async fn wait_for_available_worker(&mut self) { // We must crash here because otherwise we have a batch that has been selected from the // mempool, but which is now in limbo. This effectively corrupts the mempool. @@ -189,12 +190,12 @@ impl BatchJob { .await; } - #[instrument(target = COMPONENT, name = "batch_builder.select_batch", skip_all)] + #[instrument(COMPONENT:)] async fn select_batch(&self) -> Option { self.mempool.lock().await.select_batch() } - #[instrument(target = COMPONENT, name = "batch_builder.get_batch_inputs", skip_all, err)] + #[instrument(COMPONENT: err)] async fn get_batch_inputs( &self, batch: SelectedBatch, @@ -217,7 +218,7 @@ impl BatchJob { .map(|inputs| (batch, inputs)) } - #[instrument(target = COMPONENT, name = "batch_builder.propose_batch", skip_all, err)] + #[instrument(COMPONENT: err)] async fn propose_batch( selected: SelectedBatch, inputs: BatchInputs, @@ -237,7 +238,7 @@ impl BatchJob { .map_err(BuildBatchError::ProposeBatchError) } - #[instrument(target = COMPONENT, name = "batch_builder.prove_batch", skip_all, err)] + #[instrument(COMPONENT: err)] async fn prove_batch( &self, proposed_batch: ProposedBatch, @@ -267,7 +268,7 @@ impl BatchJob { } } - #[instrument(target = COMPONENT, name = "batch_builder.inject_failure", skip_all, err)] + #[instrument(COMPONENT: err)] async fn inject_failure(&self, value: T) -> Result { let roll = rand::rng().random::(); @@ -281,12 +282,12 @@ impl BatchJob { } } - #[instrument(target = COMPONENT, name = "batch_builder.commit_batch", skip_all)] + #[instrument(COMPONENT:)] async fn commit_batch(&self, batch: Arc) { self.mempool.lock().await.commit_batch(batch); } - #[instrument(target = COMPONENT, name = "batch_builder.rollback_batch", skip_all)] + #[instrument(COMPONENT:)] async fn rollback_batch(&self, batch_id: BatchId) { self.mempool.lock().await.rollback_batch(batch_id); } diff --git a/crates/block-producer/src/block_builder/mod.rs b/crates/block-producer/src/block_builder/mod.rs index 0a669d2854..fdd53dffcb 100644 --- a/crates/block-producer/src/block_builder/mod.rs +++ b/crates/block-producer/src/block_builder/mod.rs @@ -3,19 +3,20 @@ use std::sync::Arc; use anyhow::Context; use futures::FutureExt; +use miden_node_tracing::instrument; use miden_node_utils::tracing::OpenTelemetrySpanExt; use miden_protocol::batch::{OrderedBatches, ProvenBatch}; use miden_protocol::block::{BlockInputs, BlockNumber, ProposedBlock, ProvenBlock, SignedBlock}; use miden_protocol::note::NoteHeader; use miden_protocol::transaction::TransactionHeader; use tokio::time::Duration; -use tracing::{Span, instrument}; +use tracing::Span; +use crate::TelemetryInjectorExt; use crate::errors::BuildBlockError; use crate::mempool::SharedMempool; use crate::store::StoreClient; use crate::validator::BlockProducerValidatorClient; -use crate::{COMPONENT, TelemetryInjectorExt}; // BLOCK BUILDER // ================================================================================================= @@ -102,7 +103,7 @@ impl BlockBuilder { /// - Each stage has its own child span and are free to add further field data. /// - A failed stage will emit an error event, and both its own span and the root span will be /// marked as errors. - #[instrument(parent = None, target = COMPONENT, name = "block_builder.build_block", skip_all)] + #[instrument(COMPONENT: root)] async fn build_block(&self, mempool: &SharedMempool) -> Result<(), BuildBlockError> { use futures::TryFutureExt; @@ -126,7 +127,7 @@ impl BlockBuilder { .await } - #[instrument(target = COMPONENT, name = "block_builder.select_block", skip_all)] + #[instrument(COMPONENT:)] async fn select_block(mempool: &SharedMempool) -> SelectedBlock { let (block_number, batches) = mempool.lock().await.select_block(); SelectedBlock { block_number, batches } @@ -148,7 +149,7 @@ impl BlockBuilder { /// which nullifiers the block will actually create, we fetch witnesses for all nullifiers /// created by batches. If we knew that a certain note will be erased, we would not have to /// supply a nullifier witness for it. - #[instrument(target = COMPONENT, name = "block_builder.get_block_inputs", skip_all, err)] + #[instrument(COMPONENT: err)] async fn get_block_inputs( &self, selected_block: SelectedBlock, @@ -206,7 +207,7 @@ impl BlockBuilder { Ok(BlockBatchesAndInputs { batches, inputs }) } - #[instrument(target = COMPONENT, name = "block_builder.propose_block", skip_all, err)] + #[instrument(COMPONENT: err)] async fn propose_block( &self, batches_inputs: BlockBatchesAndInputs, @@ -220,7 +221,7 @@ impl BlockBuilder { Ok(proposed_block) } - #[instrument(target = COMPONENT, name = "block_builder.validate_block", skip_all, err)] + #[instrument(COMPONENT: err)] async fn build_and_validate_block( &self, proposed_block: ProposedBlock, @@ -254,7 +255,7 @@ impl BlockBuilder { Ok((ordered_batches, signed_block)) } - #[instrument(target = COMPONENT, name = "block_builder.commit_block", skip_all, err)] + #[instrument(COMPONENT: err)] async fn commit_block( &self, mempool: &SharedMempool, @@ -272,7 +273,7 @@ impl BlockBuilder { Ok(()) } - #[instrument(target = COMPONENT, name = "block_builder.rollback_block", skip_all)] + #[instrument(COMPONENT:)] async fn rollback_block(&self, mempool: &SharedMempool, block: BlockNumber) { mempool.lock().await.rollback_block(block); } diff --git a/crates/block-producer/src/mempool/mod.rs b/crates/block-producer/src/mempool/mod.rs index 8d59f3ad4b..dd78ef97e6 100644 --- a/crates/block-producer/src/mempool/mod.rs +++ b/crates/block-producer/src/mempool/mod.rs @@ -46,12 +46,12 @@ use std::num::NonZeroUsize; use std::sync::Arc; use miden_node_proto::domain::mempool::MempoolEvent; +use miden_node_tracing::instrument; use miden_protocol::batch::{BatchId, ProvenBatch}; use miden_protocol::block::{BlockHeader, BlockNumber}; use miden_protocol::transaction::TransactionId; use subscription::SubscriptionProvider; use tokio::sync::{Mutex, MutexGuard, mpsc}; -use tracing::{instrument, warn}; use crate::domain::batch::SelectedBatch; use crate::domain::transaction::AuthenticatedTransaction; @@ -59,7 +59,6 @@ use crate::errors::{AddTransactionError, VerifyTxError}; use crate::mempool::budget::BudgetStatus; use crate::mempool::nodes::{BlockNode, Node, NodeId, ProposedBatchNode, TransactionNode}; use crate::{ - COMPONENT, DEFAULT_MEMPOOL_TX_CAPACITY, SERVER_MEMPOOL_EXPIRATION_SLACK, SERVER_MEMPOOL_STATE_RETENTION, @@ -133,7 +132,7 @@ impl Default for MempoolConfig { // ================================================================================================ impl SharedMempool { - #[instrument(target = COMPONENT, name = "mempool.lock", skip_all)] + #[instrument(COMPONENT:)] pub async fn lock(&self) -> MutexGuard<'_, Mempool> { self.0.lock().await } @@ -204,7 +203,7 @@ impl Mempool { /// # Errors /// /// Returns an error if the transaction's initial conditions don't match the current state. - #[instrument(target = COMPONENT, name = "mempool.add_transaction", skip_all, fields(tx=%tx.id()))] + #[instrument(COMPONENT: transaction.id = %tx.id())] pub fn add_transaction( &mut self, tx: Arc, @@ -263,7 +262,7 @@ impl Mempool { /// Transactions are returned in a valid execution ordering. /// /// Returns `None` if no transactions are available. - #[instrument(target = COMPONENT, name = "mempool.select_batch", skip_all)] + #[instrument(COMPONENT:)] pub fn select_batch(&mut self) -> Option { // The selection algorithm is fairly neanderthal in nature. // @@ -343,7 +342,7 @@ impl Mempool { /// Drops the proposed batch and all of its descendants. /// /// Transactions are re-queued. - #[instrument(target = COMPONENT, name = "mempool.rollback_batch", skip_all)] + #[instrument(COMPONENT:)] pub fn rollback_batch(&mut self, batch: BatchId) { // Due to the distributed nature of the system, its possible that a proposed batch was // already proven, or already reverted. This guards against this eventuality. @@ -377,7 +376,7 @@ impl Mempool { } /// Marks a batch as proven if it exists. - #[instrument(target = COMPONENT, name = "mempool.commit_batch", skip_all)] + #[instrument(COMPONENT:)] pub fn commit_batch(&mut self, proof: Arc) { // Due to the distributed nature of the system, its possible that a proposed batch was // already proven, or already reverted. This guards against this eventuality. @@ -403,7 +402,7 @@ impl Mempool { /// # Panics /// /// Panics if there is already a block in flight. - #[instrument(target = COMPONENT, name = "mempool.select_block", skip_all)] + #[instrument(COMPONENT:)] pub fn select_block(&mut self) -> (BlockNumber, Vec>) { // The selection algorithm is fairly neanderthal in nature. // @@ -486,7 +485,7 @@ impl Mempool { /// # Panics /// /// Panics if there is no block in flight. - #[instrument(target = COMPONENT, name = "mempool.commit_block", skip_all)] + #[instrument(COMPONENT:)] pub fn commit_block(&mut self, to_commit: BlockHeader) { let block = self .nodes @@ -522,7 +521,7 @@ impl Mempool { /// # Panics /// /// Panics if there is no block in flight. - #[instrument(target = COMPONENT, name = "mempool.rollback_block", skip_all)] + #[instrument(COMPONENT:)] pub fn rollback_block(&mut self, block: BlockNumber) { // Only revert if the given block is actually inflight. // @@ -586,7 +585,7 @@ impl Mempool { /// Creates a subscription to [`MempoolEvent`] which will be emitted in the order they occur. /// /// Only emits events which occurred after the current committed block. - #[instrument(target = COMPONENT, name = "mempool.subscribe", skip_all)] + #[instrument(COMPONENT:)] pub fn subscribe(&mut self) -> mpsc::Receiver { self.subscription.subscribe() } diff --git a/crates/block-producer/src/mempool/tests.rs b/crates/block-producer/src/mempool/tests.rs index 5cafd0137d..b7fa687ecd 100644 --- a/crates/block-producer/src/mempool/tests.rs +++ b/crates/block-producer/src/mempool/tests.rs @@ -1,5 +1,7 @@ use std::sync::Arc; +use std::time::Duration; +use assert_matches::assert_matches; use miden_protocol::Word; use miden_protocol::block::{BlockHeader, BlockNumber}; use pretty_assertions::assert_eq; @@ -44,16 +46,24 @@ async fn add_transaction_traces_are_correct() { let txs = MockProvenTxBuilder::sequential(); uut.add_transaction(txs[0].clone()).unwrap(); - let span_data = rx_export.recv().await.unwrap(); - assert_eq!(span_data.name, "mempool.add_transaction"); + let mut found_span = None; + for _ in 0..500 { + if let Ok(span_data) = tokio::time::timeout(Duration::from_secs(1), rx_export.recv()).await + { + let span_data = span_data.unwrap(); + if span_data.name.as_ref() == "COMPONENT.add_transaction" { + found_span = Some(span_data); + break; + } + } + } + + assert_matches!(&found_span, Some(span_data) if span_data.name.as_ref() == "COMPONENT.add_transaction"); + let Some(span_data) = found_span else { + unreachable!(); + }; assert!(span_data.attributes.iter().any(|kv| kv.key == "code.module.name".into() && kv.value == "miden_node_block_producer::mempool".into())); - assert!( - span_data - .attributes - .iter() - .any(|kv| kv.key == "tx".into() && kv.value.to_string().starts_with("0x")) - ); } // BATCH FAILED TESTS diff --git a/crates/block-producer/src/server/mod.rs b/crates/block-producer/src/server/mod.rs index 7392a15412..1cb2520dbd 100644 --- a/crates/block-producer/src/server/mod.rs +++ b/crates/block-producer/src/server/mod.rs @@ -10,6 +10,7 @@ use miden_node_proto::domain::mempool::MempoolEvent; use miden_node_proto::generated::block_producer::api_server; use miden_node_proto::generated::{self as proto}; use miden_node_proto_build::block_producer_api_descriptor; +use miden_node_tracing::{debug, error, info, instrument}; use miden_node_utils::clap::GrpcOptionsInternal; use miden_node_utils::formatting::{format_input_notes, format_output_notes}; use miden_node_utils::panic::{CatchPanicLayer, catch_panic_layer_fn}; @@ -23,7 +24,6 @@ use tokio::sync::{Mutex, RwLock}; use tokio_stream::wrappers::{ReceiverStream, TcpListenerStream}; use tonic::Status; use tower_http::trace::TraceLayer; -use tracing::{debug, error, info, instrument}; use url::Url; use crate::batch_builder::BatchBuilder; @@ -98,11 +98,12 @@ impl BlockProducer { .min(Duration::from_secs(30)); error!( - store = %self.store_url, + target: COMPONENT, ?backoff, %retries_counter, %err, - "store connection failed while fetching chain tip, retrying" + "store connection failed while fetching chain tip from {store}, retrying", + store = self.store_url, ); retries_counter += 1; @@ -301,12 +302,7 @@ impl BlockProducerRpcServer { // RPC ENDPOINTS // -------------------------------------------------------------------------------------------- - #[instrument( - target = COMPONENT, - name = "block_producer.server.submit_proven_transaction", - skip_all, - err - )] + #[instrument(COMPONENT: err)] async fn submit_proven_transaction( &self, request: proto::transaction::ProvenTransaction, @@ -345,12 +341,7 @@ impl BlockProducerRpcServer { .map(|block_height| proto::blockchain::BlockNumber { block_num: block_height.as_u32() }) } - #[instrument( - target = COMPONENT, - name = "block_producer.server.submit_proven_batch", - skip_all, - err - )] + #[instrument(COMPONENT: err)] async fn submit_proven_batch( &self, request: proto::transaction::ProvenTransactionBatch, diff --git a/crates/block-producer/src/store/mod.rs b/crates/block-producer/src/store/mod.rs index 391f747ba1..1ac6adc974 100644 --- a/crates/block-producer/src/store/mod.rs +++ b/crates/block-producer/src/store/mod.rs @@ -7,6 +7,7 @@ use miden_node_proto::clients::{Builder, StoreBlockProducerClient}; use miden_node_proto::domain::batch::BatchInputs; use miden_node_proto::errors::{ConversionError, MissingFieldHelper}; use miden_node_proto::{AccountState, generated as proto}; +use miden_node_tracing::{debug, info, instrument}; use miden_node_utils::formatting::format_opt; use miden_protocol::Word; use miden_protocol::account::AccountId; @@ -15,7 +16,6 @@ use miden_protocol::block::{BlockHeader, BlockInputs, BlockNumber, SignedBlock}; use miden_protocol::note::Nullifier; use miden_protocol::transaction::ProvenTransaction; use miden_protocol::utils::serde::Serializable; -use tracing::{debug, info, instrument}; use url::Url; use crate::COMPONENT; @@ -137,7 +137,7 @@ impl StoreClient { } /// Returns the latest block's header from the store. - #[instrument(target = COMPONENT, name = "store.client.latest_header", skip_all, err)] + #[instrument(COMPONENT: err)] pub async fn latest_header(&self) -> Result { let response = self .client @@ -155,7 +155,7 @@ impl StoreClient { BlockHeader::try_from(response).map_err(Into::into) } - #[instrument(target = COMPONENT, name = "store.client.get_tx_inputs", skip_all, err)] + #[instrument(COMPONENT: err)] pub async fn get_tx_inputs( &self, proven_tx: &ProvenTransaction, @@ -200,7 +200,7 @@ impl StoreClient { Ok(tx_inputs) } - #[instrument(target = COMPONENT, name = "store.client.get_block_inputs", skip_all, err)] + #[instrument(COMPONENT: err)] pub async fn get_block_inputs( &self, updated_accounts: impl Iterator + Send, @@ -222,7 +222,7 @@ impl StoreClient { store_response.try_into().map_err(Into::into) } - #[instrument(target = COMPONENT, name = "store.client.get_batch_inputs", skip_all, err)] + #[instrument(COMPONENT: err)] pub async fn get_batch_inputs( &self, block_references: impl Iterator + Send, @@ -238,7 +238,7 @@ impl StoreClient { store_response.try_into().map_err(Into::into) } - #[instrument(target = COMPONENT, name = "store.client.apply_block", skip_all, err)] + #[instrument(COMPONENT: err)] pub async fn apply_block( &self, ordered_batches: &OrderedBatches, diff --git a/crates/block-producer/src/validator/mod.rs b/crates/block-producer/src/validator/mod.rs index 085ea61f12..b9e78dd721 100644 --- a/crates/block-producer/src/validator/mod.rs +++ b/crates/block-producer/src/validator/mod.rs @@ -1,10 +1,10 @@ use miden_node_proto::clients::{Builder, ValidatorClient}; use miden_node_proto::generated as proto; +use miden_node_tracing::{info, instrument}; use miden_protocol::block::ProposedBlock; use miden_protocol::crypto::dsa::ecdsa_k256_keccak::Signature; use miden_protocol::utils::serde::{Deserializable, DeserializationError, Serializable}; use thiserror::Error; -use tracing::{info, instrument}; use url::Url; use crate::COMPONENT; @@ -47,7 +47,7 @@ impl BlockProducerValidatorClient { Self { client: validator } } - #[instrument(target = COMPONENT, name = "validator.client.validate_block", skip_all, err)] + #[instrument(COMPONENT: err)] pub async fn sign_block( &self, proposed_block: ProposedBlock, diff --git a/crates/ntx-builder/Cargo.toml b/crates/ntx-builder/Cargo.toml index a614ddb1a3..84f9f7bc98 100644 --- a/crates/ntx-builder/Cargo.toml +++ b/crates/ntx-builder/Cargo.toml @@ -22,6 +22,7 @@ libsqlite3-sys = { workspace = true } miden-node-db = { workspace = true } miden-node-proto = { workspace = true } miden-node-proto-build = { features = ["internal"], workspace = true } +miden-node-tracing = { workspace = true } miden-node-utils = { workspace = true } miden-protocol = { default-features = true, workspace = true } miden-remote-prover-client = { features = ["tx-prover"], workspace = true } diff --git a/crates/ntx-builder/src/actor/execute.rs b/crates/ntx-builder/src/actor/execute.rs index 9718056eea..359b17d704 100644 --- a/crates/ntx-builder/src/actor/execute.rs +++ b/crates/ntx-builder/src/actor/execute.rs @@ -1,6 +1,7 @@ use std::collections::{BTreeMap, BTreeSet}; use std::sync::Arc; +use miden_node_tracing::instrument; use miden_node_utils::ErrorReport; use miden_node_utils::lru_cache::LruCache; use miden_node_utils::tracing::OpenTelemetrySpanExt; @@ -49,9 +50,8 @@ use miden_tx::{ TransactionProverError, }; use tokio::sync::Mutex; -use tracing::{Instrument, instrument}; +use tracing::Instrument; -use crate::COMPONENT; use crate::actor::candidate::TransactionCandidate; use crate::clients::{BlockProducerClient, StoreClient, ValidatorClient}; use crate::db::Db; @@ -175,7 +175,7 @@ impl NtxContext { /// - Transaction execution. /// - Proof generation. /// - Submission to the network. - #[instrument(target = COMPONENT, name = "ntx.execute_transaction", skip_all, err)] + #[instrument(COMPONENT:)] pub fn execute_transaction( self, tx: TransactionCandidate, @@ -251,7 +251,7 @@ impl NtxContext { /// Returns an [`NtxError`] if: /// - The consumability check fails unexpectedly. /// - All notes fail the check (i.e., no note is consumable). - #[instrument(target = COMPONENT, name = "ntx.execute_transaction.filter_notes", skip_all, err)] + #[instrument(COMPONENT:)] async fn filter_notes( &self, data_store: &NtxDataStore, @@ -294,7 +294,7 @@ impl NtxContext { } /// Creates an executes a transaction with the network account and the given set of notes. - #[instrument(target = COMPONENT, name = "ntx.execute_transaction.execute", skip_all, err)] + #[instrument(COMPONENT:)] async fn execute( &self, data_store: &NtxDataStore, @@ -314,7 +314,7 @@ impl NtxContext { /// Delegates the transaction proof to the remote prover if configured, otherwise performs the /// proof locally. - #[instrument(target = COMPONENT, name = "ntx.execute_transaction.prove", skip_all, err)] + #[instrument(COMPONENT:)] async fn prove(&self, tx_inputs: &TransactionInputs) -> NtxResult { if let Some(remote) = &self.prover { remote.prove(tx_inputs).await @@ -327,7 +327,7 @@ impl NtxContext { } /// Submits the transaction to the block producer. - #[instrument(target = COMPONENT, name = "ntx.execute_transaction.submit", skip_all, err)] + #[instrument(COMPONENT:)] async fn submit(&self, proven_tx: &ProvenTransaction) -> NtxResult<()> { self.block_producer .submit_proven_transaction(proven_tx) @@ -336,7 +336,7 @@ impl NtxContext { } /// Validates the transaction against the Validator. - #[instrument(target = COMPONENT, name = "ntx.execute_transaction.validate", skip_all, err)] + #[instrument(COMPONENT:)] async fn validate( &self, proven_tx: &ProvenTransaction, diff --git a/crates/ntx-builder/src/actor/mod.rs b/crates/ntx-builder/src/actor/mod.rs index e02354f91a..cea5236b86 100644 --- a/crates/ntx-builder/src/actor/mod.rs +++ b/crates/ntx-builder/src/actor/mod.rs @@ -9,6 +9,7 @@ use anyhow::Context; use candidate::TransactionCandidate; use futures::FutureExt; use miden_node_proto::domain::account::NetworkAccountId; +use miden_node_tracing::instrument; use miden_node_utils::ErrorReport; use miden_node_utils::lru_cache::LruCache; use miden_protocol::Word; @@ -380,10 +381,10 @@ impl AccountActor { /// Execute a transaction candidate and mark notes as failed as required. /// /// Updates the state of the actor based on the execution result. - #[tracing::instrument(name = "ntx.actor.execute_transactions", skip(self, tx_candidate))] + #[instrument(COMPONENT:)] async fn execute_transactions( &mut self, - account_id: NetworkAccountId, + _account_id: NetworkAccountId, tx_candidate: TransactionCandidate, ) { let block_num = tx_candidate.chain_tip_header.block_num(); diff --git a/crates/ntx-builder/src/builder.rs b/crates/ntx-builder/src/builder.rs index 3cb2d60a4b..1c04990d9b 100644 --- a/crates/ntx-builder/src/builder.rs +++ b/crates/ntx-builder/src/builder.rs @@ -5,6 +5,7 @@ use anyhow::Context; use futures::Stream; use miden_node_proto::domain::account::NetworkAccountId; use miden_node_proto::domain::mempool::MempoolEvent; +use miden_node_tracing::instrument; use miden_protocol::account::delta::AccountUpdateDetails; use miden_protocol::block::BlockHeader; use tokio::net::TcpListener; @@ -184,7 +185,7 @@ impl NetworkTransactionBuilder { } /// Handles account IDs loaded from the store by syncing state to DB and spawning actors. - #[tracing::instrument(name = "ntx.builder.handle_loaded_account", skip(self, account_id))] + #[instrument(COMPONENT:)] async fn handle_loaded_account( &mut self, account_id: NetworkAccountId, @@ -216,7 +217,7 @@ impl NetworkTransactionBuilder { } /// Handles mempool events by writing to DB first, then notifying actors. - #[tracing::instrument(name = "ntx.builder.handle_mempool_event", skip(self, event))] + #[instrument(COMPONENT:)] async fn handle_mempool_event(&mut self, event: MempoolEvent) -> Result<(), anyhow::Error> { match &event { MempoolEvent::TransactionAdded { account_delta, .. } => { diff --git a/crates/ntx-builder/src/clients/block_producer.rs b/crates/ntx-builder/src/clients/block_producer.rs index c58522165b..e406624b52 100644 --- a/crates/ntx-builder/src/clients/block_producer.rs +++ b/crates/ntx-builder/src/clients/block_producer.rs @@ -4,12 +4,13 @@ use futures::{TryStream, TryStreamExt}; use miden_node_proto::clients::{BlockProducerClient as InnerBlockProducerClient, Builder}; use miden_node_proto::domain::mempool::MempoolEvent; use miden_node_proto::generated::{self as proto}; +// Use standard tracing for Status errors (which don't impl std::error::Error) +use miden_node_tracing::{info, instrument}; use miden_node_utils::FlattenResult; use miden_protocol::transaction::ProvenTransaction; use miden_protocol::utils::serde::Serializable; use tokio_stream::StreamExt; use tonic::Status; -use tracing::{info, instrument}; use url::Url; use crate::COMPONENT; @@ -41,7 +42,7 @@ impl BlockProducerClient { Self { client: block_producer } } - #[instrument(target = COMPONENT, name = "ntx.block_producer.client.submit_proven_transaction", skip_all, err)] + #[instrument(COMPONENT: err)] pub async fn submit_proven_transaction( &self, proven_tx: &ProvenTransaction, @@ -57,7 +58,7 @@ impl BlockProducerClient { Ok(()) } - #[instrument(target = COMPONENT, name = "ntx.block_producer.client.subscribe_to_mempool", skip_all, err)] + #[instrument(COMPONENT: err)] pub async fn subscribe_to_mempool_with_retry( &self, ) -> Result + Send + 'static, Status> { diff --git a/crates/ntx-builder/src/clients/store.rs b/crates/ntx-builder/src/clients/store.rs index 598de6d672..5c9eb7ccbd 100644 --- a/crates/ntx-builder/src/clients/store.rs +++ b/crates/ntx-builder/src/clients/store.rs @@ -8,6 +8,7 @@ use miden_node_proto::errors::ConversionError; use miden_node_proto::generated::rpc::BlockRange; use miden_node_proto::generated::{self as proto}; use miden_node_proto::try_convert; +use miden_node_tracing::{info, instrument}; use miden_node_utils::tracing::OpenTelemetrySpanExt; use miden_protocol::Word; use miden_protocol::account::{ @@ -29,7 +30,6 @@ use miden_protocol::transaction::AccountInputs; use miden_protocol::utils::serde::{Deserializable, Serializable}; use miden_standards::note::AccountTargetNetworkNote; use thiserror::Error; -use tracing::{info, instrument}; use url::Url; use crate::COMPONENT; @@ -62,7 +62,7 @@ impl StoreClient { } /// Returns the block header and MMR peaks at the current chain tip. - #[instrument(target = COMPONENT, name = "store.client.get_latest_blockchain_data_with_retry", skip_all, err)] + #[instrument(COMPONENT: err)] pub async fn get_latest_blockchain_data_with_retry( &self, ) -> Result, StoreError> { @@ -90,7 +90,7 @@ impl StoreClient { } } - #[instrument(target = COMPONENT, name = "store.client.get_latest_blockchain_data", skip_all, err)] + #[instrument(COMPONENT: err)] async fn get_latest_blockchain_data( &self, ) -> Result, StoreError> { @@ -121,7 +121,7 @@ impl StoreClient { } } - #[instrument(target = COMPONENT, name = "store.client.get_network_account", skip_all, err)] + #[instrument(COMPONENT: err)] pub async fn get_network_account( &self, account_id: NetworkAccountId, @@ -155,7 +155,7 @@ impl StoreClient { /// Retrieves account details from the store. The retrieved details are limited to the account /// code, account header, and storage header. The vault and storage slots are not required for /// the purposes of the NTX Builder. - #[instrument(target = COMPONENT, name = "store.client.get_account_inputs", skip_all, err)] + #[instrument(COMPONENT: err)] pub async fn get_account_inputs( &self, account_id: AccountId, @@ -192,7 +192,7 @@ impl StoreClient { /// Returns the list of unconsumed network notes for a specific network account up to a /// specified block. - #[instrument(target = COMPONENT, name = "store.client.get_unconsumed_network_notes", skip_all, err)] + #[instrument(COMPONENT: err)] pub async fn get_unconsumed_network_notes( &self, network_account_id: NetworkAccountId, @@ -249,7 +249,7 @@ impl StoreClient { /// Loads a single page of network accounts and submits them to the sender. /// /// Returns the next block number to fetch from, or `None` if the chain tip has been reached. - #[instrument(target = COMPONENT, name = "store.client.load_accounts_page", skip_all, err)] + #[instrument(COMPONENT: err)] async fn load_accounts_page( &self, block_range: RangeInclusive, @@ -269,7 +269,7 @@ impl StoreClient { } } - #[instrument(target = COMPONENT, name = "store.client.fetch_network_account_ids_page", skip_all, err)] + #[instrument(COMPONENT: err)] async fn fetch_network_account_ids_page( &self, block_range: std::ops::RangeInclusive, @@ -340,11 +340,7 @@ impl StoreClient { Ok((accounts, pagination_info)) } - #[instrument( - target = COMPONENT, - name = "store.client.send_accounts_to_channel", - skip_all - )] + #[instrument(COMPONENT:)] async fn send_accounts_to_channel( &self, accounts: Vec, @@ -361,7 +357,7 @@ impl StoreClient { Ok(()) } - #[instrument(target = COMPONENT, name = "store.client.get_note_script_by_root", skip_all, err)] + #[instrument(COMPONENT: err)] pub async fn get_note_script_by_root( &self, root: Word, @@ -376,7 +372,7 @@ impl StoreClient { .map_err(StoreError::DeserializationError) } - #[instrument(target = COMPONENT, name = "store.client.get_vault_asset_witnesses", skip_all, err)] + #[instrument(COMPONENT: err)] pub async fn get_vault_asset_witnesses( &self, account_id: AccountId, @@ -417,7 +413,7 @@ impl StoreClient { Ok(asset_witnesses) } - #[instrument(target = COMPONENT, name = "store.client.get_storage_map_witness", skip_all, err)] + #[instrument(COMPONENT: err)] pub async fn get_storage_map_witness( &self, account_id: AccountId, diff --git a/crates/ntx-builder/src/coordinator.rs b/crates/ntx-builder/src/coordinator.rs index 87aa5edcd1..eba20b8b20 100644 --- a/crates/ntx-builder/src/coordinator.rs +++ b/crates/ntx-builder/src/coordinator.rs @@ -4,6 +4,7 @@ use std::sync::Arc; use miden_node_db::DatabaseError; use miden_node_proto::domain::account::NetworkAccountId; use miden_node_proto::domain::mempool::MempoolEvent; +use miden_node_tracing::instrument; use miden_protocol::account::delta::AccountUpdateDetails; use tokio::sync::{Notify, Semaphore}; use tokio::task::JoinSet; @@ -133,7 +134,7 @@ impl Coordinator { /// This method creates a new [`AccountActor`] instance for the specified account origin /// and adds it to the coordinator's management system. The actor will be responsible for /// processing transactions and managing state for the network account. - #[tracing::instrument(name = "ntx.builder.spawn_actor", skip(self, origin, actor_context))] + #[instrument(COMPONENT:)] pub fn spawn_actor(&mut self, origin: AccountOrigin, actor_context: &AccountActorContext) { let account_id = origin.id(); diff --git a/crates/ntx-builder/src/db/migrations.rs b/crates/ntx-builder/src/db/migrations.rs index f3955cb2ad..089513ea06 100644 --- a/crates/ntx-builder/src/db/migrations.rs +++ b/crates/ntx-builder/src/db/migrations.rs @@ -1,7 +1,7 @@ use diesel::SqliteConnection; use diesel_migrations::{EmbeddedMigrations, MigrationHarness, embed_migrations}; use miden_node_db::DatabaseError; -use tracing::instrument; +use miden_node_tracing::instrument; use crate::COMPONENT; use crate::db::schema_hash::verify_schema; @@ -10,7 +10,7 @@ use crate::db::schema_hash::verify_schema; // . pub const MIGRATIONS: EmbeddedMigrations = embed_migrations!("src/db/migrations"); -#[instrument(level = "debug", target = COMPONENT, skip_all, err)] +#[instrument(COMPONENT: err)] pub fn apply_migrations(conn: &mut SqliteConnection) -> Result<(), DatabaseError> { let migrations = conn.pending_migrations(MIGRATIONS).expect("In memory migrations never fail"); tracing::info!(target: COMPONENT, migrations = migrations.len(), "Applying pending migrations"); diff --git a/crates/ntx-builder/src/db/mod.rs b/crates/ntx-builder/src/db/mod.rs index 28f1fef933..5cf9afdf0e 100644 --- a/crates/ntx-builder/src/db/mod.rs +++ b/crates/ntx-builder/src/db/mod.rs @@ -3,6 +3,7 @@ use std::path::PathBuf; use anyhow::Context; use miden_node_db::DatabaseError; use miden_node_proto::domain::account::NetworkAccountId; +use miden_node_tracing::{info, instrument}; use miden_protocol::Word; use miden_protocol::account::Account; use miden_protocol::account::delta::AccountUpdateDetails; @@ -10,7 +11,6 @@ use miden_protocol::block::{BlockHeader, BlockNumber}; use miden_protocol::note::{NoteId, NoteScript, Nullifier}; use miden_protocol::transaction::TransactionId; use miden_standards::note::AccountTargetNetworkNote; -use tracing::{info, instrument}; use crate::db::migrations::apply_migrations; use crate::db::models::queries; @@ -34,13 +34,7 @@ pub struct Db { impl Db { /// Creates and initializes the database, then opens an async connection pool. - #[instrument( - target = COMPONENT, - name = "ntx_builder.database.setup", - skip_all, - fields(path=%database_filepath.display()), - err, - )] + #[instrument(COMPONENT: err)] pub async fn setup(database_filepath: PathBuf) -> anyhow::Result { let inner = miden_node_db::Db::new(&database_filepath) .context("failed to build connection pool")?; diff --git a/crates/ntx-builder/src/db/schema_hash.rs b/crates/ntx-builder/src/db/schema_hash.rs index 80d00b4c47..2ed4bff11d 100644 --- a/crates/ntx-builder/src/db/schema_hash.rs +++ b/crates/ntx-builder/src/db/schema_hash.rs @@ -12,7 +12,7 @@ use diesel::{Connection, RunQueryDsl, SqliteConnection}; use diesel_migrations::MigrationHarness; use miden_node_db::SchemaVerificationError; -use tracing::instrument; +use miden_node_tracing::instrument; use crate::COMPONENT; use crate::db::migrations::MIGRATIONS; @@ -83,7 +83,7 @@ fn compute_expected_schema() -> Result, SchemaVerificationErro /// # Errors /// /// Returns `SchemaVerificationError::Mismatch` if schemas differ. -#[instrument(level = "info", target = COMPONENT, skip_all, err)] +#[instrument(COMPONENT: err)] pub fn verify_schema(conn: &mut SqliteConnection) -> Result<(), SchemaVerificationError> { let expected = compute_expected_schema()?; let actual = extract_schema(conn)?; diff --git a/crates/rpc/Cargo.toml b/crates/rpc/Cargo.toml index 60e48c3ded..9e3a448dbc 100644 --- a/crates/rpc/Cargo.toml +++ b/crates/rpc/Cargo.toml @@ -21,6 +21,7 @@ http = { workspace = true } mediatype = { version = "0.21" } miden-node-proto = { workspace = true } miden-node-proto-build = { workspace = true } +miden-node-tracing = { workspace = true } miden-node-utils = { workspace = true } miden-protocol = { default-features = true, workspace = true } miden-tx = { default-features = true, workspace = true } diff --git a/crates/rpc/src/server/api.rs b/crates/rpc/src/server/api.rs index 8f2b8e34ae..660235c088 100644 --- a/crates/rpc/src/server/api.rs +++ b/crates/rpc/src/server/api.rs @@ -14,6 +14,7 @@ use miden_node_proto::generated::rpc::MempoolStats; use miden_node_proto::generated::rpc::api_server::{self, Api}; use miden_node_proto::generated::{self as proto}; use miden_node_proto::try_convert; +use miden_node_tracing::{debug, info}; use miden_node_utils::ErrorReport; use miden_node_utils::limiter::{ QueryParamAccountIdLimit, @@ -35,7 +36,6 @@ use miden_protocol::utils::serde::{Deserializable, Serializable}; use miden_protocol::{MIN_PROOF_SECURITY_LEVEL, Word}; use miden_tx::TransactionVerifier; use tonic::{IntoRequest, Request, Response, Status}; -use tracing::{debug, info}; use url::Url; use crate::COMPONENT; diff --git a/crates/rpc/src/server/mod.rs b/crates/rpc/src/server/mod.rs index 90b0bccd9d..67490738c9 100644 --- a/crates/rpc/src/server/mod.rs +++ b/crates/rpc/src/server/mod.rs @@ -2,6 +2,7 @@ use accept::AcceptHeaderLayer; use anyhow::Context; use miden_node_proto::generated::rpc::api_server; use miden_node_proto_build::rpc_api_descriptor; +use miden_node_tracing::info; use miden_node_utils::clap::GrpcOptionsExternal; use miden_node_utils::cors::cors_for_grpc_web_layer; use miden_node_utils::grpc; @@ -13,7 +14,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 url::Url; use crate::COMPONENT; diff --git a/crates/rpc/src/tests.rs b/crates/rpc/src/tests.rs index 9d18ab689c..19908a23e6 100644 --- a/crates/rpc/src/tests.rs +++ b/crates/rpc/src/tests.rs @@ -222,6 +222,7 @@ async fn rpc_startup_is_robust_to_network_failures() { // Start the store. let (store_runtime, data_directory, _genesis, store_addr) = start_store(store_listener).await; + wait_until_store_ready(&mut rpc_client).await; // Test: send request against RPC api and should succeed let response = send_request(&mut rpc_client).await; @@ -234,6 +235,7 @@ async fn rpc_startup_is_robust_to_network_failures() { // Test: restart the store and request should succeed let store_runtime = restart_store(store_addr, data_directory.path()).await; + wait_until_store_ready(&mut rpc_client).await; let response = send_request(&mut rpc_client).await; assert_eq!(response.unwrap().into_inner().block_header.unwrap().block_num, 0); @@ -341,8 +343,9 @@ async fn rpc_server_rejects_proven_transactions_with_invalid_commitment() { #[tokio::test] async fn rpc_server_rejects_tx_submissions_without_genesis() { // Start the RPC. - let (_, rpc_addr, store_listener) = start_rpc().await; + let (mut ready_client, rpc_addr, store_listener) = start_rpc().await; let (store_runtime, _data_directory, _genesis, _store_addr) = start_store(store_listener).await; + wait_until_store_ready(&mut ready_client).await; // Override the client so that the ACCEPT header is not set. let mut rpc_client = @@ -352,7 +355,9 @@ async fn rpc_server_rejects_tx_submissions_without_genesis() { .without_metadata_version() .without_metadata_genesis() .without_otel_context_injection() - .connect_lazy::(); + .connect::() + .await + .unwrap(); let (account, account_delta) = build_test_account([0; 32]); let tx = build_test_proven_tx(&account, &account_delta); @@ -364,10 +369,13 @@ async fn rpc_server_rejects_tx_submissions_without_genesis() { let response = rpc_client.submit_proven_transaction(request).await; + // Shutdown to avoid runtime drop error. + shutdown_store(store_runtime).await; + // Assert that the server rejected our request. assert!(response.is_err()); - // Assert that the error is due to the invalid account delta commitment. + // Assert that the error is due to incompatible media types. let err = response.as_ref().unwrap_err().message(); assert!( err.contains( @@ -375,9 +383,6 @@ async fn rpc_server_rejects_tx_submissions_without_genesis() { ), "expected error message to reference incompatible content media types but got: {err:?}" ); - - // Shutdown to avoid runtime drop error. - shutdown_store(store_runtime).await; } /// Sends an arbitrary / irrelevant request to the RPC. @@ -403,6 +408,16 @@ async fn connect_rpc(url: Url, local_address: Option) -> RpcClient { RpcClient::with_interceptor(channel, interceptor) } +async fn wait_until_store_ready(rpc_client: &mut RpcClient) { + for _ in 0..50 { + if send_request(rpc_client).await.is_ok() { + return; + } + tokio::time::sleep(Duration::from_millis(100)).await; + } + panic!("store did not become ready in time"); +} + /// Binds a socket on an available port, runs the RPC server on it, and /// returns a client to talk to the server, along with the socket address. async fn start_rpc() -> (RpcClient, std::net::SocketAddr, TcpListener) { diff --git a/crates/store/Cargo.toml b/crates/store/Cargo.toml index 4685f2fd8d..980af76e92 100644 --- a/crates/store/Cargo.toml +++ b/crates/store/Cargo.toml @@ -31,6 +31,7 @@ miden-large-smt-backend-rocksdb = { optional = true, workspace = true } miden-node-db = { workspace = true } miden-node-proto = { workspace = true } miden-node-proto-build = { features = ["internal"], workspace = true } +miden-node-tracing = { workspace = true } miden-node-utils = { workspace = true } miden-remote-prover-client = { features = ["block-prover"], workspace = true } miden-standards = { workspace = true } diff --git a/crates/store/src/account_state_forest/mod.rs b/crates/store/src/account_state_forest/mod.rs index 558c79df70..55b5841978 100644 --- a/crates/store/src/account_state_forest/mod.rs +++ b/crates/store/src/account_state_forest/mod.rs @@ -3,6 +3,7 @@ use std::collections::BTreeSet; use miden_crypto::hash::rpo::Rpo256; use miden_crypto::merkle::smt::ForestInMemoryBackend; use miden_node_proto::domain::account::AccountStorageMapDetails; +use miden_node_tracing::instrument; use miden_node_utils::ErrorReport; use miden_protocol::account::delta::{AccountDelta, AccountStorageDelta, AccountVaultDelta}; use miden_protocol::account::{ @@ -29,9 +30,7 @@ use miden_protocol::errors::{AssetError, StorageMapError}; use miden_protocol::utils::serde::Serializable; use miden_protocol::{EMPTY_WORD, Word}; use thiserror::Error; -use tracing::instrument; -use crate::COMPONENT; pub use crate::db::models::queries::HISTORICAL_BLOCK_RETENTION; #[cfg(test)] @@ -306,7 +305,7 @@ impl AccountStateForest { /// # Errors /// /// Returns an error if applying a vault delta results in a negative balance. - #[instrument(target = COMPONENT, skip_all, fields(block.number = %block_num))] + #[instrument(COMPONENT: block.number = %block_num)] pub(crate) fn apply_block_updates( &mut self, block_num: BlockNumber, @@ -646,7 +645,7 @@ impl AccountStateForest { /// The `LargeSmtForest` itself is truncated to drop historical versions beyond the cutoff. /// /// Returns the number of pruned roots for observability. - #[instrument(target = COMPONENT, skip_all, ret, fields(block.number = %chain_tip))] + #[instrument(COMPONENT: ret, block.number = %chain_tip)] pub(crate) fn prune(&mut self, chain_tip: BlockNumber) -> usize { let cutoff_block = chain_tip .checked_sub(HISTORICAL_BLOCK_RETENTION) diff --git a/crates/store/src/blocks.rs b/crates/store/src/blocks.rs index 10319214ac..020994088f 100644 --- a/crates/store/src/blocks.rs +++ b/crates/store/src/blocks.rs @@ -2,11 +2,10 @@ use std::io::ErrorKind; use std::ops::Not; use std::path::PathBuf; +use miden_node_tracing::instrument; use miden_protocol::block::BlockNumber; use miden_protocol::utils::serde::Serializable; -use tracing::instrument; -use crate::COMPONENT; use crate::genesis::GenesisBlock; #[derive(Debug)] @@ -23,13 +22,7 @@ impl BlockStore { /// # Errors /// /// Uses [`std::fs::create_dir`] and therefore has the same error conditions. - #[instrument( - target = COMPONENT, - name = "store.block_store.bootstrap", - skip_all, - err, - fields(path = %store_dir.display()), - )] + #[instrument(COMPONENT: err)] pub fn bootstrap(store_dir: PathBuf, genesis_block: &GenesisBlock) -> std::io::Result { fs_err::create_dir(&store_dir)?; @@ -74,13 +67,7 @@ impl BlockStore { } } - #[instrument( - target = COMPONENT, - name = "store.block_store.save_block", - skip(self, data), - err, - fields(block_size = data.len()) - )] + #[instrument(COMPONENT: err, block.number = %block_num)] pub async fn save_block( &self, block_num: BlockNumber, diff --git a/crates/store/src/db/migrations.rs b/crates/store/src/db/migrations.rs index 10ce01409e..266a7f8880 100644 --- a/crates/store/src/db/migrations.rs +++ b/crates/store/src/db/migrations.rs @@ -1,6 +1,6 @@ use diesel::SqliteConnection; use diesel_migrations::{EmbeddedMigrations, MigrationHarness, embed_migrations}; -use tracing::instrument; +use miden_node_tracing::instrument; use crate::COMPONENT; use crate::db::schema_hash::verify_schema; @@ -10,7 +10,7 @@ use crate::db::schema_hash::verify_schema; pub const MIGRATIONS: EmbeddedMigrations = embed_migrations!("src/db/migrations"); // TODO we have not tested this in practice! -#[instrument(level = "debug", target = COMPONENT, skip_all, err)] +#[instrument(COMPONENT: err)] pub fn apply_migrations( conn: &mut SqliteConnection, ) -> std::result::Result<(), miden_node_db::DatabaseError> { diff --git a/crates/store/src/db/mod.rs b/crates/store/src/db/mod.rs index 6fb5fd35cb..2d2e64476f 100644 --- a/crates/store/src/db/mod.rs +++ b/crates/store/src/db/mod.rs @@ -7,6 +7,7 @@ use anyhow::Context; use diesel::{Connection, QueryableByName, RunQueryDsl, SqliteConnection}; use miden_node_proto::domain::account::AccountInfo; use miden_node_proto::generated as proto; +use miden_node_tracing::{info, instrument}; use miden_node_utils::limiter::MAX_RESPONSE_PAYLOAD_BYTES; use miden_node_utils::tracing::OpenTelemetrySpanExt; use miden_protocol::Word; @@ -26,7 +27,6 @@ use miden_protocol::note::{ use miden_protocol::transaction::{InputNoteCommitment, TransactionId}; use miden_protocol::utils::serde::{Deserializable, Serializable}; use tokio::sync::oneshot; -use tracing::{info, instrument}; use crate::COMPONENT; use crate::db::migrations::apply_migrations; @@ -251,13 +251,7 @@ impl From for NoteSyncRecord { impl Db { /// Creates a new database and inserts the genesis block. - #[instrument( - target = COMPONENT, - name = "store.database.bootstrap", - skip_all, - fields(path=%database_filepath.display()) - err, - )] + #[instrument(COMPONENT: err)] pub fn bootstrap(database_filepath: PathBuf, genesis: &GenesisBlock) -> anyhow::Result<()> { // Create database. // @@ -292,7 +286,7 @@ impl Db { } /// Open a connection to the DB and apply any pending migrations. - #[instrument(target = COMPONENT, skip_all)] + #[instrument(COMPONENT:)] pub async fn load(database_filepath: PathBuf) -> Result { let db = miden_node_db::Db::new(&database_filepath)?; info!( @@ -306,7 +300,7 @@ impl Db { } /// Returns a page of nullifiers for tree rebuilding. - #[instrument(level = "debug", target = COMPONENT, skip_all, ret(level = "debug"), err)] + #[instrument(COMPONENT: ret, err)] pub async fn select_nullifiers_paged( &self, page_size: std::num::NonZeroUsize, @@ -319,14 +313,7 @@ impl Db { } /// Loads the nullifiers that match the prefixes from the DB. - #[instrument( - level = "debug", - target = COMPONENT, - skip_all, - fields(prefix_len, prefixes = nullifier_prefixes.len()), - ret(level = "debug"), - err - )] + #[instrument(COMPONENT: ret, err)] pub async fn select_nullifiers_by_prefix( &self, prefix_len: u32, @@ -351,7 +338,7 @@ impl Db { /// Search for a [`BlockHeader`] from the database by its `block_num`. /// /// When `block_number` is [None], the latest block header is returned. - #[instrument(level = "debug", target = COMPONENT, skip_all, ret(level = "debug"), err)] + #[instrument(COMPONENT: ret, err)] pub async fn select_block_header_by_block_num( &self, maybe_block_number: Option, @@ -364,7 +351,7 @@ impl Db { } /// Loads multiple block headers from the DB. - #[instrument(level = "debug", target = COMPONENT, skip_all, ret(level = "debug"), err)] + #[instrument(COMPONENT: ret, err)] pub async fn select_block_headers( &self, blocks: impl Iterator + Send + 'static, @@ -377,7 +364,7 @@ impl Db { } /// Loads all the block headers from the DB. - #[instrument(level = "debug", target = COMPONENT, skip_all, ret(level = "debug"), err)] + #[instrument(COMPONENT: ret, err)] pub async fn select_all_block_headers(&self) -> Result> { self.transact("all block headers", |conn| { let raw = queries::select_all_block_headers(conn)?; @@ -387,7 +374,7 @@ impl Db { } /// Loads all the block headers from the DB. - #[instrument(level = "debug", target = COMPONENT, skip_all, ret(level = "debug"), err)] + #[instrument(COMPONENT: ret, err)] pub async fn select_all_block_header_commitments(&self) -> Result> { self.transact("all block headers", |conn| { let raw = queries::select_all_block_header_commitments(conn)?; @@ -397,7 +384,7 @@ impl Db { } /// Returns a page of account commitments for tree rebuilding. - #[instrument(level = "debug", target = COMPONENT, skip_all, ret(level = "debug"), err)] + #[instrument(COMPONENT: ret, err)] pub async fn select_account_commitments_paged( &self, page_size: std::num::NonZeroUsize, @@ -410,7 +397,7 @@ impl Db { } /// Returns a page of public account IDs for forest rebuilding. - #[instrument(level = "debug", target = COMPONENT, skip_all, ret(level = "debug"), err)] + #[instrument(COMPONENT: ret, err)] pub async fn select_public_account_ids_paged( &self, page_size: std::num::NonZeroUsize, @@ -423,14 +410,14 @@ impl Db { } /// Loads public account details from the DB. - #[instrument(level = "debug", target = COMPONENT, skip_all, ret(level = "debug"), err)] + #[instrument(COMPONENT: ret, err)] pub async fn select_account(&self, id: AccountId) -> Result { self.transact("Get account details", move |conn| queries::select_account(conn, id)) .await } /// Loads public account details for a network account by its full account ID. - #[instrument(level = "debug", target = COMPONENT, skip_all, ret(level = "debug"), err)] + #[instrument(COMPONENT: ret, err)] pub async fn select_network_account_by_id( &self, account_id: AccountId, @@ -454,7 +441,7 @@ impl Db { /// - A vector of network account IDs. /// - The last block number that was fully included in the result. When truncated, this will be /// less than the requested range end. - #[instrument(level = "debug", target = COMPONENT, skip_all, ret(level = "debug"), err)] + #[instrument(COMPONENT: ret, err)] pub async fn select_all_network_account_ids( &self, block_range: RangeInclusive, @@ -466,7 +453,7 @@ impl Db { } /// Queries vault assets at a specific block - #[instrument(level = "debug", target = COMPONENT, skip_all, ret(level = "debug"), err)] + #[instrument(COMPONENT: ret, err)] pub async fn select_account_vault_at_block( &self, account_id: AccountId, @@ -506,7 +493,7 @@ impl Db { .await } - #[instrument(level = "debug", target = COMPONENT, skip_all, ret(level = "debug"), err)] + #[instrument(COMPONENT: ret, err)] pub async fn get_note_sync( &self, block_range: RangeInclusive, @@ -520,7 +507,7 @@ impl Db { /// Loads all the [`miden_protocol::note::Note`]s matching a certain [`NoteId`] from the /// database. - #[instrument(level = "debug", target = COMPONENT, skip_all, ret(level = "debug"), err)] + #[instrument(COMPONENT: ret, err)] pub async fn select_notes_by_id(&self, note_ids: Vec) -> Result> { self.transact("note by id", move |conn| { queries::select_notes_by_id(conn, note_ids.as_slice()) @@ -529,7 +516,7 @@ impl Db { } /// Returns all note commitments from the DB that match the provided ones. - #[instrument(level = "debug", target = COMPONENT, skip_all, ret(level = "debug"), err)] + #[instrument(COMPONENT: ret, err)] pub async fn select_existing_note_commitments( &self, note_commitments: Vec, @@ -541,7 +528,7 @@ impl Db { } /// Loads inclusion proofs for notes matching the given note commitments. - #[instrument(level = "debug", target = COMPONENT, skip_all, ret(level = "debug"), err)] + #[instrument(COMPONENT: ret, err)] pub async fn select_note_inclusion_proofs( &self, note_commitments: BTreeSet, @@ -557,7 +544,7 @@ impl Db { /// `allow_acquire` and `acquire_done` are used to synchronize writes to the DB with writes to /// the in-memory trees. Further details available on [`super::state::State::apply_block`]. // TODO: This span is logged in a root span, we should connect it to the parent one. - #[instrument(target = COMPONENT, skip_all, err)] + #[instrument(COMPONENT: err)] pub async fn apply_block( &self, allow_acquire: oneshot::Sender<()>, @@ -700,7 +687,7 @@ impl Db { } /// Emits size metrics for each table in the database, and the entire database. - #[instrument(target = COMPONENT, skip_all, err)] + #[instrument(COMPONENT: err)] pub async fn analyze_table_sizes(&self) -> Result<(), DatabaseError> { self.transact("db analysis", |conn| { #[derive(QueryableByName)] diff --git a/crates/store/src/db/models/queries/accounts.rs b/crates/store/src/db/models/queries/accounts.rs index d0e3fa8243..814f4c2e58 100644 --- a/crates/store/src/db/models/queries/accounts.rs +++ b/crates/store/src/db/models/queries/accounts.rs @@ -18,6 +18,7 @@ use diesel::{ SqliteConnection, }; use miden_node_proto::domain::account::{AccountInfo, AccountSummary}; +use miden_node_tracing::instrument; use miden_node_utils::limiter::MAX_RESPONSE_PAYLOAD_BYTES; use miden_protocol::account::delta::AccountUpdateDetails; use miden_protocol::account::{ @@ -39,7 +40,6 @@ use miden_protocol::block::{BlockAccountUpdate, BlockNumber}; use miden_protocol::utils::serde::{Deserializable, Serializable}; use miden_protocol::{Felt, Word}; -use crate::COMPONENT; use crate::db::models::conv::{SqlTypeConvert, nonce_to_raw_sql, raw_sql_to_nonce}; #[cfg(test)] use crate::db::models::vec_raw_try_into; @@ -1182,11 +1182,7 @@ fn prepare_partial_account_update( } /// Attention: Assumes the account details are NOT null! The schema explicitly allows this though! -#[tracing::instrument( - target = COMPONENT, - skip_all, - err, -)] +#[instrument(COMPONENT: err)] pub(crate) fn upsert_accounts( conn: &mut SqliteConnection, accounts: &[BlockAccountUpdate], @@ -1467,12 +1463,7 @@ pub const HISTORICAL_BLOCK_RETENTION: u32 = 50; /// /// # Returns /// A tuple of `(vault_assets_deleted, storage_map_values_deleted, account_codes_deleted)` -#[tracing::instrument( - target = COMPONENT, - skip_all, - err, - fields(cutoff_block), -)] +#[instrument(COMPONENT: err)] pub(crate) fn prune_history( conn: &mut SqliteConnection, chain_tip: BlockNumber, @@ -1486,12 +1477,7 @@ pub(crate) fn prune_history( Ok((vault_deleted, storage_deleted, codes_deleted)) } -#[tracing::instrument( - target = COMPONENT, - skip_all, - err, - fields(cutoff_block), -)] +#[instrument(COMPONENT: err)] fn prune_account_vault_assets( conn: &mut SqliteConnection, cutoff_block: i64, @@ -1507,12 +1493,7 @@ fn prune_account_vault_assets( .map_err(DatabaseError::Diesel) } -#[tracing::instrument( - target = COMPONENT, - skip_all, - err, - fields(cutoff_block), -)] +#[instrument(COMPONENT: err)] fn prune_account_storage_map_values( conn: &mut SqliteConnection, cutoff_block: i64, @@ -1546,12 +1527,7 @@ fn prune_account_storage_map_values( /// AND (block_num >= ?1 OR is_latest = 1) /// ) /// ``` -#[tracing::instrument( - target = COMPONENT, - skip_all, - err, - fields(cutoff_block), -)] +#[instrument(COMPONENT: err)] fn prune_account_codes( conn: &mut SqliteConnection, cutoff_block: i64, diff --git a/crates/store/src/db/models/queries/block_headers.rs b/crates/store/src/db/models/queries/block_headers.rs index 59c4ce530b..231e3c4857 100644 --- a/crates/store/src/db/models/queries/block_headers.rs +++ b/crates/store/src/db/models/queries/block_headers.rs @@ -13,12 +13,12 @@ use diesel::{ }; use miden_crypto::Word; use miden_crypto::dsa::ecdsa_k256_keccak::Signature; +use miden_node_tracing::instrument; use miden_node_utils::limiter::{QueryParamBlockLimit, QueryParamLimiter}; use miden_protocol::block::{BlockHeader, BlockNumber}; use miden_protocol::utils::serde::{Deserializable, Serializable}; use super::DatabaseError; -use crate::COMPONENT; use crate::db::models::conv::SqlTypeConvert; use crate::db::models::vec_raw_try_into; use crate::db::schema; @@ -227,11 +227,7 @@ impl From<(&BlockHeader, &Signature)> for BlockHeaderInsert { /// /// The [`SqliteConnection`] object is not consumed. It's up to the caller to commit or rollback the /// transaction -#[tracing::instrument( - target = COMPONENT, - skip_all, - err, -)] +#[instrument(COMPONENT: err)] pub(crate) fn insert_block_header( conn: &mut SqliteConnection, block_header: &BlockHeader, diff --git a/crates/store/src/db/models/queries/notes.rs b/crates/store/src/db/models/queries/notes.rs index b05ae4fee2..4edb648afd 100644 --- a/crates/store/src/db/models/queries/notes.rs +++ b/crates/store/src/db/models/queries/notes.rs @@ -25,6 +25,7 @@ use diesel::{ SelectableHelper, SqliteConnection, }; +use miden_node_tracing::instrument; use miden_node_utils::limiter::{ QueryParamAccountIdLimit, QueryParamLimiter, @@ -52,7 +53,6 @@ use miden_protocol::note::{ use miden_protocol::utils::serde::{Deserializable, Serializable}; use miden_standards::note::NetworkAccountTarget; -use crate::COMPONENT; use crate::db::models::conv::{ SqlTypeConvert, idx_to_raw_sql, @@ -790,11 +790,7 @@ impl TryInto for BlockNoteIndexRawRow { /// /// The [`SqliteConnection`] object is not consumed. It's up to the caller to commit or rollback the /// transaction. -#[tracing::instrument( - target = COMPONENT, - skip_all, - err, -)] +#[instrument(COMPONENT: err)] pub(crate) fn insert_notes( conn: &mut SqliteConnection, notes: &[(NoteRecord, Option)], @@ -820,11 +816,7 @@ pub(crate) fn insert_notes( /// /// The [`SqliteConnection`] object is not consumed. It's up to the caller to commit or rollback the /// transaction. -#[tracing::instrument( - target = COMPONENT, - skip_all, - err, -)] +#[instrument(COMPONENT: err)] pub(crate) fn insert_scripts<'a>( conn: &mut SqliteConnection, notes: impl IntoIterator, diff --git a/crates/store/src/db/models/queries/nullifiers.rs b/crates/store/src/db/models/queries/nullifiers.rs index 89f62b4ab3..16f8d033d4 100644 --- a/crates/store/src/db/models/queries/nullifiers.rs +++ b/crates/store/src/db/models/queries/nullifiers.rs @@ -12,6 +12,7 @@ use diesel::{ SelectableHelper, SqliteConnection, }; +use miden_node_tracing::instrument; use miden_node_utils::limiter::{ MAX_RESPONSE_PAYLOAD_BYTES, QueryParamLimiter, @@ -23,7 +24,6 @@ use miden_protocol::note::Nullifier; use miden_protocol::utils::serde::{Deserializable, Serializable}; use super::DatabaseError; -use crate::COMPONENT; use crate::db::models::conv::{SqlTypeConvert, nullifier_prefix_to_raw_sql}; use crate::db::models::utils::{get_nullifier_prefix, vec_raw_try_into}; use crate::db::{NullifierInfo, schema}; @@ -226,11 +226,7 @@ pub(crate) fn select_nullifiers_paged( /// INSERT INTO nullifiers (nullifier, nullifier_prefix, block_num) /// VALUES (?1, ?2, ?3) /// ``` -#[tracing::instrument( - target = COMPONENT, - skip_all, - err, -)] +#[instrument(COMPONENT: err)] pub(crate) fn insert_nullifiers_for_block( conn: &mut SqliteConnection, nullifiers: &[Nullifier], diff --git a/crates/store/src/db/models/queries/transactions.rs b/crates/store/src/db/models/queries/transactions.rs index 79d2bdfeb0..e313d02479 100644 --- a/crates/store/src/db/models/queries/transactions.rs +++ b/crates/store/src/db/models/queries/transactions.rs @@ -12,6 +12,7 @@ use diesel::{ SelectableHelper, SqliteConnection, }; +use miden_node_tracing::instrument; use miden_node_utils::limiter::{ MAX_RESPONSE_PAYLOAD_BYTES, QueryParamAccountIdLimit, @@ -24,7 +25,6 @@ use miden_protocol::transaction::{InputNoteCommitment, OrderedTransactionHeaders use miden_protocol::utils::serde::{Deserializable, Serializable}; use super::DatabaseError; -use crate::COMPONENT; use crate::db::models::conv::SqlTypeConvert; use crate::db::models::{serialize_vec, vec_raw_try_into}; use crate::db::schema; @@ -78,11 +78,7 @@ impl TryInto for TransactionRecordRaw { /// /// The [`SqliteConnection`] object is not consumed. It's up to the caller to commit or rollback the /// transaction. -#[tracing::instrument( - target = COMPONENT, - skip_all, - err, -)] +#[instrument(COMPONENT: err)] pub(crate) fn insert_transactions( conn: &mut SqliteConnection, block_num: BlockNumber, diff --git a/crates/store/src/db/schema_hash.rs b/crates/store/src/db/schema_hash.rs index 9a5ad1328a..4fa9f50c65 100644 --- a/crates/store/src/db/schema_hash.rs +++ b/crates/store/src/db/schema_hash.rs @@ -12,7 +12,7 @@ use diesel::{Connection, RunQueryDsl, SqliteConnection}; use diesel_migrations::MigrationHarness; use miden_node_db::SchemaVerificationError; -use tracing::instrument; +use miden_node_tracing::instrument; use crate::COMPONENT; use crate::db::migrations::MIGRATIONS; @@ -83,7 +83,7 @@ fn compute_expected_schema() -> Result, SchemaVerificationErro /// # Errors /// /// Returns `SchemaVerificationError::Mismatch` if schemas differ. -#[instrument(level = "info", target = COMPONENT, skip_all, err)] +#[instrument(COMPONENT: err)] pub fn verify_schema(conn: &mut SqliteConnection) -> Result<(), SchemaVerificationError> { let expected = compute_expected_schema()?; let actual = extract_schema(conn)?; diff --git a/crates/store/src/server/api.rs b/crates/store/src/server/api.rs index 8440cb691b..f0c739e963 100644 --- a/crates/store/src/server/api.rs +++ b/crates/store/src/server/api.rs @@ -3,6 +3,7 @@ use std::sync::Arc; use miden_node_proto::errors::ConversionError; use miden_node_proto::generated as proto; +use miden_node_tracing::{info, instrument}; use miden_node_utils::ErrorReport; use miden_protocol::Word; use miden_protocol::account::AccountId; @@ -10,7 +11,6 @@ use miden_protocol::batch::OrderedBatches; use miden_protocol::block::{BlockInputs, BlockNumber}; use miden_protocol::note::Nullifier; use tonic::{Request, Response, Status}; -use tracing::{info, instrument}; use crate::errors::GetBlockInputsError; use crate::state::State; @@ -175,13 +175,7 @@ where .map_err(Into::into) } -#[instrument( - level = "debug", - target = COMPONENT, - skip_all, - fields(nullifiers = nullifiers.len()), - err -)] +#[instrument(COMPONENT: err)] pub fn validate_nullifiers(nullifiers: &[proto::primitives::Digest]) -> Result, E> where E: From + std::fmt::Display, @@ -194,13 +188,7 @@ where .map_err(Into::into) } -#[instrument( - level = "debug", - target = COMPONENT, - skip_all, - fields(notes = notes.len()), - err -)] +#[instrument(COMPONENT: err)] pub fn validate_note_commitments(notes: &[proto::primitives::Digest]) -> Result, Status> { notes .iter() @@ -209,12 +197,7 @@ pub fn validate_note_commitments(notes: &[proto::primitives::Digest]) -> Result< .map_err(|_| invalid_argument("Digest field is not in the modulus range")) } -#[instrument( - level = "debug", - target = COMPONENT, - skip_all, - fields(block_numbers = block_numbers.len()) -)] +#[instrument(COMPONENT:)] pub fn read_block_numbers(block_numbers: &[u32]) -> BTreeSet { BTreeSet::from_iter(block_numbers.iter().map(|raw_number| BlockNumber::from(*raw_number))) } diff --git a/crates/store/src/server/block_prover_client.rs b/crates/store/src/server/block_prover_client.rs index 5af15ac433..229de0e05c 100644 --- a/crates/store/src/server/block_prover_client.rs +++ b/crates/store/src/server/block_prover_client.rs @@ -1,10 +1,8 @@ use miden_block_prover::{BlockProverError, LocalBlockProver}; +use miden_node_tracing::instrument; use miden_protocol::batch::OrderedBatches; use miden_protocol::block::{BlockHeader, BlockInputs, BlockProof}; use miden_remote_prover_client::{RemoteBlockProver, RemoteProverClientError}; -use tracing::instrument; - -use crate::COMPONENT; #[derive(Debug, thiserror::Error)] pub enum StoreProverError { @@ -35,7 +33,7 @@ impl BlockProver { Self::Remote(RemoteBlockProver::new(endpoint)) } - #[instrument(target = COMPONENT, skip_all, err)] + #[instrument(COMPONENT: err)] pub async fn prove( &self, tx_batches: OrderedBatches, diff --git a/crates/store/src/server/mod.rs b/crates/store/src/server/mod.rs index 8e9e46118b..c87c51e39b 100644 --- a/crates/store/src/server/mod.rs +++ b/crates/store/src/server/mod.rs @@ -10,6 +10,7 @@ use miden_node_proto_build::{ store_ntx_builder_api_descriptor, store_rpc_api_descriptor, }; +use miden_node_tracing::{info, instrument}; use miden_node_utils::clap::{GrpcOptionsInternal, StorageOptions}; use miden_node_utils::panic::{CatchPanicLayer, catch_panic_layer_fn}; use miden_node_utils::tracing::grpc::grpc_trace_fn; @@ -17,7 +18,6 @@ use tokio::net::TcpListener; use tokio::task::JoinSet; use tokio_stream::wrappers::TcpListenerStream; use tower_http::trace::TraceLayer; -use tracing::{info, instrument}; use url::Url; use crate::blocks::BlockStore; @@ -47,12 +47,7 @@ pub struct Store { impl Store { /// Bootstraps the Store, creating the database state and inserting the genesis block data. - #[instrument( - target = COMPONENT, - name = "store.bootstrap", - skip_all, - err, - )] + #[instrument(COMPONENT: err)] pub fn bootstrap(genesis: &GenesisBlock, data_directory: &Path) -> anyhow::Result<()> { let data_directory = DataDirectory::load(data_directory.to_path_buf()).with_context(|| { diff --git a/crates/store/src/server/ntx_builder.rs b/crates/store/src/server/ntx_builder.rs index 4c6251d131..a1af363aec 100644 --- a/crates/store/src/server/ntx_builder.rs +++ b/crates/store/src/server/ntx_builder.rs @@ -7,13 +7,13 @@ use miden_node_proto::errors::ConversionError; use miden_node_proto::generated as proto; use miden_node_proto::generated::rpc::BlockRange; use miden_node_proto::generated::store::ntx_builder_server; +use miden_node_tracing::debug; use miden_node_utils::ErrorReport; use miden_protocol::account::{StorageMapKey, StorageSlotName}; use miden_protocol::asset::AssetVaultKey; use miden_protocol::block::BlockNumber; use miden_protocol::note::Note; use tonic::{Request, Response, Status}; -use tracing::debug; use crate::COMPONENT; use crate::db::models::Page; diff --git a/crates/store/src/server/rpc_api.rs b/crates/store/src/server/rpc_api.rs index 2e70876826..b9e39343a7 100644 --- a/crates/store/src/server/rpc_api.rs +++ b/crates/store/src/server/rpc_api.rs @@ -3,6 +3,7 @@ use miden_node_proto::domain::block::InvalidBlockRange; use miden_node_proto::errors::MissingFieldHelper; use miden_node_proto::generated::store::rpc_server; use miden_node_proto::generated::{self as proto}; +use miden_node_tracing::{debug, info}; use miden_node_utils::limiter::{ QueryParamAccountIdLimit, QueryParamLimiter, @@ -15,7 +16,6 @@ use miden_protocol::account::AccountId; use miden_protocol::block::BlockNumber; use miden_protocol::note::NoteId; use tonic::{Request, Response, Status}; -use tracing::{debug, info}; use crate::COMPONENT; use crate::errors::{ diff --git a/crates/store/src/state/apply_block.rs b/crates/store/src/state/apply_block.rs index 43d3d406a5..f516c7d5da 100644 --- a/crates/store/src/state/apply_block.rs +++ b/crates/store/src/state/apply_block.rs @@ -1,5 +1,6 @@ use std::sync::Arc; +use miden_node_tracing::{info, instrument}; use miden_node_utils::ErrorReport; use miden_protocol::account::delta::AccountUpdateDetails; use miden_protocol::block::SignedBlock; @@ -7,7 +8,7 @@ use miden_protocol::note::NoteDetails; use miden_protocol::transaction::OutputNote; use miden_protocol::utils::serde::Serializable; use tokio::sync::oneshot; -use tracing::{Instrument, info, info_span, instrument}; +use tracing::info_span; use crate::db::NoteRecord; use crate::errors::{ApplyBlockError, InvalidBlockError}; @@ -40,7 +41,7 @@ impl State { /// released. // TODO: This span is logged in a root span, we should connect it to the parent span. #[expect(clippy::too_many_lines)] - #[instrument(target = COMPONENT, skip_all, err)] + #[instrument(COMPONENT: err)] pub async fn apply_block(&self, signed_block: SignedBlock) -> Result<(), ApplyBlockError> { let _lock = self.writer.try_lock().map_err(|_| ApplyBlockError::ConcurrentWrite)?; diff --git a/crates/store/src/state/loader.rs b/crates/store/src/state/loader.rs index 3863f4afbc..a9c18af389 100644 --- a/crates/store/src/state/loader.rs +++ b/crates/store/src/state/loader.rs @@ -15,6 +15,8 @@ use std::path::Path; use miden_crypto::merkle::mmr::Mmr; #[cfg(feature = "rocksdb")] use miden_large_smt_backend_rocksdb::RocksDbStorage; +use miden_node_tracing::{info, instrument}; +#[cfg(feature = "rocksdb")] use miden_node_utils::clap::RocksDbOptions; use miden_protocol::block::account_tree::{AccountIdKey, AccountTree}; use miden_protocol::block::nullifier_tree::NullifierTree; @@ -23,9 +25,6 @@ use miden_protocol::block::{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 tracing::instrument; use crate::COMPONENT; use crate::account_state_forest::AccountStateForest; @@ -138,7 +137,7 @@ impl StorageLoader for MemoryStorage { Ok(MemoryStorage::default()) } - #[instrument(target = COMPONENT, skip_all)] + #[instrument(COMPONENT:)] async fn load_account_tree( self, db: &mut Db, @@ -180,7 +179,7 @@ impl StorageLoader for MemoryStorage { // TODO: Make the loading methodology for account and nullifier trees consistent. // Currently we use `NullifierTree::new_unchecked()` for nullifiers but `AccountTree::new()` // for accounts. Consider using `NullifierTree::with_storage_from_entries()` for consistency. - #[instrument(target = COMPONENT, skip_all)] + #[instrument(COMPONENT:)] async fn load_nullifier_tree( self, db: &mut Db, @@ -236,7 +235,7 @@ impl StorageLoader for RocksDbStorage { .map_err(|e| StateInitializationError::AccountTreeIoError(e.to_string())) } - #[instrument(target = COMPONENT, skip_all)] + #[instrument(COMPONENT:)] async fn load_account_tree( self, db: &mut Db, @@ -287,7 +286,7 @@ impl StorageLoader for RocksDbStorage { AccountTree::new(smt).map_err(StateInitializationError::FailedToCreateAccountsTree) } - #[instrument(target = COMPONENT, skip_all)] + #[instrument(COMPONENT:)] async fn load_nullifier_tree( self, db: &mut Db, @@ -348,7 +347,7 @@ pub fn load_smt(storage: S) -> Result, StateInitializ // ================================================================================================ /// Loads the blockchain MMR from all block headers in the database. -#[instrument(target = COMPONENT, skip_all)] +#[instrument(COMPONENT:)] pub async fn load_mmr(db: &mut Db) -> Result { let block_commitments = db.select_all_block_header_commitments().await?; @@ -362,7 +361,7 @@ pub async fn load_mmr(db: &mut Db) -> Result, @@ -225,7 +225,7 @@ impl State { /// tree. /// /// Note: these proofs are invalidated once the nullifier tree is modified, i.e. on a new block. - #[instrument(level = "debug", target = COMPONENT, skip_all, ret)] + #[instrument(COMPONENT: ret)] pub async fn check_nullifiers(&self, nullifiers: &[Nullifier]) -> Vec { let inner = self.inner.read().await; nullifiers @@ -533,7 +533,7 @@ impl State { } /// Returns data needed by the block producer to verify transactions validity. - #[instrument(target = COMPONENT, skip_all, ret)] + #[instrument(COMPONENT: ret)] pub async fn get_transaction_inputs( &self, account_id: AccountId, diff --git a/crates/store/src/state/sync_state.rs b/crates/store/src/state/sync_state.rs index afb5212f78..1cb9ffc8e5 100644 --- a/crates/store/src/state/sync_state.rs +++ b/crates/store/src/state/sync_state.rs @@ -1,12 +1,11 @@ use std::ops::RangeInclusive; +use miden_node_tracing::instrument; use miden_protocol::account::AccountId; use miden_protocol::block::BlockNumber; use miden_protocol::crypto::merkle::mmr::{Forest, MmrDelta, MmrProof}; -use tracing::instrument; use super::State; -use crate::COMPONENT; use crate::db::models::queries::StorageMapValuesPage; use crate::db::{AccountVaultValue, NoteSyncUpdate, NullifierInfo}; use crate::errors::{DatabaseError, NoteSyncError, StateSyncError}; @@ -26,7 +25,7 @@ impl State { } /// Returns the chain MMR delta for the specified block range. - #[instrument(level = "debug", target = COMPONENT, skip_all, ret(level = "debug"), err)] + #[instrument(COMPONENT: ret, err)] pub async fn sync_chain_mmr( &self, block_range: RangeInclusive, @@ -73,7 +72,7 @@ impl State { /// - `note_tags`: The tags the client is interested in, resulting notes are restricted to the /// first block containing a matching note. /// - `block_range`: The range of blocks from which to synchronize notes. - #[instrument(level = "debug", target = COMPONENT, skip_all, ret(level = "debug"), err)] + #[instrument(COMPONENT: ret, err)] pub async fn sync_notes( &self, note_tags: Vec, diff --git a/crates/tracing-macro/Cargo.toml b/crates/tracing-macro/Cargo.toml new file mode 100644 index 0000000000..3a50883ee7 --- /dev/null +++ b/crates/tracing-macro/Cargo.toml @@ -0,0 +1,24 @@ +[package] +categories = ["development-tools::procedural-macro-helpers"] +description = "Procedural macro for tracing instrumentation with full error report context" +keywords = ["miden", "node", "tracing"] +name = "miden-node-tracing-macro" + +edition.workspace = true +license.workspace = true +readme.workspace = true +repository.workspace = true +rust-version.workspace = true +version.workspace = true + +[lints] +workspace = true + +[lib] +proc-macro = true + +[dependencies] +fuzzy-search = "0.1.0" +proc-macro2 = "1.0" +quote = "1.0" +syn = { features = ["extra-traits", "full", "parsing"], version = "2.0" } diff --git a/crates/tracing-macro/README.md b/crates/tracing-macro/README.md new file mode 100644 index 0000000000..e9525551a8 --- /dev/null +++ b/crates/tracing-macro/README.md @@ -0,0 +1,167 @@ +# miden-node-tracing-macro + +Internal procedural macro crate for `miden-node-tracing`. + +**Do not use this crate directly.** Import from `miden-node-tracing` instead, +which re-exports every macro here together with all required runtime dependencies +(`ErrorReport`, `OpenTelemetrySpanExt`, …). + +--- + +## `#[instrument]` + +Instruments a function with a [`tracing`] span. Extends `tracing::instrument` +with a component-target shorthand, an OpenTelemetry field allowlist, and a `report` +keyword for full error-chain capture. + +### Syntax + +```text +#[instrument] +#[instrument( [COMPONENT:] [element, …] )] + +COMPONENT ::= ident | "string literal" +element ::= field-entry | "ret" | "err" | "report" +field-entry ::= dotted-name "=" ["%"] expr +dotted-name ::= ident ["." ident]* -- must appear in allowlist.txt +``` + +### Keywords + +| Keyword | Requires `Result`? | Description | +|---|---|---| +| `ret` | no | Records the return value inside the span | +| `err` | yes | Emits a tracing event with the top-level error message (delegates to `tracing::instrument`'s built-in `err`) | +| `report` | yes | Emits an `error!` event with the **full error chain** via `ErrorReport::as_report()` and sets the OpenTelemetry span status to `Error`. Mutually exclusive with `err`. | + +### Field entries + +```rust +#[instrument(rpc: account.id = account_id)] // Debug → {:?} +#[instrument(rpc: account.id = %account_id)] // Display → {} +``` + +Field names must appear in [`allowlist.txt`](allowlist.txt). An undeclared name +is a compile error; the macro suggests the closest allowlisted names. + +### Full argument reference + +| Attribute | fn returns `Result`? | Valid? | Behaviour | +|---|---|---|---| +| *(empty)* | any | ✓ | Thin `#[tracing::instrument]` wrapper | +| `rpc:` | any | ✓ | Span with `target = "rpc"`, no field/ret tracking | +| `rpc: ret` | any | ✓ | `tracing::instrument` `ret` | +| `rpc: err` | yes | ✓ | `tracing::instrument` `err` (top-level message) | +| `rpc: err` | no | ✗ | `err` requires `Result` return | +| `rpc: report` | yes | ✓ | Full error chain + OpenTelemetry status | +| `rpc: report` | no | ✗ | `report` requires `Result` return | +| `rpc: err, report` | any | ✗ | Mutually exclusive | +| `rpc: report, err` | any | ✗ | Mutually exclusive (order irrelevant) | +| `rpc: ret, err` | yes | ✓ | Return value + top-level error | +| `rpc: ret, report` | yes | ✓ | Return value + full error chain | +| `rpc: ret, report` | no | ✗ | `report` requires `Result` return | +| `rpc: account.id = id` | any | ✓ | Allowlisted field, Debug | +| `rpc: account.id = %id` | any | ✓ | Allowlisted field, Display | +| `rpc: foo = id` | any | ✗ | `foo` not in allowlist | +| `rpc: foo.bar.baz = %id` | any | ✗ | `foo.bar.baz` not in allowlist | +| `rpc: account.id = %id, err` | yes | ✓ | Field + standard error | +| `rpc: account.id = %id, report` | yes | ✓ | Field + full error chain | +| `rpc: account.id = %id, ret, report` | yes | ✓ | Field + return value + full error chain | +| `rpc: account.id = %id, report, err` | yes | ✗ | Mutually exclusive | + +### `err` vs `report` + +| | `err` | `report` | +|---|---|---| +| Mechanism | `tracing::instrument` built-in | Custom body wrapper | +| Error detail | Top-level `Display`/`Debug` | Full chain via `ErrorReport::as_report()` | +| OpenTelemetry span status | Not set | Set to `Error` | +| Event level | `ERROR` | `ERROR` | + +Use `err` for lightweight internal helpers. Use `report` on RPC handlers and +any boundary where the full error chain must appear in telemetry. + +### Examples + +```rust +use miden_node_tracing::instrument; + +// Minimal – default target, no tracking. +#[instrument] +fn simple() {} + +// Component only. +#[instrument(rpc:)] +fn with_target() {} + +// Return value. +#[instrument(rpc: ret)] +fn compute() -> u32 { 42 } + +// Standard error (top-level message). +#[instrument(store: err)] +async fn load() -> Result { todo!() } + +// Full error chain + OpenTelemetry span status. +#[instrument(rpc: report)] +async fn apply_block(block: Block) -> Result<(), ApplyBlockError> { todo!() } + +// Return value + full error chain. +#[instrument(rpc: ret, report)] +async fn fetch_count() -> Result { todo!() } + +// Allowlisted field (Display) + full error chain. +#[instrument(rpc: account.id = %account_id, report)] +async fn get_account(account_id: AccountId) -> Result { todo!() } + +// Multiple allowlisted fields. +#[instrument(store: account.id = %account_id, block.number = block_num, err)] +async fn get_account_at( + account_id: AccountId, + block_num: BlockNumber, +) -> Result { todo!() } +``` + +--- + +## `warn!` / `error!` / `info!` / `debug!` / `trace!` + +These macros enforce the same rules as `#[instrument]` and then expand to the +underlying `tracing::!` macro. + +### Syntax + +```text +warn!( [COMPONENT:] [field = ["%"|"?"] expr ,]* [format_string [, args…]] ) + +COMPONENT ::= ident | string-literal +field-entry ::= dotted-name "=" ["%" | "?"] expr +dotted-name ::= ident ["." ident]* -- must appear in allowlist.txt +``` + +The optional `COMPONENT:` prefix sets the tracing target (e.g. `rpc:` → +`target: "rpc"`). Field names are validated against the OpenTelemetry allowlist; +an unlisted name is a compile error with fuzzy-matched suggestions. + +### Full argument reference for `warn!` + +| Form | Example | Valid? | +|---|---|---| +| Empty | `warn!()` | ✓ | +| Plain message | `warn!("something looks off")` | ✓ | +| Format string | `warn!("retrying after {}ms", delay_ms)` | ✓ | +| Component + message | `warn!(rpc: "request failed")` | ✓ | +| Component + format | `warn!(store: "migrated {} rows", n)` | ✓ | +| Component only | `warn!(rpc:)` | ✓ | +| Allowlisted field, Debug | `warn!(account.id = id, "context")` | ✓ | +| Allowlisted field, Display | `warn!(account.id = %id, "context")` | ✓ | +| Allowlisted field, Debug explicit | `warn!(account.id = ?id, "context")` | ✓ | +| Unlisted field | `warn!(foo = %x, "context")` | ✗ | +| Unlisted dotted field | `warn!(foo.bar = %x, "context")` | ✗ | +| Multiple allowlisted fields + message | `warn!(account.id = %id, block.number = n, "msg")` | ✓ | +| Fields only, no message | `warn!(account.id = %id, block.number = n)` | ✓ | +| Component + fields + message (full form) | `warn!(rpc: account.id = %id, "rejected")` | ✓ | +| Component + unlisted field | `warn!(rpc: foo = %x, "msg")` | ✗ | + +The same table applies to `error!`, `info!`, `debug!`, and `trace!` – only the +severity level differs. diff --git a/crates/tracing-macro/allowlist.txt b/crates/tracing-macro/allowlist.txt new file mode 100644 index 0000000000..e704aa0c50 --- /dev/null +++ b/crates/tracing-macro/allowlist.txt @@ -0,0 +1,20 @@ +# OTel field allowlist +# +# Only the names listed here may be used as field keys in `#[instrument(…)]`. +# +# Rules: +# - One dotted name per line (e.g. `account.id`). +# - Lines that are empty or start with `#` are ignored. +# - Names are matched verbatim (case-sensitive, no wildcards). +# +# When an unlisted name is supplied the macro emits a compile error and +# suggests the closest match(es) from this file (Levenshtein distance ≤ 5). +# +# To add a new name: append it below and open a PR for review. New names +# should correspond to a documented semantic convention in the OTel spec or +# in the Miden node attribute registry. + +account.id +nullifier.id +block.number +transaction.id diff --git a/crates/tracing-macro/src/allowed.rs b/crates/tracing-macro/src/allowed.rs new file mode 100644 index 0000000000..7a94afacb2 --- /dev/null +++ b/crates/tracing-macro/src/allowed.rs @@ -0,0 +1,38 @@ +use std::sync::LazyLock; + +use fuzzy_search::basic::fuzzy_search; + +const ALLOW_LIST: &str = include_str!("../allowlist.txt"); + +/// Set of permitted OpenTelemetry field names, copied into the binary `allowlist.txt`. +/// +/// Lines that are empty or start with `#` are ignored. +/// +/// Example: +/// ```text +/// foo.bar.baz +/// baz_anything_goes +/// technically.🪤.works.but.really.you_should_not +/// ``` +static ALLOWED_OPENTELEMETRY_NAMES: LazyLock> = LazyLock::new(|| { + Vec::from_iter( + ALLOW_LIST + .lines() + .map(str::trim) + .filter(|trimmed| !trimmed.is_empty() && !trimmed.starts_with('#')), + ) +}); + +/// Checks `dotted` against the open telemetry field allowlist. +/// +/// Succeeds when the given name is present in `allowlist.txt` verbatim, +/// otherwise provides suggestions in increasing levenshtein distance. +pub(crate) fn check(dotted: &str) -> Result<(), Vec> { + if ALLOWED_OPENTELEMETRY_NAMES.contains(&dotted) { + return Ok(()); + } + + let owned: Vec = ALLOWED_OPENTELEMETRY_NAMES.iter().map(|s| (*s).to_string()).collect(); + let suggestions = fuzzy_search(dotted, &owned, 5, fuzzy_search::distance::levenshtein); + Err(suggestions) +} diff --git a/crates/tracing-macro/src/instrument.rs b/crates/tracing-macro/src/instrument.rs new file mode 100644 index 0000000000..b1cbdc429e --- /dev/null +++ b/crates/tracing-macro/src/instrument.rs @@ -0,0 +1,824 @@ +use std::str::FromStr; + +use proc_macro2::{Span, TokenStream as TokenStream2}; +use quote::quote; +use syn::parse::{Parse, ParseStream}; +use syn::punctuated::Punctuated; +use syn::spanned::Spanned; +use syn::{Expr, Ident, ItemFn, LitStr, PathSegment, ReturnType, Token, Type, TypeImplTrait}; + +mod kw { + syn::custom_keyword!(ret); + syn::custom_keyword!(root); + syn::custom_keyword!(err); + syn::custom_keyword!(report); + syn::custom_keyword!(level); + syn::custom_keyword!(INFO); + syn::custom_keyword!(DEBUG); + syn::custom_keyword!(TRACE); + syn::custom_keyword!(WARN); + syn::custom_keyword!(ERROR); +} + +/// The span level declared with `level: LEVEL`. +#[derive(Clone)] +enum SpanLevel { + Info, + Debug, + Trace, + Warn, + Error, +} + +impl SpanLevel { + /// Emits the `::tracing::Level::*` token for use in `span!()`. + fn to_level_tokens(&self) -> TokenStream2 { + match self { + SpanLevel::Info => quote! { ::tracing::Level::INFO }, + SpanLevel::Debug => quote! { ::tracing::Level::DEBUG }, + SpanLevel::Trace => quote! { ::tracing::Level::TRACE }, + SpanLevel::Warn => quote! { ::tracing::Level::WARN }, + SpanLevel::Error => quote! { ::tracing::Level::ERROR }, + } + } + + /// Lowercase string for `#[tracing::instrument(level = "…")]`. + fn as_str(&self) -> &'static str { + match self { + SpanLevel::Info => "info", + SpanLevel::Debug => "debug", + SpanLevel::Trace => "trace", + SpanLevel::Warn => "warn", + SpanLevel::Error => "error", + } + } +} + +impl Parse for SpanLevel { + fn parse(input: ParseStream) -> syn::Result { + let lookahead = input.lookahead1(); + if lookahead.peek(kw::INFO) { + input.parse::()?; + Ok(SpanLevel::Info) + } else if lookahead.peek(kw::DEBUG) { + input.parse::()?; + Ok(SpanLevel::Debug) + } else if lookahead.peek(kw::TRACE) { + input.parse::()?; + Ok(SpanLevel::Trace) + } else if lookahead.peek(kw::WARN) { + input.parse::()?; + Ok(SpanLevel::Warn) + } else if lookahead.peek(kw::ERROR) { + input.parse::()?; + Ok(SpanLevel::Error) + } else { + Err(lookahead.error()) + } + } +} + +// ── Name ────────────────────────────────────────────────────────────────────── + +/// An open telemetry like dotted identifier (e.g. `account.id`, `block.number`), parsed from +/// the attribute stream but **not yet** checked against the allowlist. +/// +/// Grammar: `ident ("." ident)*` +pub(crate) struct Name { + pub(crate) segments: Punctuated, +} + +impl Name { + /// Returns the dotted string representation, e.g. `"account.id"`. + pub(crate) fn to_dotted_string(&self) -> String { + self.segments.iter().map(ToString::to_string).collect::>().join(".") + } + + /// Span for the full name. + pub(crate) fn span(&self) -> Span { + self.segments.span() + } + + /// Validates this name against the OpenTelemetry allowlist and, on success, returns a + /// [`CheckedName`] that carries the pre-computed dotted string and span. + /// + /// On failure, emits a [`syn::Error`] anchored at the name's span. If the + /// fuzzy-search backend finds close matches they are included as suggestions. + pub(crate) fn check(self) -> syn::Result { + let dotted = self.to_dotted_string(); + let span = self.span(); + crate::allowed::check(&dotted).map_err(|suggestions| { + let hint = if suggestions.is_empty() { + String::new() + } else { + format!(" – did you mean: {}?", suggestions.join(", ")) + }; + syn::Error::new(span, format!("`{dotted}` is not in the OpenTelemetry allowlist{hint}")) + })?; + Ok(CheckedName { dotted, span }) + } +} + +impl Parse for Name { + fn parse(input: ParseStream) -> syn::Result { + let mut segments = Punctuated::new(); + segments.push_value(input.parse::()?); + while input.peek(Token![.]) { + segments.push_punct(input.parse::()?); + segments.push_value(input.parse::()?); + } + Ok(Name { segments }) + } +} + +// ── CheckedName ─────────────────────────────────────────────────────────────── + +/// A field name that has been validated against the OpenTelemetry allowlist. +/// +/// The only way to construct a `CheckedName` is via [`Name::check`], ensuring +/// that unchecked names can never reach codegen. +pub(crate) struct CheckedName { + /// Pre-computed dotted representation (e.g. `"account.id"`). + pub(crate) dotted: String, + /// Span of the original [`Name`] token, forwarded for error reporting. + pub(crate) span: Span, +} + +// ── Value ───────────────────────────────────────────────────────────────────── + +/// The right-hand side of a field assignment: an optional format modifier +/// followed by an arbitrary expression. +/// +/// - `= expr` → Debug format (`{:?}`) +/// - `= %expr` → Display format (`{}`) +/// - `= ?expr` → Debug format (`{:?}`), explicit +struct Value { + display_modifier: Option, + expr: Expr, +} + +impl Parse for Value { + fn parse(input: ParseStream) -> syn::Result { + // Consume `%` (Display) or `?` (Debug-explicit). Both are accepted for + // consistency with `tracing`'s own field syntax; only `%` affects the + // generated token (Debug is the default and needs no modifier token). + let display_modifier = if input.peek(Token![%]) { + Some(input.parse::()?) + } else { + // Consume and discard `?` so the following expr parses cleanly. + input.parse::().ok(); + None + }; + let expr = input.parse::()?; + Ok(Value { display_modifier, expr }) + } +} + +// ── Field entry ─────────────────────────────────────────────────────────────── + +/// A single `dotted-name = [%] expr` pair inside the attribute list. +/// +/// The `name` has been validated against the OpenTelemetry allowlist at parse time. +/// Both `account.id = id` (Debug) and `account.id = %id` (Display) are accepted. +struct Field { + name: CheckedName, + value: Value, +} + +impl Parse for Field { + fn parse(input: ParseStream) -> syn::Result { + let raw: Name = input.parse()?; + let name = raw.check()?; + let _eq: Token![=] = input.parse()?; + let value: Value = input.parse()?; + Ok(Field { name, value }) + } +} + +// ── Element ─────────────────────────────────────────────────────────────────── + +/// A single comma-separated element inside the `#[instrument(…)]` attribute. +enum Element { + /// A `dotted-name = [%] expr` field (validated against the OpenTelemetry allowlist). + Field(Box), + /// `ret` – record the function's return value inside the span. + Ret, + /// `root` – force the span to be a root span (`parent = None`). + Root, + /// `err` – on `Err`, emit a tracing event with the top-level error message. + /// Delegates to `tracing::instrument`'s built-in `err`. Requires `Result`. + Err, + /// `report` – on `Err`, walk the full error chain via [`ErrorReport`] and set + /// the OpenTelemetry span status. Mutually exclusive with `err`. Requires `Result`. + Report, + /// `level: INFO | DEBUG | TRACE | WARN | ERROR` – override the span level (default: `INFO`). + Level(SpanLevel), +} + +impl Parse for Element { + fn parse(input: ParseStream) -> syn::Result { + if input.peek(kw::ret) { + input.parse::()?; + Ok(Element::Ret) + } else if input.peek(kw::root) { + input.parse::()?; + Ok(Element::Root) + } else if input.peek(kw::err) { + input.parse::()?; + Ok(Element::Err) + } else if input.peek(kw::report) { + input.parse::()?; + Ok(Element::Report) + } else if input.peek(kw::level) { + input.parse::()?; + let _: Token![:] = input.parse()?; + Ok(Element::Level(input.parse()?)) + } else { + Ok(Element::Field(Box::new(input.parse()?))) + } + } +} + +// ── ComponentName ───────────────────────────────────────────────────────────── + +/// The optional component prefix before the `:` separator. +/// +/// Used by both `#[instrument(…)]` and the log macros (`warn!`, `error!`, …), +/// but with different token syntax in the emitted output: +/// - span attributes use `=` (e.g. `target = "rpc"`) +/// - tracing events use `:` (e.g. `target: "rpc"`) +/// +/// ```text +/// #[instrument(rpc: …)] → Ident("rpc") → target = "rpc" +/// #[instrument("my-rpc": …)] → Literal → target = "my-rpc" +/// ``` +pub(crate) enum ComponentName { + Literal(LitStr), + Ident(Ident), +} + +impl ComponentName { + fn as_string(&self) -> String { + match self { + ComponentName::Literal(lit) => lit.value(), + ComponentName::Ident(ident) => ident.to_string(), + } + } + + /// Emits `target: "…",` for use in `tracing::!(…)` event macros. + pub(crate) fn to_event_target_tokens(&self) -> TokenStream2 { + match self { + ComponentName::Literal(lit) => quote! { target: #lit, }, + ComponentName::Ident(ident) => { + let s = ident.to_string(); + let lit = LitStr::new(&s, ident.span()); + quote! { target: #lit, } + }, + } + } +} + +// ── InstrumentArgs ──────────────────────────────────────────────────────────── + +/// Parsed representation of the full `#[instrument(…)]` attribute. +/// +/// Grammar: +/// ```text +/// InstrumentArgs ::= ε +/// | COMPONENT ":" [element ("," element)*] +/// | COMPONENT +/// | element ("," element)* +/// +/// COMPONENT ::= ident | string-literal +/// element ::= field-entry | "ret" | "root" | "err" | "report" | "level" ":" LEVEL +/// LEVEL ::= "INFO" | "DEBUG" | "TRACE" | "WARN" | "ERROR" +/// field-entry ::= dotted-name "=" ["%"] expr +/// ``` +struct InstrumentArgs { + /// The `COMPONENT:` prefix, if present. Maps to `target = "…"` in the + /// underlying `tracing::instrument`. + component: Option, + /// Comma-separated elements following the optional component prefix. + elements: Vec, +} + +impl Parse for InstrumentArgs { + fn parse(input: ParseStream) -> syn::Result { + if input.is_empty() { + return Ok(InstrumentArgs { component: None, elements: Vec::new() }); + } + + // Detect `COMPONENT:` prefix: an ident (or string literal) followed by `:`. + // The colon disambiguates from `field = value` entries whose names also + // start with an ident. + // + // A bare `COMPONENT` without a colon is also accepted when it is the only + // token in the attribute (e.g. `#[instrument(COMPONENT)]`), since no + // element can start with a lone ident that has no `=` or `.` after it. + let component = if input.peek(LitStr) && input.peek2(Token![:]) { + let lit: LitStr = input.parse()?; + let _colon: Token![:] = input.parse()?; + Some(ComponentName::Literal(lit)) + } else if input.peek(Ident) && input.peek2(Token![:]) { + let ident: Ident = input.parse()?; + let _colon: Token![:] = input.parse()?; + Some(ComponentName::Ident(ident)) + } else if input.peek(Ident) { + // Bare `COMPONENT` without colon: accepted only when the ident is the + // sole token (nothing follows it) and it is not a reserved keyword. + let forked = input.fork(); + let ident: Ident = forked.parse().expect("peek verified Ident"); + let is_keyword = + matches!(ident.to_string().as_str(), "ret" | "root" | "err" | "report" | "level"); + if !is_keyword && forked.is_empty() { + let ident: Ident = input.parse()?; + Some(ComponentName::Ident(ident)) + } else { + None + } + } else { + None + }; + + let mut elements = Vec::new(); + if !input.is_empty() { + let parsed: Punctuated = Punctuated::parse_terminated(input)?; + elements = parsed.into_iter().collect(); + } + + Ok(InstrumentArgs { component, elements }) + } +} + +// ── Result-return detection ─────────────────────────────────────────────────── + +/// Returns `true` when the function's outermost return type is `Result<…>`. +/// +/// The check inspects the AST directly: it succeeds only when the return type +/// is a [`Type::Path`] whose last segment is literally named `Result`. This +/// avoids the false positive produced by a plain string-contains search (e.g. +/// a type named `NotAResult` would previously pass). +/// +/// `async fn` is handled transparently: `syn` represents the declared return +/// type (before desugaring to `impl Future`) directly, so `async fn foo() -> +/// Result` has `sig.output = Result` just like its sync equivalent. +fn has_result_return_type(item: &ItemFn) -> bool { + let ty = match &item.sig.output { + ReturnType::Default => return false, + ReturnType::Type(_, ty) => ty.as_ref(), + }; + + let Type::Path(type_path) = ty else { + return false; + }; + + type_path + .path + .segments + .last() + .is_some_and(|PathSegment { ident, .. }| ident == "Result") +} + +/// Returns an error when the return type is an `impl Future` or `Pin>` — shapes that are not supported with `err` / `report` because the +/// body-wrapping codegen cannot `.await` the function body. +/// +/// Plain `async fn` is **not** affected: its declared return type is the inner +/// `Result`, and `tracing::instrument` desugars it correctly. +fn reject_future_return_type(item: &ItemFn) -> syn::Result<()> { + let ty = match &item.sig.output { + ReturnType::Default => return Ok(()), + ReturnType::Type(_, ty) => ty.as_ref(), + }; + + // `impl Future` — syn represents this as Type::ImplTrait. + if let Type::ImplTrait(TypeImplTrait { .. }) = ty { + return Err(syn::Error::new( + ty.span(), + "`err` / `report` is not supported on `impl Future` return types; \ + use `async fn` instead", + )); + } + + // `Pin>>` or any other outer wrapper — heuristic: check + // whether the return type is *not* a bare `Result` path and contains a + // `dyn` trait object somewhere (Type::TraitObject nested inside). + // + // We only emit the error when the outermost path does NOT end in `Result` + // to avoid false positives, and the function is not async (which would be + // fine). The check is intentionally conservative: we only flag the + // `Pin>` idiom, not every non-Result path (those are rejected + // later by `has_result_return_type`). + if item.sig.asyncness.is_none() { + if let Type::Path(tp) = ty { + if let Some(seg) = tp.path.segments.last() { + if seg.ident != "Result" { + if type_contains_dyn(ty) { + return Err(syn::Error::new( + ty.span(), + "`err` / `report` is not supported on `Box` return types; \ + use `async fn` instead", + )); + } + } + } + } + } + + Ok(()) +} + +/// Recursively checks whether a type contains a `dyn Trait` object. +fn type_contains_dyn(ty: &Type) -> bool { + match ty { + Type::TraitObject(_) => true, + Type::Path(tp) => tp.path.segments.iter().any(|seg| { + if let syn::PathArguments::AngleBracketed(ab) = &seg.arguments { + ab.args.iter().any(|arg| { + if let syn::GenericArgument::Type(inner) = arg { + type_contains_dyn(inner) + } else { + false + } + }) + } else { + false + } + }), + Type::Reference(r) => type_contains_dyn(&r.elem), + _ => false, + } +} + +// ── codegen helpers ─────────────────────────────────────────────────────────── + +/// Builds one token pair per field: `dotted.name = [%] expr`. +fn field_parts(fields: &[&Field]) -> Vec { + FromIterator::from_iter(fields.iter().map(|f| { + let name_tokens = TokenStream2::from_str(&f.name.dotted) + .unwrap_or_else(|_| panic!("invalid field name: {}", f.name.dotted)); + let expr = &f.value.expr; + if f.value.display_modifier.is_some() { + quote! { #name_tokens = %#expr } + } else { + quote! { #name_tokens = #expr } + } + })) +} + +/// Wraps [`field_parts`] in `fields(…),` for use in `#[tracing::instrument(…)]`. +fn fields_tokens(fields: &[&Field]) -> TokenStream2 { + let parts = field_parts(fields); + if parts.is_empty() { + quote! {} + } else { + quote! { fields(#(#parts),*), } + } +} + +/// Prepends an optional `ret = Empty` entry to [`field_parts`] and returns the +/// result as `, field, …` for appending directly after the span name in `span!`. +fn inline_fields_tokens(fields: &[&Field], has_ret: bool) -> TokenStream2 { + let ret = has_ret.then(|| quote! { ret = ::tracing::field::Empty }); + let parts: Vec<_> = FromIterator::from_iter(ret.into_iter().chain(field_parts(fields))); + if parts.is_empty() { + quote! {} + } else { + quote! { , #(#parts),* } + } +} + +// ── ident-component codegen ─────────────────────────────────────────────────── + +/// Code generation for [`ComponentName::Ident`]. +/// +/// Uses `::tracing::span!(target: IDENT, …)` directly so the component const's +/// runtime value (e.g. `"miden-block-producer"`) is used as the OTel target rather +/// than the identifier name `"COMPONENT"` that `tracing::instrument(target = "IDENT")` +/// would bake in. +/// +/// Sync functions use `let _guard = __span.enter()`. +/// Async functions wrap the body with `async move { … }.instrument(__span).await`. +fn codegen_with_ident_component( + component: &Ident, + level: Option<&SpanLevel>, + has_ret: bool, + has_err: bool, + has_report: bool, + has_root: bool, + fields: &[&Field], + func: ItemFn, +) -> syn::Result { + let ItemFn { attrs, vis, sig, block } = func; + let is_async = sig.asyncness.is_some(); + + let fn_name_lit = LitStr::new(&sig.ident.to_string(), sig.ident.span()); + + let parent_arg = if has_root { + quote! { parent: None, } + } else { + quote! {} + }; + + let inline_fields = inline_fields_tokens(fields, has_ret); + + let level_tok = + level.map_or_else(|| quote! { ::tracing::Level::INFO }, SpanLevel::to_level_tokens); + + let span_tok = quote! { + let __span = ::tracing::span!(target: crate::#component, #parent_arg #level_tok, #fn_name_lit #inline_fields); + }; + + let err_check = if has_err { + quote! { + if let ::core::result::Result::Err(ref __err) = __result { + ::tracing::error!(error = %__err); + } + } + } else { + quote! {} + }; + + let report_check = if has_report { + quote! { + if let ::core::result::Result::Err(ref __err) = __result { + use ::miden_node_utils::ErrorReport as _; + let __report = __err.as_report(); + ::tracing::error!(error = %__report); + use ::miden_node_utils::tracing::OpenTelemetrySpanExt as _; + ::tracing::Span::current().set_error(__err as &dyn ::std::error::Error); + } + } + } else { + quote! {} + }; + + let ret_record = if has_ret { + if has_err || has_report { + // Only record on the Ok path; the Err path is handled by err_check / report_check. + quote! { + if let ::core::result::Result::Ok(ref __ok) = __result { + ::tracing::Span::current().record("ret", ::tracing::field::debug(__ok)); + } + } + } else { + quote! { + ::tracing::Span::current().record("ret", ::tracing::field::debug(&__result)); + } + } + } else { + quote! {} + }; + + let needs_binding = has_ret || has_err || has_report; + + if is_async { + if needs_binding { + Ok(quote! { + #(#attrs)* + #vis #sig { + use ::tracing::Instrument as _; + #span_tok + async move { + let __result = #block; + #[allow(unreachable_code)] { + #err_check + #report_check + #ret_record + __result + } + }.instrument(__span).await + } + }) + } else { + Ok(quote! { + #(#attrs)* + #vis #sig { + use ::tracing::Instrument as _; + #span_tok + async move #block .instrument(__span).await + } + }) + } + } else if needs_binding { + Ok(quote! { + #(#attrs)* + #vis #sig { + #span_tok + let _guard = __span.enter(); + let __result = #block; + #[allow(unreachable_code)] { + #err_check + #report_check + #ret_record + __result + } + } + }) + } else { + Ok(quote! { + #(#attrs)* + #vis #sig { + #span_tok + let _guard = __span.enter(); + #block + } + }) + } +} + +// ── public entry point ──────────────────────────────────────────────────────── + +/// Core implementation of `#[instrument]`. +/// +/// # Validation +/// +/// | Condition | Error | +/// |---|---| +/// | `err` and `report` both present | mutually exclusive | +/// | `err` or `report` on a non-`Result` fn | `err`/`report` requires `Result` return | +/// | `ret` + `report` on a non-`Result` fn | same | +/// | field name not in `allowlist.txt` | open telemetry allowlist violation | +/// +/// # Code generation +/// +/// For `ComponentName::Ident`, delegates to [`codegen_with_ident_component`] which uses +/// `::tracing::span!` directly so the const's runtime value is used as the target. +/// +/// For `ComponentName::Literal` or no component, two output shapes: +/// +/// **`report` present** +/// ```rust,ignore +/// #[::tracing::instrument(target = "…", skip_all, fields(…), ret?)] +/// fn foo(…) -> Result { +/// let __result: Result = { /* original body */ }; +/// if let Err(ref __err) = __result { +/// use ::miden_node_utils::ErrorReport as _; +/// ::tracing::error!(error = %__err.as_report()); +/// use ::miden_node_utils::tracing::OpenTelemetrySpanExt as _; +/// ::tracing::Span::current().set_error(__err as &dyn ::std::error::Error); +/// } +/// __result +/// } +/// ``` +/// +/// **`err` or neither** +/// ```rust,ignore +/// #[::tracing::instrument(target = "…", skip_all, fields(…), ret?, err?)] +/// fn foo(…) { /* original body */ } +/// ``` +pub fn instrument2(attr: TokenStream2, item: TokenStream2) -> syn::Result { + // Fast path: empty attribute stream → plain delegation, no validation needed. + if attr.is_empty() { + let func: ItemFn = syn::parse2(item)?; + let ItemFn { attrs, vis, sig, block } = func; + return Ok(quote! { + #(#attrs)* + #[::tracing::instrument] + #vis #sig #block + }); + } + + let args: InstrumentArgs = syn::parse2(attr)?; + let func: ItemFn = syn::parse2(item)?; + + // ── collect element kinds ────────────────────────────────────────────────── + let mut has_ret = false; + let mut has_err = false; + let mut has_report = false; + let mut has_root = false; + let mut level: Option = None; + let mut fields: Vec<&Field> = Vec::new(); + + let elements = args.elements; + + for elem in &elements { + match elem { + Element::Ret => has_ret = true, + Element::Root => has_root = true, + Element::Err => has_err = true, + Element::Report => has_report = true, + Element::Level(l) => { + if level.is_some() { + return Err(syn::Error::new( + Span::call_site(), + "level specified more than once", + )); + } + level = Some(l.clone()); + }, + Element::Field(f) => fields.push(f.as_ref()), + } + } + + // ── validation ──────────────────────────────────────────────────────────── + + // err and report are mutually exclusive. + if has_err && has_report { + return Err(syn::Error::new( + Span::call_site(), + "`err` and `report` are mutually exclusive – use one or the other", + )); + } + + // Reject unsupported future-returning shapes before the Result check. + if has_err || has_report { + reject_future_return_type(&func)?; + } + + // err / report require a Result return type. + if (has_err || has_report) && !has_result_return_type(&func) { + return Err(syn::Error::new( + func.sig.ident.span(), + "`err` / `report` requires the function to return `Result`", + )); + } + + // Field names were already validated inside Field::parse via Name::check. + + // ── code generation ─────────────────────────────────────────────────────── + + // For ComponentName::Ident, use span! directly so the component const's runtime value + // (e.g. "miden-block-producer") is used as the target rather than the identifier name + // "COMPONENT" that tracing::instrument would bake in as a string literal. + if let Some(ComponentName::Ident(component_ident)) = &args.component { + return codegen_with_ident_component( + component_ident, + level.as_ref(), + has_ret, + has_err, + has_report, + has_root, + &fields, + func, + ); + } + + let level_tok = level.as_ref().map(|l| { + let s = l.as_str(); + let lit = LitStr::new(s, Span::call_site()); + quote! { level = #lit, } + }); + let target_tokens = args.component.as_ref().map(|c| { + // Ident components are handled above by the early-return into codegen_with_ident_component. + let ComponentName::Literal(lit) = c else { unreachable!() }; + quote! { target = #lit, } + }); + let name_tokens = args.component.as_ref().map(|c| { + let name = format!("{}.{}", c.as_string(), func.sig.ident); + let lit = LitStr::new(&name, func.sig.ident.span()); + quote! { name = #lit, } + }); + let fields_tok = fields_tokens(&fields); + + // Always skip all implicit fn arguments to avoid accidentally recording sensitive values. + // Explicit OTel fields declared in the attribute are still emitted via `fields(…)`. + let skip_all = quote! { skip_all, }; + + let parent_tok = if has_root { + quote! { parent = None, } + } else { + quote! {} + }; + + let ret_tok = if has_ret { + quote! { ret, } + } else { + quote! {} + }; + + let ItemFn { attrs, vis, sig, block } = func; + + if has_report { + let result_ty = match &sig.output { + ReturnType::Type(_, ty) => quote! { #ty }, + ReturnType::Default => quote! { () }, + }; + Ok(quote! { + #(#attrs)* + #[::tracing::instrument(#level_tok #parent_tok #target_tokens #name_tokens #skip_all #fields_tok #ret_tok)] + #vis #sig { + let __result: #result_ty = #block; + if let ::core::result::Result::Err(ref __err) = __result { + use ::miden_node_utils::ErrorReport as _; + let __report = __err.as_report(); + ::tracing::error!(error = %__report); + use ::miden_node_utils::tracing::OpenTelemetrySpanExt as _; + ::tracing::Span::current().set_error(__err as &dyn ::std::error::Error); + } + __result + } + }) + } else { + let err_tok = if has_err { + quote! { err } + } else { + quote! {} + }; + Ok(quote! { + #(#attrs)* + #[::tracing::instrument(#level_tok #parent_tok #target_tokens #name_tokens #skip_all #fields_tok #ret_tok #err_tok)] + #vis #sig #block + }) + } +} diff --git a/crates/tracing-macro/src/lib.rs b/crates/tracing-macro/src/lib.rs new file mode 100644 index 0000000000..1e1a910ac5 --- /dev/null +++ b/crates/tracing-macro/src/lib.rs @@ -0,0 +1,400 @@ +//! Procedural macros for structured, OpenTelemetry-aware tracing in the Miden node. +//! +//! **Do not use this crate directly.** Import from `miden-node-tracing` instead, which +//! re-exports every macro here together with all required runtime dependencies +//! (`ErrorReport`, `OpenTelemetrySpanExt`, …). +//! +//! # Overview +//! +//! This crate provides two families of macros that mirror their counterparts in the +//! [`tracing`](https://docs.rs/tracing) crate but extend them with node-specific +//! conventions: +//! +//! | Macro | Purpose | +//! |---|---| +//! | [`#[instrument]`](macro@instrument) | Attribute macro – wraps a function in a tracing span | +//! | [`error!`], [`warn!`], [`info!`], [`debug!`], [`trace!`] | Function-like macros – emit a tracing event | +//! +//! ## Key differences from `tracing` +//! +//! 1. **Component target** – instead of `target = "some::module"` you write a short component name +//! once (`rpc:`, `store:`, …) and it becomes the span target. +//! 2. **`report` keyword** – a richer alternative to `tracing`'s `err` that walks the full +//! `ErrorReport` chain, emits a structured `error!` event *and* sets the OpenTelemetry span +//! status to `Error`. +//! 3. **OpenTelemetry field allowlist** – only names declared in `allowlist.txt` may appear as +//! field keys, preventing accidental cardinality explosions in the metrics / trace backend. +//! 4. **Log macros** – `warn!`, `error!`, etc. mirror `tracing::!` syntax but additionally +//! enforce the same `COMPONENT:` target shorthand and OpenTelemetry field allowlist as +//! `#[instrument]`. +//! +//! # `#[instrument]` – complete reference +//! +//! ## Syntax +//! +//! ```text +//! #[instrument] +//! #[instrument( [COMPONENT:] [element, …] )] +//! +//! COMPONENT ::= ident | "string literal" +//! element ::= field-entry | "ret" | "err" | "report" +//! field-entry::= dotted-name "=" ["%"] expr +//! dotted-name::= ident ["." ident]* -- must be in allowlist.txt +//! ``` +//! +//! ## Combinatorial argument table +//! +//! Each row is a distinct, valid (✓) or invalid (✗) combination with the reason. +//! +//! | Attribute arguments | fn return type | Valid? | Notes | +//! |---|---|---|---| +//! | *(empty)* | any | ✓ | Thin wrapper around `#[tracing::instrument]` | +//! | `rpc:` *(no elements)* | any | ✓ | Sets `target = "rpc"`, no field/ret tracking | +//! | `rpc` *(bare, no colon)* | any | ✓ | Same as `rpc:` – colon is optional when no elements follow | +//! | `rpc: ret` | any | ✓ | Records return value via `tracing::instrument`'s `ret` | +//! | `rpc: err` | `Result<_, E>` | ✓ | Delegates to `tracing::instrument`'s `err` (single-level `Display`/`Debug`) | +//! | `rpc: err` | non-`Result` | ✗ | Compile error: `err` requires `Result` return | +//! | `rpc: report` | `Result<_, E>` | ✓ | Walks full error chain via `ErrorReport`, emits `error!` event, sets OpenTelemetry span status | +//! | `rpc: report` | non-`Result` | ✗ | Compile error: `report` requires `Result` return | +//! | `rpc: err, report` | any | ✗ | Compile error: mutually exclusive | +//! | `rpc: report, err` | any | ✗ | Compile error: mutually exclusive (order does not matter) | +//! | `rpc: ret, err` | `Result<_, E>` | ✓ | Records both return value and error via `tracing::instrument` | +//! | `rpc: ret, report` | `Result` | ✓ | Records return value (`ret`) + full error chain (`report`) | +//! | `rpc: ret, report` | non-`Result` | ✗ | Compile error: `report` requires `Result` return | +//! | `rpc: account.id = id` | any | ✓ | Attaches `account.id` field (Debug format, allowlisted) | +//! | `rpc: account.id = %id` | any | ✓ | Attaches `account.id` field (Display format via `%`) | +//! | `rpc: foo = id` | any | ✗ | Compile error: `foo` not in OpenTelemetry allowlist | +//! | `rpc: foo.bar.baz = %id` | any | ✗ | Compile error: `foo.bar.baz` not in OpenTelemetry allowlist | +//! | `rpc: account.id = %id, err` | `Result<_, E>` | ✓ | Allowlisted field + standard error tracking | +//! | `rpc: account.id = %id, report` | `Result<_, E>` | ✓ | Allowlisted field + full error chain | +//! | `rpc: account.id = %id, ret, report` | `Result` | ✓ | Field + return value + full error chain | +//! | `rpc: account.id = %id, report, err` | `Result<_, E>` | ✗ | Compile error: `report` and `err` are mutually exclusive | +//! +//! ## `err` vs `report` +//! +//! Both keywords require the function to return `Result`. They differ in *how much* of +//! the error is captured: +//! +//! | | `err` | `report` | +//! |---|---|---| +//! | Mechanism | delegates to `tracing::instrument`'s built-in `err` | custom body wrapper | +//! | Error formatting | top-level `Display` or `Debug` only | full chain via `ErrorReport::as_report` (every `source()` cause) | +//! | OpenTelemetry span status | not set | set to `Error` with the full report string | +//! | tracing event level | `ERROR` (tracing default) | `ERROR` | +//! +//! Use `err` for lightweight internal helpers where the single-level message is +//! sufficient. Use `report` on RPC handlers, block application paths, and any boundary +//! where the full error chain must appear in the telemetry. +//! +//! ## Field values and the `%` modifier +//! +//! A field entry `name = expr` records `expr` using its `Debug` implementation. +//! Prefixing the value with `%` switches to `Display`: +//! +//! ```rust,ignore +//! #[instrument(rpc: account.id = account_id)] // Debug → {:?} +//! #[instrument(rpc: account.id = %account_id)] // Display → {} +//! ``` +//! +//! All field names must appear in `allowlist.txt`. An attempt to use an unlisted name +//! produces a compile error with fuzzy-matched suggestions. +//! +//! ## Component name +//! +//! The component prefix sets `target` in the underlying `tracing::instrument` span. +//! It can be an identifier or a string literal: +//! +//! ```rust,ignore +//! #[instrument(rpc: ret)] // target = "rpc" +//! #[instrument("my-rpc": ret)] // target = "my-rpc" +//! ``` +//! +//! When omitted, no `target` override is emitted and tracing uses the default +//! (module path). +//! +//! ## Code generation summary +//! +//! | Combination | Generated code shape | +//! |---|---| +//! | empty attrs | `#[::tracing::instrument] fn …` | +//! | component only / fields / `ret` / `err` | `#[::tracing::instrument(target=…, skip_all?, fields(…)?, ret?, err?)] fn …` | +//! | `report` | `#[::tracing::instrument(…)] fn … { let __result = { … }; if Err(e) { error!(…); set_error(…); } __result }` | +//! +//! # Log macros – complete reference +//! +//! `error!`, `warn!`, `info!`, `debug!`, `trace!` enforce the same `COMPONENT:` +//! target shorthand and OpenTelemetry field allowlist as `#[instrument]`, then expand to +//! the underlying `tracing::!` macro. +//! +//! ## Syntax +//! +//! ```text +//! warn!( [COMPONENT:] [field = ["%" | "?"] expr ,]* [format_str [, args…]] ) +//! +//! COMPONENT ::= ident | string-literal +//! field-entry ::= dotted-name "=" ["%" | "?"] expr +//! dotted-name ::= ident ["." ident]* -- must appear in allowlist.txt +//! ``` +//! +//! ## Combinatorial argument table for `warn!` +//! +//! | Call form | Example | Valid? | Notes | +//! |---|---|---|---| +//! | message only | `warn!("something odd")` | ✓ | Plain string literal, no component or fields | +//! | format string | `warn!("retrying after {}ms", delay)` | ✓ | `format_args!`-style | +//! | component + message | `warn!(rpc: "something odd")` | ✓ | Emits `target: "rpc"` | +//! | component + format | `warn!(store: "migrated {} rows", n)` | ✓ | | +//! | allowlisted field, Debug | `warn!(account.id = id, "context")` | ✓ | `{:?}` format | +//! | allowlisted field, Display | `warn!(account.id = %id, "context")` | ✓ | `{}` format via `%` | +//! | allowlisted field, Debug explicit | `warn!(account.id = ?id, "context")` | ✓ | `{:?}` format via `?` | +//! | unlisted field | `warn!(foo = %x, "context")` | ✗ | Compile error: `foo` not in allowlist | +//! | unlisted dotted field | `warn!(foo.bar = %x, "context")` | ✗ | Compile error: `foo.bar` not in allowlist | +//! | multiple allowlisted fields | `warn!(account.id = %id, block.number = n, "msg")` | ✓ | Any number of allowlisted fields | +//! | fields only, no message | `warn!(account.id = %id, block.number = n)` | ✓ | Structured event, no message string | +//! | component + fields + message | `warn!(rpc: account.id = %id, "rejected")` | ✓ | Full form | +//! | component + unlisted field | `warn!(rpc: foo = %x, "msg")` | ✗ | Compile error: allowlist applies regardless of component | + +use proc_macro::TokenStream; +use proc_macro2::TokenStream as TokenStream2; + +mod allowed; +mod instrument; +mod log; + +#[cfg(test)] +mod tests; + +/// Instruments a function with a `tracing` span, with node-specific extensions. +/// +/// # Syntax +/// +/// ```text +/// #[instrument] +/// #[instrument( [COMPONENT[:]] [element, …] )] +/// #[instrument( COMPONENT )] +/// +/// COMPONENT ::= ident | "string literal" +/// element ::= field-entry | "ret" | "err" | "report" +/// field-entry ::= dotted-name "=" ["%"] expr +/// dotted-name ::= ident ["." ident]* -- must appear in allowlist.txt +/// ``` +/// +/// # Component +/// +/// An optional `IDENT:` or `"literal":` prefix sets the span's `target`. +/// The trailing colon is optional when no elements follow the component name: +/// +/// ```rust,ignore +/// #[instrument(rpc: report)] +/// #[instrument("block-producer": err)] +/// #[instrument(rpc)] // colon omitted – same as rpc: +/// ``` +/// +/// # Keywords +/// +/// - **`ret`** – records the return value inside the span (any return type). +/// - **`err`** – on `Err`, emits a tracing event with the top-level error message. Delegates to +/// `tracing::instrument`'s built-in `err`. Requires `Result` return. +/// - **`report`** – on `Err`, emits an `error!` event containing the *full error chain* via +/// `miden_node_utils::ErrorReport` and sets the OpenTelemetry span status to `Error`. Requires +/// `Result` return. Mutually exclusive with `err`. +/// +/// # Field entries +/// +/// ```rust,ignore +/// #[instrument(rpc: account.id = account_id)] // Debug +/// #[instrument(rpc: account.id = %account_id)] // Display +/// ``` +/// +/// Field names must be declared in `allowlist.txt`. An undeclared name produces a +/// compile error with fuzzy-matched suggestions from the allowlist. +/// +/// # Examples +/// +/// ```rust,ignore +/// use miden_node_tracing::instrument; +/// +/// // Minimal – span with default target, no field tracking. +/// #[instrument] +/// fn simple() {} +/// +/// // Component only – sets target = "rpc", no fields. Colon is optional. +/// #[instrument(rpc:)] +/// fn also_simple() {} +/// +/// // Bare component without colon – same as above. +/// #[instrument(rpc)] +/// fn bare_component() {} +/// +/// // Track return value on any function. +/// #[instrument(rpc: ret)] +/// fn compute() -> u32 { 42 } +/// +/// // Standard error tracking (top-level message only). +/// #[instrument(store: err)] +/// async fn load() -> Result {} +/// +/// // Full error chain + OpenTelemetry span status. +/// #[instrument(rpc: report)] +/// async fn apply_block(&self, block: Block) -> Result<(), ApplyBlockError> {} +/// +/// // Return value tracking combined with full error chain. +/// #[instrument(rpc: ret, report)] +/// async fn fetch_count() -> Result {} +/// +/// // Attach an allowlisted OpenTelemetry field (Display format). +/// #[instrument(rpc: account.id = %account_id, report)] +/// async fn get_account(account_id: AccountId) -> Result {} +/// +/// // Multiple fields. +/// #[instrument(store: account.id = %account_id, block.number = block_num, err)] +/// async fn get_account_at( +/// account_id: AccountId, +/// block_num: BlockNumber, +/// ) -> Result {} +/// ``` +#[proc_macro_attribute] +pub fn instrument(attr: TokenStream, item: TokenStream) -> TokenStream { + match instrument::instrument2(TokenStream2::from(attr), TokenStream2::from(item)) { + Ok(ts) => ts.into(), + Err(e) => e.to_compile_error().into(), + } +} + +/// Emits a tracing event at the `ERROR` level. +/// +/// Accepts the same syntax as [`warn!`]: optional `COMPONENT:` target, then +/// zero or more allowlisted `field = [%|?] expr` pairs, then an optional +/// message string with format arguments. +/// +/// # Examples +/// +/// ```rust,ignore +/// use miden_node_tracing::error; +/// +/// error!("something went wrong"); +/// error!(rpc: "request failed"); +/// error!(rpc: account.id = %id, "request failed"); +/// error!("value was {}", x); +/// ``` +#[proc_macro] +pub fn error(ts: TokenStream) -> TokenStream { + match log::parse("error", ts.into()) { + Ok(ts) => ts.into(), + Err(e) => e.to_compile_error().into(), + } +} + +/// Emits a tracing event at the `WARN` level. +/// +/// # Syntax +/// +/// ```text +/// warn!( [COMPONENT:] [field = ["%"|"?"] expr ,]* [format_str [, args…]] ) +/// ``` +/// +/// The optional `COMPONENT:` prefix sets the tracing target (e.g. `rpc:` → +/// `target: "rpc"`). Field names must appear in `allowlist.txt`; an +/// unlisted name is a compile error with fuzzy-matched suggestions. +/// +/// # Examples +/// +/// ```rust,ignore +/// use miden_node_tracing::warn; +/// +/// // Plain message. +/// warn!("something looks off"); +/// +/// // Component + message. +/// warn!(store: "migration warning"); +/// +/// // Format string. +/// warn!("retrying after {}ms", delay_ms); +/// +/// // Allowlisted field, Display. +/// warn!(account.id = %id, "unexpected account"); +/// +/// // Allowlisted field, Debug. +/// warn!(account.id = ?id, "unexpected account"); +/// +/// // Multiple allowlisted fields + message. +/// warn!(account.id = %id, block.number = n, "state inconsistency"); +/// +/// // Fields only, no message. +/// warn!(account.id = %id, block.number = n); +/// +/// // Component + allowlisted field + message (full form). +/// warn!(rpc: account.id = %id, "request rejected"); +/// ``` +#[proc_macro] +pub fn warn(ts: TokenStream) -> TokenStream { + match log::parse("warn", ts.into()) { + Ok(ts) => ts.into(), + Err(e) => e.to_compile_error().into(), + } +} + +/// Emits a tracing event at the `INFO` level. +/// +/// Same syntax as [`warn!`]: optional `COMPONENT:`, allowlisted fields, optional message. +/// +/// # Examples +/// +/// ```rust,ignore +/// use miden_node_tracing::info; +/// +/// info!("server started"); +/// info!(store: sqlite = %path.display(), "connected to database"); +/// info!(account.id = %id, block.number = n, "transaction accepted"); +/// info!("processed {} transactions", count); +/// ``` +#[proc_macro] +pub fn info(ts: TokenStream) -> TokenStream { + match log::parse("info", ts.into()) { + Ok(ts) => ts.into(), + Err(e) => e.to_compile_error().into(), + } +} + +/// Emits a tracing event at the `DEBUG` level. +/// +/// Same syntax as [`warn!`]: optional `COMPONENT:`, allowlisted fields, optional message. +/// +/// # Examples +/// +/// ```rust,ignore +/// use miden_node_tracing::debug; +/// +/// debug!("entering handler"); +/// debug!(store: "query returned {} rows", n); +/// debug!(block.number = n, "processing block"); +/// debug!("batch size: {}", batch.len()); +/// ``` +#[proc_macro] +pub fn debug(ts: TokenStream) -> TokenStream { + match log::parse("debug", ts.into()) { + Ok(ts) => ts.into(), + Err(e) => e.to_compile_error().into(), + } +} + +/// Emits a tracing event at the `TRACE` level. +/// +/// Same syntax as [`warn!`]: optional `COMPONENT:`, allowlisted fields, optional message. +/// +/// # Examples +/// +/// ```rust,ignore +/// use miden_node_tracing::trace; +/// +/// trace!("tick"); +/// trace!(mempool: "snapshot taken"); +/// trace!(nullifier.id = %id, "nullifier lookup"); +/// ``` +#[proc_macro] +pub fn trace(ts: TokenStream) -> TokenStream { + match log::parse("trace", ts.into()) { + Ok(ts) => ts.into(), + Err(e) => e.to_compile_error().into(), + } +} diff --git a/crates/tracing-macro/src/log.rs b/crates/tracing-macro/src/log.rs new file mode 100644 index 0000000000..7ab8b3e28b --- /dev/null +++ b/crates/tracing-macro/src/log.rs @@ -0,0 +1,182 @@ +use proc_macro2::TokenStream as TokenStream2; +use quote::quote; +use syn::parse::{Parse, ParseStream}; +use syn::{Expr, Ident, LitStr, Token}; + +use crate::instrument::{CheckedName, ComponentName, Name}; + +// ── LogField ───────────────────────────────────────────────────────────────── + +/// A single `dotted-name = [% | ?] expr` structured field in a log event. +/// +/// Both the `%` (Display) and `?` (Debug) value modifiers are accepted, matching +/// `tracing`'s own syntax. The field name is validated against the OpenTelemetry allowlist +/// at parse time via [`Name::check`]. +struct LogField { + name: CheckedName, + /// Raw tokens for the value, including the optional `%`/`?` prefix. We + /// preserve these verbatim so `tracing` can interpret them itself. + value_tokens: TokenStream2, +} + +impl Parse for LogField { + fn parse(input: ParseStream) -> syn::Result { + let raw: Name = input.parse()?; + let name = raw.check()?; + let _eq: Token![=] = input.parse()?; + + // Collect the optional modifier (`%` or `?`) plus the value expression as + // a token stream so we can forward it unchanged to `tracing::!`. + let mut value_tokens = TokenStream2::new(); + if input.peek(Token![%]) { + let tok: Token![%] = input.parse()?; + value_tokens.extend(quote! { #tok }); + } else if input.peek(Token![?]) { + let tok: Token![?] = input.parse()?; + value_tokens.extend(quote! { #tok }); + } + let expr: Expr = input.parse()?; + value_tokens.extend(quote! { #expr }); + + Ok(LogField { name, value_tokens }) + } +} + +// ── LogArgs ─────────────────────────────────────────────────────────────────── + +/// Parsed representation of a log-macro call. +/// +/// Grammar: +/// ```text +/// LogArgs ::= ε +/// | COMPONENT ":" [field-entry ","]* [message] +/// | [field-entry ","]* [message] +/// +/// COMPONENT ::= ident | string-literal +/// field-entry ::= dotted-name "=" ["%" | "?"] expr +/// message ::= string-literal ["," expr]* +/// ``` +/// +/// The `COMPONENT:` prefix maps to `target: "component"` in the emitted +/// `tracing::!` call. Field names are validated against the OpenTelemetry +/// allowlist at parse time. The trailing message (if any) is forwarded verbatim. +struct LogArgs { + /// Optional component prefix; emitted as `target: "…"` in the tracing call. + component: Option, + /// Structured fields, allowlist-validated at parse time. + fields: Vec, + /// Remaining tokens after the last field – the message string and any format + /// arguments, forwarded verbatim to `tracing`. + message_tokens: TokenStream2, +} + +impl Parse for LogArgs { + fn parse(input: ParseStream) -> syn::Result { + if input.is_empty() { + return Ok(LogArgs { + component: None, + fields: Vec::new(), + message_tokens: quote! {}, + }); + } + + // Detect optional `COMPONENT:` prefix: ident or string literal followed by `:`. + // Must not be mistaken for `field = value` (those use `=` not `:`). + let component = if input.peek(LitStr) && input.peek2(Token![:]) { + let lit: LitStr = input.parse()?; + let _colon: Token![:] = input.parse()?; + Some(ComponentName::Literal(lit)) + } else if input.peek(Ident) && input.peek2(Token![:]) { + let ident: Ident = input.parse()?; + let _colon: Token![:] = input.parse()?; + Some(ComponentName::Ident(ident)) + } else { + None + }; + + // Parse comma-separated fields. We stop at the first token that cannot + // start a field: a string literal marks the beginning of the message. + // + // A field starts with an ident (the first segment of a dotted name) and + // must be followed at some point by `=`. We use a forked parse to check + // whether the next comma-delimited token is a field or the message. + let mut fields: Vec = Vec::new(); + + loop { + if input.is_empty() { + break; + } + // A string literal cannot be a field name → it starts the message. + if input.peek(LitStr) { + break; + } + // Try to parse a field: `name = …`. If the lookahead shows an ident + // but no `=` follows the name, it's not a field either (bare ident + // expressions are not supported as log messages here). + // + // We fork so that a failed parse doesn't consume input. + let forked = input.fork(); + if forked.parse::().is_ok() && forked.peek(Token![=]) { + let field: LogField = input.parse()?; + fields.push(field); + // Consume the trailing comma, if any. + if input.peek(Token![,]) { + let _: Token![,] = input.parse()?; + } + } else { + // Not a field – the rest is the message. + break; + } + } + + // Everything that remains (message string + format args) is forwarded + // verbatim. + let message_tokens: TokenStream2 = input.parse()?; + + Ok(LogArgs { component, fields, message_tokens }) + } +} + +// ── public entry point ──────────────────────────────────────────────────────── + +/// Parses and validates a log-macro call, then expands it to +/// `::tracing::event!(target: "…", Level::LEVEL, field = value, …, "message", …)`. +/// +/// [`tracing::event!`] is used instead of the level-specific macros (`warn!`, `info!`, …) +/// because those macros only accept ident keys when `target:` is present, rejecting the +/// string-literal dotted keys we emit (e.g. `"account.id"`). `event!` has a more permissive +/// parser that accepts string literal keys in all argument positions. +/// +/// Called by all five log proc-macros (`error!`, `warn!`, `info!`, `debug!`, `trace!`). +pub(crate) fn parse(level: &'static str, ts: TokenStream2) -> syn::Result { + let args: LogArgs = syn::parse2(ts)?; + + // `tracing::Level` variant matching the requested level. + let level_variant = syn::Ident::new(&level.to_uppercase(), proc_macro2::Span::call_site()); + + // Build the target fragment (present only when a component was given). + let target_tok = args.component.as_ref().map(ComponentName::to_event_target_tokens); + + // Build the field fragments: `"dotted.name" = [%|?] expr`. + let field_toks: Vec = args + .fields + .iter() + .map(|f| { + let name_lit = LitStr::new(&f.name.dotted, f.name.span); + let val = &f.value_tokens; + quote! { #name_lit = #val } + }) + .collect(); + + // Emit trailing comma between fields and message only when both are present. + let msg = &args.message_tokens; + let sep = if !field_toks.is_empty() && !msg.is_empty() { + quote! { , } + } else { + quote! {} + }; + + Ok(quote! { + ::tracing::event!(#target_tok ::tracing::Level::#level_variant, #(#field_toks),* #sep #msg) + }) +} diff --git a/crates/tracing-macro/src/tests.rs b/crates/tracing-macro/src/tests.rs new file mode 100644 index 0000000000..236b10bb7c --- /dev/null +++ b/crates/tracing-macro/src/tests.rs @@ -0,0 +1,546 @@ +use proc_macro2::TokenStream as TokenStream2; +use quote::quote; + +use crate::instrument::instrument2; +use crate::log; + +fn warn2(ts: TokenStream2) -> syn::Result { + log::parse("warn", ts) +} + +fn error2(ts: TokenStream2) -> syn::Result { + log::parse("error", ts) +} + +fn info2(ts: TokenStream2) -> syn::Result { + log::parse("info", ts) +} + +fn debug2(ts: TokenStream2) -> syn::Result { + log::parse("debug", ts) +} + +fn trace2(ts: TokenStream2) -> syn::Result { + log::parse("trace", ts) +} + +/// A function whose return type *contains* the word "Result" but is not `Result`. +/// The old string-contains check would incorrectly accept this. +fn item_fake_result_fn() -> TokenStream2 { + quote! { fn foo() -> NotAResult { NotAResult } } +} + +// ── item fixtures ───────────────────────────────────────────────────────────── + +/// Plain function, does not return a Result. +fn item_bare_fn() -> TokenStream2 { + quote! { fn foo() {} } +} + +/// Function returning Result<(), String> – Ok type is unit (no Display needed). +fn item_result_unit_fn() -> TokenStream2 { + quote! { fn foo() -> Result<(), String> { Ok(()) } } +} + +/// Function returning Result – Ok type implements Display. +fn item_result_display_fn() -> TokenStream2 { + quote! { fn foo() -> Result { Ok(42) } } +} + +// ── #[instrument] / #[instrument()] ──────────────────────────────────────── + +#[test] +fn instrument_bare_succeeds() { + // #[instrument] – empty attr stream, any fn → ok + let result = instrument2(quote! {}, item_bare_fn()); + assert!(result.is_ok(), "{result:?}"); +} + +#[test] +fn instrument_ident_component_uses_ident_as_target() { + // The ident `rpc` must appear as `crate::rpc` (a path, not a string literal) so the + // const's runtime value drives the OTel target instead of the identifier name. + let result = instrument2(quote! { rpc: }, item_bare_fn()).expect("expansion should succeed"); + let tokens = result.to_string(); + assert!( + tokens.contains("crate :: rpc"), + "expected crate path target in output, got: {tokens}" + ); + assert!( + !tokens.contains("\"rpc\""), + "expected no string literal for component, got: {tokens}" + ); +} + +#[test] +fn instrument_ident_component_uses_ident_as_target_for_report() { + let result = instrument2(quote! { rpc: report }, item_result_unit_fn()) + .expect("expansion should succeed"); + let tokens = result.to_string(); + assert!( + tokens.contains("crate :: rpc"), + "expected crate path target in output, got: {tokens}" + ); +} + +#[test] +fn instrument_ident_component_uses_ident_as_target_for_err() { + let result = + instrument2(quote! { rpc: err }, item_result_unit_fn()).expect("expansion should succeed"); + let tokens = result.to_string(); + assert!( + tokens.contains("crate :: rpc"), + "expected crate path target in output, got: {tokens}" + ); +} + +// ── level ───────────────────────────────────────────────────────────────────── + +#[test] +fn instrument_default_level_is_info() { + let result = instrument2(quote! { rpc: }, item_bare_fn()).expect("expansion should succeed"); + assert!(result.to_string().contains("Level :: INFO"), "{}", result); +} + +#[test] +fn instrument_explicit_debug_level() { + let result = instrument2(quote! { rpc: level: DEBUG }, item_bare_fn()) + .expect("expansion should succeed"); + assert!(result.to_string().contains("Level :: DEBUG"), "{}", result); +} + +#[test] +fn instrument_level_specified_twice_fails() { + let result = instrument2(quote! { rpc: level: INFO, level: DEBUG }, item_bare_fn()); + assert!(result.is_err(), "{result:?}"); +} + +#[test] +fn instrument_invalid_level_fails() { + let result = instrument2(quote! { rpc: level: VERBOSE }, item_bare_fn()); + assert!(result.is_err(), "{result:?}"); +} + +// ── root ────────────────────────────────────────────────────────────────────── + +#[test] +fn instrument_root_emits_parent_none() { + // For ident components, root is expressed as `parent: None` in `info_span!` syntax. + let result = + instrument2(quote! { rpc: root }, item_bare_fn()).expect("expansion should succeed"); + let tokens = result.to_string(); + assert!( + tokens.contains("parent : None"), + "expected `parent : None` in info_span! output, got: {tokens}" + ); +} + +// ── report ──────────────────────────────────────────────────────────────────── + +#[test] +fn instrument_report_on_bare_fn_fails() { + // #[instrument(rpc: report)] – fn does NOT return Result → error + let result = instrument2(quote! { rpc: report }, item_bare_fn()); + assert!(result.is_err(), "{result:?}"); +} + +// ── err ─────────────────────────────────────────────────────────────────────── + +#[test] +fn instrument_err_on_bare_fn_fails() { + // #[instrument(rpc: err)] – fn does NOT return Result → error + let result = instrument2(quote! { rpc: err }, item_bare_fn()); + assert!(result.is_err(), "{result:?}"); +} + +// ── report, err (mutually exclusive) ──────────────────────────────────────── + +#[test] +fn instrument_report_err_fails() { + // #[instrument(rpc: report, err)] – mutually exclusive → error + let result = instrument2(quote! { rpc: report, err }, item_result_unit_fn()); + assert!(result.is_err(), "{result:?}"); +} + +#[test] +fn instrument_err_report_fails() { + // #[instrument(rpc: err, report)] – same constraint, reversed order → error + let result = instrument2(quote! { rpc: err, report }, item_result_unit_fn()); + assert!(result.is_err(), "{result:?}"); +} + +// ── ret ─────────────────────────────────────────────────────────────────────── + +#[test] +fn instrument_ret_succeeds() { + // #[instrument(rpc: ret)] – any fn → ok (no Result required) + let result = instrument2(quote! { rpc: ret }, item_bare_fn()); + assert!(result.is_ok(), "{result:?}"); +} + +// ── ret, report ─────────────────────────────────────────────────────────────── + +#[test] +fn instrument_ret_report_on_result_display_fn_succeeds() { + // #[instrument(rpc: ret, report)] + // fn returns Result AND Ok: Display → ok + // (Display on Ok is a call-site constraint; the macro accepts the syntax) + let result = instrument2(quote! { rpc: ret, report }, item_result_display_fn()); + assert!(result.is_ok(), "{result:?}"); +} + +#[test] +fn instrument_ret_report_on_bare_fn_fails() { + // #[instrument(rpc: ret, report)] – fn does NOT return Result → error + let result = instrument2(quote! { rpc: ret, report }, item_bare_fn()); + assert!(result.is_err(), "{result:?}"); +} + +// ── allowlisted field = value ───────────────────────────────────────────────── + +#[test] +fn instrument_allowlisted_field_eq_value_succeeds() { + // #[instrument(rpc: account.id = bar)] – account.id is in the allowlist → ok + let result = instrument2(quote! { rpc: account.id = bar }, item_bare_fn()); + assert!(result.is_ok(), "{result:?}"); +} + +#[test] +fn instrument_unlisted_field_eq_value_fails() { + // #[instrument(rpc: foo = bar)] – foo NOT in allowlist → error + let result = instrument2(quote! { rpc: foo = bar }, item_bare_fn()); + assert!(result.is_err(), "{result:?}"); +} + +// ── allowlisted field = %value (Display modifier) ─────────────────────────── + +#[test] +fn instrument_allowlisted_field_display_value_succeeds() { + // #[instrument(rpc: account.id = %bar)] – account.id allowlisted, % modifier → ok + let result = instrument2(quote! { rpc: account.id = %bar }, item_bare_fn()); + assert!(result.is_ok(), "{result:?}"); +} + +#[test] +fn instrument_allowlisted_field_debug_explicit_value_succeeds() { + // #[instrument(rpc: account.id = ?bar)] – account.id allowlisted, ? modifier → ok + let result = instrument2(quote! { rpc: account.id = ?bar }, item_bare_fn()); + assert!(result.is_ok(), "{result:?}"); +} + +#[test] +fn instrument_unlisted_field_display_value_fails() { + // #[instrument(rpc: foo.bar.baz = %bar)] – foo.bar.baz NOT in allowlist → error + let result = instrument2(quote! { rpc: foo.bar.baz = %bar }, item_bare_fn()); + assert!(result.is_err(), "{result:?}"); +} + +// ── combined: allowlisted fields + err/report ───────────────────────────────── + +#[test] +fn instrument_allowlisted_field_display_err_on_result_fn_succeeds() { + // #[instrument(rpc: account.id = %bar, err)] + // allowlisted + % + err + Result → ok + let result = instrument2(quote! { rpc: account.id = %bar, err }, item_result_unit_fn()); + assert!(result.is_ok(), "{result:?}"); +} + +#[test] +fn instrument_allowlisted_field_display_report_on_result_fn_succeeds() { + // #[instrument(rpc: nullifier.id = %bar, report)] + // allowlisted + % + report + Result → ok + let result = instrument2(quote! { rpc: nullifier.id = %bar, report }, item_result_unit_fn()); + assert!(result.is_ok(), "{result:?}"); +} + +#[test] +fn instrument_allowlisted_field_display_ret_report_on_result_display_fn_succeeds() { + // #[instrument(rpc: account.id = %bar, ret, report)] + // allowlisted + % + ret + report + Result → ok + let result = + instrument2(quote! { rpc: account.id = %bar, ret, report }, item_result_display_fn()); + assert!(result.is_ok(), "{result:?}"); +} + +#[test] +fn instrument_unlisted_field_display_err_on_result_fn_fails() { + // #[instrument(rpc: foo = bar, err)] – foo NOT in allowlist → error + // (allowlist check fires regardless of the presence of err) + let result = instrument2(quote! { rpc: foo = bar, err }, item_result_unit_fn()); + assert!(result.is_err(), "{result:?}"); +} + +#[test] +fn instrument_allowlisted_field_display_report_err_fails() { + // #[instrument(rpc: account.id = %bar, report, err)] + // allowlist ok, but report + err are mutually exclusive → error + let result = instrument2(quote! { rpc: account.id = %bar, report, err }, item_result_unit_fn()); + assert!(result.is_err(), "{result:?}"); +} + +// ── warn! / log macros ──────────────────────────────────────────────────────── + +// ── empty / message only ────────────────────────────────────────────────────── + +#[test] +fn warn_empty_succeeds() { + // warn!() – empty stream → ok (empty tracing event) + let result = warn2(quote! {}); + assert!(result.is_ok(), "{result:?}"); +} + +#[test] +fn warn_message_only_succeeds() { + // warn!("something odd") – plain string literal → ok + let result = warn2(quote! { "something odd" }); + assert!(result.is_ok(), "{result:?}"); +} + +#[test] +fn warn_format_string_succeeds() { + // warn!("retry after {}ms", delay) – format string → ok + let result = warn2(quote! { "retry after {}ms", delay }); + assert!(result.is_ok(), "{result:?}"); +} + +// ── component ───────────────────────────────────────────────────────────────── + +#[test] +fn warn_component_ident_message_succeeds() { + // warn!(rpc: "msg") – component ident + message → ok + let result = warn2(quote! { rpc: "msg" }); + assert!(result.is_ok(), "{result:?}"); +} + +#[test] +fn warn_component_literal_message_succeeds() { + // warn!("block-producer": "msg") – string-literal component → ok + let result = warn2(quote! { "block-producer": "msg" }); + assert!(result.is_ok(), "{result:?}"); +} + +#[test] +fn warn_component_only_succeeds() { + // warn!(rpc:) – component with no fields or message → ok + let result = warn2(quote! { rpc: }); + assert!(result.is_ok(), "{result:?}"); +} + +// ── allowlisted fields ──────────────────────────────────────────────────────── + +#[test] +fn warn_allowlisted_field_debug_succeeds() { + // warn!(account.id = id, "msg") – allowlisted, Debug format → ok + let result = warn2(quote! { account.id = id, "msg" }); + assert!(result.is_ok(), "{result:?}"); +} + +#[test] +fn warn_allowlisted_field_display_succeeds() { + // warn!(account.id = %id, "msg") – allowlisted, Display format → ok + let result = warn2(quote! { account.id = %id, "msg" }); + assert!(result.is_ok(), "{result:?}"); +} + +#[test] +fn warn_allowlisted_field_debug_explicit_succeeds() { + // warn!(account.id = ?id, "msg") – allowlisted, explicit Debug → ok + let result = warn2(quote! { account.id = ?id, "msg" }); + assert!(result.is_ok(), "{result:?}"); +} + +#[test] +fn warn_multiple_allowlisted_fields_succeeds() { + // warn!(account.id = %id, block.number = n, "msg") – two allowlisted fields → ok + let result = warn2(quote! { account.id = %id, block.number = n, "msg" }); + assert!(result.is_ok(), "{result:?}"); +} + +#[test] +fn warn_allowlisted_fields_no_message_succeeds() { + // warn!(account.id = %id, block.number = n) – fields only, no message → ok + let result = warn2(quote! { account.id = %id, block.number = n }); + assert!(result.is_ok(), "{result:?}"); +} + +// ── unlisted fields ─────────────────────────────────────────────────────────── + +#[test] +fn warn_unlisted_field_fails() { + // warn!(foo = %x, "msg") – foo NOT in allowlist → error + let result = warn2(quote! { foo = %x, "msg" }); + assert!(result.is_err(), "{result:?}"); +} + +#[test] +fn warn_unlisted_dotted_field_fails() { + // warn!(foo.bar = %x, "msg") – foo.bar NOT in allowlist → error + let result = warn2(quote! { foo.bar = %x, "msg" }); + assert!(result.is_err(), "{result:?}"); +} + +// ── component + fields ──────────────────────────────────────────────────────── + +#[test] +fn warn_component_allowlisted_field_message_succeeds() { + // warn!(rpc: account.id = %id, "msg") – component + allowlisted + message → ok + let result = warn2(quote! { rpc: account.id = %id, "msg" }); + assert!(result.is_ok(), "{result:?}"); +} + +#[test] +fn warn_component_unlisted_field_fails() { + // warn!(rpc: foo = %x, "msg") – component present but foo NOT in allowlist → error + // (allowlist applies regardless of component) + let result = warn2(quote! { rpc: foo = %x, "msg" }); + assert!(result.is_err(), "{result:?}"); +} + +#[test] +fn warn_component_multiple_fields_message_succeeds() { + // warn!(store: account.id = %id, block.number = n, "msg") → ok + let result = warn2(quote! { store: account.id = %id, block.number = n, "msg" }); + assert!(result.is_ok(), "{result:?}"); +} + +#[test] +fn warn_component_nullifier_field_succeeds() { + // warn!(rpc: nullifier.id = %id, "msg") – nullifier.id allowlisted → ok + let result = warn2(quote! { rpc: nullifier.id = %id, "msg" }); + assert!(result.is_ok(), "{result:?}"); +} + +// ── returns_result false-positive regression ────────────────────────────────── + +#[test] +fn instrument_report_on_fake_result_fn_fails() { + // `NotAResult` contains "Result" as a substring → the string-contains check + // would incorrectly accept this, but the typed check must reject it. + let result = instrument2(quote! { rpc: report }, item_fake_result_fn()); + assert!(result.is_err(), "expected error: report requires Result return, got {result:?}"); +} + +#[test] +fn instrument_err_on_fake_result_fn_fails() { + // Same false-positive gate for `err`. + let result = instrument2(quote! { rpc: err }, item_fake_result_fn()); + assert!(result.is_err(), "expected error: err requires Result return, got {result:?}"); +} + +// ── per-level log dispatch regression ───────────────────────────────────────── + +/// Checks that a log expansion contains the expected level identifier. +fn assert_level(result: syn::Result, expected_level: &str) { + let ts = result.expect("expansion should succeed"); + let s = ts.to_string(); + assert!( + s.contains(expected_level), + "expected level `{expected_level}` in output, got: {s}" + ); +} + +#[test] +fn error_level_dispatch() { + assert_level(error2(quote! { "msg" }), "ERROR"); +} + +#[test] +fn warn_level_dispatch() { + assert_level(warn2(quote! { "msg" }), "WARN"); +} + +#[test] +fn info_level_dispatch() { + assert_level(info2(quote! { "msg" }), "INFO"); +} + +#[test] +fn debug_level_dispatch() { + assert_level(debug2(quote! { "msg" }), "DEBUG"); +} + +#[test] +fn trace_level_dispatch() { + assert_level(trace2(quote! { "msg" }), "TRACE"); +} + +// ── async fn support ───────────────────────────────────────────────────────── + +/// `async fn` returning `Result` – `report` must succeed. +fn item_async_result_fn() -> TokenStream2 { + quote! { async fn foo() -> Result<(), String> { Ok(()) } } +} + +/// `async fn` returning nothing – `report` must fail. +fn item_async_bare_fn() -> TokenStream2 { + quote! { async fn foo() {} } +} + +#[test] +fn instrument_report_on_async_result_fn_succeeds() { + // async fn returning Result is syntactically identical to a sync Result fn + // from syn's perspective; the declared return type is Result, not a Future. + let result = instrument2(quote! { rpc: report }, item_async_result_fn()); + assert!(result.is_ok(), "{result:?}"); +} + +#[test] +fn instrument_err_on_async_result_fn_succeeds() { + let result = instrument2(quote! { rpc: err }, item_async_result_fn()); + assert!(result.is_ok(), "{result:?}"); +} + +#[test] +fn instrument_report_on_async_bare_fn_fails() { + let result = instrument2(quote! { rpc: report }, item_async_bare_fn()); + assert!(result.is_err(), "{result:?}"); +} + +// ── impl Future / Box rejection ─────────────────────────────────── + +/// `fn` returning `impl Future>` – `report` must be rejected +/// with a clear error because the body-wrap codegen cannot `.await` the block. +fn item_impl_future_result_fn() -> TokenStream2 { + quote! { + fn foo() -> impl ::std::future::Future> { + async { Ok(()) } + } + } +} + +/// `fn` returning `Pin>>>` – same restriction. +fn item_pin_box_future_result_fn() -> TokenStream2 { + quote! { + fn foo() -> ::std::pin::Pin>>> { + Box::pin(async { Ok(()) }) + } + } +} + +#[test] +fn instrument_report_on_impl_future_fails() { + let result = instrument2(quote! { rpc: report }, item_impl_future_result_fn()); + assert!(result.is_err(), "expected error for impl Future, got {result:?}"); + let msg = result.unwrap_err().to_string(); + assert!(msg.contains("impl Future"), "unexpected error message: {msg}"); +} + +#[test] +fn instrument_err_on_impl_future_fails() { + let result = instrument2(quote! { rpc: err }, item_impl_future_result_fn()); + assert!(result.is_err(), "expected error for impl Future, got {result:?}"); +} + +#[test] +fn instrument_report_on_pin_box_future_fails() { + let result = instrument2(quote! { rpc: report }, item_pin_box_future_result_fn()); + assert!(result.is_err(), "expected error for Box, got {result:?}"); + let msg = result.unwrap_err().to_string(); + assert!(msg.contains("Box"), "unexpected error message: {msg}"); +} + +#[test] +fn instrument_err_on_pin_box_future_fails() { + let result = instrument2(quote! { rpc: err }, item_pin_box_future_result_fn()); + assert!(result.is_err(), "expected error for Box, got {result:?}"); +} diff --git a/crates/tracing/Cargo.toml b/crates/tracing/Cargo.toml new file mode 100644 index 0000000000..e44a8928dc --- /dev/null +++ b/crates/tracing/Cargo.toml @@ -0,0 +1,25 @@ +[package] +categories = ["development-tools::debugging"] +description = "Tracing utilities for Miden node with enhanced error reporting" +keywords = ["miden", "node", "tracing"] +name = "miden-node-tracing" + +edition.workspace = true +license.workspace = true +readme.workspace = true +repository.workspace = true +rust-version.workspace = true +version.workspace = true + +[lints] +workspace = true + +[dependencies] +miden-node-tracing-macro = { workspace = true } +miden-node-utils = { workspace = true } +opentelemetry = { version = "0.31" } +tracing = { workspace = true } + +[dev-dependencies] +async-trait = { workspace = true } +trybuild = { workspace = true } diff --git a/crates/tracing/README.md b/crates/tracing/README.md new file mode 100644 index 0000000000..46eba1ef5f --- /dev/null +++ b/crates/tracing/README.md @@ -0,0 +1,75 @@ +# Miden Node Tracing + +Tracing utilities for Miden node with enhanced error reporting. + +## Overview + +This crate provides an `#[instrument]` attribute macro that wraps `tracing::instrument` with a +custom syntax that enforces OpenTelemetry field naming conventions and adds optional full +error-chain reporting. It is **not** a drop-in replacement for `tracing::instrument`. + +All function arguments are skipped automatically. The component name becomes the tracing `target`; +for string-literal components it also prefixes the span name (`"component.fn_name"`). + +## Usage + +```rust +use miden_node_tracing::instrument; + +// COMPONENT is a `&str` const defined in the calling crate, e.g.: +// pub const COMPONENT: &str = "miden-store"; + +#[instrument(COMPONENT: report)] +pub async fn apply_block(&self, block: ProvenBlock) -> Result<(), ApplyBlockError> { + // Function body... +} +``` + +The component prefix can also be a string literal: + +```rust +#[instrument("miden-store": err)] +pub fn get_account(&self, id: AccountId) -> Result { ... } +``` + +## Supported Syntax + +``` +#[instrument] +#[instrument(COMPONENT)] +#[instrument(COMPONENT:)] +#[instrument(COMPONENT: element, element, ...)] +``` + +`COMPONENT` is either an identifier (referencing a `&str` const in scope, resolved as +`crate::IDENT`) or a string literal. + +### Elements + +| Element | Description | +|---------|-------------| +| `report` | On `Err`: walk the full error chain via `ErrorReport`, log it, and set the OpenTelemetry span status. Mutually exclusive with `err`. Requires `Result` return. | +| `err` | On `Err`: emit a tracing event with the top-level error message. Mutually exclusive with `report`. Requires `Result` return. | +| `ret` | Record the function's return value inside the span. | +| `root` | Force the span to be a root span (`parent = None`). | +| `level: LEVEL` | Set the span level. `LEVEL` must be one of `INFO`, `DEBUG`, `TRACE`, `WARN`, `ERROR`. Defaults to `INFO`. | +| `dotted.name = [%\|?] expr` | Add an OTel span field. The name must be present in `allowlist.txt`. `%` uses Display; `?` or no modifier uses Debug. | + +`skip_all` is always injected automatically. There is no way to record individual arguments; +use explicit field entries instead. + +## Enhanced Error Reporting + +When `report` is used and an error occurs, the full error chain is recorded: + +```text +ERROR apply_block: error = "failed to apply block +caused by: database error +caused by: SQLite error: table 'blocks' has 10 columns but 9 values were supplied" +``` + +## Requirements + +- `report` / `err` require the function to return `Result`. +- `report` additionally requires `E: std::error::Error` (via the `ErrorReport` blanket impl from `miden-node-utils`). +- `async fn` returning `Result` is fully supported. `impl Future` and `Pin>` return types are not. diff --git a/crates/tracing/src/lib.rs b/crates/tracing/src/lib.rs new file mode 100644 index 0000000000..f17fab5698 --- /dev/null +++ b/crates/tracing/src/lib.rs @@ -0,0 +1,42 @@ +//! Tracing utilities for Miden node with enhanced error reporting. +//! +//! This crate provides an `#[instrument]` attribute macro that wraps +//! `tracing::instrument` with a custom syntax enforcing OpenTelemetry field +//! naming and optional full error-chain reporting. +//! +//! # Usage +//! +//! ```rust,ignore +//! use miden_node_tracing::instrument; +//! +//! // COMPONENT is a &str const defined in the calling crate. +//! #[instrument(COMPONENT: report)] +//! async fn apply_block(&self, block: Block) -> Result<(), ApplyBlockError> { +//! // ... +//! } +//! ``` +//! +//! All function arguments are skipped automatically. Additional span fields +//! must use names from the OpenTelemetry allowlist: +//! +//! ```rust,ignore +//! #[instrument(COMPONENT: level: DEBUG, account.id = %id, err)] +//! fn get_account(&self, id: AccountId) -> Result { ... } +//! ``` +//! +//! When `report` is used and an error occurs, the full error chain is recorded: +//! ```text +//! ERROR apply_block: error = "failed to apply block +//! caused by: database error +//! caused by: SQLite error: table 'blocks' has 10 columns but 9 values were supplied" +//! ``` + +pub use miden_node_tracing_macro::{debug, error, info, instrument, trace, warn}; +pub use miden_node_utils::ErrorReport; +pub use miden_node_utils::tracing::OpenTelemetrySpanExt; +#[doc(hidden)] +pub use opentelemetry::trace::Status as OtelStatus; +#[doc(hidden)] +pub use tracing::field::Empty as FieldEmpty; +#[doc(hidden)] +pub use tracing::{Instrument, Level, Span, event}; diff --git a/crates/tracing/tests/ui.rs b/crates/tracing/tests/ui.rs new file mode 100644 index 0000000000..ccf475d5ee --- /dev/null +++ b/crates/tracing/tests/ui.rs @@ -0,0 +1,7 @@ +#[test] +fn ui() { + let t = trybuild::TestCases::new(); + t.pass("tests/ui/pass/*.rs"); + t.compile_fail("tests/ui/instrument/*.rs"); + t.compile_fail("tests/ui/log/*.rs"); +} diff --git a/crates/tracing/tests/ui/instrument/dotted_field_not_in_allowlist.rs b/crates/tracing/tests/ui/instrument/dotted_field_not_in_allowlist.rs new file mode 100644 index 0000000000..7061301a80 --- /dev/null +++ b/crates/tracing/tests/ui/instrument/dotted_field_not_in_allowlist.rs @@ -0,0 +1,6 @@ +use miden_node_tracing::instrument; + +#[instrument(rpc: foo.bar.baz = %bar)] +fn foo() {} + +fn main() {} diff --git a/crates/tracing/tests/ui/instrument/dotted_field_not_in_allowlist.stderr b/crates/tracing/tests/ui/instrument/dotted_field_not_in_allowlist.stderr new file mode 100644 index 0000000000..3dd6713944 --- /dev/null +++ b/crates/tracing/tests/ui/instrument/dotted_field_not_in_allowlist.stderr @@ -0,0 +1,5 @@ +error: `foo.bar.baz` is not in the OpenTelemetry allowlist + --> tests/ui/instrument/dotted_field_not_in_allowlist.rs:3:19 + | +3 | #[instrument(rpc: foo.bar.baz = %bar)] + | ^^^ diff --git a/crates/tracing/tests/ui/instrument/err_on_async_trait.rs b/crates/tracing/tests/ui/instrument/err_on_async_trait.rs new file mode 100644 index 0000000000..8f7e790055 --- /dev/null +++ b/crates/tracing/tests/ui/instrument/err_on_async_trait.rs @@ -0,0 +1,19 @@ +use async_trait::async_trait; +use miden_node_tracing::instrument; + +#[async_trait] +trait Service { + async fn call(&self) -> Result<(), String>; +} + +struct Impl; + +#[async_trait] +impl Service for Impl { + #[instrument(rpc: err)] + async fn call(&self) -> Result<(), String> { + Ok(()) + } +} + +fn main() {} diff --git a/crates/tracing/tests/ui/instrument/err_on_async_trait.stderr b/crates/tracing/tests/ui/instrument/err_on_async_trait.stderr new file mode 100644 index 0000000000..a2b626ede8 --- /dev/null +++ b/crates/tracing/tests/ui/instrument/err_on_async_trait.stderr @@ -0,0 +1,16 @@ +error: `err` / `report` is not supported on `Box` return types; use `async fn` instead + --> tests/ui/instrument/err_on_async_trait.rs:11:1 + | +11 | #[async_trait] + | ^^^^^^^^^^^^^^ + | + = note: this error originates in the attribute macro `async_trait` (in Nightly builds, run with -Z macro-backtrace for more info) + +error[E0046]: not all trait items implemented, missing: `call` + --> tests/ui/instrument/err_on_async_trait.rs:12:1 + | + 6 | async fn call(&self) -> Result<(), String>; + | ------------------------------------------- `call` from trait +... +12 | impl Service for Impl { + | ^^^^^^^^^^^^^^^^^^^^^ missing `call` in implementation diff --git a/crates/tracing/tests/ui/instrument/err_requires_result.rs b/crates/tracing/tests/ui/instrument/err_requires_result.rs new file mode 100644 index 0000000000..0cf6ae3a55 --- /dev/null +++ b/crates/tracing/tests/ui/instrument/err_requires_result.rs @@ -0,0 +1,6 @@ +use miden_node_tracing::instrument; + +#[instrument(rpc: err)] +fn foo() {} + +fn main() {} diff --git a/crates/tracing/tests/ui/instrument/err_requires_result.stderr b/crates/tracing/tests/ui/instrument/err_requires_result.stderr new file mode 100644 index 0000000000..1a2161d751 --- /dev/null +++ b/crates/tracing/tests/ui/instrument/err_requires_result.stderr @@ -0,0 +1,5 @@ +error: `err` / `report` requires the function to return `Result` + --> tests/ui/instrument/err_requires_result.rs:4:4 + | +4 | fn foo() {} + | ^^^ diff --git a/crates/tracing/tests/ui/instrument/field_not_in_allowlist.rs b/crates/tracing/tests/ui/instrument/field_not_in_allowlist.rs new file mode 100644 index 0000000000..2558eac5de --- /dev/null +++ b/crates/tracing/tests/ui/instrument/field_not_in_allowlist.rs @@ -0,0 +1,6 @@ +use miden_node_tracing::instrument; + +#[instrument(rpc: foo = bar)] +fn foo() {} + +fn main() {} diff --git a/crates/tracing/tests/ui/instrument/field_not_in_allowlist.stderr b/crates/tracing/tests/ui/instrument/field_not_in_allowlist.stderr new file mode 100644 index 0000000000..d4d1a57a3a --- /dev/null +++ b/crates/tracing/tests/ui/instrument/field_not_in_allowlist.stderr @@ -0,0 +1,5 @@ +error: `foo` is not in the OpenTelemetry allowlist + --> tests/ui/instrument/field_not_in_allowlist.rs:3:19 + | +3 | #[instrument(rpc: foo = bar)] + | ^^^ diff --git a/crates/tracing/tests/ui/instrument/report_and_err_exclusive.rs b/crates/tracing/tests/ui/instrument/report_and_err_exclusive.rs new file mode 100644 index 0000000000..2a21f9593e --- /dev/null +++ b/crates/tracing/tests/ui/instrument/report_and_err_exclusive.rs @@ -0,0 +1,8 @@ +use miden_node_tracing::instrument; + +#[instrument(rpc: report, err)] +fn foo() -> Result<(), String> { + Ok(()) +} + +fn main() {} diff --git a/crates/tracing/tests/ui/instrument/report_and_err_exclusive.stderr b/crates/tracing/tests/ui/instrument/report_and_err_exclusive.stderr new file mode 100644 index 0000000000..d1562835f8 --- /dev/null +++ b/crates/tracing/tests/ui/instrument/report_and_err_exclusive.stderr @@ -0,0 +1,7 @@ +error: `err` and `report` are mutually exclusive – use one or the other + --> tests/ui/instrument/report_and_err_exclusive.rs:3:1 + | +3 | #[instrument(rpc: report, err)] + | ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ + | + = note: this error originates in the attribute macro `instrument` (in Nightly builds, run with -Z macro-backtrace for more info) diff --git a/crates/tracing/tests/ui/instrument/report_on_async_trait.rs b/crates/tracing/tests/ui/instrument/report_on_async_trait.rs new file mode 100644 index 0000000000..e591b004fd --- /dev/null +++ b/crates/tracing/tests/ui/instrument/report_on_async_trait.rs @@ -0,0 +1,19 @@ +use async_trait::async_trait; +use miden_node_tracing::instrument; + +#[async_trait] +trait Service { + async fn call(&self) -> Result<(), String>; +} + +struct Impl; + +#[async_trait] +impl Service for Impl { + #[instrument(rpc: report)] + async fn call(&self) -> Result<(), String> { + Ok(()) + } +} + +fn main() {} diff --git a/crates/tracing/tests/ui/instrument/report_on_async_trait.stderr b/crates/tracing/tests/ui/instrument/report_on_async_trait.stderr new file mode 100644 index 0000000000..c340206612 --- /dev/null +++ b/crates/tracing/tests/ui/instrument/report_on_async_trait.stderr @@ -0,0 +1,16 @@ +error: `err` / `report` is not supported on `Box` return types; use `async fn` instead + --> tests/ui/instrument/report_on_async_trait.rs:11:1 + | +11 | #[async_trait] + | ^^^^^^^^^^^^^^ + | + = note: this error originates in the attribute macro `async_trait` (in Nightly builds, run with -Z macro-backtrace for more info) + +error[E0046]: not all trait items implemented, missing: `call` + --> tests/ui/instrument/report_on_async_trait.rs:12:1 + | + 6 | async fn call(&self) -> Result<(), String>; + | ------------------------------------------- `call` from trait +... +12 | impl Service for Impl { + | ^^^^^^^^^^^^^^^^^^^^^ missing `call` in implementation diff --git a/crates/tracing/tests/ui/instrument/report_on_impl_future.rs b/crates/tracing/tests/ui/instrument/report_on_impl_future.rs new file mode 100644 index 0000000000..3dc5886254 --- /dev/null +++ b/crates/tracing/tests/ui/instrument/report_on_impl_future.rs @@ -0,0 +1,8 @@ +use miden_node_tracing::instrument; + +#[instrument(rpc: report)] +fn foo() -> impl std::future::Future> { + async { Ok(()) } +} + +fn main() {} diff --git a/crates/tracing/tests/ui/instrument/report_on_impl_future.stderr b/crates/tracing/tests/ui/instrument/report_on_impl_future.stderr new file mode 100644 index 0000000000..3defb713f8 --- /dev/null +++ b/crates/tracing/tests/ui/instrument/report_on_impl_future.stderr @@ -0,0 +1,5 @@ +error: `err` / `report` is not supported on `impl Future` return types; use `async fn` instead + --> tests/ui/instrument/report_on_impl_future.rs:4:13 + | +4 | fn foo() -> impl std::future::Future> { + | ^^^^ diff --git a/crates/tracing/tests/ui/instrument/report_on_pin_box_future.rs b/crates/tracing/tests/ui/instrument/report_on_pin_box_future.rs new file mode 100644 index 0000000000..6f29f2bf4d --- /dev/null +++ b/crates/tracing/tests/ui/instrument/report_on_pin_box_future.rs @@ -0,0 +1,8 @@ +use miden_node_tracing::instrument; + +#[instrument(rpc: report)] +fn foo() -> std::pin::Pin>>> { + Box::pin(async { Ok(()) }) +} + +fn main() {} diff --git a/crates/tracing/tests/ui/instrument/report_on_pin_box_future.stderr b/crates/tracing/tests/ui/instrument/report_on_pin_box_future.stderr new file mode 100644 index 0000000000..6f02ceac01 --- /dev/null +++ b/crates/tracing/tests/ui/instrument/report_on_pin_box_future.stderr @@ -0,0 +1,5 @@ +error: `err` / `report` is not supported on `Box` return types; use `async fn` instead + --> tests/ui/instrument/report_on_pin_box_future.rs:4:13 + | +4 | fn foo() -> std::pin::Pin>>> { + | ^^^ diff --git a/crates/tracing/tests/ui/instrument/report_requires_result.rs b/crates/tracing/tests/ui/instrument/report_requires_result.rs new file mode 100644 index 0000000000..c8d82a72f9 --- /dev/null +++ b/crates/tracing/tests/ui/instrument/report_requires_result.rs @@ -0,0 +1,6 @@ +use miden_node_tracing::instrument; + +#[instrument(rpc: report)] +fn foo() {} + +fn main() {} diff --git a/crates/tracing/tests/ui/instrument/report_requires_result.stderr b/crates/tracing/tests/ui/instrument/report_requires_result.stderr new file mode 100644 index 0000000000..d6ae4e6891 --- /dev/null +++ b/crates/tracing/tests/ui/instrument/report_requires_result.stderr @@ -0,0 +1,5 @@ +error: `err` / `report` requires the function to return `Result` + --> tests/ui/instrument/report_requires_result.rs:4:4 + | +4 | fn foo() {} + | ^^^ diff --git a/crates/tracing/tests/ui/instrument/ret_report_requires_result.rs b/crates/tracing/tests/ui/instrument/ret_report_requires_result.rs new file mode 100644 index 0000000000..9301d8d6f2 --- /dev/null +++ b/crates/tracing/tests/ui/instrument/ret_report_requires_result.rs @@ -0,0 +1,6 @@ +use miden_node_tracing::instrument; + +#[instrument(rpc: ret, report)] +fn foo() {} + +fn main() {} diff --git a/crates/tracing/tests/ui/instrument/ret_report_requires_result.stderr b/crates/tracing/tests/ui/instrument/ret_report_requires_result.stderr new file mode 100644 index 0000000000..98cc58cd5f --- /dev/null +++ b/crates/tracing/tests/ui/instrument/ret_report_requires_result.stderr @@ -0,0 +1,5 @@ +error: `err` / `report` requires the function to return `Result` + --> tests/ui/instrument/ret_report_requires_result.rs:4:4 + | +4 | fn foo() {} + | ^^^ diff --git a/crates/tracing/tests/ui/log/component_with_unlisted_field.rs b/crates/tracing/tests/ui/log/component_with_unlisted_field.rs new file mode 100644 index 0000000000..165bcf4976 --- /dev/null +++ b/crates/tracing/tests/ui/log/component_with_unlisted_field.rs @@ -0,0 +1,5 @@ +use miden_node_tracing::warn; + +fn main() { + warn!(rpc: foo = %x, "msg"); +} diff --git a/crates/tracing/tests/ui/log/component_with_unlisted_field.stderr b/crates/tracing/tests/ui/log/component_with_unlisted_field.stderr new file mode 100644 index 0000000000..1c54259943 --- /dev/null +++ b/crates/tracing/tests/ui/log/component_with_unlisted_field.stderr @@ -0,0 +1,5 @@ +error: `foo` is not in the OpenTelemetry allowlist + --> tests/ui/log/component_with_unlisted_field.rs:4:16 + | +4 | warn!(rpc: foo = %x, "msg"); + | ^^^ diff --git a/crates/tracing/tests/ui/log/dotted_field_not_in_allowlist.rs b/crates/tracing/tests/ui/log/dotted_field_not_in_allowlist.rs new file mode 100644 index 0000000000..1299fc5c05 --- /dev/null +++ b/crates/tracing/tests/ui/log/dotted_field_not_in_allowlist.rs @@ -0,0 +1,5 @@ +use miden_node_tracing::warn; + +fn main() { + warn!(foo.bar = %x, "msg"); +} diff --git a/crates/tracing/tests/ui/log/dotted_field_not_in_allowlist.stderr b/crates/tracing/tests/ui/log/dotted_field_not_in_allowlist.stderr new file mode 100644 index 0000000000..d114d5fec1 --- /dev/null +++ b/crates/tracing/tests/ui/log/dotted_field_not_in_allowlist.stderr @@ -0,0 +1,5 @@ +error: `foo.bar` is not in the OpenTelemetry allowlist + --> tests/ui/log/dotted_field_not_in_allowlist.rs:4:11 + | +4 | warn!(foo.bar = %x, "msg"); + | ^^^ diff --git a/crates/tracing/tests/ui/log/field_not_in_allowlist.rs b/crates/tracing/tests/ui/log/field_not_in_allowlist.rs new file mode 100644 index 0000000000..da98fb86f7 --- /dev/null +++ b/crates/tracing/tests/ui/log/field_not_in_allowlist.rs @@ -0,0 +1,5 @@ +use miden_node_tracing::warn; + +fn main() { + warn!(foo = %x, "msg"); +} diff --git a/crates/tracing/tests/ui/log/field_not_in_allowlist.stderr b/crates/tracing/tests/ui/log/field_not_in_allowlist.stderr new file mode 100644 index 0000000000..0ed26af62b --- /dev/null +++ b/crates/tracing/tests/ui/log/field_not_in_allowlist.stderr @@ -0,0 +1,5 @@ +error: `foo` is not in the OpenTelemetry allowlist + --> tests/ui/log/field_not_in_allowlist.rs:4:11 + | +4 | warn!(foo = %x, "msg"); + | ^^^ diff --git a/crates/tracing/tests/ui/pass/instrument.rs b/crates/tracing/tests/ui/pass/instrument.rs new file mode 100644 index 0000000000..bb140c5e4b --- /dev/null +++ b/crates/tracing/tests/ui/pass/instrument.rs @@ -0,0 +1,55 @@ +use miden_node_tracing::instrument; + +#[derive(Debug)] +struct MyError; +impl std::fmt::Display for MyError { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + f.write_str("my error") + } +} +impl std::error::Error for MyError {} + +// bare – no args +#[instrument] +fn bare() {} + +// component only +#[instrument(rpc:)] +fn component_only() {} + +// bare component without colon – same as rpc: +#[instrument(rpc)] +fn component_no_colon() {} + +// ret on a plain fn +#[instrument(rpc: ret)] +fn with_ret() -> u32 { 42 } + +// err on a Result fn +#[instrument(store: err)] +fn with_err() -> Result<(), MyError> { Ok(()) } + +// report on a Result fn +#[instrument(rpc: report)] +fn with_report() -> Result<(), MyError> { Ok(()) } + +// ret + err on a Result fn +#[instrument(rpc: ret, err)] +fn with_ret_err() -> Result { Ok(42) } + +// ret + report on a Result fn +#[instrument(rpc: ret, report)] +fn with_ret_report() -> Result { Ok(42) } + +// string-literal component +#[instrument("block-producer": err)] +fn string_literal_component() -> Result<(), MyError> { Ok(()) } + +// async fn – report/err read the declared return type, which is Result +#[instrument(rpc: report)] +async fn async_with_report() -> Result<(), MyError> { Ok(()) } + +#[instrument(store: err)] +async fn async_with_err() -> Result<(), MyError> { Ok(()) } + +fn main() {} diff --git a/crates/tracing/tests/ui/pass/instrument_root.rs b/crates/tracing/tests/ui/pass/instrument_root.rs new file mode 100644 index 0000000000..4cdc4b9d67 --- /dev/null +++ b/crates/tracing/tests/ui/pass/instrument_root.rs @@ -0,0 +1,12 @@ +use miden_node_tracing::instrument; + +#[instrument(rpc: root)] +fn root_sync() {} + +#[instrument(rpc: root, ret)] +fn root_with_ret() -> u32 { 1 } + +fn main() { + root_sync(); + let _ = root_with_ret(); +} diff --git a/crates/tracing/tests/ui/pass/log.rs b/crates/tracing/tests/ui/pass/log.rs new file mode 100644 index 0000000000..21225b26f0 --- /dev/null +++ b/crates/tracing/tests/ui/pass/log.rs @@ -0,0 +1,67 @@ +use miden_node_tracing::{debug, error, info, trace, warn}; + +fn main() { + // ── plain message ───────────────────────────────────────────────────────── + + error!("hard failure"); + warn!("something looks off"); + info!("block applied"); + debug!("trace point"); + trace!("tick"); + + // ── format string ───────────────────────────────────────────────────────── + + error!("failed after {} retries", 3); + warn!("retrying after {}ms", 100u64); + info!("migrated {} rows", 42usize); + debug!("response size: {} bytes", 128usize); + trace!("loop iteration {}", 7u32); + + // ── component + message ─────────────────────────────────────────────────── + + error!(rpc: "connection refused"); + warn!(store: "slow query detected"); + info!(rpc: "server started"); + debug!(store: "cache miss"); + trace!(rpc: "entering handler"); + + // ── component + format string ───────────────────────────────────────────── + + error!(rpc: "rejected {} requests", 5u32); + warn!(store: "table has {} rows", 1000usize); + info!(rpc: "listening on port {}", 8080u16); + debug!(store: "query took {}ms", 12u64); + trace!(rpc: "payload {} bytes", 256usize); + + // ── string-literal component ────────────────────────────────────────────── + + warn!("block-producer": "batch timeout"); + info!("block-producer": "produced block {}", 42u32); + + // ── component + allowlisted dotted fields + message ─────────────────────── + + warn!(rpc: account.id = %1u64, "unexpected account"); + error!(store: nullifier.id = %2u64, "double spend"); + info!(rpc: block.number = 3u32, "block committed"); + debug!(store: account.id = %1u64, block.number = 3u32, "state check"); + trace!(rpc: nullifier.id = ?2u64, account.id = %1u64, "lookup"); + + // ── component + fields + format string ──────────────────────────────────── + + warn!(rpc: account.id = %1u64, "rejected after {} retries", 3u32); + info!(store: block.number = 3u32, "applied in {}ms", 12u64); + + // ── fields without component ────────────────────────────────────────────── + + warn!(account.id = %1u64, block.number = 3u32, "state inconsistency"); + error!(nullifier.id = %2u64, block.number = 3u32, "double spend at block"); + + // ── fields only, no message ─────────────────────────────────────────────── + + warn!(account.id = %1u64, block.number = 3u32); + info!(nullifier.id = %2u64); + + // ── component + fields only, no message ────────────────────────────────── + + warn!(rpc: account.id = %1u64, block.number = 3u32); +} diff --git a/crates/validator/Cargo.toml b/crates/validator/Cargo.toml index 84ed6b2484..3459571191 100644 --- a/crates/validator/Cargo.toml +++ b/crates/validator/Cargo.toml @@ -25,6 +25,7 @@ diesel_migrations = { workspace = true } miden-node-db = { workspace = true } miden-node-proto = { workspace = true } miden-node-proto-build = { features = ["internal"], workspace = true } +miden-node-tracing = { workspace = true } miden-node-utils = { features = ["testing"], workspace = true } miden-protocol = { workspace = true } miden-tx = { workspace = true } diff --git a/crates/validator/src/block_validation/mod.rs b/crates/validator/src/block_validation/mod.rs index 0a1b4052a3..e39bd367ca 100644 --- a/crates/validator/src/block_validation/mod.rs +++ b/crates/validator/src/block_validation/mod.rs @@ -1,14 +1,14 @@ use miden_node_db::{DatabaseError, Db}; +use miden_node_tracing::instrument; use miden_node_utils::tracing::OpenTelemetrySpanExt; use miden_protocol::block::{BlockHeader, BlockNumber, ProposedBlock}; use miden_protocol::crypto::dsa::ecdsa_k256_keccak::Signature; use miden_protocol::errors::ProposedBlockError; use miden_protocol::transaction::{TransactionHeader, TransactionId}; -use tracing::{Span, instrument}; +use tracing::Span; +use crate::ValidatorSigner; use crate::db::{find_unvalidated_transactions, load_block_header}; -use crate::{COMPONENT, ValidatorSigner}; - // BLOCK VALIDATION ERROR // ================================================================================================ @@ -44,7 +44,7 @@ pub enum BlockValidationError { /// tip, validated against the previous block header. /// /// On success, returns the signature and the validated block header. -#[instrument(target = COMPONENT, skip_all, err, fields(tip.number = chain_tip.block_num().as_u32()))] +#[instrument(COMPONENT: err)] pub async fn validate_block( proposed_block: ProposedBlock, signer: &ValidatorSigner, @@ -110,7 +110,7 @@ pub async fn validate_block( } /// Signs a block header using the validator's signer. -#[instrument(target = COMPONENT, name = "sign_block", skip_all, err, fields(block.number = header.block_num().as_u32()))] +#[instrument(COMPONENT: err)] async fn sign_header( signer: &ValidatorSigner, header: &BlockHeader, diff --git a/crates/validator/src/db/migrations.rs b/crates/validator/src/db/migrations.rs index 240c29033b..b09d2590e6 100644 --- a/crates/validator/src/db/migrations.rs +++ b/crates/validator/src/db/migrations.rs @@ -1,7 +1,7 @@ use diesel::SqliteConnection; use diesel_migrations::{EmbeddedMigrations, MigrationHarness, embed_migrations}; use miden_node_db::DatabaseError; -use tracing::instrument; +use miden_node_tracing::instrument; use crate::COMPONENT; @@ -9,7 +9,7 @@ use crate::COMPONENT; // . pub const MIGRATIONS: EmbeddedMigrations = embed_migrations!("src/db/migrations"); -#[instrument(level = "debug", target = COMPONENT, skip_all, err)] +#[instrument(COMPONENT: err)] pub fn apply_migrations(conn: &mut SqliteConnection) -> std::result::Result<(), DatabaseError> { let migrations = conn.pending_migrations(MIGRATIONS).expect("In memory migrations never fail"); tracing::info!(target = COMPONENT, "Applying {} migration(s)", migrations.len()); diff --git a/crates/validator/src/db/mod.rs b/crates/validator/src/db/mod.rs index 96c210f8a3..f6e9c3ed83 100644 --- a/crates/validator/src/db/mod.rs +++ b/crates/validator/src/db/mod.rs @@ -8,10 +8,10 @@ use diesel::SqliteConnection; use diesel::dsl::exists; use diesel::prelude::*; use miden_node_db::{DatabaseError, Db, SqlTypeConvert}; +use miden_node_tracing::instrument; use miden_protocol::block::{BlockHeader, BlockNumber}; use miden_protocol::transaction::TransactionId; use miden_protocol::utils::serde::{Deserializable, Serializable}; -use tracing::instrument; use crate::COMPONENT; use crate::db::migrations::apply_migrations; @@ -19,7 +19,7 @@ use crate::db::models::{BlockHeaderRowInsert, ValidatedTransactionRowInsert}; use crate::tx_validation::ValidatedTransaction; /// Open a connection to the DB and apply any pending migrations. -#[instrument(target = COMPONENT, skip_all)] +#[instrument(COMPONENT:)] pub async fn load(database_filepath: PathBuf) -> Result { let db = Db::new(&database_filepath)?; tracing::info!( @@ -33,7 +33,7 @@ pub async fn load(database_filepath: PathBuf) -> Result { } /// Inserts a new validated transaction into the database. -#[instrument(target = COMPONENT, skip_all, fields(tx_id = %tx_info.tx_id()), err)] +#[instrument(COMPONENT: err)] pub(crate) fn insert_transaction( conn: &mut SqliteConnection, tx_info: &ValidatedTransaction, @@ -59,7 +59,7 @@ pub(crate) fn insert_transaction( /// WHERE id = ? /// ); /// ``` -#[instrument(target = COMPONENT, skip(conn), err)] +#[instrument(COMPONENT: err)] pub(crate) fn find_unvalidated_transactions( conn: &mut SqliteConnection, tx_ids: &[TransactionId], @@ -84,7 +84,7 @@ pub(crate) fn find_unvalidated_transactions( /// /// Inserts a new row if no block header exists at the given block number, or replaces the /// existing block header if one already exists. -#[instrument(target = COMPONENT, skip(conn, header), err)] +#[instrument(COMPONENT: err)] pub fn upsert_block_header( conn: &mut SqliteConnection, header: &BlockHeader, @@ -100,7 +100,7 @@ pub fn upsert_block_header( /// Loads the chain tip (block header with the highest block number) from the database. /// /// Returns `None` if no block headers have been persisted (i.e. bootstrap has not been run). -#[instrument(target = COMPONENT, skip(conn), err)] +#[instrument(COMPONENT: err)] pub fn load_chain_tip(conn: &mut SqliteConnection) -> Result, DatabaseError> { let row = schema::block_headers::table .order(schema::block_headers::block_num.desc()) @@ -118,7 +118,7 @@ pub fn load_chain_tip(conn: &mut SqliteConnection) -> Result /// Loads a block header by its block number. /// /// Returns `None` if no block header exists at the given block number. -#[instrument(target = COMPONENT, skip(conn), err)] +#[instrument(COMPONENT: err)] pub fn load_block_header( conn: &mut SqliteConnection, block_num: BlockNumber, diff --git a/crates/validator/src/server/mod.rs b/crates/validator/src/server/mod.rs index 6471784792..e606c893f1 100644 --- a/crates/validator/src/server/mod.rs +++ b/crates/validator/src/server/mod.rs @@ -7,6 +7,7 @@ use miden_node_db::Db; use miden_node_proto::generated::validator::api_server; use miden_node_proto::generated::{self as proto}; use miden_node_proto_build::validator_api_descriptor; +use miden_node_tracing::instrument; use miden_node_utils::ErrorReport; use miden_node_utils::clap::GrpcOptionsInternal; use miden_node_utils::panic::catch_panic_layer_fn; @@ -21,7 +22,7 @@ use tokio_stream::wrappers::TcpListenerStream; use tonic::Status; use tower_http::catch_panic::CatchPanicLayer; use tower_http::trace::TraceLayer; -use tracing::{info_span, instrument}; +use tracing::info_span; use crate::block_validation::validate_block; use crate::db::{insert_transaction, load, load_chain_tip, upsert_block_header}; @@ -122,7 +123,7 @@ impl api_server::Api for ValidatorServer { } /// Receives a proven transaction, then validates and stores it. - #[instrument(target = COMPONENT, skip_all, err)] + #[instrument(COMPONENT:)] async fn submit_proven_transaction( &self, request: tonic::Request, diff --git a/crates/validator/src/tx_validation/mod.rs b/crates/validator/src/tx_validation/mod.rs index f2d1250a20..93c555a60f 100644 --- a/crates/validator/src/tx_validation/mod.rs +++ b/crates/validator/src/tx_validation/mod.rs @@ -2,15 +2,14 @@ mod data_store; mod validated_tx; pub use data_store::TransactionInputsDataStore; +use miden_node_tracing::instrument; use miden_protocol::MIN_PROOF_SECURITY_LEVEL; use miden_protocol::transaction::{ProvenTransaction, TransactionHeader, TransactionInputs}; use miden_tx::auth::UnreachableAuth; use miden_tx::{TransactionExecutor, TransactionExecutorError, TransactionVerifier}; -use tracing::{Instrument, info_span, instrument}; +use tracing::info_span; pub use validated_tx::ValidatedTransaction; -use crate::COMPONENT; - // TRANSACTION VALIDATION ERROR // ================================================================================================ @@ -34,7 +33,7 @@ pub enum TransactionValidationError { /// provided proven transaction. /// /// Returns the header of the executed transaction if successful. -#[instrument(target = COMPONENT, skip_all, err)] +#[instrument(COMPONENT: err)] pub async fn validate_transaction( proven_tx: ProvenTransaction, tx_inputs: TransactionInputs,