Quectel EG21 modem QMI connection works but MM fallbacks to ttyUSB2 as primary port

Tue Nov 24 15:25:47 UTC 2020

Hi,

I have a custom OS built in the buildroot framework and try to integrate
Modem Manager to handle Quectel EG21[the same VID:PID as EC21] using QMI.
I've followed Quectel instruction with patching option.c and qmi_wwan in
the kernel, libqmi seems to work as expected. Unfortunately, when creating
connection over mmcli it always uses ttyUSB2 as primary port, instead of
cdc-wdm0 and expecting PPP to be onboard in order to obtain IP address.

I've spent a few days trying to figure out the root cause, here are my
findings:
1. I can connect to network using qmicli, get IP address using udhcpc and
ping DNS address

*#  qmicli --device=/dev/cdc-wdm0 --device-open-proxy
--wds-start-network="ip-type=4,apn=datamobile.ag <http://datamobile.ag>"
--client-no-release-cid --device-open-qmi[01 Jan 1970, 04:00:08] -Warning
** [/dev/cdc-wdm0] couldn't detect transport type of port: unexpected
driver detected: qmi_wwan_q[01 Jan 1970, 04:00:08] -Warning **
[/dev/cdc-wdm0] requested QMI mode but unexpected transport type
found[/dev/cdc-wdm0] Network started Packet data handle:
'2263396000'[/dev/cdc-wdm0] Client ID not released: Service: 'wds'    CID:
'5'#  udhcpc -q -f -i wwan0udhcpc: started, v1.32.0udhcpc: sending
discoverudhcpc: sending select for 100.76.170.231udhcpc: lease of
100.76.170.231 obtained, lease time 7200deleting routersadding dns 8.8.8.8*

*adding dns 8.8.4.4*

2. When using mmcli simple connect command, I can connect to network but
get stuck on IP request - that's because I don't use PPP, here is the
relevant debug log:

*Jan  1 04:43:56 zubrOS ModemManager[342]: <debug> [000017037.002863]
[modem0/bearer0] looking for best CID matching APN 'datamobile.ag
<http://datamobile.ag>' and PDP type 'ipv4'...Jan  1 04:43:56 zubrOS
ModemManager[342]: <debug> [000017037.003039] [modem0/bearer0] found exact
context at CID 4Jan  1 04:43:56 zubrOS ModemManager[342]: <debug>
[000017037.003261] [modem0/ttyUSB2/at] device open count is 3 (open)Jan  1
04:43:56 zubrOS ModemManager[342]: <debug> [000017037.003403]
[modem0/bearer0] connection through a plain serial AT port: ttyUSB2Jan  1
04:43:56 zubrOS ModemManager[342]: <debug> [000017037.003608]
[modem0/ttyUSB2/at] device open count is 4 (open)Jan  1 04:43:56 zubrOS
ModemManager[342]: <debug> [000017037.003919] [modem0/ttyUSB2/at] device
open count is 3 (close)Jan  1 04:43:56 zubrOS ModemManager[342]: <debug>
[000017037.004334] [modem0/ttyUSB2/at] --> 'ATD*99***4#<CR>'Jan  1 04:43:57
zubrOS ModemManager[342]: <debug> [000017037.059613] [modem0/ttyUSB2/at]
<-- '<CR><LF>CONNECT 150000000<CR><LF>'Jan  1 04:43:57 zubrOS
ModemManager[342]: <debug> [000017037.065783] [modem0/bearer0] setting flow
control in ttyUSB2: rts-ctsJan  1 04:43:57 zubrOS ModemManager[342]:
<debug> [000017037.068708] [modem0/ttyUSB2/at] enabling RTS/CTS flow
controlJan  1 04:43:57 zubrOS ModemManager[342]: <debug> [000017037.069096]
[modem0/ttyUSB2/at] port attributes not fully setJan  1 04:43:57 zubrOS
ModemManager[342]: <debug> [000017037.069307] [modem0/ttyUSB2/at] flow
control settings updated to rts-ctsJan  1 04:43:57 zubrOS
ModemManager[342]: <debug> [000017037.069642] [modem0/ttyUSB2/at] port now
connectedJan  1 04:43:57 zubrOS ModemManager[342]: <debug>
[000017037.070119] [modem0/bearer0] connectedJan  1 04:43:57 zubrOS
ModemManager[342]: <debug> [000017037.071269] [modem0/bearer0] PPP is
required for connection, will ignore disconnection reportsJan  1 04:43:57
zubrOS ModemManager[342]: <info>  [000017037.071682] [modem0] state changed
(connecting -> connected)Jan  1 04:43:57 zubrOS ModemManager[342]: <info>
 [000017037.092887] [modem0] simple connect state (8/8): all done*

