consistent printf race conditions

consistent printf race conditions

[Nicholas Murphy]

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

Re: 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

Re: consistent printf race conditions

[Josh Stone]

On 10/24/2012 01:40 PM, Nicholas Murphy 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?

Can you provide a more complete script which demonstrates the error,
with at least the two close and wait probes?  And what sort of workload
do you run where it consistently fails?

I don't know why it would do this, but it will help if I can reproduce
the corruption locally.

It would also help if you could attach the output of stap-report.

Thanks,
Josh

Re: consistent printf race conditions

[Nicholas Murphy]

Scripts below.  Unfortunately, part of what I'm using this script for is figuring out what the workload is, so I can't provide you with a reliable way to replicate it.  I'll try to include some of the surrounding output on the offchance that might help.  FWIW, this is SystemTap 1.3.

-----
probe syscall.close.return {
  uid = uid()
  track_uid =   uid == 42 // normally does more checks like this
  if ((execname() != "stap" && execname() != "salt-minion" && execname() != "stap-io" && track_uid) && $return == 0) {
    // checks if pid and fd are in an associative array
    if (!is_fd_blacklisted(pid(), $fd)) {
        printf("{\"execname\":\"%s\",\"fd\":%d,\"op\":\"%s\",\"pid\":%d,\"ppid\":%d,\"return\":%d,\"timestamp\":%d,\"uid
\":%d}\n",clean_string(execname()),$fd,clean_string("CLOSE"),pid(),ppid(),$return,gettimeofday_ms(),uid())
    }
    unblacklist_fd(pid(), $fd)
    delete write_fds[pid(), $fd]
    delete read_fds[pid(), $fd]
  }   
}
-----
probe kernel.function("sys_wait4").call {
  uid = uid()
  track_uid =   uid == 0
  if ((execname() != "stap" && execname() != "salt-minion" && execname() != "stap-io" && track_uid)) {
    printf("{\"execname\":\"%s\",\"op\":\"%s\",\"options\":%d,\"pid\":%d,\"ppid\":%d,\"timestamp\":%d,\"uid\":%d}\n",cle
an_string(execname()),clean_string("WAITPID_CALL"),$options,$pid,ppid(),gettimeofday_ms(),uid())
  }
}
-----

Here's some output surrounding one of those errors (changed some values for security):
-----
{"execname":"bash","fd":3,"op":"CLOSE","pid":13562,"ppid":13561,"return":0,"timestamp":1347749678387,"uid":1}
{"execname":"bash","op":"PIPE","pid":13562,"pipe0":3,"pipe1":4,"ppid":13561,"return":0,"timestamp":1347749678387,       "uid":1}
{"execname":"bash","op":"FORK","pid":13562,"ppid":13561,"return":15121,"timestamp":1347749678387,"uid":1}
{"execname":"bash","fd":4,"op":"CLOSE","pid":15121,"ppid":13562,"return":0,"timestamp":1347749678387,"uid":1}
{"execname":"bash","fd":3,"op":"CLOSE","pid":13562,"ppid":13561,"return":0,"timestamp":1347749678388,"uid":1}
{"execname":"bash","fd":4,"op":"CLOSE","pid":13562,"ppid":13561,"return":0,"timestamp":1347749678388,"uid":1}
{"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":1}
{"args":"\"ls\" \"--color=tty\" \"-l\" \"t\"\"Output/\"","execname":"bash","filename":"<unknown>","op":"EXECVE_CALL","pid":15121,"ppid":13562,"pwd":"somepath","timestamp":1347749678388,"uid":1}
{"execname":"ls","fd":3,"op":"CLOSE","pid":15121,"ppid":13562,"return":0,"timestamp":1347749678388,"uid":1}
{"execname":"ls","op":"EXECVE_RETURN","pid":15121,"ppid":13562,"return":0,"timestamp":1347749678388,"uid":1}

On Oct 24, 2012, at 7:27 PM, Josh Stone <jistone@redhat.com> wrote:

> On 10/24/2012 01:40 PM, Nicholas Murphy 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?
> 
> Can you provide a more complete script which demonstrates the error,
> with at least the two close and wait probes?  And what sort of workload
> do you run where it consistently fails?
> 
> I don't know why it would do this, but it will help if I can reproduce
> the corruption locally.
> 
> It would also help if you could attach the output of stap-report.
> 
> Thanks,
> Josh

Re: consistent printf race conditions

[Frank Ch. Eigler]

Hi, Nicholas -


halcyonic wrote:

> Scripts below.  [...]
> probe syscall.close.return { [...]
>         printf("{\"execname\":\"%s\",\"fd\":%d,\"op\":\"%s\",\"pid\":%d,\"ppid\":%d,\"return\":%d,\"timestamp\":%d,\"uid
> \":%d}\n",clean_string(execname()),$fd,clean_string("CLOSE"),pid(),ppid(),$return,gettimeofday_ms(),uid())
> [...]

What does clean_string() look like?  Does it by any chance run
sprintf() or similar?


> Here's some output surrounding one of those errors (changed some
> values for security):

Could you try stap -b (bulk mode), resulting in some per-cpu trace files,
and then stap_merge'ing them back together?


- FChE

Re: consistent printf race conditions

[Nicholas Murphy]

Here's clean_string():
-----
function clean_string:string(str:string) {
    newstr = str_replace(str, "\"", "|||q")
    newstr = str_replace(newstr, "\n", "|||n")

    return newstr
}
-----

It's not happening as often as I'd thought...if I see it happening more, I'll try to capture it using the method you described and will let you know.

Thanks!

Nick

On Oct 24, 2012, at 8:48 PM, fche@redhat.com (Frank Ch. Eigler) wrote:

> 
> Hi, Nicholas -
> 
> 
> halcyonic wrote:
> 
>> Scripts below.  [...]
>> probe syscall.close.return { [...]
>>        printf("{\"execname\":\"%s\",\"fd\":%d,\"op\":\"%s\",\"pid\":%d,\"ppid\":%d,\"return\":%d,\"timestamp\":%d,\"uid
>> \":%d}\n",clean_string(execname()),$fd,clean_string("CLOSE"),pid(),ppid(),$return,gettimeofday_ms(),uid())
>> [...]
> 
> What does clean_string() look like?  Does it by any chance run
> sprintf() or similar?
> 
> 
>> Here's some output surrounding one of those errors (changed some
>> values for security):
> 
> Could you try stap -b (bulk mode), resulting in some per-cpu trace files,
> and then stap_merge'ing them back together?
> 
> 
> - FChE