From ce613f879535254d31d633307a356a89e179c10f Mon Sep 17 00:00:00 2001 From: Wiktor Sikora Date: Fri, 8 Apr 2022 19:57:36 +0200 Subject: [PATCH] journald: remove span field prefixes; add separate fields for span data (#1968) ## Motivation Currently, `tracing-journald` prefixes event fields with the number of parent spans, if present, in order to namespace field values. This turned out to be unnecessary as journald preserves values for duplicated field names. ## Solution This branch removes event field prefixes and emits parent span names and their field/value pairs as additional key/value pairs. --- tracing-journald/src/lib.rs | 74 ++++++++--------- tracing-journald/tests/journal.rs | 131 +++++++++++++++++++++++++++++- 2 files changed, 163 insertions(+), 42 deletions(-) diff --git a/tracing-journald/src/lib.rs b/tracing-journald/src/lib.rs index ac126599..26808697 100644 --- a/tracing-journald/src/lib.rs +++ b/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,16 +214,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 +228,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 +251,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 +259,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 +271,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 +338,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 25c1412e..c2e07cc9 100644 --- a/tracing-journald/tests/journal.rs +++ b/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 { } 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), 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 +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> 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"]); + }); +}