rr replay error with “Assertion `ok' failed to hold. Tracee died unexpectedly” It can be reproduced using x86 wine.

[IamHuskar]

arch: x86
os: ububtu22.04
kernel:6.8.0-90-generic
cpu: 13th Gen Intel(R) Core(TM) i5-13600KF
wine-version: wine-10.13-561-gf5a0f2ca435
rr: master branch

rr record ~/wine-source/wine64-build/wine whoami

./kill_all_wine_proc.sh
rr record ~/wine-source/wine64-build/wine whoami
rr: Saving execution to trace directory `/home/ubu/.local/share/rr/wine-0'.
UBU-D2H\ubu

rr record exit successfully.

rr ps
PID     PPID    EXIT    CMD
666600  --      0       /home/ubu/wine-source/wine64-build/wine whoami
666601  666600  0       /home/ubu/wine-source/wine64-build/server/wineserver
666602  666601  -9      (forked without exec)
666603  666600  0       (forked without exec)
666604  666603  0       /home/ubu/wine-source/wine64-build/loader/wine-preloader /home/ubu/wine-source/wine64-build/loader/wine C:\windows\system32\wineboot.exe 
...............
...............
666696  666600  0       (forked without exec)
666697  666696  0       /home/ubu/wine-source/wine64-build/loader/wine-preloader /home/ubu/wine-source/wine64-build/loader/wine C:\windows\system32\whoami.exe

run

rr replay -p 666697

