WAN connection eventually dies after couple of days

JohnnyBeGood · Jul 20, 2011, 1:47 AM

Hi all,

Before I did clean install of 2.0-RC3 four days ago I used to upgrade between each RC and I believe after RC1 this issue started to happen.
Basically what happens is that WAN connection dies and I loose internet. Initially I thought there was problem with my ISP but no
all what it takes is to reboot pfSense and internet is back on.
Any idea what I should look for?
I thought fresh install will fix things but still no joy.

Thanks in advance!

Here's the system log:


Jul 19 18:16:50 	php: : The command '/sbin/dhclient -c /var/etc/dhclient_wan.conf em1 > /tmp/em1_output > /tmp/em1_error_output' returned exit code '15', the output was ''
Jul 19 18:16:51 	kernel: arpresolve: can't allocate llinfo for 24.17.112.1
Jul 19 18:16:51 	check_reload_status: Linkup starting em1
Jul 19 18:16:51 	kernel: em1: link state changed to UP
Jul 19 18:16:51 	dhclient: PREINIT
Jul 19 18:16:51 	kernel: arpresolve: can't allocate llinfo for 24.17.112.1
Jul 19 18:16:51 	dhclient[49986]: DHCPREQUEST on em1 to 255.255.255.255 port 67
Jul 19 18:16:52 	dhclient[49986]: DHCPREQUEST on em1 to 255.255.255.255 port 67
Jul 19 18:16:52 	kernel: arpresolve: can't allocate llinfo for 24.17.112.1
Jul 19 18:16:52 	kernel: arpresolve: can't allocate llinfo for 24.17.112.1
Jul 19 18:16:53 	kernel: arpresolve: can't allocate llinfo for 24.17.112.1
Jul 19 18:16:54 	php: : DEVD Ethernet attached event for wan
Jul 19 18:16:54 	php: : HOTPLUG: Configuring interface wan
Jul 19 18:16:54 	dhclient[49986]: DHCPREQUEST on em1 to 255.255.255.255 port 67
Jul 19 18:16:54 	kernel: em1: link state changed to DOWN
Jul 19 18:16:54 	check_reload_status: Linkup starting em1
Jul 19 18:16:55 	kernel: arpresolve: can't allocate llinfo for 24.17.112.1
Jul 19 18:16:56 	php: : DEVD Ethernet detached event for wan
Jul 19 18:16:56 	dhclient[51468]: connection closed
Jul 19 18:16:56 	dhclient[51468]: connection closed
Jul 19 18:16:56 	dhclient[51468]: exiting.
Jul 19 18:16:56 	dhclient[51468]: exiting.
Jul 19 18:16:56 	php: : The command '/sbin/dhclient -c /var/etc/dhclient_wan.conf em1 > /tmp/em1_output > /tmp/em1_error_output' returned exit code '15', the output was ''
Jul 19 18:16:57 	check_reload_status: Linkup starting em1
Jul 19 18:16:57 	kernel: em1: link state changed to UP
Jul 19 18:16:57 	dhclient: PREINIT
Jul 19 18:16:57 	dhclient[55023]: DHCPREQUEST on em1 to 255.255.255.255 port 67
Jul 19 18:16:57 	dhclient[55023]: DHCPREQUEST on em1 to 255.255.255.255 port 67
Jul 19 18:16:59 	dhclient[55023]: DHCPREQUEST on em1 to 255.255.255.255 port 67
Jul 19 18:16:59 	kernel: arpresolve: can't allocate llinfo for 24.17.112.1
Jul 19 18:16:59 	php: : DEVD Ethernet attached event for wan
Jul 19 18:16:59 	php: : HOTPLUG: Configuring interface wan
Jul 19 18:16:59 	check_reload_status: Linkup starting em1
Jul 19 18:16:59 	kernel: em1: link state changed to DOWN
Jul 19 18:17:02 	php: : DEVD Ethernet detached event for wan
Jul 19 18:17:02 	dhclient[56561]: connection closed
Jul 19 18:17:02 	dhclient[56561]: connection closed
Jul 19 18:17:02 	dhclient[56561]: exiting.
Jul 19 18:17:02 	dhclient[56561]: exiting.
Jul 19 18:17:02 	php: : The command '/sbin/dhclient -c /var/etc/dhclient_wan.conf em1 > /tmp/em1_output > /tmp/em1_error_output' returned exit code '15', the output was ''
Jul 19 18:17:02 	kernel: arpresolve: can't allocate llinfo for 24.17.112.1
Jul 19 18:17:03 	kernel: arpresolve: can't allocate llinfo for 24.17.112.1
Jul 19 18:17:03 	kernel: arpresolve: can't allocate llinfo for 24.17.112.1
Jul 19 18:17:04 	check_reload_status: Linkup starting em1
Jul 19 18:17:04 	kernel: em1: link state changed to UP
Jul 19 18:17:04 	dhclient: PREINIT
Jul 19 18:17:04 	kernel: arpresolve: can't allocate llinfo for 24.17.112.1
Jul 19 18:17:04 	dhclient[60647]: DHCPREQUEST on em1 to 255.255.255.255 port 67
Jul 19 18:17:04 	dhclient[60647]: DHCPREQUEST on em1 to 255.255.255.255 port 67
Jul 19 18:17:05 	kernel: arpresolve: can't allocate llinfo for 24.17.112.1
Jul 19 18:17:06 	php: : DEVD Ethernet attached event for wan
Jul 19 18:17:06 	php: : HOTPLUG: Configuring interface wan
Jul 19 18:17:06 	check_reload_status: Linkup starting em1
Jul 19 18:17:06 	kernel: em1: link state changed to DOWN
Jul 19 18:17:06 	kernel: arpresolve: can't allocate llinfo for 24.17.112.1
Jul 19 18:17:07 	dhclient[60647]: DHCPREQUEST on em1 to 255.255.255.255 port 67
Jul 19 18:17:07 	kernel: arpresolve: can't allocate llinfo for 24.17.112.1
Jul 19 18:17:09 	php: : DEVD Ethernet detached event for wan
Jul 19 18:17:09 	dhclient[467]: connection closed
Jul 19 18:17:09 	dhclient[467]: connection closed
Jul 19 18:17:09 	dhclient[467]: exiting.
Jul 19 18:17:09 	dhclient[467]: exiting.
Jul 19 18:17:09 	php: : The command '/sbin/dhclient -c /var/etc/dhclient_wan.conf em1 > /tmp/em1_output > /tmp/em1_error_output' returned exit code '15', the output was ''
Jul 19 18:17:11 	check_reload_status: Linkup starting em1
Jul 19 18:17:11 	kernel: em1: link state changed to UP
Jul 19 18:17:11 	dhclient: PREINIT
Jul 19 18:17:11 	dhclient[2444]: DHCPREQUEST on em1 to 255.255.255.255 port 67
Jul 19 18:17:12 	dhclient[2444]: DHCPREQUEST on em1 to 255.255.255.255 port 67
Jul 19 18:17:13 	php: : DEVD Ethernet attached event for wan
Jul 19 18:17:13 	php: : HOTPLUG: Configuring interface wan
Jul 19 18:17:13 	check_reload_status: Linkup starting em1
Jul 19 18:17:13 	kernel: em1: link state changed to DOWN
Jul 19 18:17:14 	dhclient[2444]: DHCPREQUEST on em1 to 255.255.255.255 port 67
Jul 19 18:17:16 	dhclient[2444]: DHCPREQUEST on em1 to 255.255.255.255 port 67
Jul 19 18:17:16 	php: : DEVD Ethernet detached event for wan
Jul 19 18:17:16 	dhclient[4641]: connection closed
Jul 19 18:17:16 	dhclient[4641]: connection closed
Jul 19 18:17:16 	dhclient[4641]: exiting.
Jul 19 18:17:16 	dhclient[4641]: exiting.
Jul 19 18:17:16 	php: : The command '/sbin/dhclient -c /var/etc/dhclient_wan.conf em1 > /tmp/em1_output > /tmp/em1_error_output' returned exit code '15', the output was ''
Jul 19 18:17:16 	kernel: arpresolve: can't allocate llinfo for 24.17.112.1
Jul 19 18:17:17 	check_reload_status: Linkup starting em1
Jul 19 18:17:17 	kernel: arpresolve: can't allocate llinfo for 24.17.112.1
Jul 19 18:17:17 	kernel: em1: link state changed to UP
Jul 19 18:17:18 	dhclient: PREINIT
Jul 19 18:17:18 	dhclient[7407]: DHCPREQUEST on em1 to 255.255.255.255 port 67
Jul 19 18:17:18 	dhclient[7407]: DHCPREQUEST on em1 to 255.255.255.255 port 67
Jul 19 18:17:18 	kernel: arpresolve: can't allocate llinfo for 24.17.112.1
Jul 19 18:17:19 	kernel: arpresolve: can't allocate llinfo for 24.17.112.1
Jul 19 18:17:20 	php: : DEVD Ethernet attached event for wan
Jul 19 18:17:20 	php: : HOTPLUG: Configuring interface wan
Jul 19 18:17:20 	dhclient[7407]: DHCPREQUEST on em1 to 255.255.255.255 port 67
Jul 19 18:17:20 	check_reload_status: Linkup starting em1
Jul 19 18:17:20 	kernel: em1: link state changed to DOWN
Jul 19 18:17:20 	kernel: arpresolve: can't allocate llinfo for 24.17.112.1
Jul 19 18:17:22 	php: : DEVD Ethernet detached event for wan
Jul 19 18:17:22 	dhclient[11505]: connection closed
Jul 19 18:17:22 	dhclient[11505]: connection closed
Jul 19 18:17:22 	dhclient[11505]: exiting.
Jul 19 18:17:22 	dhclient[11505]: exiting.
Jul 19 18:17:22 	php: : The command '/sbin/dhclient -c /var/etc/dhclient_wan.conf em1 > /tmp/em1_output > /tmp/em1_error_output' returned exit code '15', the output was ''
Jul 19 18:17:23 	check_reload_status: Linkup starting em1
Jul 19 18:17:23 	kernel: em1: link state changed to UP
Jul 19 18:17:23 	dhclient: PREINIT
Jul 19 18:17:23 	dhclient[13903]: DHCPREQUEST on em1 to 255.255.255.255 port 67
Jul 19 18:17:23 	dhclient[13903]: DHCPREQUEST on em1 to 255.255.255.255 port 67
Jul 19 18:17:25 	php: /index.php: Successful webConfigurator login for user 'admin' from 192.168.1.108
Jul 19 18:17:25 	php: /index.php: Successful webConfigurator login for user 'admin' from 192.168.1.108
Jul 19 18:17:25 	dhclient[13903]: DHCPREQUEST on em1 to 255.255.255.255 port 67
Jul 19 18:17:25 	php: : DEVD Ethernet attached event for wan
Jul 19 18:17:25 	php: : HOTPLUG: Configuring interface wan
Jul 19 18:17:26 	kernel: em1: link state changed to DOWN
Jul 19 18:17:26 	check_reload_status: Linkup starting em1
Jul 19 18:17:28 	php: : DEVD Ethernet detached event for wan
Jul 19 18:17:28 	dhclient[15224]: connection closed
Jul 19 18:17:28 	dhclient[15224]: connection closed
Jul 19 18:17:28 	dhclient[15224]: exiting.
Jul 19 18:17:28 	dhclient[15224]: exiting.
Jul 19 18:17:28 	php: : The command '/sbin/dhclient -c /var/etc/dhclient_wan.conf em1 > /tmp/em1_output > /tmp/em1_error_output' returned exit code '15', the output was ''
Jul 19 18:17:30 	check_reload_status: Linkup starting em1
Jul 19 18:17:30 	kernel: em1: link state changed to UP
Jul 19 18:17:30 	kernel: arpresolve: can't allocate llinfo for 24.17.112.1
Jul 19 18:17:31 	dhclient: PREINIT
Jul 19 18:17:31 	dhclient[27439]: DHCPREQUEST on em1 to 255.255.255.255 port 67
Jul 19 18:17:31 	dhclient[27439]: DHCPREQUEST on em1 to 255.255.255.255 port 67
Jul 19 18:17:31 	kernel: arpresolve: can't allocate llinfo for 24.17.112.1
Jul 19 18:17:31 	kernel: arpresolve: can't allocate llinfo for 24.17.112.1

