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!bcb32l7WW_bIT > > 7ln5dMwj61RKGwdHkSYFKdck8TnaZlEYURb9P1kUPLZt59wLw$ [aleksander[.]es]
