Diagnosing routine loss of 4G connection

RVIT · 2018-10-22T14:10:04.970Z

I’ve had this issue occur with some minor variations on both the MT300N-V2 and GL-MiFi, and am hoping the wise forum can help me diagnose and fix what’s causing it. The logs used in this post are from a GL-MiFi.

Essentially, I have both devices on 4G connections, and they work great until at some point they lose internet connectivity. Rebooting the devices then brings the connection back up, but this seems to happen on a regular schedule (nightly?).

The routers are connected to an OpenVPN access server, and set to keepalive. This VPN configuration is working fine, and gives evidence that the 4G connection is down in the logs as it continues to attempt to establish a tunnel after the WAN connection is severed.

I’m also specifying custom DNS (google) via the GL-iNet administration UI. I’ve tried both using the /tmp/resolv.conf.auto file and ignoring it, but this connection drop issue seems to occur regardless. However, I have noticed variations where I can get back to the router through the VPN, and this may be when I elect to ignore the resolv file This would suggest that the router itself is still able to get out to the internet to sustain the tunnel in these instances, but the clients on that router are not being server proper DNS/DHCP? In any event, the account below is not one of those instances where I can get back to the router through the VPN tunnel.

The pattern is generally the same each time…

Wireless carrier issues hour-long leases…

Mon Oct 22 01:06:39 2018 daemon.notice netifd: modem_4 (1949): udhcpc: sending renew
Mon Oct 22 01:06:39 2018 daemon.notice netifd: modem_4 (1949): udhcpc: lease of 25.121.209.255 obtained, lease time 7200
...
Mon Oct 22 02:06:39 2018 daemon.notice netifd: modem_4 (1949): udhcpc: sending renew
Mon Oct 22 02:06:39 2018 daemon.notice netifd: modem_4 (1949): udhcpc: lease of 25.121.209.255 obtained, lease time 7200

Then at one of these reissues, seemingly for no reason, my router renews its lease on the same IP address, and then promptly loses its internet connection…

Mon Oct 22 03:06:39 2018 daemon.notice netifd: modem_4 (1949): udhcpc: sending renew
Mon Oct 22 03:06:39 2018 daemon.notice netifd: modem_4 (1949): udhcpc: lease of 25.121.209.255 obtained, lease time 7200
Mon Oct 22 03:06:47 2018 daemon.info hostapd: wlan0: STA bc:83:85:ee:05:48 WPA: group key handshake completed (RSN)
Mon Oct 22 03:06:47 2018 daemon.info hostapd: wlan0: STA c8:d9:d2:44:d0:17 WPA: group key handshake completed (RSN)
Mon Oct 22 03:06:55 2018 daemon.info gl-health>>: AP Ok=1
Mon Oct 22 03:06:55 2018 daemon.info gl-health>>: network(caIfnames) = DROIDTETHER modem tethering wan wan6
Mon Oct 22 03:06:55 2018 daemon.info gl-health>>: STA Ok=1
Mon Oct 22 03:06:55 2018 daemon.info gl-health>>: Everthing is OK!!!
Mon Oct 22 03:06:55 2018 daemon.info gl-health>>: check wpa runing = 
Mon Oct 22 03:07:25 2018 daemon.info gl-health>>: AP Ok=1
Mon Oct 22 03:07:25 2018 daemon.info gl-health>>: network(caIfnames) = DROIDTETHER modem tethering wan wan6
Mon Oct 22 03:07:25 2018 daemon.info gl-health>>: STA Ok=1
Mon Oct 22 03:07:25 2018 daemon.info gl-health>>: Everthing is OK!!!
Mon Oct 22 03:07:25 2018 daemon.info gl-health>>: check wpa runing = 
Mon Oct 22 03:07:55 2018 daemon.info gl-health>>: AP Ok=1
Mon Oct 22 03:07:56 2018 daemon.info gl-health>>: network(caIfnames) = DROIDTETHER modem tethering wan wan6
Mon Oct 22 03:07:56 2018 daemon.info gl-health>>: STA Ok=1
Mon Oct 22 03:07:56 2018 daemon.info gl-health>>: Everthing is OK!!!
Mon Oct 22 03:07:56 2018 daemon.info gl-health>>: check wpa runing = 
Mon Oct 22 03:08:26 2018 daemon.info gl-health>>: AP Ok=1
Mon Oct 22 03:08:26 2018 daemon.info gl-health>>: network(caIfnames) = DROIDTETHER modem tethering wan wan6
Mon Oct 22 03:08:26 2018 daemon.info gl-health>>: STA Ok=1
Mon Oct 22 03:08:26 2018 daemon.info gl-health>>: Everthing is OK!!!
Mon Oct 22 03:08:26 2018 daemon.info gl-health>>: check wpa runing = 
Mon Oct 22 03:08:56 2018 daemon.info gl-health>>: AP Ok=1
Mon Oct 22 03:08:56 2018 daemon.info gl-health>>: network(caIfnames) = DROIDTETHER modem tethering wan wan6
Mon Oct 22 03:08:56 2018 daemon.info gl-health>>: STA Ok=1
Mon Oct 22 03:08:56 2018 daemon.info gl-health>>: Everthing is OK!!!
Mon Oct 22 03:08:56 2018 daemon.info gl-health>>: check wpa runing = 
Mon Oct 22 03:09:21 2018 daemon.notice openvpn[3239]: [OpenVPN Server] Inactivity timeout (--ping-restart), restarting
Mon Oct 22 03:09:21 2018 daemon.notice openvpn[3239]: SIGUSR1[soft,ping-restart] received, process restarting
Mon Oct 22 03:09:21 2018 daemon.notice openvpn[3239]: Restart pause, 60 second(s)

