Bjørn, does this ring any bell?

Created attachment 120295 [details]
experimental NDP relocation patch

There is one issue that springs to mind: The E3372 is the same hardware where we had similar unexplainable issues with NCM, isn't it?  Until Enrico figured out that the firmware wanted the NDP *after* the IP packets, and applied a workaround for that in the huawei_cdc_ncm driver.

I could imagine the same problem appying to their MBIM implementation as well, given the close relationship between the protocols.  Unfortunately it's not that simple to fix there, since we have to be prepared for more than one NDP in each NTB.  But I hope this patch will work well enough to let us figure out if this is really the problem.

Are you able to test this?

Note: This cannot be used as a permanent fix.  We'd need to rewrite the NDP allocation code so it supports multiple NDPs placed after their respective packets.

Hmm, don't think this will explain the rx errors in any case, so there is most likely something else going on here...  Could you enable a bit more debugging in the rx path?  If you have built with dynamic_debugging, then this should provide some insight (adjust as necessary):


 echo 'module cdc_mbim +fp' >/sys/kernel/debug/dynamic_debug/control 
 echo 'module cdc_ncm +fp' >/sys/kernel/debug/dynamic_debug/control 
 ethtool -s wwp5s0u1c2 msglvl rx_err on

Sami: would yo be able to test Bjørn's cdc_mbim driver patch?

Bjørn, yes, this is one of those Huawei devices that requires the NDP fix, I actually tested it 2 weeks ago in NCM mode, but no longer have access to it.

I had dynamic debug enabled but I didn't know also enabling debugs with ethtool was required.

wwp5s0u1c2: flags=4291<UP,BROADCAST,RUNNING,NOARP,MULTICAST>  mtu 1500
        inet 46.132.191.93  netmask 255.255.255.252  broadcast 46.132.191.95
        ether 4a:2a:90:69:e7:ad  txqueuelen 1000  (Ethernet)
        RX packets 0  bytes 0 (0.0 B)
        RX errors 9984  dropped 0  overruns 0  frame 0
        TX packets 0  bytes 0 (0.0 B)
        TX errors 767  dropped 0 overruns 0  carrier 0  collisions 0

# ethtool -S wwp5s0u1c2
NIC statistics:
     tx_reason_ntb_full: 0
     tx_reason_ndp_full: 0
     tx_reason_timeout: 767
     tx_reason_max_datagram: 0
     tx_overhead: 144656
     tx_ntbs: 767
     rx_overhead: 0
     rx_ntbs: 0

# ethtool  wwp5s0u1c2 
Settings for wwp5s0u1c2:
	Current message level: 0x00000041 (65)
			       drv rx_err
	Link detected: yes
#



