Dispatch::level_for seems broken

[stevenroose]

Dispatch::level_for seems broken

[stevenroose]

Oh I noticed that it's really only the hyper::proto::h1::role module that gets through. All other hyper logs, and there's many at trace level, get filtered.

[daboross]

Interesting! It looks like that's the only module in hyper which uses tracing's trace_span! macro. I wonder if there's something different about the way tracing is including the module path in the span! and trace_span! macros.

If you're still actively debugging this, it might be interesting to include the module_path with the {:?} debug printing and see if there's any weird characters in there?

Fern's module matching logic is at

fern/src/log_impl.rs

Line 250 in fab151f

fn find_module(&self, module: &str) -> Option<log::LevelFilter> {

- it doesn't use split, but its code is at least moderately unit-tested and should behave similarly.

It may take me a few days to find the time to look into this further, so any further debugging you can do conveniently would be much appreciated!

[stevenroose]

It doesn't look different. (I allowed some other modules to get an example:)

[2021-10-15 13:52:44.109][TRACE]["want"] signal: Want
[2021-10-15 13:52:44.110][TRACE]["hyper::proto::h1::role"] encode_headers
[2021-10-15 13:52:44.110][TRACE]["hyper::proto::h1::role"] -> encode_headers
[2021-10-15 13:52:44.110][TRACE]["hyper::proto::h1::role"] <- encode_headers
[2021-10-15 13:52:44.110][TRACE]["hyper::proto::h1::role"] -- encode_headers
[2021-10-15 13:52:44.110][TRACE]["want"] signal: Want
[2021-10-15 13:52:44.110][TRACE]["mio::poll"] deregistering event source from poller

The Debug format adds the quotes, but nothing more it seems.

[stevenroose]

Aha, I found something!

When I replace the module with record.metadata().target(), it prints this:

[2021-10-15 13:57:47.313][TRACE][tracing::span] encode_headers
[2021-10-15 13:57:47.313][TRACE][tracing::span::active] -> encode_headers
[2021-10-15 13:57:47.313][TRACE][tracing::span::active] <- encode_headers
[2021-10-15 13:57:47.313][TRACE][tracing::span] -- encode_headers
[2021-10-15 13:57:47.319][TRACE][tracing::span] parse_headers
[2021-10-15 13:57:47.319][TRACE][tracing::span::active] -> parse_headers
[2021-10-15 13:57:47.320][TRACE][tracing::span::active] <- parse_headers
[2021-10-15 13:57:47.320][TRACE][tracing::span] -- parse_headers
[2021-10-15 13:57:47.321][TRACE][tracing::span] encode_headers
[2021-10-15 13:57:47.321][TRACE][tracing::span::active] -> encode_headers
[2021-10-15 13:57:47.321][TRACE][tracing::span::active] <- encode_headers
[2021-10-15 13:57:47.322][TRACE][tracing::span] -- encode_headers

So somehow, fern finds that the module is hyper, but the target that is used for filtering is tracing.

[daboross]

Ah! Interesting. That would explain the difference.

I would need to do more investigation, but I'm leaning towards this possibly being a bug in tracing right now, then? I think the log "target" is really what we should filter on as a log backend, rather than the module path, and it seems like a bug that calls from hyper would end up in the tracing log target. But maybe this is intentional? I have not followed what tracing has been doing for a while.

[daboross]

I think this code in tracing is causing this:

https://github.com/tokio-rs/tracing/blob/0fa74b9caee1dbb01b8d67ed1e526061ab7156b6/tracing/src/span.rs#L575-L579

If there are no attributes associated with a span, then it creates a log record with the target "tracing::span" rather than the target specified by the span's metadata.

Specifically, this call to trace_span!("parse_headers"):

https://github.com/hyperium/hyper/blob/e48519a1e2f94eb7fa3fe929a1b34cd426892555/src/proto/h1/role.rs#L70

Calls into this:

https://github.com/tokio-rs/tracing/blob/a1868eacd606e0922bfff492995258572c123a76/tracing/src/macros.rs#L204-L211

Which calls here:

https://github.com/tokio-rs/tracing/blob/a1868eacd606e0922bfff492995258572c123a76/tracing/src/macros.rs#L55-L85

Line 73 of that calls Span::new(meta, valueset!(meta.fields(),)). But, meta.fields() is empty because it was created with CALLSITE.metadata(), and that CALLSITE's fields were just populated with $(fields)*, of which none were given.

So we end up at

https://github.com/tokio-rs/tracing/blob/0fa74b9caee1dbb01b8d67ed1e526061ab7156b6/tracing/src/span.rs#L434-L436

with values being empty. This goes to

https://github.com/tokio-rs/tracing/blob/0fa74b9caee1dbb01b8d67ed1e526061ab7156b6/tracing/src/span.rs#L440-L447

still, with empty values. Finally, we get to Span::make_with with an empty new_span parameter:

https://github.com/tokio-rs/tracing/blob/0fa74b9caee1dbb01b8d67ed1e526061ab7156b6/tracing/src/span.rs#L560-L584

This, for some reason, then decides that since we haven't supplied any attributes, we should get the default log target.

Now... I've still got no idea whether or not this is a bug, or intended. I don't know tracing's design philosophy. But this should at least be a good start for talking to tracing about whether this is correct?

[daboross]

I think this is tracing's issue here - as far as I can tell, fern is correct to use target when filtering like this.

I've filed a new feature issue in fern for separate filtering based on modules, not targets, here: #109

However, I do view that as a feature, not a bug, and I believe tracing is incorrect in its behavior with regards to this issue.