Spitz AX tethering - not renewing dhcp

Here is a log I have captured today regarding my tethering failing. It appears to be related to DHCP not working properly. Once the lease expires, the connection drops.

Mon Jan 20 18:19:00 2025 daemon.notice netifd: tethering (941): udhcpc: received SIGTERM
Mon Jan 20 18:19:00 2025 daemon.notice netifd: tethering (941): udhcpc: entering released state
Mon Jan 20 18:19:00 2025 daemon.notice netifd: tethering (941): Command failed: Permission denied
Mon Jan 20 18:19:00 2025 daemon.notice netifd: Interface 'tethering' is now down
Mon Jan 20 18:19:00 2025 daemon.notice netifd: Interface 'tethering' is disabled
Mon Jan 20 18:19:00 2025 daemon.notice netifd: Interface 'tethering' has link connectivity loss
Mon Jan 20 18:19:00 2025 user.notice firewall: Reloading firewall due to ifdown of tethering ()
Mon Jan 20 18:19:00 2025 user.notice kmwan: config json str={ "op": 3, "data": { "cells": [ "tethering" ] } }
Mon Jan 20 18:19:02 2025 daemon.notice netifd: Interface 'tethering' is enabled
Mon Jan 20 18:19:02 2025 daemon.notice netifd: Interface 'tethering' has link connectivity
Mon Jan 20 18:19:02 2025 daemon.notice netifd: Interface 'tethering' is setting up now
Mon Jan 20 18:19:02 2025 daemon.notice netifd: tethering (14776): udhcpc: started, v1.33.2
Mon Jan 20 18:19:02 2025 daemon.notice netifd: tethering (14776): udhcpc: sending discover
Mon Jan 20 18:19:02 2025 daemon.notice netifd: tethering (14776): udhcpc: sending select for 172.20.10.6
Mon Jan 20 18:19:02 2025 daemon.notice netifd: tethering (14776): udhcpc: lease of 172.20.10.6 obtained, lease time 3600
Mon Jan 20 18:19:02 2025 daemon.notice netifd: Interface 'tethering' is now up
Mon Jan 20 18:19:02 2025 user.notice firewall: Reloading firewall due to ifup of tethering (eth2)
Mon Jan 20 18:19:02 2025 user.notice kmwan: config json str={ "op": 2, "data": { "cells": [ { "interface": "tethering", "netdev": "eth2", "track_mode": "force", "addr_type": 4, "tracks": [ { "type": "ping", "ip": "1.1.1.1" }, { "type": "ping", "ip": "8.8.8.8" }, { "type": "ping", "ip": "208.67.222.222" }, { "type": "ping", "ip": "208.67.220.220" } ] } ] } }
Mon Jan 20 18:19:02 2025 kern.debug kernel: [2103637.507755] [add_dev_config 303]add node success. iface:tethering, dev:eth2, ifindex:47
Mon Jan 20 18:49:02 2025 daemon.notice netifd: tethering (14776): udhcpc: sending renew to 172.20.10.1
Mon Jan 20 19:04:02 2025 daemon.notice netifd: tethering (14776): udhcpc: sending renew to 172.20.10.1
Mon Jan 20 19:11:32 2025 daemon.notice netifd: tethering (14776): udhcpc: sending renew to 172.20.10.1
Mon Jan 20 19:15:17 2025 daemon.notice netifd: tethering (14776): udhcpc: sending renew to 172.20.10.1
Mon Jan 20 19:17:09 2025 daemon.notice netifd: tethering (14776): udhcpc: sending renew to 172.20.10.1
Mon Jan 20 19:18:05 2025 daemon.notice netifd: tethering (14776): udhcpc: sending renew to 0.0.0.0
Mon Jan 20 19:18:33 2025 daemon.notice netifd: tethering (14776): udhcpc: sending renew to 0.0.0.0
Mon Jan 20 19:18:47 2025 daemon.notice netifd: tethering (14776): udhcpc: sending renew to 0.0.0.0
Mon Jan 20 19:18:54 2025 daemon.notice netifd: tethering (14776): udhcpc: sending renew to 0.0.0.0
Mon Jan 20 19:18:58 2025 daemon.notice netifd: tethering (14776): udhcpc: sending renew to 0.0.0.0
Mon Jan 20 19:18:59 2025 daemon.notice netifd: tethering (14776): udhcpc: sending renew to 0.0.0.0
Mon Jan 20 19:18:59 2025 daemon.notice netifd: tethering (14776): udhcpc: lease lost, entering init state
Mon Jan 20 19:18:59 2025 daemon.notice netifd: Interface 'tethering' has lost the connection
Mon Jan 20 19:18:59 2025 daemon.notice netifd: tethering (14776): udhcpc: sending discover
Mon Jan 20 19:18:59 2025 user.notice firewall: Reloading firewall due to ifdown of tethering ()
Mon Jan 20 19:18:59 2025 user.notice kmwan: config json str={ "op": 3, "data": { "cells": [ "tethering" ] } }
Mon Jan 20 19:18:59 2025 kern.debug kernel: [2107233.580851] kmwan: Delete node:tethering
Mon Jan 20 19:19:02 2025 daemon.notice netifd: tethering (14776): udhcpc: sending discover
Mon Jan 20 21:58:53 2025 daemon.notice netifd: tethering (14776): udhcpc: received SIGTERM
Mon Jan 20 21:58:53 2025 daemon.notice netifd: tethering (14776): udhcpc: entering released state
Mon Jan 20 21:58:53 2025 daemon.notice netifd: tethering (14776): Command failed: Permission denied
Mon Jan 20 21:58:53 2025 daemon.notice netifd: Interface 'tethering' is now down
Mon Jan 20 21:58:53 2025 daemon.notice netifd: Interface 'tethering' is disabled
Mon Jan 20 21:58:53 2025 daemon.notice netifd: Interface 'tethering' has link connectivity loss
Mon Jan 20 21:58:53 2025 user.notice firewall: Reloading firewall due to ifdown of tethering ()
Mon Jan 20 21:58:54 2025 user.notice kmwan: config json str={ "op": 3, "data": { "cells": [ "tethering" ] } }
Mon Jan 20 21:58:54 2025 daemon.notice netifd: Interface 'tethering' is enabled
Mon Jan 20 21:58:54 2025 daemon.notice netifd: Interface 'tethering' has link connectivity
Mon Jan 20 21:58:54 2025 daemon.notice netifd: Interface 'tethering' is setting up now
Mon Jan 20 21:58:54 2025 daemon.notice netifd: tethering (23738): udhcpc: started, v1.33.2
Mon Jan 20 21:58:54 2025 daemon.notice netifd: tethering (23738): udhcpc: sending discover
Mon Jan 20 21:58:54 2025 daemon.notice netifd: tethering (23738): udhcpc: sending select for 172.20.10.6
Mon Jan 20 21:58:54 2025 daemon.notice netifd: tethering (23738): udhcpc: lease of 172.20.10.6 obtained, lease time 3600
Mon Jan 20 21:58:54 2025 daemon.notice netifd: Interface 'tethering' is now up
Mon Jan 20 21:58:55 2025 user.notice firewall: Reloading firewall due to ifup of tethering (eth2)
Mon Jan 20 21:58:55 2025 user.notice kmwan: config json str={ "op": 2, "data": { "cells": [ { "interface": "tethering", "netdev": "eth2", "track_mode": "force", "addr_type": 4, "tracks": [ { "type": "ping", "ip": "1.1.1.1" }, { "type": "ping", "ip": "8.8.8.8" }, { "type": "ping", "ip": "208.67.222.222" }, { "type": "ping", "ip": "208.67.220.220" } ] } ] } }
Mon Jan 20 21:58:55 2025 kern.debug kernel: [2116826.964003] [add_dev_config 303]add node success. iface:tethering, dev:eth2, ifindex:47

