Spitz AX Cellular connection stop working after a couple of days

Technical Support for Routers
1

I am testing with latest beta (2023-04-25), after sometimes (usually 2 days) the cellular connection stop working.
On the UI I have the message “interface is connected but internet can’t be accessed”.
Clicking on “manual setup” and choosing my saved APN makes the connection start again.
Maybe this is happening when my IP is changing?
On log I have:

Sat May  6 13:44:06 2023 user.notice mwan3[2088]: Execute ifdown event on interface modem_0001 (rmnet_mhi0)
Sat May  6 13:44:06 2023 user.notice firewall: Reloading firewall due to ifdown of modem_0001 (rmnet_mhi0)
Sat May  6 13:44:07 2023 user.info mwan3track[14450]: Detect ifdown event on interface modem_0001 (rmnet_mhi0)
Sat May  6 13:44:12 2023 user.notice mwan3track[14450]: Interface modem_0001 (rmnet_mhi0) is offline
2023 daemon.notice netifd: modem_0001_4 (14181): udhcpc: received SIGTERM
Sat May  6 13:52:24 2023 daemon.notice netifd: modem_0001_4 (14181): udhcpc: unicasting a release of 10.21.xxx.xxx to 10.21.xxx.xxx
Sat May  6 13:52:24 2023 daemon.notice netifd: modem_0001_4 (14181): udhcpc: sending release
Sat May  6 13:52:24 2023 daemon.notice netifd: modem_0001_4 (14181): udhcpc: entering released state
Sat May  6 13:52:24 2023 daemon.notice netifd: modem_0001 (14146): [05-05_13:46:13:372] requestGetSIMStatus SIMStatus: SIM_READY
Sat May  6 13:52:24 2023 daemon.notice netifd: modem_0001 (14146): [05-05_13:46:13:375] requestGetProfile[1] casa.postemobile.it///0/IPV4
Sat May  6 13:52:24 2023 daemon.notice netifd: modem_0001 (14146): [05-05_13:46:13:375] requestSetProfile[1] casa.postemobile.it///0/IPV4
Sat May  6 13:52:24 2023 daemon.notice netifd: modem_0001 (14146): [05-05_13:46:13:375] no need to set skip the rest
Sat May  6 13:52:24 2023 daemon.notice netifd: modem_0001 (14146): [05-05_13:46:13:377] requestRegistrationState2 MCC: 222, MNC: 10, PS: Attached, DataCap: LTE
Sat May  6 13:52:24 2023 daemon.notice netifd: modem_0001 (14146): [05-05_13:46:13:379] requestQueryDataCall IPv4ConnectionStatus: DISCONNECTED
Sat May  6 13:52:24 2023 daemon.notice netifd: modem_0001 (14146): [05-05_13:46:13:387] requestSetupDataCall WdsConnectionIPv4Handle: 0x72ba2fe0
Sat May  6 13:52:24 2023 daemon.notice netifd: modem_0001 (14146): [05-06_13:43:27:287] requestQueryDataCall IPv4ConnectionStatus: DISCONNECTED
Sat May  6 13:52:24 2023 daemon.notice netifd: modem_0001 (14146): [05-06_13:43:28:158] requestRegistrationState2 MCC: 222, MNC: 10, PS: Attached, DataCap: LTE
Sat May  6 13:52:24 2023 daemon.notice netifd: modem_0001 (14146): [05-06_13:43:29:170] requestSetupDataCall WdsConnectionIPv4Handle: 0x72ba2fe0
Sat May  6 13:52:24 2023 daemon.notice netifd: modem_0001 (14146): [05-06_13:52:24:790] requestDeactivateDefaultPDP WdsConnectionIPv4Handle
Sat May  6 13:52:24 2023 daemon.notice netifd: modem_0001 (14146): [05-06_13:52:24:813] QmiWwanThread exit
Sat May  6 13:52:24 2023 daemon.notice netifd: modem_0001 (14146): [05-06_13:52:24:813] qmi_main exit
Sat May  6 13:52:24 2023 daemon.notice netifd: Interface 'modem_0001' is now down
Sat May  6 13:52:24 2023 daemon.notice netifd: modem_0001_4 (14181): Command failed: Permission denied
Sat May  6 13:52:24 2023 daemon.notice netifd: Interface 'modem_0001_4' is now down
Sat May  6 13:52:24 2023 daemon.notice netifd: Interface 'modem_0001_4' is disabled
Sat May  6 13:52:24 2023 daemon.notice netifd: Network alias '' link is down
Sat May  6 13:52:24 2023 daemon.notice netifd: Interface 'modem_0001_4' has link connectivity loss
Sat May  6 13:52:25 2023 user.warn : skip line without '=' Default
Sat May  6 13:52:25 2023 user.warn : skip line without '='
Sat May  6 13:52:25 2023 user.warn : skip line without '=' Default
Sat May  6 13:52:25 2023 user.warn : skip line without '='
Sat May  6 13:52:25 2023 user.warn : skip line without '=' Default
Sat May  6 13:52:25 2023 user.warn : skip line without '='
Sat May  6 13:52:25 2023 user.notice firewall: Reloading firewall due to ifdown of modem_0001 ()
Sat May  6 13:52:25 2023 user.warn : skip line without '=' Default
Sat May  6 13:52:25 2023 user.warn : skip line without '='
Sat May  6 13:52:25 2023 user.warn : skip line without '=' Default
Sat May  6 13:52:25 2023 user.warn : skip line without '='
Sat May  6 13:52:25 2023 daemon.notice netifd: Interface 'modem_0001' is setting up now
Sat May  6 13:52:25 2023 user.warn : skip line without '=' Default
Sat May  6 13:52:25 2023 user.warn : skip line without '='
Sat May  6 13:52:25 2023 user.warn : skip line without '=' Default
Sat May  6 13:52:25 2023 user.warn : skip line without '='
Sat May  6 13:52:25 2023 daemon.notice netifd: modem_0001 (22414):
Sat May  6 13:52:25 2023 daemon.notice netifd: modem_0001 (22414):
Sat May  6 13:52:25 2023 daemon.notice netifd: modem_0001 (22414): OK
Sat May  6 13:52:25 2023 user.warn : skip line without '=' Default
Sat May  6 13:52:25 2023 user.warn : skip line without '='
Sat May  6 13:52:25 2023 user.warn : skip line without '=' Default
Sat May  6 13:52:25 2023 user.warn : skip line without '='
Sat May  6 13:52:25 2023 user.warn : skip line without '=' Default
Sat May  6 13:52:25 2023 user.warn : skip line without '='
Sat May  6 13:52:26 2023 daemon.notice netifd: modem_0001 (22414): Failed to parse message data
Sat May  6 13:52:26 2023 daemon.notice netifd: modem_0001 (22414):
Sat May  6 13:52:26 2023 daemon.notice netifd: modem_0001 (22414):
Sat May  6 13:52:26 2023 daemon.notice netifd: modem_0001 (22414): OK
Sat May  6 13:52:26 2023 daemon.notice netifd: modem_0001 (22414):
Sat May  6 13:52:26 2023 daemon.notice netifd: modem_0001 (22414):
Sat May  6 13:52:26 2023 daemon.notice netifd: modem_0001 (22414): OK
Sat May  6 13:52:26 2023 daemon.notice netifd: modem_0001 (22414):
Sat May  6 13:52:26 2023 daemon.notice netifd: modem_0001 (22414):
Sat May  6 13:52:26 2023 daemon.notice netifd: modem_0001 (22414): ERROR
Sat May  6 13:52:26 2023 daemon.notice netifd: modem_0001 (22414):
Sat May  6 13:52:26 2023 daemon.notice netifd: modem_0001 (22414):
Sat May  6 13:52:26 2023 daemon.notice netifd: modem_0001 (22414): ERROR
Sat May  6 13:52:26 2023 daemon.notice netifd: modem_0001 (22414):
Sat May  6 13:52:26 2023 daemon.notice netifd: modem_0001 (22414):
Sat May  6 13:52:26 2023 daemon.notice netifd: modem_0001 (22414): ERROR
Sat May  6 13:52:26 2023 daemon.notice netifd: modem_0001 (22994): [05-06_13:52:26:432] QConnectManager_Linux_V1.6.3.1
Sat May  6 13:52:26 2023 kern.err kernel: [86816.264435] [I][mhi_netdev_open] Opened net dev interface
Sat May  6 13:52:26 2023 daemon.notice netifd: Interface 'modem_0001' is now up
Sat May  6 13:52:26 2023 daemon.notice netifd: Network device 'rmnet_mhi0' link is up
Sat May  6 13:52:26 2023 daemon.notice netifd: Network alias 'rmnet_mhi0' link is up
Sat May  6 13:52:26 2023 daemon.notice netifd: Interface 'modem_0001_4' is enabled
Sat May  6 13:52:26 2023 daemon.notice netifd: Interface 'modem_0001_4' has link connectivity
Sat May  6 13:52:26 2023 daemon.notice netifd: Interface 'modem_0001_4' is setting up now
Sat May  6 13:52:26 2023 daemon.notice netifd: modem_0001 (22994): [05-06_13:52:26:433] Find /sys/bus/usb/devices/1-1.2 idVendor=0x2c7c idProduct=0x801, bus=0x001, dev=0x004
Sat May  6 13:52:26 2023 daemon.notice netifd: modem_0001 (22994): [05-06_13:52:26:433] network interface '' or qmidev '' is not exist
Sat May  6 13:52:26 2023 daemon.notice netifd: modem_0001 (22994): [05-06_13:52:26:433] netcard driver = pcie_mhi, driver version = V1.3.4
Sat May  6 13:52:26 2023 daemon.notice netifd: modem_0001 (22994): [05-06_13:52:26:434] qmap_mode = 1, qmap_version = 9, qmap_size = 15360, muxid = 0x81, qmap_netcard = rmnet_mhi0
Sat May  6 13:52:26 2023 daemon.notice netifd: modem_0001 (22994): [05-06_13:52:26:434] Modem works in QMI mode
Sat May  6 13:52:26 2023 daemon.notice netifd: modem_0001 (22994): [05-06_13:52:26:448] cdc_wdm_fd = 7
Sat May  6 13:52:26 2023 daemon.notice netifd: modem_0001 (22994): [05-06_13:52:26:462] Get clientWDS = 14
Sat May  6 13:52:26 2023 daemon.notice netifd: modem_0001 (22994): [05-06_13:52:26:464] Get clientDMS = 1
Sat May  6 13:52:26 2023 daemon.notice netifd: modem_0001 (22994): [05-06_13:52:26:467] Get clientNAS = 3
Sat May  6 13:52:26 2023 daemon.notice netifd: modem_0001 (22994): [05-06_13:52:26:470] Get clientUIM = 2
Sat May  6 13:52:26 2023 daemon.notice netifd: modem_0001 (22994): [05-06_13:52:26:472] Get clientWDA = 1
Sat May  6 13:52:26 2023 daemon.notice netifd: modem_0001 (22994): [05-06_13:52:26:475] requestBaseBandVersion RM520NGLAAR01A06M4G
Sat May  6 13:52:26 2023 daemon.notice netifd: modem_0001 (22994): [05-06_13:52:26:478] qmap_settings.rx_urb_size = 15360
Sat May  6 13:52:26 2023 daemon.notice netifd: modem_0001 (22994): [05-06_13:52:26:478] qmap_settings.ul_data_aggregation_max_datagrams  = 11
Sat May  6 13:52:26 2023 daemon.notice netifd: modem_0001 (22994): [05-06_13:52:26:478] qmap_settings.ul_data_aggregation_max_size       = 8192
Sat May  6 13:52:26 2023 daemon.notice netifd: modem_0001 (22994): [05-06_13:52:26:478] qmap_settings.dl_minimum_padding                 = 0
Sat May  6 13:52:26 2023 daemon.notice netifd: modem_0001_4 (23052): udhcpc: started, v1.33.2
Sat May  6 13:52:26 2023 daemon.notice netifd: modem_0001_4 (23052): udhcpc: sending discover
Sat May  6 13:52:26 2023 daemon.notice netifd: modem_0001_4 (23052): udhcpc: sending select for 10.45.xx.xxx
Sat May  6 13:52:26 2023 daemon.notice netifd: modem_0001_4 (23052): udhcpc: lease of 10.45.xx.xxx obtained, lease time 7200
Sat May  6 13:52:26 2023 daemon.notice netifd: Interface 'modem_0001_4' is now up

