Escalate USB recovery when keyboard HID writes time out

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

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
+}

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)
+	}
+}

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
+}

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()
 }

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()