strace lockup when tracing exec in go

[I am CCing strace mailing list because even if this turns out to be a
kernel bug strace seems to be doing something unexpected - more on that below]

Hi,
Aleksa has reported the following lockup when stracing the following go program

% cat exec.go
package main

import (

    "os"
    "syscall"

)

func main() {
    syscall.Exec("/bin/echo", []string{"/bin/echo", "Hello"}, os.Environ())
}
$ go version
go version go1.6.3 linux/amd64
$ go build -o exec exec.go

$ strace -f ./exec
[snip]
[pid 10349] select(0, NULL, NULL, NULL, {0, 100} 
[pid 10346] <... select resumed> )      = 0 (Timeout)
[pid 10346] select(0, NULL, NULL, NULL, {0, 20} 
[pid 10345] execve("/bin/echo", ["/bin/echo", "Hello"], [/* 95 vars */] 
[pid 10346] <... select resumed> )      = 0 (Timeout)
[pid 10349] <... select resumed> )      = 0 (Timeout)

execve will never finish unless the strace process get killed with SIGKILL. The following was debugged on 3.12 kernel and the current kernel seems to not trigger the issue as easily but I believe the same problem is there as well.

The further investigation shown that the tracer (strace) is stuck waiting for cred_guard_mutex

[<0000000000000000>] mm_access+0x22/0xa0
[<0000000000000000>] process_vm_rw_core.isra.1+0x112/0x6c0
[<0000000000000000>] process_vm_rw+0xab/0x110
[<0000000000000000>] SyS_process_vm_readv+0x15/0x20
[<0000000000000000>] system_call_fastpath+0x16/0x1b

[<0000000000000000>] 0x7f186f031c3a
[<0000000000000000>] 0xffffffffffffffff

while the traced process (3 threads) are trying to perform the exec. That means that 2 threads are dead (in fact zombies) waiting in their final schedule.

Call Trace:
 [] do_exit+0x6f7/0xa70
 [] do_group_exit+0x39/0xa0
 [] get_signal_to_deliver+0x1e8/0x5c0
 [] do_signal+0x42/0x670
 [] do_notify_resume+0x78/0xc0
 [] int_signal+0x12/0x17
 [<00007f3a33f3ffb9>] 0x7f3a33f3ffb8

and one is

Call Trace:
 [] flush_old_exec+0xdf/0x890
 [] load_elf_binary+0x307/0xda0
 [] search_binary_handler+0xae/0x1f0
 [] do_execve_common.isra.26+0x64e/0x810
 [] SyS_execve+0x31/0x50
 [] stub_execve+0x69/0xa0
 [<00007f3a33f16527>] 0x7f3a33f16526

waiting for notify_count to drop down to 0

        while (sig->notify_count) {
                __set_current_state(TASK_KILLABLE);
                spin_unlock_irq(lock);
                schedule(); <<<<<<<<<
                if (unlikely(__fatal_signal_pending(tsk)))
                        goto killed;
                spin_lock_irq(lock);
        }

this however doesn't happen because both threads which are dead are zombies waiting to be reaped by the parent and to call their release_task->__exit_signal. The tracer is blocked on the lock held by exec (in prepare_bprm_creds). This is the case in the current kernel as well AFAICS so the same should be possible as well. So is this a bug or something somewhere else makes sure that this will not happen in newer kernels?

master.today...

So I've stared into do_notify_parent some more and the following was just very confusing

if (!tsk->ptrace && sig == SIGCHLD &&
(psig->action[SIGCHLD-1].sa.sa_handler == SIG_IGN ||
(psig->action[SIGCHLD-1].sa.sa_flags & SA_NOCLDWAIT))) {
/*
* We are exiting and our parent doesn't care. POSIX.1
* defines special semantics for setting SIGCHLD to SIG_IGN
* or setting the SA_NOCLDWAIT flag: we should be reaped
* automatically and not left for our parent's wait4 call.
* Rather than having the parent do it as a magic kind of
* signal handler, we just set this to tell do_exit that we
* can be cleaned up without becoming a zombie. Note that
* we still call __wake_up_parent in this case, because a
* blocked sys_wait4 might now return -ECHILD. *
* Whether we send SIGCHLD or not for SA_NOCLDWAIT
* is implementation-defined: we do (if you don't want
* it, just use SIG_IGN instead).
*/
autoreap = true;
if (psig->action[SIGCHLD-1].sa.sa_handler == SIG_IGN)
sig = 0;
}

