kernel changes post-4.7 cause PTRACE_SYSCALL notifications to happen before PTRACE_SECCOMP_EVENT

[rocallahan]

See torvalds/linux@93e35ef. @pipcet reported this in #1552.

This breaks rr, but not fatally. In fact, it makes rr recording a bit more efficient. When recording a non-buffered syscall before, we'd have incur three ptrace-stops: PTRACE_SECCOMP_EVENT, PTRACE_SYSCALL stop, then a final PTRACE_SYSCALL stop for syscall exit. The second stop there is basically redundant with the first stop, but there was no way to stop at syscall exit without incurring that second stop. With the new event ordering, if we always continue to the next system call with PTRACE_CONT, we'll skip right over the syscall-entry PTRACE_SYSCALL stop and just incur two stops: PTRACE_SECCOMP_EVENT and the PTRACE_SYSCALL stop for syscall exit.

We have to update a fair bit of code to detect and handle this reordering. Syscall-entry code that used to run at the first PTRACE_SYSCALL stop has to be triggered by PTRACE_SECCOMP_EVENT instead. Of course, for many years we'll have to support both behaviors.

[rocallahan]

I've got this mostly working, with 92% of tests passing. I'm stuck on the clock_nanosleep test, which is very simple and the problem is probably affecting the other tests: the main thread does an exit_group while another thread is still running, and sometimes that other thread exits without us getting a PTRACE_EVENT_EXIT for it :-(. The problem is intermittent and seems to not be reproducible if I run rr under ftrace, or strace, or gdb, though it usually does happen if I run rr normally.

This could have been a preexisting bug (in older kernels, or rr without my changes), but I don't recall seeing it ever happen before. My changes might somehow cause this, but I can't see how (the logs look very clear about what happens):

[RecordSession] trace time 228: Active task is 32702. Events:
[RecordSession]   32702: handle_ptrace_event PTRACE_EVENT_SECCOMP: event (none)
[RecordSession]   traced syscall entered: nanosleep
[RecordTask]   is syscall interruption of recorded (none)? (now nanosleep)
[RecordSession] EXEC_SYSCALL_ENTRY: status=0x7057f (PTRACE_EVENT_SECCOMP)
[RecordSession] after cont: status=0x7057f (PTRACE_EVENT_SECCOMP)
[RecordSession] EXEC_START: status=0x7057f (PTRACE_EVENT_SECCOMP)
[RecordTask]   is syscall interruption of recorded SYSCALL: nanosleep? (now nanosleep)
[Task] resuming execution of 32702 with PTRACE_SYSCALL
[Scheduler] Scheduling next task
[Scheduler]   32702 is blocked on SYSCALL: nanosleep; checking status ...
[Task] waitpid(32702, NOHANG) returns 0, status 0 (EXIT-0)
[Scheduler]   still blocked
[Scheduler]   need to reschedule
... no mentions of 32702 ...
[Scheduler] Scheduling next task
[Scheduler]   (32701 is un-switchable at SYSCALL: exit_group)
[Scheduler]   and running; waiting for state change
[Task] going into blocking waitpid(32701) ...
[Task]   waitpid(32701) returns 32701; status 0x6057f (PTRACE_EVENT_EXIT)
[Task]   (refreshing register cache)
[Scheduler]   new status is 0x6057f (PTRACE_EVENT_EXIT)
[RecordSession] trace time 241: Active task is 32701. Events:
[WARN handle_ptrace_exit_event() errno: SUCCESS] unstable exit; may misrecord CLONE_CHILD_CLEARTID memory race
[Task] task 32701 (rec:32701) is dying ...
[WARN ~Task() errno: SUCCESS] 32701 is unstable; not blocking on its termination
[Task]   dead
[Scheduler] Scheduling next task
[Scheduler]   need to reschedule
[Scheduler]   32702 is unstable
[Scheduler]   all tasks blocked or some unstable, waiting for runnable (1 total)
[Scheduler]   32702 changed status to 0 (EXIT-0)
[Task]   (refreshing register cache)
[FATAL /home/roc/rr/rr/src/Task.cc:1276:did_waitpid() errno: ESRCH] 
 (task 32702 (rec:32702) at time 242)
 -> Assertion `false' failed to hold. 
Launch gdb with 
  gdb '-l' '-1' '-ex' 'target extended-remote :32702' /home/roc/rr/obj/bin/clock_nanosleep

So maybe it's a regression in the kernel ... maybe related to the seccomp changes, maybe not.

[rocallahan]

Building Linux master with that one commit reverted seems to make the bug go away, so it's definitely that kernel commit or my rr changes.

[rocallahan]

This also happens in the nanosleep test.

What seems to happen is that the non-main thread enters its final, long nanosleep, rr gets the notification, and then the non-main thread is not scheduled again. The main thread proceeds to exit_group; at this point the non-main thread's kernel stack looks like

[<ffffffff810b5837>] ptrace_stop+0x167/0x2a0
[<ffffffff810b5a08>] ptrace_do_notify+0x98/0xc0
[<ffffffff810b6e6b>] ptrace_notify+0x5b/0x80
[<ffffffff8116235a>] __seccomp_filter+0x20a/0x270
[<ffffffff81162a35>] __secure_computing+0x35/0xb0
[<ffffffff810033ae>] syscall_trace_enter+0xce/0x2f0
[<ffffffff81003d37>] do_syscall_64+0x147/0x160
[<ffffffff817f4821>] return_from_SYSCALL_64+0x0/0x6a
[<ffffffffffffffff>] 0xffffffffffffffff

[rocallahan]

With a fair amount of pain I've managed to construct a standalone testcase: https://gist.github.com/rocallahan/b09b1de28a32918cb27d4ad68421678d
I've fairly confident it's a kernel bug now.

[rocallahan]

And it reproduces in a kernel without the seccomp reordering changes. So it seems to be a longstanding kernel bug where an exit_group while a thread is at that point in ptrace_stop causes the thread to exit without reporting PTRACE_EVENT_EXIT.

[rocallahan]

I've figured this out. Here's what happens...

The problem occurs in this code in __seccomp_filter:

                /* Allow the BPF to provide the event message */
                ptrace_event(PTRACE_EVENT_SECCOMP, data);
                /*
                 * The delivery of a fatal signal during event
                 * notification may silently skip tracer notification.
                 * Terminating the task now avoids executing a system
                 * call that may not be intended.
                 */
                if (fatal_signal_pending(current)) {
                        do_exit(SIGSYS);
                }

When another thread in the thread-group does exit_group while a tracee thread is in the above ptrace-stop (or just after the stop has resumed but before we reach the fatal_signal_pending check), zap_other_threads marks the tracee thread as having a pending SIGKILL, so the tracee thread takes this do_exit path. do_exit calls ptrace_event(PTRACE_EVENT_EXIT, code) which puts the tracee thread into state TASK_TRACED and then (indirectly) calls __schedule. __schedule has this code:

                 if (unlikely(signal_pending_state(prev->state, prev))) {
                        prev->state = TASK_RUNNING;

In this case, SIGKILL is still pending so we change the state to TASK_RUNNING. The ptracer is notified and wakes up in wait4, which examines the tracee thread in wait_task_stopped. wait_task_stopped (via task_stopped_code) decides to skip the tracee because it is not in the TASK_TRACED state, so the ptracer doesn't see the PTRACE_EVENT_EXIT.

When a thread does an exit_group while the tracee thread is anywhere else, the synthetic SIGKILL is detected via get_signal which dequeues the signal before calling do_exit, which means the scheduler code does not force the transition back to TASK_RUNNING and everything works.

[rocallahan]

The seccomp reordering change made this a problem for rr because before that change, rr would always advance a tracee from the PTRACE_EVENT_SECCOMP stop to the PTRACE_SYSCALL stop before running any other tracee, so there was no way for another thread to do exit_group while the tracee was in the problematic section.

[rocallahan]

I'm not sure how to fix this, though that's mainly my lack of kernel experience. I think probably the seccomp code should dequeue the fatal signal before entering do_exit, to behave more like get_signal.

[rocallahan]

Email sent to LKML.

[rocallahan]

Here is the email thread: http://marc.info/?l=linux-kernel&m=147026862328685&w=2

[khuey]

This got fixed \o/