Unable to connect using a Quectel EC25-E modem and libqmi 1.18.0
Amr Bekhit
amrbekhit at gmail.com
Tue Jun 13 05:42:39 UTC 2017
>
> 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?
I've just tried this on a regular laptop running a live USB image of
ArchLinux (archlinux-2017.04.01-x86_64.iso). This runs kernel
4.10.6-1-ARCH, which as far as I can tell, uses the same drivers as 4.9 (at
least comparing qmi_wwan). This exhibited the same issue that I faced when
working with the modem on the Raspberry Pi:
root at archiso ~ # qmi-network /dev/cdc-wdm1 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-wdm1 --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-wdm1
--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
#
qmi-proxy in the meantime shows the following:
root at archiso ~ # /usr/lib/libqmi/qmi-proxy --no-exit --verbose
[07 Jun 2017, 16:27:39] [Debug] creating UNIX socket service...
[07 Jun 2017, 16:27:39] [Debug] starting UNIX socket service at
'qmi-proxy'...
[07 Jun 2017, 16:28:54] [Debug] Client (6) connection open...
[07 Jun 2017, 16:28:54] [Debug] valid request to open connection to QMI
device file: /dev/cdc-wdm1
[07 Jun 2017, 16:28:54] [Debug] [/dev/cdc-wdm1] Opening device with flags
'none'...
[07 Jun 2017, 16:28:54] [Debug] [/dev/cdc-wdm1] loaded driver of cdc-wdm
port: qmi_wwan
[07 Jun 2017, 16:28:54] [Debug] connection to QMI device '/dev/cdc-wdm1'
established
[07 Jun 2017, 16:28:54] [Debug] Client (6) TX: 19 bytes
[07 Jun 2017, 16:28:54] [Debug] [/dev/cdc-wdm1] 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, 16:28:54] [Debug] [/dev/cdc-wdm1] 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, 16:29:04] [Debug] Client (6) connection closed...
[07 Jun 2017, 16:29:04] [Debug] closing device '/dev/cdc-wdm1': no longer
used
Once again it freezes in kernel code, and I get the following in dmesg:
[ 491.177149] INFO: task qmi-proxy:978 blocked for more than 120 seconds.
[ 491.177256] Not tainted 4.10.6-1-ARCH #1
[ 491.177311] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables
this message.
[ 491.177400] qmi-proxy D 0 978 969 0x00000000
[ 491.177407] Call Trace:
[ 491.177424] __schedule+0x22f/0x700
[ 491.177431] ? __vfs_write+0x37/0x140
[ 491.177436] schedule+0x3d/0x90
[ 491.177446] wdm_flush+0x85/0x100 [cdc_wdm]
[ 491.177451] ? wake_atomic_t_function+0x60/0x60
[ 491.177459] filp_close+0x2f/0x80
[ 491.177466] __close_fd+0x8f/0xb0
[ 491.177471] SyS_close+0x23/0x50
[ 491.177477] entry_SYSCALL_64_fastpath+0x1a/0xa9
[ 491.177480] RIP: 0033:0x7f8424bc8aed
[ 491.177483] RSP: 002b:00007ffd24fde9c0 EFLAGS: 00000293 ORIG_RAX:
0000000000000003
[ 491.177487] RAX: ffffffffffffffda RBX: 00000000024a9b10 RCX:
00007f8424bc8aed
[ 491.177490] RDX: 0000000000000000 RSI: 0000000000000000 RDI:
0000000000000007
[ 491.177492] RBP: 0000000000000001 R08: 00000000024bfc40 R09:
0000000000000000
[ 491.177495] R10: 000000000000069b R11: 0000000000000293 R12:
00000000024a9b10
[ 491.177497] R13: 00000000ffffffff R14: 00007f8424ee85f0 R15:
0000000000000004
At this point, qmi-proxy doesn't respond to signals and so I can't quit it
- the only way is to unplug the modem from the USB port, after which
qmi-proxy exits kernel code and can respond to signals again.
So, this does seem to confirm your theory that it is a driver/kernel bug,
as I've witnessed the same thing happening on completely different
hardware/architectures.
I then ran the experiment again, but this time using a live USB of
archlinux-2017.06.01-x86_64, which runs kernel 4.11. With this kernel I
didn't have any problem starting the network as shown below:
root at archiso ~ # qmi-network /dev/cdc-wdm1 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-wdm1 --wda-get-data-format
--device-open-proxy'...
error: couldn't create client for the 'wda' service: QMI protocol error
(3): 'Internal'
Device link layer protocol not retrieved: WDA unsupported
Starting network with 'qmicli -d /dev/cdc-wdm1
--wds-start-network=apn='internet' --client-no-release-cid
--device-open-proxy'...
Saving state at /tmp/qmi-network-state-cdc-wdm1... (CID: 19)
Saving state at /tmp/qmi-network-state-cdc-wdm1... (PDH: 2275398688)
Network started successfully
Meanwhile the log from qmi-proxy was as follows:
root at archiso ~ # /usr/lib/libqmi/qmi-proxy --no-exit --verbose
[07 Jun 2017, 17:49:38] [Debug] creating UNIX socket service...
[07 Jun 2017, 17:49:38] [Debug] starting UNIX socket service at
'qmi-proxy'...
[07 Jun 2017, 17:51:52] [Debug] Client (6) connection open...
[07 Jun 2017, 17:51:52] [Debug] valid request to open connection to QMI
device file: /dev/cdc-wdm1
[07 Jun 2017, 17:51:52] [Debug] [/dev/cdc-wdm1] Opening device with flags
'none'...
[07 Jun 2017, 17:51:52] [Debug] [/dev/cdc-wdm1] loaded driver of cdc-wdm
port: qmi_wwan
[07 Jun 2017, 17:51:52] [Debug] connection to QMI device '/dev/cdc-wdm1'
established
[07 Jun 2017, 17:51:52] [Debug] Client (6) TX: 19 bytes
[07 Jun 2017, 17:51:52] [Debug] [/dev/cdc-wdm1] 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, 17:51:52] [Debug] [/dev/cdc-wdm1] 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, 17:51:52] [Debug] [/dev/cdc-wdm1] received message...
<<<<<< RAW:
<<<<<< length = 12
<<<<<< data = 01:0B:00:80:00:00:02:00:27:00:00:00
[07 Jun 2017, 17:51:52] [Debug] [/dev/cdc-wdm1] received generic indication
(translated)...
<<<<<< QMUX:
<<<<<< length = 11
<<<<<< flags = 0x80
<<<<<< service = "ctl"
<<<<<< client = 0
<<<<<< QMI:
<<<<<< flags = "indication"
<<<<<< transaction = 0
<<<<<< tlv_length = 0
<<<<<< message = "Sync" (0x0027)
[07 Jun 2017, 17:51:52] [Debug] [/dev/cdc-wdm1] Sync indication received
[07 Jun 2017, 17:51:52] [Debug] [/dev/cdc-wdm1] received message...
<<<<<< RAW:
<<<<<< length = 19
<<<<<< data = 01:12:00:80:00:00:01:01:22:00:07:00:02:04:00:01:00:03:00
[07 Jun 2017, 17:51:52] [Debug] [/dev/cdc-wdm1] received generic response
(translated)...
<<<<<< QMUX:
<<<<<< length = 18
<<<<<< flags = 0x80
<<<<<< service = "ctl"
<<<<<< client = 0
<<<<<< QMI:
<<<<<< flags = "response"
<<<<<< transaction = 1
<<<<<< tlv_length = 7
<<<<<< message = "Allocate CID" (0x0022)
<<<<<< TLV:
<<<<<< type = "Result" (0x02)
<<<<<< length = 4
<<<<<< value = 01:00:03:00
<<<<<< translated = FAILURE: Internal
[07 Jun 2017, 17:51:52] [Debug] Client (6) TX: 19 bytes
[07 Jun 2017, 17:51:52] [Debug] Client (6) connection closed...
[07 Jun 2017, 17:51:52] [Debug] closing device '/dev/cdc-wdm1': no longer
used
[07 Jun 2017, 17:51:52] [Debug] Client (6) connection open...
[07 Jun 2017, 17:51:52] [Debug] valid request to open connection to QMI
device file: /dev/cdc-wdm1
[07 Jun 2017, 17:51:52] [Debug] [/dev/cdc-wdm1] Opening device with flags
'none'...
[07 Jun 2017, 17:51:52] [Debug] [/dev/cdc-wdm1] loaded driver of cdc-wdm
port: qmi_wwan
[07 Jun 2017, 17:51:52] [Debug] connection to QMI device '/dev/cdc-wdm1'
established
[07 Jun 2017, 17:51:52] [Debug] Client (6) TX: 19 bytes
[07 Jun 2017, 17:51:52] [Debug] [/dev/cdc-wdm1] sent message...
<<<<<< RAW:
<<<<<< length = 16
<<<<<< data = 01:0F:00:00:00:00:00:01:22:00:04:00:01:01:00:01
[07 Jun 2017, 17:51:52] [Debug] [/dev/cdc-wdm1] 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 = 01
<<<<<< translated = wds
[07 Jun 2017, 17:51:52] [Debug] [/dev/cdc-wdm1] received message...
<<<<<< RAW:
<<<<<< length = 24
<<<<<< data =
01:17:00:80:00:00:01:01:22:00:0C:00:02:04:00:00:00:00:00:01:02:00:01:13
[07 Jun 2017, 17:51:52] [Debug] [/dev/cdc-wdm1] received generic response
(translated)...
<<<<<< QMUX:
<<<<<< length = 23
<<<<<< flags = 0x80
<<<<<< service = "ctl"
<<<<<< client = 0
<<<<<< QMI:
<<<<<< flags = "response"
<<<<<< transaction = 1
<<<<<< tlv_length = 12
<<<<<< message = "Allocate CID" (0x0022)
<<<<<< TLV:
<<<<<< type = "Result" (0x02)
<<<<<< length = 4
<<<<<< value = 00:00:00:00
<<<<<< translated = SUCCESS
<<<<<< TLV:
<<<<<< type = "Allocation Info" (0x01)
<<<<<< length = 2
<<<<<< value = 01:13
<<<<<< translated = [ service = 'wds' cid = '19' ]
[07 Jun 2017, 17:51:52] [Debug] QMI client tracked [/dev/cdc-wdm1,wds,19]
[07 Jun 2017, 17:51:52] [Debug] Client (6) TX: 24 bytes
[07 Jun 2017, 17:51:52] [Debug] [/dev/cdc-wdm1] sent message...
<<<<<< RAW:
<<<<<< length = 28
<<<<<< data =
01:1B:00:00:01:13:00:01:00:20:00:0F:00:19:01:00:08:14:08:00:69:6E:74:65:72:6E:65:74
[07 Jun 2017, 17:51:52] [Debug] [/dev/cdc-wdm1] sent generic request
(translated)...
<<<<<< QMUX:
<<<<<< length = 27
<<<<<< flags = 0x00
<<<<<< service = "wds"
<<<<<< client = 19
<<<<<< QMI:
<<<<<< flags = "none"
<<<<<< transaction = 1
<<<<<< tlv_length = 15
<<<<<< message = "Start Network" (0x0020)
<<<<<< TLV:
<<<<<< type = "IP Family Preference" (0x19)
<<<<<< length = 1
<<<<<< value = 08
<<<<<< translated = unspecified
<<<<<< TLV:
<<<<<< type = "APN" (0x14)
<<<<<< length = 8
<<<<<< value = 69:6E:74:65:72:6E:65:74
<<<<<< translated = internet
[07 Jun 2017, 17:51:52] [Debug] [/dev/cdc-wdm1] received message...
<<<<<< RAW:
<<<<<< length = 27
<<<<<< data =
01:1A:00:80:01:13:02:01:00:20:00:0E:00:02:04:00:00:00:00:00:01:04:00:20:D4:9F:87
[07 Jun 2017, 17:51:52] [Debug] [/dev/cdc-wdm1] received generic response
(translated)...
<<<<<< QMUX:
<<<<<< length = 26
<<<<<< flags = 0x80
<<<<<< service = "wds"
<<<<<< client = 19
<<<<<< QMI:
<<<<<< flags = "response"
<<<<<< transaction = 1
<<<<<< tlv_length = 14
<<<<<< message = "Start Network" (0x0020)
<<<<<< TLV:
<<<<<< type = "Result" (0x02)
<<<<<< length = 4
<<<<<< value = 00:00:00:00
<<<<<< translated = SUCCESS
<<<<<< TLV:
<<<<<< type = "Packet Data Handle" (0x01)
<<<<<< length = 4
<<<<<< value = 20:D4:9F:87
<<<<<< translated = 2275398688
[07 Jun 2017, 17:51:52] [Debug] Client (6) TX: 27 bytes
[07 Jun 2017, 17:51:52] [Debug] Client (6) connection closed...
[07 Jun 2017, 17:51:52] [Debug] closing device '/dev/cdc-wdm1': no longer
used
However, I was unable to run dhcp on the network interface and thus
ultimately, wasn't able to connect:
root at archiso ~ # dhcpcd $(qmicli -d /dev/cdc-wdm1 -w)
:(
DUID 00:01:00:01:20:ca:f5:4f:2c:27:d7:7f:1a:83
wwp0s29u1u1i4: IAID 3a:7c:a8:5b
wwp0s29u1u1i4: soliciting a DHCP lease
wwp0s29u1u1i4: soliciting an IPv6 router
wwp0s29u1u1i4: no IPv6 Routers available
timed out
dhcpcd exited
So unfortunately, either way I'm still unable to use the modem to connect
to the internet using libqmi.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.freedesktop.org/archives/libqmi-devel/attachments/20170613/30714e43/attachment-0001.html>
More information about the libqmi-devel
mailing list