Re: Broken stack traces on crashed programs

[Ludovic Courtès]

Hi,

Samuel Thibault <samuel.thibault@gnu.org> skribis:

> Ludovic Courtès, le mar. 17 nov. 2020 14:55:32 +0100, a ecrit:
>> Samuel Thibault <samuel.thibault@gnu.org> skribis:
>> 
>> > Ludovic Courtès, le mar. 17 nov. 2020 10:57:43 +0100, a ecrit:
>> >> I’ve noticed that I’d always get “broken” stack traces in GDB when (1)
>> >> attaching to a program suspended by /servers/crash-suspend, (2)
>> >> examining a core dump, or (3) spawning a program in GDB and examining it
>> >> after it’s received an unhandled signal like SIGILL.
>
> Ah, in all case you mean when receiving an unhandled signal?

Yes.

> I see that happen indeed.

Ah ha!

With a native GDB build¹ I observe the same phenomenon.

>> I get pretty back traces until the program gets an unhandled signal,
>> AFAICT.  This makes me think it could have something to do with how GDB
>> obtains thread state info for suspended threads.
>
> Probably, yes.

I looked around in gdb/*gnu-nat.c though I’m not quite sure what to look
for.

‘set debug gnu-nat on’ gives this right before the inferior, started
from GDB, gets an unhandled SIGILL:

--8<---------------cut here---------------start------------->8---
../../gdb-9.2/gdb/gnu-nat.c:953: {inf 8543 0x88062a0}: running...
../../gdb-9.2/gdb/gnu-nat.c:688: {inf 8543 0x88062a0}: clearing wait
../../gdb-9.2/gdb/gnu-nat.c:1535: {inf 8543 0x88062a0}: waiting for an event...
receiving objects   1% [                                                      
]../../gdb-9.2/gdb/gnu-nat.c:1027: {inf 8543 0x88062a0}: fetching threads
../../gdb-9.2/gdb/gnu-nat.c:927: {inf 8543 0x88062a0}: updating suspend counts
../../gdb-9.2/gdb/gnu-nat.c:273: {proc 8543/-1 0x8806b10}: sc: 0 --> 1
../../gdb-9.2/gdb/gnu-nat.c:312: {proc 8543/-1 0x8806b10}: is suspended
../../gdb-9.2/gdb/gnu-nat.c:312: {proc 8543/4 0x88083d0}: is running
../../gdb-9.2/gdb/gnu-nat.c:312: {proc 8543/5 0x8da2db0}: is running
../../gdb-9.2/gdb/gnu-nat.c:312: {proc 8543/6 0x8d9d9d0}: is running
../../gdb-9.2/gdb/gnu-nat.c:312: {proc 8543/7 0x8ece5b0}: is running
../../gdb-9.2/gdb/gnu-nat.c:953: {inf 8543 0x88062a0}: not running...
../../gdb-9.2/gdb/gnu-nat.c:1564: {inf 8543 0x88062a0}: event: msgid = 24120
../../gdb-9.2/gdb/gnu-nat.c:1827: {inf 8543 0x88062a0}: err = 0, pid = 8543, 
status = 0x47f, sigcode = 0
../../gdb-9.2/gdb/gnu-nat.c:1842: {inf 8543 0x88062a0}: waits pending now: 0
../../gdb-9.2/gdb/gnu-nat.c:1863: {inf 8543 0x88062a0}: process has stopped 
itself
../../gdb-9.2/gdb/gnu-nat.c:1027: {inf 8543 0x88062a0}: fetching threads
../../gdb-9.2/gdb/gnu-nat.c:1653: {inf 8543 0x88062a0}: returning ptid = Thread 
8543.4, status->kind = stopped, signal = GDB_SIGNAL_ILL
../../gdb-9.2/gdb/gnu-nat.c:374: {proc 8543/4 0x88083d0}: updating state info
../../gdb-9.2/gdb/gnu-nat.c:356: {proc 8543/4 0x88083d0}: aborted
../../gdb-9.2/gdb/gnu-nat.c:389: {proc 8543/4 0x88083d0}: getting thread state
../../gdb-9.2/gdb/i386-gnu-nat.c:149: {proc 8543/4 0x88083d0}: fetching 
register eip

Thread 4 received signal SIGILL, Illegal instruction.
../../gdb-9.2/gdb/gnu-nat.c:2525: {inf 8543 0x88062a0}: writing 0x11270[1] <-- 
0x881d5d8
../../gdb-9.2/gdb/gnu-nat.c:2532: {inf 8543 0x88062a0}: reading 0x810be88[1] 
--> 0x280479f
../../gdb-9.2/gdb/gnu-nat.c:2532: {inf 8543 0x88062a0}: reading 0x810be88[1] 
--> 0x280479b
../../gdb-9.2/gdb/gnu-nat.c:2532: {inf 8543 0x88062a0}: reading 0x810be80[64] 
--> 0x8f0f710
0x0810be88 in ?? ()
(gdb) bt
#0  0x0810be88 in ?? ()
../../gdb-9.2/gdb/gnu-nat.c:374: {proc 8543/4 0x88083d0}: updating state info
../../gdb-9.2/gdb/i386-gnu-nat.c:149: {proc 8543/4 0x88083d0}: fetching 
register ebp
../../gdb-9.2/gdb/gnu-nat.c:2532: {inf 8543 0x88062a0}: reading 0x813b480[64] 
--> 0x95328f0
../../gdb-9.2/gdb/gnu-nat.c:2532: {inf 8543 0x88062a0}: reading 0x0[64] --> 
0x8f60410
../../gdb-9.2/gdb/gnu-nat.c:2532: {inf 8543 0x88062a0}: reading 0x0[1] --> 
0x280478c
#1  0x00000000 in ?? ()
../../gdb-9.2/gdb/gnu-nat.c:2532: {inf 8543 0x88062a0}: reading 0x813b4c0[64] 
--> 0x8f60410
../../gdb-9.2/gdb/gnu-nat.c:2532: {inf 8543 0x88062a0}: reading 0x0[64] --> 
0x960e1b0
../../gdb-9.2/gdb/gnu-nat.c:2532: {inf 8543 0x88062a0}: reading 0x1[1] --> 
0x28047cc
(gdb) thread 5
[Switching to thread 5 (Thread 8543.5)]
../../gdb-9.2/gdb/gnu-nat.c:2532: {inf 8543 0x88062a0}: reading 0x123582c[1] 
--> 0x280468f
#0  0x0123582c in mach_msg_trap () at 
/tmp/guix-build-glibc-cross-i586-pc-gnu-2.31.drv-0/build/mach/mach_msg_trap.S:2
2       
/tmp/guix-build-glibc-cross-i586-pc-gnu-2.31.drv-0/build/mach/mach_msg_trap.S: 
No such file or directory.
(gdb) bt
#0  0x0123582c in mach_msg_trap () at 
/tmp/guix-build-glibc-cross-i586-pc-gnu-2.31.drv-0/build/mach/mach_msg_trap.S:2
../../gdb-9.2/gdb/gnu-nat.c:374: {proc 8543/5 0x8da2db0}: updating state info
../../gdb-9.2/gdb/i386-gnu-nat.c:149: {proc 8543/5 0x8da2db0}: fetching 
register esp
../../gdb-9.2/gdb/gnu-nat.c:2532: {inf 8543 0x88062a0}: reading 0x2802e80[64] 
--> 0x8f60410
#1  0x01235f2a in __GI___mach_msg (../../gdb-9.2/gdb/gnu-nat.c:2532: {inf 8543 
0x88062a0}: reading 0x2802ec0[64] --> 0x95328f0
../../gdb-9.2/gdb/gnu-nat.c:2532: {inf 8543 0x88062a0}: reading 0x2802f00[64] 
--> 0x8f0f710
msg=0x2803f30, option=3, send_size=32, rcv_size=4096, rcv_name=108, timeout=0, 
notify=0) at msg.c:111
#2  0x0123651a in __mach_msg_server_timeout (../../gdb-9.2/gdb/gnu-nat.c:2532: 
{inf 8543 0x88062a0}: reading 0x2804f40[64] --> 0x960e1b0
demux=0x124a9b0 <msgport_server>, max_size=4096, rcv_name=108, option=0, 
../../gdb-9.2/gdb/gnu-nat.c:2532: {inf 8543 0x88062a0}: reading 0x2804f80[64] 
--> 0x9381cb0
timeout=0) at msgserver.c:150
#3  0x01236607 in __mach_msg_server (demux=0x124a9b0 <msgport_server>, 
max_size=4096, rcv_name=108) at msgserver.c:195
#4  0x0124aa86 in _hurd_msgport_receive () at msgportdemux.c:67
../../gdb-9.2/gdb/gnu-nat.c:2532: {inf 8543 0x88062a0}: reading 0x2804fc0[64] 
--> 0x94220c0
#5  0x0120aa50 in entry_point (self=0x804a8d0, start_routine=0x124aa30 
<_hurd_msgport_receive>, arg=0x0) at pt-create.c:62
#6  0x00000000 in ?? ()
(gdb) thread 4 
[Switching to thread 4 (Thread 8543.4)]
../../gdb-9.2/gdb/gnu-nat.c:2532: {inf 8543 0x88062a0}: reading 0x810be88[1] 
--> 0x280468f
../../gdb-9.2/gdb/gnu-nat.c:2532: {inf 8543 0x88062a0}: reading 0x810be88[1] 
--> 0x280468b
../../gdb-9.2/gdb/gnu-nat.c:2532: {inf 8543 0x88062a0}: reading 0x810be80[64] 
--> 0x8f60410
#0  0x0810be88 in ?? ()
--8<---------------cut here---------------end--------------->8---

We don’t see it fetch ‘sp’ for the bogus thread (thread 4).  Could it be
that it’s using a stale cached value?

Thanks,
Ludo’.

¹ Currently using this pretty hack:
  guix build gdb-minimal --no-grafts --without-tests=acl --without-tests=python 
--without-tests=python-minimal --without-tests=util-linux 
--without-tests=gdb-minimal --without-tests=tcl --without-tests=expect 
--without-tests=hurd