WAN flaps when cable disconnected

eri-- · Dec 2, 2014, 10:33 AM

Can you please test with a next snapshot coming!
I pushed fixes to avoid this so it should behave better.

pnwbob · Dec 3, 2014, 7:45 AM

Is this snapshot recent enough? https://snapshots.pfsense.org/FreeBSD_releng/10.1/i386/pfSense_HEAD/updates/pfSense-Full-Update-2.2-BETA-i386-20141201-1400.tgz. Or should I wait for a newer one?

Thanks for the heads up,
-Bob

eri-- · Dec 3, 2014, 8:58 AM

Just catch the today one

pnwbob · Dec 4, 2014, 8:29 AM

After a slight detour by downloading the wrong arch :-[ I think I'm up and working. I'm able to unplug the WAN ethernet cable and the system comes back when I plug it back in.

This is the version info:
2.2-BETA (i386)
built on Wed Dec 03 22:28:13 CST 2014
FreeBSD 10.1-RELEASE

Thanks for fixing this and helping me out,
-Bob

dr.diesel · Dec 4, 2014, 2:58 PM

I'm having this same issue, with Dec 4th update. If I yank the Ethernet cable or simply release the WAN connection (WAN is DHCP).

Perfectly repeatable, happy to test provide further info.

2.2-BETA (amd64)
built on Thu Dec 04 07:06:21 CST 2014
FreeBSD 10.1-RELEASE

IPs replaced with ???

Dec 4 09:51:00 kernel: arpresolve: can't allocate llinfo for ???.???.???.??? on re0
Dec 4 09:51:00 kernel: arpresolve: can't allocate llinfo for ???.???.???.??? on re0
Dec 4 09:51:00 kernel: arpresolve: can't allocate llinfo for ???.???.???.??? on re0
Dec 4 09:51:00 kernel: arpresolve: can't allocate llinfo for ???.???.???.??? on re0
Dec 4 09:51:00 kernel: arpresolve: can't allocate llinfo for ???.???.???.??? on re0
Dec 4 09:51:00 kernel: re0: link state changed to DOWN
Dec 4 09:51:00 check_reload_status: Linkup starting re0
Dec 4 09:51:00 php-fpm[87600]: /rc.linkup: HOTPLUG: Configuring interface wan
Dec 4 09:51:00 php-fpm[87600]: /rc.linkup: DEVD Ethernet attached event for wan
Dec 4 09:50:59 php-fpm[94867]: /rc.start_packages: No pfBlocker action during boot process.
Dec 4 09:50:59 check_reload_status: Syncing firewall
Dec 4 09:50:59 check_reload_status: Syncing firewall
Dec 4 09:50:59 kernel: Bump sched buckets to 256 (was 0)
Dec 4 09:50:59 kernel: Bump sched buckets to 256 (was 0)
Dec 4 09:50:59 php-fpm[94867]: /rc.start_packages: The command 'ln -s /usr/local/bin/perl /usr/bin/perl' returned exit code '1', the output was 'ln: /usr/bin/perl: File exists'
Dec 4 09:50:59 php-fpm[53090]: /rc.linkup: DEVD Ethernet detached event for wan
Dec 4 09:50:59 check_reload_status: updating dyndns wan
Dec 4 09:50:59 php-fpm[94867]: /rc.start_packages: Restarting/Starting all packages.
Dec 4 09:50:58 check_reload_status: Reloading filter
Dec 4 09:50:58 check_reload_status: Starting packages
Dec 4 09:50:58 php-fpm[94867]: /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - ???.???.???.??? -> ???.???.???.??? - Restarting packages.
Dec 4 09:50:56 php-fpm[94867]: /rc.newwanip: Creating rrd update script
Dec 4 09:50:56 php-fpm[94867]: /rc.newwanip: Resyncing OpenVPN instances for interface WAN.
Dec 4 09:50:56 php-fpm[94867]: /rc.newwanip: ROUTING: setting default route to ???.???.???.???
Dec 4 09:50:56 php-fpm[94867]: /rc.newwanip: rc.newwanip: on (IP address: ???.???.???.???) (interface: WAN[wan]) (real interface: re0).
Dec 4 09:50:56 php-fpm[94867]: /rc.newwanip: rc.newwanip: Info: starting on re0.
Dec 4 09:50:55 php-fpm[45185]: /rc.linkup: ROUTING: setting default route to ???.???.???.???
Dec 4 09:50:55 check_reload_status: rc.newwanip starting re0
Dec 4 09:50:55 kernel: arpresolve: can't allocate llinfo for ???.???.???.??? on re0
Dec 4 09:50:54 kernel: re0: link state changed to UP
Dec 4 09:50:54 check_reload_status: Linkup starting re0
Dec 4 09:50:52 kernel: arpresolve: can't allocate llinfo for ???.???.???.??? on re0
Dec 4 09:50:51 kernel: arpresolve: can't allocate llinfo for ???.???.???.??? on re0
Dec 4 09:50:51 kernel: re0: link state changed to DOWN
Dec 4 09:50:51 check_reload_status: Linkup starting re0
Dec 4 09:50:50 php-fpm[45185]: /rc.linkup: HOTPLUG: Configuring interface wan
Dec 4 09:50:50 php-fpm[45185]: /rc.linkup: DEVD Ethernet attached event for wan
Dec 4 09:50:50 kernel: Bump sched buckets to 256 (was 0)
Dec 4 09:50:50 kernel: Bump sched buckets to 256 (was 0)
Dec 4 09:50:50 php-fpm[53090]: /rc.start_packages: No pfBlocker action during boot process.
Dec 4 09:50:50 check_reload_status: Syncing firewall
Dec 4 09:50:50 check_reload_status: Syncing firewall
Dec 4 09:50:50 php-fpm[53090]: /rc.start_packages: The command 'ln -s /usr/local/bin/perl /usr/bin/perl' returned exit code '1', the output was 'ln: /usr/bin/perl: File exists'
Dec 4 09:50:50 php-fpm[53090]: /rc.start_packages: Restarting/Starting all packages.
Dec 4 09:50:49 php-fpm[10667]: /rc.linkup: DEVD Ethernet detached event for wan
Dec 4 09:50:49 check_reload_status: updating dyndns wan
Dec 4 09:50:49 check_reload_status: Reloading filter
Dec 4 09:50:49 check_reload_status: Starting packages
Dec 4 09:50:49 php-fpm[53090]: /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - ???.???.???.??? -> ???.???.???.??? - Restarting packages.
Dec 4 09:50:47 php-fpm[53090]: /rc.newwanip: Creating rrd update script

Dec 4 09:51:17 apinger: Could not bind socket on address(???.???.???.???) for monitoring address ???.???.???.???(WAN) with error Can't assign requested address
Dec 4 09:51:16 apinger: Could not bind socket on address(???.???.???.???) for monitoring address ???.???.???.???(WAN) with error Can't assign requested address
Dec 4 09:51:13 apinger: SIGHUP received, reloading configuration.
Dec 4 09:51:10 apinger: Could not bind socket on address(???.???.???.???) for monitoring address ???.???.???.???(WAN) with error Can't assign requested address
Dec 4 09:51:09 apinger: Could not bind socket on address(???.???.???.???) for monitoring address ???.???.???.???(WAN) with error Can't assign requested address
Dec 4 09:51:08 apinger: Could not bind socket on address(???.???.???.???) for monitoring address ???.???.???.???(WAN) with error Can't assign requested address
Dec 4 09:51:05 apinger: SIGHUP received, reloading configuration.
Dec 4 09:51:02 apinger: Could not bind socket on address(???.???.???.???) for monitoring address ???.???.???.???(WAN) with error Can't assign requested address
Dec 4 09:51:01 apinger: Could not bind socket on address(???.???.???.???) for monitoring address ???.???.???.???(WAN) with error Can't assign requested address
Dec 4 09:51:00 apinger: Could not bind socket on address(???.???.???.???) for monitoring address ???.???.???.???(WAN) with error Can't assign requested address
Dec 4 09:50:56 apinger: SIGHUP received, reloading configuration.
Dec 4 09:50:54 apinger: Could not bind socket on address(???.???.???.???) for monitoring address ???.???.???.???(WAN) with error Can't assign requested address
Dec 4 09:50:53 apinger: Could not bind socket on address(???.???.???.???) for monitoring address ???.???.???.???(WAN) with error Can't assign requested address
Dec 4 09:50:52 apinger: Could not bind socket on address(???.???.???.???) for monitoring address ???.???.???.???(WAN) with error Can't assign requested address
Dec 4 09:50:51 apinger: Could not bind socket on address(???.???.???.???) for monitoring address ???.???.???.???(WAN) with error Can't assign requested address
Dec 4 09:50:47 apinger: SIGHUP received, reloading configuration.
Dec 4 09:50:45 apinger: Could not bind socket on address(???.???.???.???) for monitoring address ???.???.???.???(WAN) with error Can't assign requested address
Dec 4 09:50:44 apinger: Could not bind socket on address(???.???.???.???) for monitoring address ???.???.???.???(WAN) with error Can't assign requested address
Dec 4 09:50:43 apinger: Could not bind socket on address(???.???.???.???) for monitoring address ???.???.???.???(WAN) with error Can't assign requested address
Dec 4 09:50:42 apinger: Could not bind socket on address(???.???.???.???) for monitoring address ???.???.???.???(WAN) with error Can't assign requested address
Dec 4 09:50:38 apinger: SIGHUP received, reloading configuration.
Dec 4 09:50:36 apinger: Could not bind socket on address(???.???.???.???) for monitoring address ???.???.???.???(WAN) with error Can't assign requested address
Dec 4 09:50:35 apinger: Could not bind socket on address(???.???.???.???) for monitoring address ???.???.???.???(WAN) with error Can't assign requested address
Dec 4 09:50:34 apinger: Could not bind socket on address(???.???.???.???) for monitoring address ???.???.???.???(WAN) with error Can't assign requested address
Dec 4 09:50:33 apinger: Could not bind socket on address(???.???.???.???) for monitoring address ???.???.???.???(WAN) with error Can't assign requested address
Dec 4 09:50:29 apinger: SIGHUP received, reloading configuration.
Dec 4 09:50:27 apinger: Could not bind socket on address(???.???.???.???) for monitoring address ???.???.???.???(WAN) with error Can't assign requested address
Dec 4 09:50:26 apinger: Could not bind socket on address(???.???.???.???) for monitoring address ???.???.???.???(WAN) with error Can't assign requested address
Dec 4 09:50:25 apinger: Could not bind socket on address(???.???.???.???) for monitoring address ???.???.???.???(WAN) with error Can't assign requested address
Dec 4 09:50:21 apinger: SIGHUP received, reloading configuration.
Dec 4 09:50:19 apinger: Could not bind socket on address(???.???.???.???) for monitoring address ???.???.???.???(WAN) with error Can't assign requested address
Dec 4 09:50:18 apinger: Could not bind socket on address(???.???.???.???) for monitoring address ???.???.???.???(WAN) with error Can't assign requested address
Dec 4 09:50:17 apinger: Could not bind socket on address(???.???.???.???) for monitoring address ???.???.???.???(WAN) with error Can't assign requested address
Dec 4 09:50:12 apinger: SIGHUP received, reloading configuration.
Dec 4 09:50:12 apinger: ALARM: WAN(???.???.???.???) *** loss ***

eri-- · Dec 4, 2014, 3:53 PM

Can you provide a clear way to reproduce this.
From your logs seems there are mixed actions happening at the same time.

dr.diesel · Dec 4, 2014, 3:55 PM

Either pull and reinsert the wan Ethernet cable, or just release and renew. Either one will trigger the bouncing, only a restart will fix.

cmb · Dec 4, 2014, 6:05 PM

There's something more to it than that. What hardware is that? What is your config like on re0? The fact it does the same on 2.1.5 suggests it's possibly one of the broken Realteks (or one more broken than most of the others at least).

dr.diesel · Dec 4, 2014, 6:20 PM

It does the same on an Intel card, I just swapped to re for testing. I don't know if it does it in 2.1.5 also, this was a fresh install of 2.2 maybe 2-3 months ago. WAN setup is stock pfsense from 2.2 DHCP.

em1: <intel(r) 1000="" pro="" network="" connection="" 7.4.2="">port 0xe000-0xe01f mem 0xf7d20000-0xf7d3ffff,0xf7d00000-0xf7d1ffff irq 17 at device 0.1 on pci1
MB = MSI MS-7817 latest BIOS.

Dec 4 13:12:03 php-fpm[73487]: /rc.linkup: HOTPLUG: Configuring interface wan
Dec 4 13:12:03 php-fpm[73487]: /rc.linkup: DEVD Ethernet attached event for wan
Dec 4 13:12:02 kernel: em1: link state changed to DOWN
Dec 4 13:12:02 check_reload_status: Linkup starting em1
Dec 4 13:12:02 php-fpm[59827]: /rc.linkup: DEVD Ethernet detached event for wan
Dec 4 13:12:02 check_reload_status: updating dyndns wan
Dec 4 13:11:58 php-fpm[16280]: /rc.linkup: ROUTING: setting default route to 24.100.??.?
Dec 4 13:11:58 check_reload_status: rc.newwanip starting em1
Dec 4 13:11:57 kernel: em1: link state changed to UP
Dec 4 13:11:57 check_reload_status: Linkup starting em1
Dec 4 13:11:55 check_reload_status: Configuring interface wan
Dec 4 13:11:55 php-fpm[7437]: /rc.newwanip: rc.newwanip: Failed to update wan IP, restarting…
Dec 4 13:11:55 php-fpm[7437]: /rc.newwanip: rc.newwanip: on (IP address: ) (interface: WAN[wan]) (real interface: em1).
Dec 4 13:11:55 php-fpm[7437]: /rc.newwanip: rc.newwanip: Info: starting on em1.
Dec 4 13:11:55 kernel: em1: link state changed to DOWN
Dec 4 13:11:55 check_reload_status: Linkup starting em1
Dec 4 13:11:55 php-fpm[16280]: /rc.linkup: HOTPLUG: Configuring interface wan
Dec 4 13:11:55 php-fpm[16280]: /rc.linkup: DEVD Ethernet attached event for wan
Dec 4 13:11:54 php-fpm[73487]: /rc.linkup: DEVD Ethernet detached event for wan
Dec 4 13:11:54 check_reload_status: updating dyndns wan
Dec 4 13:11:50 php-fpm[7437]: /rc.linkup: ROUTING: setting default route to 24.100.??.?
Dec 4 13:11:50 check_reload_status: rc.newwanip starting em1
Dec 4 13:11:50 kernel: arpresolve: can't allocate llinfo for 24.100.??.? on em1
Dec 4 13:11:49 kernel: arpresolve: can't allocate llinfo for 24.100.??.? on em1
Dec 4 13:11:49 kernel: arpresolve: can't allocate llinfo for 24.100.??.? on em1
Dec 4 13:11:49 kernel: arpresolve: can't allocate llinfo for 24.100.??.? on em1
Dec 4 13:11:49 kernel: arpresolve: can't allocate llinfo for 24.100.??.? on em1
Dec 4 13:11:49 kernel: arpresolve: can't allocate llinfo for 24.100.??.? on em1
Dec 4 13:11:49 kernel: arpresolve: can't allocate llinfo for 24.100.??.? on em1
Dec 4 13:11:48 check_reload_status: Linkup starting em1
Dec 4 13:11:48 kernel: em1: link state changed to UP
Dec 4 13:11:47 kernel: arpresolve: can't allocate llinfo for 24.100.??.? on em1
Dec 4 13:11:47 kernel: arpresolve: can't allocate llinfo for 24.100.??.? on em1
Dec 4 13:11:47 kernel: arpresolve: can't allocate llinfo for 24.100.??.? on em1
Dec 4 13:11:46 kernel: arpresolve: can't allocate llinfo for 24.100.??.? on em1
Dec 4 13:11:46 kernel: arpresolve: can't allocate llinfo for 24.100.??.? on em1
Dec 4 13:11:45 check_reload_status: Linkup starting em1</intel(r)>

cmb · Dec 4, 2014, 6:28 PM

Ok that rules out the re NIC at least. It seems highly likely it's your modem at this stage. I'm guessing you're plugged straight from WAN NIC into the modem. What if you put a switch in between, so the link down never happens to the modem, what does that do?

dr.diesel · Dec 4, 2014, 6:32 PM

Tested with a switch yesterday!

If I pull just the WAN on pfsense, without touching the cable modem side, WAN port still bounces until pfsense reboot.

dr.diesel · Dec 4, 2014, 6:57 PM

Plugged my laptop directly into the cable modem, works without issue.

But I might have lied, this pfsense install might have been an upgrade from 2.1.5 and not a fresh install. Sorry, to many different installs, I don't recall for-sure.

I could blast it and confirm with a fresh install if that adds any value?

cmb · Dec 4, 2014, 7:09 PM

Unless you're getting in and changing source, or messing around with a lot of unstable packages, or making other changes under the hood, a clean install will be functionally equivalent to an upgraded system. It's pretty quick and easy to start from scratch and restore your config though. That's probably the next best bet, start on a clean install of the most recent 2.2 snapshot. First test a new config with the most basic setup possible - WAN on DHCP, LAN static, nothing else configured beyond defaults. Then see whether that still happens. Then you can restore your config backup after trying that.

dr.diesel · Dec 5, 2014, 7:45 PM

I'm not doing anything special, no source changing or under the hood tweaks.

I've tried everything under the sun and for some reason can't get the memstick image to boot, done this a zillion times successfully in the past.

Anyhow, I bought several of these MSI MBs, all have given me trouble, might just toss it out the window and get a proper supermicro.

Thanks for the help. I will report back, but it might be a month as I start on an outage this Monday.

dr.diesel · Dec 9, 2014, 5:36 PM

I did find a temp fix while on outage. I changed the WAN configuration from auto detect (which was auto detecting 1000BT/full) to 1000BT/full static and the problem vanished.