Missing incomming USB HID packet on RP4

yoctopuce commented 4 years ago

Describe the bug

Incomming USB HID packet that work at Full Speed are not reported by the libUSB 1.0. Using an USB analyser we can see that all packet are acknowleged by the USB Host controller, but in the application the configured callback never get called. We have not been able to determine if the issue is in the libUSB or the Linux kernel. But we have write a simple program exhibits the problem. It's a simple threaded example that iterates over all Yoctopuce connected devices and send 15 USB packets. For each sent packet the device with respond with an USB Packet.

To reproduce We have publish on GitHub a complete description of the problem and a program that exhibits this issue: https://github.com/yoctopuce-examples/raspberry_4_usb_bug

Expected behaviour Incomming USB HID packet should be reported by the LibUSB 1.0.

Actual behaviour Incomming USB HID packet are not reported by the LibUSB 1.0.

System System Information

Raspberry Pi 4 Model B Rev 1.1 PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)"

Raspberry Pi reference 2019-07-10 Generated using pi-gen, https://github.com/RPi-Distro/pi-gen, 175dfb027ffabd4b8d5080097af0e51ed9a4a56c, stage2

Linux raspberrypi 4.19.57-v7l+ #1244 SMP Thu Jul 4 18:48:07 BST 2019 armv7l GNU/Linux Hardware : BCM2835 Revision : c03111 Serial : 100000001060871a Throttled flag : throttled=0x0 Camera : supported=0 detected=0

Videocore information

alloc failures: 0 compactions: 0 legacy block fails: 0

Filesystem information

Filesystem 1K-blocks Used Available Use% Mounted on /dev/root 30491968 3104168 26116680 11% / devtmpfs 1867796 0 1867796 0% /dev tmpfs 1999892 0 1999892 0% /dev/shm tmpfs 1999892 8584 1991308 1% /run tmpfs 5120 4 5116 1% /run/lock tmpfs 1999892 0 1999892 0% /sys/fs/cgroup /dev/mmcblk0p1 258096 39970 218126 16% /boot tmpfs 399976 0 399976 0% /run/user/1000

Filename Type Size Used Priority /var/swap file 102396 0 -2

Package version information

raspberrypi-ui-mods: Installed: (none) raspberrypi-sys-mods: Installed: 20190429 openbox: Installed: (none) lxpanel: Installed: (none) pcmanfm: Installed: (none) rpd-plym-splash: Installed: (none)

Networking Information

eth0: flags=4163<UP,BROADCAST,RUNNING,MULTICAST> mtu 1500 inet x.x.x.x netmask x.x.x.x broadcast x.x.x.x inet6 y::y.y.y.y prefixlen 64 scopeid 0x20 ether m.m.m.m txqueuelen 1000 (Ethernet) RX packets 1087 bytes 95556 (93.3 KiB) RX errors 0 dropped 0 overruns 0 frame 0 TX packets 171 bytes 19051 (18.6 KiB) TX errors 0 dropped 0 overruns 0 carrier 0 collisions 0

lo: flags=73<UP,LOOPBACK,RUNNING> mtu 65536 inet x.x.x.x netmask x.x.x.x inet6 ::1 prefixlen 128 scopeid 0x10 loop txqueuelen 1000 (Local Loopback) RX packets 0 bytes 0 (0.0 B) RX errors 0 dropped 0 overruns 0 frame 0 TX packets 0 bytes 0 (0.0 B) TX errors 0 dropped 0 overruns 0 carrier 0 collisions 0

wlan0: flags=4099<UP,BROADCAST,MULTICAST> mtu 1500 ether m.m.m.m txqueuelen 1000 (Ethernet) RX packets 0 bytes 0 (0.0 B) RX errors 0 dropped 0 overruns 0 frame 0 TX packets 0 bytes 0 (0.0 B) TX errors 0 dropped 0 overruns 0 carrier 0 collisions 0

USB Information

/: Bus 03.Port 1: Dev 1, Class=root_hub, Driver=dwc_otg/1p, 480M /: Bus 02.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/4p, 5000M /: Bus 01.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/1p, 480M | Port 1: Dev 2, If 0, Class=Hub, Driver=hub/4p, 480M | Port 3: Dev 3, If 0, Class=Human Interface Device, Driver=usbhid, 12M

config.txt

arm_freq=1500 audio_pwm_mode=514 config_hdmi_boost=5 core_freq=500 core_freq_min=250 disable_commandline_tags=2 disable_l2cache=1 display_hdmi_rotate=-1 display_lcd_rotate=-1 enable_gic=1 force_eeprom_read=1 force_pwm_open=1 framebuffer_depth=16 framebuffer_ignore_alpha=1 framebuffer_swap=1 gpu_freq=500 gpu_freq_min=500 init_uart_clock=0x2dc6c00 lcd_framerate=60 mask_gpu_interrupt0=1024 mask_gpu_interrupt1=0x10000 max_framebuffers=2 pause_burst_frames=1 program_serial_random=1 hdmi_force_cec_address:0=65535 hdmi_force_cec_address:1=65535 hdmi_pixel_freq_limit:0=0x11e1a300 hdmi_pixel_freq_limit:1=0x11e1a300 device_tree=- hdmi_cvt:0= hdmi_cvt:1= hdmi_edid_filename:0= hdmi_edid_filename:1= hdmi_timings:0= hdmi_timings:1=

cmdline.txt

coherent_pool=1M 8250.nr_uarts=0 cma=64M cma=256M smsc95xx.macaddr=DC:A6:32:16:EB:1D vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000 dwc_otg.lpm_enable=0 console=ttyS0,115200 console=tty1 root=PARTUUID=8232c186-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait

raspi-gpio settings

vcdbg log messages

debug_sym: vc_mem_copy: Unable to open '/dev/fb0': No such file or directory(2)

