ICE with RUST_LOG=debug and dependency rand

[Eroc33]

UPDATE: Note that @eddyb would like to mentor and wrote out some steps to fix this in a comment below.

---

cargo 0.13.0-nightly (2ef3cde 2016-09-04)
rustc 1.13.0-nightly (cbe4de78e 2016-09-05)

repro steps:

1. Create a new cargo project with cargo new --bin whatever
2. add rand to the dependencies
3. compile with RUST_LOG=debug cargo run

(Edit: RUST_LOG=debug cargo build also triggers the ICE)

(Note that using various different crates as dependencies will also cause various different ICEs)

(Also note that most of these ICEs do not occur if not setting RUST_LOG while compiling)

full log: ice_log.txt

Relevant excerpt:

INFO:rustc_trans::base: trans_closure(..., <I as std::iter::IntoIterator><std::iter::Chain<std::iter::Map<std::slice::Iter<u64>, [closure@C:\Users\euan\.cargo\registry\src\github.com-1ecc6299db9ec823\rand-0.3.14\src\isaac.rs:462:41: 462:47]>, std::iter::Repeat<u64>>>::into_iter)
INFO:rustc_trans::base: trans_closure(..., <I as std::iter::IntoIterator><std::iter::Map<std::ops::Range<usize>, [closure@C:\Users\euan\.cargo\registry\src\github.com-1ecc6299db9ec823\rand-0.3.14\src\isaac.rs:378:47: 378:56]>>::into_iter)
INFO:rustc_trans::base: trans_closure(..., <I as std::iter::IntoIterator><std::iter::Zip<std::slice::IterMut<std::num::Wrapping<u64>>, std::iter::Chain<std::iter::Map<std::slice::Iter<u64>, [closure@C:\Users\euan\.cargo\registry\src\github.com-1ecc6299db9ec823\rand-0.3.14\src\isaac.rs:462:41: 462:47]>, std::iter::Repeat<u64>>>>::into_iter)
INFO:rustc_trans::base: trans_closure(..., <&'a T as std::fmt::Display><str>::fmt)
INFO:rustc_trans::base: trans_closure(..., <std::rc::Rc<T> as std::ops::Drop><std::cell::RefCell<reseeding::ReseedingRng<StdRng, ThreadRngReseeder>>>::drop)
INFO:rustc_trans::base: trans_closure(..., <std::rc::Rc<T> as std::ops::Deref><std::cell::RefCell<reseeding::ReseedingRng<StdRng, ThreadRngReseeder>>>::deref)
INFO:rustc_trans::base: trans_closure(..., <std::rc::Rc<std::cell::RefCell<reseeding::ReseedingRng<StdRng, ThreadRngReseeder>>> as std::rc::RcBoxPtr<std::cell::RefCell<reseeding::ReseedingRng<StdRng, ThreadRngReseeder>>>>::dec_strong)
INFO:rustc_trans::base: trans_closure(..., <std::rc::Rc<std::cell::RefCell<reseeding::ReseedingRng<StdRng, ThreadRngReseeder>>> as std::rc::RcBoxPtr<std::cell::RefCell<reseeding::ReseedingRng<StdRng, ThreadRngReseeder>>>>::inc_strong)
INFO:rustc_trans::base: trans_closure(..., ERROR:rbml::reader: failed to find block with tag 143
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/blob/master/CONTRIBUTING.md#bug-reports

note: run with `RUST_BACKTRACE=1` for a backtrace

thread 'rustc' panicked at 'explicit panic', ../src/librbml/lib.rs:436
stack backtrace:
   0:     0x7ffa3ff56fda - <std::rand::OsRng as rand::Rng>::fill_bytes::h076068e3d5c70638
   1:     0x7ffa3ff54d40 - std::panicking::Location::line::h1d71b2da86bcc037
   2:     0x7ffa3ff557cd - std::panicking::rust_panic_with_hook::hb1322e5f2588b4db
   3:     0x7ffa44651273 - <unknown>
   4:     0x7ffa4465302c - rbml::reader::get_doc::hf109ec97c202ad64
   5:     0x7ffa3d024707 - rustc_metadata::decoder::get_generics::hf99308a6734a6c62
   6:     0x7ffa3d04409f - rustc_metadata::csearch::<impl rustc::middle::cstore::CrateStore<'tcx> for rustc_metadata::cstore::CStore>::item_generics::h44e6e64c15136301
   7:     0x7ffa3780a432 - rustc::ty::<impl rustc::ty::context::TyCtxt<'a, 'gcx, 'tcx>>::lookup_generics::h5d0ec4d9f7a8a996
   8:     0x7ffa378122b2 - rustc::util::ppaux::parameterized::hfe6ba681ef424d4e
   9:     0x7ffa3fbc61aa - <rustc_trans::monomorphize::Instance<'tcx> as core::fmt::Display>::fmt::h4bb5172b1516f67e
  10:     0x7ffa3ff85694 - core::fmt::write::h300d6e605e327781
  11:     0x7ffa3ff85392 - <core::fmt::Arguments<'a> as core::fmt::Debug>::fmt::h1da25a9952bf0c75
  12:     0x7ffa3ff85694 - core::fmt::write::h300d6e605e327781
  13:     0x7ffa3ff337dd - <std::io::stdio::Stderr as std::io::Write>::write_fmt::h559a8ee8db54dc03
  14:     0x7ffa4ae41fbc - <log::DefaultLogger as log::Logger>::log::h514ee6b9954c2db7
  15:     0x7ffa4ae42d85 - log::log::h551356a60d785f61
  16:     0x7ffa3fb2f1a6 - rustc_trans::base::<impl rustc_trans::common::FunctionContext<'blk, 'tcx>>::build_return_block::hc40c124e6ced672c
  17:     0x7ffa3fb54cf1 - <rustc_trans::cleanup::UnwindKind as core::cmp::PartialEq>::eq::h586cba4e1cacdefe
  18:     0x7ffa3fbbdec2 - <rustc_trans::mir::operand::OperandRef<'tcx> as core::fmt::Debug>::fmt::hebcdf3c5cd4db77c
  19:     0x7ffa3fbaa046 - <rustc_trans::mir::analyze::CleanupKind as core::cmp::PartialEq>::ne::ha52631b54e0dcbae
  20:     0x7ffa3fba725f - <rustc_trans::mir::CachedMir<'mir, 'tcx> as core::ops::Deref>::deref::h6f4e0d0cf4c71518
  21:     0x7ffa3fb2f409 - rustc_trans::base::<impl rustc_trans::common::FunctionContext<'blk, 'tcx>>::build_return_block::hc40c124e6ced672c
  22:     0x7ffa3fbcf025 - rustc_trans::trans_item::TransItem::define::h159a1f0a8708f3d3
  23:     0x7ffa3fb33221 - rustc_trans::base::trans_crate::hf067cf9d0a8bcbf2
  24:     0x7ffa4024deb4 - rustc_driver::driver::phase_4_translate_to_llvm::he9d5d0022988d46e
  25:     0x7ffa4029d483 - rustc_driver::main::h5a1049f207c7c577
  26:     0x7ffa40280641 - rustc_driver::main::h5a1049f207c7c577
  27:     0x7ffa401be5d2 - <unknown>
  28:     0x7ffa4023dadf - rustc_driver::driver::compile_input::h7dacd98cd2fd7d2b
  29:     0x7ffa4026a5e9 - rustc_driver::run_compiler::h37c4294ab73436f7
  30:     0x7ffa4018b051 - <unknown>
  31:     0x7ffa3ff5fa31 - _rust_maybe_catch_panic
  32:     0x7ffa401a84f4 - <unknown>
  33:     0x7ffa3ff529ce - std::sys::thread::Thread::new::h117e066ad5633902
  34:     0x7ffa65788363 - BaseThreadInitThunk

INFO:cargo::ops::cargo_rustc::job_queue: end: rand v0.3.14 => Target(lib)/Profile(build) => Host
DEBUG:cargo: handle_error; err=CliError { error: Some(ChainedError { error: Could not compile `rand`., cause: Process didn't exit successfully: `rustc C:\Users\euan\.cargo\registry\src\github.com-1ecc6299db9ec823\rand-0.3.14\src\lib.rs --crate-name rand --crate-type lib -g -C metadata=49a08859d086fffe -C extra-filename=-49a08859d086fffe --out-dir D:\dev\rust\testing\target\debug\deps --emit=dep-info,link -L dependency=D:\dev\rust\testing\target\debug\deps --extern libc=D:\dev\rust\testing\target\debug\deps\liblibc-1417726cb94dbc83.rlib --cap-lints allow` (exit code: 101) }), unknown: false, exit_code: 101 }
error: Could not compile `rand`.

[est31]

As rbml is gone now (#36551), maybe worth a try to re-test?

[est31]

Suprisingly, this is still reproducible with 1.14.0-nightly (289f3a4ca 2016-09-29):

INFO:rustc_trans::base: trans_closure(..., std::fs::OpenOptions::open::<&std::path::Path>)
INFO:rustc_trans::base: trans_closure(..., std::fs::File::open::<&str>)
INFO:rustc_trans::base: trans_closure(..., std::io::read_to_end::<std::fs::File>)
INFO:rustc_trans::base: trans_closure(..., std::io::append_to_string::<[closure@DefId { krate: CrateNum(1), node: DefIndex(4235) => std/75fe2fdafd75f237ff013f4ea8c6fac39cd701ee2ed7455130a3f74d5902d10c::io[0]::Read[0]::read_to_string[0]::{{closure}}[0] } 0:&mut &mut std::fs::File]>)
INFO:rustc_trans::base: trans_closure(..., 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/blob/master/CONTRIBUTING.md#bug-reports

note: run with `RUST_BACKTRACE=1` for a backtrace

thread 'rustc' panicked at 'called `Option::unwrap()` on a `None` value', ../src/libcore/option.rs:323
stack backtrace:
   1:     0x7ff02394c43f - std::sys::backtrace::tracing::imp::write::h22f199c1dbb72ba2
   2:     0x7ff02395b94d - std::panicking::default_hook::{{closure}}::h9a389c462b6a22dd
   3:     0x7ff023958e0e - std::panicking::default_hook::h852b4223c1c00c59
   4:     0x7ff0239594f8 - std::panicking::rust_panic_with_hook::hcd9d05f53fa0dafc
   5:     0x7ff023959392 - std::panicking::begin_panic::hf6c488cee66e7f17
   6:     0x7ff0239592d0 - std::panicking::begin_panic_fmt::hb0a7126ee57cdd27
   7:     0x7ff023959251 - rust_begin_unwind
   8:     0x7ff0239a6a1f - core::panicking::panic_fmt::h9af671b78898cdba
   9:     0x7ff0239a694b - core::panicking::panic::h1a2d1a6b50eaa468
  10:     0x7ff0215c2fce - rustc_metadata::decoder::<impl rustc_metadata::cstore::CrateMetadata>::get_generics::hd1475c0f11fab8b0
  11:     0x7ff0215c9e73 - rustc_metadata::csearch::<impl rustc::middle::cstore::CrateStore<'tcx> for rustc_metadata::cstore::CStore>::item_generics::h55da27f9db4e8cc9
  12:     0x7ff020d9ab3f - rustc::ty::<impl rustc::ty::context::TyCtxt<'a, 'gcx, 'tcx>>::lookup_generics::h7979816f3698527d
  13:     0x7ff020da1cc3 - rustc::util::ppaux::parameterized::h0bc66e5dfbaa04f2
  14:     0x7ff0239a8c95 - core::fmt::write::he349f75ae1aca1a1
  15:     0x7ff0239a8990 - <core::fmt::Arguments<'a> as core::fmt::Display>::fmt::h0e666855968de910
  16:     0x7ff0239a8c95 - core::fmt::write::he349f75ae1aca1a1
  17:     0x7ff02393b8a5 - <std::io::stdio::Stderr as std::io::Write>::write_fmt::hea40a51831b7e1f3
  18:     0x7ff01f743781 - <log::DefaultLogger as log::Logger>::log::hfc368897069c3744
  19:     0x7ff01f744507 - log::log::h4dee4f0d4cd441b1
  20:     0x7ff0224fa796 - rustc_trans::base::trans_closure::h941de14309416d66
  21:     0x7ff022517e7f - rustc_trans::closure::trans_closure_body_via_mir::hc380e80fb7895dee
  22:     0x7ff02256b219 - rustc_trans::mir::rvalue::<impl rustc_trans::mir::MirContext<'bcx, 'tcx>>::trans_rvalue::h2a14de75e2fd4285
  23:     0x7ff022559749 - rustc_trans::mir::block::<impl rustc_trans::mir::MirContext<'bcx, 'tcx>>::trans_block::he67d3259f79e4177
  24:     0x7ff022557a28 - rustc_trans::mir::trans_mir::h2fb44ecb31cfdffa
  25:     0x7ff0224fa94c - rustc_trans::base::trans_closure::h941de14309416d66
  26:     0x7ff0225775b4 - rustc_trans::trans_item::TransItem::define::ha4a18b94a3d46bf3
  27:     0x7ff0224fdec4 - rustc_trans::base::trans_crate::h9b06de31ed8799d1
  28:     0x7ff023cdebbd - rustc_driver::driver::phase_4_translate_to_llvm::hc3883ea2c4750179
  29:     0x7ff023d19cca - rustc_driver::driver::compile_input::{{closure}}::h9162a2fa292aeb3f
  30:     0x7ff023d10ec3 - rustc_driver::driver::phase_3_run_analysis_passes::{{closure}}::h1928c4704cfe9c61
  31:     0x7ff023cdc55d - rustc_driver::driver::phase_3_run_analysis_passes::he578df6b8805151c
  32:     0x7ff023cc8f59 - rustc_driver::driver::compile_input::h5b63ccd49eeeb98b
  33:     0x7ff023cf229a - rustc_driver::run_compiler::h98c7274e7cb1d11d
  34:     0x7ff023c2e0eb - std::panicking::try::do_call::h99ed0da044e497c3
  35:     0x7ff023963846 - __rust_maybe_catch_panic
  36:     0x7ff023c4d091 - <F as alloc::boxed::FnBox<A>>::call_box::hbdd5a14cd8e33b97
  37:     0x7ff023957860 - std::sys::thread::Thread::new::thread_start::h50b05608a499d2b2
  38:     0x7ff01bc286f9 - start_thread
  39:     0x7ff02361bb5c - clone
  40:                0x0 - <unknown>

error: Could not compile `rand`.

To learn more, run the command again with --verbose.

Also, it doesn't happen on the 1.12.0 release, so its a regression.

[est31]

It happens on beta as well...

[eddyb]

I think this is the closure bug (closures don't have generics atm, may change later). Technically not a language regression as this is from compiler logging and AFAIK that's disabled in non-nightly.

The correct way to use RUST_LOG is with a list of module paths (can be just crate names).

[TimNN]

@eddyb: it reproduces on beta, so it will probably also reproduce on the next stable.

[TimNN]

Introduced between nightly-2016-08-17 and nightly-2016-08-18 (Changes).

[est31]

@eddyb repeating what I said in IRC (for readers who only read this discussion on github): compiler logging works for me on stable as well. Cross linking #31847, as that issue contains discussion about which behaviour of the compiler to disable on stable and which not.

[eddyb]

@est31 Title is misleading, rustc "debug" logging (literally 99.99% of all RUST_LOG output from rustc) doesn't work on stable, but handful of info! do.

It's one of those rare cases where the information is essential to debugging ICEs and whatnot.
The closure bug is preexisting, but ended up exposed (@oli-obk and @solson hit it in miri before).

One reasonable workaround that can be backported to beta is adding a loop like this before this line, and the namespace enum argument to parametrized can be replaced with DefPathData::{Type,Value}Ns
(since the loop finishes only when one of them is reached).

Actually giving closures generics can be done after the refactor I'm working on lands, but right now it'd just be a messier hack, and printing code has to be rewritten anyway to handle multi-level generics.

EDIT: willing to mentor this as it's not too complicated but testing it would be time-consuming.

[brson]

compiler team please prioritize.

[brson]

If the solution to this involves changing the name of RUST_LOG keep in mind that cargo uses it too.

[eddyb]

@brson Did you remove T-compiler on purpose?

[brson]

@eddyb nope

[Mark-Simulacrum]

I'll take this on, will ping @eddyb when I have a chance to work on it. Shouldn't be too long.

[nikomatsakis]

triage: P-medium

We should fix this (and both @arielb1 and @Mark-Simulacrum seem to be interested) but it's not considered a "high priority" regression, since it's not visible on stable and using RUST_LOG on the compiler as an end-user is not really a recommended course of action.

[ahicks92]

@Mark-Simulacrum
Any progress? This is currently making my life difficult. It turns out that libtest now triggers it, either in master or my private branch, not sure which.

[Mark-Simulacrum]

Unfortunately not. I'm hoping to make some by the end of this week; I've tried looking at the code, but have not been able to talk to @arielb1 or @eddyb about fixing this yet: I don't quite understand what eddyb suggested in the comment above.

Feel free to steal this from me if you'd like, though.

[arielb1]

I'll be happy to mentor you tomorrow.

[Mark-Simulacrum]

@camlorn: This has been fixed; I understand you were waiting on that.

[eddyb]

Not sure closing this is the best idea, don't think RUST_LOG has been renamed yet.

[Mark-Simulacrum]

I feel like renaming RUST_LOG is unrelated to the ICE and as such should probably be filed as a separate issue?

[eddyb]

Fix is incomplete, reopening.

[arielb1]

@eddyb

I thought this issue was for the RUST_LOG crash.

[ahicks92]

@arielb1
It was, and still is. I found another one that's still this issue, or at least closely related to it, then gave it to them on IRC.

I'm sure @eddyb can explain further, as I don't know about the parts of the code that that discussion ended up leading to.