From 5c9dd439e23614d990607d4682ce4942a5dd2ac0 Mon Sep 17 00:00:00 2001 From: Thomas Eizinger Date: Tue, 6 May 2025 11:16:18 +1000 Subject: [PATCH] chore(rust): filter spammy WinTUN errors in the `sentry_layer` (#9036) By default, we send all WARN and ERROR logs to Sentry. This also includes logs emitted via the `log` crate via a facade that `tracing` installs. The wintun-rs bindings install such a logger in the native WinTUN code. The WinTUN code has a bug where it doesn't handle adapter removal idempotently. That is, if the adapter has already been removed it logs an error instead of succeeding. Typically, such logs can easily be suppressed in Sentry. In this case however, Sentry fails to group these different logs together because WinTUN's error message contains a path to a temporary directory which is different every time it gets executed. As such, these logs spam our Sentry instance with no way for us to disable them with existing tools. The WireGuard mailing list for WinTUN also appears to be dead. We attempted to contact the list in February and have not received a reply yet. The last archive goes back to November 2024 [0]. We use WinTUN as a prebuild and signed DLL so we also cannot meaningfully patch this on our end without upstreaming it. Thus, as a last resort, we add some infrastructure to our logging setup that allows us to client-side filter events based on certain patterns of the message and a log level. [0]: https://lists.zx2c4.com/pipermail/wireguard/ --------- Signed-off-by: Thomas Eizinger Co-authored-by: Copilot <175728472+Copilot@users.noreply.github.com> --- rust/Cargo.lock | 1 + rust/logging/Cargo.toml | 1 + rust/logging/src/capturing_writer.rs | 36 +++++ .../src/event_message_contains_filter.rs | 127 ++++++++++++++++++ rust/logging/src/lib.rs | 12 ++ 5 files changed, 177 insertions(+) create mode 100644 rust/logging/src/capturing_writer.rs create mode 100644 rust/logging/src/event_message_contains_filter.rs diff --git a/rust/Cargo.lock b/rust/Cargo.lock index 7e4b2aeb7..83fe39633 100644 --- a/rust/Cargo.lock +++ b/rust/Cargo.lock @@ -2322,6 +2322,7 @@ dependencies = [ "anyhow", "nu-ansi-term 0.50.1", "output_vt100", + "parking_lot", "rand 0.8.5", "sentry-tracing", "supports-color", diff --git a/rust/logging/Cargo.toml b/rust/logging/Cargo.toml index c897f5c41..84c4c7be1 100644 --- a/rust/logging/Cargo.toml +++ b/rust/logging/Cargo.toml @@ -11,6 +11,7 @@ license = { workspace = true } anyhow = { workspace = true } nu-ansi-term = { workspace = true } output_vt100 = { workspace = true } +parking_lot = { workspace = true } rand = { workspace = true } sentry-tracing = { workspace = true } supports-color = { workspace = true } diff --git a/rust/logging/src/capturing_writer.rs b/rust/logging/src/capturing_writer.rs new file mode 100644 index 000000000..b8de8473f --- /dev/null +++ b/rust/logging/src/capturing_writer.rs @@ -0,0 +1,36 @@ +use std::sync::Arc; + +use parking_lot::{Mutex, MutexGuard}; +use tracing_subscriber::fmt::MakeWriter; + +#[derive(Debug, Default, Clone)] +pub struct CapturingWriter { + content: Arc>, +} + +impl std::io::Write for CapturingWriter { + fn write(&mut self, buf: &[u8]) -> std::io::Result { + let line = std::str::from_utf8(buf).map_err(std::io::Error::other)?; + self.content.lock().push_str(line); + + Ok(buf.len()) + } + + fn flush(&mut self) -> std::io::Result<()> { + Ok(()) + } +} + +impl CapturingWriter { + pub fn lines(&self) -> MutexGuard<'_, String> { + self.content.lock() + } +} + +impl<'a> MakeWriter<'a> for CapturingWriter { + type Writer = Self; + + fn make_writer(&'a self) -> Self::Writer { + self.clone() + } +} diff --git a/rust/logging/src/event_message_contains_filter.rs b/rust/logging/src/event_message_contains_filter.rs new file mode 100644 index 000000000..36b0c6687 --- /dev/null +++ b/rust/logging/src/event_message_contains_filter.rs @@ -0,0 +1,127 @@ +use tracing::Level; +use tracing_subscriber::layer::Filter; + +/// Filters out all events whose message contains all of the given snippets. +pub struct EventMessageContains { + level: Level, + snippets: Vec<&'static str>, +} + +impl EventMessageContains { + pub fn all(level: Level, snippets: &[&'static str]) -> Self { + Self { + level, + snippets: snippets.to_vec(), + } + } +} + +impl Filter for EventMessageContains +where + S: tracing::Subscriber, +{ + fn enabled( + &self, + metadata: &tracing::Metadata<'_>, + _: &tracing_subscriber::layer::Context<'_, S>, + ) -> bool { + if metadata.level() != &self.level { + return false; + } + + true + } + + fn event_enabled( + &self, + event: &tracing::Event<'_>, + _: &tracing_subscriber::layer::Context<'_, S>, + ) -> bool { + let mut visitor = MessageVisitor { message: None }; + event.record(&mut visitor); + + let Some(message) = visitor.message else { + return true; + }; + + if self + .snippets + .iter() + .all(|snippet| message.contains(snippet)) + { + return false; + } + + true + } +} + +struct MessageVisitor { + message: Option, +} + +impl tracing::field::Visit for MessageVisitor { + fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn std::fmt::Debug) { + if self.message.is_some() { + return; + } + + if field.name() != "message" { + return; + } + + self.message = Some(format!("{value:?}")) + } +} + +#[cfg(test)] +mod tests { + use super::*; + use crate::capturing_writer::CapturingWriter; + use tracing_subscriber::{Layer, layer::SubscriberExt, util::SubscriberInitExt}; + + #[test] + fn matches_on_all_strings() { + let capture = CapturingWriter::default(); + + let _guard = tracing_subscriber::registry() + .with( + tracing_subscriber::fmt::layer() + .with_writer(capture.clone()) + .with_filter(EventMessageContains::all( + Level::DEBUG, + &["foo", r#"bar ("xyz")"#, "baz"], + )), + ) + .set_default(); + + tracing::debug!( + r#"This is a message containing foo: The error was caused by bar ("xyz") and baz"# + ); + + assert!(capture.lines().is_empty()); + } + + #[test] + fn passes_through_non_matching_events() { + let capture = CapturingWriter::default(); + + let _guard = tracing_subscriber::registry() + .with( + tracing_subscriber::fmt::layer() + .with_writer(capture.clone()) + .with_level(false) + .without_time() + .with_target(false) + .with_filter(EventMessageContains::all(Level::DEBUG, &["foo"])), + ) + .set_default(); + + tracing::debug!("This is a message"); + + assert_eq!( + *capture.lines().lines().collect::>(), + vec!["This is a message".to_owned()] + ); + } +} diff --git a/rust/logging/src/lib.rs b/rust/logging/src/lib.rs index 272fd3bcd..d5f7d2cc0 100644 --- a/rust/logging/src/lib.rs +++ b/rust/logging/src/lib.rs @@ -5,11 +5,14 @@ mod format; #[macro_use] mod unwrap_or; mod ansi; +mod capturing_writer; mod err_with_sources; +mod event_message_contains_filter; use std::sync::Arc; use anyhow::{Context, Result}; +use event_message_contains_filter::EventMessageContains; use sentry_tracing::EventFilter; use tracing::{Subscriber, subscriber::DefaultGuard}; use tracing_log::LogTracer; @@ -19,6 +22,7 @@ use tracing_subscriber::{ }; pub use ansi::stdout_supports_ansi; +pub use capturing_writer::CapturingWriter; pub use err_with_sources::{ErrorWithSources, err_with_src}; pub use format::Format; @@ -212,6 +216,14 @@ where }) .enable_span_attributes() .with_filter(parse_filter("trace").expect("static filter always parses")) + .with_filter(EventMessageContains::all( + Level::ERROR, + &[ + "WinTun: Failed to create process: rundll32", + r#"RemoveInstance "SWD\WINTUN\{E9245BC1-B8C1-44CA-AB1D-C6AAD4F13B9C}""#, + "(Code 0x00000003)", + ], + )) // Filter out noisy crates but pass all events otherwise. }