Valgrind breaks stacktraces

[lilith]

Backtraces are not available when running a Rust executable under valgrind.

RUST_BACKTRACE=1 valgrind /home/n/Documents/imazen/imageflow/target/debug/imageflow_server diagnose --call-panic
==25361== Memcheck, a memory error detector
==25361== Copyright (C) 2002-2015, and GNU GPL'd, by Julian Seward et al.
==25361== Using Valgrind-3.12.0 and LibVEX; rerun with -h for copyright info
==25361== Command: /home/n/Documents/imazen/imageflow/target/debug/imageflow_server diagnose --call-panic
==25361== 
thread 'main' panicked at 'Panicking on command', src/main.rs:99
stack backtrace:
   1:           0xd3123c - <unknown>
   2:           0xd365de - <unknown>
   3:           0xd361e4 - <unknown>
   4:           0xd36a7b - <unknown>
   5:           0x199693 - <unknown>
   6:           0x1aeee9 - <unknown>
   7:           0x1ada6c - <unknown>
   8:           0xd3dafa - <unknown>
   9:           0xd371e6 - <unknown>
  10:           0x1b1812 - <unknown>
  11:          0x5fd9f44 - __libc_start_main
  12:           0x193666 - <unknown>
  13:                0x0 - <unknown>
==25361== 
==25361== HEAP SUMMARY:
==25361==     in use at exit: 2,600 bytes in 2 blocks
==25361==   total heap usage: 84 allocs, 82 frees, 22,584 bytes allocated
==25361== 
==25361== LEAK SUMMARY:
==25361==    definitely lost: 0 bytes in 0 blocks
==25361==    indirectly lost: 0 bytes in 0 blocks
==25361==      possibly lost: 0 bytes in 0 blocks
==25361==    still reachable: 2,600 bytes in 2 blocks
==25361==         suppressed: 0 bytes in 0 blocks
==25361== Rerun with --leak-check=full to see details of leaked memory
==25361== 
==25361== For counts of detected and suppressed errors, rerun with: -v
==25361== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 0 from 0)

Without Valgrind

thread 'main' panicked at 'Panicking on command', src/main.rs:99
stack backtrace:
   1:     0x563ee9fa223c - std::sys::imp::backtrace::tracing::imp::write::hf7294f5e24536b4a
                        at /buildslave/rust-buildbot/slave/nightly-dist-rustc-linux/build/src/libstd/sys/unix/backtrace/tracing/gcc_s.rs:42
   2:     0x563ee9fa75de - std::panicking::default_hook::{{closure}}::h9a07d0b00c43fbee
                        at /buildslave/rust-buildbot/slave/nightly-dist-rustc-linux/build/src/libstd/panicking.rs:351
   3:     0x563ee9fa71e4 - std::panicking::default_hook::hf25feff2d08bf39b
                        at /buildslave/rust-buildbot/slave/nightly-dist-rustc-linux/build/src/libstd/panicking.rs:367
   4:     0x563ee9fa7a7b - std::panicking::rust_panic_with_hook::h4cb8c6fbb8386ccf
                        at /buildslave/rust-buildbot/slave/nightly-dist-rustc-linux/build/src/libstd/panicking.rs:555
   5:     0x563ee940a693 - std::panicking::begin_panic::h4f700bfae26a44e5
                        at /buildslave/rust-buildbot/slave/nightly-dist-rustc-linux/build/src/libstd/panicking.rs:517
   6:     0x563ee941fee9 - imageflow_server::main_with_exit_code::h5136f5c7061e1ac9
                        at /home/n/Documents/imazen/imageflow/imageflow_server/src/main.rs:99
   7:     0x563ee941ea6c - imageflow_server::main::h21a73832ce5c2071
                        at /home/n/Documents/imazen/imageflow/imageflow_server/src/main.rs:17
   8:     0x563ee9faeafa - __rust_maybe_catch_panic
                        at /buildslave/rust-buildbot/slave/nightly-dist-rustc-linux/build/src/libpanic_unwind/lib.rs:98
   9:     0x563ee9fa81e6 - std::rt::lang_start::h0637c2e100ff36fc
                        at /buildslave/rust-buildbot/slave/nightly-dist-rustc-linux/build/src/libstd/panicking.rs:436
                        at /buildslave/rust-buildbot/slave/nightly-dist-rustc-linux/build/src/libstd/panic.rs:361
                        at /buildslave/rust-buildbot/slave/nightly-dist-rustc-linux/build/src/libstd/rt.rs:57
  10:     0x563ee9422812 - main
  11:     0x7fe7b118af44 - __libc_start_main
  12:     0x563ee9404666 - <unknown>
  13:                0x0 - <unknown>

Meta

Host is Ubuntu 14.04, using a recently nightly.

uname -a
Linux nathanael-xeon 4.4.0-62-generic #83~14.04.1-Ubuntu SMP Wed Jan 18 18:10:30 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux

