WAN link going down

TieT

Hello,

After my upgrade to 2.2 i'm experiencing my WAN link going down from time to time.
I can see this in the system log:

Feb 3 14:13:48 	kernel: ovpns1: link state changed to DOWN
Feb 3 14:13:48 	php-fpm[84313]: /rc.openvpn: OpenVPN: Resync server1 OpenVPN Server
Feb 3 14:13:48 	php-fpm[84313]: /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use WAN_DHCP.
Feb 3 14:13:48 	php-fpm[44636]: /rc.dyndns.update: DynDNS (*****) There was an error trying to determine the public IP for interface - wan(sk0). Probably interface is not a WAN interface.
Feb 3 14:13:47 	check_reload_status: Reloading filter
Feb 3 14:13:47 	check_reload_status: Restarting OpenVPN tunnels/interfaces
Feb 3 14:13:47 	check_reload_status: Restarting ipsec tunnels
Feb 3 14:13:47 	check_reload_status: updating dyndns WAN_DHCP
Feb 3 14:13:46 	kernel: arpresolve: can't allocate llinfo for 84.192.192.1 on sk0
Feb 3 14:13:42 	kernel: arpresolve: can't allocate llinfo for 84.192.192.1 on sk0
Feb 3 14:13:42 	kernel: arpresolve: can't allocate llinfo for 84.192.192.1 on sk0
Feb 3 14:13:42 	kernel: arpresolve: can't allocate llinfo for 84.192.192.1 on sk0
Feb 3 14:13:42 	kernel: arpresolve: can't allocate llinfo for 84.192.192.1 on sk0
Feb 3 14:13:40 	kernel: arpresolve: can't allocate llinfo for 84.192.192.1 on sk0
Feb 3 14:13:39 	kernel: arpresolve: can't allocate llinfo for 84.192.192.1 on sk0
Feb 3 14:13:38 	kernel: arpresolve: can't allocate llinfo for 84.192.192.1 on sk0
Feb 3 14:13:38 	kernel: arpresolve: can't allocate llinfo for 84.192.192.1 on sk0
Feb 3 14:13:38 	kernel: arpresolve: can't allocate llinfo for 84.192.192.1 on sk0
Feb 3 14:13:37 	kernel: arpresolve: can't allocate llinfo for 84.192.192.1 on sk0
Feb 3 14:13:35 	kernel: arpresolve: can't allocate llinfo for 84.192.192.1 on sk0
Feb 3 14:13:34 	kernel: arpresolve: can't allocate llinfo for 84.192.192.1 on sk0
Feb 3 14:13:33 	kernel: arpresolve: can't allocate llinfo for 84.192.192.1 on sk0
Feb 3 14:13:33 	kernel: arpresolve: can't allocate llinfo for 84.192.192.1 on sk0
Feb 3 14:13:33 	kernel: arpresolve: can't allocate llinfo for 84.192.192.1 on sk0
Feb 3 14:13:28 	php-fpm[16093]: /rc.linkup: DEVD Ethernet detached event for wan
Feb 3 14:13:27 	kernel: sk0: link state changed to DOWN
Feb 3 14:13:27 	check_reload_status: Linkup starting sk0

Feb 3 14:13:58 	kernel: arpresolve: can't allocate llinfo for 84.192.192.1 on sk0
Feb 3 14:13:58 	kernel: arpresolve: can't allocate llinfo for 84.192.192.1 on sk0
Feb 3 14:13:56 	LCDd: Connect from host 127.0.0.1:23439 on socket 12
Feb 3 14:13:56 	kernel: arpresolve: can't allocate llinfo for 84.192.192.1 on sk0
Feb 3 14:13:55 	php: lcdproc: Start client procedure. Error counter: (0)
Feb 3 14:13:55 	LCDd: Listening for queries on 127.0.0.1:13666
Feb 3 14:13:55 	LCDd: Using Configuration File: /usr/local/etc/LCDd.conf
Feb 3 14:13:55 	LCDd: LCDd version 0.5.6 starting
Feb 3 14:13:54 	LCDd: Server shutting down on SIGTERM
Feb 3 14:13:53 	kernel: arpresolve: can't allocate llinfo for 84.192.192.1 on sk0
Feb 3 14:13:53 	check_reload_status: Syncing firewall
Feb 3 14:13:53 	check_reload_status: Syncing firewall
Feb 3 14:13:53 	LCDd: sock_send: socket write error
Feb 3 14:13:53 	LCDd: sock_send: socket write error
Feb 3 14:13:53 	LCDd: sock_send: socket write error
Feb 3 14:13:53 	LCDd: sock_send: socket write error
Feb 3 14:13:53 	LCDd: sock_send: socket write error
Feb 3 14:13:53 	LCDd: sock_send: socket write error
Feb 3 14:13:53 	LCDd: sock_send: socket write error
Feb 3 14:13:53 	LCDd: Client on socket 12 disconnected
Feb 3 14:13:52 	php-fpm[44636]: /rc.filter_configure_sync: Could not find IPv6 gateway for interface (wan).
Feb 3 14:13:52 	php-fpm[44636]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan).
Feb 3 14:13:52 	php-fpm[44636]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan).
Feb 3 14:13:52 	php-fpm[44636]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan).
Feb 3 14:13:52 	kernel: arpresolve: can't allocate llinfo for 84.192.192.1 on sk0
Feb 3 14:13:52 	php-fpm[90562]: /rc.start_packages: Reloading Squid for configuration sync
Feb 3 14:13:51 	php-fpm[90562]: /rc.start_packages: Restarting/Starting all packages.
Feb 3 14:13:50 	check_reload_status: Starting packages
Feb 3 14:13:50 	php-fpm[90562]: /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - -> 192.168.10.1 - Restarting packages.
Feb 3 14:13:50 	check_reload_status: Reloading filter
Feb 3 14:13:50 	php-fpm[90562]: /rc.newwanip: rc.newwanip: on (IP address: 192.168.10.1) (interface: []) (real interface: ovpns1).
Feb 3 14:13:50 	php-fpm[90562]: /rc.newwanip: rc.newwanip: Info: starting on ovpns1.
Feb 3 14:13:50 	php-fpm[84313]: /rc.filter_configure_sync: Could not find IPv6 gateway for interface (wan).
Feb 3 14:13:50 	php-fpm[84313]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan).
Feb 3 14:13:50 	php-fpm[84313]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan).
Feb 3 14:13:50 	php-fpm[84313]: /rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan).
Feb 3 14:13:49 	check_reload_status: rc.newwanip starting ovpns1
Feb 3 14:13:49 	kernel: ovpns1: link state changed to UP
Feb 3 14:13:48 	kernel: arpresolve: can't allocate llinfo for 84.192.192.1 on sk0
Feb 3 14:13:48 	check_reload_status: Reloading filter
Feb 3 14:13:48 	kernel: ovpns1: link state changed to DOWN

84.192.192.1 is the gateway for my WAN link, maybe the problem is apinger ?
Disabling the WAN link and enabling it back solves the problem, rebooting also solves the problem.

Can somebody maybe point me in the right direction ?

HW: Firebox x750e
BIOS: 8_1
Packages: Snort and squid, lightsquid / LcdProc

stephenw10

This:

kernel: sk0: link state changed to DOWN

Indicates that the link is actually going down not just being marked down by apinger. Are you using the modified sk(4) driver? There have been a number of reports of them not working well under various conditions. Are you seeing errors in the boot log like this?:
https://forum.pfsense.org/index.php?topic=20095.msg485091#msg485091

Steve

TieT

I'll check this when i get home, i also see inthe gateway logs that apinger couldn't get the gateway.
But that is probably cause and effect, if the link is down then the gateway can't be located.

Thank in advance steve !

TieT

Nope, i can't see any problems in the boot log.
I'm also not using the modified sk(4) drivers, it's just a default installation

Copyright (c) 1992-2014 The FreeBSD Project.
Copyright (c) 1979, 1980, 1983, 1986, 1988, 1989, 1991, 1992, 1993, 1994
        The Regents of the University of California. All rights reserved.
FreeBSD is a registered trademark of The FreeBSD Foundation.
FreeBSD 10.1-RELEASE-p4 #0 36d7dec(releng/10.1)-dirty: Thu Jan 22 15:12:38 CST 2015
    root@pfsense-22-i386-builder:/usr/obj.i386/usr/pfSensesrc/src/sys/pfSense_SMP.10 i386