it tries to prevent from what I am seeing in a way. If the SIGCHLD is ignored then it just does autoreap and everything is fine. But this doesn't seem to be the case here. In fact we are not sending the signal because sig_task_ignored is true resp. sig_handler_ignored which can fail even for handler == SIG_DFL && sig_kernel_ignore() and SIGCHLD seems to be in SIG_KERNEL_IGNORE_MASK. So I've tried

On Thu 22-09-16 06:15:02, Mike Galbraith wrote:
[...]

Quoted 1 line

master.today...

Thanks for trying to reproduce this. My tiny laptop (2 cores, 2 threads per core) cannot reproduce even in 10 minutes or so. I've tried to use the same machine I was testing with 3.12 kernel (2 sockets, 8 cores per soc. and 2 threas per core) and it hit almost instantly. I have tried mutex_lock_killable -> interruptible and it didn't help as I've expected. So the current kernel doesn't do any magic to prevent from the issue as well.

So I've stared into do_notify_parent some more and the following was just very confusing

if (!tsk->ptrace && sig == SIGCHLD &&
(psig->action[SIGCHLD-1].sa.sa_handler == SIG_IGN ||
(psig->action[SIGCHLD-1].sa.sa_flags & SA_NOCLDWAIT))) {
/*
* We are exiting and our parent doesn't care. POSIX.1
* defines special semantics for setting SIGCHLD to SIG_IGN
* or setting the SA_NOCLDWAIT flag: we should be reaped
* automatically and not left for our parent's wait4 call.
* Rather than having the parent do it as a magic kind of
* signal handler, we just set this to tell do_exit that we
* can be cleaned up without becoming a zombie. Note that
* we still call __wake_up_parent in this case, because a
* blocked sys_wait4 might now return -ECHILD. *
* Whether we send SIGCHLD or not for SA_NOCLDWAIT
* is implementation-defined: we do (if you don't want
* it, just use SIG_IGN instead).
*/
autoreap = true;
if (psig->action[SIGCHLD-1].sa.sa_handler == SIG_IGN)
sig = 0;
}

it tries to prevent from what I am seeing in a way. If the SIGCHLD is ignored then it just does autoreap and everything is fine. But this doesn't seem to be the case here. In fact we are not sending the signal because sig_task_ignored is true resp. sig_handler_ignored which can fail even for handler == SIG_DFL && sig_kernel_ignore() and SIGCHLD seems to be in SIG_KERNEL_IGNORE_MASK. So I've tried

Quoted 38 lines · Michal Hocko

On Thu 22-09-16 06:15:02, Mike Galbraith wrote:
[...]

Quoted 1 line

master.today...

Thanks for trying to reproduce this. My tiny laptop (2 cores, 2 threads per core) cannot reproduce even in 10 minutes or so. I've tried to use the same machine I was testing with 3.12 kernel (2 sockets, 8 cores per soc. and 2 threas per core) and it hit almost instantly. I have tried mutex_lock_killable -> interruptible and it didn't help as I've expected. So the current kernel doesn't do any magic to prevent from the issue as well.

So I've stared into do_notify_parent some more and the following was just very confusing