I am using an iPhone SE on AT&T for this connection.

I manually aborted the connection and restarted it, thus you see a successful reconnection. I am running 4.7 latest beta. IOS 18.2.1 (current - has been happening for a while though).

Checked the relation in the syslog, the tethering udhcpc have sent 5+5 times renew to the phone, but the phone has not replied, and the interface 'tethering' restart, the udhcpc discover and connected.

Yes, I understood what was happening based on the logs, but I don't know why it is happening. If I manually connect to tethering via web interface, it generally reconnects. Why does it require that step? On a side note, I disabled internet status tracking on that interface last night after capturing the logs and the connection has not dropped. I logged into ssh and ran a ping from that interface and it was working fine.

I will keep monitoring and see when and if it drops again.

Here is the log with the internet status tracking disabled:

Tue Jan 21 15:29:01 2025 daemon.notice netifd: tethering (23738): udhcpc: sending renew to 172.20.10.1
Tue Jan 21 15:29:01 2025 daemon.notice netifd: tethering (23738): udhcpc: lease of 172.20.10.6 obtained, lease time 3600
Tue Jan 21 15:59:01 2025 daemon.notice netifd: tethering (23738): udhcpc: sending renew to 172.20.10.1
Tue Jan 21 15:59:01 2025 daemon.notice netifd: tethering (23738): udhcpc: lease of 172.20.10.6 obtained, lease time 3600
Tue Jan 21 16:29:00 2025 daemon.notice netifd: tethering (23738): udhcpc: sending renew to 172.20.10.1
Tue Jan 21 16:29:01 2025 daemon.notice netifd: tethering (23738): udhcpc: lease of 172.20.10.6 obtained, lease time 3600
Tue Jan 21 16:59:01 2025 daemon.notice netifd: tethering (23738): udhcpc: sending renew to 172.20.10.1
Tue Jan 21 16:59:01 2025 daemon.notice netifd: tethering (23738): udhcpc: lease of 172.20.10.6 obtained, lease time 3600
Tue Jan 21 17:29:01 2025 daemon.notice netifd: tethering (23738): udhcpc: sending renew to 172.20.10.1
Tue Jan 21 17:29:01 2025 daemon.notice netifd: tethering (23738): udhcpc: lease of 172.20.10.6 obtained, lease time 3600
Tue Jan 21 17:59:01 2025 daemon.notice netifd: tethering (23738): udhcpc: sending renew to 172.20.10.1
Tue Jan 21 17:59:01 2025 daemon.notice netifd: tethering (23738): udhcpc: lease of 172.20.10.6 obtained, lease time 3600

