itsscb/tracing
1
0
Fork 0
mirror of https://github.com/tokio-rs/tracing.git synced 2025-09-28 21:42:15 +00:00
Code Issues Packages Projects Releases Wiki Activity

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

Browse Source 
## 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.
This commit is contained in:
Wiktor Sikora 2022-04-08 19:57:36 +02:00 committed by Eliza Weisman
parent b0146c5784
commit ce613f8795
2 changed files with 163 additions and 42 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

74
tracing-journald/src/lib.rs
View File

@ -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<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(),
});
}
@ -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<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 +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();

131
tracing-journald/tests/journal.rs
View File

@ -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<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!(
@ -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,
}
}
}
@ -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,
}
}
}
@ -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"]);
});
}