Dan,
Yeah, I don't understand that output, because right above it the output is
> > [/dev/cdc-wdm0] Client ID not released:
> > Service: 'wds'
> > CID: '36'
And in fact, the connection does stay up, and I can query it and get the
current settings (--wds-get-current-settings) using the same CID.
I just tried using mmcli to first create the bearer, then connect the bearer,
rather than using --simple-connect
This was successful!
root@wwan:/$ mmcli -m 0 --create-bearer="apn=broadband"
Successfully created new bearer in modem:
/org/freedesktop/ModemManager1/Bearer/0
root@wwan:/$ mmcli -b 0 -c
successfully connected the bearer
root@wwan:/$ mmcli -b 0
------------------------------------
General | path: /org/freedesktop/ModemManager1/Bearer/0
| type: default
------------------------------------
Status | connected: yes
| suspended: no
| multiplexed: no
| interface: wwan0
| ip timeout: 20
------------------------------------
Properties | apn: broadband
| roaming: allowed
------------------------------------
IPv4 configuration | method: static
| address: 10.153.221.70
| prefix: 30
| gateway: 10.153.221.69
| dns: 172.26.38.1
| mtu: 1430
------------------------------------
Statistics | bytes rx: 27006
| bytes tx: 1181
| attempts: 1
| total-bytes rx: 27006
| total-bytes tx: 1181
I have not yet analyzed the ModemManager logs to see what's different.
> -----Original Message-----
> From: Dan Williams <d...@redhat.com>
> Sent: Wednesday, January 19, 2022 9:58 AM
> To: Bushman, Jeff <jbush...@ciena.com>; Aleksander Morgado
> <aleksan...@aleksander.es>; modemmanager-devel@lists.freedesktop.org
> Subject: [**EXTERNAL**] Re: Can't connect using ModemManager when modem is
> in QMI mode
>
> 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@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 <aleksan...@aleksander.es>
> > > Sent: Tuesday, December 7, 2021 6:31 AM
> > > To: Bushman, Jeff <jbush...@ciena.com>
> > > Cc: modemmanager-devel@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 <jbush...@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!bcb32l7
> > > WW_bIT 7ln5dMwj61RKGwdHkSYFKdck8TnaZlEYURb9P1kUPLZt59wLw$
> > > [aleksander[.]es]
>
