subscriber: remove space when timestamps are disabled (#1355)

## 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

tracing-opentelemetry/src/layer.rs

@@ -691,10 +691,9 @@ mod tests {
     #[test]
     fn span_status_code() {
         let tracer = TestTracer(Arc::new(Mutex::new(None)));
-        let subscriber =
-            tracing_subscriber::registry().with(subscriber().with_tracer(tracer.clone()));
+        let subscriber = tracing_subscriber::registry().with(layer().with_tracer(tracer.clone()));
 
-        tracing::collect::with_default(subscriber, || {
+        tracing::subscriber::with_default(subscriber, || {
             tracing::debug_span!("request", otel.status_code = ?otel::StatusCode::Ok);
         });
         let recorded_status_code = tracer.0.lock().unwrap().as_ref().unwrap().status_code;
@@ -704,12 +703,11 @@ mod tests {
     #[test]
     fn span_status_message() {
         let tracer = TestTracer(Arc::new(Mutex::new(None)));
-        let subscriber =
-            tracing_subscriber::registry().with(subscriber().with_tracer(tracer.clone()));
+        let subscriber = tracing_subscriber::registry().with(layer().with_tracer(tracer.clone()));
 
         let message = "message";
 
-        tracing::collect::with_default(subscriber, || {
+        tracing::subscriber::with_default(subscriber, || {
             tracing::debug_span!("request", otel.status_message = message);
         });
 

tracing-subscriber/src/fmt/fmt_layer.rs

@@ -1070,7 +1070,7 @@ mod test {
         });
         let actual = sanitize_timings(String::from_utf8(BUF.try_lock().unwrap().to_vec()).unwrap());
         assert_eq!(
-            " span1{x=42}: tracing_subscriber::fmt::fmt_layer::test: close\n",
+            "span1{x=42}: tracing_subscriber::fmt::fmt_layer::test: close\n",
             actual.as_str()
         );
     }

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

@@ -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_layer::FmtContext,
@@ -252,6 +252,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,
@@ -264,6 +265,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,
@@ -282,6 +284,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,
@@ -318,6 +321,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,
@@ -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,
@@ -371,6 +376,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,
@@ -383,6 +389,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,
@@ -432,6 +439,34 @@ impl<F, T> Format<F, T> {
             ..self
         }
     }
+
+    #[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")]
@@ -493,10 +528,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)?;
 
         if self.display_level {
             let fmt_level = {
@@ -568,10 +601,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)?;
 
         if self.display_level {
             let fmt_level = {
@@ -1272,6 +1303,32 @@ pub(super) mod test {
         }
     }
 
+    #[test]
+    fn disable_everything() {
+        // This test reproduces https://github.com/tokio-rs/tracing/issues/1354
+        lazy_static! {
+            static ref BUF: Mutex<Vec<u8>> = Mutex::new(vec![]);
+        }
+
+        let make_writer = || MockWriter::new(&BUF);
+        let subscriber = crate::fmt::Subscriber::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);
+
+        with_default(subscriber.finish(), || {
+            tracing::info!("hello");
+        });
+
+        let actual = String::from_utf8(BUF.try_lock().unwrap().to_vec()).unwrap();
+        assert_eq!("hello\n", actual.as_str());
+    }
+
     #[cfg(feature = "ansi")]
     #[test]
     fn with_ansi_true() {

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

@@ -108,7 +108,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())

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

@@ -1,6 +1,4 @@
 //! Formatters for event timestamps.
-#[cfg(feature = "ansi")]
-use ansi_term::Style;
 use std::fmt;
 use std::time::Instant;
 
@@ -246,31 +244,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, " ")
-}