Debuginfo: Source lines for fail! invocations are incorrect

[jdm]

When I set a breakpoint in rust_begin_unwind and hit a fail! somewhere, the stack frame containing the fail! call shows the right file but the wrong line. It shows me line 66, which I suspect comes from injecting the std_macros (including fail!) into every file, since the fail! definition occurs on line 60 of that block (see syntax/etx/expand.rs).

[alexcrichton]

Do you have an example of where this goes wrong as well? I may have broken usage through nested macros recently, but normal vanilla usage should be ok I thought.

[jdm]

fn foo() {
  fail!("whoops");
}

fn main() {
  foo();
}

[jdm@rosencrantz build]$ rustc /tmp/a.rs -Z debug-info
(gdb) break rust_begin_unwind
Function "rust_begin_unwind" not defined.
Make breakpoint pending on future shared library load? (y or [n]) y
Breakpoint 1 (rust_begin_unwind) pending.
(gdb) r
Starting program: /tmp/a 
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
[New Thread 0x7ffff75c0700 (LWP 30946)]
[New Thread 0x7ffff6bff700 (LWP 30947)]
task <unnamed> failed at 'whoops', /tmp/a.rs:2
[Switching to Thread 0x7ffff75c0700 (LWP 30946)]

Breakpoint 1, rust_begin_unwind (token=839147) at /home/jdm/sdb/rust/src/rt/rust_builtin.cpp:532
532 rust_begin_unwind(uintptr_t token) {
Missing separate debuginfos, use: debuginfo-install glibc-2.16-34.fc18.x86_64 libgcc-4.7.2-8.fc18.x86_64 libstdc++-4.7.2-8.fc18.x86_64
(gdb) bt
#0  rust_begin_unwind (token=839147) at /home/jdm/sdb/rust/src/rt/rust_builtin.cpp:532
#1  0x00007ffff797a9c6 in rt::task::Unwinder::begin_unwind::h7c12263797ed0787oaP::v0.8$x2dpre () from /tmp/../usr/local/lib/rustc/x86_64-unknown-linux-gnu/lib/libstd-6c65cf4b443341b1-0.8-pre.so
#2  0x00007ffff7979e6f in sys::begin_unwind_::h89e154cd0915671::v0.8$x2dpre () from /tmp/../usr/local/lib/rustc/x86_64-unknown-linux-gnu/lib/libstd-6c65cf4b443341b1-0.8-pre.so
#3  0x00007ffff7979fc2 in sys::__extensions__::fail_with::anon::anon::expr_fn::aF () from /tmp/../usr/local/lib/rustc/x86_64-unknown-linux-gnu/lib/libstd-6c65cf4b443341b1-0.8-pre.so
#4  0x00007ffff7979978 in c_str::ToCStr::with_c_str::hc6798931b183a7aA::v0.8$x2dpre () from /tmp/../usr/local/lib/rustc/x86_64-unknown-linux-gnu/lib/libstd-6c65cf4b443341b1-0.8-pre.so
#5  0x00007ffff7979f71 in sys::__extensions__::fail_with::anon::expr_fn::aE () from /tmp/../usr/local/lib/rustc/x86_64-unknown-linux-gnu/lib/libstd-6c65cf4b443341b1-0.8-pre.so
#6  0x00007ffff7979978 in c_str::ToCStr::with_c_str::hc6798931b183a7aA::v0.8$x2dpre () from /tmp/../usr/local/lib/rustc/x86_64-unknown-linux-gnu/lib/libstd-6c65cf4b443341b1-0.8-pre.so
#7  0x00007ffff790297c in sys::FailWithCause$__extensions__::fail_with::hdb4c44d01ce4116qua8::v0.8$x2dpre () from /tmp/../usr/local/lib/rustc/x86_64-unknown-linux-gnu/lib/libstd-6c65cf4b443341b1-0.8-pre.so
#8  0x0000000000400a61 in a::foo () at /tmp/a.rs:48
#9  0x0000000000400aa9 in a::main () at /tmp/a.rs:6
#10 0x0000000000400ade in _rust_main ()
#11 0x00007ffff7997dc0 in rt::task::__extensions__::build_start_wrapper::anon::anon::expr_fn::aL () from /tmp/../usr/local/lib/rustc/x86_64-unknown-linux-gnu/lib/libstd-6c65cf4b443341b1-0.8-pre.so
#12 0x00007ffff79962b7 in rt::task::__extensions__::run::anon::expr_fn::a3 () from /tmp/../usr/local/lib/rustc/x86_64-unknown-linux-gnu/lib/libstd-6c65cf4b443341b1-0.8-pre.so
#13 0x00007ffff75fc473 in rust_try (f=<optimized out>, fptr=<optimized out>, env=<optimized out>) at /home/jdm/sdb/rust/src/rt/rust_builtin.cpp:523
#14 0x00007ffff79961ec in rt::task::Unwinder::try::h199ab8d6eb2269807oa2::v0.8$x2dpre () from /tmp/../usr/local/lib/rustc/x86_64-unknown-linux-gnu/lib/libstd-6c65cf4b443341b1-0.8-pre.so
#15 0x00007ffff7996061 in rt::task::Task::run::h199ab8d6eb226980r2a1::v0.8$x2dpre () from /tmp/../usr/local/lib/rustc/x86_64-unknown-linux-gnu/lib/libstd-6c65cf4b443341b1-0.8-pre.so
#16 0x00007ffff79979ac in rt::task::__extensions__::build_start_wrapper::anon::expr_fn::aC () from /tmp/../usr/local/lib/rustc/x86_64-unknown-linux-gnu/lib/libstd-6c65cf4b443341b1-0.8-pre.so
#17 0x0000000000000000 in ?? ()
(gdb) fr 9
#9  0x0000000000400aa9 in a::main () at /tmp/a.rs:6
6     foo();
(gdb) dow
#8  0x0000000000400a61 in a::foo () at /tmp/a.rs:48
(gdb) 

[alexcrichton]

oh you mean with debug-info! I thought you meant what it actually printed to the console. Don't mind me...

[huonw]

This is still incorrect... but in a different way; everything is now listed as being at the foo(); call on line 6.

(gdb) bt
#0  0x00000000004ad2c0 in rust_fail ()
#1  0x000000000040d237 in rt::unwind::Unwinder::begin_unwind::h14802138eb5cb0784naz::v0.10.pre ()
#2  0x0000000000405ea8 in rt::unwind::begin_unwind::h75d805b83b09d8c0aZ::v0.0
    () at 9232.rs:6
#3  0x0000000000405251 in _ZN492323fooE () at 9232.rs:6
#4  0x00000000004094a9 in _ZN492324mainE () at 9232.rs:6

[huonw]

Ah, the may be related to the change that moved the macros into libstd, since it displays the old behaviour with aa9cf4c but the behaviour I described just above with 6516b30.

cc @sfackler

[sfackler]

I suspect that the line 6 is coming from line 6 of the definition of fail here: https://github.com/mozilla/rust/blob/master/src/libstd/macros.rs#L48. Each macro is individually serialized which is why the line count shifted. I think the issue before and now is that the debug info infrastructure needs to do something special with spans that point to autogenerated "files" like "".

[steveklabnik]

Triage time!

To reproduce today, source code:

fn foo() {
  panic("whoops");
}

fn main() {
  foo();
}

compile:

$ rustc -g hello.rs

use gdb:

$ rust-gdb hello
<snip>
Reading symbols from hello...done.
(gdb) break rust_panic
Breakpoint 2 at 0x555555560e50
(gdb) r
Starting program: /home/steve/tmp/hello 
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
thread '<main>' panicked at 'whoops', hello.rs:2

Breakpoint 2, 0x0000555555560e50 in rust_panic ()
(gdb) stacktrace
Undefined command: "stacktrace".  Try "help".
(gdb) st
Ambiguous command "st": stack, start, status, step, stepi, stepping, stop, strace.
(gdb) bt
#0  0x0000555555560e50 in rust_panic ()
#1  0x000055555555aeeb in rt::unwind::begin_unwind_inner::h082f07869f4b9731ACI ()
#2  0x000055555555a2cf in hello::rt::unwind::begin_unwind<&str> (msg="whoops", 
    file_line=0x5555557a96d0 <foo::_FILE_LINE::h7e3aee1d68787d09qaa>)
    at /home/rustbuild/src/rust-buildbot/slave/beta-dist-rustc-linux/build/src/libstd/rt/unwind.rs:524
