Print hex dump of alloc on reading undef bytes #1354

divergentdave · 2020-04-22T02:38:53Z

Here's a small addition I made locally to the UB diagnostics, in case you're interested in it. This PR calls dump_alloc() on the relevant allocation if Miri fails on UB due to reading undefined bytes. This came in handy when diagnosing such an issue in a large program using unsafe Rust, in part because it wasn't deterministic enough to use -Zmiri-track-alloc-id=. If you'd like to put this behind another -Z flag, let me know.

RalfJung · 2020-04-22T07:16:12Z

Could you copy-paste an example output here so I can get a feeling for what this error looks like?

src/diagnostics.rs

divergentdave · 2020-04-22T12:46:01Z

Here's the output as-is

Console output

running 6 tests
test log_aborts ... ok
test log_chunky_iterator ... ignored
test log_writebatch ... ok
alloc35240871 (Rust heap, size: 128, align: 8192) {
    0x00 │ ff ba c7 0f ff ff ff ff ff ff ff 7f 00 00 00 00 │ ................
    0x10 │ 00 00 00 80 12 86 f0 18 07 08 00 00 14 00 00 00 │ ................
    0x20 │ 00 00 00 00 b3 f7 01 9b 09 08 00 01 24 00 00 00 │ ............$...
    0x30 │ 00 00 00 00 f5 4b 10 0e 09 08 00 02 34 00 00 00 │ .....K......4...
    0x40 │ 00 00 00 00 97 fa 5d 5d 09 08 00 03 44 00 00 00 │ ......]]....D...
    0x50 │ 00 00 00 00 e2 31 93 28 07 08 00 00 54 00 00 00 │ .....1.(....T...
    0x60 │ 00 00 00 00 __ __ __ __ __ __ __ __ __ __ __ __ │ ....░░░░░░░░░░░░
    0x70 │ __ __ __ __ __ __ __ __ __ __ __ __ __ __ __ __ │ ░░░░░░░░░░░░░░░░
}
error: Undefined Behavior: reading uninitialized memory at alloc35240871+64, but this operation requires initialized memory
   --> /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libstd/sys/unix/fd.rs:103:13
    |
103 |             libc::write(self.fd, buf.as_ptr() as *const c_void, cmp::min(buf.len(), max_len()))
    |             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ reading uninitialized memory at alloc35240871+64, but this operation requires initialized memory
    |
    = help: this indicates a bug in the program: it performed an invalid operation, and caused Undefined Behavior
    = help: see https://doc.rust-lang.org/nightly/reference/behavior-considered-undefined.html for further information
            
    = note: inside `std::sys::unix::fd::FileDesc::write` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libstd/sys/unix/fd.rs:103:13
    = note: inside `std::sys::unix::fs::File::write` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libstd/sys/unix/fs.rs:836:9
    = note: inside `<std::fs::File as std::io::Write>::write` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libstd/fs.rs:670:9
    = note: inside `sled::pagecache::parallel_io_polyfill::pwrite_all` at /home/david/Code/sled/src/pagecache/parallel_io_polyfill.rs:88:15
    = note: inside `sled::pagecache::iobuf::IoBufs::write_to_log` at /home/david/Code/sled/src/pagecache/iobuf.rs:664:13
    = note: inside closure at /home/david/Code/sled/src/pagecache/iobuf.rs:1096:29
    = note: inside `sled::threadpool::spawn::<[closure@sled::pagecache::iobuf::maybe_seal_and_write_iobuf::{{closure}}#3 0:std::sync::Arc<sled::pagecache::iobuf::IoBufs>, 1:std::sync::Arc<sled::pagecache::iobuf::IoBuf>, 2:i64], ()>` at /home/david/Code/sled/src/lib.rs:224:29
    = note: inside `sled::pagecache::iobuf::maybe_seal_and_write_iobuf` at /home/david/Code/sled/src/pagecache/iobuf.rs:1095:23
    = note: inside `sled::pagecache::iobuf::make_stable` at /home/david/Code/sled/src/pagecache/iobuf.rs:856:13
    = note: inside `sled::pagecache::iobuf::flush` at /home/david/Code/sled/src/pagecache/iobuf.rs:910:5
    = note: inside `sled::pagecache::logger::Log::flush` at /home/david/Code/sled/src/pagecache/logger.rs:38:9
    = note: inside `sled::pagecache::PageCache::flush` at /home/david/Code/sled/src/pagecache/mod.rs:657:9
    = note: inside `<sled::context::Context as std::ops::Drop>::drop` at /home/david/Code/sled/src/context.rs:34:19
    = note: inside `std::intrinsics::drop_in_place::<sled::context::Context> - shim(Some(sled::context::Context))` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libcore/ptr/mod.rs:177:1
    = note: inside `sled::db::Db::start_inner` at /home/david/Code/sled/src/db.rs:130:5
    = note: inside `sled::config::Config::open` at /home/david/Code/sled/src/config.rs:371:9
