subscriber: add Format::with_file and with_line_number (#1773)

## Motivation

Logging line numbers and file names can be useful for debugging. This
feature was suggested by #1326

## Solution

As per @hawkw's suggestions, fields were added on `Format`, along with
builder methods. Filename and line number information was gathered from
the `meta` variable.

The `Pretty` formatter already supports printing source locations, but
this is configured separately on the `Pretty` formatter rather than on
the `Format` type. This branch also changes `Pretty` to honor the
`Format`-level configurations and deprecates the `Pretty`-specific
method.

Fixes #1326 Closes #1804

Co-authored-by: David Barsky <me@davidbarsky.com>
Co-authored-by: Eliza Weisman <eliza@buoyant.io>

examples/README.md

@@ -26,6 +26,8 @@ This directory contains a collection of examples that demonstrate the use of the
     events.
   + `fmt-multiple-writers.rs`: demonstrates how `fmt::Layer` can write
     to multiple destinations (in this instance, stdout and a file) simultaneously.
+  + `fmt-source-locations.rs`: demonstrates displaying source code locations
+    with `fmt::Layer`.
   + `subscriber-filter`: Demonstrates the `tracing-subscriber::filter` module,
     which provides a layer which adds configurable filtering to a subscriber
     implementation.

examples/examples/fmt-source-locations.rs

@@ -0,0 +1,29 @@
+//! Demonstrates displaying events' source code locations with the `fmt`
+//! subscriber.
+#![deny(rust_2018_idioms)]
+#[path = "fmt/yak_shave.rs"]
+mod yak_shave;
+
+fn main() {
+    tracing_subscriber::fmt()
+        // enable everything
+        .with_max_level(tracing::Level::TRACE)
+        // display source code file paths
+        .with_file(true)
+        // display source code line numbers
+        .with_line_number(true)
+        // disable targets
+        .with_target(false)
+        // sets this to be the default, global collector for this application.
+        .init();
+
+    let number_of_yaks = 3;
+    // this creates a new event, outside of any spans.
+    tracing::info!(number_of_yaks, "preparing to shave yaks");
+
+    let number_shaved = yak_shave::shave_all(number_of_yaks);
+    tracing::info!(
+        all_yaks_shaved = number_shaved == number_of_yaks,
+        "yak shaving completed."
+    );
+}

tracing-subscriber/src/fmt/fmt_layer.rs

@@ -299,6 +299,30 @@ where
             ..self
         }
     }
+    /// Sets whether or not an event's [source code file path][file] is
+    /// displayed.
+    ///
+    /// [file]: tracing_core::Metadata::file
+    pub fn with_file(self, display_filename: bool) -> Layer<S, N, format::Format<L, T>, W> {
+        Layer {
+            fmt_event: self.fmt_event.with_file(display_filename),
+            ..self
+        }
+    }
+
+    /// Sets whether or not an event's [source code line number][line] is
+    /// displayed.
+    ///
+    /// [line]: tracing_core::Metadata::line
+    pub fn with_line_number(
+        self,
+        display_line_number: bool,
+    ) -> Layer<S, N, format::Format<L, T>, W> {
+        Layer {
+            fmt_event: self.fmt_event.with_line_number(display_line_number),
+            ..self
+        }
+    }
 
     /// Sets whether or not an event's level is displayed.
     pub fn with_level(self, display_level: bool) -> Layer<S, N, format::Format<L, T>, W> {

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

@@ -243,6 +243,18 @@ where
                 serializer.serialize_entry("target", meta.target())?;
             }
 
