From 798896ec4a0e2d0d1639af0f2e8d89ff935e1dbf Mon Sep 17 00:00:00 2001 From: Adam Shiervani Date: Thu, 2 Jul 2026 10:37:27 +0200 Subject: [PATCH] Escalate USB recovery when keyboard HID writes time out MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit After a UDC rebind, the RV1106 DWC3 race can leave /dev/hidg0 openable but non-functional: every write times out while the UDC still reports "configured". The rebind recovery path verified health by reopening the chardev — which succeeds in this state — and writeWithTimeout swallows the deadline errors (host-suspend tolerance), so nothing ever escalated to the full gadget reconfigure that actually fixes it. Keyboard input was silently dropped until the user manually cycled identifier profiles (#1512). Two complementary mechanisms: 1. Write-probe verification in the recovery ladder: after reopening the keyboard HID file, re-send the current keys-down state (a no-op for the host) and, unlike the regular report path, surface a timeout. While the UDC reports "configured", a reopen that probes broken is not success — the ladder escalates to the full reconfigure instead of declaring victory, fixing the gadget before the user ever types. 2. Runtime write-timeout streak: consecutive keyboard write timeouts are counted (reset on success, on recovery, and while the state is not "configured", where timeouts are expected — e.g. host suspend). When the streak reaches 3 while "configured", recovery runs the full reconfigure directly, rate-limited to one attempt per 30s. This catches breakage that occurs without a preceding detach event. Fixes #1512 --- internal/usbgadget/consts.go | 6 + internal/usbgadget/hid_keyboard.go | 53 +++++ internal/usbgadget/hid_write_recovery_test.go | 203 ++++++++++++++++++ internal/usbgadget/recovery.go | 31 +++ internal/usbgadget/usbgadget.go | 10 + internal/usbgadget/utils.go | 38 ++++ .../ra-hid-write-recovery.spec.ts | 140 ++++++++++++ usb.go | 134 +++++++++--- 8 files changed, 591 insertions(+), 24 deletions(-) create mode 100644 internal/usbgadget/hid_write_recovery_test.go create mode 100644 ui/e2e/remote-agent/ra-hid-write-recovery.spec.ts diff --git a/internal/usbgadget/consts.go b/internal/usbgadget/consts.go index 958aecca7..919833229 100644 --- a/internal/usbgadget/consts.go +++ b/internal/usbgadget/consts.go @@ -5,3 +5,9 @@ import "time" const dwc3Path = "/sys/bus/platform/drivers/dwc3" const hidWriteTimeout = 10 * time.Millisecond + +// hidProbeWriteTimeout bounds the recovery write probe. More generous than +// hidWriteTimeout: right after enumeration the host may not have started +// polling the interrupt endpoint yet, and a false negative here escalates to +// a disruptive full gadget reconfigure. +const hidProbeWriteTimeout = 500 * time.Millisecond diff --git a/internal/usbgadget/hid_keyboard.go b/internal/usbgadget/hid_keyboard.go index b1a1d711d..87bbe5eff 100644 --- a/internal/usbgadget/hid_keyboard.go +++ b/internal/usbgadget/hid_keyboard.go @@ -675,3 +675,56 @@ func (u *UsbGadget) KeypressReport(key byte, press bool) error { return err } + +// KeyboardWriteTimeoutStreak returns the number of consecutive write timeouts +// on the currently open keyboard HID file. Returns 0 when the file is closed. +func (u *UsbGadget) KeyboardWriteTimeoutStreak() int { + u.keyboardLock.Lock() + file := u.keyboardHidFile + u.keyboardLock.Unlock() + + if file == nil { + return 0 + } + + u.hidWriteStreakLock.Lock() + defer u.hidWriteStreakLock.Unlock() + + return u.hidWriteTimeoutStreaks[file.Name()] +} + +// VerifyKeyboardWritable proves the keyboard HID function actually accepts +// reports, not merely that the chardev opens — the #1512 broken state is a +// /dev/hidg0 that opens fine while every write times out. It re-sends the +// current keys-down state, which is a no-op for the host, and, unlike the +// regular report path, returns a write timeout instead of swallowing it. +// Only meaningful while the UDC state is "configured"; in any other state +// the host is not polling the endpoint and a stalled write proves nothing. +func (u *UsbGadget) VerifyKeyboardWritable() error { + keyboardMutex.Lock() + defer keyboardMutex.Unlock() + + if err := u.openKeyboardHidFile(); err != nil { + return err + } + + file := u.keyboardHidFile + if file == nil { + return fmt.Errorf("keyboard HID file is not open") + } + + state := u.GetKeysDownState() + keys := make([]byte, hidKeyBufferSize) + copy(keys, state.Keys) + report := append([]byte{state.Modifier, 0x00}, keys...) + + if err := file.SetWriteDeadline(time.Now().Add(hidProbeWriteTimeout)); err != nil { + return err + } + if _, err := file.Write(report); err != nil { + return fmt.Errorf("keyboard HID probe write failed: %w", err) + } + + u.resetHidWriteTimeoutStreak(file.Name()) + return nil +} diff --git a/internal/usbgadget/hid_write_recovery_test.go b/internal/usbgadget/hid_write_recovery_test.go new file mode 100644 index 000000000..b52cdc33b --- /dev/null +++ b/internal/usbgadget/hid_write_recovery_test.go @@ -0,0 +1,203 @@ +package usbgadget + +import ( + "os" + "testing" + "time" + + "github.com/rs/zerolog" +) + +// fillPipeBuffer writes to w until the kernel pipe buffer is full, so that +// subsequent writes block and exceed their write deadline — simulating a HID +// endpoint whose host side stopped draining reports (issue #1512). +func fillPipeBuffer(t *testing.T, w *os.File) { + t.Helper() + chunk := make([]byte, 4096) + for { + if err := w.SetWriteDeadline(time.Now().Add(5 * time.Millisecond)); err != nil { + t.Fatalf("SetWriteDeadline: %v", err) + } + if _, err := w.Write(chunk); err != nil { + return + } + } +} + +func drainPipe(t *testing.T, r *os.File) { + t.Helper() + buf := make([]byte, 65536) + for { + if err := r.SetReadDeadline(time.Now().Add(5 * time.Millisecond)); err != nil { + t.Fatalf("SetReadDeadline: %v", err) + } + if _, err := r.Read(buf); err != nil { + return + } + } +} + +func newTestGadgetWithKeyboard(w *os.File) *UsbGadget { + logger := zerolog.Nop() + return &UsbGadget{ + log: &logger, + logSuppressionCounter: make(map[string]int), + keyboardHidFile: w, + } +} + +func TestKeyboardWriteTimeoutStreak(t *testing.T) { + r, w, err := os.Pipe() + if err != nil { + t.Fatal(err) + } + defer r.Close() + + u := newTestGadgetWithKeyboard(w) + fillPipeBuffer(t, w) + + report := make([]byte, hidKeyBufferSize) + for i := 1; i <= HidWriteTimeoutEscalationThreshold; i++ { + // Timed-out writes are deliberately swallowed (host-suspend tolerance), + // but each one must be counted so recovery can escalate. + if err := u.keyboardWriteHidFileLocked(0, report); err != nil { + t.Fatalf("write %d: expected timeout to be swallowed, got %v", i, err) + } + if got := u.KeyboardWriteTimeoutStreak(); got != i { + t.Fatalf("after %d timed-out writes, streak = %d, want %d", i, got, i) + } + } + + // A successful write means the endpoint is healthy again: streak resets. + drainPipe(t, r) + if err := u.keyboardWriteHidFileLocked(0, report); err != nil { + t.Fatalf("write after drain: %v", err) + } + if got := u.KeyboardWriteTimeoutStreak(); got != 0 { + t.Fatalf("streak after successful write = %d, want 0", got) + } +} + +func TestResetHIDFilesClearsWriteTimeoutStreaks(t *testing.T) { + r, w, err := os.Pipe() + if err != nil { + t.Fatal(err) + } + defer r.Close() + + u := newTestGadgetWithKeyboard(w) + fillPipeBuffer(t, w) + + report := make([]byte, hidKeyBufferSize) + if err := u.keyboardWriteHidFileLocked(0, report); err != nil { + t.Fatalf("write: %v", err) + } + + // Recovery closes and reopens the HID files; stale streaks must not + // survive into the new gadget instance and immediately re-trigger it. + u.ResetHIDFiles() + if got := len(u.hidWriteTimeoutStreaks); got != 0 { + t.Fatalf("streak map has %d entries after ResetHIDFiles, want 0", got) + } + if got := u.KeyboardWriteTimeoutStreak(); got != 0 { + t.Fatalf("streak after ResetHIDFiles = %d, want 0", got) + } +} + +func TestShouldEscalateHidWriteRecovery(t *testing.T) { + now := time.Unix(100000, 0) + streak := HidWriteTimeoutEscalationThreshold + + tests := []struct { + name string + state string + desired bool + timeouts int + lastAttempt time.Time + want bool + }{ + { + name: "escalate when writes time out while configured", + state: USBStateConfigured, + desired: true, + timeouts: streak, + want: true, + }, + { + name: "skip below timeout threshold", + state: USBStateConfigured, + desired: true, + timeouts: streak - 1, + want: false, + }, + { + name: "skip when host is suspended", + state: "suspended", + desired: true, + timeouts: streak, + want: false, + }, + { + name: "skip when gadget is detached (handled by rebind recovery)", + state: USBStateNotAttached, + desired: true, + timeouts: streak, + want: false, + }, + { + name: "skip when emulation intentionally disabled", + state: USBStateConfigured, + desired: false, + timeouts: streak, + want: false, + }, + { + name: "rate limit repeated escalations", + state: USBStateConfigured, + desired: true, + timeouts: streak, + lastAttempt: now.Add(-HidWriteRecoveryRetryInterval + time.Second), + want: false, + }, + { + name: "allow retry after interval passes", + state: USBStateConfigured, + desired: true, + timeouts: streak, + lastAttempt: now.Add(-HidWriteRecoveryRetryInterval), + want: true, + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + got := ShouldEscalateHidWriteRecovery(tt.state, tt.desired, tt.timeouts, tt.lastAttempt, now) + if got != tt.want { + t.Fatalf("ShouldEscalateHidWriteRecovery() = %v, want %v", got, tt.want) + } + }) + } +} + +func TestVerifyKeyboardWritable(t *testing.T) { + r, w, err := os.Pipe() + if err != nil { + t.Fatal(err) + } + defer r.Close() + + u := newTestGadgetWithKeyboard(w) + + // Stalled endpoint: the probe must surface the timeout, not swallow it + // like the regular report path does. + fillPipeBuffer(t, w) + if err := u.VerifyKeyboardWritable(); err == nil { + t.Fatal("expected probe to fail while writes stall") + } + + // Healthy endpoint: the probe passes and is a no-op for the host. + drainPipe(t, r) + if err := u.VerifyKeyboardWritable(); err != nil { + t.Fatalf("probe on writable keyboard file: %v", err) + } +} diff --git a/internal/usbgadget/recovery.go b/internal/usbgadget/recovery.go index 50dfc8cfc..6bb07b740 100644 --- a/internal/usbgadget/recovery.go +++ b/internal/usbgadget/recovery.go @@ -20,3 +20,34 @@ func ShouldAttemptUSBRecovery(state string, desired bool, lastAttempt time.Time, return lastAttempt.IsZero() || now.Sub(lastAttempt) >= USBRecoveryRetryInterval } + +// USBStateConfigured is the UDC sysfs state when the host has configured the gadget. +const USBStateConfigured = "configured" + +// HidWriteTimeoutEscalationThreshold is the number of consecutive keyboard HID +// write timeouts, while the gadget reports "configured", after which recovery +// escalates to a full gadget reconfigure. +const HidWriteTimeoutEscalationThreshold = 3 + +// HidWriteRecoveryRetryInterval is the minimum interval between write-timeout +// escalations. A full reconfigure forces the host to re-enumerate the gadget, +// so repeated attempts are spaced well apart. +const HidWriteRecoveryRetryInterval = 30 * time.Second + +// ShouldEscalateHidWriteRecovery reports whether keyboard HID write timeouts +// should trigger a full USB gadget reconfigure. A UDC rebind can leave +// /dev/hidg0 openable but non-functional: writes time out while the UDC still +// reports "configured". Only a full gadget reconfigure recovers from that +// state. Write timeouts in any other UDC state (e.g. "suspended" while the +// host sleeps) are expected and must not trigger recovery. +func ShouldEscalateHidWriteRecovery(state string, desired bool, consecutiveTimeouts int, lastAttempt time.Time, now time.Time) bool { + if state != USBStateConfigured || !desired { + return false + } + + if consecutiveTimeouts < HidWriteTimeoutEscalationThreshold { + return false + } + + return lastAttempt.IsZero() || now.Sub(lastAttempt) >= HidWriteRecoveryRetryInterval +} diff --git a/internal/usbgadget/usbgadget.go b/internal/usbgadget/usbgadget.go index bb4a9f98a..18cd45ce7 100644 --- a/internal/usbgadget/usbgadget.go +++ b/internal/usbgadget/usbgadget.go @@ -99,6 +99,12 @@ type UsbGadget struct { logSuppressionCounter map[string]int logSuppressionLock sync.Mutex + + // hidWriteTimeoutStreaks counts consecutive write timeouts per HID device + // file; a successful write resets the streak. Used to detect a gadget left + // non-functional after a UDC rebind (writes time out while "configured"). + hidWriteTimeoutStreaks map[string]int + hidWriteStreakLock sync.Mutex } const configFSPath = "/sys/kernel/config" @@ -224,4 +230,8 @@ func (u *UsbGadget) ResetHIDFiles() { u.relMouseHidFile = nil } unlockWithLog(&u.relMouseLock, u.log, "relMouseHidFile reset") + + // The new gadget instance starts with a clean slate; stale streaks must + // not immediately re-trigger write-timeout recovery. + u.clearHidWriteTimeoutStreaks() } diff --git a/internal/usbgadget/utils.go b/internal/usbgadget/utils.go index 7ec32a23b..465fd9e88 100644 --- a/internal/usbgadget/utils.go +++ b/internal/usbgadget/utils.go @@ -119,6 +119,7 @@ func (u *UsbGadget) writeWithTimeout(file *os.File, data []byte) (n int, err err n, err = file.Write(data) if err == nil { + u.resetHidWriteTimeoutStreak(file.Name()) return } @@ -129,6 +130,11 @@ func (u *UsbGadget) writeWithTimeout(file *os.File, data []byte) (n int, err err Msg("write failed") if errors.Is(err, os.ErrDeadlineExceeded) { + // The timeout is swallowed so a suspended host doesn't surface errors + // on every report, but it is counted: consecutive timeouts while the + // gadget is "configured" mean the HID function is broken and recovery + // must escalate (see ShouldEscalateHidWriteRecovery). + u.recordHidWriteTimeout(file.Name()) u.logWithSuppression( fmt.Sprintf("writeWithTimeout_%s", file.Name()), 1000, @@ -143,6 +149,38 @@ func (u *UsbGadget) writeWithTimeout(file *os.File, data []byte) (n int, err err return } +func (u *UsbGadget) recordHidWriteTimeout(name string) { + u.hidWriteStreakLock.Lock() + defer u.hidWriteStreakLock.Unlock() + + if u.hidWriteTimeoutStreaks == nil { + u.hidWriteTimeoutStreaks = make(map[string]int) + } + u.hidWriteTimeoutStreaks[name]++ +} + +func (u *UsbGadget) resetHidWriteTimeoutStreak(name string) { + u.hidWriteStreakLock.Lock() + defer u.hidWriteStreakLock.Unlock() + + delete(u.hidWriteTimeoutStreaks, name) +} + +func (u *UsbGadget) clearHidWriteTimeoutStreaks() { + u.hidWriteStreakLock.Lock() + defer u.hidWriteStreakLock.Unlock() + + clear(u.hidWriteTimeoutStreaks) +} + +// ClearHidWriteTimeoutStreaks resets all per-file write timeout streaks. +// Called while the gadget is not in the "configured" state, where write +// timeouts are expected (e.g. host suspend) and must not accumulate into a +// spurious recovery once the state returns to "configured". +func (u *UsbGadget) ClearHidWriteTimeoutStreaks() { + u.clearHidWriteTimeoutStreaks() +} + func (u *UsbGadget) logWithSuppression(counterName string, every int, logger *zerolog.Logger, err error, msg string, args ...any) { u.logSuppressionLock.Lock() defer u.logSuppressionLock.Unlock() diff --git a/ui/e2e/remote-agent/ra-hid-write-recovery.spec.ts b/ui/e2e/remote-agent/ra-hid-write-recovery.spec.ts new file mode 100644 index 000000000..397362ebb --- /dev/null +++ b/ui/e2e/remote-agent/ra-hid-write-recovery.spec.ts @@ -0,0 +1,140 @@ +/** + * E2E regression test for issue #1512: a UDC rebind can leave /dev/hidg0 + * openable but non-functional — every keyboard report write times out while + * the UDC still reports "configured". The app must detect this and escalate + * to a full gadget reconfigure on its own instead of silently dropping + * keyboard input until the user manually cycles identifier profiles. + * + * The broken state is reproduced deterministically from the host side: + * unbinding usbhid from the gadget's keyboard interface stops the host from + * polling the interrupt IN endpoint, so gadget-side keyboard writes hit their + * write deadline while the gadget stays "configured" — the exact failure + * signature from the issue (mouse alive, keyboard silently dead). + * + * The self-recovery reconfigure forces the host to re-enumerate the gadget, + * which rebinds usbhid to the fresh interface and restores keyboard input. + * + * Run with: + * JETKVM_URL=http:// JETKVM_REMOTE_HOST= \ + * npx playwright test --project=remote-agent ra-hid-write-recovery + */ +import { execSync } from "child_process"; +import { test, expect, type Page } from "@playwright/test"; +import { HID_KEY, SSH_OPTS, ensureNoPasswordViaAPI, ensureRpcReady, tapKey } from "../helpers"; +import { createRemoteAgent, KEY, type RemoteAgent } from "./remote-agent"; + +const agent = createRemoteAgent(); + +test.describe.configure({ mode: "serial" }); + +let page: Page; + +/** Run a command on the remote host (the machine the KVM's USB plugs into). */ +function remoteHostExec(cmd: string, timeoutMs = 15000): string { + const target = process.env.JETKVM_REMOTE_HOST; + if (!target) throw new Error("JETKVM_REMOTE_HOST not set"); + const escaped = cmd.replace(/'/g, "'\\''"); + return execSync(`ssh ${SSH_OPTS} ${target} '${escaped}'`, { + encoding: "utf8", + timeout: timeoutMs, + }); +} + +/** + * Find the JetKVM gadget's boot-protocol keyboard interface on the host + * (HID class 03, protocol 01), e.g. "1-2:1.0". + */ +function findGadgetKeyboardInterface(): string { + const out = remoteHostExec( + "for d in /sys/bus/usb/devices/*-*/; do " + + '[ -f "$d/manufacturer" ] || continue; ' + + 'grep -qi jetkvm "$d/manufacturer" 2>/dev/null || continue; ' + + 'for i in "$d"*:*/; do ' + + '[ -f "$i/bInterfaceClass" ] || continue; ' + + '[ "$(cat "$i/bInterfaceClass")" = "03" ] || continue; ' + + '[ "$(cat "$i/bInterfaceProtocol")" = "01" ] && basename "$i"; ' + + "done; " + + "done", + ); + return out.trim().split("\n")[0] ?? ""; +} + +/** Keyboard round-trip: tap Space until the host observes it or timeout. */ +async function waitForKeyboardRoundTrip( + ra: RemoteAgent, + p: Page, + timeoutMs: number, + perTryMs = 3000, +) { + const deadline = Date.now() + timeoutMs; + while (Date.now() < deadline) { + try { + return await ra.expectKeyPress( + KEY.SPACE, + async () => { + await tapKey(p, HID_KEY.SPACE); + }, + perTryMs, + ); + } catch { + /* keyboard not (yet) delivering events */ + } + } + return []; +} + +test.beforeAll(async ({ browser }) => { + test.skip(!agent, "JETKVM_REMOTE_HOST not set"); + + await Promise.all([agent!.ensureDeployed(), ensureNoPasswordViaAPI()]); + + page = await browser.newPage(); + await page.goto("/", { waitUntil: "networkidle" }); + await ensureRpcReady(page); + await agent!.waitForInputDevices(["keyboard", "absolute_mouse", "relative_mouse"], 30000); +}); + +test.afterAll(async () => { + if (page) await page.close(); +}); + +test("keyboard self-recovers when HID writes time out while USB stays configured (#1512)", async () => { + test.setTimeout(240_000); + + // Sanity: the keyboard path works before we break it. + const before = await waitForKeyboardRoundTrip(agent!, page, 30_000); + expect(before.length, "keyboard round-trip must work before the test").toBeGreaterThan(0); + + const iface = findGadgetKeyboardInterface(); + expect(iface, "JetKVM keyboard interface not found on remote host").toMatch(/^[\d.-]+:\d+\.\d+$/); + + try { + // Stop the host from polling the keyboard interrupt endpoint. From the + // gadget's point of view this is the post-rebind broken state: the UDC + // stays "configured" but every /dev/hidg0 write times out. + remoteHostExec(`echo -n "${iface}" | sudo tee /sys/bus/usb/drivers/usbhid/unbind > /dev/null`); + + // Generate keyboard traffic so the gadget accumulates consecutive write + // timeouts. Old firmware swallows these forever; fixed firmware counts + // them and escalates to a full gadget reconfigure. + for (let i = 0; i < 8; i++) { + await tapKey(page, HID_KEY.SPACE); + await new Promise(r => setTimeout(r, 250)); + } + + // The reconfigure re-enumerates the gadget on the host, usbhid rebinds + // to the fresh interface, and key events flow again — without any manual + // identifier cycling. + const events = await waitForKeyboardRoundTrip(agent!, page, 120_000); + expect( + events.length, + "keyboard did not self-recover after HID write timeouts (issue #1512)", + ).toBeGreaterThan(0); + } finally { + // Failsafe for the failing (unfixed) case: rebind usbhid so the host + // keyboard is not left dead. Harmless if recovery already re-enumerated. + remoteHostExec( + `echo -n "${iface}" | sudo tee /sys/bus/usb/drivers/usbhid/bind > /dev/null 2>&1 || true`, + ); + } +}); diff --git a/usb.go b/usb.go index 577112b03..4a9f41470 100644 --- a/usb.go +++ b/usb.go @@ -142,6 +142,11 @@ var ( usbEmulationDesired = true lastUSBRecoveryTry time.Time + // lastHidWriteRecoveryTry rate-limits write-timeout escalations separately: + // lastUSBRecoveryTry is cleared on every loop iteration while the gadget is + // attached, which would defeat rate limiting for a recovery that only runs + // in the attached state. + lastHidWriteRecoveryTry time.Time ) func usbReadyForHidReports() bool { @@ -196,36 +201,115 @@ func attemptUSBRecovery(state string) string { // The next write/open must use the newly recreated device nodes. gadget.ResetHIDFiles() - // After rebind, the kernel recreates /dev/hidg* but the character - // devices take several seconds to become usable (ENXIO until the - // function driver attaches). Retry the keyboard HID file open with - // increasing delays up to ~20 seconds total. - delays := []time.Duration{ - 1 * time.Second, - 1 * time.Second, - 2 * time.Second, - 2 * time.Second, - 3 * time.Second, - 3 * time.Second, - 4 * time.Second, - 4 * time.Second, + if tryReopenKeyboard("udc_rebind") { + return gadget.GetUsbState() + } + + usbLogger.Warn().Msg("keyboard HID file not ready after UDC rebind; attempting full USB gadget reconfigure") + + if err := gadget.UpdateGadgetConfig(); err != nil { + usbLogger.Warn().Err(err).Msg("failed to recover USB gadget with full gadget reconfigure") + return gadget.GetUsbState() + } + gadget.ResetHIDFiles() + + if !tryReopenKeyboard("gadget_reconfigure") { + usbLogger.Warn().Msg("keyboard HID file not ready after full USB recovery retry window") } - tryReopenKeyboard := func(openDelays []time.Duration, reason string) bool { - for _, delay := range openDelays { - time.Sleep(delay) - if err := gadget.ReopenKeyboardHidFile(); err == nil { - usbLogger.Info().Str("reason", reason).Msg("keyboard HID file reopened successfully after USB recovery") - return true + + return gadget.GetUsbState() +} + +// usbRecoveryReopenDelays spaces out attempts to reopen /dev/hidg0 after a +// rebind or reconfigure: the kernel recreates the chardevs but they take +// several seconds to become usable (ENXIO until the function driver attaches). +// Roughly 20 seconds total. +var usbRecoveryReopenDelays = []time.Duration{ + 1 * time.Second, + 1 * time.Second, + 2 * time.Second, + 2 * time.Second, + 3 * time.Second, + 3 * time.Second, + 4 * time.Second, + 4 * time.Second, +} + +// keyboardProbeFailureLimit bails out of the reopen ladder early once the +// keyboard chardev has repeatedly reopened but failed the write probe: the +// broken post-rebind state does not heal by waiting, only by escalating. +const keyboardProbeFailureLimit = 3 + +func tryReopenKeyboard(reason string) bool { + probeFailures := 0 + for _, delay := range usbRecoveryReopenDelays { + time.Sleep(delay) + if err := gadget.ReopenKeyboardHidFile(); err != nil { + continue + } + + // Reopening is not proof of health: the #1512 broken state is a + // chardev that opens fine while every write times out. While the host + // is actively polling ("configured"), verify with a no-op report. + if gadget.GetUsbState() != usbgadget.USBStateConfigured { + // Host not polling yet (still enumerating, suspended, or off) — a + // write probe would stall regardless of gadget health. Accept the + // reopen; the runtime write-timeout streak remains as backstop. + usbLogger.Info().Str("reason", reason).Msg("keyboard HID file reopened successfully after USB recovery") + return true + } + + if err := gadget.VerifyKeyboardWritable(); err != nil { + probeFailures++ + usbLogger.Warn().Err(err).Str("reason", reason).Int("probe_failures", probeFailures). + Msg("keyboard HID file reopened but not writable") + if probeFailures >= keyboardProbeFailureLimit { + return false } + continue } - return false + + usbLogger.Info().Str("reason", reason).Msg("keyboard HID file reopened and verified writable after USB recovery") + return true } + return false +} - if tryReopenKeyboard(delays, "udc_rebind") { - return gadget.GetUsbState() +// attemptHidWriteRecovery escalates to a full gadget reconfigure when keyboard +// HID writes keep timing out even though the UDC reports "configured". This is +// the aftermath of a UDC rebind that left the HID function broken: the chardev +// reopens fine, so the rebind recovery path declares success, but every write +// times out and is silently dropped (issue #1512). A plain rebind has already +// proven insufficient at this point, so go straight to the reconfigure that +// manual identifier cycling would otherwise trigger. +func attemptHidWriteRecovery(state string) string { + if state != usbgadget.USBStateConfigured { + // Write timeouts outside "configured" (e.g. host suspend) are expected; + // don't let them accumulate into a spurious reconfigure right after the + // state returns to "configured". + gadget.ClearHidWriteTimeoutStreaks() + return state } - usbLogger.Warn().Msg("keyboard HID file not ready after UDC rebind; attempting full USB gadget reconfigure") + now := time.Now() + + usbStateLock.Lock() + desired := usbEmulationDesired + lastAttempt := lastHidWriteRecoveryTry + usbStateLock.Unlock() + + timeouts := gadget.KeyboardWriteTimeoutStreak() + if !usbgadget.ShouldEscalateHidWriteRecovery(state, desired, timeouts, lastAttempt, now) { + return state + } + + usbStateLock.Lock() + lastHidWriteRecoveryTry = now + usbStateLock.Unlock() + + usbLogger.Warn(). + Int("consecutive_timeouts", timeouts). + Msg("keyboard HID writes are timing out while USB is configured; attempting full USB gadget reconfigure") if err := gadget.UpdateGadgetConfig(); err != nil { usbLogger.Warn().Err(err).Msg("failed to recover USB gadget with full gadget reconfigure") @@ -233,7 +317,7 @@ func attemptUSBRecovery(state string) string { } gadget.ResetHIDFiles() - if !tryReopenKeyboard(delays, "gadget_reconfigure") { + if !tryReopenKeyboard("hid_write_timeout_reconfigure") { usbLogger.Warn().Msg("keyboard HID file not ready after full USB recovery retry window") } @@ -254,6 +338,8 @@ func checkUSBState() { newState := gadget.GetUsbState() if newState == usbgadget.USBStateNotAttached { newState = attemptUSBRecovery(newState) + } else { + newState = attemptHidWriteRecovery(newState) } usbStateLock.Lock()