Debugging testusb problems

New Contributor

2 years ago

Hi Aik Eu,

Thanks for getting back to me. I've setup two board, running the same firmware. It produces the same results.

On the host side, the testusb output is

# ./testusb -a
high speed      /dev/bus/usb/002/004    0
/dev/bus/usb/002/004 test 0,    0.004049 secs
/dev/bus/usb/002/004 test 1,    0.146089 secs
/dev/bus/usb/002/004 test 2,    0.278257 secs
/dev/bus/usb/002/004 test 3,    0.150696 secs
/dev/bus/usb/002/004 test 4,    0.278766 secs
/dev/bus/usb/002/004 test 5,    3.139878 secs
/dev/bus/usb/002/004 test 6,    2.610817 secs
/dev/bus/usb/002/004 test 7,    3.137456 secs
/dev/bus/usb/002/004 test 8,    2.619083 secs
/dev/bus/usb/002/004 test 9,    2.862658 secs
/dev/bus/usb/002/004 test 10,   30.767096 secs
/dev/bus/usb/002/004 test 11,   47.345873 secs
/dev/bus/usb/002/004 test 12,   46.529739 secs
/dev/bus/usb/002/004 test 13,   31.737337 secs
/dev/bus/usb/002/004 test 14 --> 22 (Invalid argument)
/dev/bus/usb/002/004 test 17,    0.156749 secs
/dev/bus/usb/002/004 test 18,    0.147973 secs
/dev/bus/usb/002/004 test 19 --> 32 (Broken pipe)
/dev/bus/usb/002/004 test 20 --> 22 (Invalid argument)
/dev/bus/usb/002/004 test 21 --> 22 (Invalid argument)
/dev/bus/usb/002/004 test 24 --> 32 (Broken pipe)
/dev/bus/usb/002/004 test 27 --> 5 (Input/output error)
/dev/bus/usb/002/004 test 28,    2.313950 secs
/dev/bus/usb/002/004 test 29 --> 22 (Invalid argument)

Dmesg (host side) produces

