better_tracing/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\":\"better_tracing::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("src")
593            .join("fmt")
594            .join("format")
595            .join("json.rs")
596            .to_str()
597            .expect("path must be valid unicode")
598            // escape windows backslashes
599            .replace('\\', "\\\\");
600        let expected =
601            &format!("{}{}{}",
602                    "{\"timestamp\":\"fake time\",\"level\":\"INFO\",\"span\":{\"answer\":42,\"name\":\"json_span\",\"number\":3},\"spans\":[{\"answer\":42,\"name\":\"json_span\",\"number\":3}],\"target\":\"better_tracing::fmt::format::json::test\",\"filename\":\"",
603                    current_path,
604                    "\",\"fields\":{\"message\":\"some json test\"}}\n");
605        let subscriber = subscriber()
606            .flatten_event(false)
607            .with_current_span(true)
608            .with_file(true)
609            .with_span_list(true);
610        test_json(expected, subscriber, || {
611            let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3);
612            let _guard = span.enter();
613            tracing::info!("some json test");
614        });
615    }
616
617    #[test]
618    fn json_line_number() {
619        let expected =
620            "{\"timestamp\":\"fake time\",\"level\":\"INFO\",\"span\":{\"answer\":42,\"name\":\"json_span\",\"number\":3},\"spans\":[{\"answer\":42,\"name\":\"json_span\",\"number\":3}],\"target\":\"better_tracing::fmt::format::json::test\",\"line_number\":42,\"fields\":{\"message\":\"some json test\"}}\n";
621        let subscriber = subscriber()
622            .flatten_event(false)
623            .with_current_span(true)
624            .with_line_number(true)
625            .with_span_list(true);
626        test_json_with_line_number(expected, subscriber, || {
627            let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3);
628            let _guard = span.enter();
629            tracing::info!("some json test");
630        });
631    }
632
633    #[test]
634    fn json_flattened_event() {
635        let expected =
636        "{\"timestamp\":\"fake time\",\"level\":\"INFO\",\"span\":{\"answer\":42,\"name\":\"json_span\",\"number\":3},\"spans\":[{\"answer\":42,\"name\":\"json_span\",\"number\":3}],\"target\":\"better_tracing::fmt::format::json::test\",\"message\":\"some json test\"}\n";
637
638        let subscriber = subscriber()
639            .flatten_event(true)
640            .with_current_span(true)
641            .with_span_list(true);
642        test_json(expected, subscriber, || {
643            let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3);
644            let _guard = span.enter();
645            tracing::info!("some json test");
646        });
647    }
648
649    #[test]
650    fn json_disabled_current_span_event() {
651        let expected =
652        "{\"timestamp\":\"fake time\",\"level\":\"INFO\",\"spans\":[{\"answer\":42,\"name\":\"json_span\",\"number\":3}],\"target\":\"better_tracing::fmt::format::json::test\",\"fields\":{\"message\":\"some json test\"}}\n";
653        let subscriber = subscriber()
654            .flatten_event(false)
655            .with_current_span(false)
656            .with_span_list(true);
657        test_json(expected, subscriber, || {
658            let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3);
659            let _guard = span.enter();
660            tracing::info!("some json test");
661        });
662    }
663
664    #[test]
665    fn json_disabled_span_list_event() {
666        let expected =
667        "{\"timestamp\":\"fake time\",\"level\":\"INFO\",\"span\":{\"answer\":42,\"name\":\"json_span\",\"number\":3},\"target\":\"better_tracing::fmt::format::json::test\",\"fields\":{\"message\":\"some json test\"}}\n";
668        let subscriber = subscriber()
669            .flatten_event(false)
670            .with_current_span(true)
671            .with_span_list(false);
672        test_json(expected, subscriber, || {
673            let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3);
674            let _guard = span.enter();
675            tracing::info!("some json test");
676        });
677    }
678
679    #[test]
680    fn json_nested_span() {
681        let expected =
682        "{\"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\":\"better_tracing::fmt::format::json::test\",\"fields\":{\"message\":\"some json test\"}}\n";
683        let subscriber = subscriber()
684            .flatten_event(false)
685            .with_current_span(true)
686            .with_span_list(true);
687        test_json(expected, subscriber, || {
688            let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3);
689            let _guard = span.enter();
690            let span = tracing::span!(
691                tracing::Level::INFO,
692                "nested_json_span",
693                answer = 43,
694                number = 4
695            );
696            let _guard = span.enter();
697            tracing::info!("some json test");
698        });
699    }
700
701    #[test]
702    fn json_no_span() {
703        let expected =
704        "{\"timestamp\":\"fake time\",\"level\":\"INFO\",\"target\":\"better_tracing::fmt::format::json::test\",\"fields\":{\"message\":\"some json test\"}}\n";
705        let subscriber = subscriber()
706            .flatten_event(false)
707            .with_current_span(true)
708            .with_span_list(true);
709        test_json(expected, subscriber, || {
710            tracing::info!("some json test");
711        });
712    }
713
714    #[test]
715    fn record_works() {
716        // This test reproduces issue #707, where using `Span::record` causes
717        // any events inside the span to be ignored.
718
719        let make_writer = MockMakeWriter::default();
720        let subscriber = crate::fmt()
721            .json()
722            .with_writer(make_writer.clone())
723            .finish();
724
725        with_default(subscriber, || {
726            tracing::info!("an event outside the root span");
727            assert_eq!(
728                parse_as_json(&make_writer)["fields"]["message"],
729                "an event outside the root span"
730            );
731
732            let span = tracing::info_span!("the span", na = tracing::field::Empty);
733            span.record("na", "value");
734            let _enter = span.enter();
735
736            tracing::info!("an event inside the root span");
737            assert_eq!(
738                parse_as_json(&make_writer)["fields"]["message"],
739                "an event inside the root span"
740            );
741        });
742    }
743
744    #[test]
745    fn json_span_event_show_correct_context() {
746        let buffer = MockMakeWriter::default();
747        let subscriber = subscriber()
748            .with_writer(buffer.clone())
749            .flatten_event(false)
750            .with_current_span(true)
751            .with_span_list(false)
752            .with_span_events(FmtSpan::FULL)
753            .finish();
754
755        with_default(subscriber, || {
756            let context = "parent";
757            let parent_span = tracing::info_span!("parent_span", context);
758
759            let event = parse_as_json(&buffer);
760            assert_eq!(event["fields"]["message"], "new");
761            assert_eq!(event["span"]["context"], "parent");
762
763            let _parent_enter = parent_span.enter();
764            let event = parse_as_json(&buffer);
765            assert_eq!(event["fields"]["message"], "enter");
766            assert_eq!(event["span"]["context"], "parent");
767
768            let context = "child";
769            let child_span = tracing::info_span!("child_span", context);
770            let event = parse_as_json(&buffer);
771            assert_eq!(event["fields"]["message"], "new");
772            assert_eq!(event["span"]["context"], "child");
773
774            let _child_enter = child_span.enter();
775            let event = parse_as_json(&buffer);
776            assert_eq!(event["fields"]["message"], "enter");
777            assert_eq!(event["span"]["context"], "child");
778
779            drop(_child_enter);
780            let event = parse_as_json(&buffer);
781            assert_eq!(event["fields"]["message"], "exit");
782            assert_eq!(event["span"]["context"], "child");
783
784            drop(child_span);
785            let event = parse_as_json(&buffer);
786            assert_eq!(event["fields"]["message"], "close");
787            assert_eq!(event["span"]["context"], "child");
788
789            drop(_parent_enter);
790            let event = parse_as_json(&buffer);
791            assert_eq!(event["fields"]["message"], "exit");
792            assert_eq!(event["span"]["context"], "parent");
793
794            drop(parent_span);
795            let event = parse_as_json(&buffer);
796            assert_eq!(event["fields"]["message"], "close");
797            assert_eq!(event["span"]["context"], "parent");
798        });
799    }
800
801    #[test]
802    fn json_span_event_with_no_fields() {
803        // Check span events serialize correctly.
804        // Discussion: https://github.com/tokio-rs/tracing/issues/829#issuecomment-661984255
805        let buffer = MockMakeWriter::default();
806        let subscriber = subscriber()
807            .with_writer(buffer.clone())
808            .flatten_event(false)
809            .with_current_span(false)
810            .with_span_list(false)
811            .with_span_events(FmtSpan::FULL)
812            .finish();
813
814        with_default(subscriber, || {
815            let span = tracing::info_span!("valid_json");
816            assert_eq!(parse_as_json(&buffer)["fields"]["message"], "new");
817
818            let _enter = span.enter();
819            assert_eq!(parse_as_json(&buffer)["fields"]["message"], "enter");
820
821            drop(_enter);
822            assert_eq!(parse_as_json(&buffer)["fields"]["message"], "exit");
823
824            drop(span);
825            assert_eq!(parse_as_json(&buffer)["fields"]["message"], "close");
826        });
827    }
828
829    fn parse_as_json(buffer: &MockMakeWriter) -> serde_json::Value {
830        let buf = String::from_utf8(buffer.buf().to_vec()).unwrap();
831        let json = buf
832            .lines()
833            .last()
834            .expect("expected at least one line to be written!");
835        match serde_json::from_str(json) {
836            Ok(v) => v,
837            Err(e) => panic!(
838                "assertion failed: JSON shouldn't be malformed\n  error: {}\n  json: {}",
839                e, json
840            ),
841        }
842    }
843
844    fn test_json<T>(
845        expected: &str,
846        builder: crate::fmt::SubscriberBuilder<JsonFields, Format<Json>>,
847        producer: impl FnOnce() -> T,
848    ) {
849        let make_writer = MockMakeWriter::default();
850        let subscriber = builder
851            .with_writer(make_writer.clone())
852            .with_timer(MockTime)
853            .finish();
854
855        with_default(subscriber, producer);
856
857        let buf = make_writer.buf();
858        let actual = std::str::from_utf8(&buf[..]).unwrap();
859        assert_eq!(
860            serde_json::from_str::<std::collections::HashMap<&str, serde_json::Value>>(expected)
861                .unwrap(),
862            serde_json::from_str(actual).unwrap()
863        );
864    }
865
866    fn test_json_with_line_number<T>(
867        expected: &str,
868        builder: crate::fmt::SubscriberBuilder<JsonFields, Format<Json>>,
869        producer: impl FnOnce() -> T,
870    ) {
871        let make_writer = MockMakeWriter::default();
872        let subscriber = builder
873            .with_writer(make_writer.clone())
874            .with_timer(MockTime)
875            .finish();
876
877        with_default(subscriber, producer);
878
879        let buf = make_writer.buf();
880        let actual = std::str::from_utf8(&buf[..]).unwrap();
881        let mut expected =
882            serde_json::from_str::<std::collections::HashMap<&str, serde_json::Value>>(expected)
883                .unwrap();
884        let expect_line_number = expected.remove("line_number").is_some();
885        let mut actual: std::collections::HashMap<&str, serde_json::Value> =
886            serde_json::from_str(actual).unwrap();
887        let line_number = actual.remove("line_number");
888        if expect_line_number {
889            assert_eq!(line_number.map(|x| x.is_number()), Some(true));
890        } else {
891            assert!(line_number.is_none());
892        }
893        assert_eq!(actual, expected);
894    }
895}