ModemManager loops and fails to get connection details when started after LTE modem is up and connected to the network.
Hello ModemManager team.
I am reaching you as we stumbled upon an issue with the ModemManager library using LTE modules. System details:
- mPCIe LTE modem connected via mbim interface over USB, powered independently from the Linux system and up before Linux
- ModemManager latest realease (as of 02.2020)
- libmbim for mbim interface
The observed problem is the following. As we start our embedded Linux, the LTE modem used for 4G connectivity is already up and running and is registered on the network. As ModemManager starts, it will attempt to connect to the network by sending requests for the LTE module to get an IP and register in the network, but not checking whether it is already registered. Thus it ends up in a loop with the connection requests being rejected.
Here is the journalctl printout showing the connection loop:
~$ sudo journalctl --unit ModemManager --follow
-- Logs begin at Thu 1970-01-01 00:00:11 UTC. --
Jan 01 00:04:33 aeler-imx7ulpea-ucom ModemManager[313]: <info> Simple connect state (6/8): Bearer
Jan 01 00:04:33 aeler-imx7ulpea-ucom ModemManager[313]: <info> Simple connect state (7/8): Connect
Jan 01 00:04:33 aeler-imx7ulpea-ucom ModemManager[313]: <info> Modem /org/freedesktop/ModemManager1/Modem/0: state changed (registered -> connecting)
Jan 01 00:05:33 aeler-imx7ulpea-ucom ModemManager[313]: <info> Modem /org/freedesktop/ModemManager1/Modem/0: state changed (connecting -> registered)
Jan 01 00:05:34 aeler-imx7ulpea-ucom ModemManager[313]: <info> Simple connect started...
Jan 01 00:05:34 aeler-imx7ulpea-ucom ModemManager[313]: <info> Simple connect state (4/8): Wait to get fully enabled
Jan 01 00:05:34 aeler-imx7ulpea-ucom ModemManager[313]: <info> Simple connect state (5/8): Register
Jan 01 00:05:34 aeler-imx7ulpea-ucom ModemManager[313]: <info> Simple connect state (6/8): Bearer
Jan 01 00:05:34 aeler-imx7ulpea-ucom ModemManager[313]: <info> Simple connect state (7/8): Connect
Jan 01 00:05:34 aeler-imx7ulpea-ucom ModemManager[313]: <info> Modem /org/freedesktop/ModemManager1/Modem/0: state changed (registered -> connecting)
Jan 01 00:06:34 aeler-imx7ulpea-ucom ModemManager[313]: <info> Modem /org/freedesktop/ModemManager1/Modem/0: state changed (connecting -> registered)
Jan 01 00:06:34 aeler-imx7ulpea-ucom ModemManager[313]: <info> Simple connect started...
Jan 01 00:06:34 aeler-imx7ulpea-ucom ModemManager[313]: <info> Simple connect state (4/8): Wait to get fully enabled
Jan 01 00:06:34 aeler-imx7ulpea-ucom ModemManager[313]: <info> Simple connect state (5/8): Register
Jan 01 00:06:34 aeler-imx7ulpea-ucom ModemManager[313]: <info> Simple connect state (6/8): Bearer
Jan 01 00:06:34 aeler-imx7ulpea-ucom ModemManager[313]: <info> Simple connect state (7/8): Connect
Jan 01 00:06:34 aeler-imx7ulpea-ucom ModemManager[313]: <info> Modem /org/freedesktop/ModemManager1/Modem/0: state changed (registered -> connecting)
Jan 01 00:06:34 aeler-imx7ulpea-ucom ModemManager[313]: [/dev/cdc-wdm0] No transaction matched in received message
Jan 01 00:06:34 aeler-imx7ulpea-ucom ModemManager[313]: [/dev/cdc-wdm0] Received unexpected message (translated)...
>>>>>> Header:
>>>>>> length = 84
>>>>>> type = command-done (0x80000003)
>>>>>> transaction = 48
>>>>>> Fragment header:
>>>>>> total = 1
>>>>>> current = 0
>>>>>> Contents:
>>>>>> status error = 'Failure' (0x00000002)
>>>>>> service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df)
>>>>>> cid = 'connect' (0x0000000c)
Jan 01 00:07:34 aeler-imx7ulpea-ucom ModemManager[313]: <info> Modem /org/freedesktop/ModemManager1/Modem/0: state changed (connecting -> registered)
Jan 01 00:07:34 aeler-imx7ulpea-ucom ModemManager[313]: <info> Simple connect started...
Jan 01 00:07:34 aeler-imx7ulpea-ucom ModemManager[313]: <info> Simple connect state (4/8): Wait to get fully enabled
Jan 01 00:07:34 aeler-imx7ulpea-ucom ModemManager[313]: <info> Simple connect state (5/8): Register
Jan 01 00:07:34 aeler-imx7ulpea-ucom ModemManager[313]: <info> Simple connect state (6/8): Bearer
Jan 01 00:07:34 aeler-imx7ulpea-ucom ModemManager[313]: <info> Simple connect state (7/8): Connect
Jan 01 00:07:34 aeler-imx7ulpea-ucom ModemManager[313]: <info> Modem /org/freedesktop/ModemManager1/Modem/0: state changed (registered -> connecting)
Jan 01 00:08:34 aeler-imx7ulpea-ucom ModemManager[313]: <info> Modem /org/freedesktop/ModemManager1/Modem/0: state changed (connecting -> registered)
Jan 01 00:08:34 aeler-imx7ulpea-ucom ModemManager[313]: <info> Simple connect started...
Jan 01 00:08:34 aeler-imx7ulpea-ucom ModemManager[313]: <info> Simple connect state (4/8): Wait to get fully enabled
Jan 01 00:08:34 aeler-imx7ulpea-ucom ModemManager[313]: <info> Simple connect state (5/8): Register
Jan 01 00:08:34 aeler-imx7ulpea-ucom ModemManager[313]: <info> Simple connect state (6/8): Bearer
Jan 01 00:08:34 aeler-imx7ulpea-ucom ModemManager[313]: <info> Simple connect state (7/8): Connect
Jan 01 00:08:34 aeler-imx7ulpea-ucom ModemManager[313]: <info> Modem /org/freedesktop/ModemManager1/Modem/0: state changed (registered -> connecting)As a workaround, forcing a module disconnect with direct AT+CGATT=0 command yields the expected connection behavior.
But it defeats the purpose of having the LTE modem up and running before Linux has started (usefull to limit system uptime in power constrained devices).
Is it something that can be solved by tweaking ModemManager configuration by maybe passing it a few optional parameters?