Somehow, it will keep renewing its leases every hour, on the hour…

Mon Oct 22 04:06:39 2018 daemon.notice netifd: modem_4 (1949): udhcpc: sending renew
Mon Oct 22 04:06:39 2018 daemon.notice netifd: modem_4 (1949): udhcpc: lease of 25.121.209.255 obtained, lease time 7200

…sometimes it doesn’t appear to get a response…

Mon Oct 22 05:06:39 2018 daemon.notice netifd: modem_4 (1949): udhcpc: sending renew
Mon Oct 22 05:06:47 2018 daemon.info hostapd: wlan0: STA bc:83:85:ee:05:48 WPA: group key handshake completed (RSN)
Mon Oct 22 05:06:47 2018 daemon.info hostapd: wlan0: STA c8:d9:d2:44:d0:17 WPA: group key handshake completed (RSN)
Mon Oct 22 05:06:58 2018 daemon.info gl-health>>: AP Ok=1
Mon Oct 22 05:06:58 2018 daemon.info gl-health>>: network(caIfnames) = DROIDTETHER modem tethering wan wan6
Mon Oct 22 05:06:58 2018 daemon.info gl-health>>: STA Ok=1
Mon Oct 22 05:06:58 2018 daemon.info gl-health>>: Everthing is OK!!!

…all the while, OpenVPN client dutifully tries to reconnect, but does not…

Mon Oct 22 05:08:13 2018 daemon.warn openvpn[3239]: WARNING: --ns-cert-type is DEPRECATED.  Use --remote-cert-tls instead.
Mon Oct 22 05:08:18 2018 daemon.err openvpn[3239]: RESOLVE: Cannot resolve host address: openvpn.hostname.com:443 (Try again)
Mon Oct 22 05:08:23 2018 daemon.err openvpn[3239]: RESOLVE: Cannot resolve host address: openvpn.hostname.com:443 (Try again)
Mon Oct 22 05:08:23 2018 daemon.warn openvpn[3239]: Could not determine IPv4/IPv6 protocol
Mon Oct 22 05:08:23 2018 daemon.notice openvpn[3239]: SIGUSR1[soft,init_instance] received, process restarting
Mon Oct 22 05:08:23 2018 daemon.notice openvpn[3239]: Restart pause, 300 second(s)