FreeBSD clang version 3.4.1 (tags/RELEASE_34/dot1-final 208032) 20140512
CPU: Intel(R) Pentium(R) M processor 2.00GHz (2000.11-MHz 686-class CPU)
  Origin = "GenuineIntel"  Id = 0x6d8  Family = 0x6  Model = 0xd  Stepping = 8
  Features=0xafe9fbff <fpu,vme,de,pse,tsc,msr,pae,mce,cx8,apic,sep,mtrr,pge,mca,cmov,pat,clflush,dts,acpi,mmx,fxsr,sse,sse2,ss,tm,pbe>Features2=0x180 <est,tm2>AMD Features=0x100000 <nx>real memory  = 2139029504 (2039 MB)
avail memory = 2064244736 (1968 MB)
Event timer "LAPIC" quality 400
ACPI APIC Table: <intelr awrdacpi="">ioapic0 <version 2.0="">irqs 0-23 on motherboard
wlan: mac acl policy registered
kbd1 at kbdmux0
random: <software, yarrow="">initialized
cryptosoft0: <software crypto="">on motherboard
padlock0: No ACE support.
acpi0: <intelr awrdacpi="">on motherboard
acpi0: Power Button (fixed)
acpi0: reservation of a2, 1e (4) failed
acpi0: reservation of e0, 10 (4) failed
acpi0: reservation of 0, a0000 (3) failed
acpi0: reservation of 100000, 7f6f0000 (3) failed
cpu0: <acpi cpu="">on acpi0
attimer0: <at timer="">port 0x40-0x43 irq 0 on acpi0
Timecounter "i8254" frequency 1193182 Hz quality 0
Event timer "i8254" frequency 1193182 Hz quality 100
atrtc0: <at realtime="" clock="">port 0x70-0x73 irq 8 on acpi0
Event timer "RTC" frequency 32768 Hz quality 0
Timecounter "ACPI-fast" frequency 3579545 Hz quality 900
acpi_timer0: <24-bit timer at 3.579545MHz> port 0x408-0x40b on acpi0
acpi_button0: <power button="">on acpi0
pcib0: <acpi host-pci="" bridge="">port 0xcf8-0xcff on acpi0
pci0: <acpi pci="" bus="">on pcib0
vgapci0: <vga-compatible display="">port 0xea00-0xea07 mem 0xd0500000-0xd057ffff,0xc0000000-0xcfffffff,0xd0580000-0xd05bffff irq 16 at device 2.0 on pci0
agp0: <intel 82915gm="" (915gm="" gmch)="" svga="" controller="">on vgapci0
agp0: aperture size is 256M, detected 7932k stolen memory
vgapci0: Boot video device
pcib1: <acpi pci-pci="" bridge="">irq 16 at device 28.0 on pci0
pci1: <acpi pci="" bus="">on pcib1
mskc0: <marvell yukon="" 88e8053="" gigabit="" ethernet="">port 0x8000-0x80ff mem 0xd0020000-0xd0023fff irq 16 at device 0.0 on pci1
msk0: <marvell technology="" group="" ltd.="" yukon="" ec="" id="" 0xb6="" rev="" 0x02="">on mskc0
miibus0: <mii bus="">on msk0
e1000phy0: <marvell 88e1111="" gigabit="" phy="">PHY 0 on miibus0
e1000phy0:  none, 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, 1000baseT, 1000baseT-master, 1000baseT-FDX, 1000baseT-FDX-master, auto, auto-flow
pcib2: <acpi pci-pci="" bridge="">irq 17 at device 28.1 on pci0
pci2: <acpi pci="" bus="">on pcib2
mskc1: <marvell yukon="" 88e8053="" gigabit="" ethernet="">port 0x9000-0x90ff mem 0xd0120000-0xd0123fff irq 17 at device 0.0 on pci2
msk1: <marvell technology="" group="" ltd.="" yukon="" ec="" id="" 0xb6="" rev="" 0x02="">on mskc1
miibus1: <mii bus="">on msk1
e1000phy1: <marvell 88e1111="" gigabit="" phy="">PHY 0 on miibus1
e1000phy1:  none, 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, 1000baseT, 1000baseT-master, 1000baseT-FDX, 1000baseT-FDX-master, auto, auto-flow
pcib3: <acpi pci-pci="" bridge="">irq 18 at device 28.2 on pci0
pci3: <acpi pci="" bus="">on pcib3
mskc2: <marvell yukon="" 88e8053="" gigabit="" ethernet="">port 0xa000-0xa0ff mem 0xd0220000-0xd0223fff irq 18 at device 0.0 on pci3
msk2: <marvell technology="" group="" ltd.="" yukon="" ec="" id="" 0xb6="" rev="" 0x02="">on mskc2
miibus2: <mii bus="">on msk2
e1000phy2: <marvell 88e1111="" gigabit="" phy="">PHY 0 on miibus2
e1000phy2:  none, 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, 1000baseT, 1000baseT-master, 1000baseT-FDX, 1000baseT-FDX-master, auto, auto-flow
pcib4: <acpi pci-pci="" bridge="">irq 19 at device 28.3 on pci0
pci4: <acpi pci="" bus="">on pcib4
mskc3: <marvell yukon="" 88e8053="" gigabit="" ethernet="">port 0xb000-0xb0ff mem 0xd0320000-0xd0323fff irq 19 at device 0.0 on pci4
msk3: <marvell technology="" group="" ltd.="" yukon="" ec="" id="" 0xb6="" rev="" 0x02="">on mskc3
miibus3: <mii bus="">on msk3
e1000phy3: <marvell 88e1111="" gigabit="" phy="">PHY 0 on miibus3
e1000phy3:  none, 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, 1000baseT, 1000baseT-master, 1000baseT-FDX, 1000baseT-FDX-master, auto, auto-flow
uhci0: <intel 82801fb="" fr="" fw="" frw="" (ich6)="" usb="" controller="" usb-a="">port 0xeb00-0xeb1f irq 23 at device 29.0 on pci0
usbus0 on uhci0
uhci1: <intel 82801fb="" fr="" fw="" frw="" (ich6)="" usb="" controller="" usb-b="">port 0xed00-0xed1f irq 19 at device 29.1 on pci0
usbus1 on uhci1
uhci2: <intel 82801fb="" fr="" fw="" frw="" (ich6)="" usb="" controller="" usb-c="">port 0xe800-0xe81f irq 18 at device 29.2 on pci0
usbus2 on uhci2
uhci3: <intel 82801fb="" fr="" fw="" frw="" (ich6)="" usb="" controller="" usb-d="">port 0xe900-0xe91f irq 16 at device 29.3 on pci0
usbus3 on uhci3
ehci0: <intel 82801fb="" (ich6)="" usb="" 2.0="" controller="">mem 0xd05c0000-0xd05c03ff irq 23 at device 29.7 on pci0
usbus4: EHCI version 1.0
usbus4 on ehci0
pcib5: <acpi pci-pci="" bridge="">at device 30.0 on pci0
pci5: <acpi pci="" bus="">on pcib5
skc0: <marvell gigabit="" ethernet="">port 0xc000-0xc0ff mem 0xd042c000-0xd042ffff irq 16 at device 0.0 on pci5
skc0: Marvell Yukon Lite Gigabit Ethernet rev. (0x9)
sk0: <marvell semiconductor,="" inc.="" yukon="">on skc0
miibus4: <mii bus="">on sk0
e1000phy4: <marvell 88e1011="" gigabit="" phy="">PHY 0 on miibus4
e1000phy4:  none, 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, 1000baseT, 1000baseT-master, 1000baseT-FDX, 1000baseT-FDX-master, auto
skc1: <marvell gigabit="" ethernet="">port 0xc400-0xc4ff mem 0xd0420000-0xd0423fff irq 17 at device 1.0 on pci5
skc1: Marvell Yukon Lite Gigabit Ethernet rev. (0x9)
sk1: <marvell semiconductor,="" inc.="" yukon="">on skc1
miibus5: <mii bus="">on sk1
e1000phy5: <marvell 88e1011="" gigabit="" phy="">PHY 0 on miibus5
e1000phy5:  none, 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, 1000baseT, 1000baseT-master, 1000baseT-FDX, 1000baseT-FDX-master, auto
skc2: <marvell gigabit="" ethernet="">port 0xc800-0xc8ff mem 0xd0424000-0xd0427fff irq 18 at device 2.0 on pci5
skc2: Marvell Yukon Lite Gigabit Ethernet rev. (0x9)
sk2: <marvell semiconductor,="" inc.="" yukon="">on skc2
miibus6: <mii bus="">on sk2
e1000phy6: <marvell 88e1011="" gigabit="" phy="">PHY 0 on miibus6
e1000phy6:  none, 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, 1000baseT, 1000baseT-master, 1000baseT-FDX, 1000baseT-FDX-master, auto
skc3: <marvell gigabit="" ethernet="">port 0xcc00-0xccff mem 0xd0428000-0xd042bfff irq 19 at device 3.0 on pci5
skc3: Marvell Yukon Lite Gigabit Ethernet rev. (0x9)
sk3: <marvell semiconductor,="" inc.="" yukon="">on skc3
miibus7: <mii bus="">on sk3
e1000phy7: <marvell 88e1011="" gigabit="" phy="">PHY 0 on miibus7
e1000phy7:  none, 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, 1000baseT, 1000baseT-master, 1000baseT-FDX, 1000baseT-FDX-master, auto
pci5: <encrypt decrypt,="" network="" computer="" crypto="">at device 4.0 (no driver attached)
isab0: <pci-isa bridge="">at device 31.0 on pci0
isa0: <isa bus="">on isab0
atapci0: <intel ich6="" udma100="" controller="">port 0x1f0-0x1f7,0x3f6,0x170-0x177,0x376,0xf000-0xf00f at device 31.1 on pci0
ata0: <ata channel="">at channel 0 on atapci0
ata1: <ata channel="">at channel 1 on atapci0
acpi_tz0: <thermal zone="">on acpi0
uart0: <16550 or compatible> port 0x3f8-0x3ff irq 4 flags 0x10 on acpi0
uart0: console (115200,n,8,1)
uart1: <16550 or compatible> port 0x2f8-0x2ff irq 3 on acpi0
ppc0: <parallel port="">port 0x378-0x37f,0x778-0x77b irq 7 on acpi0
ppc0: Generic chipset (NIBBLE-only) in COMPATIBLE mode
ppbus0: <parallel port="" bus="">on ppc0
lpt0: <printer>on ppbus0
lpt0: Interrupt-driven port
ppi0: <parallel i="" o="">on ppbus0
pmtimer0 on isa0
orm0: <isa option="" rom="">at iomem 0xc0000-0xce7ff pnpid ORM0000 on isa0
sc0: <system console="">at flags 0x100 on isa0
sc0: VGA <16 virtual consoles, flags=0x300>
vga0: <generic isa="" vga="">at port 0x3c0-0x3df iomem 0xa0000-0xbffff on isa0
atkbdc0: <keyboard controller="" (i8042)="">at port 0x60,0x64 on isa0
atkbd0: <at keyboard="">irq 1 on atkbdc0
kbd0 at atkbd0
atkbd0: [GIANT-LOCKED]
est0: <enhanced speedstep="" frequency="" control="">on cpu0
est: CPU supports Enhanced Speedstep, but is not recognized.
est: cpu_vendor GenuineIntel, msr 6120f2906000f29
device_attach: est0 attach returned 6
p4tcc0: <cpu frequency="" thermal="" control="">on cpu0
Timecounters tick every 1.000 msec
IPsec: Initialized Security Association Processing.
random: unblocking device.
usbus0: 12Mbps Full Speed USB v1.0
usbus1: 12Mbps Full Speed USB v1.0
usbus2: 12Mbps Full Speed USB v1.0
usbus3: 12Mbps Full Speed USB v1.0
ugen0.1: <intel>at usbus0
uhub0: <intel 1="" 9="" uhci="" root="" hub,="" class="" 0,="" rev="" 1.00="" 1.00,="" addr="">on usbus0
ugen1.1: <intel>at usbus1
uhub1: <intel 1="" 9="" uhci="" root="" hub,="" class="" 0,="" rev="" 1.00="" 1.00,="" addr="">on usbus1
ugen2.1: <intel>at usbus2
uhub2: <intel 1="" 9="" uhci="" root="" hub,="" class="" 0,="" rev="" 1.00="" 1.00,="" addr="">on usbus2
ugen3.1: <intel>at usbus3
uhub3: <intel 1="" 9="" uhci="" root="" hub,="" class="" 0,="" rev="" 1.00="" 1.00,="" addr="">on usbus3
usbus4: 480Mbps High Speed USB v2.0
ugen4.1: <intel>at usbus4
uhub4: <intel 1="" 9="" ehci="" root="" hub,="" class="" 0,="" rev="" 2.00="" 1.00,="" addr="">on usbus4
ata0: DMA limited to UDMA33, controller found non-ATA66 cable
ada0 at ata0 bus 0 scbus0 target 0 lun 0
ada0: <wdc wd800beve-00uyt0="" 01.04a01="">ATA-7 device
ada0: Serial Number WD-WXEX08TJ6328
ada0: 33.300MB/s transfers (UDMA2, PIO 8192bytes)
ada0: 76319MB (156301488 512 byte sectors: 16H 63S/T 16383C)
ada0: Previously was known as ad0
Timecounter "TSC" frequency 2000113799 Hz quality 800
Root mount waiting for: usbus4 usbus3 usbus2 usbus1 usbus0
uhub0: 2 ports with 2 removable, self powered
uhub1: 2 ports with 2 removable, self powered
uhub2: 2 ports with 2 removable, self powered
uhub3: 2 ports with 2 removable, self powered
Root mount waiting for: usbus4
Root mount waiting for: usbus4
Root mount waiting for: usbus4
uhub4: 8 ports with 8 removable, self powered
Trying to mount root from ufs:/dev/ad0s1a [rw]...</wdc></intel></intel></intel></intel></intel></intel></intel></intel></intel></intel></cpu></enhanced></at></keyboard></generic></system></isa></parallel></printer></parallel></parallel></thermal></ata></ata></intel></isa></pci-isa></encrypt></marvell></mii></marvell></marvell></marvell></mii></marvell></marvell></marvell></mii></marvell></marvell></marvell></mii></marvell></marvell></acpi></acpi></intel></intel></intel></intel></intel></marvell></mii></marvell></marvell></acpi></acpi></marvell></mii></marvell></marvell></acpi></acpi></marvell></mii></marvell></marvell></acpi></acpi></marvell></mii></marvell></marvell></acpi></acpi></intel></vga-compatible></acpi></acpi></power></at></at></acpi></intelr></software></software,></version></intelr></nx></est,tm2></fpu,vme,de,pse,tsc,msr,pae,mce,cx8,apic,sep,mtrr,pge,mca,cmov,pat,clflush,dts,acpi,mmx,fxsr,sse,sse2,ss,tm,pbe>

