Merge pull request #56 from TmLev/main

Format and print time at which event has occurred

Author: oli-obk

Cargo.toml

@@ -14,6 +14,7 @@ tracing-subscriber = { version = "0.3", default-features = false, features = ["r
 nu-ansi-term = "0.46.0"
 atty = "0.2"
 tracing-log = { version = "0.1", optional = true }
+time = { version = "0.3.20", optional = true, features = ["formatting", "local-offset"] }
 
 [features]
 default = ["tracing-log"]

src/lib.rs

@@ -1,6 +1,9 @@
 pub(crate) mod format;
+pub mod time;
 
+use crate::time::FormatTime;
 use format::{Buffers, ColorLevel, Config, FmtEvent, SpanMode};
+
 use nu_ansi_term::{Color, Style};
 use std::{
     fmt::{self, Write as _},
@@ -43,13 +46,15 @@ impl Visit for Data {
     }
 }
 #[derive(Debug)]
-pub struct HierarchicalLayer<W = fn() -> io::Stderr>
+pub struct HierarchicalLayer<W = fn() -> io::Stderr, FT = ()>
 where
     W: for<'writer> MakeWriter<'writer> + 'static,
+    FT: FormatTime,
 {
     make_writer: W,
     bufs: Mutex<Buffers>,
     config: Config,
+    timer: FT,
 }
 
 impl Default for HierarchicalLayer {
@@ -70,13 +75,15 @@ impl HierarchicalLayer<fn() -> io::Stderr> {
             make_writer: io::stderr,
             bufs: Mutex::new(Buffers::new()),
             config,
+            timer: (),
         }
     }
 }
 
-impl<W> HierarchicalLayer<W>
+impl<W, FT> HierarchicalLayer<W, FT>
 where
     W: for<'writer> MakeWriter<'writer> + 'static,
+    FT: FormatTime,
 {
     /// Enables terminal colors, boldness and italics.
     pub fn with_ansi(self, ansi: bool) -> Self {
@@ -86,14 +93,15 @@ where
         }
     }
 
-    pub fn with_writer<W2>(self, make_writer: W2) -> HierarchicalLayer<W2>
+    pub fn with_writer<W2>(self, make_writer: W2) -> HierarchicalLayer<W2, FT>
     where
         W2: for<'writer> MakeWriter<'writer>,
     {
         HierarchicalLayer {
             make_writer,
             config: self.config,
             bufs: self.bufs,
+            timer: self.timer,
         }
     }
 
@@ -113,6 +121,16 @@ where
         }
     }
 
+    /// Specifies how to measure and format time at which event has occurred.
+    pub fn with_timer<FT2: FormatTime>(self, timer: FT2) -> HierarchicalLayer<W, FT2> {
+        HierarchicalLayer {
+            make_writer: self.make_writer,
+            config: self.config,
+            bufs: self.bufs,
+            timer,
+        }
+    }
+
     /// Whether to render the event and span targets. Usually targets are the module path to the
     /// event/span macro invocation.
     pub fn with_targets(self, targets: bool) -> Self {
@@ -274,10 +292,11 @@ where
     }
 }
 
-impl<S, W> Layer<S> for HierarchicalLayer<W>
+impl<S, W, FT> Layer<S> for HierarchicalLayer<W, FT>
 where
     S: Subscriber + for<'span> LookupSpan<'span>,
     W: for<'writer> MakeWriter<'writer> + 'static,