note: inside `more_log_reservations_than_buffers` at tests/test_log.rs:62:14
   --> tests/test_log.rs:62:14
    |
62  |     let db = config.open()?;
    |              ^^^^^^^^^^^^^
note: inside closure at tests/test_log.rs:59:1
   --> tests/test_log.rs:59:1
    |
59  | / fn more_log_reservations_than_buffers() -> Result<()> {
60  | |     let config = Config::new().temporary(true).segment_size(128);
61  | |
62  | |     let db = config.open()?;
...   |
83  | |     Ok(())
84  | | }
    | |_^
    = note: inside `<[closure@tests/test_log.rs:59:1: 84:2] as std::ops::FnOnce<()>>::call_once - shim` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libcore/ops/function.rs:232:5
    = note: inside `<fn() as std::ops::FnOnce<()>>::call_once - shim(fn())` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libcore/ops/function.rs:232:5
    = note: inside `test::__rust_begin_short_backtrace::<fn()>` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libtest/lib.rs:517:5
    = note: inside closure at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libtest/lib.rs:508:30
    = note: inside `<[closure@test::run_test::{{closure}}#2 0:fn()] as std::ops::FnOnce<()>>::call_once - shim(vtable)` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libcore/ops/function.rs:232:5
    = note: inside `<std::boxed::Box<dyn std::ops::FnOnce() + std::marker::Send> as std::ops::FnOnce<()>>::call_once` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/liballoc/boxed.rs:1008:9
    = note: inside `<std::panic::AssertUnwindSafe<std::boxed::Box<dyn std::ops::FnOnce() + std::marker::Send>> as std::ops::FnOnce<()>>::call_once` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libstd/panic.rs:318:9
    = note: inside `std::panicking::r#try::do_call::<std::panic::AssertUnwindSafe<std::boxed::Box<dyn std::ops::FnOnce() + std::marker::Send>>, ()>` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libstd/panicking.rs:331:40
    = note: inside `std::panicking::r#try::<(), std::panic::AssertUnwindSafe<std::boxed::Box<dyn std::ops::FnOnce() + std::marker::Send>>>` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libstd/panicking.rs:274:15
    = note: inside `std::panic::catch_unwind::<std::panic::AssertUnwindSafe<std::boxed::Box<dyn std::ops::FnOnce() + std::marker::Send>>, ()>` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libstd/panic.rs:394:14
    = note: inside `test::run_test_in_process` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libtest/lib.rs:541:18
    = note: inside closure at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libtest/lib.rs:450:39
    = note: inside `test::run_test::run_test_inner` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libtest/lib.rs:475:13
    = note: inside `test::run_test` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libtest/lib.rs:505:28
    = note: inside `test::run_tests::<[closure@test::run_tests_console::{{closure}}#2 0:&mut test::console::ConsoleTestState, 1:&mut std::boxed::Box<dyn test::formatters::OutputFormatter>]>` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libtest/lib.rs:284:13
    = note: inside `test::run_tests_console` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libtest/console.rs:280:5
    = note: inside `test::test_main` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libtest/lib.rs:120:15
    = note: inside `test::test_main_static` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libtest/lib.rs:139:5
    = note: inside `main`
    = note: inside closure at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libstd/rt.rs:67:34
    = note: inside closure at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libstd/rt.rs:52:73
    = note: inside `std::sys_common::backtrace::__rust_begin_short_backtrace::<[closure@std::rt::lang_start_internal::{{closure}}#0::{{closure}}#0 0:&dyn std::ops::Fn() -> i32 + std::marker::Sync + std::panic::RefUnwindSafe], i32>` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libstd/sys_common/backtrace.rs:130:5
    = note: inside closure at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libstd/rt.rs:52:13
    = note: inside `std::panicking::r#try::do_call::<[closure@std::rt::lang_start_internal::{{closure}}#0 0:&&dyn std::ops::Fn() -> i32 + std::marker::Sync + std::panic::RefUnwindSafe], i32>` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libstd/panicking.rs:331:40
    = note: inside `std::panicking::r#try::<i32, [closure@std::rt::lang_start_internal::{{closure}}#0 0:&&dyn std::ops::Fn() -> i32 + std::marker::Sync + std::panic::RefUnwindSafe]>` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libstd/panicking.rs:274:15
    = note: inside `std::panic::catch_unwind::<[closure@std::rt::lang_start_internal::{{closure}}#0 0:&&dyn std::ops::Fn() -> i32 + std::marker::Sync + std::panic::RefUnwindSafe], i32>` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libstd/panic.rs:394:14
    = note: inside `std::rt::lang_start_internal` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libstd/rt.rs:51:25
    = note: inside `std::rt::lang_start::<()>` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libstd/rt.rs:67:5
    = note: this error originates in an attribute macro (in Nightly builds, run with -Z macro-backtrace for more info)

