Dispatch::level_for seems broken
stevenroose opened this issue · 7 comments
So I have the following setup:
fern::Dispatch::new()
.level(log::LevelFilter::Trace)
.level_for("tokio", log::LevelFilter::Warn)
.level_for("tokio_util", log::LevelFilter::Warn)
.level_for("mio", log::LevelFilter::Warn)
.level_for("hyper", log::LevelFilter::Warn)
.format(|out, msg, rec| {
let ts = chrono::Local::now().format("%Y-%m-%d %H:%M:%S%.3f");
let module = rec.module_path().unwrap_or_default().split("::").nth(0).unwrap();
out.finish(format_args!("[{}][{}][{}] {}", ts, rec.level(), module, msg))
})
.chain(std::io::stdout())
.apply()
.expect("error setting up logger");However, hyper logs are coming through:
[2021-10-15 10:13:10.417][TRACE][hyper] encode_headers
[2021-10-15 10:13:10.417][TRACE][hyper] -> encode_headers
[2021-10-15 10:13:10.418][TRACE][hyper] <- encode_headers
[2021-10-15 10:13:10.418][TRACE][hyper] -- encode_headers
I verified that my setup is otherwise working, when I remove all the level_for statements, I get a lot of mio logs that I don't get with this setup. So there seems to be something about hyper that is failing.
If I don't shorten the module path, it's this:
[2021-10-15 10:18:26.178][TRACE][hyper::proto::h1::role] encode_headers
[2021-10-15 10:18:26.178][TRACE][hyper::proto::h1::role] -> encode_headers
[2021-10-15 10:18:26.178][TRACE][hyper::proto::h1::role] <- encode_headers
[2021-10-15 10:18:26.179][TRACE][hyper::proto::h1::role] -- encode_headers
These hyper logs do listen to the global level: when I set that to "Debug", they disappear.
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.
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
Line 250 in fab151f
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!
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.
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.
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.
I think this code in tracing is causing this:
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"):
Calls into this:
Which calls here:
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
with values being empty. This goes to
still, with empty values. Finally, we get to Span::make_with with an empty new_span parameter:
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?
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.