subscriber: replace chrono with time for timestamp formatting (#1646)

## Motivation

Currently, `tracing-subscriber` supports the `chrono` crate for
timestamp formatting, via a default-on feature flag. When this code was
initially added to `tracing-subscriber`, the `time` crate did not have
support for the timestamp formatting options we needed.

Unfortunately, the `chrono` crate's maintainance status is now in
question (see #1598). Furthermore, `chrono` depends on version 0.1 of
the `time` crate, which contains a security vulnerability
(https://rustsec.org/advisories/RUSTSEC-2020-0071.html). This
vulnerability is fixed in more recent releases of `time`, but `chrono`
still uses v0.1.

## Solution

Fortunately, the `time` crate now has its own timestamp formatting
support.

This branch replaces the `ChronoLocal` and `ChronoUtc` timestamp
formatters with new `LocalTime` and `UtcTime` formatters. These
formatters use the `time` crate's formatting APIs rather than
`chrono`'s. This removes the vulnerable dependency on `time` 0.1

Additionally, the new `time` APIs are feature flagged as an _opt-in_
feature, rather than as an _opt-out_ feature. This should make it easier
to avoid accidentally depending on the `time` crate when more
sophisticated timestamp formatting is _not_ required.

In a follow-up branch, we could also add support for `humantime` as an
option for timestamp formatting.

Naturally, since this removes existing APIs, this is a breaking change,
and will thus require publishing `tracing-subscriber` 0.3. We'll want to
do some other breaking changes as well.

Fixes #1598.

Author: hawkw

examples/Cargo.toml

@@ -15,7 +15,7 @@ tracing-core = { path = "../tracing-core", version = "0.2"}
 tracing-error = { path = "../tracing-error" }
 tracing-flame = { path = "../tracing-flame" }
 tracing-tower = { version = "0.1.0", path = "../tracing-tower" }
-tracing-subscriber = { path = "../tracing-subscriber", version = "0.3", features = ["json", "chrono"] }
+tracing-subscriber = { path = "../tracing-subscriber", version = "0.3", features = ["json"] }
 tracing-futures = { version = "0.3", path = "../tracing-futures", features = ["futures-01"] }
 tracing-attributes =  { path = "../tracing-attributes", version = "0.2"}
 tracing-log = { path = "../tracing-log", version = "0.2", features = ["env_logger"] }

tracing-subscriber/Cargo.toml

@@ -23,12 +23,15 @@ keywords = ["logging", "tracing", "metrics", "subscriber"]
 
 [features]
 
-default = ["env-filter", "smallvec", "fmt", "ansi", "chrono", "tracing-log", "json"]
+default = ["env-filter", "smallvec", "fmt", "ansi", "tracing-log", "json"]
 env-filter = ["matchers", "regex", "lazy_static", "tracing"]
 fmt = ["registry"]
 ansi = ["fmt", "ansi_term"]
 registry = ["sharded-slab", "thread_local"]
 json = ["tracing-serde", "serde", "serde_json"]
+# Enables support for local time when using the `time` crate timestamp
+# formatters.
+local-time = ["time/local-offset"]
 
 [dependencies]
 tracing-core = { path = "../tracing-core", version = "0.2" }
@@ -43,7 +46,7 @@ lazy_static = { optional = true, version = "1" }
 # fmt
 tracing-log = { path = "../tracing-log", version = "0.2", optional = true, default-features = false, features = ["log-tracer", "std"] }
 ansi_term = { version = "0.12", optional = true }
-chrono = { version = "0.4.16", optional = true, default-features = false, features = ["clock", "std"] }
+time = { version = "0.3", features = ["formatting"], optional = true }
 
 # only required by the json feature
 serde_json = { version = "1.0", optional = true }
@@ -65,6 +68,8 @@ criterion = { version = "0.3", default_features = false }
 regex = { version = "1", default-features = false, features = ["std"] }
 tracing-futures = { path = "../tracing-futures", version = "0.3", default-features = false, features = ["std-future", "std"] }
 tokio = { version = "0.2", features = ["rt-core", "macros"] }
+# Enable the `time` crate's `macros` feature, for examples.
+time = { version = "0.3", features = ["formatting", "macros"] }
 
 [badges]
 maintenance = { status = "experimental" }

tracing-subscriber/benches/reload.rs

@@ -3,7 +3,6 @@ use tracing_subscriber::{
     filter::LevelFilter,
     fmt::{
         format::{DefaultFields, Format, Full},
-        time::ChronoLocal,
         Collector, CollectorBuilder,
     },
     EnvFilter,
@@ -15,8 +14,7 @@ use support::NoWriter;
 /// Prepare a real-world-inspired collector and use it to  measure the performance impact of
 /// reloadable collectors.
 
-fn mk_builder(
-) -> CollectorBuilder<DefaultFields, Format<Full, ChronoLocal>, EnvFilter, fn() -> NoWriter> {
+fn mk_builder() -> CollectorBuilder<DefaultFields, Format<Full>, EnvFilter, fn() -> NoWriter> {
     let filter = EnvFilter::default()
         .add_directive("this=off".parse().unwrap())
         .add_directive("also=off".parse().unwrap())
@@ -28,9 +26,6 @@ fn mk_builder(
     Collector::builder()
         .with_env_filter(filter)
         .with_writer(NoWriter::new as _)
-        .with_timer(ChronoLocal::with_format(
-            "%Y-%m-%d %H:%M:%S%.3f".to_string(),
-        ))
         .with_ansi(true)
         .with_target(true)
         .with_level(true)

tracing-subscriber/src/fmt/fmt_subscriber.rs

@@ -191,15 +191,18 @@ where
 {
     /// Use the given [`timer`] for span and event timestamps.
     ///
-    /// See [`time`] for the provided timer implementations.
+    /// See the [`time` module] for the provided timer implementations.
     ///
-    /// Note that using the `chrono` feature flag enables the
-    /// additional time formatters [`ChronoUtc`] and [`ChronoLocal`].
+    /// Note that using the `"time`"" feature flag enables the
+    /// additional time formatters [`UtcTime`] and [`LocalTime`], which use the
+    /// [`time` crate] to provide more sophisticated timestamp formatting
+    /// options.
     ///
-    /// [`time`]: mod@super::time
     /// [`timer`]: super::time::FormatTime
-    /// [`ChronoUtc`]: super::time::ChronoUtc
-    /// [`ChronoLocal`]: super::time::ChronoLocal
+    /// [`time` module]: mod@super::time
+    /// [`UtcTime`]: super::time::UtcTime
+    /// [`LocalTime`]: super::time::LocalTime
+    /// [`time` crate]: https://docs.rs/time/0.3
     pub fn with_timer<T2>(self, timer: T2) -> Subscriber<C, N, format::Format<L, T2>, W> {
         Subscriber {
             fmt_event: self.fmt_event.with_timer(timer),

tracing-subscriber/src/fmt/format/json.rs

@@ -1,15 +1,17 @@
 use super::{Format, FormatEvent, FormatFields, FormatTime};
 use crate::{
     field::{RecordFields, VisitOutput},
-    fmt::fmt_subscriber::{FmtContext, FormattedFields},
+    fmt::{
+        fmt_subscriber::{FmtContext, FormattedFields},
+        writer::WriteAdaptor,
+    },
     registry::LookupSpan,
 };
 use serde::ser::{SerializeMap, Serializer as _};
 use serde_json::Serializer;
 use std::{
     collections::BTreeMap,
     fmt::{self, Write},
-    io,
 };
 use tracing_core::{
     field::{self, Field},
@@ -471,44 +473,6 @@ impl<'a> field::Visit for JsonVisitor<'a> {
         };
     }
 }
-
-/// A bridge between `fmt::Write` and `io::Write`.
-///
-/// This is needed because tracing-subscriber's FormatEvent expects a fmt::Write
-/// while serde_json's Serializer expects an io::Write.
-struct WriteAdaptor<'a> {
-    fmt_write: &'a mut dyn fmt::Write,
-}
-
-impl<'a> WriteAdaptor<'a> {
-    fn new(fmt_write: &'a mut dyn fmt::Write) -> Self {
-        Self { fmt_write }
-    }
-}
-
-impl<'a> io::Write for WriteAdaptor<'a> {
-    fn write(&mut self, buf: &[u8]) -> io::Result<usize> {
-        let s =
-            std::str::from_utf8(buf).map_err(|e| io::Error::new(io::ErrorKind::InvalidData, e))?;
-
-        self.fmt_write
-            .write_str(s)
-            .map_err(|e| io::Error::new(io::ErrorKind::Other, e))?;
-
-        Ok(s.as_bytes().len())
-    }
-
-    fn flush(&mut self) -> io::Result<()> {
-        Ok(())
-    }
-}
-
-impl<'a> fmt::Debug for WriteAdaptor<'a> {
-    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
-        f.pad("WriteAdaptor { .. }")
-    }
-}
-
 #[cfg(test)]
 mod test {
     use super::*;

tracing-subscriber/src/fmt/format/mod.rs

@@ -362,13 +362,16 @@ impl<F, T> Format<F, T> {
     ///
     /// See [`time` module] for the provided timer implementations.
     ///
-    /// Note that using the `chrono` feature flag enables the
-    /// additional time formatters [`ChronoUtc`] and [`ChronoLocal`].
+    /// Note that using the `"time"` feature flag enables the
+    /// additional time formatters [`UtcTime`] and [`LocalTime`], which use the
+    /// [`time` crate] to provide more sophisticated timestamp formatting
+    /// options.
     ///
     /// [`timer`]: super::time::FormatTime
     /// [`time` module]: mod@super::time
-    /// [`ChronoUtc`]: super::time::ChronoUtc
-    /// [`ChronoLocal`]: super::time::ChronoLocal
+    /// [`UtcTime`]: super::time::UtcTime
+    /// [`LocalTime`]: super::time::LocalTime
+    /// [`time` crate]: https://docs.rs/time/0.3
     pub fn with_timer<T2>(self, timer: T2) -> Format<F, T2> {
         Format {
             format: self.format,

tracing-subscriber/src/fmt/mod.rs

@@ -611,15 +611,18 @@ where
 {
     /// Use the given [`timer`] for log message timestamps.
     ///
-    /// See [`time`] for the provided timer implementations.
+    /// See the [`time` module] for the provided timer implementations.
     ///
-    /// Note that using the `chrono` feature flag enables the
-    /// additional time formatters [`ChronoUtc`] and [`ChronoLocal`].
+    /// Note that using the `"time`"" feature flag enables the
+    /// additional time formatters [`UtcTime`] and [`LocalTime`], which use the
+    /// [`time` crate] to provide more sophisticated timestamp formatting
+    /// options.
     ///
-    /// [`time`]: mod@time
     /// [`timer`]: time::FormatTime
-    /// [`ChronoUtc`]: time::ChronoUtc
-    /// [`ChronoLocal`]: time::ChronoLocal
+    /// [`time` module]: mod@time
+    /// [`UtcTime`]: time::UtcTime
+    /// [`LocalTime`]: time::LocalTime
+    /// [`time` crate]: https://docs.rs/time/0.3
     pub fn with_timer<T2>(self, timer: T2) -> CollectorBuilder<N, format::Format<L, T2>, F, W> {
         CollectorBuilder {
             filter: self.filter,

tracing-subscriber/src/fmt/time/mod.rs

@@ -2,9 +2,15 @@
 use std::fmt;
 use std::time::Instant;
 
-#[cfg(not(feature = "chrono"))]
 mod datetime;
 
+#[cfg(feature = "time")]
+#[cfg_attr(docsrs, doc(cfg(feature = "time")))]
+mod time_crate;
+#[cfg(feature = "time")]
+#[cfg_attr(docsrs, doc(cfg(feature = "time")))]
+pub use time_crate::{LocalTime, UtcTime};
+
 /// A type that can measure and format the current time.
 ///
 /// This trait is used by `Format` to include a timestamp with each `Event` when it is logged.
@@ -81,9 +87,6 @@ impl FormatTime for fn(&mut dyn fmt::Write) -> fmt::Result {
 }
 
 /// Retrieve and print the current wall-clock time.
-///
-/// If the `chrono` feature is enabled, the current time is printed in a human-readable format like
-/// "Jun 25 14:27:12.955". Otherwise the `Debug` implementation of `std::time::SystemTime` is used.
 #[derive(Debug, Clone, Copy, Eq, PartialEq, Default)]
 pub struct SystemTime;
 
@@ -109,14 +112,6 @@ impl From<Instant> for Uptime {
     }
 }
 
-#[cfg(feature = "chrono")]
-impl FormatTime for SystemTime {
-    fn format_time(&self, w: &mut dyn fmt::Write) -> fmt::Result {
-        write!(w, "{}", chrono::Local::now().format("%b %d %H:%M:%S%.3f"))
-    }
-}
-
-#[cfg(not(feature = "chrono"))]
 impl FormatTime for SystemTime {
     fn format_time(&self, w: &mut dyn fmt::Write) -> fmt::Result {
         write!(
@@ -133,112 +128,3 @@ impl FormatTime for Uptime {
         write!(w, "{:4}.{:09}s", e.as_secs(), e.subsec_nanos())
     }
 }
-
-/// The RFC 3339 format is used by default and using
-/// this struct allows chrono to bypass the parsing
-/// used when a custom format string is provided
-#[cfg(feature = "chrono")]
-#[derive(Debug, Clone, Eq, PartialEq)]
-enum ChronoFmtType {
-    Rfc3339,
-    Custom(String),
-}
-
-#[cfg(feature = "chrono")]
-impl Default for ChronoFmtType {
-    fn default() -> Self {
-        ChronoFmtType::Rfc3339
-    }
-}
-
-/// Retrieve and print the current UTC time.
-#[cfg(feature = "chrono")]
-#[cfg_attr(docsrs, doc(cfg(feature = "chrono")))]
-#[derive(Debug, Clone, Eq, PartialEq, Default)]
-pub struct ChronoUtc {
-    format: ChronoFmtType,
-}
-
-#[cfg(feature = "chrono")]
-#[cfg_attr(docsrs, doc(cfg(feature = "chrono")))]
-impl ChronoUtc {
-    /// Format the time using the [`RFC 3339`] format
-    /// (a subset of [`ISO 8601`]).
-    ///
-    /// [`RFC 3339`]: https://tools.ietf.org/html/rfc3339
-    /// [`ISO 8601`]: https://en.wikipedia.org/wiki/ISO_8601
-    pub fn rfc3339() -> Self {
-        ChronoUtc {
-            format: ChronoFmtType::Rfc3339,
-        }
-    }
-
-    /// Format the time using the given format string.
-    ///
-    /// See [`chrono::format::strftime`]
-    /// for details on the supported syntax.
-    ///
-    pub fn with_format(format_string: String) -> Self {
-        ChronoUtc {
-            format: ChronoFmtType::Custom(format_string),
-        }
-    }
-}
-
-#[cfg(feature = "chrono")]
-#[cfg_attr(docsrs, doc(cfg(feature = "chrono")))]
-impl FormatTime for ChronoUtc {
-    fn format_time(&self, w: &mut dyn fmt::Write) -> fmt::Result {
-        let time = chrono::Utc::now();
-        match self.format {
-            ChronoFmtType::Rfc3339 => write!(w, "{}", time.to_rfc3339()),
-            ChronoFmtType::Custom(ref format_str) => write!(w, "{}", time.format(format_str)),
-        }
-    }
-}
-
-/// Retrieve and print the current local time.
-#[cfg(feature = "chrono")]
-#[cfg_attr(docsrs, doc(cfg(feature = "chrono")))]
-#[derive(Debug, Clone, Eq, PartialEq, Default)]
-pub struct ChronoLocal {
-    format: ChronoFmtType,
-}
-
-#[cfg(feature = "chrono")]
-#[cfg_attr(docsrs, doc(cfg(feature = "chrono")))]
-impl ChronoLocal {
-    /// Format the time using the [`RFC 3339`] format
-    /// (a subset of [`ISO 8601`]).
-    ///
-    /// [`RFC 3339`]: https://tools.ietf.org/html/rfc3339
-    /// [`ISO 8601`]: https://en.wikipedia.org/wiki/ISO_8601
-    pub fn rfc3339() -> Self {
-        ChronoLocal {
-            format: ChronoFmtType::Rfc3339,
-        }
-    }
-
-    /// Format the time using the given format string.
-    ///
-    /// See [`chrono::format::strftime`]
-    /// for details on the supported syntax.
-    ///
-    pub fn with_format(format_string: String) -> Self {
-        ChronoLocal {
-            format: ChronoFmtType::Custom(format_string),
-        }
-    }
-}
-
-#[cfg(feature = "chrono")]
-#[cfg_attr(docsrs, doc(cfg(feature = "chrono")))]
-impl FormatTime for ChronoLocal {
-    fn format_time(&self, w: &mut dyn fmt::Write) -> fmt::Result {
-        let time = chrono::Local::now();
-        match self.format {
-            ChronoFmtType::Rfc3339 => write!(w, "{}", time.to_rfc3339()),
-            ChronoFmtType::Custom(ref format_str) => write!(w, "{}", time.format(format_str)),
-        }
-    }
-}