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

Thu Dec 19 21:57:03 UTC 2024

On Thu, 2024-12-19 at 15:46 -0600, Dan Williams wrote:
> 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.
> 

When this happens, does MM attempt to probe the port as AT before
trying QMI?

Dan

> 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.
> > 
> 
> 
> 