Strace issue with threading

[Denys Vlasenko]

On 07/12/2013 12:00 PM, giuseppe pes wrote:
> 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; 
>     }

# gcc -Os -Wall t.c
t.c: In function ‘main’:
t.c:31:1: warning: passing argument 1 of ‘clone’ from incompatible pointer type [enabled by default]
 res=clone(hello,stack + STACK_SIZE, CLONE_SIGHAND|CLONE_FS|CLONE_VM|CLONE_FILES);
 ^
In file included from /usr/include/sched.h:42:0,
                 from t.c:8:
/usr/include/bits/sched.h:82:12: note: expected ‘int (*)(void *)’ but argument is of type ‘void (*)(void *)’
 extern int clone (int (*__fn) (void *__arg), void *__child_stack,
            ^
t.c:31:1: error: too few arguments to function ‘clone’
 res=clone(hello,stack + STACK_SIZE, CLONE_SIGHAND|CLONE_FS|CLONE_VM|CLONE_FILES);
 ^
In file included from /usr/include/sched.h:42:0,
                 from t.c:8:
/usr/include/bits/sched.h:82:12: note: declared here
 extern int clone (int (*__fn) (void *__arg), void *__child_stack,
            ^


> 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. 

It's an artifact of printf buffering.

You are using CLONE_VM, processes share their memory.

Parent's printf stores the data ("Clone result NNN") in stdout buffer,
and it gets accidentally reused by child's fprintf(stdout,...),

> 24897 write(1, "Clone result 6142\n", 18 <unfinished ...>
^^^^^^^^^
Parent

> 24898 write(1, "Clone result 6142\nHello word hop"..., 40 <unfinished ...>
^^^^^^^^^^^
Child uses parent's buffered data

If you replace [f]printf's with "dprintf(1, ...)" it stops happening.
-- 
vda