tracing-subscriber Filtering Confusion

[gatoWololo]

Bug Report

Version

tracing_example v0.1.0 (/home/gatowololo/Research/tracing_example)
├── tracing v0.1.14
│ ├── tracing-attributes v0.1.8
│ └── tracing-core v0.1.10
└── tracing-subscriber v0.2.5
├── tracing-core v0.1.10 ()
├── tracing-log v0.1.1
│ └── tracing-core v0.1.10 ()
└── tracing-serde v0.1.1
└── tracing-core v0.1.10 (*)

Platform

Linux thinkpad 5.4.0-29-generic # 33-Ubuntu SMP Wed Apr 29 14:32:27 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux

Crates

tracing-subscriber

Description

Hello I am trying to use tracing + tracing-subscriber for some fancy filtering. I have ran into some issues. I'm happy to work on fixing it but I wanted to verify this is indeed unexpected behavior. Or add to the documentation since I found some of this cases quite puzzling.

The following code is a boiled down example exhibiting my questions:

use tracing::{event, span, Level};
use tracing_subscriber::filter::{EnvFilter};
use std::thread;
use std::fmt::Debug;

struct Id {
    id: u32,
}

impl Id {
    fn new(id: u32) -> Id{
        Id { id }
    }
}

impl Debug for Id {
    fn fmt(&self, fmt: &mut std::fmt::Formatter) -> Result<(), std::fmt::Error> {
        write!(fmt, "Id<{}>", self.id)
    }
}

struct Chan {}

impl Chan {
    fn uchan() -> Chan {
        span!(Level::INFO, "Channel", id=?Id::new(3)).in_scope(||{
            event!(Level::INFO, "Creating Chan");
        });

        Chan {}
    }

    fn send(&self){
        span!(Level::INFO, "Channel", id=?Id::new(3)).in_scope(||{
            event!(Level::INFO, "Sending Message!");
        });
    }
}

fn main() {
    tracing_subscriber::fmt::Subscriber::builder()
        .without_time()
        .with_env_filter(EnvFilter::from_default_env())
        .with_target(false)
        .init();

    let span1 = span!(Level::INFO, "Thread", id=?Id::new(0));
    let _guard1 = span1.enter();
    event!(Level::INFO, "hello from logger");

    let chan = Chan::uchan();
    chan.send();

    let h = thread::spawn(move || {
        event!(Level::INFO, "Created child thread");
        let span2 = span!(Level::INFO, "Child Thread", id=?Id::new(1));
        let _guard2 = span2.enter();

        chan.send();
    });

    h.join().unwrap();
}

This code outputs the following base messages which I will be filtering:

> env RUST_LOG=trace cargo run
  INFO Thread{id=Id<0>}: hello from logger
  INFO Thread{id=Id<0>}:Channel{id=Id<3>}: Creating Chan
  INFO Thread{id=Id<0>}:Channel{id=Id<3>}: Sending Message!
  INFO Created child thread
  INFO Child Thread{id=Id<1>}:Channel{id=Id<3>}: Sending Message!

Spans don't live through thread boundaries

Even though span Thread is in scope it seems spans don't live through thread boundaries as shown by the span-less INFO Created child thread is this correct?

Env filter does not accept parentheses, braces, or curly braces as field values.

I can filter by id like:

> env RUST_LOG=[{id=Id<3>}] cargo run
  INFO Thread{id=Id<0>}:Channel{id=Id<3>}: Creating Chan
  INFO Thread{id=Id<0>}:Channel{id=Id<3>}: Sending Message!
  INFO Child Thread{id=Id<1>}:Channel{id=Id<3>}: Sending Message!

Great! But it seems I cannot use [] or () or {}:

-        write!(fmt, "Id<{}>", self.id)
+        write!(fmt, "Id({})", self.id)

Which looks like:

> RUST_LOG=trace cargo run
  INFO Thread{id=Id(0)>}: hello from logger
  INFO Thread{id=Id(0)>}:Channel{id=Id(3)>}: Creating Chan
  INFO Thread{id=Id(0)>}:Channel{id=Id(3)>}: Sending Message!
  INFO Created child thread
  INFO Child Thread{id=Id(1)>}:Channel{id=Id(3)>}: Sending Message!

This sorta makes sense since it clashes with regex syntax. Using parens seems to fail silently:

