6:12 p.m.
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(a)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