backport changes to v0.1.x

.github/workflows/CI.yml

@@ -222,3 +222,32 @@ jobs:
       with:
         token: ${{ secrets.GITHUB_TOKEN }}
         args: --all --examples --tests --benches -- -D warnings
+
+  minimal-versions:
+    # Check for minimal-versions errors where a dependency is too
+    # underconstrained to build on the minimal supported version of all
+    # dependencies in the dependency graph.
+    name: minimal-versions
+    runs-on: ubuntu-latest
+    steps:
+      - uses: actions/checkout@v2
+      - uses: actions-rs/toolchain@v1
+        with:
+          toolchain: nightly
+          profile: minimal
+          override: true
+      - name: Install cargo-hack
+        run: |
+          curl -LsSf https://github.com/taiki-e/cargo-hack/releases/latest/download/cargo-hack-x86_64-unknown-linux-gnu.tar.gz | tar xzf - -C ~/.cargo/bin
+      - name: "check --all-features -Z minimal-versions"
+        run: |
+          # Remove dev-dependencies from Cargo.toml to prevent the next `cargo update`
+          # from determining minimal versions based on dev-dependencies.
+          cargo hack --remove-dev-deps --workspace
+          # Update Cargo.lock to minimal version dependencies.
+          cargo update -Z minimal-versions
+          cargo hack check \
+            --package tracing \
+            --package tracing-core \
+            --package tracing-subscriber \
+            --all-features --ignore-private

tracing-core/Cargo.toml

@@ -34,7 +34,7 @@ std = ["lazy_static"]
 maintenance = { status = "actively-developed" }
 
 [dependencies]
-lazy_static = { version = "1", optional = true }
+lazy_static = { version = "1.0.2", optional = true }
 
 [target.'cfg(tracing_unstable)'.dependencies]
 valuable = { version = "0.1.0", optional = true, default_features = false }

tracing-error/src/lib.rs

@@ -232,5 +232,8 @@ pub mod prelude {
     //! extension traits. These traits allow attaching `SpanTrace`s to errors and
     //! subsequently retrieving them from `dyn Error` trait objects.
 
+    // apparently `as _` reexpoorts now generate `unreachable_pub` linting? which
+    // seems wrong to me...
+    #![allow(unreachable_pub)]
     pub use crate::{ExtractSpanTrace as _, InstrumentError as _, InstrumentResult as _};
 }

tracing-journald/src/lib.rs

@@ -69,12 +69,11 @@ mod socket;
 /// - `DEBUG` => Informational (6)
 /// - `TRACE` => Debug (7)
 ///
-/// Note that the naming scheme differs slightly for the latter half.
-///
 /// The standard journald `CODE_LINE` and `CODE_FILE` fields are automatically emitted. A `TARGET`
-/// field is emitted containing the event's target. Enclosing spans are numbered counting up from
-/// the root, and their fields and metadata are included in fields prefixed by `Sn_` where `n` is
-/// that number.
+/// field is emitted containing the event's target.
+///
+/// For events recorded inside spans, an additional `SPAN_NAME` field is emitted with the name of
+/// each of the event's parent spans.
 ///
 /// User-defined fields other than the event `message` field have a prefix applied by default to
 /// prevent collision with standard fields.
@@ -215,30 +214,25 @@ where
         let span = ctx.span(id).expect("unknown span");
         let mut buf = Vec::with_capacity(256);
 
-        let depth = span.scope().skip(1).count();
-
-        writeln!(buf, "S{}_NAME", depth).unwrap();
+        writeln!(buf, "SPAN_NAME").unwrap();
         put_value(&mut buf, span.name().as_bytes());
-        put_metadata(&mut buf, span.metadata(), Some(depth));
+        put_metadata(&mut buf, span.metadata(), Some("SPAN_"));
 
         attrs.record(&mut SpanVisitor {
             buf: &mut buf,
-            depth,
-            prefix: self.field_prefix.as_ref().map(|x| &x[..]),
+            field_prefix: self.field_prefix.as_deref(),
         });
 
         span.extensions_mut().insert(SpanFields(buf));
     }
 
     fn on_record(&self, id: &Id, values: &Record, ctx: Context<S>) {
         let span = ctx.span(id).expect("unknown span");
-        let depth = span.scope().skip(1).count();
         let mut exts = span.extensions_mut();
         let buf = &mut exts.get_mut::<SpanFields>().expect("missing fields").0;
         values.record(&mut SpanVisitor {
             buf,
-            depth,
-            prefix: self.field_prefix.as_ref().map(|x| &x[..]),
+            field_prefix: self.field_prefix.as_deref(),
         });
     }
 
@@ -257,14 +251,15 @@ where
         }
 
         // Record event fields
