Skip to content

Commit

Permalink
subscriber: remove space when timestamps are disabled (#1355)
Browse files Browse the repository at this point in the history
## Motivation

Currently, the default `Compact` and `Full` formatters in
`tracing-subscriber` will prefix log lines with a single space when
timestamps are disabled. The space is emitted in order to pad the
timestamp from the rest of the log line, but it shouldn't be emitted
when timestamps are turned off. This should be fixed.

## Solution

This branch fixes the issue by skipping `time::write` entirely when
timestamps are disabled. This is done by tracking an additional boolean
flag for disabling timestamps.

Incidentally, this now means that span lifecycle timing can be enabled
even if event timestamps are disabled, like this:
```rust
use tracing_subscriber::fmt;
let subscriber = fmt::subscriber()
    .without_time()
    .with_timer(SystemTime::now)
    .with_span_events(fmt::FmtSpan::FULL);
```
or similar.

I also added a new test reproducing the issue, and did a little
refactoring to try and clean up the timestamp formatting code a bit.

Closes #1354
  • Loading branch information
hawkw committed Apr 15, 2021
1 parent 7567c2d commit 9b1e113
Show file tree
Hide file tree
Showing 4 changed files with 57 additions and 41 deletions.
2 changes: 1 addition & 1 deletion tracing-subscriber/src/fmt/fmt_subscriber.rs
Original file line number Diff line number Diff line change
Expand Up @@ -1006,7 +1006,7 @@ mod test {
});
let actual = sanitize_timings(make_writer.get_string());
assert_eq!(
" span1{x=42}: tracing_subscriber::fmt::fmt_subscriber::test: close\n",
"span1{x=42}: tracing_subscriber::fmt::fmt_subscriber::test: close\n",
actual.as_str()
);
}
Expand Down
63 changes: 54 additions & 9 deletions tracing-subscriber/src/fmt/format/mod.rs
Original file line number Diff line number Diff line change
@@ -1,5 +1,5 @@
//! Formatters for logging `tracing` events.
use super::time::{self, FormatTime, SystemTime};
use super::time::{FormatTime, SystemTime};
use crate::{
field::{MakeOutput, MakeVisitor, RecordFields, VisitFmt, VisitOutput},
fmt::fmt_subscriber::FmtContext,
Expand Down Expand Up @@ -253,6 +253,7 @@ pub struct Format<F = Full, T = SystemTime> {
format: F,
pub(crate) timer: T,
pub(crate) ansi: bool,
pub(crate) display_timestamp: bool,
pub(crate) display_target: bool,
pub(crate) display_level: bool,
pub(crate) display_thread_id: bool,
Expand All @@ -265,6 +266,7 @@ impl Default for Format<Full, SystemTime> {
format: Full,
timer: SystemTime,
ansi: true,
display_timestamp: true,
display_target: true,
display_level: true,
display_thread_id: false,
Expand All @@ -283,6 +285,7 @@ impl<F, T> Format<F, T> {
timer: self.timer,
ansi: self.ansi,
display_target: false,
display_timestamp: self.display_timestamp,
display_level: self.display_level,
display_thread_id: self.display_thread_id,
display_thread_name: self.display_thread_name,
Expand Down Expand Up @@ -319,6 +322,7 @@ impl<F, T> Format<F, T> {
timer: self.timer,
ansi: self.ansi,
display_target: self.display_target,
display_timestamp: self.display_timestamp,
display_level: self.display_level,
display_thread_id: self.display_thread_id,
display_thread_name: self.display_thread_name,
Expand Down Expand Up @@ -348,6 +352,7 @@ impl<F, T> Format<F, T> {
timer: self.timer,
ansi: self.ansi,
display_target: self.display_target,
display_timestamp: self.display_timestamp,
display_level: self.display_level,
display_thread_id: self.display_thread_id,
display_thread_name: self.display_thread_name,
Expand All @@ -370,6 +375,7 @@ impl<F, T> Format<F, T> {
timer,
ansi: self.ansi,
display_target: self.display_target,
display_timestamp: self.display_timestamp,
display_level: self.display_level,
display_thread_id: self.display_thread_id,
display_thread_name: self.display_thread_name,
Expand All @@ -382,6 +388,7 @@ impl<F, T> Format<F, T> {
format: self.format,
timer: (),
ansi: self.ansi,
display_timestamp: false,
display_target: self.display_target,
display_level: self.display_level,
display_thread_id: self.display_thread_id,
Expand Down Expand Up @@ -452,6 +459,34 @@ impl<F, T> Format<F, T> {

Ok(())
}

#[inline]
fn format_timestamp(&self, writer: &mut dyn fmt::Write) -> fmt::Result
where
T: FormatTime,
{
// If timestamps are disabled, do nothing.
if !self.display_timestamp {
return Ok(());
}

// If ANSI color codes are enabled, format the timestamp with ANSI
// colors.
#[cfg(feature = "ansi")]
{
if self.ansi {
let style = Style::new().dimmed();
write!(writer, "{}", style.prefix())?;
self.timer.format_time(writer)?;
write!(writer, "{} ", style.suffix())?;
return Ok(());
}
}

// Otherwise, just format the timestamp without ANSI formatting.
self.timer.format_time(writer)?;
writer.write_char(' ')
}
}

#[cfg(feature = "json")]
Expand Down Expand Up @@ -513,11 +548,8 @@ where
let meta = normalized_meta.as_ref().unwrap_or_else(|| event.metadata());
#[cfg(not(feature = "tracing-log"))]
let meta = event.metadata();
#[cfg(feature = "ansi")]
time::write(&self.timer, writer, self.ansi)?;
#[cfg(not(feature = "ansi"))]
time::write(&self.timer, writer)?;

self.format_timestamp(writer)?;
self.format_level(*meta.level(), writer)?;

if self.display_thread_name {
Expand Down Expand Up @@ -576,11 +608,8 @@ where
let meta = normalized_meta.as_ref().unwrap_or_else(|| event.metadata());
#[cfg(not(feature = "tracing-log"))]
let meta = event.metadata();
#[cfg(feature = "ansi")]
time::write(&self.timer, writer, self.ansi)?;
#[cfg(not(feature = "ansi"))]
time::write(&self.timer, writer)?;

self.format_timestamp(writer)?;
self.format_level(*meta.level(), writer)?;

if self.display_thread_name {
Expand Down Expand Up @@ -1239,6 +1268,22 @@ pub(super) mod test {
}
}

#[test]
fn disable_everything() {
// This test reproduces https://github.com/tokio-rs/tracing/issues/1354
let make_writer = MockMakeWriter::default();
let subscriber = crate::fmt::Collector::builder()
.with_writer(make_writer.clone())
.without_time()
.with_level(false)
.with_target(false)
.with_thread_ids(false)
.with_thread_names(false);
#[cfg(feature = "ansi")]
let subscriber = subscriber.with_ansi(false);
run_test(subscriber, make_writer, "hello\n")
}

#[cfg(feature = "ansi")]
#[test]
fn with_ansi_true() {
Expand Down
3 changes: 2 additions & 1 deletion tracing-subscriber/src/fmt/format/pretty.rs
Original file line number Diff line number Diff line change
Expand Up @@ -107,7 +107,8 @@ where
#[cfg(not(feature = "tracing-log"))]
let meta = event.metadata();
write!(writer, " ")?;
time::write(&self.timer, writer, self.ansi)?;

self.format_timestamp(writer)?;

let style = if self.display_level && self.ansi {
Pretty::style_for(meta.level())
Expand Down
30 changes: 0 additions & 30 deletions tracing-subscriber/src/fmt/time/mod.rs
Original file line number Diff line number Diff line change
@@ -1,6 +1,4 @@
//! Formatters for event timestamps.
#[cfg(feature = "ansi")]
use ansi_term::Style;
use std::fmt;
use std::time::Instant;

Expand Down Expand Up @@ -244,31 +242,3 @@ impl FormatTime for ChronoLocal {
}
}
}

#[inline(always)]
#[cfg(feature = "ansi")]
pub(crate) fn write<T>(timer: T, writer: &mut dyn fmt::Write, with_ansi: bool) -> fmt::Result
where
T: FormatTime,
{
if with_ansi {
let style = Style::new().dimmed();
write!(writer, "{}", style.prefix())?;
timer.format_time(writer)?;
write!(writer, "{}", style.suffix())?;
} else {
timer.format_time(writer)?;
}
writer.write_char(' ')?;
Ok(())
}

#[inline(always)]
#[cfg(not(feature = "ansi"))]
pub(crate) fn write<T>(timer: T, writer: &mut dyn fmt::Write) -> fmt::Result
where
T: FormatTime,
{
timer.format_time(writer)?;
write!(writer, " ")
}

0 comments on commit 9b1e113

Please sign in to comment.