Show a warning when a subscriber subscribes to a log level that is disabled at compile time

[jyn514]

Feature Request

I tried to write the title using the tracing terminology, but I might have gotten it wrong. Here is a concrete use case:

Motivation

In rustc, we disable trace and debug logging by default for performance reasons, using the max_level_info feature. This is very confusing to new contributors: they add debug!("x") to the code and run RUSTC_LOG=debug rustc, but no debug information appears.

It would be great to show a warning when using RUSTC_LOG=debug but logs at the debug level are disabled; I'm imagining something like this:

$ RUSTC_LOG=debug rustc
warning: debug logging has been disabled
note: to show debug logging, do not enable the `max_level_info` feature
# info-level logging follows

Ideally this would happen whenever debug logging would normally be enabled, e.g. for RUSTC_LOG=rustc_resolve (which shows debug logging only for that module). However for a first pass I'd be ok with hard-coding this for =debug.

Alternatives

• Don't print any warning; require the downstream crate to parse the RUSTC_LOG variable themselves. This is the current situation; it avoids cluttering logs if the user already knows a level has been disabled at the cost of being confusing if they don't.
• Print a warning, but in a different format than the one I mentioned here.
• Only print the warning when the downstream crate opts-in.

See also rust-lang/rust#76608.

[hawkw]

I think having something like this definitely makes sense. The main question is where this functionality ought to go.

I think it makes sense to implement something like this in the EnvFilter type in tracing-subscriber (which is what implements the RUST_LOG-style directive-based filtering). When constructing an EnvFilter, we could validate each filter directive's level against tracing's STATIC_MAX_LEVEL constant, which is controlled by the compile-time filtering features.

There are a couple tradeoffs with implementing this warning in EnvFilter vs somewhere else, but I think this is the right choice. The potential downsides are:

1. tracing-subscriber would have to depend on tracing to access the STATIC_MAX_LEVEL constant (it presently only depends on tracing-core). However, this dependency could only be required when the env_filter feature flag is enabled.
2. This would, of course, only work with EnvFilters. Other filtering implementations would have to reimplement their own versions of this logic.

However, the biggest advantage of implementing this in EnvFilter is that the warning messages we generate could include the particular filtering directive(s) that would not be enabled. For example, we could print something like

RUST_LOG=foo=debug,bar::baz=trace,quux=info,warn myapp
warning: some trace filter directives would enable traces that are disabled statically
 | `foo=debug` would enable the DEBUG level for the `foo` target.
 | `bar::baz=trace` would enable the TRACE level for the `bar::baz` target.
 | the static maximum level is INFO.
note: to enable debug logging, do not enable the `max_level_info` feature

The alternative would be to implement this behavior in tracing-core, when processing the max level hints provided by the subscriber(s). This would have the advantage of working "out of the box" for any filtering implementation that implements max level hinting.

However, the downside of this is that we would need to move the static max level out of the tracing crate and into tracing-core. We could do this without a breaking change by forwarding the feature flags and reexporting the STATIC_MAX_LEVEL constant. However, I'd prefer not to move compile-time filtering out of the instrumentation API and into the core facade API. This is partially in order to keep tracing-core as minimal as possible, and also to allow alternative instrumentation implementations to provide their own forms of compile-time filtering — for example, I think @KodrAus is experimenting with an implementation that can express per-module filtering at compile-time.

Therefore, I think implementing this in EnvFilter (and eventually in other filter impls) is the best approach.

[hawkw]

As for how to report these errors: presently, EnvFilter has two sets of APIs for constructing an EnvFilter.

• The new, from_env, and from_default_env functions construct an EnvFilter from a string/environment variable, skipping any directives that couldn't be parsed and print a warning:
  

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

  Lines 150 to 159 in 743283d

  	pub fn new<S: AsRef<str>>(dirs: S) -> Self {
  	let directives = dirs.as_ref().split(',').filter_map(|s| match s.parse() {
  	Ok(d) => Some(d),
  	Err(err) => {
  	eprintln!("ignoring `{}`: {}", s, err);
  	None
  	}
  	});
  	Self::from_directives(directives)
  	}

• The try_new, try_from_env, and try_from_default_env functions return a Result if any filtering directives couldn't be parsed.

We could easily add this validation to the new/from_env constructors, and print the warning the same way we currently do for parse errors. However, as @jyn514's issue points out, some users (such as rustc) might want to have their own formatting for these warnings, or display them in some way other than printing them to stdout, while still using any valid filtering directives. The current API doesn't really support this — you can either get a Result back, which allows you to determine how the error should be displayed, but doesn't give you an EnvFIlter with any directives that were valid, or you can skip invalid directives, but let tracing-subscriber take control of printing the warnings.

I think what we might want to do is consider tweaking these APIs so that we have a version that returns a Result where the error type still contains an EnvFilter with any valid directives. The error type could have a method that returns the EnvFilter with the valid directives, similarly to how std::sync::Mutex's PoisonError allows the user to ignore poisoning. This way, the user knows whether the entire filter was valid, and can control how warnings are displayed, but also can still use the valid ones.

We might also want to change the error type to store all the warnings in a Vec or something, so the user can iterate over them and decide how to format or report each individual warning. Since EnvFilter parsing doesn't happen very often (typically it happens once on application startup, or infrequently as the result of a user action) the overhead of storing a bunch of error information doesn't really matter a whole lot here.

[jyn514]

However, the biggest advantage of implementing this in EnvFilter is that the warning messages we generate could include the particular filtering directive(s) that would not be enabled.

This sounds really amazing :D thanks for thinking of this! Showing exactly the logging that will be ignored is extremely helpful.

This would, of course, only work with EnvFilters. Other filtering implementations would have to reimplement their own versions of this logic.

From the rustc perspective, I have no problem with this, we're ~never going to switch away from RUSTC_LOG. It sounds like from the tracing side this is not ideal but still a reasonable trade-off.

However, as @jyn514's issue points out, some users (such as rustc) might want to have their own formatting for these warnings, or display them in some way other than printing them to stdout, while still using any valid filtering directives.

This is a 'nice to have' IMO: It would of course be great to say 'enable these logs by adding debug = true to config.toml', but just knowing that the logs are turned off gets you 90% of the way there and I can document the rest in https://rustc-dev-guide.rust-lang.org/.