Cellular not connecting on boot

dirk · May 24, 2019, 2:24pm

BalenaCloud + BalenaFin 1.1 + Quectel UC20-E + Twilio SIM
It seems something goes wrong when the ModemManager tries to access / configure the modem.
This causes the modem to not be listed:

root@e5d3c72:~# mmcli -L
No modems were found

ModemManager Logs:

root@e5d3c72:~# journalctl -u ModemManager --no-pager
-- Logs begin at Tue 2019-05-21 04:22:55 UTC, end at Fri 2019-05-24 13:50:31 UTC. --
May 24 13:38:09 localhost systemd[1]: Starting Modem Manager...
May 24 13:38:09 e5d3c72 ModemManager[655]: ModemManager (version 1.10.0) starting in system bus...
May 24 13:38:10 e5d3c72 systemd[1]: Started Modem Manager.
May 24 13:38:11 e5d3c72 ModemManager[655]: [/dev/cdc-wdm0] Opening device with flags 'version-info, proxy'...
May 24 13:38:11 e5d3c72 ModemManager[655]: [/dev/cdc-wdm0] loaded driver of cdc-wdm port: qmi_wwan
May 24 13:38:11 e5d3c72 ModemManager[655]: cannot connect to proxy: Could not connect: Connection refused
May 24 13:38:11 e5d3c72 ModemManager[655]: spawning new qmi-proxy (try 1)...
May 24 13:38:11 e5d3c72 ModemManager[655]: [/dev/cdc-wdm0] Checking version info (10 retries)...
May 24 13:38:11 e5d3c72 ModemManager[655]: [/dev/cdc-wdm0] QMI Device supports 14 services:
May 24 13:38:11 e5d3c72 ModemManager[655]: [/dev/cdc-wdm0]    ctl (1.5)
May 24 13:38:11 e5d3c72 ModemManager[655]: [/dev/cdc-wdm0]    wds (1.12)
May 24 13:38:11 e5d3c72 ModemManager[655]: [/dev/cdc-wdm0]    dms (1.6)
May 24 13:38:11 e5d3c72 ModemManager[655]: [/dev/cdc-wdm0]    nas (1.21)
May 24 13:38:11 e5d3c72 ModemManager[655]: [/dev/cdc-wdm0]    qos (1.3)
May 24 13:38:11 e5d3c72 ModemManager[655]: [/dev/cdc-wdm0]    wms (1.4)
May 24 13:38:11 e5d3c72 ModemManager[655]: [/dev/cdc-wdm0]    pds (1.10)
May 24 13:38:11 e5d3c72 ModemManager[655]: [/dev/cdc-wdm0]    auth (1.1)
May 24 13:38:11 e5d3c72 ModemManager[655]: [/dev/cdc-wdm0]    voice (2.1)
May 24 13:38:11 e5d3c72 ModemManager[655]: [/dev/cdc-wdm0]    cat2 (2.6)
May 24 13:38:11 e5d3c72 ModemManager[655]: [/dev/cdc-wdm0]    uim (1.10)
May 24 13:38:11 e5d3c72 ModemManager[655]: [/dev/cdc-wdm0]    pbm (1.4)
May 24 13:38:11 e5d3c72 ModemManager[655]: [/dev/cdc-wdm0]    wda (1.0)
May 24 13:38:11 e5d3c72 ModemManager[655]: [/dev/cdc-wdm0]    cat (2.6)
May 24 13:38:12 e5d3c72 ModemManager[655]: Couldn't check support for device '/sys/devices/platform/soc/3f300000.mmc/mmc_host/mmc1/mmc1:0001/mmc1:0001:1': not supported by any plugin
May 24 13:38:12 e5d3c72 ModemManager[655]: Couldn't check support for device '/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.1': not supported by any plugin
May 24 13:38:18 e5d3c72 ModemManager[655]: (net/wlan0): released by device '/sys/devices/platform/soc/3f300000.mmc/mmc_host/mmc1/mmc1:0001/mmc1:0001:1'
May 24 13:38:18 e5d3c72 ModemManager[655]: Couldn't check support for device '/sys/devices/platform/soc/3f300000.mmc/mmc_host/mmc1/mmc1:0001/mmc1:0001:1': Operation was cancelled
May 24 13:38:18 e5d3c72 ModemManager[655]: (usbmisc/cdc-wdm0): released by device '/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2'
May 24 13:38:18 e5d3c72 ModemManager[655]: (net/wwan0): released by device '/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2'
May 24 13:38:18 e5d3c72 ModemManager[655]: (net/eth0): released by device '/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.1'
May 24 13:38:18 e5d3c72 ModemManager[655]: Couldn't check support for device '/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.1': Operation was cancelled
May 24 13:38:18 e5d3c72 ModemManager[655]: (tty/ttyUSB1): released by device '/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2'
May 24 13:38:18 e5d3c72 ModemManager[655]: [plugin manager] task 0,ttyUSB1: error when checking support with plugin 'Cinterion': 'Operation was cancelled'
May 24 13:38:18 e5d3c72 ModemManager[655]: [plugin manager] task 0,ttyUSB1: failed: Operation was cancelled
May 24 13:38:18 e5d3c72 ModemManager[655]: (tty/ttyUSB2): released by device '/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2'
May 24 13:38:18 e5d3c72 ModemManager[655]: (tty/ttyUSB0): released by device '/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2'
May 24 13:38:18 e5d3c72 ModemManager[655]: [plugin manager] task 0,ttyUSB0: error when checking support with plugin 'Cinterion': 'Operation was cancelled'
May 24 13:38:18 e5d3c72 ModemManager[655]: [plugin manager] task 0,ttyUSB0: failed: Operation was cancelled
May 24 13:38:18 e5d3c72 ModemManager[655]: [device /sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2] creating modem with plugin 'Generic' and '1' ports
May 24 13:38:18 e5d3c72 ModemManager[655]: Modem for device '/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2' successfully created
May 24 13:38:18 e5d3c72 ModemManager[655]: (tty/ttyUSB3): released by device '/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2'
May 24 13:38:18 e5d3c72 ModemManager[655]: Modem couldn't be initialized: couldn't load current capabilities: AT sequence was cancelled
May 24 13:38:18 e5d3c72 ModemManager[655]: couldn't initialize the modem: 'Operation was cancelled'
May 24 13:43:57 e5d3c72 ModemManager[655]: (net/enxa0cec81d3f6a): released by device '/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.4'
May 24 13:43:57 e5d3c72 ModemManager[655]: Couldn't check support for device '/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.4': Operation was cancelled
root@e5d3c72:~# mmcli -L
No modems were found