casinmirad · Jul 20, 2011, 12:19 PM

kernel: arpresolve: can't allocate llinfo for 24.17.112.1

Is your System>Advanced>Miscellaneous>Sticky connections setting enabled?

It's been reported many times that this setting doesn't work at all and cause internet loss after some time.

JohnnyBeGood · Jul 20, 2011, 2:41 PM

@casinmirad:

kernel: arpresolve: can't allocate llinfo for 24.17.112.1
Is your System>Advanced>Miscellaneous>Sticky connections setting enabled?

It's been reported many times that this setting doesn't work at all and cause internet loss after some time.

Thanks for the reply!

No, I do not have it enabled. Please see attached.
Any other ideas?

JohnnyBeGood · Jul 22, 2011, 7:03 AM

Anyone?

cmb · Jul 22, 2011, 7:48 AM

you using MAC spoofing on WAN by chance?

JohnnyBeGood · Jul 22, 2011, 2:33 PM

@cmb:

you using MAC spoofing on WAN by chance?

Yes, I am. Turn it off?

cmb · Jul 22, 2011, 6:09 PM

Yeah turn it off and that will stop, dhclient has issues with MAC spoofing for an undetermined reason in the underlying OS, ticket opened to check if it's still an issue in 9 and if so we'll report it upstream.

