]>
Commit | Line | Data |
---|---|---|
f035d41b XL |
1 | use super::{Format, FormatEvent, FormatFields, FormatTime}; |
2 | use crate::{ | |
3 | field::{RecordFields, VisitOutput}, | |
4 | fmt::fmt_layer::{FmtContext, FormattedFields}, | |
5 | registry::LookupSpan, | |
6 | }; | |
7 | use serde::ser::{SerializeMap, Serializer as _}; | |
8 | use serde_json::Serializer; | |
9 | use std::{ | |
10 | collections::BTreeMap, | |
11 | fmt::{self, Write}, | |
12 | io, | |
13 | }; | |
14 | use tracing_core::{ | |
15 | field::{self, Field}, | |
16 | span::Record, | |
17 | Event, Subscriber, | |
18 | }; | |
19 | use tracing_serde::AsSerde; | |
20 | ||
21 | #[cfg(feature = "tracing-log")] | |
22 | use tracing_log::NormalizeEvent; | |
23 | ||
24 | /// Marker for `Format` that indicates that the verbose json log format should be used. | |
25 | /// | |
26 | /// The full format includes fields from all entered spans. | |
27 | /// | |
28 | /// # Example Output | |
29 | /// | |
30 | /// ```ignore,json | |
3dfed10e XL |
31 | /// { |
32 | /// "timestamp":"Feb 20 11:28:15.096", | |
33 | /// "level":"INFO", | |
3dfed10e | 34 | /// "fields":{"message":"some message","key":"value"} |
29967ef6 XL |
35 | /// "target":"mycrate", |
36 | /// "span":{name":"leaf"}, | |
37 | /// "spans":[{"name":"root"},{"name":"leaf"}], | |
3dfed10e | 38 | /// } |
f035d41b XL |
39 | /// ``` |
40 | /// | |
41 | /// # Options | |
42 | /// | |
3dfed10e XL |
43 | /// - [`Json::flatten_event`] can be used to enable flattening event fields into |
44 | /// the root | |
45 | /// - [`Json::with_current_span`] can be used to control logging of the current | |
46 | /// span | |
47 | /// - [`Json::with_span_list`] can be used to control logging of the span list | |
f035d41b XL |
48 | /// object. |
49 | /// | |
3dfed10e XL |
50 | /// By default, event fields are not flattened, and both current span and span |
51 | /// list are logged. | |
52 | /// | |
f035d41b | 53 | /// [`Json::flatten_event`]: #method.flatten_event |
3dfed10e XL |
54 | /// [`Json::with_current_span`]: #method.with_current_span |
55 | /// [`Json::with_span_list`]: #method.with_span_list | |
f035d41b XL |
56 | #[derive(Debug, Copy, Clone, Eq, PartialEq)] |
57 | pub struct Json { | |
58 | pub(crate) flatten_event: bool, | |
3dfed10e XL |
59 | pub(crate) display_current_span: bool, |
60 | pub(crate) display_span_list: bool, | |
f035d41b XL |
61 | } |
62 | ||
63 | impl Json { | |
64 | /// If set to `true` event metadata will be flattened into the root object. | |
65 | pub fn flatten_event(&mut self, flatten_event: bool) { | |
66 | self.flatten_event = flatten_event; | |
67 | } | |
3dfed10e XL |
68 | |
69 | /// If set to `false`, formatted events won't contain a field for the current span. | |
70 | pub fn with_current_span(&mut self, display_current_span: bool) { | |
71 | self.display_current_span = display_current_span; | |
72 | } | |
73 | ||
74 | /// If set to `false`, formatted events won't contain a list of all currently | |
75 | /// entered spans. Spans are logged in a list from root to leaf. | |
76 | pub fn with_span_list(&mut self, display_span_list: bool) { | |
77 | self.display_span_list = display_span_list; | |
78 | } | |
79 | } | |
80 | ||
81 | struct SerializableContext<'a, 'b, Span, N>( | |
82 | &'b crate::layer::Context<'a, Span>, | |
83 | std::marker::PhantomData<N>, | |
84 | ) | |
85 | where | |
86 | Span: Subscriber + for<'lookup> crate::registry::LookupSpan<'lookup>, | |
87 | N: for<'writer> FormatFields<'writer> + 'static; | |
88 | ||
89 | impl<'a, 'b, Span, N> serde::ser::Serialize for SerializableContext<'a, 'b, Span, N> | |
90 | where | |
91 | Span: Subscriber + for<'lookup> crate::registry::LookupSpan<'lookup>, | |
92 | N: for<'writer> FormatFields<'writer> + 'static, | |
93 | { | |
94 | fn serialize<Ser>(&self, serializer_o: Ser) -> Result<Ser::Ok, Ser::Error> | |
95 | where | |
96 | Ser: serde::ser::Serializer, | |
97 | { | |
98 | use serde::ser::SerializeSeq; | |
99 | let mut serializer = serializer_o.serialize_seq(None)?; | |
100 | ||
136023e0 XL |
101 | if let Some(leaf_span) = self.0.lookup_current() { |
102 | for span in leaf_span.scope().from_root() { | |
103 | serializer.serialize_element(&SerializableSpan(&span, self.1))?; | |
104 | } | |
3dfed10e XL |
105 | } |
106 | ||
107 | serializer.end() | |
108 | } | |
109 | } | |
110 | ||
111 | struct SerializableSpan<'a, 'b, Span, N>( | |
112 | &'b crate::registry::SpanRef<'a, Span>, | |
113 | std::marker::PhantomData<N>, | |
114 | ) | |
115 | where | |
116 | Span: for<'lookup> crate::registry::LookupSpan<'lookup>, | |
117 | N: for<'writer> FormatFields<'writer> + 'static; | |
118 | ||
119 | impl<'a, 'b, Span, N> serde::ser::Serialize for SerializableSpan<'a, 'b, Span, N> | |
120 | where | |
121 | Span: for<'lookup> crate::registry::LookupSpan<'lookup>, | |
122 | N: for<'writer> FormatFields<'writer> + 'static, | |
123 | { | |
124 | fn serialize<Ser>(&self, serializer: Ser) -> Result<Ser::Ok, Ser::Error> | |
125 | where | |
126 | Ser: serde::ser::Serializer, | |
127 | { | |
128 | let mut serializer = serializer.serialize_map(None)?; | |
129 | ||
130 | let ext = self.0.extensions(); | |
131 | let data = ext | |
132 | .get::<FormattedFields<N>>() | |
133 | .expect("Unable to find FormattedFields in extensions; this is a bug"); | |
134 | ||
135 | // TODO: let's _not_ do this, but this resolves | |
136 | // https://github.com/tokio-rs/tracing/issues/391. | |
137 | // We should probably rework this to use a `serde_json::Value` or something | |
138 | // similar in a JSON-specific layer, but I'd (david) | |
139 | // rather have a uglier fix now rather than shipping broken JSON. | |
140 | match serde_json::from_str::<serde_json::Value>(&data) { | |
141 | Ok(serde_json::Value::Object(fields)) => { | |
142 | for field in fields { | |
143 | serializer.serialize_entry(&field.0, &field.1)?; | |
144 | } | |
145 | } | |
146 | // We have fields for this span which are valid JSON but not an object. | |
147 | // This is probably a bug, so panic if we're in debug mode | |
148 | Ok(_) if cfg!(debug_assertions) => panic!( | |
149 | "span '{}' had malformed fields! this is a bug.\n error: invalid JSON object\n fields: {:?}", | |
150 | self.0.metadata().name(), | |
151 | data | |
152 | ), | |
153 | // If we *aren't* in debug mode, it's probably best not to | |
154 | // crash the program, let's log the field found but also an | |
155 | // message saying it's type is invalid | |
156 | Ok(value) => { | |
157 | serializer.serialize_entry("field", &value)?; | |
158 | serializer.serialize_entry("field_error", "field was no a valid object")? | |
159 | } | |
160 | // We have previously recorded fields for this span | |
161 | // should be valid JSON. However, they appear to *not* | |
162 | // be valid JSON. This is almost certainly a bug, so | |
163 | // panic if we're in debug mode | |
164 | Err(e) if cfg!(debug_assertions) => panic!( | |
165 | "span '{}' had malformed fields! this is a bug.\n error: {}\n fields: {:?}", | |
166 | self.0.metadata().name(), | |
167 | e, | |
168 | data | |
169 | ), | |
170 | // If we *aren't* in debug mode, it's probably best not | |
171 | // crash the program, but let's at least make sure it's clear | |
172 | // that the fields are not supposed to be missing. | |
173 | Err(e) => serializer.serialize_entry("field_error", &format!("{}", e))?, | |
174 | }; | |
175 | serializer.serialize_entry("name", self.0.metadata().name())?; | |
176 | serializer.end() | |
177 | } | |
f035d41b XL |
178 | } |
179 | ||
180 | impl<S, N, T> FormatEvent<S, N> for Format<Json, T> | |
181 | where | |
182 | S: Subscriber + for<'lookup> LookupSpan<'lookup>, | |
183 | N: for<'writer> FormatFields<'writer> + 'static, | |
184 | T: FormatTime, | |
185 | { | |
186 | fn format_event( | |
187 | &self, | |
188 | ctx: &FmtContext<'_, S, N>, | |
189 | writer: &mut dyn fmt::Write, | |
190 | event: &Event<'_>, | |
191 | ) -> fmt::Result | |
192 | where | |
193 | S: Subscriber + for<'a> LookupSpan<'a>, | |
194 | { | |
f035d41b XL |
195 | let mut timestamp = String::new(); |
196 | self.timer.format_time(&mut timestamp)?; | |
197 | ||
198 | #[cfg(feature = "tracing-log")] | |
199 | let normalized_meta = event.normalized_metadata(); | |
200 | #[cfg(feature = "tracing-log")] | |
201 | let meta = normalized_meta.as_ref().unwrap_or_else(|| event.metadata()); | |
202 | #[cfg(not(feature = "tracing-log"))] | |
203 | let meta = event.metadata(); | |
204 | ||
f035d41b XL |
205 | let mut visit = || { |
206 | let mut serializer = Serializer::new(WriteAdaptor::new(writer)); | |
207 | ||
208 | let mut serializer = serializer.serialize_map(None)?; | |
209 | ||
210 | serializer.serialize_entry("timestamp", ×tamp)?; | |
211 | serializer.serialize_entry("level", &meta.level().as_serde())?; | |
212 | ||
3dfed10e XL |
213 | let format_field_marker: std::marker::PhantomData<N> = std::marker::PhantomData; |
214 | ||
215 | let current_span = if self.format.display_current_span || self.format.display_span_list | |
216 | { | |
17df50a5 XL |
217 | event |
218 | .parent() | |
219 | .and_then(|id| ctx.span(id)) | |
220 | .or_else(|| ctx.lookup_current()) | |
3dfed10e XL |
221 | } else { |
222 | None | |
223 | }; | |
224 | ||
29967ef6 XL |
225 | if self.format.flatten_event { |
226 | let mut visitor = tracing_serde::SerdeMapVisitor::new(serializer); | |
227 | event.record(&mut visitor); | |
228 | ||
229 | serializer = visitor.take_serializer()?; | |
230 | } else { | |
231 | use tracing_serde::fields::AsMap; | |
232 | serializer.serialize_entry("fields", &event.field_map())?; | |
233 | }; | |
234 | ||
235 | if self.display_target { | |
236 | serializer.serialize_entry("target", meta.target())?; | |
3dfed10e XL |
237 | } |
238 | ||
239 | if self.format.display_current_span { | |
29967ef6 | 240 | if let Some(ref span) = current_span { |
3dfed10e | 241 | serializer |
29967ef6 | 242 | .serialize_entry("span", &SerializableSpan(span, format_field_marker)) |
3dfed10e | 243 | .unwrap_or(()); |
f035d41b XL |
244 | } |
245 | } | |
246 | ||
29967ef6 XL |
247 | if self.format.display_span_list && current_span.is_some() { |
248 | serializer.serialize_entry( | |
249 | "spans", | |
250 | &SerializableContext(&ctx.ctx, format_field_marker), | |
251 | )?; | |
f035d41b XL |
252 | } |
253 | ||
3dfed10e XL |
254 | if self.display_thread_name { |
255 | let current_thread = std::thread::current(); | |
256 | match current_thread.name() { | |
257 | Some(name) => { | |
258 | serializer.serialize_entry("threadName", name)?; | |
259 | } | |
260 | // fall-back to thread id when name is absent and ids are not enabled | |
261 | None if !self.display_thread_id => { | |
262 | serializer | |
263 | .serialize_entry("threadName", &format!("{:?}", current_thread.id()))?; | |
264 | } | |
265 | _ => {} | |
266 | } | |
267 | } | |
268 | ||
269 | if self.display_thread_id { | |
270 | serializer | |
271 | .serialize_entry("threadId", &format!("{:?}", std::thread::current().id()))?; | |
272 | } | |
273 | ||
29967ef6 | 274 | serializer.end() |
f035d41b XL |
275 | }; |
276 | ||
277 | visit().map_err(|_| fmt::Error)?; | |
278 | writeln!(writer) | |
279 | } | |
280 | } | |
281 | ||
282 | impl Default for Json { | |
283 | fn default() -> Json { | |
284 | Json { | |
285 | flatten_event: false, | |
3dfed10e XL |
286 | display_current_span: true, |
287 | display_span_list: true, | |
f035d41b XL |
288 | } |
289 | } | |
290 | } | |
291 | ||
292 | /// The JSON [`FormatFields`] implementation. | |
293 | /// | |
294 | /// [`FormatFields`]: trait.FormatFields.html | |
295 | #[derive(Debug)] | |
296 | pub struct JsonFields { | |
297 | // reserve the ability to add fields to this without causing a breaking | |
298 | // change in the future. | |
299 | _private: (), | |
300 | } | |
301 | ||
302 | impl JsonFields { | |
303 | /// Returns a new JSON [`FormatFields`] implementation. | |
304 | /// | |
305 | /// [`FormatFields`]: trait.FormatFields.html | |
306 | pub fn new() -> Self { | |
307 | Self { _private: () } | |
308 | } | |
309 | } | |
310 | ||
311 | impl Default for JsonFields { | |
312 | fn default() -> Self { | |
313 | Self::new() | |
314 | } | |
315 | } | |
316 | ||
317 | impl<'a> FormatFields<'a> for JsonFields { | |
318 | /// Format the provided `fields` to the provided `writer`, returning a result. | |
319 | fn format_fields<R: RecordFields>( | |
320 | &self, | |
321 | writer: &'a mut dyn fmt::Write, | |
322 | fields: R, | |
323 | ) -> fmt::Result { | |
324 | let mut v = JsonVisitor::new(writer); | |
325 | fields.record(&mut v); | |
326 | v.finish() | |
327 | } | |
328 | ||
329 | /// Record additional field(s) on an existing span. | |
330 | /// | |
331 | /// By default, this appends a space to the current set of fields if it is | |
332 | /// non-empty, and then calls `self.format_fields`. If different behavior is | |
333 | /// required, the default implementation of this method can be overridden. | |
334 | fn add_fields(&self, current: &'a mut String, fields: &Record<'_>) -> fmt::Result { | |
335 | if !current.is_empty() { | |
336 | // If fields were previously recorded on this span, we need to parse | |
337 | // the current set of fields as JSON, add the new fields, and | |
338 | // re-serialize them. Otherwise, if we just appended the new fields | |
339 | // to a previously serialized JSON object, we would end up with | |
340 | // malformed JSON. | |
341 | // | |
342 | // XXX(eliza): this is far from efficient, but unfortunately, it is | |
343 | // necessary as long as the JSON formatter is implemented on top of | |
344 | // an interface that stores all formatted fields as strings. | |
345 | // | |
346 | // We should consider reimplementing the JSON formatter as a | |
347 | // separate layer, rather than a formatter for the `fmt` layer — | |
348 | // then, we could store fields as JSON values, and add to them | |
349 | // without having to parse and re-serialize. | |
350 | let mut new = String::new(); | |
351 | let map: BTreeMap<&'_ str, serde_json::Value> = | |
352 | serde_json::from_str(current).map_err(|_| fmt::Error)?; | |
353 | let mut v = JsonVisitor::new(&mut new); | |
354 | v.values = map; | |
355 | fields.record(&mut v); | |
356 | v.finish()?; | |
357 | *current = new; | |
358 | } else { | |
359 | // If there are no previously recorded fields, we can just reuse the | |
360 | // existing string. | |
361 | let mut v = JsonVisitor::new(current); | |
362 | fields.record(&mut v); | |
363 | v.finish()?; | |
364 | } | |
365 | ||
366 | Ok(()) | |
367 | } | |
368 | } | |
369 | ||
370 | /// The [visitor] produced by [`JsonFields`]'s [`MakeVisitor`] implementation. | |
371 | /// | |
372 | /// [visitor]: ../../field/trait.Visit.html | |
373 | /// [`JsonFields`]: struct.JsonFields.html | |
374 | /// [`MakeVisitor`]: ../../field/trait.MakeVisitor.html | |
375 | pub struct JsonVisitor<'a> { | |
376 | values: BTreeMap<&'a str, serde_json::Value>, | |
377 | writer: &'a mut dyn Write, | |
378 | } | |
379 | ||
380 | impl<'a> fmt::Debug for JsonVisitor<'a> { | |
381 | fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { | |
382 | f.write_fmt(format_args!("JsonVisitor {{ values: {:?} }}", self.values)) | |
383 | } | |
384 | } | |
385 | ||
386 | impl<'a> JsonVisitor<'a> { | |
387 | /// Returns a new default visitor that formats to the provided `writer`. | |
388 | /// | |
389 | /// # Arguments | |
390 | /// - `writer`: the writer to format to. | |
391 | /// - `is_empty`: whether or not any fields have been previously written to | |
392 | /// that writer. | |
393 | pub fn new(writer: &'a mut dyn Write) -> Self { | |
394 | Self { | |
395 | values: BTreeMap::new(), | |
396 | writer, | |
397 | } | |
398 | } | |
399 | } | |
400 | ||
401 | impl<'a> crate::field::VisitFmt for JsonVisitor<'a> { | |
402 | fn writer(&mut self) -> &mut dyn fmt::Write { | |
403 | self.writer | |
404 | } | |
405 | } | |
406 | ||
407 | impl<'a> crate::field::VisitOutput<fmt::Result> for JsonVisitor<'a> { | |
408 | fn finish(self) -> fmt::Result { | |
409 | let inner = || { | |
410 | let mut serializer = Serializer::new(WriteAdaptor::new(self.writer)); | |
411 | let mut ser_map = serializer.serialize_map(None)?; | |
412 | ||
413 | for (k, v) in self.values { | |
414 | ser_map.serialize_entry(k, &v)?; | |
415 | } | |
416 | ||
417 | ser_map.end() | |
418 | }; | |
419 | ||
420 | if inner().is_err() { | |
421 | Err(fmt::Error) | |
422 | } else { | |
423 | Ok(()) | |
424 | } | |
425 | } | |
426 | } | |
427 | ||
428 | impl<'a> field::Visit for JsonVisitor<'a> { | |
429 | /// Visit a signed 64-bit integer value. | |
430 | fn record_i64(&mut self, field: &Field, value: i64) { | |
431 | self.values | |
432 | .insert(&field.name(), serde_json::Value::from(value)); | |
433 | } | |
434 | ||
435 | /// Visit an unsigned 64-bit integer value. | |
436 | fn record_u64(&mut self, field: &Field, value: u64) { | |
437 | self.values | |
438 | .insert(&field.name(), serde_json::Value::from(value)); | |
439 | } | |
440 | ||
441 | /// Visit a boolean value. | |
442 | fn record_bool(&mut self, field: &Field, value: bool) { | |
443 | self.values | |
444 | .insert(&field.name(), serde_json::Value::from(value)); | |
445 | } | |
446 | ||
447 | /// Visit a string value. | |
448 | fn record_str(&mut self, field: &Field, value: &str) { | |
449 | self.values | |
450 | .insert(&field.name(), serde_json::Value::from(value)); | |
451 | } | |
452 | ||
453 | fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) { | |
454 | match field.name() { | |
455 | // Skip fields that are actually log metadata that have already been handled | |
456 | #[cfg(feature = "tracing-log")] | |
457 | name if name.starts_with("log.") => (), | |
458 | name if name.starts_with("r#") => { | |
459 | self.values | |
460 | .insert(&name[2..], serde_json::Value::from(format!("{:?}", value))); | |
461 | } | |
462 | name => { | |
463 | self.values | |
464 | .insert(name, serde_json::Value::from(format!("{:?}", value))); | |
465 | } | |
466 | }; | |
467 | } | |
468 | } | |
469 | ||
470 | /// A bridge between `fmt::Write` and `io::Write`. | |
471 | /// | |
472 | /// This is needed because tracing-subscriber's FormatEvent expects a fmt::Write | |
473 | /// while serde_json's Serializer expects an io::Write. | |
474 | struct WriteAdaptor<'a> { | |
475 | fmt_write: &'a mut dyn fmt::Write, | |
476 | } | |
477 | ||
478 | impl<'a> WriteAdaptor<'a> { | |
479 | fn new(fmt_write: &'a mut dyn fmt::Write) -> Self { | |
480 | Self { fmt_write } | |
481 | } | |
482 | } | |
483 | ||
484 | impl<'a> io::Write for WriteAdaptor<'a> { | |
485 | fn write(&mut self, buf: &[u8]) -> io::Result<usize> { | |
486 | let s = | |
487 | std::str::from_utf8(buf).map_err(|e| io::Error::new(io::ErrorKind::InvalidData, e))?; | |
488 | ||
489 | self.fmt_write | |
490 | .write_str(&s) | |
491 | .map_err(|e| io::Error::new(io::ErrorKind::Other, e))?; | |
492 | ||
493 | Ok(s.as_bytes().len()) | |
494 | } | |
495 | ||
496 | fn flush(&mut self) -> io::Result<()> { | |
497 | Ok(()) | |
498 | } | |
499 | } | |
500 | ||
501 | impl<'a> fmt::Debug for WriteAdaptor<'a> { | |
502 | fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { | |
503 | f.pad("WriteAdaptor { .. }") | |
504 | } | |
505 | } | |
506 | ||
507 | #[cfg(test)] | |
508 | mod test { | |
17df50a5 XL |
509 | use super::*; |
510 | use crate::fmt::{format::FmtSpan, test::MockMakeWriter, time::FormatTime, SubscriberBuilder}; | |
f035d41b | 511 | use lazy_static::lazy_static; |
f035d41b | 512 | use std::{fmt, sync::Mutex}; |
17df50a5 | 513 | use tracing::{self, subscriber::with_default}; |
f035d41b XL |
514 | |
515 | struct MockTime; | |
516 | impl FormatTime for MockTime { | |
517 | fn format_time(&self, w: &mut dyn fmt::Write) -> fmt::Result { | |
518 | write!(w, "fake time") | |
519 | } | |
520 | } | |
521 | ||
17df50a5 XL |
522 | fn subscriber() -> SubscriberBuilder<JsonFields, Format<Json>> { |
523 | SubscriberBuilder::default().json() | |
524 | } | |
525 | ||
f035d41b XL |
526 | #[test] |
527 | fn json() { | |
528 | lazy_static! { | |
17df50a5 | 529 | static ref BUF: Mutex<Vec<u8>> = Mutex::new(Vec::new()); |
f035d41b XL |
530 | } |
531 | ||
f035d41b | 532 | let expected = |
3dfed10e | 533 | "{\"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"; |
17df50a5 XL |
534 | let subscriber = subscriber() |
535 | .flatten_event(false) | |
536 | .with_current_span(true) | |
537 | .with_span_list(true); | |
538 | test_json(expected, subscriber, &BUF, || { | |
3dfed10e XL |
539 | let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3); |
540 | let _guard = span.enter(); | |
541 | tracing::info!("some json test"); | |
542 | }); | |
f035d41b XL |
543 | } |
544 | ||
545 | #[test] | |
546 | fn json_flattened_event() { | |
547 | lazy_static! { | |
17df50a5 | 548 | static ref BUF: Mutex<Vec<u8>> = Mutex::new(Vec::new()); |
f035d41b XL |
549 | } |
550 | ||
f035d41b | 551 | let expected = |
3dfed10e | 552 | "{\"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"; |
17df50a5 XL |
553 | let subscriber = subscriber() |
554 | .flatten_event(true) | |
555 | .with_current_span(true) | |
556 | .with_span_list(true); | |
557 | test_json(expected, subscriber, &BUF, || { | |
3dfed10e XL |
558 | let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3); |
559 | let _guard = span.enter(); | |
560 | tracing::info!("some json test"); | |
561 | }); | |
562 | } | |
563 | ||
564 | #[test] | |
565 | fn json_disabled_current_span_event() { | |
566 | lazy_static! { | |
17df50a5 | 567 | static ref BUF: Mutex<Vec<u8>> = Mutex::new(Vec::new()); |
3dfed10e XL |
568 | } |
569 | ||
3dfed10e XL |
570 | let expected = |
571 | "{\"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"; | |
17df50a5 XL |
572 | let subscriber = subscriber() |
573 | .flatten_event(false) | |
574 | .with_current_span(false) | |
575 | .with_span_list(true); | |
576 | test_json(expected, subscriber, &BUF, || { | |
3dfed10e XL |
577 | let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3); |
578 | let _guard = span.enter(); | |
579 | tracing::info!("some json test"); | |
580 | }); | |
581 | } | |
582 | ||
583 | #[test] | |
584 | fn json_disabled_span_list_event() { | |
585 | lazy_static! { | |
17df50a5 | 586 | static ref BUF: Mutex<Vec<u8>> = Mutex::new(Vec::new()); |
3dfed10e XL |
587 | } |
588 | ||
3dfed10e XL |
589 | let expected = |
590 | "{\"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"; | |
17df50a5 XL |
591 | let subscriber = subscriber() |
592 | .flatten_event(false) | |
593 | .with_current_span(true) | |
594 | .with_span_list(false); | |
595 | test_json(expected, subscriber, &BUF, || { | |
3dfed10e XL |
596 | let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3); |
597 | let _guard = span.enter(); | |
598 | tracing::info!("some json test"); | |
599 | }); | |
600 | } | |
601 | ||
602 | #[test] | |
603 | fn json_nested_span() { | |
604 | lazy_static! { | |
17df50a5 | 605 | static ref BUF: Mutex<Vec<u8>> = Mutex::new(Vec::new()); |
3dfed10e XL |
606 | } |
607 | ||
3dfed10e XL |
608 | let expected = |
609 | "{\"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"; | |
17df50a5 XL |
610 | let subscriber = subscriber() |
611 | .flatten_event(false) | |
612 | .with_current_span(true) | |
613 | .with_span_list(true); | |
614 | test_json(expected, subscriber, &BUF, || { | |
3dfed10e XL |
615 | let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3); |
616 | let _guard = span.enter(); | |
617 | let span = tracing::span!( | |
618 | tracing::Level::INFO, | |
619 | "nested_json_span", | |
620 | answer = 43, | |
621 | number = 4 | |
622 | ); | |
623 | let _guard = span.enter(); | |
624 | tracing::info!("some json test"); | |
625 | }); | |
626 | } | |
627 | ||
628 | #[test] | |
629 | fn json_no_span() { | |
630 | lazy_static! { | |
17df50a5 | 631 | static ref BUF: Mutex<Vec<u8>> = Mutex::new(Vec::new()); |
3dfed10e XL |
632 | } |
633 | ||
3dfed10e XL |
634 | let expected = |
635 | "{\"timestamp\":\"fake time\",\"level\":\"INFO\",\"target\":\"tracing_subscriber::fmt::format::json::test\",\"fields\":{\"message\":\"some json test\"}}\n"; | |
17df50a5 XL |
636 | let subscriber = subscriber() |
637 | .flatten_event(false) | |
638 | .with_current_span(true) | |
639 | .with_span_list(true); | |
640 | test_json(expected, subscriber, &BUF, || { | |
3dfed10e XL |
641 | tracing::info!("some json test"); |
642 | }); | |
f035d41b XL |
643 | } |
644 | ||
645 | #[test] | |
646 | fn record_works() { | |
647 | // This test reproduces issue #707, where using `Span::record` causes | |
648 | // any events inside the span to be ignored. | |
649 | lazy_static! { | |
17df50a5 | 650 | static ref BUF: Mutex<Vec<u8>> = Mutex::new(Vec::new()); |
f035d41b XL |
651 | } |
652 | ||
17df50a5 XL |
653 | let buffer = MockMakeWriter::new(&BUF); |
654 | let subscriber = crate::fmt().json().with_writer(buffer.clone()).finish(); | |
f035d41b XL |
655 | |
656 | with_default(subscriber, || { | |
657 | tracing::info!("an event outside the root span"); | |
658 | assert_eq!( | |
17df50a5 | 659 | parse_as_json(&buffer)["fields"]["message"], |
f035d41b XL |
660 | "an event outside the root span" |
661 | ); | |
662 | ||
663 | let span = tracing::info_span!("the span", na = tracing::field::Empty); | |
664 | span.record("na", &"value"); | |
665 | let _enter = span.enter(); | |
666 | ||
667 | tracing::info!("an event inside the root span"); | |
668 | assert_eq!( | |
17df50a5 | 669 | parse_as_json(&buffer)["fields"]["message"], |
f035d41b XL |
670 | "an event inside the root span" |
671 | ); | |
672 | }); | |
673 | } | |
674 | ||
17df50a5 XL |
675 | #[test] |
676 | fn json_span_event_show_correct_context() { | |
677 | lazy_static! { | |
678 | static ref BUF: Mutex<Vec<u8>> = Mutex::new(Vec::new()); | |
679 | } | |
680 | ||
681 | let buffer = MockMakeWriter::new(&BUF); | |
682 | let subscriber = subscriber() | |
683 | .with_writer(buffer.clone()) | |
684 | .flatten_event(false) | |
685 | .with_current_span(true) | |
686 | .with_span_list(false) | |
687 | .with_span_events(FmtSpan::FULL) | |
688 | .finish(); | |
689 | ||
690 | with_default(subscriber, || { | |
691 | let context = "parent"; | |
692 | let parent_span = tracing::info_span!("parent_span", context); | |
693 | ||
694 | let event = parse_as_json(&buffer); | |
695 | assert_eq!(event["fields"]["message"], "new"); | |
696 | assert_eq!(event["span"]["context"], "parent"); | |
697 | ||
698 | let _parent_enter = parent_span.enter(); | |
699 | let event = parse_as_json(&buffer); | |
700 | assert_eq!(event["fields"]["message"], "enter"); | |
701 | assert_eq!(event["span"]["context"], "parent"); | |
702 | ||
703 | let context = "child"; | |
704 | let child_span = tracing::info_span!("child_span", context); | |
705 | let event = parse_as_json(&buffer); | |
706 | assert_eq!(event["fields"]["message"], "new"); | |
707 | assert_eq!(event["span"]["context"], "child"); | |
708 | ||
709 | let _child_enter = child_span.enter(); | |
710 | let event = parse_as_json(&buffer); | |
711 | assert_eq!(event["fields"]["message"], "enter"); | |
712 | assert_eq!(event["span"]["context"], "child"); | |
713 | ||
714 | drop(_child_enter); | |
715 | let event = parse_as_json(&buffer); | |
716 | assert_eq!(event["fields"]["message"], "exit"); | |
717 | assert_eq!(event["span"]["context"], "child"); | |
718 | ||
719 | drop(child_span); | |
720 | let event = parse_as_json(&buffer); | |
721 | assert_eq!(event["fields"]["message"], "close"); | |
722 | assert_eq!(event["span"]["context"], "child"); | |
723 | ||
724 | drop(_parent_enter); | |
725 | let event = parse_as_json(&buffer); | |
726 | assert_eq!(event["fields"]["message"], "exit"); | |
727 | assert_eq!(event["span"]["context"], "parent"); | |
728 | ||
729 | drop(parent_span); | |
730 | let event = parse_as_json(&buffer); | |
731 | assert_eq!(event["fields"]["message"], "close"); | |
732 | assert_eq!(event["span"]["context"], "parent"); | |
733 | }); | |
734 | } | |
735 | ||
736 | #[test] | |
737 | fn json_span_event_with_no_fields() { | |
738 | // Check span events serialize correctly. | |
739 | // Discussion: https://github.com/tokio-rs/tracing/issues/829#issuecomment-661984255 | |
740 | lazy_static! { | |
741 | static ref BUF: Mutex<Vec<u8>> = Mutex::new(Vec::new()); | |
742 | } | |
743 | ||
744 | let buffer = MockMakeWriter::new(&BUF); | |
745 | let subscriber = subscriber() | |
746 | .with_writer(buffer.clone()) | |
747 | .flatten_event(false) | |
748 | .with_current_span(false) | |
749 | .with_span_list(false) | |
750 | .with_span_events(FmtSpan::FULL) | |
751 | .finish(); | |
752 | ||
753 | with_default(subscriber, || { | |
754 | let span = tracing::info_span!("valid_json"); | |
755 | assert_eq!(parse_as_json(&buffer)["fields"]["message"], "new"); | |
756 | ||
757 | let _enter = span.enter(); | |
758 | assert_eq!(parse_as_json(&buffer)["fields"]["message"], "enter"); | |
759 | ||
760 | drop(_enter); | |
761 | assert_eq!(parse_as_json(&buffer)["fields"]["message"], "exit"); | |
762 | ||
763 | drop(span); | |
764 | assert_eq!(parse_as_json(&buffer)["fields"]["message"], "close"); | |
765 | }); | |
766 | } | |
767 | ||
768 | fn parse_as_json(buffer: &MockMakeWriter<'_>) -> serde_json::Value { | |
769 | let buf = String::from_utf8(buffer.buf().to_vec()).unwrap(); | |
770 | let json = buf | |
771 | .lines() | |
772 | .last() | |
773 | .expect("expected at least one line to be written!"); | |
774 | match serde_json::from_str(&json) { | |
775 | Ok(v) => v, | |
776 | Err(e) => panic!( | |
777 | "assertion failed: JSON shouldn't be malformed\n error: {}\n json: {}", | |
778 | e, json | |
779 | ), | |
780 | } | |
781 | } | |
782 | ||
783 | fn test_json<T>( | |
3dfed10e | 784 | expected: &str, |
17df50a5 XL |
785 | builder: crate::fmt::SubscriberBuilder<JsonFields, Format<Json>>, |
786 | buf: &'static Mutex<Vec<u8>>, | |
787 | producer: impl FnOnce() -> T, | |
788 | ) { | |
789 | let make_writer = MockMakeWriter::new(&buf); | |
790 | let subscriber = builder | |
791 | .with_writer(make_writer.clone()) | |
f035d41b XL |
792 | .with_timer(MockTime) |
793 | .finish(); | |
794 | ||
3dfed10e | 795 | with_default(subscriber, producer); |
f035d41b | 796 | |
17df50a5 XL |
797 | let buf = make_writer.buf(); |
798 | let actual = std::str::from_utf8(&buf[..]).unwrap(); | |
3dfed10e XL |
799 | assert_eq!( |
800 | serde_json::from_str::<std::collections::HashMap<&str, serde_json::Value>>(expected) | |
801 | .unwrap(), | |
17df50a5 | 802 | serde_json::from_str(actual).unwrap() |
3dfed10e | 803 | ); |
f035d41b XL |
804 | } |
805 | } |