use std::fmt;
use std::fmt::Write as _;
use tracing::field::{Field, Visit};
use tracing_subscriber::field::RecordFields;
use tracing_subscriber::fmt::format::Writer;
use tracing_subscriber::fmt::FormatFields;
pub const PARAM_VALUE_MAX_CHARS: usize = 1024;
pub struct CappedWriter<'a, W: fmt::Write> {
inner: &'a mut W,
remaining: usize,
}
impl<'a, W: fmt::Write> CappedWriter<'a, W> {
pub fn new(inner: &'a mut W) -> Self {
Self {
inner,
remaining: PARAM_VALUE_MAX_CHARS,
}
}
}
impl<W: fmt::Write> fmt::Write for CappedWriter<'_, W> {
fn write_str(&mut self, s: &str) -> fmt::Result {
for ch in s.chars() {
if self.remaining == 0 {
return Ok(());
}
self.remaining -= 1;
match ch {
'\n' => self.inner.write_str("\\n")?,
'\r' => self.inner.write_str("\\r")?,
'\t' => self.inner.write_str("\\t")?,
'\x00'..='\x1f' | '\x7f' => write!(self.inner, "\\x{:02x}", ch as u32)?,
'\u{80}'..='\u{9f}' | '\u{2028}' | '\u{2029}' => {
write!(self.inner, "\\u{{{:x}}}", ch as u32)?
}
_ => self.inner.write_char(ch)?,
}
}
Ok(())
}
}
#[derive(Debug, Clone, Copy, Default)]
pub struct CappedFields;
impl<'writer> FormatFields<'writer> for CappedFields {
fn format_fields<R: RecordFields>(&self, writer: Writer<'writer>, fields: R) -> fmt::Result {
let mut visitor = CappedVisitor {
writer,
is_empty: true,
result: Ok(()),
};
fields.record(&mut visitor);
visitor.result
}
}
struct CappedVisitor<'a> {
writer: Writer<'a>,
is_empty: bool,
result: fmt::Result,
}
impl CappedVisitor<'_> {
fn maybe_pad(&mut self) {
if self.is_empty {
self.is_empty = false;
} else {
self.result = self.writer.write_char(' ');
}
}
fn write_value(&mut self, value: &dyn fmt::Debug) -> fmt::Result {
write!(CappedWriter::new(&mut self.writer), "{value:?}")
}
}
impl Visit for CappedVisitor<'_> {
fn record_str(&mut self, field: &Field, value: &str) {
if self.result.is_err() {
return;
}
if field.name() == "message" {
self.record_debug(field, &format_args!("{value}"));
} else {
self.record_debug(field, &value);
}
}
fn record_error(&mut self, field: &Field, value: &(dyn std::error::Error + 'static)) {
match value.source() {
Some(source) => self.record_debug(
field,
&format_args!("{value} {}.sources={}", field.name(), ErrorSources(source)),
),
None => self.record_debug(field, &format_args!("{value}")),
}
}
fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) {
if self.result.is_err() {
return;
}
let name = field.name();
if name.starts_with("log.") {
return;
}
self.maybe_pad();
self.result = match name {
"message" => self.write_value(value),
name => {
let key = name.strip_prefix("r#").unwrap_or(name);
self.writer
.write_str(key)
.and_then(|()| self.writer.write_char('='))
.and_then(|()| self.write_value(value))
}
};
}
}
struct ErrorSources<'a>(&'a (dyn std::error::Error + 'static));
impl fmt::Display for ErrorSources<'_> {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
let mut list = f.debug_list();
let mut current = Some(self.0);
while let Some(error) = current {
list.entry(&Unquoted(error));
current = error.source();
}
list.finish()
}
}
struct Unquoted<'a>(&'a (dyn std::error::Error + 'static));
impl fmt::Debug for Unquoted<'_> {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
fmt::Display::fmt(self.0, f)
}
}
#[cfg(test)]
mod tests {
use std::sync::{Arc, Mutex};
use tracing_subscriber::fmt::format::DefaultFields;
use tracing_subscriber::layer::{Context, SubscriberExt as _};
use tracing_subscriber::Layer;
use super::*;
const ESC: char = '\x1b';
const ESCAPES: [(char, &str); 67] = [
('\u{00}', "\\x00"),
('\u{01}', "\\x01"),
('\u{02}', "\\x02"),
('\u{03}', "\\x03"),
('\u{04}', "\\x04"),
('\u{05}', "\\x05"),
('\u{06}', "\\x06"),
('\u{07}', "\\x07"),
('\u{08}', "\\x08"),
('\u{09}', "\\t"),
('\u{0a}', "\\n"),
('\u{0b}', "\\x0b"),
('\u{0c}', "\\x0c"),
('\u{0d}', "\\r"),
('\u{0e}', "\\x0e"),
('\u{0f}', "\\x0f"),
('\u{10}', "\\x10"),
('\u{11}', "\\x11"),
('\u{12}', "\\x12"),
('\u{13}', "\\x13"),
('\u{14}', "\\x14"),
('\u{15}', "\\x15"),
('\u{16}', "\\x16"),
('\u{17}', "\\x17"),
('\u{18}', "\\x18"),
('\u{19}', "\\x19"),
('\u{1a}', "\\x1a"),
('\u{1b}', "\\x1b"),
('\u{1c}', "\\x1c"),
('\u{1d}', "\\x1d"),
('\u{1e}', "\\x1e"),
('\u{1f}', "\\x1f"),
('\u{7f}', "\\x7f"),
('\u{80}', "\\u{80}"),
('\u{81}', "\\u{81}"),
('\u{82}', "\\u{82}"),
('\u{83}', "\\u{83}"),
('\u{84}', "\\u{84}"),
('\u{85}', "\\u{85}"),
('\u{86}', "\\u{86}"),
('\u{87}', "\\u{87}"),
('\u{88}', "\\u{88}"),
('\u{89}', "\\u{89}"),
('\u{8a}', "\\u{8a}"),
('\u{8b}', "\\u{8b}"),
('\u{8c}', "\\u{8c}"),
('\u{8d}', "\\u{8d}"),
('\u{8e}', "\\u{8e}"),
('\u{8f}', "\\u{8f}"),
('\u{90}', "\\u{90}"),
('\u{91}', "\\u{91}"),
('\u{92}', "\\u{92}"),
('\u{93}', "\\u{93}"),
('\u{94}', "\\u{94}"),
('\u{95}', "\\u{95}"),
('\u{96}', "\\u{96}"),
('\u{97}', "\\u{97}"),
('\u{98}', "\\u{98}"),
('\u{99}', "\\u{99}"),
('\u{9a}', "\\u{9a}"),
('\u{9b}', "\\u{9b}"),
('\u{9c}', "\\u{9c}"),
('\u{9d}', "\\u{9d}"),
('\u{9e}', "\\u{9e}"),
('\u{9f}', "\\u{9f}"),
('\u{2028}', "\\u{2028}"),
('\u{2029}', "\\u{2029}"),
];
#[derive(Clone, Debug, Default)]
struct Rendered {
default: String,
capped: String,
}
struct Differential(Arc<Mutex<Vec<Rendered>>>);
impl<S: tracing::Subscriber> Layer<S> for Differential {
fn on_event(&self, event: &tracing::Event<'_>, _ctx: Context<'_, S>) {
let mut rendered = Rendered::default();
DefaultFields::new()
.format_fields(Writer::new(&mut rendered.default), event)
.expect("a String never fails to be written");
CappedFields
.format_fields(Writer::new(&mut rendered.capped), event)
.expect("a String never fails to be written");
self.0.lock().expect("the render lock").push(rendered);
}
}
fn render(emit: impl FnOnce()) -> Vec<Rendered> {
let out: Arc<Mutex<Vec<Rendered>>> = Arc::new(Mutex::new(Vec::new()));
let subscriber = tracing_subscriber::registry().with(Differential(out.clone()));
tracing::subscriber::with_default(subscriber, emit);
let rendered = out.lock().expect("the render lock").clone();
assert!(!rendered.is_empty(), "the differential saw no events");
rendered
}
fn render_one(emit: impl FnOnce()) -> Rendered {
let mut rendered = render(emit);
assert_eq!(rendered.len(), 1, "exactly one event: {rendered:?}");
rendered.remove(0)
}
#[test]
fn the_budget_cuts_at_exactly_the_cap_on_a_char_boundary() {
for chars in [0, 1, PARAM_VALUE_MAX_CHARS - 1, PARAM_VALUE_MAX_CHARS] {
let mut out = String::new();
write!(CappedWriter::new(&mut out), "{}", "é".repeat(chars))
.expect("a String never fails to be written");
assert_eq!(out, "é".repeat(chars), "under the cap nothing moves");
}
let mut out = String::new();
write!(
CappedWriter::new(&mut out),
"{}",
"é".repeat(PARAM_VALUE_MAX_CHARS * 4)
)
.expect("a String never fails to be written");
assert_eq!(
out,
"é".repeat(PARAM_VALUE_MAX_CHARS),
"over the cap the cut is exact and lands between characters"
);
}
#[test]
fn a_value_written_in_pieces_is_cut_at_the_char_total() {
let piece = "é".repeat(PARAM_VALUE_MAX_CHARS / 2);
let mut out = String::new();
write!(CappedWriter::new(&mut out), "{piece}{piece}{piece}{piece}")
.expect("a String never fails to be written");
assert_eq!(out, "é".repeat(PARAM_VALUE_MAX_CHARS));
let mut writer = CappedWriter::new(&mut out);
writer
.write_str(&"z".repeat(PARAM_VALUE_MAX_CHARS * 2))
.expect("an exhausted budget swallows, it does not error");
writer
.write_str("z")
.expect("an exhausted budget swallows, it does not error");
assert_eq!(
out.chars().filter(|c| *c == 'z').count(),
PARAM_VALUE_MAX_CHARS,
"a second value gets its own budget and no more"
);
}
#[test]
fn the_escaping_matches_what_default_fields_does_to_a_message() {
let probe: String = ['\x1b', '\x07', '\x08', '\x0c', '\x7f']
.into_iter()
.chain(('\u{80}'..='\u{9f}').chain(['a', 'é', '"', '\\']))
.collect();
let rendered = render_one(|| tracing::info!("{probe}"));
assert_eq!(rendered.capped, rendered.default);
assert!(
rendered.capped.contains("\\x1b") && rendered.capped.contains("\\u{9b}"),
"and it really escaped something: {:?}",
rendered.capped
);
let escaped = rendered.capped.clone();
let field = render_one(|| tracing::info!(probe = %probe));
assert_eq!(field.capped, format!("probe={escaped}"));
assert!(
field.default.contains(ESC),
"the raw ESC this exists to stop must still be in what \
`DefaultFields` writes: {:?}",
field.default
);
}
#[test]
fn every_escaped_character_leaves_the_sink_as_its_escape() {
assert_eq!(
ESCAPES.map(|(ch, _)| ch).to_vec(),
('\u{00}'..='\u{1f}')
.chain(['\u{7f}'])
.chain('\u{80}'..='\u{9f}')
.chain(['\u{2028}', '\u{2029}'])
.collect::<Vec<char>>(),
"the table must walk C0, DEL, C1 and the two separators, \
in order and whole"
);
for (ch, escaped) in ESCAPES {
let value = format!("a{ch}b");
let mut out = String::new();
write!(CappedWriter::new(&mut out), "{value}")
.expect("a String never fails to be written");
assert_eq!(
out,
format!("a{escaped}b"),
"U+{:04X} must leave the adapter escaped",
ch as u32
);
assert_eq!(
render_one(|| tracing::info!(probe = %value)).capped,
format!("probe=a{escaped}b"),
"and the same through the field visitor, U+{:04X}",
ch as u32
);
}
for ch in [' ', '\u{a0}'] {
let value = format!("a{ch}b");
let mut out = String::new();
write!(CappedWriter::new(&mut out), "{value}")
.expect("a String never fails to be written");
assert_eq!(
out, value,
"U+{:04X} is outside the set and must pass through raw",
ch as u32
);
}
}
#[test]
fn the_characters_default_fields_leaves_raw_are_escaped_here() {
for (ch, escaped) in [
('\n', "\\n"),
('\r', "\\r"),
('\t', "\\t"),
('\u{01}', "\\x01"),
('\u{2028}', "\\u{2028}"),
] {
let probe = format!("a{ch}b");
let rendered = render_one(|| tracing::info!("{probe}"));
assert_eq!(
rendered.default, probe,
"tracing-subscriber leaves U+{:04X} raw even in \
`message`, which is the thing being diverged from",
ch as u32
);
assert_eq!(
rendered.capped,
format!("a{escaped}b"),
"and this sink escapes it instead, by decision: U+{:04X}",
ch as u32
);
}
}
#[test]
fn lf_cr_and_tab_read_alike_in_a_debug_field_and_a_display_one() {
let probe = "a\nb\tc\rd";
let rendered = render_one(|| tracing::info!(debug = ?probe, display = %probe)).capped;
let (debug, display) = rendered
.split_once(" display=")
.unwrap_or_else(|| panic!("both fields must reach the line: {rendered:?}"));
let debug = debug
.strip_prefix("debug=\"")
.and_then(|value| value.strip_suffix('"'))
.unwrap_or_else(|| panic!("`str`'s `Debug` quotes its value: {debug:?}"));
assert_eq!(
debug, display,
"the two shapes must render one value identically: {rendered:?}"
);
assert_eq!(
display, "a\\nb\\tc\\rd",
"and in the spellings `Debug` chose: {rendered:?}"
);
}
#[test]
fn every_field_shape_renders_exactly_as_default_fields_renders_it() {
#[derive(Debug)]
struct Inner;
impl std::fmt::Display for Inner {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
f.write_str("the inner cause")
}
}
impl std::error::Error for Inner {}
#[derive(Debug)]
struct Outer(Inner);
impl std::fmt::Display for Outer {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
f.write_str("the outer failure")
}
}
impl std::error::Error for Outer {
fn source(&self) -> Option<&(dyn std::error::Error + 'static)> {
Some(&self.0)
}
}
let text = "a plain value";
let owned = String::from("owned text");
let lone: &(dyn std::error::Error + 'static) = &Inner;
let chained: &(dyn std::error::Error + 'static) = &Outer(Inner);
let rendered = render(|| {
tracing::info!("a message alone");
tracing::info!(display = %text, "message and fields");
tracing::info!(debug = ?text, quoted = text, owned = owned.as_str());
tracing::info!(count = 7u64, signed = -7i64, ratio = 0.5, flag = true);
tracing::info!(r#type = "raw identifier", nested = ?vec![1, 2, 3]);
tracing::info!("r#type" = "a literal raw name");
tracing::error!(error = lone, "an error without a source");
tracing::error!(error = chained, "an error with a source");
tracing::info!(
log.target = "reqwest::connect",
log.module_path = "reqwest",
log.file = "connect.rs",
log.line = 1,
"a bridged record"
);
});
for one in &rendered {
assert_eq!(one.capped, one.default, "rendering must not drift");
}
let all = rendered
.iter()
.map(|one| one.capped.as_str())
.collect::<Vec<_>>()
.join("\n");
for needle in [
"display=a plain value",
"debug=\"a plain value\"",
"quoted=\"a plain value\"",
"count=7 signed=-7 ratio=0.5 flag=true",
"type=\"raw identifier\"",
"type=\"a literal raw name\"",
"nested=[1, 2, 3]",
"error=the outer failure error.sources=[the inner cause]",
] {
assert!(all.contains(needle), "{needle:?} missing from:\n{all}");
}
}
#[test]
fn the_log_bridge_fields_never_reach_the_line() {
let rendered = render_one(|| {
tracing::info!(
log.target = "hyper_util::client::legacy::pool",
kept = "yes",
log.line = 12,
also_kept = "yes",
"bridged"
);
});
assert_eq!(rendered.capped, "bridged kept=\"yes\" also_kept=\"yes\"");
assert_eq!(rendered.capped, rendered.default);
}
#[test]
fn the_message_is_capped_too() {
let long = "é".repeat(PARAM_VALUE_MAX_CHARS * 4);
let rendered = render_one(|| tracing::info!("{long}"));
assert_eq!(rendered.capped, "é".repeat(PARAM_VALUE_MAX_CHARS));
assert!(
rendered.default.chars().count() > PARAM_VALUE_MAX_CHARS,
"and `DefaultFields` is what it is being capped against: {}",
rendered.default.chars().count()
);
}
#[test]
fn the_budget_charges_the_characters_handed_in_not_the_ones_written_out() {
let mut out = String::new();
write!(
CappedWriter::new(&mut out),
"{}",
ESC.to_string().repeat(PARAM_VALUE_MAX_CHARS + 1)
)
.expect("a String never fails to be written");
assert_eq!(
out,
"\\x1b".repeat(PARAM_VALUE_MAX_CHARS),
"1024 escapes in, four characters out apiece"
);
let mut out = String::new();
write!(
CappedWriter::new(&mut out),
"{}",
"\n".repeat(PARAM_VALUE_MAX_CHARS + 1)
)
.expect("a String never fails to be written");
assert_eq!(
out,
"\\n".repeat(PARAM_VALUE_MAX_CHARS),
"1024 newlines in, two characters out apiece"
);
let mut out = String::new();
write!(
CappedWriter::new(&mut out),
"{}",
"\u{2028}".repeat(PARAM_VALUE_MAX_CHARS + 1)
)
.expect("a String never fails to be written");
assert_eq!(
out,
"\\u{2028}".repeat(PARAM_VALUE_MAX_CHARS),
"1024 line separators in, eight characters out apiece"
);
let long = format!("{ESC}{}", "é".repeat(PARAM_VALUE_MAX_CHARS * 4));
let expected = format!("\\x1b{}", "é".repeat(PARAM_VALUE_MAX_CHARS - 1));
assert_eq!(
render_one(|| tracing::info!(probe = %long)).capped,
format!("probe={expected}")
);
assert_eq!(render_one(|| tracing::info!("{long}")).capped, expected);
}
#[test]
fn every_field_is_capped_on_its_own_budget() {
let long = "é".repeat(PARAM_VALUE_MAX_CHARS * 2);
let rendered = render_one(|| tracing::info!(first = %long, second = %long, "m"));
assert_eq!(
rendered.capped,
format!(
"m first={cap} second={cap}",
cap = "é".repeat(PARAM_VALUE_MAX_CHARS)
)
);
}
}