Sierra MC7354

[szlin]

2014-03-11 18:01 GMT+08:00 Bjørn Mork <bjorn at mork.no>:
> Bjørn Mork <bjorn at mork.no> writes:
>> szlin <lin.sunze at gmail.com> writes:
>>
>>>>> #qmicli -d /dev/cdc-wdm0 --get-service-version-info
>>>>> [   79.644073] qmi_wwan 1-1:1.8: nonzero urb status received: -EPIPE
>>>>> [10 Mar 2014, 20:22:03] -Warning ** Error reading from istream: Error
>>>>> reading from file descriptor: Input/output error
>>>>>
>>>>> error: couldn't get service version info: Transaction timed out
>>>>
>>>> Hmm, wonder if that isn't a symptom of a firmware crash maybe?
>>>
>>> After seeing error message,  the system is frozen without any kernel
>>> panic/oops msg.
>>> (ping is available but other service such like ssh is unavailable)
>>
>> OK, that sounds like we end up in a busy loop somewhere. Are you testing
>> this on a single core system?
>>
>>> I'll keep trace on communication protocol between module and qmi_wwan.
>>
>> I'll try to figure out how we can end up looping at this point. It does
>> look like it is related to the status endpoint handling, so it is
>> probably in the cdc-wdm driver somewhere.  We have changed that driver
>> somewhat for v3.13, but I don't think any of the changes would fix a bug
>> like this. It would still be useful to know if you can recreate the
>> problem on v3.13.2 or later, if that is something you easily can do.
>
> Hmm, looking at the code involved I don't think we have ever changed the
> behaviour for EPIPE here.  We're reading from the control endpoint, so
> there isn't really much we can do about it...  According to
>
>
https://www.mail-archive.com/linux-usb-devel@lists.sourceforge.net/msg36748.html
>
> the cause is either a transmission error or that the device didn't
> understand the command. We never change the command - it' the same read
> URB all the time - so I don't see how the device could suddenly not
> understand it. Unless something scribbles on the memory, in which case
> you are in bigger trouble.
>
> So I guess we are looking at a transmission error of some sort.
>
> We should of course deal with that without hanging anything. The output
> from qmicli shows that the read terminates with EIO as expected in this
> case.  The question is where it goes wrong from there.  I don't really
> know.  It looks like we might end up never reading from the device
> again, unless we receive another notification, but that should really be
> fine in a sense.  The device or controller has failed and we don't know
> how to get it into a workable state again.  But where does it hang?
>
> I have no other ideas than trying to sprinkle a few debug printk's all
> around cdc-wdm.c.  At least enable the debug output that's already
> there.  If you have dynamic debugging, you can do:
>
>   mount -t debugfs none /sys/kernel/debug
>   echo 'file cdc-wdm.c +fp' > /sys/kernel/debug/dynamic_debug/control
>
> You should then see at least one "zero length - clearing WDM_READ"
> debug message after the error.  But since your system fails at this
> point, you might want to add more debug messages around the in callback
> and read functions first.
>

I did some experiments according to your suggestion.

*First time*:
I type "qmicli -d /dev/cdc-wdm0 --nas-get-system-info" I got the following
message.

