Auto merge of #2956 - oli-obk:atty, r=RalfJung

Switch over to rustc's `tracing` crate instead of using our own `log` crate

disadvantage: to turn on debug/trace logging, you need a rustc built with it
advantage: sharing our logging scheme with rustc, so our logs get nested correctly.

CONTRIBUTING.md

@@ -78,6 +78,8 @@ custom target file, you might have to set `MIRI_NO_STD=1`.
 base directory, e.g. `./miri test fail` will run all compile-fail tests). These filters are passed
 to `cargo test`, so for multiple filers you need to use `./miri test -- FILTER1 FILTER2`.
 
+#### Fine grained logging
+
 You can get a trace of which MIR statements are being executed by setting the
 `MIRI_LOG` environment variable.  For example:
 
@@ -94,9 +96,16 @@ stacked borrows implementation:
 MIRI_LOG=rustc_mir::interpret=info,miri::stacked_borrows ./miri run tests/pass/vec.rs
 ```
 
-In addition, you can set `MIRI_BACKTRACE=1` to get a backtrace of where an
+Note that you will only get `info`, `warn` or `error` messages if you use a prebuilt compiler.
+In order to get `debug` and `trace` level messages, you need to build miri with a locally built
+compiler that has `debug=true` set in `config.toml`.
+
+#### Debugging error messages
+
+You can set `MIRI_BACKTRACE=1` to get a backtrace of where an
 evaluation error was originally raised.
 
+
 ### UI testing
 
 We use ui-testing in Miri, meaning we generate `.stderr` and `.stdout` files for the output

Cargo.toml

@@ -19,8 +19,6 @@ doctest = false # and no doc tests
 
 [dependencies]
 getrandom = { version = "0.2", features = ["std"] }
-env_logger = "0.10"
-log = "0.4"
 rand = "0.8"
 smallvec = "1.7"
 aes = { version = "0.8.3", features = ["hazmat"] }

src/bin/miri.rs

@@ -13,14 +13,14 @@ extern crate rustc_log;
 extern crate rustc_metadata;
 extern crate rustc_middle;
 extern crate rustc_session;
+#[macro_use]
+extern crate tracing;
 
 use std::env::{self, VarError};
 use std::num::NonZeroU64;
 use std::path::PathBuf;
 use std::str::FromStr;
 
-use log::debug;
-
 use rustc_data_structures::sync::Lrc;
 use rustc_driver::Compilation;
 use rustc_hir::{self as hir, Node};
@@ -197,7 +197,7 @@ fn rustc_logger_config() -> rustc_log::LoggerConfig {
             // CTFE-related. Otherwise, we use it verbatim for `RUSTC_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_const_eval::interpret=debug`.
-            if log::Level::from_str(&var).is_ok() {
+            if tracing::Level::from_str(&var).is_ok() {
                 cfg.filter = Ok(format!(
                     "rustc_middle::mir::interpret={var},rustc_const_eval::interpret={var}"
                 ));
@@ -215,10 +215,6 @@ fn rustc_logger_config() -> rustc_log::LoggerConfig {
 }
 
 fn init_early_loggers(early_dcx: &EarlyDiagCtxt) {
-    // Note that our `extern crate log` is *not* the same as rustc's; as a result, we have to
-    // initialize them both, and we always initialize `miri`'s first.
-    let env = env_logger::Env::new().filter("MIRI_LOG").write_style("MIRI_LOG_STYLE");
-    env_logger::init_from_env(env);
     // Now for rustc. 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.

src/borrow_tracker/mod.rs

@@ -2,7 +2,6 @@ use std::cell::RefCell;
 use std::fmt;
 use std::num::NonZeroU64;
 
-use log::trace;
 use smallvec::SmallVec;
 
 use rustc_data_structures::fx::{FxHashMap, FxHashSet};

src/borrow_tracker/stacked_borrows/mod.rs

@@ -9,8 +9,6 @@ use std::cmp;
 use std::fmt::Write;
 use std::mem;
 
-use log::trace;
-
 use rustc_data_structures::fx::FxHashSet;
 use rustc_middle::mir::{Mutability, RetagKind};
 use rustc_middle::ty::{self, layout::HasParamEnv, Ty};

src/borrow_tracker/stacked_borrows/stack.rs

@@ -385,7 +385,7 @@ impl<'tcx> Stack {
             let upper = unique_range.end;
             for item in &mut self.borrows[lower..upper] {
                 if item.perm() == Permission::Unique {
-                    log::trace!("access: disabling item {:?}", item);
+                    trace!("access: disabling item {:?}", item);
                     visitor(*item)?;
                     item.set_permission(Permission::Disabled);
                     // Also update all copies of this item in the cache.

src/borrow_tracker/tree_borrows/mod.rs

@@ -1,5 +1,3 @@
-use log::trace;
-
 use rustc_target::abi::{Abi, Size};
 
 use crate::borrow_tracker::{AccessKind, GlobalState, GlobalStateInner, ProtectorKind};

src/concurrency/data_race.rs

@@ -466,7 +466,7 @@ impl MemoryCellClocks {
         index: VectorIdx,
         access_size: Size,
     ) -> Result<(), DataRace> {
-        log::trace!("Atomic read with vectors: {:#?} :: {:#?}", self, thread_clocks);
+        trace!("Atomic read with vectors: {:#?} :: {:#?}", self, thread_clocks);
         let atomic = self.atomic_access(thread_clocks, access_size)?;
         atomic.read_vector.set_at_index(&thread_clocks.clock, index);
         // Make sure the last non-atomic write and all non-atomic reads were before this access.
@@ -485,7 +485,7 @@ impl MemoryCellClocks {
         index: VectorIdx,
         access_size: Size,
     ) -> Result<(), DataRace> {
-        log::trace!("Atomic write with vectors: {:#?} :: {:#?}", self, thread_clocks);
+        trace!("Atomic write with vectors: {:#?} :: {:#?}", self, thread_clocks);
         let atomic = self.atomic_access(thread_clocks, access_size)?;
         atomic.write_vector.set_at_index(&thread_clocks.clock, index);
         // Make sure the last non-atomic write and all non-atomic reads were before this access.
@@ -504,7 +504,7 @@ impl MemoryCellClocks {
         index: VectorIdx,
         current_span: Span,
     ) -> Result<(), DataRace> {
-        log::trace!("Unsynchronized read with vectors: {:#?} :: {:#?}", self, thread_clocks);
+        trace!("Unsynchronized read with vectors: {:#?} :: {:#?}", self, thread_clocks);
         if !current_span.is_dummy() {
             thread_clocks.clock[index].span = current_span;
         }
@@ -533,7 +533,7 @@ impl MemoryCellClocks {
         write_type: NaWriteType,
         current_span: Span,
     ) -> Result<(), DataRace> {
-        log::trace!("Unsynchronized write with vectors: {:#?} :: {:#?}", self, thread_clocks);
+        trace!("Unsynchronized write with vectors: {:#?} :: {:#?}", self, thread_clocks);
         if !current_span.is_dummy() {
             thread_clocks.clock[index].span = current_span;
         }
@@ -743,7 +743,7 @@ pub trait EvalContextExt<'mir, 'tcx: 'mir>: MiriInterpCxExt<'mir, 'tcx> {
                 &this.machine.threads,
                 current_span,
                 |index, mut clocks| {
-                    log::trace!("Atomic fence on {:?} with ordering {:?}", index, atomic);
+                    trace!("Atomic fence on {:?} with ordering {:?}", index, atomic);
 
                     // Apply data-race detection for the current fences
                     // this treats AcqRel and SeqCst as the same as an acquire
@@ -841,7 +841,7 @@ impl VClockAlloc {
     // Find an index, if one exists where the value
     // in `l` is greater than the value in `r`.
     fn find_gt_index(l: &VClock, r: &VClock) -> Option<VectorIdx> {
-        log::trace!("Find index where not {:?} <= {:?}", l, r);
+        trace!("Find index where not {:?} <= {:?}", l, r);
         let l_slice = l.as_slice();
         let r_slice = r.as_slice();
         l_slice
@@ -1270,7 +1270,7 @@ trait EvalContextPrivExt<'mir, 'tcx: 'mir>: MiriInterpCxExt<'mir, 'tcx> {
                 // Load and log the atomic operation.
                 // Note that atomic loads are possible even from read-only allocations, so `get_alloc_extra_mut` is not an option.
                 let alloc_meta = this.get_alloc_extra(alloc_id)?.data_race.as_ref().unwrap();
-                log::trace!(
+                trace!(
                     "Atomic op({}) with ordering {:?} on {:?} (size={})",
                     access.description(),
                     &atomic,
@@ -1311,11 +1311,11 @@ trait EvalContextPrivExt<'mir, 'tcx: 'mir>: MiriInterpCxExt<'mir, 'tcx> {
                 )?;
 
                 // Log changes to atomic memory.
-                if log::log_enabled!(log::Level::Trace) {
+                if tracing::enabled!(tracing::Level::TRACE) {
                     for (_offset, mem_clocks) in
                         alloc_meta.alloc_ranges.borrow().iter(base_offset, size)
                     {
-                        log::trace!(
+                        trace!(
                             "Updated atomic memory({:?}, size={}) to {:#?}",
                             place.ptr(),
                             size.bytes(),
@@ -1530,7 +1530,7 @@ impl GlobalState {
             vector_info.push(thread)
         };
 
-        log::trace!("Creating thread = {:?} with vector index = {:?}", thread, created_index);
+        trace!("Creating thread = {:?} with vector index = {:?}", thread, created_index);
 
         // Mark the chosen vector index as in use by the thread.
         thread_info[thread].vector_index = Some(created_index);

src/concurrency/sync.rs

@@ -2,8 +2,6 @@ use std::collections::{hash_map::Entry, VecDeque};
 use std::num::NonZeroU32;
 use std::ops::Not;
 
-use log::trace;
-
 use rustc_data_structures::fx::FxHashMap;
 use rustc_index::{Idx, IndexVec};
 use rustc_middle::ty::layout::TyAndLayout;

src/concurrency/thread.rs

@@ -8,7 +8,6 @@ use std::task::Poll;
 use std::time::{Duration, SystemTime};
 
 use either::Either;
-use log::trace;
 
 use rustc_data_structures::fx::FxHashMap;
 use rustc_hir::def_id::DefId;

src/diagnostics.rs

@@ -1,8 +1,6 @@
 use std::fmt::{self, Write};
 use std::num::NonZeroU64;
 
-use log::trace;
-
 use rustc_errors::{DiagnosticBuilder, DiagnosticMessage, Level};
 use rustc_span::{SpanData, Symbol, DUMMY_SP};
 use rustc_target::abi::{Align, Size};

src/eval.rs

@@ -7,9 +7,6 @@ use std::path::PathBuf;
 use std::task::Poll;
 use std::thread;
 
-use log::info;
-use rustc_middle::ty::Ty;
-
 use crate::concurrency::thread::TlsAllocAction;
 use crate::diagnostics::report_leaks;
 use rustc_data_structures::fx::FxHashSet;
@@ -18,7 +15,7 @@ use rustc_hir::def_id::DefId;
 use rustc_middle::ty::{
     self,
     layout::{LayoutCx, LayoutOf},
-    TyCtxt,
+    Ty, TyCtxt,
 };
 use rustc_target::spec::abi::Abi;
 

src/helpers.rs

@@ -3,8 +3,6 @@ use std::iter;
 use std::num::NonZeroUsize;
 use std::time::Duration;
 
-use log::trace;
-
 use rustc_apfloat::ieee::{Double, Single};
 use rustc_apfloat::Float;
 use rustc_hir::def::{DefKind, Namespace};

src/intptrcast.rs

@@ -2,7 +2,6 @@ use std::cell::RefCell;
 use std::cmp::max;
 use std::collections::hash_map::Entry;
 
-use log::trace;
 use rand::Rng;
 
 use rustc_data_structures::fx::{FxHashMap, FxHashSet};

src/lib.rs

@@ -60,6 +60,8 @@ extern crate rustc_middle;
 extern crate rustc_session;
 extern crate rustc_span;
 extern crate rustc_target;
+#[macro_use]
+extern crate tracing;
 
 // Necessary to pull in object code as the rest of the rustc crates are shipped only as rmeta
 // files.

src/operator.rs

@@ -1,7 +1,5 @@
 use std::iter;
 
-use log::trace;
-
 use rand::{seq::IteratorRandom, Rng};
 use rustc_apfloat::{Float, FloatConvert};
 use rustc_middle::mir;

src/shims/foreign_items.rs

@@ -1,7 +1,5 @@
 use std::{collections::hash_map::Entry, io::Write, iter, path::Path};
 
-use log::trace;
-
 use rustc_apfloat::Float;
 use rustc_ast::expand::allocator::AllocatorKind;
 use rustc_hir::{

src/shims/intrinsics/mod.rs

@@ -3,8 +3,6 @@ mod simd;
 
 use std::iter;
 
-use log::trace;
-
 use rand::Rng;
 use rustc_apfloat::{Float, Round};
 use rustc_middle::ty::layout::LayoutOf;

src/shims/panic.rs

@@ -11,8 +11,6 @@
 //!   gets popped *during unwinding*, we take the panic payload and store it according to the extra
 //!   metadata we remembered when pushing said frame.
 
-use log::trace;
-
 use rustc_ast::Mutability;
 use rustc_middle::{mir, ty};
 use rustc_span::Symbol;