consistent printf race conditions

[Nicholas Murphy]

By way of update: it's not always just waitpid along with close, although it seems to virtually always involve either waitpid or execve and some other system call probe.  Again: is there any way to protect against this?  Usually SystemTap seems to be fairly good about making printf's atomic (at least at the granularity of line breaks), but it seems to be failing in this case...

Thanks,
Nick

On Oct 24, 2012, at 4:40 PM, Nicholas Murphy <halcyonic@gmail.com> wrote:

> I've been consistently seeing the following race condition: a printf from a close() system call pre-empts printing of a sys_wait4 hook.  Here's the sys_wait4 printf code:
> 
> printf("{\"execname\":\"%s\",\"op\":\"%s\",\"options\":%d,\"pid\":%d,\"ppid\":%d,\"timestamp\":%d,\"uid\":%d}\n",clean_string(execname()),clean_string("WAITPID_CALL"),$options,$pid,ppid(),gettimeofday_ms(),uid())
> 
> ...and here's an example of what I end up seeing printed:
> 
> {"execname":"bash","op":"WAITPID_CALL","options":10,"pid":-1,"ppid":13561,"timestamp":134{"execname":"bash","fd":3,"op":"CLOSE","pid":15121,"ppid":13562,"return":0,"timestamp":1347749678388,"uid":56441}
> 
> I don't see anything in the printf that would cause it to be pre-empted by another printf.  Any idea why I'm seeing this and what I could do to avoid it?  It seems to always be waitpid conflicting with close, so I could perhaps add an access to a common associative array to force synchronization between the two?
> 
> Thanks,
> Nick