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

Richard Guy Briggs
2014-12-11T19:34:18Z

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