Assertion `rt->fd_table()->get_monitor(f.fd)->type() == FileMonitor::Type::Mmapped' failed to hold

Open

#2,518 opened on Apr 19, 2020 1 comment 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

Steps to reproduce

Make sure perf utility is installed.
Run sudo rr record perf trace sleep 1

Expected

No rr assertion

Actual

rr: Saving execution to trace directory `/root/.local/share/rr/perf-3'.
[FATAL /home/constantine/Projects/builds/rr-git/src/rr/src/record_syscall.cc:4903:process_mmap()] 
 (task 60240 (rec:60240) at time 1466)
 -> Assertion `rt->fd_table()->get_monitor(f.fd)->type() == FileMonitor::Type::Mmapped' failed to hold. 
Tail of trace dump:
{
  real_time:62512.038288 global_time:1446, event:`SYSCALL: perf_event_open' (state:ENTERING_SYSCALL) tid:60240, ticks:58846775
rax:0xffffffffffffffda rbx:0x12a rcx:0xffffffffffffffff rdx:0x1 rsi:0xeb52 rdi:0x55e65192d2f0 rbp:0x681fffa0 rsp:0x681ffdf0 r8:0x8 r9:0x0 r10:0xffffffff r11:0x246 r12:0x8 r13:0xeb52 r14:0x55e65192d2e0 r15:0xffffffff rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x12a fs_base:0x7f9971c28780 gs_base:0x0
}
{
  real_time:62512.038433 global_time:1447, event:`SYSCALL: perf_event_open' (state:EXITING_SYSCALL) tid:60240, ticks:58846775
rax:0x4 rbx:0x12a rcx:0xffffffffffffffff rdx:0x1 rsi:0xeb52 rdi:0x55e65192d2f0 rbp:0x681fffa0 rsp:0x681ffdf0 r8:0x8 r9:0x0 r10:0xffffffff r11:0x246 r12:0x8 r13:0xeb52 r14:0x55e65192d2e0 r15:0xffffffff rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x12a fs_base:0x7f9971c28780 gs_base:0x0
}
{
  real_time:62512.038489 global_time:1448, event:`SYSCALL: perf_event_open' (state:ENTERING_SYSCALL) tid:60240, ticks:58846807
rax:0xffffffffffffffda rbx:0x12a rcx:0xffffffffffffffff rdx:0x2 rsi:0xeb52 rdi:0x55e65192d2f0 rbp:0x681fffa0 rsp:0x681ffdf0 r8:0x8 r9:0x0 r10:0xffffffff r11:0x246 r12:0x8 r13:0xeb52 r14:0x55e65192d2e0 r15:0xffffffff rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x12a fs_base:0x7f9971c28780 gs_base:0x0
}
{
  real_time:62512.038617 global_time:1449, event:`SYSCALL: perf_event_open' (state:EXITING_SYSCALL) tid:60240, ticks:58846807
rax:0x5 rbx:0x12a rcx:0xffffffffffffffff rdx:0x2 rsi:0xeb52 rdi:0x55e65192d2f0 rbp:0x681fffa0 rsp:0x681ffdf0 r8:0x8 r9:0x0 r10:0xffffffff r11:0x246 r12:0x8 r13:0xeb52 r14:0x55e65192d2e0 r15:0xffffffff rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x12a fs_base:0x7f9971c28780 gs_base:0x0
}
{
  real_time:62512.038670 global_time:1450, event:`SYSCALL: perf_event_open' (state:ENTERING_SYSCALL) tid:60240, ticks:58846839
rax:0xffffffffffffffda rbx:0x12a rcx:0xffffffffffffffff rdx:0x3 rsi:0xeb52 rdi:0x55e65192d2f0 rbp:0x681fffa0 rsp:0x681ffdf0 r8:0x8 r9:0x0 r10:0xffffffff r11:0x246 r12:0x8 r13:0xeb52 r14:0x55e65192d2e0 r15:0xffffffff rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x12a fs_base:0x7f9971c28780 gs_base:0x0
}
{
  real_time:62512.038740 global_time:1451, event:`SYSCALL: perf_event_open' (state:EXITING_SYSCALL) tid:60240, ticks:58846839
rax:0x7 rbx:0x12a rcx:0xffffffffffffffff rdx:0x3 rsi:0xeb52 rdi:0x55e65192d2f0 rbp:0x681fffa0 rsp:0x681ffdf0 r8:0x8 r9:0x0 r10:0xffffffff r11:0x246 r12:0x8 r13:0xeb52 r14:0x55e65192d2e0 r15:0xffffffff rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x12a fs_base:0x7f9971c28780 gs_base:0x0
}
{
  real_time:62512.038795 global_time:1452, event:`SYSCALL: perf_event_open' (state:ENTERING_SYSCALL) tid:60240, ticks:58846954
rax:0xffffffffffffffda rbx:0x12a rcx:0xffffffffffffffff rdx:0x0 rsi:0xeb52 rdi:0x55e65192fd50 rbp:0x681fffa0 rsp:0x681ffdf0 r8:0x8 r9:0x0 r10:0xffffffff r11:0x246 r12:0x8 r13:0xeb52 r14:0x55e65192fd40 r15:0xffffffff rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x12a fs_base:0x7f9971c28780 gs_base:0x0
}
{
  real_time:62512.038881 global_time:1453, event:`SYSCALL: perf_event_open' (state:EXITING_SYSCALL) tid:60240, ticks:58846954
rax:0x8 rbx:0x12a rcx:0xffffffffffffffff rdx:0x0 rsi:0xeb52 rdi:0x55e65192fd50 rbp:0x681fffa0 rsp:0x681ffdf0 r8:0x8 r9:0x0 r10:0xffffffff r11:0x246 r12:0x8 r13:0xeb52 r14:0x55e65192fd40 r15:0xffffffff rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x12a fs_base:0x7f9971c28780 gs_base:0x0
}
{
  real_time:62512.038937 global_time:1454, event:`SYSCALL: perf_event_open' (state:ENTERING_SYSCALL) tid:60240, ticks:58846986
rax:0xffffffffffffffda rbx:0x12a rcx:0xffffffffffffffff rdx:0x1 rsi:0xeb52 rdi:0x55e65192fd50 rbp:0x681fffa0 rsp:0x681ffdf0 r8:0x8 r9:0x0 r10:0xffffffff r11:0x246 r12:0x8 r13:0xeb52 r14:0x55e65192fd40 r15:0xffffffff rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x12a fs_base:0x7f9971c28780 gs_base:0x0
}
{
  real_time:62512.039005 global_time:1455, event:`SYSCALL: perf_event_open' (state:EXITING_SYSCALL) tid:60240, ticks:58846986
rax:0x9 rbx:0x12a rcx:0xffffffffffffffff rdx:0x1 rsi:0xeb52 rdi:0x55e65192fd50 rbp:0x681fffa0 rsp:0x681ffdf0 r8:0x8 r9:0x0 r10:0xffffffff r11:0x246 r12:0x8 r13:0xeb52 r14:0x55e65192fd40 r15:0xffffffff rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x12a fs_base:0x7f9971c28780 gs_base:0x0
}
{
  real_time:62512.039058 global_time:1456, event:`SYSCALL: perf_event_open' (state:ENTERING_SYSCALL) tid:60240, ticks:58847018
rax:0xffffffffffffffda rbx:0x12a rcx:0xffffffffffffffff rdx:0x2 rsi:0xeb52 rdi:0x55e65192fd50 rbp:0x681fffa0 rsp:0x681ffdf0 r8:0x8 r9:0x0 r10:0xffffffff r11:0x246 r12:0x8 r13:0xeb52 r14:0x55e65192fd40 r15:0xffffffff rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x12a fs_base:0x7f9971c28780 gs_base:0x0
}
{
  real_time:62512.039121 global_time:1457, event:`SYSCALL: perf_event_open' (state:EXITING_SYSCALL) tid:60240, ticks:58847018
rax:0xa rbx:0x12a rcx:0xffffffffffffffff rdx:0x2 rsi:0xeb52 rdi:0x55e65192fd50 rbp:0x681fffa0 rsp:0x681ffdf0 r8:0x8 r9:0x0 r10:0xffffffff r11:0x246 r12:0x8 r13:0xeb52 r14:0x55e65192fd40 r15:0xffffffff rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x12a fs_base:0x7f9971c28780 gs_base:0x0
}
{
  real_time:62512.039174 global_time:1458, event:`SYSCALL: perf_event_open' (state:ENTERING_SYSCALL) tid:60240, ticks:58847050
rax:0xffffffffffffffda rbx:0x12a rcx:0xffffffffffffffff rdx:0x3 rsi:0xeb52 rdi:0x55e65192fd50 rbp:0x681fffa0 rsp:0x681ffdf0 r8:0x8 r9:0x0 r10:0xffffffff r11:0x246 r12:0x8 r13:0xeb52 r14:0x55e65192fd40 r15:0xffffffff rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x12a fs_base:0x7f9971c28780 gs_base:0x0
}
{
  real_time:62512.039236 global_time:1459, event:`SYSCALL: perf_event_open' (state:EXITING_SYSCALL) tid:60240, ticks:58847050
rax:0xb rbx:0x12a rcx:0xffffffffffffffff rdx:0x3 rsi:0xeb52 rdi:0x55e65192fd50 rbp:0x681fffa0 rsp:0x681ffdf0 r8:0x8 r9:0x0 r10:0xffffffff r11:0x246 r12:0x8 r13:0xeb52 r14:0x55e65192fd40 r15:0xffffffff rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x12a fs_base:0x7f9971c28780 gs_base:0x0
}
{
  real_time:62512.039417 global_time:1460, event:`SYSCALLBUF_FLUSH' tid:60240, ticks:58847990
  { syscall:'openat', ret:0xc, size:0x10 }
  { syscall:'readlink', ret:0x24, size:0x34 }
  { syscall:'read', ret:0x4, size:0x14 }
  { syscall:'close', ret:0x0, size:0x10 }
}
{
  real_time:62512.039498 global_time:1461, event:`PATCH_SYSCALL' tid:60240, ticks:58847990
rax:0x9 rbx:0x22 rcx:0xffffffffffffffff rdx:0x3 rsi:0x41000 rdi:0x0 rbp:0x0 rsp:0x7ffe71d68af8 r8:0xffffffff r9:0x0 r10:0x22 r11:0x246 r12:0x41000 r13:0x1000 r14:0x4 r15:0x4031 rip:0x7f9971d5b134 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xffffffffffffffff fs_base:0x7f9971c28780 gs_base:0x0
  { tid:60240, addr:0x7f9972ade860, length:0x4f }
  { tid:60240, addr:0x7f9971d5b134, length:0x5 }
  { tid:60240, addr:0x7f9971d5b139, length:0x3 }
}
{
  real_time:62512.039503 global_time:1462, event:`SYSCALLBUF_RESET' tid:60240, ticks:58847990
}
{
  real_time:62512.039557 global_time:1463, event:`SYSCALL: mmap' (state:ENTERING_SYSCALL) tid:60240, ticks:58847996
rax:0xffffffffffffffda rbx:0x9 rcx:0xffffffffffffffff rdx:0x3 rsi:0x41000 rdi:0x0 rbp:0x681fffa0 rsp:0x681ffdf0 r8:0xffffffff r9:0x0 r10:0x22 r11:0x246 r12:0x41000 r13:0x1000 r14:0x4 r15:0x4031 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x9 fs_base:0x7f9971c28780 gs_base:0x0
}
{
  real_time:62512.039608 global_time:1464, event:`SYSCALL: mmap' (state:EXITING_SYSCALL) tid:60240, ticks:58847996
rax:0x7f9972a5a000 rbx:0x9 rcx:0xffffffffffffffff rdx:0x3 rsi:0x41000 rdi:0x0 rbp:0x681fffa0 rsp:0x681ffdf0 r8:0xffffffff r9:0x0 r10:0x22 r11:0x246 r12:0x41000 r13:0x1000 r14:0x4 r15:0x4031 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x9 fs_base:0x7f9971c28780 gs_base:0x0
  { map_file:"<ZERO>", addr:0x7f9972a5a000, length:0x41000, prot_flags:"rw-p", file_offset:0x0, device:0, inode:0, data_file:"", data_offset:0x0, file_size:0x41000 }
}
{
  real_time:62512.039680 global_time:1465, event:`SYSCALL: mmap' (state:ENTERING_SYSCALL) tid:60240, ticks:58848243
rax:0xffffffffffffffda rbx:0x9 rcx:0xffffffffffffffff rdx:0x3 rsi:0x81000 rdi:0x0 rbp:0x681fffa0 rsp:0x681ffdf0 r8:0x3 r9:0x0 r10:0x1 r11:0x246 r12:0x0 r13:0x3 r14:0x3 r15:0x3 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x9 fs_base:0x7f9971c28780 gs_base:0x0
}
=== Start rr backtrace:
rr(_ZN2rr13dump_rr_stackEv+0x41)[0x55e9f0cfa681]
rr(_ZN2rr9GdbServer15emergency_debugEPNS_4TaskE+0x7d5)[0x55e9f0befe85]
rr(+0xbb349)[0x55e9f0bff349]
rr(_ZN2rr21EmergencyDebugOstreamD2Ev+0x75)[0x55e9f0bff6f5]
rr(+0x10e7c7)[0x55e9f0c527c7]
rr(+0x115a4b)[0x55e9f0c59a4b]
rr(_ZN2rr19rec_process_syscallEPNS_10RecordTaskE+0x1c8)[0x55e9f0c5cc28]
rr(_ZN2rr13RecordSession21syscall_state_changedEPNS_10RecordTaskEPNS0_9StepStateE+0xbb1)[0x55e9f0c2ee01]
rr(_ZN2rr13RecordSession11record_stepEv+0x524)[0x55e9f0c33ff4]
rr(_ZN2rr13RecordCommand3runERSt6vectorINSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEESaIS7_EE+0x10e5)[0x55e9f0c27995]
rr(main+0x30a)[0x55e9f0b9808a]
/usr/lib/libc.so.6(__libc_start_main+0xf3)[0x7f764222e023]
rr(_start+0x2e)[0x55e9f0b981be]
=== End rr backtrace
Launch gdb with
  gdb '-l' '10000' '-ex' 'set sysroot /' '-ex' 'target extended-remote 127.0.0.1:60240' /usr/bin/perf

FWIW, launching gdb with the command at the end of the trace and looking at bt, gives just:

gdb λ bt
#0  0x0000000070000002 in _start () from /lib64/ld-linux-x86-64.so.2
#1  0x00007ff4feb6f7e3 in ?? ()
#2  0x0000000000000000 in ?? ()

Versions

Kernel: 5.6.4-arch1-1
rr: latest git, commit 9cc1b4a2

Contributor guide

Open the contributing guide

First steps

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

Research direction

Reproduce the failure with sudo rr record perf trace sleep 1, then start in src/rr/src/record_syscall.cc at process_mmap() around the reported assertion. Trace the perf_event_open and mmap handling shown in the dump; done means the command records without triggering the assertion.

Written by the indexing model from the issue text.

Assessment

Tech stack: cpp, linux
Domain: devtools, operating-systems
Issue type: Bug
Difficulty: 4/5
Estimated time: 3-5 days
Activity status: Stale
Clarity: Mostly clear
Newbie friendliness: 35/100