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 18, 2021
1 parent bbe3c1d commit 6614b2f
Show file tree
Hide file tree
Showing 11 changed files with 368 additions and 191 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.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"] }
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.2" }
Expand All @@ -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 }
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.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" }
Expand Down
7 changes: 1 addition & 6 deletions tracing-subscriber/benches/reload.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -3,7 +3,6 @@ use tracing_subscriber::{
filter::LevelFilter,
fmt::{
format::{DefaultFields, Format, Full},
time::ChronoLocal,
Collector, CollectorBuilder,
},
EnvFilter,
Expand All @@ -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())
Expand All @@ -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)
Expand Down
15 changes: 9 additions & 6 deletions tracing-subscriber/src/fmt/fmt_subscriber.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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),
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_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},
Expand Down Expand Up @@ -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::*;
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 @@ -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,
Expand Down
15 changes: 9 additions & 6 deletions tracing-subscriber/src/fmt/mod.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand Down
128 changes: 7 additions & 121 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,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)),
}
}
}
Loading

0 comments on commit 6614b2f

Please sign in to comment.