stephenw10

That's good because I'm not sure there's much we can do with the drivers! ;)

Try disabling apinger for the gateway in System > Routing, edit gateway.

In 2.2 there is an option to get more info from apinger by enabling 'gateway monitoring debug logging' in System > Advanced, Miscellaneous tab. Try that if disabling apinger makes any difference.

Steve

TieT

@stephenw10:

That's good because I'm not sure there's much we can do with the drivers! ;)

Try disabling apinger for the gateway in System > Routing, edit gateway.

In 2.2 there is an option to get more info from apinger by enabling 'gateway monitoring debug logging' in System > Advanced, Miscellaneous tab. Try that if disabling apinger makes any difference.

Steve

Ok ;D
I'll try disabling apinger first and see how it goes the next days.
Its happens always after the Firewall is online for 2 days.

Greetz
Tim

TieT

Ow yeah, I'm also getting these messages…
On a disabled interface and no cable plugged in.

They are on the same interface card though (sk..)
I only use sk0 and sk1 for now.

Feb 3 18:02:08 	php-fpm[61051]: /rc.linkup: Linkup detected on disabled interface...Ignoring
Feb 3 18:02:08 	php-fpm[61051]: /rc.linkup: Linkup detected on disabled interface...Ignoring
Feb 3 18:02:07 	check_reload_status: Linkup starting sk3
Feb 3 18:02:07 	kernel: sk3: link state changed to DOWN
Feb 3 18:02:07 	kernel: sk2: link state changed to DOWN
Feb 3 18:02:07 	check_reload_status: Linkup starting sk2

stephenw10

Is that at any time or just at boot?

TieT

@stephenw10:

Is that at any time or just at boot?

At the end of the boot cycle :)
I also see that WOL isn't working anymore.. strange

doktornotor

WOL is a known x86 issue with a patch on Redmine, completely unrelated.

phil.davis

I also see that WOL isn't working anymore.. strange

I guess you are using 32-bit pfSense 2.2 - that is effected by the gen_subnetv4_max issue, fixed by:
https://github.com/pfsense/pfsense/commit/7094c303b7d46c9f7b24c3f1bd4432187832e85c

Things that try to calculate the max IP address of a subnet are effected - WOL is one of them.