002748.915: arasan: arasan_emmc_open 002751.105: arasan: arasan_emmc_set_clock C0: 0x00000000 C1: 0x000ef447 emmc: 200000000 actual: 200000 div: 0x000001f4 target: 200000 min: 100000 max: 400000 delay: 10 002867.888: arasan: arasan_emmc_set_clock C0: 0x00000000 C1: 0x000ef447 emmc: 200000000 actual: 200000 div: 0x000001f4 target: 200000 min: 100000 max: 400000 delay: 10 002875.044: arasan: arasan_emmc_set_clock C0: 0x00000f00 C1: 0x000e01c7 emmc: 200000000 actual: 130039 div: 0x00000301 target: 130000 min: 100000 max: 400000 delay: 15 002916.536: arasan: arasan_emmc_set_clock C0: 0x00000f06 C1: 0x000e0307 emmc: 200000000 actual: 33333333 div: 0x00000003 target: 40000000 min: 0 max: 40000000 delay: 1 003194.207: brfs: File read: /mfs/sd/config.txt 003194.944: brfs: File read: 1735 bytes 003219.566: brfs: File read: /mfs/sd/config.txt 003420.401: gpioman: gpioman_get_pin_num: pin DISPLAY_DSI_PORT not defined 003422.882: *** Restart logging 003422.923: brfs: File read: 1735 bytes 003426.683: hdmi: HDMI:hdmi_get_state is deprecated, use hdmi_get_display_state instead 003430.053: hdmi: HDMI:hdmi_get_state is deprecated, use hdmi_get_display_state instead 003430.087: HDMI0: hdmi_pixel_encoding: 300000000

003430.101: HDMI1: hdmi_pixel_encoding: 300000000

003430.931: brfs: File read: /mfs/sd/cmdline.txt 003430.999: Read command line from file 'cmdline.txt': 003431.037: 'dwc_otg.lpm_enable=0 console=serial0,115200 console=tty1 root=PARTUUID=8232c186-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait' 003431.324: brfs: File read: 142 bytes 003877.973: brfs: File read: /mfs/sd/kernel7l.img 003878.009: Loading 'kernel7l.img' to 0x8000 size 0x5574d0 003882.309: No kernel trailer - assuming DT-capable 003882.363: brfs: File read: 5600464 bytes 003888.223: brfs: File read: /mfs/sd/bcm2711-rpi-4-b.dtb 003888.259: Loading 'bcm2711-rpi-4-b.dtb' to 0x55f4d0 size 0x9d5c 004112.380: brfs: File read: 40284 bytes 004114.946: brfs: File read: /mfs/sd/config.txt 004115.437: dtparam: audio=on 004141.481: brfs: File read: 1735 bytes 004155.408: brfs: File read: /mfs/sd/overlays/vc4-fkms-v3d.dtbo 004194.726: Loaded overlay 'vc4-fkms-v3d' 005510.679: Device tree loaded to 0x2eff5d00 (size 0xa26d) 005513.069: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined 008096.043: vchiq_core: vchiq_init_state: slot_zero = 0xded80000, is_master = 1 010701.431: brfs: File read: 1255 bytes

dmesg log

