fix(logs): format log level into correct status

bottlecap/Cargo.toml

@@ -34,7 +34,7 @@ tokio = { version = "1.47", default-features = false, features = ["macros", "rt-
 tokio-util = { version = "0.7", default-features = false }
 tracing = { version = "0.1", default-features = false }
 tracing-core = { version = "0.1", default-features = false }
-tracing-subscriber = { version = "0.3", default-features = false, features = ["std", "registry", "fmt", "env-filter", "tracing-log"] }
+tracing-subscriber = { version = "0.3", default-features = false, features = ["std", "registry", "fmt", "env-filter", "tracing-log", "json"] }
 hmac = { version = "0.12", default-features = false }
 sha2 = { version = "0.10", default-features = false }
 hex = { version = "0.4", default-features = false, features = ["std"] }

bottlecap/LICENSE-3rdparty.csv

@@ -235,6 +235,7 @@ tracing,https://github.com/tokio-rs/tracing,MIT,"Eliza Weisman <eliza@buoyant.io
 tracing-attributes,https://github.com/tokio-rs/tracing,MIT,"Tokio Contributors <team@tokio.rs>, Eliza Weisman <eliza@buoyant.io>, David Barsky <dbarsky@amazon.com>"
 tracing-core,https://github.com/tokio-rs/tracing,MIT,Tokio Contributors <team@tokio.rs>
 tracing-log,https://github.com/tokio-rs/tracing,MIT,Tokio Contributors <team@tokio.rs>
+tracing-serde,https://github.com/tokio-rs/tracing,MIT,Tokio Contributors <team@tokio.rs>
 tracing-subscriber,https://github.com/tokio-rs/tracing,MIT,"Eliza Weisman <eliza@buoyant.io>, David Barsky <me@davidbarsky.com>, Tokio Contributors <team@tokio.rs>"
 try-lock,https://github.com/seanmonstar/try-lock,MIT,Sean McArthur <sean@seanmonstar.com>
 twoway,https://github.com/bluss/twoway,MIT OR Apache-2.0,bluss

bottlecap/src/logger.rs

@@ -9,6 +9,23 @@ use tracing_subscriber::registry::LookupSpan;
 #[derive(Debug, Clone, Copy)]
 pub struct Formatter;
 
+/// Visitor that captures the message from tracing event fields.
+struct MessageVisitor(String);
+
+impl tracing::field::Visit for MessageVisitor {
+    fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn fmt::Debug) {
+        if field.name() == "message" {
+            self.0 = format!("{value:?}");
+        }
+    }
+
+    fn record_str(&mut self, field: &tracing::field::Field, value: &str) {
+        if field.name() == "message" {
+            self.0 = value.to_string();
+        }
+    }
+}
+
 impl<S, N> FormatEvent<S, N> for Formatter
 where
     S: Subscriber + for<'a> LookupSpan<'a>,
@@ -20,36 +37,166 @@ where
         mut writer: format::Writer<'_>,
         event: &Event<'_>,
     ) -> fmt::Result {
-        // Format values from the event's's metadata:
         let metadata = event.metadata();
-        write!(&mut writer, "DD_EXTENSION | {} | ", metadata.level())?;
+        let level = metadata.level();
 
-        // Format all the spans in the event's span context.
+        let mut visitor = MessageVisitor(String::new());
+        event.record(&mut visitor);
+
+        // Build span context prefix
+        let mut span_prefix = String::new();
         if let Some(scope) = ctx.event_scope() {
             for span in scope.from_root() {
-                write!(writer, "{}", span.name())?;
-
-                // `FormattedFields` is a formatted representation of the span's
-                // fields, which is stored in its extensions by the `fmt` layer's
-                // `new_span` method. The fields will have been formatted
-                // by the same field formatter that's provided to the event
-                // formatter in the `FmtContext`.
+                span_prefix.push_str(span.name());
                 let ext = span.extensions();
-                let fields = &ext
-                    .get::<FormattedFields<N>>()
-                    .expect("will never be `None`");
-
-                // Skip formatting the fields if the span had no fields.
-                if !fields.is_empty() {
-                    write!(writer, "{{{fields}}}")?;
+                if let Some(fields) = ext.get::<FormattedFields<N>>()
+                    && !fields.is_empty()
+                {
+                    span_prefix.push('{');
+                    span_prefix.push_str(fields);
+                    span_prefix.push('}');
                 }
-                write!(writer, ": ")?;
+                span_prefix.push_str(": ");
             }
         }
 
-        // Write fields on the event
-        ctx.field_format().format_fields(writer.by_ref(), event)?;
+        let message = format!("DD_EXTENSION | {level} | {span_prefix}{}", visitor.0);
+
+        // Use serde_json for safe serialization (handles escaping automatically)
+        let output = serde_json::json!({
+            "level": level.to_string(),
+            "message": message,
+        });
+
+        writeln!(writer, "{output}")
+    }
+}
+
+#[cfg(test)]
+#[allow(clippy::unwrap_used)]
+mod tests {
+    use super::*;
+    use tracing::subscriber::with_default;
+    use tracing_subscriber::fmt::Subscriber;
+
+    /// Captures all output from a tracing subscriber using our `Formatter`.
+    fn capture_log<F: FnOnce()>(f: F) -> String {
+        let buf = std::sync::Arc::new(std::sync::Mutex::new(Vec::new()));
+        let buf_clone = buf.clone();
+
+        let subscriber = Subscriber::builder()
+            .with_writer(move || -> Box<dyn std::io::Write + Send> {
+                Box::new(WriterGuard(buf_clone.clone()))
+            })
+            .with_max_level(tracing::Level::TRACE)
+            .with_level(true)
+            .with_target(false)
+            .without_time()
+            .event_format(Formatter)
+            .finish();
+
+        with_default(subscriber, f);
+
+        let lock = buf.lock().expect("test lock poisoned");
+        String::from_utf8(lock.clone()).expect("invalid UTF-8 in log output")
+    }
+
+    struct WriterGuard(std::sync::Arc<std::sync::Mutex<Vec<u8>>>);
+
+    impl std::io::Write for WriterGuard {
+        fn write(&mut self, buf: &[u8]) -> std::io::Result<usize> {
+            self.0
+                .lock()
+                .expect("write lock poisoned")
+                .extend_from_slice(buf);
+            Ok(buf.len())
+        }
+        fn flush(&mut self) -> std::io::Result<()> {
+            Ok(())
+        }
+    }
+
+    #[test]
+    fn test_formatter_outputs_valid_json_with_level() {
+        let output = capture_log(|| {
+            tracing::info!("hello world");
+        });
+
+        let parsed: serde_json::Value =
+            serde_json::from_str(output.trim()).expect("output should be valid JSON");
+
+        assert_eq!(parsed["level"], "INFO");
+        assert!(
+            parsed["message"]
+                .as_str()
+                .unwrap()
+                .contains("DD_EXTENSION | INFO | hello world")
+        );
+    }
+
+    #[test]
+    fn test_formatter_error_level() {
+        let output = capture_log(|| {
+            tracing::error!("something broke");
+        });
+
+        let parsed: serde_json::Value =
+            serde_json::from_str(output.trim()).expect("output should be valid JSON");
+        assert_eq!(parsed["level"], "ERROR");
+        assert!(
+            parsed["message"]
+                .as_str()
+                .unwrap()
+                .contains("DD_EXTENSION | ERROR | something broke")
+        );
+    }
+
+    #[test]
+    fn test_formatter_debug_level() {
+        let output = capture_log(|| {
+            tracing::debug!("debug details");
+        });
+
+        let parsed: serde_json::Value =
+            serde_json::from_str(output.trim()).expect("output should be valid JSON");
+        assert_eq!(parsed["level"], "DEBUG");
+        assert!(
+            parsed["message"]
+                .as_str()
+                .unwrap()
+                .contains("DD_EXTENSION | DEBUG | debug details")
+        );
+    }
+
+    #[test]
+    fn test_formatter_escapes_special_characters() {
+        let output = capture_log(|| {
+            tracing::info!("message with \"quotes\" and a\nnewline");
+        });
+
+        // The raw output must contain escaped quotes and newlines to be valid JSON
+        assert!(
+            output.contains(r#"\"quotes\""#),
+            "quotes should be escaped in raw JSON"
+        );
+        assert!(
+            output.contains(r"\n"),
+            "newline should be escaped in raw JSON"
+        );
 
-        writeln!(writer)
+        // And it must parse as valid JSON
+        let parsed: serde_json::Value = serde_json::from_str(output.trim())
+            .expect("output with special chars should be valid JSON");
+        let msg = parsed["message"]
+            .as_str()
+            .expect("message field should be a string");
+        assert!(
+            msg.contains("\"quotes\""),
+            "parsed message should contain literal quotes"
+        );
+        assert!(
+            msg.contains('\n'),
+            "parsed message should contain literal newline"
+        );
     }
 }