Outputting to stdout and file via Layers causes inconsistent ANSI format behaviour dependent on ordering

[Jefffrey]

Bug Report

Version

...> cargo tree | findstr tracing
???   ???   ????????? tracing v0.1.29
???   ???       ????????? tracing-attributes v0.1.18 (proc-macro)
???   ???       ????????? tracing-core v0.1.21
???   ????????? tracing v0.1.29 (*)
????????? tracing v0.1.29 (*)
????????? tracing-appender v0.2.0
???   ????????? tracing-subscriber v0.3.5
???       ????????? tracing-core v0.1.21 (*)
???       ????????? tracing-log v0.1.2
???           ????????? tracing-core v0.1.21 (*)
????????? tracing-futures v0.2.5
???   ????????? tracing v0.1.29 (*)
????????? tracing-subscriber v0.3.5 (*)

Platform

Windows 10 64-bit

Description

When writing both to stdout and a file using Layers, disabling ANSI for the file writer still contains ANSI characters for formatting Span fields.

Example code:

    #[tokio::test]
    async fn sandbox() {
        use tracing::{debug, error, error_span, info, metadata::LevelFilter, trace, Instrument};
        use tracing_subscriber::{
            fmt::{self, time::LocalTime},
            prelude::__tracing_subscriber_SubscriberExt,
            Layer,
        };

        let file_appender = tracing_appender::rolling::never(".", "file.log");
        let (non_blocking, _guard) = tracing_appender::non_blocking(file_appender);

        let subscriber = tracing_subscriber::registry()
            .with(
                fmt::Layer::new()
                    .with_writer(std::io::stdout)
                    .with_timer(LocalTime::rfc_3339())
                    .with_ansi(true)
                    .with_filter(LevelFilter::INFO),
            )
            .with(
                fmt::Layer::new()
                    .with_writer(non_blocking)
                    .with_timer(LocalTime::rfc_3339())
                    .with_ansi(false)
                    .with_filter(LevelFilter::DEBUG),
            );
        tracing::subscriber::set_global_default(subscriber)
            .expect("Unable to set a global subscriber");

        async {
            let cold = 1;
            info!("this is info: {}", cold);
            info!(class = "dragoon", role = "dps");
            trace!("this is trace");
            error!("this is error");
            debug!("this is debug");
        }
        .instrument(error_span!("skywalker", class = "reaper"))
        .await;

        info!("done");
    }

stdout output, as expected:

file.log output:

2022-01-05T14:19:15.6787636+11:00  INFO skywalker{class="reaper"}: bitcrystal::test: this is info: 1
2022-01-05T14:19:15.6790376+11:00  INFO skywalker{class="reaper"}: bitcrystal::test: class="dragoon" role="dps"
2022-01-05T14:19:15.6792946+11:00 ERROR skywalker{class="reaper"}: bitcrystal::test: this is error
2022-01-05T14:19:15.679349+11:00 DEBUG skywalker{class="reaper"}: bitcrystal::test: this is debug
2022-01-05T14:19:15.6795536+11:00  INFO bitcrystal::test: done

Expected output for file.log:

2022-01-05T14:23:42.3471661+11:00  INFO skywalker{class="reaper"}: bitcrystal::test: this is info: 1
2022-01-05T14:23:42.347382+11:00  INFO skywalker{class="reaper"}: bitcrystal::test: class="dragoon" role="dps"
2022-01-05T14:23:42.3475698+11:00 ERROR skywalker{class="reaper"}: bitcrystal::test: this is error
2022-01-05T14:23:42.34761+11:00 DEBUG skywalker{class="reaper"}: bitcrystal::test: this is debug
2022-01-05T14:23:42.3478064+11:00  INFO bitcrystal::test: done

Expected output (for file appender) can be achieved by setting with_ansi(false) for the stdout layer, or simply omitting the stdout layer itself, so seems to point to some behaviour from the stdout layer affecting the file appender layer.