[ReplaySession] Removing breakpoint 0xb7f (STOP-SIGSEGV)
[ReplaySession] [event 58072] 666602: replaying SYSCALL: epoll_pwait2; state ENTERING_SYSCALL
[ReplaySession]     (syscllbufsz:176, abrtcmt:0, locked:0)
[replay_syscall] processing epoll_pwait2 (entry)
[Task] resuming execution of 668045 with PTRACE_SYSEMU tick_period -1 wait 2
[Task] Flushing registers for tid 668045 { ip:0x73e4e3ea378a args:(0x16,0xfffffffffffffff0,0,0x73e4e3bffdd0,0,8) orig_syscall: -1 syscallno: 22 }
[PerfCounters] Resetting counters with period 1152921504606846976
[Task] going into blocking wait for 668045 ...
[Task]   Task 668045 changed status to 0x57f (STOP-SIGTRAP)
[Task]   (refreshing register cache)
[Task] Requesting registers from tracee 668045
[AddressSpace] Writing back 0xf at 0x70000000
[ReplaySession] [event 58073] 666602: replaying SYSCALLBUF_RESET; state  (none)
[ReplaySession]     (syscllbufsz:176, abrtcmt:0, locked:0)
[ReplaySession] [event 58074] 666606: replaying SYSCALL: read; state EXITING_SYSCALL
[ReplaySession]     (syscllbufsz:64, abrtcmt:0, locked:1)
[replay_syscall] processing read (exit)
[ReplaySession] [event 58075] 666606: replaying SYSCALLBUF_ABORT_COMMIT; state  (none)
[ReplaySession]     (syscllbufsz:64, abrtcmt:0, locked:1)
[ReplaySession] [event 58076] 666606: replaying SYSCALL: rrcall_notify_syscall_hook_exit; state ENTERING_SYSCALL
[ReplaySession]     (syscllbufsz:64, abrtcmt:1, locked:1)
[replay_syscall] processing rrcall_notify_syscall_hook_exit (entry)
[Task] resuming execution of 668056 with PTRACE_SYSEMU tick_period -1 wait 2
[Task] Flushing registers for tid 668056 { ip:0x7000000e args:(0x4,0x70002070,0x40,0,0,0) orig_syscall: 0 syscallno: 64 }
[PerfCounters] Resetting counters with period 1152921504606846976
[Task] going into blocking wait for 668056 ...
[Task]   Task 668056 changed status to 0x57f (STOP-SIGTRAP)
[Task]   (refreshing register cache)
[Task] Requesting registers from tracee 668056
[AddressSpace] Writing back 0xf at 0x70000003
[ReplaySession] [event 58077] 666606: replaying SYSCALLBUF_RESET; state  (none)
[ReplaySession]     (syscllbufsz:64, abrtcmt:0, locked:0)
[ReplaySession] [event 58078] 666606: replaying SYSCALL: rrcall_notify_syscall_hook_exit; state EXITING_SYSCALL
[ReplaySession]     (syscllbufsz:0, abrtcmt:0, locked:0)
[replay_syscall] processing rrcall_notify_syscall_hook_exit (exit)
[ReplaySession] [event 58079] 666606: replaying SYSCALLBUF_FLUSH; state  (none)
[ReplaySession]     (syscllbufsz:0, abrtcmt:0, locked:0)
[ReplaySession] Prepared 88 bytes of syscall records
[ReplaySession] Adding breakpoint
[Task] resuming execution of 668056 with PTRACE_CONT tick_period -1 wait 2
[Task] Flushing registers for tid 668056 { ip:0x70000005 args:(0x4,0x7ffffe0fea10,0x40,0x8,0x7ffc0000,140737455843848) orig_syscall: 0 syscallno: 64 }
[PerfCounters] Resetting counters with period 1152921504606846976
[Task] going into blocking wait for 668056 ...
wine client error:34: write: Bad file descriptor
[Task]   Task 668056 changed status to 0x6057f (PTRACE_EVENT_EXIT)
[Task]   (refreshing register cache)
[Task] Requesting registers from tracee 668056
[FATAL src/ReplaySession.cc:826:continue_or_step()] 
 (task 668056 (rec:666606) at time 58079)
 -> Assertion `ok' failed to hold. Tracee died unexpectedly
Tail of trace dump:
[TraceStream] Reading event for 1063: parent=666600 tid=666601
[TraceStream] Reading event for 1570: parent=666601 tid=666602
[TraceStream] Reading event for 3135: parent=666600 tid=666603
[TraceStream] Reading event for 3148: parent=666603 tid=666604
[TraceStream] Reading event for 13682: parent=666604 tid=666605
[TraceStream] Reading event for 13689: parent=666605 tid=666606
[TraceStream] Reading event for 16102: parent=666604 tid=666607
[TraceStream] Reading event for 16229: parent=666607 tid=666608
[TraceStream] Reading event for 53773: parent=666608 tid=666613
[TraceStream] Reading event for 59217: parent=666606 tid=666614
[TraceStream] Reading event for 59338: parent=666614 tid=666615
[TraceStream] Reading event for 60868: parent=666608 tid=666616
[TraceStream] Reading event for 60893: parent=666616 tid=666617
[TraceStream] Reading event for 83178: parent=666613 tid=666622
[TraceStream] Reading event for 84016: parent=666622 tid=666623
[TraceStream] Reading event for 84680: parent=666617 tid=666624
[TraceStream] Reading event for 85883: parent=666624 tid=666625
[TraceStream] Reading event for 87819: parent=666625 tid=666626
[TraceStream] Reading event for 91668: parent=666624 tid=666627
[TraceStream] Reading event for 91768: parent=666624 tid=666628
[TraceStream] Reading event for 98771: parent=666608 tid=666629
[TraceStream] Reading event for 98777: parent=666629 tid=666630
[TraceStream] Reading event for 120185: parent=666613 tid=666635
[TraceStream] Reading event for 121251: parent=666630 tid=666636
[TraceStream] Reading event for 122263: parent=666636 tid=666637
[TraceStream] Reading event for 122943: parent=666637 tid=666638
[TraceStream] Reading event for 124491: parent=666608 tid=666639
[TraceStream] Reading event for 124614: parent=666639 tid=666640
[TraceStream] Reading event for 136266: parent=666613 tid=666641
[TraceStream] Reading event for 137750: parent=666640 tid=666642
[TraceStream] Reading event for 139106: parent=666642 tid=666643
[TraceStream] Reading event for 141210: parent=666622 tid=666644
[TraceStream] Reading event for 143580: parent=666624 tid=666645
[TraceStream] Reading event for 152349: parent=666608 tid=666646
[TraceStream] Reading event for 152355: parent=666646 tid=666647
[TraceStream] Reading event for 160219: parent=666615 tid=666648
[TraceStream] Reading event for 160854: parent=666615 tid=666649
[TraceStream] Reading event for 162465: parent=666613 tid=666653
[TraceStream] Reading event for 163280: parent=666647 tid=666655
[TraceStream] Reading event for 164031: parent=666655 tid=666656
[TraceStream] Reading event for 165568: parent=666656 tid=666657
[TraceStream] Reading event for 173113: parent=666655 tid=666658
[TraceStream] Reading event for 175039: parent=666655 tid=666659
[TraceStream] Reading event for 175516: parent=666655 tid=666660
[TraceStream] Reading event for 177228: parent=666615 tid=666661
[TraceStream] Reading event for 178561: parent=666613 tid=666662
[TraceStream] Reading event for 180957: parent=666613 tid=666663
[TraceStream] Reading event for 183838: parent=666662 tid=666664
[TraceStream] Reading event for 197837: parent=666657 tid=666665
[TraceStream] Reading event for 200011: parent=666655 tid=666666
[TraceStream] Reading event for 200146: parent=666666 tid=666667
[TraceStream] Reading event for 202801: parent=666657 tid=666668
[TraceStream] Reading event for 206936: parent=666638 tid=666669
[TraceStream] Reading event for 207844: parent=666669 tid=666674
[TraceStream] Reading event for 210985: parent=666655 tid=666675
[TraceStream] Reading event for 213241: parent=666608 tid=666676
[TraceStream] Reading event for 214276: parent=666644 tid=666677
[TraceStream] Reading event for 214410: parent=666677 tid=666678
[TraceStream] Reading event for 239047: parent=666613 tid=666679
[TraceStream] Reading event for 240403: parent=666678 tid=666680
[TraceStream] Reading event for 241709: parent=666680 tid=666681
[TraceStream] Reading event for 242342: parent=666681 tid=666682
[TraceStream] Reading event for 242964: parent=666681 tid=666683
[TraceStream] Reading event for 245817: parent=666682 tid=666684
[TraceStream] Reading event for 246822: parent=666684 tid=666685
[TraceStream] Reading event for 278096: parent=666600 tid=666690
[TraceStream] Reading event for 278134: parent=666690 tid=666691
[TraceStream] Reading event for 324104: parent=666600 tid=666696
[TraceStream] Reading event for 324128: parent=666696 tid=666697
{
  real_time:1391886.424517 global_time:58059, event:`SYSCALL: epoll_pwait2' (state:EXITING_SYSCALL) tid:666602, ticks:47123838