[1972456.539585] usbcore: deregistering interface driver cdc_ether
[1972456.540028] usbnet_status_stop: usb 5-1: decremented interrupt URB count to 0
[1972464.233334] usb 5-1: USB disconnect, device number 34
[1972475.691125] usb 5-1: new high-speed USB device number 35 using xhci_hcd
[1972475.861010] usb 5-1: New USB device found, idVendor=12d1, idProduct=157d
[1972475.861013] usb 5-1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[1972475.861014] usb 5-1: Product: HUAWEI_MOBILE
[1972475.861015] usb 5-1: Manufacturer: HUAWEI_MOBILE
[1972475.861016] usb 5-1: SerialNumber: 0123456789ABCDEF
[1972475.908860] usb-storage 5-1:1.0: USB Mass Storage device detected
[1972475.909053] scsi host51: usb-storage 5-1:1.0
[1972476.767829] usb-storage 5-1:2.2: USB Mass Storage device detected
[1972476.768063] scsi host52: usb-storage 5-1:2.2
[1972477.175474] __usbnet_read_cmd: cdc_mbim 5-1:2.0 (unnamed net_device) (uninitialized): usbnet_read_cmd cmd=0x80 reqtype=a1 value=0x0000 index=0x0000 size=28
[1972477.175565] cdc_ncm_init: cdc_mbim 5-1:2.0: Setting NTB format to 16-bit
[1972477.175571] __usbnet_write_cmd: cdc_mbim 5-1:2.0 (unnamed net_device) (uninitialized): usbnet_write_cmd cmd=0x84 reqtype=21 value=0x0000 index=0x0000 size=0
[1972477.175621] cdc_ncm_init: cdc_mbim 5-1:2.0: dwNtbInMaxSize=131072 dwNtbOutMaxSize=16384 wNdpOutPayloadRemainder=2 wNdpOutDivisor=4 wNdpOutAlignment=4 wNtbOutMaxDatagrams=0 flags=0x20
[1972477.862109] cdc_mbim 5-1:2.0: setting rx_max = 16384
[1972477.862129] __usbnet_write_cmd: cdc_mbim 5-1:2.0 (unnamed net_device) (uninitialized): usbnet_write_cmd cmd=0x86 reqtype=21 value=0x0000 index=0x0000 size=4
[1972477.862235] cdc_mbim 5-1:2.0: NDP will be placed at end of frame for this device.
[1972477.862400] cdc_mbim 5-1:2.0: cdc-wdm0: USB WDM device
[1972477.862714] usbcore: registered new interface driver cdc_mbim
[1972477.870239] cdc_mbim 5-1:2.0 wwp5s0u1c2: renamed from wwan0
[1972477.874969] scsi 52:0:0:0: Direct-Access     HUAWEI   TF CARD Storage  2.31 PQ: 0 ANSI: 2
[1972477.875418] sd 52:0:0:0: Attached scsi generic sg8 type 0
[1972477.919158] sd 52:0:0:0: [sdh] Attached SCSI removable disk
[1972478.213590] wdm_write: cdc_mbim 5-1:2.0: Tx URB has been submitted index=0
[1972478.271234] wdm_int_callback: cdc_mbim 5-1:2.0: NOTIFY_RESPONSE_AVAILABLE received: index 0 len 0
[1972478.271247] wdm_int_callback: cdc_mbim 5-1:2.0: wdm_int_callback: usb_submit_urb 0
[1972478.447103] wdm_int_callback: cdc_mbim 5-1:2.0: NOTIFY_RESPONSE_AVAILABLE received: index 0 len 0
[1972478.447115] wdm_int_callback: cdc_mbim 5-1:2.0: wdm_int_callback: usb_submit_urb 0
[1972478.547020] wdm_int_callback: cdc_mbim 5-1:2.0: NOTIFY_RESPONSE_AVAILABLE received: index 0 len 0
[1972478.547032] wdm_int_callback: cdc_mbim 5-1:2.0: wdm_int_callback: usb_submit_urb 0
[1972480.312049] wdm_write: cdc_mbim 5-1:2.0: Tx URB has been submitted index=0
[1972480.447417] wdm_int_callback: cdc_mbim 5-1:2.0: NOTIFY_RESPONSE_AVAILABLE received: index 0 len 0
[1972480.447431] wdm_int_callback: cdc_mbim 5-1:2.0: wdm_int_callback: usb_submit_urb 0
[1972480.447962] wdm_write: cdc_mbim 5-1:2.0: Tx URB has been submitted index=0
[1972480.505357] wdm_int_callback: cdc_mbim 5-1:2.0: NOTIFY_RESPONSE_AVAILABLE received: index 0 len 0
[1972480.505369] wdm_int_callback: cdc_mbim 5-1:2.0: wdm_int_callback: usb_submit_urb 0
[1972480.505690] wdm_write: cdc_mbim 5-1:2.0: Tx URB has been submitted index=0
[1972480.685204] wdm_int_callback: cdc_mbim 5-1:2.0: NOTIFY_RESPONSE_AVAILABLE received: index 0 len 0
[1972480.685217] wdm_int_callback: cdc_mbim 5-1:2.0: wdm_int_callback: usb_submit_urb 0
[1972480.686334] wdm_write: cdc_mbim 5-1:2.0: Tx URB has been submitted index=0
[1972480.845083] wdm_int_callback: cdc_mbim 5-1:2.0: NOTIFY_RESPONSE_AVAILABLE received: index 0 len 0
[1972480.845095] wdm_int_callback: cdc_mbim 5-1:2.0: wdm_int_callback: usb_submit_urb 0
[1972480.845543] wdm_write: cdc_mbim 5-1:2.0: Tx URB has been submitted index=0
[1972481.026932] wdm_int_callback: cdc_mbim 5-1:2.0: NOTIFY_RESPONSE_AVAILABLE received: index 0 len 0
[1972481.026946] wdm_int_callback: cdc_mbim 5-1:2.0: wdm_int_callback: usb_submit_urb 0
[1972481.027284] wdm_write: cdc_mbim 5-1:2.0: Tx URB has been submitted index=0
[1972481.204778] wdm_int_callback: cdc_mbim 5-1:2.0: NOTIFY_RESPONSE_AVAILABLE received: index 0 len 0
[1972481.204793] wdm_int_callback: cdc_mbim 5-1:2.0: wdm_int_callback: usb_submit_urb 0

