Cannot mix SubscriberBuilder::with_env_filter with SubscriberBuilder::with_span_events

[tbraun96]

Consider this code, which has the intention to use the environment variables to determine the min/max logging levels for a (possibly specific) crate, AND, ensure that spans get written:

pub fn setup_log() {
    let _ = fmt::SubscriberBuilder::default()
        .with_env_filter(EnvFilter::from_default_env())
        .with_span_events(FmtSpan::FULL)
        .finish()
        .try_init();

    log::trace!(target: "myapp", "TRACE enabled");
    log::debug!(target: "myapp", "DEBUG enabled");
    log::info!(target: "myapp", "INFO enabled");
    log::warn!(target: "myapp", "WARN enabled");
    log::error!(target: "myapp", "ERROR enabled");
}

When using RUST_LOG=myapp=trace, we would expect that all events and spans be printed. However, using this configuration, no spans get printed. When the with_env_filter is not used, then, spans are printed, however, we are no longer using the env variables.

[hawkw]

with_span_events does not determine what spans are enabled, it simply determines what logs are printed for those spans that a filter configuration does enable.

In your example, there are no spans, so I'm not sure how to reproduce the precise issue you're having. However, I would wonder if the issue is that the spans in your code have the myapp target or not. If they don't, the myapp=trace filter will not enable those spans, and thus they will not be printed by the with_span_events configuration.

[tbraun96]

Thanks, the code for the spans was actually elsewhere and not shown in the snippet.

To get the desired behaviour, I needed to do this:

    let _ = SubscriberBuilder::default()
        .with_line_number(true)
        .with_file(true)
        .with_span_events(FmtSpan::FULL)
        .with_env_filter(EnvFilter::from_default_env())
        .finish()
        .try_init();

With this, log::info!/etc calls targetting myapp events get shown correctly, including tracing::events! that target myapp.

However, there is still a problem. When specifying a function as below:

#[cfg_attr(feature = "localhost-testing", tracing::instrument(target = "myapp", skip_all, ret, err))]
async fn dummy() -> Result<(), String> {
    Err(String::from("An error targetting `myapp` with level=error should be emitted"))
}

If the env var RUST_LOG=myapp=trace is specified, I do not see events emitted by ret/err. How can I ensure that ret properly targets myapp when emitting an event? (note: assume the feature localhost-testing is enabled)

[hawkw]

Ah, it looks like the issue there is that it looks like when an #[instrument] attribute has an overridden target (in this case, "myapp"), the events generated by ret and err do not currently have the same target as the span:

tracing/tracing-attributes/src/expand.rs

Lines 203 to 217 in 7a9e1e4

	let err_event = match args.err_mode {
	Some(FormatMode::Default) | Some(FormatMode::Display) => {
	Some(quote!(tracing::error!(error = %e)))
	}
	Some(FormatMode::Debug) => Some(quote!(tracing::error!(error = ?e))),
	_ => None,
	};
	let ret_event = match args.ret_mode {
	Some(FormatMode::Display) => Some(quote!(tracing::event!(#level, return = %x))),
	Some(FormatMode::Default) | Some(FormatMode::Debug) => {
	Some(quote!(tracing::event!(#level, return = ?x)))
	}
	_ => None,
	};

We should probably change this so that the overridden target also applies to the events generated by ret and err. Fortunately, this is probably a pretty straightforward change.

[hawkw]

I opened #2183 to track fixing this.

[tbraun96]

Awesome, thank you!