rr-debugger / rr-debugger/rr

Should have read 8 bytes from 0x68000000, but only read -1

Open
#3,092 2 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 got an assertion failure of read_bytes_helper:

[INFO log_pending_events()] SYSCALL: read
[INFO log_pending_events()] (none)
[RecordSession] EXEC_SYSCALL_DONE: status=0x857f (SYSCALL)
[RecordSession]   original_syscallno:0 (read); return val:0xfffffffffffffff2
[record_syscall] 119139: processing: SYSCALL: read -- time: 30937
[FATAL /home/zyh/rr/src/Task.cc:2832:read_bytes_helper() errno: EIO] 
 (task 119139 (rec:119139) at time 30937)
 -> Assertion `false' failed to hold. Should have read 8 bytes from 0x68000000, but only read -1
[INFO log_pending_events()] SYSCALL: read
[INFO log_pending_events()] (none)
Tail of trace dump:
[TraceStream] Reading event for 564: parent=119139 tid=119152
[TraceStream] Reading event for 943: parent=119139 tid=119153
[TraceStream] Reading event for 1282: parent=119139 tid=119157
[TraceStream] Reading event for 2097: parent=119139 tid=119158
[TraceStream] Reading event for 2106: parent=119158 tid=119159
[TraceStream] Reading event for 2652: parent=119139 tid=119173
[TraceStream] Reading event for 3209: parent=119173 tid=119185
{
  real_time:113145.025844 global_time:30917, event:`SYSCALL: read' (state:EXITING_SYSCALL) tid:119139, ticks:1910917