error: aborting due to previous error

test more_log_reservations_than_buffers ... 
error: could not compile `sled`.

To learn more, run the command again with --verbose.

RalfJung · 2020-04-22T21:18:53Z

Hm I see. Nice start, but I think we can do better. :D

So I think reordering this as I suggested above doesn't make the output worse, and it helps code structure, so IMO we should go with that.

Also, given that the allocation dump prints offsets in hex, we should also show the offset in hex, so the user does not have to do that conversion themselves. But it almost looks like +64 is already hex, just not with a 0x prefix? That's weird... (EDIT: no that should be decimal.)

Later it might be nice to point to the right spot in that dump, but that's not a must-have.

divergentdave · 2020-04-22T23:18:46Z

I swapped the order, here's what it looks like now.

Output

running 1 test
error: Undefined Behavior: reading uninitialized memory at alloc35122748+64, but this operation requires initialized memory
   --> /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libstd/sys/unix/fd.rs:103:13
    |
103 |             libc::write(self.fd, buf.as_ptr() as *const c_void, cmp::min(buf.len(), max_len()))
    |             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ reading uninitialized memory at alloc35122748+64, but this operation requires initialized memory
    |
    = help: this indicates a bug in the program: it performed an invalid operation, and caused Undefined Behavior
    = help: see https://doc.rust-lang.org/nightly/reference/behavior-considered-undefined.html for further information
            
    = note: inside `std::sys::unix::fd::FileDesc::write` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libstd/sys/unix/fd.rs:103:13
    = note: inside `std::sys::unix::fs::File::write` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libstd/sys/unix/fs.rs:836:9
    = note: inside `<std::fs::File as std::io::Write>::write` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libstd/fs.rs:670:9
    = note: inside `sled::pagecache::parallel_io_polyfill::pwrite_all` at /home/david/Code/sled/src/pagecache/parallel_io_polyfill.rs:88:15
    = note: inside `sled::pagecache::iobuf::IoBufs::write_to_log` at /home/david/Code/sled/src/pagecache/iobuf.rs:664:13
    = note: inside closure at /home/david/Code/sled/src/pagecache/iobuf.rs:1096:29
    = note: inside `sled::threadpool::spawn::<[closure@sled::pagecache::iobuf::maybe_seal_and_write_iobuf::{{closure}}#3 0:std::sync::Arc<sled::pagecache::iobuf::IoBufs>, 1:std::sync::Arc<sled::pagecache::iobuf::IoBuf>, 2:i64], ()>` at /home/david/Code/sled/src/lib.rs:224:29
    = note: inside `sled::pagecache::iobuf::maybe_seal_and_write_iobuf` at /home/david/Code/sled/src/pagecache/iobuf.rs:1095:23
    = note: inside `sled::pagecache::iobuf::make_stable` at /home/david/Code/sled/src/pagecache/iobuf.rs:856:13
    = note: inside `sled::pagecache::iobuf::flush` at /home/david/Code/sled/src/pagecache/iobuf.rs:910:5
    = note: inside `sled::pagecache::logger::Log::flush` at /home/david/Code/sled/src/pagecache/logger.rs:38:9
    = note: inside `sled::pagecache::PageCache::flush` at /home/david/Code/sled/src/pagecache/mod.rs:657:9
    = note: inside `<sled::context::Context as std::ops::Drop>::drop` at /home/david/Code/sled/src/context.rs:34:19
    = note: inside `std::intrinsics::drop_in_place::<sled::context::Context> - shim(Some(sled::context::Context))` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libcore/ptr/mod.rs:177:1
    = note: inside `sled::db::Db::start_inner` at /home/david/Code/sled/src/db.rs:130:5
    = note: inside `sled::config::Config::open` at /home/david/Code/sled/src/config.rs:371:9