> > if (!tsk->ptrace && sig == SIGCHLD &&
> > (psig->action[SIGCHLD-1].sa.sa_handler == SIG_IGN ||
> > (psig->action[SIGCHLD-1].sa.sa_flags & SA_NOCLDWAIT))) {
> > > > /*
> > > > * We are exiting and our parent doesn't care. POSIX.1
> > > > * defines special semantics for setting SIGCHLD to SIG_IGN
> > > > * or setting the SA_NOCLDWAIT flag: we should be reaped
> > > > * automatically and not left for our parent's wait4 call.
> > > > * Rather than having the parent do it as a magic kind of
> > > > * signal handler, we just set this to tell do_exit that we
> > > > * can be cleaned up without becoming a zombie. Note that
> > > > * we still call __wake_up_parent in this case, because a
> > > > * blocked sys_wait4 might now return -ECHILD.
> > > > *
> > > > * Whether we send SIGCHLD or not for SA_NOCLDWAIT
> > > > * is implementation-defined: we do (if you don't want
> > > > * it, just use SIG_IGN instead).
> > > > */
> > > > autoreap = true;
> > > > if (psig->action[SIGCHLD-1].sa.sa_handler == SIG_IGN)
> > > > > > sig = 0;
> > }

Quoted 6 lines

it tries to prevent from what I am seeing in a way. If the SIGCHLD is ignored then it just does autoreap and everything is fine. But this doesn't seem to be the case here. In fact we are not sending the signal because sig_task_ignored is true resp. sig_handler_ignored which can fail even for handler == SIG_DFL && sig_kernel_ignore() and SIGCHLD seems to be in SIG_KERNEL_IGNORE_MASK. So I've tried

Dohh, I've missed !tsk->ptrace check there. So we are not even going that via that path. So the sig_handler_ignored cannot possible help. I was just too lucky and didn't hit the lockup with the patch.

So what else might be wrong here? sig_ignored seems to be quite confusing

	> /*
	>  * Tracers may want to know about even ignored signals.
	>  */
	> return !t->ptrace;

t is the tracer here but it shouldn't have t->ptrace because the child is not stopped. So do we need something like the following? Not tested yet

kernel/signal.c +0 -0

index 1840c7f4e3c2..bd236ce4a29c 100644

Quoted 70 lines · Michal Hocko

Quoted 38 lines · Michal Hocko

On Thu 22-09-16 06:15:02, Mike Galbraith wrote:
[...]

Quoted 1 line

master.today...

Thanks for trying to reproduce this. My tiny laptop (2 cores, 2 threads per core) cannot reproduce even in 10 minutes or so. I've tried to use the same machine I was testing with 3.12 kernel (2 sockets, 8 cores per soc. and 2 threas per core) and it hit almost instantly. I have tried mutex_lock_killable -> interruptible and it didn't help as I've expected. So the current kernel doesn't do any magic to prevent from the issue as well.

So I've stared into do_notify_parent some more and the following was just very confusing

> > if (!tsk->ptrace && sig == SIGCHLD &&
> > (psig->action[SIGCHLD-1].sa.sa_handler == SIG_IGN ||
> > (psig->action[SIGCHLD-1].sa.sa_flags & SA_NOCLDWAIT))) {
> > > > /*
> > > > * We are exiting and our parent doesn't care. POSIX.1
> > > > * defines special semantics for setting SIGCHLD to SIG_IGN
> > > > * or setting the SA_NOCLDWAIT flag: we should be reaped
> > > > * automatically and not left for our parent's wait4 call.
> > > > * Rather than having the parent do it as a magic kind of
> > > > * signal handler, we just set this to tell do_exit that we
> > > > * can be cleaned up without becoming a zombie. Note that
> > > > * we still call __wake_up_parent in this case, because a
> > > > * blocked sys_wait4 might now return -ECHILD.
> > > > *
> > > > * Whether we send SIGCHLD or not for SA_NOCLDWAIT
> > > > * is implementation-defined: we do (if you don't want
> > > > * it, just use SIG_IGN instead).
> > > > */
> > > > autoreap = true;
> > > > if (psig->action[SIGCHLD-1].sa.sa_handler == SIG_IGN)
> > > > > > sig = 0;
> > }

Quoted 6 lines

