{"action":"created","issue":{"url":"https://api.github.com/repos/mozilla/rr/issues/1630","labels_url":"https://api.github.com/repos/mozilla/rr/issues/1630/labels{/name}","comments_url":"https://api.github.com/repos/mozilla/rr/issues/1630/comments","events_url":"https://api.github.com/repos/mozilla/rr/issues/1630/events","html_url":"https://github.com/mozilla/rr/issues/1630","id":128726676,"number":1630,"title":"Assertion `current->trace_reader().time() == mark.ptr->key.trace_time' failed to hold.","user":{"login":"glandium","id":1038527,"avatar_url":"https://avatars.githubusercontent.com/u/1038527?v=3","gravatar_id":"","url":"https://api.github.com/users/glandium","html_url":"https://github.com/glandium","followers_url":"https://api.github.com/users/glandium/followers","following_url":"https://api.github.com/users/glandium/following{/other_user}","gists_url":"https://api.github.com/users/glandium/gists{/gist_id}","starred_url":"https://api.github.com/users/glandium/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/glandium/subscriptions","organizations_url":"https://api.github.com/users/glandium/orgs","repos_url":"https://api.github.com/users/glandium/repos","events_url":"https://api.github.com/users/glandium/events{/privacy}","received_events_url":"https://api.github.com/users/glandium/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":16,"created_at":"2016-01-26T05:05:08Z","updated_at":"2016-01-27T05:21:02Z","closed_at":null,"body":"STR (with rr 4.0.3):\r\n- Download and extract http://people.mozilla.org/~mhommey/rr-issue.txz (the archive has everything needed at its root, so you may want to extract in a subdirectory)\r\n- Run: `(echo manifest d22db658228279626cba515d15e79bca957409ae; echo manifest a8f42f0f5743f73778fc80677258575c81393b24) | rr record ./git-cinnabar-helper`\r\n- Run: `rr replay`\r\n- `(rr) continue`\r\n- The program should die. On the exit backtrace, go to the frame in the `tree_entry` function (it's frame 14 for me, but it might be different depending on the frames for libc and librrpreload).\r\n- `(rr) watch entry->sha1`\r\n- `(rr) reverse-continue`\r\n- `(rr) watch desc->entry.sha1`\r\n- `(rr) reverse-continue`\r\n- `(rr) watch -l state->desc_git.entry.sha1`\r\n- `(rr) reverse-continue`\r\n\r\nThe error that happens then is:\r\n```\r\n[FATAL /build/rr-ovZx7I/rr-4.0.3/src/ReplayTimeline.cc:414:replay_step_to_mark() errno: 5 'Input/output error'] \r\n (task 17602 (rec:17564) at time 329)\r\n ->  Assertion `current->trace_reader().time() == mark.ptr->key.trace_time' failed to hold. \r\n```\r\n\r\nI tried to remove the intermediate steps, but it doesn't happen without them.\r\n\r\nHere is the `rr dump` around event 329:\r\n```\r\n{\r\n  global_time:320, event:`SYSCALL: mmap' (state:EXITING_SYSCALL) tid:17564, ticks:238186\r\n rax:0x7f2b3b120000 rbx:0x9 rcx:0xffffffffffffffff rdx:0x3 rsi:0x80000 rdi:0x0 rbp:0xfff rsp:0x7ffcf6577b90 r8:0xffffffff r9:0x0 r10:0x22 r11:0x202 r12:0x7f2b3b742c58 r13:0x7f2b3b742c58 r14:0x7ffcf6577c90 r15:0x7fff0 rip:0x70000018 eflags:0x202 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x9 fs_base:0x7f2b3c5f4740 gs_base:0x0\r\n}\r\n{\r\n  global_time:321, event:`PATCH_SYSCALL' tid:17564, ticks:286194\r\n}\r\n{\r\n  global_time:322, event:`SYSCALL: write' (state:ENTERING_SYSCALL) tid:17564, ticks:286200\r\n rax:0xffffffffffffffda rbx:0x1 rcx:0xffffffffffffffff rdx:0x5 rsi:0x124a980 rdi:0x1 rbp:0x0 rsp:0x7ffcf6577da0 r8:0x70b r9:0x0 r10:0x59 r11:0x202 r12:0x124a980 r13:0x5 r14:0x7ffcf6577ea0 r15:0x0 rip:0x70000018 eflags:0x202 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x1 fs_base:0x7f2b3c5f4740 gs_base:0x0\r\n}\r\n{\r\n  global_time:323, event:`SYSCALL: write' (state:EXITING_SYSCALL) tid:17564, ticks:286200\r\n rax:0x5 rbx:0x1 rcx:0xffffffffffffffff rdx:0x5 rsi:0x124a980 rdi:0x1 rbp:0x0 rsp:0x7ffcf6577da0 r8:0x70b r9:0x0 r10:0x59 r11:0x202 r12:0x124a980 r13:0x5 r14:0x7ffcf6577ea0 r15:0x0 rip:0x70000018 eflags:0x202 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x1 fs_base:0x7f2b3c5f4740 gs_base:0x0\r\n}\r\n{\r\n  global_time:324, event:`SYSCALL: write' (state:ENTERING_SYSCALL) tid:17564, ticks:286236\r\n rax:0xffffffffffffffda rbx:0x1 rcx:0xffffffffffffffff rdx:0x70b rsi:0x124acc0 rdi:0x1 rbp:0x0 rsp:0x7ffcf6577da0 r8:0xffffffff r9:0x124a980 r10:0x59 r11:0x202 r12:0x124acc0 r13:0x70b r14:0x7ffcf6577ea0 r15:0x0 rip:0x70000018 eflags:0x202 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x1 fs_base:0x7f2b3c5f4740 gs_base:0x0\r\n}\r\n{\r\n  global_time:325, event:`SYSCALL: write' (state:EXITING_SYSCALL) tid:17564, ticks:286236\r\n rax:0x70b rbx:0x1 rcx:0xffffffffffffffff rdx:0x70b rsi:0x124acc0 rdi:0x1 rbp:0x0 rsp:0x7ffcf6577da0 r8:0xffffffff r9:0x124a980 r10:0x59 r11:0x202 r12:0x124acc0 r13:0x70b r14:0x7ffcf6577ea0 r15:0x0 rip:0x70000018 eflags:0x202 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x1 fs_base:0x7f2b3c5f4740 gs_base:0x0\r\n}\r\n{\r\n  global_time:326, event:`SYSCALL: write' (state:ENTERING_SYSCALL) tid:17564, ticks:286253\r\n rax:0xffffffffffffffda rbx:0x1 rcx:0xffffffffffffffff rdx:0x1 rsi:0x49b222 rdi:0x1 rbp:0x0 rsp:0x7ffcf6577da0 r8:0xffffffff r9:0x124a980 r10:0x59 r11:0x202 r12:0x49b222 r13:0x1 r14:0x7ffcf6577ea0 r15:0x0 rip:0x70000018 eflags:0x202 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x1 fs_base:0x7f2b3c5f4740 gs_base:0x0\r\n}\r\n{\r\n  global_time:327, event:`SYSCALL: write' (state:EXITING_SYSCALL) tid:17564, ticks:286253\r\n rax:0x1 rbx:0x1 rcx:0xffffffffffffffff rdx:0x1 rsi:0x49b222 rdi:0x1 rbp:0x0 rsp:0x7ffcf6577da0 r8:0xffffffff r9:0x124a980 r10:0x59 r11:0x202 r12:0x49b222 r13:0x1 r14:0x7ffcf6577ea0 r15:0x0 rip:0x70000018 eflags:0x202 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x1 fs_base:0x7f2b3c5f4740 gs_base:0x0\r\n}\r\n{\r\n  global_time:328, event:`SYSCALLBUF_FLUSH' tid:17564, ticks:330503\r\n}\r\n{\r\n  global_time:329, event:`SYSCALL: mmap' (state:ENTERING_SYSCALL) tid:17564, ticks:330503\r\n rax:0xffffffffffffffda rbx:0x9 rcx:0xffffffffffffffff rdx:0x3 rsi:0x1000 rdi:0x0 rbp:0x7f2b3b743640 rsp:0x7ffcf65776a0 r8:0xffffffff r9:0x0 r10:0x22 r11:0x202 r12:0x7f2b3b743640 r13:0x49def7 r14:0x7ffcf65777a0 r15:0x124c040 rip:0x70000018 eflags:0x202 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x9 fs_base:0x7f2b3c5f4740 gs_base:0x0\r\n}\r\n{\r\n  global_time:330, event:`SYSCALLBUF_RESET' tid:17564, ticks:330503\r\n}\r\n{\r\n  global_time:331, event:`SYSCALL: mmap' (state:EXITING_SYSCALL) tid:17564, ticks:330503\r\n rax:0x7f2b3c61a000 rbx:0x9 rcx:0xffffffffffffffff rdx:0x3 rsi:0x1000 rdi:0x0 rbp:0x7f2b3b743640 rsp:0x7ffcf65776a0 r8:0xffffffff r9:0x0 r10:0x22 r11:0x202 r12:0x7f2b3b743640 r13:0x49def7 r14:0x7ffcf65777a0 r15:0x124c040 rip:0x70000018 eflags:0x202 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x9 fs_base:0x7f2b3c5f4740 gs_base:0x0\r\n}\r\n{\r\n  global_time:332, event:`PATCH_SYSCALL' tid:17564, ticks:331139\r\n}\r\n{\r\n  global_time:333, event:`SYSCALL: write' (state:ENTERING_SYSCALL) tid:17564, ticks:331145\r\n rax:0xffffffffffffffda rbx:0x2 rcx:0xffffffffffffffff rdx:0x19 rsi:0x7f2b3c61a000 rdi:0x2 rbp:0x0 rsp:0x7ffcf6577770 r8:0x7f2b3b744960 r9:0x7f2b3c5f4740 r10:0x41b r11:0x202 r12:0x7f2b3c61a000 r13:0x19 r14:0x7ffcf6577870 r15:0x124c040 rip:0x70000018 eflags:0x202 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x1 fs_base:0x7f2b3c5f4740 gs_base:0x0\r\n}\r\n{\r\n  global_time:334, event:`SYSCALL: write' (state:EXITING_SYSCALL) tid:17564, ticks:331145\r\n rax:0x19 rbx:0x2 rcx:0xffffffffffffffff rdx:0x19 rsi:0x7f2b3c61a000 rdi:0x2 rbp:0x0 rsp:0x7ffcf6577770 r8:0x7f2b3b744960 r9:0x7f2b3c5f4740 r10:0x41b r11:0x202 r12:0x7f2b3c61a000 r13:0x19 r14:0x7ffcf6577870 r15:0x124c040 rip:0x70000018 eflags:0x202 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x1 fs_base:0x7f2b3c5f4740 gs_base:0x0\r\n}\r\n{\r\n  global_time:335, event:`PATCH_SYSCALL' tid:17564, ticks:332564\r\n}\r\n{\r\n  global_time:336, event:`SYSCALL: exit_group' (state:ENTERING_SYSCALL) tid:17564, ticks:332565\r\n rax:0xffffffffffffffda rbx:0xe7 rcx:0xffffffffffffffff rdx:0x8 rsi:0x80 rdi:0x80 rbp:0x7f2b3b73e720 rsp:0x7ffcf65777c0 r8:0x3c r9:0xe7 r10:0xffffffffffffff78 r11:0x206 r12:0x7f2b3b73e720 r13:0x7f2b3b743dc0 r14:0x7ffcf65778c0 r15:0x124c040 rip:0x70000018 eflags:0x206 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xe7 fs_base:0x7f2b3c5f4740 gs_base:0x0\r\n}\r\n{\r\n  global_time:337, event:`EXIT' tid:17564, ticks:332565\r\n}\r\n{\r\n  global_time:338, event:`TRACE_TERMINATION' tid:0, ticks:0\r\n}\r\n```\r\n```"},"comment":{"url":"https://api.github.com/repos/mozilla/rr/issues/comments/175403444","html_url":"https://github.com/mozilla/rr/issues/1630#issuecomment-175403444","issue_url":"https://api.github.com/repos/mozilla/rr/issues/1630","id":175403444,"user":{"login":"glandium","id":1038527,"avatar_url":"https://avatars.githubusercontent.com/u/1038527?v=3","gravatar_id":"","url":"https://api.github.com/users/glandium","html_url":"https://github.com/glandium","followers_url":"https://api.github.com/users/glandium/followers","following_url":"https://api.github.com/users/glandium/following{/other_user}","gists_url":"https://api.github.com/users/glandium/gists{/gist_id}","starred_url":"https://api.github.com/users/glandium/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/glandium/subscriptions","organizations_url":"https://api.github.com/users/glandium/orgs","repos_url":"https://api.github.com/users/glandium/repos","events_url":"https://api.github.com/users/glandium/events{/privacy}","received_events_url":"https://api.github.com/users/glandium/received_events","type":"User","site_admin":false},"created_at":"2016-01-27T05:21:02Z","updated_at":"2016-01-27T05:21:02Z","body":"No, it's the only one that I hit with the conditional `current->trace_reader().time()==311`.\r\n\r\n```\r\n(gdb) call at_mark(mark)\r\n$1 = false\r\n(gdb) call t->regs()\r\n$2 = (const Registers &) @0x28ffdd0: {u = {x86regs = {ebx = 5, ecx = 0, edx = 0, esi = 0, edi = -16, ebp = -1, eax = 5, xds = 0, \r\n      xes = 661807112, xfs = 32606, xgs = 658564906, orig_eax = 32606, eip = 0, xcs = 0, eflags = 0, esp = 0, xss = 1879048240}, \r\n    x64regs = {r15 = 5, r14 = 0, r13 = 18446744073709551600, r12 = 5, rbp = 140042365460488, rbx = 140042362218282, r11 = 0, r10 = 0, \r\n      r9 = 1879048240, r8 = 0, rax = 140042365460480, rcx = 0, rdx = 140042362218262, rsi = 140042365460648, rdi = 5, \r\n      orig_rax = 18446744073709551615, rip = 140042362218282, cs = 51, cs_upper = 0, eflags = 514, eflags_upper = 0, \r\n      rsp = 140725941728968, ss = 43, ss_upper = 0, fs_base = 140042366510912, gs_base = 0, ds = 0, ds_upper = 0, es = 0, \r\n      es_upper = 0, fs = 0, fs_upper = 0, gs = 0, gs_upper = 0}}, arch_ = x86_64}\r\n(gdb) print mark.ptr->regs\r\n$3 = {u = {x86regs = {ebx = 6, ecx = 0, edx = 33, esi = 0, edi = 261748, ebp = 0, eax = 661544106, xds = 32606, xes = 5, xfs = 0, \r\n      xgs = 3, orig_eax = 0, eip = 32256736, xcs = 0, eflags = 5, esp = 0, xss = 656376064}, x64regs = {r15 = 6, r14 = 33, \r\n      r13 = 261748, r12 = 140042365197482, rbp = 5, rbx = 3, r11 = 32256736, r10 = 5, r9 = 140042360029440, r8 = 511, rax = 320, \r\n      rcx = 3, rdx = 8, rsi = 8, rdi = 0, orig_rax = 18446744073709551369, rip = 140042359981602, cs = 51, cs_upper = 0, \r\n      eflags = 514, eflags_upper = 0, rsp = 140725941727280, ss = 43, ss_upper = 0, fs_base = 140042366510912, gs_base = 0, ds = 0, \r\n      ds_upper = 0, es = 0, es_upper = 0, fs = 0, fs_upper = 0, gs = 0, gs_upper = 0}}, arch_ = x86_64}\r\n(gdb) print t->tick_count()\r\n$4 = 327143\r\n(gdb) p/x $2\r\n$5 = (const Registers &) @0x28ffdd0: {u = {x86regs = {ebx = 0x5, ecx = 0x0, edx = 0x0, esi = 0x0, edi = 0xfffffff0, ebp = 0xffffffff, \r\n      eax = 0x5, xds = 0x0, xes = 0x27726008, xfs = 0x7f5e, xgs = 0x2740e72a, orig_eax = 0x7f5e, eip = 0x0, xcs = 0x0, eflags = 0x0, \r\n      esp = 0x0, xss = 0x70000030}, x64regs = {r15 = 0x5, r14 = 0x0, r13 = 0xfffffffffffffff0, r12 = 0x5, rbp = 0x7f5e27726008, \r\n      rbx = 0x7f5e2740e72a, r11 = 0x0, r10 = 0x0, r9 = 0x70000030, r8 = 0x0, rax = 0x7f5e27726000, rcx = 0x0, rdx = 0x7f5e2740e716, \r\n      rsi = 0x7f5e277260a8, rdi = 0x5, orig_rax = 0xffffffffffffffff, rip = 0x7f5e2740e72a, cs = 0x33, cs_upper = 0x0, \r\n      eflags = 0x202, eflags_upper = 0x0, rsp = 0x7ffd4fc476c8, ss = 0x2b, ss_upper = 0x0, fs_base = 0x7f5e27826740, gs_base = 0x0, \r\n      ds = 0x0, ds_upper = 0x0, es = 0x0, es_upper = 0x0, fs = 0x0, fs_upper = 0x0, gs = 0x0, gs_upper = 0x0}}, arch_ = 0x1}\r\n(gdb) p/x $3\r\n$6 = {u = {x86regs = {ebx = 0x6, ecx = 0x0, edx = 0x21, esi = 0x0, edi = 0x3fe74, ebp = 0x0, eax = 0x276e5caa, xds = 0x7f5e, \r\n      xes = 0x5, xfs = 0x0, xgs = 0x3, orig_eax = 0x0, eip = 0x1ec32e0, xcs = 0x0, eflags = 0x5, esp = 0x0, xss = 0x271f8100}, \r\n    x64regs = {r15 = 0x6, r14 = 0x21, r13 = 0x3fe74, r12 = 0x7f5e276e5caa, rbp = 0x5, rbx = 0x3, r11 = 0x1ec32e0, r10 = 0x5, \r\n      r9 = 0x7f5e271f8100, r8 = 0x1ff, rax = 0x140, rcx = 0x3, rdx = 0x8, rsi = 0x8, rdi = 0x0, orig_rax = 0xffffffffffffff09, \r\n      rip = 0x7f5e271ec622, cs = 0x33, cs_upper = 0x0, eflags = 0x202, eflags_upper = 0x0, rsp = 0x7ffd4fc47030, ss = 0x2b, \r\n      ss_upper = 0x0, fs_base = 0x7f5e27826740, gs_base = 0x0, ds = 0x0, ds_upper = 0x0, es = 0x0, es_upper = 0x0, fs = 0x0, \r\n      fs_upper = 0x0, gs = 0x0, gs_upper = 0x0}}, arch_ = 0x1}\r\n```"}}