Non-packet events from Cynthion USB analyzer

[martinling]

This PR adds support for non-packet events that may be captured by Cynthion or other USB packet analyzers.

The scope here is limited to events related to the USB capture process itself, or that occur on the USB bus. This implies that these events have a clearly defined position within the stream of captured USB packets.

Events that occur independently of the USB bus, such as logic signals changing on the Cynthion PMOD ports, or voltage/current data points captured from the PAC1954 chip, are out of scope for this event mechanism because they can e.g. occur mid-packet, and therefore require independent timestamping and indexing.

The proposed set of initially supported events is:

CaptureStop(Requested) => "Capture stopped by request",
CaptureStop(BufferFull) => "Capture stopped due to full buffer",
CaptureStop(Error) => "Capture stopped due to an error",
CaptureStart(High) => "Capture started at High Speed (480 Mbps)",
CaptureStart(Full) => "Capture started at Full Speed (12 Mbps)",
CaptureStart(Low) => "Capture started at Low Speed (1.5 Mbps)",
CaptureStart(Auto) => "Capture started with automatic speed selection",
SpeedChange(High) => "Speed changed to High Speed (480 Mbps)",
SpeedChange(Full) => "Speed changed to Full Speed (12 Mbps)",
SpeedChange(Low) => "Speed changed to Low Speed (1.5 Mbps)",
SpeedChange(Auto) => "Speed changed to automatic selection",
LineStateChange(SE0)  => "SE0 line state detected",
LineStateChange(ChirpJ) => "Chirp J state detected",
LineStateChange(ChirpK) => "Chirp K state detected",
LineStateChange(ChirpSE1) => "Chirp SE1 state detected",
LineStateChange(LsJ) => "Low Speed idle state detected",
LineStateChange(LsK) => "Low Speed resume state detected",
LineStateChange(FsJ) => "Full Speed idle state detected",
LineStateChange(FsK) => "Full Speed resume state detected",
LineStateChange(SE1) => "Invalid SE1 line state detected",
VbusInvalid => "VBUS voltage became invalid",
VbusValid   => "VBUS voltage became valid",
LsAttach => "Device attached at Low Speed",
FsAttach => "Device attached at Full Speed",
BusReset => "Bus reset",
DeviceChirpValid => "Device HS chirp validated",
HostChirpValid => "Host HS chirp validated",
Suspend  => "Bus entered suspend",
Resume   => "Resume signal detected",
LsKeepalive => "Low Speed keepalive detected",

These correspond to work in progress on the Cynthion analyzer gateware to detect and emit these events.

TODO:

• Get working with analyzer branch from Emit, capture and display start/stop events cynthion-analyzer#11.
• Revise indexing scheme to display events in transaction and packet views.
• Implement hierarchical grouping of related events
• Store non-packet events in a PcapNG custom block type under the GSG PEN.
• Verify event detection in HITL test.
• Handle LS keepalives splitting transactions

Will close #118 when complete.

[martinling]

This will need a rebase, but I'd like to get #234 merged before I do that.

[martinling]

Rebased on #242. Let's merge that one first.

[miek]

I managed to get this to crash just now and it seems to be reliably reproducible. The setup is a Praline plugged in, speed set to auto, target power turned off with both turn on at capture start & turn off at capture end enabled. I hit capture, let it capture the enumeration, then when I hit stop it crashes with:

$ RUST_BACKTRACE=full cargo run
    Finished `dev` profile [unoptimized + debuginfo] target(s) in 0.11s
     Running `target/debug/packetry`
Capture enabled, speed: Auto
Requesting capture stop
Capture disabled

