chore: set logger without mucking around with env vars

[thomaseizinger]

Env vars are global to a process. Setting them from within the tests is problematic because those tests are run concurrently in the same process.

tracing allows us to set a logger for the current stack scope using set_default. Instead of fighting over which test should initialize the logger, we can only set it for the current scope of each test.

[thomaseizinger]

See https://docs.rs/tracing-subscriber/latest/tracing_subscriber/fmt/struct.SubscriberBuilder.html#method.with_test_writer for why this is useful in tests.

[lolgesten]

What problem are you trying to fix?

[thomaseizinger]

What problem are you trying to fix?

I hit a panic when trying to use set_default in one of the tests because another test was already setting a global logger.

I figured that setting the env var and using a OnceCell is kind of a hack so I opened this PR as a way to only set a logger for the current test.

[algesten]

This is tailored to my workflow. My requirements are:

1. cargo test shows me log for the integration tests. It's enough for me to run cargo test flappy_ice_lite_state to get my reasonable defaults.
2. I can override using RUST_LOG like so: RUST_LOG=blaha=trace cargo test flappy_ice_lite_state

With 1, this is what I expect.

martin@nugget:~/dev/str0m$ cargo test flappy_ice_lite_state
    Finished test [unoptimized + debuginfo] target(s) in 0.06s
…
running 1 test
2024-04-24T04:41:07.790877Z  INFO str0m::ice_::agent: Add local candidate: Candidate(host=1.1.1.1:1000/udp prio=2130706175)
2024-04-24T04:41:07.790927Z  INFO str0m::ice_::agent: Add local candidate: Candidate(host=2.2.2.2:2000/udp prio=2130706175)
2024-04-24T04:41:07.790977Z DEBUG str0m::channel: Allocate channel id: ChannelId(0)
2024-04-24T04:41:07.791111Z DEBUG str0m::change::sdp: Create offer
2024-04-24T04:41:07.791117Z DEBUG str0m::change::sdp: Accept offer

This PR seem to not have any reasonable defaults.

[thomaseizinger]

cargo test shows me log for the integration tests. It's enough for me to run cargo test flappy_ice_lite_state to get my reasonable defaults.

cargo's default behaviour is to not show logs if the test is passing. To override that, you need to pass --nocapture. Taken that into account, running cargo test flappy_ice_lite_state -- --nocapture does indeed display the logs.

I did notice that RA didn't show me all usages of init_log and the guard was dropped too early (including for the test you mentioned) which is now fixed.

If you don't want the --nocapture behaviour then we can remove the with_test_writer from the logger setup. However, having passing tests be quiet by default is IMO kinda nice, especially if you are running cargo test on the entire repository.

[algesten]

cargo's default behaviour is to not show logs if the test is passing. To override that, you need to pass --nocapture. Taken that into account, running cargo test flappy_ice_lite_state -- --nocapture does indeed display the logs.

Fully aware of all that. And no, I don't want to write --nocapture on every test run.

[thomaseizinger]

cargo's default behaviour is to not show logs if the test is passing. To override that, you need to pass --nocapture. Taken that into account, running cargo test flappy_ice_lite_state -- --nocapture does indeed display the logs.

Fully aware of all that. And no, I don't want to write --nocapture on every test run.

We can remove with_test_writer then!

I would like to understand the reasoning though. In what scenario do you need to see the output of a passing test?

[algesten]

I would like to understand the reasoning though. In what scenario do you need to see the output of a passing test?

Many times when I use the integration tests, it's to follow a flow of events happening. My use case is not necessarily a pass/fail check, it's figuring out what's going on using an integration test as reproduction.

This is different to unit tests, where there pretty much always is a pass/fail and I have no need to see logs for that.