rax:0x1 rbx:0x73e4e3bfffa0 rcx:0xffffffffffffffff rdx:0x80 rsi:0x7ffccab2b9c0 rdi:0x9 rbp:0x73e4e3bfffa0 rsp:0x73e4e3bffd40 r8:0x0 r9:0x8 r10:0x7ffccab2b9b0 r11:0x246 r12:0x0 r13:0x7ffccab2b9b0 r14:0x701020f0 r15:0x701026f0 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x1b9 fs_base:0x73e4e3e7d740 gs_base:0x0
  { tid:666602, addr:0x7ffccab2b9c0, length:0xc }
}
{
  real_time:1391886.424533 global_time:58060, event:`SYSCALLBUF_FLUSH' tid:666602, ticks:47124049
  { syscall:'gettimeofday', ret:0x0, size:0x20 }
  { syscall:'clock_gettime', ret:0x0, size:0x20 }
  { syscall:'read', ret:0x40, size:0x50, desched:1 }
  { syscall:'write', ret:0x40, size:0x10, desched:1 }
  { syscall:'epoll_pwait2', ret:0x0, size:0x10 }
}
{
  real_time:1391886.424533 global_time:58061, event:`SYSCALL: epoll_pwait2' (state:ENTERING_SYSCALL) tid:666602, ticks:47124049
rax:0xffffffffffffffda rbx:0x73e4e3bfffa0 rcx:0xffffffffffffffff rdx:0x80 rsi:0x7ffccab2b9c0 rdi:0x9 rbp:0x73e4e3bfffa0 rsp:0x73e4e3bffd40 r8:0x0 r9:0x8 r10:0x7ffccab2b9b0 r11:0x246 r12:0x0 r13:0x7ffccab2b9b0 r14:0x701020d0 r15:0x701026d0 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x1b9 fs_base:0x73e4e3e7d740 gs_base:0x0
}

[IamHuskar]

The error string 'wine client error:34: write: Bad file descriptor' did not appear during rr record. So, could the issue be occurring during replay?

[rocallahan]

I guess it's a divergence bug. Does it fail the same way on every replay? Does it fail the same way if you make a new recording?

[IamHuskar]

I guess it's a divergence bug. Does it fail the same way on every replay? Does it fail the same way if you make a new recording?

yes ，always the same bug,same output , It can be reproduced on my pc

[IamHuskar]

The same error occurs both when re-recording and during replay, and it is consistently reproducible. Moreover, rr replay does not stop at the entry point but instead runs directly into the error.

When running rr replay with the -M parameter, the output does not include rr’s event marker strings at the beginning.

“wine client error:34: write: Bad file descriptor”

rr replay -M -p 1167065

wine client error:34: write: Bad file descriptor
[FATAL src/ReplaySession.cc:826:continue_or_step()] 
 (task 1172335 (rec:1166901) at time 58942)
 -> Assertion `ok' failed to hold. Tracee died unexpectedly
Tail of trace dump:
{
  real_time:1416850.035106 global_time:58922, event:`SYSCALL: epoll_pwait2' (state:EXITING_SYSCALL) tid:1166897, ticks:47152592
