Package: strace
Version: 4.5.17+cvs080723-2
strace seems to have a problem in the handling of stop signals.
A traced child of a traced parent which calls raise(SIGSTOP) does not
stop execution! Instead, it continues unhindered. Furthermore, a
parent waiting in waitpid(,,WUNTRACED) remains oblivious.
See the attached test program and strace output, and the transcript
below. If I compile this with gcc -Wall and run it, it works as
expected. However, if I execute it under strace -f, the bugs above
can be seen.
In the strace, notice how at 14:46:54.621392 pid 16258 (the child) is
shown as receiving a SIGSTOP. Mysteriously this line appears twice.
However, in fact, the child does not stop as it should, and neither
does the parent's waitpid complete.
Instead the child carries on to execute its next sleep and then _exit,
and the parent's waitpid returns only at that point.
i...@thule:~$ gcc -Wall sigstop-test.c
i...@thule:~$ sh -c 'while sleep 0.25; do printf +; done' &
[1] 16186
i...@thule:~$ ++++++++++./a.out+++
BEGIN sleep1 PARENT 16202 WAITPID++++ raise GOT CHILD WIFSTOPPED 19
SLEEP3+++++++++++ KILL WAITPID sleep2++++++++ exit GOT CHILD WIFEXITED 0 EXIT
i...@thule:~$ +++++strace -tt -f -ostrace.out ./a.out++
BEGIN PARENT 16235 WAITPID sleep1++++ raise sleep2++++++++ exit GOT CHILD
WIFEXITED 0 EXIT
i...@thule:~$ ++fg++
sh -c 'while sleep 0.25; do printf +; done'
+^C
i...@thule:~$
These symptoms seem to be reproduceable on a variety of systems
including etch (strace 4.5.14-2, 2.6.18-6-i486, libc6
2.3.6.ds1-13etch7) and lenny (4.5.17+cvs080723-2, 2.6.26-1-686,
2.7-18).
A peruse of the other bugs for strace suggests this may be related to
#424706, #360700, #377200 but this is by no means certain.
Ian.
#include <assert.h>
#include <stdio.h>
#include <unistd.h>
#include <errno.h>
#include <sys/types.h>
#include <sys/wait.h>
#define D(c) write(1," " #c,sizeof(#c));
static void DI(long i) {
char buf[23];
int l;
l= sprintf(buf," %ld",i);
write(1,buf,l);
}
int main(int argc, char **argv) {
pid_t child, got;
int status;
D(BEGIN);
child= fork(); assert(child!=-1);
if (!child) {
D(sleep1);
sleep(1);
D(raise);
raise(SIGSTOP);
D(sleep2);
sleep(2);
D(exit);
_exit(0);
}
D(PARENT);
DI(child);
for (;;) {
D(WAITPID);
got= waitpid(child, &status, WUNTRACED);
D(GOT);
if (got==-1) {
assert(errno==EINTR);
D(EINTR);
continue;
}
assert(got==child);
D(CHILD);
if (WIFSTOPPED(status)) {
D(WIFSTOPPED);
DI(WSTOPSIG(status));
D(SLEEP3);
sleep(3);
D(KILL);
kill(child, SIGCONT);
} else if (WIFSIGNALED(status)) {
D(WIFSIGNALED);
DI(WTERMSIG(status));
break;
} else if (WIFEXITED(status)) {
D(WIFEXITED);
DI(WEXITSTATUS(status));
break;
} else {
D(UNKNOWN);
DI(status);
break;
}
}
D(EXIT);
write(1,"\n",1);
_exit(0);
}
16257 14:46:53.609725 execve("./a.out", ["./a.out"], [/* 18 vars */]) = 0
16257 14:46:53.610382 brk(0) = 0x804a000
16257 14:46:53.610469 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
16257 14:46:53.610565 mmap2(NULL, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f0a000
16257 14:46:53.610644 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
16257 14:46:53.610720 open("/etc/ld.so.cache", O_RDONLY) = 3
16257 14:46:53.610789 fstat64(3, {st_mode=S_IFREG|0644, st_size=33253, ...}) = 0
16257 14:46:53.610900 mmap2(NULL, 33253, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7f01000
16257 14:46:53.610956 close(3) = 0
16257 14:46:53.611015 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
16257 14:46:53.611095 open("/lib/i686/cmov/libc.so.6", O_RDONLY) = 3
16257 14:46:53.611167 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\260e\1\0004\0\0\0\4"..., 512) = 512
16257 14:46:53.611257 fstat64(3, {st_mode=S_IFREG|0755, st_size=1413540, ...}) = 0
16257 14:46:53.611361 mmap2(NULL, 1418864, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb7da6000
16257 14:46:53.611423 mmap2(0xb7efb000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x155) = 0xb7efb000
16257 14:46:53.611497 mmap2(0xb7efe000, 9840, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb7efe000
16257 14:46:53.611566 close(3) = 0
16257 14:46:53.611648 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7da5000
16257 14:46:53.611715 set_thread_area({entry_number:-1 -> 6, base_addr:0xb7da56b0, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}) = 0
16257 14:46:53.611866 mprotect(0xb7efb000, 4096, PROT_READ) = 0
16257 14:46:53.611931 munmap(0xb7f01000, 33253) = 0
16257 14:46:53.612032 write(1, " BEGIN"..., 6) = 6
16257 14:46:53.612163 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xb7da56f8) = 16258
16257 14:46:53.612452 write(1, " PARENT"..., 7) = 7
16257 14:46:53.612601 write(1, " 16258"..., 6) = 6
16257 14:46:53.612705 write(1, " WAITPID"..., 8) = 8
16257 14:46:53.612817 waitpid(16258, <unfinished ...>
16258 14:46:53.612909 write(1, " sleep1"..., 7) = 7
16258 14:46:53.613047 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
16258 14:46:53.613136 rt_sigaction(SIGCHLD, NULL, {SIG_DFL}, 8) = 0
16258 14:46:53.613201 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
16258 14:46:53.613259 nanosleep({1, 0}, {1, 0}) = 0
16258 14:46:54.621184 write(1, " raise"..., 6) = 6
16258 14:46:54.621316 tgkill(16258, 16258, SIGSTOP) = 0
16258 14:46:54.621392 --- SIGSTOP (Stopped (signal)) @ 0 (0) ---
16258 14:46:54.621435 --- SIGSTOP (Stopped (signal)) @ 0 (0) ---
16258 14:46:54.621462 write(1, " sleep2"..., 7) = 7
16258 14:46:54.621555 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
16258 14:46:54.621631 rt_sigaction(SIGCHLD, NULL, {SIG_DFL}, 8) = 0
16258 14:46:54.621705 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
16258 14:46:54.621764 nanosleep({2, 0}, {2, 0}) = 0
16258 14:46:56.631114 write(1, " exit"..., 5) = 5
16258 14:46:56.631236 exit_group(0) = ?
16257 14:46:56.631445 <... waitpid resumed> [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], WSTOPPED) = 16258
16257 14:46:56.631481 --- SIGCHLD (Child exited) @ 0 (0) ---
16257 14:46:56.631510 write(1, " GOT"..., 4) = 4
16257 14:46:56.631600 write(1, " CHILD"..., 6) = 6
16257 14:46:56.631706 write(1, " WIFEXITED"..., 10) = 10
16257 14:46:56.631813 write(1, " 0"..., 2) = 2
16257 14:46:56.631912 write(1, " EXIT"..., 5) = 5
16257 14:46:56.632013 write(1, "\n"..., 1) = 1
16257 14:46:56.632112 exit_group(0) = ?