+        put_priority(&mut buf, event.metadata());
         put_metadata(&mut buf, event.metadata(), None);
         put_field_length_encoded(&mut buf, "SYSLOG_IDENTIFIER", |buf| {
             write!(buf, "{}", self.syslog_identifier).unwrap()
         });
 
         event.record(&mut EventVisitor::new(
             &mut buf,
-            self.field_prefix.as_ref().map(|x| &x[..]),
+            self.field_prefix.as_deref(),
         ));
 
         // At this point we can't handle the error anymore so just ignore it.
@@ -276,17 +271,15 @@ struct SpanFields(Vec<u8>);
 
 struct SpanVisitor<'a> {
     buf: &'a mut Vec<u8>,
-    depth: usize,
-    prefix: Option<&'a str>,
+    field_prefix: Option<&'a str>,
 }
 
 impl SpanVisitor<'_> {
     fn put_span_prefix(&mut self) {
-        write!(self.buf, "S{}", self.depth).unwrap();
-        if let Some(prefix) = self.prefix {
+        if let Some(prefix) = self.field_prefix {
             self.buf.extend_from_slice(prefix.as_bytes());
+            self.buf.push(b'_');
         }
-        self.buf.push(b'_');
     }
 }
 
@@ -345,33 +338,34 @@ impl Visit for EventVisitor<'_> {
     }
 }
 
