Can't connect using ModemManager when modem is in QMI mode
Dan Williams
dcbw at redhat.com
Wed Jan 19 17:58:27 UTC 2022
On Wed, 2022-01-19 at 17:25 +0000, Bushman, Jeff wrote:
> 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
I see you have --client-no-release-cid however:
[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
which would terminate the data connection... not sure what the solution
is, but that's likely the cause.
Dan
> --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