<div dir="ltr"><div class="gmail_extra"><div class="gmail_quote"><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><div class="gmail-m_-743853569351062439HOEnZb"><div class="gmail-m_-743853569351062439h5"><span style="color:rgb(34,34,34)">This looks like usb_submit_urb() accepts the control request but never</span><br></div></div>
calls the callback. I don't know how that can happen, but I do believe<br>
it is an error on some lower layer than libqmi/cdc-wdm. I am unsure<br>
about current status, but the Raspberry Pi used have a really buggy USB<br>
controller/driver. Is there any way you can test this modem with some<br>
other hardware?</blockquote><div><br></div><div>I've just tried this on a regular laptop running a live USB image of ArchLinux (archlinux-2017.04.01-x86_64.<wbr>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:</div><div><br></div><div><div>root@archiso ~ # qmi-network /dev/cdc-wdm1 start</div><div><br></div><div>Loading profile at /etc/qmi-network.conf...</div><div> APN: internet</div><div> APN user: unset</div><div> APN password: unset</div><div> qmi-proxy: yes</div><div>Checking data format with 'qmicli -d /dev/cdc-wdm1 --wda-get-data-format --device-open-proxy'...</div><div>error: couldn't create client for the 'wda' service: CID allocation failed in the CTL client: Transaction timed out</div><div>Device link layer protocol not retrieved: WDA unsupported</div><div>Starting network with 'qmicli -d /dev/cdc-wdm1 --wds-start-network=apn='internet' --client-no-release-cid --device-open-proxy'...</div><div>error: couldn't open the QmiDevice: Transaction timed out</div><div>error: network start failed, client not allocated</div><div># </div></div><div><br></div><div>qmi-proxy in the meantime shows the following:</div><div><br></div><div><div>root@archiso ~ # /usr/lib/libqmi/qmi-proxy --no-exit --verbose</div><div>[07 Jun 2017, 16:27:39] [Debug] creating UNIX socket service...</div><div>[07 Jun 2017, 16:27:39] [Debug] starting UNIX socket service at 'qmi-proxy'...</div><div>[07 Jun 2017, 16:28:54] [Debug] Client (6) connection open...</div><div>[07 Jun 2017, 16:28:54] [Debug] valid request to open connection to QMI device file: /dev/cdc-wdm1</div><div>[07 Jun 2017, 16:28:54] [Debug] [/dev/cdc-wdm1] Opening device with flags 'none'...</div><div>[07 Jun 2017, 16:28:54] [Debug] [/dev/cdc-wdm1] loaded driver of cdc-wdm port: qmi_wwan</div><div>[07 Jun 2017, 16:28:54] [Debug] connection to QMI device '/dev/cdc-wdm1' established</div><div>[07 Jun 2017, 16:28:54] [Debug] Client (6) TX: 19 bytes</div><div>[07 Jun 2017, 16:28:54] [Debug] [/dev/cdc-wdm1] sent message...</div><div><<<<<< RAW:</div><div><<<<<< length = 16</div><div><<<<<< data = 01:0F:00:00:00:00:00:01:22:00:04:00:01:01:00:1A</div><div><br></div><div>[07 Jun 2017, 16:28:54] [Debug] [/dev/cdc-wdm1] sent generic request (translated)...</div><div><<<<<< QMUX:</div><div><<<<<< length = 15</div><div><<<<<< flags = 0x00</div><div><<<<<< service = "ctl"</div><div><<<<<< client = 0</div><div><<<<<< QMI:</div><div><<<<<< flags = "none"</div><div><<<<<< transaction = 1</div><div><<<<<< tlv_length = 4</div><div><<<<<< message = "Allocate CID" (0x0022)</div><div><<<<<< TLV:</div><div><<<<<< type = "Service" (0x01)</div><div><<<<<< length = 1</div><div><<<<<< value = 1A</div><div><<<<<< translated = wda</div><div><br></div><div>[07 Jun 2017, 16:29:04] [Debug] Client (6) connection closed...</div><div>[07 Jun 2017, 16:29:04] [Debug] closing device '/dev/cdc-wdm1': no longer used</div></div><div><br></div><div><br></div><div>Once again it freezes in kernel code, and I get the following in dmesg:</div><div><br></div><div><div>[ 491.177149] INFO: task qmi-proxy:978 blocked for more than 120 seconds.</div><div>[ 491.177256] Not tainted 4.10.6-1-ARCH #1</div><div>[ 491.177311] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.</div><div>[ 491.177400] qmi-proxy D 0 978 969 0x00000000</div><div>[ 491.177407] Call Trace:</div><div>[ 491.177424] __schedule+0x22f/0x700</div><div>[ 491.177431] ? __vfs_write+0x37/0x140</div><div>[ 491.177436] schedule+0x3d/0x90</div><div>[ 491.177446] wdm_flush+0x85/0x100 [cdc_wdm]</div><div>[ 491.177451] ? wake_atomic_t_function+0x60/0x60</div><div>[ 491.177459] filp_close+0x2f/0x80</div><div>[ 491.177466] __close_fd+0x8f/0xb0</div><div>[ 491.177471] SyS_close+0x23/0x50</div><div>[ 491.177477] entry_SYSCALL_64_fastpath+0x1a/0xa9</div><div>[ 491.177480] RIP: 0033:0x7f8424bc8aed</div><div>[ 491.177483] RSP: 002b:00007ffd24fde9c0 EFLAGS: 00000293 ORIG_RAX: 0000000000000003</div><div>[ 491.177487] RAX: ffffffffffffffda RBX: 00000000024a9b10 RCX: 00007f8424bc8aed</div><div>[ 491.177490] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000007</div><div>[ 491.177492] RBP: 0000000000000001 R08: 00000000024bfc40 R09: 0000000000000000</div><div>[ 491.177495] R10: 000000000000069b R11: 0000000000000293 R12: 00000000024a9b10</div><div>[ 491.177497] R13: 00000000ffffffff R14: 00007f8424ee85f0 R15: 0000000000000004</div></div><div><br></div><div><br></div><div>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.</div><div><br></div><div>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.</div><div><br></div><div>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:</div><div><br></div><div><div>root@archiso ~ # qmi-network /dev/cdc-wdm1 start</div><div>Loading profile at /etc/qmi-network.conf...</div><div> APN: internet</div><div> APN user: unset</div><div> APN password: unset</div><div> qmi-proxy: yes</div><div>Checking data format with 'qmicli -d /dev/cdc-wdm1 --wda-get-data-format --device-open-proxy'...</div><div>error: couldn't create client for the 'wda' service: QMI protocol error (3): 'Internal'</div><div>Device link layer protocol not retrieved: WDA unsupported</div><div>Starting network with 'qmicli -d /dev/cdc-wdm1 --wds-start-network=apn='internet' --client-no-release-cid --device-open-proxy'...</div><div>Saving state at /tmp/qmi-network-state-cdc-wdm1... (CID: 19)</div><div>Saving state at /tmp/qmi-network-state-cdc-wdm1... (PDH: 2275398688)</div><div>Network started successfully</div></div><div><br></div><div>Meanwhile the log from qmi-proxy was as follows:</div><div><br></div><div><div>root@archiso ~ # /usr/lib/libqmi/qmi-proxy --no-exit --verbose</div><div>[07 Jun 2017, 17:49:38] [Debug] creating UNIX socket service...</div><div>[07 Jun 2017, 17:49:38] [Debug] starting UNIX socket service at 'qmi-proxy'...</div><div>[07 Jun 2017, 17:51:52] [Debug] Client (6) connection open...</div><div>[07 Jun 2017, 17:51:52] [Debug] valid request to open connection to QMI device file: /dev/cdc-wdm1</div><div>[07 Jun 2017, 17:51:52] [Debug] [/dev/cdc-wdm1] Opening device with flags 'none'...</div><div>[07 Jun 2017, 17:51:52] [Debug] [/dev/cdc-wdm1] loaded driver of cdc-wdm port: qmi_wwan</div><div>[07 Jun 2017, 17:51:52] [Debug] connection to QMI device '/dev/cdc-wdm1' established</div><div>[07 Jun 2017, 17:51:52] [Debug] Client (6) TX: 19 bytes</div><div>[07 Jun 2017, 17:51:52] [Debug] [/dev/cdc-wdm1] sent message...</div><div><<<<<< RAW:</div><div><<<<<< length = 16</div><div><<<<<< data = 01:0F:00:00:00:00:00:01:22:00:04:00:01:01:00:1A</div><div><br></div><div>[07 Jun 2017, 17:51:52] [Debug] [/dev/cdc-wdm1] sent generic request (translated)...</div><div><<<<<< QMUX:</div><div><<<<<< length = 15</div><div><<<<<< flags = 0x00</div><div><<<<<< service = "ctl"</div><div><<<<<< client = 0</div><div><<<<<< QMI:</div><div><<<<<< flags = "none"</div><div><<<<<< transaction = 1</div><div><<<<<< tlv_length = 4</div><div><<<<<< message = "Allocate CID" (0x0022)</div><div><<<<<< TLV:</div><div><<<<<< type = "Service" (0x01)</div><div><<<<<< length = 1</div><div><<<<<< value = 1A</div><div><<<<<< translated = wda</div><div><br></div><div>[07 Jun 2017, 17:51:52] [Debug] [/dev/cdc-wdm1] received message...</div><div><<<<<< RAW:</div><div><<<<<< length = 12</div><div><<<<<< data = 01:0B:00:80:00:00:02:00:27:00:00:00</div><div><br></div><div>[07 Jun 2017, 17:51:52] [Debug] [/dev/cdc-wdm1] received generic indication (translated)...</div><div><<<<<< QMUX:</div><div><<<<<< length = 11</div><div><<<<<< flags = 0x80</div><div><<<<<< service = "ctl"</div><div><<<<<< client = 0</div><div><<<<<< QMI:</div><div><<<<<< flags = "indication"</div><div><<<<<< transaction = 0</div><div><<<<<< tlv_length = 0</div><div><<<<<< message = "Sync" (0x0027)</div><div><br></div><div>[07 Jun 2017, 17:51:52] [Debug] [/dev/cdc-wdm1] Sync indication received</div><div>[07 Jun 2017, 17:51:52] [Debug] [/dev/cdc-wdm1] received message...</div><div><<<<<< RAW:</div><div><<<<<< length = 19</div><div><<<<<< data = 01:12:00:80:00:00:01:01:22:00:07:00:02:04:00:01:00:03:00</div><div><br></div><div>[07 Jun 2017, 17:51:52] [Debug] [/dev/cdc-wdm1] received generic response (translated)...</div><div><<<<<< QMUX:</div><div><<<<<< length = 18</div><div><<<<<< flags = 0x80</div><div><<<<<< service = "ctl"</div><div><<<<<< client = 0</div><div><<<<<< QMI:</div><div><<<<<< flags = "response"</div><div><<<<<< transaction = 1</div><div><<<<<< tlv_length = 7</div><div><<<<<< message = "Allocate CID" (0x0022)</div><div><<<<<< TLV:</div><div><<<<<< type = "Result" (0x02)</div><div><<<<<< length = 4</div><div><<<<<< value = 01:00:03:00</div><div><<<<<< translated = FAILURE: Internal</div><div><br></div><div>[07 Jun 2017, 17:51:52] [Debug] Client (6) TX: 19 bytes</div><div>[07 Jun 2017, 17:51:52] [Debug] Client (6) connection closed...</div><div>[07 Jun 2017, 17:51:52] [Debug] closing device '/dev/cdc-wdm1': no longer used</div><div>[07 Jun 2017, 17:51:52] [Debug] Client (6) connection open...</div><div>[07 Jun 2017, 17:51:52] [Debug] valid request to open connection to QMI device file: /dev/cdc-wdm1</div><div>[07 Jun 2017, 17:51:52] [Debug] [/dev/cdc-wdm1] Opening device with flags 'none'...</div><div>[07 Jun 2017, 17:51:52] [Debug] [/dev/cdc-wdm1] loaded driver of cdc-wdm port: qmi_wwan</div><div>[07 Jun 2017, 17:51:52] [Debug] connection to QMI device '/dev/cdc-wdm1' established</div><div>[07 Jun 2017, 17:51:52] [Debug] Client (6) TX: 19 bytes</div><div>[07 Jun 2017, 17:51:52] [Debug] [/dev/cdc-wdm1] sent message...</div><div><<<<<< RAW:</div><div><<<<<< length = 16</div><div><<<<<< data = 01:0F:00:00:00:00:00:01:22:00:04:00:01:01:00:01</div><div><br></div><div>[07 Jun 2017, 17:51:52] [Debug] [/dev/cdc-wdm1] sent generic request (translated)...</div><div><<<<<< QMUX:</div><div><<<<<< length = 15</div><div><<<<<< flags = 0x00</div><div><<<<<< service = "ctl"</div><div><<<<<< client = 0</div><div><<<<<< QMI:</div><div><<<<<< flags = "none"</div><div><<<<<< transaction = 1</div><div><<<<<< tlv_length = 4</div><div><<<<<< message = "Allocate CID" (0x0022)</div><div><<<<<< TLV:</div><div><<<<<< type = "Service" (0x01)</div><div><<<<<< length = 1</div><div><<<<<< value = 01</div><div><<<<<< translated = wds</div><div><br></div><div>[07 Jun 2017, 17:51:52] [Debug] [/dev/cdc-wdm1] received message...</div><div><<<<<< RAW:</div><div><<<<<< length = 24</div><div><<<<<< 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</div><div><br></div><div>[07 Jun 2017, 17:51:52] [Debug] [/dev/cdc-wdm1] received generic response (translated)...</div><div><<<<<< QMUX:</div><div><<<<<< length = 23</div><div><<<<<< flags = 0x80</div><div><<<<<< service = "ctl"</div><div><<<<<< client = 0</div><div><<<<<< QMI:</div><div><<<<<< flags = "response"</div><div><<<<<< transaction = 1</div><div><<<<<< tlv_length = 12</div><div><<<<<< message = "Allocate CID" (0x0022)</div><div><<<<<< TLV:</div><div><<<<<< type = "Result" (0x02)</div><div><<<<<< length = 4</div><div><<<<<< value = 00:00:00:00</div><div><<<<<< translated = SUCCESS</div><div><<<<<< TLV:</div><div><<<<<< type = "Allocation Info" (0x01)</div><div><<<<<< length = 2</div><div><<<<<< value = 01:13</div><div><<<<<< translated = [ service = 'wds' cid = '19' ]</div><div><br></div><div>[07 Jun 2017, 17:51:52] [Debug] QMI client tracked [/dev/cdc-wdm1,wds,19]</div><div>[07 Jun 2017, 17:51:52] [Debug] Client (6) TX: 24 bytes</div><div>[07 Jun 2017, 17:51:52] [Debug] [/dev/cdc-wdm1] sent message...</div><div><<<<<< RAW:</div><div><<<<<< length = 28</div><div><<<<<< 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</div><div><br></div><div>[07 Jun 2017, 17:51:52] [Debug] [/dev/cdc-wdm1] sent generic request (translated)...</div><div><<<<<< QMUX:</div><div><<<<<< length = 27</div><div><<<<<< flags = 0x00</div><div><<<<<< service = "wds"</div><div><<<<<< client = 19</div><div><<<<<< QMI:</div><div><<<<<< flags = "none"</div><div><<<<<< transaction = 1</div><div><<<<<< tlv_length = 15</div><div><<<<<< message = "Start Network" (0x0020)</div><div><<<<<< TLV:</div><div><<<<<< type = "IP Family Preference" (0x19)</div><div><<<<<< length = 1</div><div><<<<<< value = 08</div><div><<<<<< translated = unspecified</div><div><<<<<< TLV:</div><div><<<<<< type = "APN" (0x14)</div><div><<<<<< length = 8</div><div><<<<<< value = 69:6E:74:65:72:6E:65:74</div><div><<<<<< translated = internet</div><div><br></div><div>[07 Jun 2017, 17:51:52] [Debug] [/dev/cdc-wdm1] received message...</div><div><<<<<< RAW:</div><div><<<<<< length = 27</div><div><<<<<< 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</div><div><br></div><div>[07 Jun 2017, 17:51:52] [Debug] [/dev/cdc-wdm1] received generic response (translated)...</div><div><<<<<< QMUX:</div><div><<<<<< length = 26</div><div><<<<<< flags = 0x80</div><div><<<<<< service = "wds"</div><div><<<<<< client = 19</div><div><<<<<< QMI:</div><div><<<<<< flags = "response"</div><div><<<<<< transaction = 1</div><div><<<<<< tlv_length = 14</div><div><<<<<< message = "Start Network" (0x0020)</div><div><<<<<< TLV:</div><div><<<<<< type = "Result" (0x02)</div><div><<<<<< length = 4</div><div><<<<<< value = 00:00:00:00</div><div><<<<<< translated = SUCCESS</div><div><<<<<< TLV:</div><div><<<<<< type = "Packet Data Handle" (0x01)</div><div><<<<<< length = 4</div><div><<<<<< value = 20:D4:9F:87</div><div><<<<<< translated = 2275398688</div><div><br></div><div>[07 Jun 2017, 17:51:52] [Debug] Client (6) TX: 27 bytes</div><div>[07 Jun 2017, 17:51:52] [Debug] Client (6) connection closed...</div><div>[07 Jun 2017, 17:51:52] [Debug] closing device '/dev/cdc-wdm1': no longer used</div></div><div><br></div><div>However, I was unable to run dhcp on the network interface and thus ultimately, wasn't able to connect:<br></div><div><br></div><div><div>root@archiso ~ # dhcpcd $(qmicli -d /dev/cdc-wdm1 -w) :(</div><div>DUID 00:01:00:01:20:ca:f5:4f:2c:27:d7:7f:1a:83</div><div>wwp0s29u1u1i4: IAID 3a:7c:a8:5b</div><div>wwp0s29u1u1i4: soliciting a DHCP lease</div><div>wwp0s29u1u1i4: soliciting an IPv6 router</div><div>wwp0s29u1u1i4: no IPv6 Routers available</div><div>timed out</div><div>dhcpcd exited</div></div><div><br></div><div><br></div><div>So unfortunately, either way I'm still unable to use the modem to connect to the internet using libqmi.</div></div></div></div>