Secondary WAN doesn't renew DHCP lease
-
I have a secondary WAN (Protectli USB 4G modem) configured. It will usually work for a couple days, and then suddenly drop offline. When I view that status of that interface, pfSense shows it as "Down" with DHCP as "Down" too. Clicking "Renew" causes the interface to get a new IP address successfully, and the connection starts working again. The lease time handed out by my 4G provider is 300 seconds, so the connection is successfully renewing it many times without failure, but at some point it seemingly just stops trying to renew automatically. Looking in the pfSense logs, I see "DHCPREQUEST on ue0 to x.x.x.x port 67" every ~140 seconds as would be expected, until suddenly, there just are not more such requests, the interface losses its IP address, and the connection goes down. As soon as I manually choose to renew the lease from the Interface Status page, the logs show the requests starting again.
This is what I see in the pfSense logs:
2021-04-23T16:23:15.000+0000 Interface “ue0” enabled.
2021-04-23T16:23:12.000+0000 ue0: Ethernet address: 9e:56:58:ee:62:6c
2021-04-23T16:23:12.000+0000 ue0: <USB Ethernet> on urndis0
2021-04-23T16:23:12.000+0000 urndis0: <RNDIS Communications Control> on usbus0
2021-04-23T16:23:12.000+0000 urndis0 on uhub0
2021-04-23T16:23:12.000+0000 ugen0.2: <Qualcomm MDG100> at usbus0
2021-04-23T16:23:05.000+0000 Interface “ue0” disabled.
2021-04-23T16:23:05.000+0000 13[KNL] interface ue0 disappeared
2021-04-23T16:23:05.000+0000 15[KNL] interface ue0 deactivated
2021-04-23T16:23:05.000+0000 Apr 23 23:23:05 kernel: detached
2021-04-23T16:23:05.000+0000 urndis0:
2021-04-23T16:23:05.000+0000 15[KNL] 6.191.205.58 disappeared from ue0
2021-04-23T16:23:05.000+0000 Apr 23 23:23:05 dhclient[73422]: exiting.
2021-04-23T16:23:05.000+0000 connection closed
2021-04-23T16:23:05.000+0000 Apr 23 23:23:05 dhclient[77365]: exiting.
2021-04-23T16:23:05.000+0000 No live interfaces to poll on – exiting.
2021-04-23T16:23:05.000+0000 Interface ue0 no longer appears valid.
2021-04-23T16:23:05.000+0000 ioctl(SIOCGIFFLAGS) on ue0: Operation not permitted
2021-04-23T16:23:05.000+0000 urndis0: at uhub0, port 4, addr 4 (disconnected)
2021-04-23T16:23:05.000+0000 ugen0.2: <Qualcomm MDG100> at usbus0 (disconnected)
2021-04-23T16:23:05.000+0000 receive_packet failed on ue0: Device not configured
2021-04-23T16:22:55.000+0000 merge_config: configuration reload
2021-04-23T16:22:52.000+0000 bound to 6.191.205.58 — renewal in 136 seconds.
2021-04-23T16:22:52.000+0000 Creating resolv.conf
2021-04-23T16:22:52.000+0000 Apr 23 23:22:52 dhclient[73261]: RENEW
2021-04-23T16:22:52.000+0000 DHCPACK from 6.191.205.57
2021-04-23T16:22:52.000+0000 DHCPREQUEST on ue0 to 6.191.205.57 port 67
2021-04-23T16:22:49.000+0000 Reloading filter
2021-04-23T16:22:49.000+0000 /rc.newipsecdns: IPSEC: One or more IPsec tunnel endpoints has changed its IP. Refreshing.
2021-04-23T16:22:38.000+0000 notify_monitor.php: Message sent to xxxx OK
2021-04-23T16:22:35.000+0000 /rc.dyndns.update: phpDynDNS (): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry.
2021-04-23T16:22:34.000+0000 /rc.openvpn: OpenVPN: One or more OpenVPN tunnel endpoints may have changed its IP. Reloading endpoints that may use GW_WAN_SECONDARY.
2021-04-23T16:22:34.000+0000 Apr 23 23:22:34 php-fpm[87572]: 1.0.0.1|6.191.205.58|GW_WAN_SECONDARY|76.098ms|36.747ms|25%|down|highloss
2021-04-23T16:22:34.000+0000 /rc.openvpn: MONITOR: GW_WAN_SECONDARY has packet loss, omitting from routing group DefaultGatewayGroup
2021-04-23T16:22:33.000+0000 Reloading filter
2021-04-23T16:22:33.000+0000 Restarting OpenVPN tunnels/interfaces
2021-04-23T16:22:33.000+0000 Restarting ipsec tunnels
2021-04-23T16:22:33.000+0000 updating dyndns GW_WAN_SECONDARY
2021-04-23T16:22:33.000+0000 >>> Gateway alarm: GW_WAN_SECONDARY (Addr:1.0.0.1 Alarm:1 RTT:76.407ms RTTsd:35.929ms Loss:21%)
2021-04-23T16:22:32.000+0000 GW_WAN_SECONDARY 1.0.0.1: Alarm latency 76407us stddev 35929us loss 21%
2021-04-23T16:20:39.000+0000 bound to 6.191.205.58 — renewal in 134 seconds.
2021-04-23T16:20:38.000+0000 Creating resolv.conf
2021-04-23T16:20:38.000+0000 Apr 23 23:20:38 dhclient[68765]: RENEW
2021-04-23T16:20:38.000+0000 DHCPACK from 6.191.205.57
2021-04-23T16:20:38.000+0000 DHCPREQUEST on ue0 to 6.191.205.57 port 67
2021-04-23T16:18:19.000+0000 bound to 6.191.205.58 — renewal in 139 seconds.
2021-04-23T16:18:19.000+0000 Creating resolv.conf
2021-04-23T16:18:19.000+0000 Apr 23 23:18:19 dhclient[99307]: RENEW
2021-04-23T16:18:19.000+0000 DHCPACK from 6.191.205.57
2021-04-23T16:18:19.000+0000 DHCPREQUEST on ue0 to 6.191.205.57 port 67Up until about 16:23 the interface is working (or, at least maintains an IP address). At 16:23:05 we get a message “receive_packet failed on ue0: Device not configured” and things go south. After this, the the interface loses it’s IP address and goes offline.
What is causing this interface to drop off like this?