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