An earnest appeal - please do fix APINGER in 2.2
-
@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.