[1972547.060017] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[1972547.060497] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[1972547.061014] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[1972547.061501] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[1972547.062017] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[1972547.184900] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[1972547.185461] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[1972547.185944] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[1972547.186426] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[1972547.186965] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[1972547.309760] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[1972547.310191] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[1972547.310683] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[1972547.311122] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[1972547.312017] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[1972547.434610] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[1972547.435036] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[1972547.435546] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[1972547.436295] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[1972547.436932] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[1972547.559541] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[1972547.560021] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[1972547.560537] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[1972547.561014] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[1972547.561501] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[1972547.684428] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[1972547.684901] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[1972547.685443] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[1972547.685920] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[1972547.686423] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[1972547.809304] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[1972547.809767] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[1972547.810246] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[1972547.810726] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[1972547.811227] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[1972547.934180] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[1972547.934726] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[1972547.935244] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[1972547.935740] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[1972547.936453] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted

snip some thousand lines

[1972604.382865] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[1972604.468729] wdm_int_callback: cdc_mbim 5-1:2.0: NOTIFY_RESPONSE_AVAILABLE received: index 0 len 0
[1972604.468742] wdm_int_callback: cdc_mbim 5-1:2.0: wdm_int_callback: usb_submit_urb 0
[1972604.505784] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted

[1972645.219276] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[1972645.319228] cdc_mbim_manage_power: cdc_mbim 5-1:2.0: cdc_mbim_manage_power() pmcount=2, on=0
[1972645.320463] wdm_write: cdc_mbim 5-1:2.0: Tx URB has been submitted index=0
[1972645.769897] wdm_int_callback: cdc_mbim 5-1:2.0: NOTIFY_NETWORK_CONNECTION disconnected from network
[1972645.789873] wdm_int_callback: cdc_mbim 5-1:2.0: NOTIFY_RESPONSE_AVAILABLE received: index 0 len 0
[1972645.789885] wdm_int_callback: cdc_mbim 5-1:2.0: wdm_int_callback: usb_submit_urb 0
[1972645.791359] IPv6: ADDRCONF(NETDEV_UP): wwp5s0u1c2: link is not ready
[1972648.868447] wdm_write: cdc_mbim 5-1:2.0: Tx URB has been submitted index=0
[1972648.945228] wdm_int_callback: cdc_mbim 5-1:2.0: NOTIFY_RESPONSE_AVAILABLE received: index 0 len 0
[1972648.945243] wdm_int_callback: cdc_mbim 5-1:2.0: wdm_int_callback: usb_submit_urb 0
[1972648.985151] wdm_int_callback: cdc_mbim 5-1:2.0: NOTIFY_RESPONSE_AVAILABLE received: index 0 len 0
[1972648.985164] wdm_int_callback: cdc_mbim 5-1:2.0: wdm_int_callback: usb_submit_urb 0
[1972648.985486] wdm_write: cdc_mbim 5-1:2.0: Tx URB has been submitted index=0
[1972649.354863] wdm_int_callback: cdc_mbim 5-1:2.0: NOTIFY_RESPONSE_AVAILABLE received: index 0 len 0
[1972649.354879] wdm_int_callback: cdc_mbim 5-1:2.0: wdm_int_callback: usb_submit_urb 0
[1972649.355231] wdm_write: cdc_mbim 5-1:2.0: Tx URB has been submitted index=0
[1972649.746504] wdm_int_callback: cdc_mbim 5-1:2.0: SPEED_CHANGE received (len 16)
[1972649.756503] wdm_int_callback: cdc_mbim 5-1:2.0: NOTIFY_RESPONSE_AVAILABLE received: index 0 len 0
[1972649.756515] wdm_int_callback: cdc_mbim 5-1:2.0: wdm_int_callback: usb_submit_urb 0
[1972649.756903] wdm_write: cdc_mbim 5-1:2.0: Tx URB has been submitted index=0
[1972649.808454] wdm_int_callback: cdc_mbim 5-1:2.0: NOTIFY_NETWORK_CONNECTION connected to network
[1972649.884392] wdm_int_callback: cdc_mbim 5-1:2.0: NOTIFY_RESPONSE_AVAILABLE received: index 0 len 0
[1972649.884404] wdm_int_callback: cdc_mbim 5-1:2.0: wdm_int_callback: usb_submit_urb 0
[1972649.924358] wdm_int_callback: cdc_mbim 5-1:2.0: NOTIFY_RESPONSE_AVAILABLE received: index 0 len 0
[1972649.924369] wdm_int_callback: cdc_mbim 5-1:2.0: wdm_int_callback: usb_submit_urb 0
[1972649.926709] cdc_mbim_manage_power: cdc_mbim 5-1:2.0: cdc_mbim_manage_power() pmcount=1, on=1
[1972649.926996] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted

