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

[Steve Grubb <sgrubb@redhat.com>]

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.