Skip to content

Commit

Permalink
subscriber: replace chrono with time for timestamp formatting (#1646
Browse files Browse the repository at this point in the history 
)

## 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.
  • Loading branch information
@hawkw
hawkw committed Oct 21, 2021
1 parent d169ae4 commit 6219cc7
Show file tree
Hide file tree
Showing 10 changed files with 369 additions and 189 deletions.
2 changes: 1 addition & 1 deletion examples/Cargo.toml
View file
Original file line number Diff line number Diff line change
Expand Up @@ -15,7 +15,7 @@ tracing-core = { path = "../tracing-core", version = "0.1" }
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.2.13", features = ["json", "chrono"] }
tracing-subscriber = { path = "../tracing-subscriber", version = "0.2", features = ["json"] }
tracing-futures = { version = "0.2.1", path = "../tracing-futures", features = ["futures-01"] }
tracing-attributes = { path = "../tracing-attributes", version = "0.1.2" }
tracing-log = { path = "../tracing-log", version = "0.1.1", features = ["env_logger"] }
Expand Down
9 changes: 7 additions & 2 deletions tracing-subscriber/Cargo.toml
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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.1.20" }
Expand All @@ -43,7 +46,7 @@ lazy_static = { optional = true, version = "1" }
# fmt
tracing-log = { path = "../tracing-log", version = "0.1.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 }
Expand All @@ -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.2", 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" }
Expand Down
17 changes: 10 additions & 7 deletions tracing-subscriber/src/fmt/fmt_layer.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -221,15 +221,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`]: ./time/index.html
/// [`timer`]: ./time/trait.FormatTime.html
/// [`ChronoUtc`]: ./time/struct.ChronoUtc.html
/// [`ChronoLocal`]: ./time/struct.ChronoLocal.html
/// [`timer`]: super::time::FormatTime
/// [`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) -> Layer<S, N, format::Format<L, T2>, W> {
Layer {
fmt_event: self.fmt_event.with_timer(timer),
Expand Down
44 changes: 4 additions & 40 deletions tracing-subscriber/src/fmt/format/json.rs
View file
Original file line number Diff line number Diff line change
@@ -1,15 +1,17 @@
use super::{Format, FormatEvent, FormatFields, FormatTime};
use crate::{
field::{RecordFields, VisitOutput},
fmt::fmt_layer::{FmtContext, FormattedFields},
fmt::{
fmt_layer::{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},
Expand Down Expand Up @@ -477,44 +479,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::*;
Expand Down
11 changes: 7 additions & 4 deletions tracing-subscriber/src/fmt/format/mod.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -360,13 +360,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,
Expand Down
17 changes: 10 additions & 7 deletions tracing-subscriber/src/fmt/mod.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -591,15 +591,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`]: ./time/index.html
/// [`timer`]: ./time/trait.FormatTime.html
/// [`ChronoUtc`]: ./time/struct.ChronoUtc.html
/// [`ChronoLocal`]: ./time/struct.ChronoLocal.html
/// [`timer`]: time::FormatTime
/// [`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) -> SubscriberBuilder<N, format::Format<L, T2>, F, W> {
SubscriberBuilder {
filter: self.filter,
Expand Down
130 changes: 7 additions & 123 deletions tracing-subscriber/src/fmt/time/mod.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down Expand Up @@ -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;

Expand All @@ -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!(
Expand All @@ -133,114 +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.
///
/// [`chrono::format::strftime`]: https://docs.rs/chrono/0.4.9/chrono/format/strftime/index.html
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.
///
/// [`chrono::format::strftime`]: https://docs.rs/chrono/0.4.9/chrono/format/strftime/index.html
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)),
}
}
}
Loading

0 comments on commit 6219cc7

Please sign in to comment.