rr-debugger / rr-debugger/rr

Replaying a Wine recording triggers `Assertion 'ticks_now == trace_ticks'`, mmap with MAP_PRIVATE

Open
#3,972 19 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

After @Keno 's patch finally went in some form into Wine I found there still happen diversions.
So I tried to bisect and found Wine was changing how a shared memory between wineserver and the gui processes get mapped. Unfortunately there were a few more commits making this one not alone revertable.

But I could strip it down to this modification to wine to make replaying work again by using the previous mapping flag MAP_SHARED instead of MAP_PRIVATE:

--- a/dlls/ntdll/unix/virtual.c
+++ b/dlls/ntdll/unix/virtual.c
@@ -2351,7 +2351,13 @@ static NTSTATUS map_file_into_view( struct file_view *view, int fd, size_t start
         /* changes to the file are not guaranteed to be visible in read-only MAP_PRIVATE mappings,
          * but they are on Linux so we take advantage of it */
 #ifdef __linux__
+      if (vprot & SEC_FILE) {
         flags |= MAP_PRIVATE;
+      } else {
+        flags |= MAP_SHARED;
+        prot &= ~PROT_WRITE;
+        //ERR("fd=%d flags=0x%x prot=0x%x vprot=0x%x:%d\n", fd, flags, prot, vprot, __LINE__);
+      }
 #else
         flags |= MAP_SHARED;
         prot &= ~PROT_WRITE;

This is what I got, but there was no relation to a shared memory visible:

[FATAL src/ReplaySession.cc:1278:check_ticks_consistency()] 
 (task 1131280 (rec:1131219) at time 151589)
 -> Assertion `ticks_now == trace_ticks' failed to hold. ticks mismatch for 'SYSCALL: read'; expected 24071991, got 24071980

So I tried prove this shared memory being the issue by spraying such calls syscall(-1, 0, 0); in the functions shown by the emergency shell and reached that way function shared_object_get_id in Wine, with a better to follow register mismatch:

[FATAL src/ReplayTask.cc:130:validate_regs()] 
 (task 1123897 (rec:1123824) at time 170377)
 -> Assertion `!comparison.mismatch_count' failed to hold. Mismatched registers, replay vs rec: r12 (nil) != 0x18
104             lock.id = object->id;
   0x00007f7e41638440 <+127>:   mov    0x8(%rbx),%r12
   0x00007f7e41638444 <+131>:   mov    %r12,-0x40(%rbp)

There the memory in question looks like this:

(gdb) print/x *(const shared_object_t *) 0x7ffffe9e0ef8
$5 = {seq = 0x6, id = 0x0, shm = {desktop = {flags = 0xfefefefe, cursor = {x = 0xfefefefe, y = 0xfefefefe, last_change = 0xfefefefe, clip = {left = 0xfefefefe, top = 0xfefefefe, right = 0xfefefefe, 
          bottom = 0xfefefefe}}, keystate = {0xfe <repeats 256 times>}, monitor_serial = 0xfefefefefefefefe}, queue = {hooks_count = {0xfefefefe <repeats 17 times>}, wake_mask = 0xfefefefe, wake_bits = 0xfefefefe, 
      changed_mask = 0xfefefefe, changed_bits = 0xfefefefe}, input = {foreground = 0xfefefefe, active = 0xfefefefe, focus = 0xfefefefe, capture = 0xfefefefe, menu_owner = 0xfefefefe, move_size = 0xfefefefe, 
      caret = 0xfefefefe, caret_rect = {left = 0xfefefefe, top = 0xfefefefe, right = 0xfefefefe, bottom = 0xfefefefe}, cursor = 0xfefefefe, cursor_count = 0xfefefefe, keystate = {0xfe <repeats 256 times>}, 
      keystate_lock = 0xfefefefe}}}

When I replay the wineserver to short before the diversion I see this state of the mapping:

(rr) print/x *(const shared_object_t *)0x7f872e6d0ef8
$1 = {seq = 0xe, id = 0x18, shm = {desktop = {flags = 0x0, cursor = {x = 0x0, y = 0x0, last_change = 0x0, clip = {left = 0x0, top = 0x0, right = 0x0, bottom = 0x0}}, keystate = {0x0 <repeats 41 times>, 0x80, 0x0, 
        0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x80, 0x0, 0x0, 0x55 <repeats 204 times>}, monitor_serial = 0x5555555555555555}, queue = {hooks_count = {0x0 <repeats 17 times>}, wake_mask = 0x0, wake_bits = 0x8000, 
      changed_mask = 0x0, changed_bits = 0x8000}, input = {foreground = 0x0, active = 0x0, focus = 0x0, capture = 0x0, menu_owner = 0x0, move_size = 0x0, caret = 0x0, caret_rect = {left = 0x0, top = 0x0, 
        right = 0x0, bottom = 0x0}, cursor = 0x0, cursor_count = 0x0, keystate = {0x0 <repeats 21 times>, 0x80, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x80, 0x0, 0x0, 0x55 <repeats 224 times>}, 
      keystate_lock = 0x55555555}}}

So it looks like this mapping was not propagating changes to the memory in wineserver to the wine process, which seems to show some initial state of it.

To make things more complicated this shared memory is created by wineserver by creating a temporary file and sending the fd through a socket to the wine process.

I tried to replicate this in a rr testcase, but unfortunately this is not showing the issue, so there is maybe more to it:
mmap_private_from_fd_via_socket.c.txt

I had made some tests a while ago for this issue and was seeing it at Intel hardware too, so it seems no AMD related thing.

Is this probably a known issue in rr?
Any hints how to continue from here?

PS.: To speed up things I am just recording wineserver and the wine process I am interested in. But the issue appears also when recording the whole tree.

rr record bash -c "wineserver -k; wineserver -p60; rr record --nested=release wine wineconsole cmd /c \"timeout /t 10\" & sleep 8s; echo start; WINEDLLOVERRIDES=winemenubuilder.exe=n WINEDEBUG=+pid,+timestamp wine winemine; sleep 1s; wineserver -k; sleep 1s"```

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

Reproduce the Wine recording with the command in the issue and compare the MAP_PRIVATE mapping state across record and replay. Read dlls/ntdll/unix/virtual.c, then inspect the rr failures at src/ReplaySession.cc:1278 and src/ReplayTask.cc:130; the work is done when the cause of the mismatch is identified and replay behavior is explained or fixed with a reproducer.

Written by the indexing model from the issue text.

Assessment

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

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.