An earnest appeal - please do fix APINGER in 2.2
-
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.
-
put apinger in debug mode and give me the logs.
-
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. -
@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> -
You really need to have a fixed time.
Otherwise you will get wierd results from apinger. -
Disable hyper-v time sync you really don`t need it…
-
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. :)
-
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 *** -
Hyper-v time sync disabled, kern.timecounter.hardware set to ACPI-fast, now it's all good.
Thanks to all of you.
-
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.
-
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.
-
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?
-
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.
-
locking this thread since it keeps getting hijacked, the original issues have been confirmed resolved, new ones need their own threads so we can follow up appropriately.
