1use serde_json::{Map, Value};
55use time::format_description::well_known::Iso8601;
56use time::formatting::Formattable;
57use time::OffsetDateTime;
58use tracing::level_filters::LevelFilter;
59use tracing::span::{Attributes, Record};
60use tracing::{Event, Id, Metadata, Subscriber};
61use tracing_subscriber::layer;
62use tracing_subscriber::layer::Context;
63#[allow(unused_imports)]
64use tracing_subscriber::prelude::*;
65use tracing_subscriber::registry::LookupSpan;
66
67#[derive(Debug)]
68struct CustomFieldStorage(Map<String, Value>);
69
70pub trait JsonOutput {
74 fn write(&self, value: Value);
75}
76
77#[derive(Default)]
79pub struct JsonStdout {
80 pretty: bool,
81}
82
83impl JsonOutput for JsonStdout {
84 fn write(&self, value: Value) {
85 println!(
86 "{}",
87 if self.pretty {
88 serde_json::to_string_pretty(&value).unwrap()
89 } else {
90 serde_json::to_string(&value).unwrap()
91 }
92 );
93 }
94}
95
96pub struct JsonLayer<O = JsonStdout, F = Iso8601> {
99 output: O,
100 timestamp_format: F,
101 max_level: LevelFilter,
102}
103
104impl Default for JsonLayer {
105 fn default() -> Self {
106 JsonLayer {
107 output: JsonStdout::default(),
108 timestamp_format: Iso8601::DEFAULT,
109 max_level: LevelFilter::INFO,
110 }
111 }
112}
113
114impl JsonLayer<JsonStdout, Iso8601> {
115 pub fn pretty() -> JsonLayer<JsonStdout, Iso8601> {
116 JsonLayer::default().with_output(JsonStdout { pretty: true })
117 }
118}
119
120impl<O, F> JsonLayer<O, F>
121where
122 F: Formattable,
123 O: JsonOutput,
124{
125 pub fn with_output<O2>(self, output: O2) -> JsonLayer<O2, F>
126 where
127 O2: JsonOutput,
128 {
129 JsonLayer {
130 output,
131 timestamp_format: self.timestamp_format,
132 max_level: self.max_level,
133 }
134 }
135
136 pub fn with_timestamp_format<F2>(self, timestamp_format: F2) -> JsonLayer<O, F2>
137 where
138 F2: Formattable,
139 {
140 JsonLayer {
141 output: self.output,
142 timestamp_format,
143 max_level: self.max_level,
144 }
145 }
146
147 pub fn with_level(self, max_level: LevelFilter) -> JsonLayer<O, F> {
148 JsonLayer {
149 output: self.output,
150 timestamp_format: self.timestamp_format,
151 max_level,
152 }
153 }
154}
155
156impl<S, O, F> layer::Layer<S> for JsonLayer<O, F>
157where
158 S: Subscriber + for<'a> LookupSpan<'a>,
159 O: JsonOutput + 'static,
160 F: Formattable + 'static,
161{
162 fn enabled(&self, metadata: &Metadata<'_>, _ctx: Context<'_, S>) -> bool {
163 metadata.level() <= &self.max_level
164 }
165
166 fn on_new_span(&self, attrs: &Attributes<'_>, id: &Id, ctx: Context<'_, S>) {
167 let mut fields = Map::new();
169 let mut visitor = JsonVisitor(&mut fields);
170 attrs.record(&mut visitor);
171
172 let storage = CustomFieldStorage(fields);
174
175 let span = ctx.span(id).unwrap();
177 let mut extensions = span.extensions_mut();
179 extensions.insert::<CustomFieldStorage>(storage);
181 }
182
183 fn max_level_hint(&self) -> Option<LevelFilter> {
184 Some(self.max_level)
185 }
186
187 fn on_record(&self, id: &Id, values: &Record<'_>, ctx: Context<'_, S>) {
188 let span = ctx.span(id).unwrap();
190
191 let mut extensions_mut = span.extensions_mut();
193 let custom_field_storage: &mut CustomFieldStorage =
194 extensions_mut.get_mut::<CustomFieldStorage>().unwrap();
195 let json_data: &mut Map<String, Value> = &mut custom_field_storage.0;
196
197 let mut visitor = JsonVisitor(json_data);
199 values.record(&mut visitor);
200 }
201
202 fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) {
203 let mut fields = Map::new();
204
205 if let Some(scope) = ctx.event_scope(event) {
207 for span in scope.from_root() {
208 let extensions = span.extensions();
209 let storage = extensions.get::<CustomFieldStorage>().unwrap();
210 let field_data: &Map<String, Value> = &storage.0;
211
212 for (key, value) in field_data {
213 fields.insert(key.clone(), value.clone());
214 }
215 }
216 }
217
218 let mut visitor = JsonVisitor(&mut fields);
220 event.record(&mut visitor);
221
222 fields.insert("target".to_string(), event.metadata().target().into());
224 fields.insert("name".to_string(), event.metadata().name().into());
225 fields.insert(
226 "log_level".to_string(),
227 event.metadata().level().as_str().into(),
228 );
229 fields.insert(
230 "timestamp".to_string(),
231 OffsetDateTime::now_utc()
232 .format(&self.timestamp_format)
233 .unwrap()
234 .into(),
235 );
236
237 let output = fields.into();
239
240 self.output.write(output);
241 }
242}
243
244struct JsonVisitor<'a>(&'a mut Map<String, Value>);
245
246impl<'a> tracing::field::Visit for JsonVisitor<'a> {
247 fn record_f64(&mut self, field: &tracing::field::Field, value: f64) {
248 self.0
249 .insert(field.name().to_string(), serde_json::json!(value));
250 }
251
252 fn record_i64(&mut self, field: &tracing::field::Field, value: i64) {
253 self.0
254 .insert(field.name().to_string(), serde_json::json!(value));
255 }
256
257 fn record_u64(&mut self, field: &tracing::field::Field, value: u64) {
258 self.0
259 .insert(field.name().to_string(), serde_json::json!(value));
260 }
261
262 fn record_bool(&mut self, field: &tracing::field::Field, value: bool) {
263 self.0
264 .insert(field.name().to_string(), serde_json::json!(value));
265 }
266
267 fn record_str(&mut self, field: &tracing::field::Field, value: &str) {
268 self.0
269 .insert(field.name().to_string(), serde_json::json!(value));
270 }
271
272 fn record_error(
273 &mut self,
274 field: &tracing::field::Field,
275 value: &(dyn std::error::Error + 'static),
276 ) {
277 self.0.insert(
278 field.name().to_string(),
279 serde_json::json!(value.to_string()),
280 );
281 }
282
283 fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn std::fmt::Debug) {
284 self.0.insert(
285 field.name().to_string(),
286 serde_json::json!(format!("{:?}", value)),
287 );
288 }
289}
290
291#[cfg(test)]
292mod tests {
293 use super::*;
294 use std::sync::{Arc, Mutex};
295 use std::time::Duration;
296 use time::macros::format_description;
297 use time::parsing::Parsable;
298 use time::PrimitiveDateTime;
299 use tracing::field;
300 use tracing::subscriber::with_default;
301 use tracing_subscriber::Registry;
302
303 fn assert_json_timestamp_name(
305 expected: Value,
306 name_value_prefix: &str,
307 before: &OffsetDateTime,
308 value: &mut Value,
309 ) {
310 assert_json_timestamp_name_with_format(
311 expected,
312 name_value_prefix,
313 before,
314 value,
315 &Iso8601::DEFAULT,
316 )
317 }
318
319 fn assert_json_timestamp_name_with_format(
321 expected: Value,
322 name_value_prefix: &str,
323 before: &OffsetDateTime,
324 value: &mut Value,
325 timestamp_format: &(impl Parsable + ?Sized),
326 ) {
327 let map = value.as_object_mut().unwrap();
328 assert!(map.contains_key("name"));
329 assert!(map
330 .remove("name")
331 .expect("should contain field 'name'")
332 .as_str()
333 .expect("field 'name' should be a string")
334 .starts_with(name_value_prefix));
335
336 assert!(map.contains_key("timestamp"));
337 let timestamp = map
338 .remove("timestamp")
339 .expect("should contain field 'timestamp'")
340 .as_str()
341 .expect("field 'timestamp' should be a string")
342 .to_string();
343 let parsed = PrimitiveDateTime::parse(×tamp, timestamp_format)
344 .expect("timestamp should be parseable")
345 .assume_utc();
346 assert!(
347 (parsed + Duration::from_millis(1)).ge(before),
348 "timestamp ({}) must not be before {}",
349 timestamp,
350 before
351 );
352 let now = &OffsetDateTime::now_utc();
353 assert!(
354 parsed.le(now),
355 "timestamp ({}) must not be after {}",
356 timestamp,
357 now
358 );
359
360 assert_eq!(expected, *value)
361 }
362
363 struct TestOutput {
364 data: Arc<Mutex<Vec<Value>>>,
365 }
366
367 impl JsonOutput for TestOutput {
368 fn write(&self, value: Value) {
369 let mut data = self.data.lock().unwrap();
370 (*data).push(value);
371 }
372 }
373
374 #[test]
375 fn one_span_some_fields() {
376 tracing_subscriber::fmt().pretty().init();
377
378 let data = Arc::new(Mutex::new(vec![]));
379 let layer = JsonLayer::default().with_output(TestOutput { data: data.clone() });
380
381 let subscriber = Registry::default().with(layer);
382
383 tracing::info!("BEFORE");
384
385 let before = OffsetDateTime::now_utc();
386
387 with_default(subscriber, || {
388 let _span1 = tracing::info_span!("Top level", field_top = 0).entered();
389 tracing::info!(field_event = "from event", "FOOBAR");
390 tracing::error!("BAZ");
391 });
392
393 tracing::info!("AFTER");
394
395 let mut data = data.lock().unwrap();
396 let mut iter = (*data).iter_mut();
397
398 assert_json_timestamp_name(
399 serde_json::json!({
400 "target": "tracing_json_span_fields::tests",
401 "log_level": "INFO",
402 "message": "FOOBAR",
403 "field_top": 0,
404 "field_event": "from event"
405 }),
406 "event src/lib.rs:",
407 &before,
408 iter.next().unwrap(),
409 );
410 assert_json_timestamp_name(
411 serde_json::json!({
412 "target": "tracing_json_span_fields::tests",
413 "log_level": "ERROR",
414 "message": "BAZ",
415 "field_top": 0,
416 }),
417 "event src/lib.rs:",
418 &before,
419 iter.next().unwrap(),
420 );
421 assert_eq!(None, iter.next(), "No more logged events");
422 }
423
424 #[test]
425 fn two_spans_different_fields() {
426 let data = Arc::new(Mutex::new(vec![]));
427 let layer = JsonLayer::default().with_output(TestOutput { data: data.clone() });
428
429 let subscriber = Registry::default().with(layer);
430
431 let before = OffsetDateTime::now_utc();
432
433 with_default(subscriber, || {
434 let _span1 = tracing::info_span!("Top level", field_top = 0).entered();
435 let _span2 = tracing::info_span!("Second level", field_second = 1).entered();
436 tracing::info!(field_event = "from event", "FOOBAR");
437 });
438
439 let mut data = data.lock().unwrap();
440 let mut iter = (*data).iter_mut();
441
442 assert_json_timestamp_name(
443 serde_json::json!({
444 "target": "tracing_json_span_fields::tests",
445 "log_level": "INFO",
446 "message": "FOOBAR",
447 "field_top": 0,
448 "field_second": 1,
449 "field_event": "from event"
450 }),
451 "event src/lib.rs:",
452 &before,
453 iter.next().unwrap(),
454 );
455 assert_eq!(None, iter.next(), "No more logged events");
456 }
457
458 #[test]
459 fn two_spans_same_fields() {
460 let data = Arc::new(Mutex::new(vec![]));
461 let layer = JsonLayer::default().with_output(TestOutput { data: data.clone() });
462
463 let subscriber = Registry::default().with(layer);
464
465 let before = OffsetDateTime::now_utc();
466
467 with_default(subscriber, || {
468 let _span1 = tracing::info_span!("Top level", field_overwrite = 0).entered();
469 let _span2 = tracing::info_span!("Second level", field_overwrite = 1).entered();
470 tracing::info!(field_event = "from event", "FOOBAR");
471 });
472
473 let mut data = data.lock().unwrap();
474 let mut iter = (*data).iter_mut();
475
476 assert_json_timestamp_name(
477 serde_json::json!({
478 "target": "tracing_json_span_fields::tests",
479 "log_level": "INFO",
480 "message": "FOOBAR",
481 "field_overwrite": 1,
482 "field_event": "from event"
483 }),
484 "event src/lib.rs:",
485 &before,
486 iter.next().unwrap(),
487 );
488 assert_eq!(None, iter.next(), "No more logged events");
489 }
490
491 #[test]
492 fn two_spans_same_fields_including_event() {
493 let data = Arc::new(Mutex::new(vec![]));
494 let layer = JsonLayer::default().with_output(TestOutput { data: data.clone() });
495
496 let subscriber = Registry::default().with(layer);
497
498 let before = OffsetDateTime::now_utc();
499
500 with_default(subscriber, || {
501 let _span1 = tracing::info_span!("Top level", field_overwrite = 0).entered();
502 let _span2 = tracing::info_span!("Second level", field_overwrite = 1).entered();
503 tracing::info!(field_overwrite = "from event", "FOOBAR");
504 });
505
506 let mut data = data.lock().unwrap();
507 let mut iter = (*data).iter_mut();
508
509 assert_json_timestamp_name(
510 serde_json::json!({
511 "target": "tracing_json_span_fields::tests",
512 "log_level": "INFO",
513 "message": "FOOBAR",
514 "field_overwrite": "from event"
515 }),
516 "event src/lib.rs:",
517 &before,
518 iter.next().unwrap(),
519 );
520 assert_eq!(None, iter.next(), "No more logged events");
521 }
522
523 #[test]
524 fn two_events_from_two_spans() {
525 let data = Arc::new(Mutex::new(vec![]));
526 let layer = JsonLayer::default().with_output(TestOutput { data: data.clone() });
527
528 let subscriber = Registry::default().with(layer);
529
530 let before = OffsetDateTime::now_utc();
531
532 with_default(subscriber, || {
533 let _span1 = tracing::info_span!("Top level", field_top = 0).entered();
534 tracing::info!(field_event = "from event one", "ONE");
535 let _span2 = tracing::info_span!("Second level", field_second = 1).entered();
536 tracing::info!(field_event = "from event two", "TWO");
537 });
538
539 let mut data = data.lock().unwrap();
540 let mut iter = (*data).iter_mut();
541
542 assert_json_timestamp_name(
543 serde_json::json!({
544 "target": "tracing_json_span_fields::tests",
545 "log_level": "INFO",
546 "message": "ONE",
547 "field_top": 0,
548 "field_event": "from event one"
549 }),
550 "event src/lib.rs:",
551 &before,
552 iter.next().unwrap(),
553 );
554 assert_json_timestamp_name(
555 serde_json::json!({
556 "target": "tracing_json_span_fields::tests",
557 "log_level": "INFO",
558 "message": "TWO",
559 "field_top": 0,
560 "field_second": 1,
561 "field_event": "from event two"
562 }),
563 "event src/lib.rs:",
564 &before,
565 iter.next().unwrap(),
566 );
567 assert_eq!(None, iter.next(), "No more logged events");
568 }
569
570 #[test]
571 fn one_span_recorded_field() {
572 let data = Arc::new(Mutex::new(vec![]));
573 let layer = JsonLayer::default().with_output(TestOutput { data: data.clone() });
574
575 let subscriber = Registry::default().with(layer);
576
577 let before = OffsetDateTime::now_utc();
578
579 with_default(subscriber, || {
580 let span = tracing::info_span!("A span", span_field = 0, recorded_field = field::Empty);
581 span.record("recorded_field", "foo");
582 let _span = span.entered();
583 tracing::info!(event_field = 1.1, "FOOBAR");
584 });
585
586 let mut data = data.lock().unwrap();
587 let mut iter = (*data).iter_mut();
588
589 assert_json_timestamp_name(
590 serde_json::json!({
591 "target": "tracing_json_span_fields::tests",
592 "log_level": "INFO",
593 "message": "FOOBAR",
594 "event_field": 1.1,
595 "recorded_field": "foo",
596 "span_field": 0,
597 }),
598 "event src/lib.rs:",
599 &before,
600 iter.next().unwrap(),
601 );
602 assert_eq!(None, iter.next(), "No more logged events");
603 }
604
605 #[test]
606 fn one_span_recorded_field_overwriting_initial_field() {
607 let data = Arc::new(Mutex::new(vec![]));
608 let layer = JsonLayer::default().with_output(TestOutput { data: data.clone() });
609
610 let subscriber = Registry::default().with(layer);
611
612 let before = OffsetDateTime::now_utc();
613
614 with_default(subscriber, || {
615 let span = tracing::info_span!("A span", span_field = 0);
616 span.record("span_field", "foo");
617 let _span = span.entered();
618 tracing::info!(event_field = 1.1, "FOOBAR");
619 });
620
621 let mut data = data.lock().unwrap();
622 let mut iter = (*data).iter_mut();
623
624 assert_json_timestamp_name(
625 serde_json::json!({
626 "target": "tracing_json_span_fields::tests",
627 "log_level": "INFO",
628 "message": "FOOBAR",
629 "event_field": 1.1,
630 "span_field": "foo",
631 }),
632 "event src/lib.rs:",
633 &before,
634 iter.next().unwrap(),
635 );
636 assert_eq!(None, iter.next(), "No more logged events");
637 }
638
639 #[test]
640 fn without_any_spans() {
641 let data = Arc::new(Mutex::new(vec![]));
642 let layer = JsonLayer::default().with_output(TestOutput { data: data.clone() });
643
644 let subscriber = Registry::default().with(layer);
645
646 let before = OffsetDateTime::now_utc();
647
648 with_default(subscriber, || {
649 tracing::info!(event_field = 1.1, "FOOBAR");
650 });
651
652 let mut data = data.lock().unwrap();
653 let mut iter = (*data).iter_mut();
654
655 assert_json_timestamp_name(
656 serde_json::json!({
657 "target": "tracing_json_span_fields::tests",
658 "log_level": "INFO",
659 "message": "FOOBAR",
660 "event_field": 1.1,
661 }),
662 "event src/lib.rs:",
663 &before,
664 iter.next().unwrap(),
665 );
666 assert_eq!(None, iter.next(), "No more logged events");
667 }
668
669 #[test]
670 fn custom_timestamp() {
671 let timestamp_format = format_description!(
672 "[year]-[month]-[day] [hour]:[minute]:[second].[subsecond digits:3]"
673 );
674 let data = Arc::new(Mutex::new(vec![]));
675 let layer = JsonLayer::default()
676 .with_output(TestOutput { data: data.clone() })
677 .with_timestamp_format(timestamp_format);
678
679 let subscriber = Registry::default().with(layer);
680
681 let before = OffsetDateTime::now_utc();
682
683 with_default(subscriber, || {
684 tracing::info!(event_field = 1.1, "FOOBAR");
685 });
686
687 let mut data = data.lock().unwrap();
688 let mut iter = (*data).iter_mut();
689
690 assert_json_timestamp_name_with_format(
691 serde_json::json!({
692 "target": "tracing_json_span_fields::tests",
693 "log_level": "INFO",
694 "message": "FOOBAR",
695 "event_field": 1.1,
696 }),
697 "event src/lib.rs:",
698 &before,
699 iter.next().unwrap(),
700 ×tamp_format,
701 );
702 assert_eq!(None, iter.next(), "No more logged events");
703 }
704
705 #[test]
706 fn logging_levels() {
707 let data = Arc::new(Mutex::new(vec![]));
708 let layer = JsonLayer::default().with_output(TestOutput { data: data.clone() });
709
710 let subscriber = Registry::default().with(layer);
711
712 let before = OffsetDateTime::now_utc();
713
714 with_default(subscriber, || {
715 tracing::info!("INFO");
716 tracing::trace!("TRACE");
717 });
718
719 let mut data = data.lock().unwrap();
720 let mut iter = (*data).iter_mut();
721
722 assert_json_timestamp_name(
723 serde_json::json!({
724 "target": "tracing_json_span_fields::tests",
725 "log_level": "INFO",
726 "message": "INFO",
727 }),
728 "event src/lib.rs:",
729 &before,
730 iter.next().unwrap(),
731 );
732 assert_eq!(None, iter.next(), "No more logged events");
733 }
734
735 #[test]
736 fn logging_levels_trace() {
737 let data = Arc::new(Mutex::new(vec![]));
738 let layer = JsonLayer::default()
739 .with_output(TestOutput { data: data.clone() })
740 .with_level(LevelFilter::TRACE);
741
742 let subscriber = Registry::default().with(layer);
743
744 let before = OffsetDateTime::now_utc();
745
746 with_default(subscriber, || {
747 tracing::info!("INFO");
748 tracing::trace!("TRACE");
749 });
750
751 let mut data = data.lock().unwrap();
752 let mut iter = (*data).iter_mut();
753
754 assert_json_timestamp_name(
755 serde_json::json!({
756 "target": "tracing_json_span_fields::tests",
757 "log_level": "INFO",
758 "message": "INFO",
759 }),
760 "event src/lib.rs:",
761 &before,
762 iter.next().unwrap(),
763 );
764 assert_json_timestamp_name(
765 serde_json::json!({
766 "target": "tracing_json_span_fields::tests",
767 "log_level": "TRACE",
768 "message": "TRACE",
769 }),
770 "event src/lib.rs:",
771 &before,
772 iter.next().unwrap(),
773 );
774 assert_eq!(None, iter.next(), "No more logged events");
775 }
776
777 #[test]
778 fn logging_levels_off() {
779 let data = Arc::new(Mutex::new(vec![]));
780 let layer = JsonLayer::default()
781 .with_output(TestOutput { data: data.clone() })
782 .with_level(LevelFilter::OFF);
783
784 let subscriber = Registry::default().with(layer);
785
786 with_default(subscriber, || {
787 tracing::info!("INFO");
788 tracing::trace!("TRACE");
789 });
790
791 let mut data = data.lock().unwrap();
792 let mut iter = (*data).iter_mut();
793
794 assert_eq!(None, iter.next(), "No logged events");
795 }
796}