it tries to prevent from what I am seeing in a way. If the SIGCHLD is ignored then it just does autoreap and everything is fine. But this doesn't seem to be the case here. In fact we are not sending the signal because sig_task_ignored is true resp. sig_handler_ignored which can fail even for handler == SIG_DFL && sig_kernel_ignore() and SIGCHLD seems to be in SIG_KERNEL_IGNORE_MASK. So I've tried

Dohh, I've missed !tsk->ptrace check there. So we are not even going that via that path. So the sig_handler_ignored cannot possible help. I was just too lucky and didn't hit the lockup with the patch.

So what else might be wrong here? sig_ignored seems to be quite confusing

	> /*
	>  * Tracers may want to know about even ignored signals.
	>  */
	> return !t->ptrace;

t is the tracer here but it shouldn't have t->ptrace because the child is not stopped. So do we need something like the following? Not tested yet

kernel/signal.c +0 -0

index 1840c7f4e3c2..bd236ce4a29c 100644
@@ -91,6 +91,10 @@ static int sig_ignored(struct task_struct *t, int sig, bool force)
 > 	> if (!sig_task_ignored(t, sig, force))
 > 	> 	> return 0;
 

kernel/signal.c static int sig_ignored(struct task_struct *t, int sig, bool force) · line 100

Quoted 7 lines

kernel/signal.c +4 -0

+> 	> /* Do not ignore signals sent from child to the parent */
+> 	> if (current->ptrace && current->parent == t)
+> 	> 	> return 0;
+
 > 	> /*
 > 	>  * Tracers may want to know about even ignored signals.
 > 	>  */

This patch doesn't help, nor does the previous patch... but with both applied, all is well. All you have to do now is figure out why :)

Quoted 2 lines · Mike Galbraith

This patch doesn't help, nor does the previous patch... but with both applied, all is well. All you have to do now is figure out why :)

Ohh, I should be more explicit, this needs the mm_access part as well. Sorry for not being clear enough. So the full change is

Quoted 7 lines · Michal Hocko

Quoted 2 lines · Mike Galbraith

This patch doesn't help, nor does the previous patch... but with both applied, all is well. All you have to do now is figure out why :)

Ohh, I should be more explicit, this needs the mm_access part as well. Sorry for not being clear enough. So the full change is

Ah. That was gonna happen after lunch, but since you already know it works, I can get back to un-b0rking one of my trees.

Quoted 11 lines · Mike Galbraith

Quoted 7 lines · Michal Hocko

Quoted 2 lines · Mike Galbraith

This patch doesn't help, nor does the previous patch... but with both applied, all is well. All you have to do now is figure out why :)

Ohh, I should be more explicit, this needs the mm_access part as well. Sorry for not being clear enough. So the full change is

Ah. That was gonna happen after lunch, but since you already know it works, I can get back to un-b0rking one of my trees.

Yeah, it should work. The testcase is running in a loop for more than hour already and everything seems to be ok. Now the question is whether the fix is really correct which is something for Oleg.

Also I think there is at least one more issue lurking there. Without or without the patch I can make tracer get stuck in do_wait waiting for task which doesn't seem to be alive anymore. I will report it separately after this one gets resolved to not pull more confusion in.

From fe82d463fd2ef1585d2c37bf9fa6a1761e6ee0e5 Mon Sep 17 00:00:00 2001

Quoted 9 lines

Quoted 8 lines

Quoted 5 lines

Quoted 2 lines

This patch doesn't help, nor does the previous patch... but with both applied, all is well. All you have to do now is figure out why :)

Ohh, I should be more explicit, this needs the mm_access part as well. Sorry for not being clear enough. So the full change is

Ah. That was gonna happen after lunch, but since you already know it works, I can get back to un-b0rking one of my trees.

Quoted 8 lines

Yeah, it should work. The testcase is running in a loop for more than hour already and everything seems to be ok. Now the question is whether the fix is really correct which is something for Oleg.

