Assertion failure with signal unblocking in Emacs

[dcolascione]

I'm using rr on a modified Emacs. It mostly works, but anything with signals confuses poor rr:

$ EMACSLOADPATH=$PWD/../lisp rr record ./emacs --dump-file=XXX -Q --batch --eval '(xmessage "hello world")'rr: Saving execution to trace directory `/home/dancol/.local/share/rr/emacs-28'.
loading dump file [XXX]
result: 0
Back to top level
Error in post-command-hook (eldoc-schedule-timer): (file-missing "Cannot open load file" "No such file or directory" "time-date")
[FATAL /home/dancol/software/rr/src/RecordTask.cc:1067:restore_sigmask() errno: SUCCESS] 
 (task 26263 (rec:26263) at time 11883)
 -> Assertion `has_previously_blocked_sigs' failed to hold. 
Launch gdb with 
  gdb '-l' '10000' '-ex' 'target extended-remote :26263' /home/dancol/edev/debug/src/emacs

Attaching GDB,

(gdb) where
#0  0x0000000070000002 in  ()
#1  0x00007f0d78e57018 in _raw_syscall () at /home/dancol/software/rr/src/preload/raw_syscall.S:120
#2  0x00007f0d78e5403e in traced_raw_syscall (call=call@entry=0x681fffa8)
    at /home/dancol/software/rr/src/preload/preload.c:235
#3  0x00007f0d78e54f88 in syscall_hook_internal (call=0x681fffa8)
    at /home/dancol/software/rr/src/preload/preload.c:2442
#4  0x00007f0d78e54f88 in syscall_hook (call=0x681fffa8) at /home/dancol/software/rr/src/preload/preload.c:2454
#5  0x00007f0d78e5704a in _syscall_hook_trampoline () at /home/dancol/software/rr/src/preload/syscall_hook.S:206
#6  0x00007f0d78e5708d in _syscall_hook_trampoline_48_3d_00_f0_ff_ff ()
    at /home/dancol/software/rr/src/preload/syscall_hook.S:279
#7  0x00007f0d71f15f82 in __pselect (nfds=6, readfds=0x7ffd47d06ca0, writefds=0x7ffd47d06d20, exceptfds=0x0, timeout=<optimized out>, sigmask=<optimized out>) at ../sysdeps/unix/sysv/linux/pselect.c:69
#8  0x00000000007183b7 in xg_select (fds_lim=6, rfds=0x7ffd47d07360, wfds=0x7ffd47d073e0, efds=0x0, timeout=0x7ffd47d072f0, sigmask=0x0) at xgselect.c:112
#9  0x00000000006b911a in wait_reading_process_output (time_limit=0, nsecs=0, read_kbd=-1, do_display=true, wait_for_cell=..., wait_proc=0x0, just_wait_proc=0) at process.c:5198
#10 0x000000000059b1e5 in kbd_buffer_get_event (kbp=0x7ffd47d076d8, used_mouse_menu=0x7ffd47d07d55, end_time=0x0)
    at keyboard.c:3841
#11 0x0000000000596168 in read_event_from_main_queue (end_time=0x0, local_getcjmp=0x7ffd47d07b50, used_mouse_menu=0x7ffd47d07d55) at keyboard.c:2161
#12 0x00000000005964c3 in read_decoded_event_from_main_queue (end_time=0x0, local_getcjmp=0x7ffd47d07b50, prev_event=..., used_mouse_menu=0x7ffd47d07d55) at keyboard.c:2224
#13 0x000000000059837e in read_char (commandflag=1, map=..., prev_event=..., used_mouse_menu=0x7ffd47d07d55, end_time=0x0) at keyboard.c:2812
#14 0x00000000005a891c in read_key_sequence (keybuf=0x7ffd47d07f80, bufsize=30, prompt=..., dont_downcase_last=false, can_return_switch_frame=true, fix_current_buffer=true, prevent_redisplay=false) at keyboard.c:9132
#15 0x0000000000593dbd in command_loop_1 () at keyboard.c:1378
#16 0x0000000000652283 in internal_condition_case (bfun=0x593954 <command_loop_1>, handlers=..., hfun=0x592fac <cmd_error>) at eval.c:1318
#17 0x000000000059356f in command_loop_2 (ignore=...) at keyboard.c:1120
#18 0x000000000065178a in internal_catch (tag=..., func=0x593542 <command_loop_2>, arg=...) at eval.c:1084
#19 0x000000000059350d in command_loop () at keyboard.c:1099
#20 0x0000000000592aa0 in recursive_edit_1 () at keyboard.c:705
#21 0x0000000000592c90 in Frecursive_edit () at keyboard.c:776
#22 0x00000000005909b3 in main (argc=6, argv=0x7ffd47d083d8) at emacs.c:1718

