search

jaysoffian / eap_proxy

Proxy EAP packets between interfaces on Linux devices such as the Ubiquiti Networks EdgeRouter™ and UniFi® Security Gateway.
BSD 3-Clause "New" or "Revised" License
562 stars 87 forks source link

Failover Delay #12

Closed K-MTG closed 5 years ago

K-MTG commented 5 years ago

Hi,

I am running eap_proxy on my USG 4P. The ONT is on eth2 & the gateway is on eth1. I also have a LTE Modem on WAN2 (eth 3).

If I unplug the ONT connection from the USG it failover to WAN2 but once I connect the ONT back onto the USG it doesn't fail back to WAN1/eth2. 

Feb 13 23:27:46 Router zebra[641]: interface eth2 index 4 changed <UP,BROADCAST,MULTICAST>.
Feb 13 23:27:46 Router zebra[641]: interface eth2.0 index 15 changed <UP,BROADCAST,MULTICAST>.
Feb 13 23:27:46 Router kernel: eth2: Link down
Feb 13 23:27:50 Router wlb: wlb-wan_failover-eth2.0 wlb-wan_failover-eth2.0 reachability failed, failover
Feb 13 23:27:50 Router wlb: group wan_failover, interface eth2.0 going Inactive
Feb 13 23:27:50 Router wlb: group wan_failover, interface eth3 going Active
Feb 13 23:27:50 Router wan-event: [WAN Transition] eth2.0 to state inactive
Feb 13 23:27:50 Router wan-event: [WAN Transition] eth3 to state active
Feb 13 23:29:03 Router zebra[641]: interface eth2 index 4 changed <UP,BROADCAST,RUNNING,MULTICAST>.
Feb 13 23:29:03 Router zebra[641]: interface eth2.0 index 15 changed <UP,BROADCAST,RUNNING,MULTICAST>.
Feb 13 23:29:03 Router kernel: eth2: 1000 Mbps Full duplex, port 2
Feb 13 23:29:34 Router eap_proxy[3912]: eth2: 00:90:xx:xx:xx:xx > 01:80:xx:xx:xx:xx, EAP packet (0) v1, len 15, Request (1) id 1, len 15 [11] > eth1
Feb 13 23:30:04 Router eap_proxy[3912]: eth2: 00:90:xx:xx:xx:xx > 01:80:xx:xx:xx:xx, EAP packet (0) v1, len 15, Request (1) id 1, len 15 [11] > eth1
Feb 13 23:30:34 Router eap_proxy[3912]: eth2: 00:90:xx:xx:xx:xx > 01:80:xx:xx:xx:xx, EAP packet (0) v1, len 4, Failure (4) id 1, len 4 [0] > eth1
Feb 13 23:30:34 Router eap_proxy[3912]: eth2: 00:90:xx:xx:xx:xx > 01:80:xx:xx:xx:xx, EAP packet (0) v1, len 15, Request (1) id 2, len 15 [11] > eth1
Feb 13 23:31:35  eap_proxy[3912]: last message repeated 2 times
Feb 13 23:32:05 Router eap_proxy[3912]: eth2: 00:90:xx:xx:xx:xx > 01:80:xx:xx:xx:xx, EAP packet (0) v1, len 4, Failure (4) id 2, len 4 [0] > eth1
Feb 13 23:32:05 Router eap_proxy[3912]: eth2: 00:90:xx:xx:xx:xx > 01:80:xx:xx:xx:xx, EAP packet (0) v1, len 15, Request (1) id 3, len 15 [11] > eth1
Feb 13 23:33:06  eap_proxy[3912]: last message repeated 2 times
Feb 13 23:33:36 Router eap_proxy[3912]: eth2: 00:90:xx:xx:xx:xx > 01:80:xx:xx:xx:xx, EAP packet (0) v1, len 4, Failure (4) id 3, len 4 [0] > eth1
Feb 13 23:33:36 Router eap_proxy[3912]: eth2: 00:90:xx:xx:xx:xx > 01:80:xx:xx:xx:xx, EAP packet (0) v1, len 15, Request (1) id 4, len 15 [11] > eth1
Feb 13 23:34:37  eap_proxy[3912]: last message repeated 2 times
Feb 13 23:35:07 Router eap_proxy[3912]: eth2: 00:90:xx:xx:xx:xx > 01:80:xx:xx:xx:xx, EAP packet (0) v1, len 4, Failure (4) id 4, len 4 [0] > eth1
Feb 13 23:35:07 Router eap_proxy[3912]: eth2: 00:90:xx:xx:xx:xx > 01:80:xx:xx:xx:xx, EAP packet (0) v1, len 15, Request (1) id 5, len 15 [11] > eth1
Feb 13 23:36:08  eap_proxy[3912]: last message repeated 2 times
Feb 13 23:36:38 Router eap_proxy[3912]: eth2: 00:90:xx:xx:xx:xx > 01:80:xx:xx:xx:xx, EAP packet (0) v1, len 4, Failure (4) id 5, len 4 [0] > eth1
Feb 13 23:36:38 Router eap_proxy[3912]: eth2: 00:90:xx:xx:xx:xx > 01:80:xx:xx:xx:xx, EAP packet (0) v1, len 15, Request (1) id 6, len 15 [11] > eth1
Feb 13 23:37:46  eap_proxy[3912]: last message repeated 2 times
Feb 13 23:38:09 Router eap_proxy[3912]: eth2: 00:90:xx:xx:xx:xx > 01:80:xx:xx:xx:xx, EAP packet (0) v1, len 4, Failure (4) id 6, len 4 [0] > eth1
Feb 13 23:38:09 Router eap_proxy[3912]: eth2: 00:90:xx:xx:xx:xx > 01:80:xx:xx:xx:xx, EAP packet (0) v1, len 15, Request (1) id 7, len 15 [11] > eth1
Feb 13 23:38:14 Router sshd[10054]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=10.0.1.79  user=Siddiqi
Feb 13 23:38:39 Router eap_proxy[3912]: eth2: 00:90:xx:xx:xx:xx > 01:80:xx:xx:xx:xx, EAP packet (0) v1, len 15, Request (1) id 7, len 15 [11] > eth1
Feb 13 23:39:09 Router eap_proxy[3912]: eth2: 00:90:xx:xx:xx:xx > 01:80:xx:xx:xx:xx, EAP packet (0) v1, len 15, Request (1) id 7, len 15 [11] > eth1
Feb 13 23:39:40 Router eap_proxy[3912]: eth2: 00:90:xx:xx:xx:xx > 01:80:xx:xx:xx:xx, EAP packet (0) v1, len 4, Failure (4) id 7, len 4 [0] > eth1
Feb 13 23:39:40 Router eap_proxy[3912]: eth2: 00:90:xx:xx:xx:xx > 01:80:xx:xx:xx:xx, EAP packet (0) v1, len 15, Request (1) id 8, len 15 [11] > eth1
Feb 13 23:40:47  eap_proxy[3912]: last message repeated 2 times
Feb 13 23:41:11 Router eap_proxy[3912]: eth2: 00:90:xx:xx:xx:xx > 01:80:xx:xx:xx:xx, EAP packet (0) v1, len 4, Failure (4) id 8, len 4 [0] > eth1
Feb 13 23:41:11 Router eap_proxy[3912]: eth2: 00:90:xx:xx:xx:xx > 01:80:xx:xx:xx:xx, EAP packet (0) v1, len 15, Request (1) id 9, len 15 [11] > eth1
Feb 13 23:42:17  eap_proxy[3912]: last message repeated 2 times
Feb 13 23:42:41 Router eap_proxy[3912]: eth2: 00:90:xx:xx:xx:xx > 01:80:xx:xx:xx:xx, EAP packet (0) v1, len 4, Failure (4) id 9, len 4 [0] > eth1
Feb 13 23:42:41 Router eap_proxy[3912]: eth2: 00:90:xx:xx:xx:xx > 01:80:xx:xx:xx:xx, EAP packet (0) v1, len 15, Request (1) id 10, len 15 [11] > eth1
Feb 13 23:43:42  eap_proxy[3912]: last message repeated 2 times
Feb 13 23:44:12 Router eap_proxy[3912]: eth2: 00:90:xx:xx:xx:xx > 01:80:xx:xx:xx:xx, EAP packet (0) v1, len 4, Failure (4) id 10, len 4 [0] > eth1
Feb 13 23:44:12 Router eap_proxy[3912]: eth2: 00:90:xx:xx:xx:xx > 01:80:xx:xx:xx:xx, EAP packet (0) v1, len 15, Request (1) id 11, len 15 [11] > eth1
Feb 13 23:45:13  eap_proxy[3912]: last message repeated 2 times
Feb 13 23:45:43 Router eap_proxy[3912]: eth2: 00:90:xx:xx:xx:xx > 01:80:xx:xx:xx:xx, EAP packet (0) v1, len 4, Failure (4) id 11, len 4 [0] > eth1
Feb 13 23:45:43 Router eap_proxy[3912]: eth2: 00:90:xx:xx:xx:xx > 01:80:xx:xx:xx:xx, EAP packet (0) v1, len 15, Request (1) id 12, len 15 [11] > eth1
Feb 13 23:46:44  eap_proxy[3912]: last message repeated 2 times
Feb 13 23:47:14 Router eap_proxy[3912]: eth2: 00:90:xx:xx:xx:xx > 01:80:xx:xx:xx:xx, EAP packet (0) v1, len 4, Failure (4) id 12, len 4 [0] > eth1
Feb 13 23:47:14 Router eap_proxy[3912]: eth2: 00:90:xx:xx:xx:xx > 01:80:xx:xx:xx:xx, EAP packet (0) v1, len 15, Request (1) id 13, len 15 [11] > eth1
Feb 13 23:48:15  eap_proxy[3912]: last message repeated 2 times
Feb 13 23:48:45 Router eap_proxy[3912]: eth2: 00:90:xx:xx:xx:xx > 01:80:xx:xx:xx:xx, EAP packet (0) v1, len 4, Failure (4) id 13, len 4 [0] > eth1
Feb 13 23:48:45 Router eap_proxy[3912]: eth2: 00:90:xx:xx:xx:xx > 01:80:xx:xx:xx:xx, EAP packet (0) v1, len 15, Request (1) id 14, len 15 [11] > eth1
Feb 13 23:49:46  eap_proxy[3912]: last message repeated 2 times
Feb 13 23:49:52 Router sshd[12569]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=10.0.1.105  user=Siddiqi

