From 8e8cc84d1aea1a9294c933c7481865fd56832256 Mon Sep 17 00:00:00 2001 From: enricobuehler Date: Mon, 17 Aug 2026 16:54:37 +0200 Subject: [PATCH] fix(pad): the usbip DualSense died because its calibration report was one byte too long MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `PUNKTFUNK_DUALSENSE_USBIP=1` enumerated the pad and then lost it ~400 ms later, taking the controller with it (the usbip transport replaces uhid, so there was nothing to fall back to). Three sessions blamed the ISO stream, the link speed and `actual_length` in turn. It was none of them. `DS_FEATURE_CALIBRATION` is 42 bytes. `hid-playstation` asks for 41 (`DS_FEATURE_REPORT_CALIBRATION_SIZE`), and on a USB backend an over-long reply is not truncated, it is fatal to the transport: size = urb->actual_length; /* 42, what we declared */ if (size > urb->transfer_buffer_length) /* 42 > 41 */ goto error; /* "probably malicious packet" */ error: dev_err(&urb->dev->dev, "recv xbuf, %d\n", ret); /* ret still 0 */ usbip_event_add(ud, VDEV_EVENT_ERROR_TCP); `VDEV_EVENT_ERROR_TCP` tears down the whole connection, not the one URB — hence `recv xbuf, 0` (that 0 is the untouched initialiser, not a byte count), then -EPROTO on the calibration read, `Failed to create dualsense`, and the disconnect. The dmesg order made the teardown look like the cause; it was the consequence. The blob had been wrong since it was written, and a FIXME said so. It stayed invisible because every other backend truncates: hidraw for the uhid pad, hidclass on Windows. USB/IP is the first transport that checks. Three changes, because one of them alone would leave the same trap set: - Trim the constant to 41 and pin all three feature-report sizes in a test. - Clamp every reply to the requested length in the transport (`clamp_reply`), and drop any payload a handler returns on an OUT transfer — the kernel never reads one, so those bytes would misframe every PDU after them. A handler bug now costs one wrong reply instead of the device. - `DualSenseUsbip::open` waits for the kernel to actually bind a HID driver before reporting success. A `vhci_hcd` attach succeeds immediately and enumerates asynchronously, so bringup faults were being reported as working pads; now they return Err and the caller's existing uhid fallback catches them. Also adds `PUNKTFUNK_USBIP_TRACE` (both socket directions to disk) and `scripts/usbip-trace-analyse.py`, which walks a capture and names the first frame whose declared length disagrees with what the kernel will consume. The handler's Err arm is no longer discarded either — it was the only signal distinguishing "we dropped the connection" from "the kernel did", and both read identically in dmesg. Verified on .21 (CachyOS, kernel 7.1.8): `Registered DualSense controller hw_version=0x01000208 fw_version=0x01000036`, the device stays enumerated, and snd-usb-audio mints a real ALSA card. Audio over the isochronous endpoint now runs for the first time — a 300 Hz tone on the coil pair reads back channel-exact (peak_coils=0.5000, peak_speaker=0.0000) for the whole run. A 4957-frame capture analyses clean. --- .../src/inject/linux/dualsense_usbip.rs | 103 ++++++++++- .../pf-inject/src/inject/linux/steam_usbip.rs | 47 ++++- .../pf-inject/src/inject/linux/usbip_trace.rs | 167 ++++++++++++++++++ .../src/inject/proto/dualsense_proto.rs | 43 ++++- crates/pf-inject/src/lib.rs | 6 + .../vendor/usbip-sim/src/lib.rs | 68 +++++++ scripts/usbip-trace-analyse.py | 164 +++++++++++++++++ 7 files changed, 586 insertions(+), 12 deletions(-) create mode 100644 crates/pf-inject/src/inject/linux/usbip_trace.rs create mode 100644 scripts/usbip-trace-analyse.py diff --git a/crates/pf-inject/src/inject/linux/dualsense_usbip.rs b/crates/pf-inject/src/inject/linux/dualsense_usbip.rs index cd6a1632..78356ff5 100644 --- a/crates/pf-inject/src/inject/linux/dualsense_usbip.rs +++ b/crates/pf-inject/src/inject/linux/dualsense_usbip.rs @@ -624,7 +624,20 @@ impl DualSenseUsbip { &format!("virtual DualSense {index}"), )?; - // Publish only once the device is actually attached, so a failed attach leaves no stale + // **A successful attach is not a working pad.** `vhci_hcd` accepts the socket immediately + // and enumerates asynchronously, so any protocol fault downstream of the attach — a reply + // the kernel rejects, a descriptor it will not parse — surfaces a few hundred milliseconds + // later as a device that appears and then vanishes. Returning `Ok` on the attach alone + // reported those as success, and because this transport *replaces* uhid the user was left + // with no pad at all rather than a degraded one. That has now happened twice, so the + // contract is: `open` returns `Ok` only once the kernel has actually bound a driver, and + // the caller's existing uhid fallback covers everything else. + if let Err(e) = wait_until_bound(index) { + drop(attach); // detach the port before the caller retries or degrades + return Err(e); + } + + // Publish only once the device is attached *and* bound, so a failed bringup leaves no stale // receiver for the streamer to drain forever. publish_audio_rx(index, rx); tracing::info!( @@ -668,6 +681,94 @@ impl Drop for DualSenseUsbip { } } +/// How long to give the kernel to enumerate the pad and bind a HID driver to it. +/// +/// Enumeration + `hid-playstation` bind measured ~330 ms on an idle box; the failure this guards +/// against tore the device down ~400 ms after attach. Three seconds is comfortably clear of both, +/// and the cost of waiting is paid once per pad arrival. `PUNKTFUNK_DUALSENSE_USBIP_GRACE_MS` +/// overrides it; `0` skips the check entirely (useful when bisecting the transport itself). +const BIND_GRACE: std::time::Duration = std::time::Duration::from_millis(3000); + +/// Block until the kernel has enumerated the virtual pad *and* bound a HID driver to its HID +/// interface, or the grace period expires. +/// +/// Checking for the `usb_device` node alone is not enough: in the 2026-08-17 failure the node was +/// created and then removed ~400 ms later when the calibration reply tore the connection down, so a +/// single early poll saw a healthy device. Requiring a bound HID driver with an `input` child means +/// the thing the pad exists to provide actually came up. +fn wait_until_bound(index: u8) -> Result<()> { + let grace = std::env::var("PUNKTFUNK_DUALSENSE_USBIP_GRACE_MS") + .ok() + .and_then(|s| s.parse::().ok()) + .map(std::time::Duration::from_millis) + .unwrap_or(BIND_GRACE); + if grace.is_zero() { + return Ok(()); + } + + let deadline = Instant::now() + grace; + let mut saw_device = false; + loop { + if let Some(t) = find_usb_topology() { + saw_device = true; + if hid_input_bound(&t.sysfs_path) { + tracing::debug!( + index, + sysfs = %t.sysfs_path.display(), + "usbip DualSense bound a HID driver" + ); + return Ok(()); + } + } + if Instant::now() >= deadline { + break; + } + std::thread::sleep(std::time::Duration::from_millis(50)); + } + + // Which of the two it is tells the operator where to look, so say it rather than "failed". + if saw_device { + anyhow::bail!( + "the virtual DualSense enumerated but no HID driver bound within {:?} — it is present \ + in sysfs without an input device. Check `dmesg` for a `playstation`/`hid-generic` \ + probe failure", + grace + ) + } + anyhow::bail!( + "the virtual DualSense never enumerated within {grace:?} — `vhci_hcd` accepted the attach \ + but no 054c:0ce6 device appeared (or it appeared and was torn down again). Check `dmesg`; \ + a transport fault here reads as `recv xbuf` / `sendmsg failed` from vhci_hcd" + ) +} + +/// Whether the pad's HID interface under `sysfs` has a bound HID driver that produced an input +/// device. Either `hid-playstation` or `hid-generic` counts — both give a usable pad. +fn hid_input_bound(sysfs: &std::path::Path) -> bool { + let Ok(entries) = std::fs::read_dir(sysfs) else { + return false; + }; + for e in entries.flatten() { + // The HID function is interface 3; its sysfs node is `:1.3`. + if !e.file_name().to_string_lossy().ends_with(":1.3") { + continue; + } + let Ok(children) = std::fs::read_dir(e.path()) else { + continue; + }; + for c in children.flatten() { + // `0003:054C:0CE6.000N` — the bound HID device. `input/` appears only once a driver + // has claimed it and registered; a probe that fails leaves the directory absent. + if c.file_name().to_string_lossy().starts_with("0003:") + && c.path().join("input").is_dir() + { + return true; + } + } + } + false +} + /// The sysfs path of an attached virtual DualSense's `usb_device` node, plus the udev properties /// wine turns into a Windows ContainerId. #[derive(Debug, Clone, PartialEq, Eq)] diff --git a/crates/pf-inject/src/inject/linux/steam_usbip.rs b/crates/pf-inject/src/inject/linux/steam_usbip.rs index d24fb86e..c20ecee2 100644 --- a/crates/pf-inject/src/inject/linux/steam_usbip.rs +++ b/crates/pf-inject/src/inject/linux/steam_usbip.rs @@ -225,10 +225,12 @@ struct ServerThread { } impl ServerThread { - /// Spawn the server on `listener`, serving exactly the one simulated `dev`. - fn spawn(listener: std::net::TcpListener, dev: UsbDevice) -> Result { + /// Spawn the server on `listener`, serving exactly the one simulated `dev`. `label` names the + /// device in log lines and in the `PUNKTFUNK_USBIP_TRACE` file names. + fn spawn(listener: std::net::TcpListener, dev: UsbDevice, label: &str) -> Result { let stop = Arc::new(tokio::sync::Notify::new()); let stop_t = stop.clone(); + let label = label.to_string(); let join = std::thread::Builder::new() .name("pf-deck-usbip".into()) .spawn(move || { @@ -246,6 +248,7 @@ impl ServerThread { listener, Arc::new(UsbIpServer::new_simulated(vec![dev])), stop_t, + label, )); }) .context("spawn usbip server thread")?; @@ -270,6 +273,7 @@ async fn run_server( listener: std::net::TcpListener, server: Arc, stop: Arc, + label: String, ) { let listener = match tokio::net::TcpListener::from_std(listener) { Ok(l) => l, @@ -289,8 +293,41 @@ async fn run_server( // active hidraw against a 266 Hz source). sock.set_nodelay(true).ok(); let server = server.clone(); + let trace = super::usbip_trace::trace_prefix(&label); + let label = label.clone(); tokio::spawn(async move { - let _ = usbip_sim::handler(&mut sock, server).await; + // The handler's Err arm used to be discarded. It is the *only* signal that + // we tore the connection down rather than the kernel — and the kernel's + // side of that (`recv xbuf`, `sendmsg failed`) reads identically either + // way, so throwing it away cost days of mis-attributed diagnosis. + let sink = trace.and_then(|prefix| { + match super::usbip_trace::open_trace(&prefix) { + Ok(s) => { + tracing::info!(prefix, "usbip byte trace armed"); + Some(s) + } + Err(e) => { + tracing::warn!(error = %e, "usbip trace files unopenable — running untraced"); + None + } + } + }); + let res = match sink { + Some(s) => { + let mut traced = super::usbip_trace::TracedIo::wrap(sock, s); + usbip_sim::handler(&mut traced, server).await + } + None => usbip_sim::handler(&mut sock, server).await, + }; + match res { + Ok(()) => tracing::debug!(label, "usbip connection closed by the kernel"), + Err(e) => tracing::warn!( + label, + error = %e, + "usbip server dropped the connection — the kernel will report this as a \ + transfer error on whatever URB was in flight" + ), + } }); } Err(e) => { @@ -361,7 +398,7 @@ fn attach_in_process(dev: UsbDevice, label: &str) -> Result { listener .set_nonblocking(true) .context("usbip listener set_nonblocking")?; - let server = ServerThread::spawn(listener, dev)?; + let server = ServerThread::spawn(listener, dev, label)?; // Connect to our own server and run the OP_REQ_IMPORT handshake. let mut sock = connect_loopback(port).context("connect to usbip server")?; @@ -395,7 +432,7 @@ fn attach_via_cli(dev: UsbDevice, label: &str) -> Result { listener .set_nonblocking(true) .context("usbip listener set_nonblocking")?; - let server = ServerThread::spawn(listener, dev)?; + let server = ServerThread::spawn(listener, dev, label)?; let before = vhci_used_ports(); usbip_attach_cli().context("usbip CLI attach")?; diff --git a/crates/pf-inject/src/inject/linux/usbip_trace.rs b/crates/pf-inject/src/inject/linux/usbip_trace.rs new file mode 100644 index 00000000..a39825d5 --- /dev/null +++ b/crates/pf-inject/src/inject/linux/usbip_trace.rs @@ -0,0 +1,167 @@ +//! Byte-level tracing for the USB/IP transport (`PUNKTFUNK_USBIP_TRACE`). +//! +//! # Why this exists +//! +//! A USB/IP connection is a *framed byte stream over one TCP socket*, and every frame's length is +//! declared inside the frame. So any reply that writes a different number of bytes than its header +//! declares does not corrupt that one URB — it shifts every byte after it, and the peer's next read +//! lands mid-frame. `vhci_hcd` reports the wreckage from wherever it happens to notice +//! (`recv xbuf`, `unknown pdu`, `cannot find a urb of seqnum`), which is never where the extra or +//! missing bytes were written. Reading the code cannot settle it, because the bug *is* a +//! disagreement between the code's arithmetic and the wire. +//! +//! This wraps the socket and writes both directions to disk verbatim, plus a record of where each +//! read/write call began and ended, so [`crate::usbip_trace`]'s companion analyser can walk the +//! streams as PDUs and name the first frame whose declared length and written length disagree. +//! +//! It is off unless `PUNKTFUNK_USBIP_TRACE` is set, and it is deliberately dumb: no parsing, no +//! filtering, no allocation beyond the write buffer. A tracer that interprets can be wrong in the +//! same way the code under test is wrong. +//! +//! # Using it +//! +//! ```text +//! PUNKTFUNK_USBIP_TRACE=/tmp/pad punktfunk-host pad-usbip-test --seconds 5 +//! ``` +//! +//! yields `/tmp/pad.