rich_ext/
log_handler.rs

1//! A log sink in the style of upstream `rich.logging.RichHandler`.
2//!
3//! [`RichHandler`] renders [`StructuredEvent`]s through core's
4//! [`LogRender`]: the time (blanked when it repeats), the
5//! level padded to 8 cells in `logging.level.<name>`, the message run through
6//! a highlighter and keyword highlighting, and the source file name with its
7//! line, linked to the full path. Behind the `log` and `tracing` features it
8//! is an `adapters::EventSink`, so the existing `LogAdapter` and `EventLayer`
9//! print through it.
10//!
11//! Beyond upstream, which has no spans:
12//!
13//! - An event's [spans](StructuredEvent::span_context) show before its message
14//!   (`outer{id=7}:inner: message`), or as tree guides with
15//!   [`SpanView::Tree`], where span open and close events draw the branches.
16//! - [`RichHandler::hyperlinker`] links the path column through a
17//!   [`Hyperlinker`], so an editor URL template or a base directory for
18//!   relative paths applies.
19//! - [`RichHandler::live`] prints through a [`LiveCoordinator`], above its
20//!   regions, instead of writing to the console under them.
21//!
22//! Upstream formats `record.created` in local time with `[%x %X]`. Local time
23//! needs a time-zone dependency, so the default here is UTC `[HH:MM:SS]`; an
24//! event's own `timestamp` or a [`RichHandler::time_format`] closure replaces
25//! it. Traceback rendering (`rich_tracebacks`) has no Rust counterpart.
26
27use std::io::Write;
28use std::sync::{Arc, Mutex};
29use std::time::{Duration, SystemTime, UNIX_EPOCH};
30
31use rich::{
32    Console, ConsoleOptions, Highlighter, LogRender, ReprHighlighter, Segment, Table, Text,
33};
34
35use crate::event::{Message, Severity, SpanContext, SpanEvent, StructuredEvent};
36use crate::hyperlink::Hyperlinker;
37use crate::live::{LiveCoordinator, LiveError};
38
39/// Upstream `RichHandler.KEYWORDS`: HTTP methods, styled `logging.keyword`.
40pub const KEYWORDS: &[&str] = &[
41    "GET", "POST", "HEAD", "PUT", "DELETE", "OPTIONS", "TRACE", "PATCH",
42];
43
44type TimeFormat = Box<dyn Fn() -> String + Send + Sync>;
45type Output = Box<dyn Fn(&[Segment]) -> std::io::Result<()> + Send + Sync>;
46
47/// How an event's spans are shown.
48#[derive(Clone, Copy, Debug, Default, PartialEq, Eq)]
49pub enum SpanView {
50    /// Before the message, outermost first: `outer{id=7}:inner: message`.
51    #[default]
52    Inline,
53    /// As guides: each span indents the events inside it by one `│ `, its
54    /// open event draws `┌ name field=value` and its close event
55    /// `└ name 1.20ms`.
56    Tree,
57    /// Not shown.
58    Hidden,
59}
60
61/// Renders log events like upstream's `RichHandler`.
62pub struct RichHandler {
63    console: Mutex<Console>,
64    render: Mutex<LogRender>,
65    highlighter: Option<Box<dyn Highlighter + Send + Sync>>,
66    markup: bool,
67    keywords: Vec<String>,
68    enable_link_path: bool,
69    time_format: TimeFormat,
70    span_view: SpanView,
71    hyperlinker: Option<Hyperlinker>,
72    output: Option<Output>,
73}
74
75impl RichHandler {
76    /// A handler printing to `console`, with upstream's defaults: time, level
77    /// and path shown, repeated times omitted, [`ReprHighlighter`], no markup,
78    /// [`KEYWORDS`] highlighted and paths linked.
79    pub fn new(console: Console) -> Self {
80        RichHandler {
81            console: Mutex::new(console),
82            render: Mutex::new(LogRender::new().show_level(true)),
83            highlighter: Some(Box::new(ReprHighlighter::new())),
84            markup: false,
85            keywords: KEYWORDS.iter().map(|word| word.to_string()).collect(),
86            enable_link_path: true,
87            time_format: Box::new(utc_time),
88            span_view: SpanView::Inline,
89            hyperlinker: None,
90            output: None,
91        }
92    }
93
94    /// How an event's spans are shown (default [`SpanView::Inline`]).
95    pub fn span_view(mut self, view: SpanView) -> Self {
96        self.span_view = view;
97        self
98    }
99
100    /// Link the path column through `hyperlinker` instead of a bare `file://`
101    /// URL: its editor template, base directory for relative paths (as
102    /// `tracing` reports them) and on/off switch apply.
103    pub fn hyperlinker(mut self, hyperlinker: Hyperlinker) -> Self {
104        self.hyperlinker = Some(hyperlinker);
105        self
106    }
107
108    /// Print through `live`, above its regions, so log lines never tear a
109    /// live display. Render with a console as wide as `live`'s target (see
110    /// `RenderTarget::console`); longer lines fold. The coordinator refuses
111    /// control codes, so any in a line (a message, field, span or path) are
112    /// shown as symbols instead: every line prints.
113    pub fn live<W: Write + Send + 'static>(mut self, live: Arc<Mutex<LiveCoordinator<W>>>) -> Self {
114        self.output = Some(Box::new(move |segments| {
115            let segments = neutralise(segments);
116            live.lock()
117                .unwrap_or_else(|e| e.into_inner())
118                .print(&segments)
119                .map_err(|error| match error {
120                    LiveError::Io(error) => error,
121                    other => std::io::Error::other(other.to_string()),
122                })
123        }));
124        self
125    }
126
127    fn map_render(self, f: impl FnOnce(LogRender) -> LogRender) -> Self {
128        let render = self.render.into_inner().unwrap_or_else(|e| e.into_inner());
129        RichHandler {
130            render: Mutex::new(f(render)),
131            ..self
132        }
133    }
134
135    /// Show the time column (upstream `show_time`).
136    pub fn show_time(self, show: bool) -> Self {
137        self.map_render(|render| render.show_time(show))
138    }
139
140    /// Show the level column (upstream `show_level`).
141    pub fn show_level(self, show: bool) -> Self {
142        self.map_render(|render| render.show_level(show))
143    }
144
145    /// Show the path column (upstream `show_path`).
146    pub fn show_path(self, show: bool) -> Self {
147        self.map_render(|render| render.show_path(show))
148    }
149
150    /// Blank a time equal to the previous record's (upstream
151    /// `omit_repeated_times`).
152    pub fn omit_repeated_times(self, omit: bool) -> Self {
153        self.map_render(|render| render.omit_repeated_times(omit))
154    }
155
156    /// The level column's width, or `None` to fit (upstream `log_time_format`'s
157    /// sibling `level_width`, fixed at 8 upstream).
158    pub fn level_width(self, width: Option<usize>) -> Self {
159        self.map_render(|render| render.level_width(width))
160    }
161
162    /// Parse messages as console markup (upstream `markup`).
163    pub fn markup(mut self, markup: bool) -> Self {
164        self.markup = markup;
165        self
166    }
167
168    /// The message highlighter, or `None` for none (upstream `highlighter`).
169    pub fn highlighter(mut self, highlighter: Option<Box<dyn Highlighter + Send + Sync>>) -> Self {
170        self.highlighter = highlighter;
171        self
172    }
173
174    /// Words styled `logging.keyword` (upstream `keywords`).
175    pub fn keywords<I, S>(mut self, keywords: I) -> Self
176    where
177        I: IntoIterator<Item = S>,
178        S: Into<String>,
179    {
180        self.keywords = keywords.into_iter().map(Into::into).collect();
181        self
182    }
183
184    /// Link the path column to the source file (upstream `enable_link_path`).
185    pub fn enable_link_path(mut self, enable: bool) -> Self {
186        self.enable_link_path = enable;
187        self
188    }
189
190    /// Format the current time for events without a `timestamp` (upstream
191    /// `log_time_format`).
192    pub fn time_format(mut self, format: impl Fn() -> String + Send + Sync + 'static) -> Self {
193        self.time_format = Box::new(format);
194        self
195    }
196
197    /// The level column. Port of `RichHandler.get_level_text`, with Python's
198    /// level names (`WARNING`, `CRITICAL`); `TRACE` uses `logging.level.notset`.
199    pub fn level_text(severity: Severity) -> Text {
200        let name = match severity {
201            Severity::Trace => {
202                return Text::styled(format!("{:<8}", "TRACE"), "logging.level.notset")
203            }
204            Severity::Debug => "DEBUG",
205            Severity::Info => "INFO",
206            Severity::Warn => "WARNING",
207            Severity::Error => "ERROR",
208            Severity::Fatal => "CRITICAL",
209        };
210        rich::level_text(name)
211    }
212
213    /// The message column. Port of `RichHandler.render_message`; structured
214    /// fields follow the message as `key=value`.
215    pub fn render_message(&self, event: &StructuredEvent) -> Text {
216        let ascii = self
217            .console
218            .lock()
219            .unwrap_or_else(|e| e.into_inner())
220            .ascii_only();
221        self.message_text(event, ascii)
222    }
223
224    /// [`render_message`](Self::render_message) with tree guides in ASCII when
225    /// `ascii`; callers holding the console lock pass it in.
226    fn message_text(&self, event: &StructuredEvent, ascii: bool) -> Text {
227        let spans = event.span_context();
228        let mut text = match event.span_marker() {
229            Some(marker) => self.span_line(event, marker, ascii),
230            None => {
231                let mut text = self.prefix(spans, ascii);
232                text = text.append_text(&match &event.message {
233                    Message::Literal(message) if !self.markup => Text::new(message.clone()),
234                    Message::Literal(markup) | Message::Markup(markup) => {
235                        Text::from_markup(markup).unwrap_or_else(|_| Text::new(markup.clone()))
236                    }
237                });
238                for (key, value) in &event.fields {
239                    text.append(&format!(" {key}={}", value.format(false, 0)), None);
240                }
241                text
242            }
243        };
244        if let Some(highlighter) = &self.highlighter {
245            highlighter.highlight(&mut text);
246        }
247        if !self.keywords.is_empty() {
248            let words: Vec<&str> = self.keywords.iter().map(String::as_str).collect();
249            let _ = text.highlight_words(&words, "logging.keyword", true);
250        }
251        text
252    }
253
254    /// What comes before a message for `spans`: the span chain, tree guides
255    /// or nothing, as [`SpanView`] says.
256    fn prefix(&self, spans: &[SpanContext], ascii: bool) -> Text {
257        let mut text = Text::new("");
258        match self.span_view {
259            SpanView::Hidden => {}
260            SpanView::Tree => text.append(&guide(ascii).repeat(spans.len()), Some("dim".into())),
261            SpanView::Inline if spans.is_empty() => {}
262            SpanView::Inline => {
263                for (index, span) in spans.iter().enumerate() {
264                    if index > 0 {
265                        text.append(":", Some("dim".into()));
266                    }
267                    text = text.append_text(&span_label(span, "{", "}"));
268                }
269                text.append(": ", Some("dim".into()));
270            }
271        }
272        text
273    }
274
275    /// The message of a span open or close event: `event`'s message is the
276    /// span's name, its fields the span's and its spans the span's parents.
277    fn span_line(&self, event: &StructuredEvent, marker: SpanEvent, ascii: bool) -> Text {
278        let name = match &event.message {
279            Message::Literal(name) | Message::Markup(name) => name.clone(),
280        };
281        let span = SpanContext {
282            name,
283            fields: event.fields.clone(),
284        };
285        let parents = event.span_context();
286        let elapsed = match marker {
287            SpanEvent::Open => None,
288            SpanEvent::Close { elapsed } => Some(elapsed),
289        };
290        let mut text = Text::new("");
291        match self.span_view {
292            SpanView::Tree => {
293                text.append(&guide(ascii).repeat(parents.len()), Some("dim".into()));
294                let corner = match (elapsed.is_some(), ascii) {
295                    (false, false) => "┌ ",
296                    (true, false) => "└ ",
297                    (false, true) => "+ ",
298                    (true, true) => "` ",
299                };
300                text.append(corner, Some("dim".into()));
301                // The open line shows the fields; the close line only times it.
302                if elapsed.is_some() {
303                    text = text.append_text(&Text::styled(span.name.clone(), "bold"));
304                } else {
305                    text = text.append_text(&span_label(&span, " ", ""));
306                }
307            }
308            SpanView::Inline | SpanView::Hidden => {
309                if self.span_view == SpanView::Inline {
310                    for parent in parents {
311                        text = text.append_text(&span_label(parent, "{", "}"));
312                        text.append(":", Some("dim".into()));
313                    }
314                }
315                text = text.append_text(&span_label(&span, "{", "}"));
316                text.append(
317                    if elapsed.is_some() {
318                        " closed"
319                    } else {
320                        " opened"
321                    },
322                    Some("dim".into()),
323                );
324            }
325        }
326        if let Some(elapsed) = elapsed {
327            text.append(" ", None);
328            text.append(&format_elapsed(elapsed), Some("dim".into()));
329        }
330        text
331    }
332
333    /// Lay out one event. Port of `RichHandler.render`.
334    pub fn render(&self, event: &StructuredEvent) -> Table {
335        let console = self.console.lock().unwrap_or_else(|e| e.into_inner());
336        self.render_with(&console, event)
337    }
338
339    fn render_with(&self, console: &Console, event: &StructuredEvent) -> Table {
340        let context = &event.context;
341        let time = context
342            .timestamp
343            .clone()
344            .unwrap_or_else(|| (self.time_format)());
345        let level = Self::level_text(context.severity.unwrap_or(Severity::Info));
346        let source = context.source.as_ref();
347        let full_path = source.map(|source| source.path.as_str());
348        let name = full_path.map(|path| path.rsplit(['/', '\\']).next().unwrap_or(path));
349        let render = self.render.lock().unwrap_or_else(|e| e.into_inner());
350        render.render(
351            console,
352            self.message_text(event, console.ascii_only()),
353            Some(Text::new(time)),
354            level,
355            name,
356            source.and_then(|source| u32::try_from(source.line).ok()),
357            full_path.filter(|_| self.enable_link_path),
358        )
359    }
360
361    /// Print one event. Port of `RichHandler.emit`.
362    pub fn emit_event(&self, event: &StructuredEvent) {
363        let _ = self.try_emit(event);
364    }
365
366    fn try_emit(&self, event: &StructuredEvent) -> std::io::Result<()> {
367        let console = self.console.lock().unwrap_or_else(|e| e.into_inner());
368        let table = self.render_with(&console, event);
369        if self.hyperlinker.is_none() && self.output.is_none() {
370            console.print(&table);
371            return Ok(());
372        }
373        let mut lines = console.render_lines(&table, &console.options(), false);
374        if let (Some(hyperlinker), Some(source)) = (&self.hyperlinker, &event.context.source) {
375            let line = Some(source.line).filter(|&line| line > 0);
376            let url = hyperlinker.file_url(&source.path, line, None);
377            relink(&mut lines, &source.path, url.as_deref());
378        }
379        match &self.output {
380            Some(output) => output(&join_lines(lines)),
381            None => {
382                console.print(&Lines(lines));
383                Ok(())
384            }
385        }
386    }
387}
388
389/// `segments` with the control codes a [`LiveCoordinator`] rejects made
390/// inert: control segments dropped, text passed through
391/// [`sanitize_terminal_controls`](crate::sanitize_terminal_controls) and
392/// control characters in links percent-encoded.
393fn neutralise(segments: &[Segment]) -> Vec<Segment> {
394    segments
395        .iter()
396        .filter(|segment| !segment.control)
397        .map(|segment| {
398            let mut segment = segment.clone();
399            if segment
400                .text
401                .chars()
402                .any(|c| c.is_control() && c != '\n' && c != '\t')
403            {
404                segment.text = crate::sanitize_terminal_controls(&segment.text);
405            }
406            if let Some(style) = &segment.style {
407                if let Some(link) = style
408                    .link()
409                    .filter(|link| link.chars().any(char::is_control))
410                {
411                    use std::fmt::Write as _;
412                    let mut encoded = String::with_capacity(link.len());
413                    for c in link.chars() {
414                        if c.is_control() {
415                            let mut bytes = [0; 4];
416                            for byte in c.encode_utf8(&mut bytes).bytes() {
417                                let _ = write!(encoded, "%{byte:02X}");
418                            }
419                        } else {
420                            encoded.push(c);
421                        }
422                    }
423                    segment.style = Some(style.update_link(Some(encoded)));
424                }
425            }
426            segment
427        })
428        .collect()
429}
430
431/// One tree level: `│ ` (or `| ` in ASCII).
432fn guide(ascii: bool) -> &'static str {
433    if ascii {
434        "| "
435    } else {
436        "│ "
437    }
438}
439
440/// `name{a=1 b=2}` (or `name a=1 b=2`, with `open` = `" "` and `close` = `""`),
441/// the name bold.
442fn span_label(span: &SpanContext, open: &str, close: &str) -> Text {
443    let mut text = Text::styled(span.name.clone(), "bold");
444    if !span.fields.is_empty() {
445        let fields: Vec<String> = span
446            .fields
447            .iter()
448            .map(|(key, value)| format!("{key}={}", value.format(false, 0)))
449            .collect();
450        text.append(open, Some("dim".into()));
451        text.append(&fields.join(" "), None);
452        text.append(close, Some("dim".into()));
453    }
454    text
455}
456
457/// `850µs`, `1.20ms` or `2.50s`.
458fn format_elapsed(elapsed: Duration) -> String {
459    let micros = elapsed.as_secs_f64() * 1e6;
460    if micros < 1000.0 {
461        format!("{micros:.0}µs")
462    } else if micros < 1e6 {
463        format!("{:.2}ms", micros / 1e3)
464    } else {
465        format!("{:.2}s", micros / 1e6)
466    }
467}
468
469/// Point the path column's `file://` link (from `LogRender`) at `url`, or
470/// drop it when the hyperlinker is off.
471fn relink(lines: &mut [Vec<Segment>], path: &str, url: Option<&str>) {
472    let bare = format!("file://{path}");
473    for segment in lines.iter_mut().flatten() {
474        let Some(style) = &segment.style else {
475            continue;
476        };
477        let linked = style
478            .link()
479            .is_some_and(|link| link == bare || link.starts_with(&format!("{bare}#")));
480        if linked {
481            segment.style = Some(style.update_link(url.map(str::to_owned)));
482        }
483    }
484}
485
486fn join_lines(lines: Vec<Vec<Segment>>) -> Vec<Segment> {
487    let mut segments = Vec::new();
488    for (index, line) in lines.into_iter().enumerate() {
489        if index > 0 {
490            segments.push(Segment::line());
491        }
492        segments.extend(line);
493    }
494    segments
495}
496
497/// Lines already rendered, printed as they are.
498struct Lines(Vec<Vec<Segment>>);
499
500impl rich::Renderable for Lines {
501    fn rich_render(&self, _: &Console, _: &ConsoleOptions) -> Vec<Segment> {
502        join_lines(self.0.clone())
503    }
504}
505
506#[cfg(any(feature = "log", feature = "tracing"))]
507impl crate::adapters::EventSink for RichHandler {
508    fn emit(&self, event: StructuredEvent) -> std::io::Result<()> {
509        self.emit_event(&event);
510        Ok(())
511    }
512}
513
514/// UTC `[HH:MM:SS]`.
515fn utc_time() -> String {
516    let secs = SystemTime::now()
517        .duration_since(UNIX_EPOCH)
518        .map_or(0, |elapsed| elapsed.as_secs());
519    let day = secs % 86_400;
520    format!("[{:02}:{:02}:{:02}]", day / 3600, day / 60 % 60, day % 60)
521}
522
523#[cfg(test)]
524mod tests {
525    use super::*;
526    use crate::event::{EventContext, SourceLocation, Value};
527
528    fn handler() -> RichHandler {
529        let console = Console::builder()
530            .force_terminal(true)
531            .color_system(Some(rich::ColorSystem::Truecolor))
532            .width(60)
533            .build();
534        RichHandler::new(console).time_format(|| "[12:00:00]".into())
535    }
536
537    fn event(message: &str, severity: Severity) -> StructuredEvent {
538        StructuredEvent::new(Message::Literal(message.into())).context(EventContext {
539            severity: Some(severity),
540            source: Some(SourceLocation {
541                path: "src/server/main.rs".into(),
542                line: 42,
543                column: None,
544            }),
545            ..Default::default()
546        })
547    }
548
549    #[test]
550    fn renders_time_level_message_and_file_name() {
551        let handler = handler().enable_link_path(false);
552        let console = handler.console.lock().unwrap();
553        let plain = console
554            .render_to_string(&handler.render_with(&console, &event("GET /index", Severity::Warn)));
555        assert!(plain.contains("[12:00:00]"), "{plain:?}");
556        assert!(plain.contains("WARNING"), "{plain:?}");
557        assert!(plain.contains("main.rs:42"), "{plain:?}");
558        assert!(!plain.contains("src/server"), "{plain:?}");
559        // `logging.keyword` is bold yellow.
560        assert!(plain.contains("\x1b[1;33mGET\x1b[0m"), "{plain:?}");
561    }
562
563    #[test]
564    fn links_the_full_path_and_appends_fields() {
565        let handler = handler();
566        let console = handler.console.lock().unwrap();
567        let event = event("ready", Severity::Info).field("count", Value::Integer(3));
568        let out = console.render_to_string(&handler.render_with(&console, &event));
569        assert!(out.contains("file://src/server/main.rs#42"), "{out:?}");
570        assert!(out.contains("\x1b[33mcount\x1b[0m=\x1b[1;36m3"), "{out:?}");
571    }
572
573    #[test]
574    fn fatal_is_critical_and_trace_is_notset() {
575        assert_eq!(RichHandler::level_text(Severity::Fatal).plain(), "CRITICAL");
576        let trace = RichHandler::level_text(Severity::Trace);
577        assert_eq!(trace.plain(), "TRACE   ");
578    }
579}
rich_ext/log_handler.rs

rich_ext/
log_handler.rs
