Occasional delayed output of events

[Burn Alting]

All,

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).

type=SYSCALL msg=audit(1609519896.824:44603):
type=EXECVE msg=audit(1609519896.824:44603):
type=CWD msg=audit(1609519896.824:44603):
type=PATH msg=audit(1609519896.824:44603):
type=PATH msg=audit(1609519896.824:44603):
type=PROCTITLE msg=audit(1609519896.824:44603):
type=SYSCALL msg=audit(1609519896.826:44604):
type=EXECVE msg=audit(1609519896.826:44604):
type=CWD msg=audit(1609519896.826:44604):
type=PATH msg=audit(1609519896.826:44604):
type=PATH msg=audit(1609519896.826:44604):
type=PROCTITLE msg=audit(1609519896.826:44604):
type=SYSCALL msg=audit(1609519801.338:44605):
type=EXECVE msg=audit(1609519801.338:44605):
type=CWD msg=audit(1609519801.338:44605):
type=PATH msg=audit(1609519801.338:44605):
type=PATH msg=audit(1609519801.338:44605):
type=PROCTITLE msg=audit(1609519801.338:44605):
type=SYSCALL msg=audit(1609519900.159:44606):
type=EXECVE msg=audit(1609519900.159:44606):
type=CWD msg=audit(1609519900.159:44606):
type=PATH msg=audit(1609519900.159:44606):
type=PATH msg=audit(1609519900.159:44606):
type=PROCTITLE msg=audit(1609519900.159:44606):
type=SYSCALL msg=audit(1609519900.161:44607):
type=EXECVE msg=audit(1609519900.161:44607):
type=CWD msg=audit(1609519900.161:44607):
type=PATH msg=audit(1609519900.161:44607):
type=PATH msg=audit(1609519900.161:44607):
type=PROCTITLE msg=audit(1609519900.161:44607):
type=SYSCALL msg=audit(1609519896.829:44609):
type=EXECVE msg=audit(1609519896.829:44609):
type=CWD msg=audit(1609519896.829:44609):
type=SYSCALL msg=audit(1609519900.163:44608):
type=PATH msg=audit(1609519896.829:44609):
type=EXECVE msg=audit(1609519900.163:44608):
type=CWD msg=audit(1609519900.163:44608):
type=PATH msg=audit(1609519896.829:44609):
type=PROCTITLE msg=audit(1609519896.829:44609):
type=PATH msg=audit(1609519900.163:44608):
type=PATH msg=audit(1609519900.163:44608):
type=PROCTITLE msg=audit(1609519900.163:44608):
type=CRED_DISP msg=audit(1609519900.170:44610):
type=SYSCALL msg=audit(1609519900.170:44611):
type=EXECVE msg=audit(1609519900.170:44611):
type=CWD msg=audit(1609519900.170:44611):
type=PATH msg=audit(1609519900.170:44611):
type=PATH msg=audit(1609519900.170:44611):
type=PROCTITLE msg=audit(1609519900.170:44611):

which results in an ausearch -i output sequence of
----
type=PROCTITLE msg=audit(02/01/21 03:51:36.826:44604)
type=PATH msg=audit(02/01/21 03:51:36.826:44604)
type=PATH msg=audit(02/01/21 03:51:36.826:44604)
type=CWD msg=audit(02/01/21 03:51:36.826:44604)
type=EXECVE msg=audit(02/01/21 03:51:36.826:44604)
type=SYSCALL msg=audit(02/01/21 03:51:36.826:44604)
----
type=CWD msg=audit(02/01/21 03:51:36.829:44609)
type=EXECVE msg=audit(02/01/21 03:51:36.829:44609)
type=SYSCALL msg=audit(02/01/21 03:51:36.829:44609)
----
type=PROCTITLE msg=audit(02/01/21 03:51:36.829:44609)
type=PATH msg=audit(02/01/21 03:51:36.829:44609)
type=PATH msg=audit(02/01/21 03:51:36.829:44609)
----
type=PROCTITLE msg=audit(02/01/21 03:51:40.159:44606)
type=PATH msg=audit(02/01/21 03:51:40.159:44606)
type=PATH msg=audit(02/01/21 03:51:40.159:44606)
type=CWD msg=audit(02/01/21 03:51:40.159:44606)
type=EXECVE msg=audit(02/01/21 03:51:40.159:44606)
type=SYSCALL msg=audit(02/01/21 03:51:40.159:44606)
----
type=PROCTITLE msg=audit(02/01/21 03:51:40.161:44607)
type=PATH msg=audit(02/01/21 03:51:40.161:44607)
type=PATH msg=audit(02/01/21 03:51:40.161:44607)
type=CWD msg=audit(02/01/21 03:51:40.161:44607)
type=EXECVE msg=audit(02/01/21 03:51:40.161:44607)
type=SYSCALL msg=audit(02/01/21 03:51:40.161:44607)
----
type=PROCTITLE msg=audit(02/01/21 03:51:40.163:44608)
type=PATH msg=audit(02/01/21 03:51:40.163:44608)
type=PATH msg=audit(02/01/21 03:51:40.163:44608)
type=CWD msg=audit(02/01/21 03:51:40.163:44608)
type=EXECVE msg=audit(02/01/21 03:51:40.163:44608)
type=SYSCALL msg=audit(02/01/21 03:51:40.163:44608)
----
type=CRED_DISP msg=audit(02/01/21 03:51:40.170:44610)


Regards
Burn
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://listman.redhat.com/archives/linux-audit/attachments/20210102/2675682d/attachment.htm>