gix-trace: tracing level set by subscriber not always respected

[nrdxp]

Current behavior 😯

So typically crates that implement or integrate with the tracing crate are meant to respect whatever the user set tracing level is at application start time. At a high-level, I have a cli application that sets the tracing level early in main. I also having the tracing feature enabled in gix, which is a dependency of my app.

As far as I can tell gix does not respect the default level set, at least in places. It is a bit strange actually because if I leave the default level (which is WARN in my app) I still get a few DEBUG level messages from gix, but if I set the level explicitly to DEBUG, I get more DEBUG level traces from gix components than I did before.

This essentially leads me to believe that some parts of gix are respecting the current tracing level and others are not.

Expected behavior 🤔

All tracing operations should uniformly respect the currently set level as set by the subscriber.

Git behavior

Not directly equivalent since we are talking about a rust specific tracing framework here, but git tries to maintain the correct verbosity level as set by the user, as far as I understand it.

Steps to reproduce 🕹

I first noticed this behavior when using a network client to fetch and update HEAD like so:

                let mut remote = repo
                    .find_remote(remote_str.as_str())
                    .map_err(Box::new)?
                    .with_fetch_tags(Tags::None);
                remote
                    .replace_refspecs(Some("+HEAD"), Direction::Fetch)
                    .map_err(Box::new)?;

                let client = remote.connect(Direction::Fetch).map_err(Box::new)?;
                let sync = client
                    .prepare_fetch(Discard, Options::default())
                    .map_err(Box::new)?;

                let outcome = sync
                    .receive(Discard, &AtomicBool::new(false))
                    .map_err(Box::new)?;

If I leave my app at the default level (WARN), then I still get the following DEBUG output on the cli:

DEBUG remote::Connection::ref_map():remote::Connection::fetch_refs(): gix_credentials::program: launching credential helper cmd="/bin/sh" "-c" "/nix/store/ci5hgcdq8jmqzh1vn4p3wab22pqnvfjj-gh-2.53.0/bin/gh auth git-credential \"$@\"" "--" "get"
DEBUG remote::Connection::ref_map():remote::Connection::fetch_refs(): gix_credentials::program: launching credential helper cmd="/bin/sh" "-c" "/nix/store/ci5hgcdq8jmqzh1vn4p3wab22pqnvfjj-gh-2.53.0/bin/gh auth git-credential \"$@\"" "--" "store"

However, if I increase the verbosity level to DEBUG I get:

DEBUG reqwest::connect: starting new connection: https://github.com/
DEBUG resolve{host=github.com}: hyper_util::client::legacy::connect::dns: resolving host="github.com"
DEBUG hyper_util::client::legacy::connect::http: connecting to 140.82.112.3:443
DEBUG hyper_util::client::legacy::connect::http: connected to 140.82.112.3:443
DEBUG h2::client: binding client connection
DEBUG h2::client: client connection bound
DEBUG h2::codec::framed_write: send frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384, max_header_list_size: 16384 }
DEBUG hyper_util::client::legacy::pool: pooling idle connection for ("https", github.com)
DEBUG Connection{peer=Client}: h2::codec::framed_write: send frame=WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 }
DEBUG Connection{peer=Client}: h2::codec::framed_write: send frame=Headers { stream_id: StreamId(1), flags: (0x5: END_HEADERS | END_STREAM) }
DEBUG Connection{peer=Client}: h2::codec::framed_read: received frame=Settings { flags: (0x0), max_concurrent_streams: 100, initial_window_size: 67108864, max_frame_size: 68608, enable_connect_protocol: 1 }
DEBUG Connection{peer=Client}: h2::codec::framed_write: send frame=Settings { flags: (0x1: ACK) }
DEBUG Connection{peer=Client}: h2::codec::framed_read: received frame=Settings { flags: (0x1: ACK) }
DEBUG Connection{peer=Client}: h2::proto::settings: received settings ACK; applying Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384, max_header_list_size: 16384 }
DEBUG Connection{peer=Client}: h2::codec::framed_read: received frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
DEBUG Connection{peer=Client}: h2::codec::framed_read: received frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }
DEBUG remote::Connection::ref_map():remote::Connection::fetch_refs(): gix_credentials::program: launching credential helper cmd="/bin/sh" "-c" "/nix/store/ci5hgcdq8jmqzh1vn4p3wab22pqnvfjj-gh-2.53.0/bin/gh auth git-credential \"$@\"" "--" "get"
DEBUG hyper_util::client::legacy::pool: reuse idle connection for ("https", github.com)
DEBUG Connection{peer=Client}: h2::codec::framed_write: send frame=Headers { stream_id: StreamId(3), flags: (0x5: END_HEADERS | END_STREAM) }
DEBUG Connection{peer=Client}: h2::codec::framed_read: received frame=Headers { stream_id: StreamId(3), flags: (0x4: END_HEADERS) }
DEBUG Connection{peer=Client}: h2::codec::framed_read: received frame=Data { stream_id: StreamId(3) }
DEBUG Connection{peer=Client}: h2::codec::framed_read: received frame=Data { stream_id: StreamId(3) }
DEBUG Connection{peer=Client}: h2::codec::framed_read: received frame=Data { stream_id: StreamId(3) }
DEBUG Connection{peer=Client}: h2::codec::framed_read: received frame=Data { stream_id: StreamId(3) }
DEBUG Connection{peer=Client}: h2::codec::framed_read: received frame=Data { stream_id: StreamId(3) }
DEBUG Connection{peer=Client}: h2::codec::framed_read: received frame=Data { stream_id: StreamId(3), flags: (0x1: END_STREAM) }
DEBUG remote::Connection::ref_map():remote::Connection::fetch_refs(): gix_credentials::program: launching credential helper cmd="/bin/sh" "-c" "/nix/store/ci5hgcdq8jmqzh1vn4p3wab22pqnvfjj-gh-2.53.0/bin/gh auth git-credential \"$@\"" "--" "store"
DEBUG hyper_util::client::legacy::pool: reuse idle connection for ("https", github.com)
DEBUG Connection{peer=Client}: h2::codec::framed_write: send frame=Headers { stream_id: StreamId(5), flags: (0x4: END_HEADERS) }
DEBUG Connection{peer=Client}: h2::codec::framed_write: send frame=Data { stream_id: StreamId(5), flags: (0x1: END_STREAM) }
DEBUG Connection{peer=Client}: h2::codec::framed_read: received frame=WindowUpdate { stream_id: StreamId(5), size_increment: 107 }
DEBUG Connection{peer=Client}: h2::codec::framed_read: received frame=WindowUpdate { stream_id: StreamId(0), size_increment: 2147418219 }
DEBUG Connection{peer=Client}: h2::codec::framed_read: received frame=Headers { stream_id: StreamId(5), flags: (0x4: END_HEADERS) }
DEBUG Connection{peer=Client}: h2::codec::framed_read: received frame=Data { stream_id: StreamId(5) }
DEBUG Connection{peer=Client}: h2::codec::framed_read: received frame=Data { stream_id: StreamId(5), flags: (0x1: END_STREAM) }