#3  0x000055555555a21b in hello::foo () at <std macros>:3
#4  0x000055555555a61e in hello::main () at hello.rs:6
#5  0x0000555555565409 in rust_try_inner ()
#6  0x00005555555653f6 in rust_try ()
#7  0x00005555555632cf in rt::lang_start::he050f8de3bcc02b7VRI ()
#8  0x000055555555a765 in main ()
(gdb) 

notably: hello::foo () at :3 and hello::main () at hello.rs:6

Is this wrong? should it say hello::foo() at hello.rs:2, I'd guess? It's at least different than before.

[jdm]

Yes, the output in frame 3 is not as useful as it could be, since you really want to know what line the macro was invoke on, rather than which line of the macro called begin_unwind.

[comex]

Just ran into this with a custom macro - one function contains multiple expansion of the macro, which calls another function, which panics. The backtrace doesn't make it easy to tell which expansion was involved. Not sure how this would be fixed, since the only obvious alternative would be emitting line info for the expansion site instead, which would cause the opposite problem, not being able to tell where in the macro the call came from. (This is what you get in C, and it's awful for sufficiently long macros.)

Maybe rustc could fake an inline function call somehow?

[steveklabnik]

Triage: you need to use panic!, not fail. I don't have gdb installed and so cannot attempt to reproduce, does anyone know if this is still an issue?

[tromey]

Now I see:

#0  rust_panic (msg=...) at libstd/panicking.rs:524
#1  0x00005555555891d9 in std::panicking::rust_panic_with_hook (payload=..., 
    message=..., file_line_col=0x5555555f1470) at libstd/panicking.rs:496
#2  0x0000555555562f78 in std::panicking::begin_panic (msg=..., 
    file_line_col=0x5555555f1470) at libstd/panicking.rs:410
#3  0x00005555555625dd in t::foo () at /tmp/t.rs:2
#4  0x00005555555625e6 in t::main () at /tmp/t.rs:6

Frames 3 and 4 look fine to me. I don't know whether there is a test for this or not; but if so, I think it could be closed.