You can apply that small fix and WOL should work again.

TieT

@phil.davis:

I also see that WOL isn't working anymore.. strange

I guess you are using 32-bit pfSense 2.2 - that is effected by the gen_subnetv4_max issue, fixed by:
https://github.com/pfsense/pfsense/commit/7094c303b7d46c9f7b24c3f1bd4432187832e85c

Things that try to calculate the max IP address of a subnet are effected - WOL is one of them.

You can apply that small fix and WOL should work again.

Thank you !
I was guessing in that direction, because when using WOL in the terminal it worked :)

TieT

Spoke too soon.

The WAN link is still losing its connection.

Feb 4 13:37:17 	kernel: arpresolve: can't allocate llinfo for 84.192.192.1 on sk0
Feb 4 13:37:17 	kernel: arpresolve: can't allocate llinfo for 84.192.192.1 on sk0
Feb 4 13:37:13 	kernel: arpresolve: can't allocate llinfo for 84.192.192.1 on sk0
Feb 4 13:37:06 	php-fpm[5814]: /rc.linkup: DEVD Ethernet detached event for wan
Feb 4 13:37:05 	kernel: sk0: link state changed to DOWN
Feb 4 13:37:05 	check_reload_status: Linkup starting sk0
Feb 4 13:36:10 	php-fpm[26356]: /rc.filter_configure_sync: Could not find IPv6 gateway for interface (wan).
Feb 4 13:36:08 	check_reload_status: Reloading filter
Feb 4 13:36:08 	php-fpm[26356]: /rc.newwanip: rc.newwanip: on (IP address: 192.168.1.254) (interface: LAN[lan]) (real interface: sk1).
Feb 4 13:36:08 	php-fpm[26356]: /rc.newwanip: rc.newwanip: Info: starting on sk1.
Feb 4 13:36:07 	check_reload_status: rc.newwanip starting sk1
Feb 4 13:36:07 	php-fpm[26356]: /rc.linkup: Hotplug event detected for LAN(lan) but ignoring since interface is configured with static IP (192.168.1.254 )
Feb 4 13:36:06 	kernel: sk1: link state changed to UP
Feb 4 13:36:06 	check_reload_status: Linkup starting sk1
Feb 4 13:36:01 	php-fpm[26356]: /rc.linkup: Hotplug event detected for LAN(lan) but ignoring since interface is configured with static IP (192.168.1.254 )
Feb 4 13:36:00 	kernel: sk1: link state changed to DOWN

Firewall Logs


block/1000000104
	Feb 4 13:40:18 	Direction=OUT lo0 	Default deny rule IPv4 (1000000104)		Icon Reverse Resolve with DNS Icon Easy Rule: Add to Block List 74.125.24.139:80		Icon Reverse Resolve with DNS Icon Easy Rule: Pass this traffic 84.192.215.xxx:46001		TCP:FA
block/1000000104
	Feb 4 13:40:18 	Direction=OUT lo0 	Default deny rule IPv4 (1000000104)		Icon Reverse Resolve with DNS Icon Easy Rule: Add to Block List 74.125.24.139:80		Icon Reverse Resolve with DNS Icon Easy Rule: Pass this traffic 84.192.215.xxx:46001		TCP:FA
block/1000000104
	Feb 4 13:40:17 	Direction=OUT lo0 	Default deny rule IPv4 (1000000104)		Icon Reverse Resolve with DNS Icon Easy Rule: Add to Block List 74.125.24.139:80		Icon Reverse Resolve with DNS Icon Easy Rule: Pass this traffic 84.192.215.xxx:46001		TCP:FA
pass/1422181121
	Feb 4 13:24:22 	ovpns1 	USER_RULE OpenVPN OpenVPN Server wizard (1422181121)		Icon Reverse Resolve with DNS Icon Easy Rule: Add to Block List 192.168.10.10		Icon Reverse Resolve with DNS Icon Easy Rule: Pass this traffic 192.168.1.120		ICMP
pass/1422181121
	Feb 4 13:24:11 	ovpns1 	USER_RULE OpenVPN OpenVPN Server wizard (1422181121)		Icon Reverse Resolve with DNS Icon Easy Rule: Add to Block List 192.168.10.10:55720		Icon Reverse Resolve with DNS Icon Easy Rule: Pass this traffic 192.168.1.254:443		TCP:S

TieT

I don't know if there is a relation , but tonight i noticed something strange in the logs.

My WAN ip changed to a private range… (twice)
I'm also seeing openvpn and LCDProc errors...

wtf !


