Merge pull request #502 from RalfJung/debug

Improve debug env var handling

Author: RalfJung

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.
 

src/bin/miri.rs

@@ -12,6 +12,10 @@ extern crate log_settings;
 extern crate syntax;
 extern crate log;
 
+use std::path::PathBuf;
+use std::str::FromStr;
+use std::env;
+
 use rustc::session::Session;
 use rustc_metadata::cstore::CStore;
 use rustc_driver::{Compilation, CompilerCalls, RustcDefaultCalls};
@@ -21,7 +25,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<RustcDefaultCalls>,
@@ -105,6 +108,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();
@@ -148,42 +152,39 @@ 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("<unknown module>"),
-                indentation = indentation,
-                text = record.args(),
-            )
-        } else {
-            writeln!(
-                formatter,
-                "{lvl}:{module}: {text}",
-                lvl = record.level(),
-                module = record.module_path().unwrap_or("<unknown_module>"),
-                text = record.args(),
-            )
-        }
-    };
-
-    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());
+fn init_early_loggers() {
+    // Notice that our `extern crate log` is NOT the same as rustc's!  So we have to initialize
+    // 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);
+    // 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();
     }
+}
 
-    builder.init();
+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").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.  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 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();
+        }
+    }
 }
 
 fn find_sysroot() -> String {
@@ -208,8 +209,7 @@ fn find_sysroot() -> String {
 }
 
 fn main() {
-    rustc_driver::init_rustc_env_logger();
-    init_logger();
+    init_early_loggers();
     let mut args: Vec<String> = std::env::args().collect();
 
     let sysroot_flag = String::from("--sysroot");

src/lib.rs

@@ -6,15 +6,16 @@
 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 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 +158,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 +184,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() {
@@ -195,7 +207,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);
@@ -205,7 +216,7 @@ pub fn eval_main<'a, 'tcx: 'a>(
                         trace!("    local {}: {:?}", i, local);
                     }
                 }
-            }*/
+            }
         }
     }
 }