Skip to content

Commit 3b533a0

Browse files
authored
fix(logs): format log level into correct status (#1036)
## Overview Log level was not properly formatted for AWS JSON logs – same goes for our own logs where the level was not truly respected. #807 and [SVLS-8590](https://datadoghq.atlassian.net/browse/SVLS-8590) ## Testing Unit tests and on actual resources. Before logs with `debug` appeared as `info` <img width="978" height="304" alt="Screenshot 2026-02-19 at 7 17 12 PM" src="https://github.com/user-attachments/assets/3e59f0a1-58c2-4c7f-bb98-12304284ac08" /> Now, all appear with their right level: <img width="863" height="425" alt="Screenshot 2026-02-19 at 7 17 55 PM" src="https://github.com/user-attachments/assets/7b31bf82-9ab0-439b-83ea-09de2e244009" /> [SVLS-8590]: https://datadoghq.atlassian.net/browse/SVLS-8590?atlOrigin=eyJpIjoiNWRkNTljNzYxNjVmNDY3MDlhMDU5Y2ZhYzA5YTRkZjUiLCJwIjoiZ2l0aHViLWNvbS1KU1cifQ
1 parent dfcb768 commit 3b533a0

File tree

5 files changed

+672
-23
lines changed

5 files changed

+672
-23
lines changed

bottlecap/Cargo.lock

Lines changed: 13 additions & 0 deletions
Some generated files are not rendered by default. Learn more about customizing how changed files appear on GitHub.

bottlecap/Cargo.toml

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -34,7 +34,7 @@ tokio = { version = "1.47", default-features = false, features = ["macros", "rt-
3434
tokio-util = { version = "0.7", default-features = false }
3535
tracing = { version = "0.1", default-features = false }
3636
tracing-core = { version = "0.1", default-features = false }
37-
tracing-subscriber = { version = "0.3", default-features = false, features = ["std", "registry", "fmt", "env-filter", "tracing-log"] }
37+
tracing-subscriber = { version = "0.3", default-features = false, features = ["std", "registry", "fmt", "env-filter", "tracing-log", "json"] }
3838
hmac = { version = "0.12", default-features = false }
3939
sha2 = { version = "0.10", default-features = false }
4040
hex = { version = "0.4", default-features = false, features = ["std"] }

bottlecap/LICENSE-3rdparty.csv

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -235,6 +235,7 @@ tracing,https://github.com/tokio-rs/tracing,MIT,"Eliza Weisman <eliza@buoyant.io
235235
tracing-attributes,https://github.com/tokio-rs/tracing,MIT,"Tokio Contributors <team@tokio.rs>, Eliza Weisman <eliza@buoyant.io>, David Barsky <dbarsky@amazon.com>"
236236
tracing-core,https://github.com/tokio-rs/tracing,MIT,Tokio Contributors <team@tokio.rs>
237237
tracing-log,https://github.com/tokio-rs/tracing,MIT,Tokio Contributors <team@tokio.rs>
238+
tracing-serde,https://github.com/tokio-rs/tracing,MIT,Tokio Contributors <team@tokio.rs>
238239
tracing-subscriber,https://github.com/tokio-rs/tracing,MIT,"Eliza Weisman <eliza@buoyant.io>, David Barsky <me@davidbarsky.com>, Tokio Contributors <team@tokio.rs>"
239240
try-lock,https://github.com/seanmonstar/try-lock,MIT,Sean McArthur <sean@seanmonstar.com>
240241
twoway,https://github.com/bluss/twoway,MIT OR Apache-2.0,bluss

bottlecap/src/logger.rs

Lines changed: 168 additions & 21 deletions
Original file line numberDiff line numberDiff line change
@@ -9,6 +9,23 @@ use tracing_subscriber::registry::LookupSpan;
99
#[derive(Debug, Clone, Copy)]
1010
pub struct Formatter;
1111

12+
/// Visitor that captures the message from tracing event fields.
13+
struct MessageVisitor(String);
14+
15+
impl tracing::field::Visit for MessageVisitor {
16+
fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn fmt::Debug) {
17+
if field.name() == "message" {
18+
self.0 = format!("{value:?}");
19+
}
20+
}
21+
22+
fn record_str(&mut self, field: &tracing::field::Field, value: &str) {
23+
if field.name() == "message" {
24+
self.0 = value.to_string();
25+
}
26+
}
27+
}
28+
1229
impl<S, N> FormatEvent<S, N> for Formatter
1330
where
1431
S: Subscriber + for<'a> LookupSpan<'a>,
@@ -20,36 +37,166 @@ where
2037
mut writer: format::Writer<'_>,
2138
event: &Event<'_>,
2239
) -> fmt::Result {
23-
// Format values from the event's's metadata:
2440
let metadata = event.metadata();
25-
write!(&mut writer, "DD_EXTENSION | {} | ", metadata.level())?;
41+
let level = metadata.level();
2642

27-
// Format all the spans in the event's span context.
43+
let mut visitor = MessageVisitor(String::new());
44+
event.record(&mut visitor);
45+
46+
// Build span context prefix
47+
let mut span_prefix = String::new();
2848
if let Some(scope) = ctx.event_scope() {
2949
for span in scope.from_root() {
30-
write!(writer, "{}", span.name())?;
31-
32-
// `FormattedFields` is a formatted representation of the span's
33-
// fields, which is stored in its extensions by the `fmt` layer's
34-
// `new_span` method. The fields will have been formatted
35-
// by the same field formatter that's provided to the event
36-
// formatter in the `FmtContext`.
50+
span_prefix.push_str(span.name());
3751
let ext = span.extensions();
38-
let fields = &ext
39-
.get::<FormattedFields<N>>()
40-
.expect("will never be `None`");
41-
42-
// Skip formatting the fields if the span had no fields.
43-
if !fields.is_empty() {
44-
write!(writer, "{{{fields}}}")?;
52+
if let Some(fields) = ext.get::<FormattedFields<N>>()
53+
&& !fields.is_empty()
54+
{
55+
span_prefix.push('{');
56+
span_prefix.push_str(fields);
57+
span_prefix.push('}');
4558
}
46-
write!(writer, ": ")?;
59+
span_prefix.push_str(": ");
4760
}
4861
}
4962

50-
// Write fields on the event
51-
ctx.field_format().format_fields(writer.by_ref(), event)?;
63+
let message = format!("DD_EXTENSION | {level} | {span_prefix}{}", visitor.0);
64+
65+
// Use serde_json for safe serialization (handles escaping automatically)
66+
let output = serde_json::json!({
67+
"level": level.to_string(),
68+
"message": message,
69+
});
70+
71+
writeln!(writer, "{output}")
72+
}
73+
}
74+
75+
#[cfg(test)]
76+
#[allow(clippy::unwrap_used)]
77+
mod tests {
78+
use super::*;
79+
use tracing::subscriber::with_default;
80+
use tracing_subscriber::fmt::Subscriber;
81+
82+
/// Captures all output from a tracing subscriber using our `Formatter`.
83+
fn capture_log<F: FnOnce()>(f: F) -> String {
84+
let buf = std::sync::Arc::new(std::sync::Mutex::new(Vec::new()));
85+
let buf_clone = buf.clone();
86+
87+
let subscriber = Subscriber::builder()
88+
.with_writer(move || -> Box<dyn std::io::Write + Send> {
89+
Box::new(WriterGuard(buf_clone.clone()))
90+
})
91+
.with_max_level(tracing::Level::TRACE)
92+
.with_level(true)
93+
.with_target(false)
94+
.without_time()
95+
.event_format(Formatter)
96+
.finish();
97+
98+
with_default(subscriber, f);
99+
100+
let lock = buf.lock().expect("test lock poisoned");
101+
String::from_utf8(lock.clone()).expect("invalid UTF-8 in log output")
102+
}
103+
104+
struct WriterGuard(std::sync::Arc<std::sync::Mutex<Vec<u8>>>);
105+
106+
impl std::io::Write for WriterGuard {
107+
fn write(&mut self, buf: &[u8]) -> std::io::Result<usize> {
108+
self.0
109+
.lock()
110+
.expect("write lock poisoned")
111+
.extend_from_slice(buf);
112+
Ok(buf.len())
113+
}
114+
fn flush(&mut self) -> std::io::Result<()> {
115+
Ok(())
116+
}
117+
}
118+
119+
#[test]
120+
fn test_formatter_outputs_valid_json_with_level() {
121+
let output = capture_log(|| {
122+
tracing::info!("hello world");
123+
});
124+
125+
let parsed: serde_json::Value =
126+
serde_json::from_str(output.trim()).expect("output should be valid JSON");
127+
128+
assert_eq!(parsed["level"], "INFO");
129+
assert!(
130+
parsed["message"]
131+
.as_str()
132+
.unwrap()
133+
.contains("DD_EXTENSION | INFO | hello world")
134+
);
135+
}
136+
137+
#[test]
138+
fn test_formatter_error_level() {
139+
let output = capture_log(|| {
140+
tracing::error!("something broke");
141+
});
142+
143+
let parsed: serde_json::Value =
144+
serde_json::from_str(output.trim()).expect("output should be valid JSON");
145+
assert_eq!(parsed["level"], "ERROR");
146+
assert!(
147+
parsed["message"]
148+
.as_str()
149+
.unwrap()
150+
.contains("DD_EXTENSION | ERROR | something broke")
151+
);
152+
}
153+
154+
#[test]
155+
fn test_formatter_debug_level() {
156+
let output = capture_log(|| {
157+
tracing::debug!("debug details");
158+
});
159+
160+
let parsed: serde_json::Value =
161+
serde_json::from_str(output.trim()).expect("output should be valid JSON");
162+
assert_eq!(parsed["level"], "DEBUG");
163+
assert!(
164+
parsed["message"]
165+
.as_str()
166+
.unwrap()
167+
.contains("DD_EXTENSION | DEBUG | debug details")
168+
);
169+
}
170+
171+
#[test]
172+
fn test_formatter_escapes_special_characters() {
173+
let output = capture_log(|| {
174+
tracing::info!("message with \"quotes\" and a\nnewline");
175+
});
176+
177+
// The raw output must contain escaped quotes and newlines to be valid JSON
178+
assert!(
179+
output.contains(r#"\"quotes\""#),
180+
"quotes should be escaped in raw JSON"
181+
);
182+
assert!(
183+
output.contains(r"\n"),
184+
"newline should be escaped in raw JSON"
185+
);
52186

53-
writeln!(writer)
187+
// And it must parse as valid JSON
188+
let parsed: serde_json::Value = serde_json::from_str(output.trim())
189+
.expect("output with special chars should be valid JSON");
190+
let msg = parsed["message"]
191+
.as_str()
192+
.expect("message field should be a string");
193+
assert!(
194+
msg.contains("\"quotes\""),
195+
"parsed message should contain literal quotes"
196+
);
197+
assert!(
198+
msg.contains('\n'),
199+
"parsed message should contain literal newline"
200+
);
54201
}
55202
}

0 commit comments

Comments
 (0)