Occasional delayed output of events

[Steve Grubb]

On Tuesday, January 19, 2021 3:26:04 PM EST Paul Moore wrote:
> On Tue, Jan 19, 2021 at 2:38 PM Burn Alting <burn.alting at iinet.net.au> 
wrote:
> > 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.483:1787848):
> > msg=audit(1609920994.483:1787848):
> > msg=audit(1609920994.483:1787848):
> > msg=audit(1609920994.483:1787848):
> > msg=audit(1609920994.483:1787848):
> > msg=audit(1609920994.484:1787849):
> > msg=audit(1609920994.484:1787849):
> > msg=audit(1609921000.636:1787850):
> > msg=audit(1609921000.636: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):
> > msg=audit(1609920994.484:1787849):
> > msg=audit(1609920994.484:1787849):
> > msg=audit(1609920994.484:1787849):
> > msg=audit(1609921010.837:1787852):
> > msg=audit(1609921010.837:1787852):
> > msg=audit(1609921010.837:1787852):
> 
> > msg=audit(1609921010.837:1787852):
> Looking at the extracted snippet above where event 1787849 is out of
> 
> order we see the following timestamps:
> > msg=audit(1609920994.483:1787848):
> > msg=audit(1609920994.484:1787849):
> > msg=audit(1609921000.636:1787850):
> > msg=audit(1609921008.456:1787851):
> 
> > msg=audit(1609921010.837:1787852):
>
> ... which looks correct in as much that the time doesn't appear to go
> backwards between events.  As I said before, I'm not sure how Steve's
> userspace works so the time may be a red herring.

It only handles one record at a time. No chance to mix things up.

The github issue says that 30-stig.rules is being used. If the system time 
changed with chrony, I would expect syscall events with adjtimex. But the 
only ones given are execve.

-Steve

> Barring some weird condition where auditd disconnects and quickly
> reconnects to the kernel, and/or dies and is replaced quickly, I'm not
> seeing anything obvious in the kernel which would cause this.  I'm not
> saying there isn't anything there, just that it isn't obvious to me at
> the moment :)