log_io/compat/
tracing_layer.rs

1//! `tracing_subscriber::Layer` implementation.
2
3use core::cell::RefCell;
4use core::fmt::{self, Write as _};
5use core::ops::Range;
6
7use tracing_core::field::{Field as TracingField, Visit};
8use tracing_core::span::{Attributes, Id, Record as SpanRecord};
9use tracing_core::{Event, Subscriber};
10use tracing_subscriber::layer::{Context, Layer};
11use tracing_subscriber::registry::LookupSpan;
12
13use crate::level::Level;
14use crate::logger::Logger;
15use crate::record::{Field, Metadata};
16use crate::value::{OwnedField, Value, write_error_chain, write_hex};
17
18/// A `tracing` layer that writes events through a [`Logger`].
19///
20/// * Event levels map one to one; the event's target, file and line are
21///   preserved.
22/// * The `message` field becomes the record message; every other event
23///   field becomes a record field. Integers, floats and booleans keep
24///   their type; strings, `Debug` values and errors are rendered to
25///   text.
26/// * Fields of the spans enclosing the event (root first) are attached
27///   as context. A field on an inner span shadows the same field on an
28///   outer span, and event fields shadow span fields.
29/// * The logger's filter is applied per event. The layer does not
30///   implement `Layer::enabled`, because returning `false` there would
31///   disable the event for every other layer too; combine it with
32///   `tracing-subscriber`'s own filters if you need callsite-level
33///   filtering.
34///
35/// Event fields are collected into a reused thread-local buffer, so an
36/// event does not allocate in steady state; each span's fields are
37/// stored once, when the span is created or recorded.
38///
39/// The layer needs a subscriber that stores spans, such as
40/// `tracing_subscriber::Registry` (enable `tracing-subscriber`'s
41/// `registry` feature in your own `Cargo.toml`).
42///
43/// # Examples
44///
45#[cfg_attr(all(feature = "json", feature = "tracing"), doc = "```")]
46#[cfg_attr(not(all(feature = "json", feature = "tracing")), doc = "```ignore")]
47/// use log_io::compat::TracingLayer;
48/// use log_io::{Level, Logger};
49/// use tracing_subscriber::layer::SubscriberExt;
50///
51/// let logger = Logger::builder().level(Level::Info).stdout_json().build();
52/// let subscriber = tracing_subscriber::registry().with(TracingLayer::new(logger));
53///
54/// tracing::subscriber::with_default(subscriber, || {
55///     let span = tracing::info_span!("request", id = 7);
56///     let _entered = span.enter();
57///     tracing::info!(status = 200, "handled");
58/// });
59/// ```
60#[derive(Debug, Clone)]
61pub struct TracingLayer {
62    logger: Logger,
63}
64
65impl TracingLayer {
66    /// Wrap `logger`.
67    #[must_use]
68    pub const fn new(logger: Logger) -> Self {
69        Self { logger }
70    }
71
72    /// The wrapped logger.
73    #[must_use]
74    pub const fn logger(&self) -> &Logger {
75        &self.logger
76    }
77}
78
79const fn from_tracing_level(level: tracing_core::Level) -> Level {
80    match level {
81        tracing_core::Level::ERROR => Level::Error,
82        tracing_core::Level::WARN => Level::Warn,
83        tracing_core::Level::INFO => Level::Info,
84        tracing_core::Level::DEBUG => Level::Debug,
85        tracing_core::Level::TRACE => Level::Trace,
86    }
87}
88
89/// Owned fields stored in a span's extensions.
90#[derive(Default)]
91struct SpanFields(Vec<OwnedField>);
92
93impl SpanFields {
94    fn set(&mut self, key: &'static str, value: Value<'_>) {
95        let owned = OwnedField::new(key, value);
96        if let Some(existing) = self.0.iter_mut().find(|f| &*f.key == key) {
97            *existing = owned;
98        } else {
99            self.0.push(owned);
100        }
101    }
102}
103
104impl Visit for SpanFields {
105    fn record_f64(&mut self, field: &TracingField, value: f64) {
106        self.set(field.name(), Value::F64(value));
107    }
108    fn record_i64(&mut self, field: &TracingField, value: i64) {
109        self.set(field.name(), Value::I64(value));
110    }
111    fn record_u64(&mut self, field: &TracingField, value: u64) {
112        self.set(field.name(), Value::U64(value));
113    }
114    fn record_i128(&mut self, field: &TracingField, value: i128) {
115        self.set(field.name(), Value::I128(value));
116    }
117    fn record_u128(&mut self, field: &TracingField, value: u128) {
118        self.set(field.name(), Value::U128(value));
119    }
120    fn record_bool(&mut self, field: &TracingField, value: bool) {
121        self.set(field.name(), Value::Bool(value));
122    }
123    fn record_str(&mut self, field: &TracingField, value: &str) {
124        self.set(field.name(), Value::Str(value));
125    }
126    fn record_bytes(&mut self, field: &TracingField, value: &[u8]) {
127        self.set(field.name(), Value::Bytes(value));
128    }
129    fn record_error(&mut self, field: &TracingField, value: &(dyn std::error::Error + 'static)) {
130        self.set(field.name(), Value::Error(value));
131    }
132    fn record_debug(&mut self, field: &TracingField, value: &dyn fmt::Debug) {
133        self.set(field.name(), Value::Debug(value));
134    }
135}
136
137/// Where a collected value lives.
138#[derive(Clone)]
139enum Slot {
140    /// A value with no borrowed data.
141    Scalar(Value<'static>),
142    /// Text in the arena.
143    Text(Range<usize>),
144}
145
146/// Key of a collected field.
147#[derive(Clone)]
148enum Key {
149    Static(&'static str),
150    Text(Range<usize>),
151}
152
153/// Event fields and span fields for one event, with all text in a
154/// single reusable buffer.
155struct Arena {
156    text: String,
157    message: Option<Range<usize>>,
158    event: Vec<(Key, Slot)>,
159    /// Span fields, root span first.
160    spans: Vec<(Key, Slot)>,
161    /// Span fields as collected, leaf span first, with the start index
162    /// of each span's block. Reordered into `spans` afterwards; walking
163    /// the scope leaf-first avoids the allocation in `Scope::from_root`.
164    scratch: Vec<(Key, Slot)>,
165    blocks: Vec<usize>,
166}
167
168impl Arena {
169    const fn new() -> Self {
170        Self {
171            text: String::new(),
172            message: None,
173            event: Vec::new(),
174            spans: Vec::new(),
175            scratch: Vec::new(),
176            blocks: Vec::new(),
177        }
178    }
179
180    fn clear(&mut self) {
181        self.text.clear();
182        self.message = None;
183        self.event.clear();
184        self.spans.clear();
185        self.scratch.clear();
186        self.blocks.clear();
187    }
188
189    /// Move the collected span blocks into `spans`, root span first.
190    fn order_spans_root_first(&mut self) {
191        let mut end = self.scratch.len();
192        for &start in self.blocks.iter().rev() {
193            if let Some(block) = self.scratch.get(start..end) {
194                self.spans.extend_from_slice(block);
195            }
196            end = start;
197        }
198    }
199
200    fn push_text(&mut self, f: impl FnOnce(&mut String) -> fmt::Result) -> Range<usize> {
201        let start = self.text.len();
202        // If a user `Debug` / `Display` impl fails, keep what it wrote.
203        let _partial_text_is_kept = f(&mut self.text);
204        start..self.text.len()
205    }
206
207    fn text(&self, range: &Range<usize>) -> &str {
208        self.text.get(range.clone()).unwrap_or("")
209    }
210
211    fn key(&self, key: &Key) -> &str {
212        match key {
213            Key::Static(s) => s,
214            Key::Text(r) => self.text(r),
215        }
216    }
217
218    fn value(&self, slot: &Slot) -> Value<'_> {
219        match slot {
220            Slot::Scalar(v) => *v,
221            Slot::Text(r) => Value::Str(self.text(r)),
222        }
223    }
224
225    fn add_span_field(&mut self, field: &OwnedField) {
226        let key = Key::Text(self.push_text(|t| t.write_str(&field.key)));
227        let slot = match field.as_field().value {
228            Value::Str(s) => Slot::Text(self.push_text(|t| t.write_str(s))),
229            Value::Bytes(b) => Slot::Text(self.push_text(|t| write_hex(t, b))),
230            Value::Null => Slot::Scalar(Value::Null),
231            Value::Bool(b) => Slot::Scalar(Value::Bool(b)),
232            Value::I64(n) => Slot::Scalar(Value::I64(n)),
233            Value::U64(n) => Slot::Scalar(Value::U64(n)),
234            Value::I128(n) => Slot::Scalar(Value::I128(n)),
235            Value::U128(n) => Slot::Scalar(Value::U128(n)),
236            Value::F64(n) => Slot::Scalar(Value::F64(n)),
237            Value::Char(c) => Slot::Scalar(Value::Char(c)),
238            other => Slot::Text(self.push_text(|t| write!(t, "{other}"))),
239        };
240        self.scratch.push((key, slot));
241    }
242}
243
244/// Collects one event's fields into an [`Arena`].
245struct EventVisitor<'a>(&'a mut Arena);
246
247impl EventVisitor<'_> {
248    fn scalar(&mut self, field: &TracingField, value: Value<'static>) {
249        self.0
250            .event
251            .push((Key::Static(field.name()), Slot::Scalar(value)));
252    }
253
254    fn text(&mut self, field: &TracingField, f: impl FnOnce(&mut String) -> fmt::Result) {
255        let range = self.0.push_text(f);
256        if field.name() == "message" {
257            self.0.message = Some(range);
258        } else {
259            self.0
260                .event
261                .push((Key::Static(field.name()), Slot::Text(range)));
262        }
263    }
264}
265
266impl Visit for EventVisitor<'_> {
267    fn record_f64(&mut self, field: &TracingField, value: f64) {
268        self.scalar(field, Value::F64(value));
269    }
270    fn record_i64(&mut self, field: &TracingField, value: i64) {
271        self.scalar(field, Value::I64(value));
272    }
273    fn record_u64(&mut self, field: &TracingField, value: u64) {
274        self.scalar(field, Value::U64(value));
275    }
276    fn record_i128(&mut self, field: &TracingField, value: i128) {
277        self.scalar(field, Value::I128(value));
278    }
279    fn record_u128(&mut self, field: &TracingField, value: u128) {
280        self.scalar(field, Value::U128(value));
281    }
282    fn record_bool(&mut self, field: &TracingField, value: bool) {
283        self.scalar(field, Value::Bool(value));
284    }
285    fn record_str(&mut self, field: &TracingField, value: &str) {
286        self.text(field, |t| t.write_str(value));
287    }
288    fn record_bytes(&mut self, field: &TracingField, value: &[u8]) {
289        self.text(field, |t| write_hex(t, value));
290    }
291    fn record_error(&mut self, field: &TracingField, value: &(dyn std::error::Error + 'static)) {
292        self.text(field, |t| write_error_chain(t, value));
293    }
294    fn record_debug(&mut self, field: &TracingField, value: &dyn fmt::Debug) {
295        self.text(field, |t| write!(t, "{value:?}"));
296    }
297}
298
299thread_local! {
300    static ARENA: RefCell<Arena> = const { RefCell::new(Arena::new()) };
301}
302
303/// Arena capacity kept between events; larger buffers are released.
304const MAX_RETAINED_TEXT: usize = 64 * 1024;
305
306impl<S> Layer<S> for TracingLayer
307where
308    S: Subscriber + for<'lookup> LookupSpan<'lookup>,
309{
310    fn on_new_span(&self, attrs: &Attributes<'_>, id: &Id, ctx: Context<'_, S>) {
311        let Some(span) = ctx.span(id) else {
312            return;
313        };
314        let mut fields = SpanFields::default();
315        attrs.record(&mut fields);
316        span.extensions_mut().insert(fields);
317    }
318
319    fn on_record(&self, id: &Id, values: &SpanRecord<'_>, ctx: Context<'_, S>) {
320        let Some(span) = ctx.span(id) else {
321            return;
322        };
323        let mut extensions = span.extensions_mut();
324        if let Some(fields) = extensions.get_mut::<SpanFields>() {
325            values.record(fields);
326        } else {
327            let mut fields = SpanFields::default();
328            values.record(&mut fields);
329            extensions.insert(fields);
330        }
331    }
332
333    fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) {
334        let meta = event.metadata();
335        let level = from_tracing_level(*meta.level());
336        let target = meta.target();
337        if !self.logger.enabled(target, level) {
338            return;
339        }
340        let pooled = ARENA.try_with(|cell| {
341            let mut arena = cell.try_borrow_mut().ok()?;
342            self.emit(&mut arena, event, &ctx, level);
343            if arena.text.capacity() > MAX_RETAINED_TEXT {
344                arena.text = String::new();
345            }
346            Some(())
347        });
348        if !matches!(pooled, Ok(Some(()))) {
349            // Reentrant event from inside a sink, or thread teardown.
350            self.emit(&mut Arena::new(), event, &ctx, level);
351        }
352    }
353}
354
355impl TracingLayer {
356    fn emit<S>(&self, arena: &mut Arena, event: &Event<'_>, ctx: &Context<'_, S>, level: Level)
357    where
358        S: Subscriber + for<'lookup> LookupSpan<'lookup>,
359    {
360        arena.clear();
361        event.record(&mut EventVisitor(arena));
362        if let Some(scope) = ctx.event_scope(event) {
363            for span in scope {
364                let extensions = span.extensions();
365                if let Some(fields) = extensions.get::<SpanFields>() {
366                    arena.blocks.push(arena.scratch.len());
367                    for field in &fields.0 {
368                        arena.add_span_field(field);
369                    }
370                }
371            }
372            arena.order_spans_root_first();
373        }
374
375        let meta = event.metadata();
376        let mut metadata = Metadata::new(level, meta.target());
377        if let (Some(file), Some(line)) = (meta.file(), meta.line()) {
378            metadata = metadata.with_location(file, line);
379        }
380        let arena = &*arena;
381        let message = arena.message.as_ref().map_or("", |r| arena.text(r));
382        with_fields(arena, &arena.event, |fields| {
383            with_fields(arena, &arena.spans, |spans| {
384                // Failures were already passed to the error handler.
385                let _reported = self.logger.emit_unchecked(metadata, message, fields, spans);
386            });
387        });
388    }
389}
390
391/// Materialize collected fields as `Field`s: on the stack for up to 16,
392/// on the heap beyond that.
393fn with_fields(arena: &Arena, items: &[(Key, Slot)], f: impl FnOnce(&[Field<'_>])) {
394    const EMPTY: Field<'static> = Field {
395        key: "",
396        value: Value::Null,
397    };
398    if items.len() <= 16 {
399        let mut buf = [EMPTY; 16];
400        for (slot, (key, value)) in buf.iter_mut().zip(items) {
401            *slot = Field {
402                key: arena.key(key),
403                value: arena.value(value),
404            };
405        }
406        f(&buf[..items.len()]);
407    } else {
408        let fields: Vec<Field<'_>> = items
409            .iter()
410            .map(|(key, value)| Field {
411                key: arena.key(key),
412                value: arena.value(value),
413            })
414            .collect();
415        f(&fields);
416    }
417}
418
419#[cfg(all(test, feature = "logfmt"))]
420mod tests {
421    use super::*;
422    use crate::format::LogfmtFormat;
423    use std::io::Write;
424    use std::sync::{Arc, Mutex};
425    use tracing_subscriber::layer::SubscriberExt;
426
427    #[derive(Default, Clone)]
428    struct Capture(Arc<Mutex<Vec<u8>>>);
429    impl Write for Capture {
430        fn write(&mut self, buf: &[u8]) -> std::io::Result<usize> {
431            self.0.lock().unwrap().extend_from_slice(buf);
432            Ok(buf.len())
433        }
434        fn flush(&mut self) -> std::io::Result<()> {
435            Ok(())
436        }
437    }
438    impl Capture {
439        fn take(&self) -> String {
440            String::from_utf8(std::mem::take(&mut *self.0.lock().unwrap())).unwrap()
441        }
442    }
443
444    fn layer(level: Level) -> (TracingLayer, Capture) {
445        let out = Capture::default();
446        let logger = Logger::builder()
447            .level(level)
448            .no_timestamps()
449            .no_context()
450            .writer(out.clone(), LogfmtFormat::new())
451            .build();
452        (TracingLayer::new(logger), out)
453    }
454
455    #[test]
456    fn test_tracing_layer_event_fields_and_message() {
457        let (layer, out) = layer(Level::Trace);
458        let subscriber = tracing_subscriber::registry().with(layer);
459        tracing::subscriber::with_default(subscriber, || {
460            let err = std::io::Error::other("reset");
461            tracing::warn!(
462                target: "app::net",
463                status = 503_u16,
464                retry = true,
465                ratio = 0.25,
466                peer = %"10.0.0.1",
467                tags = ?["a", "b"],
468                big = u128::MAX,
469                error = &err as &(dyn std::error::Error + 'static),
470                "upstream {} failed", "db"
471            );
472        });
473        let text = out.take();
474        assert!(
475            text.starts_with("level=warn target=app::net message=\"upstream db failed\" file="),
476            "{text}"
477        );
478        assert!(
479            text.contains(" status=503 retry=true ratio=0.25 peer=10.0.0.1 "),
480            "{text}"
481        );
482        assert!(text.contains("tags=\"[\\\"a\\\", \\\"b\\\"]\""), "{text}");
483        assert!(text.contains(&format!("big={}", u128::MAX)), "{text}");
484        assert!(text.contains("error=reset"), "{text}");
485    }
486
487    #[test]
488    fn test_tracing_layer_attaches_span_fields_with_shadowing() {
489        let (layer, out) = layer(Level::Trace);
490        let subscriber = tracing_subscriber::registry().with(layer);
491        tracing::subscriber::with_default(subscriber, || {
492            let outer = tracing::info_span!(
493                "request",
494                id = 7_u64,
495                user = "alice",
496                tenant = tracing::field::Empty
497            );
498            let _o = outer.enter();
499            let _span = outer.record("tenant", "acme");
500            let inner = tracing::debug_span!("db", user = "svc", bytes = tracing::field::Empty);
501            let _i = inner.enter();
502            let _span = inner.record("bytes", &b"\x01\xff"[..]);
503            tracing::info!(user = "event", "query");
504            tracing::info!("no user field on the event");
505        });
506        let text = out.take();
507        let mut lines = text.lines();
508        let first = lines.next().unwrap_or_default();
509        let second = lines.next().unwrap_or_default();
510        assert!(
511            second.contains(" user=svc"),
512            "inner span shadows outer: {second}"
513        );
514        assert!(
515            second.find(" id=7").unwrap() < second.find(" user=svc").unwrap(),
516            "root span fields come first: {second}"
517        );
518        let text = first.to_owned();
519        assert!(text.contains(" id=7 "), "{text}");
520        assert!(text.contains(" tenant=acme "), "{text}");
521        assert!(text.contains(" bytes=01ff"), "{text}");
522        assert_eq!(text.matches("user=").count(), 1, "{text}");
523        assert!(text.contains(" user=event"), "{text}");
524    }
525
526    #[test]
527    fn test_tracing_layer_applies_logger_filter() {
528        let (layer, out) = layer(Level::Warn);
529        assert_eq!(layer.logger().min_level(), Level::Warn);
530        let subscriber = tracing_subscriber::registry().with(layer);
531        tracing::subscriber::with_default(subscriber, || {
532            tracing::info!("dropped");
533            tracing::error!("kept");
534            tracing::trace!("dropped too");
535            tracing::debug!("dropped as well");
536        });
537        let text = out.take();
538        assert!(!text.contains("dropped"), "{text}");
539        assert!(text.contains("message=kept"), "{text}");
540    }
541
542    #[test]
543    fn test_tracing_layer_many_fields_spill_to_heap() {
544        let (layer, out) = layer(Level::Trace);
545        let subscriber = tracing_subscriber::registry().with(layer);
546        tracing::subscriber::with_default(subscriber, || {
547            tracing::info!(
548                a0 = 0,
549                a1 = 1,
550                a2 = 2,
551                a3 = 3,
552                a4 = 4,
553                a5 = 5,
554                a6 = 6,
555                a7 = 7,
556                a8 = 8,
557                a9 = 9,
558                a10 = 10,
559                a11 = 11,
560                a12 = 12,
561                a13 = 13,
562                a14 = 14,
563                a15 = 15,
564                a16 = 16,
565                a17 = 17,
566                "wide"
567            );
568        });
569        let text = out.take();
570        for i in 0..18 {
571            assert!(text.contains(&format!(" a{i}={i}")), "a{i}: {text}");
572        }
573    }
574
575    #[test]
576    fn test_tracing_level_mapping() {
577        assert_eq!(from_tracing_level(tracing_core::Level::TRACE), Level::Trace);
578        assert_eq!(from_tracing_level(tracing_core::Level::DEBUG), Level::Debug);
579        assert_eq!(from_tracing_level(tracing_core::Level::INFO), Level::Info);
580        assert_eq!(from_tracing_level(tracing_core::Level::WARN), Level::Warn);
581        assert_eq!(from_tracing_level(tracing_core::Level::ERROR), Level::Error);
582    }
583}
log_io/compat/tracing_layer.rs

log_io/compat/
tracing_layer.rs