> env RUST_LOG="[{id=Id(3)}]" cargo run
# No output

This would be useful as Rust's auto derive for debug uses curly braces and I want to filter by small arrays which use square brackets.

Span Ordering and Commas

I'm unsure what the difference is between the following filters. They all seem to produce some output:

> env RUST_LOG="[Thread Channel]" cargo run
  INFO Thread{id=Id<0>}: hello from logger
  INFO Thread{id=Id<0>}:Channel{id=Id<3>}: Creating Chan
  INFO Thread{id=Id<0>}:Channel{id=Id<3>}: Sending Message!
> env RUST_LOG="[Channel Thread]" cargo run
  INFO Channel{id=Id<3>}: Creating Chan
  INFO Channel{id=Id<3>}: Sending Message!
  INFO Channel{id=Id<3>}: Sending Message!
> env RUST_LOG="[Thread][Channel]" cargo run
  INFO Channel{id=Id<3>}: Creating Chan
  INFO Channel{id=Id<3>}: Sending Message!
  INFO Channel{id=Id<3>}: Sending Message!
> env RUST_LOG="[Thread],[Channel]" cargo run
  INFO Thread{id=Id<0>}: hello from logger
  INFO Thread{id=Id<0>}:Channel{id=Id<3>}: Creating Chan
  INFO Thread{id=Id<0>}:Channel{id=Id<3>}: Sending Message!
  INFO Channel{id=Id<3>}: Sending Message!

It seems order matters when applying filters: RUST_LOG="[Thread Channel]" vs RUST_LOG="[Channel Thread]"? I assume it tries to apply the directives in order from left to rights?

I'm not sure what the difference is between: RUST_LOG="[Thread Channel]" vs env RUST_LOG="[Thread][Channel]"?

Adding the comma produces different results between: RUST_LOG="[Thread][Channel]" vs RUST_LOG="[Thread],[Channel]"

I'm not sure if some of this syntax is documented.

Intuition behind directives and filtering | Names of fields between spans matter

I don't have a clear mental model for how directives are applied to filter spans. Specifically for field directives: I thought it worked as follows: "The directive is checked against a span to decide whether to enter that span or not".

The following examples show my confusion:

> RUST_LOG=[{id}] cargo run
  INFO Thread{id=Id<0>}: hello from logger
  INFO Thread{id=Id<0>}:Channel{id=Id<3>}: Creating Chan
  INFO Thread{id=Id<0>}:Channel{id=Id<3>}: Sending Message!
  INFO Child Thread{id=Id<1>}:Channel{id=Id<3>}: Sending Message!

This makes sense based on my filter since all spans have an id field.

> RUST_LOG=[{id=Id<3>}] cargo run
  INFO Thread{id=Id<0>}:Channel{id=Id<3>}: Creating Chan
  INFO Thread{id=Id<0>}:Channel{id=Id<3>}: Sending Message!
  INFO Child Thread{id=Id<1>}:Channel{id=Id<3>}: Sending Message!

This is a bit surprising as the Thread span id field has the wrong value (!= Id<3>) so I'm surprised it is entered (Note: this is actually the behaviour I want though since I want to see the "context", that is, all the parent spans).

But for some reason this seems to happen only because both fields are named id if I change the name of the field for the Channel from id to cid:

