DynamoRIO / DynamoRIO/dynamorio
SIGBUS in thread-private fcache_return
- Dominant language
- C
- Stars
- 3.2k
- Forks
- 629
- Avg merge
- 2d 18h
- Merged PRs (30d)
- 30
Description
_From [bruen...@google.com](https://code.google.com/u/109494838902877177630/) on June 19, 2013 17:19:11_
Observed here: https://code.google.com/p/drmemory/issues/detail?id=1265 Showed up as an assert that the stack is not readable:
13:clone
-----dynamorio/core/synch.c:194 res
15:pthread_test
-----dynamorio/core/synch.c:194 res
The assert fires b/c esp points at the very base of the dstack, so naturally reading at a higher address fails.
This was seen on FC18, and also on FC15.
Here is info from earlier debugging:
Assert is here, while processing the SIGBUS:
Jun 12 15:46:59 `#6` 0xf71d099c in is_at_do_syscall (dcontext=0x4d4cd180, pc=0x4d551f30 "\234[\211\035\240\321LMj",
Jun 12 15:47:01 esp=0x4d52f000 "") at /home/branden/Repositories/DrMem/drmemory/dynamorio/core/synch.c:196
Jun 12 15:47:02 `#7` 0xf729f82b in is_sys_kill (dcontext=0x4d4cd180, pc=0x4d551f30 "\234[\211\035\240\321LMj", xsp=0x4d52f000 "",
Jun 12 15:47:04 info=0x4d54ec8c) at /home/branden/Repositories/DrMem/drmemory/dynamorio/core/unix/signal.c:3669
Jun 12 15:47:05 `#8` 0xf72a119f in master_signal_handler_C (xsp=0x4d54ec7c "EW%\367\a")
Jun 12 15:47:07 at /home/branden/Repositories/DrMem/drmemory/dynamorio/core/unix/signal.c:4217
SIGBUS is hit here:
Jun 12 16:01:35 (gdb) x/10i sc->eip
Jun 12 16:01:36 0x55c69f30: pushf
Jun 12 16:01:38 0x55c69f31: pop %ebx
Jun 12 16:01:39 0x55c69f32: mov %ebx,0x55be51a0
Jun 12 16:01:41 0x55c69f38: push $0x0
Jun 12 16:01:43 0x55c69f3a: popf
Jun 12 16:01:44 0x55c69f3b: mov %eax,0x55be52e4
Jun 12 16:01:45 0x55c69f40: push $0x55be5180
Jun 12 16:01:47 0x55c69f45: call 0xf70d9801
Jun 12 16:01:48 0x55c69f4a: lea 0x4(%esp),%esp
Jun 12 16:01:50 0x55c69f4e: jmp 0xf7255568
That's thread-private fcache_return.
esp is 0x55c47000
/proc/self/maps:
Jun 12 16:26:54 55c3a000-55c47000 rw-p 00000000 00:00 0 [stack:21398]
Jun 12 16:26:56 55c47000-55c49000 ---p 00000000 00:00 0 [stack:21398]
Jun 12 16:21:30 p /x ((dcontext_t*)0x55be5180)->dstack
Jun 12 16:21:51 $9 = 0x55c47000
Jun 12 16:08:01 "p heapmgt->vmheap"
Jun 12 16:08:28 (gdb) p heapmgt->vmheap
Jun 12 16:08:30 $6 = {start_addr = 0x55be0000 "", end_addr = 0x65be0000
Jun 12 17:02:39 (gdb) p /x sig
Jun 12 17:02:40 $23 = 0x7
Jun 12 17:02:42 (gdb) p /x *siginfo
Jun 12 17:02:43 $24 = {si_signo = 0x7, si_errno = 0x0, si_code = 0x80, _sifields = {_pad = {0x0, 0x0,
Jun 12 17:02:45 0xabababab }, _kill = {si_pid = 0x0, si_uid = 0x0}, _timer = {si_tid = 0x0,
Jun 12 17:02:46 si_overrun = 0x0, si_sigval = {sival_int = 0xabababab, sival_ptr = 0xabababab}}, _rt = {si_pid = 0x0,
Jun 12 17:02:48 si_uid = 0x0, si_sigval = {sival_int = 0xabababab, sival_ptr = 0xabababab}}, _sigchld = {si_pid = 0x0,
Jun 12 17:02:49 si_uid = 0x0, si_status = 0xabababab, si_utime = 0xabababab, si_stime = 0xabababab}, _sigfault = {
Jun 12 17:02:51 si_addr = 0x0}, _sigpoll = {si_band = 0x0, si_fd = 0x0}}}
Jun 12 17:19:03 7 is SIGBUS
Jun 12 17:21:37 so si_code = 0x80 => just SI_KERNEL, no BUS_ value
Jun 12 17:24:43 so take a step back: we got SIGBUS on pushf when esp=0x55c47000 base of normal-looking dstack
Jun 12 18:01:08 this time it happens to be right before 'i=250000' but it has happened at just about every point along execution
Jun 12 18:01:27 in relation to 'i=nnn' being printed
(separate run)
Jun 12 18:05:34 (gdb) p/x dcontext->next_tag
Jun 12 18:05:35 $45 = 0x4c3f6280
Jun 12 18:32:39 (gdb) x/10i 0x4dc56280
Jun 12 18:32:41 0x4dc56280: syscall
Jun 12 18:32:42 0x4dc56282: mov %eax,0x4dbd119c
Jun 12 18:32:44 0x4dc56287: mov $0xf72d95cc,%eax
Jun 12 18:32:45 0x4dc5628c: jmp 0x4dc55ec0
Jun 12 18:36:12 ok this is a different run so DR's mem must cover 0x4dc now
Jun 12 18:40:39 (gdb) p/x dcontext->asynch_target
Jun 12 18:40:40 $11 = 0xf77d3425
Jun 12 18:40:42 (gdb) x/5i 0xf77d3425
Jun 12 18:40:43 0xf77d3425 <__kernel_vsyscall+5>: mov $0x2b,%ecx
Jun 12 18:40:45 0xf77d342a <__kernel_vsyscall+10>: mov %ecx,%ss
Jun 12 18:40:46 0xf77d342c <__kernel_vsyscall+12>: mov %ebp,%ecx
Jun 12 18:40:48 0xf77d342e <__kernel_vsyscall+14>: pop %ebp
Jun 12 18:40:49 0xf77d342f <__kernel_vsyscall+15>: ret
SIGBUS on pushf of anon mmap makes no sense: a race of some kind where that
address was a file mmap at the time?
_Original issue: http://code.google.com/p/dynamorio/issues/detail?id=1193_
Contributor guide
Research direction
Start by examining thread-private fcache_return and the SIGBUS handling paths in dynamorio/core/synch.c and dynamorio/core/unix/signal.c. Reproduce the failure on the reported Fedora environments, using the supplied stack, dstack, and /proc/self/maps details to investigate why pushf faults at the stack base. Done means identifying and correcting the cause of the SIGBUS without breaking signal handling.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- c, linux
- Domain
- operating-systems
- Issue type
- Bug
- Difficulty
- 5/5
- Estimated time
- Over a week
- Activity status
- Stale
- Clarity
- Needs clarification
- Newbie friendliness
- 20/100