rr-debugger / rr-debugger/rr

Assertion `!syscall_bp_vm' failed to hold.

Open
#2,292 30 comments 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

Dominant language
C++
Stars
10.7k
Forks
662
Avg merge
2d 3h
Merged PRs (30d)
2

Description

I see a similar assertion triggered as in https://github.com/mozilla/rr/issues/2286 during working with ArangoDB - this is the transcript of the rr session when it goes bad:

 (task 19660 (rec:21979) at time 578188)
 -> Assertion `!syscall_bp_vm' failed to hold. 
Tail of trace dump:
{
  real_time:4261049.062783 global_time:578168, event:`SYSCALLBUF_FLUSH' tid:21985, ticks:3288283
  { syscall:'futex', ret:0x0, size:0x14 }
  { syscall:'gettimeofday', ret:0x0, size:0x20 }
}
{
  real_time:4261049.062806 global_time:578169, event:`SYSCALL: futex' (state:ENTERING_SYSCALL) tid:21985, ticks:3288283
rax:0xffffffffffffffda rbx:0xca rcx:0xffffffffffffffff rdx:0x0 rsi:0x189 rdi:0x7efd4b1f8fc0 rbp:0x0 rsp:0x7efd49d15de0 r8:0x0 r9:0xffffffff r10:0x7efd4a513bc0 r11:0x246 r12:0x0 r13:0x7efd49d15fa0 r14:0x7efd4a513bc0 r15:0x7efd4b1f8fc8 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xca fs_base:0x7efd4a516700 gs_base:0x0
}
{
  real_time:4261049.062824 global_time:578170, event:`SYSCALLBUF_RESET' tid:21985, ticks:3288283
}
{
  real_time:4261049.076245 global_time:578171, event:`SYSCALL: poll' (state:EXITING_SYSCALL) tid:22772, ticks:785172344
rax:0x1 rbx:0x0 rcx:0xffffffffffffffff rdx:0x1f4 rsi:0x1 rdi:0x7efd2e8f12d8 rbp:0x1f4 rsp:0x7efd2e0f5de0 r8:0x0 r9:0x0 r10:0x4000 r11:0x246 r12:0x7efd2ddf6086 r13:0x7efd2e0f5fa0 r14:0x7efd2ddf607e r15:0x7efd2ddf6000 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x7 fs_base:0x7efd2e8f6700 gs_base:0x0
  { tid:22772, addr:0x7efd2e8f12d8, length:0x8 }
}
{
  real_time:4261049.076567 global_time:578172, event:`SYSCALL: getsockopt' (state:ENTERING_SYSCALL) tid:22772, ticks:785172362
rax:0xffffffffffffffda rbx:0x37 rcx:0xffffffffffffffff rdx:0x4 rsi:0x1 rdi:0x4 rbp:0x7efd2e8f13d0 rsp:0x7efd2e0f5de0 r8:0x7efd2e8f13bc r9:0x0 r10:0x7efd2e8f13b8 r11:0x246 r12:0x7efd2e8f2090 r13:0x7efd2e0f5fa0 r14:0x7efd2e8f1528 r15:0x7efd42cbd4e0 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x37 fs_base:0x7efd2e8f6700 gs_base:0x0
}
{
  real_time:4261049.076665 global_time:578173, event:`SYSCALL: getsockopt' (state:EXITING_SYSCALL) tid:22772, ticks:785172362
rax:0x0 rbx:0x37 rcx:0xffffffffffffffff rdx:0x4 rsi:0x1 rdi:0x4 rbp:0x7efd2e8f13d0 rsp:0x7efd2e0f5de0 r8:0x7efd2e8f13bc r9:0x0 r10:0x7efd2e8f13b8 r11:0x246 r12:0x7efd2e8f2090 r13:0x7efd2e0f5fa0 r14:0x7efd2e8f1528 r15:0x7efd42cbd4e0 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x37 fs_base:0x7efd2e8f6700 gs_base:0x0
  { tid:22772, addr:0x7efd2e8f13bc, length:0x4 }
  { tid:22772, addr:0x7efd2e8f13b8, length:0x4 }
}
{
  real_time:4261049.077010 global_time:578174, event:`SYSCALLBUF_FLUSH' tid:22772, ticks:785172531
  { syscall:'read', ret:0x1fff, size:0x200f }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'poll', ret:0x1, size:0x18 }
}
{
  real_time:4261049.077043 global_time:578175, event:`SYSCALL: getsockopt' (state:ENTERING_SYSCALL) tid:22772, ticks:785172531
rax:0xffffffffffffffda rbx:0x37 rcx:0xffffffffffffffff rdx:0x4 rsi:0x1 rdi:0x4 rbp:0x7efd2e8f13d0 rsp:0x7efd2e0f5de0 r8:0x7efd2e8f13bc r9:0x7efd4c4b38c0 r10:0x7efd2e8f13b8 r11:0x246 r12:0x7efd2e8f2090 r13:0x7efd2e0f5fa0 r14:0x7efd2e8f1528 r15:0x7efd42cbd4e0 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x37 fs_base:0x7efd2e8f6700 gs_base:0x0
}
{
  real_time:4261049.077071 global_time:578176, event:`SYSCALLBUF_RESET' tid:22772, ticks:785172531
}
{
  real_time:4261049.077169 global_time:578177, event:`SYSCALL: getsockopt' (state:EXITING_SYSCALL) tid:22772, ticks:785172531
rax:0x0 rbx:0x37 rcx:0xffffffffffffffff rdx:0x4 rsi:0x1 rdi:0x4 rbp:0x7efd2e8f13d0 rsp:0x7efd2e0f5de0 r8:0x7efd2e8f13bc r9:0x7efd4c4b38c0 r10:0x7efd2e8f13b8 r11:0x246 r12:0x7efd2e8f2090 r13:0x7efd2e0f5fa0 r14:0x7efd2e8f1528 r15:0x7efd42cbd4e0 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x37 fs_base:0x7efd2e8f6700 gs_base:0x0
  { tid:22772, addr:0x7efd2e8f13bc, length:0x4 }
  { tid:22772, addr:0x7efd2e8f13b8, length:0x4 }
}
{
  real_time:4261049.079935 global_time:578178, event:`SYSCALLBUF_FLUSH' tid:22772, ticks:785510960
  { syscall:'read', ret:0x939, size:0x949 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'poll', ret:0x0, size:0x18 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'futex', ret:0x1, size:0x14 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
}
{
  real_time:4261049.079951 global_time:578179, event:`SCHED' tid:22772, ticks:785510960
rax:0xc24 rbx:0x7efd4387b04e rcx:0x10 rdx:0x7efd4387d276 rsi:0xc00 rdi:0x7efd4387b051 rbp:0x7efd2e8f2460 rsp:0x7efd2e8f2438 r8:0x7efd4387d274 r9:0x7efd4387d276 r10:0xc r11:0x0 r12:0x55aada47f380 r13:0x7efd4387b051 r14:0x7efd2e8f2760 r15:0x1 rip:0x55aad914d4eb eflags:0x202 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xffffffffffffff09 fs_base:0x7efd2e8f6700 gs_base:0x0
}
{
  real_time:4261049.079968 global_time:578180, event:`SYSCALLBUF_RESET' tid:22772, ticks:785510960
}
{
  real_time:4261049.080014 global_time:578181, event:`SYSCALL: futex' (state:EXITING_SYSCALL) tid:21979, ticks:486141
rax:0x0 rbx:0xca rcx:0xffffffffffffffff rdx:0x0 rsi:0x80 rdi:0x7efd4c4ba034 rbp:0x0 rsp:0x7efd4b6b1de0 r8:0x0 r9:0x0 r10:0x0 r11:0x246 r12:0xb1 r13:0x7efd4b6b1fa0 r14:0x0 r15:0x7efd4c4ba034 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xca fs_base:0x7efd4beb2700 gs_base:0x0
}
{
  real_time:4261049.080660 global_time:578182, event:`SYSCALLBUF_FLUSH' tid:21979, ticks:492881
  { syscall:'gettimeofday', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'madvise', ret:0xffffffffffffffea, size:0x10 }
  { syscall:'madvise', ret:0x0, size:0x10 }
  { syscall:'madvise', ret:0xffffffffffffffea, size:0x10 }
  { syscall:'madvise', ret:0x0, size:0x10 }
  { syscall:'madvise', ret:0xffffffffffffffea, size:0x10 }
  { syscall:'madvise', ret:0x0, size:0x10 }
  { syscall:'madvise', ret:0xffffffffffffffea, size:0x10 }
  { syscall:'madvise', ret:0x0, size:0x10 }
  { syscall:'madvise', ret:0xffffffffffffffea, size:0x10 }
}
{
  real_time:4261049.080672 global_time:578183, event:`SCHED' tid:21979, ticks:492881
rax:0x1c rbx:0xd0 rcx:0xffffffffffffffff rdx:0x4 rsi:0x3000 rdi:0x7efd4361e000 rbp:0x7efd4b2b2000 rsp:0x7efd4b6b1de0 r8:0x0 r9:0x0 r10:0x0 r11:0x246 r12:0x7efd4c4b3980 r13:0x7efd4b6b1fa0 r14:0x7efd4b2b20fe r15:0x4000 rip:0x70000006 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xffffffffffffff09 fs_base:0x7efd4beb2700 gs_base:0x0
}
{
  real_time:4261049.080697 global_time:578184, event:`SYSCALLBUF_RESET' tid:21979, ticks:492881
}
{
  real_time:4261049.081679 global_time:578185, event:`SYSCALLBUF_FLUSH' tid:22772, ticks:785709062
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
}
{
  real_time:4261049.081705 global_time:578186, event:`SYSCALL: futex' (state:ENTERING_SYSCALL) tid:22772, ticks:785709062
rax:0xffffffffffffffda rbx:0xca rcx:0xffffffffffffffff rdx:0x0 rsi:0x80 rdi:0x7efd42b00110 rbp:0x0 rsp:0x7efd2e0f5de0 r8:0x0 r9:0x43d r10:0x0 r11:0x246 r12:0xc44 r13:0x7efd2e0f5fa0 r14:0x0 r15:0x7efd42b00110 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xca fs_base:0x7efd2e8f6700 gs_base:0x0
}
{
  real_time:4261049.081722 global_time:578187, event:`SYSCALLBUF_RESET' tid:22772, ticks:785709062
}
{
  real_time:4261049.081975 global_time:578188, event:`SYSCALL: write' (state:ENTERING_SYSCALL) tid:21979, ticks:492882
rax:0xffffffffffffffda rbx:0x7efd4b2b2000 rcx:0xffffffffffffffff rdx:0x4f rsi:0x7efd4d185725 rdi:0x2 rbp:0x7efd4beb00d0 rsp:0x7efd4b6b1e80 r8:0x0 r9:0x0 r10:0x0 r11:0x246 r12:0x7efd4c4b3980 r13:0x7efd4beb0178 r14:0x0 r15:0x7efd4b2b201e rip:0x70000005 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x1 fs_base:0x7efd4beb2700 gs_base:0x0
}
{
  real_time:4261049.082094 global_time:578189, event:`SYSCALL: write' (state:EXITING_SYSCALL) tid:21979, ticks:492882
rax:0x4f rbx:0x7efd4b2b2000 rcx:0xffffffffffffffff rdx:0x4f rsi:0x7efd4d185725 rdi:0x2 rbp:0x7efd4beb00d0 rsp:0x7efd4b6b1e80 r8:0x0 r9:0x0 r10:0x0 r11:0x246 r12:0x7efd4c4b3980 r13:0x7efd4beb0178 r14:0x0 r15:0x7efd4b2b201e rip:0x70000005 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x1 fs_base:0x7efd4beb2700 gs_base:0x0
}
=== Start rr backtrace:
rr(_ZN2rr13dump_rr_stackEv+0x37)[0x80dc67]
rr(_ZN2rr9GdbServer15emergency_debugEPNS_4TaskE+0x1c8)[0x687f38]
rr[0x6b0e35]
rr(_ZN2rr21EmergencyDebugOstreamD2Ev+0x72)[0x6b0c52]
rr(_ZN2rr13ReplaySession13enter_syscallEPNS_10ReplayTaskERKNS0_15StepConstraintsE+0x8b9)[0x770b49]
rr(_ZN2rr13ReplaySession18try_one_trace_stepEPNS_10ReplayTaskERKNS0_15StepConstraintsE+0xce)[0x774ade]
rr(_ZN2rr13ReplaySession11replay_stepERKNS0_15StepConstraintsE+0x1ac)[0x775fcc]
rr(_ZN2rr14ReplayTimeline19replay_step_forwardENS_10RunCommandEl+0x111)[0x795931]
rr(_ZN2rr9GdbServer14debug_one_stepERNS_10GdbRequestE+0x86c)[0x6847cc]
rr(_ZN2rr9GdbServer12serve_replayERKNS0_15ConnectionFlagsE+0x627)[0x685e57]
rr[0x76b58c]
rr(_ZN2rr13ReplayCommand3runERSt6vectorINSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEESaIS7_EE+0x500)[0x76a2a0]
rr(main+0x320)[0x825340]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xe7)[0x7f27a348eb17]
rr(_start+0x2a)[0x5ef49a]