[ 0.000000] Booting Linux on physical CPU 0x0 [ 0.000000] Linux version 4.19.57-v7l+ (dom@buildbot) (gcc version 4.9.3 (crosstool-NG crosstool-ng-1.22.0-88-g8460611)) #1244 SMP Thu Jul 4 18:48:07 BST 2019 [ 0.000000] CPU: ARMv7 Processor [410fd083] revision 3 (ARMv7), cr=30c5383d [ 0.000000] CPU: div instructions available: patching division code [ 0.000000] CPU: PIPT / VIPT nonaliasing data cache, PIPT instruction cache [ 0.000000] OF: fdt: Machine model: Raspberry Pi 4 Model B Rev 1.1 [ 0.000000] Memory policy: Data cache writealloc [ 0.000000] cma: Reserved 256 MiB at 0x000000001ec00000 [ 0.000000] On node 0 totalpages: 1012736 [ 0.000000] DMA zone: 1728 pages used for memmap [ 0.000000] DMA zone: 0 pages reserved [ 0.000000] DMA zone: 196608 pages, LIFO batch:63 [ 0.000000] HighMem zone: 816128 pages, LIFO batch:63 [ 0.000000] random: get_random_bytes called from start_kernel+0xc0/0x4e8 with crng_init=0 [ 0.000000] percpu: Embedded 17 pages/cpu s39488 r8192 d21952 u69632 [ 0.000000] pcpu-alloc: s39488 r8192 d21952 u69632 alloc=17*4096 [ 0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1011008 [ 0.000000] Kernel command line: coherent_pool=1M 8250.nr_uarts=0 cma=64M cma=256M smsc95xx.macaddr=m.m.m.m vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000 dwc_otg.lpm_enable=0 console=ttyS0,115200 console=tty1 root=PARTUUID=8232c186-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait [ 0.000000] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes) [ 0.000000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes) [ 0.000000] Memory: 3735596K/4050944K available (8192K kernel code, 658K rwdata, 2340K rodata, 2048K init, 850K bss, 53204K reserved, 262144K cma-reserved, 3264512K highmem) [ 0.000000] Virtual kernel memory layout: vector : 0xffff0000 - 0xffff1000 ( 4 kB) fixmap : 0xffc00000 - 0xfff00000 (3072 kB) vmalloc : 0xf0800000 - 0xff800000 ( 240 MB) lowmem : 0xc0000000 - 0xf0000000 ( 768 MB) pkmap : 0xbfe00000 - 0xc0000000 ( 2 MB) modules : 0xbf000000 - 0xbfe00000 ( 14 MB) .text : 0x(ptrval) - 0x(ptrval) (10208 kB) .init : 0x(ptrval) - 0x(ptrval) (2048 kB) .data : 0x(ptrval) - 0x(ptrval) ( 659 kB) .bss : 0x(ptrval) - 0x(ptrval) ( 851 kB) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] ftrace: allocating 27981 entries in 83 pages [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16 [ 0.000000] GIC: Using split EOI/Deactivate mode [ 0.000000] arch_timer: cp15 timer(s) running at 54.00MHz (phys). [ 0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0xc743ce346, max_idle_ns: 440795203123 ns [ 0.000005] sched_clock: 56 bits at 54MHz, resolution 18ns, wraps every 4398046511102ns [ 0.000022] Switching to timer-based delay loop, resolution 18ns [ 0.000249] Console: colour dummy device 80x30 [ 0.000716] console [tty1] enabled [ 0.000767] Calibrating delay loop (skipped), value calculated using timer frequency.. 108.00 BogoMIPS (lpj=540000) [ 0.000810] pid_max: default: 32768 minimum: 301 [ 0.001088] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes) [ 0.001121] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes) [ 0.001883] CPU: Testing write buffer coherency: ok [ 0.002301] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000 [ 0.002941] Setting up static identity map for 0x200000 - 0x20003c [ 0.003113] rcu: Hierarchical SRCU implementation. [ 0.003976] smp: Bringing up secondary CPUs ... [ 0.004880] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001 [ 0.005885] CPU2: thread -1, cpu 2, socket 0, mpidr 80000002 [ 0.006854] CPU3: thread -1, cpu 3, socket 0, mpidr 80000003 [ 0.006986] smp: Brought up 1 node, 4 CPUs [ 0.007053] SMP: Total of 4 processors activated (432.00 BogoMIPS). [ 0.007076] CPU: All CPU(s) started in HYP mode. [ 0.007096] CPU: Virtualization extensions available. [ 0.007886] devtmpfs: initialized [ 0.017937] VFP support v0.3: implementor 41 architecture 3 part 40 variant 8 rev 0 [ 0.018175] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns [ 0.018217] futex hash table entries: 1024 (order: 4, 65536 bytes) [ 0.025525] pinctrl core: initialized pinctrl subsystem [ 0.026376] NET: Registered protocol family 16 [ 0.029200] DMA: preallocated 1024 KiB pool for atomic coherent allocations [ 0.030598] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers. [ 0.030630] hw-breakpoint: maximum watchpoint size is 8 bytes. [ 0.030833] Serial: AMBA PL011 UART driver [ 0.033864] bcm2835-mbox fe00b880.mailbox: mailbox enabled [ 0.069502] bcm2835-dma fe007000.dma: DMA legacy API manager at (ptrval), dmachans=0x1 [ 0.071898] vgaarb: loaded [ 0.072274] SCSI subsystem initialized [ 0.072483] usbcore: registered new interface driver usbfs [ 0.072548] usbcore: registered new interface driver hub [ 0.072661] usbcore: registered new device driver usb [ 0.090391] raspberrypi-firmware soc:firmware: Attached to firmware from 2019-07-09 14:37, variant start [ 0.100116] raspberrypi-firmware soc:firmware: Firmware hash is d2b1b7fb01475cb3914b2086299e32d724e832f1 [ 0.111556] clocksource: Switched to clocksource arch_sys_counter [ 0.188373] VFS: Disk quotas dquot_6.6.0 [ 0.188471] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes) [ 0.188641] FS-Cache: Loaded [ 0.188828] CacheFiles: Loaded [ 0.189328] simple-framebuffer: probe of 0.framebuffer failed with error -12 [ 0.198377] NET: Registered protocol family 2 [ 0.199054] tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 6144 bytes) [ 0.199099] TCP established hash table entries: 8192 (order: 3, 32768 bytes) [ 0.199181] TCP bind hash table entries: 8192 (order: 4, 65536 bytes) [ 0.199265] TCP: Hash tables configured (established 8192 bind 8192) [ 0.199396] UDP hash table entries: 512 (order: 2, 16384 bytes) [ 0.199440] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes) [ 0.199744] NET: Registered protocol family 1 [ 0.200283] RPC: Registered named UNIX socket transport module. [ 0.200309] RPC: Registered udp transport module. [ 0.200330] RPC: Registered tcp transport module. [ 0.200352] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.200379] PCI: CLS 0 bytes, default 64 [ 0.203372] Initialise system trusted keyrings [ 0.203564] workingset: timestamp_bits=14 max_order=20 bucket_order=6 [ 0.212456] FS-Cache: Netfs 'nfs' registered for caching [ 0.212962] NFS: Registering the id_resolver key type [ 0.213000] Key type id_resolver registered [ 0.213022] Key type id_legacy registered [ 0.213052] nfs4filelayout_init: NFSv4 File Layout Driver Registering... [ 0.215249] Key type asymmetric registered [ 0.215276] Asymmetric key parser 'x509' registered [ 0.215396] bounce: pool size: 64 pages [ 0.215446] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 250) [ 0.215618] io scheduler noop registered [ 0.215642] io scheduler deadline registered (default) [ 0.215811] io scheduler cfq registered [ 0.215834] io scheduler mq-deadline registered (default) [ 0.215857] io scheduler kyber registered [ 0.244378] brcm-pcie fd500000.pcie: dmabounce: initialised - 32768 kB, threshold 0x00000000c0000000 [ 0.244423] brcm-pcie fd500000.pcie: could not get clock [ 0.244495] brcm-pcie fd500000.pcie: host bridge /scb/pcie@7d500000 ranges: [ 0.244547] brcm-pcie fd500000.pcie: MEM 0x600000000..0x603ffffff -> 0xf8000000 [ 0.301591] brcm-pcie fd500000.pcie: link up, 5.0 Gbps x1 (!SSC) [ 0.301879] brcm-pcie fd500000.pcie: PCI host bridge to bus 0000:00 [ 0.301908] pci_bus 0000:00: root bus resource [bus 00-01] [ 0.301938] pci_bus 0000:00: root bus resource [mem 0x600000000-0x603ffffff] (bus address [0xf8000000-0xfbffffff]) [ 0.302000] pci 0000:00:00.0: [14e4:2711] type 01 class 0x060400 [ 0.302135] pci 0000:00:00.0: PME# supported from D0 D3hot [ 0.304815] PCI: bus0: Fast back to back transfers disabled [ 0.304846] pci 0000:00:00.0: bridge configuration invalid ([bus 00-00]), reconfiguring [ 0.305022] pci 0000:01:00.0: [1106:3483] type 00 class 0x0c0330 [ 0.305082] pci 0000:01:00.0: reg 0x10: [mem 0x00000000-0x00000fff 64bit] [ 0.305249] pci 0000:01:00.0: PME# supported from D0 D3cold [ 0.307849] PCI: bus1: Fast back to back transfers disabled [ 0.307879] pci_bus 0000:01: busn_res: [bus 01] end is updated to 01 [ 0.307924] pci 0000:00:00.0: BAR 8: assigned [mem 0x600000000-0x6000fffff] [ 0.307957] pci 0000:01:00.0: BAR 0: assigned [mem 0x600000000-0x600000fff 64bit] [ 0.308005] pci 0000:00:00.0: PCI bridge to [bus 01] [ 0.308034] pci 0000:00:00.0: bridge window [mem 0x600000000-0x6000fffff] [ 0.308107] pci 0000:00:00.0: enabling device (0140 -> 0142) [ 0.308143] pci 0000:01:00.0: enabling device (0140 -> 0142) [ 0.311298] iproc-rng200 fe104000.rng: hwrng registered [ 0.311527] vc-mem: phys_addr:0x00000000 mem_base=0x3ec00000 mem_size:0x40000000(1024 MiB) [ 0.312075] vc-sm: Videocore shared memory driver [ 0.312472] gpiomem-bcm2835 fe200000.gpiomem: Initialised: Registers at 0xfe200000 [ 0.322373] brd: module loaded [ 0.331832] loop: module loaded [ 0.332566] Loading iSCSI transport class v2.0-870. [ 0.334208] libphy: Fixed MDIO Bus: probed [ 0.334644] bcmgenet fd580000.genet: failed to get enet clock [ 0.334674] bcmgenet fd580000.genet: GENET 5.0 EPHY: 0x0000 [ 0.334705] bcmgenet fd580000.genet: failed to get enet-wol clock [ 0.334734] bcmgenet fd580000.genet: failed to get enet-eee clock [ 0.334989] unimac-mdio unimac-mdio.-19: DMA mask not set [ 0.351593] libphy: bcmgenet MII bus: probed [ 0.392088] unimac-mdio unimac-mdio.-19: Broadcom UniMAC MDIO bus at 0x(ptrval) [ 0.392981] usbcore: registered new interface driver r8152 [ 0.393055] usbcore: registered new interface driver lan78xx [ 0.393120] usbcore: registered new interface driver smsc95xx [ 0.393397] xhci_hcd 0000:01:00.0: xHCI Host Controller [ 0.393441] xhci_hcd 0000:01:00.0: new USB bus registered, assigned bus number 1 [ 0.395219] xhci_hcd 0000:01:00.0: hcc params 0x002841eb hci version 0x100 quirks 0x0000000000000890 [ 0.395388] genirq: irq_chip Brcm_MSI did not update eff. affinity mask of irq 55 [ 0.396013] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 4.19 [ 0.396048] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1 [ 0.396078] usb usb1: Product: xHCI Host Controller [ 0.396101] usb usb1: Manufacturer: Linux 4.19.57-v7l+ xhci-hcd [ 0.396124] usb usb1: SerialNumber: 0000:01:00.0 [ 0.396648] hub 1-0:1.0: USB hub found [ 0.396713] hub 1-0:1.0: 1 port detected [ 0.397129] xhci_hcd 0000:01:00.0: xHCI Host Controller [ 0.397165] xhci_hcd 0000:01:00.0: new USB bus registered, assigned bus number 2 [ 0.397201] xhci_hcd 0000:01:00.0: Host supports USB 3.0 SuperSpeed [ 0.397557] usb usb2: New USB device found, idVendor=1d6b, idProduct=0003, bcdDevice= 4.19 [ 0.397590] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1 [ 0.397618] usb usb2: Product: xHCI Host Controller [ 0.397641] usb usb2: Manufacturer: Linux 4.19.57-v7l+ xhci-hcd [ 0.397664] usb usb2: SerialNumber: 0000:01:00.0 [ 0.398157] hub 2-0:1.0: USB hub found [ 0.398222] hub 2-0:1.0: 4 ports detected [ 0.399320] dwc_otg: version 3.00a 10-AUG-2012 (platform bus) [ 0.424895] dwc_otg fe980000.usb: base=(ptrval) [ 0.625244] Core Release: 2.80a [ 0.625271] Setting default values for core params [ 0.625312] Finished setting default values for core params [ 0.825649] Using Buffer DMA mode [ 0.825673] Periodic Transfer Interrupt Enhancement - disabled [ 0.825695] Multiprocessor Interrupt Enhancement - disabled [ 0.825720] OTG VER PARAM: 0, OTG VER FLAG: 0 [ 0.825787] Dedicated Tx FIFOs mode [ 0.826412] WARN::dwc_otg_hcd_init:1045: FIQ DMA bounce buffers: virt = ded30000 dma = 0x00000000ded30000 len=9024 [ 0.826459] FIQ FSM acceleration enabled for : Non-periodic Split Transactions Periodic Split Transactions High-Speed Isochronous Endpoints Interrupt/Control Split Transaction hack enabled [ 0.826521] dwc_otg: Microframe scheduler enabled [ 0.826628] WARN::hcd_init_fiq:457: FIQ on core 1 [ 0.826661] WARN::hcd_init_fiq:458: FIQ ASM at c07ae05c length 36 [ 0.826693] WARN::hcd_init_fiq:497: MPHI regs_base at f0810200 [ 0.826741] dwc_otg fe980000.usb: DWC OTG Controller [ 0.826785] dwc_otg fe980000.usb: new USB bus registered, assigned bus number 3 [ 0.826842] dwc_otg fe980000.usb: irq 36, io mem 0x00000000 [ 0.826907] Init: Port Power? op_state=1 [ 0.826928] Init: Power Port (0) [ 0.827185] usb usb3: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 4.19 [ 0.827219] usb usb3: New USB device strings: Mfr=3, Product=2, SerialNumber=1 [ 0.827248] usb usb3: Product: DWC OTG Controller [ 0.827271] usb usb3: Manufacturer: Linux 4.19.57-v7l+ dwc_otg_hcd [ 0.827295] usb usb3: SerialNumber: fe980000.usb [ 0.827824] hub 3-0:1.0: USB hub found [ 0.827887] hub 3-0:1.0: 1 port detected [ 0.828466] dwc_otg: FIQ enabled [ 0.828475] dwc_otg: NAK holdoff enabled [ 0.828484] dwc_otg: FIQ split-transaction FSM enabled [ 0.828497] Module dwc_common_port init [ 0.828702] usbcore: registered new interface driver uas [ 0.828826] usbcore: registered new interface driver usb-storage [ 0.829000] mousedev: PS/2 mouse device common for all mice [ 0.830142] bcm2835-wdt bcm2835-wdt: Broadcom BCM2835 watchdog timer [ 0.830348] bcm2835-cpufreq: min=600000 max=1500000 [ 0.830933] sdhci: Secure Digital Host Controller Interface driver [ 0.830957] sdhci: Copyright(c) Pierre Ossman [ 0.831349] mmc-bcm2835 fe300000.mmcnr: could not get clk, deferring probe [ 0.831811] sdhci-pltfm: SDHCI platform and OF driver helper [ 0.834786] ledtrig-cpu: registered to indicate activity on CPUs [ 0.834940] hidraw: raw HID events driver (C) Jiri Kosina [ 0.835075] usbcore: registered new interface driver usbhid [ 0.835097] usbhid: USB HID core driver [ 0.835839] vchiq: vchiq_init_state: slot_zero = (ptrval), is_master = 0

