Can't connect using ModemManager when modem is in QMI mode
Bushman, Jeff
jbushman at ciena.com
Wed Jan 19 17:25:57 UTC 2022
Hi Aleksander,
I am revisiting this with a little more information, and a better understanding of what you wrote.
A simple-connect from ModemManager always fails. I can always connect from qmicli (Abbreviated log below; stripped out raw data in this trace)
But as you say, when connecting via ModemManager, the modem sends indications that the Preferred Data System goes to 'unknown' and the ps_attach_state goes to 'detached'
Is there any way to manually turn on indications and monitor them from qmicli or get ModemManager to ignore these indications just to see if it's just a bug in the modem firmware? Could there be some other initialization of the modem by ModemManager that triggers this behavior?
Jeff
root at wwan:/$ qmicli -d /dev/cdc-wdm0 --wds-start-network=apn='broadband' --client-no-release-cid --device-open-proxy --verbose
[12 Jan 2022, 01:23:09] [Debug] [/dev/cdc-wdm0] Opening device with flags 'proxy, auto'...
[12 Jan 2022, 01:23:09] [Debug] [/dev/cdc-wdm0] automatically selecting QMI mode
[12 Jan 2022, 01:23:09] [Debug] [/dev/cdc-wdm0] created endpoint
[12 Jan 2022, 01:23:09] [Debug] [/dev/cdc-wdm0] Sent generic request (translated)...
<<<<<< QMUX:
<<<<<< length = 27
<<<<<< flags = 0x00
<<<<<< service = "ctl"
<<<<<< client = 0
<<<<<< QMI:
<<<<<< flags = "none"
<<<<<< transaction = 1
<<<<<< tlv_length = 16
<<<<<< message = "Internal Proxy Open" (0xFF00)
<<<<<< TLV:
<<<<<< type = "Device Path" (0x01)
<<<<<< length = 13
<<<<<< value = 2F:64:65:76:2F:63:64:63:2D:77:64:6D:30
<<<<<< translated = /dev/cdc-wdm0
[12 Jan 2022, 01:23:09] [Debug] [/dev/cdc-wdm0] Received generic response (translated)...
<<<<<< QMUX:
<<<<<< length = 18
<<<<<< flags = 0x80
<<<<<< service = "ctl"
<<<<<< client = 0
<<<<<< QMI:
<<<<<< flags = "response"
<<<<<< transaction = 1
<<<<<< tlv_length = 7
<<<<<< message = "Internal Proxy Open" (0xFF00)
<<<<<< TLV:
<<<<<< type = "Result" (0x02)
<<<<<< length = 4
<<<<<< value = 00:00:00:00
<<<<<< translated = SUCCESS
[12 Jan 2022, 01:23:09] [Debug] QMI Device at '/dev/cdc-wdm0' ready
[12 Jan 2022, 01:23:09] [Debug] [/dev/cdc-wdm0] Assuming service 'wds' is supported...
[12 Jan 2022, 01:23:09] [Debug] [/dev/cdc-wdm0] Allocating new client ID...
[12 Jan 2022, 01:23:09] [Debug] [/dev/cdc-wdm0] Sent generic request (translated)...
<<<<<< QMUX:
<<<<<< length = 15
<<<<<< flags = 0x00
<<<<<< service = "ctl"
<<<<<< client = 0
<<<<<< QMI:
<<<<<< flags = "none"
<<<<<< transaction = 2
<<<<<< tlv_length = 4
<<<<<< message = "Allocate CID" (0x0022)
<<<<<< TLV:
<<<<<< type = "Service" (0x01)
<<<<<< length = 1
<<<<<< value = 01
<<<<<< translated = wds
[12 Jan 2022, 01:23:09] [Debug] [/dev/cdc-wdm0] Received generic response (translated)...
<<<<<< QMUX:
<<<<<< length = 23
<<<<<< flags = 0x80
<<<<<< service = "ctl"
<<<<<< client = 0
<<<<<< QMI:
<<<<<< flags = "response"
<<<<<< transaction = 2
<<<<<< tlv_length = 12
<<<<<< message = "Allocate CID" (0x0022)
<<<<<< TLV:
<<<<<< type = "Result" (0x02)
<<<<<< length = 4
<<<<<< value = 00:00:00:00
<<<<<< translated = SUCCESS
<<<<<< TLV:
<<<<<< type = "Allocation Info" (0x01)
<<<<<< length = 2
<<<<<< value = 01:24
<<<<<< translated = [ service = 'wds' cid = '36' ]
[12 Jan 2022, 01:23:09] [Debug] [/dev/cdc-wdm0] Registered 'wds' (version unknown) client with ID '36'
[12 Jan 2022, 01:23:09] [Debug] Network start parameters set (apn: 'broadband', 3gpp_profile: '0', 3gpp2_profile: '0', auth: 'unspecified', ip-type: 'unspecified', username: 'unspecified', password: 'unspecified', autoconnect: 'unspecified')
[12 Jan 2022, 01:23:09] [Debug] Asynchronously starting network...
[12 Jan 2022, 01:23:09] [Debug] [/dev/cdc-wdm0] Sent generic request (translated)...
<<<<<< QMUX:
<<<<<< length = 28
<<<<<< flags = 0x00
<<<<<< service = "wds"
<<<<<< client = 36
<<<<<< QMI:
<<<<<< flags = "none"
<<<<<< transaction = 1
<<<<<< tlv_length = 16
<<<<<< message = "Start Network" (0x0020)
<<<<<< TLV:
<<<<<< type = "IP Family Preference" (0x19)
<<<<<< length = 1
<<<<<< value = 08
<<<<<< translated = unspecified
<<<<<< TLV:
<<<<<< type = "APN" (0x14)
<<<<<< length = 9
<<<<<< value = 62:72:6F:61:64:62:61:6E:64
<<<<<< translated = broadband
[12 Jan 2022, 01:23:09] [Debug] [/dev/cdc-wdm0] Received generic response (translated)...
<<<<<< QMUX:
<<<<<< length = 26
<<<<<< flags = 0x80
<<<<<< service = "wds"
<<<<<< client = 36
<<<<<< QMI:
<<<<<< flags = "response"
<<<<<< transaction = 1
<<<<<< tlv_length = 14
<<<<<< message = "Start Network" (0x0020)
<<<<<< TLV:
<<<<<< type = "Result" (0x02)
<<<<<< length = 4
<<<<<< value = 00:00:00:00
<<<<<< translated = SUCCESS
<<<<<< TLV:
<<<<<< type = "Packet Data Handle" (0x01)
<<<<<< length = 4
<<<<<< value = 30:30:C7:03
<<<<<< translated = 63385648
[/dev/cdc-wdm0] Network started
Packet data handle: '63385648'
[/dev/cdc-wdm0] Client ID not released:
Service: 'wds'
CID: '36'
[12 Jan 2022, 01:23:09] [Debug] [/dev/cdc-wdm0] Releasing 'wds' client with flags 'none'...
[12 Jan 2022, 01:23:09] [Debug] [/dev/cdc-wdm0] Unregistered 'wds' client with ID '36'
[12 Jan 2022, 01:23:09] [Debug] Client released
[12 Jan 2022, 01:23:09] [Debug] Closed
> -----Original Message-----
> From: Aleksander Morgado <aleksander at aleksander.es>
> Sent: Tuesday, December 7, 2021 6:31 AM
> To: Bushman, Jeff <jbushman at ciena.com>
> Cc: modemmanager-devel at lists.freedesktop.org
> Subject: [**EXTERNAL**] Re: Can't connect using ModemManager when modem is
> in QMI mode
>
> 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://urldefense.com/v3/__https://aleksander.es__;!!OSsGDw!bcb32l7WW_bIT
> 7ln5dMwj61RKGwdHkSYFKdck8TnaZlEYURb9P1kUPLZt59wLw$ [aleksander[.]es]
More information about the ModemManager-devel
mailing list