…now attempting to re-lease an IP from the carrier just 30 min after unsuccessful attempt…

Mon Oct 22 05:36:39 2018 daemon.notice netifd: modem_4 (1949): udhcpc: sending renew

…now 15 minutes after that…

Mon Oct 22 05:51:40 2018 daemon.notice netifd: modem_4 (1949): udhcpc: sending renew

…then 7.5 minutes…

Mon Oct 22 05:59:10 2018 daemon.notice netifd: modem_4 (1949): udhcpc: sending renew

…3.75 minutes…

Mon Oct 22 06:02:55 2018 daemon.notice netifd: modem_4 (1949): udhcpc: sending renew

…then half of that…

Mon Oct 22 06:04:47 2018 daemon.notice netifd: modem_4 (1949): udhcpc: sending renew

…until finally, it gets a new lease on the same IP address…

Mon Oct 22 06:05:43 2018 daemon.notice netifd: modem_4 (1949): udhcpc: sending renew
Mon Oct 22 06:05:43 2018 daemon.notice netifd: modem_4 (1949): udhcpc: lease of 25.121.209.255 obtained, lease time 7200

…but still no internet connection, as OpenVPN client is still unable to connect…

Mon Oct 22 06:10:18 2018 daemon.err openvpn[3239]: RESOLVE: Cannot resolve host address: openvpn.hostname.com:443 (Try again)
Mon Oct 22 06:10:23 2018 daemon.err openvpn[3239]: RESOLVE: Cannot resolve host address: openvpn.hostname.com:443 (Try again)
Mon Oct 22 06:10:23 2018 daemon.warn openvpn[3239]: Could not determine IPv4/IPv6 protocol
Mon Oct 22 06:10:23 2018 daemon.notice openvpn[3239]: SIGUSR1[soft,init_instance] received, process restarting
Mon Oct 22 06:10:23 2018 daemon.notice openvpn[3239]: Restart pause, 300 second(s)

…

Mon Oct 22 07:05:43 2018 daemon.notice netifd: modem_4 (1949): udhcpc: sending renew
Mon Oct 22 07:05:43 2018 daemon.notice netifd: modem_4 (1949): udhcpc: lease of 25.121.209.255 obtained, lease time 7200

…

Mon Oct 22 08:05:43 2018 daemon.notice netifd: modem_4 (1949): udhcpc: sending renew
…

Mon Oct 22 08:35:44 2018 daemon.notice netifd: modem_4 (1949): udhcpc: sending renew

…

Mon Oct 22 08:50:44 2018 daemon.notice netifd: modem_4 (1949): udhcpc: sending renew

…

Mon Oct 22 08:58:14 2018 daemon.notice netifd: modem_4 (1949): udhcpc: sending renew

…

Mon Oct 22 09:01:59 2018 daemon.notice netifd: modem_4 (1949): udhcpc: sending renew

…

Mon Oct 22 09:03:51 2018 daemon.notice netifd: modem_4 (1949): udhcpc: sending renew

…

Mon Oct 22 09:04:47 2018 daemon.notice netifd: modem_4 (1949): udhcpc: sending renew

…keeps attempting at half the delay until…

Mon Oct 22 09:05:15 2018 daemon.notice netifd: modem_4 (1949): udhcpc: sending renew
Mon Oct 22 09:05:29 2018 daemon.notice netifd: modem_4 (1949): udhcpc: sending renew
Mon Oct 22 09:05:36 2018 daemon.notice netifd: modem_4 (1949): udhcpc: sending renew
Mon Oct 22 09:05:39 2018 daemon.notice netifd: modem_4 (1949): udhcpc: sending renew
Mon Oct 22 09:05:40 2018 daemon.notice netifd: modem_4 (1949): udhcpc: sending renew

…this happens…

Mon Oct 22 09:05:40 2018 daemon.notice netifd: modem_4 (1949): udhcpc: lease lost, entering init state
Mon Oct 22 09:05:40 2018 daemon.notice netifd: Interface 'modem_4' has lost the connection

