From be879c946a148717929277ef997a9c9e692c15ed Mon Sep 17 00:00:00 2001 From: enricobuehler Date: Thu, 2 Jul 2026 21:36:35 +0000 Subject: [PATCH] fix(host/logs): mdns-sd noise gate + tracing-log target normalization in the log ring MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit log-crate events arrive through the tracing-log bridge under the shim target "log" — normalize them back to the real module path (NormalizeEvent) so the console's target column and the noise gate see mdns_sd::… , and suppress the bridge's log.* bookkeeping fields like the stderr fmt layer does. Gate known-chatty third-party DEBUG targets (mdns-sd DEBUG-logs every unparseable multicast packet — one AirPlay device floods thousands of entries per hour) to INFO-and-up in the ring, so ambient LAN noise can't evict the tail the ring exists to preserve. stderr under RUST_LOG is unaffected. Co-Authored-By: Claude Fable 5 --- Cargo.lock | 2 + crates/punktfunk-host/Cargo.toml | 6 ++ crates/punktfunk-host/src/log_capture.rs | 88 +++++++++++++++++++++--- 3 files changed, 86 insertions(+), 10 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 9fdc7bb..e458cba 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2839,6 +2839,7 @@ dependencies = [ "khronos-egl", "libc", "libloading", + "log", "mdns-sd", "nvidia-video-codec-sdk", "openh264", @@ -2863,6 +2864,7 @@ dependencies = [ "tokio-rustls", "tower", "tracing", + "tracing-log", "tracing-subscriber", "ureq", "usbip-sim", diff --git a/crates/punktfunk-host/Cargo.toml b/crates/punktfunk-host/Cargo.toml index dee214f..3465090 100644 --- a/crates/punktfunk-host/Cargo.toml +++ b/crates/punktfunk-host/Cargo.toml @@ -15,6 +15,10 @@ quinn = "0.11" anyhow = "1" tracing = "0.1" tracing-subscriber = { version = "0.3", features = ["env-filter"] } +# The log ring (log_capture.rs) normalizes `log`-crate events off the bridge's "log" shim target +# back to the real module path, so the console's target column and the ring's noise gate see +# `mdns_sd::…` instead of "log". +tracing-log = "0.2" axum = "0.8" mdns-sd = "0.20" tokio = { version = "1", features = ["full"] } @@ -64,6 +68,8 @@ tower = { version = "0.5", features = ["util"] } http-body-util = "0.1" # Disposable directory fixtures for the Steam local-librarycache scan tests (library.rs). tempfile = "3" +# Emit `log`-crate records through the tracing-log bridge in the log_capture tests. +log = "0.4" # Opus encode for the host->client audio plane — stereo (`opus::Encoder`) AND 5.1/7.1 surround # (`opus::MSEncoder`, the safe multistream API the crate exposes; no `audiopus_sys` needed). The diff --git a/crates/punktfunk-host/src/log_capture.rs b/crates/punktfunk-host/src/log_capture.rs index efc21ef..31076f5 100644 --- a/crates/punktfunk-host/src/log_capture.rs +++ b/crates/punktfunk-host/src/log_capture.rs @@ -8,6 +8,10 @@ //! //! The ring keeps the *newest* [`CAPACITY`] entries (a log tail — unlike the stats recorder, //! which keeps the head of a capture). Readers poll with an `after` sequence cursor. +//! +//! `log`-crate events (arriving via the tracing-log bridge) are normalized to their real module +//! path, and known-chatty third-party targets ([`NOISY_DEBUG_TARGETS`]) are demoted to +//! INFO-and-up so ambient LAN noise can't evict the tail the ring exists to preserve. use serde::{Deserialize, Serialize}; use std::collections::VecDeque; @@ -121,6 +125,21 @@ pub fn ring() -> &'static LogRing { RING.get_or_init(LogRing::new) } +/// Targets whose DEBUG/TRACE output is steady-state per-packet chatter, not diagnostics — left +/// in, they evict the entire ring tail (mdns-sd DEBUG-logs every multicast packet it can't parse, +/// so one chatty AirPlay/HomePod device on the LAN floods thousands of entries per hour). The +/// ring keeps their INFO-and-up; stderr under `RUST_LOG` is unaffected. Prefix-matched on module +/// path boundaries. +const NOISY_DEBUG_TARGETS: &[&str] = &["mdns_sd"]; + +fn is_noisy_debug(target: &str) -> bool { + NOISY_DEBUG_TARGETS.iter().any(|t| { + target + .strip_prefix(t) + .is_some_and(|rest| rest.is_empty() || rest.starts_with("::")) + }) +} + /// The tee: a `tracing_subscriber` layer pushing every event into [`ring`]. Install with a /// per-layer `LevelFilter::DEBUG` so the ring sees DEBUG even when `RUST_LOG` keeps stderr at /// `info` (remote debugging must not require a restart with a different env). @@ -132,7 +151,15 @@ impl tracing_subscriber::Layer for RingLayer { event: &tracing::Event<'_>, _ctx: tracing_subscriber::layer::Context<'_, S>, ) { - let meta = event.metadata(); + // Events from `log`-crate dependencies arrive through the tracing-log bridge under the + // shim target "log"; normalize back to the record's real module path so the console's + // target column and the noise gate below see `mdns_sd::…`. + use tracing_log::NormalizeEvent; + let normalized = event.normalized_metadata(); + let meta = normalized.as_ref().unwrap_or_else(|| event.metadata()); + if *meta.level() > tracing::Level::INFO && is_noisy_debug(meta.target()) { + return; + } let mut fields = FieldFmt::default(); event.record(&mut fields); ring().push(meta.level(), meta.target(), fields.finish()); @@ -152,7 +179,9 @@ impl tracing::field::Visit for FieldFmt { use std::fmt::Write; if field.name() == "message" { let _ = write!(self.msg, "{value:?}"); - } else { + } else if !field.name().starts_with("log.") { + // `log.target`/`log.file`/… are tracing-log bridge bookkeeping (already surfaced via + // the normalized target), same suppression as the stderr fmt layer. let _ = write!(self.fields, " {}={:?}", field.name(), value); } } @@ -161,7 +190,7 @@ impl tracing::field::Visit for FieldFmt { use std::fmt::Write; if field.name() == "message" { self.msg.push_str(value); - } else { + } else if !field.name().starts_with("log.") { let _ = write!(self.fields, " {}={value}", field.name()); } } @@ -236,20 +265,24 @@ mod tests { assert_eq!(head.entries.first().map(|e| e.seq), Some(page.next + 1)); } - #[test] - fn layer_captures_events_into_the_singleton_ring() { - use tracing_subscriber::layer::SubscriberExt; - - // The singleton ring is process-wide — find its current tail first (parallel tests may - // interleave, so only assert on OUR event appearing after it). + /// The singleton ring is process-wide — tests find its current tail first (parallel tests + /// may interleave, so they only assert on THEIR events appearing after it). + fn tail_seq() -> u64 { let mut cur = 0; loop { let page = ring().since(cur, MAX_PAGE); if page.entries.is_empty() { - break; + return cur; } cur = page.next; } + } + + #[test] + fn layer_captures_events_into_the_singleton_ring() { + use tracing_subscriber::layer::SubscriberExt; + + let cur = tail_seq(); let subscriber = tracing_subscriber::registry().with(RingLayer); tracing::subscriber::with_default(subscriber, || { @@ -272,6 +305,41 @@ mod tests { assert!(hit.ts_ms > 0); } + #[test] + fn log_bridge_events_normalize_target_and_noisy_debug_is_dropped() { + use tracing_subscriber::layer::SubscriberExt; + + // Route `log` records into tracing (what SubscriberInitExt::init does in main). Global, + // so tolerate a prior install; max_level explicit so debug! records reach the bridge. + let _ = tracing_log::LogTracer::init(); + log::set_max_level(log::LevelFilter::Trace); + + let cur = tail_seq(); + + let subscriber = tracing_subscriber::registry().with(RingLayer); + tracing::subscriber::with_default(subscriber, || { + log::debug!(target: "mdns_sd::service_daemon", "Invalid incoming DNS message: flood"); + log::warn!(target: "mdns_sd::service_daemon", "a real mdns problem"); + log::debug!(target: "mdns_sdx", "not actually mdns-sd"); + }); + + let page = ring().since(cur, MAX_PAGE); + assert!( + !page.entries.iter().any(|e| e.msg.contains("flood")), + "noisy-target DEBUG must not reach the ring" + ); + let warn = page + .entries + .iter() + .find(|e| e.msg.contains("a real mdns problem")) + .expect("noisy-target WARN kept"); + // Normalized off the bridge's "log" shim, and the log.* bookkeeping fields are hidden. + assert_eq!(warn.target, "mdns_sd::service_daemon"); + assert!(!warn.msg.contains("log.target"), "msg: {}", warn.msg); + // Prefix match respects module-path boundaries. + assert!(page.entries.iter().any(|e| e.target == "mdns_sdx")); + } + #[test] fn message_truncation_keeps_char_boundary() { let f = FieldFmt {