Skip to content

Commit

Permalink
journald: remove span field prefixes; add separate fields for span da…
Browse files Browse the repository at this point in the history 
…ta (#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.
  • Loading branch information
@wiktorsikora @hawkw
wiktorsikora authored and hawkw committed Apr 8, 2022
1 parent bd6c611 commit 4eed50a
Show file tree
Hide file tree
Showing 2 changed files with 163 additions and 42 deletions.
74 changes: 34 additions & 40 deletions tracing-journald/src/lib.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down Expand Up @@ -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(),
});
}

Expand All @@ -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.
Expand All @@ -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'_');
}
}

Expand Down Expand Up @@ -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();
Expand Down
131 changes: 129 additions & 2 deletions tracing-journald/tests/journal.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -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!(
Expand All @@ -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,
}
}
}
Expand All @@ -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,
}
}
}
Expand Down Expand Up @@ -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"]);
});
}

0 comments on commit 4eed50a

Please sign in to comment.