Unable to connect using a Quectel EC25-E modem and libqmi 1.18.0

Wed Jun 7 11:04:13 UTC 2017

Amr Bekhit <amrbekhit at gmail.com> writes:

> Hello all,
>
> I have a Quectel EC25-E modem that I'm trying to get working on a Raspberry
> Pi 3 Model B V1.2. The rootfs has been built using Buildroot and includes
> libqmi 1.18.0 and is running kernel 4.9.17 which has been pulled from the
> Raspberry Foundation github repo (https://github.com/raspberrypi/linux). As
> far as I can tell, there does appear to be support for the EC25 in the 4.9
> kernel (it is referenced in qmi_wwan.c).
>
> After plugging in the device, I get the following messages in dmesg:
>
> [    6.357871] usb 1-1.4: new high-speed USB device number 5 using dwc_otg
> [    6.497868] usb 1-1.4: New USB device found, idVendor=2c7c,
> idProduct=0125
> [    6.498110] usb 1-1.4: New USB device strings: Mfr=1, Product=2,
> SerialNumber=0
> [    6.498329] usb 1-1.4: Product: Android
> [    6.498444] usb 1-1.4: Manufacturer: Android
> [    6.523414] usbcore: registered new interface driver usbserial
> [    6.523740] usbcore: registered new interface driver usbserial_generic
> [    6.524027] usbserial: USB Serial support registered for generic
> [    6.543366] usbcore: registered new interface driver option
> [    6.543647] usbserial: USB Serial support registered for GSM modem
> (1-port)
> [    6.544646] option 1-1.4:1.0: GSM modem (1-port) converter detected
> [    6.545372] usb 1-1.4: GSM modem (1-port) converter now attached to
> ttyUSB0
> [    6.545849] option 1-1.4:1.1: GSM modem (1-port) converter detected
> [    6.546566] usb 1-1.4: GSM modem (1-port) converter now attached to
> ttyUSB1
> [    6.547038] option 1-1.4:1.2: GSM modem (1-port) converter detected
> [    6.547628] usb 1-1.4: GSM modem (1-port) converter now attached to
> ttyUSB2
> [    6.550785] usbcore: registered new interface driver cdc_wdm
> [    6.555116] option 1-1.4:1.3: GSM modem (1-port) converter detected
> [    6.556428] usb 1-1.4: GSM modem (1-port) converter now attached to
> ttyUSB3
> [    6.565055] qmi_wwan 1-1.4:1.4: cdc-wdm0: USB WDM device
> [    6.569221] qmi_wwan 1-1.4:1.4 wwan0: register 'qmi_wwan' at
> usb-3f980000.usb-1.4, WWAN/QMI device, 3a:e6:60:3a:76:ef
> [    6.570799] usbcore: registered new interface driver qmi_wwan
>
>
> In order to get debug information, I've manually started qmi-proxy by
> running the following:
>
> # /usr/libexec/qmi-proxy --verbose --no-exit
> [07 Jun 2017, 09:48:31] [Debug] creating UNIX socket service...
> [07 Jun 2017, 09:48:31] [Debug] starting UNIX socket service at
> 'qmi-proxy'...
>
> I've created the file /etc/qmi-network.conf with the following contents:
>
> # cat /etc/qmi-network.conf
> APN=internet
> PROXY=yes
>
> After that, I've attempted to use qmi-network to start the network by
> running the following:
>
> # qmi-network /dev/cdc-wdm0 start
> Loading profile at /etc/qmi-network.conf...
>     APN: internet
>     APN user: unset
>     APN password: unset
>     qmi-proxy: yes
> Checking data format with 'qmicli -d /dev/cdc-wdm0 --wda-get-data-format
> --device-open-proxy'...
> error: couldn't create client for the 'wda' service: CID allocation failed
> in the CTL client: Transaction timed out
> Device link layer protocol not retrieved: WDA unsupported
> Starting network with 'qmicli -d /dev/cdc-wdm0
> --wds-start-network=apn='internet'
>  --client-no-release-cid --device-open-proxy'...
> error: couldn't open the QmiDevice: Transaction timed out
> error: network start failed, client not allocated
>
> While this has been running, the following output can be seen on qmi-proxy:
>
> [07 Jun 2017, 09:48:42] [Debug] Client (6) connection open...
> [07 Jun 2017, 09:48:42] [Debug] valid request to open connection to QMI
> device file: /dev/cdc-wdm0
> [07 Jun 2017, 09:48:42] [Debug] [/dev/cdc-wdm0] Opening device with flags
> 'none'...
> [07 Jun 2017, 09:48:42] [Debug] [/dev/cdc-wdm0] loaded driver of cdc-wdm
> port: qmi_wwan
> [07 Jun 2017, 09:48:42] [Debug] connection to QMI device '/dev/cdc-wdm0'
> established
> [07 Jun 2017, 09:48:42] [Debug] Client (6) TX: 19 bytes
> [07 Jun 2017, 09:48:42] [Debug] [/dev/cdc-wdm0] sent message...
> <<<<<< RAW:
> <<<<<<   length = 16
> <<<<<<   data   = 01:0F:00:00:00:00:00:01:22:00:04:00:01:01:00:1A
>
> [07 Jun 2017, 09:48:42] [Debug] [/dev/cdc-wdm0] sent generic request
> (translated)...
> <<<<<< QMUX:
> <<<<<<   length  = 15
> <<<<<<   flags   = 0x00
> <<<<<<   service = "ctl"
> <<<<<<   client  = 0
> <<<<<< QMI:
> <<<<<<   flags       = "none"
> <<<<<<   transaction = 1
> <<<<<<   tlv_length  = 4
> <<<<<<   message     = "Allocate CID" (0x0022)
> <<<<<< TLV:
> <<<<<<   type       = "Service" (0x01)
> <<<<<<   length     = 1
> <<<<<<   value      = 1A
> <<<<<<   translated = wda
>
> [07 Jun 2017, 09:48:52] [Debug] Client (6) connection closed...
> [07 Jun 2017, 09:48:52] [Debug] closing device '/dev/cdc-wdm0': no longer
> used
>
> Obviously, the connection doesn't work.
>
> When I try and run qmi-network again, there is no new output on qmi-proxy,
> and it appears to have frozen (this may be related to
> https://bugs.freedesktop.org/show_bug.cgi?id=101271).

This looks like usb_submit_urb() accepts the control request but never
calls the callback. I don't know how that can happen, but I do believe
it is an error on some lower layer than libqmi/cdc-wdm.  I am unsure
about current status, but the Raspberry Pi used have a really buggy USB
controller/driver.  Is there any way you can test this modem with some
other hardware?

> dmesg also shows the following:
>
> [  243.678016] INFO: task qmi-proxy:325 blocked for more than 120 seconds.
> [  243.678219]       Not tainted 4.9.17-v7 #1
> [  243.678338] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables
> this message.
> [  243.682908] qmi-proxy       D    0   325    322 0x00000000
> [  243.687530] [<80718ea4>] (__schedule) from [<807193d0>]
> (schedule+0x50/0xa8)
> [  243.692023] [<807193d0>] (schedule) from [<7f3a93a0>]
> (wdm_flush+0x74/0xe4 [cdc_wdm])
> [  243.696465] [<7f3a93a0>] (wdm_flush [cdc_wdm]) from [<8026ee98>]
> (filp_close+0x40/0x8c)
> [  243.700773] [<8026ee98>] (filp_close) from [<80291768>]
> (__close_fd+0xc8/0xec)
> [  243.705090] [<80291768>] (__close_fd) from [<8026ef14>]
> (SyS_close+0x30/0x58)
> [  243.709404] [<8026ef14>] (SyS_close) from [<80107fc0>]
> (ret_fast_syscall+0x0/0x1c)
> [  366.566270] INFO: task qmi-proxy:325 blocked for more than 120 seconds.
> [  366.570693]       Not tainted 4.9.17-v7 #1
> [  366.575122] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables
> this message.
> [  366.579679] qmi-proxy       D    0   325    322 0x00000000
> [  366.584384] [<80718ea4>] (__schedule) from [<807193d0>]
> (schedule+0x50/0xa8)
> [  366.589105] [<807193d0>] (schedule) from [<7f3a93a0>]
> (wdm_flush+0x74/0xe4 [cdc_wdm])
> [  366.593802] [<7f3a93a0>] (wdm_flush [cdc_wdm]) from [<8026ee98>]
> (filp_close+0x40/0x8c)
> [  366.598465] [<8026ee98>] (filp_close) from [<80291768>]
> (__close_fd+0xc8/0xec)
> [  366.603191] [<80291768>] (__close_fd) from [<8026ef14>]
> (SyS_close+0x30/0x58)
> [  366.607938] [<8026ef14>] (SyS_close) from [<80107fc0>]
> (ret_fast_syscall+0x0/0x1c)
>
> (there are more of these repeated).

This symptom match the assumptions.  wdm_flush() waits for WDM_IN_USE to
be cleared, which will happen when wdm_out_callback() is called. This is
guaranteed to happen by the usb_submit_urb() API:

 * If the submission is successful, the complete() callback from the URB
 * will be called exactly once, when the USB core and Host Controller Driver
 * (HCD) are finished with the URB.  When the completion function is called,
 * control of the URB is returned to the device driver which issued the
 * request.  The completion handler may then immediately free or reuse that
 * URB.

But for some reason this guarantee does not hold on your hardware.  I
believe this must be a bug in the host controller and/or host controller
driver.

Bjørn