[dcolascione]

FWIW, here's ths stack trace for RR itself:

(gdb) where
#0  0x00007f244df7093d in accept () at ../sysdeps/unix/syscall-template.S:84
#1  0x000055658188c148 in rr::GdbConnection::await_debugger (this=0x556583463b30, listen_fd=...)
    at /home/dancol/software/rr/src/GdbConnection.cc:113
#2  0x000055658188c7e2 in rr::GdbConnection::await_client_connection (desired_port=26452, 
    probe=rr::GdbConnection::PROBE_PORT, tgid=26452, debugger_name="gdb", 
    exe_image="/home/dancol/edev/debug/src/emacs", features=..., client_params_fd=0x0)
    at /home/dancol/software/rr/src/GdbConnection.cc:165
#3  0x00005565818a7cbb in rr::await_connection (t=0x556583464d20, port=26452, 
    probe=rr::GdbConnection::PROBE_PORT, features=..., debugger_name="gdb", client_params_fd=0x0)
    at /home/dancol/software/rr/src/GdbServer.cc:1312
#4  0x00005565818a8606 in rr::GdbServer::emergency_debug (t=0x556583464d20)
    at /home/dancol/software/rr/src/GdbServer.cc:1407
#5  0x00005565818c8fa3 in rr::emergency_debug (t=0x556583464d20) at /home/dancol/software/rr/src/log.cc:288
#6  0x00005565818c91fc in rr::EmergencyDebugOstream::~EmergencyDebugOstream (this=0x7ffcefa12a80, 
    __in_chrg=<optimized out>) at /home/dancol/software/rr/src/log.cc:310
#7  0x0000556581935119 in rr::RecordTask::restore_sigmask (this=0x556583464d20)
    at /home/dancol/software/rr/src/RecordTask.cc:1067
#8  0x000055658193ab35 in rr::RecordTask::on_syscall_exit_arch<rr::X64Arch> (this=0x556583464d20, syscallno=270, 
    regs=...) at /home/dancol/software/rr/src/RecordTask.cc:538
#9  0x00005565819328f4 in rr::RecordTask::on_syscall_exit (this=0x556583464d20, syscallno=270, regs=...)
    at /home/dancol/software/rr/src/RecordTask.cc:547
#10 0x00005565818fdafc in rr::rec_process_syscall (t=0x556583464d20)
    at /home/dancol/software/rr/src/record_syscall.cc:4820
#11 0x00005565818e73f7 in rr::RecordSession::syscall_state_changed (this=0x556583461f60, t=0x556583464d20, 
    step_state=0x7ffcefa12f00) at /home/dancol/software/rr/src/RecordSession.cc:906
#12 0x00005565818ec0c9 in rr::RecordSession::record_step (this=0x556583461f60)
    at /home/dancol/software/rr/src/RecordSession.cc:1924
#13 0x00005565818e259f in rr::record (args=std::vector of length 6, capacity 8 = {...}, flags=...)
    at /home/dancol/software/rr/src/RecordCommand.cc:296
#14 0x00005565818e2a49 in rr::RecordCommand::run (this=0x556581c8ad60 <rr::RecordCommand::singleton>, 
    args=std::vector of length 6, capacity 8 = {...}) at /home/dancol/software/rr/src/RecordCommand.cc:363
#15 0x00005565819c1d2f in main (argc=8, argv=0x7ffcefa13258) at /home/dancol/software/rr/src/main.cc:270

[khuey]

Hmm, what was the result of that pselect call? (In other words, what's going on in rr's frame 8)

[dcolascione]

What do you mean? The pselect hasn't returned yet.

[dcolascione]

Oh, rr's frame 8. Let me look.

[dcolascione]

(gdb) print regs.syscall_failed ()
$3 = false
(gdb) print regs.syscall_result()
$4 = 0

[khuey]

Is pselect6 getting called with a NULL sigmask? From code inspection it looks like that might trigger this assertion.

[dcolascione]

Yes.

[khuey]

Ok, the bug then is that at https://github.com/mozilla/rr/blob/5e0bdeb4b71b8898edfedf754c30cf225e817799/src/RecordTask.cc#L535 we're null checking the 6th argument to pselect6, but really we should be null-checking a field within that argument. See the "The final argument of the pselect6" ... bit of https://linux.die.net/man/2/pselect6

This should be relatively straightforward for you to patch. Alternatively, I can do it when I have some spare time.

[dcolascione]

Thanks. Patched locally. Will sent the actual patch in a few days.

[khuey]

Fixed by #1928.