+            if self.display_filename {
+                if let Some(filename) = meta.file() {
+                    serializer.serialize_entry("filename", filename)?;
+                }
+            }
+
+            if self.display_line_number {
+                if let Some(line_number) = meta.line() {
+                    serializer.serialize_entry("line_number", &line_number)?;
+                }
+            }
+
             if self.format.display_current_span {
                 if let Some(ref span) = current_span {
                     serializer
@@ -488,6 +500,7 @@ mod test {
     use tracing::{self, subscriber::with_default};
 
     use std::fmt;
+    use std::path::Path;
 
     struct MockTime;
     impl FormatTime for MockTime {
@@ -515,6 +528,50 @@ mod test {
         });
     }
 
+    #[test]
+    fn json_filename() {
+        let current_path = Path::new("tracing-subscriber")
+            .join("src")
+            .join("fmt")
+            .join("format")
+            .join("json.rs")
+            .to_str()
+            .expect("path must be valid unicode")
+            // escape windows backslashes
+            .replace('\\', "\\\\");
+        let expected =
+            &format!("{}{}{}",
+                    "{\"timestamp\":\"fake time\",\"level\":\"INFO\",\"span\":{\"answer\":42,\"name\":\"json_span\",\"number\":3},\"spans\":[{\"answer\":42,\"name\":\"json_span\",\"number\":3}],\"target\":\"tracing_subscriber::fmt::format::json::test\",\"filename\":\"",
+                    current_path,
+                    "\",\"fields\":{\"message\":\"some json test\"}}\n");
+        let subscriber = subscriber()
+            .flatten_event(false)
+            .with_current_span(true)
+            .with_file(true)
+            .with_span_list(true);
+        test_json(expected, subscriber, || {
+            let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3);
+            let _guard = span.enter();
+            tracing::info!("some json test");
+        });
+    }
+
+    #[test]
+    fn json_line_number() {
+        let expected =
+            "{\"timestamp\":\"fake time\",\"level\":\"INFO\",\"span\":{\"answer\":42,\"name\":\"json_span\",\"number\":3},\"spans\":[{\"answer\":42,\"name\":\"json_span\",\"number\":3}],\"target\":\"tracing_subscriber::fmt::format::json::test\",\"line_number\":42,\"fields\":{\"message\":\"some json test\"}}\n";
+        let subscriber = subscriber()
+            .flatten_event(false)
+            .with_current_span(true)
+            .with_line_number(true)
+            .with_span_list(true);
+        test_json_with_line_number(expected, subscriber, || {
+            let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3);
+            let _guard = span.enter();
+            tracing::info!("some json test");
+        });
+    }
+
     #[test]
     fn json_flattened_event() {
         let expected =
@@ -747,4 +804,34 @@ mod test {
             serde_json::from_str(actual).unwrap()
         );
     }
+
+    fn test_json_with_line_number<T>(
+        expected: &str,
+        builder: crate::fmt::SubscriberBuilder<JsonFields, Format<Json>>,
+        producer: impl FnOnce() -> T,
+    ) {
+        let make_writer = MockMakeWriter::default();
+        let subscriber = builder
+            .with_writer(make_writer.clone())
+            .with_timer(MockTime)
+            .finish();
+
+        with_default(subscriber, producer);
+
+        let buf = make_writer.buf();
+        let actual = std::str::from_utf8(&buf[..]).unwrap();
+        let mut expected =
+            serde_json::from_str::<std::collections::HashMap<&str, serde_json::Value>>(expected)
+                .unwrap();
+        let expect_line_number = expected.remove("line_number").is_some();
+        let mut actual: std::collections::HashMap<&str, serde_json::Value> =
+            serde_json::from_str(actual).unwrap();
+        let line_number = actual.remove("line_number");
+        if expect_line_number {
+            assert_eq!(line_number.map(|x| x.is_number()), Some(true));
+        } else {
+            assert!(line_number.is_none());
+        }
+        assert_eq!(actual, expected);
+    }
 }

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

@@ -325,6 +325,8 @@ pub struct Format<F = Full, T = SystemTime> {
     pub(crate) display_level: bool,
     pub(crate) display_thread_id: bool,
     pub(crate) display_thread_name: bool,
+    pub(crate) display_filename: bool,
+    pub(crate) display_line_number: bool,
 }
 
 // === impl Writer ===
@@ -501,6 +503,8 @@ impl Default for Format<Full, SystemTime> {
             display_level: true,
             display_thread_id: false,
             display_thread_name: false,
+            display_filename: false,
+            display_line_number: false,
         }
     }
 }
@@ -519,6 +523,8 @@ impl<F, T> Format<F, T> {
             display_level: self.display_level,
             display_thread_id: self.display_thread_id,
             display_thread_name: self.display_thread_name,
+            display_filename: self.display_filename,
+            display_line_number: self.display_line_number,
         }
     }
 
@@ -556,6 +562,8 @@ impl<F, T> Format<F, T> {
             display_level: self.display_level,
             display_thread_id: self.display_thread_id,
             display_thread_name: self.display_thread_name,
+            display_filename: true,
+            display_line_number: true,
         }
     }
 
@@ -587,6 +595,8 @@ impl<F, T> Format<F, T> {
             display_level: self.display_level,
             display_thread_id: self.display_thread_id,
             display_thread_name: self.display_thread_name,
+            display_filename: self.display_filename,
+            display_line_number: self.display_line_number,
         }
     }
 