[  344.870543] usbtest 2-1:3.0: Linux gadget zero
[  344.875000] usbtest 2-1:3.0: high-speed {control in/out bulk-in bulk-out} tests (+alt)
[  415.732606] usbtest 2-1:3.0: TEST 0:  NOP
[  415.737052] usbtest 2-1:3.0: TEST 1:  write 1024 bytes 1000 times
[  415.883544] usbtest 2-1:3.0: TEST 2:  read 1024 bytes 1000 times
[  416.162200] usbtest 2-1:3.0: TEST 3:  write/1024 0..1024 bytes 1000 times
[  416.313294] usbtest 2-1:3.0: TEST 4:  read/1024 0..1024 bytes 1000 times
[  416.592455] usbtest 2-1:3.0: TEST 5:  write 1000 sglists 32 entries of 1024 bytes
[  419.733174] usbtest 2-1:3.0: TEST 6:  read 1000 sglists 32 entries of 1024 bytes
[  422.345047] usbtest 2-1:3.0: TEST 7:  write/1024 1000 sglists 32 entries 0..1024 bytes
[  425.482910] usbtest 2-1:3.0: TEST 8:  read/1024 1000 sglists 32 entries 0..1024 bytes
[  428.102398] usbtest 2-1:3.0: TEST 9:  ch9 (subset) control tests, 1000 times
[  430.966457] usbtest 2-1:3.0: TEST 10:  queue 32 control calls, 1000 times
[  461.734217] usbtest 2-1:3.0: TEST 11:  unlink 1000 reads of 1024
[  463.150059] usbtest 2-1:3.0: unlink retry
[            ] ...REPEATED...
[  508.740029] usbtest 2-1:3.0: unlink retry
[  509.080496] usbtest 2-1:3.0: TEST 12:  unlink 1000 writes of 1024
[  509.840028] usbtest 2-1:3.0: unlink retry
[            ] ...REPEATED...
[  553.538165] usbtest 2-1:3.0: unlink retry
[  555.610635] usbtest 2-1:3.0: TEST 13:  set/clear 1000 halts
[  587.348359] usbtest 2-1:3.0: TEST 14:  1000 ep0out, 1..1024 vary 1024
[  587.357009] usbtest 2-1:3.0: TEST 17:  write odd addr 1024 bytes 1000 times core map
[  587.514579] usbtest 2-1:3.0: TEST 18:  read odd addr 1024 bytes 1000 times core map
[  587.663348] usbtest 2-1:3.0: TEST 19:  write odd addr 1024 bytes 1000 times premapped
[  587.671233] ------------[ cut here ]------------
[  587.675839] WARNING: CPU: 1 PID: 324 at drivers/usb/dwc2/hcd.c:2648 dwc2_assign_and_init_hc+0x7dc/0x9b4
[  587.685224] Modules linked in: usbtest
[  587.688982] CPU: 1 PID: 324 Comm: testusb Not tainted 6.1.20-altera #1
[  587.695491] Hardware name: Altera SOCFPGA
[  587.699498]  unwind_backtrace from show_stack+0x18/0x1c
[  587.704751]  show_stack from dump_stack_lvl+0x40/0x4c
[  587.709823]  dump_stack_lvl from __warn+0x80/0x12c
[  587.714647]  __warn from warn_slowpath_fmt+0xc0/0x194
[  587.719723]  warn_slowpath_fmt from dwc2_assign_and_init_hc+0x7dc/0x9b4
[  587.726348]  dwc2_assign_and_init_hc from dwc2_hcd_select_transactions+0x110/0x1d4
[  587.733914]  dwc2_hcd_select_transactions from _dwc2_hcd_urb_enqueue+0x2c4/0x6a8
[  587.741311]  _dwc2_hcd_urb_enqueue from usb_hcd_submit_urb+0xc4/0x9bc
[  587.747765]  usb_hcd_submit_urb from simple_io+0xb0/0x200 [usbtest]
[  587.754064]  simple_io [usbtest] from test_unaligned_bulk+0x74/0x90 [usbtest]
[  587.761225]  test_unaligned_bulk [usbtest] from usbtest_do_ioctl+0x658/0x191c [usbtest]
[  587.769249]  usbtest_do_ioctl [usbtest] from usbtest_ioctl+0x188/0x288 [usbtest]
[  587.776668]  usbtest_ioctl [usbtest] from usbdev_ioctl+0x1e24/0x2958
[  587.783050]  usbdev_ioctl from sys_ioctl+0x4ac/0xc40
[  587.788027]  sys_ioctl from ret_fast_syscall+0x0/0x54
[  587.793077] Exception stack(0xe1065fa8 to 0xe1065ff0)
[  587.798119] 5fa0:                   000253b8 00000002 00000003 c00c5512 bef96ab4 bef96a98
[  587.806266] 5fc0: 000253b8 00000002 00012f14 00000036 000112a8 b6fd0d38 00000000 bef96ac4
[  587.814406] 5fe0: 00013038 bef96a88 00010f24 b6f2909c
[  587.819437] ---[ end trace 0000000000000000 ]---
[  587.908919] usb 2-1: test19 failed, iterations left 992, status -32 (not 0)
[  587.923027] usbtest 2-1:3.0: TEST 20:  read odd addr 1024 bytes 1000 times premapped
[  587.931127] usbtest 2-1:3.0: guard byte[0] 0 (not 165)
[  587.936274] usb 2-1: test20 failed, iterations left 999, status -22 (not 0)
[  587.950642] usbtest 2-1:3.0: TEST 21:  1000 ep0out odd addr, 1..1024 vary 1024
[  587.977954] usbtest 2-1:3.0: TEST 24:  unlink from 1000 queues of 32 1024-byte writes
[  587.988256] usbtest 2-1:3.0: unlink queued writes failed -32, iterations left 1000
[  588.016186] usbtest 2-1:3.0: TEST 27: bulk write 31Mbytes
[  588.025442] usbtest 2-1:3.0: during the test, 32 errors out of 0
[  588.038788] usbtest 2-1:3.0: TEST 28: bulk read 31Mbytes
[  590.359391] usbtest 2-1:3.0: TEST 29: Clear toggle between bulk writes 1000 times
[  600.820105] usb 2-1: test_toggle_sync failed, iterations left 0, status -110 (not 0)
[  600.827852] usbtest 2-1:3.0: toggle sync failed, iterations left 999

and dmesg on the gadget side produces