The backtrace from gdb:

gdb> bt full 
#0  0x0000000070000008 in ?? ()
No symbol table info available.
#1  0x00007efd4d164d15 in _raw_syscall () from /usr/local/bin/../lib/rr/librrpreload.so
No symbol table info available.
#2  0x00007efd4d162333 in untraced_syscall_base (syscallno=28, a0=<optimized out>, a1=<optimized out>, a2=-1, a3=0, a4=0, a5=0, syscall_instruction=<optimized out>) at ../src/preload/syscallbuf.c:311
        rec = <optimized out>
        ret = <optimized out>
        tmp_in_replay = <optimized out>
#3  sys_madvise (call=<optimized out>) at ../src/preload/syscallbuf.c:1648
        length = <optimized out>
        advice = <optimized out>
        ptr = 0x7efd4b2b20fe
        ret = <optimized out>
        addr = <optimized out>
        s = <optimized out>
#4  syscall_hook_internal (call=0x7efd4b6b1fa0) at ../src/preload/syscallbuf.c:2793
No locals.
#5  0x00007efd4d15f931 in syscall_hook (call=0x7efd4b6b1fa0) at ../src/preload/syscallbuf.c:2896
        result = <optimized out>
#6  0x00007efd4d15f09a in _syscall_hook_trampoline () from /usr/local/bin/../lib/rr/librrpreload.so
No symbol table info available.
#7  0x00007efd4d15f0ca in __morestack () from /usr/local/bin/../lib/rr/librrpreload.so
No symbol table info available.
#8  0x00007efd4d15f0d0 in _syscall_hook_trampoline_48_3d_01_f0_ff_ff () from /usr/local/bin/../lib/rr/librrpreload.so
No symbol table info available.
#9  0x00007efd4c931dfd in madvise () at ../sysdeps/unix/syscall-template.S:78
No locals.
#10 0x000055aad9e191ce in je_pages_purge_forced (addr=<optimized out>, size=<optimized out>) at src/pages.c:280
No locals.
#11 0x000055aad9e13b2e in je_extent_dalloc_wrapper (extent=0x7efd4c0f0840, r_extent_hooks=0x7efd4beb0178, arena=<optimized out>, tsdn=0x7efd4beb0bf8) at include/jemalloc/internal/extent_inlines.h:125
        zeroed = <optimized out>
        zeroed = <optimized out>
