ntpd never achieves synchronized, even with PPS source; ntpdig KOD

Tue Dec 18 08:21:15 UTC 2018

On Tue, Dec 18, 2018 at 12:10:07AM -0800, Hal Murray wrote:
> 
> devel at ntpsec.org said:
> > 1. ntpdig localhost always gets KOD
> > 2. ntpsec never gets syncronized state: ntpwait never gives success
> > 3. local clock ends up drifting :-( 
> The ntpq printout looks sane.  The "*" in front of SHM(1) usually indicates 
> that it is happy.
Yep, that's what I'd expect.  

Build details (Gentoo):
 * python3_6: running run_in_build_dir python_configure
CCFLAGS="-march=native -O2 -pipe" \
LINKFLAGS="-march=native -O2 -pipe -Wl,--hash-style=gnu -Wl,-O1 -Wl,--as-needed" \
"/var/tmp/portage/net-misc/ntpsec-1.1.2/work/ntpsec-1.1.2/waf" \
--prefix=/usr --libdir=/usr/lib64 --nopyc --nopyo \
--refclock=gpsd,generic,shm,pps,nmea,local --enable-lockclock --enable-seccomp configure
Setting top to                           : /var/tmp/portage/net-misc/ntpsec-1.1.2/work/ntpsec-1.1.2-python3_6 
Setting out to                           : /var/tmp/portage/net-misc/ntpsec-1.1.2/work/ntpsec-1.1.2-python3_6/build 

> Please try grepping for ntpd in /var/log/messages (or syslog, or ...) to see 
> if there is anything interesting.
I was trying to get it to print SOMETHING about trying to actually set the time, but no nice.
Here's the logs, with minor redactions for IP addresses/hostname.

2018-12-18T07:09:51.000000+00:00 REDACTED ntpd[29719]: INIT: ntpd ntpsec-1.1.2 2018-09-30T16:42:11Z: Starting
2018-12-18T07:09:51.000000+00:00 REDACTED ntpd[29719]: INIT: Command line: /usr/sbin/ntpd -p /run/ntpd.pid -g -u ntp:ntp -x -c /etc/ntp.d/default.conf -D 15
2018-12-18T07:09:51.000000+00:00 REDACTED ntpd[29720]: INIT: precision = 0.121 usec (-23)
2018-12-18T07:09:51.000000+00:00 REDACTED ntpd[29720]: INIT: successfully locked into RAM
2018-12-18T07:09:51.000000+00:00 REDACTED ntpd[29720]: CONFIG: readconfig: parsing file: /etc/ntp.d/default.conf
2018-12-18T07:09:51.000000+00:00 REDACTED ntpd[29720]: INIT: Using SO_TIMESTAMPNS
2018-12-18T07:09:51.000000+00:00 REDACTED ntpd[29720]: IO: Listen and drop on 0 v6wildcard [::]:123
2018-12-18T07:09:51.000000+00:00 REDACTED ntpd[29720]: IO: Listen and drop on 1 v4wildcard 0.0.0.0:123
2018-12-18T07:09:51.000000+00:00 REDACTED ntpd[29720]: IO: Listen normally on 2 lo 127.0.0.1:123
2018-12-18T07:09:51.000000+00:00 REDACTED ntpd[29720]: IO: Listen normally on 3 bond0 REDACTED:123
2018-12-18T07:09:51.000000+00:00 REDACTED ntpd[29720]: IO: Listen normally on 4 lo [::1]:123
2018-12-18T07:09:51.000000+00:00 REDACTED ntpd[29720]: IO: Listen normally on 5 bond0 [2001:569:REDACTED]:123
2018-12-18T07:09:51.000000+00:00 REDACTED ntpd[29720]: IO: Listen normally on 6 bond0 [2001:569:REDACTED]:123
2018-12-18T07:09:51.000000+00:00 REDACTED ntpd[29720]: IO: Listen normally on 7 bond0 [2001:470:REDACTED]:123
2018-12-18T07:09:51.000000+00:00 REDACTED ntpd[29720]: IO: Listen normally on 8 bond0 [2001:569:REDACTED]:123
2018-12-18T07:09:51.000000+00:00 REDACTED ntpd[29720]: IO: Listen normally on 9 bond0 [fe80::REDACTED]:123
2018-12-18T07:09:51.000000+00:00 REDACTED ntpd[29720]: IO: Listening on routing socket on fd #26 for interface updates
2018-12-18T07:09:51.000000+00:00 REDACTED ntpd[29720]: PROTO: 127.127.28.0 8011 81 mobilize assoc 38321
2018-12-18T07:09:51.000000+00:00 REDACTED ntpd[29720]: PROTO: 127.127.28.1 8011 81 mobilize assoc 38322
2018-12-18T07:09:51.000000+00:00 REDACTED ntpd[29720]: PROTO: 0.0.0.0 8811 81 mobilize assoc 38323
2018-12-18T07:09:51.000000+00:00 REDACTED ntpd[29720]: PROTO: 0.0.0.0 8811 81 mobilize assoc 38324
2018-12-18T07:09:51.000000+00:00 REDACTED ntpd[29720]: PROTO: 0.0.0.0 8811 81 mobilize assoc 38325
2018-12-18T07:09:51.000000+00:00 REDACTED ntpd[29720]: SYNC: Found 10 servers, suggest minsane at least 3
2018-12-18T07:09:51.000000+00:00 REDACTED ntpd[29720]: PROTO: 0.0.0.0 c016 06 restart
2018-12-18T07:09:51.000000+00:00 REDACTED ntpd[29720]: INIT: sandbox: seccomp enabled.
2018-12-18T07:09:52.000000+00:00 REDACTED ntpd[29720]: PROTO: SHM(0) 8014 84 reachable
2018-12-18T07:09:52.000000+00:00 REDACTED ntpd[29720]: PROTO: SHM(0) 901a 8a sys_peer
2018-12-18T07:09:53.000000+00:00 REDACTED ntpd[29720]: PROTO: SHM(1) 8014 84 reachable
2018-12-18T07:09:53.000000+00:00 REDACTED ntpd[29720]: PROTO: 0.0.0.0 c418 08 no_sys_peer
2018-12-18T07:09:54.000000+00:00 REDACTED ntpd[29720]: DNS: dns_probe: pool.ntp.org, cast_flags:8, flags:101
2018-12-18T07:09:54.000000+00:00 REDACTED ntpd[29720]: DNS: dns_check: processing pool.ntp.org, 8, 101
2018-12-18T07:09:54.000000+00:00 REDACTED ntpd[29720]: DNS: Pool taking: 206.108.0.132
2018-12-18T07:09:54.000000+00:00 REDACTED ntpd[29720]: PROTO: 206.108.0.132 0011 81 mobilize assoc 38326
2018-12-18T07:09:54.000000+00:00 REDACTED ntpd[29720]: DNS: Pool poking hole in restrictions for: 206.108.0.132
2018-12-18T07:09:54.000000+00:00 REDACTED ntpd[29720]: DNS: Pool taking: 144.217.75.74
2018-12-18T07:09:54.000000+00:00 REDACTED ntpd[29720]: PROTO: 144.217.75.74 0011 81 mobilize assoc 38327
2018-12-18T07:09:54.000000+00:00 REDACTED ntpd[29720]: DNS: Pool poking hole in restrictions for: 144.217.75.74
2018-12-18T07:09:54.000000+00:00 REDACTED ntpd[29720]: DNS: Pool taking: 144.217.65.184
2018-12-18T07:09:54.000000+00:00 REDACTED ntpd[29720]: PROTO: 144.217.65.184 0011 81 mobilize assoc 38328
2018-12-18T07:09:54.000000+00:00 REDACTED ntpd[29720]: DNS: Pool poking hole in restrictions for: 144.217.65.184
2018-12-18T07:09:54.000000+00:00 REDACTED ntpd[29720]: DNS: Pool taking: 199.19.167.36
2018-12-18T07:09:54.000000+00:00 REDACTED ntpd[29720]: PROTO: 199.19.167.36 0011 81 mobilize assoc 38329
2018-12-18T07:09:54.000000+00:00 REDACTED ntpd[29720]: DNS: Pool poking hole in restrictions for: 199.19.167.36
2018-12-18T07:09:54.000000+00:00 REDACTED ntpd[29720]: DNS: dns_take_status: pool.ntp.org=>good, 8
2018-12-18T07:09:54.000000+00:00 REDACTED ntpd[29720]: PROTO: 206.108.0.132 0014 84 reachable
2018-12-18T07:09:54.000000+00:00 REDACTED ntpd[29720]: PROTO: 144.217.65.184 0014 84 reachable
2018-12-18T07:09:54.000000+00:00 REDACTED ntpd[29720]: PROTO: 199.19.167.36 0014 84 reachable
2018-12-18T07:09:55.000000+00:00 REDACTED ntpd[29720]: DNS: dns_probe: gentoo.pool.ntp.org, cast_flags:8, flags:101
2018-12-18T07:09:55.000000+00:00 REDACTED ntpd[29720]: DNS: dns_check: processing gentoo.pool.ntp.org, 8, 101
2018-12-18T07:09:55.000000+00:00 REDACTED ntpd[29720]: DNS: dns_check: DNS error: -5, No address associated with hostname
2018-12-18T07:09:55.000000+00:00 REDACTED ntpd[29720]: DNS: dns_take_status: gentoo.pool.ntp.org=>error, 12
2018-12-18T07:09:56.000000+00:00 REDACTED ntpd[29720]: DNS: dns_probe: ca.pool.ntp.org, cast_flags:8, flags:101
2018-12-18T07:09:56.000000+00:00 REDACTED ntpd[29720]: DNS: dns_check: processing ca.pool.ntp.org, 8, 101
2018-12-18T07:09:56.000000+00:00 REDACTED ntpd[29720]: DNS: Pool skipping: 144.217.65.184
2018-12-18T07:09:56.000000+00:00 REDACTED ntpd[29720]: DNS: Pool skipping: 144.217.75.74
2018-12-18T07:09:56.000000+00:00 REDACTED ntpd[29720]: DNS: Pool skipping: 206.108.0.132
2018-12-18T07:09:56.000000+00:00 REDACTED ntpd[29720]: DNS: Pool skipping: 199.19.167.36
2018-12-18T07:09:56.000000+00:00 REDACTED ntpd[29720]: DNS: dns_take_status: ca.pool.ntp.org=>good, 8
2018-12-18T07:10:00.000000+00:00 REDACTED ntpd[29720]: PROTO: SHM(1) 911a 8a sys_peer
2018-12-18T07:11:00.000000+00:00 REDACTED ntpd[29720]: PROTO: 144.217.75.74 0014 84 reachable
2018-12-18T07:14:10.000000+00:00 REDACTED ntpd[29720]: DNS: dns_probe: pool.ntp.org, cast_flags:8, flags:101
2018-12-18T07:14:10.000000+00:00 REDACTED ntpd[29720]: DNS: dns_check: processing pool.ntp.org, 8, 101
2018-12-18T07:14:10.000000+00:00 REDACTED ntpd[29720]: DNS: Pool taking: 54.39.20.247
2018-12-18T07:14:10.000000+00:00 REDACTED ntpd[29720]: PROTO: 54.39.20.247 0011 81 mobilize assoc 38330
2018-12-18T07:14:10.000000+00:00 REDACTED ntpd[29720]: DNS: Pool poking hole in restrictions for: 54.39.20.247
2018-12-18T07:14:10.000000+00:00 REDACTED ntpd[29720]: DNS: Pool taking: 209.115.181.107
2018-12-18T07:14:10.000000+00:00 REDACTED ntpd[29720]: PROTO: 209.115.181.107 0011 81 mobilize assoc 38331
2018-12-18T07:14:10.000000+00:00 REDACTED ntpd[29720]: DNS: Pool poking hole in restrictions for: 209.115.181.107
2018-12-18T07:14:10.000000+00:00 REDACTED ntpd[29720]: DNS: Pool taking: 158.69.226.90
2018-12-18T07:14:10.000000+00:00 REDACTED ntpd[29720]: PROTO: 158.69.226.90 0011 81 mobilize assoc 38332
2018-12-18T07:14:10.000000+00:00 REDACTED ntpd[29720]: DNS: Pool poking hole in restrictions for: 158.69.226.90
2018-12-18T07:14:10.000000+00:00 REDACTED ntpd[29720]: DNS: Pool skipping: 206.108.0.132
2018-12-18T07:14:10.000000+00:00 REDACTED ntpd[29720]: DNS: dns_take_status: pool.ntp.org=>good, 8
2018-12-18T07:14:10.000000+00:00 REDACTED ntpd[29720]: PROTO: 209.115.181.107 0014 84 reachable
2018-12-18T07:14:10.000000+00:00 REDACTED ntpd[29720]: PROTO: 54.39.20.247 0014 84 reachable
2018-12-18T07:14:10.000000+00:00 REDACTED ntpd[29720]: PROTO: 158.69.226.90 0014 84 reachable
2018-12-18T07:21:07.000000+00:00 REDACTED ntpd[29720]: PROTO: 206.108.0.132 1315 85 restart timeout
2018-12-18T07:21:07.000000+00:00 REDACTED ntpd[29720]: PROTO: 206.108.0.132 0012 82 demobilize assoc 38326
2018-12-18T07:21:07.000000+00:00 REDACTED ntpd[29720]: PROTO: 206.108.0.132 unlink local addr REDACTED -> <null>
2018-12-18T07:23:23.000000+00:00 REDACTED ntpd[29720]: PROTO: 144.217.75.74 1315 85 restart timeout
2018-12-18T07:23:23.000000+00:00 REDACTED ntpd[29720]: PROTO: 144.217.75.74 0012 82 demobilize assoc 38327
2018-12-18T07:23:23.000000+00:00 REDACTED ntpd[29720]: PROTO: 144.217.75.74 unlink local addr REDACTED -> <null>

-- 
Robin Hugh Johnson
Gentoo Linux: Dev, Infra Lead, Foundation Treasurer
E-Mail   : robbat2 at gentoo.org
GnuPG FP : 11ACBA4F 4778E3F6 E4EDF38E B27B944E 34884E85
GnuPG FP : 7D0B3CEB E9B85B1F 825BCECF EE05E6F6 A48F6136
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 1113 bytes
Desc: Digital signature
URL: <https://lists.ntpsec.org/pipermail/devel/attachments/20181218/53b89292/attachment.bin>