diff --git a/crates/tracing-macro/src/lib.rs b/crates/tracing-macro/src/lib.rs index ee76b6ff6..9d791f90e 100644 --- a/crates/tracing-macro/src/lib.rs +++ b/crates/tracing-macro/src/lib.rs @@ -7,7 +7,19 @@ use syn::parse::{Parse, ParseStream}; use syn::punctuated::Punctuated; use syn::token::Dot; use syn::visit::Visit; -use syn::{Block, Expr, Ident, ItemFn, Macro, Result, Token, parse_macro_input, parse_quote}; +use syn::{ + Attribute, + Block, + Expr, + Ident, + ItemFn, + Macro, + Meta, + Result, + Token, + parse_macro_input, + parse_quote, +}; const ALLOWED_FIELD_NAMES: &[&str] = &[ "account.id", @@ -101,9 +113,15 @@ const ALLOWED_FIELD_NAMES: &[&str] = &[ "workers.count", ]; +/// Instruments a function using registered tracing fields. +/// +/// Append `#[nonstandard]` to a field value to permit a name outside the field registry. #[proc_macro_attribute] pub fn miden_instrument(attr: TokenStream, item: TokenStream) -> TokenStream { - let attr = TokenStream2::from(attr); + let attr = match rewrite_explicit_fields(TokenStream2::from(attr)) { + Ok(attr) => attr, + Err(error) => return error.into_compile_error().into(), + }; let mut function = parse_macro_input!(item as ItemFn); let fields = collect_recorded_fields(&function); let args = match merge_inferred_fields(attr, &fields) { @@ -130,8 +148,6 @@ pub fn miden_instrument(attr: TokenStream, item: TokenStream) -> TokenStream { } fn merge_inferred_fields(attr: TokenStream2, fields: &[FieldPath]) -> Result { - validate_explicit_fields(&attr)?; - let mut args = split_top_level_args(attr); reject_skip_directives(&args)?; @@ -193,14 +209,23 @@ fn reject_skip_directives(args: &[TokenStream2]) -> Result<()> { Ok(()) } -fn validate_explicit_fields(attr: &TokenStream2) -> Result<()> { - for arg in split_top_level_args(attr.clone()) { - if let Some(group) = fields_group(&arg) { - syn::parse2::(group.stream())?; - } - } +fn rewrite_explicit_fields(attr: TokenStream2) -> Result { + let args = split_top_level_args(attr) + .into_iter() + .map(|arg| { + if let Some(group) = fields_group(&arg) { + let fields = syn::parse2::(group.stream())?; + let fields = fields.fields.iter().map(RecordField::instrument_tokens); + let mut rewritten = Group::new(Delimiter::Parenthesis, quote! { #(#fields),* }); + rewritten.set_span(group.span()); + Ok(quote! { fields #rewritten }) + } else { + Ok(arg) + } + }) + .collect::>>()?; - Ok(()) + Ok(quote! { #(#args),* }) } fn split_top_level_args(tokens: TokenStream2) -> Vec { @@ -250,6 +275,9 @@ fn ends_with_comma(tokens: &TokenStream2) -> bool { ) } +/// Records fields on the current `miden_instrument` span. +/// +/// Append `#[nonstandard]` to a field value to permit a name outside the field registry. #[proc_macro] pub fn miden_span_record(input: TokenStream) -> TokenStream { let records = parse_macro_input!(input as RecordFields); @@ -336,6 +364,7 @@ impl Parse for Fields { } struct RecordField { + shorthand_formatter: Option, path: FieldPath, value: Option, } @@ -348,15 +377,31 @@ impl RecordField { Formatter::parse_optional(input)? }; let path = input.parse()?; - validate_field_name(&path)?; - let value = if value_required || shorthand_formatter.is_none() && input.peek(Token![=]) { - input.parse::()?; - Some(input.parse()?) - } else { - None - }; + let value: Option = + if value_required || shorthand_formatter.is_none() && input.peek(Token![=]) { + input.parse::()?; + Some(input.parse()?) + } else { + None + }; + if value.as_ref().is_none_or(|value| !value.nonstandard) { + validate_field_name(&path)?; + } + + Ok(Self { shorthand_formatter, path, value }) + } - Ok(Self { path, value }) + fn instrument_tokens(&self) -> TokenStream2 { + let path = &self.path; + if let Some(value) = &self.value { + let value = value.instrument_tokens(); + quote! { #path = #value } + } else if let Some(formatter) = self.shorthand_formatter { + let formatter = formatter.tokens(); + quote! { #formatter #path } + } else { + quote! { #path } + } } } @@ -401,6 +446,7 @@ impl ToTokens for FieldPath { struct RecordValue { formatter: Formatter, expr: Expr, + nonstandard: bool, } impl RecordValue { @@ -413,17 +459,37 @@ impl RecordValue { Formatter::Plain => quote! { &#expr }, } } + + fn instrument_tokens(&self) -> TokenStream2 { + let formatter = self.formatter.tokens(); + let expr = &self.expr; + quote! { #formatter #expr } + } } impl Parse for RecordValue { fn parse(input: ParseStream<'_>) -> Result { let formatter = Formatter::parse_optional(input)?.unwrap_or(Formatter::Plain); let expr = input.parse()?; + let attributes = input.call(Attribute::parse_outer)?; + let nonstandard = match attributes.as_slice() { + [] => false, + [attribute] if matches!(&attribute.meta, Meta::Path(path) if path.is_ident("nonstandard")) => { + true + }, + [attribute, ..] => { + return Err(syn::Error::new_spanned( + attribute, + "only `#[nonstandard]` is supported after a tracing field value", + )); + }, + }; - Ok(Self { formatter, expr }) + Ok(Self { formatter, expr, nonstandard }) } } +#[derive(Clone, Copy)] enum Formatter { Display, Debug, @@ -431,6 +497,14 @@ enum Formatter { } impl Formatter { + fn tokens(self) -> TokenStream2 { + match self { + Self::Display => quote! { % }, + Self::Debug => quote! { ? }, + Self::Plain => TokenStream2::new(), + } + } + fn parse_optional(input: ParseStream<'_>) -> Result> { if input.peek(Token![%]) { input.parse::()?; diff --git a/crates/utils/src/tracing/attribute.rs b/crates/utils/src/tracing/attribute.rs new file mode 100644 index 000000000..def474eba --- /dev/null +++ b/crates/utils/src/tracing/attribute.rs @@ -0,0 +1,480 @@ +use std::fmt::{self, Display, Formatter}; +use std::path::{Path, PathBuf}; + +use miden_protocol::Word; +use miden_protocol::account::{AccountId, AccountIdPrefix, StorageMapKey, StorageSlotName}; +use miden_protocol::batch::BatchId; +use miden_protocol::block::BlockNumber; +use miden_protocol::note::{NoteId, Nullifier}; +use miden_protocol::transaction::TransactionId; +use tracing::Value; + +const BOOLEAN_FIELD_NAMES: &[&str] = &[ + "account.updated", + "note.erased", + "note.id_resolved", + "panic", + "request.include_mmr_proof", + "request.include_proof", + "rpc.authentication.configured", +]; + +const NUMBER_FIELD_NAMES: &[&str] = &[ + "account.id.length", + "account.index", + "asset.amount", + "batch.expiration_height", + "batch.expires_at", + "batch.reference_block.number", + "batch.size", + "block.from", + "block.number", + "block.protocol.version", + "block.size", + "block.timestamp", + "block_range.from", + "block_range.to", + "counter.failures.consecutive", + "counter.latency.timeout_ms", + "counter.value.expected", + "counter.value.observed", + "counter.value.target", + "current_client_block_height", + "cutoff_block", + "db.account_state_forest.size", + "db.account_tree.size", + "db.block_store.size", + "db.nullifier_tree.size", + "db.sqlite.connection_pool_size", + "db.sqlite.size", + "db.sqlite.wal.size", + "dice_roll", + "failure_rate", + "inputs_size", + "mempool.accounts", + "mempool.batches.proposed", + "mempool.batches.proven", + "mempool.nullifiers", + "mempool.output_notes", + "mempool.transactions.unbatched", + "mempool.transactions.uncommitted", + "note.tag", + "ntx_builder.max_cycles", + "ntx_builder.tx_expiration_delta", + "port", + "pow.hash", + "pow.nonce", + "pow.target", + "pow.target.leading_zero_bits", + "prefix_len", + "proof_size", + "prover.capacity", + "prover.port", + "prover.proof_type.raw", + "reference_block.number", + "retry.attempt", + "retry.delay_ms", + "shutdown.grace_period_ms", + "snapshot.block_num", + "snapshot.lifetime_ms", + "snapshot.superseded_for_ms", + "snapshots.live", + "subscription.idle_ms", + "subscription.stall_timeout_ms", + "sync.block_gap", + "sync.ready_threshold", + "sync.upstream_block", + "timeout.ms", + "tip.number", + "tip.stale_duration_secs", + "transaction.expiration_delta", + "transaction.expires_at", + "transaction.reference_block.number", + "transaction.submitted_at", + "worker.status.raw", + "workers.active", + "workers.capacity", +]; + +const STRING_FIELD_NAMES: &[&str] = &[ + "account.id", + "account.storage.kind", + "account.storage.map.entry.operation", + "account.storage.operation", + "asset.symbol", + "batch.interval", + "block.interval", + "dependency.endpoint", + "dependency.name", + "genesis.source", + "genesis.source.kind", + "internal.listen", + "mempool.removal.reason", + "network_monitor.listen", + "node.role", + "note.execution_cycles", + "ntx_builder.endpoint", + "ntx_builder.idle_timeout", + "ntx_builder.listen", + "operation.name", + "path", + "pow.challenge.prefix", + "prover", + "prover.kind", + "prover.timeout", + "request.kind", + "rpc.endpoint", + "rpc.listen", + "sequencer.endpoint", + "service.name", + "service.version", + "shutdown.signal", + "sync.block_source.endpoint", + "task.name", + "transaction.id", + "transaction.input_notes", + "transaction.output_notes", + "tx_prover.endpoint", + "validator.admin_listen", + "validator.endpoints", + "validator.listen", + "validator.signer", + "worker.name", +]; + +/// Converts a value into its canonical tracing attribute representation. +/// +/// Implementations decide the allowed scalar field names, the attribute's primitive type, and its +/// formatting, allowing tracing macros to use one name and representation consistently at every +/// recording site. Collection implementations derive their field names by appending `s` to these +/// scalar names. +pub trait RecordAttribute { + /// Scalar field names associated with this value's type. + const FIELD_NAMES: &'static [&'static str]; + + /// Whether the final component of each field name must have an `s` suffix. + const PLURALIZE_FIELD_NAMES: bool = false; + + /// Returns the value that is passed to `tracing`. + fn record_attribute(&self) -> impl Value + '_; +} + +/// Returns whether `field_name` occurs in `field_names`. +/// +/// This is public because it is referenced by the tracing proc macros. Callers should use the +/// macros rather than invoking it directly. +#[doc(hidden)] +pub const fn field_name_allowed(field_names: &[&str], field_name: &str, pluralize: bool) -> bool { + let mut index = 0; + while index < field_names.len() { + let allowed = if pluralize { + str_eq_with_s_suffix(field_names[index], field_name) + } else { + str_eq(field_names[index], field_name) + }; + if allowed { + return true; + } + index += 1; + } + false +} + +const fn str_eq_with_s_suffix(singular: &str, plural: &str) -> bool { + let singular = singular.as_bytes(); + let plural = plural.as_bytes(); + if plural.len() != singular.len() + 1 || plural[singular.len()] != b's' { + return false; + } + + let mut index = 0; + while index < singular.len() { + if singular[index] != plural[index] { + return false; + } + index += 1; + } + true +} + +const fn str_eq(left: &str, right: &str) -> bool { + let left = left.as_bytes(); + let right = right.as_bytes(); + if left.len() != right.len() { + return false; + } + + let mut index = 0; + while index < left.len() { + if left[index] != right[index] { + return false; + } + index += 1; + } + true +} + +/// Converts an approved attribute into a `tracing` value. +/// +/// This is public because it is referenced by the tracing proc macros. Callers should use the +/// macros rather than invoking it directly. +#[doc(hidden)] +pub fn record_attribute(value: &T) -> impl Value + '_ { + value.record_attribute() +} + +macro_rules! impl_scalar_attribute { + ($field_names:expr; $($ty:ty),* $(,)?) => { + $( + impl RecordAttribute for $ty { + const FIELD_NAMES: &'static [&'static str] = $field_names; + + fn record_attribute(&self) -> impl Value + '_ { + *self + } + } + )* + }; +} + +impl_scalar_attribute!(BOOLEAN_FIELD_NAMES; bool); +impl_scalar_attribute!( + NUMBER_FIELD_NAMES; + f32, + f64, + i8, + i16, + i32, + i64, + i128, + isize, + u8, + u16, + u64, + u128, + usize, +); +impl_scalar_attribute!(NUMBER_FIELD_NAMES; u32); + +impl RecordAttribute for str { + const FIELD_NAMES: &'static [&'static str] = STRING_FIELD_NAMES; + + fn record_attribute(&self) -> impl Value + '_ { + self + } +} + +impl RecordAttribute for String { + const FIELD_NAMES: &'static [&'static str] = ::FIELD_NAMES; + + fn record_attribute(&self) -> impl Value + '_ { + self.as_str() + } +} + +impl RecordAttribute for &T { + const FIELD_NAMES: &'static [&'static str] = T::FIELD_NAMES; + const PLURALIZE_FIELD_NAMES: bool = T::PLURALIZE_FIELD_NAMES; + + fn record_attribute(&self) -> impl Value + '_ { + (*self).record_attribute() + } +} + +impl RecordAttribute for Option { + const FIELD_NAMES: &'static [&'static str] = T::FIELD_NAMES; + const PLURALIZE_FIELD_NAMES: bool = T::PLURALIZE_FIELD_NAMES; + + fn record_attribute(&self) -> impl Value + '_ { + self.as_ref().map(RecordAttribute::record_attribute) + } +} + +impl RecordAttribute for Path { + const FIELD_NAMES: &'static [&'static str] = &["data.directory", "genesis.file", "path"]; + + fn record_attribute(&self) -> impl Value + '_ { + tracing::field::display(self.display()) + } +} + +impl RecordAttribute for PathBuf { + const FIELD_NAMES: &'static [&'static str] = ::FIELD_NAMES; + + fn record_attribute(&self) -> impl Value + '_ { + self.as_path().record_attribute() + } +} + +impl RecordAttribute for BlockNumber { + const FIELD_NAMES: &'static [&'static str] = &[ + "batch.expiration_height", + "batch.expires_at", + "batch.reference_block.number", + "block.from", + "block.number", + "block_range.from", + "block_range.to", + "cutoff_block", + "current_client_block_height", + "reference_block.number", + "snapshot.block_num", + "sync.upstream_block", + "tip.number", + "transaction.expires_at", + "transaction.reference_block.number", + "transaction.submitted_at", + ]; + + fn record_attribute(&self) -> impl Value + '_ { + self.as_u64() + } +} + +macro_rules! impl_display_attribute { + ($ty:ty, $field_names:expr $(,)?) => { + impl RecordAttribute for $ty { + const FIELD_NAMES: &'static [&'static str] = $field_names; + + fn record_attribute(&self) -> impl Value + '_ { + tracing::field::display(self) + } + } + }; +} + +impl_display_attribute!( + AccountId, + &[ + "account.id", + "counter.account.id.new", + "counter.account.id.old", + "note.sender", + "wallet.account.id.new", + "wallet.account.id.old", + ], +); +impl_display_attribute!(AccountIdPrefix, &["account.id.network_prefix"]); +impl_display_attribute!(StorageMapKey, &["account.storage.map.key"]); +impl_display_attribute!(StorageSlotName, &["account.storage.slot"]); +impl_display_attribute!(BatchId, &["batch.id", "block.batch.id"]); +impl_display_attribute!(NoteId, &["note.id"]); +impl_display_attribute!(Nullifier, &["note.nullifier"]); +impl_display_attribute!(TransactionId, &["block.transaction.id", "transaction.id"]); +impl_display_attribute!( + Word, + &[ + "account.final_state.commitment", + "account.initial_state.commitment", + "account.storage.value", + "batch.reference_block.commitment", + "block.commitment", + "block.commitments.account", + "block.commitments.chain", + "block.commitments.kernel", + "block.commitments.note", + "block.commitments.nullifier", + "block.commitments.transaction", + "block.prev_block_commitment", + "block.sub_commitment", + "genesis.commitment", + "script.root", + "transaction.reference_block.commitment", + ], +); + +/// Formats a slice as one string-valued tracing attribute. +/// +/// This is not an OpenTelemetry array: `tracing::Value` has no array representation, so the `OTel` +/// tracing layer receives the formatted list as a string. +struct AttributeList<'a, T>(&'a [T]); + +impl Display for AttributeList<'_, T> { + fn fmt(&self, f: &mut Formatter<'_>) -> fmt::Result { + let mut values = self.0.iter(); + let Some(first) = values.next() else { + return f.write_str("None"); + }; + + write!(f, "[{first}")?; + for value in values { + write!(f, ", {value}")?; + } + f.write_str("]") + } +} + +impl RecordAttribute for [T] { + const FIELD_NAMES: &'static [&'static str] = T::FIELD_NAMES; + const PLURALIZE_FIELD_NAMES: bool = true; + + fn record_attribute(&self) -> impl Value + '_ { + tracing::field::display(AttributeList(self)) + } +} + +impl RecordAttribute for [T; N] { + const FIELD_NAMES: &'static [&'static str] = T::FIELD_NAMES; + const PLURALIZE_FIELD_NAMES: bool = true; + + fn record_attribute(&self) -> impl Value + '_ { + self.as_slice().record_attribute() + } +} + +impl RecordAttribute for Vec { + const FIELD_NAMES: &'static [&'static str] = T::FIELD_NAMES; + const PLURALIZE_FIELD_NAMES: bool = true; + + fn record_attribute(&self) -> impl Value + '_ { + self.as_slice().record_attribute() + } +} + +#[cfg(test)] +mod tests { + use miden_protocol::account::AccountId; + + use super::{AttributeList, RecordAttribute, field_name_allowed}; + + #[test] + fn lists_use_the_canonical_format() { + assert_eq!(AttributeList::(&[]).to_string(), "None"); + assert_eq!(AttributeList(&[1, 2, 3]).to_string(), "[1, 2, 3]"); + } + + #[test] + fn references_are_approved_when_the_referenced_type_is_approved() { + fn assert_record_attribute(_: &impl RecordAttribute) {} + + let value = "attribute"; + assert_record_attribute(&value); + assert_record_attribute(&&value); + assert_record_attribute(&Some(value)); + assert_record_attribute(&None::<&str>); + } + + #[test] + fn field_names_are_specific_to_the_attribute_type() { + assert!(field_name_allowed( + AccountId::FIELD_NAMES, + "account.id", + AccountId::PLURALIZE_FIELD_NAMES, + )); + assert!(!field_name_allowed( + AccountId::FIELD_NAMES, + "account.ids", + AccountId::PLURALIZE_FIELD_NAMES, + )); + assert!(field_name_allowed( + <[AccountId]>::FIELD_NAMES, + "account.ids", + <[AccountId]>::PLURALIZE_FIELD_NAMES, + )); + assert!(!field_name_allowed( + <[AccountId]>::FIELD_NAMES, + "account.id", + <[AccountId]>::PLURALIZE_FIELD_NAMES, + )); + } +} diff --git a/crates/utils/src/tracing/mod.rs b/crates/utils/src/tracing/mod.rs index 20f4dc6c1..ce103d9c8 100644 --- a/crates/utils/src/tracing/mod.rs +++ b/crates/utils/src/tracing/mod.rs @@ -1,5 +1,9 @@ +mod attribute; pub mod grpc; mod span_ext; +#[doc(hidden)] +pub use attribute::field_name_allowed; +pub use attribute::{RecordAttribute, record_attribute}; pub use miden_node_tracing_macro::{miden_instrument, miden_span_record}; pub use span_ext::ErrorSpanExt; diff --git a/crates/utils/tests/tracing_macros.rs b/crates/utils/tests/tracing_macros.rs index 9e5f71b1d..1fd185f7c 100644 --- a/crates/utils/tests/tracing_macros.rs +++ b/crates/utils/tests/tracing_macros.rs @@ -110,6 +110,18 @@ fn records_fields_from_multiple_calls() { ); } +#[miden_instrument( + target = "miden-node-utils-test", + name = "records_nonstandard_explicit_field", + fields(custom.explicit = %value #[nonstandard]), +)] +fn records_nonstandard_explicit_field(value: &str) {} + +#[miden_instrument(target = "miden-node-utils-test", name = "records_nonstandard_delayed_field")] +fn records_nonstandard_delayed_field() { + miden_span_record!(custom.delayed = %"delayed" #[nonstandard]); +} + #[test] fn inferred_fields_can_be_recorded_after_span_creation() { let recorded = RecordedFields::default(); @@ -167,11 +179,26 @@ fn multiple_span_record_macros_can_record_fields_after_span_creation() { assert_eq!(recorded.get("transaction.id").as_deref(), Some("multi-call-tx")); } +#[test] +fn nonstandard_fields_bypass_the_name_registry() { + let recorded = RecordedFields::default(); + let subscriber = tracing_subscriber::registry().with(recorded.clone()); + + tracing::subscriber::with_default(subscriber, || { + records_nonstandard_explicit_field("explicit"); + records_nonstandard_delayed_field(); + }); + + assert_eq!(recorded.get("custom.explicit").as_deref(), Some("explicit")); + assert_eq!(recorded.get("custom.delayed").as_deref(), Some("delayed")); +} + #[test] fn ui_tests() { let tests = trybuild::TestCases::new(); tests.pass("tests/ui/tracing_macros/pass.rs"); tests.compile_fail("tests/ui/tracing_macros/invalid_field_name.rs"); + tests.compile_fail("tests/ui/tracing_macros/invalid_field_annotation.rs"); tests.compile_fail("tests/ui/tracing_macros/invalid_instrument_field_name.rs"); tests.compile_fail("tests/ui/tracing_macros/invalid_skip.rs"); tests.compile_fail("tests/ui/tracing_macros/invalid_skip_all.rs"); diff --git a/crates/utils/tests/ui/tracing_macros/invalid_field_annotation.rs b/crates/utils/tests/ui/tracing_macros/invalid_field_annotation.rs new file mode 100644 index 000000000..be030ddc8 --- /dev/null +++ b/crates/utils/tests/ui/tracing_macros/invalid_field_annotation.rs @@ -0,0 +1,8 @@ +use miden_node_utils::tracing::{miden_instrument, miden_span_record}; + +#[miden_instrument] +fn records_invalid_annotation() { + miden_span_record!(custom.attribute = 1 #[unchecked]); +} + +fn main() {} diff --git a/crates/utils/tests/ui/tracing_macros/invalid_field_annotation.stderr b/crates/utils/tests/ui/tracing_macros/invalid_field_annotation.stderr new file mode 100644 index 000000000..298f11075 --- /dev/null +++ b/crates/utils/tests/ui/tracing_macros/invalid_field_annotation.stderr @@ -0,0 +1,5 @@ +error: only `#[nonstandard]` is supported after a tracing field value + --> tests/ui/tracing_macros/invalid_field_annotation.rs:5:45 + | +5 | miden_span_record!(custom.attribute = 1 #[unchecked]); + | ^^^^^^^^^^^^ diff --git a/crates/utils/tests/ui/tracing_macros/pass.rs b/crates/utils/tests/ui/tracing_macros/pass.rs index e9cd77d96..4c5212f5c 100644 --- a/crates/utils/tests/ui/tracing_macros/pass.rs +++ b/crates/utils/tests/ui/tracing_macros/pass.rs @@ -36,6 +36,13 @@ fn records_with_default_instrument_args(not_debug: NotDebug) { )] fn records_allowed_instrument_fields() {} +#[miden_instrument( + fields( + custom.attribute = %"explicit" #[nonstandard], + ), +)] +fn records_nonstandard_instrument_field() {} + #[miden_instrument( fields( %dice_roll, @@ -56,6 +63,11 @@ fn records_same_field_more_than_once() { ); } +#[miden_instrument] +fn records_nonstandard_delayed_field() { + miden_span_record!(custom.attribute = %"delayed" #[nonstandard]); +} + #[miden_instrument] fn records_allowed_canonical_fields() { let tx_id = "0x1234"; @@ -144,7 +156,9 @@ fn main() { records_fields(); records_with_default_instrument_args(NotDebug); records_allowed_instrument_fields(); + records_nonstandard_instrument_field(); records_allowed_shorthand_instrument_field(0.5); records_same_field_more_than_once(); + records_nonstandard_delayed_field(); records_allowed_canonical_fields(); }