consistent printf race conditions

[Nicholas Murphy <halcyonic at gmail dot com>]

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