JohnnyBeGood · Jul 22, 2011, 7:42 PM

@cmb:

Yeah turn it off and that will stop, dhclient has issues with MAC spoofing for an undetermined reason in the underlying OS, ticket opened to check if it's still an issue in 9 and if so we'll report it upstream.

I will turn it off and if the same issue happens again I'll post it here.

cmb · Jul 22, 2011, 11:08 PM

Take the MAC out, then reboot to make sure. Not sure why you're seeing it that frequently, I ran that way for almost 2 years on 2.0 and only hit it 3 times, but it was eventually annoying enough I just took it off my DHCP WAN. But I'm sure that'll fix it, unless there's some other reason you start losing link on that NIC.

JohnnyBeGood · Jul 23, 2011, 7:33 AM

@cmb:

Take the MAC out, then reboot to make sure. Not sure why you're seeing it that frequently, I ran that way for almost 2 years on 2.0 and only hit it 3 times, but it was eventually annoying enough I just took it off my DHCP WAN. But I'm sure that'll fix it, unless there's some other reason you start losing link on that NIC.

I took the MAC out and rebooted modem + pfSense. Out of curiosity how did you figure out that spoofing was causing this issue? Any links to the ticket?

cmb · Jul 23, 2011, 7:30 PM

@JohnnyBeGood:

