1pub(crate) mod format;
2pub mod time;
3
4use crate::time::FormatTime;
5use format::{write_span_mode, Buffers, ColorLevel, Config, FmtEvent, SpanMode};
6
7use nu_ansi_term::{Color, Style};
8use std::{
9 fmt::{self, Write},
10 io::{self, IsTerminal},
11 iter::Fuse,
12 mem,
13 sync::{
14 atomic::{AtomicBool, Ordering},
15 Mutex,
16 },
17 thread::LocalKey,
18 time::Instant,
19};
20use tracing_core::{
21 field::{Field, Visit},
22 span::{Attributes, Id},
23 Event, Subscriber,
24};
25#[cfg(feature = "tracing-log")]
26use tracing_log::NormalizeEvent;
27use tracing_subscriber::{
28 fmt::MakeWriter,
29 layer::{Context, Layer},
30 registry::{LookupSpan, ScopeFromRoot, SpanRef},
31};
32
33// Span extension data
34pub(crate) struct Data {
35 start: Instant,
36 kvs: Vec<(&'static str, String)>,
37 written: bool,
38}
39
40impl Data {
41 pub fn new(attrs: &Attributes<'_>, written: bool) -> Self {
42 let mut span: Data = Self {
43 start: Instant::now(),
44 kvs: Vec::new(),
45 written,
46 };
47 attrs.record(&mut span);
48 span
49 }
50}
51
52impl Visit for Data {
53 fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) {
54 self.kvs.push((field.name(), format!("{:?}", value)))
55 }
56}
57
58#[derive(Debug)]
59pub struct HierarchicalLayer<W = fn() -> io::Stderr, FT = ()>
60where
61 W: for<'writer> dynMakeWriter<'writer> + 'static,
62 FT: FormatTime,
63{
64 make_writer: W,
65 bufs: Mutex<Buffers>,
66 config: Config,
67 timer: FT,
68}
69
70impl Default for HierarchicalLayer {
71 fn default() -> Self {
72 Self::new(indent_amount:2)
73 }
74}
75
76impl HierarchicalLayer<fn() -> io::Stderr> {
77 pub fn new(indent_amount: usize) -> Self {
78 let ansi: bool = io::stderr().is_terminal();
79 let config: Config = Config {
80 ansi,
81 indent_amount,
82 ..Default::default()
83 };
84 Self {
85 make_writer: io::stderr,
86 bufs: Mutex::new(Buffers::new()),
87 config,
88 timer: (),
89 }
90 }
91}
92
93impl<W, FT> HierarchicalLayer<W, FT>
94where
95 W: for<'writer> dynMakeWriter<'writer> + 'static,
96 FT: FormatTime,
97{
98 /// Enables terminal colors, boldness and italics.
99 pub fn with_ansi(self, ansi: bool) -> Self {
100 Self {
101 config: self.config.with_ansi(ansi),
102 ..self
103 }
104 }
105
106 pub fn with_writer<W2>(self, make_writer: W2) -> HierarchicalLayer<W2, FT>
107 where
108 W2: for<'writer> MakeWriter<'writer>,
109 {
110 HierarchicalLayer {
111 make_writer,
112 config: self.config,
113 bufs: self.bufs,
114 timer: self.timer,
115 }
116 }
117
118 pub fn with_indent_amount(self, indent_amount: usize) -> Self {
119 let config = Config {
120 indent_amount,
121 ..self.config
122 };
123 Self { config, ..self }
124 }
125
126 /// Renders an ascii art tree instead of just using whitespace indentation.
127 pub fn with_indent_lines(self, indent_lines: bool) -> Self {
128 Self {
129 config: self.config.with_indent_lines(indent_lines),
130 ..self
131 }
132 }
133
134 /// Specifies how to measure and format time at which event has occurred.
135 pub fn with_timer<FT2: FormatTime>(self, timer: FT2) -> HierarchicalLayer<W, FT2> {
136 HierarchicalLayer {
137 make_writer: self.make_writer,
138 config: self.config,
139 bufs: self.bufs,
140 timer,
141 }
142 }
143
144 /// Whether to render the event and span targets. Usually targets are the module path to the
145 /// event/span macro invocation.
146 pub fn with_targets(self, targets: bool) -> Self {
147 Self {
148 config: self.config.with_targets(targets),
149 ..self
150 }
151 }
152
153 /// Whether to render the thread id in the beginning of every line. This is helpful to
154 /// untangle the tracing statements emitted by each thread.
155 pub fn with_thread_ids(self, thread_ids: bool) -> Self {
156 Self {
157 config: self.config.with_thread_ids(thread_ids),
158 ..self
159 }
160 }
161
162 /// Whether to render the thread name in the beginning of every line. Not all threads have
163 /// names, but if they do, this may be more helpful than the generic thread ids.
164 pub fn with_thread_names(self, thread_names: bool) -> Self {
165 Self {
166 config: self.config.with_thread_names(thread_names),
167 ..self
168 }
169 }
170
171 /// Resets the indentation to zero after `wraparound` indentation levels.
172 /// This is helpful if you expect very deeply nested spans as otherwise the indentation
173 /// just runs out of your screen.
174 pub fn with_wraparound(self, wraparound: usize) -> Self {
175 Self {
176 config: self.config.with_wraparound(wraparound),
177 ..self
178 }
179 }
180
181 /// Whether to print the currently active span's message again before entering a new span.
182 /// This helps if the entry to the current span was quite a while back (and with scrolling
183 /// upwards in logs).
184 pub fn with_verbose_entry(self, verbose_entry: bool) -> Self {
185 Self {
186 config: self.config.with_verbose_entry(verbose_entry),
187 ..self
188 }
189 }
190
191 /// Whether to print the currently active span's message again before dropping it.
192 /// This helps if the entry to the current span was quite a while back (and with scrolling
193 /// upwards in logs).
194 pub fn with_verbose_exit(self, verbose_exit: bool) -> Self {
195 Self {
196 config: self.config.with_verbose_exit(verbose_exit),
197 ..self
198 }
199 }
200
201 /// Whether to print the currently active span's message again if another span was entered in
202 /// the meantime
203 /// This helps during concurrent or multi-threaded events where threads are entered, but not
204 /// necessarily *exited* before other *divergent* spans are entered and generating events.
205 pub fn with_span_retrace(self, enabled: bool) -> Self {
206 Self {
207 config: self.config.with_span_retrace(enabled),
208 ..self
209 }
210 }
211
212 /// Defers printing span opening until an event is generated within the span.
213 ///
214 /// Avoids printing empty spans with no generated events.
215 pub fn with_deferred_spans(self, enabled: bool) -> Self {
216 Self {
217 config: self.config.with_deferred_spans(enabled),
218 ..self
219 }
220 }
221
222 /// Prefixes each branch with the event mode, such as `open`, or `close`
223 pub fn with_span_modes(self, enabled: bool) -> Self {
224 Self {
225 config: self.config.with_span_modes(enabled),
226 ..self
227 }
228 }
229
230 /// Whether to print `{}` around the fields when printing a span.
231 /// This can help visually distinguish fields from the rest of the message.
232 pub fn with_bracketed_fields(self, bracketed_fields: bool) -> Self {
233 Self {
234 config: self.config.with_bracketed_fields(bracketed_fields),
235 ..self
236 }
237 }
238
239 /// Whether to print the time with higher precision.
240 pub fn with_higher_precision(self, higher_precision: bool) -> Self {
241 Self {
242 config: self.config.with_higher_precision(higher_precision),
243 ..self
244 }
245 }
246
247 fn styled(&self, style: Style, text: impl AsRef<str>) -> String {
248 if self.config.ansi {
249 style.paint(text.as_ref()).to_string()
250 } else {
251 text.as_ref().to_string()
252 }
253 }
254
255 fn print_kvs<'a, I, V>(&self, buf: &mut impl fmt::Write, kvs: I) -> fmt::Result
256 where
257 I: IntoIterator<Item = (&'a str, V)>,
258 V: fmt::Display + 'a,
259 {
260 let mut kvs = kvs.into_iter();
261 if let Some((k, v)) = kvs.next() {
262 if k == "message" {
263 write!(buf, "{}", v)?;
264 } else {
265 write!(buf, "{}={}", k, v)?;
266 }
267 }
268 for (k, v) in kvs {
269 write!(buf, ", {}={}", k, v)?;
270 }
271 Ok(())
272 }
273
274 /// Ensures that `new_span` and all its ancestors are properly printed before an event
275 fn write_retrace_span<'a, S>(
276 &self,
277 new_span: &SpanRef<'a, S>,
278 bufs: &mut Buffers,
279 ctx: &'a Context<S>,
280 pre_open: bool,
281 ) where
282 S: Subscriber + for<'new_span> LookupSpan<'new_span>,
283 {
284 // Also handle deferred spans along with retrace since deferred spans may need to print
285 // multiple spans at once as a whole tree can be deferred
286 //
287 // If a another event occurs right after a previous event in the same span, this will
288 // simply print nothing since the path to the common lowest ancestor is empty
289 // if self.config.span_retrace || self.config.deferred_spans {
290 let old_span_id = bufs.current_span.replace((new_span.id()).clone());
291 let old_span_id = old_span_id.as_ref();
292 let new_span_id = new_span.id();
293
294 if Some(&new_span_id) != old_span_id {
295 let old_span = old_span_id.as_ref().and_then(|v| ctx.span(v));
296 let old_path = old_span.as_ref().map(scope_path).into_iter().flatten();
297
298 let new_path = scope_path(new_span);
299
300 // Print the path from the common base of the two spans
301 let new_path = DifferenceIter::new(old_path, new_path, |v| v.id());
302
303 for (i, span) in new_path.enumerate() {
304 // Mark traversed spans as *written*
305 let was_written = if let Some(data) = span.extensions_mut().get_mut::<Data>() {
306 mem::replace(&mut data.written, true)
307 } else {
308 // `on_new_span` was not called, before
309 // Consider if this should panic instead, which is *technically* correct but is
310 // bad behavior for a logging layer in production.
311 false
312 };
313
314 // Print the parent of the first span
315 let mut verbose = false;
316 if i == 0 && pre_open {
317 if let Some(span) = span.parent() {
318 verbose = true;
319 self.write_span_info(&span, bufs, SpanMode::PreOpen);
320 }
321 }
322
323 self.write_span_info(
324 &span,
325 bufs,
326 if was_written {
327 SpanMode::Retrace { verbose }
328 } else {
329 SpanMode::Open { verbose }
330 },
331 )
332 }
333 }
334 }
335
336 fn write_span_info<S>(&self, span: &SpanRef<S>, bufs: &mut Buffers, style: SpanMode)
337 where
338 S: Subscriber + for<'span> LookupSpan<'span>,
339 {
340 let ext = span.extensions();
341 let data = ext.get::<Data>().expect("span does not have data");
342
343 let mut current_buf = &mut bufs.current_buf;
344
345 if self.config.span_modes {
346 write_span_mode(current_buf, style)
347 }
348
349 let indent = scope_path(span).skip(1).count();
350
351 let should_write = match style {
352 SpanMode::Open { .. } | SpanMode::Event => true,
353 // Print the parent of a new span again before entering the child
354 SpanMode::PreOpen { .. } if self.config.verbose_entry => true,
355 SpanMode::Close { verbose } => verbose,
356 // Generated if `span_retrace` is enabled
357 SpanMode::Retrace { .. } => true,
358 // Generated if `verbose_exit` is enabled
359 SpanMode::PostClose => true,
360 _ => false,
361 };
362
363 if should_write {
364 if self.config.targets {
365 let target = span.metadata().target();
366 write!(
367 &mut current_buf,
368 "{}::",
369 self.styled(Style::new().dimmed(), target,),
370 )
371 .expect("Unable to write to buffer");
372 }
373
374 write!(
375 current_buf,
376 "{name}",
377 name = self.styled(Style::new().fg(Color::Green).bold(), span.metadata().name())
378 )
379 .unwrap();
380 if self.config.bracketed_fields {
381 write!(
382 current_buf,
383 "{}",
384 self.styled(Style::new().fg(Color::Green).bold(), "{") // Style::new().fg(Color::Green).dimmed().paint("{")
385 )
386 .unwrap();
387 } else {
388 write!(current_buf, " ").unwrap();
389 }
390 self.print_kvs(&mut current_buf, data.kvs.iter().map(|(k, v)| (*k, v)))
391 .unwrap();
392 if self.config.bracketed_fields {
393 write!(
394 current_buf,
395 "{}",
396 self.styled(Style::new().fg(Color::Green).bold(), "}") // Style::new().dimmed().paint("}")
397 )
398 .unwrap();
399 }
400 }
401
402 bufs.indent_current(indent, &self.config, style);
403 let writer = self.make_writer.make_writer();
404 bufs.flush_current_buf(writer)
405 }
406
407 fn get_timestamp<S>(&self, span: SpanRef<S>) -> Option<String>
408 where
409 S: Subscriber + for<'span> LookupSpan<'span>,
410 {
411 let ext = span.extensions();
412 let data = ext
413 .get::<Data>()
414 .expect("Data cannot be found in extensions");
415
416 if self.config.higher_precision {
417 Some(self.format_timestamp_with_decimals(data.start))
418 } else {
419 Some(self.format_timestamp(data.start))
420 }
421 }
422
423 fn format_timestamp(&self, start: std::time::Instant) -> String {
424 let elapsed = start.elapsed();
425 let millis = elapsed.as_millis();
426 let secs = elapsed.as_secs();
427
428 // Convert elapsed time to appropriate units: ms, s, or m.
429 // - Less than 1s : use ms
430 // - Less than 1m : use s
431 // - 1m and above : use m
432 let (n, unit) = if millis < 1000 {
433 (millis as _, "ms")
434 } else if secs < 60 {
435 (secs, "s ")
436 } else {
437 (secs / 60, "m ")
438 };
439
440 let timestamp = format!("{n:>3}");
441 self.style_timestamp(timestamp, unit)
442 }
443
444 fn format_timestamp_with_decimals(&self, start: std::time::Instant) -> String {
445 let secs = start.elapsed().as_secs_f64();
446
447 // Convert elapsed time to appropriate units: μs, ms, or s.
448 // - Less than 1ms: use μs
449 // - Less than 1s : use ms
450 // - 1s and above : use s
451 let (n, unit) = if secs < 0.001 {
452 (secs * 1_000_000.0, "μs")
453 } else if secs < 1.0 {
454 (secs * 1_000.0, "ms")
455 } else {
456 (secs, "s ")
457 };
458
459 let timestamp = format!(" {n:.2}");
460 self.style_timestamp(timestamp, unit)
461 }
462
463 fn style_timestamp(&self, timestamp: String, unit: &str) -> String {
464 format!(
465 "{timestamp}{unit} ",
466 timestamp = self.styled(Style::new().dimmed(), timestamp),
467 unit = self.styled(Style::new().dimmed(), unit),
468 )
469 }
470
471 fn is_recursive() -> Option<RecursiveGuard> {
472 thread_local! {
473 pub static IS_EMPTY: AtomicBool = const { AtomicBool::new(true) };
474 }
475
476 IS_EMPTY.with(|is_empty| {
477 is_empty
478 .compare_exchange(true, false, Ordering::Relaxed, Ordering::Relaxed)
479 .ok()
480 .map(|_| RecursiveGuard(&IS_EMPTY))
481 })
482 }
483}
484
485struct RecursiveGuard(&'static LocalKey<AtomicBool>);
486
487impl Drop for RecursiveGuard {
488 fn drop(&mut self) {
489 self.0
490 .with(|is_empty: &AtomicBool| is_empty.store(val:true, order:Ordering::Relaxed));
491 }
492}
493
494impl<S, W, FT> Layer<S> for HierarchicalLayer<W, FT>
495where
496 S: Subscriber + for<'span> dynLookupSpan<'span>,
497 W: for<'writer> dynMakeWriter<'writer> + 'static,
498 FT: FormatTime + 'static,
499{
500 fn on_new_span(&self, attrs: &Attributes, id: &Id, ctx: Context<S>) {
501 let Some(_guard) = Self::is_recursive() else {
502 return;
503 };
504
505 let span = ctx.span(id).expect("in new_span but span does not exist");
506
507 if span.extensions().get::<Data>().is_none() {
508 let data = Data::new(attrs, !self.config.deferred_spans);
509 span.extensions_mut().insert(data);
510 }
511
512 // Entry will be printed in on_event along with retrace
513 if self.config.deferred_spans {
514 return;
515 }
516
517 let bufs = &mut *self.bufs.lock().unwrap();
518
519 if self.config.span_retrace {
520 self.write_retrace_span(&span, bufs, &ctx, self.config.verbose_entry);
521 } else {
522 if self.config.verbose_entry {
523 if let Some(span) = span.parent() {
524 self.write_span_info(&span, bufs, SpanMode::PreOpen);
525 }
526 }
527 // Store the most recently entered span
528 bufs.current_span = Some(span.id());
529 self.write_span_info(
530 &span,
531 bufs,
532 SpanMode::Open {
533 verbose: self.config.verbose_entry,
534 },
535 );
536 }
537 }
538
539 fn on_event(&self, event: &Event<'_>, ctx: Context<S>) {
540 let Some(_guard) = Self::is_recursive() else {
541 return;
542 };
543
544 let span = ctx.current_span();
545 let span_id = span.id();
546 let span = span_id.and_then(|id| ctx.span(id));
547
548 let mut guard = self.bufs.lock().unwrap();
549 let bufs = &mut *guard;
550
551 if let Some(new_span) = &span {
552 if self.config.span_retrace || self.config.deferred_spans {
553 self.write_retrace_span(new_span, bufs, &ctx, self.config.verbose_entry);
554 }
555 }
556
557 let mut event_buf = &mut bufs.current_buf;
558
559 // Time.
560
561 {
562 let prev_buffer_len = event_buf.len();
563
564 self.timer
565 .format_time(&mut event_buf)
566 .expect("Unable to write time to buffer");
567
568 // Something was written to the buffer, pad it with a space.
569 if prev_buffer_len < event_buf.len() {
570 write!(event_buf, " ").expect("Unable to write to buffer");
571 }
572 }
573
574 let deindent = if self.config.indent_lines { 0 } else { 1 };
575 // printing the indentation
576 let indent = ctx
577 .event_scope(event)
578 .map(|scope| scope.count() - deindent)
579 .unwrap_or(0);
580
581 // check if this event occurred in the context of a span.
582 // if it has, get the start time of this span.
583 if let Some(span) = span {
584 if let Some(timestamp) = self.get_timestamp(span) {
585 write!(&mut event_buf, "{}", timestamp).expect("Unable to write to buffer");
586 }
587 }
588
589 #[cfg(feature = "tracing-log")]
590 let normalized_meta = event.normalized_metadata();
591 #[cfg(feature = "tracing-log")]
592 let metadata = normalized_meta.as_ref().unwrap_or_else(|| event.metadata());
593 #[cfg(not(feature = "tracing-log"))]
594 let metadata = event.metadata();
595
596 let level = metadata.level();
597 let level = if self.config.ansi {
598 ColorLevel(level).to_string()
599 } else {
600 level.to_string()
601 };
602
603 write!(&mut event_buf, "{level}", level = level).expect("Unable to write to buffer");
604
605 if self.config.targets {
606 let target = metadata.target();
607 write!(
608 &mut event_buf,
609 " {}",
610 self.styled(Style::new().dimmed(), target,),
611 )
612 .expect("Unable to write to buffer");
613 }
614
615 let mut visitor = FmtEvent { comma: false, bufs };
616 event.record(&mut visitor);
617 visitor
618 .bufs
619 .indent_current(indent, &self.config, SpanMode::Event);
620 let writer = self.make_writer.make_writer();
621 bufs.flush_current_buf(writer)
622 }
623
624 fn on_close(&self, id: Id, ctx: Context<S>) {
625 let Some(_guard) = Self::is_recursive() else {
626 return;
627 };
628
629 let bufs = &mut *self.bufs.lock().unwrap();
630
631 let span = ctx.span(&id).expect("invalid span in on_close");
632
633 // Span was not printed, so don't print an exit
634 if self.config.deferred_spans
635 && span.extensions().get::<Data>().map(|v| v.written) != Some(true)
636 {
637 return;
638 }
639
640 // self.write_retrace_span(&span, bufs, &ctx);
641
642 self.write_span_info(
643 &span,
644 bufs,
645 SpanMode::Close {
646 verbose: self.config.verbose_exit,
647 },
648 );
649
650 if let Some(parent_span) = span.parent() {
651 bufs.current_span = Some(parent_span.id());
652 if self.config.verbose_exit {
653 // Consider parent as entered
654
655 self.write_span_info(&parent_span, bufs, SpanMode::PostClose);
656 }
657 }
658 }
659}
660
661fn scope_path<'a, R: LookupSpan<'a>>(span: &SpanRef<'a, R>) -> ScopeFromRoot<'a, R> {
662 span.scope().from_root()
663}
664
665/// Runs `A` and `B` side by side and only yields items present in `B`
666struct DifferenceIter<L, R, F> {
667 left: Fuse<L>,
668 right: R,
669 compare: F,
670}
671
672impl<L: Iterator<Item = T>, R: Iterator<Item = T>, T, U: PartialEq, F: Fn(&T) -> U>
673 DifferenceIter<L, R, F>
674{
675 fn new(left: L, right: R, compare: F) -> Self {
676 Self {
677 left: left.fuse(),
678 right,
679 compare,
680 }
681 }
682}
683
684impl<L: Iterator<Item = T>, R: Iterator<Item = T>, T, U: PartialEq, F: Fn(&T) -> U> Iterator
685 for DifferenceIter<L, R, F>
686{
687 type Item = T;
688
689 fn next(&mut self) -> Option<Self::Item> {
690 loop {
691 let left: Option = self.left.next();
692 let right: T = self.right.next()?;
693
694 if left.as_ref().map(&self.compare) != Some((self.compare)(&right)) {
695 return Some(right);
696 }
697 }
698 }
699}
700