- span!(Level::INFO, "Channel", id=?Id::new(3)).in_scope(||{
+ span!(Level::INFO, "Channel", cid=?Id::new(3)).in_scope(||{

This no longer follow my intuition:

> RUST_LOG=[{cid=Id<3>}] cargo run
  INFO Channel{cid=Id<3>}: Creating Chan
  INFO Channel{cid=Id<3>}: Sending Message!
  INFO Channel{cid=Id<3>}: Sending Message!

In this example all context is lost. Which is a reasonable implementation by itself. But given the example above where the context was kept since both fields happened to be named id seems wrong.

> RUST_LOG=[{cid}] cargo run
  INFO Thread{id=Id<0>}:Channel{cid=Id<3>}: Creating Chan
  INFO Thread{id=Id<0>}:Channel{cid=Id<3>}: Sending Message!
  INFO Child Thread{id=Id<1>}:Channel{cid=Id<3>}: Sending Message!

Similarly why is the context kept in this case but not the one above?

Using primitives in Debug Instances

I can happily filter based on my Id:

> RUST_LOG=[{id=Id<3>}] cargo run
  INFO Thread{id=Id<0>}:Channel{id=Id<3>}: Creating Chan
  INFO Thread{id=Id<0>}:Channel{id=Id<3>}: Sending Message!
  INFO Child Thread{id=Id<1>}:Channel{id=Id<3>}: Sending Message!

However if I change my Debug impl for ID:

-        write!(fmt, "Id<{}>", self.id)
+        write!(fmt, "{}", self.id)

So that now it looks like:

> RUST_LOG=trace cargo run
  INFO Thread{id=0}: hello from logger
  INFO Thread{id=0}:Channel{id=3}: Creating Chan
  INFO Thread{id=0}:Channel{id=3}: Sending Message!
  INFO Created child thread
  INFO Child Thread{id=1}:Channel{id=3}: Sending Message!

Looks good... but then filtering fails:

gatowololo@thinkpad ~/R/tracing_example (master)> RUST_LOG=[{id=3}] cargo run
# No output

It seems we cannot have our Debug instances "look like" primitive types? I know tracking-subscriber treats certain numeric types, books, and strings special.

Field names cannot be reserved words?

Again I can happily filter by the id field:

> RUST_LOG=[{id}] cargo run
  INFO Thread{id=Id<0>}: hello from logger
  INFO Thread{id=Id<0>}:Channel{id=Id<3>}: Creating Chan
  INFO Thread{id=Id<0>}:Channel{id=Id<3>}: Sending Message!
  INFO Child Thread{id=Id<1>}:Channel{id=Id<3>}: Sending Message!

Looks good. But if my field is called type:

-        span!(Level::INFO, "Channel", id=?Id::new(3)).in_scope(||{
+        span!(Level::INFO, "Channel", r#type=?Id::new(3)).in_scope(||{

Looks like:

> RUST_LOG=[] cargo run
  INFO Thread{id=Id<0>}: hello from logger
  INFO Thread{id=Id<0>}:Channel{type=Id<3>}: Creating Chan
  INFO Thread{id=Id<0>}:Channel{type=Id<3>}: Sending Message!
  INFO Created child thread
  INFO Child Thread{id=Id<1>}:Channel{type=Id<3>}: Sending Message!

I don't seem to be able to filter by the field name anymore:

> RUST_LOG=[{type}] cargo run
# no output

Conclusion

I realize this is a lot of questions for one issue! Sorry! If anyone could confirm any of the observations/bugs above I'd be happy to dig deeper. I really want filtering for my project. I think the idea is extremely powerful. Thank you for making tracing!

[hawkw]

@gatoWololo Sorry I didn't see this issue earlier! Let me try and answer your questions:

Spans don't live through thread boundaries

Even though span Thread is in scope it seems spans don't live through thread boundaries as shown by the span-less INFO Created child thread is this correct?

That's correct: entering a span is per-thread; spawning a new thread does not automatically propagate the current span. This is stated in the docs here, but it might not be sufficiently clear?

Entering a span is per-thread by design, because in many cases each thread in a program is executing a separate logical unit of work, and it wouldn't make sense to propagate them by default. However, if you want a spawned thread to also enter a span, you can do this:

let span = tracing::info_span!(...);
let _enter = span.enter();

// ...

let span2 = span.clone();
let thread = std::thread::spawn(move || {
    let _enter = span2.enter();
    // ...
});

Or, if the span is not in the same scope as where the thread is spawned, you can propagate the current span to the spawned thread, like this:

let span = Span::current();
let thread = std::thread::spawn(move || {
    let _enter = span.enter();
    // ...
});

Env filter does not accept parentheses, braces, or curly braces as field values.

I can filter by id like:

> env RUST_LOG=[{id=Id<3>}] cargo run
  INFO Thread{id=Id<0>}:Channel{id=Id<3>}: Creating Chan
  INFO Thread{id=Id<0>}:Channel{id=Id<3>}: Sending Message!
  INFO Child Thread{id=Id<1>}:Channel{id=Id<3>}: Sending Message!

Great! But it seems I cannot use [] or () or {}:

-        write!(fmt, "Id<{}>", self.id)
+        write!(fmt, "Id({})", self.id)

Which looks like:

> RUST_LOG=trace cargo run
  INFO Thread{id=Id(0)>}: hello from logger
  INFO Thread{id=Id(0)>}:Channel{id=Id(3)>}: Creating Chan
  INFO Thread{id=Id(0)>}:Channel{id=Id(3)>}: Sending Message!
  INFO Created child thread
  INFO Child Thread{id=Id(1)>}:Channel{id=Id(3)>}: Sending Message!

This sorta makes sense since it clashes with regex syntax. Using parens seems to fail silently:

> env RUST_LOG="[{id=Id(3)}]" cargo run
# No output

This would be useful as Rust's auto derive for debug uses curly braces and I want to filter by small arrays which use square brackets.

If memory serves, you should be able to escape parens using \( and \)? The regex parser should interpret that as a comma character rather than as a group.

Not being able to use commas, square brackets, and curly brackets is a current limitation of the env-filter parser, since these are part of the filter syntax — we should definitely support them as well. The parser for the filtering syntax is currently quite simple, so it may require a bit of a rewrite. Square and curly brackets would also need to be escaped, as they also have a meaning in the regex syntax, but if we stopped interpreting them as part of the filter syntax when inside a field, that should just work.

This could be worth opening a separate feature-request issue, as I'd really like to get it working!

Span Ordering and Commas

I'm unsure what the difference is between the following filters. They all seem to produce some output:

> env RUST_LOG="[Thread Channel]" cargo run
  INFO Thread{id=Id<0>}: hello from logger
  INFO Thread{id=Id<0>}:Channel{id=Id<3>}: Creating Chan
  INFO Thread{id=Id<0>}:Channel{id=Id<3>}: Sending Message!
> env RUST_LOG="[Channel Thread]" cargo run
  INFO Channel{id=Id<3>}: Creating Chan
  INFO Channel{id=Id<3>}: Sending Message!
  INFO Channel{id=Id<3>}: Sending Message!
> env RUST_LOG="[Thread][Channel]" cargo run
  INFO Channel{id=Id<3>}: Creating Chan
  INFO Channel{id=Id<3>}: Sending Message!
  INFO Channel{id=Id<3>}: Sending Message!
> env RUST_LOG="[Thread],[Channel]" cargo run
  INFO Thread{id=Id<0>}: hello from logger
  INFO Thread{id=Id<0>}:Channel{id=Id<3>}: Creating Chan
  INFO Thread{id=Id<0>}:Channel{id=Id<3>}: Sending Message!
  INFO Channel{id=Id<3>}: Sending Message!

It seems order matters when applying filters: RUST_LOG="[Thread Channel]" vs RUST_LOG="[Channel Thread]"? I assume it tries to apply the directives in order from left to rights?

I'm not sure what the difference is between: RUST_LOG="[Thread Channel]" vs env RUST_LOG="[Thread][Channel]"?

Adding the comma produces different results between: RUST_LOG="[Thread][Channel]" vs RUST_LOG="[Thread],[Channel]"

I'm not sure if some of this syntax is documented.

Directives in the filter syntax are separated by commas. So [Thread],[Channel] creates two separate directives, one which enables everything occurring in a span named Thread, and a separate one which enables everything occurring in a span named Channel. On the other hand, [Thread][Channel] creates a single directive. I'm actually surprised that that parses, since the filter parser was written with the expectation that there would only be a single [...] span filter per directive.

If that form was supported, I would expect that to create a filter that enables everything inside a span named Channel which is itself inside a span named Thread — it appears that it is not enabling the Thread span, which is not quite right. We should either fix this, or make that a parse error.

On the other hand, when there is a single set of brackets, like [Channel Thread] or [Thread Channel], that's interpreted as one span name pattern. I'm actually surprised that matches anything; it should only match a span whose name is "Channel Thread" or "Thread Channel" respectively:

tracing/tracing-subscriber/src/filter/env/directive.rs

Line 154 in 18764d1

if name != meta.name() {

It's possible that's a parser bug!

I'm going to continue replying to your questions in a separate comment; this one has gotten quite long. But, it seems like you've hit a lot of edge cases in the filter implementation — I think most folks don't use a lot of the more advanced filtering options, so I think nobody else has found some of these issues. Sorry about that!

[hawkw]

Continued:

Intuition behind directives and filtering | Names of fields between spans matter

I don't have a clear mental model for how directives are applied to filter spans. Specifically for field directives: I thought it worked as follows: "The directive is checked against a span to decide whether to enter that span or not".

The following examples show my confusion:

> RUST_LOG=[{id}] cargo run
  INFO Thread{id=Id<0>}: hello from logger
  INFO Thread{id=Id<0>}:Channel{id=Id<3>}: Creating Chan
  INFO Thread{id=Id<0>}:Channel{id=Id<3>}: Sending Message!
  INFO Child Thread{id=Id<1>}:Channel{id=Id<3>}: Sending Message!

This makes sense based on my filter since all spans have an id field.

> RUST_LOG=[{id=Id<3>}] cargo run
  INFO Thread{id=Id<0>}:Channel{id=Id<3>}: Creating Chan
  INFO Thread{id=Id<0>}:Channel{id=Id<3>}: Sending Message!
  INFO Child Thread{id=Id<1>}:Channel{id=Id<3>}: Sending Message!

This is a bit surprising as the Thread span id field has the wrong value (!= Id<3>) so I'm surprised it is entered (Note: this is actually the behaviour I want though since I want to see the "context", that is, all the parent spans).

But for some reason this seems to happen only because both fields are named id if I change the name of the field for the Channel from id to cid:

- span!(Level::INFO, "Channel", id=?Id::new(3)).in_scope(||{
+ span!(Level::INFO, "Channel", cid=?Id::new(3)).in_scope(||{

This no longer follow my intuition:

> RUST_LOG=[{cid=Id<3>}] cargo run
  INFO Channel{cid=Id<3>}: Creating Chan
  INFO Channel{cid=Id<3>}: Sending Message!
  INFO Channel{cid=Id<3>}: Sending Message!

In this example all context is lost. Which is a reasonable implementation by itself. But given the example above where the context was kept since both fields happened to be named id seems wrong.

> RUST_LOG=[{cid}] cargo run
  INFO Thread{id=Id<0>}:Channel{cid=Id<3>}: Creating Chan
  INFO Thread{id=Id<0>}:Channel{cid=Id<3>}: Sending Message!
  INFO Child Thread{id=Id<1>}:Channel{cid=Id<3>}: Sending Message!

Similarly why is the context kept in this case but not the one above?

This is kind of a consequence of an interaction between a few of the more counterintuitive aspects of how span filtering works.

The filter's enabled method is called before a span is recorded; this is to ensure that we don't have to record the field values for spans that are disabled, which might be costly to evaluate. However, this means that when filtering on the values of a span's fields, the EnvFilter has to enable all spans which have the field name it cares about, regardless of their values. The span itself will be enabled so that the field's value can be recorded, and then, when the value is recorded, it's matched against the filter. If the value matches, the span will then enable all of its children, otherwise, they will only be enabled if another filter enables them. This is why the Thread span with Id(0) is enabled even though the filter expects Id(3); if the Channel span inside that span did not have Id(3), none of those events would have been enabled. On the other hand, when you change the field name to cid, none of the Thread spans are enabled, since they don't have a field by that name.

Does that make sense? I realize this behavior is somewhat surprising, and while I don't think there's a lot we can do to change the behavior here, it looks like the docs don't really explain this — that, at least, I think we can fix! :)

Using primitives in Debug Instances

I can happily filter based on my Id:

> RUST_LOG=[{id=Id<3>}] cargo run
  INFO Thread{id=Id<0>}:Channel{id=Id<3>}: Creating Chan
  INFO Thread{id=Id<0>}:Channel{id=Id<3>}: Sending Message!
  INFO Child Thread{id=Id<1>}:Channel{id=Id<3>}: Sending Message!

However if I change my Debug impl for ID:

-        write!(fmt, "Id<{}>", self.id)
+        write!(fmt, "{}", self.id)

So that now it looks like:

> RUST_LOG=trace cargo run
  INFO Thread{id=0}: hello from logger
  INFO Thread{id=0}:Channel{id=3}: Creating Chan
  INFO Thread{id=0}:Channel{id=3}: Sending Message!
  INFO Created child thread
  INFO Child Thread{id=1}:Channel{id=3}: Sending Message!

Looks good... but then filtering fails:

gatowololo@thinkpad ~/R/tracing_example (master)> RUST_LOG=[{id=3}] cargo run
# No output

It seems we cannot have our Debug instances "look like" primitive types? I know tracking-subscriber treats certain numeric types, books, and strings special.

Ah, yup, this is because the filtering DSL interprets those values as u64 primtives, not as fmt::Debug values, which creates a filter that only matches primitive values:

tracing/tracing-subscriber/src/filter/env/field.rs

Lines 40 to 45 in 18764d1

	pub(crate) enum ValueMatch {
	Bool(bool),
	U64(u64),
	I64(i64),
	Pat(Box<MatchPattern>),
	}

Since the values are recorded using fmt::Debug, they go directly to the record_debug implementation:

tracing/tracing-subscriber/src/filter/env/field.rs

Lines 315 to 321 in 18764d1

	fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) {
	match self.inner.fields.get(field) {
	Some((ValueMatch::Pat(ref e), ref matched)) if e.debug_matches(&value) => {
	matched.store(true, Release);
	}
	_ => {}
	}

and therefore don't match the filter, even though they probably should.

This behavior is...not great. I think we can fix it by not special-casing primitives here, and just performing all field matching with debug patterns in record_debug. If we removed the record_u64, record_bool, etc implementations from MatchVisitor, everything would be recorded with record_debug, and that pattern would match the u64 value 3 or a value whose debug implementation produces the string "3".

This should, at least, be pretty simple to fix.

Field names cannot be reserved words?

Again I can happily filter by the id field:

> RUST_LOG=[{id}] cargo run
  INFO Thread{id=Id<0>}: hello from logger
  INFO Thread{id=Id<0>}:Channel{id=Id<3>}: Creating Chan
  INFO Thread{id=Id<0>}:Channel{id=Id<3>}: Sending Message!
  INFO Child Thread{id=Id<1>}:Channel{id=Id<3>}: Sending Message!

Looks good. But if my field is called type:

-        span!(Level::INFO, "Channel", id=?Id::new(3)).in_scope(||{
+        span!(Level::INFO, "Channel", r#type=?Id::new(3)).in_scope(||{

Looks like:

> RUST_LOG=[] cargo run
  INFO Thread{id=Id<0>}: hello from logger
  INFO Thread{id=Id<0>}:Channel{type=Id<3>}: Creating Chan
  INFO Thread{id=Id<0>}:Channel{type=Id<3>}: Sending Message!
  INFO Created child thread
  INFO Child Thread{id=Id<1>}:Channel{type=Id<3>}: Sending Message!

I don't seem to be able to filter by the field name anymore:

> RUST_LOG=[{type}] cargo run
# no output

So, when you create a field named r#type, the field name string that's generated is r#type, not type. tracing-subscriber::fmt special-cases field names beginning with r# when formatting:

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

Line 548 in 18764d1

name if name.starts_with("r#") => write!(self.writer, "{}={:?}", &name[2..], value),

and outputs type.

However, EnvFilter doesn't currently do this. If you had written RUST_LOG=[{r#type}], it would have worked.

We should make this behavior more consistent, by changing EnvFilter to also ignore a leading r#. That, too, shouldn't be too difficult.

Conclusion

I realize this is a lot of questions for one issue! Sorry! If anyone could confirm any of the observations/bugs above I'd be happy to dig deeper. I really want filtering for my project. I think the idea is extremely powerful. Thank you for making tracing!

That's quite alright, thanks for opening the issue! I think you are probably trying to use a lot more of the advanced filtering functionality than most people tend to, and so you've hit a bunch of edge cases. Sorry about that — the filtering code is actually one of the most complex part of tracing, and it really hasn't gotten the attention it deserves. Fortunately, I think we can fix a lot of the weird or incorrect behavior you've hit, and improve the documentation for some of the things that are confusing.

Are you interested in helping out with this? If so, please let me know! I'd be happy to provide additional guidance on how to fix some of these problems. Otherwise, no pressure! I appreciate the work you've done in reporting these issues. Thanks!

[pickfire]

I am new to tracing but I am confused why span! works with tracing_subscriber::fmt().init() but does not work with tracing_subscriber::fmt::init(), it took me 2 hours to figure out that it does not work. Is there a reason for the weird behavior of tracing_subscriber::fmt::init() does not work? I thought I used span! wrongly, check here and there and finally being able to figure out that it is not tracing_subscriber::fmt::init issue but not span! issue.