openwrt / packages

Community maintained packages for OpenWrt. Documentation for submitting pull requests is in CONTRIBUTING.md
GNU General Public License v2.0
3.89k stars 3.4k forks source link

modemmanager: netifd giving up on enabling a modem device #23171

Open yegorich opened 5 months ago

yegorich commented 5 months ago

Maintainer: @mips171 / @aleksander0m Environment: ARMv7, TI Sitara AM335x, OpenWrt v23.05.2

Description:

In the following log, though the modem could be found, netifd is giving up and doesn't try to get it up once more. Restarting the interface via the web interface leads to a successful connection.

Fri Jan 26 16:57:51 2024 daemon.info ModemManager[2191]: hotplug: add network interface wwan0: event processed
Fri Jan 26 16:57:52 2024 daemon.err ModemManager[2191]: hotplug: Couldn't report kernel event: error: couldn't get bus: Could not connect: No such file or directory
Fri Jan 26 16:57:52 2024 daemon.info ModemManager[2191]: hotplug: add cdc interface cdc-wdm0: custom event processed
Fri Jan 26 16:57:52 2024 daemon.err ModemManager[2191]: hotplug: Couldn't report kernel event: error: couldn't get bus: Could not connect: No such file or directory
Fri Jan 26 16:57:52 2024 daemon.info ModemManager[2300]: hotplug: add serial interface ttyUSB0: event processed
Fri Jan 26 16:57:53 2024 daemon.err ModemManager[2300]: hotplug: Couldn't report kernel event: error: couldn't get bus: Could not connect: No such file or directory
Fri Jan 26 16:57:54 2024 daemon.info ModemManager[2374]: hotplug: add serial interface ttyUSB1: event processed
Fri Jan 26 16:57:54 2024 daemon.err ModemManager[2374]: hotplug: Couldn't report kernel event: error: couldn't get bus: Could not connect: No such file or directory
Fri Jan 26 16:57:55 2024 daemon.notice wpa_supplicant[2428]: Successfully initialized wpa_supplicant
Fri Jan 26 16:57:55 2024 daemon.info ModemManager[2493]: hotplug: add serial interface ttyUSB2: event processed
Fri Jan 26 16:57:55 2024 daemon.notice hostapd: handle_debug_config: null
Fri Jan 26 16:57:55 2024 daemon.err ModemManager[2493]: hotplug: Couldn't report kernel event: error: couldn't get bus: Could not connect: No such file or directory
Fri Jan 26 16:57:56 2024 user.notice : Added device handler type: bonding
Fri Jan 26 16:57:56 2024 user.notice : Added device handler type: 8021ad
Fri Jan 26 16:57:56 2024 user.notice : Added device handler type: 8021q
Fri Jan 26 16:57:56 2024 user.notice : Added device handler type: macvlan
Fri Jan 26 16:57:56 2024 user.notice : Added device handler type: veth
Fri Jan 26 16:57:56 2024 user.notice : Added device handler type: bridge
Fri Jan 26 16:57:56 2024 user.notice : Added device handler type: Network device
Fri Jan 26 16:57:56 2024 user.notice : Added device handler type: tunnel
Fri Jan 26 16:57:57 2024 daemon.info ModemManager[2583]: hotplug: add serial interface ttyUSB3: event processed
Fri Jan 26 16:57:57 2024 daemon.err ModemManager[2583]: hotplug: Couldn't report kernel event: error: couldn't get bus: Could not connect: No such file or directory
Fri Jan 26 16:57:58 2024 cron.err crond[2728]: crond (busybox 1.36.1) started, log level 5
Fri Jan 26 16:57:59 2024 daemon.info ModemManager[2731]: hotplug: add serial interface ttyUSB4: event processed
Fri Jan 26 16:57:59 2024 daemon.err ModemManager[2731]: hotplug: Couldn't report kernel event: error: couldn't get bus: Could not connect: No such file or directory
Fri Jan 26 16:58:03 2024 daemon.info ModemManager[2925]: hotplug: Checking if ModemManager is available...
Fri Jan 26 16:58:03 2024 daemon.info ModemManager[2924]: hotplug: checking if ModemManager is available...
Fri Jan 26 16:58:04 2024 daemon.info ModemManager[2925]: hotplug: ModemManager not yet available
Fri Jan 26 16:58:04 2024 user.notice ucitrack: Setting up /etc/config/network reload trigger for non-procd /etc/init.d/ifmodem
Fri Jan 26 16:58:04 2024 daemon.info ModemManager[2924]: hotplug: ModemManager not yet available
Fri Jan 26 16:58:04 2024 user.notice ucitrack: Setting up /etc/config/dhcp reload dependency on /etc/config/network
Fri Jan 26 16:58:04 2024 user.notice ucitrack: Setting up /etc/config/radvd reload dependency on /etc/config/network
Fri Jan 26 16:58:04 2024 user.notice ucitrack: Setting up /etc/config/network reload dependency on /etc/config/wireless
Fri Jan 26 16:58:05 2024 user.notice ucitrack: Setting up /etc/config/luci-splash reload dependency on /etc/config/firewall
Fri Jan 26 16:58:05 2024 user.notice ucitrack: Setting up /etc/config/qos reload dependency on /etc/config/firewall
Fri Jan 26 16:58:05 2024 daemon.info ModemManager[2925]: hotplug: Checking if ModemManager is available...
Fri Jan 26 16:58:05 2024 user.notice ucitrack: Setting up /etc/config/miniupnpd reload dependency on /etc/config/firewall
Fri Jan 26 16:58:05 2024 daemon.info ModemManager[2924]: hotplug: checking if ModemManager is available...
Fri Jan 26 16:58:05 2024 daemon.notice [2957]: <msg> ModemManager (version 1.22.0) starting in system bus...
Fri Jan 26 16:58:05 2024 daemon.info ModemManager[2925]: hotplug: ModemManager not yet available
Fri Jan 26 16:58:05 2024 daemon.info ModemManager[2924]: hotplug: ModemManager not yet available
Fri Jan 26 16:58:06 2024 user.notice ucitrack: Setting up /etc/config/odhcpd reload dependency on /etc/config/dhcp
Fri Jan 26 16:58:06 2024 user.notice ucitrack: Setting up non-init /etc/config/fstab reload handler: /sbin/block mount
Fri Jan 26 16:58:06 2024 daemon.info ModemManager[2925]: hotplug: Checking if ModemManager is available...
Fri Jan 26 16:58:06 2024 daemon.info ModemManager[2924]: hotplug: checking if ModemManager is available...
Fri Jan 26 16:58:06 2024 user.notice ucitrack: Setting up /etc/config/system reload trigger for non-procd /etc/init.d/led
Fri Jan 26 16:58:07 2024 user.notice ucitrack: Setting up /etc/config/luci_statistics reload dependency on /etc/config/system
Fri Jan 26 16:58:07 2024 user.notice ucitrack: Setting up /etc/config/dhcp reload dependency on /etc/config/system
Fri Jan 26 16:58:08 2024 user.notice ucitrack: Setting up /etc/config/ifmodem reload trigger for non-procd /etc/init.d/ifmodem
Fri Jan 26 16:58:09 2024 kern.info kernel: [   43.959543] cpsw-switch 4a100000.switch: starting ndev. mode: dual_mac
Fri Jan 26 16:58:09 2024 kern.info kernel: [   43.992674] Generic PHY fixed-0:00: attached PHY driver (mii_bus:phy_addr=fixed-0:00, irq=POLL)
Fri Jan 26 16:58:09 2024 kern.info kernel: [   44.002672] cpsw-switch 4a100000.switch eth0: Link is Up - 100Mbps/Full - flow control off
Fri Jan 26 16:58:09 2024 kern.info kernel: [   44.076372] 8021q: adding VLAN 0 to HW filter on device eth0
Fri Jan 26 16:58:09 2024 kern.info kernel: [   44.146923] br-lan: port 1(eth0) entered blocking state
Fri Jan 26 16:58:09 2024 kern.info kernel: [   44.152417] br-lan: port 1(eth0) entered disabled state
Fri Jan 26 16:58:09 2024 kern.info kernel: [   44.159017] device eth0 entered promiscuous mode
Fri Jan 26 16:58:09 2024 daemon.notice netifd: Interface 'lan' is enabled
Fri Jan 26 16:58:09 2024 daemon.notice netifd: Interface 'lan' is setting up now
Fri Jan 26 16:58:09 2024 daemon.notice netifd: Interface 'lan' is now up
Fri Jan 26 16:58:09 2024 daemon.notice netifd: Interface 'Mobile' is setting up now
Fri Jan 26 16:58:09 2024 daemon.notice netifd: Interface 'loopback' is enabled
Fri Jan 26 16:58:09 2024 daemon.notice netifd: Interface 'loopback' is setting up now
Fri Jan 26 16:58:09 2024 daemon.notice netifd: Interface 'loopback' is now up
Fri Jan 26 16:58:09 2024 kern.info kernel: [   44.425386] cpsw-switch 4a100000.switch: starting ndev. mode: dual_mac
Fri Jan 26 16:58:09 2024 daemon.info ModemManager[3278]: hotplug: add network interface br-lan: event processed
Fri Jan 26 16:58:09 2024 kern.info kernel: [   44.654561] Qualcomm Atheros AR8035 4a101000.mdio:07: attached PHY driver (mii_bus:phy_addr=4a101000.mdio:07, irq=POLL)
Fri Jan 26 16:58:10 2024 kern.info kernel: [   44.775636] 8021q: adding VLAN 0 to HW filter on device eth1
Fri Jan 26 16:58:10 2024 daemon.notice netifd: Interface 'wan' is enabled
Fri Jan 26 16:58:10 2024 daemon.notice netifd: Interface 'wan6' is enabled
Fri Jan 26 16:58:10 2024 daemon.notice netifd: Network device 'eth0' link is up
Fri Jan 26 16:58:10 2024 daemon.notice netifd: Network device 'lo' link is up
Fri Jan 26 16:58:10 2024 daemon.notice netifd: Interface 'loopback' has link connectivity
Fri Jan 26 16:58:10 2024 kern.info kernel: [   44.961229] br-lan: port 1(eth0) entered blocking state
Fri Jan 26 16:58:10 2024 kern.info kernel: [   44.966554] br-lan: port 1(eth0) entered forwarding state
Fri Jan 26 16:58:10 2024 daemon.notice netifd: bridge 'br-lan' link is up
Fri Jan 26 16:58:10 2024 daemon.notice netifd: Interface 'lan' has link connectivity
Fri Jan 26 16:58:10 2024 kern.info kernel: [   45.038483] IPv6: ADDRCONF(NETDEV_CHANGE): br-lan: link becomes ready
Fri Jan 26 16:58:10 2024 user.notice firewall: Reloading firewall due to ifup of lan (br-lan)
Fri Jan 26 16:58:10 2024 daemon.notice netifd: Mobile (3335): error: couldn't find modem
Fri Jan 26 16:58:11 2024 daemon.notice netifd: Mobile (3335): Device not managed by ModemManager
Fri Jan 26 16:58:12 2024 daemon.notice netifd: Mobile (3482): stopping network
Fri Jan 26 16:58:12 2024 daemon.notice netifd: Mobile (3482): error: couldn't find modem
Fri Jan 26 16:58:12 2024 daemon.notice netifd: Mobile (3482): couldn't load bearer path: disconnecting anyway
Fri Jan 26 16:58:13 2024 daemon.notice netifd: Interface 'Mobile' is now down
Fri Jan 26 16:58:19 2024 daemon.notice [2957]: <msg> [device /sys/devices/platform/ocp/47400000.target-module/47401400.usb/musb-hdrc.0/usb1/1-1/1-1.3] creating modem with plugin 'simtech' and '7' ports
Fri Jan 26 16:58:19 2024 daemon.info [2957]: <inf> [modem0] tty/ttyUSB2: at (primary)
Fri Jan 26 16:58:19 2024 daemon.info [2957]: <inf> [modem0] tty/ttyUSB3: at (secondary)
Fri Jan 26 16:58:19 2024 daemon.info [2957]: <inf> [modem0] tty/ttyUSB2: at (data primary)
Fri Jan 26 16:58:19 2024 daemon.info [2957]: <inf> [modem0] net/wwan0: net (data)
Fri Jan 26 16:58:19 2024 daemon.info [2957]: <inf> [modem0] tty/ttyUSB1: gps (nmea)
Fri Jan 26 16:58:19 2024 daemon.info [2957]: <inf> [modem0] tty/ttyUSB4: audio
Fri Jan 26 16:58:19 2024 daemon.info [2957]: <inf> [modem0] usbmisc/cdc-wdm0: qmi
Fri Jan 26 16:58:19 2024 daemon.notice [2957]: <msg> [base-manager] modem for device '/sys/devices/platform/ocp/47400000.target-module/47401400.usb/musb-hdrc.0/usb1/1-1/1-1.3' successfully created
Fri Jan 26 16:58:21 2024 daemon.info [2957]: <inf> [modem0] SIM hot swap setup succeeded
Fri Jan 26 16:58:21 2024 daemon.notice [2957]: <msg> [modem0] state changed (unknown -> locked)
Fri Jan 26 16:58:21 2024 daemon.warn [2957]: <wrn> [modem0] error initializing: Modem is currently locked, cannot fully initialize
Fri Jan 26 16:58:21 2024 daemon.info ModemManager[2925]: hotplug: interface 'Mobile' set '/sys/devices/platform/ocp/47400000.target-module/47401400.usb/musb-hdrc.0/usb1/1-1/1-1.3' state available
Fri Jan 26 16:58:21 2024 daemon.notice netifd: Interface 'Mobile' is setting up now
Fri Jan 26 16:58:22 2024 daemon.notice netifd: Mobile (3906): modem available at /org/freedesktop/ModemManager1/Modem/0
Fri Jan 26 16:58:24 2024 user.notice root: Found modem: 0
Fri Jan 26 16:58:24 2024 user.notice root: 868020033875112
Fri Jan 26 16:58:24 2024 daemon.info procd: - init complete -
Fri Jan 26 16:58:25 2024 daemon.info [2957]: <inf> [modem0] SIM is ready, and no need for the after SIM unlock step...
Fri Jan 26 16:58:25 2024 daemon.notice netifd: Mobile (3906): successfully sent PIN code to the SIM
Fri Jan 26 16:58:25 2024 daemon.notice [2957]: <msg> [modem0] state changed (locked -> initializing)
Fri Jan 26 16:58:25 2024 daemon.notice netifd: Mobile (3906): setting allowed mode to 'any'
Fri Jan 26 16:58:25 2024 daemon.info [2957]: <inf> [modem0] SIM is ready, and no need for the after SIM unlock step...
Fri Jan 26 16:58:25 2024 daemon.info [2957]: <inf> [modem0/sim0] loaded IMSI: ###
Fri Jan 26 16:58:25 2024 daemon.info [2957]: <inf> [modem0/sim0] loaded operator identifier: 46692
Fri Jan 26 16:58:25 2024 daemon.notice netifd: Mobile (3906): error: couldn't set current modes: 'GDBus.Error:org.freedesktop.ModemManager1.Error.Core.WrongState: modem in initializing state'
Fri Jan 26 16:58:25 2024 daemon.info [2957]: <inf> [modem0/sim0] loaded GID1: FFFFFFFFFFFFFFFF
Fri Jan 26 16:58:25 2024 daemon.info [2957]: <inf> [modem0/sim0] loaded GID2: FFFFFFFFFFFFFFFF
Fri Jan 26 16:58:25 2024 daemon.notice netifd: Mobile (3906): error: couldn't enable the modem: 'GDBus.Error:org.freedesktop.ModemManager1.Error.Core.WrongState: modem in initializing state'
Fri Jan 26 16:58:26 2024 daemon.notice netifd: Mobile (4140): stopping network
Fri Jan 26 16:58:26 2024 daemon.warn [2957]: <wrn> [modem0] couldn't load supported assistance data types: LOC service: general failure
Fri Jan 26 16:58:26 2024 daemon.notice netifd: Mobile (4140): couldn't load bearer path: disconnecting anyway
Fri Jan 26 16:58:26 2024 daemon.notice [2957]: <msg> [modem0] state changed (initializing -> disabled)
Fri Jan 26 16:58:26 2024 daemon.info [2957]: <inf> [modem0] processing user request to disconnect modem: all bearers
Fri Jan 26 16:58:26 2024 daemon.info [2957]: <inf> [modem0] all requested bearers disconnected
Fri Jan 26 16:58:26 2024 daemon.notice netifd: Interface 'Mobile' is now down