…and now it apparently stops attempting to renew its old address and asks for a new one…

Mon Oct 22 09:05:40 2018 daemon.info dnsmasq[3766]: reading /tmp/resolv.conf.auto
Mon Oct 22 09:05:40 2018 daemon.info dnsmasq[3766]: using nameserver 8.8.4.4#53
Mon Oct 22 09:05:40 2018 daemon.info dnsmasq[3766]: using nameserver 8.8.8.8#53
Mon Oct 22 09:05:40 2018 daemon.info dnsmasq[3766]: using local addresses only for domain localdomain.lan
Mon Oct 22 09:05:40 2018 daemon.info dnsmasq[3766]: using nameserver 8.8.8.8#53
Mon Oct 22 09:05:40 2018 daemon.info dnsmasq[3766]: using nameserver 8.8.4.4#53

…request for new IP is apparently granted…

Mon Oct 22 09:05:40 2018 daemon.notice netifd: modem_4 (1949): udhcpc: sending discover
Mon Oct 22 09:05:40 2018 daemon.notice netifd: modem_4 (1949): udhcpc: sending select for 29.16.113.153
Mon Oct 22 09:05:40 2018 daemon.notice netifd: modem_4 (1949): udhcpc: lease of 29.16.113.153 obtained, lease time 7200
Mon Oct 22 09:05:41 2018 daemon.notice netifd: Interface 'modem_4' is now up
Mon Oct 22 09:05:41 2018 daemon.info dnsmasq[3766]: reading /tmp/resolv.conf.auto
Mon Oct 22 09:05:41 2018 daemon.info dnsmasq[3766]: using nameserver 8.8.4.4#53
Mon Oct 22 09:05:41 2018 daemon.info dnsmasq[3766]: using nameserver 8.8.8.8#53
Mon Oct 22 09:05:41 2018 daemon.info dnsmasq[3766]: using local addresses only for domain localdomain.lan
Mon Oct 22 09:05:41 2018 daemon.info dnsmasq[3766]: using nameserver 8.8.8.8#53
Mon Oct 22 09:05:41 2018 daemon.info dnsmasq[3766]: using nameserver 8.8.4.4#53

…but still, OpenVPN unable to resolve server hostname…

Mon Oct 22 09:06:04 2018 daemon.err openvpn[3239]: RESOLVE: Cannot resolve host address: openvpn.hostname.com:443 (Try again)
Mon Oct 22 09:06:04 2018 daemon.warn openvpn[3239]: Could not determine IPv4/IPv6 protocol
Mon Oct 22 09:06:04 2018 daemon.notice openvpn[3239]: SIGUSR1[soft,init_instance] received, process restarting
Mon Oct 22 09:06:04 2018 daemon.notice openvpn[3239]: Restart pause, 300 second(s)

…then this routine some more…

Mon Oct 22 10:05:40 2018 daemon.notice netifd: modem_4 (1949): udhcpc: sending renew
...
Mon Oct 22 10:35:40 2018 daemon.notice netifd: modem_4 (1949): udhcpc: sending renew
...
Mon Oct 22 10:50:40 2018 daemon.notice netifd: modem_4 (1949): udhcpc: sending renew
...
Mon Oct 22 10:58:10 2018 daemon.notice netifd: modem_4 (1949): udhcpc: sending renew
…
Mon Oct 22 11:01:55 2018 daemon.notice netifd: modem_4 (1949): udhcpc: sending renew
...
Mon Oct 22 11:03:47 2018 daemon.notice netifd: modem_4 (1949): udhcpc: sending renew
...
Mon Oct 22 11:04:43 2018 daemon.notice netifd: modem_4 (1949): udhcpc: sending renew
...
Mon Oct 22 11:05:11 2018 daemon.notice netifd: modem_4 (1949): udhcpc: sending renew
Mon Oct 22 11:05:25 2018 daemon.notice netifd: modem_4 (1949): udhcpc: sending renew
Mon Oct 22 11:05:32 2018 daemon.notice netifd: modem_4 (1949): udhcpc: sending renew
Mon Oct 22 11:05:35 2018 daemon.notice netifd: modem_4 (1949): udhcpc: sending renew
Mon Oct 22 11:05:36 2018 daemon.notice netifd: modem_4 (1949): udhcpc: sending renew
Mon Oct 22 11:05:36 2018 daemon.notice netifd: modem_4 (1949): udhcpc: lease lost, entering init state
Mon Oct 22 11:05:36 2018 daemon.notice netifd: Interface 'modem_4' has lost the connection