Also I think there is at least one more issue lurking there. Without or without the patch I can make tracer get stuck in do_wait waiting for task which doesn't seem to be alive anymore. I will report it separately after this one gets resolved to not pull more confusion in.

OK, the test in the loop has survived 3h of runtime without a single lockup so the patch seems to be working for this case. I am posting the patch with the full changelog, let's see if it is correct as well. As I've said earlier this might be a strace bug which does an unexpected syscall while it should be doing wait on the child process instead.

If the patch is correct then I would mark it for stable as well.

kernel/signal.c static int sig_ignored(struct task_struct *t, int sig, bool force) · line 96

Quoted 10 lines · Michal Hocko

kernel/signal.c +3 -0

@@ -91,6 +91,10 @@ static int sig_ignored(struct task_struct *t, int sig, bool force)
 	if (!sig_task_ignored(t, sig, force))
 		return 0;
 
+	/* Do not ignore signals sent from child to the parent */
+	if (current->ptrace && current->parent == t)
+		return 0;

This doesn't look right in general, and this can't really help.

This assumes that the tracer will call do_wait() after mm_access() fails, but this is not necessarily true.

Note also ptrace_attach(), -ERESTARTNOINTR means that the tracer won't even return to user-space if SIGCHLD is ignored, the tracer will silently restart the syscall.

Quoted 14 lines · Oleg Nesterov

kernel/signal.c static int sig_ignored(struct task_struct *t, int sig, bool force) · line 96

Quoted 10 lines · Michal Hocko

kernel/signal.c +3 -0

@@ -91,6 +91,10 @@ static int sig_ignored(struct task_struct *t, int sig, bool force)
 	if (!sig_task_ignored(t, sig, force))
 		return 0;
 
+	/* Do not ignore signals sent from child to the parent */
+	if (current->ptrace && current->parent == t)
+		return 0;

This doesn't look right in general, and this can't really help.

Quoted 6 lines

This assumes that the tracer will call do_wait() after mm_access() fails, but this is not necessarily true.

Note also ptrace_attach(), -ERESTARTNOINTR means that the tracer won't even return to user-space if SIGCHLD is ignored, the tracer will silently restart the syscall.

Well, it apparently does help the strace case.

So I am not arguing this
is the best fix but can it be harmful?

Quoted 23 lines · Michal Hocko

Quoted 20 lines · Oleg Nesterov

kernel/signal.c static int sig_ignored(struct task_struct *t, int sig, bool force) · line 96

Quoted 10 lines · Michal Hocko

kernel/signal.c +3 -0

@@ -91,6 +91,10 @@ static int sig_ignored(struct task_struct *t, int sig, bool force)
 	if (!sig_task_ignored(t, sig, force))
 		return 0;
 
+	/* Do not ignore signals sent from child to the parent */
+	if (current->ptrace && current->parent == t)
+		return 0;

This doesn't look right in general, and this can't really help.

This assumes that the tracer will call do_wait() after mm_access() fails, but this is not necessarily true.

Note also ptrace_attach(), -ERESTARTNOINTR means that the tracer won't even return to user-space if SIGCHLD is ignored, the tracer will silently restart the syscall.

Quoted 1 line

Well, it apparently does help the strace case.

Only because strace doesn't even try to handle -EINTR; it assumes this is not possible, gives up, and calls wait() after that. So this change actually breaks strace.

And once again, this can't really help. SIGCHLD can come before strace calls process_vm_readv(), and in this case it will enter the syscall without signal_pending() == T. IOW, this hack can only help if the tracer already sleeps in process_vm_readv().

Plus, again, "strace -f" can equally hang if mt-exec races with PTRACE_ATTACH.

Quoted 2 lines

So I am not arguing this
is the best fix but can it be harmful?

This change is simply wrong no matter what.

We could change do_notify_parent()
to call signal_wake_up() if tsk->ptrace, but see above, this won't help.

Quoted 2 lines · Oleg Nesterov

