diff --git a/tracing-journald/src/lib.rs b/tracing-journald/src/lib.rs index ef005ee47d..a8d88a6e4b 100644 --- a/tracing-journald/src/lib.rs +++ b/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,16 +215,13 @@ 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)); @@ -232,13 +229,11 @@ where fn on_record(&self, id: &Id, values: &Record, ctx: Context) { 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::().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,6 +252,7 @@ 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() @@ -264,7 +260,7 @@ where 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); struct SpanVisitor<'a> { buf: &'a mut Vec, - 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, meta: &Metadata, span: Option) { - 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, 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, 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(); diff --git a/tracing-journald/tests/journal.rs b/tracing-journald/tests/journal.rs index 4094661a9c..dadb37aac3 100644 --- a/tracing-journald/tests/journal.rs +++ b/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 { } 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), Binary(Vec), } +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> 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"]); + }); +}