Created attachment 120313 [details]
allow bloated rx buffer

The "no read resubmitted" messages are interesting. Those are from usbnet, and means that the rx errors are caused by rx URB failures.

Now I see that there are no less than 3 different message classes used in the usbnet rx_complete(): rx_err, ifdown and link.  You could try to pinpoint the exact error with

 ethtool -s wwp5s0u1c2 msglvl rx_err on ifdown on link on

but I don't know if it helps much.  I have no idea why it would fail there.  Unless.... Hmm, we do not respect the modem's requested buffer size.  This is intentional, because the modem firmware developer is either insane or smoking some very dirty socks.  But could it be that our URBs are rejected for this reason?

Maybe we can cheat and set the rx buffer to 131072 bytes without actually implementing 32bit NDP support?  Don't know...  You could try this patch for a temporary test. It will definitely fail if you start aggregating lots of packets, bt if it works for a low packet rate then we will have some idea where the problem is. But still no idea how to fix it :)

Thanks for new patch.

NIC statistics:
     tx_reason_ntb_full: 0
     tx_reason_ndp_full: 0
     tx_reason_timeout: 1227
     tx_reason_max_datagram: 0
     tx_overhead: 231407
     tx_ntbs: 1227
     rx_overhead: 0
     rx_ntbs: 0
wwp5s0u1c2: flags=4291<UP,BROADCAST,RUNNING,NOARP,MULTICAST>  mtu 1500
        inet 193.210.231.167  netmask 255.255.255.240  broadcast 193.210.231.175
        ether 4a:2a:90:69:e7:ad  txqueuelen 1000  (Ethernet)
        RX packets 0  bytes 0 (0.0 B)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 1467  bytes 110870 (108.2 KiB)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0

not very chatty logs, ... 