[ 0.845439] [vc_sm_connected_init]: end - returning 0 [ 0.846485] Initializing XFRM netlink socket [ 0.846526] NET: Registered protocol family 17 [ 0.846615] Key type dns_resolver registered [ 0.846940] Registering SWP/SWPB emulation handler [ 0.847520] registered taskstats version 1 [ 0.847549] Loading compiled-in X.509 certificates [ 0.855258] uart-pl011 fe201000.serial: cts_event_workaround enabled [ 0.855337] fe201000.serial: ttyAMA0 at MMIO 0xfe201000 (irq = 33, base_baud = 0) is a PL011 rev2 [ 0.858262] bcm2835-power bcm2835-power: Broadcom BCM2835 power domains driver [ 0.858796] brcmstb_thermal fd5d2200.thermal: registered AVS TMON of-sensor driver [ 0.859415] mmc-bcm2835 fe300000.mmcnr: mmc_debug:0 mmc_debug2:0 [ 0.859441] mmc-bcm2835 fe300000.mmcnr: DMA channel allocated [ 0.884729] sdhci-iproc fe340000.emmc2: Linked as a consumer to regulator.1 [ 0.903987] mmc1: queuing unknown CIS tuple 0x80 (2 bytes) [ 0.905607] mmc1: queuing unknown CIS tuple 0x80 (3 bytes) [ 0.907269] mmc1: queuing unknown CIS tuple 0x80 (3 bytes) [ 0.910164] mmc1: queuing unknown CIS tuple 0x80 (7 bytes) [ 0.911800] mmc1: queuing unknown CIS tuple 0x80 (3 bytes) [ 0.919803] mmc0: SDHCI controller on fe340000.emmc2 [fe340000.emmc2] using ADMA [ 0.922309] of_cfs_init [ 0.922401] of_cfs_init: OK [ 0.922988] Waiting for root device PARTUUID=8232c186-02... [ 0.969047] random: fast init done [ 0.971597] usb 1-1: new high-speed USB device number 2 using xhci_hcd [ 0.988285] mmc1: new high speed SDIO card at address 0001 [ 1.022219] mmc0: new ultra high speed DDR50 SDHC card at address 0001 [ 1.023331] mmcblk0: mmc0:0001 EB1QT 29.8 GiB [ 1.024434] mmcblk0: p1 p2 [ 1.050298] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null) [ 1.050363] VFS: Mounted root (ext4 filesystem) readonly on device 179:2. [ 1.055572] devtmpfs: mounted [ 1.062147] Freeing unused kernel memory: 2048K [ 1.081813] Run /sbin/init as init process [ 1.163027] usb 1-1: New USB device found, idVendor=2109, idProduct=3431, bcdDevice= 4.20 [ 1.163066] usb 1-1: New USB device strings: Mfr=0, Product=1, SerialNumber=0 [ 1.163094] usb 1-1: Product: USB2.0 Hub [ 1.164698] hub 1-1:1.0: USB hub found [ 1.165004] hub 1-1:1.0: 4 ports detected [ 1.456915] systemd[1]: System time before build time, advancing clock. [ 1.501621] usb 1-1.3: new full-speed USB device number 3 using xhci_hcd [ 1.542011] NET: Registered protocol family 10 [ 1.543207] Segment Routing with IPv6 [ 1.569055] systemd[1]: systemd 241 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD -IDN2 +IDN -PCRE2 default-hierarchy=hybrid) [ 1.569762] systemd[1]: Detected architecture arm. [ 1.579703] systemd[1]: Set hostname to . [ 1.587464] systemd[1]: Failed to bump fs.file-max, ignoring: Invalid argument [ 1.652224] usb 1-1.3: New USB device found, idVendor=24e0, idProduct=001b, bcdDevice= 0.01 [ 1.652274] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3 [ 1.652314] usb 1-1.3: Product: Yocto-Volt [ 1.652339] usb 1-1.3: Manufacturer: Yoctopuce [ 1.652363] usb 1-1.3: SerialNumber: VOLTAGE1-1DCAC [ 1.664018] hid-generic 0003:24E0:001B.0001: hiddev96,hidraw0: USB HID v1.11 Device [Yoctopuce Yocto-Volt] on usb-0000:01:00.0-1.3/input0 [ 1.839467] systemd[1]: File /lib/systemd/system/systemd-journald.service:12 configures an IP firewall (IPAddressDeny=any), but the local system does not support BPF/cgroup based firewalling. [ 1.839529] systemd[1]: Proceeding WITHOUT firewalling in effect! (This warning is only shown for the first loaded unit using IP firewalling.) [ 2.156546] random: systemd: uninitialized urandom read (16 bytes read) [ 2.164350] random: systemd: uninitialized urandom read (16 bytes read) [ 2.164965] systemd[1]: Listening on udev Control Socket. [ 2.165679] random: systemd: uninitialized urandom read (16 bytes read) [ 2.165988] systemd[1]: Listening on initctl Compatibility Named Pipe. [ 2.166728] systemd[1]: Listening on udev Kernel Socket. [ 2.167569] systemd[1]: Listening on fsck to fsckd communication Socket. [ 2.790684] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null) [ 2.894451] systemd-journald[123]: Received request to flush runtime journal from PID 1 [ 3.330908] argon-mem feb00000.hevc-decoder: argon-hevcmem initialised: Registers at 0xfeb00000 length 0x0000ffff [ 3.331232] argon-mem feb10000.argon-local-intc: argon-intcmem initialised: Registers at 0xfeb10000 length 0x00000fff [ 3.332377] argon-mem feb20000.h264-decoder: argon-h264mem initialised: Registers at 0xfeb20000 length 0x0000ffff [ 3.332859] argon-mem feb30000.vp9-decoder: argon-vp9mem initialised: Registers at 0xfeb30000 length 0x0000ffff [ 3.352935] vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned. [ 3.354927] bcm2835_vc_sm_cma_probe: Videocore shared memory driver

