search

greatscottgadgets / cynthion

USB test instrument
https://greatscottgadgets.com/cynthion/
BSD 3-Clause "New" or "Revised" License
93 stars 21 forks source link

"cargo run -- --test-cynthion" fails @ Captured 249/4096 bytes #139

Closed villu164 closed 4 months ago

villu164 commented 4 months ago

I'm suspecting some noob(rust, usb) thing going on here, sorry

On an M2 Pro (13.6.7 Ventura)

cynthion run analyzer
cynthion info

Detected a Cynthion device! Bitstream: USB Analyzer (Cynthion Project) Hardware: Cynthion r1.4 Flash UID: 39411ccba3ac60de`

git clone git@github.com:greatscottgadgets/packetry.git
brew install gtk4
curl --proto '=https' --tlsv1.2 -sSf https://sh.rustup.rs | sh # from https://rustup.rs/
cargo build
cargo run

Connected the self-test setup Target C and Control connected to M2 Target A connected to AUX in M2, allowed the "Test USB Device", but it would seem that the test fails

(.venv) ➜  packetry git:(main) RUST_BACKTRACE=full cargo run -- --test-cynthion
    Finished `dev` profile [unoptimized + debuginfo] target(s) in 1.29s
     Running `target/debug/packetry --test-cynthion`

Testing at High (480Mbps):

Opening analyzer device
Disabling test device
Enabling test device
Capture enabled, speed: High (480Mbps)
Starting read from test device
Read 4096 bytes from test device
Requesting capture stop
Capture disabled
Found test device in capture
Captured 123/4096 bytes of data read from test device
thread 'main' panicked at src/test_cynthion.rs:127:5:
assertion `left == right` failed: Not all data was captured
  left: 123
 right: 4096
stack backtrace:
   0:        0x100eeaa7c - std::backtrace_rs::backtrace::libunwind::trace::he4f0a5f56afe8e37
                               at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/../../backtrace/src/backtrace/libunwind.rs:105:5
   1:        0x100eeaa7c - std::backtrace_rs::backtrace::trace_unsynchronized::habb302958e80f800
                               at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
   2:        0x100eeaa7c - std::sys_common::backtrace::_print_fmt::h9819d35e2a5cda77
                               at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/sys_common/backtrace.rs:68:5
   3:        0x100eeaa7c - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::h1f3776e0b5c7517d
                               at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/sys_common/backtrace.rs:44:22
   4:        0x100f052f4 - core::fmt::rt::Argument::fmt::h626862aa6242248a
                               at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/core/src/fmt/rt.rs:165:63
   5:        0x100f052f4 - core::fmt::write::heedef092c8c0962e
                               at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/core/src/fmt/mod.rs:1157:21
   6:        0x100ee8a9c - std::io::Write::write_fmt::h7178e8e2ea928914
                               at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/io/mod.rs:1832:15
   7:        0x100eea8d4 - std::sys_common::backtrace::_print::ha0f584bc7bfb9d2b
                               at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/sys_common/backtrace.rs:47:5
   8:        0x100eea8d4 - std::sys_common::backtrace::print::h417292deb95532ed
                               at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/sys_common/backtrace.rs:34:9
   9:        0x100eeba30 - std::panicking::default_hook::{{closure}}::h0cb68f1228c4613a
  10:        0x100eeb724 - std::panicking::default_hook::h24535936bc1f51de
                               at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/panicking.rs:298:9
  11:        0x100eec2e8 - std::panicking::rust_panic_with_hook::h5db4d2345b297bed
                               at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/panicking.rs:795:13
  12:        0x100eebd18 - std::panicking::begin_panic_handler::{{closure}}::h3fd558f09a0d5492
                               at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/panicking.rs:664:13
  13:        0x100eeaf04 - std::sys_common::backtrace::__rust_end_short_backtrace::hfc76eebe1ce501b2
                               at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/sys_common/backtrace.rs:171:18
  14:        0x100eeba88 - rust_begin_unwind
                               at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/panicking.rs:652:5
  15:        0x100f11e90 - core::panicking::panic_fmt::hc2b459a5bd3dce66
                               at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/core/src/panicking.rs:72:14
  16:        0x100f1221c - core::panicking::assert_failed_inner::h80507f91aa687ac5
  17:        0x100f0f1e8 - core::panicking::assert_failed::h4f1e18e41f0413d6
                               at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/core/src/panicking.rs:364:5
  18:        0x100cec8d0 - packetry::test_cynthion::test::h5739227256cc7069
                               at /Users/villuorav/git/packetry/src/test_cynthion.rs:127:5
  19:        0x100ceb004 - packetry::test_cynthion::run_test::h4945ae4fe1988104
                               at /Users/villuorav/git/packetry/src/test_cynthion.rs:27:9
  20:        0x100e221a0 - packetry::main::h88f8997afbc78121
                               at /Users/villuorav/git/packetry/src/main.rs:69:9
  21:        0x100d7cfec - core::ops::function::FnOnce::call_once::h304f4599fd90ddd9
                               at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/core/src/ops/function.rs:250:5
  22:        0x100ce7bc8 - std::sys_common::backtrace::__rust_begin_short_backtrace::h657ad34147092997
                               at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/sys_common/backtrace.rs:155:18
  23:        0x100d9b8f4 - std::rt::lang_start::{{closure}}::hea8ecdaf726acc6e
                               at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/rt.rs:159:18
  24:        0x100ee4dcc - core::ops::function::impls::<impl core::ops::function::FnOnce<A> for &F>::call_once::h2f86a413382a979d
                               at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/core/src/ops/function.rs:284:13
  25:        0x100ee4dcc - std::panicking::try::do_call::hd40c9eb4d233b111
                               at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/panicking.rs:559:40
  26:        0x100ee4dcc - std::panicking::try::h13ac68ffa70c387b
                               at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/panicking.rs:523:19
  27:        0x100ee4dcc - std::panic::catch_unwind::habea7b6fc986e966
                               at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/panic.rs:149:14
  28:        0x100ee4dcc - std::rt::lang_start_internal::{{closure}}::h6b16436250c3cf62
                               at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/rt.rs:141:48
  29:        0x100ee4dcc - std::panicking::try::do_call::h9970b928a0b20951
                               at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/panicking.rs:559:40
  30:        0x100ee4dcc - std::panicking::try::h4dfbe3cb4cc8f253
                               at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/panicking.rs:523:19
  31:        0x100ee4dcc - std::panic::catch_unwind::hf6a5e1e8ce5a10f5
                               at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/panic.rs:149:14
  32:        0x100ee4dcc - std::rt::lang_start_internal::hecc68fef83c8f44d
                               at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/rt.rs:141:20
  33:        0x100d9b8c0 - std::rt::lang_start::hf35c6650f38dbc27
                               at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/rt.rs:158:17
  34:        0x100e2232c - _main

Some things that work Facedancer rubber ducky, was able to issue text typing USB Thumbdrive, was able to view activity with packetry and analyzer

Some more symptoms

I have some issues with the packetry GUI, that doesn't allow changing the speed from 480 to anything else opening the dropdown, generates these lines

# all lines prefixed with (<unknown>:12147): Gtk-WARNING **: 21:13:07.599: Broken accounting of active state for widget 
0x139e69990(GtkLabel)
0x139e69820(GtkBox)
0x139faf320(GtkListItemWidget)
0x139faef90(GtkStack)
0x139faeda0(GtkBox)
0x139faec20(GtkToggleButton)
0x139fab8f0(GtkDropDown)
0x139e4ae10(GtkBox)
0x139e46740(GtkBox)
0x139e46d40(GtkCenterBox)
0x139e46350(GtkRevealer)
0x139e45eb0(GtkActionBar)
0x139e68ba0(GtkBox)
0x139e44460(GtkApplicationWindow)

https://github.com/user-attachments/assets/fbf4c2b4-f534-4e2f-b332-40ab5c36dda5

Could not get Facedancer usbproxy to work at all (including the thumbdrive, that I saw packets from) (Haven't debugged much further)

Not getting any packets from Full Speed (12 Mbps) Wireless Mouse (even after making a lot of traffic)

dmesg after connecting mouse, everything that included USB

[229481.116250]: 041910.099922 HS02@14100000: AppleUSBHostPort::enumerateDeviceComplete_block_invoke: enumerated 0x0250/3412/1001 (Wireless Mouse) at 12 Mbps
[229481.187528]: DK: AppleUserUSBHostHIDDevice-0x100005b6b waiting for server com.apple.driverkit.AppleUserHIDDrivers-100005b6b
[229481.200638]: AppleUserUSBHostHIDDevice:0x100005b6b start (state:0x0)
[229481.201235]: [IOUserUSBHostHIDDevice.cpp:504][0x100005b6b] Open interface: 0x100005b68
[229481.203090]: [IOUserUSBHostHIDDevice.cpp:648][0x100005b6b] HID descriptor interface:0 index:0 length:75 75 75
[229481.203239]: AppleUserUSBHostHIDDevice:0x100005b6b start (state:0x4)
[229481.203243]: AppleUserUSBHostHIDDevice:0x100005b6b start
[229481.203860]: [IOUserUSBHostHIDDevice.cpp:314][0x100005b6b] inPipe:1  inputReportSize:8 inMaxPacketSize:64 inBufferSize:64
[229481.203873]: [IOUserUSBHostHIDDevice.cpp:339][0x100005b6b] outPipe:0  outMaxPacketSize:0
[229481.204602]: [AppleUserUSBHostHIDDevice.cpp:126][0x100005b6b] Start ret: 0x0
[229481.204632]: DK: AppleUserUSBHostHIDDevice-0x100005b6b::start(IOUSBHostInterface-0x100005b68) ok
[229481.205792]: AppleUserUSBHostHIDDevice:0x100005b6b creating interfaces
[229481.207444]: AppleUserUSBHostHIDDevice:0x100005b6b Matching has vendor DeviceUsagePage : ff0c bundleIdentifier com.apple.AppleUserHIDDrivers ioclass AppleUserHIDEventService but transport and vendorID is missing
mossmann commented 4 months ago

I've made an issue on the Packetry repo for the drop-down menu failure which I was able to reproduce on an M1 mac: https://github.com/greatscottgadgets/packetry/issues/129

I have not been able to reproduce the problem with packetry --test-cynthion.

mossmann commented 4 months ago

Is the packetry --test-cynthion failure repeatable? Can you try it with a --release Cargo build?

villu164 commented 4 months ago 
cargo build --release

cargo run --release -- --test-cynthion
    Finished `release` profile [optimized] target(s) in 0.48s
     Running `target/release/packetry --test-cynthion`

Testing at High (480Mbps):

Opening analyzer device
Disabling test device
Enabling test device
Capture enabled, speed: High (480Mbps)
Starting read from test device
Read 4096 bytes from test device
Requesting capture stop
Capture disabled
Found test device in capture
Captured 123/4096 bytes of data read from test device
thread 'main' panicked at src/test_cynthion.rs:127:5:
assertion `left == right` failed: Not all data was captured
  left: 123
 right: 4096
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
villu164 commented 4 months ago

Also tried modifying the order to reversed

pub fn run_test(save_captures: bool) {
    for (name, speed, ep_addr, length, sof) in [
        ("FS", Speed::Full, 0x82,  512, Some((995000, 1005000,  50))),
        ("LS", Speed::Low,  0x83,   64, None),
        ("HS", Speed::High, 0x81, 4096, Some((124500,  125500, 500)))]
    {
        test(save_captures, name, speed, ep_addr, length, sof).unwrap();
    }
}

And got a bit other info too

cargo run -- --test-cynthion
    Finished `dev` profile [unoptimized + debuginfo] target(s) in 0.47s
     Running `target/debug/packetry --test-cynthion`

Testing at Full (12Mbps):

Opening analyzer device
Disabling test device
Enabling test device
Capture enabled, speed: Full (12Mbps)
Starting read from test device
Read 512 bytes from test device
Requesting capture stop
Capture disabled
Found test device in capture
Captured 512/512 bytes of data read from test device
Checking SOF timestamp intervals
Found 1833 SOF packets with expected interval range

Testing at Low (1.5Mbps):

Opening analyzer device
Disabling test device
Enabling test device
Capture enabled, speed: Low (1.5Mbps)
Starting read from test device
Read 64 bytes from test device
Requesting capture stop
Capture disabled
Found test device in capture
Captured 64/64 bytes of data read from test device

Testing at High (480Mbps):

Opening analyzer device
Disabling test device
Enabling test device
Capture enabled, speed: High (480Mbps)
Starting read from test device
Read 4096 bytes from test device
Requesting capture stop
Capture disabled
Found test device in capture
Captured 506/4096 bytes of data read from test device
thread 'main' panicked at src/test_cynthion.rs:127:5:
assertion `left == right` failed: Not all data was captured
  left: 506
 right: 4096
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
mossmann commented 4 months ago

Have you run cynthion update?

villu164 commented 4 months ago

I did run at some point, yes

villu164 commented 4 months ago

Did another update, first update failed with something. Then second succeeded, and ran --self-test again. Fails with same issue

(.venv) ➜  luna git:(main) ✗ 
(.venv) ➜  luna git:(main) ✗ cynthion info --force-offline
Detected a Cynthion device!
    Hardware: Cynthion r1.4
    Serial number: XO4I6UCMGJJVCIBAEA3DOPIO74
    Firmware version: v1.0.6
    USB API version: 1.1
    Flash UID: 0000000000000000
(.venv) ➜  luna git:(main) ✗ cynthion update              
Updating FPGA configuration flash with 253603 bytes...
Operation complete!
Traceback (most recent call last):
  File "/Users/villuorav/git/luna/.venv/lib/python3.8/site-packages/fwup/dfu.py", line 139, in __init__
    self.device = devices[index]
IndexError: list index out of range

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/Users/villuorav/git/luna/.venv/bin/cynthion", line 8, in <module>
    sys.exit(main())
  File "/Users/villuorav/git/luna/.venv/lib/python3.8/site-packages/cynthion/commands/cli.py", line 112, in main
    args.func(device, args)
  File "/Users/villuorav/git/luna/.venv/lib/python3.8/site-packages/cynthion/commands/cynthion_update.py", line 21, in cynthion_update
    flash_mcu_firmware(device, find_cynthion_asset("apollo.bin"))
  File "/Users/villuorav/git/luna/.venv/lib/python3.8/site-packages/cynthion/commands/util.py", line 127, in flash_mcu_firmware
    board = DFUTarget(idVendor=shared.usb.bVendorId.apollo, idProduct=shared.usb.bProductId.apollo)
  File "/Users/villuorav/git/luna/.venv/lib/python3.8/site-packages/fwup/dfu.py", line 141, in __init__
    raise BoardNotFoundError()
fwup.errors.BoardNotFoundError
(.venv) ➜  luna git:(main) ✗ pip install --upgrade cynthion
Requirement already satisfied: cynthion in ./.venv/lib/python3.8/site-packages (0.1.2)
Requirement already satisfied: amaranth==0.4.1 in ./.venv/lib/python3.8/site-packages (from cynthion) (0.4.1)
Requirement already satisfied: luna-soc~=0.2 in ./.venv/lib/python3.8/site-packages (from cynthion) (0.2.0)
Requirement already satisfied: pygreat~=2024.0 in ./.venv/lib/python3.8/site-packages (from cynthion) (2024.0.1)
Requirement already satisfied: pyserial>=3.5 in ./.venv/lib/python3.8/site-packages (from cynthion) (3.5)
Requirement already satisfied: importlib-resources in ./.venv/lib/python3.8/site-packages (from cynthion) (6.4.0)
Requirement already satisfied: luna-usb~=0.1 in ./.venv/lib/python3.8/site-packages (from cynthion) (0.1.1)
Requirement already satisfied: tomli in ./.venv/lib/python3.8/site-packages (from cynthion) (2.0.1)
Requirement already satisfied: future in ./.venv/lib/python3.8/site-packages (from cynthion) (1.0.0)
Requirement already satisfied: libusb1 in ./.venv/lib/python3.8/site-packages (from cynthion) (3.1.0)
Requirement already satisfied: tabulate in ./.venv/lib/python3.8/site-packages (from cynthion) (0.9.0)
Requirement already satisfied: prompt-toolkit in ./.venv/lib/python3.8/site-packages (from cynthion) (3.0.47)
Requirement already satisfied: pyfwup~=0.4 in ./.venv/lib/python3.8/site-packages (from cynthion) (0.4.0)
Requirement already satisfied: tqdm in ./.venv/lib/python3.8/site-packages (from cynthion) (4.66.4)
Requirement already satisfied: apollo-fpga~=1.0.7 in ./.venv/lib/python3.8/site-packages (from cynthion) (1.0.7)
Requirement already satisfied: pyusb in ./.venv/lib/python3.8/site-packages (from cynthion) (1.2.1)
Requirement already satisfied: pyvcd<0.5,>=0.2.2 in ./.venv/lib/python3.8/site-packages (from amaranth==0.4.1->cynthion) (0.4.0)
Requirement already satisfied: Jinja2~=3.0 in ./.venv/lib/python3.8/site-packages (from amaranth==0.4.1->cynthion) (3.1.4)
Requirement already satisfied: pyxdg>=0.27 in ./.venv/lib/python3.8/site-packages (from apollo-fpga~=1.0.7->cynthion) (0.28)
Requirement already satisfied: usb-protocol~=0.9.1 in ./.venv/lib/python3.8/site-packages (from luna-usb~=0.1->cynthion) (0.9.1)
Requirement already satisfied: wcwidth in ./.venv/lib/python3.8/site-packages (from prompt-toolkit->cynthion) (0.2.13)
Requirement already satisfied: backports.functools-lru-cache in ./.venv/lib/python3.8/site-packages (from pygreat~=2024.0->cynthion) (2.0.0)
Requirement already satisfied: zipp>=3.1.0 in ./.venv/lib/python3.8/site-packages (from importlib-resources->cynthion) (3.19.2)
Requirement already satisfied: MarkupSafe>=2.0 in ./.venv/lib/python3.8/site-packages (from Jinja2~=3.0->amaranth==0.4.1->cynthion) (2.1.5)
Requirement already satisfied: construct~=2.10 in ./.venv/lib/python3.8/site-packages (from usb-protocol~=0.9.1->luna-usb~=0.1->cynthion) (2.10.70)

[notice] A new release of pip is available: 23.0.1 -> 24.1.2
[notice] To update, run: pip install --upgrade pip
(.venv) ➜  luna git:(main) ✗ cynthion update               
Updating FPGA configuration flash with 253603 bytes...
Operation complete!
Updating device firmware with 13816 bytes...
Operation complete!                                                             
(.venv) ➜  luna git:(main) ✗ cd ..          
(.venv) ➜  git cd packetry
(.venv) ➜  packetry git:(main) ✗ cargo run -- --test-cynthion
    Finished `dev` profile [unoptimized + debuginfo] target(s) in 1.03s
     Running `target/debug/packetry --test-cynthion`

Testing at Full (12Mbps):

Opening analyzer device
Disabling test device
Enabling test device
Capture enabled, speed: Full (12Mbps)
thread '<unnamed>' panicked at src/test_cynthion.rs:66:63:
called `Result::unwrap()` on an `Err` value: Failure in capture thread

Caused by:
    0: Sender was dropped
    1: oneshot canceled
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
thread 'main' panicked at src/test_cynthion.rs:27:64:
called `Result::unwrap()` on an `Err` value: Test device not found
(.venv) ➜  packetry git:(main) ✗ cynthion run analyzer       
Uploading target bitstream to FPGA with 253603 bytes...
Operation complete!
(.venv) ➜  packetry git:(main) ✗ cargo run -- --test-cynthion
    Finished `dev` profile [unoptimized + debuginfo] target(s) in 0.78s
     Running `target/debug/packetry --test-cynthion`

Testing at Full (12Mbps):

Opening analyzer device
Disabling test device
Enabling test device
Capture enabled, speed: Full (12Mbps)
thread '<unnamed>' panicked at src/test_cynthion.rs:66:63:
called `Result::unwrap()` on an `Err` value: Failure in capture thread

Caused by:
    0: Sender was dropped
    1: oneshot canceled
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
thread 'main' panicked at src/test_cynthion.rs:27:64:
called `Result::unwrap()` on an `Err` value: Test device not found
(.venv) ➜  packetry git:(main) ✗ echo "Forgot to setup to connections, sorry"
Forgot to setup to connections, sorry
(.venv) ➜  packetry git:(main) ✗ cargo run -- --test-cynthion                
    Finished `dev` profile [unoptimized + debuginfo] target(s) in 0.77s
     Running `target/debug/packetry --test-cynthion`

Testing at Full (12Mbps):

Opening analyzer device
Disabling test device
Enabling test device
Capture enabled, speed: Full (12Mbps)
Starting read from test device
Read 512 bytes from test device
Requesting capture stop
Capture disabled
Found test device in capture
Captured 512/512 bytes of data read from test device
Checking SOF timestamp intervals
Found 4858 SOF packets with expected interval range

Testing at Low (1.5Mbps):

Opening analyzer device
Disabling test device
Enabling test device
Capture enabled, speed: Low (1.5Mbps)
Starting read from test device
Read 64 bytes from test device
Requesting capture stop
Capture disabled
Found test device in capture
Captured 64/64 bytes of data read from test device

Testing at High (480Mbps):

Opening analyzer device
Disabling test device
Enabling test device
Capture enabled, speed: High (480Mbps)
Starting read from test device
Read 4096 bytes from test device
Requesting capture stop
Capture disabled
Found test device in capture
Captured 156/4096 bytes of data read from test device
thread 'main' panicked at src/test_cynthion.rs:127:5:
assertion `left == right` failed: Not all data was captured
  left: 156
 right: 4096
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
martinling commented 4 months ago

Can you try:

cargo run -- --test-cynthion --save-captures

...and then post the resulting HITL-HS.pcap file here? (You may have to put it in a zip file to satisfy Github upload rules)

villu164 commented 4 months ago

HITL-HS.pcap.zip

martinling commented 4 months ago

This is very weird.

image

I don't think the test device endpoint should ever be sending less than a full length data packet (512 bytes); it's being fed by a counter which is always ready.

And the first few bytes of each captured packet are as you'd expect them to be: (00, 01, 02...), which is as expected if the packet length is a multiple of 256.

But after the first 15 bytes, that pattern breaks down.

Something really weird is going on.

villu164 commented 4 months ago

I think I figured it out... THE CHEAP USB CABLE, tried another cable...

Opening analyzer device
Disabling test device
Enabling test device
Capture enabled, speed: High (480Mbps)
Starting read from test device
Read 4096 bytes from test device
Requesting capture stop
Capture disabled
Found test device in capture
Captured 4096/4096 bytes of data read from test device
Checking SOF timestamp intervals
Found 14535 SOF packets with expected interval range

Sorry for the troubles...

I wonder if there could be some "test" for the cable quality

🤦‍♂️

martinling commented 4 months ago

I'm glad you found the solution, but I'd like to make sure we understand this failure mode.

Even with the bad cable, the host was able to read from the test device successfully, and also read from the analyzer successfully. It's only the capture data that was wrong.

So it seems like with the bad cable, the signal integrity was sufficient for host-device communication, but not good enough for the target PHY to capture the signal accurately.

I wonder if there could be some "test" for the cable quality

Seems like the existing test served that purpose in this case.

depili commented 4 months ago

I have run into similar issues with logic analyzers and marginal cables that worked fine until one really pushed traffic that saturated the bus into them. The lesson; for ones instruments and signal capture do not tolerate bad cables.

mossmann commented 4 months ago

@villu164 In my experience, the biggest factor in USB 2.0 cable quality for High Speed signal integrity is shielding. If you have a continuity tester, I would love to know if there is continuity from the shield on one end to the shield on the other end of your bad cable.

villu164 commented 4 months ago

Assuming, I understood you correctly, then bad cable - no continuity good cables - continuity

Bad Cable (self tested - 12 Mbps, 1.5 Mbps) - 480 Mbps fails (see above) bad_havit_cable

Good Cable (self tested - 480 Mbps, 12 Mbps, 1.5 Mbps) good_samsung_cable

Another Good Cable (self tested - 480 Mbps, 12 Mbps, 1.5 Mbps) another_good_maybe_dell

villu164 commented 4 months ago

In my defense - I use the cables mostly for charging devices. Where-ever I can, then I move data over SSD-s(which have their own cables) or wirelessly. So I have not had issues (maybe luck?) with them yet, (enthusiast, not a hardware hacker yet)

mossmann commented 4 months ago

Nice! Thank for checking that. Yeah, poor cables often work okay until you do something to push them to their limits like running the Packetry self-test or a HackRF at maximum sample rate. This self-test is pretty much the worst case scenario for High Speed USB signal integrity and EMC, so it requires good cables.

Thank you for helping us test these problems! That pcap was quite useful. I'm closing this as the Packetry drop-down issue is tracked separately.

martinling commented 4 months ago

@villu164 thanks again for your efforts to track down the issue here.

I've improved Packetry's handling of malformed packets in https://github.com/greatscottgadgets/packetry/pull/138, which should make it easier to diagnose this issue, when other folks have the same problem in future.

I've added your capture as a test case, to make sure this continues to be handled correctly in future.