ntpd "STEP storm" with small offset

Mon Jul 30 19:07:33 UTC 2018

On Fri, Jul 27, 2018 at 3:30 PM, Ward WIllats <busybox at wardco.com> wrote:
>> On Jul 25, 2018, at 10:04 AM, Denys Vlasenko <vda.linux at googlemail.com> wrote:
>>
>> This can't be happening on 1.27.2. Code simply does not do that. Step
>> offsets ought to be >= 1 second.
>>
>> Please run ntpd with -ddd and post the log.
>>
>
> Sorry for the delay. We let the system run another 24 hours to collect more data before we restarted ntpd last night to catch this.
>
> This is both -ddd output and messages from our script (tagged 'NTPd'). "foundation" is the name of of userland application.
>
> Thu Jul 26 17:16:27 2018 daemon.err ntpd[23196]: ntpd: setting time to 2018-07-26 17:16:27.117673 (offset +0.301425s)
> Thu Jul 26 17:16:27 2018 daemon.err ntpd[23196]: ntpd: executing '/usr/sbin/ntpd-hotplug step'
> Thu Jul 26 17:16:27 2018 daemon.err ntpd[23196]: ntpd: update from:128.138.141.172 offset:+0.000000 jitter:0.066460 clock drift:-29.157ppm tc:6
> Thu Jul 26 17:16:27 2018 daemon.err ntpd[23196]: ntpd: poll:8s sockets:0 interval:64s
> Thu Jul 26 17:16:27 2018 user.debug NTPd: ntpd event: step stratum=16 ppm=-29 poll_interval=64 offset=0.301425 secs
> Thu Jul 26 17:16:27 2018 user.debug NTPd: System time changed by ntpd. Telling foundation. offset=0.301425 secs
> Thu Jul 26 17:16:35 2018 daemon.err ntpd[23196]: ntpd: sending query to 184.105.182.16
> Thu Jul 26 17:16:35 2018 daemon.err ntpd[23196]: ntpd: reply from 184.105.182.16: delay 0.768580 is too high, ignoring
> Thu Jul 26 17:16:35 2018 daemon.err ntpd[23196]: ntpd: poll:24s sockets:0 interval:64s
> Thu Jul 26 17:16:59 2018 daemon.err ntpd[23196]: ntpd: sending query to 172.98.193.44
> Thu Jul 26 17:17:00 2018 daemon.err ntpd[23196]: ntpd: reply from 172.98.193.44: offset:-0.384162 delay:0.094107 status:0x24 strat:2 refid:0x9cc0a2ad rootdelay:0.055451 reach:0x6d
> Thu Jul 26 17:17:00 2018 daemon.err ntpd[23196]: ntpd: update from 128.138.141.172: same or older datapoint, not using it
> Thu Jul 26 17:17:00 2018 daemon.err ntpd[23196]: ntpd: poll:32s sockets:0 interval:64s
> Thu Jul 26 17:17:32 2018 daemon.err ntpd[23196]: ntpd: sending query to 128.138.141.172
> Thu Jul 26 17:17:33 2018 daemon.err ntpd[23196]: ntpd: poll:7s sockets:1 interval:64s
> Thu Jul 26 17:17:33 2018 daemon.err ntpd[23196]: ntpd: reply from 128.138.141.172: offset:+0.382946 delay:1.588481 status:0x1c strat:1 refid:0x5453494e rootdelay:0.000244 reach:0xff
> Thu Jul 26 17:17:33 2018 daemon.err ntpd[23196]: ntpd: current time is 2018-07-26 17:17:33.636298
> Thu Jul 26 17:17:33 2018 daemon.err ntpd[23196]: ntpd: setting time to 2018-07-26 17:17:33.252135 (offset -0.384162s)
> Thu Jul 26 17:17:33 2018 daemon.err ntpd[23196]: ntpd: executing '/usr/sbin/ntpd-hotplug step'
> Thu Jul 26 17:17:33 2018 daemon.err ntpd[23196]: ntpd: update from:172.98.193.44 offset:+0.000000 jitter:0.066460 clock drift:-29.157ppm tc:6
> Thu Jul 26 17:17:33 2018 daemon.err ntpd[23196]: ntpd: poll:7s sockets:0 interval:64s
> Thu Jul 26 17:17:33 2018 user.debug NTPd: ntpd event: step stratum=16 ppm=-29 poll_interval=64 offset=-0.384162 secs
> Thu Jul 26 17:17:33 2018 user.debug NTPd: System time changed by ntpd. Telling foundation. offset=-0.384162 secs
> Thu Jul 26 17:17:40 2018 daemon.err ntpd[23196]: ntpd: sending query to 184.105.182.16
> Thu Jul 26 17:17:41 2018 daemon.err ntpd[23196]: ntpd: poll:16s sockets:1 interval:64s
> Thu Jul 26 17:17:41 2018 daemon.err ntpd[23196]: ntpd: reply from 184.105.182.16: offset:+0.757069 delay:1.558396 status:0x24 strat:2 refid:0xcafedad8 rootdelay:0.000107 reach:0x55
> Thu Jul 26 17:17:41 2018 daemon.err ntpd[23196]: ntpd: update from 172.98.193.44: same or older datapoint, not using it
> Thu Jul 26 17:17:41 2018 daemon.err ntpd[23196]: ntpd: poll:22s sockets:0 interval:64s
> Thu Jul 26 17:18:03 2018 daemon.err ntpd[23196]: ntpd: sending query to 172.98.193.44
> Thu Jul 26 17:18:04 2018 daemon.err ntpd[23196]: ntpd: poll:16s sockets:1 interval:64s
> Thu Jul 26 17:18:06 2018 daemon.err ntpd[23196]: ntpd: reply from 172.98.193.44: delay 2.471982 is too high, ignoring
> Thu Jul 26 17:18:06 2018 daemon.err ntpd[23196]: ntpd: poll:34s sockets:0 interval:64s
> Thu Jul 26 17:18:40 2018 daemon.err ntpd[23196]: ntpd: sending query to 128.138.141.172
> Thu Jul 26 17:18:41 2018 daemon.err ntpd[23196]: ntpd: poll:7s sockets:1 interval:64s
> Thu Jul 26 17:18:43 2018 daemon.err ntpd[23196]: ntpd: reply from 128.138.141.172: offset:+1.477522 delay:3.026581 status:0x1c strat:1 refid:0x5453494e rootdelay:0.000244 reach:0xff
> Thu Jul 26 17:18:43 2018 daemon.err ntpd[23196]: ntpd: update from 172.98.193.44: same or older datapoint, not using it
> Thu Jul 26 17:18:43 2018 daemon.err ntpd[23196]: ntpd: poll:5s sockets:0 interval:64s
> Thu Jul 26 17:18:48 2018 daemon.err ntpd[23196]: ntpd: sending query to 184.105.182.16
> Thu Jul 26 17:18:48 2018 daemon.err ntpd[23196]: ntpd: reply from 184.105.182.16: offset:+0.256974 delay:0.539940 status:0x24 strat:2 refid:0xcafedad8 rootdelay:0.000107 reach:0xab
> Thu Jul 26 17:18:48 2018 daemon.err ntpd[23196]: ntpd: update from 172.98.193.44: same or older datapoint, not using it
> Thu Jul 26 17:18:48 2018 daemon.err ntpd[23196]: ntpd: poll:24s sockets:0 interval:64s
> Thu Jul 26 17:19:12 2018 daemon.err ntpd[23196]: ntpd: sending query to 172.98.193.44
> Thu Jul 26 17:19:13 2018 daemon.err ntpd[23196]: ntpd: reply from 172.98.193.44: offset:+0.351228 delay:0.784601 status:0x24 strat:2 refid:0x9cc0a2ad rootdelay:0.052827 reach:0xb5
> Thu Jul 26 17:19:13 2018 daemon.err ntpd[23196]: ntpd: current time is 2018-07-26 17:19:13.718008
> Thu Jul 26 17:19:13 2018 daemon.err ntpd[23196]: ntpd: setting time to 2018-07-26 17:19:13.974982 (offset +0.256974s)
> Thu Jul 26 17:19:13 2018 daemon.err ntpd[23196]: ntpd: executing '/usr/sbin/ntpd-hotplug step'
> Thu Jul 26 17:19:13 2018 daemon.err ntpd[23196]: ntpd: update from:184.105.182.16 offset:+0.000000 jitter:0.066460 clock drift:-29.157ppm tc:6
> Thu Jul 26 17:19:13 2018 daemon.err ntpd[23196]: ntpd: poll:34s sockets:0 interval:64s
> Thu Jul 26 17:19:14 2018 user.debug NTPd: ntpd event: step stratum=16 ppm=-29 poll_interval=64 offset=0.256974 secs
> Thu Jul 26 17:19:14 2018 user.debug NTPd: System time changed by ntpd. Telling foundation. offset=0.256974 secs
> Thu Jul 26 17:19:48 2018 daemon.err ntpd[23196]: ntpd: sending query to 128.138.141.172
> Thu Jul 26 17:19:48 2018 daemon.err ntpd[23196]: ntpd: reply from 128.138.141.172: offset:-0.095021 delay:0.371329 status:0x1c strat:1 refid:0x5453494e rootdelay:0.000244 reach:0xff
> Thu Jul 26 17:19:48 2018 daemon.err ntpd[23196]: ntpd: executing '/usr/sbin/ntpd-hotplug stratum'
> Thu Jul 26 17:19:48 2018 daemon.err ntpd[23196]: ntpd: update from:128.138.141.172 offset:-0.095021 jitter:0.074552 clock drift:-32.328ppm tc:6
...

According to your log, offsets smaller than 0.125 are slewed. Offsets
larger than that are stepped.

I bet it isn't 1.27.2. Must be 1.24.x or earlier. STEP_THRESHOLD was
increased to 1 second
in 1.25.0.