[2007430.242114] wdm_write: cdc_mbim 5-1:2.0: Tx URB has been submitted index=0
[2007430.315080] wdm_int_callback: cdc_mbim 5-1:2.0: NOTIFY_RESPONSE_AVAILABLE received: index 0 len 0
[2007430.315094] wdm_int_callback: cdc_mbim 5-1:2.0: wdm_int_callback: usb_submit_urb 0
[2007430.355038] wdm_int_callback: cdc_mbim 5-1:2.0: NOTIFY_RESPONSE_AVAILABLE received: index 0 len 0
[2007430.355051] wdm_int_callback: cdc_mbim 5-1:2.0: wdm_int_callback: usb_submit_urb 0
[2007430.355400] wdm_write: cdc_mbim 5-1:2.0: Tx URB has been submitted index=0
[2007430.724731] wdm_int_callback: cdc_mbim 5-1:2.0: NOTIFY_RESPONSE_AVAILABLE received: index 0 len 0
[2007430.724745] wdm_int_callback: cdc_mbim 5-1:2.0: wdm_int_callback: usb_submit_urb 0
[2007430.725103] wdm_write: cdc_mbim 5-1:2.0: Tx URB has been submitted index=0
[2007431.140388] wdm_int_callback: cdc_mbim 5-1:2.0: SPEED_CHANGE received (len 16)
[2007431.154369] wdm_int_callback: cdc_mbim 5-1:2.0: NOTIFY_RESPONSE_AVAILABLE received: index 0 len 0
[2007431.154382] wdm_int_callback: cdc_mbim 5-1:2.0: wdm_int_callback: usb_submit_urb 0
[2007431.154742] wdm_write: cdc_mbim 5-1:2.0: Tx URB has been submitted index=0
[2007431.194333] wdm_int_callback: cdc_mbim 5-1:2.0: NOTIFY_NETWORK_CONNECTION connected to network
[2007431.274286] wdm_int_callback: cdc_mbim 5-1:2.0: NOTIFY_RESPONSE_AVAILABLE received: index 0 len 0
[2007431.274302] wdm_int_callback: cdc_mbim 5-1:2.0: wdm_int_callback: usb_submit_urb 0
[2007431.314214] wdm_int_callback: cdc_mbim 5-1:2.0: NOTIFY_RESPONSE_AVAILABLE received: index 0 len 0
[2007431.314226] wdm_int_callback: cdc_mbim 5-1:2.0: wdm_int_callback: usb_submit_urb 0
[2007431.316646] cdc_mbim_manage_power: cdc_mbim 5-1:2.0: cdc_mbim_manage_power() pmcount=1, on=1
[2007441.849333] wdm_int_callback: cdc_mbim 5-1:2.0: NOTIFY_RESPONSE_AVAILABLE received: index 0 len 0
[2007441.849347] wdm_int_callback: cdc_mbim 5-1:2.0: wdm_int_callback: usb_submit_urb 0
[2007488.789708] cdc_mbim 5-1:2.0: unknown notification 3 received: index 0 len 4
[2007501.948625] wdm_int_callback: cdc_mbim 5-1:2.0: NOTIFY_RESPONSE_AVAILABLE received: index 0 len 0
[2007501.948638] wdm_int_callback: cdc_mbim 5-1:2.0: wdm_int_callback: usb_submit_urb 0

Strange.  The rx errors went away, but so did any rx frames at all?  I don't know how to interpret that.  Maybe I am missing something which makes cdc_mbim silently fail in this case?

Qucikly running out of ideas here...

Looking through my mailbox I see that this is not the first time we discuss this problem.  Sorry for not remembering that,

I gather that you never were able to make MBIM work with this modem?  The problem is the same as it was in February when you were testing on linux 3.19?

I found a very useful usbmon dump you provided back then, showing this:


