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.