Another day and still connected. I still have internet status tracking disbled. I am going to mark this solved as my disconnections seem to be much less frequent. I just have to remember to validate the connection is up and running before downing my cellular interface. For anyone wondering - I use the following to check:

sudo -g nonevpn curl --interface eth2 https://ipecho.net/plain && echo ""

This provide my public IP back using the tethering interface and bypassing VPN processes. Just need the curl portion if you don't use VPN.

However, @bruce, I still feel like there is an issue with the internet status tracking where it looks like it is requesting a DHCP lease renewal but I don't think it is actually doing so. Perhaps I could do a packet capture on eth2 to validate what is happening.

Thank you.

If the interface internet status tracking is enabled, does the DHCP lease renewal not work?

My connection is back down right now, so I need to go back out to check. However, with tracking enabled, i would lose connection within a few hours and saw that dhcp was not renewing properly. after disabling status tracking, it remained connected for several days without dropping. i don't know why it dropped this last time, but it might have been an iOS update or something. I may go back out this weekend to check on things.

1 Like

I went back out to the RV this weekend and restarted the tether. I also enabled remote logging, so with any luck I will be able to see when it happens again and create a notification to let me know it went down. It is not my primary connection. Cannot see any reason that it would have dropped, but hopefully I will catch the drop in a log when it happens again. If it were just every few weeks it wouldn't be too big of a deal really.