bb7b3f00 31.454695 C Bi:2:081:1 0 98 =
    6e636d68 10000000 62000000 10000000 69707300 20000000 00000000 00000000 32000000 2e000000 00000000 00000000 00000001 08000604 00014c54 9945e5d5 2e84b991 00000000 00002e84 b9920000 00000000 00000000 00000000 00000000 0000
     n c m h  . . . .  b . . .  . . . .  i p s .    . . .  . . . .  . . . .  2 . . .  . . . .  . . . .  . . . .  . . . .  . . . .  . . L T  . E . .  . . . .  . . . .  . . . .  . . . .  . . . .  . . . .  . . . .  . . . .  . .
bb7b3f00 31.454711 S Bi:2:081:1 - 16384 <
315a3480 31.468324 S Bo:2:081:1 - 226 =
    4e434d48 0c000b00 e2000c00 49505300 10000000 ba002800 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 000046c0 00280000 40000102 1be32e84 b992e000 00169404 00002200 fa020000 00010300 0000e000 00fb
     N C M H  . . . .  . . . .  I P S .  . . . .  . . ( .  . . . .  . . . .  . . . .  . . . .  . . . .  . . . .  . . . .  . . . .  . . . .  . . . .  . . . .  . . . .  . . . .  . . . .  . . . .  . . . .  . . . .  . . . .  . . . .  . . . .  . . . .  . . . .  . . . .  . . . .  . . . .  . . . .  . . . .  . . . .  . . . .  . . . .  . . . .  . . . .  . . . .  . . . .  . . . .  . . . .  . . . .  . . . .  . . . .  . . . .  . . F .  . ( . .  @ . . .  . . . .  . . . .  . . . .  . . " .  . . . .  . . . .  . . . .  . .


What we see here is the driver using 16bit mode ("NCMH" etc), and the device using 32bit mode ("ncmh" etc).  This would explain our failure to receive anything from the modem.  We don't support the 32bit mode.

I think it would be interesting to
a) verify if this is still the problem, and if so
b) look further at the  USB_CDC_SET_NTB_FORMAT processing to figure out where it goes wrong, and maybe
c) implement basic 32bit support to see if that helps, unless we can figure out an obvious failure reason

The last point might seem like a big deal, but I don't really think it is.  The only reason we never did it is because it's pointless.  We never ever want to use buffers large enough to need more than 16bit offsets, and 16bit support is mandatory in the spec.

Yes, I HAD the same problem as with 3.19.
But I smoked some old socks and it STARTED WORKING with attached patch:

wwp5s0u1c2: flags=4291<UP,BROADCAST,RUNNING,NOARP,MULTICAST>  mtu 1500
        inet 193.210.224.216  netmask 255.255.255.240  broadcast 193.210.224.223
        ether 4a:2a:90:69:e7:ad  txqueuelen 1000  (Ethernet)
        RX packets 61204  bytes 59335206 (56.5 MiB)
        RX errors 84  dropped 0  overruns 0  frame 0
        TX packets 52769  bytes 55407489 (52.8 MiB)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0

NIC statistics:
     tx_reason_ntb_full: 2333
     tx_reason_ndp_full: 0
     tx_reason_timeout: 9369
     tx_reason_max_datagram: 1
     tx_overhead: 2360969
     tx_ntbs: 11626
     rx_overhead: 964632
     rx_ntbs: 18191

Upload speed 5 MiB/s at testmy.net..

I am only getting these

[2068013.200247] wdm_int_callback: cdc_mbim 5-1:2.0: NOTIFY_RESPONSE_AVAILABLE received: index 0 len 0
[2068013.200261] wdm_int_callback: cdc_mbim 5-1:2.0: wdm_int_callback: usb_submit_urb 0
[2068015.648156] cdc_mbim 5-1:2.0: unknown notification 3 received: index 0 len 4
[2068016.757186] cdc_mbim 5-1:2.0: unknown notification 3 received: index 0 len 4
[2068073.303503] wdm_int_callback: cdc_mbim 5-1:2.0: NOTIFY_RESPONSE_AVAILABLE received: index 0 len 0
[2068073.303520] wdm_int_callback: cdc_mbim 5-1:2.0: wdm_int_callback: usb_submit_urb 0
[2068133.406767] wdm_int_callback: cdc_mbim 5-1:2.0: NOTIFY_RESPONSE_AVAILABLE received: index 0 len 0
[2068133.406781] wdm_int_callback: cdc_mbim 5-1:2.0: wdm_int_callback: usb_submit_urb 0

