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=-5.8 required=3.0 tests=BAYES_00, HEADER_FROM_DIFFERENT_DOMAINS,HTML_MESSAGE,MAILING_LIST_MULTI, MENTIONS_GIT_HOSTING,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 9A130C433E0 for ; Tue, 19 Jan 2021 19:38:47 +0000 (UTC) Received: from us-smtp-delivery-124.mimecast.com (us-smtp-delivery-124.mimecast.com [216.205.24.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 0A7E723104 for ; Tue, 19 Jan 2021 19:38:45 +0000 (UTC) DMARC-Filter: OpenDMARC Filter v1.3.2 mail.kernel.org 0A7E723104 Authentication-Results: mail.kernel.org; dmarc=none (p=none dis=none) header.from=iinet.net.au Authentication-Results: mail.kernel.org; spf=pass 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-589-htfrQLYcNjWXfY9ap6mhIw-1; Tue, 19 Jan 2021 14:38:42 -0500 X-MC-Unique: htfrQLYcNjWXfY9ap6mhIw-1 Received: from smtp.corp.redhat.com (int-mx01.intmail.prod.int.phx2.redhat.com [10.5.11.11]) (using TLSv1.2 with cipher AECDH-AES256-SHA (256/256 bits)) (No client certificate requested) by mimecast-mx01.redhat.com (Postfix) with ESMTPS id 87F6E8015C3; Tue, 19 Jan 2021 19:38:38 +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 4F3D119CBF; Tue, 19 Jan 2021 19:38:38 +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 B1BA84BB7B; Tue, 19 Jan 2021 19:38:19 +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 10JJcHXA020591 for ; Tue, 19 Jan 2021 14:38:17 -0500 Received: by smtp.corp.redhat.com (Postfix) id AA060A9E7C; Tue, 19 Jan 2021 19:38:17 +0000 (UTC) Received: from mimecast-mx02.redhat.com (mimecast06.extmail.prod.ext.rdu2.redhat.com [10.11.55.22]) by smtp.corp.redhat.com (Postfix) with ESMTPS id A44E2951D8 for ; Tue, 19 Jan 2021 19:38:15 +0000 (UTC) Received: from us-smtp-1.mimecast.com (us-smtp-delivery-1.mimecast.com [205.139.110.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 4852B187504B for ; Tue, 19 Jan 2021 19:38:15 +0000 (UTC) Received: from icp-osb-irony-out9.external.iinet.net.au (icp-osb-irony-out9.external.iinet.net.au [203.59.1.226]) by relay.mimecast.com with ESMTP id us-mta-372-0z1umiEfOlKqPLfD66ER2A-1; Tue, 19 Jan 2021 14:38:09 -0500 X-MC-Unique: 0z1umiEfOlKqPLfD66ER2A-1 X-SMTP-MATCH: 1 X-IronPort-Anti-Spam-Filtered: true X-IronPort-Anti-Spam-Result: =?us-ascii?q?A2CBCQDXMwdg/3zSRWpfAxwBAQEBAQE?= =?us-ascii?q?HAQESAQEEBAEBR4FIgXYGgSVXYoQ/iQSGNYIWAziDbJY9gVwLAQEBAQEBAQE?= =?us-ascii?q?BLAkBAgQBAYREBAICgXQmOBMCEAEBAQUBAQEBAQYDAYZSDIVzAQEBAQIBIzM?= =?us-ascii?q?jBQsLCBAcDgICVwYTgltLAYJVAQEPHxCuVXaBMoRAAYEGE4IUBoENgUOBOIZ?= =?us-ascii?q?2AYZANYFNP4FHgi41PoJdAoIAJoJSgmAEgU8OYYEHNhoGAj4RD0ofAUUSCY9?= =?us-ascii?q?1gyWIe5wELAeCeoEXBQuGUYE3hn6LOyKEWp4QhiIYmH2YSYF6MxofghYYgQ8?= =?us-ascii?q?JRxkNkEWBTYpsMDA3AgYKAQEDCVkBAYlALYIXAQE?= X-IPAS-Result: =?us-ascii?q?A2CBCQDXMwdg/3zSRWpfAxwBAQEBAQEHAQESAQEEBAEBR?= =?us-ascii?q?4FIgXYGgSVXYoQ/iQSGNYIWAziDbJY9gVwLAQEBAQEBAQEBLAkBAgQBAYREB?= =?us-ascii?q?AICgXQmOBMCEAEBAQUBAQEBAQYDAYZSDIVzAQEBAQIBIzMjBQsLCBAcDgICV?= =?us-ascii?q?wYTgltLAYJVAQEPHxCuVXaBMoRAAYEGE4IUBoENgUOBOIZ2AYZANYFNP4FHg?= =?us-ascii?q?i41PoJdAoIAJoJSgmAEgU8OYYEHNhoGAj4RD0ofAUUSCY91gyWIe5wELAeCe?= =?us-ascii?q?oEXBQuGUYE3hn6LOyKEWp4QhiIYmH2YSYF6MxofghYYgQ8JRxkNkEWBTYpsM?= =?us-ascii?q?DA3AgYKAQEDCVkBAYlALYIXAQE?= X-IronPort-AV: E=Sophos;i="5.79,359,1602518400"; d="scan'208,217";a="298674438" Received: from 106-69-210-124.dyn.iinet.net.au (HELO swtf.swtf.dyndns.org) ([106.69.210.124]) by icp-osb-irony-out9.iinet.net.au with ESMTP; 20 Jan 2021 03:38:04 +0800 Message-ID: <9fd0d1b4585214eb3ed8db6da066b571563f19bc.camel@iinet.net.au> Subject: Re: Occasional delayed output of events From: Burn Alting To: Paul Moore Date: Wed, 20 Jan 2021 06:38:03 +1100 In-Reply-To: References: <30c5dbc14368a1919717e2f39d2d4c29463c3108.camel@iinet.net.au> <5445873.DvuYhMxLoT@x2> <17715c36170.27df.85c95baa4474aabc7814e68940a78392@paul-moore.com> <3095712.44csPzL39Z@x2> <9a7ed1203fa7ec67000aa68281a215354c2ed5f5.camel@iinet.net.au> 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 Cc: Richard Guy Briggs , Linux Audit 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.11 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="===============6426578247450943780==" --===============6426578247450943780== Content-Type: multipart/alternative; boundary="=-GKbhvLPS8Mn6mgPn0Jy1" --=-GKbhvLPS8Mn6mgPn0Jy1 Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: 7bit On Tue, 2021-01-19 at 14:11 -0500, Paul Moore wrote: > On Tue, Jan 19, 2021 at 3:18 AM Burn Alting wrote: > > I tend to have a rigorous auditing posture (see the rules loaded in > > https://github.com/linux-audit/audit-userspace/issues/148) which is not normal > > for most. Perhaps, Paul, you have hit the nail on the head by stating that this > > 'severe delay' is not that unreasonable given my rules posture and we just need > > to 'deal with it' in user space.We still get the event data, I just need to > > adjust the user space tools to deal with this occurrence.As for what the system > > is doing, in my home case it's a Centos 7 VM running a tomcat service which only > > gets busy every 20 minutes and the other is a HPE Z800 running Centos 8 with 4-5 > > VM's mostly dormant. I can put any code in these hosts to assist in > > 'validating'/testing the delay. Advise and I will run. > > I took a (slightly) closer look at the queuing code just now and thecorner case I > suspected doesn't look very promising here. On failureto send a record to > userspace, the record is put back at the front ofthe queue to preserve ordering so > the kernel *should* still emitrecords in order even when auditd is under pressure, > dead, or in theprocess of a restart. Also, in this case the kernel kicks the > auditdconnection, disconnecting auditd's netlink socket; I imagine thatwould be a > notable event on your systems. > However, looking at the timestamps in the audit events you posted, Inoticed > something a little odd. If I align the timestamps a bitbetter let's see if it > jumps out at you guys ... > type=XXX msg=audit(1609519900.159:44606): ...type=XXX > msg=audit(1609519900.161:44607): ...type=XXX msg=audit(1609519900.163:44608): > ...type=XXX msg=audit(1609519896.829:44609): ...type=XXX > msg=audit(1609519900.170:44610): ... > Let me guess Burn, you're running NTP/PTP :) I'm not sure how auditdhandles > things like this, but it looks like there was a small negativetime correction > between events which caused the odd scenario whereevent N+1 actually occurred > before event N according to the wallclock. In other words, your system is time > traveling ;) . All systems use chrony (current NTP daemon). One is a VM (on top of KVM) and the other a bare metal deployment. Does the above explain my second data set (in the issue) from a bare metal Centos 8 host?Perhaps Lenny's comments bare investigation. Either way, I will offer a patch to the user space code to, based on a configuration value, manage correctly such activity. msg=audit(1609920994.481:1787844):msg=audit(1609920994.481:1787844):msg=audit(160992 0994.481:1787844):msg=audit(1609920994.481:1787844):msg=audit(1609920994.481:1787845 ):msg=audit(1609920994.481:1787845):msg=audit(1609920994.481:1787845):msg=audit(1609 920994.481:1787845):msg=audit(1609920994.481:1787845):msg=audit(1609920994.481:17878 45):msg=audit(1609920994.481:1787845):msg=audit(1609920994.481:1787846):msg=audit(16 09920994.481:1787846):msg=audit(1609920994.481:1787846):msg=audit(1609920994.481:178 7846):msg=audit(1609920994.481:1787846):msg=audit(1609920994.482:1787847):msg=audit( 1609920994.482:1787847):msg=audit(1609920994.482:1787847):msg=audit(1609920994.482:1 787847):msg=audit(1609920994.482:1787847):msg=audit(1609920994.483:1787848):msg=audi t(1609920994.483:1787848):msg=audit(1609920994.483:1787848):msg=audit(1609920994.483 :1787848):msg=audit(1609920994.483:1787848):msg=audit(1609920994.484:1787849):msg=au dit(1609920994.484:1787849):msg=audit(1609921000.636:1787850):msg=audit(1609921000.6 36:1787850):msg=audit(1609921000.636:1787850):msg=audit(1609921008.456:1787851):msg= audit(1609921008.456:1787851):msg=audit(1609921008.456:1787851):msg=audit(1609921008 .456:1787851):msg=audit(1609921008.456:1787851):msg=audit(1609921008.456:1787851):ms g=audit(1609920994.484:1787849):msg=audit(1609920994.484:1787849):msg=audit(16099209 94.484:1787849):msg=audit(1609921010.837:1787852):msg=audit(1609921010.837:1787852): msg=audit(1609921010.837:1787852):msg=audit(1609921010.837:1787852):msg=audit(160992 1010.837:1787853):msg=audit(1609921010.837:1787853):msg=audit(1609921010.837:1787853 ):msg=audit(1609921010.837:1787853):msg=audit(1609921010.837:1787853):msg=audit(1609 921010.837:1787853):msg=audit(1609921010.837:1787853):msg=audit(1609921010.838:17878 54):msg=audit(1609921010.838:1787854):msg=audit(1609921010.838:1787854):msg=audit(16 09921010.838:1787854):msg=audit(1609921010.838:1787854):msg=audit(1609921010.839:178 7855):msg=audit(1609921010.839:1787855):msg=audit(1609921010.839:1787855):msg=audit( 1609921010.839:1787855):msg=audit(1609921010.839:1787855):msg=audit(1609921010.840:1 787856):msg=audit(1609921010.840:1787856):msg=audit(1609921010.840:1787856):msg=audi t(1609921010.840:1787856):msg=audit(1609921010.840:1787856):msg=audit(1609921010.841 :1787857):msg=audit(1609921010.841:1787857):msg=audit(1609921010.841:1787857):msg=au dit(1609921010.841:1787857):msg=audit(1609921010.841:1787857): --=-GKbhvLPS8Mn6mgPn0Jy1 Content-Type: text/html; charset="utf-8" Content-Transfer-Encoding: quoted-printable
On Tue, 2021-01-19 at 14:11 -0500, Paul Moore wrote:
On Tue, Jan 19, 2021 at 3:18 AM Burn Alting <
burn.alting@iinet.net.a=
u
> wrote:
I tend to =
have a rigorous auditing posture (see the rules loaded in 
https://git=
hub.com/linux-audit/audit-userspace/issues/148
) which is not=
 normal for most. Perhaps, Paul, you have hit the nail on the head by stati=
ng that this 'severe delay' is not that unreasonable given my rules posture=
 and we just need to 'deal with it' in user space.
We still get t=
he event data, I just need to adjust the user space tools to deal with this=
 occurrence.
As for what the system is doing, in my home case it'=
s a Centos 7 VM running a tomcat service which only gets busy every 20 minu=
tes and the other is a HPE Z800 running Centos 8 with 4-5 VM's mostly dorma=
nt. I can put any code in these hosts to assist in 'validating'/testing the=
 delay. Advise and I will run.

I took=
 a (slightly) closer look at the queuing code just now and the
co=
rner case I suspected doesn't look very promising here.  On failure
to send a record to userspace, the record is put back at the front of
the queue to preserve ordering so the kernel *should* still emit
records in order even when auditd is under pressure, dead, or in th=
e
process of a restart.  Also, in this case the kernel kicks the =
auditd
connection, disconnecting auditd's netlink socket; I imagi=
ne that
would be a notable event on your systems.

<=
/pre>
However, looking at the timestamps in the audit events you posted=
, I
noticed something a little odd.  If I align the timestamps a =
bit
better let's see if it jumps out at you guys ...
type=3DXXX msg=3Daudit(1609519900.159:44606): ...
ty=
pe=3DXXX msg=3Daudit(1609519900.161:44607): ...
type=3DXXX msg=3D=
audit(1609519900.163:44608): ...
type=3DXXX msg=3Daudit(160951989=
6.829:44609): ...
type=3DXXX msg=3Daudit(1609519900.170:44610): .=
..

Let me guess Burn, you're running NTP/PTP :)  I=
'm not sure how auditd
handles things like this, but it looks lik=
e there was a small negative
time correction between events which=
 caused the odd scenario where
event N+1 actually occurred before=
 event N according to the wall
clock.  In other words, your syste=
m is time traveling ;)
. 
All systems use =
chrony (current NTP daemon). One is a VM (on top of KVM) and the other a ba=
re metal deployment. Does the above explain my second data set (in the issu=
e)  from a bare metal Centos 8 host?
Perhaps Lenny's comments bar=
e investigation. Either way, I will offer a patch to the user space code to=
, based on a configuration value, manage correctly such activity.

msg=3Daudit(1609920994.481:1787844):
msg=3Daudit(=
1609920994.481:1787844):
msg=3Daudit(1609920994.481:1787844):
msg=3Daudit(1609920994.481:1787844):
msg=3Daudit(160992099=
4.481:1787845):
msg=3Daudit(1609920994.481:1787845):
ms=
g=3Daudit(1609920994.481:1787845):
msg=3Daudit(1609920994.481:178=
7845):
msg=3Daudit(1609920994.481:1787845):
msg=3Daudit=
(1609920994.481:1787845):
msg=3Daudit(1609920994.481:1787845):
msg=3Daudit(1609920994.481:1787846):
msg=3Daudit(16099209=
94.481:1787846):
msg=3Daudit(1609920994.481:1787846):
m=
sg=3Daudit(1609920994.481:1787846):
msg=3Daudit(1609920994.481:17=
87846):
msg=3Daudit(1609920994.482:1787847):
msg=3Daudi=
t(1609920994.482:1787847):
msg=3Daudit(1609920994.482:1787847):
msg=3Daudit(1609920994.482:1787847):
msg=3Daudit(1609920=
994.482:1787847):
msg=3Daudit(1609920994.483:1787848):
=
msg=3Daudit(1609920994.483:1787848):
msg=3Daudit(1609920994.483:1=
787848):
msg=3Daudit(1609920994.483:1787848):
msg=3Daud=
it(1609920994.483:1787848):
msg=3Daudit(1609920994.484:1787849):<=
/div>
msg=3Daudit(1609920994.484:1787849):
msg=3Daudit(160992=
1000.636:1787850):
msg=3Daudit(1609921000.636:1787850):
msg=3Daudit(1609921000.636:1787850):
msg=3Daudit(1609921008.456:=
1787851):
msg=3Daudit(1609921008.456:1787851):
msg=3Dau=
dit(1609921008.456:1787851):
msg=3Daudit(1609921008.456:1787851):=

msg=3Daudit(1609921008.456:1787851):
msg=3Daudit(16099=
21008.456:1787851):
msg=3Daudit(1609920994.484:1787849):
msg=3Daudit(1609920994.484:1787849):
msg=3Daudit(1609920994.484=
:1787849):
msg=3Daudit(1609921010.837:1787852):
msg=3Da=
udit(1609921010.837:1787852):
msg=3Daudit(1609921010.837:1787852)=
:
msg=3Daudit(1609921010.837:1787852):
msg=3Daudit(1609=
921010.837:1787853):
msg=3Daudit(1609921010.837:1787853):
msg=3Daudit(1609921010.837:1787853):
msg=3Daudit(1609921010.83=
7:1787853):
msg=3Daudit(1609921010.837:1787853):
msg=3D=
audit(1609921010.837:1787853):
msg=3Daudit(1609921010.837:1787853=
):
msg=3Daudit(1609921010.838:1787854):
msg=3Daudit(160=
9921010.838:1787854):
msg=3Daudit(1609921010.838:1787854):
<=
div>msg=3Daudit(1609921010.838:1787854):
msg=3Daudit(1609921010.8=
38:1787854):
msg=3Daudit(1609921010.839:1787855):
msg=
=3Daudit(1609921010.839:1787855):
msg=3Daudit(1609921010.839:1787=
855):
msg=3Daudit(1609921010.839:1787855):
msg=3Daudit(=
1609921010.839:1787855):
msg=3Daudit(1609921010.840:1787856):
msg=3Daudit(1609921010.840:1787856):
msg=3Daudit(160992101=
0.840:1787856):
msg=3Daudit(1609921010.840:1787856):
ms=
g=3Daudit(1609921010.840:1787856):
msg=3Daudit(1609921010.841:178=
7857):
msg=3Daudit(1609921010.841:1787857):
msg=3Daudit=
(1609921010.841:1787857):
msg=3Daudit(1609921010.841:1787857):
msg=3Daudit(1609921010.841:1787857):





--=-GKbhvLPS8Mn6mgPn0Jy1--

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