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 running

    Not 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)