How to force netifd to try the initialization again?

feckert commented 5 months ago

What OpenWrt version are you using? I made some changes recently, that should fix this issue on boot. https://github.com/openwrt/packages/commits/master/net/modemmanager

yegorich commented 5 months ago

OpenWrt: r24436-0f283ab4c9, packages: f9c90fce0aad9ebec04e09b10843da3571c09f83 and two patches from @osedlbauer.

feckert commented 5 months ago

Ok, so you already have the latest changes. Normally, the new monitor service is doing this task.

When the modemmanager has recognized the modem, then the monitor service marks the uci interface section as avialable. And only then the netifd should start a connection attempt.

Is your log the output when booting?

yegorich commented 5 months ago

Yes, it is the bootlog. I have added more output.

yegorich commented 5 months ago

@feckert have already seen this thread? Seems to be related.

feckert commented 5 months ago

I think that could solve the problem. This change has the effect that the proto setup should be tried again and again as long as ifdown is not entered. The only question now is whether we should introduce a new option keep_retry for this, as it changes the current behavior. @yegorich Can you test this?

diff --git a/net/modemmanager/files/modemmanager.proto b/net/modemmanager/files/modemmanager.proto
index e67a84cf2..849e66709 100755
--- a/net/modemmanager/files/modemmanager.proto
+++ b/net/modemmanager/files/modemmanager.proto
@@ -587,8 +587,8 @@ proto_modemmanager_setup() {
        append_param "${password:+password=${password}}"

        mmcli --modem="${device}" --timeout 120 --simple-connect="${connectargs}" || {
-               proto_notify_error "${interface}" MM_CONNECT_FAILED
-               proto_block_restart "${interface}"
+               echo "connection failed -> attempting restart"
+               proto_notify_error "${interface}" MM_CONNECT_RESTART
                return 1
        }
yegorich commented 5 months ago

@feckert will do. Though, it will take some time.

feckert commented 1 month ago

The first part with the reconnect has been fixed https://github.com/openwrt/packages/pull/24370. Thanks to @osedlbauer. What is still missing is that the modem is not switched off during a reconnect in order to improve the reconnect time.