tracing_forest/printer/
pretty.rs

1use crate::printer::Formatter;
2use crate::tree::{Event, Shared, Span, Tree};
3use crate::Tag;
4use std::fmt::{self, Write};
5
6#[cfg(feature = "smallvec")]
7type IndentVec = smallvec::SmallVec<[Indent; 32]>;
8#[cfg(not(feature = "smallvec"))]
9type IndentVec = Vec<Indent>;
10
11#[cfg(feature = "ansi")]
12use ansi_term::Color;
13#[cfg(feature = "ansi")]
14use tracing::Level;
15
16/// Format logs for pretty printing.
17///
18/// # Interpreting span times
19///
20/// Spans have the following format:
21/// ```txt
22/// <NAME> [ <DURATION> | <BODY> / <ROOT> ]
23/// ```
24/// * DURATION represents the total time the span was entered for. If the span
25///   was used to instrument a `Future` that sleeps, then that time won't be counted
26///   since the `Future` won't be polled during that time, and so the span won't enter.
27/// * BODY represents the percent time the span is entered relative to the root
28///   span, *excluding* time that any child spans are entered.
29/// * ROOT represents the percent time the span is entered relative to the root
30///   span, *including* time that any child spans are entered.
31///
32/// As a mental model, look at `ROOT` to quickly narrow down which branches are
33/// costly, and look at `BASE` to pinpoint exactly which spans are expensive.
34///
35/// Spans without any child spans would have the same `BASE` and `ROOT`, so the
36/// redundency is omitted.
37///
38/// # Examples
39///
40/// An arbitrarily complex example:
41/// ```log
42/// INFO     try_from_entry_ro [ 324µs | 8.47% / 100.00% ]
43/// INFO     ┝━ server::internal_search [ 296µs | 19.02% / 91.53% ]
44/// INFO     │  ┝━ ｉ [filter.info]: Some filter info...
45/// INFO     │  ┝━ server::search [ 226µs | 10.11% / 70.01% ]
46/// INFO     │  │  ┝━ be::search [ 181µs | 6.94% / 55.85% ]
47/// INFO     │  │  │  ┕━ be::search -> filter2idl [ 158µs | 19.65% / 48.91% ]
48/// INFO     │  │  │     ┝━ be::idl_arc_sqlite::get_idl [ 20.4µs | 6.30% ]
49/// INFO     │  │  │     │  ┕━ ｉ [filter.info]: Some filter info...
50/// INFO     │  │  │     ┕━ be::idl_arc_sqlite::get_idl [ 74.3µs | 22.96% ]
51/// ERROR    │  │  │        ┝━ 🚨 [admin.error]: On no, an admin error occurred :(
52/// DEBUG    │  │  │        ┝━ 🐛 [debug]: An untagged debug log
53/// INFO     │  │  │        ┕━ ｉ [admin.info]: there's been a big mistake | alive: false | status: "very sad"
54/// INFO     │  │  ┕━ be::idl_arc_sqlite::get_identry [ 13.1µs | 4.04% ]
55/// ERROR    │  │     ┝━ 🔐 [security.critical]: A security critical log
56/// INFO     │  │     ┕━ 🔓 [security.access]: A security access log
57/// INFO     │  ┕━ server::search<filter_resolve> [ 8.08µs | 2.50% ]
58/// WARN     │     ┕━ 🚧 [filter.warn]: Some filter warning
59/// TRACE    ┕━ 📍 [trace]: Finished!
60/// ```
61#[derive(Debug)]
62pub struct Pretty;
63
64impl Formatter for Pretty {
65    type Error = fmt::Error;
66
67    fn fmt(&self, tree: &Tree) -> Result<String, fmt::Error> {
68        let mut writer = String::with_capacity(256);
69
70        Pretty::format_tree(tree, None, &mut IndentVec::new(), &mut writer)?;
71
72        Ok(writer)
73    }
74}
75
76impl Pretty {
77    fn format_tree(
78        tree: &Tree,
79        duration_root: Option<f64>,
80        indent: &mut IndentVec,
81        writer: &mut String,
82    ) -> fmt::Result {
83        match tree {
84            Tree::Event(event) => {
85                Pretty::format_shared(&event.shared, writer)?;
86                Pretty::format_indent(indent, writer)?;
87                Pretty::format_event(event, writer)
88            }
89            Tree::Span(span) => {
90                Pretty::format_shared(&span.shared, writer)?;
91                Pretty::format_indent(indent, writer)?;
92                Pretty::format_span(span, duration_root, indent, writer)
93            }
94        }
95    }
96
97    fn format_shared(shared: &Shared, writer: &mut String) -> fmt::Result {
98        #[cfg(feature = "uuid")]
99        write!(writer, "{} ", shared.uuid)?;
100
101        #[cfg(feature = "chrono")]
102        write!(writer, "{:<36} ", shared.timestamp.to_rfc3339())?;
103
104        #[cfg(feature = "ansi")]
105        return write!(writer, "{:<8} ", ColorLevel(shared.level));
106
107        #[cfg(not(feature = "ansi"))]
108        return write!(writer, "{:<8} ", shared.level);
109    }
110
111    fn format_indent(indent: &[Indent], writer: &mut String) -> fmt::Result {
112        for indent in indent {
113            writer.write_str(indent.repr())?;
114        }
115        Ok(())
116    }
117
118    fn format_event(event: &Event, writer: &mut String) -> fmt::Result {
119        let tag = event.tag().unwrap_or_else(|| Tag::from(event.level()));
120
121        write!(writer, "{} [{}]: ", tag.icon(), tag)?;
122
123        if let Some(message) = event.message() {
124            writer.write_str(message)?;
125        }
126
127        for field in event.fields() {
128            write!(writer, " | {}: {}", FieldKey(field.key()), field.value())?;
129        }
130
131        writeln!(writer)
132    }
133
134    fn format_span(
135        span: &Span,
136        duration_root: Option<f64>,
137        indent: &mut IndentVec,
138        writer: &mut String,
139    ) -> fmt::Result {
140        if !span.should_render() {
141            return Ok(());
142        }
143
144        let total_duration = span.total_duration().as_nanos() as f64;
145        let inner_duration = span.inner_duration().as_nanos() as f64;
146        let root_duration = duration_root.unwrap_or(total_duration);
147        let percent_total_of_root_duration = 100.0 * total_duration / root_duration;
148
149        write!(
150            writer,
151            "{} [ {} | ",
152            span.name(),
153            DurationDisplay(total_duration)
154        )?;
155
156        if inner_duration > 0.0 {
157            let base_duration = span.base_duration().as_nanos() as f64;
158            let percent_base_of_root_duration = 100.0 * base_duration / root_duration;
159            write!(writer, "{percent_base_of_root_duration:.2}% / ")?;
160        }
161
162        write!(writer, "{percent_total_of_root_duration:.2}% ]")?;
163
164        for (n, field) in span.shared.fields.iter().enumerate() {
165            write!(
166                writer,
167                "{} {}: {}",
168                if n == 0 { "" } else { " |" },
169                FieldKey(field.key()),
170                field.value()
171            )?;
172        }
173        writeln!(writer)?;
174
175        // We need to limit our nodes to those that *will* render, else we
176        // end up printing ghost indents.
177        let nodes: Vec<_> = span
178            .nodes()
179            .iter()
180            .filter(|node| node.should_render())
181            .collect();
182
183        if let Some((last, remaining)) = nodes.split_last() {
184            match indent.last_mut() {
185                Some(edge @ Indent::Turn) => *edge = Indent::Null,
186                Some(edge @ Indent::Fork) => *edge = Indent::Line,
187                _ => {}
188            }
189
190            indent.push(Indent::Fork);
191
192            for tree in remaining {
193                if let Some(edge) = indent.last_mut() {
194                    *edge = Indent::Fork;
195                }
196                Pretty::format_tree(tree, Some(root_duration), indent, writer)?;
197            }
198
199            if let Some(edge) = indent.last_mut() {
200                *edge = Indent::Turn;
201            }
202            Pretty::format_tree(last, Some(root_duration), indent, writer)?;
203
204            indent.pop();
205        }
206
207        Ok(())
208    }
209}
210
211enum Indent {
212    Null,
213    Line,
214    Fork,
215    Turn,
216}
217
218impl Indent {
219    fn repr(&self) -> &'static str {
220        match self {
221            Self::Null => "   ",
222            Self::Line => "│  ",
223            Self::Fork => "┝━ ",
224            Self::Turn => "┕━ ",
225        }
226    }
227}
228
229struct DurationDisplay(f64);
230
231// Taken from chrono
232impl fmt::Display for DurationDisplay {
233    fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
234        let mut t = self.0;
235        for unit in ["ns", "µs", "ms", "s"] {
236            if t < 10.0 {
237                return write!(f, "{t:.2}{unit}");
238            } else if t < 100.0 {
239                return write!(f, "{t:.1}{unit}");
240            } else if t < 1000.0 {
241                return write!(f, "{t:.0}{unit}");
242            }
243            t /= 1000.0;
244        }
245        write!(f, "{:.0}s", t * 1000.0)
246    }
247}
248
249/// Implements colored formatting for a field if enabled
250struct FieldKey<'a>(&'a str);
251
252impl fmt::Display for FieldKey<'_> {
253    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
254        #[cfg(feature = "ansi")]
255        {
256            let color = Color::White.dimmed();
257
258            write!(f, "{}{}{}", color.prefix(), self.0, color.suffix())
259        }
260        #[cfg(not(feature = "ansi"))]
261        {
262            f.write_str(self.0)
263        }
264    }
265}
266
267// From tracing-tree
268#[cfg(feature = "ansi")]
269struct ColorLevel(Level);
270
271#[cfg(feature = "ansi")]
272impl fmt::Display for ColorLevel {
273    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
274        let color = match self.0 {
275            Level::TRACE => Color::Purple,
276            Level::DEBUG => Color::Blue,
277            Level::INFO => Color::Green,
278            Level::WARN => Color::RGB(252, 234, 160), // orange
279            Level::ERROR => Color::Red,
280        };
281        let style = color.bold();
282        write!(f, "{}", style.prefix())?;
283        f.pad(self.0.as_str())?;
284        write!(f, "{}", style.suffix())
285    }
286}
tracing_forest/printer/pretty.rs

tracing_forest/printer/
pretty.rs