Feb 11 01:10:30 fw1 snort[39066]: invalid appid in appStatRecord (186)
Feb 11 01:28:21 fw1 check_reload_status: updating dyndns WAN_DHCP
Feb 11 01:28:21 fw1 check_reload_status: Restarting ipsec tunnels
Feb 11 01:28:21 fw1 check_reload_status: Restarting OpenVPN tunnels/interfaces
Feb 11 01:28:21 fw1 check_reload_status: Reloading filter
Feb 11 01:28:22 fw1 php-fpm[89141]: /rc.dyndns.update: phpDynDNS (***-ip.biz): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry.
Feb 11 01:28:22 fw1 php-fpm[76014]: /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use WAN_DHCP.
Feb 11 01:28:22 fw1 php-fpm[76014]: /rc.openvpn: OpenVPN: Resync server1 OpenVPN Server
Feb 11 01:28:22 fw1 kernel: ovpns1: link state changed to DOWN
Feb 11 01:28:22 fw1 check_reload_status: Reloading filter
Feb 11 01:28:23 fw1 kernel: ovpns1: link state changed to UP
Feb 11 01:28:23 fw1 check_reload_status: rc.newwanip starting ovpns1
Feb 11 01:28:24 fw1 php-fpm[89141]: /rc.newwanip: rc.newwanip: Info: starting on ovpns1.
Feb 11 01:28:24 fw1 php-fpm[89141]: /rc.newwanip: rc.newwanip: on (IP address: 192.168.10.1) (interface: []) (real interface: ovpns1).
Feb 11 01:28:24 fw1 check_reload_status: Reloading filter
Feb 11 01:28:24 fw1 php-fpm[89141]: /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection -  ->  192.168.10.1 - Restarting packages.
Feb 11 01:28:24 fw1 check_reload_status: Starting packages
Feb 11 01:28:24 fw1 php-fpm[76014]: /rc.filter_configure_sync: Could not find IPv6 gateway for interface (wan).
Feb 11 01:28:25 fw1 php-fpm[89141]: /rc.start_packages: Restarting/Starting all packages.
Feb 11 01:28:25 fw1 php-fpm[89141]: /rc.start_packages: Reloading Squid for configuration sync
Feb 11 01:28:26 fw1 check_reload_status: Syncing firewall
Feb 11 01:28:26 fw1 check_reload_status: Syncing firewall
Feb 11 01:28:27 fw1 php-fpm[79907]: /rc.filter_configure_sync: Could not find IPv6 gateway for interface (wan).
Feb 11 01:28:28 fw1 php: lcdproc: Start client procedure. Error counter: (0)
Feb 11 01:28:39 fw1 php: lcdproc: Failed to connect to LCDd process Operation timed out (60)
Feb 11 01:28:39 fw1 php: lcdproc: Start client procedure. Error counter: (1)
Feb 11 01:28:50 fw1 php: lcdproc: Failed to connect to LCDd process Operation timed out (60)
Feb 11 01:28:50 fw1 php: lcdproc: Start client procedure. Error counter: (2)
Feb 11 01:29:01 fw1 php: lcdproc: Failed to connect to LCDd process Operation timed out (60)
Feb 11 01:29:01 fw1 php: lcdproc: Start client procedure. Error counter: (3)
Feb 11 01:29:12 fw1 php: lcdproc: Failed to connect to LCDd process Operation timed out (60)
Feb 11 01:29:12 fw1 php: lcdproc: Too many errors, the client ends.
Feb 11 01:33:20 fw1 kernel: pid 71053 (ntpd), uid 0: exited on signal 11 (core dumped)
Feb 11 01:55:12 fw1 snort[39066]: invalid appid in appStatRecord (498)
Feb 11 02:00:31 fw1 php: snort_check_for_rule_updates.php: [Snort] Rules download error: Resolving timed out after 30622 milliseconds
Feb 11 02:00:31 fw1 php: snort_check_for_rule_updates.php: [Snort] Will retry in 15 seconds...
Feb 11 02:01:17 fw1 php: snort_check_for_rule_updates.php: [Snort] Rules download error: Resolving timed out after 30630 milliseconds
Feb 11 02:01:17 fw1 php: snort_check_for_rule_updates.php: [Snort] Will retry in 15 seconds...
Feb 11 02:02:03 fw1 php: snort_check_for_rule_updates.php: [Snort] Rules download error: Resolving timed out after 30797 milliseconds
Feb 11 02:02:03 fw1 php: snort_check_for_rule_updates.php: [Snort] Will retry in 15 seconds...
Feb 11 02:02:49 fw1 php: snort_check_for_rule_updates.php: [Snort] Rules download error: Resolving timed out after 30628 milliseconds
Feb 11 02:02:49 fw1 php: snort_check_for_rule_updates.php: [Snort] Will retry in 15 seconds...
Feb 11 02:03:04 fw1 php: snort_check_for_rule_updates.php: File 'snortrules-snapshot-2970.tar.gz.md5' download attempts: 4 ...
Feb 11 02:03:04 fw1 php: snort_check_for_rule_updates.php: [Snort] Snort VRT rules md5 download failed...
Feb 11 02:03:04 fw1 php: snort_check_for_rule_updates.php: [Snort] Server returned error code 0...
Feb 11 02:03:34 fw1 php: snort_check_for_rule_updates.php: [Snort] Rules download error: Resolving timed out after 30759 milliseconds
Feb 11 02:03:34 fw1 php: snort_check_for_rule_updates.php: [Snort] Will retry in 15 seconds...
Feb 11 02:04:20 fw1 php: snort_check_for_rule_updates.php: [Snort] Rules download error: Resolving timed out after 30773 milliseconds
Feb 11 02:04:20 fw1 php: snort_check_for_rule_updates.php: [Snort] Will retry in 15 seconds...
Feb 11 02:05:06 fw1 php: snort_check_for_rule_updates.php: [Snort] Rules download error: Resolving timed out after 30740 milliseconds
Feb 11 02:05:06 fw1 php: snort_check_for_rule_updates.php: [Snort] Will retry in 15 seconds...
Feb 11 02:05:52 fw1 php: snort_check_for_rule_updates.php: [Snort] Rules download error: Resolving timed out after 30696 milliseconds
Feb 11 02:05:52 fw1 php: snort_check_for_rule_updates.php: [Snort] Will retry in 15 seconds...
Feb 11 02:06:07 fw1 php: snort_check_for_rule_updates.php: File 'snort-openappid.tar.gz.md5' download attempts: 4 ...
Feb 11 02:06:07 fw1 php: snort_check_for_rule_updates.php: [Snort] Snort OpenAppID detectors md5 download failed...
Feb 11 02:06:07 fw1 php: snort_check_for_rule_updates.php: [Snort] Server returned error code 0...
Feb 11 02:06:37 fw1 php: snort_check_for_rule_updates.php: [Snort] Rules download error: Resolving timed out after 30597 milliseconds
Feb 11 02:06:37 fw1 php: snort_check_for_rule_updates.php: [Snort] Will retry in 15 seconds...
Feb 11 02:07:23 fw1 php: snort_check_for_rule_updates.php: [Snort] Rules download error: Resolving timed out after 30771 milliseconds
Feb 11 02:07:23 fw1 php: snort_check_for_rule_updates.php: [Snort] Will retry in 15 seconds...
Feb 11 02:08:09 fw1 php: snort_check_for_rule_updates.php: [Snort] Rules download error: Resolving timed out after 30889 milliseconds
Feb 11 02:08:09 fw1 php: snort_check_for_rule_updates.php: [Snort] Will retry in 15 seconds...
Feb 11 02:08:54 fw1 php: snort_check_for_rule_updates.php: [Snort] Rules download error: Resolving timed out after 30633 milliseconds
Feb 11 02:08:54 fw1 php: snort_check_for_rule_updates.php: [Snort] Will retry in 15 seconds...
Feb 11 02:09:09 fw1 php: snort_check_for_rule_updates.php: File 'community-rules.tar.gz.md5' download attempts: 4 ...
Feb 11 02:09:09 fw1 php: snort_check_for_rule_updates.php: [Snort] Snort GPLv2 Community Rules md5 download failed...
Feb 11 02:09:09 fw1 php: snort_check_for_rule_updates.php: [Snort] Server returned error code 0...
Feb 11 02:09:40 fw1 php: snort_check_for_rule_updates.php: [Snort] Rules download error: Resolving timed out after 30721 milliseconds
Feb 11 02:09:40 fw1 php: snort_check_for_rule_updates.php: [Snort] Will retry in 15 seconds...
Feb 11 02:10:26 fw1 php: snort_check_for_rule_updates.php: [Snort] Rules download error: Resolving timed out after 30805 milliseconds
Feb 11 02:10:26 fw1 php: snort_check_for_rule_updates.php: [Snort] Will retry in 15 seconds...
Feb 11 02:11:12 fw1 php: snort_check_for_rule_updates.php: [Snort] Rules download error: Resolving timed out after 30806 milliseconds
Feb 11 02:11:12 fw1 php: snort_check_for_rule_updates.php: [Snort] Will retry in 15 seconds...
Feb 11 02:11:58 fw1 php: snort_check_for_rule_updates.php: [Snort] Rules download error: Resolving timed out after 30717 milliseconds
Feb 11 02:11:58 fw1 php: snort_check_for_rule_updates.php: [Snort] Will retry in 15 seconds...
Feb 11 02:12:13 fw1 php: snort_check_for_rule_updates.php: File 'emerging.rules.tar.gz.md5' download attempts: 4 ...
Feb 11 02:12:13 fw1 php: snort_check_for_rule_updates.php: [Snort] Emerging Threats Open rules md5 download failed...
Feb 11 02:12:13 fw1 php: snort_check_for_rule_updates.php: [Snort] Server returned error code 0...
Feb 11 02:12:13 fw1 php: snort_check_for_rule_updates.php: [Snort] The Rules update has finished.
Feb 11 02:12:13 fw1 check_reload_status: Syncing firewall
Feb 11 02:12:14 fw1 kernel: pid 65763 (php), uid 0: exited on signal 11 (core dumped)
Feb 11 02:13:09 fw1 check_reload_status: rc.newwanip starting sk0
Feb 11 02:13:10 fw1 php-fpm[87333]: /rc.newwanip: rc.newwanip: Info: starting on sk0.
Feb 11 02:13:10 fw1 php-fpm[87333]: /rc.newwanip: rc.newwanip: on (IP address: 192.168.100.10) (interface: WAN[wan]) (real interface: sk0).
Feb 11 02:13:10 fw1 php-fpm[87333]: /rc.newwanip: IP has changed, killing states on former IP 84.192.***.***.
Feb 11 02:13:11 fw1 php-fpm[87333]: /rc.newwanip: Could not find IPv6 gateway for interface (wan).
Feb 11 02:13:12 fw1 php-fpm[87333]: /rc.newwanip: ROUTING: setting default route to 192.168.100.1
Feb 11 02:13:12 fw1 php-fpm[87333]: /rc.newwanip: Removing static route for monitor 84.192.***.***and adding a new route through 192.168.100.1
Feb 11 02:13:32 fw1 check_reload_status: updating dyndns WAN_DHCP
Feb 11 02:13:32 fw1 check_reload_status: Restarting ipsec tunnels
Feb 11 02:13:32 fw1 check_reload_status: Restarting OpenVPN tunnels/interfaces
Feb 11 02:13:32 fw1 check_reload_status: Reloading filter
Feb 11 02:13:33 fw1 php-fpm[15216]: /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use WAN_DHCP.
Feb 11 02:13:33 fw1 php-fpm[15216]: /rc.openvpn: OpenVPN: Resync server1 OpenVPN Server
Feb 11 02:13:33 fw1 kernel: ovpns1: link state changed to DOWN
Feb 11 02:13:33 fw1 check_reload_status: Reloading filter
Feb 11 02:13:34 fw1 kernel: ovpns1: link state changed to UP
Feb 11 02:13:34 fw1 check_reload_status: rc.newwanip starting ovpns1
Feb 11 02:13:35 fw1 php-fpm[15216]: /rc.filter_configure_sync: Could not find IPv6 

