Re: [PATCH 1/1] ptrace: make sure do_wait() won't hang after PTRACE_ATTACH
From: Denys Vlasenko
Date: Mon Feb 14 2011 - 13:55:51 EST
On Mon, Feb 14, 2011 at 6:51 PM, Oleg Nesterov <oleg@xxxxxxxxxx> wrote:
> On 02/14, Denys Vlasenko wrote:
>>
>> >> $ strace -tt sleep 30
>> >> 23:02:15.619262 execve("/bin/sleep", ["sleep", "30"], [/* 30 vars */]) = 0
>> >> ...
>> >> 23:02:15.622112 nanosleep({30, 0}, NULL) = ? ERESTART_RESTARTBLOCK (To be restarted)
>> >> 23:02:23.781165 --- SIGSTOP (Stopped (signal)) @ 0 (0) ---
>> >> 23:02:23.781251 --- SIGSTOP (Stopped (signal)) @ 0 (0) ---
>> >> (I forgot again why we see it twice. Another quirk I guess...)
>> >> 23:02:23.781310 restart_syscall(<... resuming interrupted call ...>) = 0
>> >> 23:02:45.622433 close(1) = 0
>> >> 23:02:45.622743 close(2) = 0
>> >> 23:02:45.622885 exit_group(0) = ?
>> >>
>> >> Why sleep didn't stop?
>> >>
>> >> Because PTRACE_SYSCALL brought the task out of group stop at once,
>> >> even though strace did try hard to not do so:
>> >>
>> >> ptrace(PTRACE_SYSCALL, $PID, 0x1, SIGSTOP) <-- note SIGSTOP!
>> >>
>> >> PTRACE_CONT in this situation would do the same.
>> >
>> > This can be fixed by updating strace, right? strace can look at the
>> > wait(2) exit code and if the tracee stopped for group stop, wait for
>> > the tracee to be continued instead of issuing PTRACE_SYSCALL.
>
> Ah, I seem to understand the confusion, let me repeat...
>
>> But tracee didn't stop _yet_.
>
> This depends on "_yet_". strace does ptrace(SYSCALL, SIGSTOP) twice.
> The first time it does this after the tracee reports the signal, and
> the tracee stopps.
>
>> Signal is not delivered _yet_, debugger
>> can decide at this point whether to deliver it:
>> ptrace(PTRACE_SYSCALL, $PID, 0x1, SIGSTOP)
>> or ignore:
>> ptrace(PTRACE_SYSCALL, $PID, 0x1, 0)
>>
>> strace has to deliver SIGSTOP if it wants to make program run exactly
>> as it would run without strace. So it tries to do so.
>> Currently, ptrace machinery doesn't react as strace, its user, expects it to.
>
> It does, see above. But then the tracee actually stopps, and report
> this to the tracer. However, strace handles this case as if this was
> another signal=SIGSTOP, so it does ptrace(SYSCALL, SIGSTOP) again.
>
> SIGSTOP has no effect, but PTRACE_SYSCALL wakeups the tracee.
I performed a small experiment. You are right, SIGSTOP here
is ignored, and PTRACE_SYSCALL wakes the tracee up:
replacing SIGSTOP with 0 doesn't change anything.
I tried to simply not do ptrace(PTRACE_SYSCALL, ..., 0) at all.
Behavior changes, but it is still wrong. Now tracee doesn't wake up
on SIGCONT. Here is the run of modified strace:
# strace -tt -s99 -oLOG ./strace sleep 55
execve("/bin/sleep", ["sleep", "55"], [/* 48 vars */]) = 0
brk(0) = 0x22a9000
...
nanosleep({55, 0}, NULL) = ? ERESTART_RESTARTBLOCK (To
be restarted)
<-- kill -STOP 25339
--- SIGSTOP (Stopped (signal)) @ 0 (0) --- STOP: si_signo:19 si_code:0
si_status:0 si_value:(nil)
--- SIGSTOP (Stopped (signal)) @ 0 (0) --- STOP:
ptrace(PTRACE_GETSIGINFO) failed
...does not exit for minutes...
<-- kill -CONT 25339
...still nothing, it is stopped, does not exit for minutes...
<-- kill -KILL 25339
+++ killed by SIGKILL +++
Here is what patched strace saw and did:
19:41:09.601764 wait4(-1, [{WIFSTOPPED(s) && WSTOPSIG(s) == SIGSTOP}],
__WALL, NULL) = 25339
19:41:09.601914 rt_sigprocmask(SIG_BLOCK, [HUP INT QUIT PIPE TERM], NULL, 8) = 0
19:41:09.602081 ptrace(PTRACE_GETSIGINFO, 25339, 0, {si_signo=SIGSTOP,
si_code=SI_USER, si_pid=10105, si_uid=0, si_value={int=0, ptr=0}}) = 0
19:41:09.602273 write(2, "--- SIGSTOP (Stopped (signal)) @ 0 (0) ---
STOP: si_signo:19 si_code:0 si_status:0 si_value:(nil) \n", 99) = 99
19:41:09.602456 ptrace(PTRACE_SYSCALL, 25339, 0x1, SIGSTOP) = 0
19:41:09.602582 --- SIGCHLD (Child exited) @ 0 (0) ---
19:41:09.602652 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
19:41:09.602792 wait4(-1, [{WIFSTOPPED(s) && WSTOPSIG(s) == SIGSTOP}],
__WALL, NULL) = 25339
19:41:09.602927 rt_sigprocmask(SIG_BLOCK, [HUP INT QUIT PIPE TERM], NULL, 8) = 0
19:41:09.603081 ptrace(PTRACE_GETSIGINFO, 25339, 0, 0x7fff436fc730) =
-1 EINVAL (Invalid argument)
19:41:09.603231 write(2, "--- SIGSTOP (Stopped (signal)) @ 0 (0) ---
STOP: ptrace(PTRACE_GETSIGINFO) failed \n", 83) = 83
19:41:09.603369 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
<<<< the change is here. Unpatched strace would do
ptrace(PTRACE_SYSCALL, 25339, 0x1, SIGSTOP) >>>
19:41:09.603511 wait4(-1, [{WIFSIGNALED(s) && WTERMSIG(s) ==
SIGKILL}], __WALL, NULL) = 25339
<<<< SIGCONT is not visible! >>>>>
19:47:00.836723 --- SIGCHLD (Child exited) @ 0 (0) ---
19:47:00.836804 rt_sigprocmask(SIG_BLOCK, [HUP INT QUIT PIPE TERM], NULL, 8) = 0
19:47:00.837010 write(2, "+++ killed by SIGKILL +++\n", 26) = 26
19:47:00.837212 rt_sigaction(SIGKILL, {SIG_DFL, [KILL],
SA_RESTORER|SA_RESTART, 0x7f5df12d5970}, {0x7fff436f0043, ~[HUP INT
BUS USR2 PIPE ALRM TTIN XCPU PROF WINCH IO PWR RTMIN RT_16 RT_17 RT_18
RT
19:47:00.837458 gettid() = 25338
19:47:00.837596 tgkill(25338, 25338, SIGKILL <unfinished ...>
19:47:00.837831 +++ killed by SIGKILL +++
As you see, SIGCONT was completely invisible to debugger.
--
vda
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/