I’ve saved the entire logread soon after this happens, if someone want to check it out I can upload it.

1 Like
2

Yes, same issue here and I do too believe it is DHCP issue since it is no renewing the IP on lease expiration. I reported it here ( X3000 bugs report page (& feedbacks) - #6 by munsuri ) but got no answer yet (maybe it got overlooked)

1 Like
3

We have received this bug feedback, and our SW engineer is analyzing it now. Hope can fix it quickly. Thanks a lot for you testing feedback.

2 Likes
5

Thank you very much.
I have an update about this issue: it indeed happens every 24 hour, so when my IP change.
But I only have a complete disconnection every 2 or 3 days. That’s because my operator is using randomly 3 other different operators for IP assignment, and I have a complete disconnection only when the IP is assigned by “Colt technology” (the others 2 operators are Vodafone and Windtre).
However, even when the automatic reconnection works, it is extremely slow, look at that:

Sun May  7 13:39:15 2023 user.notice mwan3[28991]: Execute ifdown event on interface modem_0001 (rmnet_mhi0)
Sun May  7 13:39:16 2023 user.notice firewall: Reloading firewall due to ifdown of modem_0001 (rmnet_mhi0)
Sun May  7 13:39:16 2023 user.info mwan3track[23404]: Detect ifdown event on interface modem_0001 (rmnet_mhi0)
Sun May  7 13:39:21 2023 user.notice mwan3track[23404]: Interface modem_0001 (rmnet_mhi0) is offline
Sun May  7 13:47:36 2023 daemon.info dnsmasq-dhcp[5569]: DHCPREQUEST(br-lan) 192.168.2.86 94:83:c4:19:93:83
Sun May  7 13:47:36 2023 daemon.info dnsmasq-dhcp[5569]: DHCPACK(br-lan) 192.168.2.86 94:83:c4:19:93:83 Router-Salotto
Sun May  7 13:52:28 2023 daemon.notice netifd: modem_0001_4 (23052): udhcpc: sending renew to 10.45.68.xxx
Sun May  7 14:22:28 2023 daemon.notice netifd: modem_0001_4 (23052): udhcpc: sending renew to 10.45.68.xxx
Sun May  7 14:37:28 2023 daemon.notice netifd: modem_0001_4 (23052): udhcpc: sending renew to 10.45.68.xxx
Sun May  7 14:44:58 2023 daemon.notice netifd: modem_0001_4 (23052): udhcpc: sending renew to 10.45.68.xxx
Sun May  7 14:48:43 2023 daemon.notice netifd: modem_0001_4 (23052): udhcpc: sending renew to 10.45.68.xxx
Sun May  7 14:50:35 2023 daemon.notice netifd: modem_0001_4 (23052): udhcpc: sending renew to 10.45.68.xxx
Sun May  7 14:51:31 2023 daemon.notice netifd: modem_0001_4 (23052): udhcpc: sending renew to 0.0.0.0
Sun May  7 14:51:59 2023 daemon.notice netifd: modem_0001_4 (23052): udhcpc: sending renew to 0.0.0.0
Sun May  7 14:52:14 2023 daemon.notice netifd: modem_0001_4 (23052): udhcpc: sending renew to 0.0.0.0
Sun May  7 14:52:21 2023 daemon.notice netifd: modem_0001_4 (23052): udhcpc: sending renew to 0.0.0.0
Sun May  7 14:52:24 2023 daemon.notice netifd: modem_0001_4 (23052): udhcpc: sending renew to 0.0.0.0
Sun May  7 14:52:25 2023 daemon.notice netifd: modem_0001_4 (23052): udhcpc: sending renew to 0.0.0.0
Sun May  7 14:52:25 2023 daemon.notice netifd: modem_0001_4 (23052): udhcpc: lease lost, entering init state
Sun May  7 14:52:25 2023 daemon.notice netifd: Interface 'modem_0001_4' has lost the connection
Sun May  7 14:52:25 2023 daemon.notice netifd: Interface 'wgclient' has lost the connection
Sun May  7 14:52:25 2023 daemon.warn dnsmasq[5569]: no servers found in /tmp/resolv.conf.d/resolv.conf.auto, will retry
Sun May  7 14:52:25 2023 daemon.notice netifd: Network device 'wgclient' link is down
Sun May  7 14:52:25 2023 daemon.notice netifd: modem_0001_4 (23052): udhcpc: sending discover
Sun May  7 14:52:25 2023 daemon.notice netifd: modem_0001_4 (23052): udhcpc: sending select for 10.54.53.xxx
Sun May  7 14:52:25 2023 daemon.notice netifd: wgclient (3921): RTNETLINK answers: No such process
Sun May  7 14:52:25 2023 daemon.notice netifd: modem_0001_4 (23052): udhcpc: lease of 10.54.53.xxx obtained, lease time 7200
Sun May  7 14:52:25 2023 daemon.notice netifd: Interface 'modem_0001_4' is now up
6

Just tested the new 4.3.1 beta (2023-05-12) and the issue seems resolved! :grinning:

Sat May 13 15:26:10 2023 user.notice root: modem ip different, now regain ip ...
7

Great! Please keep monitoring this issue if can reproduce it or completely fixed.
Thanks a lot.

1 Like
9

Quick update: after 10 days of continuos power-on, no disconnection. Also tested with Wireguard enabled and the reconnection on IP change is extremely fast :ok_hand:

10

IMPORTANT UPDATE: I found a Bug about the new “regain ip” function.
If I schedule a reboot, after 24h the “modem ip different, now regain ip …” function doesn’t work anymore and I have a disconnection like I described on the first post.
Stopping the schedule and rebooting seems to fix the problem…