-fn put_metadata(buf: &mut Vec<u8>, meta: &Metadata, span: Option<usize>) {
-    if span.is_none() {
-        put_field_wellformed(
-            buf,
-            "PRIORITY",
-            match *meta.level() {
-                Level::ERROR => b"3",
-                Level::WARN => b"4",
-                Level::INFO => b"5",
-                Level::DEBUG => b"6",
-                Level::TRACE => b"7",
-            },
-        );
-    }
-    if let Some(n) = span {
-        write!(buf, "S{}_", n).unwrap();
+fn put_priority(buf: &mut Vec<u8>, meta: &Metadata) {
+    put_field_wellformed(
+        buf,
+        "PRIORITY",
+        match *meta.level() {
+            Level::ERROR => b"3",
+            Level::WARN => b"4",
+            Level::INFO => b"5",
+            Level::DEBUG => b"6",
+            Level::TRACE => b"7",
+        },
+    );
+}
+
+fn put_metadata(buf: &mut Vec<u8>, meta: &Metadata, prefix: Option<&str>) {
+    if let Some(prefix) = prefix {
+        write!(buf, "{}", prefix).unwrap();
     }
     put_field_wellformed(buf, "TARGET", meta.target().as_bytes());
     if let Some(file) = meta.file() {
-        if let Some(n) = span {
-            write!(buf, "S{}_", n).unwrap();
+        if let Some(prefix) = prefix {
+            write!(buf, "{}", prefix).unwrap();
         }
         put_field_wellformed(buf, "CODE_FILE", file.as_bytes());
     }
     if let Some(line) = meta.line() {
-        if let Some(n) = span {
-            write!(buf, "S{}_", n).unwrap();
+        if let Some(prefix) = prefix {
+            write!(buf, "{}", prefix).unwrap();
         }
         // Text format is safe as a line number can't possibly contain anything funny
         writeln!(buf, "CODE_LINE={}", line).unwrap();

tracing-journald/tests/journal.rs

@@ -5,7 +5,8 @@ use std::process::Command;
 use std::time::Duration;
 
 use serde::Deserialize;
-use tracing::{debug, error, info, warn};
+
+use tracing::{debug, error, info, info_span, warn};
 use tracing_journald::Layer;
 use tracing_subscriber::layer::SubscriberExt;
 use tracing_subscriber::Registry;
@@ -16,9 +17,13 @@ fn journalctl_version() -> std::io::Result<String> {
 }
 
 fn with_journald(f: impl FnOnce()) {
+    with_journald_layer(Layer::new().unwrap().with_field_prefix(None), f)
+}
+
+fn with_journald_layer(layer: Layer, f: impl FnOnce()) {
     match journalctl_version() {
         Ok(_) => {
-            let sub = Registry::default().with(Layer::new().unwrap().with_field_prefix(None));
+            let sub = Registry::default().with(layer);
             tracing::subscriber::with_default(sub, f);
         }
         Err(error) => eprintln!(
@@ -32,15 +37,35 @@ fn with_journald(f: impl FnOnce()) {
 #[serde(untagged)]
 enum Field {
     Text(String),
+    Array(Vec<String>),
     Binary(Vec<u8>),
 }
 
+impl Field {
+    fn as_array(&self) -> Option<&[String]> {
+        match self {
+            Field::Text(_) => None,
+            Field::Binary(_) => None,
+            Field::Array(v) => Some(v),
+        }
+    }
+
+    fn as_text(&self) -> Option<&str> {
+        match self {
+            Field::Text(v) => Some(v.as_str()),
+            Field::Binary(_) => None,
+            Field::Array(_) => None,
+        }
+    }
+}
+
 // Convenience impls to compare fields against strings and bytes with assert_eq!
 impl PartialEq<&str> for Field {
     fn eq(&self, other: &&str) -> bool {
         match self {
             Field::Text(s) => s == other,
             Field::Binary(_) => false,
+            Field::Array(_) => false,
         }
     }
 }
@@ -50,6 +75,17 @@ impl PartialEq<[u8]> for Field {
         match self {
             Field::Text(s) => s.as_bytes() == other,
             Field::Binary(data) => data == other,
+            Field::Array(_) => false,
+        }
+    }
+}
+
+impl PartialEq<Vec<&str>> for Field {
+    fn eq(&self, other: &Vec<&str>) -> bool {
+        match self {
+            Field::Text(_) => false,
+            Field::Binary(_) => false,
+            Field::Array(data) => data == other,
         }
     }
 }
@@ -182,3 +218,94 @@ fn large_message() {
         assert_eq!(message["PRIORITY"], "6");
     });
 }
+
+#[test]
+fn simple_metadata() {
+    let sub = Layer::new()
+        .unwrap()
+        .with_field_prefix(None)
+        .with_syslog_identifier("test_ident".to_string());
+    with_journald_layer(sub, || {
+        info!(test.name = "simple_metadata", "Hello World");
+
+        let message = retry_read_one_line_from_journal("simple_metadata");
+        assert_eq!(message["MESSAGE"], "Hello World");
+        assert_eq!(message["PRIORITY"], "5");
+        assert_eq!(message["TARGET"], "journal");
+        assert_eq!(message["SYSLOG_IDENTIFIER"], "test_ident");
+        assert!(message["CODE_FILE"].as_text().is_some());
+        assert!(message["CODE_LINE"].as_text().is_some());
+    });
+}
+
+#[test]
+fn span_metadata() {
+    with_journald(|| {
+        let s1 = info_span!("span1", span_field1 = "foo1");
+        let _g1 = s1.enter();
+
+        info!(test.name = "span_metadata", "Hello World");
+
+        let message = retry_read_one_line_from_journal("span_metadata");
+        assert_eq!(message["MESSAGE"], "Hello World");
+        assert_eq!(message["PRIORITY"], "5");
+        assert_eq!(message["TARGET"], "journal");
+
+        assert_eq!(message["SPAN_FIELD1"].as_text(), Some("foo1"));
+        assert_eq!(message["SPAN_NAME"].as_text(), Some("span1"));
+
+        assert!(message["CODE_FILE"].as_text().is_some());
+        assert!(message["CODE_LINE"].as_text().is_some());
+
+        assert!(message["SPAN_CODE_FILE"].as_text().is_some());
+        assert!(message["SPAN_CODE_LINE"].as_text().is_some());
+    });
+}
+
+#[test]
+fn multiple_spans_metadata() {
+    with_journald(|| {
+        let s1 = info_span!("span1", span_field1 = "foo1");
+        let _g1 = s1.enter();
+        let s2 = info_span!("span2", span_field1 = "foo2");
+        let _g2 = s2.enter();
+
+        info!(test.name = "multiple_spans_metadata", "Hello World");
+
+        let message = retry_read_one_line_from_journal("multiple_spans_metadata");
+        assert_eq!(message["MESSAGE"], "Hello World");
+        assert_eq!(message["PRIORITY"], "5");
+        assert_eq!(message["TARGET"], "journal");
+
+        assert_eq!(message["SPAN_FIELD1"], vec!["foo1", "foo2"]);
+        assert_eq!(message["SPAN_NAME"], vec!["span1", "span2"]);
+
+        assert!(message["CODE_FILE"].as_text().is_some());
+        assert!(message["CODE_LINE"].as_text().is_some());
+
+        assert!(message.contains_key("SPAN_CODE_FILE"));
+        assert_eq!(message["SPAN_CODE_LINE"].as_array().unwrap().len(), 2);
+    });
+}
+
+#[test]
+fn spans_field_collision() {
+    with_journald(|| {
+        let s1 = info_span!("span1", span_field = "foo1");
+        let _g1 = s1.enter();
+        let s2 = info_span!("span2", span_field = "foo2");
+        let _g2 = s2.enter();
+
+        info!(
+            test.name = "spans_field_collision",
+            span_field = "foo3",
+            "Hello World"
+        );
+
+        let message = retry_read_one_line_from_journal("spans_field_collision");
+        assert_eq!(message["MESSAGE"], "Hello World");
+        assert_eq!(message["SPAN_NAME"], vec!["span1", "span2"]);
+
+        assert_eq!(message["SPAN_FIELD"], vec!["foo1", "foo2", "foo3"]);
+    });
+}