diff options
Diffstat (limited to 'vendor/tracing-subscriber/src/fmt/format/json.rs')
| -rw-r--r-- | vendor/tracing-subscriber/src/fmt/format/json.rs | 885 |
1 files changed, 885 insertions, 0 deletions
diff --git a/vendor/tracing-subscriber/src/fmt/format/json.rs b/vendor/tracing-subscriber/src/fmt/format/json.rs new file mode 100644 index 000000000..c2f4d3755 --- /dev/null +++ b/vendor/tracing-subscriber/src/fmt/format/json.rs @@ -0,0 +1,885 @@ +use super::{Format, FormatEvent, FormatFields, FormatTime, Writer}; +use crate::{ + field::{RecordFields, VisitOutput}, + fmt::{ + fmt_layer::{FmtContext, FormattedFields}, + writer::WriteAdaptor, + }, + registry::LookupSpan, +}; +use serde::ser::{SerializeMap, Serializer as _}; +use serde_json::Serializer; +use std::{ + collections::BTreeMap, + fmt::{self, Write}, +}; +use tracing_core::{ + field::{self, Field}, + span::Record, + Event, Subscriber, +}; +use tracing_serde::AsSerde; + +#[cfg(feature = "tracing-log")] +use tracing_log::NormalizeEvent; + +/// Marker for [`Format`] that indicates that the newline-delimited JSON log +/// format should be used. +/// +/// This formatter is intended for production use with systems where structured +/// logs are consumed as JSON by analysis and viewing tools. The JSON output is +/// not optimized for human readability; instead, it should be pretty-printed +/// using external JSON tools such as `jq`, or using a JSON log viewer. +/// +/// # Example Output +/// +/// <pre><font color="#4E9A06"><b>:;</b></font> <font color="#4E9A06">cargo</font> run --example fmt-json +/// <font color="#4E9A06"><b> Finished</b></font> dev [unoptimized + debuginfo] target(s) in 0.08s +/// <font color="#4E9A06"><b> Running</b></font> `target/debug/examples/fmt-json` +/// {"timestamp":"2022-02-15T18:47:10.821315Z","level":"INFO","fields":{"message":"preparing to shave yaks","number_of_yaks":3},"target":"fmt_json"} +/// {"timestamp":"2022-02-15T18:47:10.821422Z","level":"INFO","fields":{"message":"shaving yaks"},"target":"fmt_json::yak_shave","spans":[{"yaks":3,"name":"shaving_yaks"}]} +/// {"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"}]} +/// {"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"}]} +/// {"timestamp":"2022-02-15T18:47:10.821598Z","level":"DEBUG","fields":{"yak":1,"shaved":true},"target":"yak_events","spans":[{"yaks":3,"name":"shaving_yaks"}]} +/// {"timestamp":"2022-02-15T18:47:10.821637Z","level":"TRACE","fields":{"yaks_shaved":1},"target":"fmt_json::yak_shave","spans":[{"yaks":3,"name":"shaving_yaks"}]} +/// {"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"}]} +/// {"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"}]} +/// {"timestamp":"2022-02-15T18:47:10.821773Z","level":"DEBUG","fields":{"yak":2,"shaved":true},"target":"yak_events","spans":[{"yaks":3,"name":"shaving_yaks"}]} +/// {"timestamp":"2022-02-15T18:47:10.821806Z","level":"TRACE","fields":{"yaks_shaved":2},"target":"fmt_json::yak_shave","spans":[{"yaks":3,"name":"shaving_yaks"}]} +/// {"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"}]} +/// {"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"}]} +/// {"timestamp":"2022-02-15T18:47:10.822006Z","level":"DEBUG","fields":{"yak":3,"shaved":false},"target":"yak_events","spans":[{"yaks":3,"name":"shaving_yaks"}]} +/// {"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"}]} +/// {"timestamp":"2022-02-15T18:47:10.822079Z","level":"TRACE","fields":{"yaks_shaved":2},"target":"fmt_json::yak_shave","spans":[{"yaks":3,"name":"shaving_yaks"}]} +/// {"timestamp":"2022-02-15T18:47:10.822117Z","level":"INFO","fields":{"message":"yak shaving completed","all_yaks_shaved":false},"target":"fmt_json"} +/// </pre> +/// +/// # Options +/// +/// This formatter exposes additional options to configure the structure of the +/// output JSON objects: +/// +/// - [`Json::flatten_event`] can be used to enable flattening event fields into +/// the root +/// - [`Json::with_current_span`] can be used to control logging of the current +/// span +/// - [`Json::with_span_list`] can be used to control logging of the span list +/// object. +/// +/// By default, event fields are not flattened, and both current span and span +/// list are logged. +/// +/// # Valuable Support +/// +/// Experimental support is available for using the [`valuable`] crate to record +/// user-defined values as structured JSON. When the ["valuable" unstable +/// feature][unstable] is enabled, types implementing [`valuable::Valuable`] will +/// be recorded as structured JSON, rather than +/// using their [`std::fmt::Debug`] implementations. +/// +/// **Note**: This is an experimental feature. [Unstable features][unstable] +/// must be enabled in order to use `valuable` support. +/// +/// [`Json::flatten_event`]: Json::flatten_event() +/// [`Json::with_current_span`]: Json::with_current_span() +/// [`Json::with_span_list`]: Json::with_span_list() +/// [`valuable`]: https://crates.io/crates/valuable +/// [unstable]: crate#unstable-features +/// [`valuable::Valuable`]: https://docs.rs/valuable/latest/valuable/trait.Valuable.html +#[derive(Debug, Copy, Clone, Eq, PartialEq)] +pub struct Json { + pub(crate) flatten_event: bool, + pub(crate) display_current_span: bool, + pub(crate) display_span_list: bool, +} + +impl Json { + /// If set to `true` event metadata will be flattened into the root object. + pub fn flatten_event(&mut self, flatten_event: bool) { + self.flatten_event = flatten_event; + } + + /// If set to `false`, formatted events won't contain a field for the current span. + pub fn with_current_span(&mut self, display_current_span: bool) { + self.display_current_span = display_current_span; + } + + /// If set to `false`, formatted events won't contain a list of all currently + /// entered spans. Spans are logged in a list from root to leaf. + pub fn with_span_list(&mut self, display_span_list: bool) { + self.display_span_list = display_span_list; + } +} + +struct SerializableContext<'a, 'b, Span, N>( + &'b crate::layer::Context<'a, Span>, + std::marker::PhantomData<N>, +) +where + Span: Subscriber + for<'lookup> crate::registry::LookupSpan<'lookup>, + N: for<'writer> FormatFields<'writer> + 'static; + +impl<'a, 'b, Span, N> serde::ser::Serialize for SerializableContext<'a, 'b, Span, N> +where + Span: Subscriber + for<'lookup> crate::registry::LookupSpan<'lookup>, + N: for<'writer> FormatFields<'writer> + 'static, +{ + fn serialize<Ser>(&self, serializer_o: Ser) -> Result<Ser::Ok, Ser::Error> + where + Ser: serde::ser::Serializer, + { + use serde::ser::SerializeSeq; + let mut serializer = serializer_o.serialize_seq(None)?; + + if let Some(leaf_span) = self.0.lookup_current() { + for span in leaf_span.scope().from_root() { + serializer.serialize_element(&SerializableSpan(&span, self.1))?; + } + } + + serializer.end() + } +} + +struct SerializableSpan<'a, 'b, Span, N>( + &'b crate::registry::SpanRef<'a, Span>, + std::marker::PhantomData<N>, +) +where + Span: for<'lookup> crate::registry::LookupSpan<'lookup>, + N: for<'writer> FormatFields<'writer> + 'static; + +impl<'a, 'b, Span, N> serde::ser::Serialize for SerializableSpan<'a, 'b, Span, N> +where + Span: for<'lookup> crate::registry::LookupSpan<'lookup>, + N: for<'writer> FormatFields<'writer> + 'static, +{ + fn serialize<Ser>(&self, serializer: Ser) -> Result<Ser::Ok, Ser::Error> + where + Ser: serde::ser::Serializer, + { + let mut serializer = serializer.serialize_map(None)?; + + let ext = self.0.extensions(); + let data = ext + .get::<FormattedFields<N>>() + .expect("Unable to find FormattedFields in extensions; this is a bug"); + + // TODO: let's _not_ do this, but this resolves + // https://github.com/tokio-rs/tracing/issues/391. + // We should probably rework this to use a `serde_json::Value` or something + // similar in a JSON-specific layer, but I'd (david) + // rather have a uglier fix now rather than shipping broken JSON. + match serde_json::from_str::<serde_json::Value>(data) { + Ok(serde_json::Value::Object(fields)) => { + for field in fields { + serializer.serialize_entry(&field.0, &field.1)?; + } + } + // We have fields for this span which are valid JSON but not an object. + // This is probably a bug, so panic if we're in debug mode + Ok(_) if cfg!(debug_assertions) => panic!( + "span '{}' had malformed fields! this is a bug.\n error: invalid JSON object\n fields: {:?}", + self.0.metadata().name(), + data + ), + // If we *aren't* in debug mode, it's probably best not to + // crash the program, let's log the field found but also an + // message saying it's type is invalid + Ok(value) => { + serializer.serialize_entry("field", &value)?; + serializer.serialize_entry("field_error", "field was no a valid object")? + } + // We have previously recorded fields for this span + // should be valid JSON. However, they appear to *not* + // be valid JSON. This is almost certainly a bug, so + // panic if we're in debug mode + Err(e) if cfg!(debug_assertions) => panic!( + "span '{}' had malformed fields! this is a bug.\n error: {}\n fields: {:?}", + self.0.metadata().name(), + e, + data + ), + // If we *aren't* in debug mode, it's probably best not + // crash the program, but let's at least make sure it's clear + // that the fields are not supposed to be missing. + Err(e) => serializer.serialize_entry("field_error", &format!("{}", e))?, + }; + serializer.serialize_entry("name", self.0.metadata().name())?; + serializer.end() + } +} + +impl<S, N, T> FormatEvent<S, N> for Format<Json, T> +where + S: Subscriber + for<'lookup> LookupSpan<'lookup>, + N: for<'writer> FormatFields<'writer> + 'static, + T: FormatTime, +{ + fn format_event( + &self, + ctx: &FmtContext<'_, S, N>, + mut writer: Writer<'_>, + event: &Event<'_>, + ) -> fmt::Result + where + S: Subscriber + for<'a> LookupSpan<'a>, + { + let mut timestamp = String::new(); + self.timer.format_time(&mut Writer::new(&mut timestamp))?; + + #[cfg(feature = "tracing-log")] + let normalized_meta = event.normalized_metadata(); + #[cfg(feature = "tracing-log")] + let meta = normalized_meta.as_ref().unwrap_or_else(|| event.metadata()); + #[cfg(not(feature = "tracing-log"))] + let meta = event.metadata(); + + let mut visit = || { + let mut serializer = Serializer::new(WriteAdaptor::new(&mut writer)); + + let mut serializer = serializer.serialize_map(None)?; + + if self.display_timestamp { + serializer.serialize_entry("timestamp", ×tamp)?; + } + + if self.display_level { + serializer.serialize_entry("level", &meta.level().as_serde())?; + } + + let format_field_marker: std::marker::PhantomData<N> = std::marker::PhantomData; + + let current_span = if self.format.display_current_span || self.format.display_span_list + { + event + .parent() + .and_then(|id| ctx.span(id)) + .or_else(|| ctx.lookup_current()) + } else { + None + }; + + if self.format.flatten_event { + let mut visitor = tracing_serde::SerdeMapVisitor::new(serializer); + event.record(&mut visitor); + + serializer = visitor.take_serializer()?; + } else { + use tracing_serde::fields::AsMap; + serializer.serialize_entry("fields", &event.field_map())?; + }; + + if self.display_target { + serializer.serialize_entry("target", meta.target())?; + } + + if self.display_filename { + if let Some(filename) = meta.file() { + serializer.serialize_entry("filename", filename)?; + } + } + + if self.display_line_number { + if let Some(line_number) = meta.line() { + serializer.serialize_entry("line_number", &line_number)?; + } + } + + if self.format.display_current_span { + if let Some(ref span) = current_span { + serializer + .serialize_entry("span", &SerializableSpan(span, format_field_marker)) + .unwrap_or(()); + } + } + + if self.format.display_span_list && current_span.is_some() { + serializer.serialize_entry( + "spans", + &SerializableContext(&ctx.ctx, format_field_marker), + )?; + } + + if self.display_thread_name { + let current_thread = std::thread::current(); + match current_thread.name() { + Some(name) => { + serializer.serialize_entry("threadName", name)?; + } + // fall-back to thread id when name is absent and ids are not enabled + None if !self.display_thread_id => { + serializer + .serialize_entry("threadName", &format!("{:?}", current_thread.id()))?; + } + _ => {} + } + } + + if self.display_thread_id { + serializer + .serialize_entry("threadId", &format!("{:?}", std::thread::current().id()))?; + } + + serializer.end() + }; + + visit().map_err(|_| fmt::Error)?; + writeln!(writer) + } +} + +impl Default for Json { + fn default() -> Json { + Json { + flatten_event: false, + display_current_span: true, + display_span_list: true, + } + } +} + +/// The JSON [`FormatFields`] implementation. +/// +#[derive(Debug)] +pub struct JsonFields { + // reserve the ability to add fields to this without causing a breaking + // change in the future. + _private: (), +} + +impl JsonFields { + /// Returns a new JSON [`FormatFields`] implementation. + /// + pub fn new() -> Self { + Self { _private: () } + } +} + +impl Default for JsonFields { + fn default() -> Self { + Self::new() + } +} + +impl<'a> FormatFields<'a> for JsonFields { + /// Format the provided `fields` to the provided `writer`, returning a result. + fn format_fields<R: RecordFields>(&self, mut writer: Writer<'_>, fields: R) -> fmt::Result { + let mut v = JsonVisitor::new(&mut writer); + fields.record(&mut v); + v.finish() + } + + /// Record additional field(s) on an existing span. + /// + /// By default, this appends a space to the current set of fields if it is + /// non-empty, and then calls `self.format_fields`. If different behavior is + /// required, the default implementation of this method can be overridden. + fn add_fields( + &self, + current: &'a mut FormattedFields<Self>, + fields: &Record<'_>, + ) -> fmt::Result { + if current.is_empty() { + // If there are no previously recorded fields, we can just reuse the + // existing string. + let mut writer = current.as_writer(); + let mut v = JsonVisitor::new(&mut writer); + fields.record(&mut v); + v.finish()?; + return Ok(()); + } + + // If fields were previously recorded on this span, we need to parse + // the current set of fields as JSON, add the new fields, and + // re-serialize them. Otherwise, if we just appended the new fields + // to a previously serialized JSON object, we would end up with + // malformed JSON. + // + // XXX(eliza): this is far from efficient, but unfortunately, it is + // necessary as long as the JSON formatter is implemented on top of + // an interface that stores all formatted fields as strings. + // + // We should consider reimplementing the JSON formatter as a + // separate layer, rather than a formatter for the `fmt` layer — + // then, we could store fields as JSON values, and add to them + // without having to parse and re-serialize. + let mut new = String::new(); + let map: BTreeMap<&'_ str, serde_json::Value> = + serde_json::from_str(current).map_err(|_| fmt::Error)?; + let mut v = JsonVisitor::new(&mut new); + v.values = map; + fields.record(&mut v); + v.finish()?; + current.fields = new; + + Ok(()) + } +} + +/// The [visitor] produced by [`JsonFields`]'s [`MakeVisitor`] implementation. +/// +/// [visitor]: crate::field::Visit +/// [`MakeVisitor`]: crate::field::MakeVisitor +pub struct JsonVisitor<'a> { + values: BTreeMap<&'a str, serde_json::Value>, + writer: &'a mut dyn Write, +} + +impl<'a> fmt::Debug for JsonVisitor<'a> { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + f.write_fmt(format_args!("JsonVisitor {{ values: {:?} }}", self.values)) + } +} + +impl<'a> JsonVisitor<'a> { + /// Returns a new default visitor that formats to the provided `writer`. + /// + /// # Arguments + /// - `writer`: the writer to format to. + /// - `is_empty`: whether or not any fields have been previously written to + /// that writer. + pub fn new(writer: &'a mut dyn Write) -> Self { + Self { + values: BTreeMap::new(), + writer, + } + } +} + +impl<'a> crate::field::VisitFmt for JsonVisitor<'a> { + fn writer(&mut self) -> &mut dyn fmt::Write { + self.writer + } +} + +impl<'a> crate::field::VisitOutput<fmt::Result> for JsonVisitor<'a> { + fn finish(self) -> fmt::Result { + let inner = || { + let mut serializer = Serializer::new(WriteAdaptor::new(self.writer)); + let mut ser_map = serializer.serialize_map(None)?; + + for (k, v) in self.values { + ser_map.serialize_entry(k, &v)?; + } + + ser_map.end() + }; + + if inner().is_err() { + Err(fmt::Error) + } else { + Ok(()) + } + } +} + +impl<'a> field::Visit for JsonVisitor<'a> { + #[cfg(all(tracing_unstable, feature = "valuable"))] + fn record_value(&mut self, field: &Field, value: valuable_crate::Value<'_>) { + let value = match serde_json::to_value(valuable_serde::Serializable::new(value)) { + Ok(value) => value, + Err(_e) => { + #[cfg(debug_assertions)] + unreachable!( + "`valuable::Valuable` implementations should always serialize \ + successfully, but an error occurred: {}", + _e, + ); + + #[cfg(not(debug_assertions))] + return; + } + }; + + self.values.insert(field.name(), value); + } + + /// Visit a double precision floating point value. + fn record_f64(&mut self, field: &Field, value: f64) { + self.values + .insert(field.name(), serde_json::Value::from(value)); + } + + /// Visit a signed 64-bit integer value. + fn record_i64(&mut self, field: &Field, value: i64) { + self.values + .insert(field.name(), serde_json::Value::from(value)); + } + + /// Visit an unsigned 64-bit integer value. + fn record_u64(&mut self, field: &Field, value: u64) { + self.values + .insert(field.name(), serde_json::Value::from(value)); + } + + /// Visit a boolean value. + fn record_bool(&mut self, field: &Field, value: bool) { + self.values + .insert(field.name(), serde_json::Value::from(value)); + } + + /// Visit a string value. + fn record_str(&mut self, field: &Field, value: &str) { + self.values + .insert(field.name(), serde_json::Value::from(value)); + } + + fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) { + match field.name() { + // Skip fields that are actually log metadata that have already been handled + #[cfg(feature = "tracing-log")] + name if name.starts_with("log.") => (), + name if name.starts_with("r#") => { + self.values + .insert(&name[2..], serde_json::Value::from(format!("{:?}", value))); + } + name => { + self.values + .insert(name, serde_json::Value::from(format!("{:?}", value))); + } + }; + } +} +#[cfg(test)] +mod test { + use super::*; + use crate::fmt::{format::FmtSpan, test::MockMakeWriter, time::FormatTime, SubscriberBuilder}; + use tracing::{self, subscriber::with_default}; + + use std::fmt; + use std::path::Path; + + struct MockTime; + impl FormatTime for MockTime { + fn format_time(&self, w: &mut Writer<'_>) -> fmt::Result { + write!(w, "fake time") + } + } + + fn subscriber() -> SubscriberBuilder<JsonFields, Format<Json>> { + SubscriberBuilder::default().json() + } + + #[test] + fn json() { + let expected = + "{\"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"; + let subscriber = subscriber() + .flatten_event(false) + .with_current_span(true) + .with_span_list(true); + test_json(expected, subscriber, || { + let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3); + let _guard = span.enter(); + tracing::info!("some json test"); + }); + } + + #[test] + fn json_filename() { + let current_path = Path::new("tracing-subscriber") + .join("src") + .join("fmt") + .join("format") + .join("json.rs") + .to_str() + .expect("path must be valid unicode") + // escape windows backslashes + .replace('\\', "\\\\"); + let expected = + &format!("{}{}{}", + "{\"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\":\"", + current_path, + "\",\"fields\":{\"message\":\"some json test\"}}\n"); + let subscriber = subscriber() + .flatten_event(false) + .with_current_span(true) + .with_file(true) + .with_span_list(true); + test_json(expected, subscriber, || { + let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3); + let _guard = span.enter(); + tracing::info!("some json test"); + }); + } + + #[test] + fn json_line_number() { + let expected = + "{\"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"; + let subscriber = subscriber() + .flatten_event(false) + .with_current_span(true) + .with_line_number(true) + .with_span_list(true); + test_json_with_line_number(expected, subscriber, || { + let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3); + let _guard = span.enter(); + tracing::info!("some json test"); + }); + } + + #[test] + fn json_flattened_event() { + let expected = + "{\"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"; + + let subscriber = subscriber() + .flatten_event(true) + .with_current_span(true) + .with_span_list(true); + test_json(expected, subscriber, || { + let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3); + let _guard = span.enter(); + tracing::info!("some json test"); + }); + } + + #[test] + fn json_disabled_current_span_event() { + let expected = + "{\"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"; + let subscriber = subscriber() + .flatten_event(false) + .with_current_span(false) + .with_span_list(true); + test_json(expected, subscriber, || { + let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3); + let _guard = span.enter(); + tracing::info!("some json test"); + }); + } + + #[test] + fn json_disabled_span_list_event() { + let expected = + "{\"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"; + let subscriber = subscriber() + .flatten_event(false) + .with_current_span(true) + .with_span_list(false); + test_json(expected, subscriber, || { + let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3); + let _guard = span.enter(); + tracing::info!("some json test"); + }); + } + + #[test] + fn json_nested_span() { + let expected = + "{\"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"; + let subscriber = subscriber() + .flatten_event(false) + .with_current_span(true) + .with_span_list(true); + test_json(expected, subscriber, || { + let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3); + let _guard = span.enter(); + let span = tracing::span!( + tracing::Level::INFO, + "nested_json_span", + answer = 43, + number = 4 + ); + let _guard = span.enter(); + tracing::info!("some json test"); + }); + } + + #[test] + fn json_no_span() { + let expected = + "{\"timestamp\":\"fake time\",\"level\":\"INFO\",\"target\":\"tracing_subscriber::fmt::format::json::test\",\"fields\":{\"message\":\"some json test\"}}\n"; + let subscriber = subscriber() + .flatten_event(false) + .with_current_span(true) + .with_span_list(true); + test_json(expected, subscriber, || { + tracing::info!("some json test"); + }); + } + + #[test] + fn record_works() { + // This test reproduces issue #707, where using `Span::record` causes + // any events inside the span to be ignored. + + let make_writer = MockMakeWriter::default(); + let subscriber = crate::fmt() + .json() + .with_writer(make_writer.clone()) + .finish(); + + with_default(subscriber, || { + tracing::info!("an event outside the root span"); + assert_eq!( + parse_as_json(&make_writer)["fields"]["message"], + "an event outside the root span" + ); + + let span = tracing::info_span!("the span", na = tracing::field::Empty); + span.record("na", &"value"); + let _enter = span.enter(); + + tracing::info!("an event inside the root span"); + assert_eq!( + parse_as_json(&make_writer)["fields"]["message"], + "an event inside the root span" + ); + }); + } + + #[test] + fn json_span_event_show_correct_context() { + let buffer = MockMakeWriter::default(); + let subscriber = subscriber() + .with_writer(buffer.clone()) + .flatten_event(false) + .with_current_span(true) + .with_span_list(false) + .with_span_events(FmtSpan::FULL) + .finish(); + + with_default(subscriber, || { + let context = "parent"; + let parent_span = tracing::info_span!("parent_span", context); + + let event = parse_as_json(&buffer); + assert_eq!(event["fields"]["message"], "new"); + assert_eq!(event["span"]["context"], "parent"); + + let _parent_enter = parent_span.enter(); + let event = parse_as_json(&buffer); + assert_eq!(event["fields"]["message"], "enter"); + assert_eq!(event["span"]["context"], "parent"); + + let context = "child"; + let child_span = tracing::info_span!("child_span", context); + let event = parse_as_json(&buffer); + assert_eq!(event["fields"]["message"], "new"); + assert_eq!(event["span"]["context"], "child"); + + let _child_enter = child_span.enter(); + let event = parse_as_json(&buffer); + assert_eq!(event["fields"]["message"], "enter"); + assert_eq!(event["span"]["context"], "child"); + + drop(_child_enter); + let event = parse_as_json(&buffer); + assert_eq!(event["fields"]["message"], "exit"); + assert_eq!(event["span"]["context"], "child"); + + drop(child_span); + let event = parse_as_json(&buffer); + assert_eq!(event["fields"]["message"], "close"); + assert_eq!(event["span"]["context"], "child"); + + drop(_parent_enter); + let event = parse_as_json(&buffer); + assert_eq!(event["fields"]["message"], "exit"); + assert_eq!(event["span"]["context"], "parent"); + + drop(parent_span); + let event = parse_as_json(&buffer); + assert_eq!(event["fields"]["message"], "close"); + assert_eq!(event["span"]["context"], "parent"); + }); + } + + #[test] + fn json_span_event_with_no_fields() { + // Check span events serialize correctly. + // Discussion: https://github.com/tokio-rs/tracing/issues/829#issuecomment-661984255 + let buffer = MockMakeWriter::default(); + let subscriber = subscriber() + .with_writer(buffer.clone()) + .flatten_event(false) + .with_current_span(false) + .with_span_list(false) + .with_span_events(FmtSpan::FULL) + .finish(); + + with_default(subscriber, || { + let span = tracing::info_span!("valid_json"); + assert_eq!(parse_as_json(&buffer)["fields"]["message"], "new"); + + let _enter = span.enter(); + assert_eq!(parse_as_json(&buffer)["fields"]["message"], "enter"); + + drop(_enter); + assert_eq!(parse_as_json(&buffer)["fields"]["message"], "exit"); + + drop(span); + assert_eq!(parse_as_json(&buffer)["fields"]["message"], "close"); + }); + } + + fn parse_as_json(buffer: &MockMakeWriter) -> serde_json::Value { + let buf = String::from_utf8(buffer.buf().to_vec()).unwrap(); + let json = buf + .lines() + .last() + .expect("expected at least one line to be written!"); + match serde_json::from_str(json) { + Ok(v) => v, + Err(e) => panic!( + "assertion failed: JSON shouldn't be malformed\n error: {}\n json: {}", + e, json + ), + } + } + + fn test_json<T>( + expected: &str, + builder: crate::fmt::SubscriberBuilder<JsonFields, Format<Json>>, + producer: impl FnOnce() -> T, + ) { + let make_writer = MockMakeWriter::default(); + let subscriber = builder + .with_writer(make_writer.clone()) + .with_timer(MockTime) + .finish(); + + with_default(subscriber, producer); + + let buf = make_writer.buf(); + let actual = std::str::from_utf8(&buf[..]).unwrap(); + assert_eq!( + serde_json::from_str::<std::collections::HashMap<&str, serde_json::Value>>(expected) + .unwrap(), + serde_json::from_str(actual).unwrap() + ); + } + + fn test_json_with_line_number<T>( + expected: &str, + builder: crate::fmt::SubscriberBuilder<JsonFields, Format<Json>>, + producer: impl FnOnce() -> T, + ) { + let make_writer = MockMakeWriter::default(); + let subscriber = builder + .with_writer(make_writer.clone()) + .with_timer(MockTime) + .finish(); + + with_default(subscriber, producer); + + let buf = make_writer.buf(); + let actual = std::str::from_utf8(&buf[..]).unwrap(); + let mut expected = + serde_json::from_str::<std::collections::HashMap<&str, serde_json::Value>>(expected) + .unwrap(); + let expect_line_number = expected.remove("line_number").is_some(); + let mut actual: std::collections::HashMap<&str, serde_json::Value> = + serde_json::from_str(actual).unwrap(); + let line_number = actual.remove("line_number"); + if expect_line_number { + assert_eq!(line_number.map(|x| x.is_number()), Some(true)); + } else { + assert!(line_number.is_none()); + } + assert_eq!(actual, expected); + } +} |