Confusing EnvFilter behavior

[jshearer]

Bug Report

Version

tracing = "0.1.25"
tracing-futures = "0.2.5"
tracing-log = "0.1.2"
tracing-opentelemetry = "0.12.0"
tracing-subscriber = "0.2.18"

Platform

MacOS 11.2

Crates

Description

I'm encountering what I think is some weird behavior from EnvFilter.

My goal is to disable all spans for the /healthcheck endpoint. By default, spans are captured for it:

env RUST_LOG="info" cargo run -- -v start
May 05 12:38:24.105  INFO Server::run{addr=0.0.0.0:3030}: warp::server: listening on http://0.0.0.0:3030
May 05 12:38:26.560  INFO request{method=GET path=/healthcheck version=HTTP/1.1 remote.addr=127.0.0.1:51673}: warp::filters::trace: processing request
May 05 12:38:26.561  INFO request{method=GET path=/healthcheck version=HTTP/1.1 remote.addr=127.0.0.1:51673}: sqlx::query: /* SQLx ping */; rows: 0, elapsed: 541.089µs  
May 05 12:38:26.563  INFO request{method=GET path=/healthcheck version=HTTP/1.1 remote.addr=127.0.0.1:51673}: sqlx::query: SELECT 1; rows: 1, elapsed: 1.293ms  
May 05 12:38:26.563  INFO request{method=GET path=/healthcheck version=HTTP/1.1 remote.addr=127.0.0.1:51673}: warp::filters::trace: finished processing with success status=200
May 05 12:38:26.591  INFO request{method=GET path=/favicon.ico version=HTTP/1.1 remote.addr=127.0.0.1:51673 referer=http://localhost:3030/healthcheck}: warp::filters::trace: processing request
May 05 12:38:26.592 ERROR request{method=GET path=/favicon.ico version=HTTP/1.1 remote.addr=127.0.0.1:51673 referer=http://localhost:3030/healthcheck}: warp::filters::trace: unable to process request (internal error) status=500 error=Rejection([AuthenticationError("Must be authenticated"), AuthenticationError("Must be authenticated"), AuthenticationError("Must be authenticated"), AuthenticationError("Must be authenticated"), AuthenticationError("Must be authenticated"), AuthenticationError("Must be authenticated")])

When I do the following filter using just the default level, plus a particular target, the results are as expected:

env RUST_LOG="info,warp::filters::trace=off" cargo run -- -v start

May 05 12:36:22.506  INFO Server::run{addr=0.0.0.0:3030}: warp::server: listening on http://0.0.0.0:3030
May 05 12:36:24.110  INFO sqlx::query: /* SQLx ping */; rows: 0, elapsed: 404.931µs  
May 05 12:36:24.112  INFO sqlx::query: SELECT 1; rows: 1, elapsed: 1.128ms  

Now, reading the docs, I find that I should be able to specify particular fields in my span to match against. So I try, and get no apparent result:

env RUST_LOG="info,warp::filters::trace[request{path=/healthcheck}]=warn" cargo run -- -v start
May 05 12:40:30.222  INFO Server::run{addr=0.0.0.0:3030}: warp::server: listening on http://0.0.0.0:3030
May 05 12:40:31.339  INFO request{method=GET path=/healthcheck version=HTTP/1.1 remote.addr=127.0.0.1:51694}: warp::filters::trace: processing request
May 05 12:40:31.340  INFO request{method=GET path=/healthcheck version=HTTP/1.1 remote.addr=127.0.0.1:51694}: sqlx::query: /* SQLx ping */; rows: 0, elapsed: 535.085µs  
May 05 12:40:31.341  INFO request{method=GET path=/healthcheck version=HTTP/1.1 remote.addr=127.0.0.1:51694}: sqlx::query: SELECT 1; rows: 1, elapsed: 1.231ms  
May 05 12:40:31.341  INFO request{method=GET path=/healthcheck version=HTTP/1.1 remote.addr=127.0.0.1:51694}: warp::filters::trace: finished processing with success status=200
May 05 12:40:31.383  INFO request{method=GET path=/favicon.ico version=HTTP/1.1 remote.addr=127.0.0.1:51694 referer=http://localhost:3030/healthcheck}: warp::filters::trace: processing request
May 05 12:40:31.384 ERROR request{method=GET path=/favicon.ico version=HTTP/1.1 remote.addr=127.0.0.1:51694 referer=http://localhost:3030/healthcheck}: warp::filters::trace: unable to process request (internal error) status=500 error=Rejection([AuthenticationError("Must be authenticated"), AuthenticationError("Must be authenticated"), AuthenticationError("Must be authenticated"), AuthenticationError("Must be authenticated"), AuthenticationError("Must be authenticated"), AuthenticationError("Must be authenticated")])

I try various combinations, such as info,[request{path=/healthcheck}]=warn, info,[request{path=/healthcheck}]=off, info,[{path=/healthcheck}]=off, info,[{path=/healthcheck}]=warn, info,[{path=\"/healthcheck\"}]=off, and even info,[{path}]=off, with the same results.

In order to check whether the filtering is working at all, I tried the inverse: off,[{path=/healthcheck}]=info, and indeed only got logs about the /healthcheck endpoint:

env RUST_LOG="off,[{path=/healthcheck}]=info" cargo run -- -v start
May 05 12:46:26.670  INFO request{method=GET path=/healthcheck version=HTTP/1.1 remote.addr=127.0.0.1:51727}: warp::filters::trace: processing request
May 05 12:46:26.672  INFO request{method=GET path=/healthcheck version=HTTP/1.1 remote.addr=127.0.0.1:51727}: sqlx::query: /* SQLx ping */; rows: 0, elapsed: 472.144µs  
May 05 12:46:26.673  INFO request{method=GET path=/healthcheck version=HTTP/1.1 remote.addr=127.0.0.1:51727}: sqlx::query: SELECT 1; rows: 1, elapsed: 1.341ms  
May 05 12:46:26.674  INFO request{method=GET path=/healthcheck version=HTTP/1.1 remote.addr=127.0.0.1:51727}: warp::filters::trace: finished processing with success status=200

I suspect that somehow the info is taking priority over the second filter, and I can't figure out how to signify my intent of "ALL messages >= info, EXCEPT those matching this filter". Any ideas?

[ririsoft]

I have similar issue, I cannot make a filter such info,[conn]=error work, where conn is the name of a span.

[ririsoft]

Maybe linked to #512 ?

[ririsoft]

Interesting discussion also #722, should this one be closed as duplicate ?

[tfreiberg-fastly]

I thankfully don't need this, but I'm curious if this is fixable - it kinda seems like changing this block to return false if there's a matching directive with a lower level would solve the issue shown here.
(the entire dynamics block is currently only run if the dynamics max level is high enough to enable something, that'd need to be changed as well)

I'm pretty sure that such a change would cause many issues though, I think defining which directive is the most specific one is harder than with static directives.

Also relevant to this issue: the Ord impl of Directive (here) is how "most specific directive" is defined.

Edit: I've hit a case where I wanted this feature now, so I'm a bit more invested.
@hawkw: what's your gut feeling here, do you think it's possible to implement a "more specific dynamic filter is able to disable an event that would be enabled by a less specific static filter" feature?
I've tried to start a naive implementation and see where it breaks, but I can't get it to work (PR)

[slinkydeveloper]

Hi all,

In my use case I have a system where I have both logs and tracing with tracing-opentelemetry. I set up different EnvFilter for the tracing and log layers. Every event/span related to specific user requests have a field myapp.request.id attached, and while on tracing I want to have all the info event/spans, on logging I want to be able to setup >= warn level on user requests, as logs tends to be noisy there. So something like that [{myapp.request.id}]=warn,info would do this trick.

[fw42]

Anyone found a solution to this? It seems like #583 should have resolved this problem, but I'm still seeing the same behaviour even on the latest versions of tracing and tracing-subscriber.

cc @hawkw @davidbarsky @yaahc