NTP server not working post-2.2 upgrade
-
I'm seeing what seems to be exactly what this guy saw in the 2.2-RC thread:
https://forum.pfsense.org/index.php?topic=86502.0
Same thing, previously we were running 2.1.2 and had a number of clients inside the LAN syncing to the pfsense box. After the ugprade all the clients are un-synced. Running ntpdate from inside clients shows this (note the complaint is that the server is stratum 16):
[spork@devel4 ~]$ ntpdate -d 192.168.11.1 2 Apr 22:32:16 ntpdate[5180]: ntpdate 4.2.4p5-a (1) transmit(192.168.11.1) receive(192.168.11.1) transmit(192.168.11.1) receive(192.168.11.1) transmit(192.168.11.1) transmit(192.168.11.1) transmit(192.168.11.1) 192.168.11.1: Server dropped: strata too high server 192.168.11.1, port 123 stratum 16, precision -6, leap 11, trust 000 refid [192.168.11.1], delay 0.02605, dispersion 24.00186 transmitted 4, in filter 4 reference time: 00000000.00000000 Thu, Feb 7 2036 1:28:16.000 originate timestamp: d8c87a30.69123d7c Thu, Apr 2 2015 22:32:16.410 transmit timestamp: d8c87a31.6916bd01 Thu, Apr 2 2015 22:32:17.410 filter delay: 0.02605 0.04166 0.00000 0.00000 0.00000 0.00000 0.00000 0.00000 filter offset: 0.003524 -0.00021 0.000000 0.000000 0.000000 0.000000 0.000000 0.000000 delay 0.02605, dispersion 24.00186 offset 0.003524 2 Apr 22:32:18 ntpdate[5180]: no server suitable for synchronization found
Some stats from the server itself:
ntpq> peer remote refid st t when poll reach delay offset jitter ============================================================================== *nu.binary.net 216.229.0.179 2 u 132 128 377 51.473 11.690 2.584 +ec2-54-235-96-1 199.102.46.76 2 u 123 128 377 37.559 -20.004 1.790 +NTP1.playallian 129.6.15.30 2 u 128 128 377 74.699 -9.198 1.077 ntpq> ntpq> rv associd=0 status=061b leap_none, sync_ntp, 1 event, leap_event, version="ntpd 4.2.8p1@1.3265-o Fri Feb 13 17:22:32 UTC 2015 (1)", processor="i386", system="FreeBSD/10.1-RELEASE-p6", leap=00, stratum=3, precision=-19, rootdelay=51.702, rootdisp=54.216, refid=216.229.0.50, reftime=d8c879a1.8d8e464c Thu, Apr 2 2015 22:29:53.552, clock=d8c87a6a.49d3deb7 Thu, Apr 2 2015 22:33:14.288, peer=25885, tc=7, mintc=3, offset=-0.171923, frequency=25.245, sys_jitter=33.872938, clk_jitter=23.433, clk_wander=0.019 ntpq> sysinfo associd=0 status=061b leap_none, sync_ntp, 1 event, leap_event, system peer: nu.binary.net:123 system peer mode: client leap indicator: 00 stratum: 3 log2 precision: -19 root delay: 51.702 root dispersion: 54.456 reference ID: 216.229.0.50 reference time: d8c879a1.8d8e464c Thu, Apr 2 2015 22:29:53.552 system jitter: 33.872938 clock jitter: 23.433 clock wander: 0.019 broadcast delay: 0.000 symm. auth. delay: 0.000 ntpq>
And ntpdate on the firewall itself does not see the server as stratum 16:
[2.2.1-RELEASE][admin@fw.office.xxx.com]/root: ntpdate -d 192.168.11.1 2 Apr 22:33:48 ntpdate[43622]: ntpdate 4.2.8p1@1.3265-o Fri Feb 13 17:22:33 UTC 2015 (1) Looking for host 192.168.11.1 and service ntp 192.168.11.1 reversed to fw.office.xxx.com host found : fw.office.xxx.com transmit(192.168.11.1) receive(192.168.11.1) transmit(192.168.11.1) receive(192.168.11.1) transmit(192.168.11.1) receive(192.168.11.1) transmit(192.168.11.1) receive(192.168.11.1) server 192.168.11.1, port 123 stratum 3, precision -19, leap 00, trust 000 refid [192.168.11.1], delay 0.02591, dispersion 0.00002 transmitted 4, in filter 4 reference time: d8c879a1.8d8e464c Thu, Apr 2 2015 22:29:53.552 originate timestamp: d8c87a93.11bf9b26 Thu, Apr 2 2015 22:33:55.069 transmit timestamp: d8c87a93.119781b8 Thu, Apr 2 2015 22:33:55.068 filter delay: 0.02632 0.02594 0.02591 0.02603 0.00000 0.00000 0.00000 0.00000 filter offset: 0.000257 0.000074 0.000059 0.000090 0.000000 0.000000 0.000000 0.000000 delay 0.02591, dispersion 0.00002 offset 0.000059 2 Apr 22:33:55 ntpdate[43622]: adjust time server 192.168.11.1 offset 0.000059 sec
And the config in /var/etc/ntp.conf (this is all default for the options except for additional logging, and I'm set to only listen on the LAN interface):
cat /var/etc/ntpd.conf # # pfSense ntp configuration file # tinker panic 0 # Orphan mode stratum tos orphan 12 # Upstream Servers server 0.freebsd.pool.ntp.org iburst maxpoll 9 server 1.freebsd.pool.ntp.org iburst maxpoll 9 server 3.freebsd.pool.ntp.org iburst maxpoll 9 disable monitor enable stats statistics clockstats loopstats peerstats statsdir /var/log/ntp logconfig =syncall +clockall +peerall +sysall driftfile /var/db/ntpd.drift restrict default kod limited nomodify nopeer notrap restrict -6 default kod limited nomodify nopeer notrap interface ignore all interface listen fxp0
And the logs since the last restart:
Apr 2 21:48:25 fw ntpd[37699]: ntpd exiting on signal 15 (Terminated) Apr 2 21:48:25 fw ntpd[37699]: 0.0.0.0 061d 0d kern kernel time sync disabled Apr 2 21:48:25 fw ntpd[22713]: ntpd 4.2.8p1@1.3265-o Fri Feb 13 17:22:32 UTC 2015 (1): Starting Apr 2 21:48:25 fw ntpd[22713]: Command line: /usr/local/sbin/ntpd -g -c /var/etc/ntpd.conf -p /var/run/ntpd.pid Apr 2 21:48:25 fw ntpd[23006]: proto: precision = 2.235 usec (-19) Apr 2 21:48:25 fw ntpd[23006]: Listen and drop on 0 v6wildcard [::]:123 Apr 2 21:48:25 fw ntpd[23006]: Listen and drop on 1 v4wildcard 0.0.0.0:123 Apr 2 21:48:25 fw ntpd[23006]: Listen normally on 2 fxp0 [fe80::20e:cff:fea2:804%1]:123 Apr 2 21:48:25 fw ntpd[23006]: setsockopt IPV6_MULTICAST_IF 0 for fe80::20e:cff:fea2:804%1 fails: Can't assign requested address Apr 2 21:48:25 fw ntpd[23006]: Listen normally on 3 fxp0 192.168.11.1:123 Apr 2 21:48:25 fw ntpd[23006]: Listen normally on 4 fxp0 [2001:470:8:120e::1]:123 Apr 2 21:48:25 fw ntpd[23006]: Listen normally on 5 lo0 127.0.0.1:123 Apr 2 21:48:25 fw ntpd[23006]: Listen normally on 6 lo0 [::1]:123 Apr 2 21:48:25 fw ntpd[23006]: Listening on routing socket on fd #27 for interface updates Apr 2 21:48:25 fw ntpd[23006]: 0.0.0.0 c01d 0d kern kernel time sync enabled Apr 2 21:48:25 fw ntpd[23006]: 0.0.0.0 c012 02 freq_set kernel 25.309 PPM Apr 2 21:48:25 fw ntpd[23006]: 0.0.0.0 c016 06 restart Apr 2 21:48:25 fw ntpd[23006]: DNS 0.freebsd.pool.ntp.org -> 216.229.0.50 Apr 2 21:48:25 fw ntpd[23006]: 216.229.0.50 8011 81 mobilize assoc 25885 Apr 2 21:48:25 fw ntpd[23006]: DNS 1.freebsd.pool.ntp.org -> 54.235.96.196 Apr 2 21:48:25 fw ntpd[23006]: 54.235.96.196 8011 81 mobilize assoc 25886 Apr 2 21:48:26 fw ntpd[23006]: DNS 3.freebsd.pool.ntp.org -> 70.35.113.43 Apr 2 21:48:26 fw ntpd[23006]: 70.35.113.43 8011 81 mobilize assoc 25887 Apr 2 21:48:26 fw ntpd[23006]: 70.35.113.43 8024 84 reachable Apr 2 21:48:26 fw ntpd[23006]: 70.35.113.43 903a 8a sys_peer Apr 2 21:48:26 fw ntpd[23006]: 0.0.0.0 c615 05 clock_sync Apr 2 21:48:29 fw ntpd[23006]: 54.235.96.196 8024 84 reachable Apr 2 21:48:29 fw ntpd[23006]: 216.229.0.50 8024 84 reachable Apr 2 21:48:33 fw ntpd[23006]: 0.0.0.0 061b 0b leap_event Apr 2 21:48:36 fw ntpd[23006]: 216.229.0.50 903a 8a sys_peer
What's really odd is that the server does not seem to think it's at stratum 16, but stratum 3. But clients on the LAN don't agree.
Any ideas?
No blocks showing in the firewall logs.
-
That took a long time to write…
It's kind of fixed. If I uncheck everything in the "access restrictions" section, all is well.
Mostly.
On the first restart ntpd just crashes:
Apr 2 22:48:49 fw ntpd[11371]: ntpd 4.2.8p1@1.3265-o Fri Feb 13 17:22:32 UTC 2015 (1): Starting Apr 2 22:48:49 fw ntpd[11371]: Command line: /usr/local/sbin/ntpd -g -c /var/etc/ntpd.conf -p /var/run/ntpd.pid Apr 2 22:48:49 fw ntpd[11613]: proto: precision = 2.235 usec (-19) Apr 2 22:48:49 fw ntpd[11613]: Listen and drop on 0 v6wildcard [::]:123 Apr 2 22:48:49 fw ntpd[11613]: Listen and drop on 1 v4wildcard 0.0.0.0:123 Apr 2 22:48:49 fw ntpd[11613]: Listen normally on 2 fxp0 [fe80::20e:cff:fea2:804%1]:123 Apr 2 22:48:49 fw ntpd[11613]: setsockopt IPV6_MULTICAST_IF 0 for fe80::20e:cff:fea2:804%1 fails: Can't assign requested address Apr 2 22:48:49 fw ntpd[11613]: Listen normally on 3 fxp0 192.168.11.1:123 Apr 2 22:48:49 fw ntpd[11613]: Listen normally on 4 fxp0 [2001:470:8:120e::1]:123 Apr 2 22:48:49 fw ntpd[11613]: Listen normally on 5 lo0 127.0.0.1:123 Apr 2 22:48:49 fw ntpd[11613]: Listen normally on 6 lo0 [::1]:123 Apr 2 22:48:49 fw ntpd[11613]: Listening on routing socket on fd #27 for interface updates
That's the last of the log messages.
Then this in dmesg:
pid 82561 (ntpd), uid 0: exited on signal 11 (core dumped) and: dmesg | grep ntpd | grep dumped|wc -l 21
So it's been crashing every now and then while testing.
This is an i386 box, FWIW.
-
Try the '-u' option on ntpdate to use an unprivileged port.
port 123 udp needs to be open
-
Thanks - I don't think either of those is really applicable though.
From what I can gather, this is a config generation issue.
The ntpd crash also seems to have been addressed previously, but I don't see exactly what the current status is.
-
Most likely:
https://redmine.pfsense.org/issues/4155Under some circumstance that isn't exactly replicable (that I've found or that anyone else has been able to provide), ntpd crashes on 32 bit when there is an interface change of some sort. If you have a scenario or config where that's reliably replicable, that would help.
Using 64 bit instead will fix the problem.
-
Thanks - I don't think either of those is really applicable though.
For some reason you are not getting all the required responses from the server, see below. With ntpdate, default number of sample requests sent is four; your devel machine sent four queries, but only the first two were answered, or answered properly.
[spork@devel4 ~]$ ntpdate -d 192.168.11.1
2 Apr 22:32:16 ntpdate[5180]: ntpdate 4.2.4p5-a (1)
transmit(192.168.11.1)
receive(192.168.11.1) <== T/R OK
transmit(192.168.11.1)
receive(192.168.11.1) <== T/R OK
transmit(192.168.11.1) <== No response
transmit(192.168.11.1) <== No response
transmit(192.168.11.1) <== No response
192.168.11.1: Server dropped: strata too high <== ntpdate bails, something is wrong with 192.168.11.1
server 192.168.11.1, port 123
stratum 16, precision -6, leap 11, trust 000
refid [192.168.11.1], delay 0.02605, dispersion 24.00186
transmitted 4, in filter 4
reference time: 00000000.00000000 Thu, Feb 7 2036 1:28:16.000
originate timestamp: d8c87a30.69123d7c Thu, Apr 2 2015 22:32:16.410
transmit timestamp: d8c87a31.6916bd01 Thu, Apr 2 2015 22:32:17.410
filter delay: 0.02605 0.04166 0.00000 0.00000 <== See only two valid values in delay history samples
0.00000 0.00000 0.00000 0.00000
filter offset: 0.003524 -0.00021 0.000000 0.000000
0.000000 0.000000 0.000000 0.000000
delay 0.02605, dispersion 24.00186
offset 0.0035242 Apr 22:32:18 ntpdate[5180]: no server suitable for synchronization found
The crashing bug is something else you're right, probably 4155 as Chris mentioned. Seems to be triggered when ntpd is killed & restarted when any of the newwanip scripts are run, maybe related to 32 bit or [openvpn, ipsec] interfaces. I'm running my systems with the patch I posted here, letting ntpd handle interface changes on its own:
https://forum.pfsense.org/index.php?topic=88359.msg496016#msg496016. Not because I had any crashing issues, but ntpd has better timekeeping when it's not stopped and restarted often. If you have success with that patch, can you post back here or in the bug report?If your ntpd happens to crash after answering the first two queries, that could explain your client ntpdate issue.
-
@cmb:
Using 64 bit instead will fix the problem.
I can reproduce this on 64bit pfSense.
2.2.1-RELEASE (amd64)
built on Fri Mar 13 08:16:49 CDT 2015Attempting from a FreeBSD 9.x system on my network:
# ntpdate -d 172.17.0.1 9 Apr 23:30:45 ntpdate[5173]: ntpdate 4.2.4p5-a (1) transmit(172.17.0.1) receive(172.17.0.1) transmit(172.17.0.1) receive(172.17.0.1) transmit(172.17.0.1) transmit(172.17.0.1) transmit(172.17.0.1) 172.17.0.1: Server dropped: strata too high server 172.17.0.1, port 123 stratum 16, precision -6, leap 11, trust 000 refid [172.17.0.1], delay 0.02620, dispersion 24.00563 transmitted 4, in filter 4 reference time: 00000000.00000000 Thu, Feb 7 2036 0:28:16.000 originate timestamp: d8d1d075.a3ebf7c2 Thu, Apr 9 2015 23:30:45.640 transmit timestamp: d8d1d076.a3bed31b Thu, Apr 9 2015 23:30:46.639 filter delay: 0.02620 0.04164 0.00000 0.00000 0.00000 0.00000 0.00000 0.00000 filter offset: 0.011050 -0.00020 0.000000 0.000000 0.000000 0.000000 0.000000 0.000000 delay 0.02620, dispersion 24.00563 offset 0.011050
-
Attempting from a FreeBSD 9.x system on my network:
# ntpdate -d 172.17.0.1 9 Apr 23:30:45 ntpdate[5173]: ntpdate 4.2.4p5-a (1)
[spork@devel4 ~]$ ntpdate -d 192.168.11.1 2 Apr 22:32:16 ntpdate[5180]: ntpdate 4.2.4p5-a (1)
These both seem to be problems with ntpdate, or rather how older ntpdate reacts to modern ntpd server versions. This is not related to bug 4155, where ntpd crashes with (at least) openvpn interface changes.
I was able to duplicate the "only two response when there should be 4 or more" with ntpdate 4.2.4p5-a on a FreeBSD 9.x and 10.1 system against an ntpd 4.2.8p1 server. (But a linux ntpdate 4.2.6p5 had no problem). Then I built ntpdate from the ports collection and it successfully sync'd using the same command (below, 192.168.2.128 is my pfsense 2.2.2 server running ntpd 4.2.8p1 from ports):
Failure with ntpdate 4.2.4p5-a:
root@:~ # uname -a
FreeBSD 10.1-RELEASE FreeBSD 10.1-RELEASE #0 r274401: Tue Nov 11 21:02:49 UTC 2014 root@releng1.nyi.freebsd.org:/usr/obj/usr/src/sys/GENERIC amd64
root@:~ # ntpdate -d 192.168.2.128
10 Apr 18:33:28 ntpdate[63086]: ntpdate 4.2.4p5-a (1)
transmit(192.168.2.128)
receive(192.168.2.128)
transmit(192.168.2.128)
receive(192.168.2.128)
transmit(192.168.2.128)
transmit(192.168.2.128)
transmit(192.168.2.128)
192.168.2.128: Server dropped: strata too high
server 192.168.2.128, port 123
stratum 16, precision -6, leap 11, trust 000
refid [192.168.2.128], delay 0.02649, dispersion 24.00044
transmitted 4, in filter 4
reference time: 00000000.00000000 Thu, Feb 7 2036 6:28:16.000
originate timestamp: d8d295f8.59639498 Fri, Apr 10 2015 18:33:28.349
transmit timestamp: d8d295f9.595945d6 Fri, Apr 10 2015 18:33:29.349
filter delay: 0.02649 0.04248 0.00000 0.00000
0.00000 0.00000 0.00000 0.00000
filter offset: 0.000283 -0.00062 0.000000 0.000000
0.000000 0.000000 0.000000 0.000000
delay 0.02649, dispersion 24.00044
offset 0.00028310 Apr 18:33:30 ntpdate[63086]: no server suitable for synchronization found
Success on the same client with ntpdate 4.2.8p1 from ports:
root@:~ # /usr/local/sbin/ntpdate -d 192.168.2.128
10 Apr 18:37:12 ntpdate[63089]: ntpdate 4.2.8p1@1.3265-o Fri Apr 10 17:57:46 UTC 2015 (1)
Looking for host 192.168.2.128 and service ntp
192.168.2.128 reversed to pfsense.localdomain
host found : pfsense.localdomain
transmit(192.168.2.128)
receive(192.168.2.128)
transmit(192.168.2.128)
receive(192.168.2.128)
transmit(192.168.2.128)
receive(192.168.2.128)
transmit(192.168.2.128)
receive(192.168.2.128)
server 192.168.2.128, port 123
stratum 2, precision -21, leap 00, trust 000
refid [192.168.2.128], delay 0.02620, dispersion 0.00047
transmitted 4, in filter 4
reference time: d8d295e2.b5bc7f8a Fri, Apr 10 2015 18:33:06.709
originate timestamp: d8d296de.6d307fc2 Fri, Apr 10 2015 18:37:18.426
transmit timestamp: d8d296de.6d182b34 Fri, Apr 10 2015 18:37:18.426
filter delay: 0.02649 0.02632 0.02620 0.02658
0.00000 0.00000 0.00000 0.00000
filter offset: -0.00052 -0.00021 0.000272 -0.00019
0.000000 0.000000 0.000000 0.000000
delay 0.02620, dispersion 0.00047
offset 0.00027210 Apr 18:37:18 ntpdate[63089]: adjust time server 192.168.2.128 offset 0.000272 sec
Note that ntpdate is being deprecated, in favor of using ntpd in the 'one-shot' mode: "ntpd -qg". Here the -q means quit as soon as the client is synchronized, and -g means step the clock, a lot, if necessary. The drawbacks to this method are needing to make sure that ntpd is not already running as a daemon, and also not being able to specify a host on the command line (the normal servers configured in /var/etc/ntpd.conf are used). This approach does work with the older distributed versions of ntpd, so if you can't build ntpd from ports, that's an option you can use with older clients.
One could argue that there's a bug with ntpd, in that clients that were able to use ntpdate are no longer able to do so, but that may not get much traction as ntpdate is on its way out. In any case, it's not a pfSense bug
-
Interesting.
But that doesn't help for clients, like the IPMI client embedded in one of my servers, where I can't control their implementation.
I guess I will need to point various systems at external sources rather than my pfSense router.
-
One could argue that there's a bug with ntpd, in that clients that were able to use ntpdate are no longer able to do so, but that may not get much traction as ntpdate is on its way out. In any case, it's not a pfSense bug
True, but the old ntpdate had no issues after I changed ntp settings away from defaults on pfsense:
If I uncheck everything in the "access restrictions" section, all is well.
That's the section under Services->NTP labelled "Access restrictions" with the odd note that says "these options control access to NTP from the WAN", which seems odd as they actually seem to have an effect on LAN clients and I can't imagine anyone adding the WAN interface to the list of IPs without firewalling that off. For completeness, these are the parameters that if I uncheck them allow ntpdate and ntpd to work across all the LAN hosts:
So that's one issue, and that's dealt with (for me at least, others running older ntpdate will have to google).
The crashing issue persists, so I'm trying your suggestion of commenting out the ntpd restarts in rc.newwanip and rc.newwanipv6. I think all the clock skew that causes is also triggering issues with rekeying on one of my ipsec tunnels, so maybe that will get fixed as well.
What's interesting about this ntpd crash is how regular it is. It's not every tun up/down, but there's a pattern:
pid 27217 (ntpd), uid 0: exited on signal 11 (core dumped) ovpns1: link state changed to DOWN ovpns1: link state changed to UP ovpns1: link state changed to DOWN ovpns1: link state changed to UP ovpns1: link state changed to DOWN ovpns1: link state changed to UP ovpns1: link state changed to DOWN ovpns1: link state changed to UP pid 29157 (ntpd), uid 0: exited on signal 11 (core dumped) ovpns1: link state changed to DOWN ovpns1: link state changed to UP ovpns1: link state changed to DOWN ovpns1: link state changed to UP ovpns1: link state changed to DOWN ovpns1: link state changed to UP ovpns1: link state changed to DOWN ovpns1: link state changed to UP pid 84000 (ntpd), uid 0: exited on signal 11 (core dumped) ovpns1: link state changed to DOWN ovpns1: link state changed to UP ovpns1: link state changed to DOWN ovpns1: link state changed to UP ovpns1: link state changed to DOWN ovpns1: link state changed to UP ovpns1: link state changed to DOWN ovpns1: link state changed to UP
And I'm I the only one that gets nervous about software with this kind of security track record just falling over with a sig 11? Who would put money on whether something exploitable lurks in this crash?
-
That's the section under Services->NTP labelled "Access restrictions" with the odd note that says "these options control access to NTP from the WAN", which seems odd as they actually seem to have an effect on LAN clients and I can't imagine anyone adding the WAN interface to the list of IPs without firewalling that off. For completeness, these are the parameters that if I uncheck them allow ntpdate and ntpd to work across all the LAN hosts:
Any idea which one allows the older ntpdate to work? Does the preferred method "ntpd -gq" work for you with the defaults?
The crashing issue persists, so I'm trying your suggestion of commenting out the ntpd restarts in rc.newwanip and rc.newwanipv6. I think all the clock skew that causes is also triggering issues with rekeying on one of my ipsec tunnels, so maybe that will get fixed as well.
Interested in results you see.
And I'm I the only one that gets nervous about software with this kind of security track record just falling over with a sig 11? Who would put money on whether something exploitable lurks in this crash?
I doubt it's exploitable, as it seems to be triggered by a race condition stopping/starting ntpd.
-
That's the section under Services->NTP labelled "Access restrictions" with the odd note that says "these options control access to NTP from the WAN", which seems odd as they actually seem to have an effect on LAN clients and I can't imagine anyone adding the WAN interface to the list of IPs without firewalling that off. For completeness, these are the parameters that if I uncheck them allow ntpdate and ntpd to work across all the LAN hosts:
Any idea which one allows the older ntpdate to work? Does the preferred method "ntpd -gq" work for you with the defaults?
Not sure, I can test again at some point, but I've already annoyed people enough with my nagios alerts on ntp skew. :)
The crashing issue persists, so I'm trying your suggestion of commenting out the ntpd restarts in rc.newwanip and rc.newwanipv6. I think all the clock skew that causes is also triggering issues with rekeying on one of my ipsec tunnels, so maybe that will get fixed as well.
Interested in results you see.
So far so good. No ntpd crashes, and it might be too soon to tell, but no IPSEC VPN drops either, which I assume is just a side-effect of more accurate timekeeping.