thread 'main' panicked at src/ui/tree_list_model.rs:785:30:
attempt to subtract with overflow
stack backtrace:
   0:     0x614e5c184e52 - std::backtrace_rs::backtrace::libunwind::trace::h74680e970b6e0712
                               at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/std/src/../../backtrace/src/backtrace/libunwind.rs:117:9
   1:     0x614e5c184e52 - std::backtrace_rs::backtrace::trace_unsynchronized::ha3bf590e3565a312
                               at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/std/src/../../backtrace/src/backtrace/mod.rs:66:14
   2:     0x614e5c184e52 - std::sys::backtrace::_print_fmt::hcf16024cbdd6c458
                               at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/std/src/sys/backtrace.rs:66:9
   3:     0x614e5c184e52 - <std::sys::backtrace::BacktraceLock::print::DisplayBacktrace as core::fmt::Display>::fmt::h46a716bba2450163
                               at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/std/src/sys/backtrace.rs:39:26
   4:     0x614e5c1abf13 - core::fmt::rt::Argument::fmt::ha695e732309707b7
                               at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/core/src/fmt/rt.rs:181:76
   5:     0x614e5c1abf13 - core::fmt::write::h275e5980d7008551
                               at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/core/src/fmt/mod.rs:1446:25
   6:     0x614e5c1810a3 - std::io::default_write_fmt::hdc4119be3eb77042
                               at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/std/src/io/mod.rs:639:11
   7:     0x614e5c1810a3 - std::io::Write::write_fmt::h561a66a0340b6995
                               at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/std/src/io/mod.rs:1914:13
   8:     0x614e5c184ca2 - std::sys::backtrace::BacktraceLock::print::hafb9d5969adc39a0
                               at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/std/src/sys/backtrace.rs:42:9
   9:     0x614e5c186262 - std::panicking::default_hook::{{closure}}::hae2e97a5c4b2b777
                               at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/std/src/panicking.rs:300:22
  10:     0x614e5c186065 - std::panicking::default_hook::h3db1b505cfc4eb79
                               at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/std/src/panicking.rs:327:9
  11:     0x614e5c186c02 - std::panicking::rust_panic_with_hook::h409da73ddef13937
                               at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/std/src/panicking.rs:833:13
  12:     0x614e5c186976 - std::panicking::begin_panic_handler::{{closure}}::h159b61b27f96a9c2
                               at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/std/src/panicking.rs:699:13
  13:     0x614e5c185349 - std::sys::backtrace::__rust_end_short_backtrace::h5b56844d75e766fc
                               at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/std/src/sys/backtrace.rs:168:18
  14:     0x614e5c18663d - __rustc[4794b31dd7191200]::rust_begin_unwind
                               at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/std/src/panicking.rs:697:5
  15:     0x614e5b9154c0 - core::panicking::panic_fmt::hc8737e8cca20a7c8
                               at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/core/src/panicking.rs:75:14
  16:     0x614e5b915bb7 - core::panicking::panic_const::panic_const_sub_overflow::h91779a4adcb9aa93
                               at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/core/src/panicking.rs:175:17
  17:     0x614e5bb55080 - packetry::ui::tree_list_model::TreeListModel<Item,Model,RowData,ViewMode>::update_node::h814c07c51467e9a1
                               at /home/mike/repos/packetry/src/ui/tree_list_model.rs:785:30
  18:     0x614e5bb5a174 - packetry::ui::tree_list_model::TreeListModel<Item,Model,RowData,ViewMode>::update_node::hc06bbfad3edbe8d5
                               at /home/mike/repos/packetry/src/ui/tree_list_model.rs:846:32
  19:     0x614e5bb50fc4 - packetry::ui::tree_list_model::TreeListModel<Item,Model,RowData,ViewMode>::update::hb39f21981cba4088
                               at /home/mike/repos/packetry/src/ui/tree_list_model.rs:743:9
  20:     0x614e5b9f8410 - <packetry::ui::model::TrafficModel as packetry::ui::model::GenericModel<packetry::item::TrafficItem,packetry::item::TrafficViewMode>>::update::h95bcb0e82164befc
                               at /home/mike/repos/packetry/src/ui/model.rs:133:25
  21:     0x614e5b9c5750 - packetry::ui::update_view::{{closure}}::h59437f2bceda181a
                               at /home/mike/repos/packetry/src/ui/mod.rs:552:33
  22:     0x614e5b9c0dc8 - packetry::ui::with_ui::{{closure}}::hb0883f387c94a957
                               at /home/mike/repos/packetry/src/ui/mod.rs:195:13
  23:     0x614e5ba290fd - std::thread::local::LocalKey<T>::try_with::he9ce06b4ca1b213a
                               at /home/mike/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/thread/local.rs:315:12
  24:     0x614e5ba24a2e - std::thread::local::LocalKey<T>::with::h3326bdfd879c62b6
                               at /home/mike/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/thread/local.rs:279:15
  25:     0x614e5b9befcd - packetry::ui::with_ui::h5ef9c4675f79bb12
                               at /home/mike/repos/packetry/src/ui/mod.rs:193:5
  26:     0x614e5ba0e1c6 - packetry::ui::update_view::hd49518e892269f96
                               at /home/mike/repos/packetry/src/ui/mod.rs:499:5
  27:     0x614e5b9c6106 - packetry::ui::update_view::{{closure}}::{{closure}}::h3da7577c21da2a1d
                               at /home/mike/repos/packetry/src/ui/mod.rs:592:34
  28:     0x614e5b9f7101 - glib::source::fnmut_callback_wrapper::{{closure}}::hc201b36a7a5ce539
                               at /home/mike/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/glib-0.19.7/src/source.rs:232:9
  29:     0x614e5b9f6625 - glib::source::trampoline::haaf528c89ee25fa7
                               at /home/mike/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/glib-0.19.7/src/source.rs:86:5
  30:     0x7441aa201532 - <unknown>
  31:     0x7441aa20049e - <unknown>
  32:     0x7441aa25f737 - <unknown>
  33:     0x7441aa1ffa63 - g_main_context_iteration
  34:     0x7441aa3d387d - g_application_run
  35:     0x614e5b9188ce - gio::application::ApplicationExtManual::run_with_args::h16fa6ad12aec1686
                               at /home/mike/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/gio-0.19.5/src/application.rs:29:13
  36:     0x614e5b9189b9 - gio::application::ApplicationExtManual::run::h571c54a4a4d4ed5f
                               at /home/mike/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/gio-0.19.5/src/application.rs:22:9
  37:     0x614e5bc0852f - packetry::main::hef21b7b7482a60c9
                               at /home/mike/repos/packetry/src/main.rs:143:13
  38:     0x614e5bb91e6b - core::ops::function::FnOnce::call_once::h5fb4a7378040dcf8
                               at /home/mike/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ops/function.rs:250:5
  39:     0x614e5b9161de - std::sys::backtrace::__rust_begin_short_backtrace::h1a0c19417e273657
                               at /home/mike/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/sys/backtrace.rs:152:18
  40:     0x614e5b9f5921 - std::rt::lang_start::{{closure}}::h3e79553d54749e85
                               at /home/mike/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/rt.rs:199:18
  41:     0x614e5c17a954 - core::ops::function::impls::<impl core::ops::function::FnOnce<A> for &F>::call_once::hb4b7cf0559a1a53b
                               at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/core/src/ops/function.rs:284:13
  42:     0x614e5c17a954 - std::panicking::try::do_call::h8e6004e979ada7de
                               at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/std/src/panicking.rs:589:40
  43:     0x614e5c17a954 - std::panicking::try::hc44a0c902e55fa8c
                               at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/std/src/panicking.rs:552:19
  44:     0x614e5c17a954 - std::panic::catch_unwind::h6a5f1ccd4faaed9e
                               at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/std/src/panic.rs:359:14
  45:     0x614e5c17a954 - std::rt::lang_start_internal::{{closure}}::h40fd26f9e7cfe6a7
                               at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/std/src/rt.rs:168:24
  46:     0x614e5c17a954 - std::panicking::try::do_call::h047dd894cf3f6fd1
                               at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/std/src/panicking.rs:589:40
  47:     0x614e5c17a954 - std::panicking::try::h921841e1eaed56ce
                               at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/std/src/panicking.rs:552:19
  48:     0x614e5c17a954 - std::panic::catch_unwind::h108064a50ee785ec
                               at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/std/src/panic.rs:359:14
  49:     0x614e5c17a954 - std::rt::lang_start_internal::ha8ef919ae4984948
                               at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/std/src/rt.rs:164:5
  50:     0x614e5b9f5907 - std::rt::lang_start::ha23119afdeb42165
                               at /home/mike/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/rt.rs:198:5
  51:     0x614e5bc086ee - main
  52:     0x7441a9e2a1ca - __libc_start_call_main
                               at ./csu/../sysdeps/nptl/libc_start_call_main.h:58:16
  53:     0x7441a9e2a28b - __libc_start_main_impl
                               at ./csu/../csu/libc-start.c:360:3
  54:     0x614e5b916025 - _start
  55:                0x0 - <unknown>

[martinling]

Thank you, good catch!

I was able to reproduce that crash with the same setup. After working around the crash, by replacing the subtraction that causes the underflow and panic with a saturating_sub, I was able to look at the capture and saw that there were some SOF packets in a dangling transaction, which was messing with the child count of the top-level SOF group.

A bit more thinking later I realised that I needed to add a transaction_end call to end the current transaction when a non-packet event occurs. That change is in 63190b8 and seems to have fixed the crash for me.