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