Strace issue with threading

[giuseppe pes]

Hi, I have found a strange behavior using strace with an application that
spawns threads.  The output is printed two times and I cannot understand
why.

Here it is the source code of the application :

>
> #include <stdio.h>
> #include <sys/time.h>
> #include <stdlib.h>
> #include <errno.h>
> #include <sys/syscall.h>
> #include <sys/types.h>
> #include <sched.h>
> #include <sched.h>
> #include <linux/sched.h>
> #include <unistd.h>
> #include <sys/wait.h>
> #include <string.h>
> #include <sys/mman.h>
> #define STACK_SIZE 0x10000
> #define BUFSIZE 200
> #define _GNU_SOURCE
> void hello (void * a){
>     fprintf(stdout,"Hello word hope %ld\n", syscall(SYS_gettid));
>     _exit(0);
> }
>
> int main()
> {
> int res;
> void *stack = mmap(0, STACK_SIZE, PROT_READ|PROT_WRITE,
>                        MAP_PRIVATE|MAP_ANONYMOUS, -1, 0);
>
> printf("Stack %p\n", stack + STACK_SIZE);
> memset(stack, 0, STACK_SIZE);
> res=clone(hello,stack + STACK_SIZE,
> CLONE_SIGHAND|CLONE_FS|CLONE_VM|CLONE_FILES);
> printf("Clone result %x\n", res);
> waitpid(-1, NULL, __WALL);
> return 0;
> }


Here there is the output of strace -ff -o calls.txt ./clone.out

Clone result 6142
> Clone result 6142
> Hello word hope 24898

Stack 0x7f9bfb13f000
>

The clone result should be printed just once.

System call sequences :

24897 execve("./clone.out", ["./clone.out"], [/* 58 vars */]) = 0
24897 brk(0)                            = 0x25b1000
24897 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x7f9bfb13f000
24897 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or
directory)
24897 open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
24897 fstat(3, {st_mode=S_IFREG|0644, st_size=177209, ...}) = 0
24897 mmap(NULL, 177209, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f9bfb113000
24897 close(3)                          = 0
24897 open("/lib64/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
24897 read(3,
"\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0`L\2\0\0\0\0\0"..., 832) =
832
24897 fstat(3, {st_mode=S_IFREG|0755, st_size=1736952, ...}) = 0
24897 mmap(NULL, 3849272, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE,
3, 0) = 0x7f9bfab73000
24897 mprotect(0x7f9bfad15000, 2097152, PROT_NONE) = 0
24897 mmap(0x7f9bfaf15000, 24576, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1a2000) = 0x7f9bfaf15000
24897 mmap(0x7f9bfaf1b000, 15416, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f9bfaf1b000
24897 close(3)                          = 0
24897 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x7f9bfb112000
24897 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x7f9bfb111000
24897 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x7f9bfb110000
24897 arch_prctl(ARCH_SET_FS, 0x7f9bfb111700) = 0
24897 mprotect(0x7f9bfaf15000, 16384, PROT_READ) = 0
24897 mprotect(0x600000, 4096, PROT_READ) = 0
24897 mprotect(0x7f9bfb140000, 4096, PROT_READ) = 0
24897 munmap(0x7f9bfb113000, 177209)    = 0
24897 mmap(NULL, 65536, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS,
-1, 0) = 0x7f9bfb12f000
24897 fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 3), ...}) = 0
24897 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x7f9bfb12e000
24897 write(1, "Stack 0x7f9bfb13f000\n", 21) = 21
24897 clone(child_stack=0x7f9bfb13eff0,
flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND) = 24898
24898 gettid( <unfinished ...>
24897 write(1, "Clone result 6142\n", 18 <unfinished ...>
24898 <... gettid resumed> )            = 24898
24897 <... write resumed> )             = 18
24898 write(1, "Clone result 6142\nHello word hop"..., 40 <unfinished ...>
24897 wait4(-1,  <unfinished ...>
24898 <... write resumed> )             = 40
24898 exit_group(0)                     = ?
24898 +++ exited with 0 +++
24897 <... wait4 resumed> NULL, __WALL, NULL) = 24898
24897 exit_group(0)                     = ?
24897 +++ exited with 0 +++

I guess the problem is due to the unfinished system calls.

Could you help me to understand it ?
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.strace.io/pipermail/strace-devel/attachments/20130712/9cbbd2e7/attachment.html>