not getting the printk for ctx->max_datagram_size.

Created attachment 120339 [details] [review]
Yolo - this is what I use now

A glitch in patch.  Using CDC_NCM_NTB_MAX_SIZE_RX in cdc_ncm_check_rx_max.
So only cdc_ncm_setup and cdc_mbim_bind modified.

So both these changes were necessary:
 1) move the NDP to the end of the frame
 2) increase RX buffer to 64512

Is that correct?

Did you try experimenting with other buffer sizes?  You can change this dynamically using /sys/class/net/wwp5s0u1c2/cdc_ncm/rx_max as long as you stay within the max/min limits enforced by the driver.  So testing a 32k buffer should be as easy as doing

 echo 32768  >/sys/class/net/wwp5s0u1c2/cdc_ncm/rx_max


Fixing 1) properly is going to take some work. We should support structures like

 NCMH
   IPS0 #1
   IPS0 #2
   ..
   IPS0 #n
  NDP #1
   IPS1 #1
   IPS1 #2
  NDP #2
   DSS0 #1
  NDP #3

I believe the best way to do that is to collect all IP and DSS packets first, and create the NDPs when transmitting.  I have followed the iwlwifi A-MSDU work currently in progress with great interest.  It uses TSO to aggregate packets:
http://marc.info/?l=linux-wireless&m=144553311822496&w=2

It would be nice to do something similar for MBIM (and thereby also NCM).

But since this will take some (a number close to infinite) time, I guess we need some short term quickfix too.  How about a device ID specific restriction, allowing only one NDP per frame and using the CDC_NCM_FLAG_NDP_TO_END flag?  In fact, we could let just the flag imply the single NDP.

I'll see if I can cook up something which will fly.

Yep—mbim didn't work without CDC_NCM_FLAG_NDP_TO_END flag.

Are you talking of USB ID -based restriction? There can be many different devices assigned to the same USB ID, all with different firmware versions..

mbim does not seem as reliable as cdc_ether..  sometimes I have to try many times till it works; when it doesn't rx packets stays the same and rx errors increases.
Sometimes only reloading cdc_mbim works, powercycling the device does not help.

Connection does not stay up for very long, one hour max, sometimes 10 min:

[2075783.240488] wdm_int_callback: cdc_mbim 5-1:2.0: NOTIFY_RESPONSE_AVAILABLE received: index 0 len 0
[2075783.240500] wdm_int_callback: cdc_mbim 5-1:2.0: wdm_int_callback: usb_submit_urb 0
[2075832.261534] cdc_mbim 5-1:2.0 wwp5s0u1c2: stop stats: rx/tx 0/802, errs 105/0
[2075832.261733] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: rx shutdown, code -104
[2075832.261736] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[2075832.263149] wdm_write: cdc_mbim 5-1:2.0: Tx URB has been submitted index=0
[2075832.722751] wdm_int_callback: cdc_mbim 5-1:2.0: NOTIFY_NETWORK_CONNECTION disconnected from network

But anyways, I did more testing and it works with only CDC_NCM_FLAG_NDP_TO_END patch.  Had to do many device replugs and reloadings of cdc_mbim..

Created attachment 120352 [details]
device specific workaround

Great to know that we don't have to care about the buffers.


Here is an attempt on a quick fix patch which might be acceptable upstream.  Please test.  Thanks.

Yes, the quick fix will have to match a device ID.  I don't see what else we can do. We could expose the flags and allow you to manually set it, but that will not work for the average user.

The worst that can happen here is that we apply this to a Huawei device which will work without it. It should still work. This quick fix will affect performance for multiplexed sessions, but let's face it: Nobody (except me) uses that anyway :)