Feb 11 02:13:39 fw1 check_reload_status: Syncing firewall
Feb 11 02:13:39 fw1 php-fpm[19772]: /rc.newwanip: rc.newwanip: on (IP address: 192.168.10.1) (interface: []) (real interface: ovpns1).
Feb 11 02:13:39 fw1 check_reload_status: Reloading filter
Feb 11 02:13:39 fw1 php-fpm[19772]: /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection -  ->  192.168.10.1 - Restarting packages.
Feb 11 02:13:39 fw1 check_reload_status: Starting packages
Feb 11 02:13:39 fw1 check_reload_status: Syncing firewall
Feb 11 02:13:39 fw1 php-fpm[87333]: /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - 84.192.***.***->  192.168.100.10 - Restarting packages.
Feb 11 02:13:40 fw1 php-fpm[70546]: /rc.start_packages: Restarting/Starting all packages.
Feb 11 02:13:40 fw1 php-fpm[70546]: /rc.start_packages: Reloading Squid for configuration sync
Feb 11 02:13:41 fw1 check_reload_status: Reloading filter
Feb 11 02:13:41 fw1 php: lcdproc: Start client procedure. Error counter: (0)
Feb 11 02:13:41 fw1 check_reload_status: Syncing firewall
Feb 11 02:13:42 fw1 php-fpm[19772]: /rc.filter_configure_sync: Could not find IPv6 gateway for interface (wan).
Feb 11 02:13:44 fw1 php-fpm[87333]: /rc.filter_configure_sync: Could not find IPv6 gateway for interface (wan).
Feb 11 02:13:44 fw1 php: lcdproc: Start client procedure. Error counter: (0)
Feb 11 02:13:55 fw1 php: lcdproc: Failed to connect to LCDd process Operation timed out (60)
Feb 11 02:13:55 fw1 php: lcdproc: Start client procedure. Error counter: (1)
Feb 11 02:14:06 fw1 php: lcdproc: Failed to connect to LCDd process Operation timed out (60)
Feb 11 02:14:06 fw1 php: lcdproc: Start client procedure. Error counter: (2)
Feb 11 02:14:11 fw1 kernel: arpresolve: can't allocate llinfo for 192.168.100.1 on sk0
Feb 11 02:14:12 fw1 kernel: arpresolve: can't allocate llinfo for 192.168.100.1 on sk0
Feb 11 02:14:13 fw1 check_reload_status: rc.newwanip starting sk0
Feb 11 02:14:14 fw1 php-fpm[80275]: /rc.newwanip: rc.newwanip: Info: starting on sk0.
Feb 11 02:14:14 fw1 php-fpm[80275]: /rc.newwanip: rc.newwanip: on (IP address: 192.168.100.10) (interface: WAN[wan]) (real interface: sk0).
Feb 11 02:14:15 fw1 php-fpm[80275]: /rc.newwanip: Could not find IPv6 gateway for interface (wan).
Feb 11 02:14:16 fw1 php-fpm[80275]: /rc.newwanip: ROUTING: setting default route to 192.168.100.1
Feb 11 02:14:16 fw1 php-fpm[80275]: /rc.newwanip: Removing static route for monitor 84.192.***.*** and adding a new route through 192.168.100.1
Feb 11 02:14:17 fw1 php-fpm[80275]: /rc.newwanip: Dyndns debug information (tiet.no-ip.biz): Could not resolve checkip.dyndns.org to IP using interface IP 192.168.100.10.
Feb 11 02:14:17 fw1 php-fpm[80275]: /rc.newwanip: DynDNS (*****-ip.biz) There was an error trying to determine the public IP for interface - wan(sk0). Probably interface is not a WAN interface.
Feb 11 02:14:17 fw1 php: lcdproc: Failed to connect to LCDd process Operation timed out (60)
Feb 11 02:14:17 fw1 php: lcdproc: Start client procedure. Error counter: (3)
Feb 11 02:14:18 fw1 php-fpm[80275]: /rc.newwanip: Resyncing OpenVPN instances for interface WAN.
Feb 11 02:14:18 fw1 kernel: ovpns1: link state changed to DOWN
Feb 11 02:14:18 fw1 check_reload_status: Reloading filter
Feb 11 02:14:18 fw1 check_reload_status: Reloading filter
Feb 11 02:14:18 fw1 php-fpm[80275]: /rc.newwanip: Creating rrd update script
Feb 11 02:14:18 fw1 kernel: ovpns1: link state changed to UP
Feb 11 02:14:18 fw1 check_reload_status: rc.newwanip starting ovpns1
Feb 11 02:14:20 fw1 php-fpm[35317]: /rc.filter_configure_sync: Could not find IPv6 gateway for interface (wan).
Feb 11 02:14:20 fw1 php-fpm[80275]: /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - 192.168.100.10 ->  192.168.100.10 - Restarting packages.
Feb 11 02:14:20 fw1 check_reload_status: Starting packages
Feb 11 02:14:20 fw1 php-fpm[80275]: /rc.newwanip: rc.newwanip: Info: starting on ovpns1.
Feb 11 02:14:20 fw1 php-fpm[80275]: /rc.newwanip: rc.newwanip: on (IP address: 192.168.10.1) (interface: []) (real interface: ovpns1).
Feb 11 02:14:20 fw1 check_reload_status: Reloading filter
Feb 11 02:14:20 fw1 php-fpm[80275]: /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection -  ->  192.168.10.1 - Restarting packages.
Feb 11 02:14:20 fw1 check_reload_status: Starting packages
Feb 11 02:14:22 fw1 php-fpm[80275]: /rc.start_packages: Restarting/Starting all packages.
Feb 11 02:14:22 fw1 php-fpm[35317]: /rc.start_packages: Skipping STARTing packages process because previous/another instance is already running
Feb 11 02:14:22 fw1 php-fpm[80275]: /rc.start_packages: Reloading Squid for configuration sync
Feb 11 02:14:23 fw1 php-fpm[67206]: /rc.filter_configure_sync: Could not find IPv6 gateway for interface (wan).
Feb 11 02:14:23 fw1 check_reload_status: Syncing firewall
Feb 11 02:14:23 fw1 check_reload_status: Syncing firewall
Feb 11 02:14:25 fw1 php: lcdproc: Start client procedure. Error counter: (0)
Feb 11 02:14:36 fw1 php: lcdproc: Failed to connect to LCDd process Operation timed out (60)
Feb 11 02:14:36 fw1 php: lcdproc: Start client procedure. Error counter: (1)
Feb 11 02:14:47 fw1 php: lcdproc: Failed to connect to LCDd process Operation timed out (60)
Feb 11 02:14:47 fw1 php: lcdproc: Start client procedure. Error counter: (2)
Feb 11 02:14:58 fw1 php: lcdproc: Failed to connect to LCDd process Operation timed out (60)
Feb 11 02:14:58 fw1 php: lcdproc: Start client procedure. Error counter: (3)
Feb 11 02:15:09 fw1 php: lcdproc: Failed to connect to LCDd process Operation timed out (60)
Feb 11 02:15:09 fw1 php: lcdproc: Too many errors, the client ends.
Feb 11 02:15:14 fw1 kernel: arpresolve: can't allocate llinfo for 192.168.100.1 on sk0
Feb 11 02:15:15 fw1 kernel: arpresolve: can't allocate llinfo for 192.168.100.1 on sk0
Feb 11 02:15:16 fw1 kernel: arpresolve: can't allocate llinfo for 192.168.100.1 on sk0
Feb 11 02:15:17 fw1 kernel: arpresolve: can't allocate llinfo for 192.168.100.1 on sk0
Feb 11 02:15:18 fw1 kernel: arpresolve: can't allocate llinfo for 192.168.100.1 on sk0
Feb 11 02:15:19 fw1 kernel: arpresolve: can't allocate llinfo for 192.168.100.1 on sk0
Feb 11 02:15:20 fw1 kernel: arpresolve: can't allocate llinfo for 192.168.100.1 on sk0
Feb 11 02:15:20 fw1 check_reload_status: rc.newwanip starting sk0
Feb 11 02:15:21 fw1 kernel: arpresolve: can't allocate llinfo for 192.168.100.1 on sk0
Feb 11 02:15:21 fw1 php-fpm[67206]: /rc.newwanip: rc.newwanip: Info: starting on sk0.
Feb 11 02:15:21 fw1 php-fpm[67206]: /rc.newwanip: rc.newwanip: on (IP address: 84.192.***.***) (interface: WAN[wan]) (real interface: sk0).
Feb 11 02:15:21 fw1 php-fpm[67206]: /rc.newwanip: IP has changed, killing states on former IP 192.168.100.10.
Feb 11 02:15:23 fw1 php-fpm[67206]: /rc.newwanip: Could not find IPv6 gateway for interface (wan).
Feb 11 02:15:23 fw1 php-fpm[67206]: /rc.newwanip: ROUTING: setting default route to 84.192.***.***
Feb 11 02:15:25 fw1 php-fpm[67206]: /rc.newwanip: phpDynDNS (*****-ip.biz): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry.
Feb 11 02:15:26 fw1 php-fpm[67206]: /rc.newwanip: Resyncing OpenVPN instances for interface WAN.
Feb 11 02:15:26 fw1 kernel: ovpns1: link state changed to DOWN
Feb 11 02:15:26 fw1 check_reload_status: Reloading filter
Feb 11 02:15:26 fw1 check_reload_status: Reloading filter
Feb 11 02:15:26 fw1 php-fpm[67206]: /rc.newwanip: Creating rrd update script
Feb 11 02:15:26 fw1 kernel: ovpns1: link state changed to UP
Feb 11 02:15:26 fw1 check_reload_status: rc.newwanip starting ovpns1
Feb 11 02:15:28 fw1 php-fpm[56235]: /rc.filter_configure_sync: Could not find IPv6 gateway for interface (wan).
Feb 11 02:15:28 fw1 php-fpm[67206]: /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - 192.168.100.10 ->  84.192.***.*** - Restarting packages.
Feb 11 02:15:28 fw1 check_reload_status: Starting packages
Feb 11 02:15:28 fw1 php-fpm[67206]: /rc.newwanip: rc.newwanip: Info: starting on ovpns1.
Feb 11 02:15:28 fw1 php-fpm[67206]: /rc.newwanip: rc.newwanip: on (IP address: 192.168.10.1) (interface: []) (real interface: ovpns1).
Feb 11 02:15:28 fw1 check_reload_status: Reloading filter
Feb 11 02:15:28 fw1 php-fpm[67206]: /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection -  ->  192.168.10.1 - Restarting packages.
Feb 11 02:15:28 fw1 check_reload_status: Starting packages
Feb 11 02:15:29 fw1 php-fpm[67206]: /rc.start_packages: Restarting/Starting all packages.
Feb 11 02:15:29 fw1 php-fpm[56235]: /rc.start_packages: Skipping STARTing packages process because previous/another instance is already running
Feb 11 02:15:30 fw1 php-fpm[67206]: /rc.start_packages: Reloading Squid for configuration sync
Feb 11 02:15:30 fw1 php-fpm[86166]: /rc.filter_configure_sync: Could not find IPv6 gateway for interface (wan).
Feb 11 02:15:31 fw1 check_reload_status: Syncing firewall
Feb 11 02:15:31 fw1 check_reload_status: Syncing firewall
Feb 11 02:15:32 fw1 php: lcdproc: Start client procedure. Error counter: (0)
Feb 11 02:15:43 fw1 php: lcdproc: Failed to connect to LCDd process Operation timed out (60)
Feb 11 02:15:43 fw1 php: lcdproc: Start client procedure. Error counter: (1)
Feb 11 02:15:54 fw1 php: lcdproc: Failed to connect to LCDd process Operation timed out (60)
Feb 11 02:15:54 fw1 php: lcdproc: Start client procedure. Error counter: (2)
Feb 11 02:16:05 fw1 php: lcdproc: Failed to connect to LCDd process Operation timed out (60)
Feb 11 02:16:05 fw1 php: lcdproc: Start client procedure. Error counter: (3)
Feb 11 02:16:16 fw1 php: lcdproc: Failed to connect to LCDd process Operation timed out (60)
Feb 11 02:16:16 fw1 php: lcdproc: Too many errors, the client ends.
Feb 11 07:04:06 fw1 php-fpm[73586]: /index.php: Session timed out for user 'admin'

