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

    An earnest appeal - please do fix APINGER in 2.2

    Scheduled Pinned Locked Moved 2.2 Snapshot Feedback and Problems - RETIRED
    95 Posts 29 Posters 30.3k 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.
    • E
      eri--
      last edited by

      I also put a fix on apinger to recover from strange delay values on new snapshots.

      1 Reply Last reply Reply Quote 0
      • S
        Supermule Banned
        last edited by

        Yes. It starts to show latency and packetloss. Then I manually restart the Apinger service and it runs again no issues.

        It gets worse when the alarms are triggered and after a restart then no problem again for some time.

        1 Reply Last reply Reply Quote 0
        • A
          applerule
          last edited by

          @ermal:

          @applerule,

          are you sure your system time is on sync and not running backward?

          It was set to sync through hyper-v…I just disabled that in case it was causing issues.  Also, I just updated to the latest snapshot.  Will post update soon.

          1 Reply Last reply Reply Quote 0
          • A
            applerule
            last edited by

            Update: All looks good.

            It looks like ermal's fixes have made a huge difference.  No more weird latency issues.  I am at almost 2 days uptime, rrd graphs and gateway status is spot on.

            I am on the Monday snapshot.

            1 Reply Last reply Reply Quote 0
            • N
              naras
              last edited by

              Still got a offline opt1 on latest Thu Oct 09 15:04:15 bulid.

              1 Reply Last reply Reply Quote 0
              • E
                eri--
                last edited by

                @naras,

                can you explain the offline nic?
                Put more detail on what you mean by that.

                1 Reply Last reply Reply Quote 0
                • N
                  naras
                  last edited by

                  @ermal:

                  can you explain the offline nic?
                  Put more detail on what you mean by that.

                  I meant apinger showed me a opt1 offline status after a system upgrade in some snapshots, but in fact two pppoe lines are connected and up.

                  I got it today after upgraded to Oct 14 17:37:25 build on the first reboot, but it's disappeared after another reboot.

                  1 Reply Last reply Reply Quote 0
                  • DerelictD
                    Derelict LAYER 8 Netgate
                    last edited by

                    My HE IPv6 tunnel has been stuck at 14% packetloss - exactly - for days.  Even though it's working fine.  (2.1.5).  As far as I'm concerned, apinger should be all hands on deck at ESF.  for 2.1.6 and 2.2.  It's completely broken and the ramifications are pretty extreme.

                    I am, right now, going to go add debugging to my 2.1.5 and restart apinger.

                    ETA: I would concentrate my efforts in the logic that calculates what's debug logged as "Recently lost packets".  Something is not properly decrementing that variable.

                    Chattanooga, Tennessee, USA
                    A comprehensive network diagram is worth 10,000 words and 15 conference calls.
                    DO NOT set a source address/port in a port forward or firewall rule unless you KNOW you need it!
                    Do Not Chat For Help! NO_WAN_EGRESS(TM)

                    1 Reply Last reply Reply Quote 0
                    • E
                      eri--
                      last edited by

                      @naras,

                      put apinger in debug mode and give me the logs.

                      1 Reply Last reply Reply Quote 0
                      • E
                        eri--
                        last edited by

                        @Derelict:

                        My HE IPv6 tunnel has been stuck at 14% packetloss - exactly - for days.  Even though it's working fine.  (2.1.5).  As far as I'm concerned, apinger should be all hands on deck at ESF.  for 2.1.6 and 2.2.  It's completely broken and the ramifications are pretty extreme.

                        I am, right now, going to go add debugging to my 2.1.5 and restart apinger.

                        ETA: I would concentrate my efforts in the logic that calculates what's debug logged as "Recently lost packets".  Something is not properly decrementing that variable.

                        It needs to be replaced but when i come to it.
                        There is some statistical calculation that is wrong there especially after reloading the config.
                        Though i should have fixed most of them by now.

                        1 Reply Last reply Reply Quote 0
                        • N
                          naras
                          last edited by

                          @ermal, my latest logs:

                          Oct 16 07:39:08 syslogd: kernel boot file is /boot/kernel/kernel
                          Oct 16 07:39:08 kernel: Copyright © 1992-2014 The FreeBSD Project.
                          Oct 16 07:39:08 kernel: Copyright (c) 1979, 1980, 1983, 1986, 1988, 1989, 1991, 1992, 1993, 1994
                          Oct 16 07:39:08 kernel: The Regents of the University of California. All rights reserved.
                          Oct 16 07:39:08 kernel: FreeBSD is a registered trademark of The FreeBSD Foundation.
                          Oct 16 07:39:08 kernel: FreeBSD 10.1-RC2 #22 7f4a427(releng/10.1)-dirty: Wed Oct 15 15:06:55 CDT 2014
                          Oct 16 07:39:08 kernel: root@pf22-amd64-snap:/usr/obj.amd64/usr/pfSensesrc/src/sys/pfSense_SMP.10 amd64
                          Oct 16 07:39:08 kernel: FreeBSD clang version 3.3 (tags/RELEASE_33/final 183502) 20130610
                          Oct 16 07:39:08 kernel: CPU: Intel(R) Pentium(R) CPU G3420 @ 3.20GHz (1616.59-MHz K8-class CPU)
                          Oct 16 07:39:08 kernel: Origin = "GenuineIntel" Id = 0x306c3 Family = 0x6 Model = 0x3c Stepping = 3
                          Oct 16 07:39:08 kernel: Features=0x1f83fbff <fpu,vme,de,pse,tsc,msr,pae,mce,cx8,apic,sep,mtrr,pge,mca,cmov,pat,pse36,mmx,fxsr,sse,sse2,ss,htt>Oct 16 07:39:08 kernel: Features2=0xccd82203 <sse3,pclmulqdq,ssse3,cx16,sse4.1,sse4.2,movbe,popcnt,xsave,osxsave,rdrand,hv>Oct 16 07:39:08 kernel: AMD Features=0x20100800 <syscall,nx,lm>Oct 16 07:39:08 kernel: AMD Features2=0x21 <lahf,abm>Oct 16 07:39:08 kernel: Structured Extended Features=0x2200 <erms>Oct 16 07:39:08 kernel: real memory = 671088640 (640 MB)
                          Oct 16 07:39:08 kernel: avail memory = 608342016 (580 MB)
                          Oct 16 07:39:08 kernel: Event timer "LAPIC" quality 400
                          Oct 16 07:39:08 kernel: ACPI APIC Table: <vrtual microsft="">Oct 16 07:39:08 kernel: FreeBSD/SMP: Multiprocessor System Detected: 2 CPUs
                          Oct 16 07:39:08 kernel: FreeBSD/SMP: 1 package(s) x 2 core(s)
                          Oct 16 07:39:08 kernel: cpu0 (BSP): APIC ID: 0
                          Oct 16 07:39:08 kernel: cpu1 (AP): APIC ID: 1
                          Oct 16 07:39:08 kernel: ioapic0: Changing APIC ID to 0
                          Oct 16 07:39:08 kernel: ioapic0 <version 1.1="">irqs 0-23 on motherboard
                          Oct 16 07:39:08 kernel: wlan: mac acl policy registered
                          Oct 16 07:39:08 kernel: ipw_bss: You need to read the LICENSE file in /usr/share/doc/legal/intel_ipw/.
                          Oct 16 07:39:08 kernel: ipw_bss: If you agree with the license, set legal.intel_ipw.license_ack=1 in /boot/loader.conf.
                          Oct 16 07:39:08 kernel: module_register_init: MOD_LOAD (ipw_bss_fw, 0xffffffff805f91d0, 0) error 1
                          Oct 16 07:39:08 kernel: ipw_ibss: You need to read the LICENSE file in /usr/share/doc/legal/intel_ipw/.
                          Oct 16 07:39:08 kernel: ipw_ibss: If you agree with the license, set legal.intel_ipw.license_ack=1 in /boot/loader.conf.
                          Oct 16 07:39:08 kernel: module_register_init: MOD_LOAD (ipw_ibss_fw, 0xffffffff805f9280, 0) error 1
                          Oct 16 07:39:08 kernel: ipw_monitor: You need to read the LICENSE file in /usr/share/doc/legal/intel_ipw/.
                          Oct 16 07:39:08 kernel: ipw_monitor: If you agree with the license, set legal.intel_ipw.license_ack=1 in /boot/loader.conf.
                          Oct 16 07:39:08 kernel: module_register_init: MOD_LOAD (ipw_monitor_fw, 0xffffffff805f9330, 0) error 1
                          Oct 16 07:39:08 kernel: iwi_bss: You need to read the LICENSE file in /usr/share/doc/legal/intel_iwi/.
                          Oct 16 07:39:08 kernel: iwi_bss: If you agree with the license, set legal.intel_iwi.license_ack=1 in /boot/loader.conf.
                          Oct 16 07:39:08 kernel: module_register_init: MOD_LOAD (iwi_bss_fw, 0xffffffff8061f510, 0) error 1
                          Oct 16 07:39:08 kernel: iwi_ibss: You need to read the LICENSE file in /usr/share/doc/legal/intel_iwi/.
                          Oct 16 07:39:08 kernel: iwi_ibss: If you agree with the license, set legal.intel_iwi.license_ack=1 in /boot/loader.conf.
                          Oct 16 07:39:08 kernel: module_register_init: MOD_LOAD (iwi_ibss_fw, 0xffffffff8061f5c0, 0) error 1
                          Oct 16 07:39:08 kernel: iwi_monitor: You need to read the LICENSE file in /usr/share/doc/legal/intel_iwi/.
                          Oct 16 07:39:08 kernel: iwi_monitor: If you agree with the license, set legal.intel_iwi.license_ack=1 in /boot/loader.conf.
                          Oct 16 07:39:08 kernel: module_register_init: MOD_LOAD (iwi_monitor_fw, 0xffffffff8061f670, 0) error 1
                          Oct 16 07:39:08 kernel: random: <software, yarrow="">initialized
                          Oct 16 07:39:08 kernel: kbd1 at kbdmux0
                          Oct 16 07:39:08 kernel: vmbus0: <vmbus devices="">on motherboard
                          Oct 16 07:39:08 kernel: cryptosoft0: <software crypto="">on motherboard
                          Oct 16 07:39:08 kernel: padlock0: No ACE support.
                          Oct 16 07:39:08 kernel: acpi0: <vrtual microsft="">on motherboard
                          Oct 16 07:39:08 kernel: acpi0: Power Button (fixed)
                          Oct 16 07:39:08 kernel: acpi0: reservation of 0, a0000 (3) failed
                          Oct 16 07:39:08 kernel: acpi0: reservation of 100000, f7f00000 (3) failed
                          Oct 16 07:39:08 kernel: cpu0: <acpi cpu="">on acpi0
                          Oct 16 07:39:08 kernel: cpu1: <acpi cpu="">on acpi0
                          Oct 16 07:39:08 kernel: attimer0: <at timer="">port 0x40-0x43 irq 0 on acpi0
                          Oct 16 07:39:08 kernel: Timecounter "i8254" frequency 1193182 Hz quality 0
                          Oct 16 07:39:08 kernel: Event timer "i8254" frequency 1193182 Hz quality 100
                          Oct 16 07:39:08 kernel: atrtc0: <at realtime="" clock="">port 0x70-0x71 irq 8 on acpi0
                          Oct 16 07:39:08 kernel: Event timer "RTC" frequency 32768 Hz quality 0
                          Oct 16 07:39:08 kernel: Timecounter "ACPI-fast" frequency 3579545 Hz quality 900
                          Oct 16 07:39:08 kernel: acpi_timer0: <32-bit timer at 3.579545MHz> port 0x408-0x40b on acpi0
                          Oct 16 07:39:08 kernel: pcib0: <acpi host-pci="" bridge="">port 0xcf8-0xcff on acpi0
                          Oct 16 07:39:08 kernel: pci0: <acpi pci="" bus="">on pcib0
                          Oct 16 07:39:08 kernel: isab0: <pci-isa bridge="">at device 7.0 on pci0
                          Oct 16 07:39:08 kernel: isa0: <isa bus="">on isab0
                          Oct 16 07:39:08 kernel: atapci0: <intel piix4="" udma33="" controller="">port 0x1f0-0x1f7,0x3f6,0x170-0x177,0x376,0xffa0-0xffaf at device 7.1 on pci0
                          Oct 16 07:39:08 kernel: ata0: <hyper-v ata="" storage="" disengage="" driver="">at channel 0 on atapci0
                          Oct 16 07:39:08 kernel: ata1: <ata channel="">at channel 1 on atapci0
                          Oct 16 07:39:08 kernel: pci0: <bridge>at device 7.3 (no driver attached)
                          Oct 16 07:39:08 kernel: vgapci0: <vga-compatible display="">mem 0xf8000000-0xfbffffff irq 11 at device 8.0 on pci0
                          Oct 16 07:39:08 kernel: vgapci0: Boot video device
                          Oct 16 07:39:08 kernel: atkbdc0: <keyboard controller="" (i8042)="">port 0x60,0x64 irq 1 on acpi0
                          Oct 16 07:39:08 kernel: atkbd0: <at keyboard="">irq 1 on atkbdc0
                          Oct 16 07:39:08 kernel: kbd0 at atkbd0
                          Oct 16 07:39:08 kernel: atkbd0: [GIANT-LOCKED]
                          Oct 16 07:39:08 kernel: psm0: <ps 2="" mouse="">irq 12 on atkbdc0
                          Oct 16 07:39:08 kernel: psm0: [GIANT-LOCKED]
                          Oct 16 07:39:08 kernel: psm0: model IntelliMouse Explorer, device ID 4
                          Oct 16 07:39:08 kernel: uart0: <16550 or compatible> port 0x3f8-0x3ff irq 4 flags 0x10 on acpi0
                          Oct 16 07:39:08 kernel: uart1: <16550 or compatible> port 0x2f8-0x2ff irq 3 on acpi0
                          Oct 16 07:39:08 kernel: fdc0: <floppy drive="" controller="" (fde)="">port 0x3f0-0x3f5,0x3f7 irq 6 drq 2 on acpi0
                          Oct 16 07:39:08 kernel: fd0: <1440-KB 3.5" drive> on fdc0 drive 0
                          Oct 16 07:39:08 kernel: orm0: <isa option="" rom="">at iomem 0xc0000-0xcbfff on isa0
                          Oct 16 07:39:08 kernel: sc0: <system console="">at flags 0x100 on isa0
                          Oct 16 07:39:08 kernel: sc0: VGA <16 virtual consoles, flags=0x300>
                          Oct 16 07:39:08 kernel: vga0: <generic isa="" vga="">at port 0x3c0-0x3df iomem 0xa0000-0xbffff on isa0
                          Oct 16 07:39:08 kernel: ppc0: cannot reserve I/O port range
                          Oct 16 07:39:08 kernel: Timecounter "Hyper-V" frequency 10000000 Hz quality 10000000
                          Oct 16 07:39:08 kernel: Timecounters tick every 10.000 msec
                          Oct 16 07:39:08 kernel: IPsec: Initialized Security Association Processing.
                          Oct 16 07:39:08 kernel: storvsc0 on vmbus0
                          Oct 16 07:39:08 kernel: hyperv-utils0 on vmbus0
                          Oct 16 07:39:08 kernel: hyperv-utils0: Hyper-V Service attaching: Hyper-V Heartbeat Service
                          Oct 16 07:39:08 kernel:
                          Oct 16 07:39:08 kernel: hyperv-utils1 on vmbus0
                          Oct 16 07:39:08 kernel: hyperv-utils1: Hyper-V Service attaching: Hyper-V KVP Service
                          Oct 16 07:39:08 kernel:
                          Oct 16 07:39:08 kernel: hyperv-utils2 on vmbus0
                          Oct 16 07:39:08 kernel: hyperv-utils2: Hyper-V Service attaching: Hyper-V Shutdown Service
                          Oct 16 07:39:08 kernel:
                          Oct 16 07:39:08 kernel: hyperv-utils3 on vmbus0
                          Oct 16 07:39:08 kernel: hyperv-utils3: Hyper-V Service attaching: Hyper-V Time Synch Service
                          Oct 16 07:39:08 kernel:
                          Oct 16 07:39:08 kernel: hn0: <synthetic network="" interface="">on vmbus0
                          Oct 16 07:39:08 kernel: hn1: <synthetic network="" interface="">on vmbus0
                          Oct 16 07:39:08 kernel: cam_periph_alloc: attempt to re-allocate valid device pass0 rejected flags 0 refcount 2
                          Oct 16 07:39:08 kernel: passasync: Unable to attach new device due to status 0x6: CCB request was invalid
                          Oct 16 07:39:08 kernel: cam_periph_alloc: attempt to re-allocate valid device da0 rejected flags 0x2 refcount 3
                          Oct 16 07:39:08 kernel: daasync: Unable to attach to new device due to status 0x6
                          Oct 16 07:39:08 kernel: da0 at blkvsc0 bus 0 scbus1 target 0 lun 0
                          Oct 16 07:39:08 kernel: da0: <msft virtual="" disk="" 1.0="">Fixed Direct Access SCSI-4 device
                          Oct 16 07:39:08 kernel: da0: 300.000MB/s transfers
                          Oct 16 07:39:08 kernel: da0: Command Queueing enabled
                          Oct 16 07:39:08 kernel: da0: 1024MB (2097152 512 byte sectors: 64H 32S/T 1024C)
                          Oct 16 07:39:08 kernel: hn2: <synthetic network="" interface="">on vmbus0
                          Oct 16 07:39:08 kernel: random: unblocking device.
                          Oct 16 07:39:08 kernel: SMP: AP CPU #1 Launched!
                          Oct 16 07:39:08 kernel: Trying to mount root from ufs:/dev/ufs/pfsense0 [ro,sync,noatime]…
                          Oct 16 07:39:08 kernel:
                          Oct 16 07:39:09 php: rc.bootup: Starting 3gstats.php on device '' for interface 'wan'
                          Oct 16 07:39:09 kernel:
                          Oct 16 07:39:09 php: rc.bootup: Starting 3gstats.php on device '' for interface 'opt1'
                          Oct 16 07:39:09 php: rc.bootup: Resyncing OpenVPN instances.
                          Oct 16 07:39:09 kernel: done.
                          Oct 16 07:39:09 kernel: pflog0: promiscuous mode enabled
                          Oct 16 07:39:09 php-fpm[287]: /rc.newwanip: ROUTING: setting default route to 222.92.225.13
                          Oct 16 07:39:09 php: rc.bootup: Could not find IPv4 gateway for interface (opt1).
                          Oct 16 07:39:09 kernel: ..
                          Oct 16 07:39:10 php-fpm[287]: /rc.newwanip: RRD create failed exited with 1, the error is: ERROR: creating '/var/db/rrd/WAN_PPPOE-quality.rrd': No such file or directory
                          Oct 16 07:39:10 kernel: .done.
                          Oct 16 07:39:11 php-fpm[286]: /rc.newwanip: Removing static route for monitor 221.224.226.101 and adding a new route through 222.92.225.13
                          Oct 16 07:39:12 kernel: done.
                          Oct 16 07:39:12 kernel: done.
                          Oct 16 07:39:13 php: rc.bootup: ROUTING: setting default route to 222.92.225.13
                          Oct 16 07:39:13 kernel: done.
                          Oct 16 07:39:13 check_reload_status: Updating all dyndns
                          Oct 16 07:39:13 kernel: ….
                          Oct 16 07:39:13 kernel: .done.
                          Oct 16 07:39:14 php-fpm[285]: /rc.dyndns.update: Gateways status could not be determined, considering all as up/active. (Group: WAN_group)
                          Oct 16 07:39:18 php-fpm[286]: /rc.newwanip: phpDynDNS: updating cache file /conf/dyndns_opt1noip-free'pftest.ddns.net'1.cache: 49.75.179.6
                          Oct 16 07:39:18 php-fpm[286]: /rc.newwanip: phpDynDNS (pftest.ddns.net): (Success) DNS hostname update successful.
                          Oct 16 07:39:18 php-fpm[287]: /rc.newwanip: phpDynDNS: updating cache file /conf/dyndns_wannoip-free'.no-ip.org'0.cache: 121.236.67.137
                          Oct 16 07:39:18 php-fpm[287]: /rc.newwanip: phpDynDNS (                          .no-ip.org): (Success) DNS hostname update successful.
                          Oct 16 07:39:18 php-fpm[285]: /rc.dyndns.update: phpDynDNS (*.no-ip.org): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry.
                          Oct 16 07:39:19 php-fpm[286]: /rc.newwanip: Resyncing OpenVPN instances for interface OPT1.
                          Oct 16 07:39:19 php-fpm[286]: /rc.newwanip: Creating rrd update script
                          Oct 16 07:39:19 php: rc.bootup: Creating rrd update script
                          Oct 16 07:39:19 kernel: done.
                          Oct 16 07:39:19 kernel: done.
                          Oct 16 07:39:19 php-fpm[285]: /rc.dyndns.update: phpDynDNS (pftest.ddns.net): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry.
                          Oct 16 07:39:20 php-fpm[287]: /rc.newwanip: phpDynDNS: updating cache file /conf/dyndns_wanhe-net'mydomain.net'2.cache: 121.236.67.137
                          Oct 16 07:39:20 php-fpm[287]: /rc.newwanip: phpDynDNS: (Success) IP Address Updated Successfully!
                          Oct 16 07:39:20 php-fpm[285]: /rc.dyndns.update: phpDynDNS (mydomain.net): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry.
                          Oct 16 07:39:21 php-fpm[286]: /rc.newwanip: pfSense package system has detected an ip change 0.0.0.0 -> 49.75.179.6 … Restarting packages.
                          Oct 16 07:39:21 check_reload_status: Starting packages
                          Oct 16 07:39:21 check_reload_status: Reloading filter
                          Oct 16 07:39:21 php-fpm[286]: /rc.start_packages: Restarting/Starting all packages.
                          Oct 16 07:39:21 php-fpm[287]: /rc.newwanip: Resyncing OpenVPN instances for interface WAN.
                          Oct 16 07:39:21 php-fpm[287]: /rc.newwanip: Creating rrd update script
                          Oct 16 07:39:22 php-fpm[285]: /rc.start_packages: Restarting/Starting all packages.
                          Oct 16 07:39:22 php-fpm[286]: /rc.filter_configure_sync: MONITOR: OPT1_PPPOE is down, omitting from routing group WAN_group
                          Oct 16 07:39:22 login: login on ttyv0 as root
                          Oct 16 07:39:22 sshlockout[94036]: sshlockout/webConfigurator v3.0 starting up
                          Oct 16 07:39:23 php-fpm[287]: /rc.newwanip: pfSense package system has detected an ip change 0.0.0.0 -> 121.236.67.137 … Restarting packages.
                          Oct 16 07:39:23 check_reload_status: Starting packages
                          Oct 16 07:39:23 check_reload_status: Reloading filter
                          Oct 16 07:39:24 php-fpm[285]: /rc.start_packages: Restarting/Starting all packages.
                          Oct 16 07:39:24 php-fpm[287]: /rc.filter_configure_sync: MONITOR: OPT1_PPPOE is down, omitting from routing group WAN_group
                          Oct 16 07:39:31 check_reload_status: updating dyndns OPT1_PPPOE
                          Oct 16 07:39:31 check_reload_status: Restarting ipsec tunnels
                          Oct 16 07:39:31 check_reload_status: Restarting OpenVPN tunnels/interfaces
                          Oct 16 07:39:31 check_reload_status: Reloading filter
                          Oct 16 07:39:32 php-fpm[285]: /rc.dyndns.update: MONITOR: OPT1_PPPOE is down, omitting from routing group WAN_group
                          Oct 16 07:39:32 php-fpm[285]: /rc.dyndns.update: phpDynDNS (pftest.ddns.net): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry.
                          Oct 16 07:39:32 php-fpm[286]: /rc.filter_configure_sync: MONITOR: OPT1_PPPOE is down, omitting from routing group WAN_group
                          Oct 16 07:39:43 kernel: calcru: runtime went backwards from 608114 usec to 307592 usec for pid 287 (php-fpm)
                          Oct 16 07:39:43 kernel: calcru: runtime went backwards from 150095 usec to 75913 usec for pid 287 (php-fpm)
                          Oct 16 07:39:50 kernel: calcru: runtime went backwards from 489910 usec to 248472 usec for pid 285 (php-fpm)
                          Oct 16 07:39:50 kernel: calcru: runtime went backwards from 125135 usec to 63289 usec for pid 285 (php-fpm)
                          Oct 16 07:39:50 php-fpm[285]: /index.php: Successful login for user 'admin' from: 49.66.153.135
                          Oct 16 07:39:50 php-fpm[285]: /index.php: Successful login for user 'admin' from: 49.66.153.135
                          Oct 16 07:39:51 kernel: calcru: runtime went backwards from 1062 usec to 537 usec for pid 98284 (sleep)
                          Oct 16 07:39:51 kernel: calcru: runtime went backwards from 9024 usec to 4564 usec for pid 94407 (sh)
                          Oct 16 07:39:51 kernel: calcru: runtime went backwards from 297307 usec to 150368 usec for pid 94407 (sh)
                          Oct 16 07:39:51 kernel: calcru: runtime went backwards from 7867 usec to 3979 usec for pid 94110 (sh)
                          Oct 16 07:39:51 kernel: calcru: runtime went backwards from 6187 usec to 3161 usec for pid 94036 (sshlockout_pf)
                          Oct 16 07:39:51 kernel: calcru: runtime went backwards from 4698 usec to 2376 usec for pid 93724 (getty)
                          Oct 16 07:39:51 kernel: calcru: runtime went backwards from 15621 usec to 7900 usec for pid 93432 (login)
                          Oct 16 07:39:51 kernel: calcru: runtime went backwards from 30281 usec to 15315 usec for pid 77275 (sh)
                          Oct 16 07:39:51 kernel: calcru: runtime went backwards from 349174 usec to 176601 usec for pid 77275 (sh)
                          Oct 16 07:39:51 kernel: calcru: runtime went backwards from 452 usec to 228 usec for pid 75095 (minicron)
                          Oct 16 07:39:51 kernel: calcru: runtime went backwards from 407 usec to 206 usec for pid 74520 (minicron)
                          Oct 16 07:39:51 kernel: calcru: runtime went backwards from 839 usec to 424 usec for pid 73947 (minicron)
                          Oct 16 07:39:51 kernel: calcru: runtime went backwards from 922 usec to 466 usec for pid 73757 (minicron)
                          Oct 16 07:39:51 kernel: calcru: runtime went backwards from 4372 usec to 2211 usec for pid 73527 (minicron)
                          Oct 16 07:39:51 kernel: calcru: runtime went backwards from 898 usec to 454 usec for pid 73242 (minicron)
                          Oct 16 07:39:51 kernel: calcru: runtime went backwards from 4355 usec to 2202 usec for pid 68923 (sleep)
                          Oct 16 07:39:51 kernel: calcru: runtime went backwards from 1404 usec to 710 usec for pid 66459 (cron)
                          Oct 16 07:39:51 kernel: calcru: runtime went backwards from 17355 usec to 9541 usec for pid 33502 (dnsmasq)
                          Oct 16 07:39:51 kernel: calcru: runtime went backwards from 4046 usec to 2046 usec for pid 21550 (rrdtool)
                          Oct 16 07:39:51 kernel: calcru: runtime went backwards from 29890 usec to 23681 usec for pid 21426 (apinger)
                          Oct 16 07:39:51 kernel: calcru: runtime went backwards from 7902 usec to 3996 usec for pid 21426 (apinger)
                          Oct 16 07:39:51 kernel: calcru: runtime went backwards from 24064 usec to 15579 usec for pid 18154 (inetd)
                          Oct 16 07:39:51 kernel: calcru: runtime went backwards from 15246 usec to 8983 usec for pid 12639 (mpd5)
                          Oct 16 07:39:51 kernel: calcru: runtime went backwards from 20926 usec to 10584 usec for pid 12639 (mpd5)
                          Oct 16 07:39:51 kernel: calcru: runtime went backwards from 26683 usec to 13925 usec for pid 6870 (mpd5)
                          Oct 16 07:39:51 kernel: calcru: runtime went backwards from 49749 usec to 25161 usec for pid 6870 (mpd5)
                          Oct 16 07:39:51 kernel: calcru: runtime went backwards from 93771 usec to 66424 usec for pid 6120 (syslogd)
                          Oct 16 07:39:51 kernel: calcru: runtime went backwards from 1338 usec to 676 usec for pid 316 (devd)
                          Oct 16 07:39:51 kernel: calcru: runtime went backwards from 571 usec to 288 usec for pid 303 (check_reload_status)
                          Oct 16 07:39:51 kernel: calcru: runtime went backwards from 46730359 usec to 32501677 usec for pid 301 (check_reload_status)
                          Oct 16 07:39:51 kernel: calcru: runtime went backwards from 856949 usec to 434408 usec for pid 286 (php-fpm)
                          Oct 16 07:39:51 kernel: calcru: runtime went backwards from 506500 usec to 256171 usec for pid 286 (php-fpm)
                          Oct 16 07:39:51 kernel: calcru: runtime went backwards from 14522 usec to 8220 usec for pid 284 (php-fpm)
                          Oct 16 07:39:51 kernel: calcru: runtime went backwards from 148474 usec to 86208 usec for pid 52 (md1)
                          Oct 16 07:39:51 kernel: calcru: runtime went backwards from 14476 usec to 9870 usec for pid 47 (md0)
                          Oct 16 07:39:51 kernel: calcru: runtime went backwards from 1943 usec to 1801 usec for pid 8 (pagedaemon)
                          Oct 16 07:39:51 kernel: calcru: runtime went backwards from 99 usec to 50 usec for pid 7 (sctp_iterator)
                          Oct 16 07:39:51 kernel: calcru: runtime went backwards from 3479 usec to 1903 usec for pid 5 (fdc0)
                          Oct 16 07:39:51 kernel: calcru: runtime went backwards from 166411 usec to 105834 usec for pid 4 (cam)
                          Oct 16 07:39:51 kernel: calcru: runtime went backwards from 22521 usec to 21383 usec for pid 15 (rand_harvestq)
                          Oct 16 07:39:51 kernel: calcru: runtime went backwards from 7681 usec to 4005 usec for pid 13 (ng_queue)
                          Oct 16 07:39:51 kernel: calcru: runtime went backwards from 519456 usec to 479952 usec for pid 12 (intr)
                          Oct 16 07:39:51 kernel: calcru: runtime went backwards from 8784 usec to 4518 usec for pid 1 (init)
                          Oct 16 07:39:51 kernel: calcru: runtime went backwards from 8919513 usec to 4536056 usec for pid 1 (init)
                          Oct 16 07:39:51 kernel: calcru: runtime went backwards from 7915 usec to 4200 usec for pid 0 (kernel)
                          Oct 16 07:40:17 login: login on ttyv0 as root
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 7088 usec to 4562 usec for pid 94407 (sh)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 7867 usec to 3977 usec for pid 94110 (sh)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 56 usec to 28 usec for pid 94036 (sshlockout_pf)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 6130 usec to 3130 usec for pid 94036 (sshlockout_pf)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 4698 usec to 2375 usec for pid 93724 (getty)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 15621 usec to 7896 usec for pid 93432 (login)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 28981 usec to 25263 usec for pid 77275 (sh)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 452 usec to 228 usec for pid 75095 (minicron)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 407 usec to 206 usec for pid 74520 (minicron)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 839 usec to 424 usec for pid 73947 (minicron)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 922 usec to 466 usec for pid 73757 (minicron)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 4372 usec to 2210 usec for pid 73527 (minicron)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 898 usec to 454 usec for pid 73242 (minicron)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 1404 usec to 810 usec for pid 66459 (cron)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 16821 usec to 11749 usec for pid 33502 (dnsmasq)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 4046 usec to 2725 usec for pid 21550 (rrdtool)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 22569 usec to 15571 usec for pid 18154 (inetd)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 12125 usec to 8110 usec for pid 12639 (mpd5)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 22241 usec to 12114 usec for pid 6870 (mpd5)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 1338 usec to 709 usec for pid 316 (devd)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 571 usec to 288 usec for pid 303 (check_reload_status)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 543802 usec to 505178 usec for pid 286 (php-fpm)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 13958 usec to 9200 usec for pid 284 (php-fpm)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 144237 usec to 87653 usec for pid 52 (md1)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 101 usec to 51 usec for pid 7 (sctp_iterator)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 6181 usec to 3486 usec for pid 5 (fdc0)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 410 usec to 207 usec for pid 4 (cam)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 166075 usec to 114546 usec for pid 4 (cam)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 6040 usec to 3053 usec for pid 14 (geom)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 2361 usec to 1193 usec for pid 14 (geom)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 7288 usec to 3842 usec for pid 13 (ng_queue)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 724 usec to 366 usec for pid 12 (intr)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 147 usec to 74 usec for pid 12 (intr)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 8293 usec to 4572 usec for pid 1 (init)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 1087 usec to 779 usec for pid 0 (kernel)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 1231 usec to 622 usec for pid 0 (kernel)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 2227 usec to 1125 usec for pid 0 (kernel)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 2561 usec to 1295 usec for pid 0 (kernel)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 507 usec to 256 usec for pid 0 (kernel)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 518 usec to 261 usec for pid 0 (kernel)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 891 usec to 450 usec for pid 0 (kernel)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 875 usec to 442 usec for pid 0 (kernel)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 840 usec to 425 usec for pid 0 (kernel)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 579 usec to 292 usec for pid 0 (kernel)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 329 usec to 166 usec for pid 0 (kernel)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 331 usec to 167 usec for pid 0 (kernel)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 416 usec to 210 usec for pid 0 (kernel)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 334 usec to 168 usec for pid 0 (kernel)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 343 usec to 173 usec for pid 0 (kernel)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 1128 usec to 570 usec for pid 0 (kernel)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 8 usec to 4 usec for pid 0 (kernel)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 349 usec to 176 usec for pid 0 (kernel)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 902 usec to 509 usec for pid 0 (kernel)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 153 usec to 77 usec for pid 0 (kernel)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 7 usec to 3 usec for pid 0 (kernel)
                          Oct 16 07:40:17 kernel: calcru: runtime went backwards from 520335849 usec to 263037646 usec for pid 0 (kernel)</synthetic></msft></synthetic></synthetic></generic></system></isa></floppy></ps></at></keyboard></vga-compatible></bridge></ata></hyper-v></intel></isa></pci-isa></acpi></acpi></at></at></acpi></acpi></vrtual></software></vmbus></software,></version></vrtual></erms></lahf,abm></syscall,nx,lm></sse3,pclmulqdq,ssse3,cx16,sse4.1,sse4.2,movbe,popcnt,xsave,osxsave,rdrand,hv></fpu,vme,de,pse,tsc,msr,pae,mce,cx8,apic,sep,mtrr,pge,mca,cmov,pat,pse36,mmx,fxsr,sse,sse2,ss,htt>

                          1 Reply Last reply Reply Quote 0
                          • E
                            eri--
                            last edited by

                            You really need to have a fixed time.
                            Otherwise you will get wierd results from apinger.

                            1 Reply Last reply Reply Quote 0
                            • M
                              maverick_slo
                              last edited by

                              Disable hyper-v time sync you really don`t need it…

                              1 Reply Last reply Reply Quote 0
                              • A
                                applerule
                                last edited by

                                Figured I'd chime back in with an update.  Still on Monday Oct 06 snapshot, and no weird issues with apinger.  I have had a legitmate outage during this time and everything has recovered as expected.  I am not sure if ermal's modifications or me disabling hyper-v time sync fixed it.  It could be a combination of both.  Either way ermal pointed me in the right direction and all still appears good on my end.  I suggest anyone else with the problem to disable hyper-v time sync and configure ntp and see if that resolves your issue.  :)

                                1 Reply Last reply Reply Quote 0
                                • S
                                  Supermule Banned
                                  last edited by

                                  I havent had the issue since I initiated time sync via Vsphere client on the hosts.

                                  Oct 17 19:59:33 apinger: SIGHUP received, reloading configuration.
                                  Oct 17 19:59:32 apinger: Starting Alarm Pinger, apinger(21363)
                                  Oct 17 18:56:57 apinger: alarm canceled: WAN_DHCP(62.243.131.197) *** delay ***
                                  Oct 17 18:56:49 apinger: ALARM: WAN_DHCP(62.243.131.197) *** delay ***

                                  1 Reply Last reply Reply Quote 0
                                  • N
                                    naras
                                    last edited by

                                    Hyper-v time sync disabled, kern.timecounter.hardware set to ACPI-fast, now it's all good.

                                    Thanks to all of you.

                                    1 Reply Last reply Reply Quote 0
                                    • F
                                      firewalluser
                                      last edited by

                                      On the point of some people have experienced this but not commented, I'd just say having skimmed through the thread, symptoms seem consistent with what I have seen so will try out some of the suggestions to see where it gets me.

                                      I havent seen it on a vm of 2.1.4 but have seen it on real hw using the amd64 2.1.4 release though, so yes quite difficult to replicate.

                                      Capitalism, currently The World's best Entertainment Control System and YOU cant buy it! But you can buy this, or some of this or some of these

                                      Asch Conformity, mainly the blind leading the blind.

                                      1 Reply Last reply Reply Quote 0
                                      • N
                                        naras
                                        last edited by

                                        @naras:

                                        Hyper-v time sync disabled, kern.timecounter.hardware set to ACPI-fast, now it's all good.

                                        Thanks to all of you.

                                        This worked once, I just can't get my timing correct, OPT1 is always offline after a upgrade or reboot.

                                        I've tried almost all snapshots and all combinations of timecounter, ntpd never worked with TSC, shows "unreach/pending" for all time servers in the ntp status page, ntpd works with the timecounter i8254, but pfsense 2.2 get frozen after a period of time, and ntpd works great with Hyper-V and ACPI-fast counters, but OPT1 is always offline after upgrade or reboot.

                                        Hyper-v time syc disabled already, and two pppoe line are from same ISP.

                                        Please help me out, thanks.

                                        Maybe I was just too hasty to see good results, didn't give Apinger enough time to recover. I waited for enough time after upgraded to latest snapshot, and did see OPT1 online.

                                        1 Reply Last reply Reply Quote 0
                                        • T
                                          thiagoc
                                          last edited by

                                          I can reproduce the problem with one interface using a external monitor IP (I've used OpenDNS) with RTT > 150ms and the other using the gateway as monitor IP (RTT < 2ms).

                                          2.1.5-RELEASE (amd64)

                                          EDIT: actually the problem occurs also with the other external monitor IP. How can I enable the debug on apinger? Is there a way to use the new version of apinger on 2.1.5?

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

                                            You'll need to go to 2.2 if you want to try out the new apinger. That's pretty low-risk at this point, outside of some packages that need some work still.

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