rax:0x1 rbx:0x7dd2e1dfffa0 rcx:0xffffffffffffffff rdx:0x80 rsi:0x7ffd350d2310 rdi:0x9 rbp:0x7dd2e1dfffa0 rsp:0x7dd2e1dffd40 r8:0x0 r9:0x8 r10:0x7ffd350d2300 r11:0x246 r12:0x0 r13:0x7ffd350d2300 r14:0x701020f0 r15:0x701026f0 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x1b9 fs_base:0x7dd2e209d740 gs_base:0x0
  { tid:1166897, addr:0x7ffd350d2310, length:0xc }
}

@rocallahan

[IamHuskar]

When debugging wine with rr replay, an error occurs after executing a write function call.

The current code executes the x86 call _write instruction. I entered "when" in gdb and got the result: Completed event: 58941.

However, the events 58943 and 58944 correspond to read and epoll_pwait2. I believe a write event should have been recorded here instead. Could this indicate that an event was lost during recording?

rr dump  latest-trace -p 58940-58944 

{
  real_time:1416850.035253 global_time:58941, event:`SYSCALL: rrcall_notify_syscall_hook_exit' (state:EXITING_SYSCALL) tid:1166901, ticks:11841534
rax:0x40 rbx:0x681fffa0 rcx:0xffffffffffffffff rdx:0x40 rsi:0x7ffffe0fea10 rdi:0x4 rbp:0x7ffffe0fea10 rsp:0x681ffe10 r8:0x7ffc0000 r9:0x7ffffe0fea08 r10:0x8 r11:0x246 r12:0x40 r13:0x40 r14:0x7ffffe0fea10 r15:0x0 rip:0x70000005 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x0 fs_base:0x70f3474f4740 gs_base:0x7ffc0000
}
{
  real_time:1416850.035292 global_time:58942, event:`SYSCALLBUF_FLUSH' tid:1166901, ticks:11841755
}
{
  real_time:1416850.035293 global_time:58943, event:`SYSCALL: read' (state:ENTERING_SYSCALL) tid:1166901, ticks:11841755
rax:0xffffffffffffffda rbx:0x70002078 rcx:0xffffffffffffffff rdx:0x40 rsi:0x70002088 rdi:0x4 rbp:0x4 rsp:0x681ffd60 r8:0x0 r9:0x0 r10:0x0 r11:0x246 r12:0x70002088 r13:0x700020c8 r14:0x40 r15:0x7ffffe0fea20 rip:0x7000000e eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x0 fs_base:0x70f3474f4740 gs_base:0x7ffc0000
}
{
  real_time:1416850.035298 global_time:58944, event:`SYSCALL: epoll_pwait2' (state:EXITING_SYSCALL) tid:1166897, ticks:47153049
rax:0x1 rbx:0x7dd2e1dfffa0 rcx:0xffffffffffffffff rdx:0x80 rsi:0x7ffd350d2310 rdi:0x9 rbp:0x7dd2e1dfffa0 rsp:0x7dd2e1dffd40 r8:0x0 r9:0x8 r10:0x7ffd350d2300 r11:0x246 r12:0x0 r13:0x7ffd350d2300 r14:0x701020d0 r15:0x701026d0 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x1b9 fs_base:0x7dd2e209d740 gs_base:0x0
}

does SYSCALLBUF_FLUSH means WRITE?

[IamHuskar]

{
  real_time:1416850.035246 global_time:58939, event:`SYSCALL: rrcall_notify_syscall_hook_exit' (state:ENTERING_SYSCALL) tid:1166901, ticks:11841534
rax:0xffffffffffffffda rbx:0x681fffa0 rcx:0xffffffffffffffff rdx:0x40 rsi:0x7ffffe0fea10 rdi:0x4 rbp:0x7ffffe0fea10 rsp:0x681ffe10 r8:0x7ffc0000 r9:0x7ffffe0fea08 r10:0x8 r11:0x246 r12:0x40 r13:0x40 r14:0x7ffffe0fea10 r15:0x0 rip:0x70000005 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x3ea fs_base:0x70f3474f4740 gs_base:0x7ffc0000
}
{
  real_time:1416850.035247 global_time:58940, event:`SYSCALLBUF_RESET' tid:1166901, ticks:11841534
}
{
  real_time:1416850.035253 global_time:58941, event:`SYSCALL: rrcall_notify_syscall_hook_exit' (state:EXITING_SYSCALL) tid:1166901, ticks:11841534
rax:0x40 rbx:0x681fffa0 rcx:0xffffffffffffffff rdx:0x40 rsi:0x7ffffe0fea10 rdi:0x4 rbp:0x7ffffe0fea10 rsp:0x681ffe10 r8:0x7ffc0000 r9:0x7ffffe0fea08 r10:0x8 r11:0x246 r12:0x40 r13:0x40 r14:0x7ffffe0fea10 r15:0x0 rip:0x70000005 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x0 fs_base:0x70f3474f4740 gs_base:0x7ffc0000
}
{
  real_time:1416850.035292 global_time:58942, event:`SYSCALLBUF_FLUSH' tid:1166901, ticks:11841755
  { syscall:'rt_sigprocmask', ret:0x0, size:0x18 }
  { syscall:'rt_sigprocmask', ret:0x0, size:0x18 }
  { syscall:'rt_sigprocmask', ret:0x0, size:0x18 }
  { syscall:'write', ret:0x40, size:0x10, desched:1 }
}