This change is simply wrong no matter what.

I've just tried to extend the existing

	/*
	 * Tracers may want to know about even ignored signals.
	 */
	return !t->ptrace;

but I probably just do not understand what that actually means. I thought that the tracer is _really_ interested in hearing about the signal.

Quoted 3 lines

We could change do_notify_parent()
to call signal_wake_up() if tsk->ptrace, but see above, this won't help.

So does this mean WONTFIX? Can we at least document this behavior? It surely is unexpected.

Quoted 12 lines · Michal Hocko

Quoted 2 lines · Oleg Nesterov

This change is simply wrong no matter what.

I've just tried to extend the existing

	/*
	 * Tracers may want to know about even ignored signals.
	 */
	return !t->ptrace;

Quoted 3 lines

but I probably just do not understand what that actually means. I thought that the tracer is _really_ interested in hearing about the signal.

Yes, the tracer is really interested to know that a signal was sent to the _tracee_, not the tracer ;)

Quoted 5 lines

Quoted 2 lines

We could change do_notify_parent()
to call signal_wake_up() if tsk->ptrace, but see above, this won't help.

So does this mean WONTFIX? Can we at least document this behavior? It surely is unexpected.

No, no, no. Of course this must be fixed. The only problem is that I still do not know what should we do. I'll try to return to this problem next week. I'm afraid we will need to change de_thread() to wait until all other sub- threads have passed exit_notify() or even exit_signals(),

but ooh I don't
like this. Plus in this case we will need to finally define what PTRACE_EVENT_EXIT should actually do.

The further investigation shown that the tracer (strace) is stuck waiting for cred_guard_mutex

[<0000000000000000>] mm_access+0x22/0xa0
[<0000000000000000>] process_vm_rw_core.isra.1+0x112/0x6c0
[<0000000000000000>] process_vm_rw+0xab/0x110
[<0000000000000000>] SyS_process_vm_readv+0x15/0x20
[<0000000000000000>] system_call_fastpath+0x16/0x1b

[<0000000000000000>] 0x7f186f031c3a
[<0000000000000000>] 0xffffffffffffffff

this however doesn't happen because both threads which are dead are zombies waiting to be reaped by the parent and to call their release_task->__exit_signal.

Sorry for delay, I was offline. I'll try to return to this problem next week, currently I can't even read this thread but at first glance the proposed patch(es) do not look right...

Quoted 10 lines · Michal Hocko

The further investigation shown that the tracer (strace) is stuck waiting for cred_guard_mutex

[<0000000000000000>] mm_access+0x22/0xa0
[<0000000000000000>] process_vm_rw_core.isra.1+0x112/0x6c0
[<0000000000000000>] process_vm_rw+0xab/0x110
[<0000000000000000>] SyS_process_vm_readv+0x15/0x20
[<0000000000000000>] system_call_fastpath+0x16/0x1b

[<0000000000000000>] 0x7f186f031c3a
[<0000000000000000>] 0xffffffffffffffff

...

Quoted 3 lines

this however doesn't happen because both threads which are dead are zombies waiting to be reaped by the parent and to call their release_task->__exit_signal.

Yes, I know, this was already reported. And so far I do not see any reasonable fix. I _think_ that the "real" fix should rework the security_bprm_* helpers, but unlikely this is possible.

The trivial test-case:

	void *thread(void *arg)
	{
		ptrace(PTRACE_TRACEME, 0,0,0);
		return NULL;
	}

	int main(void)
	{
		int pid = fork();

		if (!pid) {
			pthread_t pt;
			pthread_create(&pt, NULL, thread, NULL);
			pthread_join(pt, NULL);
			execlp("echo", "echo", "passed", NULL);
		}

		sleep(1);
		// or anything else which needs ->cred_guard_mutex,
		// say open(/proc/$pid/mem)
		ptrace(PTRACE_ATTACH, pid, 0,0);
		kill(pid, SIGCONT);

		return 0;
	}

Oleg.