[PATCH] auparse.c events_are_equal() and event matching

[Guillaume Destuynder]

Trying to reproduce, I got this instead (it seems to happen every few
thousands of msgs):

type=SYSCALL msg=audit(1418253698.016:418143181): arch=c000003e
syscall=59 success=yes exit=0 a0=663e42 a1=7ffffeb612c0 a2=7ffffeb65fd0 a3=
341f418240 items=2 ppid=2101 pid=2848 auid=0 uid=0 gid=0 euid=0 suid=0
fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=65254 comm="sh" exe="/b
in/bash" key="exec"
type=EXECVE msg=audit(1418253698.016:418143181): argc=3 a0="sh" a1="-c"
a2=[redacted]
type=CWD msg=audit(1418253698.016:418143181):  cwd="/opt/observium"
type=SYSCALL msg=audit(1418253698.016:418143182): arch=c000003e
syscall=59 success=yes exit=0 a0=663e42 a1=7fff7d1ac220 a2=7fff7d1b0f30 a3=
341f418240 items=2 ppid=2744 pid=2849 auid=0 uid=0 gid=0 euid=0 suid=0
fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=65254 comm="sh" exe="/b
in/bash" key="exec"
type=PATH msg=audit(1418253698.016:418143181): item=0 name="/bin/sh"
inode=1046605 dev=08:03 mode=0100755 ouid=0 ogid=0 rdev=00:00 nametype
=NORMAL
type=PATH msg=audit(1418253698.016:418143181): item=1 name=(null)
inode=2093138 dev=08:03 mode=0100755 ouid=0 ogid=0 rdev=00:00 nametype=NO
RMAL
type=EXECVE msg=audit(1418253698.016:418143182): argc=3 a0="sh" a1="-c"
a2=[redacted]
type=CWD msg=audit(1418253698.016:418143182):  cwd="/opt/observium"
type=PATH msg=audit(1418253698.016:418143182): item=0 name="/bin/sh"
inode=1046605 dev=08:03 mode=0100755 ouid=0 ogid=0 rdev=00:00 nametype
=NORMAL
type=PATH msg=audit(1418253698.016:418143182): item=1 name=(null)
inode=2093138 dev=08:03 mode=0100755 ouid=0 ogid=0 rdev=00:00 nametype=NO
RMAL


If you look carefully:

type=SYSCALL msg=audit(1418253698.016:418143182): arch=c000003e
syscall=59 success=yes exit=0 a0=663e42 a1=7fff7d1ac220 a2=7fff7d1b0f30 a3=
341f418240 items=2 ppid=2744 pid=2849 auid=0 uid=0 gid=0 euid=0 suid=0
fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=65254 comm="sh" exe="/b
in/bash" key="exec"

is "out of order" even thus timestamp/event id are correct. This causes
libaudit to also fail (as in doesnt output the complete message when
calling auparse_feed() )

That one machine is running 2.6.32-431.17.1.el6.x86_64 (RHEL6 kernel
package).

I'm trying to get the timestamp issue reproduced as I played quite a bit
with my local files - however this one is much harder to get. It was
also part of a type=EXECVE message however.

I suspect it was part of the errors either through UDP/syslog corruption
or different kernel. I'll keep looking tho.

Guillaume

On 12/10/2014 03:54 AM, Richard Guy Briggs wrote:
> On 14/11/24, Guillaume Destuynder wrote:
>> Hi,
> 
> Hi Guillaume,
> 
>> on our RHEL6 machines, with kernel 2.6.32, we noticed that sometimes an
>> audit message comes in but libaudit does not see it as the same event.
>>
>> The milliseconds field of the timestamp differs (but the timestamp
>> seconds and event serial are identical).
>>
>> The check to determine if 2 messages are part of the same event is done
>> by events_are_equal() in auparse/auparse.c (audit userspace library).
>>
>> There is a comment that indicate that this is voluntary - however, I
>> could not find why. I suspect this is for searches over long periods of
>> time when the serial may roll over.
>>
>> In case this was simply overlooked I'm attaching a patch that fixes it
>> for us. It keeps the timestamp check for the seconds, which works fine
>> and would still work with serial rolling over.
>>
>> Again- its relatively rare in our logs that the timestamp's millisecond
>> field differs and we log very heavily - so it's not that easy to reproduce.
> 
> Do you have a set (or three) of messages that fit this situation as a
> sample?  I'm looking through the kernel code to try and see how this is
> possible.  So far I am not convincing myself this is possible, but
> perhaps I am missing a combination of messages that fits this scenario.
> 
>> Thanks!
> 
> Thanks!
> 
>> Guillaume
>>
>> Index: trunk/auparse/auparse.c
>> ===================================================================
>> --- trunk/auparse/auparse.c   (revision 1063)
>> +++ trunk/auparse/auparse.c   (working copy)
>> @@ -752,10 +752,10 @@
>>
>>  static int inline events_are_equal(au_event_t *e1, au_event_t *e2)
>>  {
>> -       // Check time & serial first since its most likely way
>> -       // to spot 2 different events
>> -       if (!(e1->serial == e2->serial && e1->milli == e2->milli &&
>> -                                       e1->sec == e2->sec))
>> +       // Check serial and timestamp - but not milliseconds
>> +       // as, even if rare, these may not match for the same message due to
>> +       // kernel processing delays
>> +       if (!(e1->serial == e2->serial && e1->sec == e2->sec))
>>                 return 0;
>>         // Hmm...same so far, check if both have a host, only a string
>>         // compare can tell if they are the same. Otherwise, if only one
> 
> - RGB
> 
> --
> Richard Guy Briggs <rbriggs at redhat.com>
> Senior Software Engineer, Kernel Security, AMER ENG Base Operating Systems, Red Hat
> Remote, Ottawa, Canada
> Voice: +1.647.777.2635, Internal: (81) 32635, Alt: +1.613.693.0684x3545
> 

-- 
Security engineer @ Mozilla