tracing_subscriber: add additional fields for printing to json fmt subscriber

examples/README.md

@@ -37,6 +37,8 @@ This directory contains a collection of examples that demonstrate the use of the
     both the terminal and the system journal.
   + `toggle-subscribers` : Demonstrates how subscribers can be wrapped with an `Option` allowing
     them to be dynamically toggled.
+  + `fmt-additional-fields`: Demonstrates how to create a subscriber that enriches
+    the `fmt` collector with additional information.
 - **tracing-futures**:
   + `spawny-thing`: Demonstrates the use of the `#[instrument]` attribute macro
     asynchronous functions.

examples/examples/fmt-additional-fields.rs

@@ -0,0 +1,73 @@
+#![deny(rust_2018_idioms)]
+
+use std::sync::atomic::{AtomicUsize, Ordering};
+
+use tracing::{span, Collect};
+use tracing_subscriber::{
+    fmt::format::AdditionalFmtSpanFields,
+    registry::LookupSpan,
+    subscribe::{CollectExt, Context},
+    util::SubscriberInitExt,
+    Subscribe,
+};
+#[path = "fmt/yak_shave.rs"]
+mod yak_shave;
+
+struct CountingSubscribe(AtomicUsize);
+
+impl<C: Collect + for<'lookup> LookupSpan<'lookup>> Subscribe<C> for CountingSubscribe {
+    fn on_new_span(&self, _attrs: &span::Attributes<'_>, id: &span::Id, ctx: Context<'_, C>) {
+        // Find the span.
+        let span = ctx
+            .span(id)
+            .expect("The span should exist in the registry.");
+
+        // Get its extensions.
+        let mut extensions = span.extensions_mut();
+
+        // Find the additional fields in the extensions or create new ones. It's
+        // important to always look for a previous value as another layer may
+        // have already added some fields.
+        let mut additional_fields = extensions
+            .remove::<AdditionalFmtSpanFields>()
+            .unwrap_or_default();
+
+        // Add something to the fields.
+        let ordinal = self.0.fetch_add(1, Ordering::Relaxed);
+        additional_fields.insert("ordinal".to_owned(), ordinal.to_string());
+
+        // And don't forget to then put the additional fields into the extensions!
+        extensions.insert(additional_fields);
+    }
+}
+
+fn main() {
+    tracing_subscriber::fmt()
+        // Use json output...
+        .json()
+        // Enable additional span fields.
+        .with_additional_span_fields(true)
+        // Disable things not needed for the example to make the output more readable.
+        .with_span_list(false)
+        .without_time()
+        .with_target(false)
+        // Enable all levels.
+        .with_max_level(tracing::Level::TRACE)
+        // Create the collector...
+        .finish()
+        // and add our enriching subscriber as another layer.
+        // Try removing this and see what changes in the output!
+        .with(CountingSubscribe(AtomicUsize::new(0)))
+        // Set this to be the default, global collector for this application.
+        .init();
+
+    let number_of_yaks = 3;
+    // this creates a new event, outside of any spans.
+    tracing::info!(number_of_yaks, "preparing to shave yaks");
+
+    let number_shaved = yak_shave::shave_all(number_of_yaks);
+    tracing::info!(
+        all_yaks_shaved = number_shaved == number_of_yaks,
+        "yak shaving completed."
+    );
+}

tracing-subscriber/src/fmt/fmt_subscriber.rs

@@ -638,6 +638,24 @@ impl<C, T, W> Subscriber<C, format::JsonFields, format::Format<format::Json, T>,
             ..self
         }
     }
