From ae2e1397279e768833a4b88a27404ef55a4740f9 Mon Sep 17 00:00:00 2001 From: Bernhard Schuster Date: Mon, 9 Mar 2026 18:48:25 +0100 Subject: [PATCH 01/12] feat: add custom tracing macro to use reports --- Cargo.lock | 24 ++ Cargo.toml | 7 +- crates/block-producer/Cargo.toml | 1 + .../block-producer/src/batch_builder/mod.rs | 21 +- crates/block-producer/src/validator/mod.rs | 5 +- crates/ntx-builder/Cargo.toml | 1 + crates/ntx-builder/src/block_producer.rs | 1 + crates/rpc/Cargo.toml | 41 +-- crates/store/Cargo.toml | 1 + crates/store/src/db/migrations.rs | 4 +- crates/tracing-macro/Cargo.toml | 23 ++ crates/tracing-macro/README.md | 16 ++ crates/tracing-macro/src/lib.rs | 260 ++++++++++++++++++ crates/tracing/Cargo.toml | 22 ++ crates/tracing/README.md | 50 ++++ crates/tracing/src/lib.rs | 38 +++ 16 files changed, 480 insertions(+), 35 deletions(-) create mode 100644 crates/tracing-macro/Cargo.toml create mode 100644 crates/tracing-macro/README.md create mode 100644 crates/tracing-macro/src/lib.rs create mode 100644 crates/tracing/Cargo.toml create mode 100644 crates/tracing/README.md create mode 100644 crates/tracing/src/lib.rs diff --git a/Cargo.lock b/Cargo.lock index 4912ac66bd..a3840e5a0d 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2945,6 +2945,7 @@ dependencies = [ "miden-node-proto-build", "miden-node-store", "miden-node-test-macro", + "miden-node-tracing", "miden-node-utils", "miden-node-validator", "miden-protocol", @@ -3003,6 +3004,7 @@ dependencies = [ "miden-node-db", "miden-node-proto", "miden-node-test-macro", + "miden-node-tracing", "miden-node-utils", "miden-protocol", "miden-remote-prover-client", @@ -3073,6 +3075,7 @@ dependencies = [ "miden-node-proto", "miden-node-proto-build", "miden-node-store", + "miden-node-tracing", "miden-node-utils", "miden-protocol", "miden-standards", @@ -3119,6 +3122,7 @@ dependencies = [ "miden-node-proto-build", "miden-node-rocksdb-cxx-linkage-fix", "miden-node-test-macro", + "miden-node-tracing", "miden-node-utils", "miden-protocol", "miden-remote-prover-client", @@ -3171,6 +3175,26 @@ dependencies = [ "syn 2.0.114", ] +[[package]] +name = "miden-node-tracing" +version = "0.14.0-alpha.1" +dependencies = [ + "miden-node-tracing-macro", + "miden-node-utils", + "opentelemetry", + "tracing", + "tracing-opentelemetry", +] + +[[package]] +name = "miden-node-tracing-macro" +version = "0.14.0-alpha.1" +dependencies = [ + "proc-macro2", + "quote", + "syn 2.0.114", +] + [[package]] name = "miden-node-utils" version = "0.14.0-alpha.1" diff --git a/Cargo.toml b/Cargo.toml index c263e4fdd3..b2f85669db 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -8,6 +8,8 @@ members = [ "crates/db", "crates/grpc-error-macro", "crates/large-smt-backend-rocksdb", + "crates/tracing", + "crates/tracing-macro", "crates/ntx-builder", "crates/proto", "crates/remote-prover-client", @@ -17,7 +19,7 @@ members = [ "crates/test-macro", "crates/utils", "crates/validator", - "proto", + "proto" ] resolver = "2" @@ -51,6 +53,7 @@ miden-node-block-producer = { path = "crates/block-producer", version = "= miden-node-db = { path = "crates/db", version = "=0.14.0-alpha.1" } miden-node-grpc-error-macro = { path = "crates/grpc-error-macro", version = "=0.14.0-alpha.1" } miden-node-ntx-builder = { path = "crates/ntx-builder", version = "=0.14.0-alpha.1" } +miden-node-tracing = { path = "crates/tracing", version = "=0.14.0-alpha.1" } miden-node-proto = { path = "crates/proto", version = "=0.14.0-alpha.1" } miden-node-proto-build = { path = "proto", version = "=0.14.0-alpha.1" } miden-node-rpc = { path = "crates/rpc", version = "=0.14.0-alpha.1" } @@ -62,6 +65,7 @@ miden-remote-prover-client = { path = "crates/remote-prover-client", versio # Temporary workaround until # is part of `rocksdb-rust` release miden-node-rocksdb-cxx-linkage-fix = { path = "crates/rocksdb-cxx-linkage-fix", version = "=0.14.0-alpha.1" } +miden-node-tracing-macro = { path = "crates/tracing-macro", version = "=0.14.0-alpha.1" } # miden-base aka protocol dependencies. These should be updated in sync. miden-block-prover = { version = "=0.14.0-alpha.1" } @@ -71,6 +75,7 @@ miden-testing = { version = "=0.14.0-alpha.1" } miden-tx = { default-features = false, version = "=0.14.0-alpha.1" } miden-tx-batch-prover = { version = "=0.14.0-alpha.1" } + # Other miden dependencies. These should align with those expected by miden-base. miden-air = { features = ["std", "testing"], version = "0.20" } diff --git a/crates/block-producer/Cargo.toml b/crates/block-producer/Cargo.toml index 6ca345217a..a5b91d293c 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..93ba9bdb33 100644 --- a/crates/block-producer/src/batch_builder/mod.rs +++ b/crates/block-producer/src/batch_builder/mod.rs @@ -14,7 +14,8 @@ use miden_tx_batch_prover::LocalBatchProver; use rand::Rng; use tokio::task::JoinSet; use tokio::time; -use tracing::{Instrument, Span, instrument}; +use miden_node_tracing::instrument_with_err_report; +use tracing::{Instrument, Span}; use url::Url; use crate::domain::batch::SelectedBatch; @@ -102,7 +103,7 @@ impl BatchBuilder { } } - #[instrument(parent = None, target = COMPONENT, name = "batch_builder.build_batch", skip_all)] + #[instrument_with_err_report(parent = None, target = COMPONENT, name = "batch_builder.build_batch", skip_all)] 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_with_err_report(target = COMPONENT, name = "batch_builder.wait_for_available_worker", skip_all)] 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_with_err_report(target = COMPONENT, name = "batch_builder.select_batch", skip_all)] 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_with_err_report(target = COMPONENT, name = "batch_builder.get_batch_inputs", skip_all, 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_with_err_report(target = COMPONENT, name = "batch_builder.propose_batch", skip_all, 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_with_err_report(target = COMPONENT, name = "batch_builder.prove_batch", skip_all, 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_with_err_report(target = COMPONENT, name = "batch_builder.inject_failure", skip_all, 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_with_err_report(target = COMPONENT, name = "batch_builder.commit_batch", skip_all)] 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_with_err_report(target = COMPONENT, name = "batch_builder.rollback_batch", skip_all)] async fn rollback_batch(&self, batch_id: BatchId) { self.mempool.lock().await.rollback_batch(batch_id); } diff --git a/crates/block-producer/src/validator/mod.rs b/crates/block-producer/src/validator/mod.rs index 9844e2d9b3..06bc670d01 100644 --- a/crates/block-producer/src/validator/mod.rs +++ b/crates/block-producer/src/validator/mod.rs @@ -4,7 +4,8 @@ use miden_protocol::block::ProposedBlock; use miden_protocol::crypto::dsa::ecdsa_k256_keccak::Signature; use miden_protocol::utils::{Deserializable, DeserializationError, Serializable}; use thiserror::Error; -use tracing::{info, instrument}; +use miden_node_tracing::instrument_with_err_report; +use tracing::info; use url::Url; use crate::COMPONENT; @@ -47,7 +48,7 @@ impl BlockProducerValidatorClient { Self { client: validator } } - #[instrument(target = COMPONENT, name = "validator.client.validate_block", skip_all, err)] + #[instrument_with_err_report(target = COMPONENT, name = "validator.client.validate_block", skip_all, 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 6110a7a6d4..8004c0c025 100644 --- a/crates/ntx-builder/Cargo.toml +++ b/crates/ntx-builder/Cargo.toml @@ -21,6 +21,7 @@ futures = { workspace = true } libsqlite3-sys = { workspace = true } miden-node-db = { workspace = true } miden-node-proto = { 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/block_producer.rs b/crates/ntx-builder/src/block_producer.rs index 53925bdcf8..9c97ab3e27 100644 --- a/crates/ntx-builder/src/block_producer.rs +++ b/crates/ntx-builder/src/block_producer.rs @@ -10,6 +10,7 @@ use miden_protocol::transaction::ProvenTransaction; use miden_tx::utils::Serializable; use tokio_stream::StreamExt; use tonic::Status; +// Use standard tracing for Status errors (which don't impl std::error::Error) use tracing::{info, instrument}; use url::Url; diff --git a/crates/rpc/Cargo.toml b/crates/rpc/Cargo.toml index 537173e67d..398dbdf3ed 100644 --- a/crates/rpc/Cargo.toml +++ b/crates/rpc/Cargo.toml @@ -15,26 +15,27 @@ version.workspace = true workspace = true [dependencies] -anyhow = { workspace = true } -futures = { version = "0.3" } -http = { workspace = true } -mediatype = { version = "0.21" } -miden-node-proto = { workspace = true } -miden-node-proto-build = { workspace = true } -miden-node-utils = { workspace = true } -miden-protocol = { default-features = true, workspace = true } -miden-tx = { default-features = true, workspace = true } -semver = { version = "1.0" } -thiserror = { workspace = true } -tokio = { features = ["macros", "net", "rt-multi-thread"], workspace = true } -tokio-stream = { features = ["net"], workspace = true } -tonic = { default-features = true, features = ["tls-native-roots", "tls-ring"], workspace = true } -tonic-reflection = { workspace = true } -tonic-web = { version = "0.14" } -tower = { workspace = true } -tower-http = { features = ["trace"], workspace = true } -tracing = { workspace = true } -url = { workspace = true } +anyhow = { workspace = true } +futures = { version = "0.3" } +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 } +semver = { version = "1.0" } +thiserror = { workspace = true } +tokio = { features = ["macros", "net", "rt-multi-thread"], workspace = true } +tokio-stream = { features = ["net"], workspace = true } +tonic = { default-features = true, features = ["tls-native-roots", "tls-ring"], workspace = true } +tonic-reflection = { workspace = true } +tonic-web = { version = "0.14" } +tower = { workspace = true } +tower-http = { features = ["trace"], workspace = true } +tracing = { workspace = true } +url = { workspace = true } [dev-dependencies] miden-air = { features = ["testing"], workspace = true } diff --git a/crates/store/Cargo.toml b/crates/store/Cargo.toml index d0642a8193..082b9e42db 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/db/migrations.rs b/crates/store/src/db/migrations.rs index 10ce01409e..fcb33026f0 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_with_err_report; 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_with_err_report(level = "debug", target = COMPONENT, skip_all, err)] pub fn apply_migrations( conn: &mut SqliteConnection, ) -> std::result::Result<(), miden_node_db::DatabaseError> { diff --git a/crates/tracing-macro/Cargo.toml b/crates/tracing-macro/Cargo.toml new file mode 100644 index 0000000000..8fda35ba83 --- /dev/null +++ b/crates/tracing-macro/Cargo.toml @@ -0,0 +1,23 @@ +[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] +proc-macro2 = "1.0" +quote = "1.0" +syn = { features = ["full", "extra-traits", "parsing"], version = "2.0" } diff --git a/crates/tracing-macro/README.md b/crates/tracing-macro/README.md new file mode 100644 index 0000000000..84f06e6f4d --- /dev/null +++ b/crates/tracing-macro/README.md @@ -0,0 +1,16 @@ +# Miden Node Tracing Macro + +Internal procedural macro crate for `miden-node-tracing`. + +**Do not use this crate directly.** Use `miden-node-tracing` instead, which re-exports this macro along with all required dependencies. + +## Usage + +```rust +use miden_node_tracing::instrument_with_err_report; + +#[instrument_with_err_report(target = COMPONENT, skip_all, err)] +pub async fn apply_block(&self, block: ProvenBlock) -> Result<(), ApplyBlockError> { + // Function body... +} +``` diff --git a/crates/tracing-macro/src/lib.rs b/crates/tracing-macro/src/lib.rs new file mode 100644 index 0000000000..1a949e6644 --- /dev/null +++ b/crates/tracing-macro/src/lib.rs @@ -0,0 +1,260 @@ +//! Procedural macro for tracing instrumentation with full error report context. +//! +//! This macro provides an `#[instrument]`-like attribute that uses `ErrorReport::as_report()` +//! to capture the full error chain in tracing spans, rather than just the `Display` output. +//! +//! **Note**: This crate should not be used directly. Use `miden-node-tracing` instead, +//! which re-exports this macro along with all required dependencies. +//! +//! # Problem +//! +//! The standard `#[instrument(err)]` from `tracing` uses `Display` or `Debug` to format errors +//! in span events. This loses the error chain context, showing only the top-level error message. +//! +//! # Solution +//! +//! This macro wraps functions that return `Result` and: +//! 1. Creates a tracing span with the configured attributes (delegating to `tracing::instrument`) +//! 2. On error, records the full error chain using `ErrorReport::as_report()` +//! 3. Sets the OpenTelemetry span status to error with the full report + +use proc_macro::TokenStream; +use proc_macro2::TokenStream as TokenStream2; +use quote::quote; +use syn::{ItemFn, ReturnType, parse_macro_input}; + +/// Instruments a function with tracing, using full error reports for context. +/// +/// This attribute macro wraps functions that return `Result` and creates +/// a tracing span. When the function returns an error, it records the full +/// error chain using `ErrorReport::as_report()` instead of just `Display`. +/// +/// This macro accepts all the same arguments as `tracing::instrument`, and +/// delegates to it for span creation. The added functionality is enhanced +/// error reporting when `err` is specified. +/// +/// # Arguments +/// +/// All arguments from `tracing::instrument` are supported: +/// - `target = "..."` - Sets the tracing target +/// - `level = "..."` - Sets the tracing level (default: "info") +/// - `name = "..."` - Sets a custom span name (default: function name) +/// - `err` - Record errors with full error chain (enhanced by this macro) +/// - `ret` / `ret(level = "...")` - Record return values +/// - `skip(arg1, arg2)` - Skip specific arguments from span fields +/// - `skip_all` - Skip all arguments from span fields +/// - `fields(key = value, ...)` - Add custom fields to the span +/// - `parent = None` - Create a root span (no parent) +/// +/// # Example +/// +/// ```rust,ignore +/// use miden_node_tracing::instrument_with_err_report; +/// +/// #[instrument_with_err_report(target = COMPONENT, skip_all, err)] +/// pub async fn apply_block(&self, block: ProvenBlock) -> Result<(), ApplyBlockError> { +/// // Function body... +/// } +/// ``` +#[proc_macro_attribute] +pub fn instrument_with_err_report(attr: TokenStream, item: TokenStream) -> TokenStream { + let attr2 = TokenStream2::from(attr.clone()); + let input = parse_macro_input!(item as ItemFn); + + // Check if 'err' is present in the attributes + let attr_str = attr2.to_string(); + let has_err = attr_str.contains("err"); + + // Check if the function returns a Result + let returns_result = match &input.sig.output { + ReturnType::Default => false, + ReturnType::Type(_, ty) => { + let ty_str = quote! { #ty }.to_string(); + ty_str.contains("Result") + } + }; + + if has_err && returns_result { + generate_with_error_reporting(attr2, input).into() + } else { + // Just delegate to standard tracing::instrument + let ItemFn { attrs, vis, sig, block } = input; + quote! { + #(#attrs)* + #[::tracing::instrument(#attr2)] + #vis #sig + #block + }.into() + } +} + +fn generate_with_error_reporting(attr: TokenStream2, input: ItemFn) -> TokenStream2 { + let ItemFn { attrs, vis, sig, block } = input; + + // Remove 'err' from the attributes we pass to tracing::instrument + // since we handle error reporting ourselves + let tracing_attr = remove_err_from_attr(&attr); + + // Get the return type for type annotation + let result_type = match &sig.output { + ReturnType::Type(_, ty) => quote! { #ty }, + ReturnType::Default => quote! { () }, + }; + + // Use absolute paths via the miden_node_tracing crate + quote! { + #(#attrs)* + #[::tracing::instrument(#tracing_attr)] + #vis #sig + { + let __result: #result_type = #block; + + if let ::core::result::Result::Err(ref __err) = __result { + // Use ErrorReport to get the full error chain + let __report = { + use ::miden_node_tracing::ErrorReport as _; + __err.as_report() + }; + + // Record the error event with the full report + ::miden_node_tracing::error!( + error.report = %__report, + "operation failed" + ); + + // Set OpenTelemetry span status if available + { + use ::miden_node_tracing::OpenTelemetrySpanExt as _; + ::miden_node_tracing::Span::current().set_error(__err as &dyn ::std::error::Error); + } + } + + __result + } + } +} + +fn remove_err_from_attr(attr: &TokenStream2) -> TokenStream2 { + // Simple string-based removal of 'err' from the attribute + // This handles both 'err' and 'err,' patterns + let attr_str = attr.to_string(); + + // Remove 'err,' or ', err' or 'err' patterns + let cleaned = attr_str + .replace(", err,", ",") + .replace(", err", "") + .replace("err,", "") + .replace("err", ""); + + // Parse the cleaned string back into tokens + cleaned.parse().unwrap_or_else(|_| attr.clone()) +} + +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn test_remove_err_from_attr_trailing() { + let attr: TokenStream2 = "target = COMPONENT, skip_all, err".parse().unwrap(); + let result = remove_err_from_attr(&attr); + let result_str = result.to_string(); + assert!(!result_str.contains("err"), "Should remove 'err': {result_str}"); + assert!(result_str.contains("target"), "Should keep 'target': {result_str}"); + assert!(result_str.contains("skip_all"), "Should keep 'skip_all': {result_str}"); + } + + #[test] + fn test_remove_err_from_attr_middle() { + let attr: TokenStream2 = "target = COMPONENT, err, skip_all".parse().unwrap(); + let result = remove_err_from_attr(&attr); + let result_str = result.to_string(); + assert!(!result_str.contains("err"), "Should remove 'err': {result_str}"); + assert!(result_str.contains("target"), "Should keep 'target': {result_str}"); + assert!(result_str.contains("skip_all"), "Should keep 'skip_all': {result_str}"); + } + + #[test] + fn test_remove_err_from_attr_only() { + let attr: TokenStream2 = "err".parse().unwrap(); + let result = remove_err_from_attr(&attr); + let result_str = result.to_string(); + assert!(!result_str.contains("err"), "Should remove 'err': {result_str}"); + } + + #[test] + fn test_remove_err_from_attr_with_ret() { + let attr: TokenStream2 = "level = \"debug\", target = COMPONENT, err, ret(level = \"debug\")".parse().unwrap(); + let result = remove_err_from_attr(&attr); + let result_str = result.to_string(); + assert!(!result_str.contains(", err,"), "Should remove ', err,': {result_str}"); + assert!(result_str.contains("level"), "Should keep 'level': {result_str}"); + assert!(result_str.contains("ret"), "Should keep 'ret': {result_str}"); + } + + #[test] + fn test_returns_result_detection() { + // Test with Result type + let fn_with_result: syn::ItemFn = syn::parse_quote! { + fn test_fn() -> Result<(), Error> { + Ok(()) + } + }; + let returns_result = match &fn_with_result.sig.output { + ReturnType::Default => false, + ReturnType::Type(_, ty) => { + let ty_str = quote! { #ty }.to_string(); + ty_str.contains("Result") + } + }; + assert!(returns_result, "Should detect Result return type"); + + // Test without Result type + let fn_without_result: syn::ItemFn = syn::parse_quote! { + fn test_fn() -> i32 { + 42 + } + }; + let returns_result = match &fn_without_result.sig.output { + ReturnType::Default => false, + ReturnType::Type(_, ty) => { + let ty_str = quote! { #ty }.to_string(); + ty_str.contains("Result") + } + }; + assert!(!returns_result, "Should not detect Result for i32 return type"); + + // Test with no return type + let fn_no_return: syn::ItemFn = syn::parse_quote! { + fn test_fn() { + println!("hello"); + } + }; + let returns_result = match &fn_no_return.sig.output { + ReturnType::Default => false, + ReturnType::Type(_, ty) => { + let ty_str = quote! { #ty }.to_string(); + ty_str.contains("Result") + } + }; + assert!(!returns_result, "Should not detect Result for unit return type"); + } + + #[test] + fn test_err_detection_in_attrs() { + // Test with err present + let attr_with_err = "target = COMPONENT, skip_all, err"; + assert!(attr_with_err.contains("err"), "Should find 'err'"); + + // Test without err + let attr_without_err = "target = COMPONENT, skip_all"; + assert!(!attr_without_err.contains("err"), "Should not find 'err'"); + + // Test with err in field name (should still match, but that's acceptable) + let attr_with_error_field = "target = COMPONENT, fields(error = true)"; + // Note: This is a known limitation - "error" contains "err" + // In practice this doesn't cause issues because if someone uses fields(error=...) + // they likely don't intend to use our error reporting anyway + assert!(attr_with_error_field.contains("err"), "Contains 'err' substring"); + } +} diff --git a/crates/tracing/Cargo.toml b/crates/tracing/Cargo.toml new file mode 100644 index 0000000000..13d2880de0 --- /dev/null +++ b/crates/tracing/Cargo.toml @@ -0,0 +1,22 @@ +[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 } +tracing = { workspace = true } +tracing-opentelemetry = { version = "0.32" } +opentelemetry = { version = "0.31" } diff --git a/crates/tracing/README.md b/crates/tracing/README.md new file mode 100644 index 0000000000..530045b320 --- /dev/null +++ b/crates/tracing/README.md @@ -0,0 +1,50 @@ +# Miden Node Tracing + +Tracing utilities for Miden node with enhanced error reporting. + +## Overview + +This crate provides an `#[instrument_with_err_report]` attribute macro that enhances the standard `tracing::instrument` with full error chain reporting. When a function returns an error, instead of just logging the top-level error message, it captures and logs the entire error chain. + +## Usage + +```rust +use miden_node_tracing::instrument_with_err_report; + +#[instrument_with_err_report(target = "my_component", skip_all, err)] +pub async fn apply_block(&self, block: ProvenBlock) -> Result<(), ApplyBlockError> { + // Function body... +} +``` + +## Enhanced Error Reporting + +When an error occurs, the full error chain is recorded: + +```text +ERROR apply_block: error.report = "failed to apply block +caused by: database error +caused by: SQLite error: table 'blocks' has 10 columns but 9 values were supplied" +``` + +This is much more useful for debugging than just seeing "failed to apply block". + +## Supported Arguments + +All arguments from `tracing::instrument` are supported: + +| Argument | Example | Description | +|----------|---------|-------------| +| `target` | `target = "my_component"` | Sets the tracing target | +| `level` | `level = "debug"` | Sets the tracing level | +| `name` | `name = "custom.span.name"` | Sets a custom span name | +| `err` | `err` | Record errors with full error chain | +| `ret` | `ret` or `ret(level = "debug")` | Record return values | +| `skip` | `skip(arg1, arg2)` | Skip specific arguments | +| `skip_all` | `skip_all` | Skip all arguments | +| `fields` | `fields(key = value)` | Add custom fields | +| `parent` | `parent = None` | Create a root span | + +## Requirements + +The enhanced error reporting requires the error type to implement `std::error::Error`. For error types that don't (like `tonic::Status` or `anyhow::Error`), use the standard `tracing::instrument` instead. diff --git a/crates/tracing/src/lib.rs b/crates/tracing/src/lib.rs new file mode 100644 index 0000000000..e472655d44 --- /dev/null +++ b/crates/tracing/src/lib.rs @@ -0,0 +1,38 @@ +//! Tracing utilities for Miden node with enhanced error reporting. +//! +//! This crate provides an `#[instrument_with_err_report]` attribute macro that enhances +//! the standard `tracing::instrument` with full error chain reporting. +//! +//! # Usage +//! +//! ```rust,ignore +//! use miden_node_tracing::instrument_with_err_report; +//! +//! #[instrument_with_err_report(target = "my_component", skip_all, err)] +//! async fn apply_block(&self, block: Block) -> Result<(), ApplyBlockError> { +//! // ... +//! } +//! ``` +//! +//! When an error occurs, the full error chain is recorded: +//! ```text +//! failed to apply block to store +//! caused by: database error +//! caused by: SQLite error: table 'blocks' has 10 columns but 9 values were supplied +//! ``` + +// Re-export the instrument macro +pub use miden_node_tracing_macro::instrument_with_err_report; + +// Re-export ErrorReport from miden-node-utils +pub use miden_node_utils::ErrorReport; + +// Re-export tracing types needed by the macro +pub use tracing::{Span, Level, Instrument, event, error}; +pub use tracing::field::Empty as FieldEmpty; + +// Re-export OpenTelemetry types needed by the macro +pub use opentelemetry::trace::Status as OtelStatus; + +// Re-export OpenTelemetrySpanExt from miden-node-utils +pub use miden_node_utils::tracing::OpenTelemetrySpanExt; From c88892f1ede0e5f7b9ac770c0bf273822b3a503b Mon Sep 17 00:00:00 2001 From: Bernhard Schuster Date: Mon, 9 Mar 2026 18:49:01 +0100 Subject: [PATCH 02/12] tracing --- crates/tracing-macro/src/lib.rs | 45 +++++++++++++++++---------------- crates/tracing/README.md | 4 +-- crates/tracing/src/lib.rs | 14 ++++------ 3 files changed, 30 insertions(+), 33 deletions(-) diff --git a/crates/tracing-macro/src/lib.rs b/crates/tracing-macro/src/lib.rs index 1a949e6644..6a329269ea 100644 --- a/crates/tracing-macro/src/lib.rs +++ b/crates/tracing-macro/src/lib.rs @@ -60,20 +60,20 @@ use syn::{ItemFn, ReturnType, parse_macro_input}; pub fn instrument_with_err_report(attr: TokenStream, item: TokenStream) -> TokenStream { let attr2 = TokenStream2::from(attr.clone()); let input = parse_macro_input!(item as ItemFn); - + // Check if 'err' is present in the attributes let attr_str = attr2.to_string(); let has_err = attr_str.contains("err"); - + // Check if the function returns a Result let returns_result = match &input.sig.output { ReturnType::Default => false, ReturnType::Type(_, ty) => { let ty_str = quote! { #ty }.to_string(); ty_str.contains("Result") - } + }, }; - + if has_err && returns_result { generate_with_error_reporting(attr2, input).into() } else { @@ -84,23 +84,24 @@ pub fn instrument_with_err_report(attr: TokenStream, item: TokenStream) -> Token #[::tracing::instrument(#attr2)] #vis #sig #block - }.into() + } + .into() } } fn generate_with_error_reporting(attr: TokenStream2, input: ItemFn) -> TokenStream2 { let ItemFn { attrs, vis, sig, block } = input; - + // Remove 'err' from the attributes we pass to tracing::instrument // since we handle error reporting ourselves let tracing_attr = remove_err_from_attr(&attr); - + // Get the return type for type annotation let result_type = match &sig.output { ReturnType::Type(_, ty) => quote! { #ty }, ReturnType::Default => quote! { () }, }; - + // Use absolute paths via the miden_node_tracing crate quote! { #(#attrs)* @@ -108,27 +109,24 @@ fn generate_with_error_reporting(attr: TokenStream2, input: ItemFn) -> TokenStre #vis #sig { let __result: #result_type = #block; - + if let ::core::result::Result::Err(ref __err) = __result { // Use ErrorReport to get the full error chain let __report = { use ::miden_node_tracing::ErrorReport as _; __err.as_report() }; - + // Record the error event with the full report - ::miden_node_tracing::error!( - error.report = %__report, - "operation failed" - ); - + ::miden_node_tracing::error!(error = %__report); + // Set OpenTelemetry span status if available { use ::miden_node_tracing::OpenTelemetrySpanExt as _; ::miden_node_tracing::Span::current().set_error(__err as &dyn ::std::error::Error); } } - + __result } } @@ -138,14 +136,14 @@ fn remove_err_from_attr(attr: &TokenStream2) -> TokenStream2 { // Simple string-based removal of 'err' from the attribute // This handles both 'err' and 'err,' patterns let attr_str = attr.to_string(); - + // Remove 'err,' or ', err' or 'err' patterns let cleaned = attr_str .replace(", err,", ",") .replace(", err", "") .replace("err,", "") .replace("err", ""); - + // Parse the cleaned string back into tokens cleaned.parse().unwrap_or_else(|_| attr.clone()) } @@ -184,7 +182,10 @@ mod tests { #[test] fn test_remove_err_from_attr_with_ret() { - let attr: TokenStream2 = "level = \"debug\", target = COMPONENT, err, ret(level = \"debug\")".parse().unwrap(); + let attr: TokenStream2 = + "level = \"debug\", target = COMPONENT, err, ret(level = \"debug\")" + .parse() + .unwrap(); let result = remove_err_from_attr(&attr); let result_str = result.to_string(); assert!(!result_str.contains(", err,"), "Should remove ', err,': {result_str}"); @@ -205,7 +206,7 @@ mod tests { ReturnType::Type(_, ty) => { let ty_str = quote! { #ty }.to_string(); ty_str.contains("Result") - } + }, }; assert!(returns_result, "Should detect Result return type"); @@ -220,7 +221,7 @@ mod tests { ReturnType::Type(_, ty) => { let ty_str = quote! { #ty }.to_string(); ty_str.contains("Result") - } + }, }; assert!(!returns_result, "Should not detect Result for i32 return type"); @@ -235,7 +236,7 @@ mod tests { ReturnType::Type(_, ty) => { let ty_str = quote! { #ty }.to_string(); ty_str.contains("Result") - } + }, }; assert!(!returns_result, "Should not detect Result for unit return type"); } diff --git a/crates/tracing/README.md b/crates/tracing/README.md index 530045b320..dc0c39b936 100644 --- a/crates/tracing/README.md +++ b/crates/tracing/README.md @@ -19,10 +19,10 @@ pub async fn apply_block(&self, block: ProvenBlock) -> Result<(), ApplyBlockErro ## Enhanced Error Reporting -When an error occurs, the full error chain is recorded: +When an error occurs, the full error chain is recorded (matching `tracing::instrument` style): ```text -ERROR apply_block: error.report = "failed to apply block +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" ``` diff --git a/crates/tracing/src/lib.rs b/crates/tracing/src/lib.rs index e472655d44..a49b45e01f 100644 --- a/crates/tracing/src/lib.rs +++ b/crates/tracing/src/lib.rs @@ -23,16 +23,12 @@ // Re-export the instrument macro pub use miden_node_tracing_macro::instrument_with_err_report; - // Re-export ErrorReport from miden-node-utils pub use miden_node_utils::ErrorReport; - -// Re-export tracing types needed by the macro -pub use tracing::{Span, Level, Instrument, event, error}; -pub use tracing::field::Empty as FieldEmpty; - -// Re-export OpenTelemetry types needed by the macro -pub use opentelemetry::trace::Status as OtelStatus; - // Re-export OpenTelemetrySpanExt from miden-node-utils pub use miden_node_utils::tracing::OpenTelemetrySpanExt; +// Re-export OpenTelemetry types needed by the macro +pub use opentelemetry::trace::Status as OtelStatus; +pub use tracing::field::Empty as FieldEmpty; +// Re-export tracing types needed by the macro +pub use tracing::{Instrument, Level, Span, error, event}; From 21ef73994c7a954b13c98021b7b1ea65412f1a95 Mon Sep 17 00:00:00 2001 From: Bernhard Schuster Date: Tue, 13 Jan 2026 13:47:33 +0100 Subject: [PATCH 03/12] tracing macro --- Cargo.lock | 2 -- crates/rpc/Cargo.toml | 41 ++++++++++++++++----------------- crates/tracing-macro/Cargo.toml | 2 +- crates/tracing-macro/src/lib.rs | 6 ++--- crates/tracing/Cargo.toml | 3 +-- 5 files changed, 25 insertions(+), 29 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index a3840e5a0d..fa89f8116f 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -3075,7 +3075,6 @@ dependencies = [ "miden-node-proto", "miden-node-proto-build", "miden-node-store", - "miden-node-tracing", "miden-node-utils", "miden-protocol", "miden-standards", @@ -3183,7 +3182,6 @@ dependencies = [ "miden-node-utils", "opentelemetry", "tracing", - "tracing-opentelemetry", ] [[package]] diff --git a/crates/rpc/Cargo.toml b/crates/rpc/Cargo.toml index 398dbdf3ed..537173e67d 100644 --- a/crates/rpc/Cargo.toml +++ b/crates/rpc/Cargo.toml @@ -15,27 +15,26 @@ version.workspace = true workspace = true [dependencies] -anyhow = { workspace = true } -futures = { version = "0.3" } -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 } -semver = { version = "1.0" } -thiserror = { workspace = true } -tokio = { features = ["macros", "net", "rt-multi-thread"], workspace = true } -tokio-stream = { features = ["net"], workspace = true } -tonic = { default-features = true, features = ["tls-native-roots", "tls-ring"], workspace = true } -tonic-reflection = { workspace = true } -tonic-web = { version = "0.14" } -tower = { workspace = true } -tower-http = { features = ["trace"], workspace = true } -tracing = { workspace = true } -url = { workspace = true } +anyhow = { workspace = true } +futures = { version = "0.3" } +http = { workspace = true } +mediatype = { version = "0.21" } +miden-node-proto = { workspace = true } +miden-node-proto-build = { workspace = true } +miden-node-utils = { workspace = true } +miden-protocol = { default-features = true, workspace = true } +miden-tx = { default-features = true, workspace = true } +semver = { version = "1.0" } +thiserror = { workspace = true } +tokio = { features = ["macros", "net", "rt-multi-thread"], workspace = true } +tokio-stream = { features = ["net"], workspace = true } +tonic = { default-features = true, features = ["tls-native-roots", "tls-ring"], workspace = true } +tonic-reflection = { workspace = true } +tonic-web = { version = "0.14" } +tower = { workspace = true } +tower-http = { features = ["trace"], workspace = true } +tracing = { workspace = true } +url = { workspace = true } [dev-dependencies] miden-air = { features = ["testing"], workspace = true } diff --git a/crates/tracing-macro/Cargo.toml b/crates/tracing-macro/Cargo.toml index 8fda35ba83..950f77663d 100644 --- a/crates/tracing-macro/Cargo.toml +++ b/crates/tracing-macro/Cargo.toml @@ -20,4 +20,4 @@ proc-macro = true [dependencies] proc-macro2 = "1.0" quote = "1.0" -syn = { features = ["full", "extra-traits", "parsing"], version = "2.0" } +syn = { features = ["extra-traits", "full", "parsing"], version = "2.0" } diff --git a/crates/tracing-macro/src/lib.rs b/crates/tracing-macro/src/lib.rs index 6a329269ea..f0f08259c9 100644 --- a/crates/tracing-macro/src/lib.rs +++ b/crates/tracing-macro/src/lib.rs @@ -75,7 +75,7 @@ pub fn instrument_with_err_report(attr: TokenStream, item: TokenStream) -> Token }; if has_err && returns_result { - generate_with_error_reporting(attr2, input).into() + generate_with_error_reporting(&attr2, input).into() } else { // Just delegate to standard tracing::instrument let ItemFn { attrs, vis, sig, block } = input; @@ -89,12 +89,12 @@ pub fn instrument_with_err_report(attr: TokenStream, item: TokenStream) -> Token } } -fn generate_with_error_reporting(attr: TokenStream2, input: ItemFn) -> TokenStream2 { +fn generate_with_error_reporting(attr: &TokenStream2, input: ItemFn) -> TokenStream2 { let ItemFn { attrs, vis, sig, block } = input; // Remove 'err' from the attributes we pass to tracing::instrument // since we handle error reporting ourselves - let tracing_attr = remove_err_from_attr(&attr); + let tracing_attr = remove_err_from_attr(attr); // Get the return type for type annotation let result_type = match &sig.output { diff --git a/crates/tracing/Cargo.toml b/crates/tracing/Cargo.toml index 13d2880de0..f3e4637162 100644 --- a/crates/tracing/Cargo.toml +++ b/crates/tracing/Cargo.toml @@ -17,6 +17,5 @@ workspace = true [dependencies] miden-node-tracing-macro = { workspace = true } miden-node-utils = { workspace = true } -tracing = { workspace = true } -tracing-opentelemetry = { version = "0.32" } opentelemetry = { version = "0.31" } +tracing = { workspace = true } From 5129bbe520c308a04e5a616a64b86812c6b0449b Mon Sep 17 00:00:00 2001 From: Bernhard Schuster Date: Mon, 9 Mar 2026 22:33:17 +0100 Subject: [PATCH 04/12] start allowlist --- crates/tracing-macro/allowlist.txt | 2 + crates/tracing-macro/src/lib.rs | 119 +---------------------------- crates/tracing-macro/src/tests.rs | 0 3 files changed, 6 insertions(+), 115 deletions(-) create mode 100644 crates/tracing-macro/allowlist.txt create mode 100644 crates/tracing-macro/src/tests.rs diff --git a/crates/tracing-macro/allowlist.txt b/crates/tracing-macro/allowlist.txt new file mode 100644 index 0000000000..5438ab84f3 --- /dev/null +++ b/crates/tracing-macro/allowlist.txt @@ -0,0 +1,2 @@ +account.id +nullifier.id diff --git a/crates/tracing-macro/src/lib.rs b/crates/tracing-macro/src/lib.rs index f0f08259c9..225339aac7 100644 --- a/crates/tracing-macro/src/lib.rs +++ b/crates/tracing-macro/src/lib.rs @@ -41,15 +41,13 @@ use syn::{ItemFn, ReturnType, parse_macro_input}; /// - `name = "..."` - Sets a custom span name (default: function name) /// - `err` - Record errors with full error chain (enhanced by this macro) /// - `ret` / `ret(level = "...")` - Record return values -/// - `skip(arg1, arg2)` - Skip specific arguments from span fields -/// - `skip_all` - Skip all arguments from span fields /// - `fields(key = value, ...)` - Add custom fields to the span -/// - `parent = None` - Create a root span (no parent) +/// - `root` - Create a root span /// /// # Example /// /// ```rust,ignore -/// use miden_node_tracing::instrument_with_err_report; +/// use miden_node_tracing::instrument; /// /// #[instrument_with_err_report(target = COMPONENT, skip_all, err)] /// pub async fn apply_block(&self, block: ProvenBlock) -> Result<(), ApplyBlockError> { @@ -57,7 +55,7 @@ use syn::{ItemFn, ReturnType, parse_macro_input}; /// } /// ``` #[proc_macro_attribute] -pub fn instrument_with_err_report(attr: TokenStream, item: TokenStream) -> TokenStream { +pub fn instrument(attr: TokenStream, item: TokenStream) -> TokenStream { let attr2 = TokenStream2::from(attr.clone()); let input = parse_macro_input!(item as ItemFn); @@ -149,113 +147,4 @@ fn remove_err_from_attr(attr: &TokenStream2) -> TokenStream2 { } #[cfg(test)] -mod tests { - use super::*; - - #[test] - fn test_remove_err_from_attr_trailing() { - let attr: TokenStream2 = "target = COMPONENT, skip_all, err".parse().unwrap(); - let result = remove_err_from_attr(&attr); - let result_str = result.to_string(); - assert!(!result_str.contains("err"), "Should remove 'err': {result_str}"); - assert!(result_str.contains("target"), "Should keep 'target': {result_str}"); - assert!(result_str.contains("skip_all"), "Should keep 'skip_all': {result_str}"); - } - - #[test] - fn test_remove_err_from_attr_middle() { - let attr: TokenStream2 = "target = COMPONENT, err, skip_all".parse().unwrap(); - let result = remove_err_from_attr(&attr); - let result_str = result.to_string(); - assert!(!result_str.contains("err"), "Should remove 'err': {result_str}"); - assert!(result_str.contains("target"), "Should keep 'target': {result_str}"); - assert!(result_str.contains("skip_all"), "Should keep 'skip_all': {result_str}"); - } - - #[test] - fn test_remove_err_from_attr_only() { - let attr: TokenStream2 = "err".parse().unwrap(); - let result = remove_err_from_attr(&attr); - let result_str = result.to_string(); - assert!(!result_str.contains("err"), "Should remove 'err': {result_str}"); - } - - #[test] - fn test_remove_err_from_attr_with_ret() { - let attr: TokenStream2 = - "level = \"debug\", target = COMPONENT, err, ret(level = \"debug\")" - .parse() - .unwrap(); - let result = remove_err_from_attr(&attr); - let result_str = result.to_string(); - assert!(!result_str.contains(", err,"), "Should remove ', err,': {result_str}"); - assert!(result_str.contains("level"), "Should keep 'level': {result_str}"); - assert!(result_str.contains("ret"), "Should keep 'ret': {result_str}"); - } - - #[test] - fn test_returns_result_detection() { - // Test with Result type - let fn_with_result: syn::ItemFn = syn::parse_quote! { - fn test_fn() -> Result<(), Error> { - Ok(()) - } - }; - let returns_result = match &fn_with_result.sig.output { - ReturnType::Default => false, - ReturnType::Type(_, ty) => { - let ty_str = quote! { #ty }.to_string(); - ty_str.contains("Result") - }, - }; - assert!(returns_result, "Should detect Result return type"); - - // Test without Result type - let fn_without_result: syn::ItemFn = syn::parse_quote! { - fn test_fn() -> i32 { - 42 - } - }; - let returns_result = match &fn_without_result.sig.output { - ReturnType::Default => false, - ReturnType::Type(_, ty) => { - let ty_str = quote! { #ty }.to_string(); - ty_str.contains("Result") - }, - }; - assert!(!returns_result, "Should not detect Result for i32 return type"); - - // Test with no return type - let fn_no_return: syn::ItemFn = syn::parse_quote! { - fn test_fn() { - println!("hello"); - } - }; - let returns_result = match &fn_no_return.sig.output { - ReturnType::Default => false, - ReturnType::Type(_, ty) => { - let ty_str = quote! { #ty }.to_string(); - ty_str.contains("Result") - }, - }; - assert!(!returns_result, "Should not detect Result for unit return type"); - } - - #[test] - fn test_err_detection_in_attrs() { - // Test with err present - let attr_with_err = "target = COMPONENT, skip_all, err"; - assert!(attr_with_err.contains("err"), "Should find 'err'"); - - // Test without err - let attr_without_err = "target = COMPONENT, skip_all"; - assert!(!attr_without_err.contains("err"), "Should not find 'err'"); - - // Test with err in field name (should still match, but that's acceptable) - let attr_with_error_field = "target = COMPONENT, fields(error = true)"; - // Note: This is a known limitation - "error" contains "err" - // In practice this doesn't cause issues because if someone uses fields(error=...) - // they likely don't intend to use our error reporting anyway - assert!(attr_with_error_field.contains("err"), "Contains 'err' substring"); - } -} +mod tests; diff --git a/crates/tracing-macro/src/tests.rs b/crates/tracing-macro/src/tests.rs new file mode 100644 index 0000000000..e69de29bb2 From f070b1d9a1300fca0e145f8d0ebb51a57261bde3 Mon Sep 17 00:00:00 2001 From: Bernhard Schuster Date: Thu, 12 Mar 2026 21:45:31 +0100 Subject: [PATCH 05/12] refactor + skel --- crates/tracing-macro/src/allowed.rs | 15 +++ crates/tracing-macro/src/instrument.rs | 162 +++++++++++++++++++++++++ crates/tracing-macro/src/lib.rs | 154 ++++++----------------- crates/tracing-macro/src/log.rs | 6 + 4 files changed, 218 insertions(+), 119 deletions(-) create mode 100644 crates/tracing-macro/src/allowed.rs create mode 100644 crates/tracing-macro/src/instrument.rs create mode 100644 crates/tracing-macro/src/log.rs diff --git a/crates/tracing-macro/src/allowed.rs b/crates/tracing-macro/src/allowed.rs new file mode 100644 index 0000000000..86e34307b1 --- /dev/null +++ b/crates/tracing-macro/src/allowed.rs @@ -0,0 +1,15 @@ +use syn::Ident; + +const ALLOWED_LINES: &str = include_str!("../allowlist.txt"); + +// TODO add preprocessed list based on line by line extraction from allowlist.txt, use OnceCell or similar, avoid lazy_static! +const X: = ; + +struct Suggestions { + orig: Name, + ranked: Vec<&'static str>, +} + +pub(crate) fn check(which: Name) -> Result<()> { + todo!() +} diff --git a/crates/tracing-macro/src/instrument.rs b/crates/tracing-macro/src/instrument.rs new file mode 100644 index 0000000000..da90aa524a --- /dev/null +++ b/crates/tracing-macro/src/instrument.rs @@ -0,0 +1,162 @@ +use proc_macro::TokenStream; +use proc_macro2::TokenStream as TokenStream2; +use quote::quote; +use syn::punctuated::Punctuated; +use syn::{Expr, Ident, ItemFn, LitStr, ReturnType, Token, parse_macro_input}; + +// #[instrument(COMPONENT: checked_name=%foo, x=%y, ret, report)] +// #[instrument(COMPONENT: checked_name=%foo, x=%y, ret, err)] +// #[instrument(COMPONENT: checked_name=%foo, x=%y)] + +/// Value of a single value to track +struct Value { + print_modifier: Option, + value: Expr, +} + +/// An otel identifier, not _yet_ checked +struct Name { + segments: Punctuated, +} + +/// An otel identifier, checked against the whitelist +struct CheckedName(Name); + +/// An raw value, which also serves as otel identifier, checked against the whitelist +struct CheckedValue(Value); + +enum Checked { + Direct(CheckedValue), + Alias { + name: CheckedName, + _equals: Option, + value: Value, + }, +} + +/// Track the return value of caller +struct RetVal {} +/// Track the error, assuming it's an `std::error::Error` +struct StdErrVal {} +/// Track the error, assuming it's a `Report` +struct ReportVal {} + +enum Ret { + /// Track the return value, commonly used for integers, bool, enums - cheap ones - when used + /// with `StdErr` or `Report` + Value, + /// Track the error variant + StdErr, +} + +/// Defines the component to use +enum ComponentName { + /// Use the explicitly provided string literal + Literal(LitStr), + /// Use the explicitly provided identifier + Ident(Ident), + /// Assume there is a `COMPONENT` variable inside the current module. + Scope, +} + +enum Element { + Track(Checked), + Ret(Ret), +} + +struct InstrumentArgs { + component: ComponentName, + _colon: Token![:], + values: Punctuated, +} + +pub fn instrument2(attr2: TokenStream2, item2: TokenStream2) -> TokenStream2 { + let attr = syn::parse_macro_input!(attr2 as InstrumentArgs); + let item = syn::parse_macro_input!(item2 as Item); + + // Check if 'err' is present in the attributes + let attr_str = attr2.to_string(); + let has_err = attr_str.contains("err"); + + // Check if the function returns a Result + let returns_result = match &item.sig.output { + ReturnType::Default => false, + ReturnType::Type(_, ty) => { + let ty_str = quote! { #ty }.to_string(); + ty_str.contains("Result") + }, + }; + + if has_err && returns_result { + generate_with_error_reporting(&attr2, input).into() + } else { + // Just delegate to standard tracing::instrument + let ItemFn { attrs, vis, sig, block } = input; + quote! { + #(#attrs)* + #[::tracing::instrument(#attr2)] + #vis #sig + #block + } + .into() + } +} + +fn generate_with_error_reporting(attr: &TokenStream2, input: ItemFn) -> TokenStream2 { + let ItemFn { attrs, vis, sig, block } = input; + + // Remove 'err' from the attributes we pass to tracing::instrument + // since we handle error reporting ourselves + let tracing_attr = remove_err_from_attr(attr); + + // Get the return type for type annotation + let result_type = match &sig.output { + ReturnType::Type(_, ty) => quote! { #ty }, + ReturnType::Default => quote! { () }, + }; + + // Use absolute paths via the miden_node_tracing crate + quote! { + #(#attrs)* + #[::tracing::instrument(#tracing_attr)] + #vis #sig + { + let __result: #result_type = #block; + + if let ::core::result::Result::Err(ref __err) = __result { + // Use ErrorReport to get the full error chain + let __report = { + use ::miden_node_tracing::ErrorReport as _; + __err.as_report() + }; + + // Record the error event with the full report + ::miden_node_tracing::error!(error = %__report); + + // Set OpenTelemetry span status if available + { + use ::miden_node_tracing::OpenTelemetrySpanExt as _; + ::miden_node_tracing::Span::current().set_error(__err as &dyn ::std::error::Error); + } + } + + __result + } + } +} + +fn remove_err_from_attr(attr: &TokenStream2) -> TokenStream2 { + // Simple string-based removal of 'err' from the attribute + // This handles both 'err' and 'err,' patterns + let attr_str = attr.to_string(); + + // Remove 'err,' or ', err' or 'err' patterns + let cleaned = attr_str + .replace(", err,", ",") + .replace(", err", "") + .replace("err,", "") + .replace("err", ""); + + // Parse the cleaned string back into tokens + cleaned.parse().unwrap_or_else(|_| attr.clone()) +} diff --git a/crates/tracing-macro/src/lib.rs b/crates/tracing-macro/src/lib.rs index 225339aac7..3f3b8922a3 100644 --- a/crates/tracing-macro/src/lib.rs +++ b/crates/tracing-macro/src/lib.rs @@ -1,6 +1,13 @@ -//! Procedural macro for tracing instrumentation with full error report context. +//! Procedural macro for tracing without(?) papercuts //! -//! This macro provides an `#[instrument]`-like attribute that uses `ErrorReport::as_report()` +//! Provides `#[instrument]` in the spirit of `tracing::instrument`, `trace/debug/info/warn/error` +//! in the spirit of `tracing::log`. +//! +//! There are however significant difference in argument parsing as well as interpretation. +//! +//! 1. `ErrorReport` is a first class citizens +//! 2. `target=` is implicitly assumed if not provided by the user +//! 3. //! to capture the full error chain in tracing spans, rather than just the `Display` output. //! //! **Note**: This crate should not be used directly. Use `miden-node-tracing` instead, @@ -20,131 +27,40 @@ use proc_macro::TokenStream; use proc_macro2::TokenStream as TokenStream2; -use quote::quote; -use syn::{ItemFn, ReturnType, parse_macro_input}; - -/// Instruments a function with tracing, using full error reports for context. -/// -/// This attribute macro wraps functions that return `Result` and creates -/// a tracing span. When the function returns an error, it records the full -/// error chain using `ErrorReport::as_report()` instead of just `Display`. -/// -/// This macro accepts all the same arguments as `tracing::instrument`, and -/// delegates to it for span creation. The added functionality is enhanced -/// error reporting when `err` is specified. -/// -/// # Arguments -/// -/// All arguments from `tracing::instrument` are supported: -/// - `target = "..."` - Sets the tracing target -/// - `level = "..."` - Sets the tracing level (default: "info") -/// - `name = "..."` - Sets a custom span name (default: function name) -/// - `err` - Record errors with full error chain (enhanced by this macro) -/// - `ret` / `ret(level = "...")` - Record return values -/// - `fields(key = value, ...)` - Add custom fields to the span -/// - `root` - Create a root span -/// -/// # Example -/// -/// ```rust,ignore -/// use miden_node_tracing::instrument; -/// -/// #[instrument_with_err_report(target = COMPONENT, skip_all, err)] -/// pub async fn apply_block(&self, block: ProvenBlock) -> Result<(), ApplyBlockError> { -/// // Function body... -/// } -/// ``` -#[proc_macro_attribute] -pub fn instrument(attr: TokenStream, item: TokenStream) -> TokenStream { - let attr2 = TokenStream2::from(attr.clone()); - let input = parse_macro_input!(item as ItemFn); - // Check if 'err' is present in the attributes - let attr_str = attr2.to_string(); - let has_err = attr_str.contains("err"); +mod allowed; +mod instrument; +mod log; - // Check if the function returns a Result - let returns_result = match &input.sig.output { - ReturnType::Default => false, - ReturnType::Type(_, ty) => { - let ty_str = quote! { #ty }.to_string(); - ty_str.contains("Result") - }, - }; +#[cfg(test)] +mod tests; - if has_err && returns_result { - generate_with_error_reporting(&attr2, input).into() - } else { - // Just delegate to standard tracing::instrument - let ItemFn { attrs, vis, sig, block } = input; - quote! { - #(#attrs)* - #[::tracing::instrument(#attr2)] - #vis #sig - #block - } - .into() - } +#[proc_macro_attribute] +pub fn instrument(attr: TokenStream, item: TokenStream) -> TokenStream { + instrument::instrument2(TokenStream2::from(attr), TokenStream2::from(item)) } -fn generate_with_error_reporting(attr: &TokenStream2, input: ItemFn) -> TokenStream2 { - let ItemFn { attrs, vis, sig, block } = input; - - // Remove 'err' from the attributes we pass to tracing::instrument - // since we handle error reporting ourselves - let tracing_attr = remove_err_from_attr(attr); - - // Get the return type for type annotation - let result_type = match &sig.output { - ReturnType::Type(_, ty) => quote! { #ty }, - ReturnType::Default => quote! { () }, - }; - - // Use absolute paths via the miden_node_tracing crate - quote! { - #(#attrs)* - #[::tracing::instrument(#tracing_attr)] - #vis #sig - { - let __result: #result_type = #block; - - if let ::core::result::Result::Err(ref __err) = __result { - // Use ErrorReport to get the full error chain - let __report = { - use ::miden_node_tracing::ErrorReport as _; - __err.as_report() - }; - - // Record the error event with the full report - ::miden_node_tracing::error!(error = %__report); - - // Set OpenTelemetry span status if available - { - use ::miden_node_tracing::OpenTelemetrySpanExt as _; - ::miden_node_tracing::Span::current().set_error(__err as &dyn ::std::error::Error); - } - } - - __result - } - } +#[proc_macro] +pub fn error(ts: TokenStream) -> TokenStream { + log::parse("error", ts.into()).into() } -fn remove_err_from_attr(attr: &TokenStream2) -> TokenStream2 { - // Simple string-based removal of 'err' from the attribute - // This handles both 'err' and 'err,' patterns - let attr_str = attr.to_string(); +#[proc_macro] +pub fn warn(ts: TokenStream) -> TokenStream { + log::parse("warn", ts.into()).into() +} - // Remove 'err,' or ', err' or 'err' patterns - let cleaned = attr_str - .replace(", err,", ",") - .replace(", err", "") - .replace("err,", "") - .replace("err", ""); +#[proc_macro] +pub fn info(ts: TokenStream) -> TokenStream { + log::parse("info", ts.into()).into() +} - // Parse the cleaned string back into tokens - cleaned.parse().unwrap_or_else(|_| attr.clone()) +#[proc_macro] +pub fn debug(ts: TokenStream) -> TokenStream { + log::parse("debug", ts.into()).into() } -#[cfg(test)] -mod tests; +#[proc_macro] +pub fn trace(ts: TokenStream) -> TokenStream { + log::parse("trace", ts.into()).into() +} diff --git a/crates/tracing-macro/src/log.rs b/crates/tracing-macro/src/log.rs new file mode 100644 index 0000000000..ac3588aa37 --- /dev/null +++ b/crates/tracing-macro/src/log.rs @@ -0,0 +1,6 @@ +use proc_macro::TokenStream; +use proc_macro2::TokenStream as TokenStream2; + +fn parse(_fn_name: &'static str, _ts: TokenStream2) -> TokenStream2 { + todo!() +} From ee48c4d9b5b7c4a461e99ef51a45c72441b9a902 Mon Sep 17 00:00:00 2001 From: Bernhard Schuster Date: Thu, 12 Mar 2026 22:13:59 +0100 Subject: [PATCH 06/12] z --- crates/tracing-macro/Cargo.toml | 1 + crates/tracing-macro/allowlist.txt | 1 + crates/tracing-macro/src/allowed.rs | 37 ++++- crates/tracing-macro/src/instrument.rs | 15 +- crates/tracing-macro/src/tests.rs | 188 +++++++++++++++++++++++++ 5 files changed, 231 insertions(+), 11 deletions(-) diff --git a/crates/tracing-macro/Cargo.toml b/crates/tracing-macro/Cargo.toml index 950f77663d..01710aa233 100644 --- a/crates/tracing-macro/Cargo.toml +++ b/crates/tracing-macro/Cargo.toml @@ -21,3 +21,4 @@ proc-macro = true proc-macro2 = "1.0" quote = "1.0" syn = { features = ["extra-traits", "full", "parsing"], version = "2.0" } +fuzzy-search = "0.1.0" diff --git a/crates/tracing-macro/allowlist.txt b/crates/tracing-macro/allowlist.txt index 5438ab84f3..771f96cead 100644 --- a/crates/tracing-macro/allowlist.txt +++ b/crates/tracing-macro/allowlist.txt @@ -1,2 +1,3 @@ account.id nullifier.id +block.number diff --git a/crates/tracing-macro/src/allowed.rs b/crates/tracing-macro/src/allowed.rs index 86e34307b1..e3f9671f33 100644 --- a/crates/tracing-macro/src/allowed.rs +++ b/crates/tracing-macro/src/allowed.rs @@ -1,15 +1,40 @@ -use syn::Ident; +use std::sync::LazyLock; -const ALLOWED_LINES: &str = include_str!("../allowlist.txt"); +use fuzzy_search::basic::fuzzy_search; -// TODO add preprocessed list based on line by line extraction from allowlist.txt, use OnceCell or similar, avoid lazy_static! -const X: = ; +use crate::instrument::Name; + +const ALLOW_LIST: &str = include_str!("../allowlist.txt"); + +static ALLOWED_OTEL_NAMES: LazyLock> = LazyLock::new(|| { + Vec::from_iter( + ALLOW_LIST + .lines() + .map(|line| line.trim()) + .filter(|trimmed| !trimmed.starts_with('#')), + ) +}); struct Suggestions { orig: Name, ranked: Vec<&'static str>, } -pub(crate) fn check(which: Name) -> Result<()> { - todo!() +/// Check against the allowlist +pub(crate) fn check(query: Name) -> Result<(), Suggestions> { + if ALLOWED_OTEL_NAMES.contains(query.name) { + Ok(()) + } else { + let suggestions = fuzzy_search( + query.to_string().as_str(), + ALLOWED_OTEL_NAMES.as_slice(), + 5, + fuzzy_search::distance::levenshtein, + ); + + Err(Suggestions { + orig: query, + ranked: Vec::from_iter(suggestions.into_iter()), + }) + } } diff --git a/crates/tracing-macro/src/instrument.rs b/crates/tracing-macro/src/instrument.rs index da90aa524a..0766001bfd 100644 --- a/crates/tracing-macro/src/instrument.rs +++ b/crates/tracing-macro/src/instrument.rs @@ -1,8 +1,7 @@ -use proc_macro::TokenStream; use proc_macro2::TokenStream as TokenStream2; use quote::quote; use syn::punctuated::Punctuated; -use syn::{Expr, Ident, ItemFn, LitStr, ReturnType, Token, parse_macro_input}; +use syn::{Expr, Ident, ItemFn, LitStr, ReturnType, Token}; // #[instrument(COMPONENT: checked_name=%foo, x=%y, ret, report)] // #[instrument(COMPONENT: checked_name=%foo, x=%y, ret, err)] @@ -15,8 +14,14 @@ struct Value { } /// An otel identifier, not _yet_ checked -struct Name { - segments: Punctuated, +pub(crate) struct Name { + segments: Punctuated, +} + +impl Name { + fn to_string(&self) -> String { + self.segments.iter().map(|ident| ident.to_string()).join(".") + } } /// An otel identifier, checked against the whitelist @@ -70,7 +75,7 @@ struct InstrumentArgs { values: Punctuated, } -pub fn instrument2(attr2: TokenStream2, item2: TokenStream2) -> TokenStream2 { +pub fn instrument2(attr2: TokenStream2, item2: TokenStream2) -> syn::Result { let attr = syn::parse_macro_input!(attr2 as InstrumentArgs); let item = syn::parse_macro_input!(item2 as Item); diff --git a/crates/tracing-macro/src/tests.rs b/crates/tracing-macro/src/tests.rs index e69de29bb2..bbb0d3e8a8 100644 --- a/crates/tracing-macro/src/tests.rs +++ b/crates/tracing-macro/src/tests.rs @@ -0,0 +1,188 @@ +use proc_macro2::TokenStream as TokenStream2; +use quote::quote; + +use crate::instrument::instrument2; + +// ── 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_empty_parens_succeeds() { + // #[instrument()] – rustc strips the outer parens before the proc-macro sees the stream, + // so the attr stream is empty – identical to the bare case above. + let result = instrument2(quote! {}, item_bare_fn()); + assert!(result.is_ok(), "{result:?}"); +} + +// ── report ──────────────────────────────────────────────────────────────────── + +#[test] +fn instrument_report_on_result_fn_succeeds() { + // #[instrument(rpc: report)] – fn returns Result → ok + let result = instrument2(quote! { rpc: report }, item_result_unit_fn()); + assert!(result.is_ok(), "{result:?}"); +} + +#[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_result_fn_succeeds() { + // #[instrument(rpc: err)] – fn returns Result → ok + let result = instrument2(quote! { rpc: err }, item_result_unit_fn()); + assert!(result.is_ok(), "{result:?}"); +} + +#[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_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:?}"); +} From baf9b38e4e212c45dc5b5a4c6ed80e9d0e1f08fb Mon Sep 17 00:00:00 2001 From: Bernhard Schuster Date: Fri, 13 Mar 2026 15:33:45 +0100 Subject: [PATCH 07/12] more work --- Cargo.lock | 21 +- .../block-producer/src/batch_builder/mod.rs | 20 +- crates/block-producer/src/validator/mod.rs | 4 +- crates/store/src/db/migrations.rs | 4 +- crates/tracing-macro/README.md | 167 +++++- crates/tracing-macro/allowlist.txt | 16 + crates/tracing-macro/src/allowed.rs | 45 +- crates/tracing-macro/src/instrument.rs | 507 ++++++++++++++---- crates/tracing-macro/src/lib.rs | 373 ++++++++++++- crates/tracing-macro/src/log.rs | 214 +++++++- crates/tracing-macro/src/tests.rs | 137 +++++ crates/tracing/README.md | 6 +- crates/tracing/src/lib.rs | 8 +- 13 files changed, 1320 insertions(+), 202 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index fa89f8116f..13afb8f0d1 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1701,6 +1701,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" @@ -2083,7 +2093,7 @@ dependencies = [ "libc", "percent-encoding", "pin-project-lite", - "socket2 0.5.10", + "socket2 0.6.2", "system-configuration", "tokio", "tower-service", @@ -3188,6 +3198,7 @@ dependencies = [ name = "miden-node-tracing-macro" version = "0.14.0-alpha.1" dependencies = [ + "fuzzy-search", "proc-macro2", "quote", "syn 2.0.114", @@ -4140,7 +4151,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ac6c3320f9abac597dcbc668774ef006702672474aad53c6d596b62e487b40b1" dependencies = [ "heck", - "itertools 0.13.0", + "itertools 0.14.0", "log", "multimap", "once_cell", @@ -4162,7 +4173,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "27c6023962132f4b30eb4c172c91ce92d933da334c59c23cddee82358ddafb0b" dependencies = [ "anyhow", - "itertools 0.13.0", + "itertools 0.14.0", "proc-macro2", "quote", "syn 2.0.114", @@ -4255,7 +4266,7 @@ dependencies = [ "quinn-udp", "rustc-hash", "rustls 0.23.36", - "socket2 0.5.10", + "socket2 0.6.2", "thiserror 2.0.18", "tokio", "tracing", @@ -4293,7 +4304,7 @@ dependencies = [ "cfg_aliases", "libc", "once_cell", - "socket2 0.5.10", + "socket2 0.6.2", "tracing", "windows-sys 0.60.2", ] diff --git a/crates/block-producer/src/batch_builder/mod.rs b/crates/block-producer/src/batch_builder/mod.rs index 93ba9bdb33..2b98690545 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,7 +15,6 @@ use miden_tx_batch_prover::LocalBatchProver; use rand::Rng; use tokio::task::JoinSet; use tokio::time; -use miden_node_tracing::instrument_with_err_report; use tracing::{Instrument, Span}; use url::Url; @@ -103,7 +103,7 @@ impl BatchBuilder { } } - #[instrument_with_err_report(parent = None, target = COMPONENT, name = "batch_builder.build_batch", skip_all)] + #[instrument(parent = None, target = COMPONENT, name = "batch_builder.build_batch", skip_all)] async fn build_batch(&mut self, mempool: SharedMempool) { Span::current().set_attribute("workers.count", self.worker_pool.len()); @@ -131,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_with_err_report(target = COMPONENT, name = "batch_builder.wait_for_available_worker", skip_all)] + #[instrument(target = COMPONENT, name = "batch_builder.wait_for_available_worker", skip_all)] 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. @@ -190,12 +190,12 @@ impl BatchJob { .await; } - #[instrument_with_err_report(target = COMPONENT, name = "batch_builder.select_batch", skip_all)] + #[instrument(target = COMPONENT, name = "batch_builder.select_batch", skip_all)] async fn select_batch(&self) -> Option { self.mempool.lock().await.select_batch() } - #[instrument_with_err_report(target = COMPONENT, name = "batch_builder.get_batch_inputs", skip_all, err)] + #[instrument(target = COMPONENT, name = "batch_builder.get_batch_inputs", skip_all, err)] async fn get_batch_inputs( &self, batch: SelectedBatch, @@ -218,7 +218,7 @@ impl BatchJob { .map(|inputs| (batch, inputs)) } - #[instrument_with_err_report(target = COMPONENT, name = "batch_builder.propose_batch", skip_all, err)] + #[instrument(target = COMPONENT, name = "batch_builder.propose_batch", skip_all, err)] async fn propose_batch( selected: SelectedBatch, inputs: BatchInputs, @@ -238,7 +238,7 @@ impl BatchJob { .map_err(BuildBatchError::ProposeBatchError) } - #[instrument_with_err_report(target = COMPONENT, name = "batch_builder.prove_batch", skip_all, err)] + #[instrument(target = COMPONENT, name = "batch_builder.prove_batch", skip_all, err)] async fn prove_batch( &self, proposed_batch: ProposedBatch, @@ -268,7 +268,7 @@ impl BatchJob { } } - #[instrument_with_err_report(target = COMPONENT, name = "batch_builder.inject_failure", skip_all, err)] + #[instrument(target = COMPONENT, name = "batch_builder.inject_failure", skip_all, err)] async fn inject_failure(&self, value: T) -> Result { let roll = rand::rng().random::(); @@ -282,12 +282,12 @@ impl BatchJob { } } - #[instrument_with_err_report(target = COMPONENT, name = "batch_builder.commit_batch", skip_all)] + #[instrument(target = COMPONENT, name = "batch_builder.commit_batch", skip_all)] async fn commit_batch(&self, batch: Arc) { self.mempool.lock().await.commit_batch(batch); } - #[instrument_with_err_report(target = COMPONENT, name = "batch_builder.rollback_batch", skip_all)] + #[instrument(target = COMPONENT, name = "batch_builder.rollback_batch", skip_all)] async fn rollback_batch(&self, batch_id: BatchId) { self.mempool.lock().await.rollback_batch(batch_id); } diff --git a/crates/block-producer/src/validator/mod.rs b/crates/block-producer/src/validator/mod.rs index 06bc670d01..59e1d08348 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::instrument; use miden_protocol::block::ProposedBlock; use miden_protocol::crypto::dsa::ecdsa_k256_keccak::Signature; use miden_protocol::utils::{Deserializable, DeserializationError, Serializable}; use thiserror::Error; -use miden_node_tracing::instrument_with_err_report; use tracing::info; use url::Url; @@ -48,7 +48,7 @@ impl BlockProducerValidatorClient { Self { client: validator } } - #[instrument_with_err_report(target = COMPONENT, name = "validator.client.validate_block", skip_all, err)] + #[instrument(target = COMPONENT, name = "validator.client.validate_block", skip_all, err)] pub async fn sign_block( &self, proposed_block: ProposedBlock, diff --git a/crates/store/src/db/migrations.rs b/crates/store/src/db/migrations.rs index fcb33026f0..6199f44b2c 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 miden_node_tracing::instrument_with_err_report; +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_with_err_report(level = "debug", target = COMPONENT, skip_all, err)] +#[instrument(level = "debug", target = COMPONENT, skip_all, err)] pub fn apply_migrations( conn: &mut SqliteConnection, ) -> std::result::Result<(), miden_node_db::DatabaseError> { diff --git a/crates/tracing-macro/README.md b/crates/tracing-macro/README.md index 84f06e6f4d..2687cb8eea 100644 --- a/crates/tracing-macro/README.md +++ b/crates/tracing-macro/README.md @@ -1,16 +1,167 @@ -# Miden Node Tracing Macro +# miden-node-tracing-macro Internal procedural macro crate for `miden-node-tracing`. -**Do not use this crate directly.** Use `miden-node-tracing` instead, which re-exports this macro along with all required dependencies. +**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`, …). -## Usage +--- + +## `#[instrument]` + +Instruments a function with a [`tracing`] span. Extends `tracing::instrument` +with a component-target shorthand, an OTel 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 OTel 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 + OTel 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()` | +| OTel 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_with_err_report; +use miden_node_tracing::instrument; -#[instrument_with_err_report(target = COMPONENT, skip_all, err)] -pub async fn apply_block(&self, block: ProvenBlock) -> Result<(), ApplyBlockError> { - // Function body... -} +// 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 + OTel 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 OTel 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 index 771f96cead..72b2249dd1 100644 --- a/crates/tracing-macro/allowlist.txt +++ b/crates/tracing-macro/allowlist.txt @@ -1,3 +1,19 @@ +# 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 diff --git a/crates/tracing-macro/src/allowed.rs b/crates/tracing-macro/src/allowed.rs index e3f9671f33..51e27250ac 100644 --- a/crates/tracing-macro/src/allowed.rs +++ b/crates/tracing-macro/src/allowed.rs @@ -6,35 +6,36 @@ use crate::instrument::Name; const ALLOW_LIST: &str = include_str!("../allowlist.txt"); +/// Set of permitted otel field names, copied into the binary `allowlist.txt`. +/// +/// Lines that are empty or start with `#` are ignored. +/// +/// Example: +/// ``` +/// foo.bar.baz +/// baz_anything_goes +/// technically.🪤.works.but.really.you_should_not +/// ``` static ALLOWED_OTEL_NAMES: LazyLock> = LazyLock::new(|| { Vec::from_iter( ALLOW_LIST .lines() .map(|line| line.trim()) - .filter(|trimmed| !trimmed.starts_with('#')), + .filter(|trimmed| !trimmed.is_empty() && !trimmed.starts_with('#')), ) }); -struct Suggestions { - orig: Name, - ranked: Vec<&'static str>, -} - -/// Check against the allowlist -pub(crate) fn check(query: Name) -> Result<(), Suggestions> { - if ALLOWED_OTEL_NAMES.contains(query.name) { - Ok(()) - } else { - let suggestions = fuzzy_search( - query.to_string().as_str(), - ALLOWED_OTEL_NAMES.as_slice(), - 5, - fuzzy_search::distance::levenshtein, - ); - - Err(Suggestions { - orig: query, - ranked: Vec::from_iter(suggestions.into_iter()), - }) +/// Checks `name` 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(name: &Name) -> Result<(), Vec> { + let dotted = name.to_dotted_string(); + if ALLOWED_OTEL_NAMES.contains(&dotted.as_str()) { + return Ok(()); } + + let owned: Vec = ALLOWED_OTEL_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 index 0766001bfd..860f543a99 100644 --- a/crates/tracing-macro/src/instrument.rs +++ b/crates/tracing-macro/src/instrument.rs @@ -1,167 +1,436 @@ -use proc_macro2::TokenStream as TokenStream2; +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, ReturnType, Token}; -// #[instrument(COMPONENT: checked_name=%foo, x=%y, ret, report)] -// #[instrument(COMPONENT: checked_name=%foo, x=%y, ret, err)] -// #[instrument(COMPONENT: checked_name=%foo, x=%y)] +// ── Name ────────────────────────────────────────────────────────────────────── -/// Value of a single value to track -struct Value { - print_modifier: Option, - value: Expr, -} - -/// An otel identifier, not _yet_ checked +/// 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 { - segments: Punctuated, + pub(crate) segments: Punctuated, } impl Name { - fn to_string(&self) -> String { - self.segments.iter().map(|ident| ident.to_string()).join(".") + /// Returns the dotted string representation, e.g. `"account.id"`. + pub(crate) fn to_dotted_string(&self) -> String { + self.segments.iter().map(|i| i.to_string()).collect::>().join(".") + } + + /// Span for the full name. + pub(crate) fn span(&self) -> Span { + self.segments.span() } } -/// An otel identifier, checked against the whitelist -struct CheckedName(Name); +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 }) + } +} -/// An raw value, which also serves as otel identifier, checked against the whitelist -struct CheckedValue(Value); +// ── Value ───────────────────────────────────────────────────────────────────── -enum Checked { - Direct(CheckedValue), - Alias { - name: CheckedName, - _equals: Option, - value: Value, - }, +/// The right-hand side of a field assignment: an optional `%` Display modifier +/// followed by an arbitrary expression. +/// +/// - `= expr` → Debug format (`{:?}`) +/// - `= %expr` → Display format (`{}`) +struct Value { + display_modifier: Option, + expr: Expr, } -/// Track the return value of caller -struct RetVal {} -/// Track the error, assuming it's an `std::error::Error` -struct StdErrVal {} -/// Track the error, assuming it's a `Report` -struct ReportVal {} +impl Parse for Value { + fn parse(input: ParseStream) -> syn::Result { + let display_modifier = input.parse::().ok(); + let expr = input.parse::()?; + Ok(Value { display_modifier, expr }) + } +} -enum Ret { - /// Track the return value, commonly used for integers, bool, enums - cheap ones - when used - /// with `StdErr` or `Report` - Value, - /// Track the error variant - StdErr, +// ── Field entry ─────────────────────────────────────────────────────────────── + +/// A single `dotted-name = [%] expr` pair inside the attribute list. +/// +/// The `name` is validated against the OTel allowlist before code is emitted. +/// Both `account.id = id` (Debug) and `account.id = %id` (Display) are accepted. +struct Field { + name: Name, + _eq: Token![=], + value: Value, +} + +impl Parse for Field { + fn parse(input: ParseStream) -> syn::Result { + Ok(Field { + name: input.parse()?, + _eq: input.parse()?, + value: input.parse()?, + }) + } +} + +// ── Element ─────────────────────────────────────────────────────────────────── + +/// A single comma-separated element inside the `#[instrument(…)]` attribute. +/// +/// Parsing priority: the three reserved keywords (`ret`, `err`, `report`) are +/// recognised by peeking at the leading identifier before attempting a full +/// `Field` parse. Any other leading identifier is treated as the start of a +/// `name = value` field entry. +enum Element { + /// A `dotted-name = [%] expr` field (validated against the OTel allowlist). + Field(Field), + /// `ret` – record the function's return value inside the span. + Ret, + /// `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 OTel span status. Mutually exclusive with `err`. Requires `Result`. + Report, } -/// Defines the component to use +impl Parse for Element { + fn parse(input: ParseStream) -> syn::Result { + let forked: Ident = input.fork().parse()?; + match forked.to_string().as_str() { + "ret" => { + let _: Ident = input.parse()?; + Ok(Element::Ret) + }, + "err" => { + let _: Ident = input.parse()?; + Ok(Element::Err) + }, + "report" => { + let _: Ident = input.parse()?; + Ok(Element::Report) + }, + _ => { + let field: Field = input.parse()?; + Ok(Element::Field(field)) + }, + } + } +} + +// ── ComponentName ───────────────────────────────────────────────────────────── + +/// The optional component prefix before the `:` separator. +/// +/// ```text +/// #[instrument(RPC: …)] → Ident("rpc") → target = RPC +/// #[instrument("my-rpc": …)] → Literal("my-rpc") → target = "my-rpc" +/// ``` enum ComponentName { - /// Use the explicitly provided string literal Literal(LitStr), - /// Use the explicitly provided identifier Ident(Ident), - /// Assume there is a `COMPONENT` variable inside the current module. - Scope, } -enum Element { - Track(Checked), - Ret(Ret), -} +// ── InstrumentArgs ──────────────────────────────────────────────────────────── +/// Parsed representation of the full `#[instrument(…)]` attribute. +/// +/// Grammar: +/// ```text +/// InstrumentArgs ::= ε +/// | COMPONENT ":" [element ("," element)*] +/// | element ("," element)* +/// +/// COMPONENT ::= ident | string-literal +/// element ::= field-entry | "ret" | "err" | "report" +/// field-entry::= dotted-name "=" ["%"] expr +/// ``` struct InstrumentArgs { - component: ComponentName, - _colon: Token![:], - values: Punctuated, + /// 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, } -pub fn instrument2(attr2: TokenStream2, item2: TokenStream2) -> syn::Result { - let attr = syn::parse_macro_input!(attr2 as InstrumentArgs); - let item = syn::parse_macro_input!(item2 as Item); +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. + 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 + }; + + 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 }) + } +} - // Check if 'err' is present in the attributes - let attr_str = attr2.to_string(); - let has_err = attr_str.contains("err"); +// ── Returns-Result helper ───────────────────────────────────────────────────── - // Check if the function returns a Result - let returns_result = match &item.sig.output { +/// Returns `true` if the function's return type token stream contains the word +/// `Result`. Syntactic check only without any type resolution! +fn returns_result(item: &ItemFn) -> bool { + match &item.sig.output { ReturnType::Default => false, ReturnType::Type(_, ty) => { - let ty_str = quote! { #ty }.to_string(); - ty_str.contains("Result") + let s = quote! { #ty }.to_string(); + s.contains("Result") // TODO be more accurate here what we support }, - }; + } +} - if has_err && returns_result { - generate_with_error_reporting(&attr2, input).into() - } else { - // Just delegate to standard tracing::instrument - let ItemFn { attrs, vis, sig, block } = input; - quote! { - #(#attrs)* - #[::tracing::instrument(#attr2)] - #vis #sig - #block +// ── allowlist check ─────────────────────────────────────────────────────────── + +/// Validates `name` against the OTel field allowlist (`allowlist.txt`). +/// +/// On failure, emits a [`syn::Error`] anchored at the name's span. If the +/// fuzzy-search backend finds close matches in the allowlist they are included in +/// the error message as suggestions. +fn check_allowlist(name: &Name) -> syn::Result<()> { + crate::allowed::check(name).map_err(|suggestions| { + let dotted = name.to_dotted_string(); + let hint = if suggestions.is_empty() { + String::new() + } else { + format!(" – did you mean: {}?", suggestions.join(", ")) + }; + syn::Error::new( + name.span(), + format!("`{dotted}` is not in the open telemetry allowlist: {hint}"), + ) + }) +} + +// ── codegen helpers ─────────────────────────────────────────────────────────── + +/// Converts the optional component into a `target = "…",` token fragment for +/// insertion into `#[tracing::instrument(…)]`. Returns `None` when no component +/// was specified so that `tracing` falls back to the default (module path). +fn component_target(component: &Option) -> Option { + match component { + Some(ComponentName::Literal(lit)) => Some(quote! { target = #lit, }), + Some(ComponentName::Ident(ident)) => { + let s = ident.to_string(); + let lit = LitStr::new(&s, ident.span()); + Some(quote! { target = #lit, }) + }, + None => None, + } +} + +/// Converts the collected `Field` entries into a `fields(…),` token fragment. +/// +/// Each field is emitted as `"dotted.name" = [%] expr`. The string-literal form +/// is used for the key so that dotted names (which are not valid Rust identifiers) +/// survive the `tracing::instrument` macro's own field-name parsing. +fn fields_tokens(fields: &[&Field]) -> TokenStream2 { + if fields.is_empty() { + return quote! {}; + } + let mut parts = Vec::new(); + for f in fields { + let name_str = f.name.to_dotted_string(); + let name_lit = LitStr::new(&name_str, f.name.span()); + let expr = &f.value.expr; + if f.value.display_modifier.is_some() { + parts.push(quote! { #name_lit = %#expr }); + } else { + parts.push(quote! { #name_lit = #expr }); } - .into() } + quote! { fields(#(#parts),*), } } -fn generate_with_error_reporting(attr: &TokenStream2, input: ItemFn) -> TokenStream2 { - let ItemFn { attrs, vis, sig, block } = input; +// ── public entry point ──────────────────────────────────────────────────────── - // Remove 'err' from the attributes we pass to tracing::instrument - // since we handle error reporting ourselves - let tracing_attr = remove_err_from_attr(attr); +/// 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 +/// +/// Three distinct output shapes depending on which keywords are present: +/// +/// **`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` present (no `report`)** +/// ```rust,ignore +/// #[::tracing::instrument(target = …, skip_all, fields(…), ret?, err)] +/// fn foo(…) -> Result { /* original body */ } +/// ``` +/// +/// **Neither `err` nor `report`** +/// ```rust,ignore +/// #[::tracing::instrument(target = …, skip_all?, fields(…)?, ret?)] +/// 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 + }); + } - // Get the return type for type annotation - let result_type = match &sig.output { - ReturnType::Type(_, ty) => quote! { #ty }, - ReturnType::Default => quote! { () }, - }; + let args: InstrumentArgs = syn::parse2(attr.clone())?; + let func: ItemFn = syn::parse2(item)?; - // Use absolute paths via the miden_node_tracing crate - quote! { - #(#attrs)* - #[::tracing::instrument(#tracing_attr)] - #vis #sig - { - let __result: #result_type = #block; - - if let ::core::result::Result::Err(ref __err) = __result { - // Use ErrorReport to get the full error chain - let __report = { - use ::miden_node_tracing::ErrorReport as _; - __err.as_report() - }; - - // Record the error event with the full report - ::miden_node_tracing::error!(error = %__report); - - // Set OpenTelemetry span status if available - { - use ::miden_node_tracing::OpenTelemetrySpanExt as _; - ::miden_node_tracing::Span::current().set_error(__err as &dyn ::std::error::Error); - } - } + // ── collect element kinds ────────────────────────────────────────────────── + let mut has_ret = false; + let mut has_err = false; + let mut has_report = false; + let mut fields: Vec<&Field> = Vec::new(); + + let elements = args.elements; - __result + for elem in &elements { + match elem { + Element::Ret => has_ret = true, + Element::Err => has_err = true, + Element::Report => has_report = true, + Element::Field(f) => fields.push(f), } } -} -fn remove_err_from_attr(attr: &TokenStream2) -> TokenStream2 { - // Simple string-based removal of 'err' from the attribute - // This handles both 'err' and 'err,' patterns - let attr_str = attr.to_string(); + // ── 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", + )); + } - // Remove 'err,' or ', err' or 'err' patterns - let cleaned = attr_str - .replace(", err,", ",") - .replace(", err", "") - .replace("err,", "") - .replace("err", ""); + // err / report require a Result return type. + if (has_err || has_report) && !returns_result(&func) { + return Err(syn::Error::new( + func.sig.ident.span(), + "`err` / `report` requires the function to return `Result`", + )); + } - // Parse the cleaned string back into tokens - cleaned.parse().unwrap_or_else(|_| attr.clone()) + // ret alone is valid on any fn; ret + report still needs Result (already covered + // by the check above when has_report is true). + if has_ret && has_report && !returns_result(&func) { + return Err(syn::Error::new( + func.sig.ident.span(), + "`ret` + `report` requires the function to return `Result`", + )); + } + + // Validate every field name against the allowlist. + for f in &fields { + check_allowlist(&f.name)?; + } + + // ── code generation ─────────────────────────────────────────────────────── + + let target_tokens = component_target(&args.component); + let fields_tok = fields_tokens(&fields); + + // When explicit fields are present, skip all implicit fn arguments to avoid + // accidentally recording sensitive values. + let skip_all = if !fields.is_empty() { + quote! { skip_all, } + } else { + quote! {} + }; + + let ret_tok = if has_ret { + quote! { ret, } + } else { + quote! {} + }; + + let ItemFn { attrs, vis, sig, block } = func; + let result_ty = match &sig.output { + ReturnType::Type(_, ty) => quote! { #ty }, + ReturnType::Default => quote! { () }, + }; + + if has_report { + // Wrap the original body so we can inspect the result before returning. + // On Err: emit the full error chain and mark the OTel span as failed. + Ok(quote! { + #(#attrs)* + #[::tracing::instrument(#target_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 if has_err { + // Delegate to tracing::instrument's built-in err support. + Ok(quote! { + #(#attrs)* + #[::tracing::instrument(#target_tokens #skip_all #fields_tok #ret_tok err)] + #vis #sig #block + }) + } else { + // No error-reporting variant – plain span wrapper. + Ok(quote! { + #(#attrs)* + #[::tracing::instrument(#target_tokens #skip_all #fields_tok #ret_tok)] + #vis #sig #block + }) + } } diff --git a/crates/tracing-macro/src/lib.rs b/crates/tracing-macro/src/lib.rs index 3f3b8922a3..796e3e0ed0 100644 --- a/crates/tracing-macro/src/lib.rs +++ b/crates/tracing-macro/src/lib.rs @@ -1,29 +1,156 @@ -//! Procedural macro for tracing without(?) papercuts +//! Procedural macros for structured, OTel-aware tracing in the Miden node. //! -//! Provides `#[instrument]` in the spirit of `tracing::instrument`, `trace/debug/info/warn/error` -//! in the spirit of `tracing::log`. +//! **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`, …). //! -//! There are however significant difference in argument parsing as well as interpretation. +//! # Overview //! -//! 1. `ErrorReport` is a first class citizens -//! 2. `target=` is implicitly assumed if not provided by the user -//! 3. -//! to capture the full error chain in tracing spans, rather than just the `Display` output. +//! 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: //! -//! **Note**: This crate should not be used directly. Use `miden-node-tracing` instead, -//! which re-exports this macro along with all required dependencies. +//! | 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 | //! -//! # Problem +//! ## Key differences from `tracing` //! -//! The standard `#[instrument(err)]` from `tracing` uses `Display` or `Debug` to format errors -//! in span events. This loses the error chain context, showing only the top-level error message. +//! 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. **OTel 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 OTel field allowlist as `#[instrument]`. //! -//! # Solution +//! # `#[instrument]` – complete reference //! -//! This macro wraps functions that return `Result` and: -//! 1. Creates a tracing span with the configured attributes (delegating to `tracing::instrument`) -//! 2. On error, records the full error chain using `ErrorReport::as_report()` -//! 3. Sets the OpenTelemetry span status to error with the full report +//! ## 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: 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 OTel 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 OTel allowlist | +//! | `rpc: foo.bar.baz = %id` | any | ✗ | Compile error: `foo.bar.baz` not in OTel 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) | +//! | OTel 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 OTel 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; @@ -35,32 +162,230 @@ mod log; #[cfg(test)] mod tests; +/// Instruments a function with a [`tracing`] span, with node-specific extensions. +/// +/// # 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 +/// ``` +/// +/// # Component +/// +/// An optional `IDENT:` or `"literal":` prefix sets the span's `target`: +/// +/// ```rust,ignore +/// #[instrument(rpc: report)] +/// #[instrument("block-producer": err)] +/// ``` +/// +/// # 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. +/// #[instrument(rpc:)] +/// fn also_simple() {} +/// +/// // 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 + OTel 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 OTel 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 { - instrument::instrument2(TokenStream2::from(attr), TokenStream2::from(item)) + 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 { - log::parse("error", ts.into()).into() + 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 { - log::parse("warn", ts.into()).into() + 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 { - log::parse("info", ts.into()).into() + 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 { - log::parse("debug", ts.into()).into() + 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 { - log::parse("trace", ts.into()).into() + 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 index ac3588aa37..933181e13f 100644 --- a/crates/tracing-macro/src/log.rs +++ b/crates/tracing-macro/src/log.rs @@ -1,6 +1,214 @@ -use proc_macro::TokenStream; use proc_macro2::TokenStream as TokenStream2; +use quote::quote; +use syn::parse::{Parse, ParseStream}; +use syn::{Expr, Ident, LitStr, Token}; -fn parse(_fn_name: &'static str, _ts: TokenStream2) -> TokenStream2 { - todo!() +use crate::instrument::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 OTel allowlist. +struct LogField { + name: Name, + _eq: Token![=], + /// 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 name: Name = input.parse()?; + 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, _eq, 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 OTel +/// allowlist. The trailing message (if any) is forwarded verbatim. +struct LogArgs { + /// Optional component prefix; emitted as `target: "…"` in the tracing call. + component: Option, + /// Validated, allowlisted structured fields. + fields: Vec, + /// Remaining tokens after the last field – the message string and any format + /// arguments, forwarded verbatim to `tracing`. + message_tokens: TokenStream2, +} + +enum ComponentName { + Literal(LitStr), + Ident(Ident), +} + +impl ComponentName { + fn to_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, } + }, + } + } +} + +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 }) + } +} + +// ── allowlist check ─────────────────────────────────────────────────────────── + +fn check_allowlist(name: &Name) -> syn::Result<()> { + crate::allowed::check(name).map_err(|suggestions| { + let dotted = name.to_dotted_string(); + let hint = if suggestions.is_empty() { + String::new() + } else { + format!(" – did you mean: {}?", suggestions.join(", ")) + }; + syn::Error::new(name.span(), format!("`{dotted}` is not in the OTel allowlist{hint}")) + }) +} + +// ── public entry point ──────────────────────────────────────────────────────── + +/// Parses and validates a log-macro call, then expands it to +/// `::tracing::!(target: "…", field = value, …, "message", …)`. +/// +/// 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)?; + + // Validate every field name against the OTel allowlist. + for field in &args.fields { + check_allowlist(&field.name)?; + } + + let level_ident = syn::Ident::new(level, 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_target_tokens); + + // Build the field fragments: `"dotted.name" = [%|?] expr`. + let field_toks: Vec = args + .fields + .iter() + .map(|f| { + let name_str = f.name.to_dotted_string(); + let name_lit = LitStr::new(&name_str, 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::#level_ident!(#target_tok #(#field_toks),* #sep #msg) + }) } diff --git a/crates/tracing-macro/src/tests.rs b/crates/tracing-macro/src/tests.rs index bbb0d3e8a8..9077b2c8eb 100644 --- a/crates/tracing-macro/src/tests.rs +++ b/crates/tracing-macro/src/tests.rs @@ -2,6 +2,11 @@ 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) +} // ── item fixtures ───────────────────────────────────────────────────────────── @@ -186,3 +191,135 @@ fn instrument_allowlisted_field_display_report_err_fails() { 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:?}"); +} diff --git a/crates/tracing/README.md b/crates/tracing/README.md index dc0c39b936..94a81ab788 100644 --- a/crates/tracing/README.md +++ b/crates/tracing/README.md @@ -4,14 +4,14 @@ Tracing utilities for Miden node with enhanced error reporting. ## Overview -This crate provides an `#[instrument_with_err_report]` attribute macro that enhances the standard `tracing::instrument` with full error chain reporting. When a function returns an error, instead of just logging the top-level error message, it captures and logs the entire error chain. +This crate provides an `#[instrument]` attribute macro that enhances the standard `tracing::instrument` with full error chain reporting. When a function returns an error, instead of just logging the top-level error message, it captures and logs the entire error chain. ## Usage ```rust -use miden_node_tracing::instrument_with_err_report; +use miden_node_tracing::instrument; -#[instrument_with_err_report(target = "my_component", skip_all, err)] +#[instrument(target = "my_component", skip_all, err)] pub async fn apply_block(&self, block: ProvenBlock) -> Result<(), ApplyBlockError> { // Function body... } diff --git a/crates/tracing/src/lib.rs b/crates/tracing/src/lib.rs index a49b45e01f..3c03acdc9d 100644 --- a/crates/tracing/src/lib.rs +++ b/crates/tracing/src/lib.rs @@ -1,14 +1,14 @@ //! Tracing utilities for Miden node with enhanced error reporting. //! -//! This crate provides an `#[instrument_with_err_report]` attribute macro that enhances +//! This crate provides an `#[instrument]` attribute macro that enhances //! the standard `tracing::instrument` with full error chain reporting. //! //! # Usage //! //! ```rust,ignore -//! use miden_node_tracing::instrument_with_err_report; +//! use miden_node_tracing::instrument; //! -//! #[instrument_with_err_report(target = "my_component", skip_all, err)] +//! #[instrument(target = "my_component", skip_all, err)] //! async fn apply_block(&self, block: Block) -> Result<(), ApplyBlockError> { //! // ... //! } @@ -22,7 +22,7 @@ //! ``` // Re-export the instrument macro -pub use miden_node_tracing_macro::instrument_with_err_report; +pub use miden_node_tracing_macro::instrument; // Re-export ErrorReport from miden-node-utils pub use miden_node_utils::ErrorReport; // Re-export OpenTelemetrySpanExt from miden-node-utils From c461cbd60e08291479d37984e37a56bf1deafa4d Mon Sep 17 00:00:00 2001 From: Bernhard Schuster Date: Fri, 13 Mar 2026 23:03:13 +0100 Subject: [PATCH 08/12] refactor/unfiy --- crates/tracing-macro/src/allowed.rs | 13 +- crates/tracing-macro/src/instrument.rs | 192 +++++++++++++++---------- crates/tracing-macro/src/log.rs | 59 ++------ crates/tracing-macro/src/tests.rs | 83 +++++++++++ 4 files changed, 212 insertions(+), 135 deletions(-) diff --git a/crates/tracing-macro/src/allowed.rs b/crates/tracing-macro/src/allowed.rs index 51e27250ac..7f9892ffb4 100644 --- a/crates/tracing-macro/src/allowed.rs +++ b/crates/tracing-macro/src/allowed.rs @@ -2,8 +2,6 @@ use std::sync::LazyLock; use fuzzy_search::basic::fuzzy_search; -use crate::instrument::Name; - const ALLOW_LIST: &str = include_str!("../allowlist.txt"); /// Set of permitted otel field names, copied into the binary `allowlist.txt`. @@ -11,7 +9,7 @@ const ALLOW_LIST: &str = include_str!("../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 @@ -25,17 +23,16 @@ static ALLOWED_OTEL_NAMES: LazyLock> = LazyLock::new(|| { ) }); -/// Checks `name` against the open telemetry field allowlist. +/// 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(name: &Name) -> Result<(), Vec> { - let dotted = name.to_dotted_string(); - if ALLOWED_OTEL_NAMES.contains(&dotted.as_str()) { +pub(crate) fn check(dotted: &str) -> Result<(), Vec> { + if ALLOWED_OTEL_NAMES.contains(&dotted) { return Ok(()); } let owned: Vec = ALLOWED_OTEL_NAMES.iter().map(|s| s.to_string()).collect(); - let suggestions = fuzzy_search(&dotted, &owned, 5, fuzzy_search::distance::levenshtein); + 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 index 860f543a99..6881eeb8c7 100644 --- a/crates/tracing-macro/src/instrument.rs +++ b/crates/tracing-macro/src/instrument.rs @@ -3,7 +3,7 @@ use quote::quote; use syn::parse::{Parse, ParseStream}; use syn::punctuated::Punctuated; use syn::spanned::Spanned; -use syn::{Expr, Ident, ItemFn, LitStr, ReturnType, Token}; +use syn::{Expr, Ident, ItemFn, LitStr, PathSegment, ReturnType, Token, Type}; // ── Name ────────────────────────────────────────────────────────────────────── @@ -25,6 +25,25 @@ impl Name { pub(crate) fn span(&self) -> Span { self.segments.span() } + + /// Validates this name against the OTel 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 OTel allowlist{hint}")) + })?; + Ok(CheckedName { dotted, span }) + } } impl Parse for Name { @@ -39,13 +58,27 @@ impl Parse for Name { } } +// ── CheckedName ─────────────────────────────────────────────────────────────── + +/// A field name that has been validated against the OTel 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 `%` Display modifier +/// 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, @@ -53,7 +86,16 @@ struct Value { impl Parse for Value { fn parse(input: ParseStream) -> syn::Result { - let display_modifier = input.parse::().ok(); + // 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 }) } @@ -63,21 +105,20 @@ impl Parse for Value { /// A single `dotted-name = [%] expr` pair inside the attribute list. /// -/// The `name` is validated against the OTel allowlist before code is emitted. +/// The `name` has been validated against the OTel allowlist at parse time. /// Both `account.id = id` (Debug) and `account.id = %id` (Display) are accepted. struct Field { - name: Name, - _eq: Token![=], + name: CheckedName, value: Value, } impl Parse for Field { fn parse(input: ParseStream) -> syn::Result { - Ok(Field { - name: input.parse()?, - _eq: input.parse()?, - value: input.parse()?, - }) + let raw: Name = input.parse()?; + let name = raw.check()?; + let _eq: Token![=] = input.parse()?; + let value: Value = input.parse()?; + Ok(Field { name, value }) } } @@ -130,15 +171,46 @@ impl Parse for Element { /// 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("my-rpc") → target = "my-rpc" +/// #[instrument(rpc: …)] → Ident("rpc") → target = "rpc" +/// #[instrument("my-rpc": …)] → Literal → target = "my-rpc" /// ``` -enum ComponentName { +pub(crate) enum ComponentName { Literal(LitStr), Ident(Ident), } +impl ComponentName { + /// Emits `target = "…",` for use in `#[tracing::instrument(…)]`. + pub(crate) fn to_span_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, } + }, + } + } + + /// 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. @@ -192,59 +264,34 @@ impl Parse for InstrumentArgs { } } -// ── Returns-Result helper ───────────────────────────────────────────────────── - -/// Returns `true` if the function's return type token stream contains the word -/// `Result`. Syntactic check only without any type resolution! -fn returns_result(item: &ItemFn) -> bool { - match &item.sig.output { - ReturnType::Default => false, - ReturnType::Type(_, ty) => { - let s = quote! { #ty }.to_string(); - s.contains("Result") // TODO be more accurate here what we support - }, - } -} +// ── Result-return detection ─────────────────────────────────────────────────── -// ── allowlist check ─────────────────────────────────────────────────────────── - -/// Validates `name` against the OTel field allowlist (`allowlist.txt`). +/// Returns `true` when the function's outermost return type is `Result<…>`. /// -/// On failure, emits a [`syn::Error`] anchored at the name's span. If the -/// fuzzy-search backend finds close matches in the allowlist they are included in -/// the error message as suggestions. -fn check_allowlist(name: &Name) -> syn::Result<()> { - crate::allowed::check(name).map_err(|suggestions| { - let dotted = name.to_dotted_string(); - let hint = if suggestions.is_empty() { - String::new() - } else { - format!(" – did you mean: {}?", suggestions.join(", ")) - }; - syn::Error::new( - name.span(), - format!("`{dotted}` is not in the open telemetry allowlist: {hint}"), - ) - }) -} +/// 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). +fn has_result_return_type(item: &ItemFn) -> bool { + let ty = match &item.sig.output { + ReturnType::Default => return false, + ReturnType::Type(_, ty) => ty.as_ref(), + }; -// ── codegen helpers ─────────────────────────────────────────────────────────── + let Type::Path(type_path) = ty else { + return false; + }; -/// Converts the optional component into a `target = "…",` token fragment for -/// insertion into `#[tracing::instrument(…)]`. Returns `None` when no component -/// was specified so that `tracing` falls back to the default (module path). -fn component_target(component: &Option) -> Option { - match component { - Some(ComponentName::Literal(lit)) => Some(quote! { target = #lit, }), - Some(ComponentName::Ident(ident)) => { - let s = ident.to_string(); - let lit = LitStr::new(&s, ident.span()); - Some(quote! { target = #lit, }) - }, - None => None, - } + type_path + .path + .segments + .last() + .map(|PathSegment { ident, .. }| ident == "Result") + .unwrap_or(false) } +// ── codegen helpers ─────────────────────────────────────────────────────────── + /// Converts the collected `Field` entries into a `fields(…),` token fragment. /// /// Each field is emitted as `"dotted.name" = [%] expr`. The string-literal form @@ -256,8 +303,7 @@ fn fields_tokens(fields: &[&Field]) -> TokenStream2 { } let mut parts = Vec::new(); for f in fields { - let name_str = f.name.to_dotted_string(); - let name_lit = LitStr::new(&name_str, f.name.span()); + let name_lit = LitStr::new(&f.name.dotted, f.name.span); let expr = &f.value.expr; if f.value.display_modifier.is_some() { parts.push(quote! { #name_lit = %#expr }); @@ -323,7 +369,7 @@ pub fn instrument2(attr: TokenStream2, item: TokenStream2) -> syn::Result syn::Result syn::Result { - let name: Name = input.parse()?; + let raw: Name = input.parse()?; + let name = raw.check()?; let _eq: Token![=] = input.parse()?; // Collect the optional modifier (`%` or `?`) plus the value expression as @@ -37,7 +38,7 @@ impl Parse for LogField { let expr: Expr = input.parse()?; value_tokens.extend(quote! { #expr }); - Ok(LogField { name, _eq, value_tokens }) + Ok(LogField { name, value_tokens }) } } @@ -58,35 +59,17 @@ impl Parse for LogField { /// /// The `COMPONENT:` prefix maps to `target: "component"` in the emitted /// `tracing::!` call. Field names are validated against the OTel -/// allowlist. The trailing message (if any) is forwarded verbatim. +/// 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, - /// Validated, allowlisted structured fields. + /// 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, } -enum ComponentName { - Literal(LitStr), - Ident(Ident), -} - -impl ComponentName { - fn to_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, } - }, - } - } -} - impl Parse for LogArgs { fn parse(input: ParseStream) -> syn::Result { if input.is_empty() { @@ -154,20 +137,6 @@ impl Parse for LogArgs { } } -// ── allowlist check ─────────────────────────────────────────────────────────── - -fn check_allowlist(name: &Name) -> syn::Result<()> { - crate::allowed::check(name).map_err(|suggestions| { - let dotted = name.to_dotted_string(); - let hint = if suggestions.is_empty() { - String::new() - } else { - format!(" – did you mean: {}?", suggestions.join(", ")) - }; - syn::Error::new(name.span(), format!("`{dotted}` is not in the OTel allowlist{hint}")) - }) -} - // ── public entry point ──────────────────────────────────────────────────────── /// Parses and validates a log-macro call, then expands it to @@ -178,23 +147,17 @@ fn check_allowlist(name: &Name) -> syn::Result<()> { pub(crate) fn parse(level: &'static str, ts: TokenStream2) -> syn::Result { let args: LogArgs = syn::parse2(ts)?; - // Validate every field name against the OTel allowlist. - for field in &args.fields { - check_allowlist(&field.name)?; - } - let level_ident = syn::Ident::new(level, 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_target_tokens); + 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_str = f.name.to_dotted_string(); - let name_lit = LitStr::new(&name_str, f.name.span()); + let name_lit = LitStr::new(&f.name.dotted, f.name.span); let val = &f.value_tokens; quote! { #name_lit = #val } }) diff --git a/crates/tracing-macro/src/tests.rs b/crates/tracing-macro/src/tests.rs index 9077b2c8eb..23590dfa07 100644 --- a/crates/tracing-macro/src/tests.rs +++ b/crates/tracing-macro/src/tests.rs @@ -8,6 +8,28 @@ 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. @@ -142,6 +164,13 @@ fn instrument_allowlisted_field_display_value_succeeds() { 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 @@ -323,3 +352,57 @@ fn warn_component_nullifier_field_succeeds() { 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"); +} From 1c82fdefa4116d9ad201513bf5948e8b75dc474b Mon Sep 17 00:00:00 2001 From: Bernhard Schuster Date: Mon, 16 Mar 2026 14:51:03 +0100 Subject: [PATCH 09/12] ui tests --- Cargo.lock | 1 + Cargo.toml | 1 + crates/tracing-macro/Cargo.toml | 7 +-- crates/tracing-macro/README.md | 12 ++--- crates/tracing-macro/src/allowed.rs | 8 ++-- crates/tracing-macro/src/instrument.rs | 14 +++--- crates/tracing-macro/src/lib.rs | 20 ++++----- crates/tracing-macro/src/log.rs | 4 +- crates/tracing/Cargo.toml | 3 ++ crates/tracing/src/lib.rs | 12 +++-- crates/tracing/tests/ui.rs | 7 +++ .../dotted_field_not_in_allowlist.rs | 6 +++ .../dotted_field_not_in_allowlist.stderr | 5 +++ .../ui/instrument/err_requires_result.rs | 6 +++ .../ui/instrument/err_requires_result.stderr | 5 +++ .../ui/instrument/field_not_in_allowlist.rs | 6 +++ .../instrument/field_not_in_allowlist.stderr | 5 +++ .../ui/instrument/report_and_err_exclusive.rs | 8 ++++ .../report_and_err_exclusive.stderr | 7 +++ .../ui/instrument/report_requires_result.rs | 6 +++ .../instrument/report_requires_result.stderr | 5 +++ .../instrument/ret_report_requires_result.rs | 6 +++ .../ret_report_requires_result.stderr | 5 +++ .../ui/log/component_with_unlisted_field.rs | 5 +++ .../log/component_with_unlisted_field.stderr | 5 +++ .../ui/log/dotted_field_not_in_allowlist.rs | 5 +++ .../log/dotted_field_not_in_allowlist.stderr | 5 +++ .../tests/ui/log/field_not_in_allowlist.rs | 5 +++ .../ui/log/field_not_in_allowlist.stderr | 5 +++ crates/tracing/tests/ui/pass/instrument.rs | 44 +++++++++++++++++++ crates/tracing/tests/ui/pass/log.rs | 17 +++++++ 31 files changed, 211 insertions(+), 39 deletions(-) create mode 100644 crates/tracing/tests/ui.rs create mode 100644 crates/tracing/tests/ui/instrument/dotted_field_not_in_allowlist.rs create mode 100644 crates/tracing/tests/ui/instrument/dotted_field_not_in_allowlist.stderr create mode 100644 crates/tracing/tests/ui/instrument/err_requires_result.rs create mode 100644 crates/tracing/tests/ui/instrument/err_requires_result.stderr create mode 100644 crates/tracing/tests/ui/instrument/field_not_in_allowlist.rs create mode 100644 crates/tracing/tests/ui/instrument/field_not_in_allowlist.stderr create mode 100644 crates/tracing/tests/ui/instrument/report_and_err_exclusive.rs create mode 100644 crates/tracing/tests/ui/instrument/report_and_err_exclusive.stderr create mode 100644 crates/tracing/tests/ui/instrument/report_requires_result.rs create mode 100644 crates/tracing/tests/ui/instrument/report_requires_result.stderr create mode 100644 crates/tracing/tests/ui/instrument/ret_report_requires_result.rs create mode 100644 crates/tracing/tests/ui/instrument/ret_report_requires_result.stderr create mode 100644 crates/tracing/tests/ui/log/component_with_unlisted_field.rs create mode 100644 crates/tracing/tests/ui/log/component_with_unlisted_field.stderr create mode 100644 crates/tracing/tests/ui/log/dotted_field_not_in_allowlist.rs create mode 100644 crates/tracing/tests/ui/log/dotted_field_not_in_allowlist.stderr create mode 100644 crates/tracing/tests/ui/log/field_not_in_allowlist.rs create mode 100644 crates/tracing/tests/ui/log/field_not_in_allowlist.stderr create mode 100644 crates/tracing/tests/ui/pass/instrument.rs create mode 100644 crates/tracing/tests/ui/pass/log.rs diff --git a/Cargo.lock b/Cargo.lock index 13afb8f0d1..6528729de3 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -3192,6 +3192,7 @@ dependencies = [ "miden-node-utils", "opentelemetry", "tracing", + "trybuild", ] [[package]] diff --git a/Cargo.toml b/Cargo.toml index b2f85669db..484bced4e1 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -66,6 +66,7 @@ miden-remote-prover-client = { path = "crates/remote-prover-client", versio # is part of `rocksdb-rust` release miden-node-rocksdb-cxx-linkage-fix = { path = "crates/rocksdb-cxx-linkage-fix", version = "=0.14.0-alpha.1" } miden-node-tracing-macro = { path = "crates/tracing-macro", version = "=0.14.0-alpha.1" } +trybuild = { version = "1.0", features = ["diff"] } # miden-base aka protocol dependencies. These should be updated in sync. miden-block-prover = { version = "=0.14.0-alpha.1" } diff --git a/crates/tracing-macro/Cargo.toml b/crates/tracing-macro/Cargo.toml index 01710aa233..3142cfb360 100644 --- a/crates/tracing-macro/Cargo.toml +++ b/crates/tracing-macro/Cargo.toml @@ -18,7 +18,8 @@ workspace = true proc-macro = true [dependencies] -proc-macro2 = "1.0" -quote = "1.0" -syn = { features = ["extra-traits", "full", "parsing"], version = "2.0" } +proc-macro2 = "1.0" +quote = "1.0" +syn = { features = ["extra-traits", "full", "parsing"], version = "2.0" } fuzzy-search = "0.1.0" + diff --git a/crates/tracing-macro/README.md b/crates/tracing-macro/README.md index 2687cb8eea..e9525551a8 100644 --- a/crates/tracing-macro/README.md +++ b/crates/tracing-macro/README.md @@ -11,7 +11,7 @@ which re-exports every macro here together with all required runtime dependencie ## `#[instrument]` Instruments a function with a [`tracing`] span. Extends `tracing::instrument` -with a component-target shorthand, an OTel field allowlist, and a `report` +with a component-target shorthand, an OpenTelemetry field allowlist, and a `report` keyword for full error-chain capture. ### Syntax @@ -32,7 +32,7 @@ dotted-name ::= ident ["." ident]* -- must appear in allowlist.txt |---|---|---| | `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 OTel span status to `Error`. Mutually exclusive with `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 @@ -53,7 +53,7 @@ is a compile error; the macro suggests the closest allowlisted names. | `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 + OTel status | +| `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) | @@ -75,7 +75,7 @@ is a compile error; the macro suggests the closest allowlisted names. |---|---|---| | Mechanism | `tracing::instrument` built-in | Custom body wrapper | | Error detail | Top-level `Display`/`Debug` | Full chain via `ErrorReport::as_report()` | -| OTel span status | Not set | Set to `Error` | +| OpenTelemetry span status | Not set | Set to `Error` | | Event level | `ERROR` | `ERROR` | Use `err` for lightweight internal helpers. Use `report` on RPC handlers and @@ -102,7 +102,7 @@ fn compute() -> u32 { 42 } #[instrument(store: err)] async fn load() -> Result { todo!() } -// Full error chain + OTel span status. +// Full error chain + OpenTelemetry span status. #[instrument(rpc: report)] async fn apply_block(block: Block) -> Result<(), ApplyBlockError> { todo!() } @@ -140,7 +140,7 @@ 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 OTel allowlist; +`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!` diff --git a/crates/tracing-macro/src/allowed.rs b/crates/tracing-macro/src/allowed.rs index 7f9892ffb4..a7ce8f2b93 100644 --- a/crates/tracing-macro/src/allowed.rs +++ b/crates/tracing-macro/src/allowed.rs @@ -4,7 +4,7 @@ use fuzzy_search::basic::fuzzy_search; const ALLOW_LIST: &str = include_str!("../allowlist.txt"); -/// Set of permitted otel field names, copied into the binary `allowlist.txt`. +/// Set of permitted OpenTelemetry field names, copied into the binary `allowlist.txt`. /// /// Lines that are empty or start with `#` are ignored. /// @@ -14,7 +14,7 @@ const ALLOW_LIST: &str = include_str!("../allowlist.txt"); /// baz_anything_goes /// technically.🪤.works.but.really.you_should_not /// ``` -static ALLOWED_OTEL_NAMES: LazyLock> = LazyLock::new(|| { +static ALLOWED_OPENTELEMETRY_NAMES: LazyLock> = LazyLock::new(|| { Vec::from_iter( ALLOW_LIST .lines() @@ -28,11 +28,11 @@ static ALLOWED_OTEL_NAMES: LazyLock> = LazyLock::new(|| { /// 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_OTEL_NAMES.contains(&dotted) { + if ALLOWED_OPENTELEMETRY_NAMES.contains(&dotted) { return Ok(()); } - let owned: Vec = ALLOWED_OTEL_NAMES.iter().map(|s| s.to_string()).collect(); + 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 index 6881eeb8c7..cc3324a3f0 100644 --- a/crates/tracing-macro/src/instrument.rs +++ b/crates/tracing-macro/src/instrument.rs @@ -26,7 +26,7 @@ impl Name { self.segments.span() } - /// Validates this name against the OTel allowlist and, on success, returns a + /// 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 @@ -40,7 +40,7 @@ impl Name { } else { format!(" – did you mean: {}?", suggestions.join(", ")) }; - syn::Error::new(span, format!("`{dotted}` is not in the OTel allowlist{hint}")) + syn::Error::new(span, format!("`{dotted}` is not in the OpenTelemetry allowlist{hint}")) })?; Ok(CheckedName { dotted, span }) } @@ -60,7 +60,7 @@ impl Parse for Name { // ── CheckedName ─────────────────────────────────────────────────────────────── -/// A field name that has been validated against the OTel allowlist. +/// 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. @@ -105,7 +105,7 @@ impl Parse for Value { /// A single `dotted-name = [%] expr` pair inside the attribute list. /// -/// The `name` has been validated against the OTel allowlist at parse time. +/// 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, @@ -131,7 +131,7 @@ impl Parse for Field { /// `Field` parse. Any other leading identifier is treated as the start of a /// `name = value` field entry. enum Element { - /// A `dotted-name = [%] expr` field (validated against the OTel allowlist). + /// A `dotted-name = [%] expr` field (validated against the OpenTelemetry allowlist). Field(Field), /// `ret` – record the function's return value inside the span. Ret, @@ -139,7 +139,7 @@ enum Element { /// Delegates to `tracing::instrument`'s built-in `err`. Requires `Result`. Err, /// `report` – on `Err`, walk the full error chain via [`ErrorReport`] and set - /// the OTel span status. Mutually exclusive with `err`. Requires `Result`. + /// the OpenTelemetry span status. Mutually exclusive with `err`. Requires `Result`. Report, } @@ -436,7 +436,7 @@ pub fn instrument2(attr: TokenStream2, item: TokenStream2) -> syn::Result!` syntax but additionally -//! enforce the same `COMPONENT:` target shorthand and OTel field allowlist as `#[instrument]`. +//! enforce the same `COMPONENT:` target shorthand and OpenTelemetry field allowlist as `#[instrument]`. //! //! # `#[instrument]` – complete reference //! @@ -52,7 +52,7 @@ //! | `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 OTel span status | +//! | `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) | @@ -61,8 +61,8 @@ //! | `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 OTel allowlist | -//! | `rpc: foo.bar.baz = %id` | any | ✗ | Compile error: `foo.bar.baz` not in OTel allowlist | +//! | `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 | @@ -77,7 +77,7 @@ //! |---|---|---| //! | 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) | -//! | OTel span status | not set | set to `Error` with the full report string | +//! | 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 @@ -121,7 +121,7 @@ //! # Log macros – complete reference //! //! `error!`, `warn!`, `info!`, `debug!`, `trace!` enforce the same `COMPONENT:` -//! target shorthand and OTel field allowlist as `#[instrument]`, then expand to +//! target shorthand and OpenTelemetry field allowlist as `#[instrument]`, then expand to //! the underlying `tracing::!` macro. //! //! ## Syntax @@ -225,7 +225,7 @@ mod tests; /// #[instrument(store: err)] /// async fn load() -> Result { … } /// -/// // Full error chain + OTel span status. +/// // Full error chain + OpenTelemetry span status. /// #[instrument(rpc: report)] /// async fn apply_block(&self, block: Block) -> Result<(), ApplyBlockError> { … } /// @@ -233,7 +233,7 @@ mod tests; /// #[instrument(rpc: ret, report)] /// async fn fetch_count() -> Result { … } /// -/// // Attach an allowlisted OTel field (Display format). +/// // Attach an allowlisted OpenTelemetry field (Display format). /// #[instrument(rpc: account.id = %account_id, report)] /// async fn get_account(account_id: AccountId) -> Result { … } /// diff --git a/crates/tracing-macro/src/log.rs b/crates/tracing-macro/src/log.rs index ce75ef8439..0d4bf94471 100644 --- a/crates/tracing-macro/src/log.rs +++ b/crates/tracing-macro/src/log.rs @@ -10,7 +10,7 @@ use crate::instrument::{CheckedName, ComponentName, Name}; /// 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 OTel allowlist +/// `tracing`'s own syntax. The field name is validated against the OpenTelemetry allowlist /// at parse time via [`Name::check`]. struct LogField { name: CheckedName, @@ -58,7 +58,7 @@ impl Parse for LogField { /// ``` /// /// The `COMPONENT:` prefix maps to `target: "component"` in the emitted -/// `tracing::!` call. Field names are validated against the OTel +/// `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. diff --git a/crates/tracing/Cargo.toml b/crates/tracing/Cargo.toml index f3e4637162..e9b1887231 100644 --- a/crates/tracing/Cargo.toml +++ b/crates/tracing/Cargo.toml @@ -19,3 +19,6 @@ miden-node-tracing-macro = { workspace = true } miden-node-utils = { workspace = true } opentelemetry = { version = "0.31" } tracing = { workspace = true } + +[dev-dependencies] +trybuild = { workspace = true } diff --git a/crates/tracing/src/lib.rs b/crates/tracing/src/lib.rs index 3c03acdc9d..85d6d4845d 100644 --- a/crates/tracing/src/lib.rs +++ b/crates/tracing/src/lib.rs @@ -21,14 +21,12 @@ //! caused by: SQLite error: table 'blocks' has 10 columns but 9 values were supplied //! ``` -// Re-export the instrument macro -pub use miden_node_tracing_macro::instrument; -// Re-export ErrorReport from miden-node-utils +pub use miden_node_tracing_macro::{debug, error, info, instrument, trace, warn}; pub use miden_node_utils::ErrorReport; -// Re-export OpenTelemetrySpanExt from miden-node-utils pub use miden_node_utils::tracing::OpenTelemetrySpanExt; -// Re-export OpenTelemetry types needed by the macro +#[doc(hidden)] pub use opentelemetry::trace::Status as OtelStatus; +#[doc(hidden)] pub use tracing::field::Empty as FieldEmpty; -// Re-export tracing types needed by the macro -pub use tracing::{Instrument, Level, Span, error, event}; +#[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_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_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..e73cf71f79 --- /dev/null +++ b/crates/tracing/tests/ui/pass/instrument.rs @@ -0,0 +1,44 @@ +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() {} + +// 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(()) } + +fn main() {} diff --git a/crates/tracing/tests/ui/pass/log.rs b/crates/tracing/tests/ui/pass/log.rs new file mode 100644 index 0000000000..01fdc1ef71 --- /dev/null +++ b/crates/tracing/tests/ui/pass/log.rs @@ -0,0 +1,17 @@ +use miden_node_tracing::{debug, error, info, trace, warn}; + +fn main() { + // plain message at each level + error!("hard failure"); + warn!("something looks off"); + info!("block applied"); + debug!("trace point"); + trace!("tick"); + + // format string at each level + error!("failed after {} retries", 3); + warn!("retrying after {}ms", 100); + info!("migrated {} rows", 42usize); + debug!("response size: {}", 128usize); + trace!("entering handler: {}", "foo"); +} From 7cd2987779d539c1096776285397c1237c12bdb5 Mon Sep 17 00:00:00 2001 From: Bernhard Schuster Date: Mon, 16 Mar 2026 15:56:15 +0100 Subject: [PATCH 10/12] better samples --- crates/tracing/tests/ui/pass/log.rs | 58 ++++++++++++++++++++++++++--- 1 file changed, 53 insertions(+), 5 deletions(-) diff --git a/crates/tracing/tests/ui/pass/log.rs b/crates/tracing/tests/ui/pass/log.rs index 01fdc1ef71..d5bc1861a8 100644 --- a/crates/tracing/tests/ui/pass/log.rs +++ b/crates/tracing/tests/ui/pass/log.rs @@ -1,17 +1,65 @@ use miden_node_tracing::{debug, error, info, trace, warn}; fn main() { - // plain message at each level + // ── plain message ───────────────────────────────────────────────────────── + error!("hard failure"); warn!("something looks off"); info!("block applied"); debug!("trace point"); trace!("tick"); - // format string at each level + // ── format string ───────────────────────────────────────────────────────── + error!("failed after {} retries", 3); - warn!("retrying after {}ms", 100); + warn!("retrying after {}ms", 100u64); info!("migrated {} rows", 42usize); - debug!("response size: {}", 128usize); - trace!("entering handler: {}", "foo"); + 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); + + // ── allowlisted dotted field, Display ───────────────────────────────────── + + warn!(account.id = %1u64, "unexpected account"); + error!(nullifier.id = %2u64, "double spend"); + info!(block.number = 3u32, "block committed"); + + // ── allowlisted dotted field, Debug ─────────────────────────────────────── + + warn!(account.id = 1u64, "unexpected account"); + debug!(block.number = 3u32, "processing"); + + // ── allowlisted dotted field, explicit Debug ────────────────────────────── + + trace!(nullifier.id = ?2u64, "lookup"); + + // ── multiple allowlisted fields + message ───────────────────────────────── + + 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); } From f0db5df87e58732f5c99955e52b2e7eb4257181b Mon Sep 17 00:00:00 2001 From: Bernhard Schuster Date: Mon, 16 Mar 2026 16:38:13 +0100 Subject: [PATCH 11/12] futures --- crates/tracing-macro/src/instrument.rs | 82 ++++++++++++++++++- crates/tracing-macro/src/log.rs | 15 ++-- crates/tracing-macro/src/tests.rs | 91 ++++++++++++++++++++-- crates/tracing/tests/ui/pass/instrument.rs | 7 ++ crates/tracing/tests/ui/pass/log.rs | 26 ++++--- 5 files changed, 198 insertions(+), 23 deletions(-) diff --git a/crates/tracing-macro/src/instrument.rs b/crates/tracing-macro/src/instrument.rs index cc3324a3f0..09eba911b9 100644 --- a/crates/tracing-macro/src/instrument.rs +++ b/crates/tracing-macro/src/instrument.rs @@ -3,7 +3,7 @@ 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}; +use syn::{Expr, Ident, ItemFn, LitStr, PathSegment, ReturnType, Token, Type, TypeImplTrait}; // ── Name ────────────────────────────────────────────────────────────────────── @@ -272,6 +272,10 @@ impl Parse for InstrumentArgs { /// 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, @@ -290,6 +294,77 @@ fn has_result_return_type(item: &ItemFn) -> bool { .unwrap_or(false) } +/// 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 ─────────────────────────────────────────────────────────── /// Converts the collected `Field` entries into a `fields(…),` token fragment. @@ -399,6 +474,11 @@ pub fn instrument2(attr: TokenStream2, item: TokenStream2) -> syn::Result!(target: "…", field = value, …, "message", …)`. +/// `::tracing::event!(target: "…", Level::LEVEL, field = value, …, "message", …)`. /// -/// Called by all five log proc-macros (`error!`, `warn!`, `info!`, `debug!`, -/// `trace!`). +/// [`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)?; - let level_ident = syn::Ident::new(level, proc_macro2::Span::call_site()); + // `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); @@ -172,6 +177,6 @@ pub(crate) fn parse(level: &'static str, ts: TokenStream2) -> syn::Result, expected_level: &str) { #[test] fn error_level_dispatch() { - assert_level(error2(quote! { "msg" }), "error"); + assert_level(error2(quote! { "msg" }), "ERROR"); } #[test] fn warn_level_dispatch() { - assert_level(warn2(quote! { "msg" }), "warn"); + assert_level(warn2(quote! { "msg" }), "WARN"); } #[test] fn info_level_dispatch() { - assert_level(info2(quote! { "msg" }), "info"); + assert_level(info2(quote! { "msg" }), "INFO"); } #[test] fn debug_level_dispatch() { - assert_level(debug2(quote! { "msg" }), "debug"); + assert_level(debug2(quote! { "msg" }), "DEBUG"); } #[test] fn trace_level_dispatch() { - assert_level(trace2(quote! { "msg" }), "trace"); + 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/tests/ui/pass/instrument.rs b/crates/tracing/tests/ui/pass/instrument.rs index e73cf71f79..360427aa7c 100644 --- a/crates/tracing/tests/ui/pass/instrument.rs +++ b/crates/tracing/tests/ui/pass/instrument.rs @@ -41,4 +41,11 @@ fn with_ret_report() -> Result { Ok(42) } #[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/log.rs b/crates/tracing/tests/ui/pass/log.rs index d5bc1861a8..21225b26f0 100644 --- a/crates/tracing/tests/ui/pass/log.rs +++ b/crates/tracing/tests/ui/pass/log.rs @@ -38,22 +38,20 @@ fn main() { warn!("block-producer": "batch timeout"); info!("block-producer": "produced block {}", 42u32); - // ── allowlisted dotted field, Display ───────────────────────────────────── + // ── component + allowlisted dotted fields + message ─────────────────────── - warn!(account.id = %1u64, "unexpected account"); - error!(nullifier.id = %2u64, "double spend"); - info!(block.number = 3u32, "block committed"); + 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"); - // ── allowlisted dotted field, Debug ─────────────────────────────────────── + // ── component + fields + format string ──────────────────────────────────── - warn!(account.id = 1u64, "unexpected account"); - debug!(block.number = 3u32, "processing"); + warn!(rpc: account.id = %1u64, "rejected after {} retries", 3u32); + info!(store: block.number = 3u32, "applied in {}ms", 12u64); - // ── allowlisted dotted field, explicit Debug ────────────────────────────── - - trace!(nullifier.id = ?2u64, "lookup"); - - // ── multiple allowlisted fields + message ───────────────────────────────── + // ── fields without component ────────────────────────────────────────────── warn!(account.id = %1u64, block.number = 3u32, "state inconsistency"); error!(nullifier.id = %2u64, block.number = 3u32, "double spend at block"); @@ -62,4 +60,8 @@ fn main() { warn!(account.id = %1u64, block.number = 3u32); info!(nullifier.id = %2u64); + + // ── component + fields only, no message ────────────────────────────────── + + warn!(rpc: account.id = %1u64, block.number = 3u32); } From 5ddbbc306710cc71d07a6764acc4879451b3470b Mon Sep 17 00:00:00 2001 From: Bernhard Schuster Date: Mon, 16 Mar 2026 16:53:37 +0100 Subject: [PATCH 12/12] actually add the ui test files --- .../tracing/tests/ui/instrument/report_on_impl_future.rs | 8 ++++++++ .../tests/ui/instrument/report_on_impl_future.stderr | 5 +++++ .../tests/ui/instrument/report_on_pin_box_future.rs | 8 ++++++++ .../tests/ui/instrument/report_on_pin_box_future.stderr | 5 +++++ 4 files changed, 26 insertions(+) create mode 100644 crates/tracing/tests/ui/instrument/report_on_impl_future.rs create mode 100644 crates/tracing/tests/ui/instrument/report_on_impl_future.stderr create mode 100644 crates/tracing/tests/ui/instrument/report_on_pin_box_future.rs create mode 100644 crates/tracing/tests/ui/instrument/report_on_pin_box_future.stderr 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>>> { + | ^^^