diff --git a/Cargo.lock b/Cargo.lock index 4912ac66bd..6528729de3 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", @@ -2945,6 +2955,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 +3014,7 @@ dependencies = [ "miden-node-db", "miden-node-proto", "miden-node-test-macro", + "miden-node-tracing", "miden-node-utils", "miden-protocol", "miden-remote-prover-client", @@ -3119,6 +3131,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 +3184,27 @@ 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", + "trybuild", +] + +[[package]] +name = "miden-node-tracing-macro" +version = "0.14.0-alpha.1" +dependencies = [ + "fuzzy-search", + "proc-macro2", + "quote", + "syn 2.0.114", +] + [[package]] name = "miden-node-utils" version = "0.14.0-alpha.1" @@ -4118,7 +4152,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", @@ -4140,7 +4174,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", @@ -4233,7 +4267,7 @@ dependencies = [ "quinn-udp", "rustc-hash", "rustls 0.23.36", - "socket2 0.5.10", + "socket2 0.6.2", "thiserror 2.0.18", "tokio", "tracing", @@ -4271,7 +4305,7 @@ dependencies = [ "cfg_aliases", "libc", "once_cell", - "socket2 0.5.10", + "socket2 0.6.2", "tracing", "windows-sys 0.60.2", ] diff --git a/Cargo.toml b/Cargo.toml index c263e4fdd3..484bced4e1 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,8 @@ 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" } +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" } @@ -71,6 +76,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..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,7 @@ use miden_tx_batch_prover::LocalBatchProver; use rand::Rng; use tokio::task::JoinSet; use tokio::time; -use tracing::{Instrument, Span, instrument}; +use tracing::{Instrument, Span}; use url::Url; use crate::domain::batch::SelectedBatch; diff --git a/crates/block-producer/src/validator/mod.rs b/crates/block-producer/src/validator/mod.rs index 9844e2d9b3..59e1d08348 100644 --- a/crates/block-producer/src/validator/mod.rs +++ b/crates/block-producer/src/validator/mod.rs @@ -1,10 +1,11 @@ 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 tracing::{info, instrument}; +use tracing::info; use url::Url; use crate::COMPONENT; 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/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..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 tracing::instrument; +use miden_node_tracing::instrument; use crate::COMPONENT; use crate::db::schema_hash::verify_schema; diff --git a/crates/tracing-macro/Cargo.toml b/crates/tracing-macro/Cargo.toml new file mode 100644 index 0000000000..3142cfb360 --- /dev/null +++ b/crates/tracing-macro/Cargo.toml @@ -0,0 +1,25 @@ +[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 = ["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 new file mode 100644 index 0000000000..e9525551a8 --- /dev/null +++ b/crates/tracing-macro/README.md @@ -0,0 +1,167 @@ +# miden-node-tracing-macro + +Internal procedural macro crate for `miden-node-tracing`. + +**Do not use this crate directly.** Import from `miden-node-tracing` instead, +which re-exports every macro here together with all required runtime dependencies +(`ErrorReport`, `OpenTelemetrySpanExt`, …). + +--- + +## `#[instrument]` + +Instruments a function with a [`tracing`] span. Extends `tracing::instrument` +with a component-target shorthand, an OpenTelemetry field allowlist, and a `report` +keyword for full error-chain capture. + +### Syntax + +```text +#[instrument] +#[instrument( [COMPONENT:] [element, …] )] + +COMPONENT ::= ident | "string literal" +element ::= field-entry | "ret" | "err" | "report" +field-entry ::= dotted-name "=" ["%"] expr +dotted-name ::= ident ["." ident]* -- must appear in allowlist.txt +``` + +### Keywords + +| Keyword | Requires `Result`? | Description | +|---|---|---| +| `ret` | no | Records the return value inside the span | +| `err` | yes | Emits a tracing event with the top-level error message (delegates to `tracing::instrument`'s built-in `err`) | +| `report` | yes | Emits an `error!` event with the **full error chain** via `ErrorReport::as_report()` and sets the OpenTelemetry span status to `Error`. Mutually exclusive with `err`. | + +### Field entries + +```rust +#[instrument(rpc: account.id = account_id)] // Debug → {:?} +#[instrument(rpc: account.id = %account_id)] // Display → {} +``` + +Field names must appear in [`allowlist.txt`](allowlist.txt). An undeclared name +is a compile error; the macro suggests the closest allowlisted names. + +### Full argument reference + +| Attribute | fn returns `Result`? | Valid? | Behaviour | +|---|---|---|---| +| *(empty)* | any | ✓ | Thin `#[tracing::instrument]` wrapper | +| `rpc:` | any | ✓ | Span with `target = "rpc"`, no field/ret tracking | +| `rpc: ret` | any | ✓ | `tracing::instrument` `ret` | +| `rpc: err` | yes | ✓ | `tracing::instrument` `err` (top-level message) | +| `rpc: err` | no | ✗ | `err` requires `Result` return | +| `rpc: report` | yes | ✓ | Full error chain + OpenTelemetry status | +| `rpc: report` | no | ✗ | `report` requires `Result` return | +| `rpc: err, report` | any | ✗ | Mutually exclusive | +| `rpc: report, err` | any | ✗ | Mutually exclusive (order irrelevant) | +| `rpc: ret, err` | yes | ✓ | Return value + top-level error | +| `rpc: ret, report` | yes | ✓ | Return value + full error chain | +| `rpc: ret, report` | no | ✗ | `report` requires `Result` return | +| `rpc: account.id = id` | any | ✓ | Allowlisted field, Debug | +| `rpc: account.id = %id` | any | ✓ | Allowlisted field, Display | +| `rpc: foo = id` | any | ✗ | `foo` not in allowlist | +| `rpc: foo.bar.baz = %id` | any | ✗ | `foo.bar.baz` not in allowlist | +| `rpc: account.id = %id, err` | yes | ✓ | Field + standard error | +| `rpc: account.id = %id, report` | yes | ✓ | Field + full error chain | +| `rpc: account.id = %id, ret, report` | yes | ✓ | Field + return value + full error chain | +| `rpc: account.id = %id, report, err` | yes | ✗ | Mutually exclusive | + +### `err` vs `report` + +| | `err` | `report` | +|---|---|---| +| Mechanism | `tracing::instrument` built-in | Custom body wrapper | +| Error detail | Top-level `Display`/`Debug` | Full chain via `ErrorReport::as_report()` | +| OpenTelemetry span status | Not set | Set to `Error` | +| Event level | `ERROR` | `ERROR` | + +Use `err` for lightweight internal helpers. Use `report` on RPC handlers and +any boundary where the full error chain must appear in telemetry. + +### Examples + +```rust +use miden_node_tracing::instrument; + +// Minimal – default target, no tracking. +#[instrument] +fn simple() {} + +// Component only. +#[instrument(rpc:)] +fn with_target() {} + +// Return value. +#[instrument(rpc: ret)] +fn compute() -> u32 { 42 } + +// Standard error (top-level message). +#[instrument(store: err)] +async fn load() -> Result { todo!() } + +// Full error chain + OpenTelemetry span status. +#[instrument(rpc: report)] +async fn apply_block(block: Block) -> Result<(), ApplyBlockError> { todo!() } + +// Return value + full error chain. +#[instrument(rpc: ret, report)] +async fn fetch_count() -> Result { todo!() } + +// Allowlisted field (Display) + full error chain. +#[instrument(rpc: account.id = %account_id, report)] +async fn get_account(account_id: AccountId) -> Result { todo!() } + +// Multiple allowlisted fields. +#[instrument(store: account.id = %account_id, block.number = block_num, err)] +async fn get_account_at( + account_id: AccountId, + block_num: BlockNumber, +) -> Result { todo!() } +``` + +--- + +## `warn!` / `error!` / `info!` / `debug!` / `trace!` + +These macros enforce the same rules as `#[instrument]` and then expand to the +underlying `tracing::!` macro. + +### Syntax + +```text +warn!( [COMPONENT:] [field = ["%"|"?"] expr ,]* [format_string [, args…]] ) + +COMPONENT ::= ident | string-literal +field-entry ::= dotted-name "=" ["%" | "?"] expr +dotted-name ::= ident ["." ident]* -- must appear in allowlist.txt +``` + +The optional `COMPONENT:` prefix sets the tracing target (e.g. `rpc:` → +`target: "rpc"`). Field names are validated against the OpenTelemetry allowlist; +an unlisted name is a compile error with fuzzy-matched suggestions. + +### Full argument reference for `warn!` + +| Form | Example | Valid? | +|---|---|---| +| Empty | `warn!()` | ✓ | +| Plain message | `warn!("something looks off")` | ✓ | +| Format string | `warn!("retrying after {}ms", delay_ms)` | ✓ | +| Component + message | `warn!(rpc: "request failed")` | ✓ | +| Component + format | `warn!(store: "migrated {} rows", n)` | ✓ | +| Component only | `warn!(rpc:)` | ✓ | +| Allowlisted field, Debug | `warn!(account.id = id, "context")` | ✓ | +| Allowlisted field, Display | `warn!(account.id = %id, "context")` | ✓ | +| Allowlisted field, Debug explicit | `warn!(account.id = ?id, "context")` | ✓ | +| Unlisted field | `warn!(foo = %x, "context")` | ✗ | +| Unlisted dotted field | `warn!(foo.bar = %x, "context")` | ✗ | +| Multiple allowlisted fields + message | `warn!(account.id = %id, block.number = n, "msg")` | ✓ | +| Fields only, no message | `warn!(account.id = %id, block.number = n)` | ✓ | +| Component + fields + message (full form) | `warn!(rpc: account.id = %id, "rejected")` | ✓ | +| Component + unlisted field | `warn!(rpc: foo = %x, "msg")` | ✗ | + +The same table applies to `error!`, `info!`, `debug!`, and `trace!` – only the +severity level differs. diff --git a/crates/tracing-macro/allowlist.txt b/crates/tracing-macro/allowlist.txt new file mode 100644 index 0000000000..72b2249dd1 --- /dev/null +++ b/crates/tracing-macro/allowlist.txt @@ -0,0 +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 new file mode 100644 index 0000000000..a7ce8f2b93 --- /dev/null +++ b/crates/tracing-macro/src/allowed.rs @@ -0,0 +1,38 @@ +use std::sync::LazyLock; + +use fuzzy_search::basic::fuzzy_search; + +const ALLOW_LIST: &str = include_str!("../allowlist.txt"); + +/// Set of permitted OpenTelemetry field names, copied into the binary `allowlist.txt`. +/// +/// Lines that are empty or start with `#` are ignored. +/// +/// Example: +/// ```text +/// foo.bar.baz +/// baz_anything_goes +/// technically.🪤.works.but.really.you_should_not +/// ``` +static ALLOWED_OPENTELEMETRY_NAMES: LazyLock> = LazyLock::new(|| { + Vec::from_iter( + ALLOW_LIST + .lines() + .map(|line| line.trim()) + .filter(|trimmed| !trimmed.is_empty() && !trimmed.starts_with('#')), + ) +}); + +/// Checks `dotted` against the open telemetry field allowlist. +/// +/// Succeeds when the given name is present in `allowlist.txt` verbatim, +/// otherwise provides suggestions in increasing levenshtein distance. +pub(crate) fn check(dotted: &str) -> Result<(), Vec> { + if ALLOWED_OPENTELEMETRY_NAMES.contains(&dotted) { + return Ok(()); + } + + let owned: Vec = ALLOWED_OPENTELEMETRY_NAMES.iter().map(|s| s.to_string()).collect(); + let suggestions = fuzzy_search(dotted, &owned, 5, fuzzy_search::distance::levenshtein); + Err(suggestions) +} diff --git a/crates/tracing-macro/src/instrument.rs b/crates/tracing-macro/src/instrument.rs new file mode 100644 index 0000000000..09eba911b9 --- /dev/null +++ b/crates/tracing-macro/src/instrument.rs @@ -0,0 +1,550 @@ +use proc_macro2::{Span, TokenStream as TokenStream2}; +use quote::quote; +use syn::parse::{Parse, ParseStream}; +use syn::punctuated::Punctuated; +use syn::spanned::Spanned; +use syn::{Expr, Ident, ItemFn, LitStr, PathSegment, ReturnType, Token, Type, TypeImplTrait}; + +// ── Name ────────────────────────────────────────────────────────────────────── + +/// An open telemetry like dotted identifier (e.g. `account.id`, `block.number`), parsed from +/// the attribute stream but **not yet** checked against the allowlist. +/// +/// Grammar: `ident ("." ident)*` +pub(crate) struct Name { + pub(crate) segments: Punctuated, +} + +impl Name { + /// Returns the dotted string representation, e.g. `"account.id"`. + pub(crate) fn to_dotted_string(&self) -> String { + self.segments.iter().map(|i| i.to_string()).collect::>().join(".") + } + + /// Span for the full name. + pub(crate) fn span(&self) -> Span { + self.segments.span() + } + + /// Validates this name against the OpenTelemetry allowlist and, on success, returns a + /// [`CheckedName`] that carries the pre-computed dotted string and span. + /// + /// On failure, emits a [`syn::Error`] anchored at the name's span. If the + /// fuzzy-search backend finds close matches they are included as suggestions. + pub(crate) fn check(self) -> syn::Result { + let dotted = self.to_dotted_string(); + let span = self.span(); + crate::allowed::check(&dotted).map_err(|suggestions| { + let hint = if suggestions.is_empty() { + String::new() + } else { + format!(" – did you mean: {}?", suggestions.join(", ")) + }; + syn::Error::new(span, format!("`{dotted}` is not in the OpenTelemetry allowlist{hint}")) + })?; + Ok(CheckedName { dotted, span }) + } +} + +impl Parse for Name { + fn parse(input: ParseStream) -> syn::Result { + let mut segments = Punctuated::new(); + segments.push_value(input.parse::()?); + while input.peek(Token![.]) { + segments.push_punct(input.parse::()?); + segments.push_value(input.parse::()?); + } + Ok(Name { segments }) + } +} + +// ── CheckedName ─────────────────────────────────────────────────────────────── + +/// A field name that has been validated against the OpenTelemetry allowlist. +/// +/// The only way to construct a `CheckedName` is via [`Name::check`], ensuring +/// that unchecked names can never reach codegen. +pub(crate) struct CheckedName { + /// Pre-computed dotted representation (e.g. `"account.id"`). + pub(crate) dotted: String, + /// Span of the original [`Name`] token, forwarded for error reporting. + pub(crate) span: Span, +} + +// ── Value ───────────────────────────────────────────────────────────────────── + +/// The right-hand side of a field assignment: an optional format modifier +/// followed by an arbitrary expression. +/// +/// - `= expr` → Debug format (`{:?}`) +/// - `= %expr` → Display format (`{}`) +/// - `= ?expr` → Debug format (`{:?}`), explicit +struct Value { + display_modifier: Option, + expr: Expr, +} + +impl Parse for Value { + fn parse(input: ParseStream) -> syn::Result { + // Consume `%` (Display) or `?` (Debug-explicit). Both are accepted for + // consistency with `tracing`'s own field syntax; only `%` affects the + // generated token (Debug is the default and needs no modifier token). + let display_modifier = if input.peek(Token![%]) { + Some(input.parse::()?) + } else { + // Consume and discard `?` so the following expr parses cleanly. + input.parse::().ok(); + None + }; + let expr = input.parse::()?; + Ok(Value { display_modifier, expr }) + } +} + +// ── Field entry ─────────────────────────────────────────────────────────────── + +/// A single `dotted-name = [%] expr` pair inside the attribute list. +/// +/// The `name` has been validated against the OpenTelemetry allowlist at parse time. +/// Both `account.id = id` (Debug) and `account.id = %id` (Display) are accepted. +struct Field { + name: CheckedName, + value: Value, +} + +impl Parse for Field { + fn parse(input: ParseStream) -> syn::Result { + let raw: Name = input.parse()?; + let name = raw.check()?; + let _eq: Token![=] = input.parse()?; + let value: Value = input.parse()?; + Ok(Field { name, value }) + } +} + +// ── Element ─────────────────────────────────────────────────────────────────── + +/// A single comma-separated element inside the `#[instrument(…)]` attribute. +/// +/// 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 OpenTelemetry 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 OpenTelemetry span status. Mutually exclusive with `err`. Requires `Result`. + Report, +} + +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. +/// +/// Used by both `#[instrument(…)]` and the log macros (`warn!`, `error!`, …), +/// but with different token syntax in the emitted output: +/// - span attributes use `=` (e.g. `target = "rpc"`) +/// - tracing events use `:` (e.g. `target: "rpc"`) +/// +/// ```text +/// #[instrument(rpc: …)] → Ident("rpc") → target = "rpc" +/// #[instrument("my-rpc": …)] → Literal → target = "my-rpc" +/// ``` +pub(crate) enum ComponentName { + Literal(LitStr), + Ident(Ident), +} + +impl ComponentName { + /// 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. +/// +/// 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 { + /// The `COMPONENT:` prefix, if present. Maps to `target = "…"` in the + /// underlying `tracing::instrument`. + component: Option, + /// Comma-separated elements following the optional component prefix. + elements: Vec, +} + +impl Parse for InstrumentArgs { + fn parse(input: ParseStream) -> syn::Result { + if input.is_empty() { + return Ok(InstrumentArgs { component: None, elements: Vec::new() }); + } + + // Detect `COMPONENT:` prefix: an ident (or string literal) followed by `:`. + // The colon disambiguates from `field = value` entries whose names also + // start with an ident. + 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 }) + } +} + +// ── Result-return detection ─────────────────────────────────────────────────── + +/// Returns `true` when the function's outermost return type is `Result<…>`. +/// +/// The check inspects the AST directly: it succeeds only when the return type +/// is a [`Type::Path`] whose last segment is literally named `Result`. This +/// avoids the false positive produced by a plain string-contains search (e.g. +/// a type named `NotAResult` would previously pass). +/// +/// `async fn` is handled transparently: `syn` represents the declared return +/// type (before desugaring to `impl Future`) directly, so `async fn foo() -> +/// Result` has `sig.output = Result` just like its sync equivalent. +fn has_result_return_type(item: &ItemFn) -> bool { + let ty = match &item.sig.output { + ReturnType::Default => return false, + ReturnType::Type(_, ty) => ty.as_ref(), + }; + + let Type::Path(type_path) = ty else { + return false; + }; + + type_path + .path + .segments + .last() + .map(|PathSegment { ident, .. }| ident == "Result") + .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. +/// +/// 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_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 }); + } else { + parts.push(quote! { #name_lit = #expr }); + } + } + quote! { fields(#(#parts),*), } +} + +// ── public entry point ──────────────────────────────────────────────────────── + +/// Core implementation of `#[instrument]`. +/// +/// # Validation +/// +/// | Condition | Error | +/// |---|---| +/// | `err` and `report` both present | mutually exclusive | +/// | `err` or `report` on a non-`Result` fn | `err`/`report` requires `Result` return | +/// | `ret` + `report` on a non-`Result` fn | same | +/// | field name not in `allowlist.txt` | open telemetry allowlist violation | +/// +/// # Code generation +/// +/// 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 + }); + } + + let args: InstrumentArgs = syn::parse2(attr)?; + let func: ItemFn = syn::parse2(item)?; + + // ── collect element kinds ────────────────────────────────────────────────── + let mut has_ret = false; + let mut has_err = false; + let mut has_report = false; + let mut fields: Vec<&Field> = Vec::new(); + + let elements = args.elements; + + 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), + } + } + + // ── validation ──────────────────────────────────────────────────────────── + + // err and report are mutually exclusive. + if has_err && has_report { + return Err(syn::Error::new( + Span::call_site(), + "`err` and `report` are mutually exclusive – use one or the other", + )); + } + + // Reject unsupported future-returning shapes before the Result check. + if has_err || has_report { + reject_future_return_type(&func)?; + } + + // err / report require a Result return type. + if (has_err || has_report) && !has_result_return_type(&func) { + return Err(syn::Error::new( + func.sig.ident.span(), + "`err` / `report` requires the function to return `Result`", + )); + } + + // Field names were already validated inside Field::parse via Name::check. + + // ── code generation ─────────────────────────────────────────────────────── + + let target_tokens = args.component.as_ref().map(ComponentName::to_span_target_tokens); + 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 OpenTelemetry 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 new file mode 100644 index 0000000000..c0e299c8ce --- /dev/null +++ b/crates/tracing-macro/src/lib.rs @@ -0,0 +1,391 @@ +//! Procedural macros for structured, OpenTelemetry-aware tracing in the Miden node. +//! +//! **Do not use this crate directly.** Import from `miden-node-tracing` instead, which +//! re-exports every macro here together with all required runtime dependencies +//! (`ErrorReport`, `OpenTelemetrySpanExt`, …). +//! +//! # Overview +//! +//! This crate provides two families of macros that mirror their counterparts in the +//! [`tracing`](https://docs.rs/tracing) crate but extend them with node-specific +//! conventions: +//! +//! | Macro | Purpose | +//! |---|---| +//! | [`#[instrument]`](macro@instrument) | Attribute macro – wraps a function in a tracing span | +//! | [`error!`], [`warn!`], [`info!`], [`debug!`], [`trace!`] | Function-like macros – emit a tracing event | +//! +//! ## Key differences from `tracing` +//! +//! 1. **Component target** – instead of `target = "some::module"` you write a short component name +//! once (`rpc:`, `store:`, …) and it becomes the span target. +//! 2. **`report` keyword** – a richer alternative to `tracing`'s `err` that walks the full +//! [`ErrorReport`] chain, emits a structured `error!` event *and* sets the OpenTelemetry span +//! status to `Error`. +//! 3. **OpenTelemetry field allowlist** – only names declared in `allowlist.txt` may appear as field keys, +//! preventing accidental cardinality explosions in the metrics / trace backend. +//! 4. **Log macros** – `warn!`, `error!`, etc. mirror `tracing::!` syntax but additionally +//! enforce the same `COMPONENT:` target shorthand and OpenTelemetry field allowlist as `#[instrument]`. +//! +//! # `#[instrument]` – complete reference +//! +//! ## Syntax +//! +//! ```text +//! #[instrument] +//! #[instrument( [COMPONENT:] [element, …] )] +//! +//! COMPONENT ::= ident | "string literal" +//! element ::= field-entry | "ret" | "err" | "report" +//! field-entry::= dotted-name "=" ["%"] expr +//! dotted-name::= ident ["." ident]* -- must be in allowlist.txt +//! ``` +//! +//! ## Combinatorial argument table +//! +//! Each row is a distinct, valid (✓) or invalid (✗) combination with the reason. +//! +//! | Attribute arguments | fn return type | Valid? | Notes | +//! |---|---|---|---| +//! | *(empty)* | any | ✓ | Thin wrapper around `#[tracing::instrument]` | +//! | `rpc:` *(no elements)* | any | ✓ | Sets `target = "rpc"`, no field/ret tracking | +//! | `rpc: ret` | any | ✓ | Records return value via `tracing::instrument`'s `ret` | +//! | `rpc: err` | `Result<_, E>` | ✓ | Delegates to `tracing::instrument`'s `err` (single-level `Display`/`Debug`) | +//! | `rpc: err` | non-`Result` | ✗ | Compile error: `err` requires `Result` return | +//! | `rpc: report` | `Result<_, E>` | ✓ | Walks full error chain via [`ErrorReport`], emits `error!` event, sets OpenTelemetry span status | +//! | `rpc: report` | non-`Result` | ✗ | Compile error: `report` requires `Result` return | +//! | `rpc: err, report` | any | ✗ | Compile error: mutually exclusive | +//! | `rpc: report, err` | any | ✗ | Compile error: mutually exclusive (order does not matter) | +//! | `rpc: ret, err` | `Result<_, E>` | ✓ | Records both return value and error via `tracing::instrument` | +//! | `rpc: ret, report` | `Result` | ✓ | Records return value (`ret`) + full error chain (`report`) | +//! | `rpc: ret, report` | non-`Result` | ✗ | Compile error: `report` requires `Result` return | +//! | `rpc: account.id = id` | any | ✓ | Attaches `account.id` field (Debug format, allowlisted) | +//! | `rpc: account.id = %id` | any | ✓ | Attaches `account.id` field (Display format via `%`) | +//! | `rpc: foo = id` | any | ✗ | Compile error: `foo` not in OpenTelemetry allowlist | +//! | `rpc: foo.bar.baz = %id` | any | ✗ | Compile error: `foo.bar.baz` not in OpenTelemetry allowlist | +//! | `rpc: account.id = %id, err` | `Result<_, E>` | ✓ | Allowlisted field + standard error tracking | +//! | `rpc: account.id = %id, report` | `Result<_, E>` | ✓ | Allowlisted field + full error chain | +//! | `rpc: account.id = %id, ret, report` | `Result` | ✓ | Field + return value + full error chain | +//! | `rpc: account.id = %id, report, err` | `Result<_, E>` | ✗ | Compile error: `report` and `err` are mutually exclusive | +//! +//! ## `err` vs `report` +//! +//! Both keywords require the function to return `Result`. They differ in *how much* of +//! the error is captured: +//! +//! | | `err` | `report` | +//! |---|---|---| +//! | Mechanism | delegates to `tracing::instrument`'s built-in `err` | custom body wrapper | +//! | Error formatting | top-level `Display` or `Debug` only | full chain via [`ErrorReport::as_report`] (every `source()` cause) | +//! | OpenTelemetry span status | not set | set to `Error` with the full report string | +//! | tracing event level | `ERROR` (tracing default) | `ERROR` | +//! +//! Use `err` for lightweight internal helpers where the single-level message is +//! sufficient. Use `report` on RPC handlers, block application paths, and any boundary +//! where the full error chain must appear in the telemetry. +//! +//! ## Field values and the `%` modifier +//! +//! A field entry `name = expr` records `expr` using its `Debug` implementation. +//! Prefixing the value with `%` switches to `Display`: +//! +//! ```rust,ignore +//! #[instrument(rpc: account.id = account_id)] // Debug → {:?} +//! #[instrument(rpc: account.id = %account_id)] // Display → {} +//! ``` +//! +//! All field names must appear in `allowlist.txt`. An attempt to use an unlisted name +//! produces a compile error with fuzzy-matched suggestions. +//! +//! ## Component name +//! +//! The component prefix sets `target` in the underlying `tracing::instrument` span. +//! It can be an identifier or a string literal: +//! +//! ```rust,ignore +//! #[instrument(rpc: ret)] // target = "rpc" +//! #[instrument("my-rpc": ret)] // target = "my-rpc" +//! ``` +//! +//! When omitted, no `target` override is emitted and tracing uses the default +//! (module path). +//! +//! ## Code generation summary +//! +//! | Combination | Generated code shape | +//! |---|---| +//! | empty attrs | `#[::tracing::instrument] fn …` | +//! | component only / fields / `ret` / `err` | `#[::tracing::instrument(target=…, skip_all?, fields(…)?, ret?, err?)] fn …` | +//! | `report` | `#[::tracing::instrument(…)] fn … { let __result = { … }; if Err(e) { error!(…); set_error(…); } __result }` | +//! +//! # Log macros – complete reference +//! +//! `error!`, `warn!`, `info!`, `debug!`, `trace!` enforce the same `COMPONENT:` +//! target shorthand and OpenTelemetry field allowlist as `#[instrument]`, then expand to +//! the underlying `tracing::!` macro. +//! +//! ## Syntax +//! +//! ```text +//! warn!( [COMPONENT:] [field = ["%" | "?"] expr ,]* [format_str [, args…]] ) +//! +//! COMPONENT ::= ident | string-literal +//! field-entry ::= dotted-name "=" ["%" | "?"] expr +//! dotted-name ::= ident ["." ident]* -- must appear in allowlist.txt +//! ``` +//! +//! ## Combinatorial argument table for `warn!` +//! +//! | Call form | Example | Valid? | Notes | +//! |---|---|---|---| +//! | message only | `warn!("something odd")` | ✓ | Plain string literal, no component or fields | +//! | format string | `warn!("retrying after {}ms", delay)` | ✓ | `format_args!`-style | +//! | component + message | `warn!(rpc: "something odd")` | ✓ | Emits `target: "rpc"` | +//! | component + format | `warn!(store: "migrated {} rows", n)` | ✓ | | +//! | allowlisted field, Debug | `warn!(account.id = id, "context")` | ✓ | `{:?}` format | +//! | allowlisted field, Display | `warn!(account.id = %id, "context")` | ✓ | `{}` format via `%` | +//! | allowlisted field, Debug explicit | `warn!(account.id = ?id, "context")` | ✓ | `{:?}` format via `?` | +//! | unlisted field | `warn!(foo = %x, "context")` | ✗ | Compile error: `foo` not in allowlist | +//! | unlisted dotted field | `warn!(foo.bar = %x, "context")` | ✗ | Compile error: `foo.bar` not in allowlist | +//! | multiple allowlisted fields | `warn!(account.id = %id, block.number = n, "msg")` | ✓ | Any number of allowlisted fields | +//! | fields only, no message | `warn!(account.id = %id, block.number = n)` | ✓ | Structured event, no message string | +//! | component + fields + message | `warn!(rpc: account.id = %id, "rejected")` | ✓ | Full form | +//! | component + unlisted field | `warn!(rpc: foo = %x, "msg")` | ✗ | Compile error: allowlist applies regardless of component | + +use proc_macro::TokenStream; +use proc_macro2::TokenStream as TokenStream2; + +mod allowed; +mod instrument; +mod log; + +#[cfg(test)] +mod tests; + +/// Instruments a function with a [`tracing`] span, with node-specific extensions. +/// +/// # Syntax +/// +/// ```text +/// #[instrument] +/// #[instrument( [COMPONENT:] [element, …] )] +/// +/// 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 + OpenTelemetry span status. +/// #[instrument(rpc: report)] +/// async fn apply_block(&self, block: Block) -> Result<(), ApplyBlockError> { … } +/// +/// // Return value tracking combined with full error chain. +/// #[instrument(rpc: ret, report)] +/// async fn fetch_count() -> Result { … } +/// +/// // Attach an allowlisted OpenTelemetry field (Display format). +/// #[instrument(rpc: account.id = %account_id, report)] +/// async fn get_account(account_id: AccountId) -> Result { … } +/// +/// // Multiple fields. +/// #[instrument(store: account.id = %account_id, block.number = block_num, err)] +/// async fn get_account_at( +/// account_id: AccountId, +/// block_num: BlockNumber, +/// ) -> Result { … } +/// ``` +#[proc_macro_attribute] +pub fn instrument(attr: TokenStream, item: TokenStream) -> TokenStream { + match instrument::instrument2(TokenStream2::from(attr), TokenStream2::from(item)) { + Ok(ts) => ts.into(), + Err(e) => e.to_compile_error().into(), + } +} + +/// Emits a tracing event at the `ERROR` level. +/// +/// Accepts the same syntax as [`warn!`]: optional `COMPONENT:` target, then +/// zero or more allowlisted `field = [%|?] expr` pairs, then an optional +/// message string with format arguments. +/// +/// # Examples +/// +/// ```rust,ignore +/// use miden_node_tracing::error; +/// +/// error!("something went wrong"); +/// error!(rpc: "request failed"); +/// error!(rpc: account.id = %id, "request failed"); +/// error!("value was {}", x); +/// ``` +#[proc_macro] +pub fn error(ts: TokenStream) -> TokenStream { + match log::parse("error", ts.into()) { + Ok(ts) => ts.into(), + Err(e) => e.to_compile_error().into(), + } +} + +/// Emits a tracing event at the `WARN` level. +/// +/// # Syntax +/// +/// ```text +/// warn!( [COMPONENT:] [field = ["%"|"?"] expr ,]* [format_str [, args…]] ) +/// ``` +/// +/// The optional `COMPONENT:` prefix sets the tracing target (e.g. `rpc:` → +/// `target: "rpc"`). Field names must appear in `allowlist.txt`; an +/// unlisted name is a compile error with fuzzy-matched suggestions. +/// +/// # Examples +/// +/// ```rust,ignore +/// use miden_node_tracing::warn; +/// +/// // Plain message. +/// warn!("something looks off"); +/// +/// // Component + message. +/// warn!(store: "migration warning"); +/// +/// // Format string. +/// warn!("retrying after {}ms", delay_ms); +/// +/// // Allowlisted field, Display. +/// warn!(account.id = %id, "unexpected account"); +/// +/// // Allowlisted field, Debug. +/// warn!(account.id = ?id, "unexpected account"); +/// +/// // Multiple allowlisted fields + message. +/// warn!(account.id = %id, block.number = n, "state inconsistency"); +/// +/// // Fields only, no message. +/// warn!(account.id = %id, block.number = n); +/// +/// // Component + allowlisted field + message (full form). +/// warn!(rpc: account.id = %id, "request rejected"); +/// ``` +#[proc_macro] +pub fn warn(ts: TokenStream) -> TokenStream { + match log::parse("warn", ts.into()) { + Ok(ts) => ts.into(), + Err(e) => e.to_compile_error().into(), + } +} + +/// Emits a tracing event at the `INFO` level. +/// +/// Same syntax as [`warn!`]: optional `COMPONENT:`, allowlisted fields, optional message. +/// +/// # Examples +/// +/// ```rust,ignore +/// use miden_node_tracing::info; +/// +/// info!("server started"); +/// info!(store: sqlite = %path.display(), "connected to database"); +/// info!(account.id = %id, block.number = n, "transaction accepted"); +/// info!("processed {} transactions", count); +/// ``` +#[proc_macro] +pub fn info(ts: TokenStream) -> TokenStream { + match log::parse("info", ts.into()) { + Ok(ts) => ts.into(), + Err(e) => e.to_compile_error().into(), + } +} + +/// Emits a tracing event at the `DEBUG` level. +/// +/// Same syntax as [`warn!`]: optional `COMPONENT:`, allowlisted fields, optional message. +/// +/// # Examples +/// +/// ```rust,ignore +/// use miden_node_tracing::debug; +/// +/// debug!("entering handler"); +/// debug!(store: "query returned {} rows", n); +/// debug!(block.number = n, "processing block"); +/// debug!("batch size: {}", batch.len()); +/// ``` +#[proc_macro] +pub fn debug(ts: TokenStream) -> TokenStream { + match log::parse("debug", ts.into()) { + Ok(ts) => ts.into(), + Err(e) => e.to_compile_error().into(), + } +} + +/// Emits a tracing event at the `TRACE` level. +/// +/// Same syntax as [`warn!`]: optional `COMPONENT:`, allowlisted fields, optional message. +/// +/// # Examples +/// +/// ```rust,ignore +/// use miden_node_tracing::trace; +/// +/// trace!("tick"); +/// trace!(mempool: "snapshot taken"); +/// trace!(nullifier.id = %id, "nullifier lookup"); +/// ``` +#[proc_macro] +pub fn trace(ts: TokenStream) -> TokenStream { + match log::parse("trace", ts.into()) { + Ok(ts) => ts.into(), + Err(e) => e.to_compile_error().into(), + } +} diff --git a/crates/tracing-macro/src/log.rs b/crates/tracing-macro/src/log.rs new file mode 100644 index 0000000000..7ab8b3e28b --- /dev/null +++ b/crates/tracing-macro/src/log.rs @@ -0,0 +1,182 @@ +use proc_macro2::TokenStream as TokenStream2; +use quote::quote; +use syn::parse::{Parse, ParseStream}; +use syn::{Expr, Ident, LitStr, Token}; + +use crate::instrument::{CheckedName, ComponentName, Name}; + +// ── LogField ───────────────────────────────────────────────────────────────── + +/// A single `dotted-name = [% | ?] expr` structured field in a log event. +/// +/// Both the `%` (Display) and `?` (Debug) value modifiers are accepted, matching +/// `tracing`'s own syntax. The field name is validated against the OpenTelemetry allowlist +/// at parse time via [`Name::check`]. +struct LogField { + name: CheckedName, + /// Raw tokens for the value, including the optional `%`/`?` prefix. We + /// preserve these verbatim so `tracing` can interpret them itself. + value_tokens: TokenStream2, +} + +impl Parse for LogField { + fn parse(input: ParseStream) -> syn::Result { + let raw: Name = input.parse()?; + let name = raw.check()?; + let _eq: Token![=] = input.parse()?; + + // Collect the optional modifier (`%` or `?`) plus the value expression as + // a token stream so we can forward it unchanged to `tracing::!`. + let mut value_tokens = TokenStream2::new(); + if input.peek(Token![%]) { + let tok: Token![%] = input.parse()?; + value_tokens.extend(quote! { #tok }); + } else if input.peek(Token![?]) { + let tok: Token![?] = input.parse()?; + value_tokens.extend(quote! { #tok }); + } + let expr: Expr = input.parse()?; + value_tokens.extend(quote! { #expr }); + + Ok(LogField { name, value_tokens }) + } +} + +// ── LogArgs ─────────────────────────────────────────────────────────────────── + +/// Parsed representation of a log-macro call. +/// +/// Grammar: +/// ```text +/// LogArgs ::= ε +/// | COMPONENT ":" [field-entry ","]* [message] +/// | [field-entry ","]* [message] +/// +/// COMPONENT ::= ident | string-literal +/// field-entry ::= dotted-name "=" ["%" | "?"] expr +/// message ::= string-literal ["," expr]* +/// ``` +/// +/// The `COMPONENT:` prefix maps to `target: "component"` in the emitted +/// `tracing::!` call. Field names are validated against the OpenTelemetry +/// allowlist at parse time. The trailing message (if any) is forwarded verbatim. +struct LogArgs { + /// Optional component prefix; emitted as `target: "…"` in the tracing call. + component: Option, + /// Structured fields, allowlist-validated at parse time. + fields: Vec, + /// Remaining tokens after the last field – the message string and any format + /// arguments, forwarded verbatim to `tracing`. + message_tokens: TokenStream2, +} + +impl Parse for LogArgs { + fn parse(input: ParseStream) -> syn::Result { + if input.is_empty() { + return Ok(LogArgs { + component: None, + fields: Vec::new(), + message_tokens: quote! {}, + }); + } + + // Detect optional `COMPONENT:` prefix: ident or string literal followed by `:`. + // Must not be mistaken for `field = value` (those use `=` not `:`). + let component = if input.peek(LitStr) && input.peek2(Token![:]) { + let lit: LitStr = input.parse()?; + let _colon: Token![:] = input.parse()?; + Some(ComponentName::Literal(lit)) + } else if input.peek(Ident) && input.peek2(Token![:]) { + let ident: Ident = input.parse()?; + let _colon: Token![:] = input.parse()?; + Some(ComponentName::Ident(ident)) + } else { + None + }; + + // Parse comma-separated fields. We stop at the first token that cannot + // start a field: a string literal marks the beginning of the message. + // + // A field starts with an ident (the first segment of a dotted name) and + // must be followed at some point by `=`. We use a forked parse to check + // whether the next comma-delimited token is a field or the message. + let mut fields: Vec = Vec::new(); + + loop { + if input.is_empty() { + break; + } + // A string literal cannot be a field name → it starts the message. + if input.peek(LitStr) { + break; + } + // Try to parse a field: `name = …`. If the lookahead shows an ident + // but no `=` follows the name, it's not a field either (bare ident + // expressions are not supported as log messages here). + // + // We fork so that a failed parse doesn't consume input. + let forked = input.fork(); + if forked.parse::().is_ok() && forked.peek(Token![=]) { + let field: LogField = input.parse()?; + fields.push(field); + // Consume the trailing comma, if any. + if input.peek(Token![,]) { + let _: Token![,] = input.parse()?; + } + } else { + // Not a field – the rest is the message. + break; + } + } + + // Everything that remains (message string + format args) is forwarded + // verbatim. + let message_tokens: TokenStream2 = input.parse()?; + + Ok(LogArgs { component, fields, message_tokens }) + } +} + +// ── public entry point ──────────────────────────────────────────────────────── + +/// Parses and validates a log-macro call, then expands it to +/// `::tracing::event!(target: "…", Level::LEVEL, field = value, …, "message", …)`. +/// +/// [`tracing::event!`] is used instead of the level-specific macros (`warn!`, `info!`, …) +/// because those macros only accept ident keys when `target:` is present, rejecting the +/// string-literal dotted keys we emit (e.g. `"account.id"`). `event!` has a more permissive +/// parser that accepts string literal keys in all argument positions. +/// +/// Called by all five log proc-macros (`error!`, `warn!`, `info!`, `debug!`, `trace!`). +pub(crate) fn parse(level: &'static str, ts: TokenStream2) -> syn::Result { + let args: LogArgs = syn::parse2(ts)?; + + // `tracing::Level` variant matching the requested level. + let level_variant = syn::Ident::new(&level.to_uppercase(), proc_macro2::Span::call_site()); + + // Build the target fragment (present only when a component was given). + let target_tok = args.component.as_ref().map(ComponentName::to_event_target_tokens); + + // Build the field fragments: `"dotted.name" = [%|?] expr`. + let field_toks: Vec = args + .fields + .iter() + .map(|f| { + let name_lit = LitStr::new(&f.name.dotted, f.name.span); + let val = &f.value_tokens; + quote! { #name_lit = #val } + }) + .collect(); + + // Emit trailing comma between fields and message only when both are present. + let msg = &args.message_tokens; + let sep = if !field_toks.is_empty() && !msg.is_empty() { + quote! { , } + } else { + quote! {} + }; + + Ok(quote! { + ::tracing::event!(#target_tok ::tracing::Level::#level_variant, #(#field_toks),* #sep #msg) + }) +} diff --git a/crates/tracing-macro/src/tests.rs b/crates/tracing-macro/src/tests.rs new file mode 100644 index 0000000000..06baa0718e --- /dev/null +++ b/crates/tracing-macro/src/tests.rs @@ -0,0 +1,489 @@ +use proc_macro2::TokenStream as TokenStream2; +use quote::quote; + +use crate::instrument::instrument2; +use crate::log; + +fn warn2(ts: TokenStream2) -> syn::Result { + log::parse("warn", ts) +} + +fn error2(ts: TokenStream2) -> syn::Result { + log::parse("error", ts) +} + +fn info2(ts: TokenStream2) -> syn::Result { + log::parse("info", ts) +} + +fn debug2(ts: TokenStream2) -> syn::Result { + log::parse("debug", ts) +} + +fn trace2(ts: TokenStream2) -> syn::Result { + log::parse("trace", ts) +} + +/// A function whose return type *contains* the word "Result" but is not `Result`. +/// The old string-contains check would incorrectly accept this. +fn item_fake_result_fn() -> TokenStream2 { + quote! { fn foo() -> NotAResult { NotAResult } } +} + +// ── item fixtures ───────────────────────────────────────────────────────────── + +/// Plain function, does not return a Result. +fn item_bare_fn() -> TokenStream2 { + quote! { fn foo() {} } +} + +/// Function returning Result<(), String> – Ok type is unit (no Display needed). +fn item_result_unit_fn() -> TokenStream2 { + quote! { fn foo() -> Result<(), String> { Ok(()) } } +} + +/// Function returning Result – Ok type implements Display. +fn item_result_display_fn() -> TokenStream2 { + quote! { fn foo() -> Result { Ok(42) } } +} + +// ── #[instrument] / #[instrument()] ──────────────────────────────────────── + +#[test] +fn instrument_bare_succeeds() { + // #[instrument] – empty attr stream, any fn → ok + let result = instrument2(quote! {}, item_bare_fn()); + assert!(result.is_ok(), "{result:?}"); +} + +#[test] +fn instrument_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_allowlisted_field_debug_explicit_value_succeeds() { + // #[instrument(rpc: account.id = ?bar)] – account.id allowlisted, ? modifier → ok + let result = instrument2(quote! { rpc: account.id = ?bar }, item_bare_fn()); + assert!(result.is_ok(), "{result:?}"); +} + +#[test] +fn instrument_unlisted_field_display_value_fails() { + // #[instrument(rpc: foo.bar.baz = %bar)] – foo.bar.baz NOT in allowlist → error + let result = instrument2(quote! { rpc: foo.bar.baz = %bar }, item_bare_fn()); + assert!(result.is_err(), "{result:?}"); +} + +// ── combined: allowlisted fields + err/report ───────────────────────────────── + +#[test] +fn instrument_allowlisted_field_display_err_on_result_fn_succeeds() { + // #[instrument(rpc: account.id = %bar, err)] + // allowlisted + % + err + Result → ok + let result = instrument2(quote! { rpc: account.id = %bar, err }, item_result_unit_fn()); + assert!(result.is_ok(), "{result:?}"); +} + +#[test] +fn instrument_allowlisted_field_display_report_on_result_fn_succeeds() { + // #[instrument(rpc: nullifier.id = %bar, report)] + // allowlisted + % + report + Result → ok + let result = instrument2(quote! { rpc: nullifier.id = %bar, report }, item_result_unit_fn()); + assert!(result.is_ok(), "{result:?}"); +} + +#[test] +fn instrument_allowlisted_field_display_ret_report_on_result_display_fn_succeeds() { + // #[instrument(rpc: account.id = %bar, ret, report)] + // allowlisted + % + ret + report + Result → ok + let result = + instrument2(quote! { rpc: account.id = %bar, ret, report }, item_result_display_fn()); + assert!(result.is_ok(), "{result:?}"); +} + +#[test] +fn instrument_unlisted_field_display_err_on_result_fn_fails() { + // #[instrument(rpc: foo = bar, err)] – foo NOT in allowlist → error + // (allowlist check fires regardless of the presence of err) + let result = instrument2(quote! { rpc: foo = bar, err }, item_result_unit_fn()); + assert!(result.is_err(), "{result:?}"); +} + +#[test] +fn instrument_allowlisted_field_display_report_err_fails() { + // #[instrument(rpc: account.id = %bar, report, err)] + // allowlist ok, but report + err are mutually exclusive → error + let result = instrument2(quote! { rpc: account.id = %bar, report, err }, item_result_unit_fn()); + assert!(result.is_err(), "{result:?}"); +} + +// ── warn! / log macros ──────────────────────────────────────────────────────── + +// ── empty / message only ────────────────────────────────────────────────────── + +#[test] +fn warn_empty_succeeds() { + // warn!() – empty stream → ok (empty tracing event) + let result = warn2(quote! {}); + assert!(result.is_ok(), "{result:?}"); +} + +#[test] +fn warn_message_only_succeeds() { + // warn!("something odd") – plain string literal → ok + let result = warn2(quote! { "something odd" }); + assert!(result.is_ok(), "{result:?}"); +} + +#[test] +fn warn_format_string_succeeds() { + // warn!("retry after {}ms", delay) – format string → ok + let result = warn2(quote! { "retry after {}ms", delay }); + assert!(result.is_ok(), "{result:?}"); +} + +// ── component ───────────────────────────────────────────────────────────────── + +#[test] +fn warn_component_ident_message_succeeds() { + // warn!(rpc: "msg") – component ident + message → ok + let result = warn2(quote! { rpc: "msg" }); + assert!(result.is_ok(), "{result:?}"); +} + +#[test] +fn warn_component_literal_message_succeeds() { + // warn!("block-producer": "msg") – string-literal component → ok + let result = warn2(quote! { "block-producer": "msg" }); + assert!(result.is_ok(), "{result:?}"); +} + +#[test] +fn warn_component_only_succeeds() { + // warn!(rpc:) – component with no fields or message → ok + let result = warn2(quote! { rpc: }); + assert!(result.is_ok(), "{result:?}"); +} + +// ── allowlisted fields ──────────────────────────────────────────────────────── + +#[test] +fn warn_allowlisted_field_debug_succeeds() { + // warn!(account.id = id, "msg") – allowlisted, Debug format → ok + let result = warn2(quote! { account.id = id, "msg" }); + assert!(result.is_ok(), "{result:?}"); +} + +#[test] +fn warn_allowlisted_field_display_succeeds() { + // warn!(account.id = %id, "msg") – allowlisted, Display format → ok + let result = warn2(quote! { account.id = %id, "msg" }); + assert!(result.is_ok(), "{result:?}"); +} + +#[test] +fn warn_allowlisted_field_debug_explicit_succeeds() { + // warn!(account.id = ?id, "msg") – allowlisted, explicit Debug → ok + let result = warn2(quote! { account.id = ?id, "msg" }); + assert!(result.is_ok(), "{result:?}"); +} + +#[test] +fn warn_multiple_allowlisted_fields_succeeds() { + // warn!(account.id = %id, block.number = n, "msg") – two allowlisted fields → ok + let result = warn2(quote! { account.id = %id, block.number = n, "msg" }); + assert!(result.is_ok(), "{result:?}"); +} + +#[test] +fn warn_allowlisted_fields_no_message_succeeds() { + // warn!(account.id = %id, block.number = n) – fields only, no message → ok + let result = warn2(quote! { account.id = %id, block.number = n }); + assert!(result.is_ok(), "{result:?}"); +} + +// ── unlisted fields ─────────────────────────────────────────────────────────── + +#[test] +fn warn_unlisted_field_fails() { + // warn!(foo = %x, "msg") – foo NOT in allowlist → error + let result = warn2(quote! { foo = %x, "msg" }); + assert!(result.is_err(), "{result:?}"); +} + +#[test] +fn warn_unlisted_dotted_field_fails() { + // warn!(foo.bar = %x, "msg") – foo.bar NOT in allowlist → error + let result = warn2(quote! { foo.bar = %x, "msg" }); + assert!(result.is_err(), "{result:?}"); +} + +// ── component + fields ──────────────────────────────────────────────────────── + +#[test] +fn warn_component_allowlisted_field_message_succeeds() { + // warn!(rpc: account.id = %id, "msg") – component + allowlisted + message → ok + let result = warn2(quote! { rpc: account.id = %id, "msg" }); + assert!(result.is_ok(), "{result:?}"); +} + +#[test] +fn warn_component_unlisted_field_fails() { + // warn!(rpc: foo = %x, "msg") – component present but foo NOT in allowlist → error + // (allowlist applies regardless of component) + let result = warn2(quote! { rpc: foo = %x, "msg" }); + assert!(result.is_err(), "{result:?}"); +} + +#[test] +fn warn_component_multiple_fields_message_succeeds() { + // warn!(store: account.id = %id, block.number = n, "msg") → ok + let result = warn2(quote! { store: account.id = %id, block.number = n, "msg" }); + assert!(result.is_ok(), "{result:?}"); +} + +#[test] +fn warn_component_nullifier_field_succeeds() { + // warn!(rpc: nullifier.id = %id, "msg") – nullifier.id allowlisted → ok + let result = warn2(quote! { rpc: nullifier.id = %id, "msg" }); + assert!(result.is_ok(), "{result:?}"); +} + +// ── returns_result false-positive regression ────────────────────────────────── + +#[test] +fn instrument_report_on_fake_result_fn_fails() { + // `NotAResult` contains "Result" as a substring → the string-contains check + // would incorrectly accept this, but the typed check must reject it. + let result = instrument2(quote! { rpc: report }, item_fake_result_fn()); + assert!(result.is_err(), "expected error: report requires Result return, got {result:?}"); +} + +#[test] +fn instrument_err_on_fake_result_fn_fails() { + // Same false-positive gate for `err`. + let result = instrument2(quote! { rpc: err }, item_fake_result_fn()); + assert!(result.is_err(), "expected error: err requires Result return, got {result:?}"); +} + +// ── per-level log dispatch regression ───────────────────────────────────────── + +/// Checks that a log expansion contains the expected level identifier. +fn assert_level(result: syn::Result, expected_level: &str) { + let ts = result.expect("expansion should succeed"); + let s = ts.to_string(); + assert!( + s.contains(expected_level), + "expected level `{expected_level}` in output, got: {s}" + ); +} + +#[test] +fn error_level_dispatch() { + assert_level(error2(quote! { "msg" }), "ERROR"); +} + +#[test] +fn warn_level_dispatch() { + assert_level(warn2(quote! { "msg" }), "WARN"); +} + +#[test] +fn info_level_dispatch() { + assert_level(info2(quote! { "msg" }), "INFO"); +} + +#[test] +fn debug_level_dispatch() { + assert_level(debug2(quote! { "msg" }), "DEBUG"); +} + +#[test] +fn trace_level_dispatch() { + assert_level(trace2(quote! { "msg" }), "TRACE"); +} + +// ── async fn support ───────────────────────────────────────────────────────── + +/// `async fn` returning `Result` – `report` must succeed. +fn item_async_result_fn() -> TokenStream2 { + quote! { async fn foo() -> Result<(), String> { Ok(()) } } +} + +/// `async fn` returning nothing – `report` must fail. +fn item_async_bare_fn() -> TokenStream2 { + quote! { async fn foo() {} } +} + +#[test] +fn instrument_report_on_async_result_fn_succeeds() { + // async fn returning Result is syntactically identical to a sync Result fn + // from syn's perspective; the declared return type is Result, not a Future. + let result = instrument2(quote! { rpc: report }, item_async_result_fn()); + assert!(result.is_ok(), "{result:?}"); +} + +#[test] +fn instrument_err_on_async_result_fn_succeeds() { + let result = instrument2(quote! { rpc: err }, item_async_result_fn()); + assert!(result.is_ok(), "{result:?}"); +} + +#[test] +fn instrument_report_on_async_bare_fn_fails() { + let result = instrument2(quote! { rpc: report }, item_async_bare_fn()); + assert!(result.is_err(), "{result:?}"); +} + +// ── impl Future / Box rejection ─────────────────────────────────── + +/// `fn` returning `impl Future>` – `report` must be rejected +/// with a clear error because the body-wrap codegen cannot `.await` the block. +fn item_impl_future_result_fn() -> TokenStream2 { + quote! { + fn foo() -> impl ::std::future::Future> { + async { Ok(()) } + } + } +} + +/// `fn` returning `Pin>>>` – same restriction. +fn item_pin_box_future_result_fn() -> TokenStream2 { + quote! { + fn foo() -> ::std::pin::Pin>>> { + Box::pin(async { Ok(()) }) + } + } +} + +#[test] +fn instrument_report_on_impl_future_fails() { + let result = instrument2(quote! { rpc: report }, item_impl_future_result_fn()); + assert!(result.is_err(), "expected error for impl Future, got {result:?}"); + let msg = result.unwrap_err().to_string(); + assert!(msg.contains("impl Future"), "unexpected error message: {msg}"); +} + +#[test] +fn instrument_err_on_impl_future_fails() { + let result = instrument2(quote! { rpc: err }, item_impl_future_result_fn()); + assert!(result.is_err(), "expected error for impl Future, got {result:?}"); +} + +#[test] +fn instrument_report_on_pin_box_future_fails() { + let result = instrument2(quote! { rpc: report }, item_pin_box_future_result_fn()); + assert!(result.is_err(), "expected error for Box, got {result:?}"); + let msg = result.unwrap_err().to_string(); + assert!(msg.contains("Box"), "unexpected error message: {msg}"); +} + +#[test] +fn instrument_err_on_pin_box_future_fails() { + let result = instrument2(quote! { rpc: err }, item_pin_box_future_result_fn()); + assert!(result.is_err(), "expected error for Box, got {result:?}"); +} diff --git a/crates/tracing/Cargo.toml b/crates/tracing/Cargo.toml new file mode 100644 index 0000000000..e9b1887231 --- /dev/null +++ b/crates/tracing/Cargo.toml @@ -0,0 +1,24 @@ +[package] +categories = ["development-tools::debugging"] +description = "Tracing utilities for Miden node with enhanced error reporting" +keywords = ["miden", "node", "tracing"] +name = "miden-node-tracing" + +edition.workspace = true +license.workspace = true +readme.workspace = true +repository.workspace = true +rust-version.workspace = true +version.workspace = true + +[lints] +workspace = true + +[dependencies] +miden-node-tracing-macro = { workspace = true } +miden-node-utils = { workspace = true } +opentelemetry = { version = "0.31" } +tracing = { workspace = true } + +[dev-dependencies] +trybuild = { workspace = true } diff --git a/crates/tracing/README.md b/crates/tracing/README.md new file mode 100644 index 0000000000..94a81ab788 --- /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]` 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; + +#[instrument(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 (matching `tracing::instrument` style): + +```text +ERROR apply_block: error = "failed to apply block +caused by: database error +caused by: SQLite error: table 'blocks' has 10 columns but 9 values were supplied" +``` + +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..85d6d4845d --- /dev/null +++ b/crates/tracing/src/lib.rs @@ -0,0 +1,32 @@ +//! Tracing utilities for Miden node with enhanced error reporting. +//! +//! 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; +//! +//! #[instrument(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 +//! ``` + +pub use miden_node_tracing_macro::{debug, error, info, instrument, trace, warn}; +pub use miden_node_utils::ErrorReport; +pub use miden_node_utils::tracing::OpenTelemetrySpanExt; +#[doc(hidden)] +pub use opentelemetry::trace::Status as OtelStatus; +#[doc(hidden)] +pub use tracing::field::Empty as FieldEmpty; +#[doc(hidden)] +pub use tracing::{Instrument, Level, Span, event}; diff --git a/crates/tracing/tests/ui.rs b/crates/tracing/tests/ui.rs new file mode 100644 index 0000000000..ccf475d5ee --- /dev/null +++ b/crates/tracing/tests/ui.rs @@ -0,0 +1,7 @@ +#[test] +fn ui() { + let t = trybuild::TestCases::new(); + t.pass("tests/ui/pass/*.rs"); + t.compile_fail("tests/ui/instrument/*.rs"); + t.compile_fail("tests/ui/log/*.rs"); +} diff --git a/crates/tracing/tests/ui/instrument/dotted_field_not_in_allowlist.rs b/crates/tracing/tests/ui/instrument/dotted_field_not_in_allowlist.rs new file mode 100644 index 0000000000..7061301a80 --- /dev/null +++ b/crates/tracing/tests/ui/instrument/dotted_field_not_in_allowlist.rs @@ -0,0 +1,6 @@ +use miden_node_tracing::instrument; + +#[instrument(rpc: foo.bar.baz = %bar)] +fn foo() {} + +fn main() {} diff --git a/crates/tracing/tests/ui/instrument/dotted_field_not_in_allowlist.stderr b/crates/tracing/tests/ui/instrument/dotted_field_not_in_allowlist.stderr new file mode 100644 index 0000000000..3dd6713944 --- /dev/null +++ b/crates/tracing/tests/ui/instrument/dotted_field_not_in_allowlist.stderr @@ -0,0 +1,5 @@ +error: `foo.bar.baz` is not in the OpenTelemetry allowlist + --> tests/ui/instrument/dotted_field_not_in_allowlist.rs:3:19 + | +3 | #[instrument(rpc: foo.bar.baz = %bar)] + | ^^^ diff --git a/crates/tracing/tests/ui/instrument/err_requires_result.rs b/crates/tracing/tests/ui/instrument/err_requires_result.rs new file mode 100644 index 0000000000..0cf6ae3a55 --- /dev/null +++ b/crates/tracing/tests/ui/instrument/err_requires_result.rs @@ -0,0 +1,6 @@ +use miden_node_tracing::instrument; + +#[instrument(rpc: err)] +fn foo() {} + +fn main() {} diff --git a/crates/tracing/tests/ui/instrument/err_requires_result.stderr b/crates/tracing/tests/ui/instrument/err_requires_result.stderr new file mode 100644 index 0000000000..1a2161d751 --- /dev/null +++ b/crates/tracing/tests/ui/instrument/err_requires_result.stderr @@ -0,0 +1,5 @@ +error: `err` / `report` requires the function to return `Result` + --> tests/ui/instrument/err_requires_result.rs:4:4 + | +4 | fn foo() {} + | ^^^ diff --git a/crates/tracing/tests/ui/instrument/field_not_in_allowlist.rs b/crates/tracing/tests/ui/instrument/field_not_in_allowlist.rs new file mode 100644 index 0000000000..2558eac5de --- /dev/null +++ b/crates/tracing/tests/ui/instrument/field_not_in_allowlist.rs @@ -0,0 +1,6 @@ +use miden_node_tracing::instrument; + +#[instrument(rpc: foo = bar)] +fn foo() {} + +fn main() {} diff --git a/crates/tracing/tests/ui/instrument/field_not_in_allowlist.stderr b/crates/tracing/tests/ui/instrument/field_not_in_allowlist.stderr new file mode 100644 index 0000000000..d4d1a57a3a --- /dev/null +++ b/crates/tracing/tests/ui/instrument/field_not_in_allowlist.stderr @@ -0,0 +1,5 @@ +error: `foo` is not in the OpenTelemetry allowlist + --> tests/ui/instrument/field_not_in_allowlist.rs:3:19 + | +3 | #[instrument(rpc: foo = bar)] + | ^^^ diff --git a/crates/tracing/tests/ui/instrument/report_and_err_exclusive.rs b/crates/tracing/tests/ui/instrument/report_and_err_exclusive.rs new file mode 100644 index 0000000000..2a21f9593e --- /dev/null +++ b/crates/tracing/tests/ui/instrument/report_and_err_exclusive.rs @@ -0,0 +1,8 @@ +use miden_node_tracing::instrument; + +#[instrument(rpc: report, err)] +fn foo() -> Result<(), String> { + Ok(()) +} + +fn main() {} diff --git a/crates/tracing/tests/ui/instrument/report_and_err_exclusive.stderr b/crates/tracing/tests/ui/instrument/report_and_err_exclusive.stderr new file mode 100644 index 0000000000..d1562835f8 --- /dev/null +++ b/crates/tracing/tests/ui/instrument/report_and_err_exclusive.stderr @@ -0,0 +1,7 @@ +error: `err` and `report` are mutually exclusive – use one or the other + --> tests/ui/instrument/report_and_err_exclusive.rs:3:1 + | +3 | #[instrument(rpc: report, err)] + | ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ + | + = note: this error originates in the attribute macro `instrument` (in Nightly builds, run with -Z macro-backtrace for more info) diff --git a/crates/tracing/tests/ui/instrument/report_on_impl_future.rs b/crates/tracing/tests/ui/instrument/report_on_impl_future.rs new file mode 100644 index 0000000000..3dc5886254 --- /dev/null +++ b/crates/tracing/tests/ui/instrument/report_on_impl_future.rs @@ -0,0 +1,8 @@ +use miden_node_tracing::instrument; + +#[instrument(rpc: report)] +fn foo() -> impl std::future::Future> { + async { Ok(()) } +} + +fn main() {} diff --git a/crates/tracing/tests/ui/instrument/report_on_impl_future.stderr b/crates/tracing/tests/ui/instrument/report_on_impl_future.stderr new file mode 100644 index 0000000000..3defb713f8 --- /dev/null +++ b/crates/tracing/tests/ui/instrument/report_on_impl_future.stderr @@ -0,0 +1,5 @@ +error: `err` / `report` is not supported on `impl Future` return types; use `async fn` instead + --> tests/ui/instrument/report_on_impl_future.rs:4:13 + | +4 | fn foo() -> impl std::future::Future> { + | ^^^^ diff --git a/crates/tracing/tests/ui/instrument/report_on_pin_box_future.rs b/crates/tracing/tests/ui/instrument/report_on_pin_box_future.rs new file mode 100644 index 0000000000..6f29f2bf4d --- /dev/null +++ b/crates/tracing/tests/ui/instrument/report_on_pin_box_future.rs @@ -0,0 +1,8 @@ +use miden_node_tracing::instrument; + +#[instrument(rpc: report)] +fn foo() -> std::pin::Pin>>> { + Box::pin(async { Ok(()) }) +} + +fn main() {} diff --git a/crates/tracing/tests/ui/instrument/report_on_pin_box_future.stderr b/crates/tracing/tests/ui/instrument/report_on_pin_box_future.stderr new file mode 100644 index 0000000000..6f02ceac01 --- /dev/null +++ b/crates/tracing/tests/ui/instrument/report_on_pin_box_future.stderr @@ -0,0 +1,5 @@ +error: `err` / `report` is not supported on `Box` return types; use `async fn` instead + --> tests/ui/instrument/report_on_pin_box_future.rs:4:13 + | +4 | fn foo() -> std::pin::Pin>>> { + | ^^^ diff --git a/crates/tracing/tests/ui/instrument/report_requires_result.rs b/crates/tracing/tests/ui/instrument/report_requires_result.rs new file mode 100644 index 0000000000..c8d82a72f9 --- /dev/null +++ b/crates/tracing/tests/ui/instrument/report_requires_result.rs @@ -0,0 +1,6 @@ +use miden_node_tracing::instrument; + +#[instrument(rpc: report)] +fn foo() {} + +fn main() {} diff --git a/crates/tracing/tests/ui/instrument/report_requires_result.stderr b/crates/tracing/tests/ui/instrument/report_requires_result.stderr new file mode 100644 index 0000000000..d6ae4e6891 --- /dev/null +++ b/crates/tracing/tests/ui/instrument/report_requires_result.stderr @@ -0,0 +1,5 @@ +error: `err` / `report` requires the function to return `Result` + --> tests/ui/instrument/report_requires_result.rs:4:4 + | +4 | fn foo() {} + | ^^^ diff --git a/crates/tracing/tests/ui/instrument/ret_report_requires_result.rs b/crates/tracing/tests/ui/instrument/ret_report_requires_result.rs new file mode 100644 index 0000000000..9301d8d6f2 --- /dev/null +++ b/crates/tracing/tests/ui/instrument/ret_report_requires_result.rs @@ -0,0 +1,6 @@ +use miden_node_tracing::instrument; + +#[instrument(rpc: ret, report)] +fn foo() {} + +fn main() {} diff --git a/crates/tracing/tests/ui/instrument/ret_report_requires_result.stderr b/crates/tracing/tests/ui/instrument/ret_report_requires_result.stderr new file mode 100644 index 0000000000..98cc58cd5f --- /dev/null +++ b/crates/tracing/tests/ui/instrument/ret_report_requires_result.stderr @@ -0,0 +1,5 @@ +error: `err` / `report` requires the function to return `Result` + --> tests/ui/instrument/ret_report_requires_result.rs:4:4 + | +4 | fn foo() {} + | ^^^ diff --git a/crates/tracing/tests/ui/log/component_with_unlisted_field.rs b/crates/tracing/tests/ui/log/component_with_unlisted_field.rs new file mode 100644 index 0000000000..165bcf4976 --- /dev/null +++ b/crates/tracing/tests/ui/log/component_with_unlisted_field.rs @@ -0,0 +1,5 @@ +use miden_node_tracing::warn; + +fn main() { + warn!(rpc: foo = %x, "msg"); +} diff --git a/crates/tracing/tests/ui/log/component_with_unlisted_field.stderr b/crates/tracing/tests/ui/log/component_with_unlisted_field.stderr new file mode 100644 index 0000000000..1c54259943 --- /dev/null +++ b/crates/tracing/tests/ui/log/component_with_unlisted_field.stderr @@ -0,0 +1,5 @@ +error: `foo` is not in the OpenTelemetry allowlist + --> tests/ui/log/component_with_unlisted_field.rs:4:16 + | +4 | warn!(rpc: foo = %x, "msg"); + | ^^^ diff --git a/crates/tracing/tests/ui/log/dotted_field_not_in_allowlist.rs b/crates/tracing/tests/ui/log/dotted_field_not_in_allowlist.rs new file mode 100644 index 0000000000..1299fc5c05 --- /dev/null +++ b/crates/tracing/tests/ui/log/dotted_field_not_in_allowlist.rs @@ -0,0 +1,5 @@ +use miden_node_tracing::warn; + +fn main() { + warn!(foo.bar = %x, "msg"); +} diff --git a/crates/tracing/tests/ui/log/dotted_field_not_in_allowlist.stderr b/crates/tracing/tests/ui/log/dotted_field_not_in_allowlist.stderr new file mode 100644 index 0000000000..d114d5fec1 --- /dev/null +++ b/crates/tracing/tests/ui/log/dotted_field_not_in_allowlist.stderr @@ -0,0 +1,5 @@ +error: `foo.bar` is not in the OpenTelemetry allowlist + --> tests/ui/log/dotted_field_not_in_allowlist.rs:4:11 + | +4 | warn!(foo.bar = %x, "msg"); + | ^^^ diff --git a/crates/tracing/tests/ui/log/field_not_in_allowlist.rs b/crates/tracing/tests/ui/log/field_not_in_allowlist.rs new file mode 100644 index 0000000000..da98fb86f7 --- /dev/null +++ b/crates/tracing/tests/ui/log/field_not_in_allowlist.rs @@ -0,0 +1,5 @@ +use miden_node_tracing::warn; + +fn main() { + warn!(foo = %x, "msg"); +} diff --git a/crates/tracing/tests/ui/log/field_not_in_allowlist.stderr b/crates/tracing/tests/ui/log/field_not_in_allowlist.stderr new file mode 100644 index 0000000000..0ed26af62b --- /dev/null +++ b/crates/tracing/tests/ui/log/field_not_in_allowlist.stderr @@ -0,0 +1,5 @@ +error: `foo` is not in the OpenTelemetry allowlist + --> tests/ui/log/field_not_in_allowlist.rs:4:11 + | +4 | warn!(foo = %x, "msg"); + | ^^^ diff --git a/crates/tracing/tests/ui/pass/instrument.rs b/crates/tracing/tests/ui/pass/instrument.rs new file mode 100644 index 0000000000..360427aa7c --- /dev/null +++ b/crates/tracing/tests/ui/pass/instrument.rs @@ -0,0 +1,51 @@ +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(()) } + +// 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 new file mode 100644 index 0000000000..21225b26f0 --- /dev/null +++ b/crates/tracing/tests/ui/pass/log.rs @@ -0,0 +1,67 @@ +use miden_node_tracing::{debug, error, info, trace, warn}; + +fn main() { + // ── plain message ───────────────────────────────────────────────────────── + + error!("hard failure"); + warn!("something looks off"); + info!("block applied"); + debug!("trace point"); + trace!("tick"); + + // ── format string ───────────────────────────────────────────────────────── + + error!("failed after {} retries", 3); + warn!("retrying after {}ms", 100u64); + info!("migrated {} rows", 42usize); + debug!("response size: {} bytes", 128usize); + trace!("loop iteration {}", 7u32); + + // ── component + message ─────────────────────────────────────────────────── + + error!(rpc: "connection refused"); + warn!(store: "slow query detected"); + info!(rpc: "server started"); + debug!(store: "cache miss"); + trace!(rpc: "entering handler"); + + // ── component + format string ───────────────────────────────────────────── + + error!(rpc: "rejected {} requests", 5u32); + warn!(store: "table has {} rows", 1000usize); + info!(rpc: "listening on port {}", 8080u16); + debug!(store: "query took {}ms", 12u64); + trace!(rpc: "payload {} bytes", 256usize); + + // ── string-literal component ────────────────────────────────────────────── + + warn!("block-producer": "batch timeout"); + info!("block-producer": "produced block {}", 42u32); + + // ── component + allowlisted dotted fields + message ─────────────────────── + + warn!(rpc: account.id = %1u64, "unexpected account"); + error!(store: nullifier.id = %2u64, "double spend"); + info!(rpc: block.number = 3u32, "block committed"); + debug!(store: account.id = %1u64, block.number = 3u32, "state check"); + trace!(rpc: nullifier.id = ?2u64, account.id = %1u64, "lookup"); + + // ── component + fields + format string ──────────────────────────────────── + + warn!(rpc: account.id = %1u64, "rejected after {} retries", 3u32); + info!(store: block.number = 3u32, "applied in {}ms", 12u64); + + // ── fields without component ────────────────────────────────────────────── + + warn!(account.id = %1u64, block.number = 3u32, "state inconsistency"); + error!(nullifier.id = %2u64, block.number = 3u32, "double spend at block"); + + // ── fields only, no message ─────────────────────────────────────────────── + + warn!(account.id = %1u64, block.number = 3u32); + info!(nullifier.id = %2u64); + + // ── component + fields only, no message ────────────────────────────────── + + warn!(rpc: account.id = %1u64, block.number = 3u32); +}