note: inside `more_log_reservations_than_buffers` at tests/test_log.rs:62:14
   --> tests/test_log.rs:62:14
    |
62  |     let db = config.open()?;
    |              ^^^^^^^^^^^^^
note: inside closure at tests/test_log.rs:59:1
   --> tests/test_log.rs:59:1
    |
59  | / fn more_log_reservations_than_buffers() -> Result<()> {
60  | |     let config = Config::new().temporary(true).segment_size(128);
61  | |
62  | |     let db = config.open()?;
...   |
83  | |     Ok(())
84  | | }
    | |_^
    = note: inside `<[closure@tests/test_log.rs:59:1: 84:2] as std::ops::FnOnce<()>>::call_once - shim` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libcore/ops/function.rs:232:5
    = note: inside `<fn() as std::ops::FnOnce<()>>::call_once - shim(fn())` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libcore/ops/function.rs:232:5
    = note: inside `test::__rust_begin_short_backtrace::<fn()>` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libtest/lib.rs:517:5
    = note: inside closure at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libtest/lib.rs:508:30
    = note: inside `<[closure@test::run_test::{{closure}}#2 0:fn()] as std::ops::FnOnce<()>>::call_once - shim(vtable)` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libcore/ops/function.rs:232:5
    = note: inside `<std::boxed::Box<dyn std::ops::FnOnce() + std::marker::Send> as std::ops::FnOnce<()>>::call_once` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/liballoc/boxed.rs:1008:9
    = note: inside `<std::panic::AssertUnwindSafe<std::boxed::Box<dyn std::ops::FnOnce() + std::marker::Send>> as std::ops::FnOnce<()>>::call_once` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libstd/panic.rs:318:9
    = note: inside `std::panicking::r#try::do_call::<std::panic::AssertUnwindSafe<std::boxed::Box<dyn std::ops::FnOnce() + std::marker::Send>>, ()>` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libstd/panicking.rs:331:40
    = note: inside `std::panicking::r#try::<(), std::panic::AssertUnwindSafe<std::boxed::Box<dyn std::ops::FnOnce() + std::marker::Send>>>` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libstd/panicking.rs:274:15
    = note: inside `std::panic::catch_unwind::<std::panic::AssertUnwindSafe<std::boxed::Box<dyn std::ops::FnOnce() + std::marker::Send>>, ()>` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libstd/panic.rs:394:14
    = note: inside `test::run_test_in_process` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libtest/lib.rs:541:18
    = note: inside closure at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libtest/lib.rs:450:39
    = note: inside `test::run_test::run_test_inner` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libtest/lib.rs:475:13
    = note: inside `test::run_test` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libtest/lib.rs:505:28
    = note: inside `test::run_tests::<[closure@test::run_tests_console::{{closure}}#2 0:&mut test::console::ConsoleTestState, 1:&mut std::boxed::Box<dyn test::formatters::OutputFormatter>]>` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libtest/lib.rs:284:13
    = note: inside `test::run_tests_console` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libtest/console.rs:280:5
    = note: inside `test::test_main` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libtest/lib.rs:120:15
    = note: inside `test::test_main_static` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libtest/lib.rs:139:5
    = note: inside `main`
    = note: inside closure at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libstd/rt.rs:67:34
    = note: inside closure at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libstd/rt.rs:52:73
    = note: inside `std::sys_common::backtrace::__rust_begin_short_backtrace::<[closure@std::rt::lang_start_internal::{{closure}}#0::{{closure}}#0 0:&dyn std::ops::Fn() -> i32 + std::marker::Sync + std::panic::RefUnwindSafe], i32>` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libstd/sys_common/backtrace.rs:130:5
    = note: inside closure at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libstd/rt.rs:52:13
    = note: inside `std::panicking::r#try::do_call::<[closure@std::rt::lang_start_internal::{{closure}}#0 0:&&dyn std::ops::Fn() -> i32 + std::marker::Sync + std::panic::RefUnwindSafe], i32>` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libstd/panicking.rs:331:40
    = note: inside `std::panicking::r#try::<i32, [closure@std::rt::lang_start_internal::{{closure}}#0 0:&&dyn std::ops::Fn() -> i32 + std::marker::Sync + std::panic::RefUnwindSafe]>` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libstd/panicking.rs:274:15
    = note: inside `std::panic::catch_unwind::<[closure@std::rt::lang_start_internal::{{closure}}#0 0:&&dyn std::ops::Fn() -> i32 + std::marker::Sync + std::panic::RefUnwindSafe], i32>` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libstd/panic.rs:394:14
    = note: inside `std::rt::lang_start_internal` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libstd/rt.rs:51:25
    = note: inside `std::rt::lang_start::<()>` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libstd/rt.rs:67:5
    = note: this error originates in an attribute macro (in Nightly builds, run with -Z macro-backtrace for more info)

