with_ansi(false) has no effect to event in span with arg on 2nd layer

[wesley800]

Bug Report

Version

tracing v0.1.40
tracing-appender v0.2.3
tracing-subscriber v0.3.18 (*) features = ["env-filter"]

Platform

Windows 64bit

Description

Sorry I'm not sure which sub-crate this issue belongs to.

Please check the code at https://gist.github.com/wesley800/7192074d665243adc47b8216a540aa16 . After compile and running (with --release, I didn't test it in debug mode), one should see a new file named test.log and some escape characters in it, only on the second log line. I believe the extra chars are the same within console which add color and bold style to the log.

The problem disappears by doing ANY of the following:

1. Swap .with(file_layer) and .with(console_layer), which makes file_layer become the first (inner, I guess?) layer.
2. Delete the span argument arg.
3. Delete the span. (Of course, cause the first log line behaves normally)

[kaffarell]

Ooh, this was an interesting rabbit hole :)
So basically the Registry keeps track of all the spans that are entered and stores their attributes (in this case the arg). It stores the attributes in a HashMap with a TypeId as a key (this is the formatter) and a Box<Any> as value. Now obviously in your example, we create two fmt-layer with both the same format::DefaultFields formatter. This means it only stores the arg attribute once, with the ansi config set to true (as that is the first one). You can see here

tracing/tracing-subscriber/src/fmt/fmt_subscriber.rs

Line 837 in 527b4f6

if extensions.get_mut::<FormattedFields<N>>().is_none() {

that we check if there is anything in the extensions with a key of N (which is the formatter FormatField-impl).

Now we can easily fix this by adding a dummy formatter which uses the DefaultVisitor:

struct CustomFormatter;

impl<'a> MakeVisitor<Writer<'a>> for CustomFormatter {
    type Visitor = DefaultVisitor<'a>;

    #[inline]
    fn make_visitor(&self, target: Writer<'a>) -> Self::Visitor {
        DefaultVisitor::new(target, true)
    }
}

and add it to the file_layer:

  let file_layer = tracing_subscriber::fmt::layer()
      .with_writer(file_log_nonblock)
      .with_ansi(false)
      .fmt_fields(formatter)
      .with_filter(file_log_filter);

This way the second layer has a different formatter and arg is stored twice in the extensions, once for format::DefaultFields and once for CustomFormatter.

Obviously you could also just use the pretty or json formatter on one of the layers.

Maybe someone more experienced with tracing can chime in and provide an easier solution...