Miri engine logging: strange log tail after interpreter failure

[RalfJung]

When the interpreter quits with an error, there are some strange messages being printed after the error:

2:rustc├─20ms  INFO rustc_mir::interpret::step StorageLive(_10)
2:rustc├─20ms  INFO rustc_mir::interpret::step _10 = &mut (*_2)
2:rustc├─20ms  INFO rustc_mir::interpret::step Retag(_10)
error: Undefined Behavior: trying to reborrow for Unique, but parent tag <3901> does not have an appropriate item in the borrow stack
  --> tests/run-pass/box.rs:18:6
   |
18 |     *(&mut *r) = 17;
   |      ^^^^^^^^^ trying to reborrow for Unique, but parent tag <3901> does not have an appropriate item in the borrow stack
   |
   = help: this indicates a potential bug in the program: it performed an invalid operation, but the rules it violated are still experimental
   = help: see https://github.com/rust-lang/unsafe-code-guidelines/blob/master/wip/stacked-borrows.md for further information
           
   = note: inside `into_raw` at tests/run-pass/box.rs:18:6
note: inside `main` at tests/run-pass/box.rs:4:5
  --> tests/run-pass/box.rs:4:5
   |
4  |     into_raw();
   |     ^^^^^^^^^^
   = note: inside `<fn() as std::ops::FnOnce<()>>::call_once - shim(fn())` at /home/r/.rustup/toolchains/miri/lib/rustlib/src/rust/library/core/src/ops/function.rs:227:5
   = note: inside `std::sys_common::backtrace::__rust_begin_short_backtrace::<fn(), ()>` at /home/r/.rustup/toolchains/miri/lib/rustlib/src/rust/library/std/src/sys_common/backtrace.rs:125:18
   = note: inside closure at /home/r/.rustup/toolchains/miri/lib/rustlib/src/rust/library/std/src/rt.rs:66:18
   = note: inside `std::ops::function::impls::<impl std::ops::FnOnce<()> for &dyn std::ops::Fn() -> i32 + std::marker::Sync + std::panic::RefUnwindSafe>::call_once` at /home/r/.rustup/toolchains/miri/lib/rustlib/src/rust/library/core/src/ops/function.rs:259:13
   = note: inside `std::panicking::try::do_call::<&dyn std::ops::Fn() -> i32 + std::marker::Sync + std::panic::RefUnwindSafe, i32>` at /home/r/.rustup/toolchains/miri/lib/rustlib/src/rust/library/std/src/panicking.rs:381:40
   = note: inside `std::panicking::try::<i32, &dyn std::ops::Fn() -> i32 + std::marker::Sync + std::panic::RefUnwindSafe>` at /home/r/.rustup/toolchains/miri/lib/rustlib/src/rust/library/std/src/panicking.rs:345:19
   = note: inside `std::panic::catch_unwind::<&dyn std::ops::Fn() -> i32 + std::marker::Sync + std::panic::RefUnwindSafe, i32>` at /home/r/.rustup/toolchains/miri/lib/rustlib/src/rust/library/std/src/panic.rs:382:14
   = note: inside `std::rt::lang_start_internal` at /home/r/.rustup/toolchains/miri/lib/rustlib/src/rust/library/std/src/rt.rs:51:25
   = note: inside `std::rt::lang_start::<()>` at /home/r/.rustup/toolchains/miri/lib/rustlib/src/rust/library/std/src/rt.rs:65:5

