From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-0.8 required=3.0 tests=BAYES_00, HEADER_FROM_DIFFERENT_DOMAINS,HTML_MESSAGE,MAILING_LIST_MULTI,SPF_HELO_NONE, SPF_PASS autolearn=no autolearn_force=no version=3.4.0 Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id 8E8A0C433DB for ; Fri, 1 Jan 2021 21:26:06 +0000 (UTC) Received: from us-smtp-delivery-124.mimecast.com (us-smtp-delivery-124.mimecast.com [63.128.21.124]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-SHA384 (256/256 bits)) (No client certificate requested) by mail.kernel.org (Postfix) with ESMTPS id B57E922509 for ; Fri, 1 Jan 2021 21:26:05 +0000 (UTC) DMARC-Filter: OpenDMARC Filter v1.3.2 mail.kernel.org B57E922509 Authentication-Results: mail.kernel.org; dmarc=none (p=none dis=none) header.from=iinet.net.au Authentication-Results: mail.kernel.org; spf=tempfail smtp.mailfrom=linux-audit-bounces@redhat.com Received: from mimecast-mx01.redhat.com (mimecast-mx01.redhat.com [209.132.183.4]) (Using TLS) by relay.mimecast.com with ESMTP id us-mta-466-IArMBWzfMECMD6rAKsl3CQ-1; Fri, 01 Jan 2021 16:26:01 -0500 X-MC-Unique: IArMBWzfMECMD6rAKsl3CQ-1 Received: from smtp.corp.redhat.com (int-mx03.intmail.prod.int.phx2.redhat.com [10.5.11.13]) (using TLSv1.2 with cipher AECDH-AES256-SHA (256/256 bits)) (No client certificate requested) by mimecast-mx01.redhat.com (Postfix) with ESMTPS id E1A23180A08A; Fri, 1 Jan 2021 21:25:55 +0000 (UTC) Received: from colo-mx.corp.redhat.com (colo-mx02.intmail.prod.int.phx2.redhat.com [10.5.11.21]) by smtp.corp.redhat.com (Postfix) with ESMTPS id D0B396085A; Fri, 1 Jan 2021 21:25:53 +0000 (UTC) Received: from lists01.pubmisc.prod.ext.phx2.redhat.com (lists01.pubmisc.prod.ext.phx2.redhat.com [10.5.19.33]) by colo-mx.corp.redhat.com (Postfix) with ESMTP id 392004A7C6; Fri, 1 Jan 2021 21:25:51 +0000 (UTC) Received: from smtp.corp.redhat.com (int-mx05.intmail.prod.int.rdu2.redhat.com [10.11.54.5]) by lists01.pubmisc.prod.ext.phx2.redhat.com (8.13.8/8.13.8) with ESMTP id 101LPlXu001181 for ; Fri, 1 Jan 2021 16:25:48 -0500 Received: by smtp.corp.redhat.com (Postfix) id 983E19D486; Fri, 1 Jan 2021 21:25:47 +0000 (UTC) Received: from mimecast-mx02.redhat.com (mimecast03.extmail.prod.ext.rdu2.redhat.com [10.11.55.19]) by smtp.corp.redhat.com (Postfix) with ESMTPS id 9244A51E1 for ; Fri, 1 Jan 2021 21:25:45 +0000 (UTC) Received: from us-smtp-1.mimecast.com (us-smtp-delivery-1.mimecast.com [207.211.31.120]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-SHA384 (256/256 bits)) (No client certificate requested) by mimecast-mx02.redhat.com (Postfix) with ESMTPS id 5E8C0811E76 for ; Fri, 1 Jan 2021 21:25:45 +0000 (UTC) Received: from icp-osb-irony-out2.external.iinet.net.au (icp-osb-irony-out2.external.iinet.net.au [203.59.1.155]) by relay.mimecast.com with ESMTP id us-mta-417-yiwPbYQKPU6qadWa5VuoDQ-1; Fri, 01 Jan 2021 16:25:41 -0500 X-MC-Unique: yiwPbYQKPU6qadWa5VuoDQ-1 X-SMTP-MATCH: 1 X-IronPort-Anti-Spam-Filtered: true X-IronPort-Anti-Spam-Result: =?us-ascii?q?A2AQEQBske9f/1enWttigRCDRIF8hSB?= =?us-ascii?q?xiBOGGIJQg2yWN4FcCwEBAQEBAQEBARwZAQIEAQGERASBdCY4EwIQAQEBBQE?= =?us-ascii?q?BAQEBBgMBhl6GHTNGLA4CX4JuS4JWAQEurkGBMoVGE4IdBoENgUKBOI1egU0?= =?us-ascii?q?/gUeCNgGIQIJgBIJZd5V+iHObfCwHgnkEgRMFC4ZPk2IiolCGHRiqD4cQgXo?= =?us-ascii?q?zGh+CFhiBEE8ZDVaOcAEIAY0uMGcCBgoBAQMJWQEBjT8BAQ?= X-IPAS-Result: =?us-ascii?q?A2AQEQBske9f/1enWttigRCDRIF8hSBxiBOGGIJQg2yWN?= =?us-ascii?q?4FcCwEBAQEBAQEBARwZAQIEAQGERASBdCY4EwIQAQEBBQEBAQEBBgMBhl6GH?= =?us-ascii?q?TNGLA4CX4JuS4JWAQEurkGBMoVGE4IdBoENgUKBOI1egU0/gUeCNgGIQIJgB?= =?us-ascii?q?IJZd5V+iHObfCwHgnkEgRMFC4ZPk2IiolCGHRiqD4cQgXozGh+CFhiBEE8ZD?= =?us-ascii?q?VaOcAEIAY0uMGcCBgoBAQMJWQEBjT8BAQ?= X-IronPort-AV: E=Sophos;i="5.78,468,1599494400"; d="scan'208,217";a="332656297" Received: from 219-90-167-87.ip.adam.com.au (HELO swtf.swtf.dyndns.org) ([219.90.167.87]) by icp-osb-irony-out2.iinet.net.au with ESMTP; 02 Jan 2021 05:22:34 +0800 Message-ID: <30c5dbc14368a1919717e2f39d2d4c29463c3108.camel@iinet.net.au> Subject: Occasional delayed output of events From: Burn Alting To: Linux Audit Date: Sat, 02 Jan 2021 08:22:33 +1100 Mime-Version: 1.0 X-Mimecast-Impersonation-Protect: Policy=CLT - Impersonation Protection Definition; Similar Internal Domain=false; Similar Monitored External Domain=false; Custom External Domain=false; Mimecast External Domain=false; Newly Observed Domain=false; Internal User Name=false; Custom Display Name List=false; Reply-to Address Mismatch=false; Targeted Threat Dictionary=false; Mimecast Threat Dictionary=false; Custom Threat Dictionary=false X-Scanned-By: MIMEDefang 2.79 on 10.11.54.5 X-loop: linux-audit@redhat.com X-BeenThere: linux-audit@redhat.com X-Mailman-Version: 2.1.12 Precedence: junk Reply-To: burn@swtf.dyndns.org List-Id: Linux Audit Discussion List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Sender: linux-audit-bounces@redhat.com Errors-To: linux-audit-bounces@redhat.com X-Scanned-By: MIMEDefang 2.79 on 10.5.11.13 Authentication-Results: relay.mimecast.com; auth=pass smtp.auth=CUSA124A263 smtp.mailfrom=linux-audit-bounces@redhat.com X-Mimecast-Spam-Score: 0 X-Mimecast-Originator: redhat.com Content-Type: multipart/mixed; boundary="===============8950353093969438611==" --===============8950353093969438611== Content-Type: multipart/alternative; boundary="=-y9qBf5Se0b2aDXmOcn+r" --=-y9qBf5Se0b2aDXmOcn+r Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: 7bit 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 --=-y9qBf5Se0b2aDXmOcn+r Content-Type: text/html; charset="utf-8" Content-Transfer-Encoding: quoted-printable
All,

