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

[Dan Williams]

On Wed, 2024-12-18 at 17:08 +0100, Lech Perczak wrote:
> 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.

Well that's not awesome; I'll dig into it. If you figure out anything
too, let me know.

Sorry about that...

Dan

> 
> 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\0
> C\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\0
> 2\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.
>