3. I've checked lastest version 1.14.8  as well as 1.12.6, results are the
same.
4. I've looked into the debug logs, looks like the problem is that for some
reason Modem Manager tries to use cdc-wdm0 port as a AT command port - AT
command check fails so it ignores cdc-wdm0 and fallbacks to ttyUSB2:

*Jan  1 04:51:00 zubrOS ModemManager[342]: <debug> [000017460.859237]
[filter]   cdc-wdm devices allowed:    yesJan  1 04:51:35 zubrOS kernel: [
  54.178239] qmi_wwan_q 1-1:1.4: cdc-wdm0: USB WDM deviceJan  1 04:51:35
zubrOS ModemManager[342]: <debug> [000017495.405464] [base-manager] adding
port cdc-wdm0 at sysfs path:
/sys/devices/soc0/soc/2100000.aips-bus/2184200.usb/ci_hdrc.1/usb1/1-1/1-1:1.4/usbmisc/cdc-wdm0Jan
 1 04:51:35 zubrOS ModemManager[342]: <debug> [000017495.420915] [cdc-wdm0]
could not get vendor/product idJan  1 04:51:35 zubrOS ModemManager[342]:
<debug> [000017495.438657] [filter] (usbmisc/cdc-wdm0) port allowed:
cdc-wdm deviceJan  1 04:51:35 zubrOS ModemManager[342]: <debug>
[000017495.447846] [base-manager] port cdc-wdm0 is first in device
/sys/devices/soc0/soc/2100000.aips-bus/2184200.usb/ci_hdrc.1/usb1/1-1Jan  1
04:51:35 zubrOS ModemManager[342]: <debug> [000017495.452686] [cdc-wdm0]
could not get vendor/product idJan  1 04:51:35 zubrOS ModemManager[342]:
<debug> [000017495.452926] [cdc-wdm0] could not get vendor/product idJan  1
04:51:35 zubrOS ModemManager[342]: <debug> [000017495.453594]
[plugin-manager] task 5: port grabbed: cdc-wdm0Jan  1 04:51:35 zubrOS
ModemManager[342]: <debug> [000017495.453830] [plugin-manager] task
5,cdc-wdm0: new support task for portJan  1 04:51:35 zubrOS
ModemManager[342]: <debug> [000017495.453969] [plugin-manager] task
5,cdc-wdm0: deferred until min wait time elapsedJan  1 04:51:37 zubrOS
ModemManager[342]: <debug> [000017497.097261] [plugin-manager] task
5,cdc-wdm0: found '2' plugins to tryJan  1 04:51:37 zubrOS
ModemManager[342]: <debug> [000017497.097370] [plugin-manager] task
5,cdc-wdm0: will try with plugin 'quectel'Jan  1 04:51:37 zubrOS
ModemManager[342]: <debug> [000017497.097474] [plugin-manager] task
5,cdc-wdm0: will try with plugin 'generic'Jan  1 04:51:37 zubrOS
ModemManager[342]: <debug> [000017497.097620] [plugin-manager] task
5,cdc-wdm0: startedJan  1 04:51:37 zubrOS ModemManager[342]: <debug>
[000017497.097735] [plugin-manager] task 5,cdc-wdm0: checking with plugin
'quectel'Jan  1 04:51:37 zubrOS ModemManager[342]: <debug>
[000017497.097997] [plugin/quectel] probes required for port cdc-wdm0:
'at'Jan  1 04:51:37 zubrOS ModemManager[342]: <debug> [000017497.105918]
[cdc-wdm0/probe] launching port probing: 'at'Jan  1 04:51:37 zubrOS
ModemManager[342]: <debug> [000017497.180827] [cdc-wdm0/at] opening serial
port...Jan  1 04:51:37 zubrOS ModemManager[342]: <debug> [000017497.182859]
[cdc-wdm0/at] device open count is 1 (open)Jan  1 04:51:37 zubrOS
ModemManager[342]: <debug> [000017497.184505] [cdc-wdm0/at] -->
'AT<CR><LF>'Jan  1 04:51:37 zubrOS ModemManager[342]: <debug>
[000017497.316902] [plugin-manager] task 5: still 6 running probes (5
active): ttyUSB3, ttyUSB0, ttyUSB1, ttyUSB2, wwan0, cdc-wdm0Jan  1 04:51:37
zubrOS ModemManager[342]: <debug> [000017497.472725] [plugin-manager] task
5,cdc-wdm0: got suggested plugin (quectel)Jan  1 04:51:37 zubrOS
ModemManager[342]: <debug> [000017497.472903] [plugin-manager] task 5:
still 5 running probes (5 active): ttyUSB0, ttyUSB1, ttyUSB2, wwan0,
cdc-wdm0Jan  1 04:51:37 zubrOS ModemManager[342]: <debug>
[000017497.529726] [plugin-manager] task 5: still 4 running probes (4
active): ttyUSB0, ttyUSB1, ttyUSB2, cdc-wdm0Jan  1 04:51:37 zubrOS
ModemManager[342]: <debug> [000017497.748822] [plugin-manager] task 5:
still 3 running probes (3 active): ttyUSB0, ttyUSB1, cdc-wdm0Jan  1
04:51:37 zubrOS ModemManager[342]: <debug> [000017497.967929]
[plugin-manager] task 5: still 3 running probes (3 active): ttyUSB0,
ttyUSB1, cdc-wdm0Jan  1 04:51:39 zubrOS ModemManager[342]: <debug>
[000017499.975497] [cdc-wdm0/at] --> 'AT<CR><LF>'Jan  1 04:51:42 zubrOS
ModemManager[342]: <debug> [000017502.972692] [cdc-wdm0/at] -->
'AT<CR><LF>'Jan  1 04:51:44 zubrOS ModemManager[342]: <debug>
[000017504.098907] [plugin-manager] task 5: still 2 running probes (2
active): ttyUSB0, cdc-wdm0Jan  1 04:51:45 zubrOS ModemManager[342]: <debug>
[000017505.974499] [cdc-wdm0/probe] port is not AT-capableJan  1 04:51:45
zubrOS ModemManager[342]: <debug> [000017505.975249] [plugin-manager] task
5,cdc-wdm0: found best plugin for port (quectel)Jan  1 04:51:45 zubrOS
ModemManager[342]: <debug> [000017505.975721] [plugin-manager] task
5,cdc-wdm0: finished in '10.521877' secondsJan  1 04:51:45 zubrOS
ModemManager[342]: <debug> [000017505.976232] [plugin-manager] task
5,cdc-wdm0: best plugin matches device reported one: quectelJan  1 04:51:45
zubrOS ModemManager[342]: <debug> [000017505.977365] [cdc-wdm0/at] device
open count is 0 (close)Jan  1 04:51:45 zubrOS ModemManager[342]: <debug>
[000017505.977820] [cdc-wdm0/at] closing serial port...Jan  1 04:51:45
zubrOS ModemManager[342]: <debug> [000017505.990382] [cdc-wdm0/at] serial
port closedJan  1 04:51:45 zubrOS ModemManager[342]: <debug>
[000017505.993552] [cdc-wdm0/at] forced to close portJan  1 04:51:47 zubrOS
ModemManager[342]: <warn>  [000017507.074976] [plugin/quectel] could not
grab port cdc-wdm0: Cannot add port 'usbmisc/cdc-wdm0', unsupported*

That's the point where I stucked and ran out of ideas for further
debugging. I expect there might be some udev rule missing for EG21 to make
it work, something that would suggest Modem Manager to use cdc-wdm0 as QMI
interface instead of AT.

Any ideas what is the problem I am facing here? I will appreciate any help.

Best Regards,
Rafał
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.freedesktop.org/archives/modemmanager-devel/attachments/20201124/59c6319a/attachment.htm>