#12 je_extent_dalloc_wrapper (tsdn=tsdn@entry=0x7efd4beb0bf8, arena=arena@entry=0x7efd4c4b3980, r_extent_hooks=r_extent_hooks@entry=0x7efd4beb0178, extent=extent@entry=0x7efd4c0f0840) at src/extent.c:1521
        zeroed = <optimized out>
#13 0x000055aad9ddf263 in arena_decay_stashed (is_background_thread=<optimized out>, decay_extents=<synthetic pointer>, all=<optimized out>, extents=0x7efd4c4b55e8, decay=0x7efd4c4b6a88, r_extent_hooks=0x7efd4beb0178, arena=0x7efd4c4b3980, tsdn=0x7efd4beb0bf8) at src/arena.c:956
        npages = 3
        extent = 0x7efd4c0f0840
        nmadvise = 5
        nunmapped = 12
        npurged = 15
        muzzy_decay_ms = <optimized out>
        nmadvise = <optimized out>
        nunmapped = <optimized out>
        npurged = <optimized out>
        muzzy_decay_ms = <optimized out>
        extent = <optimized out>
        npages = <optimized out>
#14 arena_decay_to_limit (tsdn=tsdn@entry=0x7efd4beb0bf8, arena=arena@entry=0x7efd4c4b3980, decay=decay@entry=0x7efd4c4b6a88, extents=extents@entry=0x7efd4c4b55e8, all=all@entry=false, npages_limit=<optimized out>, is_background_thread=true) at src/arena.c:1010
        npurged = <optimized out>
        extent_hooks = 0x55aadab55840 <je_extent_hooks_default>
        decay_extents = {qlh_first = 0x7efd4c0f5ac0}
        npurge = <optimized out>