alloc35122748 (Rust heap, size: 128, align: 8192) {
    0x00 │ ff ba c7 0f ff ff ff ff ff ff ff 7f 00 00 00 00 │ ................
    0x10 │ 00 00 00 80 12 86 f0 18 07 08 00 00 14 00 00 00 │ ................
    0x20 │ 00 00 00 00 b3 f7 01 9b 09 08 00 01 24 00 00 00 │ ............$...
    0x30 │ 00 00 00 00 f5 4b 10 0e 09 08 00 02 34 00 00 00 │ .....K......4...
    0x40 │ 00 00 00 00 97 fa 5d 5d 09 08 00 03 44 00 00 00 │ ......]]....D...
    0x50 │ 00 00 00 00 e2 31 93 28 07 08 00 00 54 00 00 00 │ .....1.(....T...
    0x60 │ 00 00 00 00 __ __ __ __ __ __ __ __ __ __ __ __ │ ....░░░░░░░░░░░░
    0x70 │ __ __ __ __ __ __ __ __ __ __ __ __ __ __ __ __ │ ░░░░░░░░░░░░░░░░
}
error: aborting due to previous error

test more_log_reservations_than_buffers ... 
error: could not compile `sled`.

To learn more, run the command again with --verbose.

That offset is in hexadecimal, it's formatted by this https://github.com/rust-lang/rust/blob/b2e36e6c2d229126b59e892c9147fbb68115d292/src/librustc_middle/mir/interpret/pointer.rs#L122-L132. I can submit a PR to add a leading "0x" over there.

