tracing_subscriber/fmt/format/
json.rs

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