@@ -614,6 +624,8 @@ impl<F, T> Format<F, T> {
             display_level: self.display_level,
             display_thread_id: self.display_thread_id,
             display_thread_name: self.display_thread_name,
+            display_filename: self.display_filename,
+            display_line_number: self.display_line_number,
         }
     }
 
@@ -628,6 +640,8 @@ impl<F, T> Format<F, T> {
             display_level: self.display_level,
             display_thread_id: self.display_thread_id,
             display_thread_name: self.display_thread_name,
+            display_filename: self.display_filename,
+            display_line_number: self.display_line_number,
         }
     }
 
@@ -677,6 +691,38 @@ impl<F, T> Format<F, T> {
         }
     }
 
+    /// Sets whether or not an event's [source code file path][file] is
+    /// displayed.
+    ///
+    /// [file]: tracing_core::Metadata::file
+    pub fn with_file(self, display_filename: bool) -> Format<F, T> {
+        Format {
+            display_filename,
+            ..self
+        }
+    }
+
+    /// Sets whether or not an event's [source code line number][line] is
+    /// displayed.
+    ///
+    /// [line]: tracing_core::Metadata::line
+    pub fn with_line_number(self, display_line_number: bool) -> Format<F, T> {
+        Format {
+            display_line_number,
+            ..self
+        }
+    }
+
+    /// Sets whether or not the source code location from which an event
+    /// originated is displayed.
+    ///
+    /// This is equivalent to calling [`Format::with_file`] and
+    /// [`Format::with_line_number`] with the same value.
+    pub fn with_source_location(self, display_location: bool) -> Self {
+        self.with_line_number(display_location)
+            .with_file(display_location)
+    }
+
     #[inline]
     fn format_timestamp(&self, writer: &mut Writer<'_>) -> fmt::Result
     where
@@ -852,6 +898,34 @@ where
             )?;
         }
 
+        let line_number = if self.display_line_number {
+            meta.line()
+        } else {
+            None
+        };
+
+        if self.display_filename {
+            if let Some(filename) = meta.file() {
+                write!(
+                    writer,
+                    "{}{}{}",
+                    dimmed.paint(filename),
+                    dimmed.paint(":"),
+                    if line_number.is_some() { "" } else { " " }
+                )?;
+            }
+        }
+
+        if let Some(line_number) = line_number {
+            write!(
+                writer,
+                "{}{}:{} ",
+                dimmed.prefix(),
+                line_number,
+                dimmed.suffix()
+            )?;
+        }
+
         ctx.format_fields(writer.by_ref(), event)?;
         writeln!(writer)
     }
@@ -930,18 +1004,45 @@ where
         };
         write!(writer, "{}", fmt_ctx)?;
 
+        let bold = writer.bold();
+        let dimmed = writer.dimmed();
+
+        let mut needs_space = false;
         if self.display_target {
+            write!(writer, "{}{}", bold.paint(meta.target()), dimmed.paint(":"))?;
+            needs_space = true;
+        }
+
+        if self.display_filename {
+            if let Some(filename) = meta.file() {
+                if self.display_target {
+                    writer.write_char(' ')?;
+                }
+                write!(writer, "{}{}", bold.paint(filename), dimmed.paint(":"))?;
+                needs_space = true;
+            }
+        }
+
+        if self.display_line_number {
+            if let Some(line_number) = meta.line() {
                 write!(
                     writer,
-                "{}{} ",
-                writer.bold().paint(meta.target()),
-                writer.dimmed().paint(":")
+                    "{}{}{}{}",
+                    bold.prefix(),
+                    line_number,
+                    bold.suffix(),
+                    dimmed.paint(":")
                 )?;
+                needs_space = true;
+            }
+        }
+
+        if needs_space {
+            writer.write_char(' ')?;
         }
 
         ctx.format_fields(writer.by_ref(), event)?;
 
-        let dimmed = writer.dimmed();
         for span in ctx
             .event_scope()
             .into_iter()
@@ -1213,6 +1314,14 @@ impl Style {
     fn paint(&self, d: impl fmt::Display) -> impl fmt::Display {
         d
     }
+
+    fn prefix(&self) -> impl fmt::Display {
+        ""
+    }
+
+    fn suffix(&self) -> impl fmt::Display {
+        ""
+    }
 }
 
 struct FmtThreadName<'a> {