[  428.402140] zero gadget.0: Gadget Zero, version: Cinco de Mayo 2008
[  428.408514] zero gadget.0: zero ready
[  428.412189] dwc2 ffb00000.usb: bound driver zero
[  455.676134] dwc2 ffb00000.usb: new device is high-speed
[  455.896122] dwc2 ffb00000.usb: new device is high-speed
[  456.046118] dwc2 ffb00000.usb: new address 4
[  542.190016] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep 06938844 ep0, 0)
[  542.196727] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt: can't clear halt on ep0
[  542.205002] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep 06938844 ep0, 0)
[  542.211706] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt: can't clear halt on ep0
...REPEATED...
[  572.912673] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep 06938844 ep0, 0)
[  572.919368] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt: can't clear halt on ep0
[  572.926905] systemd-journald[69]: /dev/kmsg buffer overrun, some messages lost.
[  572.934774] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep 06938844 ep0, 0)
[  572.941464] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt: can't clear halt on ep0
[  572.951634] systemd-journald[69]: /dev/kmsg buffer overrun, some messages lost.
[  666.832135] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep f1d60933 ep1in, 1)
[  666.839990] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep f1d60933 ep1in, 0)
[  666.847483] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep 2c511fcf ep1out, 1)
[  666.854821] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep 2c511fcf ep1out, 0)
...REPEATED...
[  698.533924] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep f1d60933 ep1in, 1)
[  698.541120] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep f1d60933 ep1in, 0)
[  698.548597] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep 2c511fcf ep1out, 1)
[  698.555937] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep 2c511fcf ep1out, 0)
[  698.564138] systemd-journald[69]: /dev/kmsg buffer overrun, some messages lost.
[  699.039391] zero gadget.0: bad OUT byte, buf[0] = 165
[  699.044456] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep 2c511fcf ep1out, 1)
[  699.051523] zero gadget.0: bad OUT byte, buf[0] = 165
[  699.056571] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep 2c511fcf ep1out, 1)
[  699.063632] zero gadget.0: bad OUT byte, buf[0] = 165
[  699.068679] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep 2c511fcf ep1out, 1)
[  699.075719] zero gadget.0: bad OUT byte, buf[0] = 165
[  699.080763] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep 2c511fcf ep1out, 1)
[  699.087800] zero gadget.0: bad OUT byte, buf[0] = 165
[  699.092845] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep 2c511fcf ep1out, 1)
[  699.099880] zero gadget.0: bad OUT byte, buf[0] = 165
[  699.104925] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep 2c511fcf ep1out, 1)
[  699.111961] zero gadget.0: bad OUT byte, buf[0] = 165
[  699.117007] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep 2c511fcf ep1out, 1)
[  699.131847] dwc2 ffb00000.usb: dwc2_hsotg_start_req: ep1 is stalled
[  699.159461] dwc2 ffb00000.usb: dwc2_hsotg_start_req: ep1 is stalled
[  699.173742] dwc2 ffb00000.usb: dwc2_hsotg_start_req: ep1 is stalled
[  699.180303] dwc2 ffb00000.usb: dwc2_hsotg_start_req: ep1 is stalled
[  699.186816] dwc2 ffb00000.usb: dwc2_hsotg_start_req: ep1 is stalled
[  699.212008] dwc2 ffb00000.usb: dwc2_hsotg_start_req: ep1 is stalled
[  699.218567] dwc2 ffb00000.usb: dwc2_hsotg_start_req: ep1 is stalled
[  699.225048] dwc2 ffb00000.usb: dwc2_hsotg_start_req: ep1 is stalled
[  699.247607] dwc2 ffb00000.usb: dwc2_hsotg_start_req: ep1 is stalled
[  701.568207] dwc2 ffb00000.usb: dwc2_hsotg_start_req: ep1 is stalled
[  701.582168] dwc2 ffb00000.usb: dwc2_hsotg_ep_sethalt(ep 2c511fcf ep1out, 0)

Good thing to try! Unfortunately, I'm not sure how to proceed.

Forum Discussion

Recent Discussions

Cyclone V SoC 5CSXC6 Series GXB Utilization and Limitations

MAX 10: Can an ASx1 RBF be written directly to internal CFM via on-chip flash Avalon-MM?

JESD204B RX Link Never Achieves CGS at 12.8 Gbps on S10 ES (1SG280LU3F50E3VGS1, Quartus Pro 17.1)

Unable to Generate Valid PAM4 Eye Diagram and BER Measurements on Stratix 10 SI E-Tile Native PHY

Error (209014): CONF_DONE pin failed to go high in device 1.