rax:0x1 rbx:0x0 rcx:0xffffffffffffffff rdx:0x1 rsi:0x7f8a645dd32b rdi:0x5 rbp:0x7f8a645dd360 rsp:0x7f8a645dd360 r8:0xffffffffffffffff r9:0x0 r10:0x22 r11:0x246 r12:0x11101040 r13:0x7fffffffd8e0 r14:0x0 r15:0x0 rip:0x7f8a625e82df eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x0 fs_base:0x7ffff7d7ab80 gs_base:0x0
  { tid:119139, addr:0x7f8a645dd32b, length:0x1 }
}
{
  real_time:113145.026097 global_time:30918, event:`SYSCALL: read' (state:ENTERING_SYSCALL) tid:119139, ticks:1910922
rax:0xffffffffffffffda rbx:0x0 rcx:0xffffffffffffffff rdx:0x1 rsi:0x7f8a645dd32b rdi:0x5 rbp:0x7f8a645dd360 rsp:0x7f8a645dd360 r8:0xffffffffffffffff r9:0x0 r10:0x22 r11:0x246 r12:0x11101040 r13:0x7fffffffd8e0 r14:0x0 r15:0x0 rip:0x7f8a625e82df eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x0 fs_base:0x7ffff7d7ab80 gs_base:0x0
}
{
  real_time:113145.026341 global_time:30919, event:`SYSCALL: read' (state:EXITING_SYSCALL) tid:119139, ticks:1910922
rax:0x1 rbx:0x0 rcx:0xffffffffffffffff rdx:0x1 rsi:0x7f8a645dd32b rdi:0x5 rbp:0x7f8a645dd360 rsp:0x7f8a645dd360 r8:0xffffffffffffffff r9:0x0 r10:0x22 r11:0x246 r12:0x11101040 r13:0x7fffffffd8e0 r14:0x0 r15:0x0 rip:0x7f8a625e82df eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x0 fs_base:0x7ffff7d7ab80 gs_base:0x0
  { tid:119139, addr:0x7f8a645dd32b, length:0x1 }
}
{
  real_time:113145.026628 global_time:30920, event:`SYSCALL: read' (state:ENTERING_SYSCALL) tid:119139, ticks:1910930
rax:0xffffffffffffffda rbx:0x0 rcx:0xffffffffffffffff rdx:0x1 rsi:0x7f8a645dd32b rdi:0x5 rbp:0x7f8a645dd360 rsp:0x7f8a645dd360 r8:0xffffffffffffffff r9:0x0 r10:0x22 r11:0x246 r12:0x11101040 r13:0x7fffffffd8e0 r14:0x0 r15:0x0 rip:0x7f8a625e82df eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x0 fs_base:0x7ffff7d7ab80 gs_base:0x0
}
{
  real_time:113145.026810 global_time:30921, event:`SYSCALL: read' (state:EXITING_SYSCALL) tid:119139, ticks:1910930
rax:0x1 rbx:0x0 rcx:0xffffffffffffffff rdx:0x1 rsi:0x7f8a645dd32b rdi:0x5 rbp:0x7f8a645dd360 rsp:0x7f8a645dd360 r8:0xffffffffffffffff r9:0x0 r10:0x22 r11:0x246 r12:0x11101040 r13:0x7fffffffd8e0 r14:0x0 r15:0x0 rip:0x7f8a625e82df eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x0 fs_base:0x7ffff7d7ab80 gs_base:0x0
  { tid:119139, addr:0x7f8a645dd32b, length:0x1 }
}
{
  real_time:113145.027020 global_time:30922, event:`SYSCALL: read' (state:ENTERING_SYSCALL) tid:119139, ticks:1910935
rax:0xffffffffffffffda rbx:0x0 rcx:0xffffffffffffffff rdx:0x1 rsi:0x7f8a645dd32b rdi:0x5 rbp:0x7f8a645dd360 rsp:0x7f8a645dd360 r8:0xffffffffffffffff r9:0x0 r10:0x22 r11:0x246 r12:0x11101040 r13:0x7fffffffd8e0 r14:0x0 r15:0x0 rip:0x7f8a625e82df eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x0 fs_base:0x7ffff7d7ab80 gs_base:0x0
}
{
  real_time:113145.027159 global_time:30923, event:`SYSCALL: read' (state:EXITING_SYSCALL) tid:119139, ticks:1910935
rax:0x1 rbx:0x0 rcx:0xffffffffffffffff rdx:0x1 rsi:0x7f8a645dd32b rdi:0x5 rbp:0x7f8a645dd360 rsp:0x7f8a645dd360 r8:0xffffffffffffffff r9:0x0 r10:0x22 r11:0x246 r12:0x11101040 r13:0x7fffffffd8e0 r14:0x0 r15:0x0 rip:0x7f8a625e82df eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x0 fs_base:0x7ffff7d7ab80 gs_base:0x0
  { tid:119139, addr:0x7f8a645dd32b, length:0x1 }
}
{
  real_time:113145.027364 global_time:30924, event:`SYSCALL: read' (state:ENTERING_SYSCALL) tid:119139, ticks:1910940
rax:0xffffffffffffffda rbx:0x0 rcx:0xffffffffffffffff rdx:0x1 rsi:0x7f8a645dd32b rdi:0x5 rbp:0x7f8a645dd360 rsp:0x7f8a645dd360 r8:0xffffffffffffffff r9:0x0 r10:0x22 r11:0x246 r12:0x11101040 r13:0x7fffffffd8e0 r14:0x0 r15:0x0 rip:0x7f8a625e82df eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x0 fs_base:0x7ffff7d7ab80 gs_base:0x0
}
{
  real_time:113145.027495 global_time:30925, event:`SYSCALL: read' (state:EXITING_SYSCALL) tid:119139, ticks:1910940
rax:0x1 rbx:0x0 rcx:0xffffffffffffffff rdx:0x1 rsi:0x7f8a645dd32b rdi:0x5 rbp:0x7f8a645dd360 rsp:0x7f8a645dd360 r8:0xffffffffffffffff r9:0x0 r10:0x22 r11:0x246 r12:0x11101040 r13:0x7fffffffd8e0 r14:0x0 r15:0x0 rip:0x7f8a625e82df eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x0 fs_base:0x7ffff7d7ab80 gs_base:0x0
  { tid:119139, addr:0x7f8a645dd32b, length:0x1 }
}
{
  real_time:113145.027751 global_time:30926, event:`SYSCALL: read' (state:ENTERING_SYSCALL) tid:119139, ticks:1910947
rax:0xffffffffffffffda rbx:0x0 rcx:0xffffffffffffffff rdx:0x1 rsi:0x7f8a645dd32b rdi:0x5 rbp:0x7f8a645dd360 rsp:0x7f8a645dd360 r8:0xffffffffffffffff r9:0x0 r10:0x22 r11:0x246 r12:0x11101040 r13:0x7fffffffd8e0 r14:0x0 r15:0x0 rip:0x7f8a625e82df eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x0 fs_base:0x7ffff7d7ab80 gs_base:0x0
}
{
  real_time:113145.027909 global_time:30927, event:`SYSCALL: read' (state:EXITING_SYSCALL) tid:119139, ticks:1910947
rax:0x1 rbx:0x0 rcx:0xffffffffffffffff rdx:0x1 rsi:0x7f8a645dd32b rdi:0x5 rbp:0x7f8a645dd360 rsp:0x7f8a645dd360 r8:0xffffffffffffffff r9:0x0 r10:0x22 r11:0x246 r12:0x11101040 r13:0x7fffffffd8e0 r14:0x0 r15:0x0 rip:0x7f8a625e82df eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x0 fs_base:0x7ffff7d7ab80 gs_base:0x0
  { tid:119139, addr:0x7f8a645dd32b, length:0x1 }
}
{
  real_time:113145.028157 global_time:30928, event:`SYSCALL: read' (state:ENTERING_SYSCALL) tid:119139, ticks:1910952
rax:0xffffffffffffffda rbx:0x0 rcx:0xffffffffffffffff rdx:0x1 rsi:0x7f8a645dd32b rdi:0x5 rbp:0x7f8a645dd360 rsp:0x7f8a645dd360 r8:0xffffffffffffffff r9:0x0 r10:0x22 r11:0x246 r12:0x11101040 r13:0x7fffffffd8e0 r14:0x0 r15:0x0 rip:0x7f8a625e82df eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x0 fs_base:0x7ffff7d7ab80 gs_base:0x0
}
{
  real_time:113145.028324 global_time:30929, event:`SYSCALL: read' (state:EXITING_SYSCALL) tid:119139, ticks:1910952
rax:0x1 rbx:0x0 rcx:0xffffffffffffffff rdx:0x1 rsi:0x7f8a645dd32b rdi:0x5 rbp:0x7f8a645dd360 rsp:0x7f8a645dd360 r8:0xffffffffffffffff r9:0x0 r10:0x22 r11:0x246 r12:0x11101040 r13:0x7fffffffd8e0 r14:0x0 r15:0x0 rip:0x7f8a625e82df eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x0 fs_base:0x7ffff7d7ab80 gs_base:0x0
  { tid:119139, addr:0x7f8a645dd32b, length:0x1 }
}
{
  real_time:113145.028561 global_time:30930, event:`SYSCALL: read' (state:ENTERING_SYSCALL) tid:119139, ticks:1910957
rax:0xffffffffffffffda rbx:0x0 rcx:0xffffffffffffffff rdx:0x1 rsi:0x7f8a645dd35b rdi:0x5 rbp:0x7f8a645dd390 rsp:0x7f8a645dd390 r8:0xffffffffffffffff r9:0x0 r10:0x22 r11:0x246 r12:0x11101040 r13:0x7fffffffd8e0 r14:0x0 r15:0x0 rip:0x7f8a625e82df eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x0 fs_base:0x7ffff7d7ab80 gs_base:0x0
}
{
  real_time:113145.028748 global_time:30931, event:`SYSCALL: read' (state:EXITING_SYSCALL) tid:119139, ticks:1910957
rax:0x1 rbx:0x0 rcx:0xffffffffffffffff rdx:0x1 rsi:0x7f8a645dd35b rdi:0x5 rbp:0x7f8a645dd390 rsp:0x7f8a645dd390 r8:0xffffffffffffffff r9:0x0 r10:0x22 r11:0x246 r12:0x11101040 r13:0x7fffffffd8e0 r14:0x0 r15:0x0 rip:0x7f8a625e82df eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x0 fs_base:0x7ffff7d7ab80 gs_base:0x0
  { tid:119139, addr:0x7f8a645dd35b, length:0x1 }
}
{
  real_time:113145.028982 global_time:30932, event:`SYSCALL: munmap' (state:ENTERING_SYSCALL) tid:119139, ticks:1911003
rax:0xffffffffffffffda rbx:0x0 rcx:0xffffffffffffffff rdx:0xffffffa5 rsi:0x200000 rdi:0x68000000 rbp:0x7f8a645de590 rsp:0x7f8a645dd400 r8:0xffffffffffffffff r9:0x0 r10:0x22 r11:0x246 r12:0x11101040 r13:0x7fffffffd8e0 r14:0x0 r15:0x0 rip:0x7f8a625e4e7f eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xb fs_base:0x7ffff7d7ab80 gs_base:0x0
}
{
  real_time:113145.029126 global_time:30933, event:`SYSCALL: munmap' (state:EXITING_SYSCALL) tid:119139, ticks:1911003
rax:0x0 rbx:0x0 rcx:0xffffffffffffffff rdx:0xffffffa5 rsi:0x200000 rdi:0x68000000 rbp:0x7f8a645de590 rsp:0x7f8a645dd400 r8:0xffffffffffffffff r9:0x0 r10:0x22 r11:0x246 r12:0x11101040 r13:0x7fffffffd8e0 r14:0x0 r15:0x0 rip:0x7f8a625e4e7f eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xb fs_base:0x7ffff7d7ab80 gs_base:0x0
}
{
  real_time:113145.029321 global_time:30934, event:`SYSCALL: lseek' (state:ENTERING_SYSCALL) tid:119139, ticks:1911005
rax:0xffffffffffffffda rbx:0x0 rcx:0xffffffffffffffff rdx:0x0 rsi:0x0 rdi:0x5 rbp:0x7f8a645de590 rsp:0x7f8a645dd400 r8:0xffffffffffffffff r9:0x0 r10:0x22 r11:0x246 r12:0x11101040 r13:0x7fffffffd8e0 r14:0x0 r15:0x0 rip:0x7f8a625e4fb0 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x8 fs_base:0x7ffff7d7ab80 gs_base:0x0
}
{
  real_time:113145.029441 global_time:30935, event:`SYSCALL: lseek' (state:EXITING_SYSCALL) tid:119139, ticks:1911005
rax:0x0 rbx:0x0 rcx:0xffffffffffffffff rdx:0x0 rsi:0x0 rdi:0x5 rbp:0x7f8a645de590 rsp:0x7f8a645dd400 r8:0xffffffffffffffff r9:0x0 r10:0x22 r11:0x246 r12:0x11101040 r13:0x7fffffffd8e0 r14:0x0 r15:0x0 rip:0x7f8a625e4fb0 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x8 fs_base:0x7ffff7d7ab80 gs_base:0x0
}
{
  real_time:113145.029632 global_time:30936, event:`SYSCALL: read' (state:ENTERING_SYSCALL) tid:119139, ticks:1911006
rax:0xffffffffffffffda rbx:0x0 rcx:0xffffffffffffffff rdx:0x1 rsi:0x7f8a645dd32b rdi:0x5 rbp:0x7f8a645dd360 rsp:0x7f8a645dd360 r8:0xffffffffffffffff r9:0x0 r10:0x22 r11:0x246 r12:0x11101040 r13:0x7fffffffd8e0 r14:0x0 r15:0x0 rip:0x7f8a625e82df eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x0 fs_base:0x7ffff7d7ab80 gs_base:0x0
}
=== Start rr backtrace:
/home/zyh/rr/build/bin/rr(_ZN2rr13dump_rr_stackEv+0x5d)[0x555555ad820c]
/home/zyh/rr/build/bin/rr(_ZN2rr9GdbServer15emergency_debugEPNS_4TaskE+0x1a6)[0x5555558df01e]
/home/zyh/rr/build/bin/rr(+0x3c3ac4)[0x555555917ac4]
/home/zyh/rr/build/bin/rr(_ZN2rr21EmergencyDebugOstreamD1Ev+0x66)[0x555555917d4c]
/home/zyh/rr/build/bin/rr(_ZN2rr4Task17read_bytes_helperENS_10remote_ptrIvEElPvPb+0x11c)[0x555555a96f60]
/home/zyh/rr/build/bin/rr(_ZN2rr4Task8read_memIhEESt6vectorIT_SaIS3_EENS_10remote_ptrIS3_EEmPb+0x94)[0x55555584a796]
/home/zyh/rr/build/bin/rr(_ZN2rr16TaskSyscallState23process_syscall_resultsEv+0x126)[0x555555977eda]
/home/zyh/rr/build/bin/rr(_ZN2rr19rec_process_syscallEPNS_10RecordTaskE+0xf1)[0x555555982536]
/home/zyh/rr/build/bin/rr(_ZN2rr13RecordSession21syscall_state_changedEPNS_10RecordTaskEPNS0_9StepStateE+0xd2b)[0x55555595ee69]
/home/zyh/rr/build/bin/rr(_ZN2rr13RecordSession11record_stepEv+0x507)[0x555555964c99]
/home/zyh/rr/build/bin/rr(+0x402e11)[0x555555956e11]
/home/zyh/rr/build/bin/rr(_ZN2rr13RecordCommand3runERSt6vectorINSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEESaIS7_EE+0x40f)[0x555555957adf]
/home/zyh/rr/build/bin/rr(main+0x27d)[0x555555af406f]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf3)[0x7ffff750e0b3]
/home/zyh/rr/build/bin/rr(_start+0x2e)[0x5555558346ee]
=== End rr backtrace

The debugged application is dmtcp (restarting a program), kernel is
Linux pc 5.4.0-100-generic #113-Ubuntu SMP Thu Feb 3 18:43:29 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux

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 with Task.cc around read_bytes_helper() at line 2832, then follow Task::read_mem(), TaskSyscallState::process_syscall_results(), and rec_process_syscall() in the reported backtrace. Compare the failing read at 0x68000000 with the preceding munmap and lseek events to determine why the recorded syscall results no longer match the task memory. Done means explaining the failure and adding a regression test if the cause can be reproduced.

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.