diff --git a/CHANGELOG.md b/CHANGELOG.md index 296c7a4..cf60a98 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -9,6 +9,13 @@ All notable changes to this project will be documented in this file. ## [Unreleased] +## [0.24.16] - 2025-11-01 + +### Fixed +- Refresh tracing callsite interest while flushing telemetry so late subscriber + installs still emit a single `masterror::error` event when logging existing + errors. + ## [0.24.15] - 2025-10-31 ### Fixed diff --git a/Cargo.lock b/Cargo.lock index 8bafd4f..bb2a69c 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1804,7 +1804,7 @@ dependencies = [ [[package]] name = "masterror" -version = "0.24.15" +version = "0.24.16" dependencies = [ "actix-web", "anyhow", diff --git a/Cargo.toml b/Cargo.toml index d521de0..cb3bf86 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -4,7 +4,7 @@ [package] name = "masterror" -version = "0.24.15" +version = "0.24.16" rust-version = "1.90" edition = "2024" license = "MIT OR Apache-2.0" diff --git a/README.md b/README.md index 293ae48..5f4ac52 100644 --- a/README.md +++ b/README.md @@ -80,9 +80,9 @@ The build script keeps the full feature snippet below in sync with ~~~toml [dependencies] -masterror = { version = "0.24.15", default-features = false } +masterror = { version = "0.24.16", default-features = false } # or with features: -# masterror = { version = "0.24.15", features = [ +# masterror = { version = "0.24.16", features = [ # "std", "axum", "actix", "openapi", # "serde_json", "tracing", "metrics", "backtrace", # "sqlx", "sqlx-migrate", "reqwest", "redis", @@ -453,4 +453,3 @@ assert_eq!(problem.grpc.expect("grpc").name, "UNAUTHENTICATED"); MSRV: **1.90** · License: **MIT OR Apache-2.0** · No `unsafe` - diff --git a/src/app_error/core.rs b/src/app_error/core.rs index 452d890..a313864 100644 --- a/src/app_error/core.rs +++ b/src/app_error/core.rs @@ -24,6 +24,8 @@ use serde::Serialize; #[cfg(feature = "serde_json")] use serde_json::{Value as JsonValue, to_value}; #[cfg(feature = "tracing")] +use tracing::callsite::rebuild_interest_cache; +#[cfg(feature = "tracing")] use tracing::{Level, event}; use super::metadata::{Field, FieldRedaction, Metadata}; @@ -353,8 +355,12 @@ impl Error { } if !tracing::event_enabled!(target: "masterror::error", Level::ERROR) { - self.mark_tracing_dirty(); - return; + rebuild_interest_cache(); + + if !tracing::event_enabled!(target: "masterror::error", Level::ERROR) { + self.mark_tracing_dirty(); + return; + } } let message = self.message.as_deref(); diff --git a/src/app_error/tests.rs b/src/app_error/tests.rs index a984a3d..4d84d9a 100644 --- a/src/app_error/tests.rs +++ b/src/app_error/tests.rs @@ -42,6 +42,90 @@ static BACKTRACE_ENV_GUARD: Mutex<()> = Mutex::new(()); #[cfg(feature = "tracing")] static TELEMETRY_GUARD: Mutex<()> = Mutex::new(()); +#[cfg(feature = "tracing")] +mod telemetry_support { + use std::{ + fmt, + sync::{Arc, Mutex} + }; + + use tracing::{ + Dispatch, Event, Subscriber, + field::{Field, Visit} + }; + use tracing_subscriber::{ + Registry, + layer::{Context, Layer, SubscriberExt} + }; + + #[derive(Default, Clone)] + pub(super) struct RecordedEvent { + pub(super) trace_id: Option, + pub(super) code: Option, + pub(super) category: Option + } + + pub(super) type RecordedEvents = Arc>>; + + pub(super) fn new_recording_dispatch() -> (Dispatch, RecordedEvents) { + let events = Arc::new(Mutex::new(Vec::new())); + let layer = RecordingLayer { + events: events.clone() + }; + let subscriber = Registry::default().with(layer); + let dispatch = Dispatch::new(subscriber); + (dispatch, events) + } + + struct RecordingLayer { + events: RecordedEvents + } + + impl Layer for RecordingLayer + where + S: Subscriber + { + fn on_event(&self, event: &Event<'_>, _ctx: Context<'_, S>) { + if event.metadata().target() != "masterror::error" { + return; + } + + let mut record = RecordedEvent::default(); + event.record(&mut EventVisitor { + record: &mut record + }); + self.events.lock().expect("events lock").push(record); + } + } + + struct EventVisitor<'a> { + record: &'a mut RecordedEvent + } + + impl<'a> Visit for EventVisitor<'a> { + fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) { + let normalized = normalize_debug(value); + match field.name() { + "trace_id" => self.record.trace_id = Some(normalized), + "code" => self.record.code = Some(normalized), + "category" => self.record.category = Some(normalized), + _ => {} + } + } + } + + fn normalize_debug(value: &dyn fmt::Debug) -> String { + let mut rendered = format!("{value:?}"); + while let Some(stripped) = rendered + .strip_prefix("Some(") + .and_then(|s| s.strip_suffix(')')) + { + rendered = stripped.to_owned(); + } + rendered.trim_matches('"').to_owned() + } +} + use super::{AppError, FieldRedaction, FieldValue, MessageEditPolicy, field}; use crate::{AppCode, AppErrorKind, Context, ErrorResponse, ResultExt}; @@ -501,84 +585,14 @@ fn log_uses_kind_and_code() { fn telemetry_emits_single_tracing_event_with_trace_id() { let _guard = TELEMETRY_GUARD.lock().expect("telemetry guard"); - use std::{ - fmt, - sync::{Arc, Mutex} - }; + use telemetry_support::new_recording_dispatch; + use tracing::{callsite::rebuild_interest_cache, dispatcher}; - use tracing::{ - Dispatch, Event, Subscriber, callsite, dispatcher, - field::{Field, Visit} - }; - use tracing_subscriber::{ - Registry, - layer::{Context, Layer, SubscriberExt} - }; - - #[derive(Default, Clone)] - struct RecordedEvent { - trace_id: Option, - code: Option, - category: Option - } - - struct RecordingLayer { - events: Arc>> - } - - impl Layer for RecordingLayer - where - S: Subscriber - { - fn on_event(&self, event: &Event<'_>, _ctx: Context<'_, S>) { - if event.metadata().target() != "masterror::error" { - return; - } - - let mut record = RecordedEvent::default(); - event.record(&mut EventVisitor { - record: &mut record - }); - self.events.lock().expect("events lock").push(record); - } - } - - struct EventVisitor<'a> { - record: &'a mut RecordedEvent - } - - impl<'a> Visit for EventVisitor<'a> { - fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) { - let normalized = normalize_debug(value); - match field.name() { - "trace_id" => self.record.trace_id = Some(normalized), - "code" => self.record.code = Some(normalized), - "category" => self.record.category = Some(normalized), - _ => {} - } - } - } - - fn normalize_debug(value: &dyn fmt::Debug) -> String { - let mut rendered = format!("{value:?}"); - while let Some(stripped) = rendered - .strip_prefix("Some(") - .and_then(|s| s.strip_suffix(')')) - { - rendered = stripped.to_owned(); - } - rendered.trim_matches('"').to_owned() - } - - let events = Arc::new(Mutex::new(Vec::new())); - let layer = RecordingLayer { - events: events.clone() - }; - let subscriber = Registry::default().with(layer); - let dispatch = Dispatch::new(subscriber); + let (dispatch, events) = new_recording_dispatch(); + let events = events.clone(); dispatcher::with_default(&dispatch, || { - callsite::rebuild_interest_cache(); + rebuild_interest_cache(); log_mdc::insert("trace_id", "trace-123"); let err = AppError::internal("boom"); err.log(); @@ -599,6 +613,34 @@ fn telemetry_emits_single_tracing_event_with_trace_id() { }); } +#[cfg(feature = "tracing")] +#[test] +fn telemetry_flushes_after_subscriber_install() { + let _guard = TELEMETRY_GUARD.lock().expect("telemetry guard"); + + use telemetry_support::new_recording_dispatch; + use tracing::dispatcher; + + let err = AppError::internal("boom"); + + let (dispatch, events) = new_recording_dispatch(); + let events = events.clone(); + + dispatcher::with_default(&dispatch, || { + err.log(); + }); + + let events = events.lock().expect("events lock"); + assert_eq!( + events.len(), + 1, + "expected telemetry after subscriber install" + ); + let event = &events[0]; + assert_eq!(event.code.as_deref(), Some(AppCode::Internal.as_str())); + assert_eq!(event.category.as_deref(), Some("Internal")); +} + #[cfg(feature = "metrics")] #[test] fn metrics_counter_is_incremented_once() {