Repository navigation
rr assertion during recording of firefox/mochitest run: !is_in_untraced_syscall() || 0 == (SYSCALLBUF_LOCKED_TRACEE & read_mem(REMOTE_PTR_FIELD(syscallbuf_child, locked))) #2154
Description
Using rr ed91e25 (rr version 5.0.0).
[FATAL /home/sfink/src/rr/src/Task.cc:2012:reset_syscallbuf()]
(task 27107 (rec:27107) at time 6815702)
-> Assertion `!is_in_untraced_syscall() || 0 == (SYSCALLBUF_LOCKED_TRACEE & read_mem(REMOTE_PTR_FIELD(syscallbuf_child, locked)))' failed to hold.
=== Start rr backtrace:
rr(_ZN2rr13dump_rr_stackEv+0x28)[0x544118]
rr(_ZN2rr9GdbServer15emergency_debugEPNS_4TaskE+0x615)[0x4892f5]
rr(_ZN2rr21EmergencyDebugOstreamD2Ev+0xe1)[0x4952f1]
rr(_ZN2rr4Task16reset_syscallbufEv+0x82)[0x529e02]
rr(_ZN2rr10RecordTask22maybe_reset_syscallbufEv+0x6c)[0x4e92bc]
rr(_ZN2rr10RecordTask12record_eventERKNS_5EventENS0_15FlushSyscallbufEPKNS_9RegistersE+0x14e)[0x4e8b4e]
rr[0x4b1193]
rr(_ZN2rr13RecordSession11record_stepEv+0x184)[0x4b4ee4]
rr(_ZN2rr13RecordCommand3runERSt6vectorINSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEESaIS7_EE+0xbae)[0x4aca9e]
rr(main+0x1e8)[0x54c49a]
/lib64/libc.so.6(__libc_start_main+0xf1)[0x7f07ff8db431]
rr(_start+0x2a)[0x43f35a]
=== End rr backtrace
Launch gdb with
gdb '-l' '10000' '-ex' 'set sysroot /' '-ex' 'target extended-remote 127.0.0.1:27107' /home/sfink/src/mozilla2/obj-x86_64-pc-linux-gnu/dist/bin/xpcshell
tail of rr dump -t 27107 is:
{
real_time:32321.485824 global_time:6815657, event:`SYSCALLBUF_ABORT_COMMIT' tid:27107, ticks:175252
}
{
real_time:32321.485880 global_time:6815658, event:`SYSCALL: rrcall_notify_syscall_hook_exit' (state:ENTERING_SYSCALL) tid:27107, ticks:175260
rax:0xffffffffffffffda rbx:0x7fc03f758fa0 rcx:0xffffffffffffffff rdx:0xffffffff rsi:0x2 rdi:0xd0e62518ad0 rbp:0x1 rsp:0x7fc03f758e20 r8:0x0 r9:0x59f670d0 r10:0x0 r11:0x246 r12:0xd0e62518ad0 r13:0x7fc03f459306 r14:0xffffffff r15:0x10 rip:0x70000005 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x1bc fs_base:0xd0e6251a700 gs_base:0x0
}
{
real_time:32321.485882 global_time:6815659, event:`SYSCALLBUF_RESET' tid:27107, ticks:175260
}
{
real_time:32321.485894 global_time:6815660, event:`SYSCALL: rrcall_notify_syscall_hook_exit' (state:EXITING_SYSCALL) tid:27107, ticks:175260
rax:0x1 rbx:0x7fc03f758fa0 rcx:0xffffffffffffffff rdx:0xffffffff rsi:0x2 rdi:0xd0e62518ad0 rbp:0x1 rsp:0x7fc03f758e20 r8:0x0 r9:0x59f670d0 r10:0x0 r11:0x246 r12:0xd0e62518ad0 r13:0x7fc03f459306 r14:0xffffffff r15:0x10 rip:0x70000005 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x7 fs_base:0xd0e6251a700 gs_base:0x0
}
{
real_time:32321.486054 global_time:6815661, event:`SYSCALLBUF_FLUSH' tid:27107, ticks:183241
}
{
real_time:32321.486056 global_time:6815662, event:`SYSCALL: poll' (state:ENTERING_SYSCALL) tid:27107, ticks:183241
rax:0xffffffffffffffda rbx:0x7fc03f4592e6 rcx:0xffffffffffffffff rdx:0xffffffffffffffff rsi:0x2 rdi:0x7fc03f4592f6 rbp:0x7fc03f4592f6 rsp:0x7fc03f758e00 r8:0x0 r9:0x0 r10:0x0 r11:0x246 r12:0xd0e62518ad0 r13:0x7fc03f459306 r14:0xffffffff r15:0x10 rip:0x7000000e eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x7 fs_base:0xd0e6251a700 gs_base:0x0
}
{
real_time:32321.486260 global_time:6815670, event:`SYSCALL: poll' (state:EXITING_SYSCALL) tid:27107, ticks:183241
rax:0x1 rbx:0x7fc03f4592e6 rcx:0xffffffffffffffff rdx:0xffffffffffffffff rsi:0x2 rdi:0x7fc03f4592f6 rbp:0x7fc03f4592f6 rsp:0x7fc03f758e00 r8:0x0 r9:0x0 r10:0x0 r11:0x246 r12:0xd0e62518ad0 r13:0x7fc03f459306 r14:0xffffffff r15:0x10 rip:0x7000000e eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x7 fs_base:0xd0e6251a700 gs_base:0x0
}
{
real_time:32321.486261 global_time:6815671, event:`SYSCALLBUF_ABORT_COMMIT' tid:27107, ticks:183241
}
{
real_time:32321.487074 global_time:6815701, event:`SCHED' tid:27107, ticks:183246
rax:0x0 rbx:0x7fc03f459000 rcx:0xffffffffffffffff rdx:0x0 rsi:0x2401 rdi:0x67 rbp:0x7fc03f4592e6 rsp:0x7fc03f758e00 r8:0x0 r9:0x0 r10:0x0 r11:0x246 r12:0x1 r13:0x7fc03f459306 r14:0xffffffff r15:0x10 rip:0x70000017 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x10 fs_base:0xd0e6251a700 gs_base:0x0
}
Backtrace of that process:
(gdb) bt
bt
#0 0x0000000070000017 in ()
#1 0x0000013e561a2222 in _raw_syscall () at /home/sfink/src/rr/src/preload/raw_syscall.S:120
#2 0x0000013e5619ee33 in disarm_desched_event () at /home/sfink/src/rr/src/preload/syscallbuf.c:729
#3 0x0000013e5619ee33 in commit_raw_syscall (syscallno=syscallno@entry=7, record_end=record_end@entry=0x7fc03f459306, ret=1) at /home/sfink/src/rr/src/preload/syscallbuf.c:894
#4 0x0000013e561a0dc7 in sys_poll (call=0x7fc03f758fa0)
at /home/sfink/src/rr/src/preload/syscallbuf.c:1698
#5 0x0000013e561a0dc7 in syscall_hook_internal (call=0x7fc03f758fa0)
at /home/sfink/src/rr/src/preload/syscallbuf.c:2489
#6 0x0000013e561a0dc7 in syscall_hook (call=0x7fc03f758fa0)
at /home/sfink/src/rr/src/preload/syscallbuf.c:2576
#7 0x0000013e5619eaca in _syscall_hook_trampoline ()
at /home/sfink/src/rr/src/preload/syscall_hook.S:282
#8 0x0000013e5619eafa in __morestack () at /home/sfink/src/rr/src/preload/syscall_hook.S:417
#9 0x0000013e5619eb2a in _syscall_hook_trampoline_48_8b_3c_24 ()
at /home/sfink/src/rr/src/preload/syscall_hook.S:433
#10 0x000018055f96ff41 in poll () at ../sysdeps/unix/syscall-template.S:84
Activity
hotsphink commentedon Dec 2, 2017
My command line, fwiw, was
rr record -h ./mach mochitest -f plain --total-chunks=16 --this-chunk=1 --headless
hotsphink commentedon Dec 2, 2017
Also note that the process it crashed on is not the one with the crash bug I'm looking for. So far at least, this recording appears to be fully usable for debugging.
\o/
rocallahan commentedon Jan 23, 2018
Sorry for dropping this on the floor :-(.
It appears we took a
TIME_SLICE_SIGNALjust after a bufferedpoll()syscall and recorded theSCHEDevent while we're still in the syscallbuf code. This should not have happened; signal processing should have been deferred until after we leave syscallbuf.I can't reproduce this with a simple synthetic stress test.
Sorry @hotsphink, I assume the conditions that caused this are long gone. It would have been hard to debug anyway because you would probably not have been able to reproduce it.
yshui commentedon Jun 12, 2018
I'm seeing exactly this right now. @rocallahan
khuey commentedon Jun 12, 2018
@yshui please file a new issue and note the rr revision you're using, steps to reproduce if any, etc
yshui commentedon Jun 12, 2018
@khuey I noticed that rr is storing some Task related data (syscallbuf ?) inside the child process. Could those data be trashed when the child process do OOB memory access?
yshui commentedon Jun 12, 2018
@khuey passing
-nseems to prevent the assertion failurekhuey commentedon Jun 12, 2018
Please file a new issue to discuss this.