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

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

[Guillaume Destuynder]

Hi,

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.

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

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

[Steve Grubb]

On Monday, November 24, 2014 08:23:26 PM Guillaume Destuynder wrote:
> 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).

This seems to be a bug in the kernel code. Its a fundamental principle that 
all records that make up an event have the same time stamp and serial number. 
My guess (not having looked at the code) is that its calling a convenience 
function that looks up the time anew for each record rather than reading it 
once and reusing it as it outputs each record of the event.

The code in audit_log_exit is probably the only place where it really matters 
because it can generate multiple records composing 1 event. We might need a 
audit_log_start_time() function that takes the timestamp as a parameter. The 
old audit_log_start can grab a new timestamp and call the new function with 
the timestamp.

I think we should fix the source of the problem. This is a really good finding. 
I didn't realize this was happening.

Thanks,
-Steve

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

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

[Richard Guy Briggs]

On 14/12/01, Steve Grubb wrote:
> On Monday, November 24, 2014 08:23:26 PM Guillaume Destuynder wrote:
> > 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).
> 
> This seems to be a bug in the kernel code. Its a fundamental principle that 
> all records that make up an event have the same time stamp and serial number. 

Is it?  I don't know if there is any value in serializing the parts that
make up one event.

> My guess (not having looked at the code) is that its calling a convenience 
> function that looks up the time anew for each record rather than reading it 
> once and reusing it as it outputs each record of the event.

They are acquired in two different places...

> The code in audit_log_exit is probably the only place where it really matters 
> because it can generate multiple records composing 1 event. We might need a 
> audit_log_start_time() function that takes the timestamp as a parameter. The 
> old audit_log_start can grab a new timestamp and call the new function with 
> the timestamp.

For non-syscall timestamps, it is fine since they are both acquired at
the same time (and it doesn't matter since there is only one message).
For syscalls, the timestamp comes from __audit_syscall_entry(), while
the serial number is later assigned in auditsc_get_stamp().

> I think we should fix the source of the problem. This is a really good finding. 
> I didn't realize this was happening.

Agreed.  I'm looking at it.

> Thanks,
> -Steve
> 
> > 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.

- RGB

--
Richard Guy Briggs <rbriggs@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

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

[Steve Grubb]

On Monday, December 01, 2014 09:51:47 PM Richard Guy Briggs wrote:
> On 14/12/01, Steve Grubb wrote:
> > On Monday, November 24, 2014 08:23:26 PM Guillaume Destuynder wrote:
> > > 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).
> > 
> > This seems to be a bug in the kernel code. Its a fundamental principle
> > that all records that make up an event have the same time stamp and serial
> > number.
>
> Is it?  I don't know if there is any value in serializing the parts that
> make up one event.

Yes it is. This is a day 1 design decision. The serial number is to 
differentiate events within the same millisecond. Its not to be an identifier 
that alone is used for serialization. Without this ordering, we cannot glue 
all the parts of the event back together because the kernel _itself_ does not 
serialize events. Events can come out intermingled.

The original design:
https://www.kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.5-rc1/2.6.5-rc1-mm2/broken-out/lightweight-auditing-framework.patch

excerpt:
 The timestamp of the
 record and this serial number are used by the user-space daemon to
 determine which pieces belong to the same audit record.  The
 (timestamp,serial) tuple is unique for each syscall and is live from
 syscall entry to syscall exit.


-Steve

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

[Richard Guy Briggs]

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

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

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

[Richard Guy Briggs]

On 14/12/11, Guillaume Destuynder wrote:
> 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() )

It isn't out of order...  It is interleaved with another event.

That should not cause a problem to auditd or other userland tools, and
if it does, then that sounds like a bug in the log parsing/reassembly
code to me.

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

That is a bit helpful, but a smoking gun example would be more so...

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

Thanks for trying to track down more detail.

> 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@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
> 
> --
> Linux-audit mailing list
> Linux-audit@redhat.com
> https://www.redhat.com/mailman/listinfo/linux-audit

- RGB

--
Richard Guy Briggs <rbriggs@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