ntpsec - flood of logs relating to sys_fuzz

[Eric S. Raymond]

Gautam Mani via users <users at ntpsec.org>:
> I have been running ntpsec-1.1.5 on FreeBSD-12 for many weeks now. However,
> yesterday I noticed this kind of log flooding. HW is a VPS cloud instance -
> and this kind of logging was not seen earlier. I checked online, found some
> earlier discussions on mailing lists about clocks not keeping time
> correctly etc., but could not nail down the exact issue. I noticed that
> ntpd (present in FreeBSD source) does not have this kind of logging and
> this seems to be an addition to ntpsec. As an intermediate step, I have
> fallen back to ntpd-4.2.8p12-a which is version present in FreeBSD base.
> 
> >From external time monitoring, the ntpd instance with ntpsec has been doing
> quite OK - and offset is < 2-10ms which is more than sufficient for my
> usage.
> 
> What needs to be done to eliminate this error / fix it ? Moving to a
> bare-metal HW is not an option for me.
> 
> Any suggestions ? Is the error of any consequence - from my usage, I cannot
> find anything wrong. In that case, any options to reduce this logging or
> moving it to DEBUG level so that it isn't swamping the logs ?
> 
> Aug 16 11:00:00 mx ntpd[22907]: CLOCK: ts_prev 1565920800 s + 188617128 ns,
> ts_min 1565920800 s + 188611858 ns
> Aug 16 11:00:00 mx ntpd[22907]: CLOCK: ts 1565920800 s + 188617128 ns
> Aug 16 11:00:00 mx ntpd[22907]: CLOCK: sys_fuzz 5920 nsec, prior fuzz
> 0.000005908
> Aug 16 11:00:00 mx ntpd[22907]: CLOCK: this fuzz -0.000005773
> Aug 16 11:00:00 mx ntpd[22907]: CLOCK: prev get_systime 0xe1008ca0.3048ddb0
> is 0.000000492 later than 0xe1008ca0.3048d571
> Aug 16 11:00:01 mx ntpd[22907]: CLOCK: ts_prev 1565920801 s + 53212996 ns,
> ts_min 1565920801 s + 53207666 ns
> Aug 16 11:00:01 mx ntpd[22907]: CLOCK: ts 1565920801 s + 53212996 ns
> Aug 16 11:00:01 mx ntpd[22907]: CLOCK: sys_fuzz 5920 nsec, prior fuzz
> 0.000005510
> Aug 16 11:00:01 mx ntpd[22907]: CLOCK: this fuzz -0.000005780
> Aug 16 11:00:01 mx ntpd[22907]: CLOCK: prev get_systime 0xe1008ca1.0d9efd9e
> is 0.000000039 later than 0xe1008ca1.0d9efcf7
> Aug 16 11:00:01 mx ntpd[22907]: CLOCK: ts_prev 1565920801 s + 476724846 ns,
> ts_min 1565920801 s + 476719376 ns
> Aug 16 11:00:01 mx ntpd[22907]: CLOCK: ts 1565920801 s + 476724846 ns
> Aug 16 11:00:01 mx ntpd[22907]: CLOCK: sys_fuzz 5920 nsec, prior fuzz
> 0.000005816
> Aug 16 11:00:01 mx ntpd[22907]: CLOCK: this fuzz -0.000005799
> Aug 16 11:00:01 mx ntpd[22907]: CLOCK: prev get_systime 0xe1008ca1.7a0a4634
> is 0.000000225 later than 0xe1008ca1.7a0a426c
> Aug 16 11:00:02 mx ntpd[22907]: CLOCK: ts_prev 1565920802 s + 117453431 ns,
> ts_min 1565920802 s + 117448341 ns
> Aug 16 11:00:02 mx ntpd[22907]: CLOCK: ts 1565920802 s + 117453431 ns

I was pretty sure I knew what I'd find when I looked into this.  
And I was totally wrong. :-)

This code at first looks like verbose debugging that someone on the NTPsec team dropped
in while investigating an issue, code that that could be safely removed.

But...the NTP Classic tree I have, which is 4.3.91 from 2016, *does*
have this logging.  It must have been introduced after 4.2.8 but
before we forked the code.

It looks to me like you have a real problem. Not one with NTPsec; the
3.91/NTPsec messages are saying that successive clock samples are
returning decreasing values. Something appears to have gone awry with the
PLL code in your kernel, well below the level where an NTPsec bug 
could mess anything up.

This is almost certainly happening under 4.2 as well; it's just that 4.2
is giving you no heads-up about it.

Unfortunately, here we reach the limits of my knowledge. I don't know
how to troubleshoot this kind of problem.  We have a couple of people
with more NTP operations experience than me; hopefully one of them will
have something useful to say.

Gary?  Hal?  Achim?  Does this look like anything you've seen before? 
-- 
		<a href="http://www.catb.org/~esr/">Eric S. Raymond</a>