Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Merged
merged 11 commits into from
Apr 8, 2022
Next Next commit
option to disable prefix of user-defined span fields
  • Loading branch information
wiktorsikora committed Mar 5, 2022
commit d1430cd5cc3dc1b4fb9354f713381c6b63a1d7ca
32 changes: 23 additions & 9 deletions tracing-journald/src/lib.rs
Original file line number Diff line number Diff line change
@@ -74,7 +74,7 @@ mod socket;
/// 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.
/// that number. Prefixing user-defined span fields may be disabled.
wiktorsikora marked this conversation as resolved.
Show resolved Hide resolved
///
/// User-defined fields other than the event `message` field have a prefix applied by default to
/// prevent collision with standard fields.
@@ -84,6 +84,7 @@ pub struct Subscriber {
#[cfg(unix)]
socket: UnixDatagram,
field_prefix: Option<String>,
span_field_prefix: Option<String>,
syslog_identifier: String,
}

@@ -102,6 +103,7 @@ impl Subscriber {
let sub = Self {
socket,
field_prefix: Some("F".into()),
span_field_prefix: Some("S".into()),
syslog_identifier: std::env::current_exe()
.ok()
.as_ref()
@@ -129,6 +131,13 @@ impl Subscriber {
self
}

/// Sets the prefix to apply to names of user-defined span fields.
/// Defaults to `Some("S")`.
wiktorsikora marked this conversation as resolved.
Show resolved Hide resolved
pub fn with_span_field_prefix(mut self, x: Option<String>) -> Self {
self.span_field_prefix = x;
wiktorsikora marked this conversation as resolved.
Show resolved Hide resolved
self
}

/// Sets the syslog identifier for this logger.
///
/// The syslog identifier comes from the classic syslog interface (`openlog()`
@@ -224,7 +233,8 @@ where
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_field_prefix: self.span_field_prefix.as_deref(),
});

span.extensions_mut().insert(SpanFields(buf));
@@ -238,7 +248,8 @@ where
values.record(&mut SpanVisitor {
buf,
depth,
prefix: self.field_prefix.as_ref().map(|x| &x[..]),
field_prefix: self.field_prefix.as_deref(),
span_field_prefix: self.span_field_prefix.as_deref(),
});
}

@@ -264,7 +275,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.
@@ -277,16 +288,19 @@ struct SpanFields(Vec<u8>);
struct SpanVisitor<'a> {
buf: &'a mut Vec<u8>,
depth: usize,
prefix: Option<&'a str>,
field_prefix: Option<&'a str>,
span_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 {
self.buf.extend_from_slice(prefix.as_bytes());
if let Some(span_prefix) = self.span_field_prefix {
write!(self.buf, "{}{}", span_prefix, self.depth).unwrap();
wiktorsikora marked this conversation as resolved.
Show resolved Hide resolved
if let Some(prefix) = self.field_prefix {
self.buf.extend_from_slice(prefix.as_bytes());
}
wiktorsikora marked this conversation as resolved.
Show resolved Hide resolved
self.buf.push(b'_');
}
self.buf.push(b'_');
}
}

91 changes: 89 additions & 2 deletions tracing-journald/tests/journal.rs
Original file line number Diff line number Diff line change
@@ -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);
Ralith marked this conversation as resolved.
Show resolved Hide resolved
tracing::collect::with_default(sub, f);
}
Err(error) => eprintln!(
@@ -32,6 +36,7 @@ fn with_journald(f: impl FnOnce()) {
#[serde(untagged)]
enum Field {
Text(String),
Array(Vec<String>),
Binary(Vec<u8>),
}

@@ -41,6 +46,7 @@ impl PartialEq<&str> for Field {
match self {
Field::Text(s) => s == other,
Field::Binary(_) => false,
Field::Array(_) => false
}
}
}
@@ -50,6 +56,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 +199,73 @@ fn large_message() {
assert_eq!(message["PRIORITY"], "6");
});
}

#[test]
fn span_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 = "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["S0_SPAN_FIELD1"], "foo1");
assert_eq!(message["S0_NAME"], "span1");
assert!(message.contains_key("S0_CODE_FILE"));
assert!(message.contains_key("S0_CODE_LINE"));

assert_eq!(message["S1_SPAN_FIELD1"], "foo2");
assert_eq!(message["S1_NAME"], "span2");
assert!(message.contains_key("S1_CODE_FILE"));
assert!(message.contains_key("S1_CODE_LINE"));
});
}

#[test]
fn no_span_field_prefix() {
let sub = Subscriber::new().unwrap()
.with_field_prefix(None)
.with_span_field_prefix(None);
with_journald_subscriber(sub, || {
let s1 = info_span!("span1", span_field = "foo");
let _guard = s1.enter();
info!(test.name = "no_span_prefix", "Hello World");

let message = retry_read_one_line_from_journal("no_span_prefix");
assert_eq!(message["MESSAGE"], "Hello World");
assert_eq!(message["PRIORITY"], "5");

// standard fields still prefixed
assert_eq!(message["S0_NAME"], "span1");
assert!(message.contains_key("S0_CODE_FILE"));
assert!(message.contains_key("S0_CODE_LINE"));

assert_eq!(message["SPAN_FIELD"], "foo");
});
}

#[test]
fn spans_field_collision() {
let sub = Subscriber::new().unwrap()
.with_field_prefix(None)
.with_span_field_prefix(None);
with_journald_subscriber(sub, || {
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", "Hello World");

let message = retry_read_one_line_from_journal("spans_field_collision");
assert_eq!(message["MESSAGE"], "Hello World");
assert_eq!(message["S0_NAME"], "span1");

assert_eq!(message["SPAN_FIELD"], vec!["foo1", "foo2"]);
});
}