modemmanager: netifd giving up on enabling a modem device

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?