🛈 Note: This is pre-release documentation for the upcoming tracing 0.2.0 ecosystem.

For the release documentation, please see docs.rs, instead.

tracing_subscriber/fmt/format/
json.rs

1use super::{Format, FormatEvent, FormatFields, FormatTime, Writer};
2use crate::{
3    field::{RecordFields, VisitOutput},
4    fmt::{
5        fmt_subscriber::{FmtContext, FormattedFields},
6        writer::WriteAdaptor,
7    },
8    registry::LookupSpan,
9};
10use serde::ser::{SerializeMap, Serializer as _};
11use serde_json::Serializer;
12use std::{
13    collections::BTreeMap,
14    fmt::{self, Write},
15};
16use tracing_core::{
17    field::{self, Field},
18    span::Record,
19    Collect, Event,
20};
21use tracing_serde::AsSerde;
22
23#[cfg(feature = "tracing-log")]
24use tracing_log::NormalizeEvent;
25
26/// Marker for [`Format`] that indicates that the newline-delimited JSON log
27/// format should be used.
28///
29/// This formatter is intended for production use with systems where structured
30/// logs are consumed as JSON by analysis and viewing tools. The JSON output is
31/// not optimized for human readability; instead, it should be pretty-printed
32/// using external JSON tools such as `jq`, or using a JSON log viewer.
33///
34/// # Example Output
35///
36/// <pre><font color="#4E9A06"><b>:;</b></font> <font color="#4E9A06">cargo</font> run --example fmt-json
37/// <font color="#4E9A06"><b>    Finished</b></font> dev [unoptimized + debuginfo] target(s) in 0.08s
38/// <font color="#4E9A06"><b>     Running</b></font> `target/debug/examples/fmt-json`
39/// {&quot;timestamp&quot;:&quot;2022-02-15T18:47:10.821315Z&quot;,&quot;level&quot;:&quot;INFO&quot;,&quot;fields&quot;:{&quot;message&quot;:&quot;preparing to shave yaks&quot;,&quot;number_of_yaks&quot;:3},&quot;target&quot;:&quot;fmt_json&quot;}
40/// {&quot;timestamp&quot;:&quot;2022-02-15T18:47:10.821422Z&quot;,&quot;level&quot;:&quot;INFO&quot;,&quot;fields&quot;:{&quot;message&quot;:&quot;shaving yaks&quot;},&quot;target&quot;:&quot;fmt_json::yak_shave&quot;,&quot;spans&quot;:[{&quot;yaks&quot;:3,&quot;name&quot;:&quot;shaving_yaks&quot;}]}
41/// {&quot;timestamp&quot;:&quot;2022-02-15T18:47:10.821495Z&quot;,&quot;level&quot;:&quot;TRACE&quot;,&quot;fields&quot;:{&quot;message&quot;:&quot;hello! I&apos;m gonna shave a yak&quot;,&quot;excitement&quot;:&quot;yay!&quot;},&quot;target&quot;:&quot;fmt_json::yak_shave&quot;,&quot;spans&quot;:[{&quot;yaks&quot;:3,&quot;name&quot;:&quot;shaving_yaks&quot;},{&quot;yak&quot;:1,&quot;name&quot;:&quot;shave&quot;}]}
42/// {&quot;timestamp&quot;:&quot;2022-02-15T18:47:10.821546Z&quot;,&quot;level&quot;:&quot;TRACE&quot;,&quot;fields&quot;:{&quot;message&quot;:&quot;yak shaved successfully&quot;},&quot;target&quot;:&quot;fmt_json::yak_shave&quot;,&quot;spans&quot;:[{&quot;yaks&quot;:3,&quot;name&quot;:&quot;shaving_yaks&quot;},{&quot;yak&quot;:1,&quot;name&quot;:&quot;shave&quot;}]}
43/// {&quot;timestamp&quot;:&quot;2022-02-15T18:47:10.821598Z&quot;,&quot;level&quot;:&quot;DEBUG&quot;,&quot;fields&quot;:{&quot;yak&quot;:1,&quot;shaved&quot;:true},&quot;target&quot;:&quot;yak_events&quot;,&quot;spans&quot;:[{&quot;yaks&quot;:3,&quot;name&quot;:&quot;shaving_yaks&quot;}]}
44/// {&quot;timestamp&quot;:&quot;2022-02-15T18:47:10.821637Z&quot;,&quot;level&quot;:&quot;TRACE&quot;,&quot;fields&quot;:{&quot;yaks_shaved&quot;:1},&quot;target&quot;:&quot;fmt_json::yak_shave&quot;,&quot;spans&quot;:[{&quot;yaks&quot;:3,&quot;name&quot;:&quot;shaving_yaks&quot;}]}
45/// {&quot;timestamp&quot;:&quot;2022-02-15T18:47:10.821684Z&quot;,&quot;level&quot;:&quot;TRACE&quot;,&quot;fields&quot;:{&quot;message&quot;:&quot;hello! I&apos;m gonna shave a yak&quot;,&quot;excitement&quot;:&quot;yay!&quot;},&quot;target&quot;:&quot;fmt_json::yak_shave&quot;,&quot;spans&quot;:[{&quot;yaks&quot;:3,&quot;name&quot;:&quot;shaving_yaks&quot;},{&quot;yak&quot;:2,&quot;name&quot;:&quot;shave&quot;}]}
46/// {&quot;timestamp&quot;:&quot;2022-02-15T18:47:10.821727Z&quot;,&quot;level&quot;:&quot;TRACE&quot;,&quot;fields&quot;:{&quot;message&quot;:&quot;yak shaved successfully&quot;},&quot;target&quot;:&quot;fmt_json::yak_shave&quot;,&quot;spans&quot;:[{&quot;yaks&quot;:3,&quot;name&quot;:&quot;shaving_yaks&quot;},{&quot;yak&quot;:2,&quot;name&quot;:&quot;shave&quot;}]}
47/// {&quot;timestamp&quot;:&quot;2022-02-15T18:47:10.821773Z&quot;,&quot;level&quot;:&quot;DEBUG&quot;,&quot;fields&quot;:{&quot;yak&quot;:2,&quot;shaved&quot;:true},&quot;target&quot;:&quot;yak_events&quot;,&quot;spans&quot;:[{&quot;yaks&quot;:3,&quot;name&quot;:&quot;shaving_yaks&quot;}]}
48/// {&quot;timestamp&quot;:&quot;2022-02-15T18:47:10.821806Z&quot;,&quot;level&quot;:&quot;TRACE&quot;,&quot;fields&quot;:{&quot;yaks_shaved&quot;:2},&quot;target&quot;:&quot;fmt_json::yak_shave&quot;,&quot;spans&quot;:[{&quot;yaks&quot;:3,&quot;name&quot;:&quot;shaving_yaks&quot;}]}
49/// {&quot;timestamp&quot;:&quot;2022-02-15T18:47:10.821909Z&quot;,&quot;level&quot;:&quot;TRACE&quot;,&quot;fields&quot;:{&quot;message&quot;:&quot;hello! I&apos;m gonna shave a yak&quot;,&quot;excitement&quot;:&quot;yay!&quot;},&quot;target&quot;:&quot;fmt_json::yak_shave&quot;,&quot;spans&quot;:[{&quot;yaks&quot;:3,&quot;name&quot;:&quot;shaving_yaks&quot;},{&quot;yak&quot;:3,&quot;name&quot;:&quot;shave&quot;}]}
50/// {&quot;timestamp&quot;:&quot;2022-02-15T18:47:10.821956Z&quot;,&quot;level&quot;:&quot;WARN&quot;,&quot;fields&quot;:{&quot;message&quot;:&quot;could not locate yak&quot;},&quot;target&quot;:&quot;fmt_json::yak_shave&quot;,&quot;spans&quot;:[{&quot;yaks&quot;:3,&quot;name&quot;:&quot;shaving_yaks&quot;},{&quot;yak&quot;:3,&quot;name&quot;:&quot;shave&quot;}]}
51/// {&quot;timestamp&quot;:&quot;2022-02-15T18:47:10.822006Z&quot;,&quot;level&quot;:&quot;DEBUG&quot;,&quot;fields&quot;:{&quot;yak&quot;:3,&quot;shaved&quot;:false},&quot;target&quot;:&quot;yak_events&quot;,&quot;spans&quot;:[{&quot;yaks&quot;:3,&quot;name&quot;:&quot;shaving_yaks&quot;}]}
52/// {&quot;timestamp&quot;:&quot;2022-02-15T18:47:10.822041Z&quot;,&quot;level&quot;:&quot;ERROR&quot;,&quot;fields&quot;:{&quot;message&quot;:&quot;failed to shave yak&quot;,&quot;yak&quot;:3,&quot;error&quot;:&quot;missing yak&quot;},&quot;target&quot;:&quot;fmt_json::yak_shave&quot;,&quot;spans&quot;:[{&quot;yaks&quot;:3,&quot;name&quot;:&quot;shaving_yaks&quot;}]}
53/// {&quot;timestamp&quot;:&quot;2022-02-15T18:47:10.822079Z&quot;,&quot;level&quot;:&quot;TRACE&quot;,&quot;fields&quot;:{&quot;yaks_shaved&quot;:2},&quot;target&quot;:&quot;fmt_json::yak_shave&quot;,&quot;spans&quot;:[{&quot;yaks&quot;:3,&quot;name&quot;:&quot;shaving_yaks&quot;}]}
54/// {&quot;timestamp&quot;:&quot;2022-02-15T18:47:10.822117Z&quot;,&quot;level&quot;:&quot;INFO&quot;,&quot;fields&quot;:{&quot;message&quot;:&quot;yak shaving completed&quot;,&quot;all_yaks_shaved&quot;:false},&quot;target&quot;:&quot;fmt_json&quot;}
55/// </pre>
56///
57/// # Options
58///
59/// This formatter exposes additional options to configure the structure of the
60/// output JSON objects:
61///
62/// - [`Json::flatten_event`] can be used to enable flattening event fields into
63///   the root
64/// - [`Json::with_current_span`] can be used to control logging of the current
65///   span
66/// - [`Json::with_span_list`] can be used to control logging of the span list
67///   object.
68///
69/// By default, event fields are not flattened, and both current span and span
70/// list are logged.
71///
72#[derive(Debug, Copy, Clone, Eq, PartialEq)]
73pub struct Json {
74    pub(crate) flatten_event: bool,
75    pub(crate) display_current_span: bool,
76    pub(crate) display_span_list: bool,
77}
78
79impl Json {
80    /// If set to `true` event metadata will be flattened into the root object.
81    pub fn flatten_event(&mut self, flatten_event: bool) {
82        self.flatten_event = flatten_event;
83    }
84
85    /// If set to `false`, formatted events won't contain a field for the current span.
86    pub fn with_current_span(&mut self, display_current_span: bool) {
87        self.display_current_span = display_current_span;
88    }
89
90    /// If set to `false`, formatted events won't contain a list of all currently
91    /// entered spans. Spans are logged in a list from root to leaf.
92    pub fn with_span_list(&mut self, display_span_list: bool) {
93        self.display_span_list = display_span_list;
94    }
95}
96
97struct SerializableContext<'a, 'b, Span, N>(
98    &'b crate::subscribe::Context<'a, Span>,
99    std::marker::PhantomData<N>,
100)
101where
102    Span: Collect + for<'lookup> crate::registry::LookupSpan<'lookup>,
103    N: for<'writer> FormatFields<'writer> + 'static;
104
105impl<Span, N> serde::ser::Serialize for SerializableContext<'_, '_, Span, N>
106where
107    Span: Collect + for<'lookup> crate::registry::LookupSpan<'lookup>,
108    N: for<'writer> FormatFields<'writer> + 'static,
109{
110    fn serialize<Ser>(&self, serializer_o: Ser) -> Result<Ser::Ok, Ser::Error>
111    where
112        Ser: serde::ser::Serializer,
113    {
114        use serde::ser::SerializeSeq;
115        let mut serializer = serializer_o.serialize_seq(None)?;
116
117        if let Some(leaf_span) = self.0.lookup_current() {
118            for span in leaf_span.scope().from_root() {
119                serializer.serialize_element(&SerializableSpan(&span, self.1))?;
120            }
121        }
122
123        serializer.end()
124    }
125}
126
127struct SerializableSpan<'a, 'b, Span, N>(
128    &'b crate::registry::SpanRef<'a, Span>,
129    std::marker::PhantomData<N>,
130)
131where
132    Span: for<'lookup> crate::registry::LookupSpan<'lookup>,
133    N: for<'writer> FormatFields<'writer> + 'static;
134
135impl<Span, N> serde::ser::Serialize for SerializableSpan<'_, '_, Span, N>
136where
137    Span: for<'lookup> crate::registry::LookupSpan<'lookup>,
138    N: for<'writer> FormatFields<'writer> + 'static,
139{
140    fn serialize<Ser>(&self, serializer: Ser) -> Result<Ser::Ok, Ser::Error>
141    where
142        Ser: serde::ser::Serializer,
143    {
144        let mut serializer = serializer.serialize_map(None)?;
145
146        let ext = self.0.extensions();
147        let data = ext
148            .get::<FormattedFields<N>>()
149            .expect("Unable to find FormattedFields in extensions; this is a bug");
150
151        // TODO: let's _not_ do this, but this resolves
152        // https://github.com/tokio-rs/tracing/issues/391.
153        // We should probably rework this to use a `serde_json::Value` or something
154        // similar in a JSON-specific layer, but I'd (david)
155        // rather have a uglier fix now rather than shipping broken JSON.
156        match serde_json::from_str::<serde_json::Value>(data) {
157            Ok(serde_json::Value::Object(fields)) => {
158                for field in fields {
159                    serializer.serialize_entry(&field.0, &field.1)?;
160                }
161            }
162            // We have fields for this span which are valid JSON but not an object.
163            // This is probably a bug, so panic if we're in debug mode
164            Ok(_) if cfg!(debug_assertions) => panic!(
165                "span '{}' had malformed fields! this is a bug.\n  error: invalid JSON object\n  fields: {:?}",
166                self.0.metadata().name(),
167                data
168            ),
169            // If we *aren't* in debug mode, it's probably best not to
170            // crash the program, let's log the field found but also an
171            // message saying it's type  is invalid
172            Ok(value) => {
173                serializer.serialize_entry("field", &value)?;
174                serializer.serialize_entry("field_error", "field was no a valid object")?
175            }
176            // We have previously recorded fields for this span
177            // should be valid JSON. However, they appear to *not*
178            // be valid JSON. This is almost certainly a bug, so
179            // panic if we're in debug mode
180            Err(e) if cfg!(debug_assertions) => panic!(
181                "span '{}' had malformed fields! this is a bug.\n  error: {}\n  fields: {:?}",
182                self.0.metadata().name(),
183                e,
184                data
185            ),
186            // If we *aren't* in debug mode, it's probably best not
187            // crash the program, but let's at least make sure it's clear
188            // that the fields are not supposed to be missing.
189            Err(e) => serializer.serialize_entry("field_error", &format!("{}", e))?,
190        };
191        serializer.serialize_entry("name", self.0.metadata().name())?;
192        serializer.end()
193    }
194}
195
196impl<C, N, T> FormatEvent<C, N> for Format<Json, T>
197where
198    C: Collect + for<'lookup> LookupSpan<'lookup>,
199    N: for<'writer> FormatFields<'writer> + 'static,
200    T: FormatTime,
201{
202    fn format_event(
203        &self,
204        ctx: &FmtContext<'_, C, N>,
205        mut writer: Writer<'_>,
206        event: &Event<'_>,
207    ) -> fmt::Result
208    where
209        C: Collect + for<'a> LookupSpan<'a>,
210    {
211        let mut timestamp = String::new();
212        self.timer.format_time(&mut Writer::new(&mut timestamp))?;
213
214        #[cfg(feature = "tracing-log")]
215        let normalized_meta = event.normalized_metadata();
216        #[cfg(feature = "tracing-log")]
217        let meta = normalized_meta.as_ref().unwrap_or_else(|| event.metadata());
218        #[cfg(not(feature = "tracing-log"))]
219        let meta = event.metadata();
220
221        let mut visit = || {
222            let mut serializer = Serializer::new(WriteAdaptor::new(&mut writer));
223
224            let mut serializer = serializer.serialize_map(None)?;
225
226            if self.display_timestamp {
227                serializer.serialize_entry("timestamp", &timestamp)?;
228            }
229
230            if self.display_level {
231                serializer.serialize_entry("level", &meta.level().as_serde())?;
232            }
233
234            let format_field_marker: std::marker::PhantomData<N> = std::marker::PhantomData;
235
236            let current_span = if self.format.display_current_span || self.format.display_span_list
237            {
238                event
239                    .parent()
240                    .and_then(|id| ctx.span(id))
241                    .or_else(|| ctx.lookup_current())
242            } else {
243                None
244            };
245
246            if self.format.flatten_event {
247                let mut visitor = tracing_serde::SerdeMapVisitor::new(serializer);
248                event.record(&mut visitor);
249
250                serializer = visitor.take_serializer()?;
251            } else {
252                use tracing_serde::fields::AsMap;
253                serializer.serialize_entry("fields", &event.field_map())?;
254            };
255
256            if self.display_target {
257                serializer.serialize_entry("target", meta.target())?;
258            }
259
260            if self.display_filename {
261                if let Some(filename) = meta.file() {
262                    serializer.serialize_entry("filename", filename)?;
263                }
264            }
265
266            if self.display_line_number {
267                if let Some(line_number) = meta.line() {
268                    serializer.serialize_entry("line_number", &line_number)?;
269                }
270            }
271
272            if self.format.display_current_span {
273                if let Some(ref span) = current_span {
274                    serializer
275                        .serialize_entry("span", &SerializableSpan(span, format_field_marker))
276                        .unwrap_or(());
277                }
278            }
279
280            if self.format.display_span_list && current_span.is_some() {
281                serializer.serialize_entry(
282                    "spans",
283                    &SerializableContext(&ctx.ctx, format_field_marker),
284                )?;
285            }
286
287            if self.display_thread_name {
288                let current_thread = std::thread::current();
289                match current_thread.name() {
290                    Some(name) => {
291                        serializer.serialize_entry("threadName", name)?;
292                    }
293                    // fall-back to thread id when name is absent and ids are not enabled
294                    None if !self.display_thread_id => {
295                        serializer
296                            .serialize_entry("threadName", &format!("{:?}", current_thread.id()))?;
297                    }
298                    _ => {}
299                }
300            }
301
302            if self.display_thread_id {
303                serializer
304                    .serialize_entry("threadId", &format!("{:?}", std::thread::current().id()))?;
305            }
306
307            serializer.end()
308        };
309
310        visit().map_err(|_| fmt::Error)?;
311        writeln!(writer)
312    }
313}
314
315impl Default for Json {
316    fn default() -> Json {
317        Json {
318            flatten_event: false,
319            display_current_span: true,
320            display_span_list: true,
321        }
322    }
323}
324
325/// The JSON [`FormatFields`] implementation.
326///
327#[derive(Debug)]
328pub struct JsonFields {
329    // reserve the ability to add fields to this without causing a breaking
330    // change in the future.
331    _private: (),
332}
333
334impl JsonFields {
335    /// Returns a new JSON [`FormatFields`] implementation.
336    ///
337    pub fn new() -> Self {
338        Self { _private: () }
339    }
340}
341
342impl Default for JsonFields {
343    fn default() -> Self {
344        Self::new()
345    }
346}
347
348impl<'a> FormatFields<'a> for JsonFields {
349    /// Format the provided `fields` to the provided `writer`, returning a result.
350    fn format_fields<R: RecordFields>(&self, mut writer: Writer<'_>, fields: R) -> fmt::Result {
351        let mut v = JsonVisitor::new(&mut writer);
352        fields.record(&mut v);
353        v.finish()
354    }
355
356    /// Record additional field(s) on an existing span.
357    ///
358    /// By default, this appends a space to the current set of fields if it is
359    /// non-empty, and then calls `self.format_fields`. If different behavior is
360    /// required, the default implementation of this method can be overridden.
361    fn add_fields(
362        &self,
363        current: &'a mut FormattedFields<Self>,
364        fields: &Record<'_>,
365    ) -> fmt::Result {
366        if current.is_empty() {
367            // If there are no previously recorded fields, we can just reuse the
368            // existing string.
369            let mut writer = current.as_writer();
370            let mut v = JsonVisitor::new(&mut writer);
371            fields.record(&mut v);
372            v.finish()?;
373            return Ok(());
374        }
375
376        // If fields were previously recorded on this span, we need to parse
377        // the current set of fields as JSON, add the new fields, and
378        // re-serialize them. Otherwise, if we just appended the new fields
379        // to a previously serialized JSON object, we would end up with
380        // malformed JSON.
381        //
382        // XXX(eliza): this is far from efficient, but unfortunately, it is
383        // necessary as long as the JSON formatter is implemented on top of
384        // an interface that stores all formatted fields as strings.
385        //
386        // We should consider reimplementing the JSON formatter as a
387        // separate layer, rather than a formatter for the `fmt` layer —
388        // then, we could store fields as JSON values, and add to them
389        // without having to parse and re-serialize.
390        let mut new = String::new();
391        let map: BTreeMap<&'_ str, serde_json::Value> =
392            serde_json::from_str(current).map_err(|_| fmt::Error)?;
393        let mut v = JsonVisitor::new(&mut new);
394        v.values = map;
395        fields.record(&mut v);
396        v.finish()?;
397        current.fields = new;
398
399        Ok(())
400    }
401}
402
403/// The [visitor] produced by [`JsonFields`]'s [`MakeVisitor`] implementation.
404///
405/// [visitor]: crate::field::Visit
406/// [`MakeVisitor`]: crate::field::MakeVisitor
407pub struct JsonVisitor<'a> {
408    values: BTreeMap<&'a str, serde_json::Value>,
409    writer: &'a mut dyn Write,
410}
411
412impl fmt::Debug for JsonVisitor<'_> {
413    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
414        f.write_fmt(format_args!("JsonVisitor {{ values: {:?} }}", self.values))
415    }
416}
417
418impl<'a> JsonVisitor<'a> {
419    /// Returns a new default visitor that formats to the provided `writer`.
420    ///
421    /// # Arguments
422    /// - `writer`: the writer to format to.
423    /// - `is_empty`: whether or not any fields have been previously written to
424    ///   that writer.
425    pub fn new(writer: &'a mut dyn Write) -> Self {
426        Self {
427            values: BTreeMap::new(),
428            writer,
429        }
430    }
431}
432
433impl crate::field::VisitFmt for JsonVisitor<'_> {
434    fn writer(&mut self) -> &mut dyn fmt::Write {
435        self.writer
436    }
437}
438
439impl crate::field::VisitOutput<fmt::Result> for JsonVisitor<'_> {
440    fn finish(self) -> fmt::Result {
441        let inner = || {
442            let mut serializer = Serializer::new(WriteAdaptor::new(self.writer));
443            let mut ser_map = serializer.serialize_map(None)?;
444
445            for (k, v) in self.values {
446                ser_map.serialize_entry(k, &v)?;
447            }
448
449            ser_map.end()
450        };
451
452        if inner().is_err() {
453            Err(fmt::Error)
454        } else {
455            Ok(())
456        }
457    }
458}
459
460impl field::Visit for JsonVisitor<'_> {
461    /// Visit a double precision floating point value.
462    fn record_f64(&mut self, field: &Field, value: f64) {
463        self.values
464            .insert(field.name(), serde_json::Value::from(value));
465    }
466
467    /// Visit a signed 64-bit integer value.
468    fn record_i64(&mut self, field: &Field, value: i64) {
469        self.values
470            .insert(field.name(), serde_json::Value::from(value));
471    }
472
473    /// Visit an unsigned 64-bit integer value.
474    fn record_u64(&mut self, field: &Field, value: u64) {
475        self.values
476            .insert(field.name(), serde_json::Value::from(value));
477    }
478
479    /// Visit a boolean value.
480    fn record_bool(&mut self, field: &Field, value: bool) {
481        self.values
482            .insert(field.name(), serde_json::Value::from(value));
483    }
484
485    /// Visit a string value.
486    fn record_str(&mut self, field: &Field, value: &str) {
487        self.values
488            .insert(field.name(), serde_json::Value::from(value));
489    }
490
491    fn record_bytes(&mut self, field: &Field, value: &[u8]) {
492        self.values
493            .insert(field.name(), serde_json::Value::from(value));
494    }
495
496    fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) {
497        match field.name() {
498            // Skip fields that are actually log metadata that have already been handled
499            #[cfg(feature = "tracing-log")]
500            name if name.starts_with("log.") => (),
501            name if name.starts_with("r#") => {
502                self.values
503                    .insert(&name[2..], serde_json::Value::from(format!("{:?}", value)));
504            }
505            name => {
506                self.values
507                    .insert(name, serde_json::Value::from(format!("{:?}", value)));
508            }
509        };
510    }
511}
512#[cfg(test)]
513mod test {
514    use super::*;
515    use crate::fmt::{format::FmtSpan, test::MockMakeWriter, time::FormatTime, CollectorBuilder};
516
517    use tracing::{self, collect::with_default};
518
519    use std::fmt;
520    use std::path::Path;
521
522    struct MockTime;
523    impl FormatTime for MockTime {
524        fn format_time(&self, w: &mut Writer<'_>) -> fmt::Result {
525            write!(w, "fake time")
526        }
527    }
528
529    fn collector() -> CollectorBuilder<JsonFields, Format<Json>> {
530        crate::fmt::CollectorBuilder::default().json()
531    }
532
533    #[test]
534    fn json() {
535        let expected =
536        "{\"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";
537        let collector = collector()
538            .flatten_event(false)
539            .with_current_span(true)
540            .with_span_list(true);
541        test_json(expected, collector, || {
542            let span = tracing::span!(
543                tracing::Level::INFO,
544                "json_span",
545                answer = 42,
546                number = 3,
547                slice = &b"abc"[..]
548            );
549            let _guard = span.enter();
550            tracing::info!("some json test");
551        });
552    }
553
554    #[test]
555    fn json_filename() {
556        let current_path = Path::new("tracing-subscriber")
557            .join("src")
558            .join("fmt")
559            .join("format")
560            .join("json.rs")
561            .to_str()
562            .expect("path must be valid unicode")
563            // escape windows backslashes
564            .replace('\\', "\\\\");
565        let expected =
566            &format!("{}{}{}",
567                    "{\"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\",\"filename\":\"",
568                    current_path,
569                    "\",\"fields\":{\"message\":\"some json test\"}}\n");
570        let collector = collector()
571            .flatten_event(false)
572            .with_current_span(true)
573            .with_file(true)
574            .with_span_list(true);
575        test_json(expected, collector, || {
576            let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3);
577            let _guard = span.enter();
578            tracing::info!("some json test");
579        });
580    }
581
582    #[test]
583    fn json_line_number() {
584        let expected =
585            "{\"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\",\"line_number\":42,\"fields\":{\"message\":\"some json test\"}}\n";
586        let collector = collector()
587            .flatten_event(false)
588            .with_current_span(true)
589            .with_line_number(true)
590            .with_span_list(true);
591        test_json_with_line_number(expected, collector, || {
592            let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3);
593            let _guard = span.enter();
594            tracing::info!("some json test");
595        });
596    }
597
598    #[test]
599    fn json_flattened_event() {
600        let expected =
601        "{\"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\",\"message\":\"some json test\"}\n";
602
603        let collector = collector()
604            .flatten_event(true)
605            .with_current_span(true)
606            .with_span_list(true);
607        test_json(expected, collector, || {
608            let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3);
609            let _guard = span.enter();
610            tracing::info!("some json test");
611        });
612    }
613
614    #[test]
615    fn json_disabled_current_span_event() {
616        let expected =
617        "{\"timestamp\":\"fake time\",\"level\":\"INFO\",\"spans\":[{\"answer\":42,\"name\":\"json_span\",\"number\":3}],\"target\":\"tracing_subscriber::fmt::format::json::test\",\"fields\":{\"message\":\"some json test\"}}\n";
618        let collector = collector()
619            .flatten_event(false)
620            .with_current_span(false)
621            .with_span_list(true);
622        test_json(expected, collector, || {
623            let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3);
624            let _guard = span.enter();
625            tracing::info!("some json test");
626        });
627    }
628
629    #[test]
630    fn json_disabled_span_list_event() {
631        let expected =
632        "{\"timestamp\":\"fake time\",\"level\":\"INFO\",\"span\":{\"answer\":42,\"name\":\"json_span\",\"number\":3},\"target\":\"tracing_subscriber::fmt::format::json::test\",\"fields\":{\"message\":\"some json test\"}}\n";
633        let collector = collector()
634            .flatten_event(false)
635            .with_current_span(true)
636            .with_span_list(false);
637        test_json(expected, collector, || {
638            let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3);
639            let _guard = span.enter();
640            tracing::info!("some json test");
641        });
642    }
643
644    #[test]
645    fn json_nested_span() {
646        let expected =
647        "{\"timestamp\":\"fake time\",\"level\":\"INFO\",\"span\":{\"answer\":43,\"name\":\"nested_json_span\",\"number\":4},\"spans\":[{\"answer\":42,\"name\":\"json_span\",\"number\":3},{\"answer\":43,\"name\":\"nested_json_span\",\"number\":4}],\"target\":\"tracing_subscriber::fmt::format::json::test\",\"fields\":{\"message\":\"some json test\"}}\n";
648        let collector = collector()
649            .flatten_event(false)
650            .with_current_span(true)
651            .with_span_list(true);
652        test_json(expected, collector, || {
653            let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3);
654            let _guard = span.enter();
655            let span = tracing::span!(
656                tracing::Level::INFO,
657                "nested_json_span",
658                answer = 43,
659                number = 4
660            );
661            let _guard = span.enter();
662            tracing::info!("some json test");
663        });
664    }
665
666    #[test]
667    fn json_no_span() {
668        let expected =
669        "{\"timestamp\":\"fake time\",\"level\":\"INFO\",\"target\":\"tracing_subscriber::fmt::format::json::test\",\"fields\":{\"message\":\"some json test\"}}\n";
670        let collector = collector()
671            .flatten_event(false)
672            .with_current_span(true)
673            .with_span_list(true);
674        test_json(expected, collector, || {
675            tracing::info!("some json test");
676        });
677    }
678
679    #[test]
680    fn record_works() {
681        // This test reproduces issue #707, where using `Span::record` causes
682        // any events inside the span to be ignored.
683
684        let buffer = MockMakeWriter::default();
685        let subscriber = crate::fmt().json().with_writer(buffer.clone()).finish();
686
687        with_default(subscriber, || {
688            tracing::info!("an event outside the root span");
689            assert_eq!(
690                parse_as_json(&buffer)["fields"]["message"],
691                "an event outside the root span"
692            );
693
694            let span = tracing::info_span!("the span", na = tracing::field::Empty);
695            span.record("na", "value");
696            let _enter = span.enter();
697
698            tracing::info!("an event inside the root span");
699            assert_eq!(
700                parse_as_json(&buffer)["fields"]["message"],
701                "an event inside the root span"
702            );
703        });
704    }
705
706    #[test]
707    fn json_span_event_show_correct_context() {
708        let buffer = MockMakeWriter::default();
709        let subscriber = collector()
710            .with_writer(buffer.clone())
711            .flatten_event(false)
712            .with_current_span(true)
713            .with_span_list(false)
714            .with_span_events(FmtSpan::FULL)
715            .finish();
716
717        with_default(subscriber, || {
718            let context = "parent";
719            let parent_span = tracing::info_span!("parent_span", context);
720
721            let event = parse_as_json(&buffer);
722            assert_eq!(event["fields"]["message"], "new");
723            assert_eq!(event["span"]["context"], "parent");
724
725            let _parent_enter = parent_span.enter();
726            let event = parse_as_json(&buffer);
727            assert_eq!(event["fields"]["message"], "enter");
728            assert_eq!(event["span"]["context"], "parent");
729
730            let context = "child";
731            let child_span = tracing::info_span!("child_span", context);
732            let event = parse_as_json(&buffer);
733            assert_eq!(event["fields"]["message"], "new");
734            assert_eq!(event["span"]["context"], "child");
735
736            let _child_enter = child_span.enter();
737            let event = parse_as_json(&buffer);
738            assert_eq!(event["fields"]["message"], "enter");
739            assert_eq!(event["span"]["context"], "child");
740
741            drop(_child_enter);
742            let event = parse_as_json(&buffer);
743            assert_eq!(event["fields"]["message"], "exit");
744            assert_eq!(event["span"]["context"], "child");
745
746            drop(child_span);
747            let event = parse_as_json(&buffer);
748            assert_eq!(event["fields"]["message"], "close");
749            assert_eq!(event["span"]["context"], "child");
750
751            drop(_parent_enter);
752            let event = parse_as_json(&buffer);
753            assert_eq!(event["fields"]["message"], "exit");
754            assert_eq!(event["span"]["context"], "parent");
755
756            drop(parent_span);
757            let event = parse_as_json(&buffer);
758            assert_eq!(event["fields"]["message"], "close");
759            assert_eq!(event["span"]["context"], "parent");
760        });
761    }
762
763    #[test]
764    fn json_span_event_with_no_fields() {
765        // Check span events serialize correctly.
766        // Discussion: https://github.com/tokio-rs/tracing/issues/829#issuecomment-661984255
767        //
768        let buffer = MockMakeWriter::default();
769        let subscriber = collector()
770            .with_writer(buffer.clone())
771            .flatten_event(false)
772            .with_current_span(false)
773            .with_span_list(false)
774            .with_span_events(FmtSpan::FULL)
775            .finish();
776
777        with_default(subscriber, || {
778            let span = tracing::info_span!("valid_json");
779            assert_eq!(parse_as_json(&buffer)["fields"]["message"], "new");
780
781            let _enter = span.enter();
782            assert_eq!(parse_as_json(&buffer)["fields"]["message"], "enter");
783
784            drop(_enter);
785            assert_eq!(parse_as_json(&buffer)["fields"]["message"], "exit");
786
787            drop(span);
788            assert_eq!(parse_as_json(&buffer)["fields"]["message"], "close");
789        });
790    }
791
792    fn parse_as_json(buffer: &MockMakeWriter) -> serde_json::Value {
793        let buf = String::from_utf8(buffer.buf().to_vec()).unwrap();
794        let json = buf
795            .lines()
796            .last()
797            .expect("expected at least one line to be written!");
798        match serde_json::from_str(json) {
799            Ok(v) => v,
800            Err(e) => panic!(
801                "assertion failed: JSON shouldn't be malformed\n  error: {}\n  json: {}",
802                e, json
803            ),
804        }
805    }
806
807    fn test_json<T>(
808        expected: &str,
809        builder: crate::fmt::CollectorBuilder<JsonFields, Format<Json>>,
810        producer: impl FnOnce() -> T,
811    ) {
812        let make_writer = MockMakeWriter::default();
813        let collector = builder
814            .with_writer(make_writer.clone())
815            .with_timer(MockTime)
816            .finish();
817
818        with_default(collector, producer);
819
820        let buf = make_writer.buf();
821        let actual = std::str::from_utf8(&buf[..]).unwrap();
822        assert_eq!(
823            serde_json::from_str::<std::collections::HashMap<&str, serde_json::Value>>(expected)
824                .unwrap(),
825            serde_json::from_str(actual).unwrap()
826        );
827    }
828
829    fn test_json_with_line_number<T>(
830        expected: &str,
831        builder: crate::fmt::CollectorBuilder<JsonFields, Format<Json>>,
832        producer: impl FnOnce() -> T,
833    ) {
834        let make_writer = MockMakeWriter::default();
835        let collector = builder
836            .with_writer(make_writer.clone())
837            .with_timer(MockTime)
838            .finish();
839
840        with_default(collector, producer);
841
842        let buf = make_writer.buf();
843        let actual = std::str::from_utf8(&buf[..]).unwrap();
844        let mut expected =
845            serde_json::from_str::<std::collections::HashMap<&str, serde_json::Value>>(expected)
846                .unwrap();
847        let expect_line_number = expected.remove("line_number").is_some();
848        let mut actual: std::collections::HashMap<&str, serde_json::Value> =
849            serde_json::from_str(actual).unwrap();
850        let line_number = actual.remove("line_number");
851        if expect_line_number {
852            assert_eq!(line_number.map(|x| x.is_number()), Some(true));
853        } else {
854            assert!(line_number.is_none());
855        }
856        assert_eq!(actual, expected);
857    }
858}