Not seeing log after adding a warn! statement to debug a dependency

[Teajey]

I've forked a dependency of my project here and added a warn! line to try to see what the code is doing: https://github.com/Teajey/actix-web/commit/7821e35494093244f467b30e96c0881f115c4377

I've overridden the official package with:

[patch.crates-io]
actix-http = { git = "https://github.com/Teajey/actix-web.git", branch = "debug-headers" }

But I'm not seeing this warning in the tracing output of my end application. Is there something obvious that I could be missing that would prevent the log from reaching stdout? I am using RUST_LOG=debug.

[hawkw]

How are you configuring the tracing subscriber in your program? Do traces emitted elsewhere in the program work correctly?

[Teajey]

I'm running this right at the beginning of main():

tracing_subscriber::fmt()
            .with_env_filter(EnvFilter::from_default_env())
            .init();

All of the other traces are appearing normally:

rustserver-1  | Mar 11 20:04:32.638 DEBUG rustls::server::hs: decided upon suite Tls12(Tls12CipherSuite { suite: TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384, bulk: Aes256Gcm })    
rustserver-1  | Mar 11 20:04:32.638 DEBUG rustls::server::tls12::client_hello: Resuming connection    
rustserver-1  | Mar 11 20:04:32.639  INFO actix_web::middleware::logger: 172.20.0.5 "POST /graphql HTTP/1.0" 200 126 "http://localhost:3000/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:98.0) Gecko/20100101 Firefox/98.0" 0.000171    
rustserver-1  | Mar 11 20:04:32.639 DEBUG rustls::conn: Sending warning alert CloseNotify

I'm wondering if it could have anything to do with the actix-http package not being configured. There are other trace statements within it, but no configuration. I've never seen any traces from actix-http appear in stdout

[hawkw]

That's...quite strange. If you're enabling the debug level with RUST_LOG, the warn level should definitely also be enabled. I'm assuming the println! you added in actix/actix-web@452a801 did get printed out, so the code in question is executing?

[Teajey]

No, that println! did not make it to stdout either... But this code is definitely being used because I changed the response reason here: https://github.com/Teajey/actix-web/commit/7493fd5413be91c7d922ad6ccb626d4ef4ee0e96 and saw the message change on the frontend.

Y'know I've found that another package, actix-web-actors, can also return NoWebsocketUpgrade. It may just be that I made a bad assumption about where the message is coming from. Let me test this...

[Teajey]

Yep, that was it. It was coming from actix-web-actors!

[hawkw]

Oh, great, glad you figured it out!

[Teajey]

Turns out I should have been putting the warn! line inside actix-web-actors, not actix-http. Always make sure you're tracing the right code ;)