From e6bc750cb39a68805748dc205aae929befbd97ca Mon Sep 17 00:00:00 2001 From: Oli Scherer Date: Mon, 3 Jul 2023 09:01:24 +0000 Subject: [PATCH] Switch over to rustc's `tracing` crate instead of using our own `log` crate --- CONTRIBUTING.md | 11 +++- Cargo.lock | 56 --------------------- Cargo.toml | 2 - src/bin/miri.rs | 10 ++-- src/borrow_tracker/mod.rs | 1 - src/borrow_tracker/stacked_borrows/mod.rs | 2 - src/borrow_tracker/stacked_borrows/stack.rs | 2 +- src/borrow_tracker/tree_borrows/mod.rs | 2 - src/concurrency/data_race.rs | 20 ++++---- src/concurrency/sync.rs | 2 - src/concurrency/thread.rs | 1 - src/diagnostics.rs | 2 - src/eval.rs | 5 +- src/helpers.rs | 2 - src/intptrcast.rs | 1 - src/lib.rs | 2 + src/operator.rs | 2 - src/shims/foreign_items.rs | 2 - src/shims/intrinsics/mod.rs | 2 - src/shims/panic.rs | 2 - src/shims/tls.rs | 2 - src/shims/unix/foreign_items.rs | 2 - src/shims/unix/fs.rs | 2 - 23 files changed, 27 insertions(+), 108 deletions(-) diff --git a/CONTRIBUTING.md b/CONTRIBUTING.md index 7a49ff3372..f2f3a642e0 100644 --- a/CONTRIBUTING.md +++ b/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 diff --git a/Cargo.lock b/Cargo.lock index 8cd996d856..87dc51bd61 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -273,19 +273,6 @@ version = "0.3.6" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "a357d28ed41a50f9c765dbfe56cbc04a64e53e5fc58ba79fbc34c10ef3df831f" -[[package]] -name = "env_logger" -version = "0.10.1" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "95b3f3e67048839cb0d0781f445682a35113da7121f7c949db0e2be96a4fbece" -dependencies = [ - "humantime", - "is-terminal", - "log", - "regex", - "termcolor", -] - [[package]] name = "errno" version = "0.3.8" @@ -339,18 +326,6 @@ version = "0.28.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "4271d37baee1b8c7e4b708028c57d816cf9d2434acb33a549475f78c181f6253" -[[package]] -name = "hermit-abi" -version = "0.3.3" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "d77f7ec81a6d05a3abb01ab6eb7590f6083d08449fe5a1c8b1e620283546ccb7" - -[[package]] -name = "humantime" -version = "2.1.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "9a3a5bfb195931eeb336b2a7b4d761daec841b97f947d34394601737a7bba5e4" - [[package]] name = "indenter" version = "0.3.3" @@ -388,17 +363,6 @@ dependencies = [ "cfg-if", ] -[[package]] -name = "is-terminal" -version = "0.4.10" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "0bad00257d07be169d870ab665980b06cdb366d792ad690bf2e76876dc503455" -dependencies = [ - "hermit-abi", - "rustix", - "windows-sys 0.52.0", -] - [[package]] name = "itoa" version = "1.0.10" @@ -529,14 +493,12 @@ dependencies = [ "aes", "colored", "ctrlc", - "env_logger", "getrandom", "jemalloc-sys", "lazy_static", "libc", "libffi", "libloading", - "log", "measureme", "rand", "regex", @@ -875,15 +837,6 @@ dependencies = [ "windows-sys 0.52.0", ] -[[package]] -name = "termcolor" -version = "1.4.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "ff1bc3d3f05aff0403e8ac0d92ced918ec05b666a43f83297ccef5bea8a3d449" -dependencies = [ - "winapi-util", -] - [[package]] name = "thiserror" version = "1.0.56" @@ -1034,15 +987,6 @@ version = "0.4.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ac3b87c63620426dd9b991e5ce0329eff545bccbbb34f3be09ff6fb6ab51b7b6" -[[package]] -name = "winapi-util" -version = "0.1.6" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "f29e6f9198ba0d26b4c9f07dbe6f9ed633e1f3d5b8b414090084349e46a52596" -dependencies = [ - "winapi", -] - [[package]] name = "winapi-x86_64-pc-windows-gnu" version = "0.4.0" diff --git a/Cargo.toml b/Cargo.toml index a65010b055..39122c847c 100644 --- a/Cargo.toml +++ b/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"] } diff --git a/src/bin/miri.rs b/src/bin/miri.rs index e8e10f64ad..c78444fa94 100644 --- a/src/bin/miri.rs +++ b/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. diff --git a/src/borrow_tracker/mod.rs b/src/borrow_tracker/mod.rs index 74ff6ed4e0..c5cd78ad66 100644 --- a/src/borrow_tracker/mod.rs +++ b/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}; diff --git a/src/borrow_tracker/stacked_borrows/mod.rs b/src/borrow_tracker/stacked_borrows/mod.rs index 7740d383ee..0fe422180f 100644 --- a/src/borrow_tracker/stacked_borrows/mod.rs +++ b/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}; diff --git a/src/borrow_tracker/stacked_borrows/stack.rs b/src/borrow_tracker/stacked_borrows/stack.rs index 291807c25e..712c26a9af 100644 --- a/src/borrow_tracker/stacked_borrows/stack.rs +++ b/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. diff --git a/src/borrow_tracker/tree_borrows/mod.rs b/src/borrow_tracker/tree_borrows/mod.rs index 0945a5292b..cc98286534 100644 --- a/src/borrow_tracker/tree_borrows/mod.rs +++ b/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}; diff --git a/src/concurrency/data_race.rs b/src/concurrency/data_race.rs index 80d0402fc8..a280448ae0 100644 --- a/src/concurrency/data_race.rs +++ b/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 { - 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); diff --git a/src/concurrency/sync.rs b/src/concurrency/sync.rs index b288b69e0c..42b9161afd 100644 --- a/src/concurrency/sync.rs +++ b/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; diff --git a/src/concurrency/thread.rs b/src/concurrency/thread.rs index 754cfa4d2a..64e1f3c5b5 100644 --- a/src/concurrency/thread.rs +++ b/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; diff --git a/src/diagnostics.rs b/src/diagnostics.rs index bf3284df59..7565bb580f 100644 --- a/src/diagnostics.rs +++ b/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}; diff --git a/src/eval.rs b/src/eval.rs index 6095b8842e..9bab9488e3 100644 --- a/src/eval.rs +++ b/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; diff --git a/src/helpers.rs b/src/helpers.rs index d6b1e13580..932a35d9bf 100644 --- a/src/helpers.rs +++ b/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}; diff --git a/src/intptrcast.rs b/src/intptrcast.rs index 68c9a7660e..3fe127f973 100644 --- a/src/intptrcast.rs +++ b/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}; diff --git a/src/lib.rs b/src/lib.rs index 057b883a3b..6fbf28a752 100644 --- a/src/lib.rs +++ b/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. diff --git a/src/operator.rs b/src/operator.rs index 6f19dead2e..d99be39177 100644 --- a/src/operator.rs +++ b/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; diff --git a/src/shims/foreign_items.rs b/src/shims/foreign_items.rs index a002f2aad0..dd3e8efb6e 100644 --- a/src/shims/foreign_items.rs +++ b/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::{ diff --git a/src/shims/intrinsics/mod.rs b/src/shims/intrinsics/mod.rs index e34fb118f7..7a5a079c1c 100644 --- a/src/shims/intrinsics/mod.rs +++ b/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; diff --git a/src/shims/panic.rs b/src/shims/panic.rs index 28652c25c2..4c054d8dc8 100644 --- a/src/shims/panic.rs +++ b/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; diff --git a/src/shims/tls.rs b/src/shims/tls.rs index b319516c25..84c1feb88e 100644 --- a/src/shims/tls.rs +++ b/src/shims/tls.rs @@ -4,8 +4,6 @@ use std::collections::btree_map::Entry as BTreeEntry; use std::collections::BTreeMap; use std::task::Poll; -use log::trace; - use rustc_middle::ty; use rustc_target::abi::{HasDataLayout, Size}; use rustc_target::spec::abi::Abi; diff --git a/src/shims/unix/foreign_items.rs b/src/shims/unix/foreign_items.rs index 35036ce078..30c1fe7add 100644 --- a/src/shims/unix/foreign_items.rs +++ b/src/shims/unix/foreign_items.rs @@ -1,8 +1,6 @@ use std::ffi::OsStr; use std::str; -use log::trace; - use rustc_middle::ty::layout::LayoutOf; use rustc_span::Symbol; use rustc_target::abi::{Align, Size}; diff --git a/src/shims/unix/fs.rs b/src/shims/unix/fs.rs index 53f975baa8..b141ca4a01 100644 --- a/src/shims/unix/fs.rs +++ b/src/shims/unix/fs.rs @@ -8,8 +8,6 @@ use std::io::{self, ErrorKind, IsTerminal, Read, Seek, SeekFrom, Write}; use std::path::{Path, PathBuf}; use std::time::SystemTime; -use log::trace; - use rustc_data_structures::fx::FxHashMap; use rustc_middle::ty::TyCtxt; use rustc_target::abi::Size;