stephenw10

A private IP on your WAN is usually caused by a cable modem that's lost its upstream connection. Could that be happening here. Is the private address being assigned in any of your internal subnets?

Steve

Derelict

Is your modem rebooting? That might explain both symptoms.

TieT

Don't know , but that makes sense in a way… :)
On the other hand it's giving me 2 different IP's.

stephenw10

You mean 192.168.10.1 and 192.168.100.10?
You aren't using either of those subnets (/24) internally?

Steve

TieT

Nope :-)

The 192.168.10.0/24 range is used by openvpn for vpn access

stephenw10

Ok, so you could have something handing out address in that subnet. The 100.1 address is totally spurious, not used as a tunnel address etc?

Steve

TieT

Nope not used.

But the WAN link seems stable for now.
I made some changes in the System general settings and they seem to work.

stephenw10

What did you change?

Steve

q54e3w

I have the same issue and posted some logs in another thread yesterday. I've seen a few posts like this recently do possibly something needs tweaking. I'll add a link to my logs tomorrow when I get back to my desk. I've tried setting static address, disabling monitoring but every 3-7 days my line drops and needs s reboot of wan or box to resolve.

Edit: here's the link to my logs… https://forum.pfsense.org/index.php?topic=88236.msg491251#msg491251

TieT

In System -> general settings i added 127.0.0.1 as first dns server without any gateway
then on the second line:
8.8.8.8 with the gateway from my provider 84.192.192.1
on the third:
8.8.4.4 with 84.192.192.1

the option to automatically find the gateway seems to f*ck the wan link sometimes…

I didn't make any changes otherwise to the network config.

Only updated LCDProc and used your guide to set it up because it kept crashing badly.

stephenw10

Interesting, thanks.

xtofh

Hi,

Are you sure this is resolved? I find it strange that changing dns settings solves this.

Looking at your IP gateway, we're using the same internet provider and I'm having the same issue. (only updated yesterday, noticed the link going down today)

I had a similar issue a few years back: https://forum.pfsense.org/index.php?topic=51420.0

It was solved by using the 2.1 release. But now the problem returned after updating to 2.2.

I'll keep an eye on it (it only happened once now) and will collect logs in case it returns.

Regards,
Kristof.

xtofh

Okay, just had this happen again, here's the logs from that time.

All VPNs going down..

Feb 25 13:53:01 pfsense kernel: ovpns23: link state changed to DOWN
Feb 25 13:53:01 pfsense php-fpm[89891]: /rc.newwanip: rc.newwanip: Info: starting on ovpns19.
Feb 25 13:53:01 pfsense php-fpm[89891]: /rc.newwanip: rc.newwanip: on (IP address: 192.168.250.17) (interface: []) (real interface: ovpns19).
Feb 25 13:53:01 pfsense php-fpm[89891]: /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection -  ->  192.168.250.17 - Restarting packages.
Feb 25 13:53:01 pfsense check_reload_status: Starting packages
Feb 25 13:53:02 pfsense php-fpm[21603]: /rc.openvpn: OpenVPN: Resync server24 [CUST26] S2S
Feb 25 13:53:02 pfsense kernel: ovpns23: link state changed to UP
Feb 25 13:53:02 pfsense check_reload_status: rc.newwanip starting ovpns23
Feb 25 13:53:02 pfsense kernel: ovpns24: link state changed to DOWN
Feb 25 13:53:02 pfsense check_reload_status: Reloading filter

Our WAN interface.. (em1)

Feb 25 13:53:02 pfsense kernel: em1: Watchdog timeout -- resetting
Feb 25 13:53:02 pfsense kernel: em1: Queue(0) tdh = 801, hw tdt = 770
Feb 25 13:53:02 pfsense kernel: em1: TX(0) desc avail = 31,Next TX to Clean = 801

