auparse.c events_are_equal() and event matching

PATCH In review Guillaume Destuynder 3 participants 7 messages Nov 25, 2014 – Dec 11, 2014

lore

Share & tools

lore

Guillaume Destuynder

author

2014-11-25 04:23 UTC #0 lore raw

PATCH 1/1 auparse.c events_are_equal() and event matching

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

auparse/auparse.c (working copy) renamed from auparse/auparse.c (revision 1063) +4 -4

Index: trunk/auparse/auparse.c
===================================================================
@@ -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

Steve Grubb

2014-12-01 14:58 UTC #1 lore raw

Quoted 5 lines · Guillaume Destuynder

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

Quoted 13 lines

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.

Richard Guy Briggs

2014-12-02 02:51 UTC #2 lore raw

Quoted 9 lines · Steve Grubb

Quoted 5 lines · Guillaume Destuynder
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.

Quoted 3 lines

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

Quoted 5 lines

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

Quoted 2 lines

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.

Quoted 16 lines

Thanks,
-Steve
Quoted 13 lines
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 <[email protected]>
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

Steve Grubb

2014-12-02 13:44 UTC #3 lore raw

Quoted 8 lines · Richard Guy Briggs

Quoted 7 lines · Steve Grubb
Quoted 5 lines · Guillaume Destuynder
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).

Quoted 6 lines

Quoted 3 lines
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

Richard Guy Briggs

2014-12-10 02:54 UTC #4 lore raw

In reply to Guillaume Destuynder

Quoted 1 line · Guillaume Destuynder

Hi,

Hi Guillaume,

Quoted 13 lines

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.

Quoted 6 lines

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.

Quoted 1 line

Thanks!

Thanks!

Quoted 11 lines

Guillaume
Index: trunk/auparse/auparse.c
===================================================================
auparse/auparse.c (working copy) renamed from auparse/auparse.c (revision 1063) +0 -1
@@ -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

auparse/auparse.c (working copy) line 761

Quoted 10 lines

auparse/auparse.c (working copy) renamed from auparse/auparse.c (revision 1063) +4 -3

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

Guillaume Destuynder

author

2014-12-11 00:12 UTC #5 lore raw

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

Quoted 64 lines · Richard Guy Briggs

Quoted 1 line · Guillaume Destuynder
Hi,
Hi Guillaume,
Quoted 13 lines
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.
Quoted 6 lines
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.
Quoted 1 line
Thanks!
Thanks!
Quoted 11 lines
Guillaume
Index: trunk/auparse/auparse.c
===================================================================
auparse/auparse.c (working copy) renamed from auparse/auparse.c (revision 1063) +0 -1
@@ -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
auparse/auparse.c (working copy) line 761
Quoted 10 lines
auparse/auparse.c (working copy) renamed from auparse/auparse.c (revision 1063) +4 -3
-       // 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 <[email protected]>
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

Signature · 1 line

Security engineer @ Mozilla

Richard Guy Briggs

2014-12-11 19:34 UTC #6 lore raw

Quoted 41 lines · 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"

Quoted 3 lines

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.

Quoted 6 lines

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

Quoted 2 lines

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.

Quoted 61 lines

Guillaume
Quoted 58 lines · Richard Guy Briggs
Quoted 1 line · Guillaume Destuynder
Hi,
Hi Guillaume,
Quoted 13 lines
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.
Quoted 6 lines
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.
Quoted 1 line
Thanks!
Thanks!
Quoted 11 lines
Guillaume
Index: trunk/auparse/auparse.c
===================================================================
auparse/auparse.c (working copy) renamed from auparse/auparse.c (revision 1063) +0 -1
@@ -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
auparse/auparse.c (working copy) line 761
Quoted 10 lines
auparse/auparse.c (working copy) renamed from auparse/auparse.c (revision 1063) +4 -3
-       // 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

Quoted 14 lines

Quoted 6 lines
--
Richard Guy Briggs <[email protected]>
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
Signature · 6 lines
Security engineer @ Mozilla

--
Linux-audit mailing list
[email protected]
https://www.redhat.com/mailman/listinfo/linux-audit

- RGB