Re: Occasional delayed output of events
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