Test broken by fa7fb04db4d72b9d

On my development server, at revision fa7fb04db4d72b9d, I got 100% reproducible failures for thread_exit_signal and set_tid_address (both with and without syscallbuf). I could not reproduce on the previous revision, or on my laptop. Both are 64-bit.

set_tid_address was failing during record with

FAILED: errno=11 (Resource temporarily unavailable)
set_tid_address: /home/dreiss/local/rr/src/test/set_tid_address.c:26: main: Assertion `"FAILED: !" && check_cond(0 == syscall(202, &v, 0, 1, ((void *)0), ((void *)0), 0))' failed.

This suggests that the thread created on line 25 of set_tid_address.c is running to completion before the futex syscall starts. When futex starts, v has already been set to zero, so futex fails with EAGAIN. I ran the "rr record" command on both my laptop and server with RR_LOG=Scheduler and found this...

laptop (working):

[Scheduler] Scheduling next task
[Scheduler]   (29307 is un-switchable at (none))
[Scheduler]   and running; waiting for state change
[Scheduler]   new status is 0x857f
[Scheduler] Scheduling next task
[Scheduler]   29307 is blocked on SYSCALL: clone; checking status ...
[Scheduler]   ready with status 0x857f
[Scheduler]   Carrying on with task 29307
[Scheduler] Scheduling next task
[Scheduler]   (29307 is un-switchable at SYSCALL: clone)
[Scheduler] Scheduling next task
[Scheduler]   29307 isn't blocked
[Scheduler]   Carrying on with task 29307
[Scheduler] Scheduling next task
[Scheduler]   (29307 is un-switchable at (none))
[Scheduler]   and running; waiting for state change
[Scheduler]   new status is 0x7057f
[Scheduler] Scheduling next task
[Scheduler]   (29307 is un-switchable at (none))
[Scheduler]   and running; waiting for state change
[Scheduler]   new status is 0x857f
[Scheduler] Scheduling next task
[Scheduler]   (29307 is un-switchable at (none))
[Scheduler]   and running; waiting for state change
[Scheduler]   new status is 0x7057f
[Scheduler] Scheduling next task
[Scheduler]   (29307 is un-switchable at (none))
[Scheduler]   and running; waiting for state change
[Scheduler]   new status is 0x857f
[Scheduler] Scheduling next task
[Scheduler]   29307 is blocked on SYSCALL: futex; checking status ...
[Scheduler]   still blocked
[Scheduler]   need to reschedule
[Scheduler]   29308 isn't blocked
[Scheduler]   selecting task 29308
[Scheduler] Switching from 29307(set_tid_address) to 29308(set_tid_address) (priority 0 to 0) at 180

When it checks the status of 29307, clone is not blocked, so it's able to start the futex syscall before running the new thread.

server (not working):

[Scheduler] Scheduling next task
[Scheduler]   (29307 is un-switchable at (none))
[Scheduler]   and running; waiting for state change
[Scheduler]   new status is 0x857f
[Scheduler] Scheduling next task
[Scheduler]   29307 is blocked on SYSCALL: clone; checking status ...
[Scheduler]   still blocked
[Scheduler]   need to reschedule
[Scheduler]   29308 isn't blocked
[Scheduler]   selecting task 29308
[Scheduler] Switching from 29307(set_tid_address) to 29308(set_tid_address) (priority 0 to 0) at 175

(note that I modified the task numbers in this log to match the laptop log for easier diffing.

Any idea why clone would still be blocked on one machine, but continue right away on another? My next step will be to try to get the contents of /proc/PID/stack when the scheduler sees clone as blocked. I'm not sure whether that will be reliable, though.

thread_exit_signal was failing during replay with

[FATAL /home/dreiss/local/rr/src/ReplaySession.cc:423:guard_unexpected_signal() errno: 0 'Success'] 
 (task 1221071 (rec:1219426) at time 316)
 -> Assertion `false' failed to hold. Replay got unrecorded event SIGNAL: SIGSEGV(async) while awaiting signal
Launch gdb with
  gdb /tmp/rr-test-thread_exit_signal-aIdgc8K9s/thread_exit_signal-aIdgc8K9s

