journald: remove span field prefixes; add separate fields for span data

tracing-journald/src/lib.rs

@@ -37,6 +37,7 @@
     html_favicon_url = "https://raw.githubusercontent.com/tokio-rs/tracing/master/assets/favicon.ico",
     issue_tracker_base_url = "https://github.com/tokio-rs/tracing/issues/"
 )]
+
 #[cfg(unix)]
 use std::os::unix::net::UnixDatagram;
 use std::{fmt, io, io::Write};
@@ -69,12 +70,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 +215,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<C>) {
         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 +252,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 +272,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 +339,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,7 @@ 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::Subscriber;
 use tracing_subscriber::subscribe::CollectExt;
 use tracing_subscriber::Registry;
@@ -16,9 +16,13 @@ fn journalctl_version() -> std::io::Result<String> {
 }
 
 fn with_journald(f: impl FnOnce()) {
+    with_journald_subscriber(Subscriber::new().unwrap().with_field_prefix(None), f)
+}
+
+fn with_journald_subscriber(subscriber: Subscriber, f: impl FnOnce()) {
     match journalctl_version() {
         Ok(_) => {
-            let sub = Registry::default().with(Subscriber::new().unwrap().with_field_prefix(None));
+            let sub = Registry::default().with(subscriber);
             tracing::collect::with_default(sub, f);
         }
         Err(error) => eprintln!(
@@ -32,15 +36,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 +74,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 +217,94 @@ fn large_message() {
         assert_eq!(message["PRIORITY"], "6");
     });
 }
+
+#[test]
+fn simple_metadata() {
+    let sub = Subscriber::new()
+        .unwrap()
+        .with_field_prefix(None)
+        .with_syslog_identifier("test_ident".to_string());
+    with_journald_subscriber(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"]);
+    });
+}