From 0c47131ce6d1fc9d8c6a7b295a18ba853cadd531 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?David=20Ml=C3=A1dek?= Date: Fri, 26 Apr 2024 00:33:19 +0200 Subject: [PATCH 1/3] tracing: allow `&[u8]` to be recorded as event/span field --- tracing-core/src/field.rs | 13 +++++++++++++ tracing-subscriber/src/fmt/format/json.rs | 9 +++++++-- tracing-subscriber/src/fmt/format/pretty.rs | 11 +++++++++++ 3 files changed, 31 insertions(+), 2 deletions(-) diff --git a/tracing-core/src/field.rs b/tracing-core/src/field.rs index d9ba1707cd..948762baee 100644 --- a/tracing-core/src/field.rs +++ b/tracing-core/src/field.rs @@ -224,6 +224,11 @@ pub trait Visit { self.record_debug(field, &value) } + /// Visit a byte slice. + fn record_byte_slice(&mut self, field: &Field, value: &[u8]) { + self.record_debug(field, &value) + } + /// Records a type implementing `Error`. /// ///
@@ -443,6 +448,14 @@ impl Value for str { } } +impl crate::sealed::Sealed for [u8] {} + +impl Value for [u8] { + fn record(&self, key: &Field, visitor: &mut dyn Visit) { + visitor.record_byte_slice(key, self) + } +} + #[cfg(feature = "std")] impl crate::sealed::Sealed for dyn std::error::Error + 'static {} diff --git a/tracing-subscriber/src/fmt/format/json.rs b/tracing-subscriber/src/fmt/format/json.rs index f4e61fb123..e7e0eea10f 100644 --- a/tracing-subscriber/src/fmt/format/json.rs +++ b/tracing-subscriber/src/fmt/format/json.rs @@ -488,6 +488,11 @@ impl<'a> field::Visit for JsonVisitor<'a> { .insert(field.name(), serde_json::Value::from(value)); } + fn record_byte_slice(&mut self, field: &Field, value: &[u8]) { + self.values + .insert(field.name(), serde_json::Value::from(value)); + } + fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) { match field.name() { // Skip fields that are actually log metadata that have already been handled @@ -528,13 +533,13 @@ mod test { #[test] fn json() { let expected = - "{\"timestamp\":\"fake time\",\"level\":\"INFO\",\"span\":{\"answer\":42,\"name\":\"json_span\",\"number\":3},\"spans\":[{\"answer\":42,\"name\":\"json_span\",\"number\":3}],\"target\":\"tracing_subscriber::fmt::format::json::test\",\"fields\":{\"message\":\"some json test\"}}\n"; + "{\"timestamp\":\"fake time\",\"level\":\"INFO\",\"span\":{\"answer\":42,\"name\":\"json_span\",\"number\":3,\"slice\":[97,98,99]},\"spans\":[{\"answer\":42,\"name\":\"json_span\",\"number\":3,\"slice\":[97,98,99]}],\"target\":\"tracing_subscriber::fmt::format::json::test\",\"fields\":{\"message\":\"some json test\"}}\n"; let collector = collector() .flatten_event(false) .with_current_span(true) .with_span_list(true); test_json(expected, collector, || { - let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3); + let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3, slice = &b"abc"[..]); let _guard = span.enter(); tracing::info!("some json test"); }); diff --git a/tracing-subscriber/src/fmt/format/pretty.rs b/tracing-subscriber/src/fmt/format/pretty.rs index 1a0edd428c..ed31ce7aa0 100644 --- a/tracing-subscriber/src/fmt/format/pretty.rs +++ b/tracing-subscriber/src/fmt/format/pretty.rs @@ -426,6 +426,17 @@ impl<'a> PrettyVisitor<'a> { } impl<'a> field::Visit for PrettyVisitor<'a> { + fn record_byte_slice(&mut self, field: &Field, value: &[u8]) { + let hex = + value + .iter() + .fold(String::with_capacity(value.len() * 2), |mut acc, byte| { + acc.push_str(&format!("{byte:02x}")); + acc + }); + self.record_debug(field, &format_args!("{}", hex)); + } + fn record_str(&mut self, field: &Field, value: &str) { if self.result.is_err() { return; From 7d935e82ec50bca39cd469fdc9238208bef4652f Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?David=20Ml=C3=A1dek?= Date: Fri, 26 Apr 2024 09:40:39 +0200 Subject: [PATCH 2/3] review fixes `record_byte_slice` renamed to `record_bytes`, default implementation provides a type that prints hex representation of the bytes in its debug impl, removed both overriding implementations (json and pretty) because hex is good enough for both --- tracing-core/src/field.rs | 37 +++++++++++++++++++-- tracing-subscriber/src/fmt/format/json.rs | 7 +--- tracing-subscriber/src/fmt/format/pretty.rs | 11 ------ 3 files changed, 35 insertions(+), 20 deletions(-) diff --git a/tracing-core/src/field.rs b/tracing-core/src/field.rs index 948762baee..5ef4834f89 100644 --- a/tracing-core/src/field.rs +++ b/tracing-core/src/field.rs @@ -225,8 +225,8 @@ pub trait Visit { } /// Visit a byte slice. - fn record_byte_slice(&mut self, field: &Field, value: &[u8]) { - self.record_debug(field, &value) + fn record_bytes(&mut self, field: &Field, value: &[u8]) { + self.record_debug(field, &HexBytes(value)) } /// Records a type implementing `Error`. @@ -288,6 +288,18 @@ where DebugValue(t) } +struct HexBytes<'a>(&'a [u8]); + +impl<'a> fmt::Debug for HexBytes<'a> { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + for byte in self.0 { + f.write_fmt(format_args!("{byte:02x}"))?; + } + + Ok(()) + } +} + // ===== impl Visit ===== impl<'a, 'b> Visit for fmt::DebugStruct<'a, 'b> { @@ -452,7 +464,7 @@ impl crate::sealed::Sealed for [u8] {} impl Value for [u8] { fn record(&self, key: &Field, visitor: &mut dyn Visit) { - visitor.record_byte_slice(key, self) + visitor.record_bytes(key, self) } } @@ -1144,4 +1156,23 @@ mod test { }); assert_eq!(result, format!("{}", err)); } + + #[test] + fn record_bytes() { + let fields = TEST_META_1.fields(); + let first = &b"abc"[..]; + let second: &[u8] = &[192, 255, 238]; + let values = &[ + (&fields.field("foo").unwrap(), Some(&first as &dyn Value)), + (&fields.field("bar").unwrap(), Some(&" " as &dyn Value)), + (&fields.field("baz").unwrap(), Some(&second as &dyn Value)), + ]; + let valueset = fields.value_set(values); + let mut result = String::new(); + valueset.record(&mut |_: &Field, value: &dyn fmt::Debug| { + use core::fmt::Write; + write!(&mut result, "{:?}", value).unwrap(); + }); + assert_eq!(result, format!("{}", r#"616263" "c0ffee"#)); + } } diff --git a/tracing-subscriber/src/fmt/format/json.rs b/tracing-subscriber/src/fmt/format/json.rs index e7e0eea10f..d56f1dbd6c 100644 --- a/tracing-subscriber/src/fmt/format/json.rs +++ b/tracing-subscriber/src/fmt/format/json.rs @@ -488,11 +488,6 @@ impl<'a> field::Visit for JsonVisitor<'a> { .insert(field.name(), serde_json::Value::from(value)); } - fn record_byte_slice(&mut self, field: &Field, value: &[u8]) { - self.values - .insert(field.name(), serde_json::Value::from(value)); - } - fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) { match field.name() { // Skip fields that are actually log metadata that have already been handled @@ -533,7 +528,7 @@ mod test { #[test] fn json() { let expected = - "{\"timestamp\":\"fake time\",\"level\":\"INFO\",\"span\":{\"answer\":42,\"name\":\"json_span\",\"number\":3,\"slice\":[97,98,99]},\"spans\":[{\"answer\":42,\"name\":\"json_span\",\"number\":3,\"slice\":[97,98,99]}],\"target\":\"tracing_subscriber::fmt::format::json::test\",\"fields\":{\"message\":\"some json test\"}}\n"; + "{\"timestamp\":\"fake time\",\"level\":\"INFO\",\"span\":{\"answer\":42,\"name\":\"json_span\",\"number\":3,\"slice\":\"616263\"},\"spans\":[{\"answer\":42,\"name\":\"json_span\",\"number\":3,\"slice\":\"616263\"}],\"target\":\"tracing_subscriber::fmt::format::json::test\",\"fields\":{\"message\":\"some json test\"}}\n"; let collector = collector() .flatten_event(false) .with_current_span(true) diff --git a/tracing-subscriber/src/fmt/format/pretty.rs b/tracing-subscriber/src/fmt/format/pretty.rs index ed31ce7aa0..1a0edd428c 100644 --- a/tracing-subscriber/src/fmt/format/pretty.rs +++ b/tracing-subscriber/src/fmt/format/pretty.rs @@ -426,17 +426,6 @@ impl<'a> PrettyVisitor<'a> { } impl<'a> field::Visit for PrettyVisitor<'a> { - fn record_byte_slice(&mut self, field: &Field, value: &[u8]) { - let hex = - value - .iter() - .fold(String::with_capacity(value.len() * 2), |mut acc, byte| { - acc.push_str(&format!("{byte:02x}")); - acc - }); - self.record_debug(field, &format_args!("{}", hex)); - } - fn record_str(&mut self, field: &Field, value: &str) { if self.result.is_err() { return; From 6ac7c0a27830e10268ea4a3300afb8b3f28bb2c5 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?David=20Ml=C3=A1dek?= Date: Sat, 27 Apr 2024 01:24:06 +0200 Subject: [PATCH 3/3] review second round - debug impl output changed to [de ad be ef] and json has its own implementation --- tracing-core/src/field.rs | 16 ++++++++++++---- tracing-subscriber/src/fmt/format/json.rs | 15 +++++++++++++-- 2 files changed, 25 insertions(+), 6 deletions(-) diff --git a/tracing-core/src/field.rs b/tracing-core/src/field.rs index 5ef4834f89..bc8bcfecf0 100644 --- a/tracing-core/src/field.rs +++ b/tracing-core/src/field.rs @@ -38,7 +38,7 @@ use crate::callsite; use core::{ borrow::Borrow, - fmt, + fmt::{self, Write}, hash::{Hash, Hasher}, num, ops::Range, @@ -292,11 +292,19 @@ struct HexBytes<'a>(&'a [u8]); impl<'a> fmt::Debug for HexBytes<'a> { fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { - for byte in self.0 { + f.write_char('[')?; + + let mut bytes = self.0.iter(); + + if let Some(byte) = bytes.next() { f.write_fmt(format_args!("{byte:02x}"))?; } - Ok(()) + for byte in bytes { + f.write_fmt(format_args!(" {byte:02x}"))?; + } + + f.write_char(']') } } @@ -1173,6 +1181,6 @@ mod test { use core::fmt::Write; write!(&mut result, "{:?}", value).unwrap(); }); - assert_eq!(result, format!("{}", r#"616263" "c0ffee"#)); + assert_eq!(result, format!("{}", r#"[61 62 63]" "[c0 ff ee]"#)); } } diff --git a/tracing-subscriber/src/fmt/format/json.rs b/tracing-subscriber/src/fmt/format/json.rs index d56f1dbd6c..1f045d93b5 100644 --- a/tracing-subscriber/src/fmt/format/json.rs +++ b/tracing-subscriber/src/fmt/format/json.rs @@ -488,6 +488,11 @@ impl<'a> field::Visit for JsonVisitor<'a> { .insert(field.name(), serde_json::Value::from(value)); } + fn record_bytes(&mut self, field: &Field, value: &[u8]) { + self.values + .insert(field.name(), serde_json::Value::from(value)); + } + fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) { match field.name() { // Skip fields that are actually log metadata that have already been handled @@ -528,13 +533,19 @@ mod test { #[test] fn json() { let expected = - "{\"timestamp\":\"fake time\",\"level\":\"INFO\",\"span\":{\"answer\":42,\"name\":\"json_span\",\"number\":3,\"slice\":\"616263\"},\"spans\":[{\"answer\":42,\"name\":\"json_span\",\"number\":3,\"slice\":\"616263\"}],\"target\":\"tracing_subscriber::fmt::format::json::test\",\"fields\":{\"message\":\"some json test\"}}\n"; + "{\"timestamp\":\"fake time\",\"level\":\"INFO\",\"span\":{\"answer\":42,\"name\":\"json_span\",\"number\":3,\"slice\":[97,98,99]},\"spans\":[{\"answer\":42,\"name\":\"json_span\",\"number\":3,\"slice\":[97,98,99]}],\"target\":\"tracing_subscriber::fmt::format::json::test\",\"fields\":{\"message\":\"some json test\"}}\n"; let collector = collector() .flatten_event(false) .with_current_span(true) .with_span_list(true); test_json(expected, collector, || { - let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3, slice = &b"abc"[..]); + let span = tracing::span!( + tracing::Level::INFO, + "json_span", + answer = 42, + number = 3, + slice = &b"abc"[..] + ); let _guard = span.enter(); tracing::info!("some json test"); });