Bug 1914603

Summary: Ausearch fails to correctly parse an event whose timestamp appears more than 2 seconds later than co-located events
Product: Red Hat Enterprise Linux 7 Reporter: Burn Alting <burn>
Component: auditAssignee: Sergio Correia <scorreia>
Status: CLOSED WONTFIX QA Contact: BaseOS QE Security Team <qe-baseos-security>
Severity: unspecified Docs Contact: Steve Grubb <sgrubb>
Priority: unspecified    
Version: 7.9CC: lvrabec
Target Milestone: rc   
Target Release: ---   
Hardware: Unspecified   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of:
: 1921658 (view as bug list) Environment:
Last Closed: 2021-01-27 15:55:56 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 1921658    
Attachments:
Description Flags
Sample source of a delayed event in an audit.log file. none

Description Burn Alting 2021-01-10 04:36:14 UTC 
Created attachment 1745953 [details]
Sample source of a delayed event in an audit.log file.

Created attachment 1745953 [details]
Sample source of a delayed event in an audit.log file.

Description of problem:
Ausearch(8) fails to parse an audit event correctly if it's timestamp is such that is more than two seconds earlier than a co-located event.

Version-Release number of selected component (if applicable):
audit-2.8.5-4.el7.x86_64
audit-3.0-1.fc33.x86_64

This also occurs in RHEL-8 and Fedora ... it is a fundamental bug in upstream audit-userspace package.

How reproducible:
Always

Steps to Reproduce:
1. Have a heavily used host generate events for all execves
2. Monitor audit.log files for error
3.

Actual results:
[root@auditdtest audit-userspace]# ausearch -if /tmp/audit.test.log
----
time->Sat Jan  2 03:51:36 2021
type=CWD msg=audit(1609519896.829:44609):  cwd="/usr/security/auditd/queue"
type=EXECVE msg=audit(1609519896.829:44609): argc=6 a0="find" a1="." a2="-regextype" a3="posix-extended" a4="-regex" a5="./auditdProcessed.[0-9]+.[0-9]+$"
type=SYSCALL msg=audit(1609519896.829:44609): arch=c000003e syscall=59 success=yes exit=0 a0=254c440 a1=2527e90 a2=252b650 a3=7ffdfdce0cd0 items=2 ppid=27755 pid=27854 auid=0 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=268 comm="find" exe="/usr/bin/find" subj=system_u:system_r:system_cronjob_t:s0-s0:c0.c1023 key="cmds"
----
time->Sat Jan  2 03:51:36 2021
type=PROCTITLE msg=audit(1609519896.829:44609): proctitle=66696E64002E002D72656765787479706500706F7369782D657874656E646564002D7265676578002E2F61756469746450726F6365737365642E5B302D395D2B2E5B302D395D2B24
type=PATH msg=audit(1609519896.829:44609): item=1 name="/lib64/ld-linux-x86-64.so.2" inode=209023 dev=fd:00 mode=0100755 ouid=0 ogid=0 rdev=00:00 obj=system_u:object_r:ld_so_t:s0 objtype=NORMAL cap_fp=0000000000000000 cap_fi=0000000000000000 cap_fe=0 cap_fver=0
type=PATH msg=audit(1609519896.829:44609): item=0 name="/usr/bin/find" inode=50332900 dev=fd:00 mode=0100755 ouid=0 ogid=0 rdev=00:00 obj=system_u:object_r:bin_t:s0 objtype=NORMAL cap_fp=0000000000000000 cap_fi=0000000000000000 cap_fe=0 cap_fver=0
----
time->Sat Jan  2 03:51:40 2021
type=PROCTITLE msg=audit(1609519900.161:44607): proctitle="hostname"
type=PATH msg=audit(1609519900.161:44607): item=1 name="/lib64/ld-linux-x86-64.so.2" inode=209023 dev=fd:00 mode=0100755 ouid=0 ogid=0 rdev=00:00 obj=system_u:object_r:ld_so_t:s0 objtype=NORMAL cap_fp=0000000000000000 cap_fi=0000000000000000 cap_fe=0 cap_fver=0
type=PATH msg=audit(1609519900.161:44607): item=0 name="/usr/bin/hostname" inode=50333283 dev=fd:00 mode=0100755 ouid=0 ogid=0 rdev=00:00 obj=system_u:object_r:hostname_exec_t:s0 objtype=NORMAL cap_fp=0000000000000000 cap_fi=0000000000000000 cap_fe=0 cap_fver=0
type=CWD msg=audit(1609519900.161:44607):  cwd="/root"
type=EXECVE msg=audit(1609519900.161:44607): argc=1 a0="hostname"
type=SYSCALL msg=audit(1609519900.161:44607): arch=c000003e syscall=59 success=yes exit=0 a0=1130ce0 a1=1125fd0 a2=1124650 a3=7ffdb79a1440 items=2 ppid=27828 pid=27856 auid=0 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=269 comm="hostname" exe="/usr/bin/hostname" subj=system_u:system_r:system_cronjob_t:s0-s0:c0.c1023 key="cmds"



