usb_modem and mbimcli

[Duss Pirmin]

Hello Genodians

I have a SIMCOM 7600G mPCI modem, which I have configured to use MBIM
mode. The device is recognized by `usb_drv` as follows:
```
<device label="usb-1-4" vendor_id="0x1e0e" product_id="0x9003" bus="0x1"
dev="0x4" class="0xff">
    <interface class="0xff" protocol="0xff"/>
    <interface class="0xff" protocol="0x0"/>
    <interface class="0xff" protocol="0x0"/>
    <interface class="0xff" protocol="0x0"/>
    <interface class="0xff" protocol="0x0"/>
    <interface class="0x2" protocol="0x0"/>
    <interface class="0xa" protocol="0x2"/>
</device>
```

As described in the README of the driver I added a configuration to
`usb_modem_drv.

Most of the times when I execute mbimcli.run (with or without a SIM card
inserted) I get the following error:
```
Error: couldn't open the MbimDevice: Operation timed out: device is closed
```
On a low fraction of runs without SIM `mbimcli` reports that no sim is
inserted.

Setting the `TRACE` enum in `construct.cc` of mbimcli to `TRUE`, I see
the following debug output.

```
[13:44:42.820] [init -> mbimcli] <<<<<< RAW:
[13:44:42.821] [init -> mbimcli] <<<<<<   length = 16
[13:44:42.821] [init -> mbimcli] <<<<<<   data   =
01:00:00:00:10:00:00:00:01:00:00:00:00:10:00:00
[13:44:42.842] [init -> mbimcli]
[13:44:42.842] [init -> mbimcli] [Debug] [/dev/cdc-wdm0] Sent message
(translated)...
[13:44:42.843] [init -> mbimcli] <<<<<< Header:
[13:44:42.843] [init -> mbimcli] <<<<<<   length      = 16
[13:44:42.843] [init -> mbimcli] <<<<<<   type        = open (0x00000001)
[13:44:42.855] [init -> mbimcli] <<<<<<   transaction = 1
[13:44:42.856] [init -> mbimcli] <<<<<< Contents:
[13:44:42.856] [init -> mbimcli] <<<<<<   max control transfer = 4096
[13:44:42.856] [init -> mbimcli]
[13:44:47.821] [init -> mbimcli] [Debug] [/dev/cdc-wdm0] Sent message...
[13:44:47.822] [init -> mbimcli] <<<<<< RAW:
[13:44:47.822] [init -> mbimcli] <<<<<<   length = 16
[13:44:47.822] [init -> mbimcli] <<<<<<   data   =
01:00:00:00:10:00:00:00:02:00:00:00:00:10:00:00
[13:44:47.844] [init -> mbimcli]
[13:44:47.844] [init -> mbimcli] [Debug] [/dev/cdc-wdm0] Sent message
(translated)...
[13:44:47.845] [init -> mbimcli] <<<<<< Header:
[13:44:47.845] [init -> mbimcli] <<<<<<   length      = 16
[13:44:47.845] [init -> mbimcli] <<<<<<   type        = open (0x00000001)
[13:44:47.857] [init -> mbimcli] <<<<<<   transaction = 2
[13:44:47.857] [init -> mbimcli] <<<<<< Contents:
[13:44:47.857] [init -> mbimcli] <<<<<<   max control transfer = 4096
[13:44:47.858] [init -> mbimcli]
[13:44:50.890] [init -> mbimcli] [Debug] [/dev/cdc-wdm0] Received message...
[13:44:50.891] [init -> mbimcli] >>>>>> RAW:
[13:44:50.891] [init -> mbimcli] >>>>>>   length = 16
[13:44:50.891] [init -> mbimcli] >>>>>>   data   =
01:00:00:80:10:00:00:00:01:00:00:00:00:00:00:00
[13:44:50.898] [init -> mbimcli]
[13:44:50.899] [init -> mbimcli] [Debug] [/dev/cdc-wdm0] No transaction
matched in received message
[13:44:50.921] [init -> mbimcli] [Debug] [/dev/cdc-wdm0] Received
unexpected message (translated)...
[13:44:50.921] [init -> mbimcli] >>>>>> Header:
[13:44:50.921] [init -> mbimcli] >>>>>>   length      = 16
[13:44:50.921] [init -> mbimcli] >>>>>>   type        = open-done
(0x80000001)
[13:44:50.936] [init -> mbimcli] >>>>>>   transaction = 1
[13:44:50.936] [init -> mbimcli] >>>>>> Contents:
[13:44:50.936] [init -> mbimcli] >>>>>>   status error = 'None' (0x00000000)
[13:44:50.936] [init -> mbimcli]
[13:44:52.824] [init -> mbimcli] [Debug] [/dev/cdc-wdm0] Sent message...
[13:44:52.825] [init -> mbimcli] <<<<<< RAW:
[13:44:52.825] [init -> mbimcli] <<<<<<   length = 16
[13:44:52.825] [init -> mbimcli] <<<<<<   data   =
01:00:00:00:10:00:00:00:03:00:00:00:00:10:00:00
[13:44:52.846] [init -> mbimcli]
[13:44:52.846] [init -> mbimcli] [Debug] [/dev/cdc-wdm0] Sent message
(translated)...
[13:44:52.847] [init -> mbimcli] <<<<<< Header:
[13:44:52.847] [init -> mbimcli] <<<<<<   length      = 16
[13:44:52.847] [init -> mbimcli] <<<<<<   type        = open (0x00000001)
[13:44:52.859] [init -> mbimcli] <<<<<<   transaction = 3
[13:44:52.859] [init -> mbimcli] <<<<<< Contents:
[13:44:52.860] [init -> mbimcli] <<<<<<   max control transfer = 4096
[13:44:52.860] [init -> mbimcli]
...
```
This looks to me, as if the device is too slow in answering the first
request. `mbimcli` will continue to send until transaction ID nine is
reached and then stop with the error message from above. Only one
response is ever received per test run on error.

When I insert a SIM card, then a second message is received directly
after the first which looks as follows:
```
[15:24:15.668] [init -> mbimcli] [Debug] [/dev/cdc-wdm0] Received message...
[15:24:15.668] [init -> mbimcli] >>>>>> RAW:
[15:24:15.668] [init -> mbimcli] >>>>>>   length = 92
[15:24:15.691] [init -> mbimcli] >>>>>>   data   =
07:00:00:80:5C:00:00:00:00:00:00:00:01:00:00:00:00:00:00:00:53:3F:BE:EB:14:FE:44:67:9F:90:33:A2:23:E5:6C:3F:01:00:00:00:30:00:00:00:01:00:00:00:00:00:00:00:35:00:00:00:00:00:00:00:18:00:00:00:18:00:00:00:2B:00:34:
[15:24:15.691] [init -> mbimcli]
00:31:00:37:00:39:00:34:00:39:00:39:00:39:00:30:00:30:00:30:00
[15:24:15.691] [init -> mbimcli]
[15:24:15.714] [init -> mbimcli] [Debug] [/dev/cdc-wdm0] Received
message (translated)...
[15:24:15.715] [init -> mbimcli] >>>>>> Header:
[15:24:15.715] [init -> mbimcli] >>>>>>   length      = 92
[15:24:15.715] [init -> mbimcli] >>>>>>   type        = indicate-status
(0x80000007)
[15:24:15.736] [init -> mbimcli] >>>>>>   transaction = 0
[15:24:15.736] [init -> mbimcli] >>>>>> Fragment header:
[15:24:15.737] [init -> mbimcli] >>>>>>   total   = 1
[15:24:15.737] [init -> mbimcli] >>>>>>   current = 0
[15:24:15.737] [init -> mbimcli] >>>>>> Contents:
[15:24:15.753] [init -> mbimcli] >>>>>>   service = 'sms'
(533fbeeb-14fe-4467-9f90-33a223e56c3f)
[15:24:15.753] [init -> mbimcli] >>>>>>   cid     = 'configuration'
(0x00000001)
[15:24:15.754] [init -> mbimcli] >>>>>> Fields: Unknown contents
[15:24:15.754] [init -> mbimcli]
```
Still `mbimcli` will send further open requests. What I do not
understand is that a service `sms` is reported, however the SIM in use
doesn't support sending/receiving of SMS.

In rare cases the following message also appears in the output:
```
[init -> usb_modem_drv] dev_err: nonzero urb status received: -EPIPE
```
I'm not sure if it is related, but as the modem is connected via USB it
could be.

The device is connected to a iMX8m mini, which uses the same
`usb_host_drv` as the iMX6q sabrelite.

Has anybody an idea how I could narrow down the issue?

Best regards,
Pirmin