@@ -1540,9 +1649,9 @@ pub(super) mod test {
     };
 
     use super::*;
-    use std::fmt;
 
     use regex::Regex;
+    use std::{fmt, path::Path};
 
     pub(crate) struct MockTime;
     impl FormatTime for MockTime {
@@ -1612,6 +1721,99 @@ pub(super) mod test {
         run_test(subscriber, make_writer, expected);
     }
 
+    #[test]
+    fn with_line_number_and_file_name() {
+        let make_writer = MockMakeWriter::default();
+        let subscriber = crate::fmt::Subscriber::builder()
+            .with_writer(make_writer.clone())
+            .with_file(true)
+            .with_line_number(true)
+            .with_level(false)
+            .with_ansi(false)
+            .with_timer(MockTime);
+
+        let expected = Regex::new(&format!(
+            "^fake time tracing_subscriber::fmt::format::test: {}:[0-9]+: hello\n$",
+            current_path()
+                // if we're on Windows, the path might contain backslashes, which
+                // have to be escpaed before compiling the regex.
+                .replace('\\', "\\\\")
+        ))
+        .unwrap();
+        let _default = set_default(&subscriber.into());
+        tracing::info!("hello");
+        let res = make_writer.get_string();
+        assert!(expected.is_match(&res));
+    }
+
+    #[test]
+    fn with_line_number() {
+        let make_writer = MockMakeWriter::default();
+        let subscriber = crate::fmt::Subscriber::builder()
+            .with_writer(make_writer.clone())
+            .with_line_number(true)
+            .with_level(false)
+            .with_ansi(false)
+            .with_timer(MockTime);
+
+        let expected =
+            Regex::new("^fake time tracing_subscriber::fmt::format::test: [0-9]+: hello\n$")
+                .unwrap();
+        let _default = set_default(&subscriber.into());
+        tracing::info!("hello");
+        let res = make_writer.get_string();
+        assert!(expected.is_match(&res));
+    }
+
+    #[test]
+    fn with_filename() {
+        let make_writer = MockMakeWriter::default();
+        let subscriber = crate::fmt::Subscriber::builder()
+            .with_writer(make_writer.clone())
+            .with_file(true)
+            .with_level(false)
+            .with_ansi(false)
+            .with_timer(MockTime);
+        let expected = &format!(
+            "fake time tracing_subscriber::fmt::format::test: {}: hello\n",
+            current_path(),
+        );
+        assert_info_hello(subscriber, make_writer, expected);
+    }
+
+    #[test]
+    fn with_thread_ids() {
+        let make_writer = MockMakeWriter::default();
+        let subscriber = crate::fmt::Subscriber::builder()
+            .with_writer(make_writer.clone())
+            .with_thread_ids(true)
+            .with_ansi(false)
+            .with_timer(MockTime);
+        let expected =
+            "fake time  INFO ThreadId(NUMERIC) tracing_subscriber::fmt::format::test: hello\n";
+
+        assert_info_hello_ignore_numeric(subscriber, make_writer, expected);
+    }
+
+    #[test]
+    fn pretty_default() {
+        let make_writer = MockMakeWriter::default();
+        let subscriber = crate::fmt::Subscriber::builder()
+            .pretty()
+            .with_writer(make_writer.clone())
+            .with_ansi(false)
+            .with_timer(MockTime);
+        let expected = format!(
+            r#"  fake time  INFO tracing_subscriber::fmt::format::test: hello
+    at {}:NUMERIC
+
+"#,
+            file!()
+        );
+
+        assert_info_hello_ignore_numeric(subscriber, make_writer, &expected)
+    }
+
     fn assert_info_hello(subscriber: impl Into<Dispatch>, buf: MockMakeWriter, expected: &str) {
         let _default = set_default(&subscriber.into());
         tracing::info!("hello");
@@ -1645,14 +1847,14 @@ pub(super) mod test {
         T: Send + Sync + 'static,
     {
         let make_writer = MockMakeWriter::default();
-        let collector = builder
+        let subscriber = builder
             .with_writer(make_writer.clone())
             .with_level(false)
             .with_ansi(false)
             .with_timer(MockTime)
             .finish();
 
-        with_default(collector, || {
+        with_default(subscriber, || {
             let span1 = tracing::info_span!("span1", span = 1);
             let span2 = tracing::info_span!(parent: &span1, "span2", span = 2);
             tracing::info!(parent: &span2, "hello");
@@ -1869,4 +2071,16 @@ pub(super) mod test {
         assert!(!f.contains(FmtSpan::EXIT));
         assert!(f.contains(FmtSpan::CLOSE));
     }
+
+    /// Returns the test's module path.
+    fn current_path() -> String {
+        Path::new("tracing-subscriber")
+            .join("src")
+            .join("fmt")
+            .join("format")
+            .join("mod.rs")
+            .to_str()
+            .expect("path must not contain invalid unicode")
+            .to_owned()
+    }
 }

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

@@ -76,6 +76,10 @@ impl Pretty {
     /// Sets whether the event's source code location is displayed.
     ///
     /// This defaults to `true`.
+    #[deprecated(
+        since = "0.3.6",
+        note = "all formatters now support configurable source locations. Use `Format::with_source_location` instead."
+    )]
     pub fn with_source_location(self, display_location: bool) -> Self {
         Self {
             display_location,
@@ -84,17 +88,6 @@ impl Pretty {
     }
 }
 
-impl<T> Format<Pretty, T> {
-    /// Sets whether or not the source code location from which an event
-    /// originated is displayed.
-    ///
-    /// This defaults to `true`.
-    pub fn with_source_location(mut self, display_location: bool) -> Self {
-        self.format = self.format.with_source_location(display_location);
-        self
-    }
-}
-
 impl<C, N, T> FormatEvent<C, N> for Format<Pretty, T>
 where
     C: Subscriber + for<'a> LookupSpan<'a>,
@@ -147,12 +140,37 @@ where
             };
             write!(
                 writer,
-                "{}{}{}: ",
+                "{}{}{}:",
                 target_style.prefix(),
                 meta.target(),
                 target_style.infix(style)
             )?;
         }
+        let line_number = if self.display_line_number {
+            meta.line()
+        } else {
+            None
+        };
+
+        // If the file name is disabled, format the line number right after the
+        // target. Otherwise, if we also display the file, it'll go on a
+        // separate line.
+        if let (Some(line_number), false, true) = (
+            line_number,
+            self.display_filename,
+            self.format.display_location,
+        ) {
+            write!(
+                writer,
+                "{}{}{}:",
+                style.prefix(),
+                line_number,
+                style.infix(style)
+            )?;
+        }
+
+        writer.write_char(' ')?;
+
         let mut v = PrettyVisitor::new(writer.by_ref(), true).with_style(style);
         event.record(&mut v);
         v.finish()?;
@@ -164,20 +182,21 @@ where
             Style::new()
         };
         let thread = self.display_thread_name || self.display_thread_id;
-        if let (true, Some(file), Some(line)) =
-            (self.format.display_location, meta.file(), meta.line())
-        {
-            write!(
-                writer,
-                "    {} {}:{}{}",
-                dimmed.paint("at"),
-                file,
-                line,
-                dimmed.paint(if thread { " " } else { "\n" })
-            )?;
+
+        if let (Some(file), true, true) = (
+            meta.file(),
+            self.format.display_location,
+            self.display_filename,
+        ) {
+            write!(writer, "    {} {}", dimmed.paint("at"), file,)?;
+
+            if let Some(line) = line_number {
+                write!(writer, ":{}", line)?;
+            }
+            writer.write_char(if thread { ' ' } else { '\n' })?;
         } else if thread {
             write!(writer, "    ")?;
-        }
+        };
 
         if thread {
             write!(writer, "{} ", dimmed.paint("on"))?;

tracing-subscriber/src/fmt/mod.rs

@@ -734,6 +734,34 @@ where
         }
     }
 
+    /// Sets whether or not an event's [source code file path][file] is
+    /// displayed.
+    ///
+    /// [file]: tracing_core::Metadata::file
+    pub fn with_file(
+        self,
+        display_filename: bool,
+    ) -> SubscriberBuilder<N, format::Format<L, T>, F, W> {
+        SubscriberBuilder {
+            inner: self.inner.with_file(display_filename),
+            ..self
+        }
+    }
+
+    /// Sets whether or not an event's [source code line number][line] is
+    /// displayed.
+    ///
+    /// [line]: tracing_core::Metadata::line
+    pub fn with_line_number(
+        self,
+        display_line_number: bool,
+    ) -> SubscriberBuilder<N, format::Format<L, T>, F, W> {
+        SubscriberBuilder {
+            inner: self.inner.with_line_number(display_line_number),
+            ..self
+        }
+    }
+
     /// Sets whether or not an event's level is displayed.
     pub fn with_level(
         self,