[ 3.355544] [vc_sm_connected_init]: installed successfully [ 3.360266] media: Linux media interface: v0.10 [ 3.384274] videodev: Linux video capture interface: v2.00 [ 3.407957] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned. [ 3.423391] bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned. [ 3.424711] bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned. [ 3.432290] bcm2835-codec bcm2835-codec: Device registered as /dev/video10 [ 3.432303] bcm2835-codec bcm2835-codec: Loaded V4L2 decode [ 3.452741] bcm2835-codec bcm2835-codec: Device registered as /dev/video11 [ 3.452754] bcm2835-codec bcm2835-codec: Loaded V4L2 encode [ 3.459529] bcm2835-codec bcm2835-codec: Device registered as /dev/video12 [ 3.459543] bcm2835-codec bcm2835-codec: Loaded V4L2 isp [ 3.548036] snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned. [ 3.601714] bcm2835_audio soc:audio: card created with 8 channels [ 3.684125] cfg80211: Loading compiled-in X.509 certificates for regulatory database [ 3.752410] [drm] Initialized v3d 1.0.0 20180419 for fec00000.v3d on minor 0 [ 3.793529] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7' [ 3.844753] [drm] No displays found. Consider forcing hotplug if HDMI is attached [ 3.844847] vc4-drm soc:gpu: bound fe600000.firmwarekms (ops vc4_fkms_ops [vc4]) [ 3.844868] brcmfmac: F1 signature read @0x18000000=0x15264345 [ 3.846789] [drm] Initialized vc4 0.0.0 20140616 for soc:gpu on minor 1 [ 3.846802] [drm] Supports vblank timestamp caching Rev 2 (21.10.2013). [ 3.846811] [drm] No driver support for vblank timestamp query. [ 3.846820] [drm] Setting vblank_disable_immediate to false because get_vblank_timestamp == NULL [ 3.856052] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6 [ 3.856709] usbcore: registered new interface driver brcmfmac [ 4.072666] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6 [ 4.086361] brcmfmac: brcmf_c_preinit_dcmds: Firmware: BCM4345/6 wl0: Feb 27 2018 03:15:32 version 7.45.154 (r684107 CY) FWID 01-4fbe0b04 [ 5.772585] uart-pl011 fe201000.serial: no DMA platform data [ 5.780008] 8021q: 802.1Q VLAN Support v1.8 [ 5.861296] random: crng init done [ 5.861311] random: 7 urandom warning(s) missed due to ratelimiting [ 5.983623] Adding 102396k swap on /var/swap. Priority:-2 extents:1 across:102396k SSFS [ 6.029564] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready [ 6.029572] brcmfmac: power management disabled [ 6.321808] bcmgenet fd580000.genet: configuring instance for external RGMII (no delay) [ 6.322026] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready [ 7.351821] bcmgenet fd580000.genet eth0: Link is Down [ 11.511832] bcmgenet fd580000.genet eth0: Link is Up - 1Gbps/Full - flow control rx/tx [ 11.511867] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready [ 12.405931] Bluetooth: Core ver 2.22 [ 12.406004] NET: Registered protocol family 31 [ 12.406014] Bluetooth: HCI device and connection manager initialized [ 12.406035] Bluetooth: HCI socket layer initialized [ 12.406049] Bluetooth: L2CAP socket layer initialized [ 12.406094] Bluetooth: SCO socket layer initialized [ 12.418032] Bluetooth: HCI UART driver ver 2.3 [ 12.418048] Bluetooth: HCI UART protocol H4 registered [ 12.418130] Bluetooth: HCI UART protocol Three-wire (H5) registered [ 12.418371] Bluetooth: HCI UART protocol Broadcom registered [ 12.603357] Bluetooth: BNEP (Ethernet Emulation) ver 1.3 [ 12.603362] Bluetooth: BNEP filters: protocol multicast [ 12.603372] Bluetooth: BNEP socket layer initialized

