Changed RUST_LOG usage to CARGO_LOG to avoid confusion.

[zachlute]

Fixes #6189.

Changes Cargo to to initialize env_logger with the CARGO_LOG variable instead of RUST_LOG. Also updated documentation, tests, etc. to match the change.

This was previously discussed in PR #6190 but closed at the time due to the soft feature freeze pre-2018. Now that we're beyond that, it seemed worth bringing this up again since there otherwise seemed to generally be support for it.

This particular version also updates the change to change the pretty_env_logger variable as well.

[rust-highfive]

r? @alexcrichton

(rust_highfive has picked a reviewer for you, use r? to override)

[Eh2406]

I am very in faver!

[alexcrichton]

Thanks for this again! I think though that we'll want to coordinate with rustc on this as well, as Cargo isn't the only consumer of RUST_LOG. If we really want RUST_LOG=foo cargo run to only print application-specific logs, then all of rustup, rustc, and cargo will need to use a different variable.

Would you be willing to coordinate with at least rustc to see if there's interest in changing there as well?

[zachlute]

That's a really good point, and one I should have considered, because you're right that this is only part of the story. As far as I can tell, rustup doesn't use env_logger (though I would appreciate being corrected on this), but rustc does and would require similar intervention to get the desired result:

https://github.com/rust-lang/rust/blob/8611577360e66f90470bd40c498cf8d194f67926/src/librustc_driver/lib.rs#L1627

That initially made me wonder if I'm thinking about this whole problem backwards and should just say, "If you don't like this behavior, then have your application use a different environment variable." But that ignores that libraries your application uses might also use env_logger, and you want that output, but can't get without the cargo and rustc stuff. In the end, you can work around all of that by just specifying modules in the variable, but what initially prompted me to go down this road was the idea that the 'default' behavior should be significantly less surprising than it currently is, and that I still believe that most users don't actually want the output from the tools and would be perfectly happy jumping through one more hoop if that's what they wanted.

All of that said, it's probably worth at least exploring options with rustc. Is the best path just to open an issue there and try to get eyes on it? It also raises the question of whether we'd want cargo and rustc to use the same variable or different ones, but I guess we'll cross that bridge once we see if there's any interest.

[alexcrichton]

Ok good to know about rustup! I think yeah opening an issue or a PR on the compiler is a good next step, and once there's consensus there if it's to change we can merge this too!

[Eh2406]

I personally have gotten confused by cargo's logging and have never seen rustc logging. That may be because I'm mostly working on cargo. But it is also what I observed at RBR, and we observed a fair bit of confusion over this at RBR.

I like consistency, but am not entirely convinced that the two necessarily need to be connected.

[zachlute]

I do tend to agree. It seems like it's unlikely that if both rustc and cargo changed their variable, that they would want to use the same variable. Rustc, if it changes at all, is likely to use something like RUSTC_LOG, which wouldn't really make sense to use for cargo.

Ultimately, I think this change can be considered independently of the rustc one, and has value even if rustc never changes.

[alexcrichton]

I feel that if we changed Cargo and not rustc it wouldn't really solve the original problem, while rustc can be avoided sometimes because we don't always run rustc, it can be surprising for folks to run with RUST_LOG and sporadically get huge amounts of logs

[dwijnand]

Maybe instead of trying to play "ignore the convention" we should have another way of specifying environment variables to the binaries run or tested by cargo run and cargo test. cargo run --env-var RUST_LOG=debug?

[zachlute]

I feel like that's actually just another workaround for the 'problem'. The core of the matter (for me) is a 'principle of least surprise' sort of thing. As a user, if I learn about env_logger or have it recommended to me and set it up in my application and then try to use it and run my program the way I always run it, I'm then confronted with a bunch of confusing stuff.

For me, because the need to see cargo and rustc output should (ideally) never be something the user needs to do, it also shouldn't be on the user to jump through hoops to prevent it.

[dwijnand]

try to use it and run my program the way I always run it

Except the env_logger that you just learned about or were recommended doesn't document to use cargo run: https://docs.rs/env_logger/0.6.0/env_logger/#example.

RUST_LOG is the env var used (by default) to configure env_logger, which is also in use by cargo and rustc. If you use it while running cargo, you'll see cargo and rustc's output too. If you want to restrict it to just the binary of a program, then set it in the smaller context where you're running the binary. One way to do that is by building the binary, then setting the env var, and then running the binary. If we want to support doing that while running the binary via cargo, we should support that directly, not change the outer wrappers to avoid the conventions.

[zachlute]

So, I want to stress something that may be lost in the discussion here: This isn't a hypothetical scenario I'm creating where these users are doing this. This whole change was inspired by actual events.

At RBR, I watched basically a whole room of people in a workshop learn about env_logger, set RUST_LOG=debug and then cargo run their program and stare in horror at the result. We obviously figured out what was going on, but it was not a smooth experience.

The point I'm trying to make is that, documentation aside, these were just people using environment variables and cargo in the way they were used to doing to unexpected results.

If we don't think that's worth making this change, that's understandable. This obviously isn't vital in any sense. But it's a point of friction I saw in person that seemed easily corrected.

[bors]

☔ The latest upstream changes (presumably #6687) made this pull request unmergeable. Please resolve the merge conflicts.

[Eh2406]

An example of someone complaining about this in the wild:
https://hyperbo.la/w/reflections-on-learning-rust/ under the heading "log and env_logger"

[bors]

☔ The latest upstream changes (presumably #6695) made this pull request unmergeable. Please resolve the merge conflicts.

[dwijnand]

In Rustup we're considering moving from its custom notifications/term2 setup to more commonplace log + env_logger crates, which is relevant here. So I'm going to nominate this for discussion at next week's meeting.

[ehuss]

For reference, the rustc issue is: rust-lang/rust#57985

[zachlute]

Yeah, haven't had time to work on the rustc PR yet (I'm in the middle of job hunting...woo) but there does seem to be general approval (or at least not any active disapproval) of the suggestion.

[bors]

☔ The latest upstream changes (presumably #6832) made this pull request unmergeable. Please resolve the merge conflicts.

[alexcrichton]

I'm gonna close this to help clear out our queue, but I believe the conclusion remains that we can add this at any time but we'll just want to make sure the rustc side lands first.