Running mmcli -S fixes the issue, but we have to be able to trust the device to come online without manual intervention…

It could be a timing issue, plus the fact the ModemManager doesn’t recover/retry.
Is there a way to debug this further?
Any workarounds or configuration options I’m missing? (other than an mmcli cronjob :-))

majorz · May 24, 2019, 3:14pm

Hi, can you please compare the behavior between the recently released OS version 2.36 and the previous 2.30 (I think you are using 2.36 now)? There was a ModemManager update between those two versions. Let’s see what behavior is on 2.30 and then we can figure out our next steps.
Thanks a lot,
Zahari

dirk · May 24, 2019, 4:56pm

Seems to get stranger still…
We were indeed on 2.36, so I downloaded a 2.29 image (2.30 is not available), flashed the device, connected it to BalenaCloud, created a /etc/NetworkManager/system-connections/cellular network config file (remotely) and rebooted. That worked, the modem was listed without intervention from me!

Then I rebooted again to try it without an ethernet cable connected as well and it didn’t come online anymore. Now I’m in the same situation as before.

Could it be related to my using the /etc/NetworkManager/system-connections as opposed to the resin-boot/system-connections folder?

Full ModemManager logs (first boot without success, then 5 minute wait, then mmcli -S with success):

root@38c7ea0:~# journalctl -u ModemManager --no-pager
-- Logs begin at Wed 2018-11-14 13:51:36 UTC, end at Fri 2019-05-24 16:56:52 UTC. --
May 24 16:46:11 localhost systemd[1]: Starting Modem Manager...
May 24 16:46:11 38c7ea0 ModemManager[667]: ModemManager (version 1.8.2) starting in system bus...
May 24 16:46:13 38c7ea0 systemd[1]: Started Modem Manager.
May 24 16:46:14 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0] Opening device with flags 'version-info, proxy'...
May 24 16:46:14 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0] loaded driver of cdc-wdm port: qmi_wwan
May 24 16:46:14 38c7ea0 ModemManager[667]: cannot connect to proxy: Could not connect: Connection refused
May 24 16:46:14 38c7ea0 ModemManager[667]: spawning new qmi-proxy (try 1)...
May 24 16:46:14 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0] Checking version info (10 retries)...
May 24 16:46:14 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0] QMI Device supports 14 services:
May 24 16:46:14 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0]    ctl (1.5)
May 24 16:46:14 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0]    wds (1.12)
May 24 16:46:14 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0]    dms (1.6)
May 24 16:46:14 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0]    nas (1.21)
May 24 16:46:14 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0]    qos (1.3)
May 24 16:46:14 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0]    wms (1.4)
May 24 16:46:14 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0]    pds (1.10)
May 24 16:46:14 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0]    auth (1.1)
May 24 16:46:14 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0]    voice (2.1)
May 24 16:46:14 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0]    cat2 (2.6)
May 24 16:46:14 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0]    uim (1.10)
May 24 16:46:14 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0]    pbm (1.4)
May 24 16:46:14 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0]    wda (1.0)
May 24 16:46:14 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0]    cat (2.6)
May 24 16:46:15 38c7ea0 ModemManager[667]: Couldn't check support for device '/sys/devices/platform/soc/3f300000.mmc/mmc_host/mmc1/mmc1:0001/mmc1:0001:1': not supported by any plugin
May 24 16:46:15 38c7ea0 ModemManager[667]: Couldn't check support for device '/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.1': not supported by any plugin
May 24 16:46:21 38c7ea0 ModemManager[667]: (net/wlan0): released by device '/sys/devices/platform/soc/3f300000.mmc/mmc_host/mmc1/mmc1:0001/mmc1:0001:1'
May 24 16:46:21 38c7ea0 ModemManager[667]: Couldn't check support for device '/sys/devices/platform/soc/3f300000.mmc/mmc_host/mmc1/mmc1:0001/mmc1:0001:1': Operation was cancelled
May 24 16:46:21 38c7ea0 ModemManager[667]: (net/eth0): released by device '/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.1'
May 24 16:46:21 38c7ea0 ModemManager[667]: Couldn't check support for device '/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.1': Operation was cancelled
May 24 16:46:21 38c7ea0 ModemManager[667]: (usbmisc/cdc-wdm0): released by device '/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2'
May 24 16:46:21 38c7ea0 ModemManager[667]: (net/wwan0): released by device '/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2'
May 24 16:46:21 38c7ea0 ModemManager[667]: (tty/ttyUSB1): released by device '/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2'
May 24 16:46:21 38c7ea0 ModemManager[667]: [plugin manager] task 0,ttyUSB1: error when checking support with plugin 'Telit': 'Operation was cancelled'
May 24 16:46:21 38c7ea0 ModemManager[667]: [plugin manager] task 0,ttyUSB1: failed: Operation was cancelled
May 24 16:46:21 38c7ea0 ModemManager[667]: (tty/ttyUSB2): released by device '/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2'
May 24 16:46:21 38c7ea0 ModemManager[667]: (tty/ttyUSB0): released by device '/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2'
May 24 16:46:21 38c7ea0 ModemManager[667]: (tty/ttyUSB3): released by device '/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2'
May 24 16:46:22 38c7ea0 ModemManager[667]: [plugin manager] task 0,ttyUSB0: error when checking support with plugin 'Telit': 'Operation was cancelled'
May 24 16:46:22 38c7ea0 ModemManager[667]: [plugin manager] task 0,ttyUSB0: failed: Operation was cancelled
May 24 16:46:22 38c7ea0 ModemManager[667]: Couldn't check support for device '/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2': Operation was cancelled
May 24 16:51:18 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0] Opening device with flags 'version-info, proxy'...
May 24 16:51:18 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0] loaded driver of cdc-wdm port: qmi_wwan
May 24 16:51:18 38c7ea0 ModemManager[667]: cannot connect to proxy: Could not connect: Connection refused
May 24 16:51:18 38c7ea0 ModemManager[667]: spawning new qmi-proxy (try 1)...
May 24 16:51:19 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0] Checking version info (10 retries)...
May 24 16:51:19 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0] QMI Device supports 14 services:
May 24 16:51:19 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0]    ctl (1.5)
May 24 16:51:19 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0]    wds (1.12)
May 24 16:51:19 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0]    dms (1.6)
May 24 16:51:19 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0]    nas (1.21)
May 24 16:51:19 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0]    qos (1.3)
May 24 16:51:19 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0]    wms (1.4)
May 24 16:51:19 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0]    pds (1.10)
May 24 16:51:19 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0]    auth (1.1)
May 24 16:51:19 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0]    voice (2.1)
May 24 16:51:19 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0]    cat2 (2.6)
May 24 16:51:19 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0]    uim (1.10)
May 24 16:51:19 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0]    pbm (1.4)
May 24 16:51:19 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0]    wda (1.0)
May 24 16:51:19 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0]    cat (2.6)
May 24 16:51:19 38c7ea0 ModemManager[667]: Couldn't check support for device '/sys/devices/platform/soc/3f300000.mmc/mmc_host/mmc1/mmc1:0001/mmc1:0001:1': not supported by any plugin
May 24 16:51:19 38c7ea0 ModemManager[667]: Couldn't check support for device '/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.1': not supported by any plugin
May 24 16:51:37 38c7ea0 ModemManager[667]: [device /sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2] creating modem with plugin 'Generic' and '6' ports
May 24 16:51:37 38c7ea0 ModemManager[667]: Could not grab port (tty/ttyUSB1): 'Cannot add port 'tty/ttyUSB1', unhandled serial type'
May 24 16:51:37 38c7ea0 ModemManager[667]: Modem for device '/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2' successfully created
May 24 16:51:37 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0] Opening device with flags 'version-info, proxy'...
May 24 16:51:37 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0] loaded driver of cdc-wdm port: qmi_wwan
May 24 16:51:37 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0] Checking version info (10 retries)...
May 24 16:51:38 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0] QMI Device supports 14 services:
May 24 16:51:38 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0]    ctl (1.5)
May 24 16:51:38 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0]    wds (1.12)
May 24 16:51:38 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0]    dms (1.6)
May 24 16:51:38 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0]    nas (1.21)
May 24 16:51:38 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0]    qos (1.3)
May 24 16:51:38 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0]    wms (1.4)
May 24 16:51:38 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0]    pds (1.10)
May 24 16:51:38 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0]    auth (1.1)
May 24 16:51:38 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0]    voice (2.1)
May 24 16:51:38 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0]    cat2 (2.6)
May 24 16:51:38 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0]    uim (1.10)
May 24 16:51:38 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0]    pbm (1.4)
May 24 16:51:38 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0]    wda (1.0)
May 24 16:51:38 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0]    cat (2.6)
May 24 16:51:38 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0] Reading expected data format from: /sys/class/net/wwan0/qmi/raw_ip
May 24 16:51:38 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0] Allocating new client ID...
May 24 16:51:38 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0] Registered 'wda' (version 1.0) client with ID '1'
May 24 16:51:38 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0] Allocating new client ID...
May 24 16:51:38 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0] Releasing 'wda' client with flags 'release-cid'...
May 24 16:51:38 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0] Unregistered 'wda' client with ID '1'
May 24 16:51:38 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0] Registered 'dms' (version 1.6) client with ID '1'
May 24 16:51:38 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0] Allocating new client ID...
May 24 16:51:38 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0] Registered 'nas' (version 1.21) client with ID '1'
May 24 16:51:38 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0] Allocating new client ID...
May 24 16:51:38 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0] Registered 'wms' (version 1.4) client with ID '1'
May 24 16:51:38 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0] Allocating new client ID...
May 24 16:51:38 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0] Registered 'pds' (version 1.10) client with ID '1'
May 24 16:51:38 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0] Allocating new client ID...
May 24 16:51:38 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0] Registered 'uim' (version 1.10) client with ID '1'
May 24 16:51:38 38c7ea0 ModemManager[667]: couldn't load list of Own Numbers: 'Couldn't get MSISDN: QMI protocol error (16): 'NotProvisioned''
May 24 16:51:38 38c7ea0 ModemManager[667]: couldn't load UE mode of operation for EPS: 'Unknown error'
May 24 16:51:38 38c7ea0 ModemManager[667]: Modem: state changed (unknown -> disabled)
May 24 16:51:38 38c7ea0 ModemManager[667]: Modem /org/freedesktop/ModemManager1/Modem/0: state changed (disabled -> enabling)
May 24 16:51:38 38c7ea0 ModemManager[667]: Simple connect started...
May 24 16:51:38 38c7ea0 ModemManager[667]: Simple connect state (4/8): Wait to get fully enabled
May 24 16:51:39 38c7ea0 ModemManager[667]: Modem /org/freedesktop/ModemManager1/Modem/0: state changed (enabling -> enabled)
May 24 16:51:39 38c7ea0 ModemManager[667]: Simple connect state (5/8): Register
May 24 16:51:39 38c7ea0 ModemManager[667]: Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (unknown -> registering)
May 24 16:51:39 38c7ea0 ModemManager[667]: Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (registering -> roaming)
May 24 16:51:39 38c7ea0 ModemManager[667]: Modem /org/freedesktop/ModemManager1/Modem/0: state changed (enabled -> registered)
May 24 16:51:39 38c7ea0 ModemManager[667]: Simple connect state (6/8): Bearer
May 24 16:51:39 38c7ea0 ModemManager[667]: Simple connect state (7/8): Connect
May 24 16:51:39 38c7ea0 ModemManager[667]: Modem /org/freedesktop/ModemManager1/Modem/0: state changed (registered -> connecting)
May 24 16:51:39 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0] Allocating new client ID...
May 24 16:51:39 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0] Registered 'wds' (version 1.12) client with ID '1'
May 24 16:51:40 38c7ea0 ModemManager[667]: Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (roaming -> searching)
May 24 16:52:24 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0] Allocating new client ID...
May 24 16:52:24 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0] Registered 'wds' (version 1.12) client with ID '2'
May 24 16:52:24 38c7ea0 ModemManager[667]: [/dev/cdc-wdm0] No transaction matched in received message
May 24 16:52:24 38c7ea0 ModemManager[667]: error: couldn't start network: QMI protocol error (14): 'CallFailed'
May 24 16:52:24 38c7ea0 ModemManager[667]: call end reason (3): 'generic-no-service'
May 24 16:52:24 38c7ea0 ModemManager[667]: verbose call end reason (2,204): [internal] unknown-cause
May 24 16:52:24 38c7ea0 ModemManager[667]: Modem /org/freedesktop/ModemManager1/Modem/0: state changed (connecting -> searching)
May 24 16:52:24 38c7ea0 ModemManager[667]: Simple connect started...
May 24 16:52:24 38c7ea0 ModemManager[667]: Simple connect state (4/8): Wait to get fully enabled
May 24 16:52:24 38c7ea0 ModemManager[667]: Simple connect state (5/8): Register
May 24 16:53:08 38c7ea0 ModemManager[667]: Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (searching -> idle)
May 24 16:53:11 38c7ea0 ModemManager[667]: Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (idle -> registering)
May 24 16:53:11 38c7ea0 ModemManager[667]: Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (registering -> roaming)
May 24 16:53:11 38c7ea0 ModemManager[667]: Modem /org/freedesktop/ModemManager1/Modem/0: state changed (searching -> registered)
May 24 16:53:12 38c7ea0 ModemManager[667]: Simple connect state (6/8): Bearer
May 24 16:53:12 38c7ea0 ModemManager[667]: Simple connect state (7/8): Connect
May 24 16:53:12 38c7ea0 ModemManager[667]: Modem /org/freedesktop/ModemManager1/Modem/0: state changed (registered -> connecting)
May 24 16:53:17 38c7ea0 ModemManager[667]: QMI IPv4 Settings:
May 24 16:53:17 38c7ea0 ModemManager[667]:     Address: 26.83.54.85/30
May 24 16:53:17 38c7ea0 ModemManager[667]:     Gateway: 26.83.54.86
May 24 16:53:17 38c7ea0 ModemManager[667]:     DNS #1: 10.177.0.34
May 24 16:53:17 38c7ea0 ModemManager[667]:     DNS #2: 10.177.0.210
May 24 16:53:17 38c7ea0 ModemManager[667]:        MTU: 1500
May 24 16:53:17 38c7ea0 ModemManager[667]: Modem /org/freedesktop/ModemManager1/Modem/0: state changed (connecting -> connected)
May 24 16:53:17 38c7ea0 ModemManager[667]: Simple connect state (8/8): All done
May 24 16:53:22 38c7ea0 ModemManager[667]: Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (roaming -> registering)
May 24 16:53:22 38c7ea0 ModemManager[667]: Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (registering -> home)

dirk · May 24, 2019, 8:39pm

Since I had another card at hand (Quectel UC20-G), I also tried that one, just to make sure the 3G hardware wasn’t at fault: same result.

majorz · May 24, 2019, 9:10pm

Can you please try the same without any application container deployed (empty application) and without any connection profile as well?

I suspect that if you have application deployed with udev enabled in the container, it may interfere with the modem detection on boot. Let’s check whether this is the case so that we eliminate this as an option.

dirk · May 27, 2019, 9:06am

I can indeed confirm that (ie. doing the same configuration with an empty application makes the device boot up properly)
I assume the recommended way forward would then be to base our images off the balenalib instead of the resin ones?

dirk · May 27, 2019, 9:26am

BTW: Would setting a device env var UDEV=0 be sufficient a) as a temporary solution and b) as a way to deterministically confirm udev is the issue?

majorz · May 28, 2019, 7:15am

Hi, great to hear that we identified the issue. I would recommend using the newer base images (balenalib), but you can continue using the older ones if upgrade is difficult (they are deprecated). The newer ones have udev switched off by default.
Thanks,
Zahari