rustc --version --verbose
rustc 1.17.0-nightly (ea7a6486a 2017-02-04)
binary: rustc
commit-hash: ea7a6486a26af085862cd7a5596bb69e83d85e12
commit-date: 2017-02-04
host: x86_64-unknown-linux-gnu
release: 1.17.0-nightly
LLVM version: 3.9

[sanmai-NL]

Thanks. Breaking up that output text as described in the contribution guidelines will help people spot the necessary info.

[sfackler]

cc @michaelwoerister

[lilith]

@sanmai-NL Like this?

[alexcrichton]

The backtrace here looks correct, it looks like it's just the step of translating an address to a symbol that's failing. That in turn is probably because by default libbacktrace uses /proc/self/exe on Linux which I doubt works when you're running under valgrind.

tl;dr; the bug is to find the dwarf debug section, as the current logic is probably finding the wrong one.

[alecmocatta]

From a quick skim, libbacktrace opens /proc/self/exe. This will indeed return the Valgrind binary. The easiest workaround would be to, if running on Valgrind, readlink /proc/self/exe, which Valgrind hooks to return the path of the user's executable, and open that instead.

[pnkfelix]

Visiting for wg-debugging triage

Its been so long since this issue was touched, we should have someone go and confirm that it still reproduces. I'm adding E-help-wanted to reflect that.

@rustbot label: E-help-wanted