P33M commented 4 years ago

Linux raspberrypi 4.19.57-v7l+ #1244 SMP Thu Jul 4 18:48:07 BST 2019 armv7l GNU/Linux Does the issue exist on a newer apt kernel? There have been several xhci-related fixes in the meantime.

yoctopuce commented 4 years ago

I've updated the kernel with sudo rpi-update and the bug is still present:

System Information
------------------

Raspberry Pi 4 Model B Rev 1.1
PRETTY_NAME="Raspbian GNU/Linux 10 (buster)"
NAME="Raspbian GNU/Linux"
VERSION_ID="10"
VERSION="10 (buster)"

Raspberry Pi reference 2019-07-10
Generated using pi-gen, https://github.com/RPi-Distro/pi-gen, 175dfb027ffabd4b8d5080097af0e51ed9a4a56c, stage2

Linux raspberrypi 4.19.75-v7l+ #1271 SMP Mon Sep 30 13:51:15 BST 2019 armv7l GNU/Linux
Revision    : c03111
Serial      : 100000001060871a
Model       : Raspberry Pi 4 Model B Rev 1.1
Throttled flag  : throttled=0x0
Camera          : supported=0 detected=0

P33M commented 4 years ago

Please capture an event trace that includes plugging the device in and running the command until it fails. Once the command fails, immediately unplug the device.

sudo -s
cd /sys/kernel/debug/tracing
echo 1 > events/xhci-hcd/enable
[Plug device in]
[Perform device manipulation until it breaks]
[Disconnect device]
cat trace > /home/pi/some-sensible-filename.txt

The trace is going to be large, so it may be better to add as an attachment rather than inline. Ideally, capture a trace where the device breaks on the first invocation of your test program.

To clear a previous trace (events will still be enabled):

# echo > trace

yoctopuce commented 4 years ago

I've first updated the firmware to see if I get any "magical bug fix" but the bug is still present.

Then I've run your test and updated the bug report repository with the requested traces:

https://github.com/yoctopuce-examples/raspberry_4_usb_bug/tree/master/xhci-hcd_traces

Let us know if you need any other informations?

Note: If you want to reproduce the bug in your lab, we can send you a device free of charge. Just send use an email to support@yoctopuce.com.

P33M commented 4 years ago

I am unable to reproduce the bug on either a Yocto-Light-V3 or a Yocto-RelayHi1

Both devices have been updated to latest Yocto firmwares. The Pi 4 has no other devices attached and is using VLI firmware version 0137ab.

pi@raspberrypi:~/raspberry_4_usb_bug $ sudo ./a.out
this is a simple program that exhibit a bug in the USB stack
of the Raspberry PI Zero and any Yoctopuce device
Use libUSB v1.0.22.11312
List all Yoctopuce devices present on this host:
 - USB dev: LIGHTMK3-9342A (24E0:50:0)