The rest of the VPNs going down. (we've got 30 or so)

Feb 25 13:53:02 pfsense php-fpm[21603]: /rc.openvpn: OpenVPN: Resync server25 [CUST25] S2S
Feb 25 13:53:02 pfsense kernel: ovpns24: link state changed to UP
Feb 25 13:53:02 pfsense check_reload_status: rc.newwanip starting ovpns24
Feb 25 13:53:02 pfsense kernel: ovpns25: link state changed to DOWN
Feb 25 13:53:02 pfsense kernel: em1: link state changed to DOWN
Feb 25 13:53:02 pfsense check_reload_status: Linkup starting em1
Feb 25 13:53:02 pfsense php-fpm[21603]: /rc.openvpn: OpenVPN: Resync server26 [CUST26] S2S
Feb 25 13:53:02 pfsense kernel: ovpns25: link state changed to UP
Feb 25 13:53:02 pfsense check_reload_status: rc.newwanip starting ovpns25
Feb 25 13:53:02 pfsense kernel: ovpns26: link state changed to DOWN
Feb 25 13:53:03 pfsense php-fpm[21603]: /rc.linkup: DEVD Ethernet detached event for wan
Feb 25 13:53:04 pfsense kernel: arpresolve: can't allocate llinfo for 81.82.192.1 on em1
Feb 25 13:53:04 pfsense kernel: arpresolve: can't allocate llinfo for 81.82.192.1 on em1
Feb 25 13:53:04 pfsense kernel: arpresolve: can't allocate llinfo for 81.82.192.1 on em1
Feb 25 13:53:04 pfsense kernel: arpresolve: can't allocate llinfo for 81.82.192.1 on em1

And then it continues with the can't allocate llinfo.

I tried disconnecting and re-connecting the network cable: no result.
I tried rebooting the cable modem: no result.

It did try getting a new DHCP address:


$ tcpdump -i em1 -n
14:04:25.808903 IP 81.82.209.44.68 > 255.255.255.255.67: BOOTP/DHCP, Request from 00:0d:88:cc:fa:2f, length 300
14:04:27.003202 IP 81.82.209.44.68 > 255.255.255.255.67: BOOTP/DHCP, Request from 00:0d:88:cc:fa:2f, length 300
14:04:31.003925 IP 81.82.209.44.68 > 255.255.255.255.67: BOOTP/DHCP, Request from 00:0d:88:cc:fa:2f, length 300
14:04:40.009358 IP 0.0.0.0.68 > 255.255.255.255.67: BOOTP/DHCP, Request from 00:0d:88:cc:fa:2f, length 300
14:04:41.009469 IP 0.0.0.0.68 > 255.255.255.255.67: BOOTP/DHCP, Request from 00:0d:88:cc:fa:2f, length 300
14:04:42.000206 IP 0.0.0.0.68 > 255.255.255.255.67: BOOTP/DHCP, Request from 00:0d:88:cc:fa:2f, length 300
14:04:44.001156 IP 0.0.0.0.68 > 255.255.255.255.67: BOOTP/DHCP, Request from 00:0d:88:cc:fa:2f, length 300

But that's it, never got any.

Final step we took (because it was taking us +5 minutes already) was reboot the pfsense. After the reboot connection was good..

I will probably take a 2.1.5 to temporarily switch this one out (luckily it's in our building) but will leave the 2.2 in place so I can switch easily.

So I there's anything I can/should try, let me know, no problem.

Regards,
Kristof

q54e3w

Id love to share with you a solution but Im seeing exactly the same thing here and can confirm its not fixed for me by manipulating DNS as TieT suggested fixed his. My issue is triggered by my ISP WAN dhcp address expiring every seven days. Rebooting the firewall is the easiest way to fix it, I spent a couple of hours last time it went down capturing packets and what not and it appears in my situation to be related to DHCP queries not syncing. It could be specific to my ISP and I'll keep capturing and investigating if/when it continues. Thanks for sharing your logs.

xtofh

I've put my 2.1.5 back in place. let's see how this goes. (I'm pretty sure this will stay up)

I also suspect it has something to do with the dhcp renewal.

2.1 solved it in 2012 for me :-) - https://forum.pfsense.org/index.php?topic=51420.0

stephenw10

Feb 25 13:53:02 pfsense kernel: em1: Watchdog timeout -- resetting

That is a pretty bad sign.

You might try looking at sysctl dev.em.1
There may be some error couters there that show something nasty happened.

Steve

xtofh

Ok, put a switch in between modem<->pfsense , recorded the current state of sysctl dev.em.1 (attached)

Currently it's good :o (lol) but if the problem returns I'll redo the sysctl dev.em.1 and won't reboot. (I'll just use a 2.1.5 device so can grab any logs needed of the 2.2)

Thanks, I'll keep you posted.

Kristof

devem1.txt

JWTech

I'm getting the same issue.

Seems my external IPv4, which is set by DHCP, is randomly disconnecting while the IPv6 address is fine.

No clue what's the cause, but I'm running the latest version on a Nano USB.

xtofh

Ok, not resolved yet :(

My current configuration is Modem <-> Switch <-> pfsense.

I did see some bad things in the sysctl.em.1 :

dev.em.1.mac_stats.collision_count: 0
dev.em.1.mac_stats.symbol_errors: 4294967295
dev.em.1.mac_stats.sequence_errors: 0
dev.em.1.mac_stats.missed_packets: 28403

My log was already full (I will make it bigger or use remote syslog) but I did see this:

.. first a ton of these messages:
Feb 28 11:21:04 pfsense kernel: arpresolve: can't allocate llinfo for 81.82.192.1 on em1
Feb 28 11:21:04 pfsense kernel: arpresolve: can't allocate llinfo for 81.82.192.1 on em1
Feb 28 11:21:04 pfsense kernel: arpresolve: can't allocate llinfo for 81.82.192.1 on em1
Feb 28 11:21:05 pfsense kernel: em1: Watchdog timeout -- resetting
Feb 28 11:21:05 pfsense kernel: em1: Queue(0) tdh = 0, hw tdt = 993
Feb 28 11:21:05 pfsense kernel: em1: TX(0) desc avail = 31,Next TX to Clean = 0
Feb 28 11:21:05 pfsense kernel: em1: link state changed to DOWN
Feb 28 11:21:05 pfsense check_reload_status: Linkup starting em1
Feb 28 11:21:06 pfsense php-fpm[43360]: /rc.linkup: DEVD Ethernet detached event for wan
Feb 28 11:21:06 pfsense kernel: arpresolve: can't allocate llinfo for 81.82.192.1 on em1
Feb 28 11:21:06 pfsense kernel: arpresolve: can't allocate llinfo for 81.82.192.1 on em1
Feb 28 11:21:09 pfsense check_reload_status: Linkup starting em1
Feb 28 11:21:09 pfsense kernel: em1: link state changed to UP
Feb 28 11:21:10 pfsense kernel: arpresolve: can't allocate llinfo for 81.82.192.1 on em1
Feb 28 11:21:10 pfsense kernel: arpresolve: can't allocate llinfo for 81.82.192.1 on em1
Feb 28 11:21:11 pfsense php-fpm[43360]: /rc.linkup: Shutting down Router Advertisment daemon cleanly
Feb 28 11:21:11 pfsense php-fpm[54180]: /rc.linkup: DEVD Ethernet attached event for wan
Feb 28 11:21:11 pfsense php-fpm[54180]: /rc.linkup: HOTPLUG: Configuring interface wan
Feb 28 11:21:13 pfsense kernel: arpresolve: can't allocate llinfo for 81.82.192.1 on em1
Feb 28 11:21:13 pfsense kernel: arpresolve: can't allocate llinfo for 81.82.192.1 on em1
Feb 28 11:21:14 pfsense kernel: arpresolve: can't allocate llinfo for 81.82.192.1 on em1
.. and then more of these

This only happens on 2.2, the same configuration with 2.1.5, no problem. It took about 30 hours before it occured the first time.

Anything else I might try to resolve/further pinpoint this?

Regards,
Kristof.

Derelict

New hardware?

xtofh

@Derelict:

New hardware?

No, only diiference: 2.1.5 -> 2.2.

Derelict

@man:

arpresolve: can't allocate llinfo for %d.%d.%d.%d The route for the ref-
erenced host points to a device upon which ARP is required, but ARP was
unable to allocate a routing table entry in which to store the host's MAC
address. This usually points to a misconfigured routing table. It can
also occur if the kernel cannot allocate memory.

What's in netstat -rn when it's failing?

JWTech

Just resolved my issue by disabling the local DNS resolution. Changed it to just use Google's DNS servers instead (8.8.8.8, 8.8.4.4) and it's working fine.

Not sure if it's the exact same issue as what everyone else has had, but that's what did it for me.

TieT

Test it for a few days, it worked for me for a few days, but then the gateway was lost again.
It seems when I create a vpn to my fw the issue begins…

@JWTech:

Just resolved my issue by disabling the local DNS resolution. Changed it to just use Google's DNS servers instead (8.8.8.8, 8.8.4.4) and it's working fine.

Not sure if it's the exact same issue as what everyone else has had, but that's what did it for me.

xtofh

@Derelict:

@man:

arpresolve: can't allocate llinfo for %d.%d.%d.%d The route for the ref-
erenced host points to a device upon which ARP is required, but ARP was
unable to allocate a routing table entry in which to store the host's MAC
address. This usually points to a misconfigured routing table. It can
also occur if the kernel cannot allocate memory.

What's in netstat -rn when it's failing?

Tnx for the suggestion, will try this and the sysctl dev.em.1 on next problem.

I'm waiting for it to occur again (it can take several hours but it might as well take 48 hours) and report back.

Kristof

stephenw10

I find it odd that in both cases here the actual physical link is going down. If that was a modem issue I would expect the switch to as least show a different result. I guess in a watchdog time-out scenario the link is probably brought down when the NIC is reset. Hmmm.

Steve