Latest snapshot has borked system after NTP activated - HyperV
-
Bearing in mind I am new to pfSense I am having none of my installed packages restarting after a reboot now.
It appears to have happened after I enabled NTP and turned off Time Synchronization in Hyper-V.
The time is correct and aligns with other servers but I am seeing alot of: "calcru: runtime went backwards" errors in the log:
No packages start including squid and quagga. Quagga has this for status:
grep: /var/etc/quagga/zebra.conf: No such file or directory
grep: /var/etc/quagga/ospfd.conf: No such file or directory
ospfd does not appear to be runningNot sure what is really going on.
I have uninstalled all the packages. I am considering removing the NTP server and going back to time synchronization through Hyper-V.
Other errors:
Apr 8 13:57:27 php-fpm 261 /rc.newwanip: The command '/usr/bin/nice -n20 /usr/local/bin/rrdtool update /var/db/rrd/captiveportal-lan-loggedin.rrd N:U' returned exit code '1', the output was 'ERROR: /var/db/rrd/captiveportal-lan-loggedin.rrd: illegal attempt to update using time 1460087847 when last update time is 1460101896 (minimum one second step)'
Apr 8 13:57:27 php-fpm 261 /rc.newwanip: Creating rrd update script
Apr 8 13:57:27 php-cgi rc.bootup: The command '/usr/bin/nice -n20 /usr/local/bin/rrdtool update /var/db/rrd/wan-traffic.rrd N:U:U:U:U:U:U:U:U' returned exit code '1', the output was 'ERROR: /var/db/rrd/wan-traffic.rrd: illegal attempt to update using time 1460087847 when last update time is 1460102310 (minimum one second step)'
done.
Apr 8 13:57:28 syslogd exiting on signal 15
Apr 8 13:57:28 syslogd kernel boot file is /boot/kernel/kernel
Apr 8 13:57:28 php-fpm 260 /rc.start_packages: Skipping STARTing packages process because previous/another instance is already running
Apr 8 13:57:28 kernel done.
Apr 8 13:57:29 php-fpm 261 /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - 10.4.yy.xx -> 10.4.xx.33 - Restarting packages.
Apr 8 13:57:29 check_reload_status Starting packages
Apr 8 13:57:30 php-fpm 260 /rc.start_packages: Skipping STARTing packages process because previous/another instance is already running
Apr 8 13:57:30 login login on ttyv0 as root
Apr 8 13:57:30 sshlockout 24915 sshlockout/webConfigurator v3.0 starting up
Apr 8 13:57:44 kernel calcru: runtime went backwards from 125881 usec to 64863 usec for pid 260 (php-fpm)
Apr 8 13:57:44 kernel calcru: runtime went backwards from 41098 usec to 21171 usec for pid 260 (php-fpm)
Apr 8 13:57:56 php-fpm 260 /diag_reboot.php: Successful login for user 'admin' from: 10.0.0.30
Apr 8 13:58:01 kernel calcru: runtime went backwards from 531724 usec to 273936 usec for pid 259 (php-fpm)
Apr 8 13:58:01 kernel calcru: runtime went backwards from 90073 usec to 46401 usec for pid 259 (php-fpm) -
That sounds like the expected result when the time sync in Hyper-V and NTP are both enabled. From what I've gathered from others' experiences reported here, disabling one or the other of those has always been fine. You sure the Hyper-V time sync is really disabled?
-
Just disabled NTP and it crashed.
Switched Time Sync on HyperV back on but still have the calcru errors bigtime.
8 14:07:48 kernel calcru: runtime went backwards from 45 usec to 22 usec for pid 16327 (sshlockout_pf)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 10462 usec to 5290 usec for pid 16327 (sshlockout_pf)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 1677 usec to 848 usec for pid 16207 (sshd)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 1677 usec to 848 usec for pid 16207 (sshd)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 4453 usec to 2251 usec for pid 9777 (xinetd)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 4453 usec to 2251 usec for pid 9777 (xinetd)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 368431 usec to 241009 usec for pid 9199 (openvpn)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 21535 usec to 10889 usec for pid 9199 (openvpn)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 368307 usec to 241009 usec for pid 9199 (openvpn)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 2489 usec to 1280 usec for pid 310 (devd)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 14292 usec to 7226 usec for pid 310 (devd)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 2489 usec to 1280 usec for pid 310 (devd)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 403 usec to 203 usec for pid 300 (check_reload_status)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 403 usec to 203 usec for pid 300 (check_reload_status)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 6158 usec to 3113 usec for pid 298 (check_reload_status)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 5410 usec to 3113 usec for pid 298 (check_reload_status)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 606818 usec to 486460 usec for pid 262 (php-fpm)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 8660 usec to 5958 usec for pid 258 (php-fpm)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 8576 usec to 5958 usec for pid 258 (php-fpm)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 20517 usec to 10788 usec for pid 50 (md0)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 20397 usec to 10788 usec for pid 50 (md0)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 5302 usec to 4128 usec for pid 18 (bufdaemon)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 4260 usec to 3955 usec for pid 18 (bufdaemon)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 40 usec to 20 usec for pid 7 (sctp_iterator)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 42 usec to 21 usec for pid 7 (sctp_iterator)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 11642 usec to 6050 usec for pid 5 (fdc0)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 12584 usec to 6532 usec for pid 5 (fdc0)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 88779 usec to 49657 usec for pid 4 (cam)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 219977 usec to 111232 usec for pid 4 (cam)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 85795 usec to 50814 usec for pid 4 (cam)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 26023 usec to 13159 usec for pid 14 (geom)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 3263 usec to 1650 usec for pid 14 (geom)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 534 usec to 270 usec for pid 14 (geom)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 22460 usec to 11357 usec for pid 14 (geom)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 28 usec to 14 usec for pid 13 (ng_queue)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 32 usec to 16 usec for pid 13 (ng_queue)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 281 usec to 142 usec for pid 12 (intr)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 13417 usec to 6784 usec for pid 12 (intr)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 183 usec to 92 usec for pid 12 (intr)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 145 usec to 73 usec for pid 12 (intr)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 10296 usec to 5238 usec for pid 1 (init)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 12323683 usec to 6231750 usec for pid 1 (init)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 8820 usec to 5238 usec for pid 1 (init)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 2122 usec to 1279 usec for pid 0 (kernel)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 129751 usec to 65609 usec for pid 0 (kernel)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 17 usec to 8 usec for pid 0 (kernel)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 1207 usec to 650 usec for pid 0 (kernel)
Apr 8 14:07:48 kernel calcru: runtime went backwards from 12 usec to 6 usec for pid 0 (kernel)