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 <[email protected]>
Co-authored-by: Eliza Weisman <[email protected]>

Author: 3 people

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::Subcriber` can write to multiple
     destinations (in this instance, stdout and a file) simultaneously.
+  + `fmt-source-locations.rs`: demonstrates displaying source code locations
+    with `fmt::Subscriber`.
   + `subscriber-filter`: Demonstrates the `tracing-subscriber::filter` module,
     which provides a subscriber which adds configurable filtering to a collector
     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_subscriber.rs

@@ -297,6 +297,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) -> Subscriber<C, N, format::Format<L, T>, W> {
+        Subscriber {
+            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,
+    ) -> Subscriber<C, N, format::Format<L, T>, W> {
+        Subscriber {
+            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) -> Subscriber<C, N, format::Format<L, T>, W> {

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

@@ -240,6 +240,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
@@ -483,6 +495,7 @@ mod test {
     use tracing::{self, collect::with_default};
 
     use std::fmt;
+    use std::path::Path;
 
     struct MockTime;
     impl FormatTime for MockTime {
@@ -510,6 +523,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 collector = collector()
+            .flatten_event(false)
+            .with_current_span(true)
+            .with_file(true)
+            .with_span_list(true);
+        test_json(expected, collector, || {
+            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 collector = collector()
+            .flatten_event(false)
+            .with_current_span(true)
+            .with_line_number(true)
+            .with_span_list(true);
+        test_json_with_line_number(expected, collector, || {
+            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 =
@@ -740,4 +797,34 @@ mod test {
             serde_json::from_str(actual).unwrap()
         );
     }
+
+    fn test_json_with_line_number<T>(
+        expected: &str,
+        builder: crate::fmt::CollectorBuilder<JsonFields, Format<Json>>,
+        producer: impl FnOnce() -> T,
+    ) {
+        let make_writer = MockMakeWriter::default();
+        let collector = builder
+            .with_writer(make_writer.clone())
+            .with_timer(MockTime)
+            .finish();
+
+        with_default(collector, 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);
+    }
 }