on sys_write-->untraced_syscall_full:
thread_locals->pending_untraced_syscall_result = &rec->ret;
rec->ret should be 0x40
but here is 0

In the rr dump, I found that the return value of the "write" is correct: 0x40. However, during replay, the value of rec->ret in untraced_syscall_full is 0. { syscall:'rt_sigprocmask', ret:0x0, size:0x18 }

[IamHuskar]

During replay, I noticed that an extra syscall rt_sigprocmask appears in the recorded trace. This causes the return value of the write syscall to be incorrectly replaced with the result of rt_sigprocmask, leading to the error. Should I debug during recording to figure out why this additional rt_sigprocmask call occurred?@rocallahan @khuey

{
real_time:1495350.476366 global_time:58677, event:`SYSCALLBUF_FLUSH' tid:3091586, ticks:12162127
{ syscall:'rt_sigprocmask', ret:0x0, size:0x18 }
{ syscall:'rt_sigprocmask', ret:0x0, size:0x18 }
{ syscall:'rt_sigprocmask', ret:0x0, size:0x18 } //this is an extra rt_sigprocmask syscall . {syscall:'write', ret:0x40, size:0x10, desched:1} should be here
{ syscall:'write', ret:0x40, size:0x10, desched:1 }
}

[khuey]

When you say this syscall is "extra" is your baseline what happened during replay or what would happen outside of rr?

[IamHuskar]

When you say this syscall is "extra" is your baseline what happened during replay or what would happen outside of rr?

Based on my current testing,

The original Wine function should be:

wine_server_call(){
    _pthread_sigmask
    write(fd)      // write to server
    read(fd)       // read from server
    _pthread_sigmask
}

Two consecutive wine_server_call invocations in the NtUserSetThreadDesktop function should produce the following call sequence:

{
    _pthread_sigmask
    write
    read
    _pthread_sigmask  // event 1

    _pthread_sigmask  // event 2
    write             // event 3
    read
    _pthread_sigmask
}

However, the actual recording shows three rt_sigprocmask events before the write event 3:

real_time:1495350.476366 global_time:58677, event:`SYSCALLBUF_FLUSH' tid:3091586, ticks:12162127
{ syscall:'rt_sigprocmask', ret:0x0, size:0x18 }
{ syscall:'rt_sigprocmask', ret:0x0, size:0x18 }
{ syscall:'rt_sigprocmask', ret:0x0, size:0x18 } 
{ syscall:'write', ret:0x40, size:0x10, desched:1 }

When I try rr replay, event 2 is already completed. When processing event 3,

it enters sys_write and calls untraced_syscall_full

struct syscallbuf_record* rec = (struct syscallbuf_record*)buffer_last();
thread_locals->pending_untraced_syscall_result = &rec->ret;

Here, struct syscallbuf_record* rec points to { syscall:'rt_sigprocmask', ret:0x0, size:0x18 },

causing the return value filled for write to be 0. This makes the system think the write operation failed,

outputting the error: wine client error:34: write: Bad file descriptor.

During recording, the error wine client error:34: write: Bad file descriptor does not appear.

Therefore, I believe one of the three rt_sigprocmask events is extra.

Can I use rr record --nested=detach rr record wine whoami to debug why rr record generated three rt_sigprocmask events?

Since this issue is reproducible on my machine, I would like to locate and fix the problem.

[IamHuskar]

If I first run wine cmd and then run rr record wine whoami, the bug does not appear.
However, if I kill all wine processes first and then start recording, the bug occurs.

[Keno]

Wine uses shared memory communication. You need to be careful that the wineserver execution ends up in your trace.

[IamHuskar]

Wine uses shared memory communication. You need to be careful that the wineserver execution ends up in your trace.

Thank you. Indeed, such issues can be quite tricky to debug, as modifying and recompiling some Wine code for testing leads to different error scenarios.