RalfJung · 2020-04-23T07:06:00Z

I can submit a PR to add a leading "0x" over there.

Yes please do.

I swapped the order, here's what it looks like now.

Great!
Now could you please add a line of text about the alloc dump explaining what we are seeing? I am imagining something like

Uninitialized read occurred at offset 0x?? into this allocation:
alloc35122748 (Rust heap, size: 128, align: 8192) {
    0x00 │ ff ba c7 0f ff ff ff ff ff ff ff 7f 00 00 00 00 │ ................
    0x10 │ 00 00 00 80 12 86 f0 18 07 08 00 00 14 00 00 00 │ ................
    0x20 │ 00 00 00 00 b3 f7 01 9b 09 08 00 01 24 00 00 00 │ ............$...
    0x30 │ 00 00 00 00 f5 4b 10 0e 09 08 00 02 34 00 00 00 │ .....K......4...
    0x40 │ 00 00 00 00 97 fa 5d 5d 09 08 00 03 44 00 00 00 │ ......]]....D...
    0x50 │ 00 00 00 00 e2 31 93 28 07 08 00 00 54 00 00 00 │ .....1.(....T...
    0x60 │ 00 00 00 00 __ __ __ __ __ __ __ __ __ __ __ __ │ ....░░░░░░░░░░░░
    0x70 │ __ __ __ __ __ __ __ __ __ __ __ __ __ __ __ __ │ ░░░░░░░░░░░░░░░░
}

Do you think that would be useful? Suggestions welcome.

In the future I think it'd be nice to give not just the start offset but also the end offset. That will require tracking the access size in InvalidUndefBytes. Do you want o make a PR for that? (I can also add it to my list.)

@RalfJung

…RalfJung Add leading 0x to offset in Debug fmt of Pointer Currently the `Debug` format for `Pointer` prints its offset in hexadecimal, for example, `alloc38657819+e2` or `alloc35122748+64`. This PR adds a leading `0x` to the offset, in order to make it apparent that it is indeed a hexadecimal number. This came up during discussion of rust-lang/miri#1354. r? @RalfJung

@RalfJung

…RalfJung Add leading 0x to offset in Debug fmt of Pointer Currently the `Debug` format for `Pointer` prints its offset in hexadecimal, for example, `alloc38657819+e2` or `alloc35122748+64`. This PR adds a leading `0x` to the offset, in order to make it apparent that it is indeed a hexadecimal number. This came up during discussion of rust-lang/miri#1354. r? @RalfJung

divergentdave · 2020-04-24T01:10:07Z

OK, added the explanatory message and added a compile-fail test that exercises it. Output:

$ ./miri run tests/compile-fail/undefined_buffer.rs 
    Finished release [optimized] target(s) in 0.04s
    Finished release [optimized] target(s) in 0.04s
     Running `target/release/cargo-miri miri setup`
A libstd for Miri is now available in `/home/david/.cache/miri/HOST`.
    Finished release [optimized] target(s) in 0.04s
     Running `target/release/miri --sysroot /home/david/.cache/miri/HOST tests/compile-fail/undefined_buffer.rs`
error: Undefined Behavior: reading uninitialized memory at alloc1421+4, but this operation requires initialized memory
    --> /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libcore/slice/mod.rs:5968:22
     |
5968 |             unsafe { memcmp(left.as_ptr(), right.as_ptr(), cmp::min(left.len(), right.len())) };
     |                      ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ reading uninitialized memory at alloc1421+4, but this operation requires initialized memory
     |
     = help: this indicates a bug in the program: it performed an invalid operation, and caused Undefined Behavior
     = help: see https://doc.rust-lang.org/nightly/reference/behavior-considered-undefined.html for further information
             
     = note: inside `<u8 as core::slice::SliceOrd>::compare` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libcore/slice/mod.rs:5968:22
     = note: inside `core::slice::<impl std::cmp::Ord for [u8]>::cmp` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libcore/slice/mod.rs:5800:9