+    FT: FormatTime + 'static,
 {
     fn on_new_span(&self, attrs: &Attributes, id: &Id, ctx: Context<S>) {
         let span = ctx.span(id).expect("in new_span but span does not exist");
@@ -306,6 +325,21 @@ where
         let bufs = &mut *guard;
         let mut event_buf = &mut bufs.current_buf;
 
+        // Time.
+
+        {
+            let prev_buffer_len = event_buf.len();
+
+            self.timer
+                .format_time(&mut event_buf)
+                .expect("Unable to write time to buffer");
+
+            // Something was written to the buffer, pad it with a space.
+            if prev_buffer_len < event_buf.len() {
+                write!(event_buf, " ").expect("Unable to write to buffer");
+            }
+        }
+
         // printing the indentation
         let indent = ctx
             .event_scope(event)

src/time.rs

@@ -0,0 +1,119 @@
+/// A type that can measure and format the current time.
+///
+/// This trait is used by [HierarchicalLayer] to include a timestamp with each
+/// [Event] when it is logged.
+///
+/// Notable default implementations of this trait are [LocalDateTime] and `()`.
+/// The former prints the current time as reported by [time's OffsetDateTime]
+/// (note that it requires a `time` feature to be enabled and may panic!
+/// make sure to check out the docs for the [LocalDateTime]),
+/// and the latter does not print the current time at all.
+///
+/// Inspired by the [FormatTime] trait from [tracing-subscriber].
+///
+/// [HierarchicalLayer]: crate::HierarchicalLayer
+/// [Event]: tracing_core::Event
+/// [time's OffsetDateTime]: time::OffsetDateTime
+/// [FormatTime]: tracing_subscriber::fmt::time::FormatTime
+/// [tracing-subscriber]: tracing_subscriber
+// NB:
+//   We can't use `tracing_subscriber::fmt::format::Writer`
+//   since it doesn't have a public constructor.
+pub trait FormatTime {
+    fn format_time(&self, w: &mut impl std::fmt::Write) -> std::fmt::Result;
+}
+
+////////////////////////////////////////////////////////////////////////////////////////////////////
+
+/// Default do-nothing time formatter.
+impl FormatTime for () {
+    fn format_time(&self, _w: &mut impl std::fmt::Write) -> std::fmt::Result {
+        Ok(())
+    }
+}
+
+////////////////////////////////////////////////////////////////////////////////////////////////////
+
+/// Retrieve and print the current wall-clock time in UTC timezone.
+#[cfg(feature = "time")]
+#[derive(Debug, Clone, Copy, Eq, PartialEq, Default)]
+pub struct UtcDateTime;
+
+#[cfg(feature = "time")]
+impl FormatTime for UtcDateTime {
+    fn format_time(&self, w: &mut impl std::fmt::Write) -> std::fmt::Result {
+        let time = time::OffsetDateTime::now_utc();
+        write!(w, "{} {}", time.date(), time.time())
+    }
+}
+
+////////////////////////////////////////////////////////////////////////////////////////////////////
+
+/// Retrieve and print the current wall-clock time.
+///
+/// # Panics
+///
+/// Panics if [time crate] cannot determine the local UTC offset.
+///
+/// [time crate]: time
+// NB:
+//   Can't use `tracing_subscriber::fmt::time::SystemTime` since it uses
+//   private `datetime` module to format the actual time.
+#[cfg(feature = "time")]
+#[derive(Debug, Clone, Copy, Eq, PartialEq, Default)]
+pub struct LocalDateTime;
+
+#[cfg(feature = "time")]
+impl FormatTime for LocalDateTime {
+    fn format_time(&self, w: &mut impl std::fmt::Write) -> std::fmt::Result {
+        let time = time::OffsetDateTime::now_local().expect("time offset cannot be determined");
+        write!(w, "{}", time)
+    }
+}
+
+////////////////////////////////////////////////////////////////////////////////////////////////////
+
+/// Retrieve and print the relative elapsed wall-clock time since an epoch.
+///
+/// The `Default` implementation for `Uptime` makes the epoch the current time.
+// NB: Copy-pasted from `tracing-subscriber::fmt::time::Uptime`.
+#[derive(Debug, Clone, Copy, Eq, PartialEq)]
+pub struct Uptime {
+    epoch: std::time::Instant,
+}
+
+impl Default for Uptime {
+    fn default() -> Self {
+        Uptime {
+            epoch: std::time::Instant::now(),
+        }
+    }
+}
+
+impl From<std::time::Instant> for Uptime {
+    fn from(epoch: std::time::Instant) -> Self {
+        Uptime { epoch }
+    }
+}
+
+impl FormatTime for Uptime {
+    fn format_time(&self, w: &mut impl std::fmt::Write) -> std::fmt::Result {
+        let e = self.epoch.elapsed();
+        write!(w, "{:4}.{:06}s", e.as_secs(), e.subsec_micros())
+    }
+}
+
+////////////////////////////////////////////////////////////////////////////////////////////////////
+
+impl<'a, F> FormatTime for &'a F
+where
+    F: FormatTime,
+{
+    fn format_time(&self, w: &mut impl std::fmt::Write) -> std::fmt::Result {
+        (*self).format_time(w)
+    }
+}
+
+// NB:
+//   Can't impl for `fn(&mut impl std::fmt::Write)` since impl trait is not allowed
+//   outside of function and inherent method return types for now.

tests/format_time.rs

@@ -0,0 +1,79 @@
+use std::{
+    fmt::Write,
+    sync::{
+        atomic::{AtomicU64, Ordering},
+        Arc,
+    },
+};
+
+use tracing::{span, Level};
+use tracing_subscriber::{layer::SubscriberExt, Registry};
+
+use tracing_tree::{time::FormatTime, HierarchicalLayer};
+
+#[derive(Debug)]
+struct FormatTimeCounter(Arc<AtomicU64>);
+
+impl FormatTime for FormatTimeCounter {
+    fn format_time(&self, _w: &mut impl Write) -> std::fmt::Result {
+        self.0.fetch_add(1, Ordering::Relaxed);
+        Ok(())
+    }
+}
+
+#[test]
+fn format_time_num_calls() {
+    let num_called = Arc::new(AtomicU64::new(0));
+    let format_time_counter = FormatTimeCounter(Arc::clone(&num_called));
+
+    let layer = HierarchicalLayer::default()
+        .with_writer(std::io::stdout)
+        .with_indent_lines(true)
+        .with_indent_amount(2)
+        .with_timer(format_time_counter)
+        .with_thread_names(true)
+        .with_thread_ids(true)
+        .with_verbose_exit(true)
+        .with_verbose_entry(true)
+        .with_targets(true);
+
+    let subscriber = Registry::default().with(layer);
+    tracing::subscriber::set_global_default(subscriber).unwrap();
+
+    let test_span = span!(Level::TRACE, "format-time-num-calls-test", version = %0.1);
+    let _e = test_span.enter();
+
+    tracing::info!("first event");
+    assert_eq!(num_called.load(Ordering::Relaxed), 1);
+
+    std::thread::sleep(std::time::Duration::from_millis(100));
+    tracing::info!("second event");
+    assert_eq!(num_called.load(Ordering::Relaxed), 2);
+
+    let nested_span = span!(Level::TRACE, "nested-span");
+    nested_span.in_scope(|| {
+        tracing::debug!("nested event");
+        assert_eq!(num_called.load(Ordering::Relaxed), 3);
+
+        tracing::info!("important nested event");
+        assert_eq!(num_called.load(Ordering::Relaxed), 4);
+    });
+    drop(nested_span);
+
+    instrumented_function();
+    assert_eq!(num_called.load(Ordering::Relaxed), 6);
+
+    tracing::info!("exiting");
+    assert_eq!(num_called.load(Ordering::Relaxed), 7);
+}
+
+#[tracing::instrument]
+fn instrumented_function() {
+    tracing::info!("instrumented function");
+    nested_instrumented_function();
+}
+
+#[tracing::instrument]
+fn nested_instrumented_function() {
+    tracing::warn!("nested instrumented function");
+}