occasionally missing PTRACE_EVENT_VFORK when running ptrace

Question

I'm sorry that I can't post code to reproduce this. My problem is precisely that I don't know how to go about debugging this issue.

I am using ptrace with PTRACE_O_TRACEFORK | PTRACE_O_TRACEEXEC | PTRACE_O_TRACEVFORK | PTRACE_O_TRACEVFORKDONE | PTRACE_O_TRACECLONE to trace a process and it's children (and the children's children). The mechanism is much like strace, but with slightly different purposes, as I'm just tracking files that are read or modified.

My code (written in C) works fine on Debian wheezy and Debian jessie on the x86-64 architecture (and also less-tested on i386). When I try to compile and run on an Ubuntu Precise x86-64 virtual machine (which uses a 3.2.0 kernel), I run into trouble.

On the Precise machine, I sometimes find that I do not receive a PTRACE_EVENT_VFORK immediately after a vfork call happens, but instead start receiving events (a couple of SIGSTOP events, and a few system calls) without ever getting the PTRACE_EVENT_VFORK event. I don't see anything suspicious in the system calls being performed, and the behavior is not predictable.

I'm not sure what to try to reduce this to a minimal error case, and I really have no idea as to what might be going wrong, having never before seen this behavior of missing events. It is conceivable that the difference is not the kernel, but rather the build tools that I am tracing (which is a combination of python + gcc).

Any suggestions?

Answer 1

I was working on something similar recently. I suspect you've solved your problem long ago or gave up, but let's write an answer here for posterity.

The various events you register with PTRACE_SETOPTIONS generate messages different from the normal ptrace events. But the normal events are still generated. One normal event is that a newly forked process starts stopped and has to be continued from the tracer.

This means that if you have registered events you watch with PTRACE_O_TRACEFORK (or VFORK) waitpid will trigger twice for the same process after a fork.

One will be with a status that is:

WIFSTOPPED(status) && (WSTOPSIG(status) & 0xff == SIGSTOP)

The other one will be with:

WIFSTOPPED(status) && (WSTOPSIG(status) & 0xff == 0) &&
    ((status >> 16) == PTRACE_EVENT_FORK) /* or VFORK */

There does not seem to be any guarantee from the kernel in which order they will arrive. I found it being close to 50/50 on my system.

To handle this my code looks something like this:

static void
proc_register(struct magic *pwi, pid_t pid, bool fork) {
    /*
     * When a new process starts two things happen:
     *  - We get a wait with STOPPED, SIGTRAP, PTRACE_EVENT_{CLONE,FORK,VFORK}
     *  - We get a wait with STOPPED, SIGSTOP
     *
     * Those can come in any order, so to get the proc in the right
     * state this function should be called twice on every new proc. If
     * it's called with fork first, we set the state to NEW_FORKED, if
     * it's called with STOP first, we set NEW_STOPPED. Then when the
     * other call comes, we set the state to TRACED and continue the
     * process.
     */
    if ((p = find_proc(pwi, pid)) == NULL) {
            p = calloc(1, sizeof(*p));
            p->pid = pid;
            TAILQ_INSERT_TAIL(&pwi->procs, p, list);
            if (fork) {
                    p->state = NEW_FORKED;
            } else {
                    p->state = NEW_STOPPED;
            }
    } else {
            assert((fork && p->state == NEW_STOPPED) || (!fork && p->state == NEW_FORKED));
            p->state = TRACED;
            int flags = PTRACE_O_TRACEEXEC|PTRACE_O_TRACEEXIT|PTRACE_O_TRACEFORK|PTRACE_O_TRACEVFORK;

            if (ptrace(PTRACE_SETOPTIONS, pid, NULL, flags))
                    err(1, "ptrace(SETOPTIONS, %d)", pid);
            if (ptrace(PTRACE_CONT, pid, NULL, signal) == -1)
                    err(1, "ptrace(CONT, %d, %d)", pid, signal);
    }
}
[...]
    pid = waitpid(-1, &status, __WALL);
    if (WIFSTOPPED(status) && (WSTOPSIG(status) & 0xff == SIGSTOP)) {
            proc_register(magic, pid, false);
    } else if (WIFSTOPPED(status) && (WSTOPSIG(status) & 0xff == 0) && ((status >> 16) == PTRACE_EVENT_FORK)) {
            proc_register(magic, pid, true);
    } else {
            /* ... */
    }

The key to making this work was to not send PTRACE_CONT until we receive both events. When figuring out how this works I was sending PTRACE_CONT way too much and the kernel happily accepted them which sometimes even led to my processes exiting long before PTRACE_EVENT_FORK arrived. This made it quite hard to debug.

N.B. I haven't found any documentation about this or anything saying that this is the way it should be. I just found out that this makes things work as things are today. YMMV.

Answer 2

I've bumped into this page several times (for different reasons). If the tracer traces lots of tracees, and there're lots of events (such as when SECCOMP is set to RET_TRACE). waitpid(-1, ...) maybe not the best thing to wait for any tracees, because there could be a lot of tracees changing states, especially in SMP systems (who else is still running UP system), which means there could be tons of events arriving in very short amount of time, and OP was right the events can be out-of-order: some event or signal can happen even before PTRACE_EVENT_FORK.

However, this is not the case (no out-of-order events) when tracer calls waitpid(specific_pid_greater_than_zero,...): we wait a specific tracee ONLY. Granted you program model might not looks as elegant/simple, you may even need to track tracee states (blocking or not), and decides when/which tracee to continue (PTRACE_CONT), but with the bonus not to worry about the hacky ways to handle out-of-order events (also hardly to get it right).