On Fri, Jul 27, 2018 at 3:30 PM, Ward WIllats <[email protected]> wrote: >> On Jul 25, 2018, at 10:04 AM, Denys Vlasenko <[email protected]> >> 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. _______________________________________________ busybox mailing list [email protected] http://lists.busybox.net/mailman/listinfo/busybox
