1:38 p.m.
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(a)iinet.net.au> 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):