1 Like

The connection went down today again. here are the logs containing tethering:

Feb  5 15:55:29 10.0.0.2 kmwan: config json str={ "op": 3, "data": { "cells": [ "tethering" ] } }
 
Feb  5 15:55:29 10.0.0.2 firewall: Reloading firewall due to ifdown of tethering ()
 
Feb  5 15:55:29 10.0.0.2 netifd: Interface 'tethering' is disabled
 
Feb  5 15:55:29 10.0.0.2 netifd: Interface 'tethering' is now down
 
Feb  5 15:55:29 10.0.0.2 netifd: tethering (17696): Command failed: Permission denied
 
Feb  5 15:55:29 10.0.0.2 netifd: tethering (17696): udhcpc: entering released state
 
Feb  5 15:55:29 10.0.0.2 netifd: tethering (17696): udhcpc: bindtodevice: No such device
 
Feb  5 15:55:29 10.0.0.2 netifd: tethering (17696): udhcpc: can't bind to interface eth2: No such device
 
Feb  5 15:55:29 10.0.0.2 netifd: tethering (17696): udhcpc: sending release
 
Feb  5 15:55:29 10.0.0.2 netifd: tethering (17696): udhcpc: unicasting a release of 172.20.10.6 to 172.20.10.1
 
Feb  5 15:55:29 10.0.0.2 netifd: tethering (17696): udhcpc: received SIGTERM
 
Feb  5 15:55:29 10.0.0.2 netifd: tethering (17696): udhcpc: SIOCGIFINDEX: No such device
 
Feb  5 15:55:28 10.0.0.2 netifd: Interface 'tethering' has link connectivity loss
 
Feb  5 15:51:08 10.0.0.2 netifd: tethering (17696): udhcpc: lease of 172.20.10.6 obtained, lease time 3600

And here are all the logs entries for the time period:

Feb  5 15:55:29 10.0.0.2 kmwan: config json str={ "op": 3, "data": { "cells": [ "tethering" ] } }

Feb  5 15:55:29 10.0.0.2 firewall: Reloading firewall due to ifdown of tethering ()

Feb  5 15:55:29 10.0.0.2 netifd: Interface 'tethering' is disabled

Feb  5 15:55:29 10.0.0.2 netifd: Interface 'tethering' is now down

Feb  5 15:55:29 10.0.0.2 netifd: tethering (17696): Command failed: Permission denied

Feb  5 15:55:29 10.0.0.2 netifd: tethering (17696): udhcpc: entering released state

Feb  5 15:55:29 10.0.0.2 netifd: tethering (17696): udhcpc: bindtodevice: No such device

Feb  5 15:55:29 10.0.0.2 netifd: tethering (17696): udhcpc: can't bind to interface eth2: No such device

Feb  5 15:55:29 10.0.0.2 netifd: tethering (17696): udhcpc: sending release

Feb  5 15:55:29 10.0.0.2 netifd: tethering (17696): udhcpc: unicasting a release of 172.20.10.6 to 172.20.10.1

Feb  5 15:55:29 10.0.0.2 netifd: tethering (17696): udhcpc: received SIGTERM

Feb  5 15:55:29 10.0.0.2 netifd: tethering (17696): udhcpc: SIOCGIFINDEX: No such device

Feb  5 15:55:28 10.0.0.2 netifd: Interface 'tethering' has link connectivity loss

Feb  5 15:51:08 10.0.0.2 netifd: tethering (17696): udhcpc: lease of 172.20.10.6 obtained, lease time 3600

Feb  5 15:55:28 10.0.0.2 usbmuxd[15499]: [15:55:28.070][3] Removed device 1 on location 0x1000e

Feb  5 15:55:07 10.0.0.2 kernel: [3477066.065944] 7981@C13L1,tx_free_v3_notify_handler() 3533: token used by current wcid = 1, free_token_cnt = 2299