I wasn't able to get any useful information by connecting to the emergency debug server, but I did attach gdb to rr itself and got this stack:

#4  0x000000000061c4e6 in rr::emergency_debug (t=0x998300) at /home/dreiss/local/rr/src/log.cc:267
#5  0x000000000061c6c0 in rr::EmergencyDebugOstream::~EmergencyDebugOstream (this=0x7fff583d21f0, __in_chrg=<optimized out>) at /home/dreiss/local/rr/src/log.cc:287
#6  0x000000000067be59 in rr::guard_unexpected_signal (t=0x998300) at /home/dreiss/local/rr/src/ReplaySession.cc:423
#7  0x000000000067cd18 in rr::ReplaySession::emulate_async_signal (this=0x980fd0, t=0x998300, constraints=..., ticks=0) at /home/dreiss/local/rr/src/ReplaySession.cc:681
#8  0x000000000067e40d in rr::ReplaySession::try_one_trace_step (this=0x980fd0, t=0x998300, constraints=...) at /home/dreiss/local/rr/src/ReplaySession.cc:990
#9  0x000000000067f050 in rr::ReplaySession::replay_step (this=0x980fd0, constraints=...) at /home/dreiss/local/rr/src/ReplaySession.cc:1189
#10 0x0000000000679c44 in rr::ReplaySession::replay_step (this=0x980fd0, command=rr::RUN_CONTINUE) at /home/dreiss/local/rr/src/ReplaySession.h:259
#11 0x0000000000678c1e in rr::serve_replay_no_debugger (trace_dir="", flags=...) at /home/dreiss/local/rr/src/ReplayCommand.cc:270
#12 0x0000000000679039 in rr::replay (trace_dir="", flags=...) at /home/dreiss/local/rr/src/ReplayCommand.cc:350

and this information about the pending signal

(gdb) frame 7
#7  0x000000000067cd18 in rr::ReplaySession::emulate_async_signal (this=0x980fd0, t=0x998300, constraints=..., ticks=0) at /home/dreiss/local/rr/src/ReplaySession.cc:681
681       guard_unexpected_signal(t);
(gdb) p t->pending_sig()
$1 = 11
(gdb) p t->pending_siginfo
$2 = {
  si_signo = 11, 
  si_errno = 0, 
  si_code = 128, 
  _sifields = {
    _pad = {0, 0, 113, 0, -503875560, 32568, -503875560, 32568, -503881280, 32568, 353, 0, -503875320, 32568, -503875320, 32568, -1, 0, 1886221359, 762475055, 1953719668, 
      1919448109, 1600414053, 1953069157, 1734964063, 762077550, 1734625633, 961230947}, 
    _kill = {
      si_pid = 0, 
      si_uid = 0
    }, 
    _timer = {
      si_tid = 0, 
      si_overrun = 0, 
      si_sigval = {
        sival_int = 113, 
        sival_ptr = 0x71
      }
    }, 
    _rt = {
      si_pid = 0, 
      si_uid = 0, 
      si_sigval = {
        sival_int = 113, 
        sival_ptr = 0x71
      }
    }, 
    _sigchld = {
      si_pid = 0, 
      si_uid = 0, 
      si_status = 113, 
      si_utime = 139882285987864, 
      si_stime = 139882285987864
    }, 
    _sigfault = {
      si_addr = 0x0
    }, 
    _sigpoll = {
      si_band = 0, 
      si_fd = 113
    }, 
    _sigsys = {
      _call_addr = 0x0, 
      _syscall = 113, 
      _arch = 0
    }
  }
}

The strange thing is si_code = 128, which doesn't appear to be a valid value. From my brief experiments, it seems like some fault addresses (for example, 0xdeadbeefdeadbeef) generate si_code = 128 with si_addr = 0. I'll try to collect some more information about where the SIGSEGV came from, but I'm wondering if you have any ideas of what to look for.

Start with src/test/set_tid_address.c and the scheduler logs using RR_LOG=Scheduler, then inspect ReplaySession.cc around guard_unexpected_signal and emulate_async_signal. Reproduce both failures with rr record and rr replay on the affected 64-bit environment, and compare behavior across revisions. Done means the two tests pass without the scheduling failure or unexpected SIGSEGV.