So it is possibly a single call site that is the issue. I will attempt to triage later myself when I have the time, but this is as much as I know so far.

[Byron]

Thanks a lot for letting me know!

This is indeed unexpected and unintended, and from all I know that shouldn't be possible. gix doesn't mess with tracing in any way, and just uses the gix-tracing crate which probably holds the key to what's happening here.

It feels a bit like… codepaths that are encountered before the parent application sets the tracing level see the default, which might be DEBUG, and use it from that point on. That would explain why after setting the application level to DEBUG, even more traces show up.

Maybe that can also be explained with the tracing-subscriber being 'cached' in spans, along with its settings.

Assuming that the application truly sets up its tracing as the first thing the application does, I'd expect no issues.

[nrdxp]

Hmm I'll have to review my code as well, perhaps I am doing something to cause this. The only thing that runs before setting up the subscriber is clap, but I have some custom value parsers that may actually be causing an issue now that you mention it.

[nrdxp]

No its not my parser. I temporarily disabled them just to test, but its still exhibiting the same behavior. I suppose I should add this is with the latest stable crate, as well.

[nrdxp]

After spending a bit of time trying to triage this, I am also confused. I see that, when tracing is enabled, you simply reuse the tracing levels from upstream tracing_core, which should respect the set level in the subscriber. In fact, if the subscriber had not been set, the messages wouldn't even show at all (which I confirmed).

But somehow the message prints at an inappropriate level, it could be this is an upstream bug in tracing core itself, or perhaps gix unintentially ignores and/or resets the tracing level somewhere? Still trying to see if I can find out...

edit
potentially related?
tokio-rs/tracing#2927

[nrdxp]

Okay so I'm not sure the linked issue is actually relevant, at least according to the information in the post. My tracing-core version in my lockfile is the v0.1.32, which is the version the OP mentioned did not exhibit this issue.

In order to debug this further, and because I was curious if perhaps the custom tracing macros in gitoxide were to blame, I did a quick and dirty swap for the call to gix_trace::debug! to simply tracing::debug! (by temporarily adding the latter as a dependency to the gix-credential crate where one of the problematic calls originates).

Sure enough, using the upstream tracing macro correctly respects the set global subscriber level in my app. So the issue seems to be lying somewhere in gix_trace::debug! or its underlying machinery. I am still too new to the codebase here to understand why you might have opted to use custom tracing macros and spans instead of simply reusing usptream, but wouldn't relying on tracing be less of a maintenance burden in the long run?

[Byron]

Thanks a lot for digging into this! That makes sense, probably there is some issue with the way the macro is implemented then.

I am still too new to the codebase here to understand why you might have opted to use custom tracing macros and spans instead of simply reusing usptream, but wouldn't relying on tracing be less of a maintenance burden in the long run?

The idea here was to have macros purpose-made for how I usually use these tracing capabilities. But even more important, these macros compile to nothing if tracing is disabled, so the tracing dependency can be completely removed, and is an opt-in.

[Byron]

I took a look and couldn't find a reason for the level not being respected.

https://github.com/Byron/gitoxide/blob/3ef3bc20a1b90799e5ac26858f898bc7a7c96901/gix-trace/src/enabled.rs#L139-L157

Maybe it's even more subtle somehow.

[nrdxp]

I was wondering if perhaps the no-op implementation here had something to do with it:
https://github.com/Byron/gitoxide/blob/3ef3bc20a1b90799e5ac26858f898bc7a7c96901/gix-trace/src/enabled.rs#L74

[Byron]

That looks like an interesting lead!

Maybe a correct implementation has to implement this as the subscriber might tell it to simply never interact with it.

I think the reason this custom call-site implementation even exists is that when the crate was created, it was not possible to use the tracing callsite implementation - maybe that changed?

If not, maybe one has to copy more of the implementation in order to be more correct.

[nrdxp]

So I took a crack at using the tracing_core::callsite::DefaultCallsite in place of your custom MetaOnlyCallsite type, but it seems we won't be able to use it easily in a static context due to:
rust-lang/rust#80384

Just wanted to see if it would even help though, still not sure.