(also, @wesleywiser notes that this may have the same root (or at least related) cause as #101913 .)

[pnkfelix]

In particular, it looks like sufficiently new versions of valgrind may have addressed this (by intercepting open and openat of /proc/self/exe in the same manner that it was already intercepting readlink, and substituting the user's executable in response.)

So I would not be shocked if this bug no longer replicates, for sufficiently recent versions of valgrind...

[pnkfelix]

I just confirmed that a test case (namely the immediately panicking program from #101913); see transcript below.

Thus, closing as resolved.

$ RUST_BACKTRACE=1 ./target/debug/ld-so-backtraces
thread 'main' panicked at 'explicit panic', src/main.rs:1:13
stack backtrace:
   0: rust_begin_unwind
             at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:584:5
   1: core::panicking::panic_fmt
             at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/panicking.rs:143:14
   2: core::panicking::panic
             at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/panicking.rs:48:5
   3: ld_so_backtraces::main
             at ./src/main.rs:1:13
   4: core::ops::function::FnOnce::call_once
             at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/ops/function.rs:227:5
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
$ RUST_BACKTRACE=1 valgrind ./target/debug/ld-so-backtraces
==136503== Memcheck, a memory error detector
==136503== Copyright (C) 2002-2017, and GNU GPL'd, by Julian Seward et al.
==136503== Using Valgrind-3.15.0 and LibVEX; rerun with -h for copyright info
==136503== Command: ./target/debug/ld-so-backtraces
==136503==
thread 'main' panicked at 'explicit panic', src/main.rs:1:13
stack backtrace:
==136503== Syscall param statx(file_name) points to unaddressable byte(s)
==136503==    at 0x49A588E: statx (statx.c:29)
==136503==    by 0x1282E1: statx (weak.rs:178)
==136503==    by 0x1282E1: std::sys::unix::fs::try_statx (fs.rs:150)
==136503==    by 0x129555: file_attr (fs.rs:810)
==136503==    by 0x129555: metadata (fs.rs:494)
==136503==    by 0x129555: std::backtrace_rs::symbolize::gimli::mmap (gimli.rs:138)
==136503==    by 0x1298D7: new (elf.rs:21)
==136503==    by 0x1298D7: mapping_for_lib (gimli.rs:320)
==136503==    by 0x1298D7: std::backtrace_rs::symbolize::gimli::resolve::{{closure}} (gimli.rs:354)
==136503==    by 0x129794: with_global<std::backtrace_rs::symbolize::gimli::resolve::{closure_env#1}> (gimli.rs:266)
==136503==    by 0x129794: std::backtrace_rs::symbolize::gimli::resolve (gimli.rs:346)
==136503==    by 0x1230AE: resolve_frame_unsynchronized<std::sys_common::backtrace::_print_fmt::{closure#1}::{closure_env#0}> (mod.rs:178)
==136503==    by 0x1230AE: std::sys_common::backtrace::_print_fmt::{{closure}} (backtrace.rs:73)
==136503==    by 0x1283A0: call_mut<(&std::backtrace_rs::backtrace::Frame), dyn core::ops::function::FnMut<(&std::backtrace_rs::backtrace::Frame), Output=bool>> (function.rs:269)
==136503==    by 0x1283A0: std::backtrace_rs::backtrace::libunwind::trace::trace_fn (libunwind.rs:105)
==136503==    by 0x4865793: _Unwind_Backtrace (in /usr/lib/x86_64-linux-gnu/libgcc_s.so.1)
==136503==    by 0x122F1C: trace (libunwind.rs:93)
==136503==    by 0x122F1C: trace_unsynchronized<std::sys_common::backtrace::_print_fmt::{closure_env#1}> (mod.rs:66)
==136503==    by 0x122F1C: _print_fmt (backtrace.rs:66)
==136503==    by 0x122F1C: <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt (backtrace.rs:45)
==136503==    by 0x13EC0B: core::fmt::write (mod.rs:1190)
==136503==    by 0x11FF77: std::io::Write::write_fmt (mod.rs:1657)
==136503==    by 0x124A73: _print (backtrace.rs:48)
==136503==    by 0x124A73: print (backtrace.rs:35)
==136503==    by 0x124A73: std::panicking::default_hook::{{closure}} (panicking.rs:292)
==136503==  Address 0x0 is not stack'd, malloc'd or (recently) free'd
==136503==
==136503== Syscall param statx(buf) points to unaddressable byte(s)
==136503==    at 0x49A588E: statx (statx.c:29)
==136503==    by 0x1282E1: statx (weak.rs:178)
==136503==    by 0x1282E1: std::sys::unix::fs::try_statx (fs.rs:150)
==136503==    by 0x129555: file_attr (fs.rs:810)
==136503==    by 0x129555: metadata (fs.rs:494)
==136503==    by 0x129555: std::backtrace_rs::symbolize::gimli::mmap (gimli.rs:138)
==136503==    by 0x1298D7: new (elf.rs:21)
==136503==    by 0x1298D7: mapping_for_lib (gimli.rs:320)
==136503==    by 0x1298D7: std::backtrace_rs::symbolize::gimli::resolve::{{closure}} (gimli.rs:354)
==136503==    by 0x129794: with_global<std::backtrace_rs::symbolize::gimli::resolve::{closure_env#1}> (gimli.rs:266)
==136503==    by 0x129794: std::backtrace_rs::symbolize::gimli::resolve (gimli.rs:346)
==136503==    by 0x1230AE: resolve_frame_unsynchronized<std::sys_common::backtrace::_print_fmt::{closure#1}::{closure_env#0}> (mod.rs:178)
==136503==    by 0x1230AE: std::sys_common::backtrace::_print_fmt::{{closure}} (backtrace.rs:73)
==136503==    by 0x1283A0: call_mut<(&std::backtrace_rs::backtrace::Frame), dyn core::ops::function::FnMut<(&std::backtrace_rs::backtrace::Frame), Output=bool>> (function.rs:269)
==136503==    by 0x1283A0: std::backtrace_rs::backtrace::libunwind::trace::trace_fn (libunwind.rs:105)
==136503==    by 0x4865793: _Unwind_Backtrace (in /usr/lib/x86_64-linux-gnu/libgcc_s.so.1)
==136503==    by 0x122F1C: trace (libunwind.rs:93)
==136503==    by 0x122F1C: trace_unsynchronized<std::sys_common::backtrace::_print_fmt::{closure_env#1}> (mod.rs:66)
==136503==    by 0x122F1C: _print_fmt (backtrace.rs:66)
==136503==    by 0x122F1C: <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt (backtrace.rs:45)
==136503==    by 0x13EC0B: core::fmt::write (mod.rs:1190)
==136503==    by 0x11FF77: std::io::Write::write_fmt (mod.rs:1657)
==136503==    by 0x124A73: _print (backtrace.rs:48)
==136503==    by 0x124A73: print (backtrace.rs:35)
==136503==    by 0x124A73: std::panicking::default_hook::{{closure}} (panicking.rs:292)
==136503==  Address 0x0 is not stack'd, malloc'd or (recently) free'd
==136503==
   0: rust_begin_unwind
             at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:584:5
   1: core::panicking::panic_fmt
             at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/panicking.rs:143:14
   2: core::panicking::panic
             at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/panicking.rs:48:5
   3: ld_so_backtraces::main
             at ./src/main.rs:1:13
   4: core::ops::function::FnOnce::call_once
             at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/ops/function.rs:227:5
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
==136503==
==136503== HEAP SUMMARY:
==136503==     in use at exit: 1,636,120 bytes in 2,702 blocks
==136503==   total heap usage: 9,340 allocs, 6,638 frees, 5,711,794 bytes allocated
==136503==
==136503== LEAK SUMMARY:
==136503==    definitely lost: 0 bytes in 0 blocks
==136503==    indirectly lost: 0 bytes in 0 blocks
==136503==      possibly lost: 0 bytes in 0 blocks
==136503==    still reachable: 1,636,120 bytes in 2,702 blocks
==136503==         suppressed: 0 bytes in 0 blocks
==136503== Rerun with --leak-check=full to see details of leaked memory
==136503==
==136503== For lists of detected and suppressed errors, rerun with: -s
==136503== ERROR SUMMARY: 2 errors from 2 contexts (suppressed: 0 from 0)