Ntpd exited on signal 11 on startup during boot



  • Alix 2D13 CF card nanoBSD
    2.2-BETA (i386)
    built on Thu Nov 27 14:02:50 CST 2014
    FreeBSD 10.1-RELEASE

    I have 2 WAN (WAN and OPT1). At the moment WAN is physically disconnected and OPT1 is the way upstream and is set as default gateway (I don't think any of that should matter).
    There are 2 OpenVPN site-to-site clients to 2 other offices.

    ntpd dies a few seconds after starting up at boot time. After waiting a few minutes, it is still down. Then I start it manually from Status->Services and it runs.

    System log around ntpd exit:

    Nov 28 09:31:29 	check_reload_status: rc.newwanip starting ovpnc1
    Nov 28 09:31:29 	kernel: ovpnc1: link state changed to UP
    Nov 28 09:31:29 	kernel: pid 61287 (ntpd), uid 0: exited on signal 11 (core dumped)
    Nov 28 09:31:29 	kernel:
    Nov 28 09:31:16 	snmpd[58250]: disk_OS_get_disks: adding device 'ada0' to device list
    Nov 28 09:31:15 	kernel: done.
    
    

    NTPd log (looks OK - shame it exited after starting up):

    Nov 28 09:31:26 	ntpd[61287]: Listening on routing socket on fd #48 for interface updates
    Nov 28 09:31:26 	ntpd[61287]: Listen normally on 27 ovpnc2 10.49.239.2:123
    Nov 28 09:31:26 	ntpd[61287]: setsockopt IPV6_MULTICAST_IF 0 for fe80::20d:b9ff:fe24:59c0%18 fails: Can't assign requested address
    Nov 28 09:31:26 	ntpd[61287]: Listen normally on 26 ovpnc2 [fe80::20d:b9ff:fe24:59c0%18]:123
    Nov 28 09:31:26 	ntpd[61287]: Listen normally on 25 gif0 [fe80::20d:b9ff:fe24:59c0%16]:123
    Nov 28 09:31:26 	ntpd[61287]: Listen normally on 24 gif0 [2001:470:35:a7c::2]:123
    Nov 28 09:31:26 	ntpd[61287]: Listen normally on 23 vr0_vlan70 10.11.70.250:123
    Nov 28 09:31:26 	ntpd[61287]: setsockopt IPV6_MULTICAST_IF 0 for fe80::20d:b9ff:fe24:59c0%15 fails: Can't assign requested address
    Nov 28 09:31:26 	ntpd[61287]: Listen normally on 22 vr0_vlan70 [fe80::20d:b9ff:fe24:59c0%15]:123
    Nov 28 09:31:26 	ntpd[61287]: Listen normally on 21 vr0_vlan60 10.11.60.250:123
    Nov 28 09:31:26 	ntpd[61287]: setsockopt IPV6_MULTICAST_IF 0 for fe80::20d:b9ff:fe24:59c0%14 fails: Can't assign requested address
    Nov 28 09:31:26 	ntpd[61287]: Listen normally on 20 vr0_vlan60 [fe80::20d:b9ff:fe24:59c0%14]:123
    Nov 28 09:31:26 	ntpd[61287]: Listen normally on 19 vr0_vlan50 10.11.50.250:123
    Nov 28 09:31:26 	ntpd[61287]: setsockopt IPV6_MULTICAST_IF 0 for fe80::20d:b9ff:fe24:59c0%13 fails: Can't assign requested address
    Nov 28 09:31:26 	ntpd[61287]: Listen normally on 18 vr0_vlan50 [fe80::20d:b9ff:fe24:59c0%13]:123
    Nov 28 09:31:26 	ntpd[61287]: Listen normally on 17 vr0_vlan40 10.11.40.250:123
    Nov 28 09:31:26 	ntpd[61287]: setsockopt IPV6_MULTICAST_IF 0 for fe80::20d:b9ff:fe24:59c0%12 fails: Can't assign requested address
    Nov 28 09:31:26 	ntpd[61287]: Listen normally on 16 vr0_vlan40 [fe80::20d:b9ff:fe24:59c0%12]:123
    Nov 28 09:31:26 	ntpd[61287]: Listen normally on 15 vr0_vlan30 10.11.30.250:123
    Nov 28 09:31:26 	ntpd[61287]: setsockopt IPV6_MULTICAST_IF 0 for fe80::20d:b9ff:fe24:59c0%11 fails: Can't assign requested address
    Nov 28 09:31:26 	ntpd[61287]: Listen normally on 14 vr0_vlan30 [fe80::20d:b9ff:fe24:59c0%11]:123
    Nov 28 09:31:26 	ntpd[61287]: Listen normally on 13 vr0_vlan20 10.11.20.250:123
    Nov 28 09:31:26 	ntpd[61287]: setsockopt IPV6_MULTICAST_IF 0 for fe80::20d:b9ff:fe24:59c0%10 fails: Can't assign requested address
    Nov 28 09:31:26 	ntpd[61287]: Listen normally on 12 vr0_vlan20 [fe80::20d:b9ff:fe24:59c0%10]:123
    Nov 28 09:31:26 	ntpd[61287]: Listen normally on 11 ath0_wlan0 10.49.212.250:123
    Nov 28 09:31:26 	ntpd[61287]: setsockopt IPV6_MULTICAST_IF 0 for fe80::6202:b4ff:fe0c:4539%9 fails: Can't assign requested address
    Nov 28 09:31:26 	ntpd[61287]: Listen normally on 10 ath0_wlan0 [fe80::6202:b4ff:fe0c:4539%9]:123
    Nov 28 09:31:26 	ntpd[61287]: setsockopt IPV6_MULTICAST_IF 0 for fe80::1%7 fails: Can't assign requested address
    Nov 28 09:31:26 	ntpd[61287]: Listen normally on 9 lo0 [fe80::1%7]:123
    Nov 28 09:31:26 	ntpd[61287]: Listen normally on 8 lo0 [::1]:123
    Nov 28 09:31:26 	ntpd[61287]: Listen normally on 7 lo0 127.0.0.1:123
    Nov 28 09:31:26 	ntpd[61287]: Listen normally on 6 vr2 192.168.2.200:123
    Nov 28 09:31:26 	ntpd[61287]: setsockopt IPV6_MULTICAST_IF 0 for fe80::20d:b9ff:fe24:59c2%3 fails: Can't assign requested address
    Nov 28 09:31:26 	ntpd[61287]: Listen normally on 5 vr2 [fe80::20d:b9ff:fe24:59c2%3]:123
    Nov 28 09:31:26 	ntpd[61287]: setsockopt IPV6_MULTICAST_IF 0 for fe80::20d:b9ff:fe24:59c1%2 fails: Can't assign requested address
    Nov 28 09:31:26 	ntpd[61287]: Listen normally on 4 vr1 [fe80::20d:b9ff:fe24:59c1%2]:123
    Nov 28 09:31:26 	ntpd[61287]: Listen normally on 3 vr0 10.49.208.250:123
    Nov 28 09:31:26 	ntpd[61287]: setsockopt IPV6_MULTICAST_IF 0 for fe80::20d:b9ff:fe24:59c0%1 fails: Can't assign requested address
    Nov 28 09:31:26 	ntpd[61287]: Listen normally on 2 vr0 [fe80::20d:b9ff:fe24:59c0%1]:123
    Nov 28 09:31:26 	ntpd[61287]: Listen and drop on 1 v4wildcard 0.0.0.0:123
    Nov 28 09:31:26 	ntpd[61287]: Listen and drop on 0 v6wildcard [::]:123
    Nov 28 09:31:26 	ntpd[61287]: proto: precision = 2.337 usec (-19)
    Nov 28 09:31:26 	ntpd[61126]: Command line: /usr/local/sbin/ntpd -g -c /var/etc/ntpd.conf -p /var/run/ntpd.pid
    Nov 28 09:31:26 	ntpd[61126]: ntpd 4.2.7p479@1.2483-o Tue Nov 18 19:58:26 UTC 2014 (1): Starting
    Nov 28 09:31:26 	ntp: Starting NTP Daemon.
    Nov 28 09:31:26 	ntp: Successfully synced time after 1 attempts.
    Nov 28 09:31:26 	ntpdate[49942]: adjust time server 27.114.150.13 offset -0.075321 sec
    
    

    Anyone got this?
    I have tried multiple boots and it always happens.


  • Netgate Administrator

    Yep also seeing this on my test box, earlier snapshot than you though:

    [2.2-BETA][root@pfSense.localdomain]/root: uname -a
    FreeBSD pfSense.localdomain 10.1-RELEASE FreeBSD 10.1-RELEASE #0 29f4af5(releng/10.1)-dirty: Thu Nov 27 01:06:40 CST 2014     root@pfsense-22-i386-builder:/usr/obj.i386/usr/pfSensesrc/src/sys/pfSense_wrap.10.i386  i386
    
    

    I found NTPd had crashed out at boot, I tried to restart it from Status: NTP: and it crashed out again. A few minutes later I retarted it again from Status: Services: and it started fine, though it's still reporting 'no peers found'. I had set ntpd to listen on LAN only as apposed to the default 'nothing selcted, listen on all inetrfaces. That could be something different.

    Nov 28 09:12:02 	check_reload_status: Starting packages
    Nov 28 09:12:02 	check_reload_status: Reloading filter
    Nov 28 09:12:03 	php-fpm[285]: /rc.start_packages: Restarting/Starting all packages.
    Nov 28 09:12:22 	kernel: pid 67911 (ntpd), uid 0: exited on signal 11 (core dumped)
    Nov 28 10:24:42 	sshd[25076]: Connection closed by 192.168.200.11 [preauth]
    Nov 28 10:35:41 	php-fpm[286]: /index.php: Successful login for user 'admin' from: 192.168.200.10
    Nov 28 10:35:41 	php-fpm[286]: /index.php: Successful login for user 'admin' from: 192.168.200.10
    Nov 28 10:36:53 	sshd[97616]: Accepted keyboard-interactive/pam for root from 192.168.200.10 port 36133 ssh2
    Nov 28 10:39:56 	check_reload_status: Syncing firewall
    Nov 28 10:43:35 	sshd[19779]: Accepted keyboard-interactive/pam for root from 192.168.200.10 port 36137 ssh2
    Nov 28 10:49:28 	php-fpm[287]: /status_services.php: NTPD is starting up.
    Nov 28 10:49:31 	kernel: pid 42382 (ntpd), uid 0: exited on signal 11 (core dumped)
    Nov 28 10:50:01 	php-fpm[285]: /status_services.php: NTPD is starting up.
    Nov 28 10:52:08 	php-fpm[286]: /services_ntpd.php: Creating rrd update script
    Nov 28 10:52:09 	php-fpm[286]: /services_ntpd.php: NTPD is starting up.
    Nov 28 10:52:09 	check_reload_status: Syncing firewall
    

    My box has bridged interfaces and they go up and down like a yoyo at boot:

    Nov 28 09:06:25 	kernel: Trying to mount root from ufs:/dev/ufs/pfsense0 [ro,sync,noatime]...
    Nov 28 09:06:25 	kernel: done.
    Nov 28 09:06:25 	kernel: sk0: link state changed to DOWN
    Nov 28 09:06:27 	kernel: sk0: link state changed to UP
    Nov 28 09:06:30 	kernel: sk2: link state changed to DOWN
    Nov 28 09:06:30 	kernel: sk3: link state changed to DOWN
    Nov 28 09:06:31 	kernel: sk1: link state changed to DOWN
    Nov 28 09:06:31 	kernel: bridge0: link state changed to DOWN
    Nov 28 09:06:31 	kernel: sk2: promiscuous mode enabled
    Nov 28 09:06:31 	kernel: sk3: promiscuous mode enabled
    Nov 28 09:06:31 	kernel: sk1: promiscuous mode enabled
    Nov 28 09:06:31 	kernel: done.
    Nov 28 09:06:31 	kernel: pflog0: promiscuous mode enabled
    Nov 28 09:06:31 	kernel: ...done.
    Nov 28 09:06:33 	kernel:
    Nov 28 09:06:33 	kernel: sk1: link state changed to UP
    Nov 28 09:06:33 	kernel: bridge0: link state changed to UP
    Nov 28 09:06:35 	kernel: done.
    Nov 28 09:06:36 	kernel: done.
    Nov 28 09:06:37 	kernel: done.
    Nov 28 09:06:37 	kernel: .done.
    Nov 28 09:06:44 	kernel: done.
    Nov 28 09:06:44 	kernel: done.
    Nov 28 09:09:23 	kernel: sk1: link state changed to DOWN
    Nov 28 09:09:23 	kernel: bridge0: link state changed to DOWN
    Nov 28 09:09:25 	kernel: sk1: link state changed to UP
    Nov 28 09:09:25 	kernel: bridge0: link state changed to UP
    Nov 28 09:09:30 	kernel: sk1: link state changed to DOWN
    Nov 28 09:09:30 	kernel: bridge0: link state changed to DOWN
    Nov 28 09:09:31 	kernel: sk1: link state changed to UP
    Nov 28 09:09:31 	kernel: bridge0: link state changed to UP
    Nov 28 09:09:50 	kernel: sk1: link state changed to DOWN
    Nov 28 09:09:50 	kernel: bridge0: link state changed to DOWN
    Nov 28 09:09:52 	kernel: sk1: link state changed to UP
    Nov 28 09:09:52 	kernel: bridge0: link state changed to UP
    Nov 28 09:10:37 	kernel: sk3: link state changed to UP
    Nov 28 09:11:56 	kernel: sk3: link state changed to DOWN
    Nov 28 09:11:58 	kernel: sk3: link state changed to UP
    Nov 28 09:12:22 	kernel: pid 67911 (ntpd), uid 0: exited on signal 11 (core dumped)
    Nov 28 10:49:31 	kernel: pid 42382 (ntpd), uid 0: exited on signal 11 (core dumped)
    
    

    Also I noticed that after boot the filesystem was mounted R/W, it's not set to permanent rw, after some time it had changed back to R/O without me doing anything. I don't know if that relevant at all.  :-\

    This also not looking good:

    [2.2-BETA][root@pfSense.localdomain]/root: ntpq -p
    ntpq: write to localhost failed: Operation not permitted
    
    

    Steve



  • Can you add the "-U 0" fix to disable ntpd dynamic interface scanning, as described in this thread: https://forum.pfsense.org/index.php?topic=78194.0 ?

    As mentioned there, it's a crutch until the real race condition can be found (IMHO).

    Thinking about this further, why does pfSense have to stop & re-start ntpd on an interface up / down event?  Why can't we let ntpd take care of it, using the built-in dynamic interface scanning instead of forcing scanning off with '-U 0'?  Maybe that historical ntpd reset code comes from when pfSense used openntpd, which I believe lacked dynamic interface scanning.

    What happens if you simply comment out the two lines that call system_ntp_configure() and ntpdate_sync_once.sh() in rc.newwanip and rc.newwanipv6?



  • Searching our dev/test Splunk install where a couple dozen of our dev/test installs log, the only ntpd signals that we've seen is 15 (which is normal).

    Is there some atypical circumstance where this happens?

    @stephenw10:

    Also I noticed that after boot the filesystem was mounted R/W, it's not set to permanent rw, after some time it had changed back to R/O without me doing anything. I don't know if that relevant at all.

    Maybe package reinstall was still running and it finished? That's assuming that boot was post-upgrade, maybe it wasn't. Could have been something else in the boot process that was still running maybe.



  • @stephenw10:

    This also not looking good:

    [2.2-BETA][root@pfSense.localdomain]/root: ntpq -p
    ntpq: write to localhost failed: Operation not permitted
    
    

    ntpq generally wouldn't hit localhost unless you had localhost configured as one of your NTP servers, or maybe if it fell back to that for some reason (seems to default to that if it has nothing else). What NTP server(s) do you have configured?


  • Netgate Administrator

    To be honest I would have assumed it was something I had done until I read Phil's post. I'll have to gather more info but I'm almost certain it wasn't installing packages. I had upgraded the box the day before and restarted several times since. The logs were taken having booted the box in the morning and donr nothing else.

    The ntp settings were as default until I set it to listen on LAN only. The only server configured was 0.pfsense.pool.ntp.org (Edit: corrected URL). The address resolves and is pingable from the box.

    I'll come back with more after some testing.

    Steve



  • Just reporting that this ntpd exit continues to happen after ntpd first starts at boot. But I have seen it not happen, just occasionally ntpd is still running fine after boot. So it is not a hard error. After starting the service again, it stays up fine.

    This example on:
    2.2-BETA (i386)
    built on Sat Nov 29 02:37:09 CST 2014
    FreeBSD 10.1-RELEASE

    System log entry:

    Nov 29 21:54:01 	kernel: pid 71413 (ntpd), uid 0: exited on signal 11 (core dumped)
    

    NTP log:

    Nov 29 21:53:58 	ntpd[71413]: Listening on routing socket on fd #50 for interface updates
    Nov 29 21:53:58 	ntpd[71413]: Listen normally on 29 ovpnc2 10.49.239.2:123
    Nov 29 21:53:58 	ntpd[71413]: setsockopt IPV6_MULTICAST_IF 0 for fe80::20d:b9ff:fe24:59c0%18 fails: Can't assign requested address
    Nov 29 21:53:58 	ntpd[71413]: Listen normally on 28 ovpnc2 [fe80::20d:b9ff:fe24:59c0%18]:123
    Nov 29 21:53:58 	ntpd[71413]: Listen normally on 27 ovpnc1 10.49.255.2:123
    Nov 29 21:53:58 	ntpd[71413]: setsockopt IPV6_MULTICAST_IF 0 for fe80::20d:b9ff:fe24:59c0%17 fails: Can't assign requested address
    Nov 29 21:53:58 	ntpd[71413]: Listen normally on 26 ovpnc1 [fe80::20d:b9ff:fe24:59c0%17]:123
    Nov 29 21:53:58 	ntpd[71413]: Listen normally on 25 gif0 [fe80::20d:b9ff:fe24:59c0%16]:123
    Nov 29 21:53:58 	ntpd[71413]: Listen normally on 24 gif0 [2001:470:35:a7c::2]:123
    Nov 29 21:53:58 	ntpd[71413]: Listen normally on 23 vr0_vlan70 10.11.70.250:123
    Nov 29 21:53:58 	ntpd[71413]: setsockopt IPV6_MULTICAST_IF 0 for fe80::20d:b9ff:fe24:59c0%15 fails: Can't assign requested address
    Nov 29 21:53:58 	ntpd[71413]: Listen normally on 22 vr0_vlan70 [fe80::20d:b9ff:fe24:59c0%15]:123
    Nov 29 21:53:58 	ntpd[71413]: Listen normally on 21 vr0_vlan60 10.11.60.250:123
    Nov 29 21:53:58 	ntpd[71413]: setsockopt IPV6_MULTICAST_IF 0 for fe80::20d:b9ff:fe24:59c0%14 fails: Can't assign requested address
    Nov 29 21:53:58 	ntpd[71413]: Listen normally on 20 vr0_vlan60 [fe80::20d:b9ff:fe24:59c0%14]:123
    Nov 29 21:53:58 	ntpd[71413]: Listen normally on 19 vr0_vlan50 10.11.50.250:123
    Nov 29 21:53:58 	ntpd[71413]: setsockopt IPV6_MULTICAST_IF 0 for fe80::20d:b9ff:fe24:59c0%13 fails: Can't assign requested address
    Nov 29 21:53:58 	ntpd[71413]: Listen normally on 18 vr0_vlan50 [fe80::20d:b9ff:fe24:59c0%13]:123
    Nov 29 21:53:58 	ntpd[71413]: Listen normally on 17 vr0_vlan40 10.11.40.250:123
    Nov 29 21:53:58 	ntpd[71413]: setsockopt IPV6_MULTICAST_IF 0 for fe80::20d:b9ff:fe24:59c0%12 fails: Can't assign requested address
    Nov 29 21:53:58 	ntpd[71413]: Listen normally on 16 vr0_vlan40 [fe80::20d:b9ff:fe24:59c0%12]:123
    Nov 29 21:53:58 	ntpd[71413]: Listen normally on 15 vr0_vlan30 10.11.30.250:123
    Nov 29 21:53:58 	ntpd[71413]: setsockopt IPV6_MULTICAST_IF 0 for fe80::20d:b9ff:fe24:59c0%11 fails: Can't assign requested address
    Nov 29 21:53:58 	ntpd[71413]: Listen normally on 14 vr0_vlan30 [fe80::20d:b9ff:fe24:59c0%11]:123
    Nov 29 21:53:58 	ntpd[71413]: Listen normally on 13 vr0_vlan20 10.11.20.250:123
    Nov 29 21:53:58 	ntpd[71413]: setsockopt IPV6_MULTICAST_IF 0 for fe80::20d:b9ff:fe24:59c0%10 fails: Can't assign requested address
    Nov 29 21:53:58 	ntpd[71413]: Listen normally on 12 vr0_vlan20 [fe80::20d:b9ff:fe24:59c0%10]:123
    Nov 29 21:53:58 	ntpd[71413]: Listen normally on 11 ath0_wlan0 10.49.212.250:123
    Nov 29 21:53:58 	ntpd[71413]: setsockopt IPV6_MULTICAST_IF 0 for fe80::6202:b4ff:fe0c:4539%9 fails: Can't assign requested address
    Nov 29 21:53:58 	ntpd[71413]: Listen normally on 10 ath0_wlan0 [fe80::6202:b4ff:fe0c:4539%9]:123
    Nov 29 21:53:58 	ntpd[71413]: setsockopt IPV6_MULTICAST_IF 0 for fe80::1%7 fails: Can't assign requested address
    Nov 29 21:53:58 	ntpd[71413]: Listen normally on 9 lo0 [fe80::1%7]:123
    Nov 29 21:53:58 	ntpd[71413]: Listen normally on 8 lo0 [::1]:123
    Nov 29 21:53:58 	ntpd[71413]: Listen normally on 7 lo0 127.0.0.1:123
    Nov 29 21:53:58 	ntpd[71413]: Listen normally on 6 vr2 192.168.2.200:123
    Nov 29 21:53:58 	ntpd[71413]: setsockopt IPV6_MULTICAST_IF 0 for fe80::20d:b9ff:fe24:59c2%3 fails: Can't assign requested address
    Nov 29 21:53:58 	ntpd[71413]: Listen normally on 5 vr2 [fe80::20d:b9ff:fe24:59c2%3]:123
    Nov 29 21:53:58 	ntpd[71413]: setsockopt IPV6_MULTICAST_IF 0 for fe80::20d:b9ff:fe24:59c1%2 fails: Can't assign requested address
    Nov 29 21:53:58 	ntpd[71413]: Listen normally on 4 vr1 [fe80::20d:b9ff:fe24:59c1%2]:123
    Nov 29 21:53:58 	ntpd[71413]: Listen normally on 3 vr0 10.49.208.250:123
    Nov 29 21:53:58 	ntpd[71413]: setsockopt IPV6_MULTICAST_IF 0 for fe80::20d:b9ff:fe24:59c0%1 fails: Can't assign requested address
    Nov 29 21:53:58 	ntpd[71413]: Listen normally on 2 vr0 [fe80::20d:b9ff:fe24:59c0%1]:123
    Nov 29 21:53:58 	ntpd[71413]: Listen and drop on 1 v4wildcard 0.0.0.0:123
    Nov 29 21:53:58 	ntpd[71413]: Listen and drop on 0 v6wildcard [::]:123
    Nov 29 21:53:58 	ntpd[71413]: proto: precision = 2.315 usec (-19)
    Nov 29 21:53:58 	ntpd[71273]: Command line: /usr/local/sbin/ntpd -g -c /var/etc/ntpd.conf -p /var/run/ntpd.pid
    Nov 29 21:53:58 	ntpd[71273]: ntpd 4.2.7p479@1.2483-o Tue Nov 18 19:58:26 UTC 2014 (1): Starting
    Nov 29 21:53:58 	ntp: Starting NTP Daemon.
    Nov 29 21:53:58 	ntp: Successfully synced time after 1 attempts.
    Nov 29 21:53:58 	ntpdate[55589]: step time server 50.31.240.56 offset 0.955186 sec
    
    


  • i am seeing simular things in log but says i have no peers

    Nov 29 08:16:07 ntpd[93342]: 129.6.15.30 941a 8a sys_peer
    Nov 29 07:32:15 ntpd[93342]: 206.246.122.250 941a 8a sys_peer
    Nov 29 06:21:50 ntpd[93342]: 129.6.15.30 941a 8a sys_peer
    Nov 29 04:53:38 ntpd[93342]: 206.246.122.250 941a 8a sys_peer
    Nov 29 04:48:02 ntpd[93342]: 129.6.15.30 941a 8a sys_peer
    Nov 29 04:18:19 ntpd[93342]: 206.246.122.250 941a 8a sys_peer
    Nov 29 03:29:02 ntpd[93342]: 129.6.15.30 941a 8a sys_peer
    Nov 29 03:03:38 ntpd[93342]: 206.246.122.250 941a 8a sys_peer
    Nov 29 02:53:51 ntpd[93342]: 129.6.15.30 941a 8a sys_peer
    Nov 29 02:46:00 ntpd[93342]: 206.246.122.250 943a 8a sys_peer
    Nov 29 00:36:56 ntpd[93342]: 0.0.0.0 061b 0b leap_event
    Nov 29 00:36:49 ntpd[93342]: 206.246.122.250 8024 84 reachable
    Nov 29 00:36:49 ntpd[93342]: 0.0.0.0 c615 05 clock_sync
    Nov 29 00:36:49 ntpd[93342]: 129.6.15.30 903a 8a sys_peer
    Nov 29 00:36:49 ntpd[93342]: 129.6.15.30 8024 84 reachable
    Nov 29 00:36:48 ntpd[93342]: 129.6.15.30 8011 81 mobilize assoc 23951
    Nov 29 00:36:48 ntpd[93342]: DNS time-c.nist.gov -> 129.6.15.30
    Nov 29 00:36:48 ntpd[93342]: 206.246.122.250 8011 81 mobilize assoc 23950
    Nov 29 00:36:48 ntpd[93342]: DNS nist1-pa.ustiming.org -> 206.246.122.250
    Nov 29 00:36:48 ntpd[93342]: 0.0.0.0 c016 06 restart
    Nov 29 00:36:48 ntpd[93342]: 0.0.0.0 c012 02 freq_set kernel 11.434 PPM
    Nov 29 00:36:48 ntpd[93342]: 0.0.0.0 c01d 0d kern kernel time sync enabled
    Nov 29 00:36:48 ntpd[93342]: 127.127.20.0 local addr 127.0.0.1 -> <null>Nov 29 00:36:48 ntpd[93342]: refclock_open /dev/gps0: Is a directory
    Nov 29 00:36:48 ntpd[93342]: Listening on routing socket on fd #26 for interface updates
    Nov 29 00:36:48 ntpd[93342]: Listen normally on 5 lo0 [::1]:123
    Nov 29 00:36:48 ntpd[93342]: Listen normally on 4 lo0 127.0.0.1:123
    Nov 29 00:36:48 ntpd[93342]: setsockopt IPV6_MULTICAST_IF 0 for fe80::215:17ff:fe37:94d6%3 fails: Can't assign requested address
    Nov 29 00:36:48 ntpd[93342]: Listen normally on 3 em2 [fe80::215:17ff:fe37:94d6%3]:123
    Nov 29 00:36:48 ntpd[93342]: Listen normally on 2 em2 192.168.35.1:123
    Nov 29 00:36:48 ntpd[93342]: Listen and drop on 1 v4wildcard 0.0.0.0:123
    Nov 29 00:36:48 ntpd[93342]: Listen and drop on 0 v6wildcard [::]:123
    Nov 29 00:36:48 ntpd[93342]: proto: precision = 0.345 usec (-21)
    Nov 29 00:36:48 ntpd[93277]: Command line: /usr/local/sbin/ntpd -g -c /var/etc/ntpd.conf -p /var/run/ntpd.pid
    Nov 29 00:36:48 ntpd[93277]: ntpd 4.2.7p479@1.2483-o Tue Nov 18 19:39:09 UTC 2014 (1): Starting
    Nov 29 00:36:48 ntp: Starting NTP Daemon.

    Network Time Protocol Status
    Status Server Ref ID Stratum Type When Poll Reach Delay Offset Jitter
    No peers found, is the ntp service running?.</null>



  • Hmmm, good point. Even after I started my NTPd service and it has been running for 15 minutes, Status->NTP still shows:

    No peers found, is the ntp service running?.


  • Netgate Administrator

    Ok, back at the box and some things become clearer.
    NTPd does not crash out for me at boot though the only change I made was to add further peers from the same pool. Changing back to listening on all interfaces generates a load of distracting but non-fatal errors:

    ntpd[90064]: setsockopt IPV6_MULTICAST_IF 0 for fe80::290:7fff:fe3e:2cfd%1 fails: Can't assign requested address
    

    The Status: NTP: reports 'no peers found' and ntpq at the command line fails but the ntp logs show:

    ntpdate[41641]: step time server 193.47.164.28 offset -0.656167 sec
    

    So it appears to have an external time source.

    NTPd appears to be running correctly as I'm able to query it from a local machine:

    steve@steve-Satellite-Pro-A300:~$ ntpdate -d 192.168.200.1
    29 Nov 16:26:11 ntpdate[4568]: ntpdate 4.2.6p5@1.2349-o Wed Oct  9 19:08:07 UTC 2013 (1)
    Looking for host 192.168.200.1 and service ntp
    host found : pfSense.localdomain
    transmit(192.168.200.1)
    receive(192.168.200.1)
    transmit(192.168.200.1)
    receive(192.168.200.1)
    transmit(192.168.200.1)
    receive(192.168.200.1)
    transmit(192.168.200.1)
    receive(192.168.200.1)
    server 192.168.200.1, port 123
    stratum 3, precision -21, leap 00, trust 000
    refid [192.168.200.1], delay 0.02597, dispersion 0.00021
    transmitted 4, in filter 4
    reference time:    d8247166.7d786a69  Sat, Nov 29 2014 16:23:02.490
    originate timestamp: d8247229.306d84ba  Sat, Nov 29 2014 16:26:17.189
    transmit timestamp:  d8247229.330bca9b  Sat, Nov 29 2014 16:26:17.199
    filter delay:  0.02602  0.02605  0.02599  0.02597 
             0.00000  0.00000  0.00000  0.00000 
    filter offset: -0.01000 -0.01023 -0.01036 -0.01048
             0.000000 0.000000 0.000000 0.000000
    delay 0.02597, dispersion 0.00021
    offset -0.010484
    
    29 Nov 16:26:17 ntpdate[4568]: adjust time server 192.168.200.1 offset -0.010484 sec
    

    Additionally the filesystem on this box is definitely left RW after boot until I make some change in the webgui when the csript correctly sets it RO. Or I can set it RO manually at any time. The logs show it trying to mount RO at boot:

    Nov 29 16:13:25 	kernel: Trying to mount root from ufs:/dev/ufs/pfsense0 [ro,sync,noatime]...
    

    This is probably unrelated or could just be this box. Anyone else seeing that?

    Steve



  • mine is a full install

    2.2-BETA (amd64)
    built on Fri Nov 28 17:01:21 CST 2014
    FreeBSD 10.1-RELEASE


  • Netgate Administrator

    I have a vague recollection about a bug in ntpd that had a straight forward fix but it broke ntpq. When people were messing about with the ntp gps config this was a problem. I'll have to read back….

    Ah, yes it was the ntp amplification vulnerability from a while back. Discussed here:
    https://forum.pfsense.org/index.php?topic=67189.msg399050#msg399050
    Probably unrelated.

    Steve


  • Netgate Administrator

    If you enable peer logging in the ntp config you can clearly see it is associating with peers and working correctly.  :-
    This does look like a local query problem.

    Updated to latest snap. No change to either NTP or RW filesystem.

    Steve