Occasional delayed output of events

[Steve Grubb]

On Friday, January 1, 2021 4:22:33 PM EST Burn Alting wrote:
> Sometimes, events recorded in /var/log/audit/audit.log appear some seconds
> past co- located events which results in auparse:au_check_events() marking
> these events complete before they are. An example of this can be seen
> below with the offending event id 44609.
>
> This has been plaguing me for a year or two and this morning was the first
> time I still had access to the raw audit.log files (I monitor a lot of
> event types and the log files roll over fairly quickly).
> The example below is from a fully patched Centos 7 but I have also seen
> this on a patched Fedora 32.
> 
> Has this been seen before? Do we need to re-evaluate how auparse
> 'completes' an event (ie 2 seconds is too quick).

I have never seen this. But on the way to disk, auditd only does light 
processing of the event.  If the format is enriched, it looks things up on a 
record by record basis. It does not collect events until they are complete - 
it dumps it to disk as soon as it can tack on the extra information.

So, the question would be, does this delay happen on the way to disk? Or is 
this an artifact of post processing the logs with an auparse based utility? 
Can this be observed repeatedly on the same raw logs? If so, then maybe 
auparse does have some issue. But if this is a post processing issue, then 
the wall clock doesn't matter because this event should have collected up 
together.

I'd say this merits some investigation.

-Steve