UPDATE - So it finally reverted back to the ONT but it took ~30 minutes. 

Feb 14 00:05:25 Router eap_proxy[3912]: eth2: 00:xx:xx:xx:xx > 01:80:xx:xx:xx:xx, EAP packet (0) v1, len 4, Failure (4) id 24, len 4 [0] > eth1
Feb 14 00:05:25 Router eap_proxy[3912]: eth2: 00:xx:xx:xx:xx > 01:80:xx:xx:xx:xx, EAP packet (0) v1, len 15, Request (1) id 25, len 15 [11] > eth1
Feb 14 00:06:26  eap_proxy[3912]: last message repeated 2 times
Feb 14 00:06:56 Router eap_proxy[3912]: eth2: 00:xx:xx:xx:xx > 01:80:xx:xx:xx:xx, EAP packet (0) v1, len 4, Failure (4) id 25, len 4 [0] > eth1
Feb 14 00:06:56 Router eap_proxy[3912]: eth2: 00:xx:xx:xx:xx > 01:80:xx:xx:xx:xx, EAP packet (0) v1, len 15, Request (1) id 26, len 15 [11] > eth1
Feb 14 00:07:09 Router ipsec-dhclient-hook: DHCP address updated to from xxx.x.xxx.xx: Updating ipsec configuration.
Feb 14 00:07:10 Router ipsec-dhclient-hook: DHCP address updated to from xxx.x.xxx.xx: Updating ipsec configuration.
Feb 14 00:07:10 Router xl2tpd[4808]: death_handler: Fatal signal 15 received
Feb 14 00:07:10 Router xl2tpd[15489]: parse_config: line 3: set_ip: host '' not found
Feb 14 00:07:10 Router xl2tpd[15489]: init: Unable to load config file
Feb 14 00:07:26 Router eap_proxy[3912]: eth2: 00:xx:xx:xx:xx > 01:80:xx:xx:xx:xx, EAP packet (0) v1, len 15, Request (1) id 26, len 15 [11] > eth1
Feb 14 00:07:26 Router eap_proxy[3912]: eth1: 90:xx:xx:xx:xx > 01:80:xx:xx:xx:xx, EAP packet (0) v2, len 22, Response (2) id 26, len 22 [18] > eth2
Feb 14 00:07:26 Router eap_proxy[3912]: eth2: 00:xx:xx:xx:xx > 90:xx:xx:xx:xx, EAP packet (0) v1, len 6, Request (1) id 27, len 6 [2] > eth1
Feb 14 00:07:27 Router eap_proxy[3912]: eth1: 90:xx:xx:xx:xx > 01:80:xx:xx:xx:xx, EAP packet (0) v2, len 92, Response (2) id 27, len 92 [88] > eth2
Feb 14 00:07:27 Router eap_proxy[3912]: eth2: 00:xx:xx:xx:xx > 90:xx:xx:xx:xx, EAP packet (0) v1, len 1020, Request (1) id 28, len 1020 [1016] > eth1
Feb 14 00:07:27 Router eap_proxy[3912]: eth1: 90:xx:xx:xx:xx > 01:80:xx:xx:xx:xx, EAP packet (0) v2, len 6, Response (2) id 28, len 6 [2] > eth2
Feb 14 00:07:27 Router eap_proxy[3912]: eth2: 00:xx:xx:xx:xx > 90:xx:xx:xx:xx, EAP packet (0) v1, len 1020, Request (1) id 29, len 1020 [1016] > eth1
Feb 14 00:07:27 Router eap_proxy[3912]: eth1: 90:xx:xx:xx:xx > 01:80:xx:xx:xx:xx, EAP packet (0) v2, len 6, Response (2) id 29, len 6 [2] > eth2
Feb 14 00:07:27 Router eap_proxy[3912]: eth2: 00:xx:xx:xx:xx > 90:xx:xx:xx:xx, EAP packet (0) v1, len 1020, Request (1) id 30, len 1020 [1016] > eth1
Feb 14 00:07:27 Router eap_proxy[3912]: eth1: 90:xx:xx:xx:xx > 01:80:xx:xx:xx:xx, EAP packet (0) v2, len 6, Response (2) id 30, len 6 [2] > eth2
Feb 14 00:07:27 Router eap_proxy[3912]: eth2: 00:xx:xx:xx:xx > 90:xx:xx:xx:xx, EAP packet (0) v1, len 193, Request (1) id 31, len 193 [189] > eth1
Feb 14 00:07:28 Router eap_proxy[3912]: eth1: 90:xx:xx:xx:xx > 01:80:xx:xx:xx:xx, EAP packet (0) v2, len 906, Response (2) id 31, len 906 [902] > eth2
Feb 14 00:07:28 Router eap_proxy[3912]: eth2: 00:xx:xx:xx:xx > 90:xx:xx:xx:xx, EAP packet (0) v1, len 6, Request (1) id 32, len 6 [2] > eth1
Feb 14 00:07:28 Router eap_proxy[3912]: eth1: 90:xx:xx:xx:xx > 01:80:xx:xx:xx:xx, EAP packet (0) v2, len 902, Response (2) id 32, len 902 [898] > eth2
Feb 14 00:07:28 Router eap_proxy[3912]: eth2: 00:xx:xx:xx:xx > 90:xx:xx:xx:xx, EAP packet (0) v1, len 6, Request (1) id 33, len 6 [2] > eth1
Feb 14 00:07:28 Router eap_proxy[3912]: eth1: 90:xx:xx:xx:xx > 01:80:xx:xx:xx:xx, EAP packet (0) v2, len 902, Response (2) id 33, len 902 [898] > eth2
Feb 14 00:07:28 Router eap_proxy[3912]: eth2: 00:xx:xx:xx:xx > 90:xx:xx:xx:xx, EAP packet (0) v1, len 6, Request (1) id 34, len 6 [2] > eth1
Feb 14 00:07:29 Router eap_proxy[3912]: eth1: 90:xx:xx:xx:xx > 01:80:xx:xx:xx:xx, EAP packet (0) v2, len 485, Response (2) id 34, len 485 [481] > eth2
Feb 14 00:07:29 Router eap_proxy[3912]: eth2: 00:xx:xx:xx:xx > 90:xx:xx:xx:xx, EAP packet (0) v1, len 69, Request (1) id 35, len 69 [65] > eth1
Feb 14 00:07:29 Router eap_proxy[3912]: eth1: 90:xx:xx:xx:xx > 01:80:xx:xx:xx:xx, EAP packet (0) v2, len 6, Response (2) id 35, len 6 [2] > eth2
Feb 14 00:07:29 Router eap_proxy[3912]: eth2.0: restarting dhclient
Feb 14 00:07:30 Router ipsec-dhclient-hook: DHCP address updated to from xxx.x.xxx.xx: Updating ipsec configuration.
Feb 14 00:07:30 Router ipsec-dhclient-hook: DHCP address updated to from xxx.x.xxx.xx: Updating ipsec configuration.
Feb 14 00:07:30 Router xl2tpd[15630]: parse_config: line 3: set_ip: host '' not found
Feb 14 00:07:30 Router xl2tpd[15630]: init: Unable to load config file
Feb 14 00:07:31 Router eap_proxy[3912]: eth2: 00:xx:xx:xx:xx > 01:80:xx:xx:xx:xx, EAP packet (0) v1, len 4, Success (3) id 35, len 4 [0] > eth1
Feb 14 00:07:33 Router ipsec-dhclient-hook: DHCP address updated to xxx.x.xxx.xx from xxx.x.xxx.xx: Updating ipsec configuration.
Feb 14 00:07:33 Router ipsec-dhclient-hook: DHCP address updated to xxx.x.xxx.xx from xxx.x.xxx.xx: Updating ipsec configuration.
Feb 14 00:07:33 Router xl2tpd[15756]: setsockopt recvref[30]: Protocol not available
Feb 14 00:09:01 Router wlb: group wan_failover, interface eth2.0 going Active
Feb 14 00:09:01 Router wan-event: [WAN Transition] eth2.0 to state active
Feb 14 00:09:01 Router wan-event: [WAN Transition] eth3 to state failover
Feb 14 00:09:31 Router kernel: [WAN_IN-3003-A]IN=eth2.0 OUT=eth0 MAC=90:xx:xx:xx:xx:00:03:fa:6a:45:21:08:00:45:00:00:3c SRC=34.xxx.xxx.xx DST=10.0.1.3 LEN=60 TOS=0x00 PREC=0x00 TTL=33 ID=24432 DF PROTO=TCP SPT=37340 DPT=32400 WINDOW=7300 RES=0x00 SYN URGP=0 MARK=0x64800000

