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 /// {"timestamp":"2022-02-15T18:47:10.821315Z","level":"INFO","fields":{"message":"preparing to shave yaks","number_of_yaks":3},"target":"fmt_json"} 40 /// {"timestamp":"2022-02-15T18:47:10.821422Z","level":"INFO","fields":{"message":"shaving yaks"},"target":"fmt_json::yak_shave","spans":[{"yaks":3,"name":"shaving_yaks"}]} 41 /// {"timestamp":"2022-02-15T18:47:10.821495Z","level":"TRACE","fields":{"message":"hello! I'm gonna shave a yak","excitement":"yay!"},"target":"fmt_json::yak_shave","spans":[{"yaks":3,"name":"shaving_yaks"},{"yak":1,"name":"shave"}]} 42 /// {"timestamp":"2022-02-15T18:47:10.821546Z","level":"TRACE","fields":{"message":"yak shaved successfully"},"target":"fmt_json::yak_shave","spans":[{"yaks":3,"name":"shaving_yaks"},{"yak":1,"name":"shave"}]} 43 /// {"timestamp":"2022-02-15T18:47:10.821598Z","level":"DEBUG","fields":{"yak":1,"shaved":true},"target":"yak_events","spans":[{"yaks":3,"name":"shaving_yaks"}]} 44 /// {"timestamp":"2022-02-15T18:47:10.821637Z","level":"TRACE","fields":{"yaks_shaved":1},"target":"fmt_json::yak_shave","spans":[{"yaks":3,"name":"shaving_yaks"}]} 45 /// {"timestamp":"2022-02-15T18:47:10.821684Z","level":"TRACE","fields":{"message":"hello! I'm gonna shave a yak","excitement":"yay!"},"target":"fmt_json::yak_shave","spans":[{"yaks":3,"name":"shaving_yaks"},{"yak":2,"name":"shave"}]} 46 /// {"timestamp":"2022-02-15T18:47:10.821727Z","level":"TRACE","fields":{"message":"yak shaved successfully"},"target":"fmt_json::yak_shave","spans":[{"yaks":3,"name":"shaving_yaks"},{"yak":2,"name":"shave"}]} 47 /// {"timestamp":"2022-02-15T18:47:10.821773Z","level":"DEBUG","fields":{"yak":2,"shaved":true},"target":"yak_events","spans":[{"yaks":3,"name":"shaving_yaks"}]} 48 /// {"timestamp":"2022-02-15T18:47:10.821806Z","level":"TRACE","fields":{"yaks_shaved":2},"target":"fmt_json::yak_shave","spans":[{"yaks":3,"name":"shaving_yaks"}]} 49 /// {"timestamp":"2022-02-15T18:47:10.821909Z","level":"TRACE","fields":{"message":"hello! I'm gonna shave a yak","excitement":"yay!"},"target":"fmt_json::yak_shave","spans":[{"yaks":3,"name":"shaving_yaks"},{"yak":3,"name":"shave"}]} 50 /// {"timestamp":"2022-02-15T18:47:10.821956Z","level":"WARN","fields":{"message":"could not locate yak"},"target":"fmt_json::yak_shave","spans":[{"yaks":3,"name":"shaving_yaks"},{"yak":3,"name":"shave"}]} 51 /// {"timestamp":"2022-02-15T18:47:10.822006Z","level":"DEBUG","fields":{"yak":3,"shaved":false},"target":"yak_events","spans":[{"yaks":3,"name":"shaving_yaks"}]} 52 /// {"timestamp":"2022-02-15T18:47:10.822041Z","level":"ERROR","fields":{"message":"failed to shave yak","yak":3,"error":"missing yak"},"target":"fmt_json::yak_shave","spans":[{"yaks":3,"name":"shaving_yaks"}]} 53 /// {"timestamp":"2022-02-15T18:47:10.822079Z","level":"TRACE","fields":{"yaks_shaved":2},"target":"fmt_json::yak_shave","spans":[{"yaks":3,"name":"shaving_yaks"}]} 54 /// {"timestamp":"2022-02-15T18:47:10.822117Z","level":"INFO","fields":{"message":"yak shaving completed","all_yaks_shaved":false},"target":"fmt_json"} 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)] 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. flatten_event(&mut self, flatten_event: bool)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. with_current_span(&mut self, display_current_span: bool)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. with_span_list(&mut self, display_span_list: bool)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 { serialize<Ser>(&self, serializer_o: Ser) -> Result<Ser::Ok, Ser::Error> where Ser: serde::ser::Serializer,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 { serialize<Ser>(&self, serializer: Ser) -> Result<Ser::Ok, Ser::Error> where Ser: serde::ser::Serializer,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 { format_event( &self, ctx: &FmtContext<'_, S, N>, mut writer: Writer<'_>, event: &Event<'_>, ) -> fmt::Result where S: Subscriber + for<'a> LookupSpan<'a>,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", ×tamp)?; 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 { default() -> Json333 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)] 345 pub struct JsonFields { 346 // reserve the ability to add fields to this without causing a breaking 347 // change in the future. 348 _private: (), 349 } 350 351 impl JsonFields { 352 /// Returns a new JSON [`FormatFields`] implementation. 353 /// new() -> Self354 pub fn new() -> Self { 355 Self { _private: () } 356 } 357 } 358 359 impl Default for JsonFields { default() -> Self360 fn default() -> Self { 361 Self::new() 362 } 363 } 364 365 impl<'a> FormatFields<'a> for JsonFields { 366 /// Format the provided `fields` to the provided `writer`, returning a result. format_fields<R: RecordFields>(&self, mut writer: Writer<'_>, fields: R) -> fmt::Result367 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. add_fields( &self, current: &'a mut FormattedFields<Self>, fields: &Record<'_>, ) -> fmt::Result378 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 424 pub struct JsonVisitor<'a> { 425 values: BTreeMap<&'a str, serde_json::Value>, 426 writer: &'a mut dyn Write, 427 } 428 429 impl<'a> fmt::Debug for JsonVisitor<'a> { fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result430 fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { 431 f.write_fmt(format_args!("JsonVisitor {{ values: {:?} }}", self.values)) 432 } 433 } 434 435 impl<'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. new(writer: &'a mut dyn Write) -> Self442 pub fn new(writer: &'a mut dyn Write) -> Self { 443 Self { 444 values: BTreeMap::new(), 445 writer, 446 } 447 } 448 } 449 450 impl<'a> crate::field::VisitFmt for JsonVisitor<'a> { writer(&mut self) -> &mut dyn fmt::Write451 fn writer(&mut self) -> &mut dyn fmt::Write { 452 self.writer 453 } 454 } 455 456 impl<'a> crate::field::VisitOutput<fmt::Result> for JsonVisitor<'a> { finish(self) -> fmt::Result457 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 477 impl<'a> field::Visit for JsonVisitor<'a> { 478 #[cfg(all(tracing_unstable, feature = "valuable"))] record_value(&mut self, field: &Field, value: valuable_crate::Value<'_>)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. record_f64(&mut self, field: &Field, value: f64)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. record_i64(&mut self, field: &Field, value: i64)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. record_u64(&mut self, field: &Field, value: u64)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. record_bool(&mut self, field: &Field, value: bool)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. record_str(&mut self, field: &Field, value: &str)523 fn record_str(&mut self, field: &Field, value: &str) { 524 self.values 525 .insert(field.name(), serde_json::Value::from(value)); 526 } 527 record_debug(&mut self, field: &Field, value: &dyn fmt::Debug)528 fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) { 529 match field.name() { 530 // Skip fields that are actually log metadata that have already been handled 531 #[cfg(feature = "tracing-log")] 532 name if name.starts_with("log.") => (), 533 name if name.starts_with("r#") => { 534 self.values 535 .insert(&name[2..], serde_json::Value::from(format!("{:?}", value))); 536 } 537 name => { 538 self.values 539 .insert(name, serde_json::Value::from(format!("{:?}", value))); 540 } 541 }; 542 } 543 } 544 #[cfg(test)] 545 mod test { 546 use super::*; 547 use crate::fmt::{format::FmtSpan, test::MockMakeWriter, time::FormatTime, SubscriberBuilder}; 548 use tracing::{self, subscriber::with_default}; 549 550 use std::fmt; 551 use std::path::Path; 552 553 struct MockTime; 554 impl FormatTime for MockTime { format_time(&self, w: &mut Writer<'_>) -> fmt::Result555 fn format_time(&self, w: &mut Writer<'_>) -> fmt::Result { 556 write!(w, "fake time") 557 } 558 } 559 subscriber() -> SubscriberBuilder<JsonFields, Format<Json>>560 fn subscriber() -> SubscriberBuilder<JsonFields, Format<Json>> { 561 SubscriberBuilder::default().json() 562 } 563 564 #[test] json()565 fn json() { 566 let expected = 567 "{\"timestamp\":\"fake time\",\"level\":\"INFO\",\"span\":{\"answer\":42,\"name\":\"json_span\",\"number\":3},\"spans\":[{\"answer\":42,\"name\":\"json_span\",\"number\":3}],\"target\":\"tracing_subscriber::fmt::format::json::test\",\"fields\":{\"message\":\"some json test\"}}\n"; 568 let subscriber = subscriber() 569 .flatten_event(false) 570 .with_current_span(true) 571 .with_span_list(true); 572 test_json(expected, subscriber, || { 573 let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3); 574 let _guard = span.enter(); 575 tracing::info!("some json test"); 576 }); 577 } 578 579 #[test] json_filename()580 fn json_filename() { 581 let current_path = Path::new("tracing-subscriber") 582 .join("src") 583 .join("fmt") 584 .join("format") 585 .join("json.rs") 586 .to_str() 587 .expect("path must be valid unicode") 588 // escape windows backslashes 589 .replace('\\', "\\\\"); 590 let expected = 591 &format!("{}{}{}", 592 "{\"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\":\"", 593 current_path, 594 "\",\"fields\":{\"message\":\"some json test\"}}\n"); 595 let subscriber = subscriber() 596 .flatten_event(false) 597 .with_current_span(true) 598 .with_file(true) 599 .with_span_list(true); 600 test_json(expected, subscriber, || { 601 let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3); 602 let _guard = span.enter(); 603 tracing::info!("some json test"); 604 }); 605 } 606 607 #[test] json_line_number()608 fn json_line_number() { 609 let expected = 610 "{\"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"; 611 let subscriber = subscriber() 612 .flatten_event(false) 613 .with_current_span(true) 614 .with_line_number(true) 615 .with_span_list(true); 616 test_json_with_line_number(expected, subscriber, || { 617 let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3); 618 let _guard = span.enter(); 619 tracing::info!("some json test"); 620 }); 621 } 622 623 #[test] json_flattened_event()624 fn json_flattened_event() { 625 let expected = 626 "{\"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"; 627 628 let subscriber = subscriber() 629 .flatten_event(true) 630 .with_current_span(true) 631 .with_span_list(true); 632 test_json(expected, subscriber, || { 633 let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3); 634 let _guard = span.enter(); 635 tracing::info!("some json test"); 636 }); 637 } 638 639 #[test] json_disabled_current_span_event()640 fn json_disabled_current_span_event() { 641 let expected = 642 "{\"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"; 643 let subscriber = subscriber() 644 .flatten_event(false) 645 .with_current_span(false) 646 .with_span_list(true); 647 test_json(expected, subscriber, || { 648 let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3); 649 let _guard = span.enter(); 650 tracing::info!("some json test"); 651 }); 652 } 653 654 #[test] json_disabled_span_list_event()655 fn json_disabled_span_list_event() { 656 let expected = 657 "{\"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"; 658 let subscriber = subscriber() 659 .flatten_event(false) 660 .with_current_span(true) 661 .with_span_list(false); 662 test_json(expected, subscriber, || { 663 let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3); 664 let _guard = span.enter(); 665 tracing::info!("some json test"); 666 }); 667 } 668 669 #[test] json_nested_span()670 fn json_nested_span() { 671 let expected = 672 "{\"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"; 673 let subscriber = subscriber() 674 .flatten_event(false) 675 .with_current_span(true) 676 .with_span_list(true); 677 test_json(expected, subscriber, || { 678 let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3); 679 let _guard = span.enter(); 680 let span = tracing::span!( 681 tracing::Level::INFO, 682 "nested_json_span", 683 answer = 43, 684 number = 4 685 ); 686 let _guard = span.enter(); 687 tracing::info!("some json test"); 688 }); 689 } 690 691 #[test] json_no_span()692 fn json_no_span() { 693 let expected = 694 "{\"timestamp\":\"fake time\",\"level\":\"INFO\",\"target\":\"tracing_subscriber::fmt::format::json::test\",\"fields\":{\"message\":\"some json test\"}}\n"; 695 let subscriber = subscriber() 696 .flatten_event(false) 697 .with_current_span(true) 698 .with_span_list(true); 699 test_json(expected, subscriber, || { 700 tracing::info!("some json test"); 701 }); 702 } 703 704 #[test] record_works()705 fn record_works() { 706 // This test reproduces issue #707, where using `Span::record` causes 707 // any events inside the span to be ignored. 708 709 let make_writer = MockMakeWriter::default(); 710 let subscriber = crate::fmt() 711 .json() 712 .with_writer(make_writer.clone()) 713 .finish(); 714 715 with_default(subscriber, || { 716 tracing::info!("an event outside the root span"); 717 assert_eq!( 718 parse_as_json(&make_writer)["fields"]["message"], 719 "an event outside the root span" 720 ); 721 722 let span = tracing::info_span!("the span", na = tracing::field::Empty); 723 span.record("na", "value"); 724 let _enter = span.enter(); 725 726 tracing::info!("an event inside the root span"); 727 assert_eq!( 728 parse_as_json(&make_writer)["fields"]["message"], 729 "an event inside the root span" 730 ); 731 }); 732 } 733 734 #[test] json_span_event_show_correct_context()735 fn json_span_event_show_correct_context() { 736 let buffer = MockMakeWriter::default(); 737 let subscriber = subscriber() 738 .with_writer(buffer.clone()) 739 .flatten_event(false) 740 .with_current_span(true) 741 .with_span_list(false) 742 .with_span_events(FmtSpan::FULL) 743 .finish(); 744 745 with_default(subscriber, || { 746 let context = "parent"; 747 let parent_span = tracing::info_span!("parent_span", context); 748 749 let event = parse_as_json(&buffer); 750 assert_eq!(event["fields"]["message"], "new"); 751 assert_eq!(event["span"]["context"], "parent"); 752 753 let _parent_enter = parent_span.enter(); 754 let event = parse_as_json(&buffer); 755 assert_eq!(event["fields"]["message"], "enter"); 756 assert_eq!(event["span"]["context"], "parent"); 757 758 let context = "child"; 759 let child_span = tracing::info_span!("child_span", context); 760 let event = parse_as_json(&buffer); 761 assert_eq!(event["fields"]["message"], "new"); 762 assert_eq!(event["span"]["context"], "child"); 763 764 let _child_enter = child_span.enter(); 765 let event = parse_as_json(&buffer); 766 assert_eq!(event["fields"]["message"], "enter"); 767 assert_eq!(event["span"]["context"], "child"); 768 769 drop(_child_enter); 770 let event = parse_as_json(&buffer); 771 assert_eq!(event["fields"]["message"], "exit"); 772 assert_eq!(event["span"]["context"], "child"); 773 774 drop(child_span); 775 let event = parse_as_json(&buffer); 776 assert_eq!(event["fields"]["message"], "close"); 777 assert_eq!(event["span"]["context"], "child"); 778 779 drop(_parent_enter); 780 let event = parse_as_json(&buffer); 781 assert_eq!(event["fields"]["message"], "exit"); 782 assert_eq!(event["span"]["context"], "parent"); 783 784 drop(parent_span); 785 let event = parse_as_json(&buffer); 786 assert_eq!(event["fields"]["message"], "close"); 787 assert_eq!(event["span"]["context"], "parent"); 788 }); 789 } 790 791 #[test] json_span_event_with_no_fields()792 fn json_span_event_with_no_fields() { 793 // Check span events serialize correctly. 794 // Discussion: https://github.com/tokio-rs/tracing/issues/829#issuecomment-661984255 795 let buffer = MockMakeWriter::default(); 796 let subscriber = subscriber() 797 .with_writer(buffer.clone()) 798 .flatten_event(false) 799 .with_current_span(false) 800 .with_span_list(false) 801 .with_span_events(FmtSpan::FULL) 802 .finish(); 803 804 with_default(subscriber, || { 805 let span = tracing::info_span!("valid_json"); 806 assert_eq!(parse_as_json(&buffer)["fields"]["message"], "new"); 807 808 let _enter = span.enter(); 809 assert_eq!(parse_as_json(&buffer)["fields"]["message"], "enter"); 810 811 drop(_enter); 812 assert_eq!(parse_as_json(&buffer)["fields"]["message"], "exit"); 813 814 drop(span); 815 assert_eq!(parse_as_json(&buffer)["fields"]["message"], "close"); 816 }); 817 } 818 parse_as_json(buffer: &MockMakeWriter) -> serde_json::Value819 fn parse_as_json(buffer: &MockMakeWriter) -> serde_json::Value { 820 let buf = String::from_utf8(buffer.buf().to_vec()).unwrap(); 821 let json = buf 822 .lines() 823 .last() 824 .expect("expected at least one line to be written!"); 825 match serde_json::from_str(json) { 826 Ok(v) => v, 827 Err(e) => panic!( 828 "assertion failed: JSON shouldn't be malformed\n error: {}\n json: {}", 829 e, json 830 ), 831 } 832 } 833 test_json<T>( expected: &str, builder: crate::fmt::SubscriberBuilder<JsonFields, Format<Json>>, producer: impl FnOnce() -> T, )834 fn test_json<T>( 835 expected: &str, 836 builder: crate::fmt::SubscriberBuilder<JsonFields, Format<Json>>, 837 producer: impl FnOnce() -> T, 838 ) { 839 let make_writer = MockMakeWriter::default(); 840 let subscriber = builder 841 .with_writer(make_writer.clone()) 842 .with_timer(MockTime) 843 .finish(); 844 845 with_default(subscriber, producer); 846 847 let buf = make_writer.buf(); 848 let actual = std::str::from_utf8(&buf[..]).unwrap(); 849 assert_eq!( 850 serde_json::from_str::<std::collections::HashMap<&str, serde_json::Value>>(expected) 851 .unwrap(), 852 serde_json::from_str(actual).unwrap() 853 ); 854 } 855 test_json_with_line_number<T>( expected: &str, builder: crate::fmt::SubscriberBuilder<JsonFields, Format<Json>>, producer: impl FnOnce() -> T, )856 fn test_json_with_line_number<T>( 857 expected: &str, 858 builder: crate::fmt::SubscriberBuilder<JsonFields, Format<Json>>, 859 producer: impl FnOnce() -> T, 860 ) { 861 let make_writer = MockMakeWriter::default(); 862 let subscriber = builder 863 .with_writer(make_writer.clone()) 864 .with_timer(MockTime) 865 .finish(); 866 867 with_default(subscriber, producer); 868 869 let buf = make_writer.buf(); 870 let actual = std::str::from_utf8(&buf[..]).unwrap(); 871 let mut expected = 872 serde_json::from_str::<std::collections::HashMap<&str, serde_json::Value>>(expected) 873 .unwrap(); 874 let expect_line_number = expected.remove("line_number").is_some(); 875 let mut actual: std::collections::HashMap<&str, serde_json::Value> = 876 serde_json::from_str(actual).unwrap(); 877 let line_number = actual.remove("line_number"); 878 if expect_line_number { 879 assert_eq!(line_number.map(|x| x.is_number()), Some(true)); 880 } else { 881 assert!(line_number.is_none()); 882 } 883 assert_eq!(actual, expected); 884 } 885 } 886