From dacc40272171d227d8beddf445eb9908652aee8e Mon Sep 17 00:00:00 2001
From: Thomas Eizinger <thomas@eizinger.io>
Date: Thu, 24 Jul 2025 11:37:43 +1000
Subject: [PATCH] chore(connlib): only log span field name into message (#9981)

When looking at logs, reducing noise is critical to make it easier to
spot important information. When sending logs to Sentry, we currently
append the fields of certain spans to message to make the output similar
to that of `tracing_subscriber::fmt`.

The actual name of a field inside a span is separated from the span name
by a colon. For example, here is a log message as we see it in Sentry
today:

> handle_input:class=success response
handle_input:from=C1A0479AA153FACA0722A5DF76343CF2BEECB10E:3478
handle_input:method=binding handle_input:rtt=34.7479ms
handle_input:tid=BB30E859ED88FFDF0786B634 request=["Software(snownet;
session=BCA42EF159C794F41AE45BF5099E54D3A193A7184C4D2C3560C2FE49C4C6CFB7)"]
response=["Software(firezone-relay; rev=e4ba5a69)",
"XorMappedAddress(B824B4035A78A6B188EF38BE13AA3C1B1B1196D6:52625)"]

Really, what we would like to see is only this:

> class=success response
from=C1A0479AA153FACA0722A5DF76343CF2BEECB10E:3478 method=binding
rtt=34.7479ms tid=BB30E859ED88FFDF0786B634 request=["Software(snownet;
session=BCA42EF159C794F41AE45BF5099E54D3A193A7184C4D2C3560C2FE49C4C6CFB7)"]
response=["Software(firezone-relay; rev=e4ba5a69)",
"XorMappedAddress(B824B4035A78A6B188EF38BE13AA3C1B1B1196D6:52625)"]

The duplication of `handle_input:` is just noise. In our local log
output, we already strip the name of the span to make it easier to read.
Here we now also do the same for the logs reported to Sentry.
---
 rust/telemetry/src/lib.rs | 40 +++++++++++++++++++++++++++++++++++++++
 1 file changed, 40 insertions(+)

diff --git a/rust/telemetry/src/lib.rs b/rust/telemetry/src/lib.rs
index c71d1cac3..5fce4b4e5 100644
--- a/rust/telemetry/src/lib.rs
+++ b/rust/telemetry/src/lib.rs
@@ -311,6 +311,11 @@ fn append_tracing_fields_to_message(mut log: Log) -> Option<Log> {
             continue;
         }
 
+        let key = match key.rsplit_once(':') {
+            Some((_, key)) => key,
+            None => key,
+        };
+
         log.body.push_str(&format!(" {key}={attr_string}"));
     }
 
@@ -332,6 +337,8 @@ fn set_current_user(user: Option<sentry::User>) {
 
 #[cfg(test)]
 mod tests {
+    use std::time::SystemTime;
+
     use super::*;
 
     #[tokio::test]
@@ -363,10 +370,43 @@ mod tests {
         assert!(before_send(event1.clone()).is_some());
     }
 
+    #[test]
+    fn trims_name_of_span_from_field_before_pushing_to_message() {
+        let log = log(
+            "Foobar",
+            &[
+                ("handle_input:class", "success response"),
+                ("handle_input:from", "1.1.1.1:3478"),
+                ("handle_input:method", "binding"),
+            ],
+        );
+
+        let log = append_tracing_fields_to_message(log).unwrap();
+
+        assert_eq!(
+            log.body,
+            "Foobar class=success response from=1.1.1.1:3478 method=binding"
+        )
+    }
+
     fn event(msg: &str) -> Event<'static> {
         Event {
             message: Some(msg.to_owned()),
             ..Default::default()
         }
     }
+
+    fn log(msg: &str, attrs: &[(&str, &str)]) -> Log {
+        Log {
+            level: sentry::protocol::LogLevel::Info,
+            body: msg.to_owned(),
+            trace_id: None,
+            timestamp: SystemTime::now(),
+            severity_number: None,
+            attributes: attrs
+                .iter()
+                .map(|(k, v)| (k.to_string(), v.to_owned().into()))
+                .collect(),
+        }
+    }
 }