From b1db5d6c924acec2e588ccca4676493111200279 Mon Sep 17 00:00:00 2001 From: Pruthvikar Reddy Date: Mon, 16 Mar 2026 17:06:26 +0000 Subject: [PATCH 1/3] fix: record latency before ret/err events The latency field was recorded AFTER ret/err events fired, so the events' log output always showed latency as Empty. This broke the previous TraceLatency Drop-based approach where the timer dropped (recording latency) inside the block before events fired. Move latency_inst and latency_record into each mk_fut variant so that latency is recorded after the block completes but before any ret/err events emit their log lines. Co-Authored-By: Claude Opus 4.6 (1M context) --- tracing-attributes/src/expand.rs | 63 +++++++++++++++++++------------- 1 file changed, 38 insertions(+), 25 deletions(-) diff --git a/tracing-attributes/src/expand.rs b/tracing-attributes/src/expand.rs index 3bac5f7e9..53e62077c 100644 --- a/tracing-attributes/src/expand.rs +++ b/tracing-attributes/src/expand.rs @@ -302,10 +302,27 @@ fn gen_block( // If `ret` is in args, instrument any resulting `Ok`s when the function // returns `Result`s, otherwise instrument any resulting values. if async_context { + let latency_inst = args.latency.then(|| { + quote!(let __tracing_attr_latency = ::std::time::Instant::now();) + }); + let latency_record = args.latency.then(|| { + quote!( + __tracing_attr_span.record( + "latency", + __tracing_attr_latency.elapsed().as_millis() as u64, + ); + ) + }); + + // Record latency BEFORE ret/err events so it appears in their log output. + // This matches the old TraceLatency Drop behavior where the timer was a + // local inside the block that dropped before events fired. let mk_fut = match (err_event, ret_event) { (Some(err_event), Some(ret_event)) => quote_spanned!(block.span()=> async move { + #latency_inst let __match_scrutinee = async move #block.await; + #latency_record match __match_scrutinee { #[allow(clippy::unit_arg)] Ok(x) => { @@ -321,7 +338,10 @@ fn gen_block( ), (Some(err_event), None) => quote_spanned!(block.span()=> async move { - match async move #block.await { + #latency_inst + let __match_scrutinee = async move #block.await; + #latency_record + match __match_scrutinee { #[allow(clippy::unit_arg)] Ok(x) => Ok(x), Err(e) => { @@ -333,36 +353,26 @@ fn gen_block( ), (None, Some(ret_event)) => quote_spanned!(block.span()=> async move { + #latency_inst let x = async move #block.await; + #latency_record #ret_event; x } ), (None, None) => quote_spanned!(block.span()=> - async move #block + async move { + #latency_inst + let __tracing_attr_result = async move #block.await; + #latency_record + __tracing_attr_result + } ), }; - let latency_inst = args.latency.then(|| { - quote!(let __tracing_attr_latency = ::std::time::Instant::now();) - }); - let latency_record = args.latency.then(|| { - quote!( - __tracing_attr_span.record( - "latency", - __tracing_attr_latency.elapsed().as_millis() as u64, - ); - ) - }); - return quote!( let __tracing_attr_span = #span; - let __tracing_instrument_future = async { - #latency_inst - let __tracing_attr_result = #mk_fut .await; - #latency_record - __tracing_attr_result - }; + let __tracing_instrument_future = #mk_fut; if !__tracing_attr_span.is_disabled() { #follows_from ::tracing::Instrument::instrument( @@ -409,11 +419,14 @@ fn gen_block( #latency_inst ); + // Record latency BEFORE ret/err events so it appears in their log output. match (err_event, ret_event) { (Some(err_event), Some(ret_event)) => quote_spanned! {block.span()=> #span #[allow(clippy::redundant_closure_call)] - let __tracing_attr_result = match (move || #block)() { + let __tracing_attr_block_result = (move || #block)(); + #latency_record + let __tracing_attr_result = match __tracing_attr_block_result { #[allow(clippy::unit_arg)] Ok(x) => { #ret_event; @@ -424,13 +437,14 @@ fn gen_block( Err(e) } }; - #latency_record __tracing_attr_result }, (Some(err_event), None) => quote_spanned!(block.span()=> #span #[allow(clippy::redundant_closure_call)] - let __tracing_attr_result = match (move || #block)() { + let __tracing_attr_block_result = (move || #block)(); + #latency_record + let __tracing_attr_result = match __tracing_attr_block_result { #[allow(clippy::unit_arg)] Ok(x) => Ok(x), Err(e) => { @@ -438,15 +452,14 @@ fn gen_block( Err(e) } }; - #latency_record __tracing_attr_result ), (None, Some(ret_event)) => quote_spanned!(block.span()=> #span #[allow(clippy::redundant_closure_call)] let x = (move || #block)(); - #ret_event; #latency_record + #ret_event; x ), (None, None) => quote_spanned!(block.span() => From 1114d326d85d4f4cdafb6c7342e0172441773ccc Mon Sep 17 00:00:00 2001 From: Pruthvikar Reddy Date: Mon, 16 Mar 2026 17:28:02 +0000 Subject: [PATCH 2/3] style: format expand.rs with rustfmt Co-Authored-By: Claude Opus 4.6 (1M context) --- tracing-attributes/src/expand.rs | 16 +++++++++------- 1 file changed, 9 insertions(+), 7 deletions(-) diff --git a/tracing-attributes/src/expand.rs b/tracing-attributes/src/expand.rs index 53e62077c..d3512e851 100644 --- a/tracing-attributes/src/expand.rs +++ b/tracing-attributes/src/expand.rs @@ -243,7 +243,9 @@ fn gen_block( } let custom_fields = &args.fields; - let latency_field = args.latency.then(|| quote!(latency = ::tracing::field::Empty,)); + let latency_field = args + .latency + .then(|| quote!(latency = ::tracing::field::Empty,)); quote!(::tracing::span!( target: #target, @@ -302,9 +304,9 @@ fn gen_block( // If `ret` is in args, instrument any resulting `Ok`s when the function // returns `Result`s, otherwise instrument any resulting values. if async_context { - let latency_inst = args.latency.then(|| { - quote!(let __tracing_attr_latency = ::std::time::Instant::now();) - }); + let latency_inst = args + .latency + .then(|| quote!(let __tracing_attr_latency = ::std::time::Instant::now();)); let latency_record = args.latency.then(|| { quote!( __tracing_attr_span.record( @@ -386,9 +388,9 @@ fn gen_block( ); } - let latency_inst = args.latency.then(|| { - quote!(let __tracing_attr_latency = ::std::time::Instant::now();) - }); + let latency_inst = args + .latency + .then(|| quote!(let __tracing_attr_latency = ::std::time::Instant::now();)); let latency_record = args.latency.then(|| { quote!( __tracing_attr_span.record( From c250d296680030e3de6f5cfd09813a6d72217ac4 Mon Sep 17 00:00:00 2001 From: Pruthvikar Reddy Date: Mon, 16 Mar 2026 17:41:13 +0000 Subject: [PATCH 3/3] fix: resolve clippy warnings in tracing-subscriber - Box `matchers::BuildError` in closure to fix `result_large_err` - Use `self.cmp(other)` in `PartialOrd` impls for `MatchPattern` and `MatchDebug` to fix `non_canonical_partial_ord_impl` Co-Authored-By: Claude Opus 4.6 (1M context) --- tracing-subscriber/src/filter/env/field.rs | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/tracing-subscriber/src/filter/env/field.rs b/tracing-subscriber/src/filter/env/field.rs index 6ddb52e9f..2aa6890e1 100644 --- a/tracing-subscriber/src/filter/env/field.rs +++ b/tracing-subscriber/src/filter/env/field.rs @@ -169,7 +169,7 @@ impl Match { let value = parts .next() .map(|part| match regex { - true => ValueMatch::parse_regex(part), + true => ValueMatch::parse_regex(part).map_err(Box::new), false => Ok(ValueMatch::parse_non_regex(part)), }) .transpose()?; @@ -334,7 +334,7 @@ impl Eq for MatchPattern {} impl PartialOrd for MatchPattern { #[inline] fn partial_cmp(&self, other: &Self) -> Option { - Some(self.pattern.cmp(&other.pattern)) + Some(self.cmp(other)) } } @@ -430,7 +430,7 @@ impl Eq for MatchDebug {} impl PartialOrd for MatchDebug { #[inline] fn partial_cmp(&self, other: &Self) -> Option { - Some(self.pattern.cmp(&other.pattern)) + Some(self.cmp(other)) } }