Also can be achieved by reordering the with() calls to have stdout last, like so:

            .with(
                fmt::Layer::new()
                    .with_writer(non_blocking)
                    .with_timer(LocalTime::rfc_3339())
                    .with_ansi(false)
                    .with_filter(LevelFilter::DEBUG),
            )
            .with(
                fmt::Layer::new()
                    .with_writer(std::io::stdout)
                    .with_timer(LocalTime::rfc_3339())
                    .with_ansi(true)
                    .with_filter(LevelFilter::INFO),
            )

[davidbarsky]

I'm able to reproduce this with the following:

use tracing::{debug, error, error_span, info, metadata::LevelFilter, trace, Instrument};
use tracing_subscriber::{
    fmt::{self},
    prelude::__tracing_subscriber_SubscriberExt,
    Layer,
};

fn main() {
    let file_appender = tracing_appender::rolling::never(".", "file.log");
    let (non_blocking, _guard) = tracing_appender::non_blocking(file_appender);

    let subscriber = tracing_subscriber::registry()
        .with(
            fmt::Layer::new()
                .with_writer(std::io::stdout)
                .with_filter(LevelFilter::INFO),
        )
        .with(
            fmt::Layer::new()
                .with_ansi(false)
                .with_writer(non_blocking)
                .with_filter(LevelFilter::DEBUG),
        );
    tracing::subscriber::set_global_default(subscriber).expect("Unable to set a global subscriber");

    let _guard = error_span!("skywalker", class = "reaper").entered();

    let cold = 1;
    info!("this is info: {}", cold);
    info!(class = "dragoon", role = "dps");
    trace!("this is trace");
    error!("this is error");
    debug!("this is debug");

    info!("done");
}

I'm digging into see what's going on.

[davidbarsky]

I think a portion of the issue is that the span formatters don't respect the .with_ansi setting, resulting output similar to this (notably, the event data does not have ansi markings):

2022-01-07T18:56:06.457863Z  INFO skywalker{class="reaper"}: ordering_layers: this is info: 1
2022-01-07T18:56:06.457906Z  INFO skywalker{class="reaper"}: ordering_layers: class="dragoon" role="dps"
2022-01-07T18:56:06.457937Z ERROR skywalker{class="reaper"}: ordering_layers: this is error
2022-01-07T18:56:06.457953Z DEBUG skywalker{class="reaper"}: ordering_layers: this is debug
2022-01-07T18:56:06.457980Z  INFO skywalker{class="reaper"}: ordering_layers: done

I'm not entirely sure why ordering helps resolve the issues, but I have a few hunches. More soon.

[davidbarsky]

Oh, I figured it out. The type variable N (FormatFields) is being shared between multiple layers in the Registry, resulting in the order-dependent behavior you're seeing. For context, tracing_subscriber::fmt::{Layer, Subscriber} use the type ID of FormatFields to distinguish between buffered data between different Layers, but since the type ID doesn't change, you're seeing this behavior.

I think this can be resolved by making ansi formatting a const generic on FormatFields, but that might be a breaking change to tracing-subscriber.

[hawkw]

I think this can be resolved by making ansi formatting a const generic on FormatFields, but that might be a breaking change to tracing-subscriber.

Yes, changing the type of FormatFields is a breaking change. I think a slightly better breaking change would be to change the FormattedFields type to be FormattedFields<N, const ANSI: bool>, rather than FormatFields --- that way, we could get the same behavior with user formatters, and just get the ANSI value from the Writer directly. It could be worth doing that in tracing-subscriber 0.4.

In the meantime, I think there are some non-breaking solutions, although they're potentially less nice. One of them is to just back out the commit that added ANSI formatting inside of span fields, and only apply ANSI formatting to the entire formatted field string when it's actually being written to IO. This might be a bit less pretty, but it would solve the problem for now.

Another thing we could do is have FormattedFields record whether the fields were formatted using ANSI as a boolean field on the struct, and then strip out the ANSI formatting chars if the fields were formatted with ANSI but they're being written to a writer that doesn't support ANSI. This would let us keep the pretty formatting, but it would add some non-trivial overhead and just kind of seems like a gross hack.

