Skip to content

Commit

Permalink
subscriber: fix missing event fields in Compact formatter (#1755)
Browse files Browse the repository at this point in the history 
The line of code that prints the event's fields (including its message)
was accidentally deleted in 0a16972,
while backporting PR #1696 from `master` (where the `Compact` formatter
implementation is significantly different).

This branch puts it back. Also, I've added tests for the `Compact` formatter's
output, to guard against accidentally breaking it in the future. Previously, we
only had tests for the `Full` and `Json` formatters.

Fixes #1741

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
  • Loading branch information
@hawkw
hawkw committed Nov 29, 2021
1 parent b3f508d commit e671318
Showing 1 changed file with 165 additions and 73 deletions.
238 changes: 165 additions & 73 deletions tracing-subscriber/src/fmt/format/mod.rs
View file
Expand Up @@ -906,15 +906,6 @@ where
write!(writer, "{:0>2?} ", std::thread::current().id())?;
}

if self.display_target {
write!(
writer,
"{}{}",
writer.bold().paint(meta.target()),
writer.dimmed().paint(":")
)?;
}

let fmt_ctx = {
#[cfg(feature = "ansi")]
{
Expand All @@ -927,6 +918,17 @@ where
};
write!(writer, "{}", fmt_ctx)?;

if self.display_target {
write!(
writer,
"{}{} ",
writer.bold().paint(meta.target()),
writer.dimmed().paint(":")
)?;
}

ctx.format_fields(writer.by_ref(), event)?;

let dimmed = writer.dimmed();
for span in ctx
.event_scope()
Expand Down Expand Up @@ -1525,7 +1527,7 @@ pub(super) mod test {
subscriber::with_default,
};

use super::{FmtSpan, TimingDisplay, Writer};
use super::*;
use std::fmt;

pub(crate) struct MockTime;
Expand All @@ -1551,111 +1553,201 @@ pub(super) mod test {
run_test(subscriber, make_writer, "hello\n")
}

#[cfg(feature = "ansi")]
#[test]
fn with_ansi_true() {
let expected = "\u{1b}[2mfake time\u{1b}[0m \u{1b}[32m INFO\u{1b}[0m \u{1b}[2mtracing_subscriber::fmt::format::test\u{1b}[0m\u{1b}[2m:\u{1b}[0m hello\n";
test_ansi(true, expected);
}

#[cfg(feature = "ansi")]
#[test]
fn with_ansi_false() {
let expected = "fake time INFO tracing_subscriber::fmt::format::test: hello\n";
test_ansi(false, expected);
fn test_ansi<T>(
is_ansi: bool,
expected: &str,
builder: crate::fmt::SubscriberBuilder<DefaultFields, Format<T>>,
) where
Format<T, MockTime>: FormatEvent<crate::Registry, DefaultFields>,
T: Send + Sync + 'static,
{
let make_writer = MockMakeWriter::default();
let subscriber = builder
.with_writer(make_writer.clone())
.with_ansi(is_ansi)
.with_timer(MockTime);
run_test(subscriber, make_writer, expected)
}

#[cfg(not(feature = "ansi"))]
#[test]
fn without_ansi() {
fn test_without_ansi<T>(
expected: &str,
builder: crate::fmt::SubscriberBuilder<DefaultFields, Format<T>>,
) where
Format<T, MockTime>: FormatEvent<crate::Registry, DefaultFields>,
T: Send + Sync,
{
let make_writer = MockMakeWriter::default();
let expected = "fake time INFO tracing_subscriber::fmt::format::test: hello\n";
let subscriber = crate::fmt::Subscriber::builder()
.with_writer(make_writer)
.with_timer(MockTime);
run_test(subscriber, make_writer, expected);
let subscriber = builder.with_writer(make_writer).with_timer(MockTime);
run_test(subscriber, make_writer, expected)
}

#[test]
fn without_level() {
fn test_without_level<T>(
expected: &str,
builder: crate::fmt::SubscriberBuilder<DefaultFields, Format<T>>,
) where
Format<T, MockTime>: FormatEvent<crate::Registry, DefaultFields>,
T: Send + Sync + 'static,
{
let make_writer = MockMakeWriter::default();
let subscriber = crate::fmt::Subscriber::builder()
let subscriber = builder
.with_writer(make_writer.clone())
.with_level(false)
.with_ansi(false)
.with_timer(MockTime);
let expected = "fake time tracing_subscriber::fmt::format::test: hello\n";

run_test(subscriber, make_writer, expected);
}

#[cfg(feature = "ansi")]
fn test_ansi(is_ansi: bool, expected: &str) {
let make_writer = MockMakeWriter::default();
let subscriber = crate::fmt::Subscriber::builder()
.with_writer(make_writer.clone())
.with_ansi(is_ansi)
.with_timer(MockTime);
run_test(subscriber, make_writer, expected)
}

fn run_test(subscriber: impl Into<Dispatch>, buf: MockMakeWriter, expected: &str) {
let _default = set_default(&subscriber.into());
tracing::info!("hello");
assert_eq!(expected, buf.get_string())
}

#[test]
fn overridden_parents() {
fn test_overridden_parents<T>(
expected: &str,
builder: crate::fmt::SubscriberBuilder<DefaultFields, Format<T>>,
) where
Format<T, MockTime>: FormatEvent<crate::Registry, DefaultFields>,
T: Send + Sync + 'static,
{
let make_writer = MockMakeWriter::default();
let collector = crate::fmt::Subscriber::builder()
let collector = builder
.with_writer(make_writer.clone())
.with_level(false)
.with_ansi(false)
.with_timer(MockTime)
.finish();

with_default(collector, || {
let span1 = tracing::info_span!("span1");
let span2 = tracing::info_span!(parent: &span1, "span2");
let span1 = tracing::info_span!("span1", span = 1);
let span2 = tracing::info_span!(parent: &span1, "span2", span = 2);
tracing::info!(parent: &span2, "hello");
});
assert_eq!(
"fake time span1:span2: tracing_subscriber::fmt::format::test: hello\n",
make_writer.get_string()
);
assert_eq!(expected, make_writer.get_string());
}

#[test]
fn overridden_parents_in_scope() {
fn test_overridden_parents_in_scope<T>(
expected1: &str,
expected2: &str,
builder: crate::fmt::SubscriberBuilder<DefaultFields, Format<T>>,
) where
Format<T, MockTime>: FormatEvent<crate::Registry, DefaultFields>,
T: Send + Sync + 'static,
{
let make_writer = MockMakeWriter::default();
let subscriber = crate::fmt::Subscriber::builder()
let subscriber = builder
.with_writer(make_writer.clone())
.with_level(false)
.with_ansi(false)
.with_timer(MockTime)
.finish();

with_default(subscriber, || {
let span1 = tracing::info_span!("span1");
let span2 = tracing::info_span!(parent: &span1, "span2");
let span3 = tracing::info_span!("span3");
let span1 = tracing::info_span!("span1", span = 1);
let span2 = tracing::info_span!(parent: &span1, "span2", span = 2);
let span3 = tracing::info_span!("span3", span = 3);
let _e3 = span3.enter();

tracing::info!("hello");
assert_eq!(
"fake time span3: tracing_subscriber::fmt::format::test: hello\n",
make_writer.get_string().as_str()
);
assert_eq!(expected1, make_writer.get_string().as_str());

tracing::info!(parent: &span2, "hello");
assert_eq!(
"fake time span1:span2: tracing_subscriber::fmt::format::test: hello\n",
make_writer.get_string().as_str()
);
assert_eq!(expected2, make_writer.get_string().as_str());
});
}

fn run_test(subscriber: impl Into<Dispatch>, buf: MockMakeWriter, expected: &str) {
let _default = set_default(&subscriber.into());
tracing::info!("hello");
assert_eq!(expected, buf.get_string())
}

mod default {
use super::*;
#[cfg(feature = "ansi")]
#[test]
fn with_ansi_true() {
let expected = "\u{1b}[2mfake time\u{1b}[0m \u{1b}[32m INFO\u{1b}[0m \u{1b}[2mtracing_subscriber::fmt::format::test\u{1b}[0m\u{1b}[2m:\u{1b}[0m hello\n";
test_ansi(true, expected, crate::fmt::Subscriber::builder());
}

#[cfg(feature = "ansi")]
#[test]
fn with_ansi_false() {
let expected = "fake time INFO tracing_subscriber::fmt::format::test: hello\n";
test_ansi(false, expected, crate::fmt::Subscriber::builder());
}

#[cfg(not(feature = "ansi"))]
#[test]
fn without_ansi() {
let expected = "fake time INFO tracing_subscriber::fmt::format::test: hello\n";
test_without_ansi(expected, crate::fmt::Subscriber::builder())
}

#[test]
fn without_level() {
let expected = "fake time tracing_subscriber::fmt::format::test: hello\n";
test_without_level(expected, crate::fmt::Subscriber::builder())
}

#[test]
fn overridden_parents() {
let expected = "fake time span1{span=1}:span2{span=2}: tracing_subscriber::fmt::format::test: hello\n";
test_overridden_parents(expected, crate::fmt::Subscriber::builder())
}

#[test]
fn overridden_parents_in_scope() {
test_overridden_parents_in_scope(
"fake time span3{span=3}: tracing_subscriber::fmt::format::test: hello\n",
"fake time span1{span=1}:span2{span=2}: tracing_subscriber::fmt::format::test: hello\n",
crate::fmt::Subscriber::builder(),
)
}
}

mod compact {
use super::*;

#[cfg(feature = "ansi")]
#[test]
fn with_ansi_true() {
let expected = "\u{1b}[2mfake time\u{1b}[0m \u{1b}[32m INFO\u{1b}[0m \u{1b}[1mtracing_subscriber::fmt::format::test\u{1b}[0m\u{1b}[2m:\u{1b}[0m hello\n";
test_ansi(true, expected, crate::fmt::Subscriber::builder().compact())
}

#[cfg(feature = "ansi")]
#[test]
fn with_ansi_false() {
let expected = "fake time INFO tracing_subscriber::fmt::format::test: hello\n";
test_ansi(false, expected, crate::fmt::Subscriber::builder().compact());
}

#[cfg(not(feature = "ansi"))]
#[test]
fn without_ansi() {
let expected = "fake time INFO tracing_subscriber::fmt::format::test: hello\n";
test_without_ansi(expected, crate::fmt::Subscriber::builder().compact())
}

#[test]
fn without_level() {
let expected = "fake time tracing_subscriber::fmt::format::test: hello\n";
test_without_level(expected, crate::fmt::Subscriber::builder().compact());
}

#[test]
fn overridden_parents() {
let expected = "fake time span1:span2: tracing_subscriber::fmt::format::test: hello span=1 span=2\n";
test_overridden_parents(expected, crate::fmt::Subscriber::builder().compact())
}

#[test]
fn overridden_parents_in_scope() {
test_overridden_parents_in_scope(
"fake time span3: tracing_subscriber::fmt::format::test: hello span=3\n",
"fake time span1:span2: tracing_subscriber::fmt::format::test: hello span=1 span=2\n",
crate::fmt::Subscriber::builder().compact(),
)
}
}

#[test]
fn format_nanos() {
fn fmt(t: u64) -> String {
Expand Down

0 comments on commit e671318

Please sign in to comment.