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):