Pretty formatter adds a bunch of commas at the end of output and does not display levels

[ranile]

Bug Report

Version

tracing = { git = "https://github.com/tokio-rs/tracing/", rev = "07b81bb5c125de125f01cc9b91a0bfe2273a643a" }
tracing-subscriber = { git = "https://github.com/tokio-rs/tracing/", rev = "07b81bb5c125de125f01cc9b91a0bfe2273a643a" }
tracing-appender = { git = "https://github.com/tokio-rs/tracing/", rev = "07b81bb5c125de125f01cc9b91a0bfe2273a643a" }

Platform

Linux hamza 5.10.7-arch1-1 #1 SMP PREEMPT Wed, 13 Jan 2021 12:02:01 +0000 x86_64 GNU/Linux

Description

Pretty formatter adds a bunch of commas at the end of output (only for logs outputed by log) and does not display levels.

Code:

let filter = std::env::var("RUST_LOG")
    .unwrap_or_else(|_| "debug,hyper=info,sqlx::query=warn".to_owned());
let filter = EnvFilter::from_str(&filter)?;

let file_appender = tracing_appender::rolling::minutely("logs", "backend.log");
let (non_blocking, _guard) = tracing_appender::non_blocking(file_appender);

tracing_subscriber::registry()
    .with(filter)
    .with(
        fmt::Subscriber::new()
            .with_target(true)
            .with_level(true)
            .with_writer(io::stdout)
            .pretty(),
    )
    .with(fmt::Subscriber::new().with_writer(non_blocking))
    .init();

Output:

    Finished dev [unoptimized + debuginfo] target(s) in 10.97s
     Running `target/debug/backend`
  Jan 26 23:07:06.462 : relation "_sqlx_migrations" already exists, skipping, , , , 
    at /home/hamza/.cargo/git/checkouts/sqlx-f05f33ba4f5c3036/df39312/sqlx-core/src/postgres/connection/stream.rs:137

  Jan 26 23:07:06.477 backend: running server at http://0.0.0.0:9090/
    at backend/src/main.rs:44

Notice how there the sqlx log has a bunch of commas at the end of the line. sqlx uses the log crate so this bug is present on the first log but not the other which is logged as (in my main.rs)

tracing::info!("running server at http://{}/", addr);

Also, notice how there are no levels when there should be.

None of these errors are present when using the regular formatter (after removing the .pretty() line from config)

    Finished dev [unoptimized + debuginfo] target(s) in 0.91s
     Running `target/debug/backend`
Jan 26 23:09:27.588  INFO : relation "_sqlx_migrations" already exists, skipping    
Jan 26 23:09:27.630  INFO backend: running server at http://0.0.0.0:9090/

[hawkw]

Notice how there the sqlx log has a bunch of commas at the end of the line. sqlx uses the log crate so this bug is present on the first log but not the other which is logged as (in my main.rs)

Yup, that definitely looks like a bug, I'll take a look!

Also, notice how there are no levels when there should be.

Right now the Pretty formatter shows levels by changing the color of the event line. If this isn't sufficient, we could change the output to also include the level as part of the text output?

[ranile]

Right now the Pretty formatter shows levels by changing the color of the event line. If this isn't sufficient, we could change the output to also include the level as part of the text output?

It certainly wasn't clear to me that it does that. It's also isn't documented which color corresponds to what colors and it is impossible to use that in files as that would mess up the contents. It's best to give user the option decide what behavior they want but including the level as part of text output would be better than what we have right now.

[hawkw]

It's best to give user the option decide what behavior they want but including the level as part of text output would be better than what we have right now.

Sure, we can add them to the text output. For what it's worth, that formatter is intended primarily to be used in command-line tools and for local development, so supporting output without terminal colors (such as files) is not as high a priority there as for the other formatters. We could also make that a bit clearer in the documentation.

[ranile]

For what it's worth, that formatter is intended primarily to be used in command-line tools and for local development, so supporting output without terminal colors (such as files) is not as high a priority there as for the other formatters.

It makes a lot more sense now. These points should definitely be mentioned in the docs.

[lenaschoenburg]

I went on a bit of a hunt and I think I figured out why there are a bunch of commas at the end.
sqlx logs a record with metadata about source file and line:
https://github.com/launchbadge/sqlx/blob/d5f9f08c62f2480eb6a5aac515a25c86a0508000/sqlx-core/src/postgres/connection/stream.rs#L130-L139

For the pretty formatter this record will end up as fields log.line, log.file etc here:

tracing/tracing-subscriber/src/fmt/format/pretty.rs

Lines 285 to 303 in a0e1daa

	fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) {
	if self.result.is_err() {
	return;
	}
	let bold = self.style.bold();
	self.maybe_pad();
	self.result = match field.name() {
	"message" => write!(self.writer, "{}{:?}", self.style.prefix(), value,),
	// Skip fields that are actually log metadata that have already been handled
	#[cfg(feature = "tracing-log")]
	name if name.starts_with("log.") => Ok(()),
	name if name.starts_with("r#") => write!(
	self.writer,
	"{}{}{}: {:?}",
	bold.prefix(),
	&name[2..],
	bold.infix(self.style),
	value
	),

where maybe_pad() writes a comma to the output because the field is not empty. This is usually ok but here comes this part:

tracing/tracing-subscriber/src/fmt/format/pretty.rs

Lines 293 to 295 in a0e1daa

	// Skip fields that are actually log metadata that have already been handled
	#[cfg(feature = "tracing-log")]
	name if name.starts_with("log.") => Ok(()),

where we don't actually write a value. So maybe_pad() in combination with log metadata will produce extra commas.