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.
This commit is contained in:
Thomas Eizinger
2025-07-24 11:37:43 +10:00
committed by GitHub
parent 301d2137e5
commit dacc402721

View File

@@ -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(),
}
}
}