MIRI_LOG no longer works

[RalfJung]

Something semi-recently seems to have broken MIRI_LOG:

$ MIRI_LOG=info ./miri run tests/pass/hello.rs
    Finished dev [optimized + debuginfo] target(s) in 0.05s
    Finished dev [optimized + debuginfo] target(s) in 0.03s
     Running `target/debug/cargo-miri miri setup --print-sysroot`
    Finished dev [optimized + debuginfo] target(s) in 0.04s
     Running `target/debug/miri tests/pass/hello.rs`
thread 'rustc' panicked at 'called `Result::unwrap()` on an `Err` value: SetGlobalDefaultError { _no_construct: () }', compiler/rustc_log/src/lib.rs:119:65
stack backtrace:
   0:     0x7f0c69d6632a - std::backtrace_rs::backtrace::libunwind::trace::h081f29f716721cea
                               at /rustc/f3126500f25114ba4e0ac3e76694dd45a22de56d/library/std/src/../../backtrace/src/backtrace/libunwind.rs:93:5
   1:     0x7f0c69d6632a - std::backtrace_rs::backtrace::trace_unsynchronized::h1c7fc4c4ccf8cfff
                               at /rustc/f3126500f25114ba4e0ac3e76694dd45a22de56d/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
   2:     0x7f0c69d6632a - std::sys_common::backtrace::_print_fmt::hb7786e9419686803
                               at /rustc/f3126500f25114ba4e0ac3e76694dd45a22de56d/library/std/src/sys_common/backtrace.rs:65:5
   3:     0x7f0c69d6632a - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::h94ad8e373d395c6e
                               at /rustc/f3126500f25114ba4e0ac3e76694dd45a22de56d/library/std/src/sys_common/backtrace.rs:44:22
   4:     0x7f0c69dc845e - core::fmt::write::h46ba6a9e2a6d4adf
                               at /rustc/f3126500f25114ba4e0ac3e76694dd45a22de56d/library/core/src/fmt/mod.rs:1232:17
   5:     0x7f0c69d56a75 - std::io::Write::write_fmt::h6f4267f20ec68788
                               at /rustc/f3126500f25114ba4e0ac3e76694dd45a22de56d/library/std/src/io/mod.rs:1682:15
   6:     0x7f0c69d660f5 - std::sys_common::backtrace::_print::hb5c67b8e69014d61
                               at /rustc/f3126500f25114ba4e0ac3e76694dd45a22de56d/library/std/src/sys_common/backtrace.rs:47:5
   7:     0x7f0c69d660f5 - std::sys_common::backtrace::print::h2ff0f6ec8fe8dee2
                               at /rustc/f3126500f25114ba4e0ac3e76694dd45a22de56d/library/std/src/sys_common/backtrace.rs:34:9
   8:     0x7f0c69d68ebf - std::panicking::default_hook::{{closure}}::h8f2dc7f3e286efd1
                               at /rustc/f3126500f25114ba4e0ac3e76694dd45a22de56d/library/std/src/panicking.rs:267:22
   9:     0x7f0c69d68bfb - std::panicking::default_hook::heeca694d4cd7d11c
                               at /rustc/f3126500f25114ba4e0ac3e76694dd45a22de56d/library/std/src/panicking.rs:286:9
  10:     0x7f0c6d11e7b4 - rustc_driver[d168a790576a7dcc]::DEFAULT_HOOK::{closure#0}::{closure#0}
  11:     0x7f0c69d696fa - <alloc::boxed::Box<F,A> as core::ops::function::Fn<Args>>::call::h9cd7f28d670041a2
                               at /rustc/f3126500f25114ba4e0ac3e76694dd45a22de56d/library/alloc/src/boxed.rs:2002:9
  12:     0x7f0c69d696fa - std::panicking::rust_panic_with_hook::h892e6adff61670d4
                               at /rustc/f3126500f25114ba4e0ac3e76694dd45a22de56d/library/std/src/panicking.rs:692:13
  13:     0x7f0c69d69479 - std::panicking::begin_panic_handler::{{closure}}::he0859e3e131b2a3c
                               at /rustc/f3126500f25114ba4e0ac3e76694dd45a22de56d/library/std/src/panicking.rs:579:13
  14:     0x7f0c69d667dc - std::sys_common::backtrace::__rust_end_short_backtrace::he7b65f460b4dc3cf
                               at /rustc/f3126500f25114ba4e0ac3e76694dd45a22de56d/library/std/src/sys_common/backtrace.rs:137:18
  15:     0x7f0c69d69182 - rust_begin_unwind
                               at /rustc/f3126500f25114ba4e0ac3e76694dd45a22de56d/library/std/src/panicking.rs:575:5
  16:     0x7f0c69dc4e03 - core::panicking::panic_fmt::h4c3a1b54039d0595
                               at /rustc/f3126500f25114ba4e0ac3e76694dd45a22de56d/library/core/src/panicking.rs:64:14
  17:     0x7f0c69dc5393 - core::result::unwrap_failed::hc5aac3cc35b742e2
                               at /rustc/f3126500f25114ba4e0ac3e76694dd45a22de56d/library/core/src/result.rs:1790:5
  18:     0x7f0c6c73427e - rustc_log[71e99a26091a3a15]::init_env_logger_with_backtrace_option
  19:     0x7f0c6c731775 - rustc_driver[d168a790576a7dcc]::init_rustc_env_logger_with_backtrace_option
  20:     0x55caf47ef169 - miri::init_late_loggers::h8ef23e1edaa43f97
                               at /home/r/src/rust/miri/src/bin/miri.rs:199:13
  21:     0x55caf47eb3b9 - <miri::MiriCompilerCalls as rustc_driver::Callbacks>::after_analysis::{{closure}}::h3b3bad24dbb96be2
                               at /home/r/src/rust/miri/src/bin/miri.rs:65:13
  22:     0x55caf47eb3b9 - rustc_interface::passes::QueryContext::enter::{{closure}}::heb3e4fe1e56ac0af
                               at /rustc/f3126500f25114ba4e0ac3e76694dd45a22de56d/compiler/rustc_interface/src/passes.rs:753:42
  23:     0x55caf47eb3b9 - rustc_middle::ty::context::tls::enter_context::{{closure}}::ha72bb7d9b6d52b7c
                               at /rustc/f3126500f25114ba4e0ac3e76694dd45a22de56d/compiler/rustc_middle/src/ty/context/tls.rs:115:38
  24:     0x55caf47eb3b9 - rustc_middle::ty::context::tls::tlv::with_tlv::hce8acd257fbd2200
                               at /rustc/f3126500f25114ba4e0ac3e76694dd45a22de56d/compiler/rustc_middle/src/ty/context/tls.rs:95:9
  25:     0x55caf47eb3b9 - rustc_middle::ty::context::tls::enter_context::h7d16235b0a60688d
                               at /rustc/f3126500f25114ba4e0ac3e76694dd45a22de56d/compiler/rustc_middle/src/ty/context/tls.rs:115:5
  26:     0x55caf47eb3b9 - rustc_interface::passes::QueryContext::enter::h95be488bfbabcc43
                               at /rustc/f3126500f25114ba4e0ac3e76694dd45a22de56d/compiler/rustc_interface/src/passes.rs:753:9
  27:     0x55caf47eeebb - rustc_interface::queries::QueryResult<rustc_interface::passes::QueryContext>::enter::h8ff4444a2eb3b67a
                               at /rustc/f3126500f25114ba4e0ac3e76694dd45a22de56d/compiler/rustc_interface/src/queries.rs:69:9
  28:     0x55caf47eeebb - <miri::MiriCompilerCalls as rustc_driver::Callbacks>::after_analysis::h2d290463544ad805
                               at /home/r/src/rust/miri/src/bin/miri.rs:62:9
  29:     0x7f0c6c3474a9 - rustc_span[90cd83e1cc6358cf]::with_source_map::<core[be13c3a4a0166a5d]::result::Result<(), rustc_errors[a3f9bdfc7e623733]::ErrorGuaranteed>, rustc_interface[5e583a021ee4110c]::interface::run_compiler<core[be13c3a4a0166a5d]::result::Result<(), rustc_errors[a3f9bdfc7e623733]::ErrorGuaranteed>, rustc_driver[d168a790576a7dcc]::run_compiler::{closure#1}>::{closure#0}::{closure#0}>
  30:     0x7f0c6c33f0f4 - <scoped_tls[51f5e5aadba18ca0]::ScopedKey<rustc_span[90cd83e1cc6358cf]::SessionGlobals>>::set::<rustc_interface[5e583a021ee4110c]::interface::run_compiler<core[be13c3a4a0166a5d]::result::Result<(), rustc_errors[a3f9bdfc7e623733]::ErrorGuaranteed>, rustc_driver[d168a790576a7dcc]::run_compiler::{closure#1}>::{closure#0}, core[be13c3a4a0166a5d]::result::Result<(), rustc_errors[a3f9bdfc7e623733]::ErrorGuaranteed>>
  31:     0x7f0c6c33e7f2 - std[6b8bd2f9a6d311d6]::sys_common::backtrace::__rust_begin_short_backtrace::<rustc_interface[5e583a021ee4110c]::util::run_in_thread_pool_with_globals<rustc_interface[5e583a021ee4110c]::interface::run_compiler<core[be13c3a4a0166a5d]::result::Result<(), rustc_errors[a3f9bdfc7e623733]::ErrorGuaranteed>, rustc_driver[d168a790576a7dcc]::run_compiler::{closure#1}>::{closure#0}, core[be13c3a4a0166a5d]::result::Result<(), rustc_errors[a3f9bdfc7e623733]::ErrorGuaranteed>>::{closure#0}::{closure#0}, core[be13c3a4a0166a5d]::result::Result<(), rustc_errors[a3f9bdfc7e623733]::ErrorGuaranteed>>
  32:     0x7f0c6c9bfd8c - <<std[6b8bd2f9a6d311d6]::thread::Builder>::spawn_unchecked_<rustc_interface[5e583a021ee4110c]::util::run_in_thread_pool_with_globals<rustc_interface[5e583a021ee4110c]::interface::run_compiler<core[be13c3a4a0166a5d]::result::Result<(), rustc_errors[a3f9bdfc7e623733]::ErrorGuaranteed>, rustc_driver[d168a790576a7dcc]::run_compiler::{closure#1}>::{closure#0}, core[be13c3a4a0166a5d]::result::Result<(), rustc_errors[a3f9bdfc7e623733]::ErrorGuaranteed>>::{closure#0}::{closure#0}, core[be13c3a4a0166a5d]::result::Result<(), rustc_errors[a3f9bdfc7e623733]::ErrorGuaranteed>>::{closure#1} as core[be13c3a4a0166a5d]::ops::function::FnOnce<()>>::call_once::{shim:vtable#0}
  33:     0x7f0c69d73793 - <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once::hf05b4b3c0eebe09f
                               at /rustc/f3126500f25114ba4e0ac3e76694dd45a22de56d/library/alloc/src/boxed.rs:1988:9
  34:     0x7f0c69d73793 - <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once::h42d3453ce26899c4
                               at /rustc/f3126500f25114ba4e0ac3e76694dd45a22de56d/library/alloc/src/boxed.rs:1988:9
  35:     0x7f0c69d73793 - std::sys::unix::thread::Thread::new::thread_start::h53c357220671f65c
                               at /rustc/f3126500f25114ba4e0ac3e76694dd45a22de56d/library/std/src/sys/unix/thread.rs:108:17
  36:     0x7f0c69a2dfd4 - start_thread
                               at ./nptl/./nptl/pthread_create.c:442:8
  37:     0x7f0c69aae66c - __GI___clone3
                               at ./misc/../sysdeps/unix/sysv/linux/x86_64/clone3.S:81
  38:                0x0 - <unknown>

error: internal compiler error: unexpected panic

note: the compiler unexpectedly panicked. this is a bug.

note: we would appreciate a bug report: https://github.com/rust-lang/rust/issues/new?labels=C-bug%2C+I-ICE%2C+T-compiler&template=ice.md

note: rustc 1.69.0-nightly (f3126500f 2023-02-02) running on x86_64-unknown-linux-gnu

My guess would be that the loggers are initialized twice, but it's not very clear -- we are just getting a generic SetGlobalDefaultError.

@oli-obk any idea what might have caused this change in behavior?

[bjorn3]

My guess would be that the loggers are initialized twice, but it's not very clear -- we are just getting a generic SetGlobalDefaultError.

SetGlobalDefaultError is returned when the global logger has already been set and in no other cases. The problem is that the logger has already been set very early in the compilation at https://github.com/rust-lang/rust/blob/e7813fee92c56621d08e8dbe83948d9f4a30a9ec/compiler/rustc_driver_impl/src/lib.rs#L233, but miri tries to set it again later at

miri/src/bin/miri.rs

Line 199 in 1bc3e00

rustc_driver::init_rustc_env_logger();

. The call in rustc was introduced by rust-lang/rust#104645.

[RalfJung]

Ah, so that's the diff.

Yeah Miri deliberately delayed calling logger initialization until pretty late, to avoid getting log spam from the rustc part of interpretation (in particular from const-eval during MIR building). This used to work because rustc_driver didn't force-init the loggers. Now it does, so this hack stopped working...

Sadly we also cannot change log filters at runtime, so looks like avoiding the const-eval log spam when debugging Miri has become impossible? :(

[oli-obk]

Ah yes, we even discussed a similar situation in the PR itself. I'll change it so that we stop logging so early

[bjorn3]

Maybe you could implement a new tracing::Subscriber in miri to set as global logger and have this Subscriber first discard everything, but right before actual interpretation by miri starts have it switch to forwarding to the default subscriber rustc uses. Note if max_level_hint isn't unconditionally forwarded, you will have to call tracing_core::callsite::rebuild_interest_cache() when switching and in any case register_callsite needs to return Interest::sometimes() before the switch. There may be some other methods which also have special requirements around changing their return value.