Random QMI port probe failures after ed13e053cd42 ("port-probe: fix custom init probing not having open AT port")

Wed Dec 18 16:08:32 UTC 2024

Hello,

After updating to the latest main (at eda130f3bf1c), in our team we've noticed, that in our CI, that QMI port sometimes fails to probe,
with Telit LE910C4-WWXD. The result is the modem having only AT ports available, thus falling back to using PPP for the data connection.

I've bisected ModemManager's source code from previous update, which was working OK, and narrowed down the issue to the following commit:
ed13e053cd42 ("port-probe: fix custom init probing not having open AT port").
Reverting it for testing fixes the issue.

I haven't yet dug to the root cause fully, but since current main branch is affected, I decided to reach out early.
The debug logs show, that probe fails right after first QMI transaction, and usbmon capture (attached) confirms that:

ModemManager[13321]: <DEBUG>  <dbg> [1734028733.422964] [/dev/cdc-wdm0] sent message...#012<<<<<< RAW:#012<<<<<<   length = 28#012<<<<<<   data   = 01:1B:00:00:00:00:00:01:00:FF:10:00...#012
ModemManager[13321]: <DEBUG>  <dbg> [1734028733.423671] [/dev/cdc-wdm0] sent generic request (translated)...#012<<<<<< QMUX:#012<<<<<<   length  = 27#012<<<<<<   flags   = 0x00#012<<<<<<   service = "ctl"#012<<<<<<   client  = 0#012<<<<<< QMI:#012<<<<<<   flags       = "none"#012<<<<<<   transaction = 1#012<<<<<<   tlv_length  = 16#012<<<<<<   message     = "Internal Proxy Open" (0xFF00)#012<<<<<< TLV:#012<<<<<<   type       = "Device Path" (0x01)#012<<<<<<   length     = 13#012<<<<<<   value      = 2F:64:65:76:2F:63:64:63:2D:77:64:6D:30#012<<<<<<   translated = /dev/cdc-wdm0#012
ModemManager[13321]: <DEBUG>  <dbg> [1734028733.429528] [/dev/cdc-wdm0] received message...#012<<<<<< RAW:#012<<<<<<   length = 19#012<<<<<<   data   = 01:12:00:80:00:00:01:01:00:FF:07:00...#012
ModemManager[13321]: <DEBUG>  <dbg> [1734028733.430244] [/dev/cdc-wdm0] received generic response (translated)...#012<<<<<< QMUX:#012<<<<<<   length  = 18#012<<<<<<   flags   = 0x80#012<<<<<<   service = "ctl"#012<<<<<<   client  = 0#012<<<<<< QMI:#012<<<<<<   flags       = "response"#012<<<<<<   transaction = 1#012<<<<<<   tlv_length  = 7#012<<<<<<   message     = "Internal Proxy Open" (0xFF00)#012<<<<<< TLV:#012<<<<<<   type       = "Result" (0x02)#012<<<<<<   length     = 4#012<<<<<<   value      = 00:00:00:00#012<<<<<<   translated = SUCCESS#012
ModemManager[13321]: <DEBUG>  <dbg> [1734028733.430446] [/dev/cdc-wdm0] checking version info (45 retries)...
ModemManager[13321]: <DEBUG>  <dbg> [1734028733.430596] [/dev/cdc-wdm0] sent message...#012<<<<<< RAW:#012<<<<<<   length = 12#012<<<<<<   data   = 01:0B:00:00:00:00:00:02:21:00:00:00...#012
ModemManager[13321]: <DEBUG>  <dbg> [1734028733.430673] [/dev/cdc-wdm0] sent generic request (translated)...#012<<<<<< QMUX:#012<<<<<<   length  = 11#012<<<<<<   flags   = 0x00#012<<<<<<   service = "ctl"#012<<<<<<   client  = 0#012<<<<<< QMI:#012<<<<<<   flags       = "none"#012<<<<<<   transaction = 2#012<<<<<<   tlv_length  = 0#012<<<<<<   message     = "Get Version Info" (0x0021)#012
ModemManager[13321]: <DEBUG>  <dbg> [1734028733.434635] [cdc-wdm0/at] <-- '\1\197\0\128\0\0\1\1!\0\186\0\2\4\0\0\0\0\0\1\176\0#\0\1\0\5\0\1\1\0C\0\2\1\0\0\0\3\1\0\25\0\4\1\0\12\0\5\1\0<LF>\0\7\1\0\3\0\8\1\0\4\0\9\2\0\1\0<LF>\2\0\24\0\11\1\0W\0\12\1\0\4\0\15\1\0\0\0\16\2\0\0\0\17\1\0\0\0\18\1\0\0\0\20\1\0\0\0\23\1\0\0\0\24\1\0\0\0\26\1\0\16\0\29\1\0\1\0\31\1\0\0\0!\1\0\0\0"\1\0\0\0$\1\0\0\0)\1\0\0\0*\1\0\0\00\1\0\0\02\1\0\0\06\1\0\0\0I\1\0\0\0\231\1\0\0\0\232\1\0\0\0\235\1\0\0\0\237\1\0\0\0'
ModemManager[13321]: <WARNING>  <wrn> [1734028733.435136] Cannot read from istream: connection broken
ModemManager[13321]: <DEBUG>  <dbg> [1734028733.435205] [/dev/cdc-wdm0] endpoint hangup: removed
ModemManager[13321]: <DEBUG>  <dbg> [1734028733.435485] [cdc-wdm0/qmi] QMI port open operation failed: endpoint hangup
ModemManager[13321]: <DEBUG>  <dbg> [1734028733.435821] [cdc-wdm0/probe] error checking QMI support: endpoint hangup
ModemManager[13321]: <DEBUG>  <dbg> [1734028733.435881] [cdc-wdm0/probe] port is not QMI-capable
ModemManager[13321]: <NOTICE>  <msg> [1734028733.436181] [cdc-wdm0/probe] probe step: done

The line containing binary dump with '[cdc-wdm0/at]' faintly suggests, that port type might be misdetected - but - I have yet to confirm that.
Since the issue was caused by pretty significant refactoring, it may take some time, but maybe someone can spot the error faster - so I'm reaching out for help, especially to Dan :-)

Reproducibility is around 50%
Any help would be greatly appreciated.

-- 
Pozdrawiam/With kind regards,
Lech Perczak

Sr. Software Engineer
Camlin Technologies Poland Limited Sp. z o.o.
Strzegomska 54,
53-611 Wroclaw
Tel:     (+48) 71 75 000 16
Email:   lech.perczak at camlingroup.com
Website: http://www.camlingroup.com
-------------- next part --------------
A non-text attachment was scrubbed...
Name: le910c4_qmi_probe_fail.pcap
Type: application/vnd.tcpdump.pcap
Size: 4013 bytes
Desc: not available
URL: <https://lists.freedesktop.org/archives/modemmanager-devel/attachments/20241218/4938a459/attachment-0001.pcap>