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=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=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=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=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=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=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=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=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=PROCTITLE 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=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=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