Wan interface not coming back up after failover

Valhalla1 · May 20, 2008, 6:08 AM

Does it bring back your cable connection if you enter " dhclient re0 " in console?

yep, this instantly brought the WAN online to the load balancer.

this time, while WAN was marked down on the loadbalancer, before I did anything I looked at the states, and active sessions on the WAN with 'iftop' and and even though the WAN was marked DOWN on the Load Balancer, there werestill active connections being used on the wan link. However no "new" traffic was being sent over it. Also I had the correct IP and interface was "Active" when I did "ifconfig".
After I issued 'dclient re0' from ssh, new traffic instantly started flowing over WAN as it was marked up by load balancer. the ip didn't change or anything

so it looks like its marking it down when its really not down, or perhaps I need to automate issuing "dhclient re0" when it detects WAN DOWN

any advice how to proceed? thanks for the help so far

Perry · May 20, 2008, 10:12 AM

Good. I've made a bug report http://cvstrac.pfsense.com/tktview?tn=1729
For now you could try using afterfilterchangeshellcmd for it.
http://forum.pfsense.org/index.php/topic,7808.msg46725.html#msg46725
change code to something like this.
#!/bin/sh
sleep 60
dhclient re0

cmb · May 20, 2008, 9:46 PM

@Perry:

But it has been recommend before to have something between a cable modem and pfSense.

The only time that's recommended is if you have two Internet connections using the same gateway IP, then it's the only way you can use multi-WAN. If that's not the case, as it isn't here, I wouldn't recommend doing that.

Valhalla1: when the cable modem goes down, what do you see on that interface in Status-> Interfaces? And what does your system log show?

Power cycling your cable modem just creates a link up event on pfSense, which runs dhclient on the interface, which appears to be the resolution. It shouldn't ever need to be manually run though, which is why we need to know what the interface and logs are showing. Without that info there's no telling what is actually happening, and no way we can fix it.

Valhalla1 · May 22, 2008, 10:12 PM

I implemented the <afterfilterchangeshellcmd> to run a script
#!/bin/sh
sleep 60
dhclient re0

this now seems to be keeping the WAN connection online to the load balancer, however it seems to be running literally every 2 minutes… the system logs are now filling up with dhcp requests over the cable connection.

I'm out of town unfortunately at the moment so I can't troubleshoot this as easily. my users are not reporting internet problems however, even with the constant dhcp requests. However my VPN connection to pfsense does die briefly every couple mins.
maybe this will work till get I get back onsite in a couple weeks, then I'll un-implement that afterfilterchangesshellcmd script and allow the connection to show "DOWN" so I can let you know what the system logs and interface page look like

kinda dont want to let the WAN connection stay down right now as then I wont be able to vpn in unless I call up a user to go reboot the modem for me</afterfilterchangeshellcmd>

Valhalla1 · May 22, 2008, 10:21 PM

