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