If I were to reboot the USG, it would just take a few seconds.

jaysoffian commented 5 years ago

Unfortunately it doesn't seem like there's much eap_proxy can do here. From the logs, the proxy is forwarding the auth packets from the ONT to the RG, but the RG isn't responding. I think what's going on here is that the RG, after not being able to get online for some period of time, goes into a state where it stops responding to the ONT. At some point the RG appears to reset itself at which point is responds as expected.

Perhaps resetting the interface the RG is on could get it to respond again. Another possibility is forwarding more traffic than just the auth packets between the ONT and RG to fool the RG into thinking it's online. I'm not sure really, and don't currently have any time to look into it.

jaysoffian commented 5 years ago

FWIW, even without the proxy in place, when I've had my ONT go down and the come back due to line issues, I've had to reset my RG to get it back online.

K-MTG commented 5 years ago

So rebooting the RG would do the trick? Maybe I can just get a smart outlet and reboot the RG remotely.

steboknapp commented 5 years ago

To add to this, I have the same setup with a cellular backup on WAN2. (My only difference is my WAN1 is on the SFP port)

I noticed that on bootup, the IP the USGP4 pulled on the WAN1 network is actually from my LTE Modem, which is on WAN2. So far, unplugging the LTE modem from WAN2, then plugging it in after the WAN1 is up and active has been ok.

I'm also having issue with the eap_proxy script running on reboot, so there may be correlation.

steboknapp commented 5 years ago

I looked back and realized I left the --vlan-id 2 out of my eap_proxy.sh (was only using it in the terminal command to check initially) after updating that the script does load as expected on reboot.

It now works as expected with both WAN1 and WAN2 connected on reboot (proper IPs on each interface). I'll test mimicking a failover event when I get a chance and see if my experience is the same as @K-MTG

Thanks for all your work on this @jaysoffian !