May 22 15:11:45 	slbd[5169]: ICMP poll succeeded for 65.41.120.51, marking service UP
May 22 15:11:45 	slbd[5169]: ICMP poll succeeded for 68.105.28.11, marking service UP
May 22 15:11:45 	slbd[5169]: ICMP poll succeeded for 68.105.28.11, marking service UP
May 22 15:11:45 	slbd[5169]: ICMP poll succeeded for 65.41.120.51, marking service UP
May 22 15:11:45 	check_reload_status: reloading filter
May 22 15:11:45 	slbd[5169]: ICMP poll succeeded for 65.41.120.51, marking service UP
May 22 15:11:45 	slbd[5169]: ICMP poll succeeded for 68.105.28.11, marking service UP
May 22 15:11:45 	php: : Configuring slbd
May 22 15:11:42 	dnsmasq[1582]: using nameserver 68.105.28.11#53
May 22 15:11:42 	dnsmasq[1582]: using nameserver 68.105.29.11#53
May 22 15:11:42 	dnsmasq[1582]: using nameserver 68.105.28.12#53
May 22 15:11:42 	dnsmasq[1582]: reading /etc/resolv.conf
May 22 15:11:42 	php: : Creating rrd update script
May 22 15:11:41 	php: : Informational: DHClient spawned /etc/rc.newwanip and the new ip is wan - 68.224.153.16.
May 22 15:11:36 	php: : rc.newwanip working with (IP address: 68.224.153.16) (interface: wan) (interface real: re0).
May 22 15:11:36 	php: : Informational: rc.newwanip is starting re0.
May 22 15:11:35 	check_reload_status: rc.newwanip starting
May 22 15:11:30 	php: : phpDynDNS: No Change In My IP Address and/or 25 Days Has Not Past. Not Updating Dynamic DNS Entry.
May 22 15:11:30 	php: : DynDns: Cached IP: 68.224.153.16
May 22 15:11:30 	php: : DynDns: Current WAN IP: 68.224.153.16
May 22 15:11:30 	php: : DynDns: _detectChange() starting.
May 22 15:11:30 	php: : DynDns: updatedns() starting
May 22 15:11:30 	php: : DynDns: Running updatedns()
May 22 15:11:28 	check_reload_status: updating dyndns
May 22 15:11:27 	last message repeated 2 times
May 22 15:11:28 	dhclient[4779]: bound to 68.224.153.16 -- renewal in 43200 seconds.
May 22 15:11:27 	dhclient[4779]: DHCPACK from 68.224.153.1
May 22 15:11:27 	kernel: arpresolve: can't allocate route for 68.224.153.1
May 22 15:11:27 	slbd[3737]: Service LoadBalance changed status, reloading filter policy
May 22 15:11:27 	slbd[3737]: Service WAN2FailsToWAN1 changed status, reloading filter policy
May 22 15:11:27 	slbd[3737]: ICMP poll failed for 68.105.28.11, marking service DOWN
May 22 15:11:27 	slbd[3737]: ICMP poll failed for 68.105.28.11, marking service DOWN
May 22 15:11:27 	slbd[3737]: Service WAN1FailsToWAN2 changed status, reloading filter policy
May 22 15:11:27 	slbd[3737]: ICMP poll failed for 68.105.28.11, marking service DOWN
May 22 15:11:27 	kernel: arpresolve: can't allocate route for 68.224.153.1
May 22 15:11:26 	dhclient[3377]: exiting.
May 22 15:11:26 	dhclient[3377]: exiting.
May 22 15:11:26 	dhclient[3377]: connection closed
May 22 15:11:26 	dhclient[3377]: connection closed
May 22 15:11:26 	dhclient[4779]: DHCPREQUEST on re0 to 255.255.255.255 port 67
May 22 15:11:26 	kernel: arpresolve: can't allocate route for 68.224.153.1
May 22 15:10:21 	slbd[3737]: ICMP poll succeeded for 65.41.120.51, marking service UP
May 22 15:10:21 	slbd[3737]: ICMP poll succeeded for 68.105.28.11, marking service UP
May 22 15:10:21 	slbd[3737]: ICMP poll succeeded for 68.105.28.11, marking service UP
May 22 15:10:21 	slbd[3737]: ICMP poll succeeded for 65.41.120.51, marking service UP
May 22 15:10:21 	slbd[3737]: ICMP poll succeeded for 65.41.120.51, marking service UP
May 22 15:10:21 	check_reload_status: reloading filter
May 22 15:10:21 	slbd[3737]: ICMP poll succeeded for 68.105.28.11, marking service UP
May 22 15:10:20 	php: : Configuring slbd
May 22 15:10:18 	dnsmasq[1582]: using nameserver 68.105.28.11#53

there's 1 mins worth of the logs, but this basically repeats itself every minute or two.. at least the connections staying online to the load balancer and my users aren't reporting any problems

Valhalla1 · May 23, 2008, 11:14 PM

so I guess it seems that the script I put in afterfilterchangesshellcmd is running like constantly.. its set to sleep 60 then issue dhclient re0, and seemingly every 1 minute its indeed running. it seems to just abitrarily run it 24/7 as it waits 60 seconds (sleep 60) then the dhcp refreshes on WAN which among other things nukes my vpn connection going over wan

I was hoping it would only run this when it detects WAN is down

I should take this out and let things happen as they happen so we can troubleshoot the actual problem instead of this workaround hack but first I need to get openvpn working on the opt1 wan connection so I can access the box still when wan goes down

Perry · May 23, 2008, 11:54 PM

