Can't connect using ModemManager when modem is in QMI mode

[Aleksander Morgado]

Hey

On Wed, Dec 1, 2021 at 7:34 PM Bushman, Jeff <jbushman at ciena.com> wrote:
>
> I have attached the modem manager debug logs. Search for "simple connect". One odd thing I noticed was a log message about "reseting expected kernel data format to 802.3 in data interface 'wwan0'" which is not correct. The interface has always worked as raw-ip.
>

Not really sure what to say.

I can see the modem was registered in LTE:
ModemManager[142927]: <info>  [1638319821.344780] [modem0] 3GPP
registration state changed (idle -> registering)
ModemManager[142927]: <debug> [1638319821.344842] [modem0] 3GPP
location area code updated: '0000->FFFE'
ModemManager[142927]: <debug> [1638319821.344868] [modem0] 3GPP
tracking area code updated: '000000->008B45'
ModemManager[142927]: <debug> [1638319821.344889] [modem0] 3GPP cell
id updated: '00000000->0A34E708'
ModemManager[142927]: <debug> [1638319821.344911] [modem0] 3GPP
location updated (MCCMNC: '310410', location area code: 'FFFE',
tracking area code: '008B45', cell ID: '0A34E708')
ModemManager[142927]: <debug> [1638319821.344939] [modem0] initial
3GPP registration checks finished
ModemManager[142927]: <info>  [1638319821.345060] [modem0] 3GPP
registration state changed (registering -> home)

Then the user request to connect arrives:
ModemManager[142927]: <debug> [1638319848.008932] [modem0] user
request to connect modem

The start command is sent to the modem:
ModemManager[142927]: <debug> [1638319848.096731] [modem0/bearer1]
starting IPv4 connection...

Then suddenly we're reported as unregistered:
ModemManager[142927]: <info>  [1638319848.512828] [modem0] 3GPP
registration state changed (home -> idle)

And we abort the connection attempt at that time:

ModemManager[142927]: <debug> [1638319848.513019] [modem0/bearer1]
bearer not allowed to connect, not registered in 3GPP network
ModemManager[142927]: <debug> [1638319848.513039] [modem0/bearer1]
forcing disconnection

And we get the operation cancelled error sent back to the user,
because we were the ones aborting the attempt:

ModemManager[142927]: <warn>  [1638319848.640846] [modem0/bearer1]
connection attempt #1 failed: operation cancelled

A bit later we're now searching again:

ModemManager[142927]: <info>  [1638319848.960755] [modem0] 3GPP
registration state changed (idle -> searching)

And later on registered again:

ModemManager[142927]: <info>  [1638319849.537496] [modem0] 3GPP
registration state changed (registering -> home)

For the looks of it, if this is reproduced every time, it seems our
connection attempt is the one triggering the modem unregistration in
the modem, which ends up forcing the connection attempt abort. I'm not
sure how our connection attempt could trigger that. Maybe related to
having the initial EPS bearer with the same settings as the data
connection bearer? I can see they both use the same "broadband" APN.

Could you play around a bit trying to connect the modem using qmicli
commands to see if we can find some reliable way of doing it without
ModemManager involved? Maybe we should assume the connection is up
already when the data bearer settings match the initial eps bearer
settings.

-- 
Aleksander
https://aleksander.es