Expected results:
[root@auditdtest audit-userspace]# ausearch -if /tmp/audit.test.log 
----
time->Sat Jan  2 03:51:36 2021
type=PROCTITLE msg=audit(1609519896.829:44609): proctitle=66696E64002E002D72656765787479706500706F7369782D657874656E646564002D7265676578002E2F61756469746450726F6365737365642E5B302D395D2B2E5B302D395D2B24
type=PATH msg=audit(1609519896.829:44609): item=1 name="/lib64/ld-linux-x86-64.so.2" inode=209023 dev=fd:00 mode=0100755 ouid=0 ogid=0 rdev=00:00 obj=system_u:object_r:ld_so_t:s0 objtype=NORMAL cap_fp=0000000000000000 cap_fi=0000000000000000 cap_fe=0 cap_fver=0
type=PATH msg=audit(1609519896.829:44609): item=0 name="/usr/bin/find" inode=50332900 dev=fd:00 mode=0100755 ouid=0 ogid=0 rdev=00:00 obj=system_u:object_r:bin_t:s0 objtype=NORMAL cap_fp=0000000000000000 cap_fi=0000000000000000 cap_fe=0 cap_fver=0
type=CWD msg=audit(1609519896.829:44609):  cwd="/usr/security/auditd/queue"
type=EXECVE msg=audit(1609519896.829:44609): argc=6 a0="find" a1="." a2="-regextype" a3="posix-extended" a4="-regex" a5="./auditdProcessed.[0-9]+.[0-9]+$"
type=SYSCALL msg=audit(1609519896.829:44609): arch=c000003e syscall=59 success=yes exit=0 a0=254c440 a1=2527e90 a2=252b650 a3=7ffdfdce0cd0 items=2 ppid=27755 pid=27854 auid=0 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=268 comm="find" exe="/usr/bin/find" subj=system_u:system_r:system_cronjob_t:s0-s0:c0.c1023 key="cmds"
----
time->Sat Jan  2 03:51:40 2021
type=PROCTITLE msg=audit(1609519900.161:44607): proctitle="hostname"
type=PATH msg=audit(1609519900.161:44607): item=1 name="/lib64/ld-linux-x86-64.so.2" inode=209023 dev=fd:00 mode=0100755 ouid=0 ogid=0 rdev=00:00 obj=system_u:object_r:ld_so_t:s0 objtype=NORMAL cap_fp=0000000000000000 cap_fi=0000000000000000 cap_fe=0 cap_fver=0
type=PATH msg=audit(1609519900.161:44607): item=0 name="/usr/bin/hostname" inode=50333283 dev=fd:00 mode=0100755 ouid=0 ogid=0 rdev=00:00 obj=system_u:object_r:hostname_exec_t:s0 objtype=NORMAL cap_fp=0000000000000000 cap_fi=0000000000000000 cap_fe=0 cap_fver=0
type=CWD msg=audit(1609519900.161:44607):  cwd="/root"
type=EXECVE msg=audit(1609519900.161:44607): argc=1 a0="hostname"
type=SYSCALL msg=audit(1609519900.161:44607): arch=c000003e syscall=59 success=yes exit=0 a0=1130ce0 a1=1125fd0 a2=1124650 a3=7ffdb79a1440 items=2 ppid=27828 pid=27856 auid=0 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=269 comm="hostname" exe="/usr/bin/hostname" subj=system_u:system_r:system_cronjob_t:s0-s0:c0.c1023 key="cmds"


Additional info:

See Github Issue https://github.com/linux-audit/audit-userspace/issues/148

It is expected that the bug will be fixed in the upstream audit-userspace code shortly (patch will be offered in the week Jan 10-17 2021).
Comment 2 Lukas Vrabec 2021-01-27 15:55:56 UTC 
Red Hat Enterprise Linux 7.9 was the last minor release scheduled for RHEL 7 and the product entered Maintenance Support 2 Phase, when Red Hat defined Critical and Important impact Security Advisories and selected Urgent Priority Bug Fix Advisories may be released as they become available.

This bugzilla does not seem to meet the inclusion criteria for Maintenance Phase 2, therefore it is closing now, but if you believe that it qualifies for the Maintenance Support 2 Phase, please re-open; otherwise, we recommend moving the request to Red Hat Enterprise Linux 8 if applicable.

Please refer to the Red Hat Enterprise Linux Life Cycle document for more details:
https://access.redhat.com/support/policy/updates/errata#Maintenance_Support_2_Phase
Comment 3 Burn Alting 2021-01-28 07:27:39 UTC 
This bug also appears in RHEL 8. Changing target to RHEL 8.
Also a patch has been provided upstream.