Netgate Discussion Forum
    • Categories
    • Recent
    • Tags
    • Popular
    • Users
    • Search
    • Register
    • Login

    Latest snapshot has borked system after NTP activated - HyperV

    Scheduled Pinned Locked Moved General pfSense Questions
    3 Posts 2 Posters 1.6k Views
    Loading More Posts
    • Oldest to Newest
    • Newest to Oldest
    • Most Votes
    Reply
    • Reply as topic
    Log in to reply
    This topic has been deleted. Only users with topic management privileges can see it.
    • O Offline
      oben
      last edited by

      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)

      1 Reply Last reply Reply Quote 0
      • C Offline
        cmb
        last edited by

        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?

        1 Reply Last reply Reply Quote 0
        • O Offline
          oben
          last edited by

          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)

          1 Reply Last reply Reply Quote 0
          • First post
            Last post
          Copyright 2025 Rubicon Communications LLC (Netgate). All rights reserved.