[ANN] ModemManager 1.2-rc1
Bjørn Mork
bjorn at mork.no
Thu Dec 19 05:57:54 PST 2013
Bjørn Mork <bjorn at mork.no> writes:
> Aleksander Morgado <aleksander at lanedo.com> writes:
>
>>> Strange things I observed: The modemmanager only works reliable with kernel
>>> 3.12.x.
>>> Under kernel 3.13rc3 / linux-next it gets timeouts via /dev/cdc-wdm0 with mbim
>>> and with qmi.
>>>
>>
>> I'm in 3.12 myself, didn't try with 3.13 yet. Bjørn may now more?
>
> I am trying out the 3.13-rc's, and when you mention it I might have seen
> problems like that. I've been ignoring them so far because I've been
> working on some other issue, and I forget what I'm doing unless I stick
> strictly to the task at hand...
>
> But I'll try to look into it if I encounter anything suspicious again.
> There is one nice cdc-wdm fix in 3.13, and as always: Good fixes have
> potentional for regressions ;-)
>
> If any of you encounter this cdc-wdm timeout: Try to get a usbmon
> capture of it. Even a capture started after the problem occured is
> better than nothing.
I just got one of these timeouts, and I think the logs confirms my worst
fears...
I enabled all debug messages in cdc-wdm and started a usbmon capture
nemi:/tmp# grep wdm /sys/kernel/debug/dynamic_debug/control
drivers/usb/class/cdc-wdm.c:1043 [cdc_wdm]wdm_resume =pf "wdm%d_resume\012"
drivers/usb/class/cdc-wdm.c:993 [cdc_wdm]wdm_suspend =pf "wdm%d_suspend\012"
drivers/usb/class/cdc-wdm.c:983 [cdc_wdm]wdm_disconnect =pf "%s: %d open files - postponing cleanup\012"
drivers/usb/class/cdc-wdm.c:667 [cdc_wdm]wdm_release =pf "wdm_release: cleanup"
drivers/usb/class/cdc-wdm.c:675 [cdc_wdm]wdm_release =pf "cdc_wdm %s: device gone - cleaning up\012"
drivers/usb/class/cdc-wdm.c:425 [cdc_wdm]wdm_write =pf "Tx URB has been submitted index=%d"
drivers/usb/class/cdc-wdm.c:505 [cdc_wdm]wdm_read =pf "%s: zero length - clearing WDM_READ\012"
drivers/usb/class/cdc-wdm.c:891 [cdc_wdm]wdm_probe =pf "Finding maximum buffer length: %d"
drivers/usb/class/cdc-wdm.c:170 [cdc_wdm]wdm_in_callback =pf "nonzero urb status received: -ENOENT"
drivers/usb/class/cdc-wdm.c:174 [cdc_wdm]wdm_in_callback =pf "nonzero urb status received: -ECONNRESET"
drivers/usb/class/cdc-wdm.c:178 [cdc_wdm]wdm_in_callback =pf "nonzero urb status received: -ESHUTDOWN"
drivers/usb/class/cdc-wdm.c:248 [cdc_wdm]wdm_int_callback =pf "NOTIFY_RESPONSE_AVAILABLE received: index %d len %d"
drivers/usb/class/cdc-wdm.c:255 [cdc_wdm]wdm_int_callback =pf "NOTIFY_NETWORK_CONNECTION %s network"
drivers/usb/class/cdc-wdm.c:259 [cdc_wdm]wdm_int_callback =pf "SPEED_CHANGE received (len %u)"
drivers/usb/class/cdc-wdm.c:276 [cdc_wdm]wdm_int_callback =pf "%s: usb_submit_urb %d"
Making MM send a MBIM command resulted in only these two messages:
[106916.387357] wdm_write: cdc_mbim 5-4:2.12: Tx URB has been submitted index=12
[106916.389431] wdm_int_callback: cdc_mbim 5-4:2.12: NOTIFY_RESPONSE_AVAILABLE received: index 12 len 0
Which also is confirmed by the usbmon trace below. Only one control out
and one interrupt in message:
No. Time HW src Source HW dst Destination Protocol Info
1 0.000000000 host 91.0 USB URB_CONTROL out
Frame 1: 172 bytes on wire (1376 bits), 172 bytes captured (1376 bits) on interface 0
Interface id: 0
Encapsulation type: USB packets with Linux header and padding (115)
Arrival Time: Dec 19, 2013 14:32:25.934688000 CET
[Time shift for this packet: 0.000000000 seconds]
Epoch Time: 1387459945.934688000 seconds
[Time delta from previous captured frame: 0.000000000 seconds]
[Time delta from previous displayed frame: 0.000000000 seconds]
[Time since reference or first frame: 0.000000000 seconds]
Frame Number: 1
Frame Length: 172 bytes (1376 bits)
Capture Length: 172 bytes (1376 bits)
[Frame is marked: False]
[Frame is ignored: False]
[Protocols in frame: usb]
USB URB
URB id: 0xffff8800b11a7200
URB type: URB_SUBMIT ('S')
URB transfer type: URB_CONTROL (0x02)
Endpoint: 0x00, Direction: OUT
0... .... = Direction: OUT (0)
.000 0000 = Endpoint value: 0
Device: 91
URB bus id: 5
Device setup request: relevant (0)
Data: present (0)
URB sec: 1387459945
URB usec: 934688
URB status: Operation now in progress (-EINPROGRESS) (-115)
URB length [bytes]: 108
Data length [bytes]: 108
[Response in: 2]
[bInterfaceClass: Unknown (0xffff)]
URB setup
bmRequestType: 0x21
0... .... = Direction: Host-to-device
.01. .... = Type: Class (0x01)
...0 0001 = Recipient: Interface (0x01)
bRequest: 0
wValue: 0x0000
wIndex: 12
wLength: 108
Leftover Capture Data: 030000006c0000002d0000000100000000000000a289cc33...
0000 00 72 1a b1 00 88 ff ff 53 02 00 5b 05 00 00 00 .r......S..[....
0010 69 f5 b2 52 00 00 00 00 20 43 0e 00 8d ff ff ff i..R.... C......
0020 6c 00 00 00 6c 00 00 00 21 00 00 00 0c 00 6c 00 l...l...!.....l.
0030 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
0040 03 00 00 00 6c 00 00 00 2d 00 00 00 01 00 00 00 ....l...-.......
0050 00 00 00 00 a2 89 cc 33 bc bb 8b 4f b6 b0 13 3e .......3...O...>
0060 c2 aa e6 df 0c 00 00 00 01 00 00 00 3c 00 00 00 ............<...
0070 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
0080 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
0090 00 00 00 00 00 00 00 00 00 00 00 00 7e 5e 2a 7e ............~^*~
00a0 4e 6f 72 72 73 6b 65 6e 7e 5e 2a 7e Norrsken~^*~
No. Time HW src Source HW dst Destination Protocol Info
2 0.000790000 91.0 host USB URB_CONTROL out
Frame 2: 64 bytes on wire (512 bits), 64 bytes captured (512 bits) on interface 0
Interface id: 0
Encapsulation type: USB packets with Linux header and padding (115)
Arrival Time: Dec 19, 2013 14:32:25.935478000 CET
[Time shift for this packet: 0.000000000 seconds]
Epoch Time: 1387459945.935478000 seconds
[Time delta from previous captured frame: 0.000790000 seconds]
[Time delta from previous displayed frame: 0.000790000 seconds]
[Time since reference or first frame: 0.000790000 seconds]
Frame Number: 2
Frame Length: 64 bytes (512 bits)
Capture Length: 64 bytes (512 bits)
[Frame is marked: False]
[Frame is ignored: False]
[Protocols in frame: usb]
USB URB
URB id: 0xffff8800b11a7200
URB type: URB_COMPLETE ('C')
URB transfer type: URB_CONTROL (0x02)
Endpoint: 0x00, Direction: OUT
0... .... = Direction: OUT (0)
.000 0000 = Endpoint value: 0
Device: 91
URB bus id: 5
Device setup request: not relevant ('-')
Data: not present ('>')
URB sec: 1387459945
URB usec: 935478
URB status: Success (0)
URB length [bytes]: 108
Data length [bytes]: 0
[Request in: 1]
[Time from request: 0.000790000 seconds]
[bInterfaceClass: Unknown (0xffff)]
0000 00 72 1a b1 00 88 ff ff 43 02 00 5b 05 00 2d 3e .r......C..[..->
0010 69 f5 b2 52 00 00 00 00 36 46 0e 00 00 00 00 00 i..R....6F......
0020 6c 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 l...............
0030 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
No. Time HW src Source HW dst Destination Protocol Info
3 0.001031000 91.1 host USB URB_INTERRUPT in
Frame 3: 72 bytes on wire (576 bits), 72 bytes captured (576 bits) on interface 0
Interface id: 0
Encapsulation type: USB packets with Linux header and padding (115)
Arrival Time: Dec 19, 2013 14:32:25.935719000 CET
[Time shift for this packet: 0.000000000 seconds]
Epoch Time: 1387459945.935719000 seconds
[Time delta from previous captured frame: 0.000241000 seconds]
[Time delta from previous displayed frame: 0.000241000 seconds]
[Time since reference or first frame: 0.001031000 seconds]
Frame Number: 3
Frame Length: 72 bytes (576 bits)
Capture Length: 72 bytes (576 bits)
[Frame is marked: False]
[Frame is ignored: False]
[Protocols in frame: usb]
USB URB
URB id: 0xffff8801ea0e3480
URB type: URB_COMPLETE ('C')
URB transfer type: URB_INTERRUPT (0x01)
Endpoint: 0x81, Direction: IN
1... .... = Direction: IN (1)
.000 0001 = Endpoint value: 1
Device: 91
URB bus id: 5
Device setup request: not relevant ('-')
Data: present (0)
URB sec: 1387459945
URB usec: 935719
URB status: Success (0)
URB length [bytes]: 8
Data length [bytes]: 8
[bInterfaceClass: Unknown (0xffff)]
Leftover Capture Data: a10100000c000000
0000 80 34 0e ea 01 88 ff ff 43 01 81 5b 05 00 2d 00 .4......C..[..-.
0010 69 f5 b2 52 00 00 00 00 27 47 0e 00 00 00 00 00 i..R....'G......
0020 08 00 00 00 08 00 00 00 00 00 00 00 00 00 00 00 ................
0030 10 00 00 00 00 00 00 00 00 02 00 00 00 00 00 00 ................
0040 a1 01 00 00 0c 00 00 00 ........
No. Time HW src Source HW dst Destination Protocol Info
4 0.001040000 host 91.1 USB URB_INTERRUPT in
Frame 4: 64 bytes on wire (512 bits), 64 bytes captured (512 bits) on interface 0
Interface id: 0
Encapsulation type: USB packets with Linux header and padding (115)
Arrival Time: Dec 19, 2013 14:32:25.935728000 CET
[Time shift for this packet: 0.000000000 seconds]
Epoch Time: 1387459945.935728000 seconds
[Time delta from previous captured frame: 0.000009000 seconds]
[Time delta from previous displayed frame: 0.000009000 seconds]
[Time since reference or first frame: 0.001040000 seconds]
Frame Number: 4
Frame Length: 64 bytes (512 bits)
Capture Length: 64 bytes (512 bits)
[Frame is marked: False]
[Frame is ignored: False]
[Protocols in frame: usb]
USB URB
URB id: 0xffff8801ea0e3480
URB type: URB_SUBMIT ('S')
URB transfer type: URB_INTERRUPT (0x01)
Endpoint: 0x81, Direction: IN
1... .... = Direction: IN (1)
.000 0001 = Endpoint value: 1
Device: 91
URB bus id: 5
Device setup request: not relevant ('-')
Data: not present ('<')
URB sec: 1387459945
URB usec: 935728
URB status: Operation now in progress (-EINPROGRESS) (-115)
URB length [bytes]: 64
Data length [bytes]: 0
[bInterfaceClass: Unknown (0xffff)]
0000 80 34 0e ea 01 88 ff ff 53 01 81 5b 05 00 2d 3c .4......S..[..-<
0010 69 f5 b2 52 00 00 00 00 30 47 0e 00 8d ff ff ff i..R....0G......
0020 40 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 @...............
0030 10 00 00 00 00 00 00 00 00 02 00 00 00 00 00 00 ................
What's missing here is of course the expected read.
Normally, we should have seen a "usb_submit_urb" message logged
immediately after receiving a NOTIFY_RESPONSE_AVAILABLE. The suspected
change in v3.13 has modified this so that we never will submit the read
urb if we are already waiting for a response. But somehow the device
and driver has obviously come out of sync here.
Not good at all. I'll see if I can find the problem. If not, then I
think we have to revert that change.
I think I'll start by adding some more debugging.
Bjørn
More information about the ModemManager-devel
mailing list