As part of a new PCI-DSS server deployment I am in the process of configuring a fully auditable NTP time change history. All is working as expected however I am now seeing audit logs written every single second relating to time change operations. After a lot of searching I'm still no closer to understanding what is going on. The issue shows itself in /var/log/messages where an audit message is being written continuously.
My research suggests that the syscall "exit=5" message means that the clock was not properly synchronised:
adjtimex() syscall response "#define TIME_BAD 5 /* clock not synchronized */".
So, in summary it appears that the clock is synced correctly (as far as my understanding takes me) however it is constantly changing - unexpected behaviour with the polling interval set at the default 64s.
Is anyone able to offer suggestions? I've included as much detail as I can muster below:
Audit time rules:
[09:31] callum pci-fram-ipa1 ~ $ sudo cat /etc/audit/rules.d/audit_time_rules.rules
-a always,exit -F arch=b64 -S adjtimex -S settimeofday -k time-change
-a always,exit -F arch=b32 -S adjtimex -S settimeofday -S stime -k time-change
-a always,exit -F arch=b64 -S clock_settime -k time-change
-a always,exit -F arch=b32 -S clock_settime -k time-change
-w /etc/localtime -p wa -k time-change
System time vs clock time:
[09:14] callum pci-fram-ipa1 ~ $ sudo clock;date
Thu 05 Jan 2017 09:14:01 GMT -0.500708 seconds
Thu 5 Jan 09:14:01 GMT 2017
Example audit output:
[09:15] callum pci-fram-ipa1 ~ $ sudo tail -f /var/log/messages|grep time
Jan 5 09:15:25 pci-fram-ipa1 audispd: node=pci-fram-ipa1.x.net type=SYSCALL msg=audit(1483607725.390:2328215): arch=c000003e syscall=159 success=yes exit=5 a0=7ffe85ddc320 a1=7ffe85ddc410 a2=861 a3=2 items=0 ppid=1 pid=11479 auid=4294967295 uid=38 gid=38 euid=38 suid=38 fsuid=38 egid=38 sgid=38 fsgid=38 tty=(none) ses=4294967295 comm="ntpd" exe="/usr/sbin/ntpd" subj=system_u:system_r:ntpd_t:s0 key="time-change"
Jan 5 09:15:26 pci-fram-ipa1 audispd: node=pci-fram-ipa1.x.net type=SYSCALL msg=audit(1483607726.390:2328216): arch=c000003e syscall=159 success=yes exit=5 a0=7ffe85ddc320 a1=7ffe85ddc410 a2=861 a3=2 items=0 ppid=1 pid=11479 auid=4294967295 uid=38 gid=38 euid=38 suid=38 fsuid=38 egid=38 sgid=38 fsgid=38 tty=(none) ses=4294967295 comm="ntpd" exe="/usr/sbin/ntpd" subj=system_u:system_r:ntpd_t:s0 key="time-change"
Jan 5 09:15:27 pci-fram-ipa1 audispd: node=pci-fram-ipa1.x.net type=SYSCALL msg=audit(1483607727.390:2328217): arch=c000003e syscall=159 success=yes exit=5 a0=7ffe85ddc320 a1=7ffe85ddc410 a2=861 a3=2 items=0 ppid=1 pid=11479 auid=4294967295 uid=38 gid=38 euid=38 suid=38 fsuid=38 egid=38 sgid=38 fsgid=38 tty=(none) ses=4294967295 comm="ntpd" exe="/usr/sbin/ntpd" subj=system_u:system_r:ntpd_t:s0 key="time-change"
Jan 5 09:15:28 pci-fram-ipa1 audispd: node=pci-fram-ipa1.x.net type=SYSCALL msg=audit(1483607728.390:2328218): arch=c000003e syscall=159 success=yes exit=5 a0=7ffe85ddc320 a1=7ffe85ddc410 a2=861 a3=2 items=0 ppid=1 pid=11479 auid=4294967295 uid=38 gid=38 euid=38 suid=38 fsuid=38 egid=38 sgid=38 fsgid=38 tty=(none) ses=4294967295 comm="ntpd" exe="/usr/sbin/ntpd" subj=system_u:system_r:ntpd_t:s0 key="time-change"
Jan 5 09:15:29 pci-fram-ipa1 audispd: node=pci-fram-ipa1.x.net type=SYSCALL msg=audit(1483607729.390:2328219): arch=c000003e syscall=159 success=yes exit=5 a0=7ffe85ddc320 a1=7ffe85ddc410 a2=861 a3=2 items=0 ppid=1 pid=11479 auid=4294967295 uid=38 gid=38 euid=38 suid=38 fsuid=38 egid=38 sgid=38 fsgid=38 tty=(none) ses=4294967295 comm="ntpd" exe="/usr/sbin/ntpd" subj=system_u:system_r:ntpd_t:s0 key="time-change"
Jan 5 09:15:30 pci-fram-ipa1 audispd: node=pci-fram-ipa1.x.net type=SYSCALL msg=audit(1483607730.390:2328220): arch=c000003e syscall=159 success=yes exit=5 a0=7ffe85ddc320 a1=7ffe85ddc410 a2=861 a3=2 items=0 ppid=1 pid=11479 auid=4294967295 uid=38 gid=38 euid=38 suid=38 fsuid=38 egid=38 sgid=38 fsgid=38 tty=(none) ses=4294967295 comm="ntpd" exe="/usr/sbin/ntpd" subj=system_u:system_r:ntpd_t:s0 key="time-change"
Jan 5 09:15:31 pci-fram-ipa1 audispd: node=pci-fram-ipa1.x.net type=SYSCALL msg=audit(1483607731.390:2328221): arch=c000003e syscall=159 success=yes exit=5 a0=7ffe85ddc320 a1=7ffe85ddc410 a2=861 a3=2 items=0 ppid=1 pid=11479 auid=4294967295 uid=38 gid=38 euid=38 suid=38 fsuid=38 egid=38 sgid=38 fsgid=38 tty=(none) ses=4294967295 comm="ntpd" exe="/usr/sbin/ntpd" subj=system_u:system_r:ntpd_t:s0 key="time-change"
Jan 5 09:15:32 pci-fram-ipa1 audispd: node=pci-fram-ipa1.x.net type=SYSCALL msg=audit(1483607732.390:2328222): arch=c000003e syscall=159 success=yes exit=5 a0=7ffe85ddc320 a1=7ffe85ddc410 a2=861 a3=2 items=0 ppid=1 pid=11479 auid=4294967295 uid=38 gid=38 euid=38 suid=38 fsuid=38 egid=38 sgid=38 fsgid=38 tty=(none) ses=4294967295 comm="ntpd" exe="/usr/sbin/ntpd" subj=system_u:system_r:ntpd_t:s0 key="time-change"
Jan 5 09:15:33 pci-fram-ipa1 audispd: node=pci-fram-ipa1.x.net type=SYSCALL msg=audit(1483607733.390:2328223): arch=c000003e syscall=159 success=yes exit=5 a0=7ffe85ddc320 a1=7ffe85ddc410 a2=861 a3=2 items=0 ppid=1 pid=11479 auid=4294967295 uid=38 gid=38 euid=38 suid=38 fsuid=38 egid=38 sgid=38 fsgid=38 tty=(none) ses=4294967295 comm="ntpd" exe="/usr/sbin/ntpd" subj=system_u:system_r:ntpd_t:s0 key="time-change"
Jan 5 09:15:34 pci-fram-ipa1 audispd: node=pci-fram-ipa1.x.net type=SYSCALL msg=audit(1483607734.390:2328224): arch=c000003e syscall=159 success=yes exit=5 a0=7ffe85ddc320 a1=7ffe85ddc410 a2=861 a3=2 items=0 ppid=1 pid=11479 auid=4294967295 uid=38 gid=38 euid=38 suid=38 fsuid=38 egid=38 sgid=38 fsgid=38 tty=(none) ses=4294967295 comm="ntpd" exe="/usr/sbin/ntpd" subj=system_u:system_r:ntpd_t:s0 key="time-change"
Sync stats:
[09:15] callum pci-fram-ipa1 ~ $ sudo ntpq -p
remote refid st t when poll reach delay offset jitter
==============================================================================
*neon.trippett.o 131.188.3.221 2 u 112 256 377 17.924 -0.704 0.252
+uno.alvm.me 193.79.237.14 2 u 196 256 377 19.737 0.505 0.436
+greenore.zeip.e 140.203.204.77 2 u 165 256 377 19.616 0.019 0.252
+devrandom.pl 87.124.126.49 3 u 124 256 377 19.675 0.371 0.572
Additional info:
[09:17] callum pci-fram-ipa1 ~ $ ntpdc -c sysinfo
system peer: neon.trippett.org
system peer mode: client
leap indicator: 00
stratum: 3
precision: -23
root distance: 0.03258 s
root dispersion: 0.04211 s
reference ID: [178.62.6.103]
reference time: dc188cec.d9ea15c5 Thu, Jan 5 2017 9:14:20.851
system flags: auth ntp stats
jitter: 0.000320 s
stability: 0.000 ppm
broadcastdelay: 0.000000 s
authdelay: 0.000000 s
This sounds like this could be expected behavior, based upon how often NTP skews a clock
From NTP documentation:
5.1.3.2. How frequently will the System Clock be updated?
As time should be a continuous and steady stream, ntpd updates the clock in small quantities. However, to keep up with clock errors, such corrections have to be applied frequently. If adjtime() is used, ntpd will update the system clock
every second(I know this is not adjtimex, but adjtimex can function just as adjtime in the ADJ_OFFSET_SINGLESHOT mode: see adjtimex man page). If ntp_adjtime() is available, the operating system can compensate clock errors automatically, requiring only infrequent updates. See also Section 5.2 and Q: 5.1.6.1..The polling interval has nothing to do with this though. It's instead how often the upstream(lower time stratum) time server is "queried" for reference.
If the problem is that you're seeing the audit entries and you don't wish to see them for the ntp user - and you only want to see nefarious time skews, then follow the advice from this link, and exclude the ntp uid/auid.
Also, from the adjtimex man page, it seems that the TIME_BAD error you see may not mean that the time was never correctly slewed: