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

   1 use super::{Format, FormatEvent, FormatFields, FormatTime, Writer};
   2 use crate::{
   3     field::{RecordFields, VisitOutput},
   4     fmt::{
   5         fmt_layer::{FmtContext, FormattedFields},
   6         writer::WriteAdaptor,
   7     },
   8     registry::LookupSpan,
   9 };
  10 use serde::ser::{SerializeMap, Serializer as _};
  11 use serde_json::Serializer;
  12 use std::{
  13     collections::BTreeMap,
  14     fmt::{self, Write},
  15 };
  16 use tracing_core::{
  17     field::{self, Field},
  18     span::Record,
  19     Event, Subscriber,
  20 };
  21 use tracing_serde::AsSerde;
  22
  23 #[cfg(feature = "tracing-log")]
  24 use 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`]: #method.flatten_event
  84 /// [`Json::with_current_span`]: #method.with_current_span
  85 /// [`Json::with_span_list`]: #method.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)]
  90 pub struct Json {
  91     pub(crate) flatten_event: bool,
  92     pub(crate) display_current_span: bool,
  93     pub(crate) display_span_list: bool,
  94 }
  95
  96 impl 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
 114 struct SerializableContext<'a, 'b, Span, N>(
 115     &'b crate::layer::Context<'a, Span>,
 116     std::marker::PhantomData<N>,
 117 )
 118 where
 119     Span: Subscriber + for<'lookup> crate::registry::LookupSpan<'lookup>,
 120     N: for<'writer> FormatFields<'writer> + 'static;
 121
 122 impl<'a, 'b, Span, N> serde::ser::Serialize for SerializableContext<'a, 'b, Span, N>
 123 where
 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
 144 struct SerializableSpan<'a, 'b, Span, N>(
 145     &'b crate::registry::SpanRef<'a, Span>,
 146     std::marker::PhantomData<N>,
 147 )
 148 where
 149     Span: for<'lookup> crate::registry::LookupSpan<'lookup>,
 150     N: for<'writer> FormatFields<'writer> + 'static;
 151
 152 impl<'a, 'b, Span, N> serde::ser::Serialize for SerializableSpan<'a, 'b, Span, N>
 153 where
 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
 213 impl<S, N, T> FormatEvent<S, N> for Format<Json, T>
 214 where
 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
 332 impl 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 /// [`FormatFields`]: trait.FormatFields.html
 345 #[derive(Debug)]
 346 pub struct JsonFields {
 347     // reserve the ability to add fields to this without causing a breaking
 348     // change in the future.
 349     _private: (),
 350 }
 351
 352 impl JsonFields {
 353     /// Returns a new JSON [`FormatFields`] implementation.
 354     ///
 355     /// [`FormatFields`]: trait.FormatFields.html
 356     pub fn new() -> Self {
 357         Self { _private: () }
 358     }
 359 }
 360
 361 impl Default for JsonFields {
 362     fn default() -> Self {
 363         Self::new()
 364     }
 365 }
 366
 367 impl<'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]: ../../field/trait.Visit.html
 425 /// [`JsonFields`]: struct.JsonFields.html
 426 /// [`MakeVisitor`]: ../../field/trait.MakeVisitor.html
 427 pub struct JsonVisitor<'a> {
 428     values: BTreeMap<&'a str, serde_json::Value>,
 429     writer: &'a mut dyn Write,
 430 }
 431
 432 impl<'a> fmt::Debug for JsonVisitor<'a> {
 433     fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
 434         f.write_fmt(format_args!("JsonVisitor {{ values: {:?} }}", self.values))
 435     }
 436 }
 437
 438 impl<'a> JsonVisitor<'a> {
 439     /// Returns a new default visitor that formats to the provided `writer`.
 440     ///
 441     /// # Arguments
 442     /// - `writer`: the writer to format to.
 443     /// - `is_empty`: whether or not any fields have been previously written to
 444     ///   that writer.
 445     pub fn new(writer: &'a mut dyn Write) -> Self {
 446         Self {
 447             values: BTreeMap::new(),
 448             writer,
 449         }
 450     }
 451 }
 452
 453 impl<'a> crate::field::VisitFmt for JsonVisitor<'a> {
 454     fn writer(&mut self) -> &mut dyn fmt::Write {
 455         self.writer
 456     }
 457 }
 458
 459 impl<'a> crate::field::VisitOutput<fmt::Result> for JsonVisitor<'a> {
 460     fn finish(self) -> fmt::Result {
 461         let inner = || {
 462             let mut serializer = Serializer::new(WriteAdaptor::new(self.writer));
 463             let mut ser_map = serializer.serialize_map(None)?;
 464
 465             for (k, v) in self.values {
 466                 ser_map.serialize_entry(k, &v)?;
 467             }
 468
 469             ser_map.end()
 470         };
 471
 472         if inner().is_err() {
 473             Err(fmt::Error)
 474         } else {
 475             Ok(())
 476         }
 477     }
 478 }
 479
 480 impl<'a> field::Visit for JsonVisitor<'a> {
 481     #[cfg(all(tracing_unstable, feature = "valuable"))]
 482     fn record_value(&mut self, field: &Field, value: valuable_crate::Value<'_>) {
 483         let value = match serde_json::to_value(valuable_serde::Serializable::new(value)) {
 484             Ok(value) => value,
 485             Err(_e) => {
 486                 #[cfg(debug_assertions)]
 487                 unreachable!(
 488                     "`valuable::Valuable` implementations should always serialize \
 489                     successfully, but an error occurred: {}",
 490                     _e,
 491                 );
 492
 493                 #[cfg(not(debug_assertions))]
 494                 return;
 495             }
 496         };
 497
 498         self.values.insert(field.name(), value);
 499     }
 500
 501     /// Visit a double precision floating point value.
 502     fn record_f64(&mut self, field: &Field, value: f64) {
 503         self.values
 504             .insert(field.name(), serde_json::Value::from(value));
 505     }
 506
 507     /// Visit a signed 64-bit integer value.
 508     fn record_i64(&mut self, field: &Field, value: i64) {
 509         self.values
 510             .insert(field.name(), serde_json::Value::from(value));
 511     }
 512
 513     /// Visit an unsigned 64-bit integer value.
 514     fn record_u64(&mut self, field: &Field, value: u64) {
 515         self.values
 516             .insert(field.name(), serde_json::Value::from(value));
 517     }
 518
 519     /// Visit a boolean value.
 520     fn record_bool(&mut self, field: &Field, value: bool) {
 521         self.values
 522             .insert(field.name(), serde_json::Value::from(value));
 523     }
 524
 525     /// Visit a string value.
 526     fn record_str(&mut self, field: &Field, value: &str) {
 527         self.values
 528             .insert(field.name(), serde_json::Value::from(value));
 529     }
 530
 531     fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) {
 532         match field.name() {
 533             // Skip fields that are actually log metadata that have already been handled
 534             #[cfg(feature = "tracing-log")]
 535             name if name.starts_with("log.") => (),
 536             name if name.starts_with("r#") => {
 537                 self.values
 538                     .insert(&name[2..], serde_json::Value::from(format!("{:?}", value)));
 539             }
 540             name => {
 541                 self.values
 542                     .insert(name, serde_json::Value::from(format!("{:?}", value)));
 543             }
 544         };
 545     }
 546 }
 547 #[cfg(test)]
 548 mod test {
 549     use super::*;
 550     use crate::fmt::{format::FmtSpan, test::MockMakeWriter, time::FormatTime, SubscriberBuilder};
 551     use tracing::{self, subscriber::with_default};
 552
 553     use std::fmt;
 554     use std::path::Path;
 555
 556     struct MockTime;
 557     impl FormatTime for MockTime {
 558         fn format_time(&self, w: &mut Writer<'_>) -> fmt::Result {
 559             write!(w, "fake time")
 560         }
 561     }
 562
 563     fn subscriber() -> SubscriberBuilder<JsonFields, Format<Json>> {
 564         SubscriberBuilder::default().json()
 565     }
 566
 567     #[test]
 568     fn json() {
 569         let expected =
 570         "{\"timestamp\":\"fake time\",\"level\":\"INFO\",\"span\":{\"answer\":42,\"name\":\"json_span\",\"number\":3},\"spans\":[{\"answer\":42,\"name\":\"json_span\",\"number\":3}],\"target\":\"tracing_subscriber::fmt::format::json::test\",\"fields\":{\"message\":\"some json test\"}}\n";
 571         let subscriber = subscriber()
 572             .flatten_event(false)
 573             .with_current_span(true)
 574             .with_span_list(true);
 575         test_json(expected, subscriber, || {
 576             let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3);
 577             let _guard = span.enter();
 578             tracing::info!("some json test");
 579         });
 580     }
 581
 582     #[test]
 583     fn json_filename() {
 584         let current_path = Path::new("tracing-subscriber")
 585             .join("src")
 586             .join("fmt")
 587             .join("format")
 588             .join("json.rs")
 589             .to_str()
 590             .expect("path must be valid unicode")
 591             // escape windows backslashes
 592             .replace('\\', "\\\\");
 593         let expected =
 594             &format!("{}{}{}",
 595                     "{\"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\":\"",
 596                     current_path,
 597                     "\",\"fields\":{\"message\":\"some json test\"}}\n");
 598         let subscriber = subscriber()
 599             .flatten_event(false)
 600             .with_current_span(true)
 601             .with_file(true)
 602             .with_span_list(true);
 603         test_json(expected, subscriber, || {
 604             let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3);
 605             let _guard = span.enter();
 606             tracing::info!("some json test");
 607         });
 608     }
 609
 610     #[test]
 611     fn json_line_number() {
 612         let expected =
 613             "{\"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";
 614         let subscriber = subscriber()
 615             .flatten_event(false)
 616             .with_current_span(true)
 617             .with_line_number(true)
 618             .with_span_list(true);
 619         test_json_with_line_number(expected, subscriber, || {
 620             let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3);
 621             let _guard = span.enter();
 622             tracing::info!("some json test");
 623         });
 624     }
 625
 626     #[test]
 627     fn json_flattened_event() {
 628         let expected =
 629         "{\"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";
 630
 631         let subscriber = subscriber()
 632             .flatten_event(true)
 633             .with_current_span(true)
 634             .with_span_list(true);
 635         test_json(expected, subscriber, || {
 636             let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3);
 637             let _guard = span.enter();
 638             tracing::info!("some json test");
 639         });
 640     }
 641
 642     #[test]
 643     fn json_disabled_current_span_event() {
 644         let expected =
 645         "{\"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";
 646         let subscriber = subscriber()
 647             .flatten_event(false)
 648             .with_current_span(false)
 649             .with_span_list(true);
 650         test_json(expected, subscriber, || {
 651             let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3);
 652             let _guard = span.enter();
 653             tracing::info!("some json test");
 654         });
 655     }
 656
 657     #[test]
 658     fn json_disabled_span_list_event() {
 659         let expected =
 660         "{\"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";
 661         let subscriber = subscriber()
 662             .flatten_event(false)
 663             .with_current_span(true)
 664             .with_span_list(false);
 665         test_json(expected, subscriber, || {
 666             let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3);
 667             let _guard = span.enter();
 668             tracing::info!("some json test");
 669         });
 670     }
 671
 672     #[test]
 673     fn json_nested_span() {
 674         let expected =
 675         "{\"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";
 676         let subscriber = subscriber()
 677             .flatten_event(false)
 678             .with_current_span(true)
 679             .with_span_list(true);
 680         test_json(expected, subscriber, || {
 681             let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3);
 682             let _guard = span.enter();
 683             let span = tracing::span!(
 684                 tracing::Level::INFO,
 685                 "nested_json_span",
 686                 answer = 43,
 687                 number = 4
 688             );
 689             let _guard = span.enter();
 690             tracing::info!("some json test");
 691         });
 692     }
 693
 694     #[test]
 695     fn json_no_span() {
 696         let expected =
 697         "{\"timestamp\":\"fake time\",\"level\":\"INFO\",\"target\":\"tracing_subscriber::fmt::format::json::test\",\"fields\":{\"message\":\"some json test\"}}\n";
 698         let subscriber = subscriber()
 699             .flatten_event(false)
 700             .with_current_span(true)
 701             .with_span_list(true);
 702         test_json(expected, subscriber, || {
 703             tracing::info!("some json test");
 704         });
 705     }
 706
 707     #[test]
 708     fn record_works() {
 709         // This test reproduces issue #707, where using `Span::record` causes
 710         // any events inside the span to be ignored.
 711
 712         let make_writer = MockMakeWriter::default();
 713         let subscriber = crate::fmt()
 714             .json()
 715             .with_writer(make_writer.clone())
 716             .finish();
 717
 718         with_default(subscriber, || {
 719             tracing::info!("an event outside the root span");
 720             assert_eq!(
 721                 parse_as_json(&make_writer)["fields"]["message"],
 722                 "an event outside the root span"
 723             );
 724
 725             let span = tracing::info_span!("the span", na = tracing::field::Empty);
 726             span.record("na", &"value");
 727             let _enter = span.enter();
 728
 729             tracing::info!("an event inside the root span");
 730             assert_eq!(
 731                 parse_as_json(&make_writer)["fields"]["message"],
 732                 "an event inside the root span"
 733             );
 734         });
 735     }
 736
 737     #[test]
 738     fn json_span_event_show_correct_context() {
 739         let buffer = MockMakeWriter::default();
 740         let subscriber = subscriber()
 741             .with_writer(buffer.clone())
 742             .flatten_event(false)
 743             .with_current_span(true)
 744             .with_span_list(false)
 745             .with_span_events(FmtSpan::FULL)
 746             .finish();
 747
 748         with_default(subscriber, || {
 749             let context = "parent";
 750             let parent_span = tracing::info_span!("parent_span", context);
 751
 752             let event = parse_as_json(&buffer);
 753             assert_eq!(event["fields"]["message"], "new");
 754             assert_eq!(event["span"]["context"], "parent");
 755
 756             let _parent_enter = parent_span.enter();
 757             let event = parse_as_json(&buffer);
 758             assert_eq!(event["fields"]["message"], "enter");
 759             assert_eq!(event["span"]["context"], "parent");
 760
 761             let context = "child";
 762             let child_span = tracing::info_span!("child_span", context);
 763             let event = parse_as_json(&buffer);
 764             assert_eq!(event["fields"]["message"], "new");
 765             assert_eq!(event["span"]["context"], "child");
 766
 767             let _child_enter = child_span.enter();
 768             let event = parse_as_json(&buffer);
 769             assert_eq!(event["fields"]["message"], "enter");
 770             assert_eq!(event["span"]["context"], "child");
 771
 772             drop(_child_enter);
 773             let event = parse_as_json(&buffer);
 774             assert_eq!(event["fields"]["message"], "exit");
 775             assert_eq!(event["span"]["context"], "child");
 776
 777             drop(child_span);
 778             let event = parse_as_json(&buffer);
 779             assert_eq!(event["fields"]["message"], "close");
 780             assert_eq!(event["span"]["context"], "child");
 781
 782             drop(_parent_enter);
 783             let event = parse_as_json(&buffer);
 784             assert_eq!(event["fields"]["message"], "exit");
 785             assert_eq!(event["span"]["context"], "parent");
 786
 787             drop(parent_span);
 788             let event = parse_as_json(&buffer);
 789             assert_eq!(event["fields"]["message"], "close");
 790             assert_eq!(event["span"]["context"], "parent");
 791         });
 792     }
 793
 794     #[test]
 795     fn json_span_event_with_no_fields() {
 796         // Check span events serialize correctly.
 797         // Discussion: https://github.com/tokio-rs/tracing/issues/829#issuecomment-661984255
 798         let buffer = MockMakeWriter::default();
 799         let subscriber = subscriber()
 800             .with_writer(buffer.clone())
 801             .flatten_event(false)
 802             .with_current_span(false)
 803             .with_span_list(false)
 804             .with_span_events(FmtSpan::FULL)
 805             .finish();
 806
 807         with_default(subscriber, || {
 808             let span = tracing::info_span!("valid_json");
 809             assert_eq!(parse_as_json(&buffer)["fields"]["message"], "new");
 810
 811             let _enter = span.enter();
 812             assert_eq!(parse_as_json(&buffer)["fields"]["message"], "enter");
 813
 814             drop(_enter);
 815             assert_eq!(parse_as_json(&buffer)["fields"]["message"], "exit");
 816
 817             drop(span);
 818             assert_eq!(parse_as_json(&buffer)["fields"]["message"], "close");
 819         });
 820     }
 821
 822     fn parse_as_json(buffer: &MockMakeWriter) -> serde_json::Value {
 823         let buf = String::from_utf8(buffer.buf().to_vec()).unwrap();
 824         let json = buf
 825             .lines()
 826             .last()
 827             .expect("expected at least one line to be written!");
 828         match serde_json::from_str(json) {
 829             Ok(v) => v,
 830             Err(e) => panic!(
 831                 "assertion failed: JSON shouldn't be malformed\n  error: {}\n  json: {}",
 832                 e, json
 833             ),
 834         }
 835     }
 836
 837     fn test_json<T>(
 838         expected: &str,
 839         builder: crate::fmt::SubscriberBuilder<JsonFields, Format<Json>>,
 840         producer: impl FnOnce() -> T,
 841     ) {
 842         let make_writer = MockMakeWriter::default();
 843         let subscriber = builder
 844             .with_writer(make_writer.clone())
 845             .with_timer(MockTime)
 846             .finish();
 847
 848         with_default(subscriber, producer);
 849
 850         let buf = make_writer.buf();
 851         let actual = std::str::from_utf8(&buf[..]).unwrap();
 852         assert_eq!(
 853             serde_json::from_str::<std::collections::HashMap<&str, serde_json::Value>>(expected)
 854                 .unwrap(),
 855             serde_json::from_str(actual).unwrap()
 856         );
 857     }
 858
 859     fn test_json_with_line_number<T>(
 860         expected: &str,
 861         builder: crate::fmt::SubscriberBuilder<JsonFields, Format<Json>>,
 862         producer: impl FnOnce() -> T,
 863     ) {
 864         let make_writer = MockMakeWriter::default();
 865         let subscriber = builder
 866             .with_writer(make_writer.clone())
 867             .with_timer(MockTime)
 868             .finish();
 869
 870         with_default(subscriber, producer);
 871
 872         let buf = make_writer.buf();
 873         let actual = std::str::from_utf8(&buf[..]).unwrap();
 874         let mut expected =
 875             serde_json::from_str::<std::collections::HashMap<&str, serde_json::Value>>(expected)
 876                 .unwrap();
 877         let expect_line_number = expected.remove("line_number").is_some();
 878         let mut actual: std::collections::HashMap<&str, serde_json::Value> =
 879             serde_json::from_str(actual).unwrap();
 880         let line_number = actual.remove("line_number");
 881         if expect_line_number {
 882             assert_eq!(line_number.map(|x| x.is_number()), Some(true));
 883         } else {
 884             assert!(line_number.is_none());
 885         }
 886         assert_eq!(actual, expected);
 887     }
 888 }