From eb153810e35748d2b4556d39dd6778d35ceb1a9e Mon Sep 17 00:00:00 2001 From: Ralf Jung Date: Wed, 31 Oct 2018 10:09:55 +0100 Subject: [PATCH 1/6] Use MIRI_ env vars to set RUST_ ones This means we can do `MIRI_LOG=debug cargo run` and get something reasonable, even if cargo has to build some dependencies first. --- src/bin/miri.rs | 64 +++++++++++++++++++++---------------------------- src/lib.rs | 15 +++++++++++- 2 files changed, 41 insertions(+), 38 deletions(-) diff --git a/src/bin/miri.rs b/src/bin/miri.rs index d4494a838852..c8103c2a1176 100644 --- a/src/bin/miri.rs +++ b/src/bin/miri.rs @@ -12,6 +12,9 @@ extern crate log_settings; extern crate syntax; extern crate log; +use std::path::PathBuf; +use std::env; + use rustc::session::Session; use rustc_metadata::cstore::CStore; use rustc_driver::{Compilation, CompilerCalls, RustcDefaultCalls}; @@ -21,7 +24,6 @@ use rustc::hir::{self, itemlikevisit}; use rustc::ty::TyCtxt; use rustc_codegen_utils::codegen_backend::CodegenBackend; use syntax::ast; -use std::path::PathBuf; struct MiriCompilerCalls { default: Box, @@ -148,42 +150,31 @@ fn after_analysis<'a, 'tcx>( } } -fn init_logger() { - let format = |formatter: &mut env_logger::fmt::Formatter, record: &log::Record| { - use std::io::Write; - if record.level() == log::Level::Trace { - // prepend frame number - let indentation = log_settings::settings().indentation; - writeln!( - formatter, - "{indentation}:{lvl}:{module}: {text}", - lvl = record.level(), - module = record.module_path().unwrap_or(""), - indentation = indentation, - text = record.args(), - ) - } else { - writeln!( - formatter, - "{lvl}:{module}: {text}", - lvl = record.level(), - module = record.module_path().unwrap_or(""), - text = record.args(), - ) +fn init_loggers() { + // Notice that our `extern crate log` is NOT the same as rustc's! So we have to initialize + // them both. + // First, miri. + let env = env_logger::Env::new().filter("MIRI_LOG").write_style("MIRI_LOG_STYLE"); + env_logger::init_from_env(env); + // Now, change the RUST_LOG env var to control rustc's logger. + // If MIRI_LOG is set and RUST_LOG is not, set RUST_LOG. + if let Ok(var) = env::var("MIRI_LOG") { + if env::var("RUST_LOG") == Err(env::VarError::NotPresent) { + // We try to be a bit clever here: If MIRI_LOG is just a single level + // used for everything, we only apply it to the parts of rustc that are + // CTFE-related. Only if MIRI_LOG contains `module=level`, we just + // use the same value for RUST_LOG. + // This way, if you set `MIRI_LOG=trace`, you get only the right parts of + // rustc traced, but you can also do `MIRI_LOG=miri=trace,rustc_mir::interpret=debug`. + if var.contains('=') { + env::set_var("RUST_LOG", &var); + } else { + env::set_var("RUST_LOG", + &format!("rustc::mir::interpret={0},rustc_mir::interpret={0}", var)); + } } - }; - - let mut builder = env_logger::Builder::new(); - builder.format(format).filter( - None, - log::LevelFilter::Info, - ); - - if std::env::var("MIRI_LOG").is_ok() { - builder.parse(&std::env::var("MIRI_LOG").unwrap()); } - - builder.init(); + rustc_driver::init_rustc_env_logger(); } fn find_sysroot() -> String { @@ -208,8 +199,7 @@ fn find_sysroot() -> String { } fn main() { - rustc_driver::init_rustc_env_logger(); - init_logger(); + init_loggers(); let mut args: Vec = std::env::args().collect(); let sysroot_flag = String::from("--sysroot"); diff --git a/src/lib.rs b/src/lib.rs index 9f4eb00877e4..fa60a0da00d5 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -11,10 +11,12 @@ extern crate rustc; extern crate rustc_data_structures; extern crate rustc_mir; extern crate rustc_target; +extern crate rustc_driver; extern crate syntax; use std::collections::HashMap; use std::borrow::Cow; +use std::env; use rustc::ty::{self, Ty, TyCtxt, query::TyCtxtAt}; use rustc::ty::layout::{TyLayout, LayoutOf, Size}; @@ -157,11 +159,21 @@ pub fn eval_main<'a, 'tcx: 'a>( ) { let mut ecx = create_ecx(tcx, main_id, validate).expect("Couldn't create ecx"); + // If MIRI_BACKTRACE is set and RUST_CTFE_BACKTRACE is not, set RUST_CTFE_BACKTRACE. + // Do this late, so we really only apply this to miri's errors. + if let Ok(var) = env::var("MIRI_BACKTRACE") { + if env::var("RUST_CTFE_BACKTRACE") == Err(env::VarError::NotPresent) { + env::set_var("RUST_CTFE_BACKTRACE", &var); + } + } + + // Run! The main execution. let res: EvalResult = (|| { ecx.run()?; ecx.run_tls_dtors() })(); + // Process the result. match res { Ok(()) => { let leaks = ecx.memory().leak_report(); @@ -173,7 +185,8 @@ pub fn eval_main<'a, 'tcx: 'a>( tcx.sess.err("the evaluated program leaked memory"); } } - Err(e) => { + Err(mut e) => { + e.print_backtrace(); if let Some(frame) = ecx.stack().last() { let block = &frame.mir.basic_blocks()[frame.block]; let span = if frame.stmt < block.statements.len() { From cd256448d5483bb8ad6200aada68639a14ae9543 Mon Sep 17 00:00:00 2001 From: Ralf Jung Date: Wed, 31 Oct 2018 10:16:42 +0100 Subject: [PATCH 2/6] dumping locals with MIRI_BACKTRACE=1 is feasible now --- src/lib.rs | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/src/lib.rs b/src/lib.rs index fa60a0da00d5..ee265f8b0a89 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -208,7 +208,6 @@ pub fn eval_main<'a, 'tcx: 'a>( ecx.tcx.sess.err(&e.to_string()); } - /* Nice try, but with MIRI_BACKTRACE this shows 100s of backtraces. for (i, frame) in ecx.stack().iter().enumerate() { trace!("-------------------"); trace!("Frame {}", i); @@ -218,7 +217,7 @@ pub fn eval_main<'a, 'tcx: 'a>( trace!(" local {}: {:?}", i, local); } } - }*/ + } } } } From 8f811fe12f20e6f969490d2db9e05319d6856721 Mon Sep 17 00:00:00 2001 From: Ralf Jung Date: Wed, 31 Oct 2018 10:16:50 +0100 Subject: [PATCH 3/6] update README --- README.md | 26 ++++++++++++++++++++------ 1 file changed, 20 insertions(+), 6 deletions(-) diff --git a/README.md b/README.md index 0e88c8138a51..a905c2aeffb7 100644 --- a/README.md +++ b/README.md @@ -114,7 +114,7 @@ Several `-Z` flags are relevant for miri: Since the heart of Miri (the main interpreter engine) lives in rustc, working on Miri will often require using a locally built rustc. This includes getting a -trace of the execution, as distributed rustc has `trace!` disabled. +trace of the execution, as distributed rustc has `debug!` and `trace!` disabled. The first-time setup for a local rustc looks as follows: ``` @@ -130,14 +130,28 @@ rustup override set custom ``` The `build` step can take 30 minutes and more. -Now you can `cargo build` Miri, and you can `cargo test --tests`. (`--tests` -is needed to skip doctests because we have not built rustdoc for your custom -toolchain.) You can also set `RUST_LOG=rustc_mir::interpret=trace` as -environment variable to get a step-by-step trace. +Now you can `cargo build` Miri, and you can `cargo test` it. But the key point +is, you can now run Miri with a trace of all execution steps: + +```sh +MIRI_LOG=debug cargo run tests/run-pass/vecs.rs +``` + +Setting `MIRI_LOG` like this will configure logging for miri itself as well as +the `rustc::mir::interpret` and `rustc_mir::interpret` modules in rustc. You +can also do more targeted configuration, e.g. to debug the stacked borrows +implementation: + +```sh +MIRI_LOG=miri::stacked_borrows=trace,rustc_mir::interpret=debug cargo run tests/run-pass/vecs.rs +``` + +In addition, you can set `MIRI_BACKTRACE=1` to get a backtrace of where an +evaluation error was originally created. If you changed something in rustc and want to re-build, run ``` -./x.py build src/rustc --keep-stage 0 +./x.py --keep-stage 0 build src/rustc ``` This avoids rebuilding the entire stage 0, which can save a lot of time. From 7a6a68731e670aeda7cdabc1478e3fd1c34472b0 Mon Sep 17 00:00:00 2001 From: Ralf Jung Date: Wed, 31 Oct 2018 10:19:20 +0100 Subject: [PATCH 4/6] remove unused extern crate --- src/lib.rs | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/src/lib.rs b/src/lib.rs index ee265f8b0a89..650998c3e16c 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -6,13 +6,12 @@ extern crate log; // From rustc. +extern crate syntax; #[macro_use] extern crate rustc; extern crate rustc_data_structures; extern crate rustc_mir; extern crate rustc_target; -extern crate rustc_driver; -extern crate syntax; use std::collections::HashMap; use std::borrow::Cow; From 5397f2e43647d1a78c3a4637cdcb398120b603f6 Mon Sep 17 00:00:00 2001 From: Ralf Jung Date: Wed, 31 Oct 2018 10:53:37 +0100 Subject: [PATCH 5/6] when using MIRI_LOG, avoid logging for what rustc does before miri gets started --- src/bin/miri.rs | 26 ++++++++++++++++++-------- 1 file changed, 18 insertions(+), 8 deletions(-) diff --git a/src/bin/miri.rs b/src/bin/miri.rs index c8103c2a1176..6d0f0b5f6a23 100644 --- a/src/bin/miri.rs +++ b/src/bin/miri.rs @@ -107,6 +107,7 @@ fn after_analysis<'a, 'tcx>( state: &mut CompileState<'a, 'tcx>, validate: bool, ) { + init_late_loggers(); state.session.abort_if_errors(); let tcx = state.tcx.unwrap(); @@ -150,16 +151,25 @@ fn after_analysis<'a, 'tcx>( } } -fn init_loggers() { +fn init_early_loggers() { // Notice that our `extern crate log` is NOT the same as rustc's! So we have to initialize - // them both. - // First, miri. + // them both. We always initialize miri early. let env = env_logger::Env::new().filter("MIRI_LOG").write_style("MIRI_LOG_STYLE"); env_logger::init_from_env(env); - // Now, change the RUST_LOG env var to control rustc's logger. - // If MIRI_LOG is set and RUST_LOG is not, set RUST_LOG. + // We only initialize rustc if the env var is set (so the user asked for it). + // If it is not set, we avoid initializing now so that we can initialize + // later with our custom settings, and NOT log anything for what happens before + // miri gets started. + if env::var("RUST_LOG").is_ok() { + rustc_driver::init_rustc_env_logger(); + } +} + +fn init_late_loggers() { + // Initializing loggers right before we start evaluation. We overwrite the RUST_LOG + // env var if it is not set, control it based on MIRI_LOG. if let Ok(var) = env::var("MIRI_LOG") { - if env::var("RUST_LOG") == Err(env::VarError::NotPresent) { + if env::var("RUST_LOG").is_err() { // We try to be a bit clever here: If MIRI_LOG is just a single level // used for everything, we only apply it to the parts of rustc that are // CTFE-related. Only if MIRI_LOG contains `module=level`, we just @@ -172,9 +182,9 @@ fn init_loggers() { env::set_var("RUST_LOG", &format!("rustc::mir::interpret={0},rustc_mir::interpret={0}", var)); } + rustc_driver::init_rustc_env_logger(); } } - rustc_driver::init_rustc_env_logger(); } fn find_sysroot() -> String { @@ -199,7 +209,7 @@ fn find_sysroot() -> String { } fn main() { - init_loggers(); + init_early_loggers(); let mut args: Vec = std::env::args().collect(); let sysroot_flag = String::from("--sysroot"); From 016009a3016dde768806a352aaa5da9c852d9dc5 Mon Sep 17 00:00:00 2001 From: Ralf Jung Date: Wed, 31 Oct 2018 10:58:19 +0100 Subject: [PATCH 6/6] properly recognize log levels --- src/bin/miri.rs | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/src/bin/miri.rs b/src/bin/miri.rs index 6d0f0b5f6a23..bacea04c9768 100644 --- a/src/bin/miri.rs +++ b/src/bin/miri.rs @@ -13,6 +13,7 @@ extern crate syntax; extern crate log; use std::path::PathBuf; +use std::str::FromStr; use std::env; use rustc::session::Session; @@ -172,15 +173,14 @@ fn init_late_loggers() { if env::var("RUST_LOG").is_err() { // We try to be a bit clever here: If MIRI_LOG is just a single level // used for everything, we only apply it to the parts of rustc that are - // CTFE-related. Only if MIRI_LOG contains `module=level`, we just - // use the same value for RUST_LOG. + // CTFE-related. Otherwise, we use it verbatim for RUST_LOG. // This way, if you set `MIRI_LOG=trace`, you get only the right parts of // rustc traced, but you can also do `MIRI_LOG=miri=trace,rustc_mir::interpret=debug`. - if var.contains('=') { - env::set_var("RUST_LOG", &var); - } else { + if log::Level::from_str(&var).is_ok() { env::set_var("RUST_LOG", &format!("rustc::mir::interpret={0},rustc_mir::interpret={0}", var)); + } else { + env::set_var("RUST_LOG", &var); } rustc_driver::init_rustc_env_logger(); }