Bug 481753

Created attachment 330087 [details]
Test program

Can't reproduce on rhel 5.3

Denys, could you verify that all sub-threads have exited?

It could be the bug in strace (or in kernel, of course).

> EXIT_FLAG
>
> so, obviously, program reached exit(). But strace did not exit!

Perhaps not. Yes, the process exited, but the thread group can't
be reaped until all sub-threads have exited, and the traced
sub-thread can't "disappear" automatically (as it normally
happens) because it is traced.

Ok, I was wrong. RHEL does not have this bug, but Fedora does, specifically, kernel-2.6.29-0.28.rc1.fc11.

I will correct Product/version fields now.

Created attachment 330135 [details]
Example of (an older) testcase run under strace.

Strace itself was straced too. You can see how strace PTRACE_CONTed the tracee which was stopped at the entry to exit_group(), but subsequent wait4() nevertheless does not pick this process:


wait4(4294967295, [{WIFSTOPPED(s) && WSTOPSIG(s) == 133}], __WALL, NULL) = 4376
write(2, " [wait(0x857f) = 4376]\n", 23) = 23
wait4(4294967295, 0x7fff77bf5c9c, WNOHANG|__WALL, NULL) = 0
write(2, "pid 4376 stopped, [133]\n", 24) = 24
ptrace(PTRACE_PEEKUSER, 4376, 8*ORIG_RAX, [0xe7]) = 0
ptrace(PTRACE_PEEKUSER, 4376, 8*CS, [0x33]) = 0
ptrace(PTRACE_PEEKUSER, 4376, 8*RAX, [0xffffffffffffffda]) = 0
ptrace(PTRACE_PEEKUSER, 4376, 8*RDI, [0]) = 0
write(3, "4376  exit_group(0)             "..., 44) = 44
ptrace(PTRACE_CONT, 4376, 0x1, SIG_0)   = 0
--- SIGCHLD (Child exited) @ 0 (0) ---
write(2, "PTRACE_CONTed 4376\n", 19)    = 19
wait4(4294967295,

Task 4376 has two threads:

# ls -1 /proc/4376/task/
4376
4434

and looking into strace's strace, latest events with thread 4434 are:

wait4(4294967295, [{WIFSTOPPED(s) && WSTOPSIG(s) == 133}], __WALL, NULL) = 4434
write(2, " [wait(0x857f) = 4434]\n", 23) = 23
wait4(4294967295, 0x7fff77bf5c9c, WNOHANG|__WALL, NULL) = 0
write(2, "pid 4434 stopped, [133]\n", 24) = 24
ptrace(PTRACE_PEEKUSER, 4434, 8*ORIG_RAX, [0x3c]) = 0
ptrace(PTRACE_PEEKUSER, 4434, 8*CS, [0x33]) = 0
ptrace(PTRACE_PEEKUSER, 4434, 8*RAX, [0xffffffffffffffda]) = 0
ptrace(PTRACE_PEEKUSER, 4434, 8*RDI, [0]) = 0
write(3, "4434  _exit(0)                  "..., 44) = 44
ptrace(PTRACE_DETACH, 4434, 0x1, SIG_0) = 0
--- SIGCHLD (Child exited) @ 0 (0) ---
wait4(4294967295, [{WIFSTOPPED(s) && WSTOPSIG(s) == 133}], __WALL, NULL) = 4436

After this, we never see 4434 mentioned again. So it should disappear (since it's a thread and threads do not become zombies). But it didn't.

Oleg, per our discussion:

Having no timestamps in the log, I can't prove that _exit() in thread 4434 couldn't race with exit_group() in thread 4376, but it's very unlikely since
_exit is on line 9913 and
exit_group is on line 35149 of the log.

Looks like _exit() in a thread sometimes doesn't work properly when it is launched by PTRACE_DETACH.

(In reply to comment #5)
>
> Task 4376 has two threads:
>
> # ls -1 /proc/4376/task/
> 4376
> 4434

OK, so the hang in do_wait() is correct.

> and looking into strace's strace, latest events with thread 4434 are:
>
> wait4(4294967295, [{WIFSTOPPED(s) && WSTOPSIG(s) == 133}], __WALL, NULL) = 434
> write(2, " [wait(0x857f) = 4434]\n", 23) = 23
> wait4(4294967295, 0x7fff77bf5c9c, WNOHANG|__WALL, NULL) = 0
> write(2, "pid 4434 stopped, [133]\n", 24) = 24
> ptrace(PTRACE_PEEKUSER, 4434, 8*ORIG_RAX, [0x3c]) = 0
> ptrace(PTRACE_PEEKUSER, 4434, 8*CS, [0x33]) = 0
> ptrace(PTRACE_PEEKUSER, 4434, 8*RAX, [0xffffffffffffffda]) = 0
> ptrace(PTRACE_PEEKUSER, 4434, 8*RDI, [0]) = 0
> write(3, "4434  _exit(0)                  "..., 44) = 44
> ptrace(PTRACE_DETACH, 4434, 0x1, SIG_0) = 0

... and note that PTRACE_DETACH returns success, this sub-thread
was really stopped when strace entered sys_ptrace()

> After this, we never see 4434 mentioned again. So it should disappear (since
> it's a thread and threads do not become zombies). But it didn't.

Yep. Looks like we have the kernel bug, and now I don't understand
why it is not reproducible on upstream.

Currently I am not sure I understand what happens, just a guess.
We can race with the main thread which does group_exit() and sends
SIGKILL to sub-thread.

The sub-thread T is stopped, the tracer S does PTRACE_DETACH, and
T's group leader L does group_exit().

S enters sys_ptrace(PTRACE_DETACH), sees T->state == TASK_TRACED
and calls ptrace_detach().

L does group_exit(), sends SIGKILL to T and wakes up it.

T does do_exit()->exit_notify(). It notices ->ptrace != 0, so it
doesn't autoreap itself, but sets ->exit_state = TASK_ZOMBIE.

S does __ptrace_detach() and finally untraces this thread.


Now, nobody can reap T: it is not visible to do_wait() because
its ->exit_signal == -1. And L is not eligible_child() because
thread_group_empty() == F.

More. Even if we kill the original parent (strace in this case),
/sbin/init can't reap this thread group too for the same reason.

(In reply to comment #6)
> 
> Having no timestamps in the log, I can't prove that _exit() in thread 4434
> couldn't race with exit_group() in thread 4376, but it's very unlikely since
> _exit is on line 9913 and
> exit_group is on line 35149 of the log.

Agreed.

> Looks like _exit() in a thread sometimes doesn't work properly when it is
> launched by PTRACE_DETACH.

I have to re-check this, but looks like utrace make things a bit
worse in this respect. We do not need to race with SIGKILL.

This tracee does exit(), yes? Then, unless I missed something,
ptrace_detach_task() may cause utrace_wakeup(). In that case
T proceeds and passes exit_notify() before we untrace it.

So we have the same race in effect.

But again, unless I missed something.

Created attachment 330158 [details]
debug kernel patch: ptrace_detach() can leak a zombie?

I tried to install kernel-2.6.29-0.28.rc1.fc11, but failed.
The rhts machine is lost after reboot.

Until I find the way to do something else, perhaps someone
can re-test with this patch. The patch is not complete and
untested, just to check the theory.

To summarize.

This is upstream bug, but it is more "visible" with redhat kernels.

The patches were sent upstream, currently there are in -mm tree.
Denys confirms (thanks!) they really fix the problem.

Created a testcase for it, detach-sigkill-race:

http://sources.redhat.com/cgi-bin/cvsweb.cgi/~checkout~/tests/ptrace-tests/tests/detach-sigkill-race.c?cvsroot=systemtap

Oleg, do you expect those patches to be merged in 2.6.29?

(In reply to comment #13)
>
> Oleg, do you expect those patches to be merged in 2.6.29?

No, there are targeted for 2.6.30. Too late for 2.6.29.

(In reply to comment #14)
> (In reply to comment #13)
> >
> > Oleg, do you expect those patches to be merged in 2.6.29?
> 
> No, there are targeted for 2.6.30. Too late for 2.6.29.

Are they merged now? If so can you get the commit IDs?

(in reply to comment #15)
>
> Are they merged now?

Yes.

> If so can you get the commit IDs?

6d69cb87f05eef3b02370b2f7bae608ad2301a00
b1b4c6799fb59e710454bfe0ab477cb8523a8667
95c3eb76dc07fd81289888ffc42948196b34b444
4576145c1ecdaaea9ef8976a48335206aa1ebf91

This bug is really hard to reproduce -- I got one failure in 7000 test runs on one machine so far.

Do you mean 7000 runs of detach-sigkill-race?  It runs 2000 iterations.
Denys, can you tune detach-sigkill-race so it is more likely to hit the problem on an affected kernel?

(In reply to comment #18)
> Do you mean 7000 runs of detach-sigkill-race?  It runs 2000 iterations.

On a quad-core machine I was only able to get one failure in thousands of runs of detach-sigkill-race. On a dual-core it happened after ~100 runs.

fixed in 2.6.29.4-173

kernel-2.6.29.5-191.fc11 has been submitted as an update for Fedora 11.
http://admin.fedoraproject.org/updates/kernel-2.6.29.5-191.fc11

kernel-2.6.29.5-191.fc11 has been pushed to the Fedora 11 testing repository.  If problems still persist, please make note of it in this bug report.
 If you want to test the update, you can install it with 
 su -c 'yum --enablerepo=updates-testing update kernel'.  You can provide feedback for this update here: http://admin.fedoraproject.org/updates/F11/FEDORA-2009-6768

kernel-2.6.29.5-191.fc11 has been pushed to the Fedora 11 stable repository.  If problems still persist, please make note of it in this bug report.