2:rustc│┌┘rustc_mir::interpret::eval_context::frame std::rt::lang_start::<()>
2:rustc├┘rustc_mir::interpret::eval_context::frame into_raw
2:rustc│┌┘rustc_mir::interpret::eval_context::frame std::rt::lang_start_internal
2:rustc├┘rustc_mir::interpret::eval_context::frame into_raw
2:rustc│┌┘rustc_mir::interpret::eval_context::frame std::panic::catch_unwind::<&dyn std::ops::Fn() -> i32 + std::marker::Sync + std::panic::RefUnwindSafe, i32>
2:rustc├┘rustc_mir::interpret::eval_context::frame into_raw
2:rustc│┌┘rustc_mir::interpret::eval_context::frame std::panicking::try::<i32, &dyn std::ops::Fn() -> i32 + std::marker::Sync + std::panic::RefUnwindSafe>
2:rustc├┘rustc_mir::interpret::eval_context::frame into_raw
2:rustc│┌┘rustc_mir::interpret::eval_context::frame std::panicking::try::do_call::<&dyn std::ops::Fn() -> i32 + std::marker::Sync + std::panic::RefUnwindSafe, i32>
2:rustc├┘rustc_mir::interpret::eval_context::frame into_raw
2:rustc│┌┘rustc_mir::interpret::eval_context::frame std::ops::function::impls::<impl std::ops::FnOnce<()> for &dyn std::ops::Fn() -> i32 + std::marker::Sync + std::panic::RefUnwindSafe>::call_once
2:rustc├┘rustc_mir::interpret::eval_context::frame into_raw
2:rustc│┌┘rustc_mir::interpret::eval_context::frame std::rt::lang_start::<()>::{closure#0}
2:rustc├┘rustc_mir::interpret::eval_context::frame into_raw
2:rustc│┌┘rustc_mir::interpret::eval_context::frame std::sys_common::backtrace::__rust_begin_short_backtrace::<fn(), ()>
2:rustc├┘rustc_mir::interpret::eval_context::frame into_raw
2:rustc│┌┘rustc_mir::interpret::eval_context::frame <fn() as std::ops::FnOnce<()>>::call_once - shim(fn())
2:rustc├┘rustc_mir::interpret::eval_context::frame into_raw
2:rustc│┌┘rustc_mir::interpret::eval_context::frame main
2:rustc├┘rustc_mir::interpret::eval_context::frame into_raw
2:rustcrustc_mir::interpret::eval_context::frame into_raw
error: aborting due to previous error

Likely this is because the remaining stackframes are dropped when the interpreter is torn down, but those frames are not actually popped so this should not be logged. Also indentation seems to be completely broken at this point.

Cc @oli-obk

[oli-obk]

oh... yea I think the indentation problem is because they are dropped in the reverse order than how they should get pushed.

I think these should still get logged, as their scope must get removed, which is an independent thing from popping stack frames. We are leaving those frames, even if we aren't unwinding or returning in order to do so.

[RalfJung]

That seems very strange, it'll just be noise at the bottom of the log (below the error).

Also in that case we certainly need a was to distinguish "leaving the scope" from "returning/unwinding from the function".

[oli-obk]

we can invoke a debug!("leaving function's scope due to error") just before doing that in each frame. Other than that... I can try to figure out whether we can silently leave a scope by temporarily overwriting the logger. But shouldn't the large error message at the top also convey this?

A miri-only solution may be the best way to go forward here. Basically we'll disable the logger, drop the stack, reenable the logger.

[RalfJung]

Basically we'll disable the logger, drop the stack, reenable the logger.

That seems like quite the hack. :/

[oli-obk]

well... anything we do will be a different level of hacky.

• We can leak the scopes, which only works for miri because it shuts down after execution, so acting as if we are still in those scopes is fine, but rustc can't do that.
• We can disable the logger as already suggested.
• We can find the scopes and overwrite their message (not sure that is possible right now with tracing)
• We can emit a debug! message before dropping the scope to mention why we are dropping it here (so we still see the messages).
• We can overwrite the verbose_span_exit flag in tracing_tree instead of disabling the logger

The concept of sometimes destroying a span without letting the logger know you are exiting it does not exist in tracing afaict. The closest I found was https://docs.rs/tracing/0.1.21/tracing/trait.Subscriber.html#method.try_close but I still think that will end up signalling a span exit.

[RalfJung]

Cc @hawkw -- do you have any other ideas?