note: inside `main` at tests/compile-fail/undefined_buffer.rs:17:14
    --> tests/compile-fail/undefined_buffer.rs:17:14
     |
17   |         drop(slice1.cmp(slice2));
     |              ^^^^^^^^^^^^^^^^^^
     = note: inside closure at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libstd/rt.rs:67:34
     = note: inside closure at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libstd/rt.rs:52:73
     = note: inside `std::sys_common::backtrace::__rust_begin_short_backtrace::<[closure@std::rt::lang_start_internal::{{closure}}#0::{{closure}}#0 0:&dyn std::ops::Fn() -> i32 + std::marker::Sync + std::panic::RefUnwindSafe], i32>` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libstd/sys_common/backtrace.rs:130:5
     = note: inside closure at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libstd/rt.rs:52:13
     = note: inside `std::panicking::try::do_call::<[closure@std::rt::lang_start_internal::{{closure}}#0 0:&&dyn std::ops::Fn() -> i32 + std::marker::Sync + std::panic::RefUnwindSafe], i32>` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libstd/panicking.rs:331:40
     = note: inside `std::panicking::try::<i32, [closure@std::rt::lang_start_internal::{{closure}}#0 0:&&dyn std::ops::Fn() -> i32 + std::marker::Sync + std::panic::RefUnwindSafe]>` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libstd/panicking.rs:274:15
     = note: inside `std::panic::catch_unwind::<[closure@std::rt::lang_start_internal::{{closure}}#0 0:&&dyn std::ops::Fn() -> i32 + std::marker::Sync + std::panic::RefUnwindSafe], i32>` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libstd/panic.rs:394:14
     = note: inside `std::rt::lang_start_internal` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libstd/rt.rs:51:25
     = note: inside `std::rt::lang_start::<()>` at /home/david/.rustup/toolchains/miri/lib/rustlib/src/rust/src/libstd/rt.rs:67:5

Uninitialized read occurred at offset 0x4 into this allocation:
alloc1421 (Rust heap, size: 32, align: 8) {
    0x00 │ 41 42 43 44 __ __ __ __ __ __ __ __ __ __ __ __ │ ABCD░░░░░░░░░░░░
    0x10 │ 00 __ __ __ __ __ __ __ __ __ __ __ __ __ __ __ │ .░░░░░░░░░░░░░░░
}

error: aborting due to previous error

divergentdave · 2020-04-24T02:52:43Z

In the future I think it'd be nice to give not just the start offset but also the end offset. That will require tracking the access size in InvalidUndefBytes. Do you want to make a PR for that? (I can also add it to my list.)

I took a look at this briefly, one issue is that the Pointer inside InvalidUndefBytes points to the first undefined byte accessed, not to the beginning of the access, so storing the original access size wouldn't suffice. Perhaps InvalidUndefBytes could track a Pointer and a Size to indicate what contiguous interval of undefined bytes was accessed? (see Allocation::check_defined and UndefMask::is_range_defined in src/librustc_middle/mir/interpret/allocation.rs)

divergentdave · 2020-04-24T13:11:07Z

Here's my first pass on the above, haven't opened a PR for it yet. rust-lang/rust@8e28d0b

RalfJung · 2020-04-24T16:05:33Z

src/diagnostics.rs

@@ -118,7 +118,12 @@ pub fn report_error<'tcx, 'mir>(
    let result = report_msg(ecx, &format!("{}: {}", title, msg), msg, helps, true);


report_msg always returns None, no idea why it even has a return type... we can clean that up later though if you prefer.

src/diagnostics.rs

RalfJung · 2020-04-24T16:09:34Z

Here's my first pass on the above, haven't opened a PR for it yet. rust-lang/rust@8e28d0b

That looks like a great start, could you open a PR?

RalfJung · 2020-04-27T09:33:26Z

Thanks. :)
@bors r+

bors · 2020-04-27T09:33:28Z

📌 Commit e267fb4 has been approved by RalfJung