1 Yoctopuce devices are present
\ Test device LIGHTMK3-9342A (24E0:50)
+ Send USB pkt no 0
- rd_callback for LIGHTMK3-9342A : response 0 is valid (len=64)
+ Send USB pkt no 1
- rd_callback for LIGHTMK3-9342A : response 1 is valid (len=64)
+ Send USB pkt no 2
- rd_callback for LIGHTMK3-9342A : response 2 is valid (len=64)
+ Send USB pkt no 3
- rd_callback for LIGHTMK3-9342A : response 3 is valid (len=64)
+ Send USB pkt no 4
- rd_callback for LIGHTMK3-9342A : response 4 is valid (len=64)
+ Send USB pkt no 5
- rd_callback for LIGHTMK3-9342A : response 5 is valid (len=64)
+ Send USB pkt no 6
- rd_callback for LIGHTMK3-9342A : response 6 is valid (len=64)
+ Send USB pkt no 7
- rd_callback for LIGHTMK3-9342A : response 7 is valid (len=64)
+ Send USB pkt no 8
- rd_callback for LIGHTMK3-9342A : response 8 is valid (len=64)
+ Send USB pkt no 9
- rd_callback for LIGHTMK3-9342A : response 9 is valid (len=64)
+ Send USB pkt no 10
- rd_callback for LIGHTMK3-9342A : response 10 is valid (len=64)
+ Send USB pkt no 11
- rd_callback for LIGHTMK3-9342A : response 11 is valid (len=64)
+ Send USB pkt no 12
- rd_callback for LIGHTMK3-9342A : response 12 is valid (len=64)
+ Send USB pkt no 13
- rd_callback for LIGHTMK3-9342A : response 13 is valid (len=64)
+ Send USB pkt no 14
- rd_callback for LIGHTMK3-9342A : response 14 is valid (len=64)
= result: 15 pkt sent vs 15 pkt received
Cancel and free all pending transactions

If I revert to VLI firmware 013701, the test program fails:

pi@raspberrypi:~/raspberry_4_usb_bug $ sudo ./a.out
this is a simple program that exhibit a bug in the USB stack
of the Raspberry PI Zero and any Yoctopuce device
Use libUSB v1.0.22.11312
List all Yoctopuce devices present on this host:
 - USB dev: LIGHTMK3-9342A (24E0:50:0)
1 Yoctopuce devices are present
\ Test device LIGHTMK3-9342A (24E0:50)
- need to detach kernel driver
+ Send USB pkt no 0
No USB pkt received after 5 second
= result: 1 pkt sent vs 0 pkt received
!!! ERROR : 1 packets missing !!!
Cancel and free all pending transactions

An upgrade of the VLI firmware can be done semi-automatically by installing the apt package rpi-eeprom and rebooting. To check the current version of bootloader and VLI firmware, run sudo rpi-eeprom-update with no arguments.

yoctopuce commented 4 years ago

You are right with the latest firmware the bug is fixed.

Now the big questions are.

When this new firmware will be installed by default?
How can I detect which firmware is installed without rpi-eeprom package?
And do you have any official documentation on the magic command sudo rpi-eeprom-update -a?
What is the difference between rpi-eeprom-update and sudo rpi-update ? Will one day rpi-update install this new firmware?

The problem is that we have multiples customers who are using our product on Raspberry Pi 4 and our product is not working correctly on it. It would be nice to have some documentation which explain what the sudo rpi-eeprom-update -a do and what will be changed. Do you have some documentation and/or release notes where we can forward them to?

P33M commented 4 years ago

https://www.raspberrypi.org/forums/viewtopic.php?f=29&t=255001

When this new firmware will be installed by default?

It is installed by default if the rpi-eeprom package is installed. The package is not yet a default package but this will change soon.

How can I detect which firmware is installed without rpi-eeprom package?

The package installs a tool that reads the pci config space for the firmware version. Alternatively, use the pciutils tool lspci to read the config space:

pi@raspberrypi:~$ sudo lspci -xxx
01:00.0 USB controller: VIA Technologies, Inc. VL805 USB 3.0 Host Controller (rev 01)
00: 06 11 83 34 46 05 10 00 01 30 03 0c 10 00 00 00
10: 04 00 00 f8 00 00 00 00 00 00 00 00 00 00 00 00
20: 00 00 00 00 00 00 00 00 00 00 00 00 06 11 83 34
30: 00 00 00 00 80 00 00 00 00 00 00 00 37 01 00 00
40: 00 00 00 00 00 01 00 00 09 30 d0 1e 00 00 00 00
50: ab 37 01 00 00 00 00 00 00 00 00 00 06 11 83 34
60: 30 20 00 00 00 00 00 00 00 00 00 00 00 00 00 00
70: 00 00 00 00 00 00 00 00 f0 00 04 00 00 00 00 00
80: 01 90 c3 89 00 00 00 00 00 00 00 00 00 00 00 00
90: 05 c4 85 00 fc ff ff ff 0f 00 00 00 40 65 00 00
a0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
b0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
c0: 00 20 00 00 10 00 02 00 01 80 00 00 10 28 10 00
d0: 12 5c 06 00 43 00 12 10 00 00 00 00 00 00 00 00
e0: 00 00 00 00 00 00 00 00 12 00 00 00 00 00 00 00
f0: 00 00 00 00 22 00 01 00 00 00 00 00 00 00 00 00

The firmware version is at offset 0x50 and is 4 bytes long: ab 37 01 00 => 000137ab

And do you have any official documentation on the magic command sudo rpi-eeprom-update -a

The program is a shell script. Documentation on the bootloader and bootloader utility is here: https://www.raspberrypi.org/documentation/hardware/raspberrypi/booteeprom.md

What is the difference between rpi-eeprom-update and sudo rpi-update ? Will one day rpi-update install this new firmware?

rpi-update will never touch bootloader firmware. rpi-update only updates files on the boot partition of the SD card and any associated kernel files.

JamesH65 commented 4 years ago

rpi-update should not be used for general updates. It pulls in untested beta software, so should not be recommended to end users. Use apt for all updating.

yoctopuce commented 4 years ago

I've done more intensive test and I confirm that the following commands fix the issue:

sudo apt-get install rpi-eeprom
sudo rpi-eeprom-update -a

Thank's for your help

sbazaz commented 4 years ago

Hi yoctopuce,

We are experiencing the same issue with one of our HID devices and RPI4, to be clear the HID device is not one of your products. The RPI4 firmware update improves the number of packet losses on RPI4 but does not eliminate it for us. I look at the USB bus traces you posted and noticed that you send one request per second and I was wondering if you ever performed the test at much higher rate (maybe send the requests in a tight loop) to see if any packet loss occurs?

Thanks

yoctopuce commented 4 years ago

Our production code send much more packet (up to 1 every millisecond) and everything work fine.

JacoFourie commented 4 years ago

Hi. We are starting to use LibUSB on the Pi. On the Pi 4 all works fine. But on the Pi 3 I get random corrupt data and timeouts. Is there somthing I need to do on the Pi 3 to get it to work the same way as the Pi 4 ?

yoctopuce commented 4 years ago