+
+    /// Sets whether or not the JSON subscriber being built will include
+    /// additional span fields dynamically added by
+    /// [`Subscribe`](crate::Subscribe) implementations in formatted events.
+    ///
+    /// See [`format::Json`] for details.
+    pub fn with_additional_span_fields(
+        self,
+        display_additional_span_fields: bool,
+    ) -> Subscriber<C, format::JsonFields, format::Format<format::Json, T>, W> {
+        Subscriber {
+            fmt_event: self
+                .fmt_event
+                .with_additional_span_fields(display_additional_span_fields),
+            fmt_fields: format::JsonFields::new(),
+            ..self
+        }
+    }
 }
 
 impl<C, N, E, W> Subscriber<C, N, E, W> {

tracing-subscriber/src/fmt/format/json.rs

@@ -1,4 +1,4 @@
-use super::{Format, FormatEvent, FormatFields, FormatTime, Writer};
+use super::{AdditionalFmtSpanFields, Format, FormatEvent, FormatFields, FormatTime, Writer};
 use crate::{
     field::{RecordFields, VisitOutput},
     fmt::{
@@ -74,6 +74,7 @@ pub struct Json {
     pub(crate) flatten_event: bool,
     pub(crate) display_current_span: bool,
     pub(crate) display_span_list: bool,
+    pub(crate) display_additional_span_fields: bool,
 }
 
 impl Json {
@@ -87,20 +88,30 @@ impl Json {
         self.display_current_span = display_current_span;
     }
 
+    /// If set to `false`, formatted events won't additional dynamic fields for the current span.
+    ///
+    /// These fields can be added by layered [`Subscribe`](crate::Subscribe) implementations that
+    /// may enrich the span by fields not defined by the callsite.
+    pub fn with_additional_span_fields(&mut self, display_additional_field_spans: bool) {
+        self.display_additional_span_fields = display_additional_field_spans;
+    }
+
     /// If set to `false`, formatted events won't contain a list of all currently
     /// entered spans. Spans are logged in a list from root to leaf.
     pub fn with_span_list(&mut self, display_span_list: bool) {
         self.display_span_list = display_span_list;
     }
 }
 
-struct SerializableContext<'a, 'b, Span, N>(
-    &'b crate::subscribe::Context<'a, Span>,
-    std::marker::PhantomData<N>,
-)
+struct SerializableContext<'a, 'b, Span, N>
 where
     Span: Collect + for<'lookup> crate::registry::LookupSpan<'lookup>,
-    N: for<'writer> FormatFields<'writer> + 'static;
+    N: for<'writer> FormatFields<'writer> + 'static,
+{
+    context: &'b crate::subscribe::Context<'a, Span>,
+    display_additional_fields: bool,
+    format_field_marker: std::marker::PhantomData<N>,
+}
 
 impl<'a, 'b, Span, N> serde::ser::Serialize for SerializableContext<'a, 'b, Span, N>
 where
@@ -114,23 +125,29 @@ where
         use serde::ser::SerializeSeq;
         let mut serializer = serializer_o.serialize_seq(None)?;
 
-        if let Some(leaf_span) = self.0.lookup_current() {
+        if let Some(leaf_span) = self.context.lookup_current() {
             for span in leaf_span.scope().from_root() {
-                serializer.serialize_element(&SerializableSpan(&span, self.1))?;
+                serializer.serialize_element(&SerializableSpan {
+                    span: &span,
+                    display_additional_fields: self.display_additional_fields,
+                    format_field_marker: self.format_field_marker,
+                })?;
             }
         }
 
         serializer.end()
     }
 }
 
-struct SerializableSpan<'a, 'b, Span, N>(
-    &'b crate::registry::SpanRef<'a, Span>,
-    std::marker::PhantomData<N>,
-)
+struct SerializableSpan<'a, 'b, Span, N>
 where
     Span: for<'lookup> crate::registry::LookupSpan<'lookup>,
-    N: for<'writer> FormatFields<'writer> + 'static;
+    N: for<'writer> FormatFields<'writer> + 'static,
+{
+    span: &'b crate::registry::SpanRef<'a, Span>,
+    display_additional_fields: bool,
+    format_field_marker: std::marker::PhantomData<N>,
+}
 
 impl<'a, 'b, Span, N> serde::ser::Serialize for SerializableSpan<'a, 'b, Span, N>
 where
@@ -143,7 +160,7 @@ where
     {
         let mut serializer = serializer.serialize_map(None)?;
 
-        let ext = self.0.extensions();
+        let ext = self.span.extensions();
         let data = ext
             .get::<FormattedFields<N>>()
             .expect("Unable to find FormattedFields in extensions; this is a bug");
@@ -158,37 +175,44 @@ where
                 for field in fields {
                     serializer.serialize_entry(&field.0, &field.1)?;
                 }
+                if self.display_additional_fields {
+                    if let Some(additional) = ext.get::<AdditionalFmtSpanFields>() {
+                        for field in &additional.0 {
+                            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(),
+                self.span.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
+            // crash the program, let's log the field found but also a
+            // message saying its type is invalid
             Ok(value) => {
                 serializer.serialize_entry("field", &value)?;
-                serializer.serialize_entry("field_error", "field was no a valid object")?
+                serializer.serialize_entry("field_error", "field was not a valid object")?
             }
             // 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(),
+                self.span.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))?,
+            Err(e) => serializer.serialize_entry("field_error", &format_args!("{}", e))?,
         };
-        serializer.serialize_entry("name", self.0.metadata().name())?;
+        serializer.serialize_entry("name", self.span.metadata().name())?;
         serializer.end()
     }
 }
@@ -272,15 +296,28 @@ where
             if self.format.display_current_span {
                 if let Some(ref span) = current_span {
                     serializer
-                        .serialize_entry("span", &SerializableSpan(span, format_field_marker))
+                        .serialize_entry(
+                            "span",
+                            &SerializableSpan {
+                                span,
+                                display_additional_fields: self
+                                    .format
+                                    .display_additional_span_fields,
+                                format_field_marker,
+                            },
+                        )
                         .unwrap_or(());
                 }
             }
 
             if self.format.display_span_list && current_span.is_some() {
                 serializer.serialize_entry(
                     "spans",
-                    &SerializableContext(&ctx.ctx, format_field_marker),
+                    &SerializableContext {
+                        context: &ctx.ctx,
+                        display_additional_fields: self.format.display_additional_span_fields,
+                        format_field_marker,
+                    },
                 )?;
             }
 
@@ -318,6 +355,7 @@ impl Default for Json {
             flatten_event: false,
             display_current_span: true,
             display_span_list: true,
+            display_additional_span_fields: true,
         }
     }
 }