drivers/net/usb/usbnet.c:596 [usbnet]unlink_urbs - "unlink urb err, %d\012"
drivers/net/usb/usbnet.c:639 [usbnet]usbnet_terminate_urbs - "waited for %d
urb completions\012"
drivers/net/usb/usbnet.c:518 [usbnet]intr_complete - "intr shutdown, code
%d\012"
drivers/net/usb/usbnet.c:525 [usbnet]intr_complete - "intr status %d\012"
drivers/net/usb/usbnet.c:1325 [usbnet]usbnet_probe - "blacklisted by %s\012"
drivers/net/usb/usbnet.c:215 [usbnet]init_status - "status ep%din, %d bytes
period %d\012"
drivers/net/usb/usbnet.c:730 [usbnet]usbnet_open - "can't open; %d\012"
drivers/net/usb/usbnet.c:171 [usbnet]usbnet_get_ethernet_addr - "bad MAC
string %d fetch, %d\012"
drivers/net/usb/usbnet.c:544 [usbnet]usbnet_pause_rx - "paused rx queue
enabled\012"
drivers/net/usb/usbnet.c:315 [usbnet]usbnet_defer_kevent - "kevent %d
scheduled\012"
drivers/net/usb/usbnet.c:332 [usbnet]rx_submit - "no rx skb\012"
drivers/net/usb/usbnet.c:362 [usbnet]rx_submit - "device gone\012"
drivers/net/usb/usbnet.c:370 [usbnet]rx_submit - "rx submit, %d\012"
drivers/net/usb/usbnet.c:377 [usbnet]rx_submit - "rx: stopped\012"
drivers/net/usb/usbnet.c:979 [usbnet]kevent - "kevent done, flags =
0x%lx\012"
drivers/net/usb/usbnet.c:438 [usbnet]rx_complete - "rx length %d\012"
drivers/net/usb/usbnet.c:456 [usbnet]rx_complete - "rx shutdown, code
%d\012"
drivers/net/usb/usbnet.c:470 [usbnet]rx_complete - "rx throttle %d\012"
drivers/net/usb/usbnet.c:486 [usbnet]rx_complete - "rx status %d\012"
drivers/net/usb/usbnet.c:500 [usbnet]rx_complete - "no read resubmitted\012"
drivers/net/usb/usbnet.c:1069 [usbnet]usbnet_start_xmit - "can't tx_fixup
skb\012"
drivers/net/usb/usbnet.c:1080 [usbnet]usbnet_start_xmit - "no urb\012"
drivers/net/usb/usbnet.c:1128 [usbnet]usbnet_start_xmit - "Delaying
transmission for resumption\012"
drivers/net/usb/usbnet.c:1142 [usbnet]usbnet_start_xmit - "tx: submit urb
err %d\012"
drivers/net/usb/usbnet.c:1153 [usbnet]usbnet_start_xmit - "drop, code
%d\012"
drivers/net/usb/usbnet.c:1162 [usbnet]usbnet_start_xmit - "> tx, len %d,
type 0x%x\012"
drivers/net/usb/usbnet.c:1017 [usbnet]tx_complete - "tx throttle %d\012"
drivers/net/usb/usbnet.c:1023 [usbnet]tx_complete - "tx err %d\012"
drivers/net/usb/usbnet.c:239 [usbnet]usbnet_skb_return - "< rx, len %zu,
type 0x%x\012"
drivers/net/usb/usbnet.c:248 [usbnet]usbnet_skb_return - "netif_rx status
%d\012"
drivers/net/usb/usbnet.c:411 [usbnet]rx_process - "drop\012"
drivers/net/usb/usbnet.c:1193 [usbnet]usbnet_bh - "bogus skb state %d\012"
drivers/net/usb/usbnet.c:1227 [usbnet]usbnet_bh - "rxqlen %d --> %d\012"
drivers/net/usb/usbnet.c:563 [usbnet]usbnet_resume_rx - "paused rx queue
disabled, %d skbs requeued\012"
drivers/usb/class/cdc-wdm.c:938 [cdc_wdm]wdm_suspend - "wdm%d_suspend\012"
drivers/usb/class/cdc-wdm.c:424 [cdc_wdm]wdm_write - "Tx URB has been
submitted index=%d"
drivers/usb/class/cdc-wdm.c:928 [cdc_wdm]wdm_disconnect - "%s: %d open
files - postponing cleanup\012"
drivers/usb/class/cdc-wdm.c:637 [cdc_wdm]wdm_release - "wdm_release:
cleanup"
drivers/usb/class/cdc-wdm.c:642 [cdc_wdm]wdm_release - "cdc_wdm %s: device
gone - cleaning up\012"
drivers/usb/class/cdc-wdm.c:836 [cdc_wdm]wdm_probe - "Finding maximum
buffer length: %d"
drivers/usb/class/cdc-wdm.c:178 [cdc_wdm]wdm_in_callback - "nonzero urb
status received: -ENOENT"
drivers/usb/class/cdc-wdm.c:182 [cdc_wdm]wdm_in_callback - "nonzero urb
status received: -ECONNRESET"
drivers/usb/class/cdc-wdm.c:186 [cdc_wdm]wdm_in_callback - "nonzero urb
status received: -ESHUTDOWN"
drivers/usb/class/cdc-wdm.c:247 [cdc_wdm]wdm_int_callback -
"NOTIFY_RESPONSE_AVAILABLE received: index %d len %d"
drivers/usb/class/cdc-wdm.c:254 [cdc_wdm]wdm_int_callback -
"NOTIFY_NETWORK_CONNECTION %s network"
drivers/usb/class/cdc-wdm.c:271 [cdc_wdm]wdm_int_callback - "%s:
usb_submit_urb %d"
drivers/usb/class/cdc-wdm.c:988 [cdc_wdm]wdm_resume - "wdm%d_resume\012"
drivers/net/usb/qmi_wwan.c:183 [qmi_wwan]qmi_wwan_manage_power - "%s()
pmcount=%d, on=%d\012"
drivers/net/usb/qmi_wwan.c:85 [qmi_wwan]qmi_wwan_bind - "guessing
\042control\042 => %s, \042data\042 => this\012"
drivers/net/usb/qmi_wwan.c:99 [qmi_wwan]qmi_wwan_bind - "extra CDC
header\012"
drivers/net/usb/qmi_wwan.c:103 [qmi_wwan]qmi_wwan_bind - "CDC header len
%u\012"
drivers/net/usb/qmi_wwan.c:109 [qmi_wwan]qmi_wwan_bind - "extra CDC
union\012"
drivers/net/usb/qmi_wwan.c:113 [qmi_wwan]qmi_wwan_bind - "CDC union len
%u\012"
drivers/net/usb/qmi_wwan.c:120 [qmi_wwan]qmi_wwan_bind - "extra CDC
ether\012"
drivers/net/usb/qmi_wwan.c:124 [qmi_wwan]qmi_wwan_bind - "CDC ether len
%u\012"

*Second time*:
Type the same command again, the system is frozen!
I also added some debug messages into read function, the result shows it is
frozen when I got the read buffer.


I just got another sierra module - MC7304, which product id is the same as
the MC7354. Maybe I could do some experiments to clarify this issue.

>
> Bjørn
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freedesktop.org/archives/libqmi-devel/attachments/20140311/7024bca7/attachment-0001.html>