Feb  5 15:55:07 10.0.0.2 kernel: [3477066.056376] 7981@C13L1,tx_free_v3_notify_handler() 3530: ContTxFailCntTotal = 6, ContTxFailCnt300ms = 1

Feb  5 15:55:05 10.0.0.2 kernel: [3477063.760477] 7981@C13L1,tx_free_v3_notify_handler() 3533: token used by current wcid = 1, free_token_cnt = 2303

Feb  5 15:55:05 10.0.0.2 kernel: [3477063.750914] 7981@C13L1,tx_free_v3_notify_handler() 3530: ContTxFailCntTotal = 5, ContTxFailCnt300ms = 1

Feb  5 15:55:04 10.0.0.2 kernel: [3477062.462606] 7981@C13L1,tx_free_v3_notify_handler() 3533: token used by current wcid = 1, free_token_cnt = 2303

Feb  5 15:55:04 10.0.0.2 kernel: [3477062.453036] 7981@C13L1,tx_free_v3_notify_handler() 3530: ContTxFailCntTotal = 4, ContTxFailCnt300ms = 2

Feb  5 15:55:03 10.0.0.2 kernel: [3477061.892528] 7981@C13L1,tx_free_v3_notify_handler() 3533: token used by current wcid = 2, free_token_cnt = 2302

Feb  5 15:55:03 10.0.0.2 kernel: [3477061.882962] 7981@C13L1,tx_free_v3_notify_handler() 3530: ContTxFailCntTotal = 2, ContTxFailCnt300ms = 1

Feb  5 15:55:02 10.0.0.2 kernel: [3477061.034529] 7981@C13L1,tx_free_v3_notify_handler() 3533: token used by current wcid = 1, free_token_cnt = 2303

Feb  5 15:55:02 10.0.0.2 kernel: [3477061.024954] 7981@C13L1,tx_free_v3_notify_handler() 3530: ContTxFailCntTotal = 1, ContTxFailCnt300ms = 1

Feb  5 15:51:08 10.0.0.2 netifd: tethering (17696): udhcpc: lease of 172.20.10.6 obtained, lease time 3600

Feb  5 15:51:08 10.0.0.2 netifd: tethering (17696): udhcpc: sending renew to 172.20.10.1

Another thing I am seeing - the phone is slowly losing power according to the "Find My" app even though it is plugged into the router. It was holding a charge prior to the disconnect. So whatever is happening, it is having a physical affect on the connection as well. I have tried 3 different cables, so I am pretty confident that is not the issue. 2 of those were brand new apple cables out of the box (one is still in use right now).

Is the multi-wan enabled on this issue log period?

Please PM me the whole syslog "logread.tar" file. Thank you.

Multi-wan is set up for fail over, but internet status tracking was disabled. Cellular is above tethering in the connection priority and they are the only enabled wan interfaces. I will have to wait until another dropout to grab logs and send to you.

1 Like

I was able to get back out to the router yesterday. It was disconnected via tether but still plugged in. The phone was powered off but charged to 100% when I powered it back on. I updated the phone (iOS 18.3 to 18.3.1) while I was out there. But I validated tethering was up and working and then went back home.

This morning I noticed the modem interface wasn't passing much traffic at all (I monitor via SNMP) but the tethering interface (eth2) had passed about 200mb overnight. This is unusual, so I looked into the issue. Both the cellular and the tethering interfaces were up and connected. I have the internet status monitoring enabled for cellular but disabled for tethering.

I noticed a "Low Power" box next to the cellular interface. First time I had seen this, so I check it out and the cellular interface was set to Low Data mode somehow. So even though cellular was higher in the interface priority list, the router was using the tethering interface for traffic. I changed it to normal and the router switched back to the cellular interface. Any idea why the cellular interface seems to have defaulted to Low Power?

I will watch for a drop of the tethering interface and capture the logs at that point and send them to you @bruce. Until then, I will wait and see what happens.