Sometimes, events recorded in /var/l= og/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 t= he first time I still had access to the raw audit.log files (I monitor a lo= t of event types and the log files roll over fairly quickly).
Th= e 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 i= s too quick).

type=3DSYSCALL msg=3Daudit(160951989= 6.824:44603):
type=3DEXECVE msg=3Daudit(1609519896.824:44603):
type=3DCWD msg=3Daudit(1609519896.824:44603):
type=3DPATH= msg=3Daudit(1609519896.824:44603):
type=3DPATH msg=3Daudit(16095= 19896.824:44603):
type=3DPROCTITLE msg=3Daudit(1609519896.824:446= 03):
type=3DSYSCALL msg=3Daudit(1609519896.826:44604):
= type=3DEXECVE msg=3Daudit(1609519896.826:44604):
type=3DCWD msg= =3Daudit(1609519896.826:44604):
type=3DPATH msg=3Daudit(160951989= 6.826:44604):
type=3DPATH msg=3Daudit(1609519896.826:44604):
type=3DPROCTITLE msg=3Daudit(1609519896.826:44604):
type=3D= SYSCALL msg=3Daudit(1609519801.338:44605):
type=3DEXECVE msg=3Dau= dit(1609519801.338:44605):
type=3DCWD msg=3Daudit(1609519801.338:= 44605):
type=3DPATH msg=3Daudit(1609519801.338:44605):
= type=3DPATH msg=3Daudit(1609519801.338:44605):
type=3DPROCTITLE m= sg=3Daudit(1609519801.338:44605):
type=3DSYSCALL msg=3Daudit(1609= 519900.159:44606):
type=3DEXECVE msg=3Daudit(1609519900.159:44606= ):
type=3DCWD msg=3Daudit(1609519900.159:44606):
type= =3DPATH msg=3Daudit(1609519900.159:44606):
type=3DPATH msg=3Daudi= t(1609519900.159:44606):
type=3DPROCTITLE msg=3Daudit(1609519900.= 159:44606):
type=3DSYSCALL msg=3Daudit(1609519900.161:44607):
type=3DEXECVE msg=3Daudit(1609519900.161:44607):
type=3DCW= D msg=3Daudit(1609519900.161:44607):
type=3DPATH msg=3Daudit(1609= 519900.161:44607):
type=3DPATH msg=3Daudit(1609519900.161:44607):=
type=3DPROCTITLE msg=3Daudit(1609519900.161:44607):
ty= pe=3DSYSCALL msg=3Daudit(1609519896.829:44609):
type=3DEXECVE msg= =3Daudit(1609519896.829:44609):
type=3DCWD msg=3Daudit(1609519896= .829:44609):
type=3DSYSCALL msg=3Daudit(1609519900.163:44608):
type=3DPATH msg=3Daudit(1609519896.829:44609):
type=3DEXE= CVE msg=3Daudit(1609519900.163:44608):
type=3DCWD msg=3Daudit(160= 9519900.163:44608):
type=3DPATH msg=3Daudit(1609519896.829:44609)= :
type=3DPROCTITLE msg=3Daudit(1609519896.829:44609):
t= ype=3DPATH msg=3Daudit(1609519900.163:44608):
type=3DPATH msg=3Da= udit(1609519900.163:44608):
type=3DPROCTITLE msg=3Daudit(16095199= 00.163:44608):
type=3DCRED_DISP msg=3Daudit(1609519900.170:44610)= :
type=3DSYSCALL msg=3Daudit(1609519900.170:44611):
typ= e=3DEXECVE msg=3Daudit(1609519900.170:44611):
type=3DCWD msg=3Dau= dit(1609519900.170:44611):
type=3DPATH msg=3Daudit(1609519900.170= :44611):
type=3DPATH msg=3Daudit(1609519900.170:44611):
type=3DPROCTITLE msg=3Daudit(1609519900.170:44611):
<= br>
which results in an ausearch -i output sequence of
= ----
type=3DPROCTITLE msg=3Daudit(02/01/21 03:51:36.826:44604)
type=3DPATH msg=3Daudit(02/01/21 03:51:36.826:44604)
type= =3DPATH msg=3Daudit(02/01/21 03:51:36.826:44604)
type=3DCWD msg= =3Daudit(02/01/21 03:51:36.826:44604)
type=3DEXECVE msg=3Daudit(0= 2/01/21 03:51:36.826:44604)
type=3DSYSCALL msg=3Daudit(02/01/21 0= 3:51:36.826:44604)
----
type=3DCWD msg=3Daudit(02/01/21= 03:51:36.829:44609)
type=3DEXECVE msg=3Daudit(02/01/21 03:51:36.= 829:44609)
type=3DSYSCALL msg=3Daudit(02/01/21 03:51:36.829:44609= )
----
type=3DPROCTITLE msg=3Daudit(02/01/21 03:51:36.8= 29:44609)
type=3DPATH msg=3Daudit(02/01/21 03:51:36.829:44609)
type=3DPATH msg=3Daudit(02/01/21 03:51:36.829:44609)
----=
type=3DPROCTITLE msg=3Daudit(02/01/21 03:51:40.159:44606)
<= div>type=3DPATH msg=3Daudit(02/01/21 03:51:40.159:44606)
type=3DP= ATH msg=3Daudit(02/01/21 03:51:40.159:44606)
type=3DCWD msg=3Daud= it(02/01/21 03:51:40.159:44606)
type=3DEXECVE msg=3Daudit(02/01/2= 1 03:51:40.159:44606)
type=3DSYSCALL msg=3Daudit(02/01/21 03:51:4= 0.159:44606)
----
type=3DPROCTITLE msg=3Daudit(02/01/21= 03:51:40.161:44607)
type=3DPATH msg=3Daudit(02/01/21 03:51:40.16= 1:44607)
type=3DPATH msg=3Daudit(02/01/21 03:51:40.161:44607)
type=3DCWD msg=3Daudit(02/01/21 03:51:40.161:44607)
type= =3DEXECVE msg=3Daudit(02/01/21 03:51:40.161:44607)
type=3DSYSCALL= msg=3Daudit(02/01/21 03:51:40.161:44607)
----
type=3DP= ROCTITLE msg=3Daudit(02/01/21 03:51:40.163:44608)
type=3DPATH msg= =3Daudit(02/01/21 03:51:40.163:44608)
type=3DPATH msg=3Daudit(02/= 01/21 03:51:40.163:44608)
type=3DCWD msg=3Daudit(02/01/21 03:51:4= 0.163:44608)
type=3DEXECVE msg=3Daudit(02/01/21 03:51:40.163:4460= 8)
type=3DSYSCALL msg=3Daudit(02/01/21 03:51:40.163:44608)
<= div>----
type=3DCRED_DISP msg=3Daudit(02/01/21 03:51:40.170:44610= )


Regards
Burn
=
--=-y9qBf5Se0b2aDXmOcn+r-- --===============8950353093969438611== Content-Type: text/plain; charset="us-ascii" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit Content-Disposition: inline -- Linux-audit mailing list Linux-audit@redhat.com https://www.redhat.com/mailman/listinfo/linux-audit --===============8950353093969438611==--