From 5f1baccf16d8b5918f99bc36f885292805ac8372 Mon Sep 17 00:00:00 2001 From: Leonid Beschastny Date: Tue, 22 Jul 2025 16:25:28 +0200 Subject: [PATCH 1/2] tracing-subscriber: optimise span fields serialisation Move formatted fields from Span to json log without storing them in an intermediate `serde_json::Value` by using a smart serde visitor. --- tracing-subscriber/Cargo.toml | 2 +- tracing-subscriber/src/fmt/format/json.rs | 89 ++++++++++++----------- 2 files changed, 49 insertions(+), 42 deletions(-) diff --git a/tracing-subscriber/Cargo.toml b/tracing-subscriber/Cargo.toml index 1ea08eb70b..4f99f67204 100644 --- a/tracing-subscriber/Cargo.toml +++ b/tracing-subscriber/Cargo.toml @@ -31,7 +31,7 @@ env-filter = ["matchers", "once_cell", "tracing", "std", "thread_local", "dep:re fmt = ["registry", "std"] ansi = ["fmt", "nu-ansi-term"] registry = ["sharded-slab", "thread_local", "std"] -json = ["tracing-serde", "serde", "serde_json"] +json = ["tracing-serde", "serde", "serde_json", "serde/derive"] valuable = ["tracing-core/valuable", "valuable_crate", "valuable-serde", "tracing-serde/valuable"] # Enables support for local time when using the `time` crate timestamp # formatters. diff --git a/tracing-subscriber/src/fmt/format/json.rs b/tracing-subscriber/src/fmt/format/json.rs index 3ef0fcd653..d5600aba1d 100644 --- a/tracing-subscriber/src/fmt/format/json.rs +++ b/tracing-subscriber/src/fmt/format/json.rs @@ -7,8 +7,8 @@ use crate::{ }, registry::LookupSpan, }; -use serde::ser::{SerializeMap, Serializer as _}; -use serde_json::Serializer; +use serde::{ser::SerializeMap, Deserialize, Deserializer as _, Serialize, Serializer as _}; +use serde_json::{Deserializer, Serializer}; use std::{ collections::BTreeMap, fmt::{self, Write}, @@ -165,46 +165,24 @@ where .get::>() .expect("Unable to find FormattedFields in extensions; this is a bug"); - // TODO: let's _not_ do this, but this resolves - // https://github.com/tokio-rs/tracing/issues/391. - // We should probably rework this to use a `serde_json::Value` or something - // similar in a JSON-specific layer, but I'd (david) - // rather have a uglier fix now rather than shipping broken JSON. - match serde_json::from_str::(data) { - Ok(serde_json::Value::Object(fields)) => { - for field in fields { - serializer.serialize_entry(&field.0, &field.1)?; - } - } - // We have fields for this span which are valid JSON but not an object. - // This is probably a bug, so panic if we're in debug mode - Ok(_) if cfg!(debug_assertions) => panic!( - "span '{}' had malformed fields! this is a bug.\n error: invalid JSON object\n fields: {:?}", - self.0.metadata().name(), - data - ), - // If we *aren't* in debug mode, it's probably best not to - // crash the program, let's log the field found but also an - // message saying it's type is invalid - Ok(value) => { - serializer.serialize_entry("field", &value)?; - serializer.serialize_entry("field_error", "field was no a valid object")? + let mut deserializer = Deserializer::from_str(data); + if let Err(error) = deserializer.deserialize_map(SerializeMapVisitor(&mut serializer)) { + // We have fields for this span which are not a valid JSON object. + if cfg!(debug_assertions) { + // This is probably a bug, so panic if we're in debug mode + panic!( + "span '{}' had malformed fields! this is a bug.\n error: {}\n fields: {:?}", + self.0.metadata().name(), + error, + data + ); + } else { + // If we *aren't* in debug mode, it's probably best not to crash the program, + // let's log the raw fields together with the parsing error from serde + serializer.serialize_entry("fields", &data.fields)?; + serializer.serialize_entry("fields_error", &format!("{error:?}"))?; } - // We have previously recorded fields for this span - // should be valid JSON. However, they appear to *not* - // be valid JSON. This is almost certainly a bug, so - // panic if we're in debug mode - Err(e) if cfg!(debug_assertions) => panic!( - "span '{}' had malformed fields! this is a bug.\n error: {}\n fields: {:?}", - self.0.metadata().name(), - e, - data - ), - // If we *aren't* in debug mode, it's probably best not - // crash the program, but let's at least make sure it's clear - // that the fields are not supposed to be missing. - Err(e) => serializer.serialize_entry("field_error", &format!("{}", e))?, - }; + } serializer.serialize_entry("name", self.0.metadata().name())?; serializer.end() } @@ -417,6 +395,35 @@ impl<'a> FormatFields<'a> for JsonFields { } } +#[derive(Serialize, Deserialize)] +#[serde(untagged)] +enum SpanFieldsValue<'a> { + /// String which could be borrowed directly from the input json + Borrowed(&'a str), + /// Any other value + Owned(serde_json::Value), +} + +/// The [serde::de::Visitor] which moves entries from one map to another. +struct SerializeMapVisitor<'a, S: SerializeMap>(&'a mut S); + +impl<'de, S: SerializeMap> serde::de::Visitor<'de> for SerializeMapVisitor<'_, S> { + type Value = (); + + fn expecting(&self, formatter: &mut fmt::Formatter<'_>) -> fmt::Result { + write!(formatter, "a map of values") + } + + fn visit_map>(self, mut map: A) -> Result { + while let Some((key, value)) = map.next_entry::<&str, SpanFieldsValue<'_>>()? { + self.0 + .serialize_entry(key, &value) + .map_err(serde::de::Error::custom)?; + } + Ok(()) + } +} + /// The [visitor] produced by [`JsonFields`]'s [`MakeVisitor`] implementation. /// /// [visitor]: crate::field::Visit From 80edbf533762c3b5818678627148d8d133740c89 Mon Sep 17 00:00:00 2001 From: Leonid Beschastny Date: Tue, 22 Jul 2025 21:54:51 +0200 Subject: [PATCH 2/2] Drop custom SpanFieldsValue in favour of better optimised serde_json::Value --- tracing-subscriber/Cargo.toml | 2 +- tracing-subscriber/src/fmt/format/json.rs | 13 ++----------- 2 files changed, 3 insertions(+), 12 deletions(-) diff --git a/tracing-subscriber/Cargo.toml b/tracing-subscriber/Cargo.toml index 4f99f67204..1ea08eb70b 100644 --- a/tracing-subscriber/Cargo.toml +++ b/tracing-subscriber/Cargo.toml @@ -31,7 +31,7 @@ env-filter = ["matchers", "once_cell", "tracing", "std", "thread_local", "dep:re fmt = ["registry", "std"] ansi = ["fmt", "nu-ansi-term"] registry = ["sharded-slab", "thread_local", "std"] -json = ["tracing-serde", "serde", "serde_json", "serde/derive"] +json = ["tracing-serde", "serde", "serde_json"] valuable = ["tracing-core/valuable", "valuable_crate", "valuable-serde", "tracing-serde/valuable"] # Enables support for local time when using the `time` crate timestamp # formatters. diff --git a/tracing-subscriber/src/fmt/format/json.rs b/tracing-subscriber/src/fmt/format/json.rs index d5600aba1d..cfb8291c89 100644 --- a/tracing-subscriber/src/fmt/format/json.rs +++ b/tracing-subscriber/src/fmt/format/json.rs @@ -7,7 +7,7 @@ use crate::{ }, registry::LookupSpan, }; -use serde::{ser::SerializeMap, Deserialize, Deserializer as _, Serialize, Serializer as _}; +use serde::{ser::SerializeMap, Deserializer as _, Serializer as _}; use serde_json::{Deserializer, Serializer}; use std::{ collections::BTreeMap, @@ -395,15 +395,6 @@ impl<'a> FormatFields<'a> for JsonFields { } } -#[derive(Serialize, Deserialize)] -#[serde(untagged)] -enum SpanFieldsValue<'a> { - /// String which could be borrowed directly from the input json - Borrowed(&'a str), - /// Any other value - Owned(serde_json::Value), -} - /// The [serde::de::Visitor] which moves entries from one map to another. struct SerializeMapVisitor<'a, S: SerializeMap>(&'a mut S); @@ -415,7 +406,7 @@ impl<'de, S: SerializeMap> serde::de::Visitor<'de> for SerializeMapVisitor<'_, S } fn visit_map>(self, mut map: A) -> Result { - while let Some((key, value)) = map.next_entry::<&str, SpanFieldsValue<'_>>()? { + while let Some((key, value)) = map.next_entry::<&str, serde_json::Value>()? { self.0 .serialize_entry(key, &value) .map_err(serde::de::Error::custom)?;