Yeah dhclient must trick afterfilter….. My initiate idea was a cron job but found it wrong to make that loop :-[

BTW Did you ever try replacing the nic?

ilko · May 24, 2008, 2:09 AM

If that helps- in our machine when we had 3 the same NICs it was going crazy in a similar way when 2 WANs were up. Every minute or so WANs were going up and down. If only one WAN is up things were fine. Plug back the second WAN cable- goes crazy again.
Changing either of the NICs with another brand resolved the problem. Put back the removed NIC, replacing a similar one- no issues, so it wasn't a faulty NIC.

Valhalla1 · May 24, 2008, 2:48 AM

@Perry:

Yeah dhclient must trick afterfilter….. My initiate idea was a cron job but found it wrong to make that loop :-[

BTW Did you ever try replacing the nic?
[/quote]

can't replace the nic on this particular box, as its custom hardware, watchguard firebox x500 with 6 onboard realtek nics

it could very well be hardware related, but I haven't seen similar reports from people that have the same hardware I do.. although I don't know if they are running dual wan

I guess when I get back in town I will try a few diff things, worst case scenario I'll load up a generic pc with different nics and see if it does the same thing as the watchguard hardware

olaf · May 30, 2008, 5:33 AM

Hi:

I'm having the same issues Valhalla1 has. But I have complete different hardware:

vr0: flags=8843 <up,broadcast,running,simplex,multicast>mtu 1500
        inet 192.168.4.2 netmask 0xffffff00 broadcast 192.168.4.255
        inet6 fe80::206:25ff:fe07:a43f%vr0 prefixlen 64 scopeid 0x1
        ether 00:06:25:07:a4:3f
        media: Ethernet autoselect (10baseT/UTP)
        status: active
vr1: flags=8943 <up,broadcast,running,promisc,simplex,multicast>mtu 1500
        inet 192.168.5.1 netmask 0xffffff00 broadcast 192.168.5.255
        inet6 fe80::20c:41ff:fee7:903a%vr1 prefixlen 64 scopeid 0x2
        ether 00:0c:41:e7:90:3a
        media: Ethernet autoselect (100baseTX <full-duplex>)
        status: active
dc0: flags=8843 <up,broadcast,running,simplex,multicast>mtu 1500
        options=8 <vlan_mtu>inet 10.34.89.2 netmask 0xffffff00 broadcast 10.34.89.255
        inet6 fe80::20c:41ff:fe22:d97%dc0 prefixlen 64 scopeid 0x3
        ether 00:0c:41:22:0d:97
        media: Ethernet autoselect (100baseTX <full-duplex>)
        status: active
vr2: flags=8843 <up,broadcast,running,simplex,multicast>mtu 1500
        inet6 fe80::20f:eaff:fe14:8d61%vr2 prefixlen 64 scopeid 0x4
        inet 192.168.6.2 netmask 0xffffff00 broadcast 192.168.6.255
        ether 00:0f:ea:14:8d:61
        media: Ethernet autoselect (100baseTX <full-duplex>)
        status: active</full-duplex></up,broadcast,running,simplex,multicast></full-duplex></vlan_mtu></up,broadcast,running,simplex,multicast></full-duplex></up,broadcast,running,promisc,simplex,multicast></up,broadcast,running,simplex,multicast>

That is the hardware.

vr0 is the Opt1 interface.
vr1 is the Lan interface.
dc0 is connected to a VPN.
vr2 is the WAN interface.

WAN and Opt1 are in a Load Balance (actually in FailOver due to problems with sticky connections).

And this is the log of last WAN down in loadbalance:

May 29 17:22:29 	slbd[81452]: Service Balancer changed status, reloading filter policy
May 29 17:22:29 	slbd[81452]: ICMP poll succeeded for 87.217.47.1, marking service UP
May 29 17:12:32 	slbd[81452]: ICMP poll succeeded for 87.235.0.10, marking service UP
May 29 17:12:32 	slbd[81452]: ICMP poll failed for 87.217.47.1, marking service DOWN
May 29 17:12:32 	slbd[81452]: VIP 127.0.0.1:666 added real service 87.235.0.10:666
May 29 17:12:32 	slbd[81452]: VIP 127.0.0.1:666 added real service 87.217.47.1:666
May 29 17:12:32 	slbd[81452]: VIP 127.0.0.1:666 sitedown at 127.0.0.1:666
May 29 17:12:32 	slbd[81452]: VIP 127.0.0.1:666 configured as "127.0.0.1"
May 29 17:12:32 	slbd[81452]: Using configuration file /var/etc/slbd.conf
May 29 17:12:32 	slbd[81452]: Using r_refresh of 5000 milliseconds
May 29 14:31:10 	slbd[358]: Service Balancer changed status, reloading filter policy
May 29 14:31:10 	slbd[358]: ICMP poll failed for 87.217.47.1, marking service DOWN

As you can see, at 14:31 the WAN interface is marked as down.

At 17 I saw the interface down in load balancer status, then I reboot the Cisco 857 that is connected to WAN interface. I see ADSL Link of router is up after reboot, but the WAN interface of load balancer not up.

Other times, I reconfig the load balancer pool with "text change" to force reload of pool status. But this time indeed that not up the WAN interface. See at 17:12:32.

Then I decided to down interface vr2 (ifconfig vr2 down), and up again.

May 29 17:22:29 	check_reload_status: reloading filter
May 29 17:22:29 	slbd[81452]: Service Balancer changed status, reloading filter policy
May 29 17:22:29 	slbd[81452]: ICMP poll succeeded for 87.217.47.1, marking service UP
May 29 17:22:25 	kernel: vr2: Using force reset command.
May 29 17:13:31 	sshd[81903]: Accepted keyboard-interactive/pam for root from 192.168.0.8 port 44027 ssh2
May 29 17:12:32 	slbd[81452]: ICMP poll succeeded for 87.235.0.10, marking service UP
May 29 17:12:32 	slbd[81452]: ICMP poll failed for 87.217.47.1, marking service DOWN
May 29 17:12:31 	check_reload_status: reloading filter

Actually, do you think that these problems may be caused by the fact of using same drivers in interface hardware?

I could try to change the hardware if you are certainly sure that it is the root cause.

Please, all advices are wellcome…

Best regards,

Olaf

Valhalla1 · Jun 9, 2008, 7:31 PM

well I've since placed a soekris net4501 running m0n0wall in between my cable modem and the WAN interface on my pfsense loadbalancer and now the WAN connection seems to stay online
only concern is my cable connection I've seen burst up to 20mbit/sec speeds, and hopefully the net4501 won't bottleneck that

olaf · Jun 10, 2008, 1:44 PM

Hi Valhalla:

You can setup static routes en general config, but don't forget to permit that routes in firewall. Also you can force the route to out through the wan interface (put these routes before the loadbalance route which shoul be the last one).

I hope some developer could tell us why the interface is not backing up when the link is recover.

I have time to troubleshoot these issues.

Regards,

Olaf