bors · 2020-04-27T09:33:35Z

⌛ Testing commit e267fb4 with merge da940eb...

bors · 2020-04-27T09:54:31Z

☀️ Test successful - checks-travis, status-appveyor
Approved by: RalfJung
Pushing da940eb to master...

@RalfJung

…ge, r=RalfJung InvalidUndefBytes: Track size of undef region used This PR adds a size to `UndefinedBehaviorInfo::InvalidUndefBytes`, to keep track of how many undefined bytes in a row were accessed, and changes a few methods to pass this information through. This additional information will eventually be used in Miri to improve diagnostics for this UB error. See also rust-lang/miri#1354 for prior discussion. I expect Miri will break the next time its submodule is updated, due to this change to the `InvalidUndefBytes`. (The current commit for src/tools/miri predates rust-lang/miri#1354, and thus does not try to destructure the `InvalidUndefBytes` variant) I have a corresponding change prepared for that repository. r? @RalfJung

Print hex dump of alloc on reading undef bytes

e37d0e3

RalfJung reviewed Apr 22, 2020

View reviewed changes

src/diagnostics.rs Show resolved Hide resolved

Reorder output

9057dae

divergentdave force-pushed the dump-alloc-on-undef-read branch from 63c68d0 to 9057dae Compare April 22, 2020 22:44

divergentdave mentioned this pull request Apr 23, 2020

Add leading 0x to offset in Debug fmt of Pointer rust-lang/rust#71459

Merged

divergentdave added 2 commits April 23, 2020 20:00

Add message before dumping alloc

d9ac84d

Add test to exercise InvalidUndefBytes

7f92eab

RalfJung reviewed Apr 24, 2020

View reviewed changes

src/diagnostics.rs Show resolved Hide resolved

Review comments

e267fb4

bors merged commit da940eb into rust-lang:master Apr 27, 2020

bors mentioned this pull request Apr 27, 2020

Add sync primitives #1362

Merged

divergentdave mentioned this pull request Apr 27, 2020

InvalidUndefBytes: Track size of undef region used rust-lang/rust#71610

Merged

divergentdave deleted the dump-alloc-on-undef-read branch April 27, 2020 15:22

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Print hex dump of alloc on reading undef bytes #1354

Print hex dump of alloc on reading undef bytes #1354

divergentdave commented Apr 22, 2020

RalfJung commented Apr 22, 2020

divergentdave commented Apr 22, 2020

RalfJung commented Apr 22, 2020 •

edited

Loading

divergentdave commented Apr 22, 2020

RalfJung commented Apr 23, 2020

divergentdave commented Apr 24, 2020

divergentdave commented Apr 24, 2020

divergentdave commented Apr 24, 2020

RalfJung Apr 24, 2020

RalfJung commented Apr 24, 2020

RalfJung commented Apr 27, 2020

bors commented Apr 27, 2020

bors commented Apr 27, 2020

bors commented Apr 27, 2020

		@@ -118,7 +118,12 @@ pub fn report_error<'tcx, 'mir>(
		let result = report_msg(ecx, &format!("{}: {}", title, msg), msg, helps, true);

Print hex dump of alloc on reading undef bytes #1354

Print hex dump of alloc on reading undef bytes #1354

Conversation

divergentdave commented Apr 22, 2020

RalfJung commented Apr 22, 2020

divergentdave commented Apr 22, 2020

RalfJung commented Apr 22, 2020 • edited Loading

divergentdave commented Apr 22, 2020

RalfJung commented Apr 23, 2020

divergentdave commented Apr 24, 2020

divergentdave commented Apr 24, 2020

divergentdave commented Apr 24, 2020

RalfJung Apr 24, 2020

Choose a reason for hiding this comment

RalfJung commented Apr 24, 2020

RalfJung commented Apr 27, 2020

bors commented Apr 27, 2020

bors commented Apr 27, 2020

bors commented Apr 27, 2020

RalfJung commented Apr 22, 2020 •

edited

Loading