Project

General

Profile

Actions
Copy link

Bug #5490

open

ISO IN urb sometimes completes with less than full data / incomplete frame

Added by laforge over 1 year ago. Updated about 1 year ago.

Status:
Feedback
Priority:
Normal
Assignee:
tnt
Category:
-
Target version:
-
Start date:
03/14/2022
Due date:
% Done:

0%

Spec Reference:

Description

This is happening frequently at gruetzkopf:

Assert failed size % 32 == 0 mux_demux.c:419

This means that a non-modulo-32 length (plus 5 byte header) was received in an ISO IN URB.

22:00 <@gruetzkopf> <0001> mux_demux.c:421 (I0:L0) Transfer cut short, size was 251 bytes
23:58 <@gruetzkopf> just so i don't forget: i've also seen 253 and 252 by now

So this means that instead of 256 (+4) we've seen 251-253 (+4) byte transfer length.

I've checked the firmware, an I don't see any way how the firmware could do something wrong here: It uses (n * 32) + 4) as length, whic hcan never be one of those odd values.

On the osmo-e1d side, we are always checking for LIBUSB_TRANSFER_COMPLETED state, so both the transfer/urb, as well as the individual packets have LIBUSB_TRANSFER_COMPLETED before passing them higher up to the mux_demux code which is asserting here.

So I guess the underlying question is: Is this a kernel/libusb bug? Is it legal for ISO IN packets to complete with a length less than what was submitted?

If this is legal, then the next question si why it it is happening.

We can of course plaster around the issue and substitute the missing data with 0xff or something, creating various bit errors, rathe than asserting.

Files

usbmon.pcap usbmon.pcap 4.18 MB laforge, 09/15/2022 09:48 AM
usbmon2.pcap usbmon2.pcap 3.92 MB laforge, 09/15/2022 09:50 AM
ice1usb-os5490-openvizsla.pcap.bz2 ice1usb-os5490-openvizsla.pcap.bz2 6.29 MB laforge, 09/15/2022 12:10 PM
Actions
Copy link
 #1

Updated by tnt over 1 year ago

Well it's definitely "legal" if the device actually responded with a frame shorter.
But that shouldn't happen with the icE1usb.

And if the frame was somehow "cut short" on the wire, the CRC would be invalid and the frame rejected.

Actions
Copy link
 #2

Updated by laforge over 1 year ago

There's now a laforge/e1oip-trunc branch which should fill the missing bytes with random garbage instead of asserting - untested as the problem doesn't appear locally here.

Actions
Copy link
 #3

Updated by tnt over 1 year ago

btw gruetzkopf if you have any way to make low level bus captures of the event, that would be useful. (openvizsla, logic analyzer, scope, ...)

Actions
Copy link
 #4

Updated by gruetzkopf over 1 year ago

tnt I will borrow a fast-enough LA (sadly no openvizla nor LUNA present)

Actions
Copy link
 #5

Updated by laforge about 1 year ago

I've now observed this behavior on the icE1usb + APU3 setup that is supposed to become the co-located OCTOI hub next week.

converting the ASSERT to a LOG statement renders:

<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=140 size%32=12
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=144 size%32=16
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=144 size%32=16
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=140 size%32=12
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=140 size%32=12
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=148 size%32=20
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=148 size%32=20
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=148 size%32=20
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=140 size%32=12
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=144 size%32=16
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=144 size%32=16
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=144 size%32=16
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=148 size%32=20
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=148 size%32=20
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=144 size%32=16
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=144 size%32=16
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=148 size%32=20
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=140 size%32=12
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=140 size%32=12
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=144 size%32=16
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=140 size%32=12
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=148 size%32=20
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=148 size%32=20
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=148 size%32=20
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=140 size%32=12
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=148 size%32=20
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=148 size%32=20
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=148 size%32=20
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=148 size%32=20
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=148 size%32=20
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=140 size%32=12
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=144 size%32=16
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=140 size%32=12
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=144 size%32=16
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=144 size%32=16
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=148 size%32=20
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=148 size%32=20
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=144 size%32=16
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=144 size%32=16
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=144 size%32=16
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=140 size%32=12
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=144 size%32=16
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=148 size%32=20
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=148 size%32=20
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=144 size%32=16
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=144 size%32=16
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=140 size%32=12
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=144 size%32=16
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=148 size%32=20
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=148 size%32=20
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=148 size%32=20
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=148 size%32=20
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=148 size%32=20
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=148 size%32=20
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=148 size%32=20
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=148 size%32=20
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=140 size%32=12
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=144 size%32=16
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=148 size%32=20
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=148 size%32=20
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=148 size%32=20
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=148 size%32=20
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=148 size%32=20
<0001> mux_demux.c:423 (I0:L0) IN ASSERT: size=148 size%32=20

A usbmon pcap file can be found attached as usbmon.pcap

As tnt pointed out, the third iso packet of the URB was alwsy the affected one.

After modifying osmo-e1d to only sumbmit USBs with two iso packets, the problem persisted (now it was the second iso packet in some of the URB which was short). Pcap file of that attempt at usbmon2.pcap

The USB device in question in those traces is 1.3.2, the ISO IN endpoint is 0x82.

Actions
Copy link
 #6

Updated by laforge about 1 year ago

Attaching an OpenVizsla USB packet trace: ice1usb-os5490-openvizsla.pcap.bz2

USB address of icE1usb is 22, so usbll.device_addr 22 || usbll.src "22.2" should be the proper filter string

Actions
Copy link
 #7

Updated by laforge about 1 year ago 

14:14 <@tnt> I'm not seeing any bad packet sizes there.
14:14 -!- wimpman is now known as W|MPy
14:16 <@LaF0rge> tnt: indeed. only three zero-length pckets matching "(usbll.src == "22.2") && !(frame.len == 263)" 
14:17 <@LaF0rge> meanwhile at least 40 odd-length packets reported by libusb :(
14:18 <@LaF0rge> [every second]

I now had to power-cycle the USB device + rmmod/insmod ehci_pci and of course it works again

Actions
Copy link

Also available in: Atom PDF

Add picture from clipboard (Maximum size: 48.8 MB)