#15 0x000055aad9ddf939 in arena_decay_try_purge (is_background_thread=<optimized out>, npages_limit=<optimized out>, current_npages=<optimized out>, extents=<optimized out>, decay=<optimized out>, arena=<optimized out>, tsdn=<optimized out>) at src/arena.c:694
No locals.
#16 arena_maybe_decay (tsdn=tsdn@entry=0x7efd4beb0bf8, arena=arena@entry=0x7efd4c4b3980, decay=decay@entry=0x7efd4c4b6a88, extents=extents@entry=0x7efd4c4b55e8, is_background_thread=is_background_thread@entry=true) at src/arena.c:839
        decay_ms = <optimized out>
        time = {ns = 4261049077121149}
        advance_epoch = false
#17 0x000055aad9de189a in arena_maybe_decay (is_background_thread=true, extents=0x7efd4c4b6a88, decay=0x7efd4c4b6a88, arena=0x7efd4c4b3980, tsdn=0x7efd4beb0bf8) at src/arena.c:798
        decay_ms = <optimized out>
        time = <optimized out>
        advance_epoch = <optimized out>
        decay_ms = <optimized out>
        time = <optimized out>
        advance_epoch = <optimized out>
#18 arena_decay_impl (all=<optimized out>, is_background_thread=true, extents=0x7efd4c4b6a88, decay=0x7efd4c4b6a88, arena=0x7efd4c4b3980, tsdn=0x7efd4beb0bf8) at src/arena.c:1037
        epoch_advanced = <optimized out>
        npages_new = <optimized out>
        epoch_advanced = <optimized out>
        npages_new = <optimized out>
