Add #[test_log(default_log_filter = "___")]

[DarrenTsung]

Users can now specify a default_log_filter via #[test_log(default_log_filter = "foo")] which will be used when RUST_LOG is not specified.

Please note that because env_logger is initialized globally, it is possible that this value will be ignored if the logger is already initialized.

Fixes: #25

[DarrenTsung]

I found it easier to have a separate attribute like:

#[test_log::test(tokio::test)]
#[test_log(default_log_filter = "debug")]

instead of my original proposal:

#[test_log::test(default_log_filter = "debug", tokio::test)]

---

Didn't get to updating the docs yet, wanted to get your take on the implementation so far. Also now that we're using syn::Error::into_compile_error the repo could use some UI tests via trybuild (https://crates.io/crates/trybuild), but didn't want to bloat this PR.

[d-e-s-o]

Will take a look later this week. Thanks for the pull request.

[d-e-s-o]

Overall this looks fine, thanks! I think having a separate attribute makes sense and makes copy and paste easier. Though I will say that I am not 100% sold on the usefulness of this attribute in general. Do you have a workflow/use case that could illustrate better why it would make sense to add such an attribute to one test but not others? I feel like I am still lacking the mental model.

Do I assume correctly that on top of adding some documentation you'd also want to add logic for tracing support? I think that would be the main missing piece. Left a few suggestions/comments.

Also now that we're using syn::Error::into_compile_error the repo could use some UI tests via trybuild (https://crates.io/crates/trybuild), but didn't want to bloat this PR.

Yeah, build tests are one thing. But I am not happy with even the runtime correctness testing story of the crate at all, but haven't had cycles or interest to really rework it. If I understand correctly there are crates that could allow capturing of log output and checking for match programmatically, as opposed to what we do currently with just emitting it and then somehow having a human "verify" (or not...) that things didn't regress. But yeah, it's a separate effort.

[d-e-s-o]

Nit: Probably just a personal thing, but I find the logic somewhat hard to follow or at least review. Can we move the attribute_args definition closer to where it is used? And then would it make sense to just call a top level function here that parses all args and spits out the AttributeArgs object and the rest? And then perhaps rename populate_attribute_args to something containing _single or so to make it clearer that it's handling a single attribute?

[DarrenTsung]

I moved it around and changed the function to be attribute_args.try_parse_attribute_single(attr), lemme know wdyt

[DarrenTsung]

Thanks for the review!

Though I will say that I am not 100% sold on the usefulness of this attribute in general. Do you have a workflow/use case that could illustrate better why it would make sense to add such an attribute to one test but not others?

Re: usefulness in general - my use-case is that I work at a company that has a decent sized Rust codebase and we have a test framework within a larger crate that standardizes on #[test_log]. It's not obvious for programmers that haven't worked with Rust or test_log before how to get the tests to log everything (I also forget to add RUST_LOG=.. when I come back to debugging these tests after a couple months), so it'd improve the UX of working with the tests if just running them with cargo test enabled the logs by default.

Also for various reasons, the optimal RUST_LOG configuration is something like "info,foo_crate=debug" instead of the trivial "info" or "debug" so it's nice to codify that into the source code instead of having it in the bash history / slack messages / README.

Re: attribution on one test and not others - this is more of a limitation I saw with the implementation rather than desired behavior. There are a lot of existing tests within the crate that I'm working in that I don't really want to audit + I think it's possible that someone will commit a env_logger::try_init() call to some test elsewhere within the crate. Which can break the logging when you're running all the tests and the logger gets setup non-deterministically based on the order of the tests.. but IMO that's fine because it's more of a UX improvement that's nice to have. And anyways if someone is debugging a specific test that is failing by specifying it in the cmd (cargo test my_failing_test), then the logger will be setup with the correct defaults.

Do I assume correctly that on top of adding some documentation you'd also want to add logic for tracing support? I think that would be the main missing piece.

Yeah sure I can add something, I didn't actually know about the tracing support for this crate until I looked at the source code. Do you think it would be using the same attribute or a different one?

[d-e-s-o]

Thanks for the review!

Though I will say that I am not 100% sold on the usefulness of this attribute in general. Do you have a workflow/use case that could illustrate better why it would make sense to add such an attribute to one test but not others?

Re: usefulness in general - [...]

Makes sense, thanks for the explanation.

Re: attribution on one test and not others - this is more of a limitation I saw with the implementation rather than desired behavior. There are a lot of existing tests within the crate that I'm working in that I don't really want to audit + I think it's possible that someone will commit a env_logger::try_init() call to some test elsewhere within the crate. Which can break the logging when you're running all the tests and the logger gets setup non-deterministically based on the order of the tests.. but IMO that's fine because it's more of a UX improvement that's nice to have. And anyways if someone is debugging a specific test that is failing by specifying it in the cmd (cargo test my_failing_test), then the logger will be setup with the correct defaults.

Fair enough. I was gonna say that it's the only thing we could add anyway, but thinking about it some more...couldn't we also support a global (crate-wide) #![test_log(...)] attribute with similar (if not the same) machinery? It seems nice and symmetrical to have both, though I have never implemented such an attribute, so perhaps there are limitations there from the Rust side. I can also look into that if that's nothing you have use for.

Do I assume correctly that on top of adding some documentation you'd also want to add logic for tracing support? I think that would be the main missing piece.

Yeah sure I can add something, I didn't actually know about the tracing support for this crate until I looked at the source code. Do you think it would be using the same attribute or a different one?

It shouldn't be much more than passing the args string to to https://docs.rs/tracing-subscriber/0.3.17/tracing_subscriber/fmt/struct.SubscriberBuilder.html#method.with_env_filter, I'd think.

[d-e-s-o]

Fair enough. I was gonna say that it's the only thing we could add anyway, but thinking about it some more...couldn't we also support a global (crate-wide) #![test_log(...)] attribute with similar (if not the same) machinery? It seems nice and symmetrical to have both, though I have never implemented such an attribute, so perhaps there are limitations there from the Rust side. I can also look into that if that's nothing you have use for.

Ah, seems to be unstable currently, sigh. rust-lang/rust#54726 That's a shame, but at least we should be able to make it work once stable.

[DarrenTsung]

Updated the commit with the feedback, I see what you mean with having to manually verify the test output. I added a new tracing test and checked that the log output was correct:

❯ cargo test --features trace trace_with_default_log_filter -- --nocapture
[...]
running 1 test
2023-10-30T16:19:11.126461Z  INFO instrumented{input=6}: r#mod: input = 6
2023-10-30T16:19:11.126485Z  INFO instrumented{input=6}: r#mod: result = 7
2023-10-30T16:19:11.126507Z  INFO instrumented{input=4}: r#mod: input = 4
2023-10-30T16:19:11.126515Z ERROR instrumented{input=4}: r#mod: here we go
2023-10-30T16:19:11.126520Z  INFO instrumented{input=4}: r#mod: result = 5
test trace_with_default_log_filter ... ok

Compared to:

❯ cargo test --features trace trace_with_tokio_attribute_with_arguments -- --nocapture
[...]
running 1 test
2023-10-30T16:19:51.455156Z ERROR r#mod: here we go
test trace_with_tokio_attribute_with_arguments ... ok

(Also tested with RUST_LOG=debug overriding the default_log_filter, etc).

[d-e-s-o]

Thanks! Will take a look at the weekend. Sorry for the delay.

[d-e-s-o]

I made a few more mostly cosmetical changes, added changelog entries, and merged the changes. Thanks for your contribution! Let me know if you need an new released immediately.

[DarrenTsung]

Not in a rush to get a new release if you want to get other things in, just ping me whenever that happens!

[d-e-s-o]

Sounds good. We will need to add some more documentation for the new attribute before we cut a new release. If you have the cycles to come up with something, feel free to open a pull request.