No. our code work on all Raspberry Pi.

JacoFourie commented 4 years ago

Hi. do you use LibUSB 1.0.0 ? or do you use Libhidapi-libusb or libhidapi-hidraw ?

yoctopuce commented 4 years ago

LibUSB 1.0.0.

You can have a look at the source code of our C++ library: https://github.com/yoctopuce/yoctolib_cpp/blob/master/Sources/yapi/ypkt_lin.c

JacoFourie commented 4 years ago

I am getting random timeouts and corrupted data on the Pi 3 when I use linUSB. If I use linhidapi_libusb I aslo get the same errors but if I use libhidapi_hidraw then all works fine. I am communicating with a very slow usb device. Where can I start to look why the code does not work on the Pi3 but well on the Pi 4 ?

yoctopuce commented 4 years ago

Hi, it seems that the bug is not completely fixed.

I've updated the distributions and the EEPROM but without any success

root@raspberrypi:/home/pi/raspberry_4_usb_bug# rpi-eeprom-update
BCM2711 detected
BOOTLOADER: up-to-date
CURRENT: Tue 10 Sep 10:41:50 UTC 2019 (1568112110)
 LATEST: Tue 10 Sep 10:41:50 UTC 2019 (1568112110)
VL805: up-to-date
CURRENT: 000137ad
 LATEST: 000137ad
root@raspberrypi:/home/pi/raspberry_4_usb_bug# uname -a
Linux raspberrypi 4.19.97-v7l+ #1294 SMP Thu Jan 30 13:21:14 GMT 2020 armv7l GNU/Linux

When I run the same test but for longer and with more devices (>4 devices) I've randomly have the same issue: I no not receive one USB packet. The problem seem to be some kind of racing condition and is very hard to isolate.

What I've been able to see it that every time the USB capture (done with usbmon) end with a URB status of -108:

db1aa600 2077058666 S Ci:1:024:0 s 80 06 0303 0000 0200 512 <
db1aa600 2077061564 C Ci:1:024:0 0 30 = 1e035900 50005700 4d005400 58003000 31002d00 42003900 36003200 3500
db1aa600 2077062012 S Ci:1:020:0 s 80 06 0303 0000 0200 512 <
db1aa600 2077063437 C Ci:1:020:0 0 30 = 1e035900 42005500 54005400 4f004e00 31002d00 32003000 37003200 4400
db1aa600 2077063804 S Ci:1:017:0 s 80 06 0303 0000 0200 512 <
db1aa600 2077065811 C Ci:1:017:0 0 30 = 1e035900 50005700 4d005200 58003000 31002d00 41004500 33003900 3100
db1aa600 2077066161 S Ci:1:015:0 s 80 06 0303 0000 0200 512 <
db1aa600 2077067936 C Ci:1:015:0 0 30 = 1e035200 45004c00 41005900 4c004f00 31002d00 32003700 45004100 4200
db1aa600 2077068312 S Ci:1:022:0 s 80 06 0303 0000 0200 512 <
db1aa600 2077069687 C Ci:1:022:0 0 30 = 1e034c00 49004700 48005400 4d004b00 31002d00 39003500 36004300 3900
db1aa600 2077070826 S Ci:1:023:0 s 80 06 0303 0000 0200 512 <
db1aa600 2077074313 C Ci:1:023:0 0 32 = 20035900 52004700 42004c00 45004400 32002d00 31003000 41003400 44004500
db1aa600 2077074698 S Ci:1:019:0 s 80 06 0303 0000 0200 512 <
db1aa600 2077077688 C Ci:1:019:0 0 30 = 1e034c00 49004700 48005400 4d004b00 31002d00 39003500 36004100 4600
db1aa600 2077078338 S Ii:1:024:1 -115:1 64 <
db1aaa80 2077078467 S Io:1:024:1 -115:1 64 = 00150902 01000100 dc000000 00000000 00000000 00000000 00000000 00000000
db1aaa80 2077080194 C Io:1:024:1 0:1 64 >
db1aa600 2082086647 C Ii:1:024:1 -108:1 0

I've updated the debug program to run the same test for longer and multiples time: https://github.com/yoctopuce-examples/raspberry_4_usb_bug

Could you see if you are able to reproduce this issue?

sbazaz commented 4 years ago

Our USB HID products show the same problem on RPI4. They work without any issues on other versions of RPI.

It seems when bInterval value of the out endpoint is set to 1, the host side driver occasionally does not pass the reply from the device on to libusb even though it was present on the bus.

Changing the out endpoint descriptor bInterval value from 1 to 2 in our device's firmware makes the problem stop occurring. For now we had to use this change as a workaround until the issue is fixed in RPI4.

IvoBCD commented 3 years ago

We're also noticing this, with RPI4 SiLabs CP2112 (both with kernel driver, and user-space driver). And yes, this device also has an out endpoint with bInterval set to 1. Unfortunately we can't change bInterval.

d-csr commented 3 years ago

I have a similar problem with a 3rd party device, bInterval=0, using interrupts. It randomly just misses packets and needs to be reset to work again.

srinsoz commented 3 years ago

Changing the bInterval cannot be done for our devices, doing that will have performance drawback on all other platform (including Raspberry Pi 3). Does anyone is still investigating this issue?

sirus20x6 commented 3 years ago

We believe we are having this issue with our custom usb full speed hardware, but changing the binterval does not seem to help us.

jmw182 commented 1 year ago

I am also experiencing this issue with an 8 GB Raspberry Pi 4 with the latest VL805 firmware (000138a1). I have tried both the latest 64-bit Raspberry Pi OS (Bullseye) and Ubuntu 22.04 (Jammy). My device uses bInterval 1 and the raspberry pi frequently fails to read from the device (HID interrupt reads). I do not have this issue when using a raspberry pi 3B+.

Are there any updates on this issue?

buha commented 11 months ago

I'm experiencing this issue on Raspberry Pi 4 by using openocd to program some Maxim microcontrollers. Openocd uses hidapi which seems to not work well either due to RPi4 HW or FW issues.

With the original RPi4 firmware, the failure in programming microcontrollers with openocd occurred >90% or the time. With the latest RPi4 firmware the situation improved to maybe half/half but wasn't fixed.

jeanphi-francois commented 8 months ago

I have a similar issue. I have a software working fine with a CM3+ board. Software communicates with and HID device, and never misses anything on the CM3+ version. It occasionally happens on the CM4S board. I can provide pcap file if it helps. Kernel is built from linux-1.20230405 tag

raspberrypi / linux