Once we have the real fix in place (that is an infinite number of years from now), we can apply that wholesale to every device.  I don't see any problem doing that.  The fact that Huawei can add a bug like this proves that the Windows drivers behave this way.  Which implies that there is no device with the reversed bug, requiring the NDP before the IP packets.

I tried for 30 minutes to get mbim to work with this latest patch and failed.
Do you think the quirk is applied when lsusb shows the id 12d1:157d _after_ usb_modeswitch has been executed and link is up according to networkmanager..?
With cdc_ether I have 12d1:14dc , I'd guess it should be :14db with mbim..

I got now errors I haven't seen before:

[2095639.090043] usbnet_bh: cdc_mbim 5-1:2.0 wwp5s0u1c2: rxqlen 0 --> 5
[2095639.090324] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: rx throttle -71
[2095639.090328] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[2095639.090793] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[2095639.091308] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[2095639.091797] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[2095639.092291] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[2095639.214922] usbnet_bh: cdc_mbim 5-1:2.0 wwp5s0u1c2: rxqlen 0 --> 5
[2095639.215206] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: rx throttle -71
[2095639.215209] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[2095639.215662] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[2095639.216147] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[2095639.216624] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted
[2095639.217080] rx_complete: cdc_mbim 5-1:2.0 wwp5s0u1c2: no read resubmitted

rx errors increased by increments of five.

once I got this (got USB_CDC_NCM_NTH32_SIGN instead!):

[2096198.958237] cdc_ncm_rx_verify_nth16: cdc_mbim 5-1:2.0 wwp5s0u1c2: invalid NTH16 signature <0x686d636e>
[2096201.955391] cdc_ncm_rx_verify_nth16: cdc_mbim 5-1:2.0 wwp5s0u1c2: invalid NTH16 signature <0x686d636e>
[2096204.952554] cdc_ncm_rx_verify_nth16: cdc_mbim 5-1:2.0 wwp5s0u1c2: invalid NTH16 signature <0x686d636e>
[2096207.949711] cdc_ncm_rx_verify_nth16: cdc_mbim 5-1:2.0 wwp5s0u1c2: invalid NTH16 signature <0x686d636e>
[2096210.946884] cdc_ncm_rx_verify_nth16: cdc_mbim 5-1:2.0 wwp5s0u1c2: invalid NTH16 signature <0x686d636e>
[2096213.944049] cdc_ncm_rx_verify_nth16: cdc_mbim 5-1:2.0 wwp5s0u1c2: invalid NTH16 signature <0x686d636e>
[2096216.941223] cdc_ncm_rx_verify_nth16: cdc_mbim 5-1:2.0 wwp5s0u1c2: invalid NTH16 signature <0x686d636e>
[2096219.938401] cdc_ncm_rx_verify_nth16: cdc_mbim 5-1:2.0 wwp5s0u1c2: invalid NTH16 signature <0x686d636e>
[2096222.935560] cdc_ncm_rx_verify_nth16: cdc_mbim 5-1:2.0 wwp5s0u1c2: invalid NTH16 signature <0x686d636e>

sometimes I managed to receive packets, like one in two minutes:
2015-12-04T20:08:26.398955Z IP (tos 0x20, ttl 48, id 42548, offset 0, flags [none], proto UDP (17), length 131)
    69.249.19.73.27392 > 46.132.184.166.6889: UDP, length 103

Created attachment 120357 [details]
new version of the device specific workaround

yes, sorry.  I cut and pasted the wrong device ID.  Hopefully this version is better?  I included an info-printk so it's easier to verify that the quirk is actually attempted.

Interesting to see the 32bit "ncmh" frames received again.  Wonder how that happens, and how it could be related to this bug?

Quirk logged and it works 😉  Had to reload cdc_mbim only once to get it working.
Thanks a lot.

Bjørn, was your patch sent to netdev/linux-usb?

Yes, it was:
http://www.spinics.net/lists/netdev/msg355393.html

Closing the bugreport.