Ntpd exiting due to assertion failure

ccb056 · Jan 19, 2014, 6:47 AM

NTP isn't working, my log is below.


Jan 19 01:47:44	ntpd[57646]: exiting (due to assertion failure)
Jan 19 01:47:44	ntpd[57646]: work_thread.c:271: INSIST(((void *)0) != req) failed
Jan 19 01:47:43	ntpd[57646]: Listening on routing socket on fd #26 for interface updates
Jan 19 01:47:43	ntpd[57646]: Listen normally on 5 lo0 [::1]:123
Jan 19 01:47:43	ntpd[57646]: Listen normally on 4 lo0 127.0.0.1:123
Jan 19 01:47:43	ntpd[57646]: setsockopt IPV6_MULTICAST_IF 0 for fe80::202:a5ff:fe4e:ed81%4 fails: Can't assign requested address
Jan 19 01:47:43	ntpd[57646]: Listen normally on 3 em1 [fe80::202:a5ff:fe4e:ed81%4]:123
Jan 19 01:47:43	ntpd[57646]: Listen normally on 2 em1 192.168.13.1:123
Jan 19 01:47:43	ntpd[57646]: Listen and drop on 1 v4wildcard 0.0.0.0:123
Jan 19 01:47:43	ntpd[57646]: Listen and drop on 0 v6wildcard [::]:123
Jan 19 01:47:43	ntpd[57646]: proto: precision = 1.397 usec (-19)
Jan 19 01:47:43	ntpd[57556]: Command line: /usr/local/sbin/ntpd -g -c /var/etc/ntpd.conf -p /var/run/ntpd.pid
Jan 19 01:47:43	ntpd[57556]: ntpd 4.2.7p411@1.2483-o Wed Jan 15 17:47:32 UTC 2014 (1): Starting

phil.davis · Jan 19, 2014, 7:02 AM

For the record, my NTP is working. There are plenty of "Can't assign requested address" - now I wonder if those are "normal" messages that appeared in 2.1. At least mine does not crash.

Jan 19 12:41:47 	ntpdate[44034]: step time server 203.174.83.202 offset 0.661536 sec
Jan 19 12:41:47 	ntp: Successfully synced time after 1 attempts.
Jan 19 12:41:47 	ntp: Starting NTP Daemon.
Jan 19 12:41:47 	ntpd[46262]: ntpd 4.2.7p411@1.2483-o Wed Jan 15 17:47:30 UTC 2014 (1): Starting
Jan 19 12:41:47 	ntpd[46262]: Command line: /usr/local/sbin/ntpd -g -c /var/etc/ntpd.conf -p /var/run/ntpd.pid
Jan 19 12:41:47 	ntpd[46777]: proto: precision = 3.678 usec (-18)
Jan 19 12:41:47 	ntpd[46777]: Listen and drop on 0 v6wildcard [::]:123
Jan 19 12:41:47 	ntpd[46777]: Listen and drop on 1 v4wildcard 0.0.0.0:123
Jan 19 12:41:47 	ntpd[46777]: Listen normally on 2 vr0 10.49.160.250:123
Jan 19 12:41:47 	ntpd[46777]: Listen normally on 3 vr0 [fe80::20d:b9ff:fe24:5900%1]:123
Jan 19 12:41:47 	ntpd[46777]: setsockopt IPV6_MULTICAST_IF 0 for fe80::20d:b9ff:fe24:5900%1 fails: Can't assign requested address
Jan 19 12:41:47 	ntpd[46777]: Listen normally on 4 vr1 10.49.175.1:123
Jan 19 12:41:47 	ntpd[46777]: Listen normally on 5 vr1 [fe80::20d:b9ff:fe24:5901%2]:123
Jan 19 12:41:47 	ntpd[46777]: setsockopt IPV6_MULTICAST_IF 0 for fe80::20d:b9ff:fe24:5901%2 fails: Can't assign requested address
Jan 19 12:41:47 	ntpd[46777]: Listen normally on 6 vr2 10.49.174.1:123
Jan 19 12:41:47 	ntpd[46777]: Listen normally on 7 vr2 [fe80::20d:b9ff:fe24:5902%3]:123
Jan 19 12:41:47 	ntpd[46777]: setsockopt IPV6_MULTICAST_IF 0 for fe80::20d:b9ff:fe24:5902%3 fails: Can't assign requested address
Jan 19 12:41:47 	ntpd[46777]: Listen normally on 8 lo0 127.0.0.1:123
Jan 19 12:41:47 	ntpd[46777]: Listen normally on 9 lo0 [::1]:123
Jan 19 12:41:47 	ntpd[46777]: Listen normally on 10 lo0 [fe80::1%7]:123
Jan 19 12:41:47 	ntpd[46777]: setsockopt IPV6_MULTICAST_IF 0 for fe80::1%7 fails: Can't assign requested address
Jan 19 12:41:47 	ntpd[46777]: Listen normally on 11 ovpns3 [fe80::20d:b9ff:fe24:5900%8]:123
Jan 19 12:41:47 	ntpd[46777]: setsockopt IPV6_MULTICAST_IF 0 for fe80::20d:b9ff:fe24:5900%8 fails: Can't assign requested address
Jan 19 12:41:47 	ntpd[46777]: Listen normally on 12 ovpns3 10.50.160.1:123
Jan 19 12:41:47 	ntpd[46777]: Listen normally on 13 ovpnc1 [fe80::20d:b9ff:fe24:5900%9]:123
Jan 19 12:41:47 	ntpd[46777]: setsockopt IPV6_MULTICAST_IF 0 for fe80::20d:b9ff:fe24:5900%9 fails: Can't assign requested address
Jan 19 12:41:47 	ntpd[46777]: Listen normally on 14 ovpnc1 10.49.235.2:123
Jan 19 12:41:47 	ntpd[46777]: Listen normally on 15 ovpnc2 [fe80::20d:b9ff:fe24:5900%10]:123
Jan 19 12:41:47 	ntpd[46777]: setsockopt IPV6_MULTICAST_IF 0 for fe80::20d:b9ff:fe24:5900%10 fails: Can't assign requested address
Jan 19 12:41:47 	ntpd[46777]: Listen normally on 16 ovpnc2 10.49.251.2:123
Jan 19 12:41:47 	ntpd[46777]: Listening on routing socket on fd #37 for interface updates