@@ -513,7 +551,10 @@ impl<'a> field::Visit for JsonVisitor<'a> {
 mod test {
     use super::*;
     use crate::fmt::{format::FmtSpan, test::MockMakeWriter, time::FormatTime, CollectorBuilder};
+    use crate::subscribe::{self, CollectExt};
+    use crate::Subscribe;
 
+    use tracing::span;
     use tracing::{self, collect::with_default};
 
     use std::fmt;
@@ -529,6 +570,21 @@ mod test {
     fn collector() -> CollectorBuilder<JsonFields, Format<Json>> {
         crate::fmt::CollectorBuilder::default().json()
     }
+    struct InjectingSubscriber;
+    impl<C: Collect + for<'lookup> LookupSpan<'lookup>> Subscribe<C> for InjectingSubscriber {
+        fn on_new_span(
+            &self,
+            _attrs: &span::Attributes<'_>,
+            id: &span::Id,
+            ctx: subscribe::Context<'_, C>,
+        ) {
+            let mut additional = AdditionalFmtSpanFields::default();
+            additional.insert("additional".to_owned(), "value".to_owned());
+            let span_ref = ctx.span(id).unwrap();
+            let mut extensions = span_ref.extensions_mut();
+            extensions.insert(additional);
+        }
+    }
 
     #[test]
     fn json() {
@@ -855,4 +911,64 @@ mod test {
         }
         assert_eq!(actual, expected);
     }
+
+    #[test]
+    fn additional_fields() {
+        let expected =
+        "{\"timestamp\":\"fake time\",\"level\":\"INFO\",\"span\":{\"answer\":42,\"name\":\"json_span\",\"number\":3,\"additional\":\"value\"},\"spans\":[{\"answer\":42,\"name\":\"json_span\",\"number\":3,\"additional\":\"value\"}],\"target\":\"tracing_subscriber::fmt::format::json::test\",\"fields\":{\"message\":\"some json test\"}}\n";
+        let make_writer = MockMakeWriter::default();
+        let collector = collector()
+            .flatten_event(false)
+            .with_current_span(true)
+            .with_span_list(true)
+            .with_additional_span_fields(true)
+            .with_writer(make_writer.clone())
+            .with_timer(MockTime)
+            .finish()
+            .with(InjectingSubscriber);
+
+        with_default(collector, || {
+            let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3);
+            let _guard = span.enter();
+            tracing::info!("some json test");
+        });
+
+        let buf = make_writer.buf();
+        let actual = std::str::from_utf8(&buf[..]).unwrap();
+        assert_eq!(
+            serde_json::from_str::<std::collections::HashMap<&str, serde_json::Value>>(expected)
+                .unwrap(),
+            serde_json::from_str(actual).unwrap()
+        );
+    }
+
+    #[test]
+    fn additional_fields_turned_off() {
+        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";
+        let make_writer = MockMakeWriter::default();
+        let collector = collector()
+            .flatten_event(false)
+            .with_current_span(true)
+            .with_span_list(true)
+            .with_additional_span_fields(false)
+            .with_writer(make_writer.clone())
+            .with_timer(MockTime)
+            .finish()
+            .with(InjectingSubscriber);
+
+        with_default(collector, || {
+            let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3);
+            let _guard = span.enter();
+            tracing::info!("some json test");
+        });
+
+        let buf = make_writer.buf();
+        let actual = std::str::from_utf8(&buf[..]).unwrap();
+        assert_eq!(
+            serde_json::from_str::<std::collections::HashMap<&str, serde_json::Value>>(expected)
+                .unwrap(),
+            serde_json::from_str(actual).unwrap()
+        );
+    }
 }