#19 arena_decay_dirty (all=<optimized out>, is_background_thread=true, arena=0x7efd4c4b3980, tsdn=0x7efd4beb0bf8) at src/arena.c:1057
No locals.
#20 je_arena_decay (tsdn=0x7efd4beb0bf8, arena=0x7efd4c4b3980, is_background_thread=true, all=<optimized out>) at src/arena.c:1070
No locals.
#21 0x000055aad9de76b5 in background_work_sleep_once (ind=0, info=<optimized out>, tsdn=<optimized out>) at src/background_thread.c:294
        arena = 0x7efd4c4b3980
        interval = <optimized out>
        i = 0
        min_interval = 18446744073709551615
        narenas = 1
        min_interval = <optimized out>
        narenas = <optimized out>
        i = <optimized out>
        arena = <optimized out>
        interval = <optimized out>
#22 background_thread0_work (tsd=<optimized out>) at src/background_thread.c:450
        created_threads = 0x7efd4beb02a0
        i = 1
        n_created = 1
        created_threads = <optimized out>
        i = <optimized out>
        n_created = <optimized out>
        info = <optimized out>
#23 background_work (ind=<optimized out>, tsd=<optimized out>) at src/background_thread.c:483
        info = <optimized out>
        info = <optimized out>
#24 background_thread_entry () at src/background_thread.c:513
        thread_ind = <optimized out>
#25 0x00007efd4cd36f2a in start_thread (arg=0x7efd4beb2700) at pthread_create.c:463
        pd = 0x7efd4beb2700
        now = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {139626365527808, 9152745134204300188, 140731180643582, 140731180643583, 140731180643584, 0, -9007336819256284260, -9007326170654790756}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
#26 0x00007efd4c936edf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
No locals.

Contributor guide

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Start by comparing this failure with issue 2286 and reproducing the ArangoDB rr session from the supplied trace. Inspect src/ReplaySession.cc at enter_syscall() and the madvise path in src/preload/syscallbuf.c; done means identifying the cause and confirming that replay no longer reaches the assertion.

Written by the indexing model from the issue text.

Assessment

Tech stack
cpp, linux
Domain
devtools, operating-systems
Issue type
Bug
Difficulty
5/5
Estimated time
Over a week
Activity status
Stale
Clarity
Needs clarification
Newbie friendliness
20/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.