The NTP status looks good:

Status ▾ 	Server 	Ref ID 	Stratum 	Type 	When 	Poll 	Reach 	Delay 	Offset 	Jitter
Active Peer 	203.174.83.202 	133.243.238.163 	2 	u 	55 	64 	77 	127.222 	50.485 	38.432

ccb056 · Jan 19, 2014, 7:05 AM

It looks like things start to go wrong here:


Jan 19 01:47:44	ntpd[57646]: work_thread.c:271: INSIST(((void *)0) != req) failed

ccb056 · Jan 19, 2014, 7:18 AM

OK, I figured it out:

Originally in 2.1, I had the following NTP servers defined:


0.us.pool.ntp.org 1.us.pool.ntp.org 2.us.pool.ntp.org 3.us.pool.ntp.org 0.pfsense.pool.ntp.org tick.cerias.purdue.edu tock.cerias.purdue.edu tack.cerias.purdue.edu ntp.itd.umich.edu ntp.msu.edu nist.expertsmi.com nist.netservicesgroup.com atlas.digitalenigma.net pbody.digitalenigma.net nisttime.carsoncity.k12.mi.us time.nist.gov ac-ntp0.net.cmu.edu ac-ntp1.net.cmu.edu ac-ntp2.net.cmu.edu

Now, I have to have a shorter list:


0.us.pool.ntp.org 1.us.pool.ntp.org 2.us.pool.ntp.org 3.us.pool.ntp.org 0.pfsense.pool.ntp.org tick.cerias.purdue.edu tock.cerias.purdue.edu tack.cerias.purdue.edu ntp.itd.umich.edu ntp.msu.edu nist.expertsmi.com nist.netservicesgroup.com atlas.digitalenigma.net pbody.digitalenigma.net nisttime.carsoncity.k12.mi.us time.nist.gov ac-ntp0.net.cmu.edu

jimp · Jan 19, 2014, 4:18 PM

@ccb056:

OK, I figured it out:

Originally in 2.1, I had the following NTP servers defined:
Now, I have to have a shorter list:

Given that we're running ntp-devel at the moment, consider reporting that to the NTP project: http://ntp.org/bugs.html

We are not making any patches or changes to their code, so giving them a copy of your NTP config from /var/etc/ they should be able to reproduce the issue.

jimp · Jan 19, 2014, 4:19 PM

@phil.davis:

For the record, my NTP is working. There are plenty of "Can't assign requested address" - now I wonder if those are "normal" messages that appeared in 2.1. At least mine does not crash.
Jan 19 12:41:47 	ntpd[46777]: setsockopt IPV6_MULTICAST_IF 0 for fe80::20d:b9ff:fe24:5900%1 fails: Can't assign requested address

Note those all refer to multicast on scoped IPv6 link-local IPs. AFAIK that isn't something that will impact our usage.

fragged · Jan 19, 2014, 7:45 PM

Would it be possible to get support for pool directive to the pfSense GUI? I would also love to see the settings moved from General to Service -> NTP as a whole and have more control over NTP through the GUI. Maybe not for 2.1.X, but for 2.2 maybe?

jimp · Jan 19, 2014, 10:37 PM

There is already some work to improve the NTP settings for dealing with GPS units on 2.2 in a separate thread.

robi · Jan 20, 2014, 9:51 AM

@fragged:

Would it be possible to get support for pool directive to the pfSense GUI? I would also love to see the settings moved from General to Service -> NTP as a whole and have more control over NTP through the GUI. Maybe not for 2.1.X, but for 2.2 maybe?

Check this out:
https://forum.pfsense.org/index.php/topic,67189.105.html