> 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 Thu Jul 26 17:19:48 2018 daemon.err ntpd[23196]: ntpd: poll:8s sockets:0 interval:64s Thu Jul 26 17:19:48 2018 user.debug NTPd: ntpd event: stratum stratum=2 ppm=-29 poll_interval=64 offset=-0.095021 secs Thu Jul 26 17:19:56 2018 daemon.err ntpd[23196]: ntpd: sending query to 184.105.182.16 Thu Jul 26 17:19:56 2018 daemon.err ntpd[23196]: ntpd: reply from 184.105.182.16: offset:-0.039768 delay:0.453280 status:0x24 strat:2 refid:0xcafedad8 rootdelay:0.000107 reach:0x57 Thu Jul 26 17:19:56 2018 daemon.err ntpd[23196]: ntpd: update from 128.138.141.172: same or older datapoint, not using it Thu Jul 26 17:19:56 2018 daemon.err ntpd[23196]: ntpd: poll:25s sockets:0 interval:64s Thu Jul 26 17:20:21 2018 daemon.err ntpd[23196]: ntpd: sending query to 172.98.193.44 Thu Jul 26 17:20:22 2018 daemon.err ntpd[23196]: ntpd: poll:16s sockets:1 interval:64s Thu Jul 26 17:20:24 2018 daemon.err ntpd[23196]: ntpd: reply from 172.98.193.44: offset:+0.895777 delay:2.373204 status:0x24 strat:2 refid:0x9cc0a2ad rootdelay:0.052827 reach:0x6b Thu Jul 26 17:20:24 2018 daemon.err ntpd[23196]: ntpd: update from 128.138.141.172: same or older datapoint, not using it Thu Jul 26 17:20:24 2018 daemon.err ntpd[23196]: ntpd: poll:31s sockets:0 interval:64s Thu Jul 26 17:20:55 2018 daemon.err ntpd[23196]: ntpd: sending query to 128.138.141.172 Thu Jul 26 17:20:55 2018 daemon.err ntpd[23196]: ntpd: reply from 128.138.141.172: offset:-0.103032 delay:0.328571 status:0x1c strat:1 refid:0x5453494e rootdelay:0.000244 reach:0xff Thu Jul 26 17:20:55 2018 daemon.err ntpd[23196]: ntpd: update from:128.138.141.172 offset:-0.103032 jitter:0.064656 clock drift:-38.911ppm tc:6 Thu Jul 26 17:20:55 2018 daemon.err ntpd[23196]: ntpd: poll:9s sockets:0 interval:64s Thu Jul 26 17:21:04 2018 daemon.err ntpd[23196]: ntpd: sending query to 184.105.182.16 Thu Jul 26 17:21:05 2018 daemon.err ntpd[23196]: ntpd: reply from 184.105.182.16: offset:+0.173695 delay:0.839908 status:0x24 strat:2 refid:0xcafedad8 rootdelay:0.000107 reach:0xaf Thu Jul 26 17:21:05 2018 daemon.err ntpd[23196]: ntpd: update from 128.138.141.172: same or older datapoint, not using it Thu Jul 26 17:21:05 2018 daemon.err ntpd[23196]: ntpd: poll:23s sockets:0 interval:64s Thu Jul 26 17:21:28 2018 daemon.err ntpd[23196]: ntpd: sending query to 172.98.193.44 Thu Jul 26 17:21:29 2018 daemon.err ntpd[23196]: ntpd: poll:16s sockets:1 interval:64s Thu Jul 26 17:21:32 2018 daemon.err ntpd[23196]: ntpd: reply from 172.98.193.44: offset:+1.640760 delay:3.812868 status:0x24 strat:2 refid:0x9cc0a2ad rootdelay:0.052827 reach:0xd7 Thu Jul 26 17:21:32 2018 daemon.err ntpd[23196]: ntpd: update from 128.138.141.172: same or older datapoint, not using it Thu Jul 26 17:21:32 2018 daemon.err ntpd[23196]: ntpd: poll:31s sockets:0 interval:64s Thu Jul 26 17:22:03 2018 daemon.err ntpd[23196]: ntpd: sending query to 128.138.141.172 Thu Jul 26 17:22:04 2018 daemon.err ntpd[23196]: ntpd: poll:6s sockets:1 interval:64s Thu Jul 26 17:22:04 2018 daemon.err ntpd[23196]: ntpd: reply from 128.138.141.172: offset:+0.319707 delay:1.111947 status:0x1c strat:1 refid:0x5453494e rootdelay:0.000244 reach:0xff Thu Jul 26 17:22:04 2018 daemon.err ntpd[23196]: ntpd: current time is 2018-07-26 17:22:04.427175 Thu Jul 26 17:22:04 2018 daemon.err ntpd[23196]: ntpd: setting time to 2018-07-26 17:22:04.746882 (offset +0.319707s) Thu Jul 26 17:22:04 2018 daemon.err ntpd[23196]: ntpd: executing '/usr/sbin/ntpd-hotplug step' Thu Jul 26 17:22:04 2018 daemon.err ntpd[23196]: ntpd: update from:128.138.141.172 offset:+0.000000 jitter:0.064656 clock drift:-38.911ppm tc:6 Thu Jul 26 17:22:04 2018 daemon.err ntpd[23196]: ntpd: poll:6s sockets:0 interval:64s Thu Jul 26 17:22:04 2018 user.debug NTPd: ntpd event: step stratum=16 ppm=-38 poll_interval=64 offset=0.319707 secs Thu Jul 26 17:22:04 2018 user.debug NTPd: System time changed by ntpd. Telling foundation. offset=0.319707 secs Thu Jul 26 17:22:10 2018 daemon.err ntpd[23196]: ntpd: sending query to 184.105.182.16 Thu Jul 26 17:22:11 2018 daemon.err ntpd[23196]: ntpd: poll:16s sockets:1 interval:64s Thu Jul 26 17:22:12 2018 daemon.err ntpd[23196]: ntpd: reply from 184.105.182.16: offset:+0.435153 delay:1.956825 status:0x24 strat:2 refid:0xcafedad8 rootdelay:0.000107 reach:0x5f Thu Jul 26 17:22:12 2018 daemon.err ntpd[23196]: ntpd: update from 128.138.141.172: same or older datapoint, not using it Thu Jul 26 17:22:12 2018 daemon.err ntpd[23196]: ntpd: poll:27s sockets:0 interval:64s Thu Jul 26 17:22:39 2018 daemon.err ntpd[23196]: ntpd: sending query to 172.98.193.44 Thu Jul 26 17:22:39 2018 daemon.err ntpd[23196]: ntpd: reply from 172.98.193.44: offset:-0.464905 delay:0.205654 status:0x24 strat:2 refid:0x9cc0a2ad rootdelay:0.052827 reach:0xaf Thu Jul 26 17:22:39 2018 daemon.err ntpd[23196]: ntpd: update from 128.138.141.172: same or older datapoint, not using it Thu Jul 26 17:22:39 2018 daemon.err ntpd[23196]: ntpd: poll:30s sockets:0 interval:64s Thu Jul 26 17:23:09 2018 daemon.err ntpd[23196]: ntpd: sending query to 128.138.141.172 Thu Jul 26 17:23:10 2018 daemon.err ntpd[23196]: ntpd: poll:8s sockets:1 interval:64s Thu Jul 26 17:23:14 2018 daemon.err ntpd[23196]: ntpd: reply from 128.138.141.172: delay 4.530644 is too high, ignoring Thu Jul 26 17:23:14 2018 daemon.err ntpd[23196]: ntpd: poll:5s sockets:0 interval:64s Thu Jul 26 17:23:19 2018 daemon.err ntpd[23196]: ntpd: sending query to 184.105.182.16 Thu Jul 26 17:23:19 2018 daemon.err ntpd[23196]: ntpd: reply from 184.105.182.16: offset:-0.472908 delay:0.121887 status:0x24 strat:2 refid:0xcafedad8 rootdelay:0.000107 reach:0xbf Thu Jul 26 17:23:19 2018 daemon.err ntpd[23196]: ntpd: current time is 2018-07-26 17:23:19.631399 Thu Jul 26 17:23:19 2018 daemon.err ntpd[23196]: ntpd: setting time to 2018-07-26 17:23:19.158490 (offset -0.472908s) Thu Jul 26 17:23:19 2018 daemon.err ntpd[23196]: ntpd: executing '/usr/sbin/ntpd-hotplug step' Thu Jul 26 17:23:19 2018 daemon.err ntpd[23196]: ntpd: update from:184.105.182.16 offset:+0.000000 jitter:0.064656 clock drift:-38.911ppm tc:6 Thu Jul 26 17:23:19 2018 daemon.err ntpd[23196]: ntpd: poll:26s sockets:0 interval:64s Thu Jul 26 17:23:19 2018 user.debug NTPd: ntpd event: step stratum=16 ppm=-38 poll_interval=64 offset=-0.472908 secs Thu Jul 26 17:23:19 2018 user.debug NTPd: System time changed by ntpd. Telling foundation. offset=-0.472908 secs Thu Jul 26 17:23:45 2018 daemon.err ntpd[23196]: ntpd: sending query t... _______________________________________________ busybox mailing list [email protected] http://lists.busybox.net/mailman/listinfo/busybox
