1 | pub(crate) mod format; |
2 | pub mod time; |
3 | |
4 | use crate::time::FormatTime; |
5 | use format::{Buffers, ColorLevel, Config, FmtEvent, SpanMode}; |
6 | |
7 | use is_terminal::IsTerminal; |
8 | use nu_ansi_term::{Color, Style}; |
9 | use std::{ |
10 | fmt::{self, Write as _}, |
11 | io, |
12 | sync::Mutex, |
13 | time::Instant, |
14 | }; |
15 | use tracing_core::{ |
16 | field::{Field, Visit}, |
17 | span::{Attributes, Id}, |
18 | Event, Subscriber, |
19 | }; |
20 | #[cfg (feature = "tracing-log" )] |
21 | use tracing_log::NormalizeEvent; |
22 | use tracing_subscriber::{ |
23 | fmt::MakeWriter, |
24 | layer::{Context, Layer}, |
25 | registry::{self, LookupSpan}, |
26 | }; |
27 | |
28 | pub(crate) struct Data { |
29 | start: Instant, |
30 | kvs: Vec<(&'static str, String)>, |
31 | } |
32 | |
33 | impl Data { |
34 | pub fn new(attrs: &Attributes<'_>) -> Self { |
35 | let mut span: Data = Self { |
36 | start: Instant::now(), |
37 | kvs: Vec::new(), |
38 | }; |
39 | attrs.record(&mut span); |
40 | span |
41 | } |
42 | } |
43 | |
44 | impl Visit for Data { |
45 | fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) { |
46 | self.kvs.push((field.name(), format!(" {:?}" , value))) |
47 | } |
48 | } |
49 | #[derive (Debug)] |
50 | pub struct HierarchicalLayer<W = fn() -> io::Stderr, FT = ()> |
51 | where |
52 | W: for<'writer> MakeWriter<'writer> + 'static, |
53 | FT: FormatTime, |
54 | { |
55 | make_writer: W, |
56 | bufs: Mutex<Buffers>, |
57 | config: Config, |
58 | timer: FT, |
59 | } |
60 | |
61 | impl Default for HierarchicalLayer { |
62 | fn default() -> Self { |
63 | Self::new(indent_amount:2) |
64 | } |
65 | } |
66 | |
67 | impl HierarchicalLayer<fn() -> io::Stderr> { |
68 | pub fn new(indent_amount: usize) -> Self { |
69 | let ansi: bool = io::stderr().is_terminal(); |
70 | let config: Config = Config { |
71 | ansi, |
72 | indent_amount, |
73 | ..Default::default() |
74 | }; |
75 | Self { |
76 | make_writer: io::stderr, |
77 | bufs: Mutex::new(Buffers::new()), |
78 | config, |
79 | timer: (), |
80 | } |
81 | } |
82 | } |
83 | |
84 | impl<W, FT> HierarchicalLayer<W, FT> |
85 | where |
86 | W: for<'writer> MakeWriter<'writer> + 'static, |
87 | FT: FormatTime, |
88 | { |
89 | /// Enables terminal colors, boldness and italics. |
90 | pub fn with_ansi(self, ansi: bool) -> Self { |
91 | Self { |
92 | config: self.config.with_ansi(ansi), |
93 | ..self |
94 | } |
95 | } |
96 | |
97 | pub fn with_writer<W2>(self, make_writer: W2) -> HierarchicalLayer<W2, FT> |
98 | where |
99 | W2: for<'writer> MakeWriter<'writer>, |
100 | { |
101 | HierarchicalLayer { |
102 | make_writer, |
103 | config: self.config, |
104 | bufs: self.bufs, |
105 | timer: self.timer, |
106 | } |
107 | } |
108 | |
109 | pub fn with_indent_amount(self, indent_amount: usize) -> Self { |
110 | let config = Config { |
111 | indent_amount, |
112 | ..self.config |
113 | }; |
114 | Self { config, ..self } |
115 | } |
116 | |
117 | /// Renders an ascii art tree instead of just using whitespace indentation. |
118 | pub fn with_indent_lines(self, indent_lines: bool) -> Self { |
119 | Self { |
120 | config: self.config.with_indent_lines(indent_lines), |
121 | ..self |
122 | } |
123 | } |
124 | |
125 | /// Specifies how to measure and format time at which event has occurred. |
126 | pub fn with_timer<FT2: FormatTime>(self, timer: FT2) -> HierarchicalLayer<W, FT2> { |
127 | HierarchicalLayer { |
128 | make_writer: self.make_writer, |
129 | config: self.config, |
130 | bufs: self.bufs, |
131 | timer, |
132 | } |
133 | } |
134 | |
135 | /// Whether to render the event and span targets. Usually targets are the module path to the |
136 | /// event/span macro invocation. |
137 | pub fn with_targets(self, targets: bool) -> Self { |
138 | Self { |
139 | config: self.config.with_targets(targets), |
140 | ..self |
141 | } |
142 | } |
143 | |
144 | /// Whether to render the thread id in the beginning of every line. This is helpful to |
145 | /// untangle the tracing statements emitted by each thread. |
146 | pub fn with_thread_ids(self, thread_ids: bool) -> Self { |
147 | Self { |
148 | config: self.config.with_thread_ids(thread_ids), |
149 | ..self |
150 | } |
151 | } |
152 | |
153 | /// Whether to render the thread name in the beginning of every line. Not all threads have |
154 | /// names, but if they do, this may be more helpful than the generic thread ids. |
155 | pub fn with_thread_names(self, thread_names: bool) -> Self { |
156 | Self { |
157 | config: self.config.with_thread_names(thread_names), |
158 | ..self |
159 | } |
160 | } |
161 | |
162 | /// Resets the indentation to zero after `wraparound` indentation levels. |
163 | /// This is helpful if you expect very deeply nested spans as otherwise the indentation |
164 | /// just runs out of your screen. |
165 | pub fn with_wraparound(self, wraparound: usize) -> Self { |
166 | Self { |
167 | config: self.config.with_wraparound(wraparound), |
168 | ..self |
169 | } |
170 | } |
171 | |
172 | /// Whether to print the currently active span's message again before entering a new span. |
173 | /// This helps if the entry to the current span was quite a while back (and with scrolling |
174 | /// upwards in logs). |
175 | pub fn with_verbose_entry(self, verbose_entry: bool) -> Self { |
176 | Self { |
177 | config: self.config.with_verbose_entry(verbose_entry), |
178 | ..self |
179 | } |
180 | } |
181 | |
182 | /// Whether to print the currently active span's message again before dropping it. |
183 | /// This helps if the entry to the current span was quite a while back (and with scrolling |
184 | /// upwards in logs). |
185 | pub fn with_verbose_exit(self, verbose_exit: bool) -> Self { |
186 | Self { |
187 | config: self.config.with_verbose_exit(verbose_exit), |
188 | ..self |
189 | } |
190 | } |
191 | |
192 | /// Whether to print `{}` around the fields when printing a span. |
193 | /// This can help visually distinguish fields from the rest of the message. |
194 | pub fn with_bracketed_fields(self, bracketed_fields: bool) -> Self { |
195 | Self { |
196 | config: self.config.with_bracketed_fields(bracketed_fields), |
197 | ..self |
198 | } |
199 | } |
200 | |
201 | fn styled(&self, style: Style, text: impl AsRef<str>) -> String { |
202 | if self.config.ansi { |
203 | style.paint(text.as_ref()).to_string() |
204 | } else { |
205 | text.as_ref().to_string() |
206 | } |
207 | } |
208 | |
209 | fn print_kvs<'a, I, V>(&self, buf: &mut impl fmt::Write, kvs: I) -> fmt::Result |
210 | where |
211 | I: IntoIterator<Item = (&'a str, V)>, |
212 | V: fmt::Display + 'a, |
213 | { |
214 | let mut kvs = kvs.into_iter(); |
215 | if let Some((k, v)) = kvs.next() { |
216 | if k == "message" { |
217 | write!(buf, " {}" , v)?; |
218 | } else { |
219 | write!(buf, " {}= {}" , k, v)?; |
220 | } |
221 | } |
222 | for (k, v) in kvs { |
223 | write!(buf, ", {}= {}" , k, v)?; |
224 | } |
225 | Ok(()) |
226 | } |
227 | |
228 | fn write_span_info<S>(&self, id: &Id, ctx: &Context<S>, style: SpanMode) |
229 | where |
230 | S: Subscriber + for<'span> LookupSpan<'span>, |
231 | { |
232 | let span = ctx |
233 | .span(id) |
234 | .expect("in on_enter/on_exit but span does not exist" ); |
235 | let ext = span.extensions(); |
236 | let data = ext.get::<Data>().expect("span does not have data" ); |
237 | |
238 | let mut guard = self.bufs.lock().unwrap(); |
239 | let bufs = &mut *guard; |
240 | let mut current_buf = &mut bufs.current_buf; |
241 | |
242 | let indent = ctx |
243 | .lookup_current() |
244 | .as_ref() |
245 | .map(registry::SpanRef::scope) |
246 | .map(registry::Scope::from_root) |
247 | .into_iter() |
248 | .flatten() |
249 | .count(); |
250 | |
251 | if self.config.verbose_entry || matches!(style, SpanMode::Open { .. } | SpanMode::Event) { |
252 | if self.config.targets { |
253 | let target = span.metadata().target(); |
254 | write!( |
255 | &mut current_buf, |
256 | " {}::" , |
257 | self.styled(Style::new().dimmed(), target,), |
258 | ) |
259 | .expect("Unable to write to buffer" ); |
260 | } |
261 | |
262 | write!( |
263 | current_buf, |
264 | " {name}" , |
265 | name = self.styled(Style::new().fg(Color::Green).bold(), span.metadata().name()) |
266 | ) |
267 | .unwrap(); |
268 | if self.config.bracketed_fields { |
269 | write!( |
270 | current_buf, |
271 | " {}" , |
272 | self.styled(Style::new().fg(Color::Green).bold(), "{" ) // Style::new().fg(Color::Green).dimmed().paint("{") |
273 | ) |
274 | .unwrap(); |
275 | } else { |
276 | write!(current_buf, " " ).unwrap(); |
277 | } |
278 | self.print_kvs(&mut current_buf, data.kvs.iter().map(|(k, v)| (*k, v))) |
279 | .unwrap(); |
280 | if self.config.bracketed_fields { |
281 | write!( |
282 | current_buf, |
283 | " {}" , |
284 | self.styled(Style::new().fg(Color::Green).bold(), "}" ) // Style::new().dimmed().paint("}") |
285 | ) |
286 | .unwrap(); |
287 | } |
288 | } |
289 | |
290 | bufs.indent_current(indent, &self.config, style); |
291 | let writer = self.make_writer.make_writer(); |
292 | bufs.flush_current_buf(writer) |
293 | } |
294 | } |
295 | |
296 | impl<S, W, FT> Layer<S> for HierarchicalLayer<W, FT> |
297 | where |
298 | S: Subscriber + for<'span> LookupSpan<'span>, |
299 | W: for<'writer> MakeWriter<'writer> + 'static, |
300 | FT: FormatTime + 'static, |
301 | { |
302 | fn on_new_span(&self, attrs: &Attributes, id: &Id, ctx: Context<S>) { |
303 | let span = ctx.span(id).expect("in new_span but span does not exist" ); |
304 | if span.extensions().get::<Data>().is_none() { |
305 | let data = Data::new(attrs); |
306 | span.extensions_mut().insert(data); |
307 | } |
308 | |
309 | if self.config.verbose_exit { |
310 | if let Some(span) = span.parent() { |
311 | self.write_span_info(&span.id(), &ctx, SpanMode::PreOpen); |
312 | } |
313 | } |
314 | |
315 | self.write_span_info( |
316 | id, |
317 | &ctx, |
318 | SpanMode::Open { |
319 | verbose: self.config.verbose_entry, |
320 | }, |
321 | ); |
322 | } |
323 | |
324 | fn on_event(&self, event: &Event<'_>, ctx: Context<S>) { |
325 | let mut guard = self.bufs.lock().unwrap(); |
326 | let bufs = &mut *guard; |
327 | let mut event_buf = &mut bufs.current_buf; |
328 | |
329 | // Time. |
330 | |
331 | { |
332 | let prev_buffer_len = event_buf.len(); |
333 | |
334 | self.timer |
335 | .format_time(&mut event_buf) |
336 | .expect("Unable to write time to buffer" ); |
337 | |
338 | // Something was written to the buffer, pad it with a space. |
339 | if prev_buffer_len < event_buf.len() { |
340 | write!(event_buf, " " ).expect("Unable to write to buffer" ); |
341 | } |
342 | } |
343 | |
344 | // printing the indentation |
345 | let indent = ctx |
346 | .event_scope(event) |
347 | .map(|scope| scope.count()) |
348 | .unwrap_or(0); |
349 | |
350 | // check if this event occurred in the context of a span. |
351 | // if it has, get the start time of this span. |
352 | let start = match ctx.current_span().id() { |
353 | Some(id) => match ctx.span(id) { |
354 | // if the event is in a span, get the span's starting point. |
355 | Some(ctx) => { |
356 | let ext = ctx.extensions(); |
357 | let data = ext |
358 | .get::<Data>() |
359 | .expect("Data cannot be found in extensions" ); |
360 | Some(data.start) |
361 | } |
362 | None => None, |
363 | }, |
364 | None => None, |
365 | }; |
366 | if let Some(start) = start { |
367 | let elapsed = start.elapsed(); |
368 | let millis = elapsed.as_millis(); |
369 | let secs = elapsed.as_secs(); |
370 | let (n, unit) = if millis < 1000 { |
371 | (millis as _, "ms" ) |
372 | } else if secs < 60 { |
373 | (secs, "s " ) |
374 | } else { |
375 | (secs / 60, "m " ) |
376 | }; |
377 | let n = format!(" {n:>3}" ); |
378 | write!( |
379 | &mut event_buf, |
380 | " {timestamp}{unit} " , |
381 | timestamp = self.styled(Style::new().dimmed(), n), |
382 | unit = self.styled(Style::new().dimmed(), unit), |
383 | ) |
384 | .expect("Unable to write to buffer" ); |
385 | } |
386 | |
387 | #[cfg (feature = "tracing-log" )] |
388 | let normalized_meta = event.normalized_metadata(); |
389 | #[cfg (feature = "tracing-log" )] |
390 | let metadata = normalized_meta.as_ref().unwrap_or_else(|| event.metadata()); |
391 | #[cfg (not(feature = "tracing-log" ))] |
392 | let metadata = event.metadata(); |
393 | |
394 | let level = metadata.level(); |
395 | let level = if self.config.ansi { |
396 | ColorLevel(level).to_string() |
397 | } else { |
398 | level.to_string() |
399 | }; |
400 | write!(&mut event_buf, " {level}" , level = level).expect("Unable to write to buffer" ); |
401 | |
402 | if self.config.targets { |
403 | let target = metadata.target(); |
404 | write!( |
405 | &mut event_buf, |
406 | " {}" , |
407 | self.styled(Style::new().dimmed(), target,), |
408 | ) |
409 | .expect("Unable to write to buffer" ); |
410 | } |
411 | |
412 | let mut visitor = FmtEvent { comma: false, bufs }; |
413 | event.record(&mut visitor); |
414 | visitor |
415 | .bufs |
416 | .indent_current(indent, &self.config, SpanMode::Event); |
417 | let writer = self.make_writer.make_writer(); |
418 | bufs.flush_current_buf(writer) |
419 | } |
420 | |
421 | fn on_close(&self, id: Id, ctx: Context<S>) { |
422 | self.write_span_info( |
423 | &id, |
424 | &ctx, |
425 | SpanMode::Close { |
426 | verbose: self.config.verbose_exit, |
427 | }, |
428 | ); |
429 | |
430 | if self.config.verbose_exit { |
431 | if let Some(span) = ctx.span(&id).and_then(|span| span.parent()) { |
432 | self.write_span_info(&span.id(), &ctx, SpanMode::PostClose); |
433 | } |
434 | } |
435 | } |
436 | } |
437 | |