…then the PREVIOUS IP GETS RE-ISSUED!

Mon Oct 22 11:05:36 2018 daemon.notice netifd: modem_4 (1949): udhcpc: sending discover
Mon Oct 22 11:05:36 2018 daemon.notice netifd: modem_4 (1949): udhcpc: sending select for 25.121.209.255
Mon Oct 22 11:05:36 2018 daemon.notice netifd: modem_4 (1949): udhcpc: lease of 25.121.209.255 obtained, lease time 7200

…and still no connection available for OpenVPN…

Mon Oct 22 11:10:00 2018 daemon.err openvpn[3239]: RESOLVE: Cannot resolve host address: openvpn.hostname.com:443 (Try again)
Mon Oct 22 11:10:05 2018 daemon.err openvpn[3239]: RESOLVE: Cannot resolve host address: openvpn.hostname.com:443 (Try again)
Mon Oct 22 11:10:05 2018 daemon.warn openvpn[3239]: Could not determine IPv4/IPv6 protocol
Mon Oct 22 11:10:05 2018 daemon.notice openvpn[3239]: SIGUSR1[soft,init_instance] received, process restarting
Mon Oct 22 11:10:05 2018 daemon.notice openvpn[3239]: Restart pause, 300 second(s)

A simple etc/init.d/network restart brings everything back up. So what’s going on? My theory is there’s something in my local DHCP config, which issues leases every 12 h, that is conflicting when the carrier DHCP reissue. Is that possible? Or perhaps the various DNS settings I’ve tried are conflicting with the carrier IP lease? See etc/config/dhcp contents below:

config dnsmasq
        option localise_queries '1'
        option expandhosts '1'
        option readethers '1'
        option leasefile '/tmp/dhcp.leases'
        option rebind_protection '0'
        option local '/local.lan/'
        option domain local.lan'
        option localservice '0'
        option nonwildcard '0'
        list server '8.8.8.8'
        list server '8.8.4.4'
        option noresolv '1'

config dhcp 'lan'
        option interface 'lan'
        option leasetime '12h'
        option limit '50'
        option start '1'

config dhcp 'wan'
        option interface 'wan'
        option ignore '1'

config odhcpd 'odhcpd'
        option maindhcp '0'
        option leasefile '/tmp/hosts/odhcpd'
        option leasetrigger '/usr/sbin/odhcpd-update'

config domain 'localhost'
        option name 'console.gl-inet.com'
        option ip '10.28.0.1'

config dhcp 'lan2'
        option leasetime '12h'
        option interface 'lan2'
        option limit '50'
        option start '1'

kyson-lok · 2018-10-23T09:45:59.889Z

Which firmware do you use?

Would it be caused by the weak signal strength of your modem?

RVIT:

…but still, OpenVPN unable to resolve server hostname…

In this case, could you ping other sites or 8.8.8.8 to check if the internet is connected or not?

RVIT · 2018-10-23T13:11:41.326Z

kyson-lok:

Which firmware do you use?

Would it be caused by the weak signal strength of your modem?

RVIT:

…but still, OpenVPN unable to resolve server hostname…

In this case, could you ping other sites or 8.8.8.8 to check if the internet is connected or not?

I’m using 2.271 on both devices.

Well, its certainly possible that signal is dropping on the 4G, but as soon as I do a /etc/init.d/network reset (or power cycle the router), the connection comes back up just fine. This would indicate there is an adequate signal available.

I suspect dnsmasq may be where the issue lies, but I can’t seem to figure out whats going on.

