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

rich_ext/
log_handler.rs