Out of curiosity how did you figure out that spoofing was causing this issue? Any links to the ticket?

I saw link cycling in your logs, and short of a physical cabling, modem or NIC issue that would cause that, which would probably be unlikely given a reboot makes it go away, it matches that issue.
http://redmine.pfsense.org/issues/1572

JohnnyBeGood · Jul 24, 2011, 2:55 AM

Thanks!

I replied to that post confirming same issue. Hopefully it gets fixed in the next release.
I'm glad that I have "stable" system not worrying when WAN connection will go down :)

shadow · Aug 2, 2011, 4:11 AM

Huh. I wonder if this (http://forum.pfsense.org/index.php/topic,36643.0.html) is this. Because, well, I am spoofing. I'll tweak and check it out.

JohnnyBeGood · Aug 2, 2011, 5:18 AM

So, far it's been running great and WAN its not dying like before. This is definitely a bug. Turning off mac spoofing fixed my problem.

Thanks guys!

shadow · Aug 12, 2011, 8:30 PM

Turned off spoofing (i was spoofing my real mac for some reason; i don't remember enabling this, but…) and now all is well. no more ~daily dropping offline on the wan.

GoldServe · Aug 15, 2011, 5:11 AM

Can anyone figure out what is causing the link to cycle when mac spoofing? I kind of need mac spoofing and this is a serious issue that requires a reboot!

jimp · Aug 18, 2011, 2:34 PM

There is an open ticket for it. I'm not sure if anyone has been able to track it down yet.

Most people only need MAC spoofing for a short-term fix (ARP cache issues, upstream equipment, etc) and once the situation resolves itself, they remove the spoofing.

tha_toadman · Aug 21, 2011, 6:06 AM

This issue has been a problem for me as of late. It may have been there when I upgraded to RC3 but only until recently have I noticed it.

I'm set for DHCP from my ISP with no MAC spoofing and every couple of days I'll randomly just get a DHCP failure on my boxes and my WAN connectivity drops out. I've had to release/renew to regain connectivity. I looked into the logs and I have an "apinger" entry that occurs around the same time as the DHCP trouble on my LAN. I failed to check tonight but typically this leads to a 169 IP (before the release/renew).


Aug 21 00:20:05 	apinger: alarm canceled: WAN(x.x.x.x) *** down ***
Aug 21 00:14:41 	check_reload_status: Reloading filter
Aug 21 00:14:31 	apinger: ALARM: WAN(x.x.x.x) *** down ***
Aug 20 21:49:55 	dhclient: Creating resolv.conf

FWIW, I saw another post mentioning the apinger issue and he was using the same modem that I am which is an SB6120. Perhaps there is an issue with this modem and pfSense? I can tell you that with this modem downstreams are bonded together for improved bandwidth. I'm not sure if that could be something of concern but I thought I would mention it.

Here is the post I was referring to…
http://forum.pfsense.org/index.php/topic,39205.msg202106.html#msg202106