[lilyball]

Oh dear, this looks exactly like an issue I theorized as part of https://github.com/tokio-rs/tracing/issues/1763

[arifd]

I was experiencing this problem (using the Pretty formatter), and Eliza very helpfully suggested this workaround, sharing in case it helps anyone from the future.

struct NewType(Pretty);

impl<'writer> FormatFields<'writer> for NewType {
    fn format_fields<R: RecordFields>(
        &self,
        writer: Writer<'writer>,
        fields: R,
    ) -> core::fmt::Result {
        self.0.format_fields(writer, fields)
    }
}

Now add the newtype wrapper to your layer:

fmt::Layer::default()
    .pretty()
    .fmt_fields(NewType(Pretty::default()));
    .with_ansi(false)

[abonander]

While trying to figure out why this is happening (and before stumbling on this issue), I managed to create a pretty simple repro that might be useful for testing:

fn main() {
    let file = Arc::new(File::create("test.txt").unwrap());

    tracing_subscriber::registry()
        .with(
            tracing_subscriber::fmt::layer()
                .with_ansi(false)
                .with_writer(file.clone()),
        )
        .with(tracing_subscriber::fmt::layer())
        .init();

    let _span = tracing::info_span!("foo", foo = "foo").entered();

    tracing::info!(bar = "bar", "foo");

    // Required to get output on Windows.
    (&mut &*file).flush().unwrap();
}

It writes to a file because I wanted to be able to pull it up in a context that I knew wouldn't interpret the escape codes. For a regression test you'd probably want to write to a Vec<u8> instead.

[colinmarc]

I was experiencing this problem (using the Pretty formatter), and Eliza very helpfully suggested this workaround, sharing in case it helps anyone from the future.

How do I use this with Full or Compact?

struct LogFull(tracing_subscriber::fmt::format::Full);

impl<'writer> tracing_subscriber::fmt::format::FormatFields<'writer> for LogFull {
    fn format_fields<R: tracing_subscriber::field::RecordFields>(
        &self,
        writer: tracing_subscriber::fmt::format::Writer<'writer>,
        fields: R,
    ) -> core::fmt::Result {
        self.0.format_fields(writer, fields)
    }
}

Results in

error[E0599]: the method `format_fields` exists for struct `Full`, but its trait bounds were not satisfied
   --> mm-server/src/main.rs:116:16
    |
116 |         self.0.format_fields(writer, fields)
    |                ^^^^^^^^^^^^^ method cannot be called on `Full` due to unsatisfied trait bounds
    |
   ::: /home/colinmarc/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-subscriber-0.3.18/src/fmt/format/mod.rs:388:1
    |
388 | pub struct Full;
    | ---------------
    | |
    | doesn't satisfy `<_ as FnOnce<(Writer<'_>,)>>::Output = _`
    | doesn't satisfy `_: Fn<(Writer<'_>,)>`
    | doesn't satisfy `_: FormatFields<'_>`
    | doesn't satisfy `_: MakeOutput<Writer<'_>, Result<(), Error>>`
    |
    = note: the following trait bounds were not satisfied:
            `tracing_subscriber::fmt::format::Full: MakeOutput<tracing_subscriber::fmt::format::Writer<'_>, std::result::Result<(), std::fmt::Error>>`
            which is required by `tracing_subscriber::fmt::format::Full: FormatFields<'_>`
            `<tracing_subscriber::fmt::format::Full as FnOnce<(tracing_subscriber::fmt::format::Writer<'_>,)>>::Output = _`
            which is required by `tracing_subscriber::fmt::format::Full: FormatFields<'_>`
            `tracing_subscriber::fmt::format::Full: std::ops::Fn<(tracing_subscriber::fmt::format::Writer<'_>,)>`
            which is required by `tracing_subscriber::fmt::format::Full: FormatFields<'_>`