Same thing this morning, I was connected to the MiFi overnight via ethernet. When I woke up, no internet connection and no local network connection on ethernet interface. Tried to print to a local printer but this did not work. Connected to Wifi and the page began printing immediately. Power cycled the MiFi and was able to print again from ethernet.

RVIT · 2018-10-23T13:29:21.560Z

What are your thoughts about some of the following DNS/DHCP settings potentially causing issues?

noresolv ‘1’
localise_queries ‘1’
expandhosts ‘1’
readethers ‘1’

Under odhcpd does it matter if maindhcp is set to 0 or 1?
maindhcp ‘0’

kyson-lok · 2018-10-24T02:22:26.672Z

RVIT:

When I woke up, no internet connection and no local network connection on ethernet interface. Tried to print to a local printer but this did not work

Doesn’t it assign an IP address to devices?

kyson-lok · 2018-10-24T02:28:16.877Z

It is nothing with odhcpd, because OpenWRT uses dnsmasq by default, it will ignore odhcpd configuration.

Could you try our v3.0 firmware? http://download.gl-inet.com/firmware/mifi/testing/

Please don’t keep settings when upgrading.

RVIT · 2018-10-24T03:14:01.532Z

kyson-lok:

Doesn’t it assign an IP address to devices?

Yes, I thought that was strange. It did have an IP address in the correct subnet, but not able to access local network resources until I switched to the wireless interface.

RVIT · 2018-10-24T03:16:55.667Z

kyson-lok:

It is nothing with odhcpd, because OpenWRT uses dnsmasq by default, it will ignore odhcpd configuration.

Could you try our v3.0 firmware? http://download.gl-inet.com/firmware/mifi/testing/

Please don’t keep settings when upgrading.

I had installed that initially, but was unable to run two SSIDs on segregated subnets using the 3.0 firmware. Will try again and see if I can get it to work.

I do have about 60 MT300N-V2s running 2.271 already deployed, some of which exhibit the same issue, so I’d like to figure out the cause if possible. Appreciate your help.

kyson-lok · 2018-10-24T03:18:26.284Z

Could you PM me all the configuration files? You can get it on luci.

RVIT · 2018-10-24T03:20:28.451Z

kyson-lok:

Could you PM me all the configuration files? You can get it on luci.

Certainly, sending over momentarily.

doujinflip · 2018-10-26T06:22:47.766Z

I too seem to require routine modem resets or power cycles to keep my MiFi on the network. I know it’s not a signal issue as I’m using it in all the same places as before. I’m on v3.005 and it seems to be getting worse with every new beta.

RVIT · 2018-10-31T13:37:08.479Z

Mine is definitely related to ISP IP changes. I lost all internet again this morning, but could access the MiFi device via Luci and ssh. When I checked the logs, the device had been renewing the same IP address from the 4G provider for the last 7 days without incident. Then attempted another renewal in the middle of the night and was unsuccessful. Its next renewal attempt received a different IP address, and from that point forward, the device did not have a connection out to the internet - the router itself could not ping hostnames or IP addresses over the WAN (nor could any of the clients). Oddly enough, it could ping the ISP gateway IP without an issue.

Performing an etc/init.d/network reset restored the internet connection to both the MiFi and its clients (and it retained the same IP that it had received in the middle of the night when the internet connection was lost).

If it were just an issue with DNS resolution, there would be more failure points to check, but since IP traffic is also not going through, it seems like perhaps a routing table issue? I’ll have to remember next time the problem occurs to check whether the default route is perhaps not updating when the IP switches over.

alzhao · 2018-10-31T16:56:01.828Z

Yes. Pls get all the log and route next time before you restart the firewall.

@kyson-lok have a check of this.

kyson-lok · 2018-11-02T03:02:27.086Z

@RVIT Could you please upgrade to the latest testing firmware? It is available in http://download.gl-inet.com.s3.amazonaws.com/firmware/mifi/testing/gl-mifi-3.006-1101.bin. Please untick “keep settings” when upgrading.