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