From 53f7d95adb15d81742e2d5f45b96e6a898ff4d72 Mon Sep 17 00:00:00 2001 From: jsd1982 Date: Thu, 27 Aug 2026 21:52:42 -0500 Subject: [PATCH 01/12] fxpakpro: fix protocol desyncs and unbounded I/O that wedge the device Chasing a report of large PutFile transfers failing part way through -- with SNI appearing to freeze afterwards -- turned up several distinct problems, all confirmed against real hardware. Error paths abandoned a data phase the firmware had already committed to. usbint_handler_cmd picks its next state before it knows whether the command succeeded, so: * LS of a missing directory still emits a block holding the 0xFF terminator. Returning on the error code left it in the pipe, so the next command read it as its response header and everything after was out of step. Drain it before returning. * PUT sets cmdDat=1 in usbint_recv_block before f_open is even attempted, so a failed PUT parks the device in HANDLE_LOCK awaiting the payload. Returning without sending it meant the next command's bytes were consumed as file data, after which f_write on the failed handle returns zero bytes written forever inside the USB interrupt handler -- a wedge needing a physical power cycle. Report it as fatal so autoCloseableDevice reconnects within the one command of slack the firmware allows; usbint_check_connect() resets its state on the disconnect. * GET has the same shape but cannot be recovered from the host: the firmware spins in usbint_handler_dat on a size taken from a FILINFO that a failed f_stat never wrote. Report it as fatal with an explanatory message so the failure is attributed here rather than to whatever request came next. Writes were unbounded. go.bug.st/serial sets WriteTotalTimeoutConstant to 0 on Windows, which Win32 defines as "wait forever", and its Port interface exposes no SetWriteTimeout. A device that stopped draining its USB endpoint therefore hung the caller indefinitely while it held d.lock, blocking every other request for that device -- caught in a goroutine dump sitting 29 minutes inside WriteFile. Writes now run on their own goroutine under a timeout, and abandoning one closes the port so the orphan cannot interleave with whatever the caller does next. sendSerialProgress also assigned writeExact's error and carried on, so the next iteration overwrote it and a chunk that failed to send was reported as a successful transfer. The timeouts are configurable: fxpakpro_read_timeout, fxpakpro_write_timeout, and fxpakpro_honor_caller_deadline, the last controlling whether a caller's deadline aborts I/O already in flight. Also in here: openPort walked all 14 baud rates on errors that had nothing to do with speed, taking ~8 minutes to fail against a wedged device; the caller's context now reaches the write path through sendSerialProgress; stale buffers are flushed on open so a leftover block cannot desync the first command after a reconnect; and Init's hardcoded 2s budget now follows the configured read timeout, since it bounds writes as well now and too tight a value would close healthy devices. None of this stops the device wedging. A PUT onto a card that runs out of space mid-transfer spins the firmware in its interrupt handler with no error code the host can observe; these changes turn that from a silent indefinite freeze into a prompt error naming the byte offset it stopped at. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01ARLkt3NCnrwBMvpP8eAfDR --- cmd/sni/config/config.go | 20 ++- devices/snes/drivers/fxpakpro/boot.go | 2 +- devices/snes/drivers/fxpakpro/control.go | 4 +- devices/snes/drivers/fxpakpro/device.go | 38 ++++- devices/snes/drivers/fxpakpro/driver.go | 65 ++++++- devices/snes/drivers/fxpakpro/get.go | 4 +- devices/snes/drivers/fxpakpro/getfile.go | 25 ++- devices/snes/drivers/fxpakpro/info.go | 2 +- devices/snes/drivers/fxpakpro/ls.go | 46 ++++- devices/snes/drivers/fxpakpro/mkdir.go | 2 +- devices/snes/drivers/fxpakpro/mv.go | 2 +- devices/snes/drivers/fxpakpro/put.go | 4 +- devices/snes/drivers/fxpakpro/putfile.go | 50 +++++- devices/snes/drivers/fxpakpro/rm.go | 2 +- devices/snes/drivers/fxpakpro/serial.go | 209 ++++++++++++++++++----- 15 files changed, 398 insertions(+), 77 deletions(-) diff --git a/cmd/sni/config/config.go b/cmd/sni/config/config.go index e186718..efcf918 100644 --- a/cmd/sni/config/config.go +++ b/cmd/sni/config/config.go @@ -50,6 +50,20 @@ var ( "usb2snes_listen_addrs": "0.0.0.0:23074", "fxpakpro_disable": false, + // How long the fxpakpro driver waits on a device that has gone quiet or + // stopped accepting data. The firmware does its FAT work inside the USB + // interrupt handler, so a cluster allocation on a large, full, fragmented + // card can stall for seconds before it can answer; raise these if you see + // spurious timeouts on such a card. + "fxpakpro_read_timeout": "15s", + "fxpakpro_write_timeout": "15s", + // Whether a caller's context deadline or cancellation aborts I/O already + // in flight to the device. With this off, a request that has already + // started talking to the fxpakpro runs to completion (bounded by the two + // timeouts above) rather than being cut short mid-transfer by an + // impatient client. + "fxpakpro_honor_caller_deadline": true, + "retroarch_disable": false, "retroarch_hosts": "localhost:55355", "retroarch_detect_log": false, @@ -64,8 +78,8 @@ var ( "emunw_disable": false, "emunw_detect_log": false, - "proxy_disable": false, - "proxy_backend_host": "", + "proxy_disable": false, + "proxy_backend_host": "", } nwaConfigs = map[string]any{ "nwa_port_range": NwaDefaultPort, @@ -91,7 +105,7 @@ func InitDir() { Dir = filepath.Join(Dir, ".sni") // Follow XDG Base Directory Specification - if _, err := os.Stat(Dir); err != nil { + if _, err := os.Stat(Dir); err != nil { var xdgConfig = os.Getenv("XDG_CONFIG_HOME") if xdgConfig == "" { homeDir, _ := os.UserHomeDir() diff --git a/devices/snes/drivers/fxpakpro/boot.go b/devices/snes/drivers/fxpakpro/boot.go index d23b53f..b3f2f52 100644 --- a/devices/snes/drivers/fxpakpro/boot.go +++ b/devices/snes/drivers/fxpakpro/boot.go @@ -22,7 +22,7 @@ func (d *Device) boot(ctx context.Context, path string) (err error) { } // send command: - err = sendSerialChunked(d.f, 512, sb) + err = sendSerialChunked(ctx, d.f, 512, sb) if err != nil { err = d.FatalError(err) return diff --git a/devices/snes/drivers/fxpakpro/control.go b/devices/snes/drivers/fxpakpro/control.go index cffffcf..8aa2885 100644 --- a/devices/snes/drivers/fxpakpro/control.go +++ b/devices/snes/drivers/fxpakpro/control.go @@ -17,7 +17,7 @@ func (d *Device) ResetSystem(ctx context.Context) (err error) { defer d.lock.Unlock() } - err = sendSerialChunked(d.f, 512, sb) + err = sendSerialChunked(ctx, d.f, 512, sb) if err != nil { err = d.FatalError(err) return @@ -55,7 +55,7 @@ func (d *Device) ResetToMenu(ctx context.Context) (err error) { defer d.lock.Unlock() } - err = sendSerialChunked(d.f, 512, sb) + err = sendSerialChunked(ctx, d.f, 512, sb) if err != nil { err = d.FatalError(err) return diff --git a/devices/snes/drivers/fxpakpro/device.go b/devices/snes/drivers/fxpakpro/device.go index c73f347..719c5fc 100644 --- a/devices/snes/drivers/fxpakpro/device.go +++ b/devices/snes/drivers/fxpakpro/device.go @@ -6,14 +6,29 @@ import ( "go.bug.st/serial" "sni/devices" "sync" + "sync/atomic" "time" ) +// devicePort wraps the serial port so that any close marks the device closed -- +// including one done by the write path, which closes the port when it abandons +// a write so an orphaned goroutine cannot interleave with later commands. That +// close does not go through Device.Close(), so without this the isClosed flag +// would stay false and autoCloseableDevice would keep a device whose port is +// dead in its container (it consults IsClosed() to decide whether to drop it). +type devicePort struct { + serial.Port + closed atomic.Bool +} + +func (p *devicePort) Close() error { + p.closed.Store(true) + return p.Port.Close() +} + type Device struct { lock sync.Mutex - f serial.Port - - isClosed bool + f *devicePort } func (d *Device) FatalError(cause error) devices.DeviceError { @@ -25,7 +40,16 @@ func (d *Device) NonFatalError(cause error) devices.DeviceError { } func (d *Device) Init() (err error) { - ctx, cancel := context.WithDeadline(context.Background(), time.Now().Add(time.Second*2)) + // This budget used to be a hardcoded 2 seconds, back when a context + // deadline only bounded reads. It now bounds writes as well, and abandoning + // a write closes the port -- so too tight a value here would close healthy + // devices. A write only blocks when the device is not draining its USB + // endpoint, which happens while the firmware is busy inside its interrupt + // handler: FatFs cluster allocation on a large, full, fragmented card has + // been measured stalling for hundreds of milliseconds and can reach seconds. + // Use the same configured budget as every other read, so there is one knob + // (fxpakpro_read_timeout) rather than a hidden second one. + ctx, cancel := context.WithDeadline(context.Background(), time.Now().Add(noDataTimeout)) defer cancel() // run an INFO request to make sure the fxpakpro is in a valid state, else this should @@ -52,13 +76,11 @@ func (d *Device) Init() (err error) { } func (d *Device) IsClosed() bool { - return d.isClosed + return d.f.closed.Load() } func (d *Device) Close() (err error) { - err = d.f.Close() - d.isClosed = true - return + return d.f.Close() } type lockedKeyType int diff --git a/devices/snes/drivers/fxpakpro/driver.go b/devices/snes/drivers/fxpakpro/driver.go index 307ccdc..2b33ad3 100644 --- a/devices/snes/drivers/fxpakpro/driver.go +++ b/devices/snes/drivers/fxpakpro/driver.go @@ -1,6 +1,7 @@ package fxpakpro import ( + "errors" "fmt" "log" "net/url" @@ -149,6 +150,19 @@ func (d *Driver) openPort(portName string, baudRequest int) (f serial.Port, err break } log.Printf("%s: open(name=\"%s\"): %v\n", driverName, portName, err) + + // Only walk down to the next rate when this one specifically was + // rejected. Any other failure -- the port is gone, busy, or wedged -- + // applies equally to every rate, and retrying all of them just delays + // the error. A wedged fxpakpro makes each open attempt block for tens of + // seconds on Windows, so retrying the whole table costs minutes during + // which the caller is stuck. + var portErr *serial.PortError + if !errors.As(err, &portErr) || portErr.Code() != serial.InvalidSpeed { + return nil, fmt.Errorf( + "%s: failed to open serial port %s at baud %d: %w", + driverName, portName, baud, err) + } } if err != nil { return nil, fmt.Errorf("%s: failed to open serial port at any baud rate: %w", driverName, err) @@ -162,6 +176,22 @@ func (d *Driver) openPort(portName string, baudRequest int) (f serial.Port, err return nil, fmt.Errorf("%s: failed to set DTR: %w", driverName, err) } + // Discard anything left over from a previous session before issuing the + // first command. The fxpakpro cannot reset its transmit state when a client + // disconnects, so a reconnect can find bytes from an interrupted command + // still queued. Reading those as the first response desyncs the protocol: + // INFO comes back well-formed but with empty fields, Init() rejects it as a + // fatal error, and autoCloseableDevice reacts to that by closing and + // reopening -- turning one stale block into a reconnect loop. + // + // Failure to flush is not itself fatal; log it and let Init() decide. + if ferr := f.ResetInputBuffer(); ferr != nil { + log.Printf("%s: ResetInputBuffer: %v\n", driverName, ferr) + } + if ferr := f.ResetOutputBuffer(); ferr != nil { + log.Printf("%s: ResetOutputBuffer: %v\n", driverName, ferr) + } + return } @@ -199,7 +229,7 @@ func (d *Driver) openDevice(uri *url.URL) (device devices.Device, err error) { return } - dev := &Device{f: f} + dev := &Device{f: &devicePort{Port: f}} // attempt to init the device: if err = dev.Init(); err != nil { @@ -240,9 +270,42 @@ func DriverInit() { ) } + loadTimeoutConfig() + log.Println("Enabling fxpakpro snes driver") driver = &Driver{} driver.container = devices.NewDeviceDriverContainer(driver.openDevice) devices.Register(driverName, driver) } + +// loadTimeoutConfig applies the driver's timeout and cancellation settings from +// configuration. Each is only overridden when actually configured, so the +// built-in defaults in serial.go still apply when the driver is initialized +// without a loaded config -- as the tests do. viper's IsSet reports true once a +// default is registered, so this picks up the values in config.sniConfigs as +// well as anything the user set. +func loadTimeoutConfig() { + if config.Config.IsSet("fxpakpro_read_timeout") { + if v := config.Config.GetDuration("fxpakpro_read_timeout"); v > 0 { + noDataTimeout = v + } else { + log.Printf("%s: ignoring non-positive fxpakpro_read_timeout %q\n", + driverName, config.Config.GetString("fxpakpro_read_timeout")) + } + } + if config.Config.IsSet("fxpakpro_write_timeout") { + if v := config.Config.GetDuration("fxpakpro_write_timeout"); v > 0 { + writeTimeout = v + } else { + log.Printf("%s: ignoring non-positive fxpakpro_write_timeout %q\n", + driverName, config.Config.GetString("fxpakpro_write_timeout")) + } + } + if config.Config.IsSet("fxpakpro_honor_caller_deadline") { + honorCallerDeadline = config.Config.GetBool("fxpakpro_honor_caller_deadline") + } + + log.Printf("%s: read timeout %v, write timeout %v, honor caller deadline %v\n", + driverName, noDataTimeout, writeTimeout, honorCallerDeadline) +} diff --git a/devices/snes/drivers/fxpakpro/get.go b/devices/snes/drivers/fxpakpro/get.go index 5109608..3b4fb74 100644 --- a/devices/snes/drivers/fxpakpro/get.go +++ b/devices/snes/drivers/fxpakpro/get.go @@ -25,7 +25,7 @@ func (d *Device) get(ctx context.Context, space space, address uint32, size uint } // send the data to the USB port: - err = sendSerialChunked(d.f, 512, sb) + err = sendSerialChunked(ctx, d.f, 512, sb) if err != nil { err = d.FatalError(err) return @@ -40,7 +40,7 @@ func (d *Device) get(ctx context.Context, space space, address uint32, size uint n = copy(dest, data) data = data[n:] - err = sendSerialChunked(d.f, 512, sb) + err = sendSerialChunked(ctx, d.f, 512, sb) if err != nil { err = d.FatalError(err) return diff --git a/devices/snes/drivers/fxpakpro/getfile.go b/devices/snes/drivers/fxpakpro/getfile.go index 293c44d..80a0cc3 100644 --- a/devices/snes/drivers/fxpakpro/getfile.go +++ b/devices/snes/drivers/fxpakpro/getfile.go @@ -25,7 +25,7 @@ func (d *Device) getFile(ctx context.Context, path string, w io.Writer, sizeRece } // send command: - err = sendSerialChunked(d.f, 512, sb) + err = sendSerialChunked(ctx, d.f, 512, sb) if err != nil { err = d.FatalError(err) return @@ -48,8 +48,27 @@ func (d *Device) getFile(ctx context.Context, path string, w io.Writer, sizeRece return } if ec := sb[5]; ec != 0 { - received, err = 0, fmt.Errorf("getFile: %w", fxpakproError(ec)) - err = d.NonFatalError(err) + // Like PUT, the firmware commits to a data phase before it knows whether + // the command succeeded: usbint_handler_cmd sets HANDLE_DAT for GET + // regardless of whether f_stat and f_open worked. Unlike PUT, this one + // cannot be recovered from the host side. + // + // server_info.size is taken from fi.fsize, and a failed f_stat never + // writes fi -- it is a stale global shared with f_readdir. If it holds a + // non-zero value, usbint_handler_dat spins forever: f_read on the failed + // handle returns zero bytes while the loop waits for bytesSent to reach + // block_size. The main loop never gets back to usbint_check_connect(), so + // disconnecting does not help, and usbint_server_busy() reports HANDLE_DAT + // as busy, so CDC_BulkOut stops draining the OUT endpoint and writes from + // the host block too. Confirmed on hardware: this needs a power cycle. + // + // Report it as fatal so SNI closes the device and stops issuing commands + // into a pak that cannot answer, and so the failure is attributed here + // rather than to whatever unrelated request came next. + received, err = 0, fmt.Errorf( + "getFile: %w (a GET for a file the device cannot open may hang its "+ + "firmware until power cycled)", fxpakproError(ec)) + err = d.FatalError(err) return } diff --git a/devices/snes/drivers/fxpakpro/info.go b/devices/snes/drivers/fxpakpro/info.go index acf6c7e..b79f607 100644 --- a/devices/snes/drivers/fxpakpro/info.go +++ b/devices/snes/drivers/fxpakpro/info.go @@ -50,7 +50,7 @@ func (d *Device) info(ctx context.Context) (version, device, rom string, err err } // send command: - err = sendSerialChunked(d.f, 512, sb) + err = sendSerialChunked(ctx, d.f, 512, sb) if err != nil { err = d.FatalError(err) return diff --git a/devices/snes/drivers/fxpakpro/ls.go b/devices/snes/drivers/fxpakpro/ls.go index 082589d..ad086cd 100644 --- a/devices/snes/drivers/fxpakpro/ls.go +++ b/devices/snes/drivers/fxpakpro/ls.go @@ -24,7 +24,7 @@ func (d *Device) listFiles(ctx context.Context, path string) (files []devices.Di } // send the data to the USB port: - err = sendSerialChunked(d.f, 512, sb) + err = sendSerialChunked(ctx, d.f, 512, sb) if err != nil { err = d.FatalError(err) return @@ -55,8 +55,23 @@ func (d *Device) listFiles(ctx context.Context, path string) (files []devices.Di return } if ec := sb[5]; ec != 0 { - files, err = nil, fmt.Errorf("ls: failed to list for path %#v: %w", path, fxpakproError(ec)) - err = d.NonFatalError(err) + // The firmware moves to HANDLE_DAT for LS whether or not f_opendir + // succeeded, and its data handler still emits one block holding the 0xFF + // terminator on the error path (usbinterface.c, USBINT_SERVER_OPCODE_LS + // in both usbint_handler_cmd and usbint_handler_dat). Returning without + // consuming that block leaves it in the pipe, so the next command reads + // it as its response header and every command after this one is out of + // step. Because this error is non-fatal, SNI would otherwise keep using + // the desynced connection rather than reconnecting -- listing a + // directory that does not exist is routine, so this is easy to hit. + listErr := fmt.Errorf("ls: failed to list for path %#v: %w", path, fxpakproError(ec)) + if derr := drainListingTerminator(ctx, d); derr != nil { + // the stream is now of unknown alignment; force a reconnect: + files, err = nil, d.FatalError( + fmt.Errorf("%w (draining the terminating block failed: %v)", listErr, derr)) + return + } + files, err = nil, d.NonFatalError(listErr) return } @@ -126,3 +141,28 @@ recvLoop: return } + +// drainListingTerminator consumes the data block the firmware sends after a +// failed LS, so the stream stays aligned for the next command. The error path +// emits a single block starting with the 0xFF terminator, but scan the whole +// block and allow a few of them rather than assuming, so an unexpected shape +// still leaves the stream aligned rather than silently off by one. +func drainListingTerminator(ctx context.Context, d *Device) (err error) { + const maxBlocks = 4 + + sb := make([]byte, 512) + for block := 0; block < maxBlocks; block++ { + iterCtx, iterCancel := context.WithTimeout(ctx, safeTimeout) + err = recvSerial(iterCtx, d.f, sb, 512) + iterCancel() + if err != nil { + return fmt.Errorf("ls: reading terminating block %d: %w", block, err) + } + for i := 0; i < 512; i++ { + if sb[i] == 0xFF { + return nil + } + } + } + return fmt.Errorf("ls: no terminator in %d blocks after a failed listing", maxBlocks) +} diff --git a/devices/snes/drivers/fxpakpro/mkdir.go b/devices/snes/drivers/fxpakpro/mkdir.go index 705b606..6233e5d 100644 --- a/devices/snes/drivers/fxpakpro/mkdir.go +++ b/devices/snes/drivers/fxpakpro/mkdir.go @@ -22,7 +22,7 @@ func (d *Device) mkdir(ctx context.Context, path string) (err error) { } // send command: - err = sendSerialChunked(d.f, 512, sb) + err = sendSerialChunked(ctx, d.f, 512, sb) if err != nil { err = d.FatalError(err) return diff --git a/devices/snes/drivers/fxpakpro/mv.go b/devices/snes/drivers/fxpakpro/mv.go index e16d85f..4c9fd4b 100644 --- a/devices/snes/drivers/fxpakpro/mv.go +++ b/devices/snes/drivers/fxpakpro/mv.go @@ -25,7 +25,7 @@ func (d *Device) mv(ctx context.Context, path, newFilename string) (err error) { } // send command: - err = sendSerialChunked(d.f, 512, sb) + err = sendSerialChunked(ctx, d.f, 512, sb) if err != nil { err = d.FatalError(err) return diff --git a/devices/snes/drivers/fxpakpro/put.go b/devices/snes/drivers/fxpakpro/put.go index c4fd041..bce2119 100644 --- a/devices/snes/drivers/fxpakpro/put.go +++ b/devices/snes/drivers/fxpakpro/put.go @@ -26,7 +26,7 @@ func (d *Device) put(ctx context.Context, space space, address uint32, data []by } // send the data to the USB port: - err = sendSerialChunked(d.f, 512, sb) + err = sendSerialChunked(ctx, d.f, 512, sb) if err != nil { err = d.FatalError(err) return @@ -41,7 +41,7 @@ func (d *Device) put(ctx context.Context, space space, address uint32, data []by n = copy(dest, data) data = data[n:] - err = sendSerialChunked(d.f, 512, sb) + err = sendSerialChunked(ctx, d.f, 512, sb) if err != nil { err = d.FatalError(err) return diff --git a/devices/snes/drivers/fxpakpro/putfile.go b/devices/snes/drivers/fxpakpro/putfile.go index 53f5d97..ac4b246 100644 --- a/devices/snes/drivers/fxpakpro/putfile.go +++ b/devices/snes/drivers/fxpakpro/putfile.go @@ -8,6 +8,11 @@ import ( "sni/devices" ) +// putFileVerifyAfterWrite controls the post-transfer INFO round trip below. +// It exists so tests can measure the device's behavior with and without the +// extra command; production code should leave it enabled. +var putFileVerifyAfterWrite = true + type putFileRequest struct { path string rom []byte @@ -34,7 +39,7 @@ func (d *Device) putFile(ctx context.Context, path string, size uint32, r io.Rea } // send command: - err = sendSerialChunked(d.f, 512, sb) + err = sendSerialChunked(ctx, d.f, 512, sb) if err != nil { err = d.FatalError(err) return @@ -57,8 +62,27 @@ func (d *Device) putFile(ctx context.Context, path string, size uint32, r io.Rea return } if ec := sb[5]; ec != 0 { - n, err = size, fmt.Errorf("putfile: %w", fxpakproError(ec)) - err = d.NonFatalError(err) + // The device is now mid-transaction and must not be written to again. + // + // usbint_recv_block sets cmdDat=1 as soon as it sees a PUT opcode, before + // usbint_handler_cmd has even attempted f_open. So a PUT that fails still + // parks the firmware in HANDLE_LOCK waiting for the entire payload; + // server_state only leaves HANDLE_LOCK once count >= server_info.size. + // We are not sending that payload. + // + // Whatever is written next is therefore consumed as file data, and once a + // full 512-byte block lands, f_write on the failed handle returns zero + // bytes written while the loop waits for bytesRecv to reach block_size -- + // an infinite loop inside the USB interrupt handler. Confirmed on + // hardware: one failed PUT plus one following command bricks the device + // until it is physically power cycled. + // + // Reporting this as fatal makes autoCloseableDevice close and reopen the + // device, and the firmware's usbint_check_connect() resets server_state + // and cmdDat on disconnect. That is the only clean way out, and it only + // works while nothing else has been written. + n, err = 0, fmt.Errorf("putfile: %w", fxpakproError(ec)) + err = d.FatalError(err) return } @@ -78,11 +102,29 @@ func (d *Device) putFile(ctx context.Context, path string, size uint32, r io.Rea } // send data: - n, err = sendSerialProgress(d.f, 512, size, r, progress) + n, err = sendSerialProgress(ctx, d.f, 512, size, r, progress) if err != nil { err = d.FatalError(err) return } + // The fxpakpro sends exactly one response for a PUT, and it sends it before + // the data phase, so nothing in the transfer itself tells us the device kept + // up. A successful write() only means the host handed the bytes to the OS. + // The firmware does its FAT work inside the USB interrupt handler, so if it + // ever loses a packet mid-transfer it desyncs silently and we would report a + // success here, leaving the failure to surface on some later unrelated + // command. Round-trip an INFO to confirm the device is still responsive and + // still framing the protocol correctly. + // + // d.lock is already held, so mark the context to keep info() from re-locking: + if putFileVerifyAfterWrite { + subctx := context.WithValue(ctx, lockedKey, &struct{}{}) + if _, _, _, verr := d.info(subctx); verr != nil { + err = d.FatalError(fmt.Errorf("putfile: device did not respond after writing %d bytes to %#v: %w", n, path, verr)) + return + } + } + return } diff --git a/devices/snes/drivers/fxpakpro/rm.go b/devices/snes/drivers/fxpakpro/rm.go index 4d1a728..c17b51f 100644 --- a/devices/snes/drivers/fxpakpro/rm.go +++ b/devices/snes/drivers/fxpakpro/rm.go @@ -22,7 +22,7 @@ func (d *Device) rm(ctx context.Context, path string) (err error) { } // send command: - err = sendSerialChunked(d.f, 512, sb) + err = sendSerialChunked(ctx, d.f, 512, sb) if err != nil { err = d.FatalError(err) return diff --git a/devices/snes/drivers/fxpakpro/serial.go b/devices/snes/drivers/fxpakpro/serial.go index 1b6a4d6..3c96bc6 100644 --- a/devices/snes/drivers/fxpakpro/serial.go +++ b/devices/snes/drivers/fxpakpro/serial.go @@ -7,6 +7,7 @@ import ( "fmt" "go.bug.st/serial" "io" + "log" "runtime/trace" "sni/devices" "time" @@ -14,6 +15,30 @@ import ( const safeTimeout = time.Second * 1 +// Timeout and cancellation policy for talking to the device. These are vars +// rather than consts because DriverInit() overrides them from configuration +// (SNI_FXPAKPRO_READ_TIMEOUT, SNI_FXPAKPRO_WRITE_TIMEOUT and +// SNI_FXPAKPRO_HONOR_CALLER_DEADLINE); tests also adjust them directly. The +// values here are the defaults used when configuration has not been loaded. +var ( + // noDataTimeout is how long readExact waits with no bytes at all arriving + // before declaring the device unresponsive. + noDataTimeout = time.Second * 15 + + // writeTimeout is how long a single write is allowed to make no progress + // before the device is declared unable to accept data. See + // writeWithTimeout. + writeTimeout = time.Second * 15 + + // honorCallerDeadline controls whether a caller's context deadline or + // cancellation aborts I/O already in flight to the device. When false, only + // the two timeouts above bound device I/O, so a transfer that has already + // started is not cut short by an impatient client. The device has no way to + // be told that a command was abandoned, so stopping midway through one + // leaves the protocol out of step until the stream is drained. + honorCallerDeadline = true +) + func readExactGeneric(ctx context.Context, f io.Reader, chunkSize uint32, buf []byte) (p uint32, err error) { ctx, task := trace.NewTask(ctx, "readExactGeneric") defer task.End() @@ -57,12 +82,21 @@ func readExact(ctx context.Context, f serial.Port, chunkSize uint32, buf []byte) haveHardDeadline := false var deadline time.Time - if deadline, ok = ctx.Deadline(); ok { - trace.Logf(ctx, "deadline", "deadline=%v", deadline) - haveHardDeadline = true + if honorCallerDeadline { + if deadline, ok = ctx.Deadline(); ok { + trace.Logf(ctx, "deadline", "deadline=%v", deadline) + haveHardDeadline = true + } } - attempts := 0 + // Budget for how long the device may stay completely silent before we give + // up. This is a total elapsed time since the last byte arrived, not a count + // of read attempts. FatFs runs inside the firmware's USB interrupt handler, + // and a cluster allocation on a large, full, fragmented card can scan a + // sizeable fraction of the FAT before the device can reply: a 64 GB card + // with 32 KB clusters has an ~8 MB FAT, so a worst-case scan is on the order + // of ten seconds. + lastProgress := time.Now() p = 0 for p < chunkSize { // update the read timeout if applicable: @@ -71,9 +105,14 @@ func readExact(ctx context.Context, f serial.Port, chunkSize uint32, buf []byte) if haveHardDeadline { // we have a hard deadline to meet: timeout = time.Until(deadline) - if timeout < 0 { - // deadline already exceeded so cause Read() to fail instantly: - timeout = 0 + if timeout <= 0 { + // Deadline already exceeded. Return now rather than looping: + // Read() would come straight back with zero bytes and spin + // until the silence budget expired. + err = fmt.Errorf( + "readExact: context deadline exceeded after reading %d of %d bytes", + p, chunkSize) + return } } else { // no hard deadline; each read() attempt gets its own timeout: @@ -100,14 +139,16 @@ func readExact(ctx context.Context, f serial.Port, chunkSize uint32, buf []byte) } p += uint32(n) if p == lastp { - attempts++ - trace.Logf(ctx, "retry", "attempts = %v", attempts) - if attempts >= 9 { - err = fmt.Errorf("readExact: timed out after %d attempts of reading zero bytes", attempts) + silent := time.Since(lastProgress) + trace.Logf(ctx, "retry", "silent for %v", silent) + if silent >= noDataTimeout { + err = fmt.Errorf( + "readExact: no data from device for %v after reading %d of %d bytes", + silent, p, chunkSize) return } } else { - attempts = 0 + lastProgress = time.Now() } if err != nil { return @@ -118,59 +159,130 @@ func readExact(ctx context.Context, f serial.Port, chunkSize uint32, buf []byte) return } -func writeExact(ctx context.Context, w io.Writer, chunkSize uint32, buf []byte) (p uint32, err error) { - ctx, task := trace.NewTask(ctx, "writeExact") - defer task.End() - - p = uint32(0) - for p < chunkSize { +// blockingWrite writes all of buf to w. It can block indefinitely, so it is +// only ever called on a goroutine owned by writeWithTimeout. +func blockingWrite(w io.Writer, buf []byte) (p uint32, err error) { + for p < uint32(len(buf)) { var n int - n, err = w.Write(buf[p:chunkSize]) - trace.Logf(ctx, "write", "write(buf[%d:%d]) = %v, %v", p, chunkSize, n, err) + n, err = w.Write(buf[p:]) if n < 0 { n = 0 } if debugLog != nil { - debugLog.Printf("writeExact: write returned n=%d, err=%v\n%s", n, err, hex.Dump(buf[p:p+uint32(n)])) + debugLog.Printf("write returned n=%d, err=%v\n%s", n, err, hex.Dump(buf[p:p+uint32(n)])) } if err != nil { return } p += uint32(n) } - return } +// writeWithTimeout writes all of buf to w, giving up if the device stops +// accepting data. +// +// This has to be done on a separate goroutine because there is no way to bound +// the write itself. go.bug.st/serial's Port interface exposes SetReadTimeout +// but no SetWriteTimeout, and on Windows the library sets +// WriteTotalTimeoutConstant and WriteTotalTimeoutMultiplier to 0, which Win32 +// COMMTIMEOUTS defines as "wait forever". So when the fxpakpro stops draining +// its USB OUT endpoint and NAKs indefinitely, a plain Write() never returns. +// Left unbounded that hangs the calling goroutine while it holds d.lock, which +// blocks every other request for that device -- SNI appears to freeze rather +// than reporting a failed transfer. +// +// When we give up, the goroutine is still inside Write() and may yet put bytes +// on the wire. It must never be left running alongside a later command: the +// caller releases d.lock on the way out, so the next command would write +// concurrently with the orphan and interleave with it, corrupting the protocol. +// (Observed in practice: after an abandoned write the following command read +// the abandoned one's USBA response.) +// +// So abandoning a write also closes the port. That makes the pending Write() +// fail so the goroutine exits, and guarantees every later write on this port +// fails immediately instead of racing. Both callers already treat this error as +// fatal, which makes SNI close and reopen the device anyway; doing it here just +// removes the window in between. +func writeWithTimeout(ctx context.Context, w io.Writer, buf []byte) (p uint32, err error) { + type writeResult struct { + p uint32 + err error + } + // buffered so the goroutine can always finish even if we stopped waiting: + done := make(chan writeResult, 1) + go func() { + wp, werr := blockingWrite(w, buf) + done <- writeResult{wp, werr} + }() + + // Wait on the caller's context and our own budget separately, rather than + // clamping one to the other, so the error names the actual cause: a + // cancelled request and an unresponsive device are different problems. + // + // When the caller's deadline is not honored, cancelled stays nil, and a + // receive on a nil channel blocks forever -- which disables that arm of the + // select without needing a second copy of it. + var cancelled <-chan struct{} + if honorCallerDeadline { + cancelled = ctx.Done() + } + + timer := time.NewTimer(writeTimeout) + defer timer.Stop() + + select { + case r := <-done: + trace.Logf(ctx, "write", "write(%d bytes) = %v, %v", len(buf), r.p, r.err) + return r.p, r.err + case <-cancelled: + abandonPort(w) + return 0, fmt.Errorf("write: abandoned %d byte write: %w", len(buf), ctx.Err()) + case <-timer.C: + abandonPort(w) + // how much made it out is unknown, so report none of it: + return 0, fmt.Errorf( + "write: device accepted no data for %v while writing %d bytes; "+ + "it is not draining its USB endpoint", writeTimeout, len(buf)) + } +} + +// abandonPort closes the port underneath a write we have stopped waiting for, +// so the orphaned goroutine cannot interleave with whatever the caller does +// next. Closing is what unblocks it: a pending Write() fails once the handle is +// gone. Errors are logged rather than returned; the caller already has a more +// useful error describing why the write was abandoned. +func abandonPort(w io.Writer) { + c, ok := w.(io.Closer) + if !ok { + return + } + if err := c.Close(); err != nil { + log.Printf("%s: closing port after an abandoned write: %v\n", driverName, err) + } +} + +func writeExact(ctx context.Context, w io.Writer, chunkSize uint32, buf []byte) (p uint32, err error) { + ctx, task := trace.NewTask(ctx, "writeExact") + defer task.End() + + return writeWithTimeout(ctx, w, buf[:chunkSize]) +} + func sendSerial(ctx context.Context, f serial.Port, buf []byte) (err error) { ctx, task := trace.NewTask(ctx, "sendSerial") defer task.End() - sent := 0 - for sent < len(buf) { - var n int - n, err = f.Write(buf[sent:]) - trace.Logf(ctx, "write", "write(buf[%d:]) = %v, %v", sent, n, err) - if n < 0 { - n = 0 - } - if debugLog != nil { - debugLog.Printf("sendSerial: write returned n=%d, err=%v\n%v", n, err, hex.Dump(buf[sent:sent+n])) - } - if err != nil { - return - } - sent += n - } - return nil + _, err = writeWithTimeout(ctx, f, buf) + return } -func sendSerialChunked(f serial.Port, chunkSize uint32, buf []byte) (err error) { - _, err = sendSerialProgress(f, chunkSize, uint32(len(buf)), bytes.NewReader(buf), nil) +func sendSerialChunked(ctx context.Context, f serial.Port, chunkSize uint32, buf []byte) (err error) { + _, err = sendSerialProgress(ctx, f, chunkSize, uint32(len(buf)), bytes.NewReader(buf), nil) return } -func sendSerialProgress(f serial.Port, chunkSize uint32, size uint32, r io.Reader, report devices.ProgressReportFunc) (sent uint32, err error) { +func sendSerialProgress(ctx context.Context, f serial.Port, chunkSize uint32, size uint32, r io.Reader, report devices.ProgressReportFunc) (sent uint32, err error) { // chunkSize is how many bytes each chunk is expected to be sized according to the protocol; valid values are [64, 512]. if chunkSize != 64 && chunkSize != 512 { panic("chunkSize must be either 64 or 512") @@ -178,8 +290,6 @@ func sendSerialProgress(f serial.Port, chunkSize uint32, size uint32, r io.Reade var buf [512]byte - ctx := context.Background() - // transfer main chunks: chunks := size / chunkSize for i := uint32(0); i < chunks; i++ { @@ -204,6 +314,13 @@ func sendSerialProgress(f serial.Port, chunkSize uint32, size uint32, r io.Reade n, err = writeExact(ctx, f, chunkSize, buf[:chunkSize]) sent += n + if err != nil { + // bail out immediately; continuing would silently drop this error + // when the next iteration reassigns err, reporting a short or + // corrupt transfer as a success: + err = fmt.Errorf("sendSerialProgress: write failed after %d of %d bytes: %w", sent, size, err) + return + } } // transfer any remainder: @@ -228,6 +345,10 @@ func sendSerialProgress(f serial.Port, chunkSize uint32, size uint32, r io.Reade n, err = writeExact(ctx, f, chunkSize, buf[:chunkSize]) sent += n + if err != nil { + err = fmt.Errorf("sendSerialProgress: write failed after %d of %d bytes: %w", sent, size, err) + return + } } // final progress report: From a90d0350c1e365d7a2a1a28b5078480718317e9c Mon Sep 17 00:00:00 2001 From: jsd1982 Date: Thu, 27 Aug 2026 21:53:03 -0500 Subject: [PATCH 02/12] fxpakpro: add tests covering the transfer failures and error paths Unit tests, which need no hardware: * sendserial_test.go covers the swallowed write error and the write timeout. The write-error case needs a transient failure to be meaningful: a permanently broken port leaves err set on the final loop iteration, so it gets returned by accident and the bug hides. Against the unfixed code this returns a nil error with sent=7680 of 8192 -- one chunk silently dropped. * driver_config_test.go covers the timeout settings, including that a non-positive value is rejected rather than applied, which would otherwise reintroduce the unbounded wait. * openport_test.go asserts one baud rate is tried, not fourteen. Hardware tests, which skip when no fxpakpro is attached: * stress_test.go interleaves PUT/GET/LS/MKDIR/RM and memory reads in a seeded random order at sizes deliberately off the 512 byte block boundary. Every operation is logged so a failure can be replayed with SNI_TEST_SEED, and on failure it probes whether the device was merely slow, lost the command, or is wedged. Mixing VGET in matters: it uses a 64 byte command block where the filesystem commands use 512, and the firmware only re-evaluates cmd_size when recv_buffer_offset crosses 64 from below. * errorpath_test.go issues a failing ls/get/put and checks whether the stream is still aligned afterwards, one path per run since a failure can wedge the device. putErrorRecovers covers the fix through AutoCloseableDevice, the layer grpcimpl uses. * diskfull_test.go fills the card to find the boundary, and reports which of the two disk-full cases occurred: a clean rejection before the data phase, or the unrecoverable mid-transfer stall. * putfile_test.go adds large-transfer, write-size and overwrite cases. The write-size sweep is what ruled out the original theory that the host was outrunning the device: throughput is identical whether SNI writes 512 bytes or 64 KiB per call, because the host is already blocked on USB NAKs, so inter-chunk sleeps would change nothing. * deadline_test.go, largexfer_test.go, bootpath_test.go and cleanup_test.go cover the deadline policy, repeated large transfers, menu versus in-game state, and clearing leftovers off the card. device_test.go wires the SNI_FXPAKPRO_* environment variables into the test binary. Test binaries never call config.Load(), so the settings were silently inert under test and any config-dependent result would have been meaningless. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01ARLkt3NCnrwBMvpP8eAfDR --- .../snes/drivers/fxpakpro/bootpath_test.go | 80 ++++ devices/snes/drivers/fxpakpro/cleanup_test.go | 71 +++ .../snes/drivers/fxpakpro/deadline_test.go | 85 ++++ devices/snes/drivers/fxpakpro/device_test.go | 33 ++ .../snes/drivers/fxpakpro/diskfull_test.go | 97 ++++ .../drivers/fxpakpro/driver_config_test.go | 78 ++++ .../snes/drivers/fxpakpro/errorpath_test.go | 141 ++++++ .../snes/drivers/fxpakpro/largexfer_test.go | 99 ++++ .../snes/drivers/fxpakpro/openport_test.go | 45 ++ .../fxpakpro/putfile_autoclose_test.go | 101 +++++ .../drivers/fxpakpro/putfile_drain_test.go | 117 +++++ .../drivers/fxpakpro/putfile_snfm_test.go | 139 ++++++ devices/snes/drivers/fxpakpro/putfile_test.go | 427 ++++++++++++++++++ .../snes/drivers/fxpakpro/sendserial_test.go | 176 ++++++++ devices/snes/drivers/fxpakpro/stress_test.go | 339 ++++++++++++++ 15 files changed, 2028 insertions(+) create mode 100644 devices/snes/drivers/fxpakpro/bootpath_test.go create mode 100644 devices/snes/drivers/fxpakpro/cleanup_test.go create mode 100644 devices/snes/drivers/fxpakpro/deadline_test.go create mode 100644 devices/snes/drivers/fxpakpro/diskfull_test.go create mode 100644 devices/snes/drivers/fxpakpro/driver_config_test.go create mode 100644 devices/snes/drivers/fxpakpro/errorpath_test.go create mode 100644 devices/snes/drivers/fxpakpro/largexfer_test.go create mode 100644 devices/snes/drivers/fxpakpro/openport_test.go create mode 100644 devices/snes/drivers/fxpakpro/putfile_autoclose_test.go create mode 100644 devices/snes/drivers/fxpakpro/putfile_drain_test.go create mode 100644 devices/snes/drivers/fxpakpro/putfile_snfm_test.go create mode 100644 devices/snes/drivers/fxpakpro/sendserial_test.go create mode 100644 devices/snes/drivers/fxpakpro/stress_test.go diff --git a/devices/snes/drivers/fxpakpro/bootpath_test.go b/devices/snes/drivers/fxpakpro/bootpath_test.go new file mode 100644 index 0000000..a02c1cf --- /dev/null +++ b/devices/snes/drivers/fxpakpro/bootpath_test.go @@ -0,0 +1,80 @@ +package fxpakpro + +import ( + "context" + "os" + "testing" + "time" +) + +// TestDevice_bootPath boots the ROM named by SNI_TEST_BOOT_PATH and reports +// what the device says it is running afterwards. The firmware polls USB very +// differently depending on whether it sits in the system menu or runs a ROM: +// menu_main_loop() sleeps 20ms per iteration before calling usbint_handler(), +// whereas the in-game loop in main.c calls it every iteration with no sleep. +// An MSU-1 ROM is different again -- it runs while(!msu1_loop()), which reaches +// usbint_handler() only when it has no command of its own and is streaming +// audio off the same SD card. +func TestDevice_bootPath(t *testing.T) { + path := os.Getenv("SNI_TEST_BOOT_PATH") + if path == "" { + t.Skip("set SNI_TEST_BOOT_PATH to the ROM to boot") + } + + d := openExactDevice(t) + defer d.Close() + ctx := context.Background() + + if _, _, rom, err := d.info(ctx); err != nil { + t.Fatalf("info() before boot: %v", err) + } else { + t.Logf("before boot, running: %q", rom) + } + + start := time.Now() + if err := d.boot(ctx, path); err != nil { + t.Fatalf("boot(%s): %v", path, err) + } + t.Logf("boot(%s) returned in %v", path, time.Since(start)) + + // give the SNES a moment to actually start the ROM. Each probe gets its own + // short deadline, with a pause between them, so a device that has stopped + // answering fails quickly instead of spinning. + for attempt := 1; attempt <= 10; attempt++ { + time.Sleep(2 * time.Second) + + pctx, cancel := context.WithTimeout(context.Background(), 3*time.Second) + _, _, rom, err := d.info(pctx) + cancel() + if err != nil { + t.Logf("probe %d: info() -> %v", attempt, err) + continue + } + t.Logf("probe %d: running %q", attempt, rom) + if rom != "" && rom != "/sd2snes/menu.bin" { + t.Logf("boot confirmed after %v", time.Since(start)) + return + } + } + t.Errorf("device never reported a booted ROM within 10 probes") +} + +// TestDevice_info reports what the device is currently running. Useful as a +// liveness and state probe between tests, particularly to confirm whether the +// firmware is sitting in the system menu or executing a ROM, which changes how +// often the main loop calls usbint_handler(). +func TestDevice_info(t *testing.T) { + d := openExactDevice(t) + defer d.Close() + + version, device, rom, err := d.info(context.Background()) + if err != nil { + t.Fatalf("info(): %v", err) + } + t.Logf("version=%q device=%q rom=%q", version, device, rom) + if rom == "/sd2snes/menu.bin" || rom == "/sd2snes/m3nu.bin" { + t.Logf("state: SYSTEM MENU (menu_main_loop, sleep_ms(20) per usbint_handler call)") + } else { + t.Logf("state: IN-GAME (main.c loop, usbint_handler every iteration)") + } +} diff --git a/devices/snes/drivers/fxpakpro/cleanup_test.go b/devices/snes/drivers/fxpakpro/cleanup_test.go new file mode 100644 index 0000000..eda8e97 --- /dev/null +++ b/devices/snes/drivers/fxpakpro/cleanup_test.go @@ -0,0 +1,71 @@ +package fxpakpro + +import ( + "context" + "os" + "strings" + "testing" +) + +// TestCleanupDirs removes everything under the directories named in +// SNI_TEST_CLEANUP_DIRS (comma separated), then the directories themselves. +// Aborted test runs leave files behind, and this card has very little free +// space, so they need clearing between runs. +func TestCleanupDirs(t *testing.T) { + list := os.Getenv("SNI_TEST_CLEANUP_DIRS") + if list == "" { + t.Skip("set SNI_TEST_CLEANUP_DIRS to a comma separated list of directories") + } + + d := openExactDevice(t) + defer d.Close() + ctx := context.Background() + + var rmDir func(dir string, depth int) + rmDir = func(dir string, depth int) { + files, err := d.listFiles(ctx, dir) + if err != nil { + t.Logf("ls(%s): %v", dir, err) + return + } + for _, f := range files { + if f.Name == "." || f.Name == ".." { + continue + } + child := dir + "/" + f.Name + if f.Type == 0 && depth < 4 { + rmDir(child, depth+1) + continue + } + if err := d.rm(ctx, child); err != nil { + t.Logf("rm(%s): %v", child, err) + } + } + if err := d.rm(ctx, dir); err != nil { + t.Logf("rm(%s): %v", dir, err) + } else { + t.Logf("removed %s", dir) + } + } + + for _, dir := range strings.Split(list, ",") { + dir = strings.TrimSpace(dir) + if dir == "" { + continue + } + rmDir(dir, 0) + } + + // show what is left at the root + files, err := d.listFiles(ctx, "") + if err != nil { + t.Logf("ls(root): %v", err) + return + } + for _, f := range files { + if f.Name == "." || f.Name == ".." { + continue + } + t.Logf("root: %q (type=%v)", f.Name, f.Type) + } +} diff --git a/devices/snes/drivers/fxpakpro/deadline_test.go b/devices/snes/drivers/fxpakpro/deadline_test.go new file mode 100644 index 0000000..e37928a --- /dev/null +++ b/devices/snes/drivers/fxpakpro/deadline_test.go @@ -0,0 +1,85 @@ +package fxpakpro + +import ( + "context" + "testing" + "time" +) + +func expiredContext() (context.Context, context.CancelFunc) { + return context.WithDeadline(context.Background(), time.Now().Add(-time.Second)) +} + +// TestDevice_deadlinePolicy exercises fxpakpro_honor_caller_deadline against +// the real device. With the policy on, a caller whose deadline has already +// passed must not get to talk to the device; with it off, the same call must +// run to completion under the driver's own timeouts instead. +func TestDevice_deadlinePolicy(t *testing.T) { + d := openExactDevice(t) + defer d.Close() + + restore := honorCallerDeadline + defer func() { honorCallerDeadline = restore }() + + // baseline: the device is healthy before we start + if _, _, rom, err := d.info(context.Background()); err != nil { + t.Fatalf("baseline info(): %v", err) + } else { + t.Logf("baseline ok, rom=%q", rom) + } + + // The policy-off case runs first: honoring an expired deadline abandons a + // write, which closes the port, so that case has to come last. + t.Run("ignored", func(t *testing.T) { + honorCallerDeadline = false + + ctx, cancel := expiredContext() + defer cancel() + + start := time.Now() + version, _, rom, err := d.info(ctx) + elapsed := time.Since(start) + if err != nil { + t.Fatalf("info() with the deadline policy off failed after %v: %v", elapsed, err) + } + if version == "" { + t.Fatalf("info() returned an empty version; the stream is out of step") + } + t.Logf("completed in %v despite the expired deadline: version=%q rom=%q", + elapsed, version, rom) + }) + + t.Run("honored", func(t *testing.T) { + honorCallerDeadline = true + + ctx, cancel := expiredContext() + defer cancel() + + start := time.Now() + _, _, _, err := d.info(ctx) + elapsed := time.Since(start) + if err == nil { + t.Fatalf("info() with an expired deadline succeeded after %v; want it aborted", elapsed) + } + t.Logf("aborted after %v: %v", elapsed, err) + if elapsed > 5*time.Second { + t.Errorf("abort took %v; an already-expired deadline should return promptly", elapsed) + } + + // Abandoning the write must have closed the port, so the orphaned + // goroutine cannot interleave with a later command. The next call has to + // fail immediately rather than sitting through the write timeout. + nstart := time.Now() + _, _, _, nerr := d.info(context.Background()) + nelapsed := time.Since(nstart) + if nerr == nil { + t.Errorf("a command succeeded after an abandoned write; the port should be closed") + } else { + t.Logf("next command failed in %v as expected: %v", nelapsed, nerr) + } + if nelapsed > 5*time.Second { + t.Errorf("next command took %v; a closed port should fail immediately, "+ + "not sit through the %v write timeout", nelapsed, writeTimeout) + } + }) +} diff --git a/devices/snes/drivers/fxpakpro/device_test.go b/devices/snes/drivers/fxpakpro/device_test.go index 4edd7cb..3cb0d2c 100644 --- a/devices/snes/drivers/fxpakpro/device_test.go +++ b/devices/snes/drivers/fxpakpro/device_test.go @@ -2,12 +2,33 @@ package fxpakpro import ( "context" + "fmt" + "net/url" + "os" + "strings" + + "sni/cmd/sni/config" "sni/devices" "sni/protos/sni" "testing" ) func init() { + // The daemon binds SNI_* environment variables to config keys during + // config.Load(), which test binaries never call. Wire up just the fxpakpro + // timeout knobs here so hardware tests can be run against different + // settings without dragging in the rest of the config bootstrap and its + // filesystem side effects. + for _, key := range []string{ + "fxpakpro_read_timeout", + "fxpakpro_write_timeout", + "fxpakpro_honor_caller_deadline", + } { + if v := os.Getenv("SNI_" + strings.ToUpper(key)); v != "" { + config.Config.Set(key, v) + } + } + DriverInit() } @@ -155,3 +176,15 @@ func BenchmarkMemory(b *testing.B) { } }) } + +// firstDeviceURI returns the URI of the first detected fxpakpro device. +func firstDeviceURI() (*url.URL, error) { + devs, err := driver.Detect() + if err != nil { + return nil, err + } + if len(devs) == 0 { + return nil, fmt.Errorf("no fxpakpro devices found") + } + return &devs[0].Uri, nil +} diff --git a/devices/snes/drivers/fxpakpro/diskfull_test.go b/devices/snes/drivers/fxpakpro/diskfull_test.go new file mode 100644 index 0000000..5e558eb --- /dev/null +++ b/devices/snes/drivers/fxpakpro/diskfull_test.go @@ -0,0 +1,97 @@ +package fxpakpro + +import ( + "bytes" + "context" + "fmt" + "os" + "strconv" + "testing" + "time" +) + +// TestDevice_fillUntilFull writes files until the card runs out of space, to +// find out what the device does at the boundary. +// +// There are two distinct disk-full cases and they behave very differently: +// +// - f_open fails up front, the device answers with an error code, and SNI can +// bail out cleanly. putFile now treats that as fatal so the connection is +// torn down inside the one-command window the firmware allows. +// - f_open succeeds and f_write fails partway through the data phase. There is +// no error code to see: usbint_recv_block loops +// `while (bytesRecv != block_size && count < size)` and adds bytesWritten, +// which is 0 once the card is full, so it never advances -- an infinite loop +// inside the USB interrupt handler. The device stops draining its OUT +// endpoint and the host blocks mid-transfer. +// +// The second is unrecoverable and is the better match for an end user uploading +// a 4 MiB ROM to a card packed with MSU tracks. +func TestDevice_fillUntilFull(t *testing.T) { + if os.Getenv("SNI_TEST_FILL") == "" { + t.Skip("set SNI_TEST_FILL=1; this fills the SD card and can wedge the device") + } + + size := uint32(4 * 1024 * 1024) + if v := os.Getenv("SNI_TEST_XFER_SIZE"); v != "" { + n, err := strconv.ParseUint(v, 0, 32) + if err != nil { + t.Fatalf("SNI_TEST_XFER_SIZE=%q: %v", v, err) + } + size = uint32(n) + } + + d := openExactDevice(t) + defer d.Close() + ctx := context.Background() + + const dir = "unittest-fill" + if err := d.mkdir(ctx, dir); err != nil { + if _, lserr := d.listFiles(ctx, dir); lserr != nil { + t.Fatalf("mkdir(%s): %v (and it does not exist: %v)", dir, err, lserr) + } + } + + payload := filePattern(0xa5a5a5a5, size) + t.Logf("filling with %d byte files", size) + + start := time.Now() + for i := 1; ; i++ { + path := fmt.Sprintf("%s/fill%04d.bin", dir, i) + + putStart := time.Now() + n, err := d.putFile(ctx, path, size, bytes.NewReader(payload), nil) + putDur := time.Since(putStart) + + if err == nil { + if i%10 == 0 { + t.Logf("file %d written (%v each, %v total)", i, + putDur.Round(time.Millisecond), time.Since(start).Round(time.Second)) + } + continue + } + + // This is the interesting part: how did it fail? + t.Logf("file %d FAILED after %v having sent %d of %d bytes", i, putDur, n, size) + t.Logf("error: %v", err) + + switch { + case n == 0: + t.Logf("=> clean rejection before the data phase (device answered with "+ + "an error code); %d files written in %v", i-1, time.Since(start)) + case n < size: + t.Logf("=> WEDGED MID-TRANSFER: the device accepted the command, then "+ + "stopped draining after %d of %d bytes. This is the f_write "+ + "disk-full case: no error code to see, and the firmware is "+ + "spinning in its USB interrupt handler.", n, size) + } + + // is it still alive? + probe := time.Now() + if _, _, _, ierr := d.info(ctx); ierr != nil { + t.Fatalf("device unresponsive %v after the failure: %v", time.Since(probe), ierr) + } + t.Logf("device still responds after the failure (%v)", time.Since(probe)) + return + } +} diff --git a/devices/snes/drivers/fxpakpro/driver_config_test.go b/devices/snes/drivers/fxpakpro/driver_config_test.go new file mode 100644 index 0000000..41f4f87 --- /dev/null +++ b/devices/snes/drivers/fxpakpro/driver_config_test.go @@ -0,0 +1,78 @@ +package fxpakpro + +import ( + "context" + "testing" + "time" + + "sni/cmd/sni/config" +) + +// contextExpired returns a context whose deadline has already passed. +func contextExpired() (context.Context, context.CancelFunc) { + return context.WithDeadline(context.Background(), time.Now().Add(-time.Second)) +} + +func Test_loadTimeoutConfig(t *testing.T) { + oldRead, oldWrite, oldHonor := noDataTimeout, writeTimeout, honorCallerDeadline + defer func() { + noDataTimeout, writeTimeout, honorCallerDeadline = oldRead, oldWrite, oldHonor + }() + + config.Config.Set("fxpakpro_read_timeout", "42s") + config.Config.Set("fxpakpro_write_timeout", "7s") + config.Config.Set("fxpakpro_honor_caller_deadline", false) + + loadTimeoutConfig() + + if noDataTimeout != 42*time.Second { + t.Errorf("noDataTimeout = %v; want 42s", noDataTimeout) + } + if writeTimeout != 7*time.Second { + t.Errorf("writeTimeout = %v; want 7s", writeTimeout) + } + if honorCallerDeadline { + t.Errorf("honorCallerDeadline = true; want false") + } + + // a nonsense value must not disable the timeout entirely, which would + // reintroduce the unbounded wait these settings exist to prevent: + config.Config.Set("fxpakpro_read_timeout", "0s") + config.Config.Set("fxpakpro_write_timeout", "-5s") + loadTimeoutConfig() + + if noDataTimeout != 42*time.Second { + t.Errorf("noDataTimeout = %v after a 0s setting; want the previous value kept", noDataTimeout) + } + if writeTimeout != 7*time.Second { + t.Errorf("writeTimeout = %v after a negative setting; want the previous value kept", writeTimeout) + } +} + +// Test_honorCallerDeadline_off checks that with the policy disabled, a caller's +// expired deadline no longer aborts a write; only the driver's own budget does. +func Test_honorCallerDeadline_off(t *testing.T) { + oldHonor, oldWrite := honorCallerDeadline, writeTimeout + honorCallerDeadline = false + writeTimeout = 150 * time.Millisecond + defer func() { honorCallerDeadline, writeTimeout = oldHonor, oldWrite }() + + p := &blockingPort{release: make(chan struct{}), started: make(chan struct{})} + defer close(p.release) + + // already-expired context: with the policy on this returns immediately. + ctx, cancel := contextExpired() + defer cancel() + + start := time.Now() + _, err := writeExact(ctx, p, 512, make([]byte, 512)) + elapsed := time.Since(start) + + if err == nil { + t.Fatalf("writeExact() returned nil error; want the write-timeout error") + } + if elapsed < 100*time.Millisecond { + t.Errorf("writeExact() returned after %v; with the caller deadline ignored "+ + "it should have waited for the %v budget", elapsed, writeTimeout) + } +} diff --git a/devices/snes/drivers/fxpakpro/errorpath_test.go b/devices/snes/drivers/fxpakpro/errorpath_test.go new file mode 100644 index 0000000..2720604 --- /dev/null +++ b/devices/snes/drivers/fxpakpro/errorpath_test.go @@ -0,0 +1,141 @@ +package fxpakpro + +import ( + "bytes" + "context" + "os" + "testing" + "time" +) + +// TestDevice_errorPathStaysAligned checks that a command which fails with a +// device error code leaves the protocol stream aligned, by issuing a normal +// command afterwards and seeing whether it still gets a sane reply. +// +// This matters because the firmware commits to a data phase before it knows +// whether the command succeeded: +// +// - LS sets HANDLE_DAT regardless of f_opendir, and still emits a block +// holding the 0xFF terminator on the error path. +// - GET sets HANDLE_DAT regardless of f_stat/f_open, with server_info.size +// taken from a FILINFO that a failed f_stat never wrote. +// - PUT sets cmdDat=1 in usbint_recv_block before f_open is even attempted, +// then waits in HANDLE_LOCK for the whole payload; server_state only leaves +// HANDLE_LOCK once count >= server_info.size in usbint_recv_block. +// +// SNI returns as soon as it sees the error code in every case, so anything the +// device still expects to send or receive is left in the pipe. +// +// Select which path to exercise with SNI_TEST_ERROR_PATH=ls|get|put. One per +// run, because a failure here can wedge the device. +func TestDevice_errorPathStaysAligned(t *testing.T) { + which := os.Getenv("SNI_TEST_ERROR_PATH") + if which == "" { + t.Skip("set SNI_TEST_ERROR_PATH to ls, get or put") + } + + d := openExactDevice(t) + defer d.Close() + ctx := context.Background() + + if _, _, rom, err := d.info(ctx); err != nil { + t.Fatalf("baseline info(): %v", err) + } else { + t.Logf("baseline ok, rom=%q", rom) + } + + const missingDir = "unittest-does-not-exist-xyz" + const missingFile = missingDir + "/nope.bin" + + start := time.Now() + var opErr error + switch which { + case "ls": + _, opErr = d.listFiles(ctx, missingDir) + case "get": + var w bytes.Buffer + _, opErr = d.getFile(ctx, missingFile, &w, nil, nil) + case "put": + // a path whose parent does not exist, so f_open fails on the device + payload := make([]byte, 4096) + _, opErr = d.putFile(ctx, missingFile, uint32(len(payload)), bytes.NewReader(payload), nil) + default: + t.Fatalf("SNI_TEST_ERROR_PATH=%q: want ls, get or put", which) + } + + if opErr == nil { + t.Fatalf("%s on a missing path unexpectedly succeeded", which) + } + t.Logf("%s failed as expected in %v: %v", which, time.Since(start), opErr) + + // The real question: is the stream still aligned? + probeStart := time.Now() + version, _, _, err := d.info(ctx) + probeElapsed := time.Since(probeStart) + if err != nil { + t.Fatalf("DESYNCED: info() after a failed %s took %v and failed: %v", + which, probeElapsed, err) + } + if version == "" { + t.Fatalf("DESYNCED: info() after a failed %s returned an empty version "+ + "(read someone else's block)", which) + } + t.Logf("stream still aligned after a failed %s: version=%q (%v)", which, version, probeElapsed) + + // and a second one, in case the damage is one command further along + if v2, _, _, err := d.info(ctx); err != nil || v2 == "" { + t.Fatalf("DESYNCED on the second command after a failed %s: version=%q err=%v", + which, v2, err) + } + t.Logf("second command also fine") +} + +// TestDevice_putErrorRecovers verifies the fix for the failed-PUT desync +// through devices.AutoCloseableDevice, the layer services/grpcimpl uses. A +// command error from PUT is reported as fatal, so ensureOpened closes and +// deletes the device before anything else is written; the firmware's +// usbint_check_connect() then resets server_state and cmdDat on the disconnect, +// and the following request reopens onto a clean device. +// +// Before the fix this same sequence bricked the pak: the error was non-fatal, +// SNI carried on, and the next command's 512 bytes were consumed as file data. +func TestDevice_putErrorRecovers(t *testing.T) { + d := openAutoCloseableDevice(t) + defer d.Close() + + ctx := context.Background() + + if v, err := d.FetchFields(ctx, 0); err != nil { + t.Fatalf("baseline FetchFields(): %v", err) + } else { + t.Logf("baseline ok: %v", v) + } + + const missingFile = "unittest-does-not-exist-xyz/nope.bin" + payload := make([]byte, 4096) + + start := time.Now() + _, err := d.PutFile(ctx, missingFile, uint32(len(payload)), bytes.NewReader(payload), nil) + if err == nil { + t.Fatalf("PutFile to a missing directory unexpectedly succeeded") + } + t.Logf("PutFile failed as expected in %v: %v", time.Since(start), err) + + // The device should have been closed and dropped on that fatal error, so + // this call reopens onto a device the disconnect has reset. + probe := time.Now() + v, err := d.FetchFields(ctx, 0) + if err != nil { + t.Fatalf("NOT RECOVERED: FetchFields() after a failed PutFile took %v: %v", + time.Since(probe), err) + } + t.Logf("recovered in %v: %v", time.Since(probe), v) + + // exercise it a bit further to be sure the stream is genuinely aligned + for i := 0; i < 3; i++ { + if _, err := d.ReadDirectory(ctx, ""); err != nil { + t.Fatalf("ReadDirectory() %d after recovery: %v", i, err) + } + } + t.Logf("device fully functional after recovery") +} diff --git a/devices/snes/drivers/fxpakpro/largexfer_test.go b/devices/snes/drivers/fxpakpro/largexfer_test.go new file mode 100644 index 0000000..0725099 --- /dev/null +++ b/devices/snes/drivers/fxpakpro/largexfer_test.go @@ -0,0 +1,99 @@ +package fxpakpro + +import ( + "bytes" + "context" + "fmt" + "os" + "strconv" + "testing" + "time" +) + +// TestDevice_repeatLargeTransfer repeatedly PUTs and GETs a single large file, +// counting how many round trips the device survives. +// +// Every wedge observed so far involved a large transfer: getFile at 188416 and +// 198201 bytes, and putFile at 131071 bytes. This narrows the random stress mix +// down to just that, to find out whether large transfers alone are the trigger +// and how many it takes -- a far tighter reproduction to hand to the firmware +// than "run 6000 random operations". +// +// SNI_TEST_XFER_SIZE sets the payload size, so the threshold can be bisected. +func TestDevice_repeatLargeTransfer(t *testing.T) { + size := uint32(128 * 1024) + if v := os.Getenv("SNI_TEST_XFER_SIZE"); v != "" { + n, err := strconv.ParseUint(v, 0, 32) + if err != nil { + t.Fatalf("SNI_TEST_XFER_SIZE=%q: %v", v, err) + } + size = uint32(n) + } + iterations := 200 + if v := os.Getenv("SNI_TEST_ITERATIONS"); v != "" { + n, err := strconv.Atoi(v) + if err != nil { + t.Fatalf("SNI_TEST_ITERATIONS=%q: %v", v, err) + } + iterations = n + } + + d := openExactDevice(t) + defer d.Close() + ctx := context.Background() + + const dir = "unittest-large-xfer" + if err := d.mkdir(ctx, dir); err != nil { + if _, lserr := d.listFiles(ctx, dir); lserr != nil { + t.Fatalf("mkdir(%s): %v (and it does not exist: %v)", dir, err, lserr) + } + } + + t.Logf("payload %d bytes (%.1f KiB), up to %d round trips", + size, float64(size)/1024.0, iterations) + + payload := filePattern(0x5a5a5a5a, size) + path := dir + "/xfer.bin" + start := time.Now() + + for i := 1; i <= iterations; i++ { + putStart := time.Now() + n, err := d.putFile(ctx, path, size, bytes.NewReader(payload), nil) + if err != nil { + t.Fatalf("WEDGED on round trip %d after %v: putFile: %v", i, time.Since(start), err) + } + if n != size { + t.Fatalf("round trip %d: putFile sent %d bytes, want %d", i, n, size) + } + putDur := time.Since(putStart) + + getStart := time.Now() + var w bytes.Buffer + w.Grow(int(size)) + received, err := d.getFile(ctx, path, &w, nil, nil) + if err != nil { + t.Fatalf("WEDGED on round trip %d after %v: getFile: %v", i, time.Since(start), err) + } + if received != size { + t.Fatalf("round trip %d: getFile received %d bytes, want %d", i, received, size) + } + if !bytes.Equal(w.Bytes(), payload) { + t.Fatalf("round trip %d: %s", i, + describeStressMismatch(w.Bytes(), payload, 0x5a5a5a5a)) + } + getDur := time.Since(getStart) + + if err := d.rm(ctx, path); err != nil { + t.Fatalf("WEDGED on round trip %d after %v: rm: %v", i, time.Since(start), err) + } + + if i%10 == 0 || i <= 5 { + t.Logf("round trip %3d ok (put %v, get %v, total elapsed %v)", + i, putDur.Round(time.Millisecond), getDur.Round(time.Millisecond), + time.Since(start).Round(time.Millisecond)) + } + } + + t.Logf("survived %d round trips of %s in %v", + iterations, fmt.Sprintf("%d bytes", size), time.Since(start)) +} diff --git a/devices/snes/drivers/fxpakpro/openport_test.go b/devices/snes/drivers/fxpakpro/openport_test.go new file mode 100644 index 0000000..6e80a4d --- /dev/null +++ b/devices/snes/drivers/fxpakpro/openport_test.go @@ -0,0 +1,45 @@ +package fxpakpro + +import ( + "bytes" + "log" + "strings" + "testing" + "time" +) + +// Test_openPort_failsFastOnBadPort checks that opening a port which is not +// merely at the wrong speed gives up after one attempt instead of walking the +// whole baud table. +// +// A wedged fxpakpro makes each open attempt block for tens of seconds on +// Windows. Retrying all 14 rates cost roughly eight minutes of a caller sitting +// on a device that was never going to open, which is what this prevents. +func Test_openPort_failsFastOnBadPort(t *testing.T) { + var buf bytes.Buffer + old := log.Default().Writer() + log.SetOutput(&buf) + defer log.SetOutput(old) + + d := &Driver{} + + start := time.Now() + f, err := d.openPort("/dev/nonexistent-fxpakpro-port-for-test", baudRates[0]) + elapsed := time.Since(start) + + if err == nil { + if f != nil { + _ = f.Close() + } + t.Fatalf("openPort() on a nonexistent port returned no error") + } + + attempts := strings.Count(buf.String(), "open(name=\"/dev/nonexistent-fxpakpro-port-for-test\", baud=") + if attempts != 1 { + t.Errorf("openPort() tried %d baud rates; want 1 (log:\n%s)", attempts, buf.String()) + } + if elapsed > 10*time.Second { + t.Errorf("openPort() took %v to fail", elapsed) + } + t.Logf("failed after %d attempt(s) in %v: %v", attempts, elapsed, err) +} diff --git a/devices/snes/drivers/fxpakpro/putfile_autoclose_test.go b/devices/snes/drivers/fxpakpro/putfile_autoclose_test.go new file mode 100644 index 0000000..8aeec0d --- /dev/null +++ b/devices/snes/drivers/fxpakpro/putfile_autoclose_test.go @@ -0,0 +1,101 @@ +package fxpakpro + +import ( + "bytes" + "context" + "os" + "strconv" + "testing" + "time" +) + +// TestDevice_snfmSequence_autoCloseable runs the SNFM command sequence through +// devices.AutoCloseableDevice, the same wrapper services/grpcimpl uses, rather +// than against the driver directly. That layer is what turns a fatal error into +// a Close() plus DeleteDevice(), so the following request reopens the serial +// port -- and the fxpakpro firmware has no path to re-establish a USB session, +// which makes the reopen unrecoverable without a power cycle. +func TestDevice_snfmSequence_autoCloseable(t *testing.T) { + verify := true + if v := os.Getenv("SNI_TEST_PUTFILE_VERIFY"); v != "" { + b, err := strconv.ParseBool(v) + if err != nil { + t.Fatalf("SNI_TEST_PUTFILE_VERIFY=%q: %v", v, err) + } + verify = b + } + old := putFileVerifyAfterWrite + putFileVerifyAfterWrite = verify + defer func() { putFileVerifyAfterWrite = old }() + + size := uint32(largeTestSize) + if s := os.Getenv("SNI_TEST_PUTFILE_SIZE"); s != "" { + v, err := strconv.ParseUint(s, 0, 32) + if err != nil { + t.Fatalf("SNI_TEST_PUTFILE_SIZE=%q: %v", s, err) + } + size = uint32(v) + } + + iterations := 1 + if v := os.Getenv("SNI_TEST_ITERATIONS"); v != "" { + n, err := strconv.Atoi(v) + if err != nil { + t.Fatalf("SNI_TEST_ITERATIONS=%q: %v", v, err) + } + iterations = n + } + + t.Logf("putFileVerifyAfterWrite=%v, size=%d, iterations=%d", verify, size, iterations) + + d := openAutoCloseableDevice(t) + defer d.Close() + + ctx := context.Background() + parents := []string{"unittest-snfm", "unittest-snfm/sub"} + dir := parents[len(parents)-1] + path := dir + "/snfm-test.bin" + + lsDir := dir + if v := os.Getenv("SNI_TEST_LS_DIR"); v != "" { + lsDir = v + } + + expected := offsetPattern(size) + + for i := 0; i < iterations; i++ { + // SNFM creates the folder and each parent first: + for _, p := range parents { + if err := d.MakeDirectory(ctx, p); err != nil { + t.Logf("[%d] mkdir(%s): %v (assuming it exists)", i, p, err) + } + } + + start := time.Now() + n, err := d.PutFile(ctx, path, size, bytes.NewReader(expected), nil) + if err != nil { + t.Fatalf("[%d] PutFile(%s, %d): %v", i, path, size, err) + } + if n != size { + t.Fatalf("[%d] PutFile() sent %d bytes, want %d", i, n, size) + } + putDur := time.Since(start) + + lsStart := time.Now() + files, err := d.ReadDirectory(ctx, lsDir) + if err != nil { + t.Fatalf("[%d] FAILURE: ReadDirectory(%s) after PutFile() failed after %v: %v", + i, lsDir, time.Since(lsStart), err) + } + t.Logf("[%d] PutFile %v; ReadDirectory(%s) -> %d entries in %v", + i, putDur, lsDir, len(files), time.Since(lsStart)) + + if _, err := d.FetchFields(ctx, 0); err != nil { + t.Fatalf("[%d] FAILURE: FetchFields() after ReadDirectory(): %v", i, err) + } + + if err := d.RemoveFile(ctx, path); err != nil { + t.Fatalf("[%d] RemoveFile(%s): %v", i, path, err) + } + } +} diff --git a/devices/snes/drivers/fxpakpro/putfile_drain_test.go b/devices/snes/drivers/fxpakpro/putfile_drain_test.go new file mode 100644 index 0000000..bf7e109 --- /dev/null +++ b/devices/snes/drivers/fxpakpro/putfile_drain_test.go @@ -0,0 +1,117 @@ +package fxpakpro + +import ( + "bytes" + "context" + "os" + "testing" + "time" +) + +// TestDevice_putFile_closeWithoutDrain tests whether closing the serial port +// straight after a PUT can wedge the device. +// +// putFile returns as soon as the last write() is buffered by the OS, and +// Device.Close() calls f.Close() without ever calling f.Drain(). If the close +// discards output the CDC driver had not yet transmitted, the firmware is left +// holding a partial 512-byte block in recv_buffer. usbint_check_connect() +// resets server_state, data_ready and cmdDat on disconnect but never resets +// recv_buffer_offset, so every command after the next connect is misframed by +// that leftover count and never assembles into a valid USBA block: the device +// enumerates, accepts bytes, and never answers. +// +// SNI_TEST_CLOSE_MODE selects what happens between the last data write and the +// close: +// +// none - close immediately (the current behavior) +// drain - call Drain() first +// info - round-trip an INFO first (fix #2) +func TestDevice_putFile_closeWithoutDrain(t *testing.T) { + mode := os.Getenv("SNI_TEST_CLOSE_MODE") + if mode == "" { + mode = "none" + } + t.Logf("close mode: %q", mode) + + const size = uint32(largeTestSize) + const path = "unittest-snfm/sub/drain-test.bin" + + putFileVerifyAfterWrite = (mode == "info") + defer func() { putFileVerifyAfterWrite = true }() + + // phase 1: upload, then close the port according to the mode. + { + d := openExactDevice(t) + ctx := context.Background() + + if err := d.mkdir(ctx, "unittest-snfm"); err != nil { + t.Logf("mkdir: %v (assuming exists)", err) + } + if err := d.mkdir(ctx, "unittest-snfm/sub"); err != nil { + t.Logf("mkdir sub: %v (assuming exists)", err) + } + + start := time.Now() + n, err := d.putFile(ctx, path, size, bytes.NewReader(offsetPattern(size)), nil) + if err != nil { + d.Close() + t.Fatalf("putFile: %v", err) + } + t.Logf("putFile: %d bytes in %v", n, time.Since(start)) + + // SNI_TEST_GETFILE=1 adds a 4 MiB read-back before the close. The one + // wedge observed in this session followed a test whose final device + // operation was exactly this: a getFile, then Close(), then an idle + // period, then a reopen that could not complete INFO. + if os.Getenv("SNI_TEST_GETFILE") == "1" { + var w bytes.Buffer + w.Grow(int(size)) + gs := time.Now() + received, gerr := d.getFile(ctx, path, &w, nil, nil) + if gerr != nil { + d.Close() + t.Fatalf("getFile: %v", gerr) + } + t.Logf("getFile: %d bytes in %v", received, time.Since(gs)) + } + + if mode == "drain" { + ds := time.Now() + if err := d.f.Drain(); err != nil { + t.Logf("Drain(): %v", err) + } + t.Logf("Drain() took %v", time.Since(ds)) + } + + // close immediately, exactly as SNI does when a device is released: + if err := d.Close(); err != nil { + t.Logf("Close(): %v", err) + } + t.Logf("closed port") + } + + // phase 2: reopen and see whether the device still answers a command. + // driver.openDevice runs Init(), which issues INFO -- the same command that + // failed in the wedge we observed. + uri, err := firstDeviceURI() + if err != nil { + t.Fatalf("detect: %v", err) + } + + start := time.Now() + dev, err := driver.openDevice(uri) + if err != nil { + t.Fatalf("REPRODUCED: reopen after close failed in %v: %v", time.Since(start), err) + } + d2 := dev.(*Device) + defer d2.Close() + t.Logf("reopened and INFO succeeded in %v", time.Since(start)) + + ctx := context.Background() + if _, err := d2.listFiles(ctx, "unittest-snfm/sub"); err != nil { + t.Fatalf("REPRODUCED: ls after reopen failed: %v", err) + } + if err := d2.rm(ctx, path); err != nil { + t.Logf("cleanup rm: %v", err) + } +} diff --git a/devices/snes/drivers/fxpakpro/putfile_snfm_test.go b/devices/snes/drivers/fxpakpro/putfile_snfm_test.go new file mode 100644 index 0000000..8ccb520 --- /dev/null +++ b/devices/snes/drivers/fxpakpro/putfile_snfm_test.go @@ -0,0 +1,139 @@ +package fxpakpro + +import ( + "bytes" + "context" + "os" + "strconv" + "testing" + "time" +) + +// TestDevice_putFile_thenLS reproduces the command sequence the SNFM file +// transfer tool issues: MKDIR for the target folder and each of its parents, +// then PutFile, then LS of the folder it just wrote into. +// +// LS is the interesting part. usbint_handler_cmd sets server_state to +// USBINT_SERVER_STATE_HANDLE_DAT for LS (as it does for GET/VGET), and +// usbint_server_busy() counts HANDLE_DAT as busy -- unlike PUT's HANDLE_LOCK, +// which it deliberately excludes. While the server is busy, CDC_BulkOut() +// returns without calling USB_ReadEP(), so the packet the USB hardware already +// ACKed is discarded and its endpoint buffer is never released with +// CMD_CLR_BUF. The endpoint interrupt was already cleared by the ISR before the +// callback ran, so nothing brings that buffer back. +// +// SNI_TEST_PUTFILE_VERIFY=0 disables the post-PUT INFO round trip in putFile() +// so the two behaviors can be compared. +func TestDevice_putFile_thenLS(t *testing.T) { + verify := true + if v := os.Getenv("SNI_TEST_PUTFILE_VERIFY"); v != "" { + b, err := strconv.ParseBool(v) + if err != nil { + t.Fatalf("SNI_TEST_PUTFILE_VERIFY=%q: %v", v, err) + } + verify = b + } + old := putFileVerifyAfterWrite + putFileVerifyAfterWrite = verify + defer func() { putFileVerifyAfterWrite = old }() + + size := uint32(largeTestSize) + if s := os.Getenv("SNI_TEST_PUTFILE_SIZE"); s != "" { + v, err := strconv.ParseUint(s, 0, 32) + if err != nil { + t.Fatalf("SNI_TEST_PUTFILE_SIZE=%q: %v", s, err) + } + size = uint32(v) + } + + t.Logf("putFileVerifyAfterWrite=%v, size=%d bytes (%.1f MiB)", + verify, size, float64(size)/1024.0/1024.0) + + d := openExactDevice(t) + t.Cleanup(func() { d.Close() }) + ctx := context.Background() + + // SNFM creates the target folder and each parent in turn: + parents := []string{"unittest-snfm", "unittest-snfm/sub"} + dir := parents[len(parents)-1] + for _, p := range parents { + if err := d.mkdir(ctx, p); err != nil { + // error code 1 just means it already exists: + if _, lserr := d.listFiles(ctx, p); lserr != nil { + t.Fatalf("mkdir(%s): %v (and it does not already exist: %v)", p, err, lserr) + } + t.Logf("mkdir(%s): already exists", p) + } + } + + // LS target: default the folder we uploaded into, as SNFM does. A folder + // with many entries makes the LS data phase -- and therefore the window in + // which usbint_server_busy() reports busy -- much longer. + lsDir := dir + if v := os.Getenv("SNI_TEST_LS_DIR"); v != "" { + lsDir = v + } + + iterations := 1 + if v := os.Getenv("SNI_TEST_ITERATIONS"); v != "" { + n, err := strconv.Atoi(v) + if err != nil { + t.Fatalf("SNI_TEST_ITERATIONS=%q: %v", v, err) + } + iterations = n + } + t.Logf("ls target %q, %d iteration(s)", lsDir, iterations) + + path := dir + "/snfm-test.bin" + t.Cleanup(func() { + if err := d.rm(context.Background(), path); err != nil { + t.Logf("cleanup: rm(%s): %v", path, err) + } + }) + + expected := offsetPattern(size) + + for i := 0; i < iterations; i++ { + start := time.Now() + n, err := d.putFile(ctx, path, size, bytes.NewReader(expected), nil) + if err != nil { + t.Fatalf("[%d] putFile(%s, %d): %v", i, path, size, err) + } + if n != size { + t.Fatalf("[%d] putFile() sent %d bytes, want %d", i, n, size) + } + putDur := time.Since(start) + + // LS immediately, exactly as SNFM does. This is the command reported to + // fail, so give it its own error handling. + lsStart := time.Now() + files, err := d.listFiles(ctx, lsDir) + if err != nil { + t.Fatalf("[%d] FAILURE: ls(%s) immediately after putFile() failed after %v: %v", + i, lsDir, time.Since(lsStart), err) + } + t.Logf("[%d] putFile %v; ls(%s) -> %d entries in %v", + i, putDur, lsDir, len(files), time.Since(lsStart)) + + if lsDir == dir { + var found bool + for _, f := range files { + if f.Name == "snfm-test.bin" { + found = true + } + } + if !found { + t.Fatalf("[%d] ls(%s) did not list the file just uploaded", i, dir) + } + } + + // a second command afterwards catches a device left in a bad state: + if _, _, _, err := d.info(ctx); err != nil { + t.Fatalf("[%d] FAILURE: info() after ls() failed: %v", i, err) + } + + if err := d.rm(ctx, path); err != nil { + t.Fatalf("[%d] rm(%s) between iterations: %v", i, path, err) + } + } +} diff --git a/devices/snes/drivers/fxpakpro/putfile_test.go b/devices/snes/drivers/fxpakpro/putfile_test.go index bf85f0f..28606f1 100644 --- a/devices/snes/drivers/fxpakpro/putfile_test.go +++ b/devices/snes/drivers/fxpakpro/putfile_test.go @@ -1,9 +1,16 @@ package fxpakpro import ( + "bytes" "context" + "encoding/binary" + "fmt" "io" + "os" + "sort" + "strconv" "testing" + "time" ) type patternReader struct { @@ -80,3 +87,423 @@ func TestDevice_putFile(t *testing.T) { }) } } + +// The tests below investigate an end-user report: uploading a large (4 MiB) +// file over the gRPC PutFile API fails under normal use but succeeds when +// SNI_DEBUG=1 is set. The working theory was that debug logging slows the host +// down enough to stop it from outrunning the device. + +const largeTestDir = "unittest-large" +const largeTestSize = 4 * 1024 * 1024 + +// offsetPattern fills a buffer with a deterministic pattern where each 4-byte +// little-endian word holds its own byte offset within the file. If the stream +// desyncs, the value read back at a given offset reveals exactly how far the +// data shifted, which separates a dropped or duplicated run of bytes from +// bit-level corruption. +func offsetPattern(size uint32) []byte { + d := make([]byte, size) + for i := uint32(0); i+4 <= size; i += 4 { + binary.LittleEndian.PutUint32(d[i:], i) + } + return d +} + +// describeMismatch locates the first differing byte and reports the words on +// either side of it. +func describeMismatch(actual, expected []byte) string { + for i := range expected { + if i >= len(actual) { + return fmt.Sprintf("contents truncated at offset %d ($%06x)", i, i) + } + if actual[i] == expected[i] { + continue + } + lo := i &^ 3 + got := binary.LittleEndian.Uint32(actual[lo:]) + want := binary.LittleEndian.Uint32(expected[lo:]) + return fmt.Sprintf( + "contents differ starting at offset %d ($%06x): got word $%08x, want $%08x (shifted by %d bytes)", + i, i, got, want, int64(got)-int64(want), + ) + } + return "contents match" +} + +// openLargeTestDir opens the device and ensures the scratch folder exists off +// the root of the SD card, cleaning up its contents when the test ends. The +// device is opened once and reused for every iteration: the fxpakpro firmware +// cannot tear down and re-establish a USB session, so reconnecting per +// iteration would wedge it before we reached the condition we are hunting for. +func openLargeTestDir(t *testing.T) (*Device, context.Context) { + d := openExactDevice(t) + // runs last, after the cleanup registered below: + t.Cleanup(func() { d.Close() }) + + ctx := context.Background() + + // mkdir fails with error code 1 if the folder already exists, so fall back + // to listing it to tell "already there" apart from a real failure: + if err := d.mkdir(ctx, largeTestDir); err != nil { + if _, lserr := d.listFiles(ctx, largeTestDir); lserr != nil { + t.Fatalf("mkdir(%s): %v (and it does not already exist: %v)", largeTestDir, err, lserr) + } + } + + t.Cleanup(func() { + // best-effort; the device may be wedged by the time we get here: + files, err := d.listFiles(context.Background(), largeTestDir) + if err != nil { + t.Logf("cleanup: ls(%s): %v", largeTestDir, err) + return + } + for _, f := range files { + if f.Name == "." || f.Name == ".." { + continue + } + p := largeTestDir + "/" + f.Name + if err := d.rm(context.Background(), p); err != nil { + t.Logf("cleanup: rm(%s): %v", p, err) + } + } + if err := d.rm(context.Background(), largeTestDir); err != nil { + t.Logf("cleanup: rm(%s): %v", largeTestDir, err) + } + }) + + return d, ctx +} + +// verifyFile reads path back off the device and compares it to expected. +func verifyFile(t *testing.T, d *Device, ctx context.Context, path string, expected []byte) { + t.Helper() + + // the device must still be responsive on the very next command: + if _, _, _, err := d.info(ctx); err != nil { + t.Fatalf("info() after putFile(): %v", err) + } + + var w bytes.Buffer + w.Grow(len(expected)) + received, err := d.getFile(ctx, path, &w, nil, nil) + if err != nil { + t.Fatalf("getFile(%s): %v", path, err) + } + if received != uint32(len(expected)) { + t.Fatalf("getFile() received %d bytes, want %d", received, len(expected)) + } + if actual := w.Bytes(); !bytes.Equal(actual, expected) { + t.Fatalf("%s", describeMismatch(actual, expected)) + } +} + +// TestDevice_putFile_large uploads a 4 MiB file several times over a single +// connection, verifying each upload byte-for-byte, to look for an intermittent +// transfer failure. +func TestDevice_putFile_large(t *testing.T) { + const iterations = 5 + + d, ctx := openLargeTestDir(t) + expected := offsetPattern(largeTestSize) + + for i := 0; i < iterations; i++ { + path := fmt.Sprintf("%s/large%d.bin", largeTestDir, i) + + // match what services/grpcimpl passes down from a gRPC PutFile: the + // whole payload in memory as a bytes.Reader and no progress callback. + start := time.Now() + n, err := d.putFile(ctx, path, largeTestSize, bytes.NewReader(expected), nil) + elapsed := time.Since(start) + if err != nil { + t.Fatalf("[%d] putFile(%s, %d): %v", i, path, largeTestSize, err) + } + if n != largeTestSize { + t.Fatalf("[%d] putFile() sent %d bytes, want %d", i, n, largeTestSize) + } + t.Logf("[%d] putFile: %d bytes in %v (%.1f KiB/s)", i, n, elapsed, float64(n)/1024.0/elapsed.Seconds()) + + verifyFile(t, d, ctx, path, expected) + } +} + +// putFileWriteSize performs the same PUT as Device.putFile but writes the +// payload in writeSize-byte calls instead of the 512-byte calls that +// sendSerialProgress uses. The bytes on the wire are identical; only the gap +// between successive write() syscalls changes. A large writeSize lets the host +// driver stream USB packets back-to-back with no user-space gap, which is the +// opposite of what SNI_DEBUG=1 does when it interposes a hex dump between every +// 512-byte chunk. +func putFileWriteSize(t *testing.T, d *Device, ctx context.Context, path string, payload []byte, writeSize int) { + t.Helper() + + sb := make([]byte, 512) + sb[0], sb[1], sb[2], sb[3] = byte('U'), byte('S'), byte('B'), byte('A') + sb[4] = byte(OpPUT) + sb[5] = byte(SpaceFILE) + sb[6] = byte(FlagNONE) + copy(sb[256:512], []byte(path)) + binary.BigEndian.PutUint32(sb[252:], uint32(len(payload))) + + d.lock.Lock() + defer d.lock.Unlock() + + if err := sendSerialChunked(ctx, d.f, 512, sb); err != nil { + t.Fatalf("send PUT command: %v", err) + } + if err := recvSerial(ctx, d.f, sb, 512); err != nil { + t.Fatalf("recv PUT response: %v", err) + } + if sb[0] != 'U' || sb[1] != 'S' || sb[2] != 'B' || sb[3] != 'A' { + t.Fatalf("PUT response missing USBA header: %x", sb[:8]) + } + if ec := sb[5]; ec != 0 { + t.Fatalf("PUT response error: %v", fxpakproError(ec)) + } + + for off := 0; off < len(payload); off += writeSize { + end := off + writeSize + if end > len(payload) { + end = len(payload) + } + p := payload[off:end] + for len(p) > 0 { + n, err := d.f.Write(p) + if err != nil { + t.Fatalf("write at offset %d: %v", off, err) + } + p = p[n:] + } + } +} + +// TestDevice_putFile_writeSizes uploads the same 4 MiB payload at host write +// sizes from the 512 bytes SNI uses today up to 64 KiB. If the reported failure +// were caused by the host outrunning the device, the larger write sizes are +// where it should first appear, and throughput should rise as the gaps between +// writes shrink. Identical throughput across all sizes instead means the +// transfer is device-bound: USB NAK flow control is pacing the host, and +// host-side pacing changes nothing on the wire. +func TestDevice_putFile_writeSizes(t *testing.T) { + d, ctx := openLargeTestDir(t) + expected := offsetPattern(largeTestSize) + + for _, writeSize := range []int{512, 4096, 16384, 65536} { + t.Run(fmt.Sprintf("write%d", writeSize), func(t *testing.T) { + path := fmt.Sprintf("%s/ws%d.bin", largeTestDir, writeSize) + + start := time.Now() + putFileWriteSize(t, d, ctx, path, expected, writeSize) + elapsed := time.Since(start) + t.Logf("putFile(writeSize=%d): %d bytes in %v (%.1f KiB/s)", + writeSize, largeTestSize, elapsed, float64(largeTestSize)/1024.0/elapsed.Seconds()) + + verifyFile(t, d, ctx, path, expected) + }) + } +} + +// TestDevice_putFile_overwrite uploads a 4 MiB file to the same path several +// times. Every upload after the first forces the firmware to truncate the +// previous 4 MiB file inside f_open(FA_WRITE|FA_CREATE_ALWAYS) before it can +// reply, which is the slowest device-side step in a PUT and the one most likely +// to trip the host's response timeout. SNI reads that reply with readExact, +// which gives up after 9 consecutive one-second zero-byte reads, or at the +// context deadline if the caller set one. +func TestDevice_putFile_overwrite(t *testing.T) { + const iterations = 4 + const path = largeTestDir + "/overwrite.bin" + + d, ctx := openLargeTestDir(t) + expected := offsetPattern(largeTestSize) + + for i := 0; i < iterations; i++ { + sb := make([]byte, 512) + sb[0], sb[1], sb[2], sb[3] = byte('U'), byte('S'), byte('B'), byte('A') + sb[4] = byte(OpPUT) + sb[5] = byte(SpaceFILE) + sb[6] = byte(FlagNONE) + copy(sb[256:512], []byte(path)) + binary.BigEndian.PutUint32(sb[252:], largeTestSize) + + d.lock.Lock() + if err := sendSerialChunked(ctx, d.f, 512, sb); err != nil { + d.lock.Unlock() + t.Fatalf("[%d] send PUT command: %v", i, err) + } + + // time the command->response round trip on its own; this is the f_open: + start := time.Now() + err := recvSerial(ctx, d.f, sb, 512) + latency := time.Since(start) + if err != nil { + d.lock.Unlock() + t.Fatalf("[%d] recv PUT response after %v: %v", i, latency, err) + } + if ec := sb[5]; ec != 0 { + d.lock.Unlock() + t.Fatalf("[%d] PUT response error: %v", i, fxpakproError(ec)) + } + + sent, err := sendSerialProgress(ctx, d.f, 512, largeTestSize, bytes.NewReader(expected), nil) + d.lock.Unlock() + if err != nil { + t.Fatalf("[%d] sendSerialProgress: %v", i, err) + } + if sent != largeTestSize { + t.Fatalf("[%d] sent %d bytes, want %d", i, sent, largeTestSize) + } + t.Logf("[%d] f_open latency: %v", i, latency) + + verifyFile(t, d, ctx, path, expected) + } +} + +// chunkTiming records how long one 512-byte write to the serial port took. +type chunkTiming struct { + offset uint32 + dur time.Duration +} + +// putFileInstrumented performs a PUT and records the wall time of every +// 512-byte write to the serial port, plus the command->response latency (the +// device-side f_open). Because the transfer is device-bound -- the host blocks +// in write() while the fxpakpro NAKs -- a long stall inside the firmware's USB +// interrupt handler shows up directly as a slow write() here. FatFs does its +// cluster allocation inside that ISR, so a nearly-full or fragmented card makes +// create_chain scan the FAT, and that scan is what we expect to see. +func putFileInstrumented(t *testing.T, d *Device, ctx context.Context, path string, payload []byte) { + t.Helper() + + size := uint32(len(payload)) + + sb := make([]byte, 512) + sb[0], sb[1], sb[2], sb[3] = byte('U'), byte('S'), byte('B'), byte('A') + sb[4] = byte(OpPUT) + sb[5] = byte(SpaceFILE) + sb[6] = byte(FlagNONE) + copy(sb[256:512], []byte(path)) + binary.BigEndian.PutUint32(sb[252:], size) + + d.lock.Lock() + defer d.lock.Unlock() + + if err := sendSerialChunked(ctx, d.f, 512, sb); err != nil { + t.Fatalf("send PUT command: %v", err) + } + + openStart := time.Now() + if err := recvSerial(ctx, d.f, sb, 512); err != nil { + t.Fatalf("recv PUT response after %v: %v", time.Since(openStart), err) + } + openLatency := time.Since(openStart) + if ec := sb[5]; ec != 0 { + t.Fatalf("PUT response error: %v", fxpakproError(ec)) + } + + timings := make([]chunkTiming, 0, size/512) + start := time.Now() + for off := uint32(0); off < size; off += 512 { + end := off + 512 + if end > size { + end = size + } + p := payload[off:end] + + wStart := time.Now() + for len(p) > 0 { + n, err := d.f.Write(p) + if err != nil { + t.Fatalf("write at offset %d (%d chunks in, %v elapsed): %v", + off, off/512, time.Since(start), err) + } + p = p[n:] + } + timings = append(timings, chunkTiming{offset: off, dur: time.Since(wStart)}) + } + total := time.Since(start) + + // summarize: sort a copy by duration to find the worst stalls. + sorted := make([]chunkTiming, len(timings)) + copy(sorted, timings) + sort.Slice(sorted, func(i, j int) bool { return sorted[i].dur > sorted[j].dur }) + + pct := func(p float64) time.Duration { + if len(sorted) == 0 { + return 0 + } + i := int(float64(len(sorted)-1) * (1.0 - p/100.0)) + return sorted[i].dur + } + + t.Logf("f_open latency: %v", openLatency) + t.Logf("data phase: %d chunks in %v (%.1f KiB/s)", + len(timings), total, float64(size)/1024.0/total.Seconds()) + t.Logf("per-chunk write latency: p50=%v p99=%v p99.9=%v max=%v", + pct(50), pct(99), pct(99.9), sorted[0].dur) + + t.Logf("10 slowest chunks:") + for i := 0; i < 10 && i < len(sorted); i++ { + t.Logf(" offset %8d ($%06x, chunk %5d): %v", + sorted[i].offset, sorted[i].offset, sorted[i].offset/512, sorted[i].dur) + } + + // count how much total time went into stalls above a threshold: + for _, thresh := range []time.Duration{10 * time.Millisecond, 50 * time.Millisecond, 200 * time.Millisecond} { + var count int + var sum time.Duration + for _, ct := range timings { + if ct.dur >= thresh { + count++ + sum += ct.dur + } + } + t.Logf("chunks >= %v: %d (%v total)", thresh, count, sum) + } +} + +// TestDevice_putFile_intoDir uploads a 4 MiB file into an existing folder on +// the SD card, chosen with SNI_TEST_PUTFILE_DIR, and reports where the device +// stalled. Point it at a folder holding many large files (an MSU-1 track set, +// say) to test the theory that FAT work inside the firmware's USB interrupt +// handler is what loses packets. +func TestDevice_putFile_intoDir(t *testing.T) { + dir := os.Getenv("SNI_TEST_PUTFILE_DIR") + if dir == "" { + t.Skip("set SNI_TEST_PUTFILE_DIR to the folder to upload into") + } + + // SNI_TEST_PUTFILE_SIZE overrides the payload size in bytes. Sizing the + // upload close to the volume's remaining free space is what forces the + // firmware's allocator to scan for each hole in a fragmented FAT. + size := uint32(largeTestSize) + if s := os.Getenv("SNI_TEST_PUTFILE_SIZE"); s != "" { + v, err := strconv.ParseUint(s, 0, 32) + if err != nil { + t.Fatalf("SNI_TEST_PUTFILE_SIZE=%q: %v", s, err) + } + size = uint32(v) + } + + d := openExactDevice(t) + // registered first so it runs last, after the rm cleanup below: + t.Cleanup(func() { d.Close() }) + ctx := context.Background() + + files, err := d.listFiles(ctx, dir) + if err != nil { + t.Fatalf("ls(%s): %v", dir, err) + } + t.Logf("target folder %q holds %d directory entries", dir, len(files)) + + path := dir + "/sni-putfile-test.bin" + t.Cleanup(func() { + if err := d.rm(context.Background(), path); err != nil { + t.Logf("cleanup: rm(%s): %v", path, err) + } + }) + + t.Logf("uploading %d bytes (%.1f MiB)", size, float64(size)/1024.0/1024.0) + expected := offsetPattern(size) + putFileInstrumented(t, d, ctx, path, expected) + verifyFile(t, d, ctx, path, expected) +} diff --git a/devices/snes/drivers/fxpakpro/sendserial_test.go b/devices/snes/drivers/fxpakpro/sendserial_test.go new file mode 100644 index 0000000..7cdd2a5 --- /dev/null +++ b/devices/snes/drivers/fxpakpro/sendserial_test.go @@ -0,0 +1,176 @@ +package fxpakpro + +import ( + "bytes" + "context" + "errors" + "sync" + "testing" + "time" + + "go.bug.st/serial" +) + +// failingPort is a serial.Port that fails the failOnCall'th Write and succeeds +// on every other one. A transient failure is what actually exposes the bug: a +// permanently broken port leaves err set on the final loop iteration, so it +// gets returned by accident. When a later write succeeds, the old code's +// readExactGeneric reassigned err and the failure vanished. +type failingPort struct { + stubPort + calls int + written int + failOnCall int + err error +} + +func (p *failingPort) Write(b []byte) (int, error) { + p.calls++ + if p.calls == p.failOnCall { + return 0, p.err + } + p.written += len(b) + return len(b), nil +} + +// stubPort supplies the parts of serial.Port the tests do not care about. +type stubPort struct{} + +func (stubPort) Read(b []byte) (int, error) { return 0, nil } +func (stubPort) SetMode(*serial.Mode) error { return nil } +func (stubPort) Drain() error { return nil } +func (stubPort) ResetInputBuffer() error { return nil } +func (stubPort) ResetOutputBuffer() error { return nil } +func (stubPort) SetDTR(bool) error { return nil } +func (stubPort) SetRTS(bool) error { return nil } +func (stubPort) GetModemStatusBits() (*serial.ModemStatusBits, error) { + return &serial.ModemStatusBits{}, nil +} +func (stubPort) SetReadTimeout(time.Duration) error { return nil } +func (stubPort) Close() error { return nil } +func (stubPort) Break(time.Duration) error { return nil } + +// Test_sendSerialProgress_writeError checks that a write failure partway +// through a transfer is reported rather than swallowed. The loop previously +// discarded writeExact's error and kept going, so the next iteration's +// readExactGeneric reassigned err and the caller saw a success for a transfer +// that had actually stopped writing. +func Test_sendSerialProgress_writeError(t *testing.T) { + const size = 8192 + // fail the 5th chunk, so 4 chunks (2048 bytes) go out first and the + // remaining chunks would have succeeded: + const failOnCall = 5 + const wantSent = (failOnCall - 1) * 512 + + wantErr := errors.New("simulated write failure") + p := &failingPort{failOnCall: failOnCall, err: wantErr} + + sent, err := sendSerialProgress(context.Background(), p, 512, size, bytes.NewReader(make([]byte, size)), nil) + if err == nil { + t.Fatalf("sendSerialProgress() returned nil error after a failed write; want %v (sent=%d of %d)", + wantErr, sent, size) + } + if !errors.Is(err, wantErr) { + t.Errorf("sendSerialProgress() error = %v; want it to wrap %v", err, wantErr) + } + if sent != wantSent { + t.Errorf("sendSerialProgress() sent = %d; want %d (should stop at the failed write)", sent, wantSent) + } +} + +// Test_sendSerialProgress_success covers the ordinary path, including a size +// that is not a multiple of the chunk size so the remainder branch runs. +func Test_sendSerialProgress_success(t *testing.T) { + for _, size := range []uint32{512, 8192, 513, 1023} { + p := &failingPort{failOnCall: -1} + sent, err := sendSerialProgress(context.Background(), p, 512, size, bytes.NewReader(make([]byte, size)), nil) + if err != nil { + t.Errorf("size %d: sendSerialProgress() error = %v", size, err) + continue + } + // the protocol pads the final short chunk out to a full 512 bytes: + want := ((size + 511) / 512) * 512 + if sent != want { + t.Errorf("size %d: sent = %d; want %d", size, sent, want) + } + } +} + +// blockingPort models a device that has stopped draining its USB endpoint: the +// write never completes until the port is closed. +type blockingPort struct { + stubPort + release chan struct{} + started chan struct{} + once sync.Once +} + +func (p *blockingPort) Write(b []byte) (int, error) { + p.once.Do(func() { close(p.started) }) + <-p.release + return 0, errors.New("port closed") +} + +// Test_writeWithTimeout_deviceNotDraining checks that a write to a device that +// never accepts data returns instead of hanging forever. go.bug.st/serial sets +// WriteTotalTimeoutConstant to 0 on Windows, which Win32 treats as "wait +// forever", and the Port interface offers no SetWriteTimeout, so the bound has +// to come from us. Without it the caller hangs while holding d.lock, blocking +// every other request for that device. +func Test_writeWithTimeout_deviceNotDraining(t *testing.T) { + old := writeTimeout + writeTimeout = 150 * time.Millisecond + defer func() { writeTimeout = old }() + + p := &blockingPort{release: make(chan struct{}), started: make(chan struct{})} + // release the abandoned goroutine at the end, as closing the port would: + defer close(p.release) + + start := time.Now() + n, err := writeExact(context.Background(), p, 512, make([]byte, 512)) + elapsed := time.Since(start) + + if err == nil { + t.Fatalf("writeExact() returned nil error after %v; want a timeout", elapsed) + } + if n != 0 { + t.Errorf("writeExact() = %d bytes; want 0 when the write never completed", n) + } + if elapsed > 5*time.Second { + t.Errorf("writeExact() took %v; it should give up near the %v budget", elapsed, writeTimeout) + } + + select { + case <-p.started: + default: + t.Errorf("Write() was never called") + } +} + +// Test_writeWithTimeout_contextCancelled checks that a caller's context bounds +// the write too, so a cancelled request does not sit on the device lock. +func Test_writeWithTimeout_contextCancelled(t *testing.T) { + old := writeTimeout + writeTimeout = time.Minute // ensure the context is what ends the wait + defer func() { writeTimeout = old }() + + p := &blockingPort{release: make(chan struct{}), started: make(chan struct{})} + defer close(p.release) + + ctx, cancel := context.WithTimeout(context.Background(), 150*time.Millisecond) + defer cancel() + + start := time.Now() + _, err := writeExact(ctx, p, 512, make([]byte, 512)) + elapsed := time.Since(start) + + if err == nil { + t.Fatalf("writeExact() returned nil error after %v; want context deadline exceeded", elapsed) + } + if !errors.Is(err, context.DeadlineExceeded) { + t.Errorf("writeExact() error = %v; want it to wrap context.DeadlineExceeded", err) + } + if elapsed > 5*time.Second { + t.Errorf("writeExact() took %v; it should stop at the context deadline", elapsed) + } +} diff --git a/devices/snes/drivers/fxpakpro/stress_test.go b/devices/snes/drivers/fxpakpro/stress_test.go new file mode 100644 index 0000000..7bf3dc0 --- /dev/null +++ b/devices/snes/drivers/fxpakpro/stress_test.go @@ -0,0 +1,339 @@ +package fxpakpro + +import ( + "bytes" + "context" + "encoding/binary" + "encoding/hex" + "fmt" + "math/rand" + "os" + "strconv" + "testing" + "time" + + "sni/devices" + "sni/protos/sni" +) + +// filePattern builds deterministic content that encodes both the byte offset +// and a per-file tag. A stream desync shows up as a shifted offset; data from +// the wrong file shows up as a wrong tag. Both are recoverable from a single +// mismatched word. +func filePattern(tag, size uint32) []byte { + d := make([]byte, size) + i := uint32(0) + for ; i+4 <= size; i += 4 { + binary.LittleEndian.PutUint32(d[i:], i^tag) + } + for ; i < size; i++ { + d[i] = byte(i ^ tag) + } + return d +} + +func describeStressMismatch(actual, expected []byte, tag uint32) string { + for i := range expected { + if i >= len(actual) { + return fmt.Sprintf("truncated at offset %d ($%06x)", i, i) + } + if actual[i] == expected[i] { + continue + } + lo := i &^ 3 + var got, want uint32 + if lo+4 <= len(actual) { + got = binary.LittleEndian.Uint32(actual[lo:]) + } + if lo+4 <= len(expected) { + want = binary.LittleEndian.Uint32(expected[lo:]) + } + return fmt.Sprintf( + "differs at offset %d ($%06x): got word $%08x, want $%08x; "+ + "decoded offset %d (shift %d), decoded tag $%08x (want $%08x)", + i, i, got, want, got^tag, int64(got^tag)-int64(lo), got^uint32(lo), tag) + } + return "contents match" +} + +// awkwardSizes clusters around the protocol's 64- and 512-byte block +// boundaries, where the padding and remainder paths in sendSerialProgress and +// getFile behave differently. +var awkwardSizes = []uint32{ + 1, 2, 3, 63, 64, 65, 127, 128, 129, 255, 256, 257, + 511, 512, 513, 767, 1023, 1024, 1025, 1535, 2047, 2048, 2049, + 4095, 4096, 4097, 8191, 8193, 12289, 65535, 65537, 100003, 131071, +} + +type stressFile struct { + path string + tag uint32 + size uint32 +} + +// TestDevice_stressMixed interleaves PUT, GET, LS, MKDIR, RM and INFO in a +// seeded random order, using file sizes that are deliberately not multiples of +// the 512-byte block size. Every operation is logged so a failure can be +// replayed with SNI_TEST_SEED. +func TestDevice_stressMixed(t *testing.T) { + seed := time.Now().UnixNano() + if v := os.Getenv("SNI_TEST_SEED"); v != "" { + s, err := strconv.ParseInt(v, 10, 64) + if err != nil { + t.Fatalf("SNI_TEST_SEED=%q: %v", v, err) + } + seed = s + } + ops := 300 + if v := os.Getenv("SNI_TEST_OPS"); v != "" { + n, err := strconv.Atoi(v) + if err != nil { + t.Fatalf("SNI_TEST_OPS=%q: %v", v, err) + } + ops = n + } + // the card is nearly full, so keep live data well inside free space: + maxLive := uint32(3 * 1024 * 1024) + if v := os.Getenv("SNI_TEST_MAX_LIVE"); v != "" { + n, err := strconv.ParseUint(v, 0, 32) + if err != nil { + t.Fatalf("SNI_TEST_MAX_LIVE=%q: %v", v, err) + } + maxLive = uint32(n) + } + + t.Logf("seed=%d ops=%d maxLive=%d (replay with SNI_TEST_SEED=%d)", seed, ops, maxLive, seed) + rng := rand.New(rand.NewSource(seed)) + + d := openExactDevice(t) + defer d.Close() + ctx := context.Background() + + const root = "unittest-stress" + dirs := []string{root, root + "/a", root + "/b", root + "/a/c"} + for _, dir := range dirs { + if err := d.mkdir(ctx, dir); err != nil { + if _, lserr := d.listFiles(ctx, dir); lserr != nil { + t.Fatalf("setup mkdir(%s): %v (and does not exist: %v)", dir, err, lserr) + } + } + } + + live := make([]stressFile, 0, 64) + var liveBytes uint32 + seq := 0 + + // history keeps the recent operation log so a failure can report what led + // up to it rather than just the failing call. + history := make([]string, 0, 32) + record := func(format string, args ...interface{}) { + s := fmt.Sprintf(format, args...) + history = append(history, s) + if len(history) > 24 { + history = history[1:] + } + } + // probeRecovery distinguishes the possible failure modes after a command + // gets no answer within readExact's 9x1s budget: + // - a late response still arriving => the device was merely slow + // - nothing, then INFO works => the command itself was lost + // - nothing, and INFO keeps failing => the device is wedged + probeRecovery := func() { + t.Errorf("--- recovery probe ---") + + // is a late response still on its way? + buf := make([]byte, 512) + dctx, dcancel := context.WithTimeout(context.Background(), 30*time.Second) + start := time.Now() + n, derr := readExact(dctx, d.f, 512, buf) + dcancel() + if n > 0 { + t.Errorf(" LATE DATA: %d bytes arrived %v after the timeout: %v", + n, time.Since(start), derr) + t.Errorf(" first 32 bytes: %s", hex.EncodeToString(buf[:min(int(n), 32)])) + } else { + t.Errorf(" no late data within %v (%v)", time.Since(start), derr) + } + + // does the device answer a fresh command? + for attempt := 1; attempt <= 3; attempt++ { + ps := time.Now() + _, _, _, ierr := d.info(context.Background()) + t.Errorf(" probe %d: info() -> %v [%v]", attempt, ierr, time.Since(ps)) + if ierr == nil { + t.Errorf(" device answered again on probe %d", attempt) + return + } + } + t.Errorf(" device still unresponsive after 3 probes") + } + + fail := func(format string, args ...interface{}) { + t.Errorf("preceding operations (seed=%d):", seed) + for _, h := range history { + t.Errorf(" %s", h) + } + probeRecovery() + t.Fatalf(format, args...) + } + + rmFile := func(i int) { + f := live[i] + start := time.Now() + err := d.rm(ctx, f.path) + record("rm(%s) -> %v [%v]", f.path, err, time.Since(start)) + if err != nil { + fail("rm(%s) failed: %v", f.path, err) + } + liveBytes -= f.size + live = append(live[:i], live[i+1:]...) + } + + doPut := func() { + size := awkwardSizes[rng.Intn(len(awkwardSizes))] + if rng.Intn(3) == 0 { + // mix in wholly arbitrary sizes too: + size = uint32(rng.Intn(200*1024)) + 1 + } + for liveBytes+size > maxLive && len(live) > 0 { + rmFile(rng.Intn(len(live))) + } + seq++ + f := stressFile{ + path: fmt.Sprintf("%s/f%04d.bin", dirs[rng.Intn(len(dirs))], seq), + tag: rng.Uint32(), + size: size, + } + start := time.Now() + n, err := d.putFile(ctx, f.path, f.size, bytes.NewReader(filePattern(f.tag, f.size)), nil) + record("putFile(%s, size=%d, tag=$%08x) -> n=%d, %v [%v]", + f.path, f.size, f.tag, n, err, time.Since(start)) + if err != nil { + fail("putFile(%s, %d) failed: %v", f.path, f.size, err) + } + live = append(live, f) + liveBytes += f.size + } + + doGet := func() { + if len(live) == 0 { + doPut() + return + } + f := live[rng.Intn(len(live))] + var w bytes.Buffer + w.Grow(int(f.size)) + start := time.Now() + received, err := d.getFile(ctx, f.path, &w, nil, nil) + record("getFile(%s, size=%d, tag=$%08x) -> received=%d, %v [%v]", + f.path, f.size, f.tag, received, err, time.Since(start)) + if err != nil { + fail("getFile(%s) failed: %v", f.path, err) + } + if received != f.size { + fail("getFile(%s) received %d bytes, want %d", f.path, received, f.size) + } + expected := filePattern(f.tag, f.size) + if !bytes.Equal(w.Bytes(), expected) { + fail("getFile(%s) content mismatch: %s", + f.path, describeStressMismatch(w.Bytes(), expected, f.tag)) + } + } + + doLs := func() { + dir := dirs[rng.Intn(len(dirs))] + start := time.Now() + files, err := d.listFiles(ctx, dir) + record("ls(%s) -> %d entries, %v [%v]", dir, len(files), err, time.Since(start)) + if err != nil { + fail("ls(%s) failed: %v", dir, err) + } + } + + doMkdir := func() { + dir := fmt.Sprintf("%s/d%04d", dirs[rng.Intn(len(dirs))], rng.Intn(8)) + start := time.Now() + err := d.mkdir(ctx, dir) + record("mkdir(%s) -> %v [%v]", dir, err, time.Since(start)) + // error code 1 just means it already exists; only a transport failure + // matters here, and that surfaces as a read timeout instead. + } + + doInfo := func() { + start := time.Now() + _, _, _, err := d.info(ctx) + record("info() -> %v [%v]", err, time.Since(start)) + if err != nil { + fail("info() failed: %v", err) + } + } + + // doMemRead issues a VGET. Memory reads use a 64-byte command block with + // FlagDATA64B|FlagNORESP, whereas every filesystem command uses 512 bytes. + // The firmware re-evaluates server_info.cmd_size only when + // recv_buffer_offset crosses 64 from below, so interleaving the two sizes + // is where a framing desync between commands would show up. + doMemRead := func() { + // WRAM and SRAM, sizes chosen to span the 64-byte packet boundary: + addrs := []uint32{0xF50010, 0xF50100, 0xE00000, 0xF5F340} + sizes := []int{1, 2, 63, 64, 65, 100} + req := devices.MemoryReadRequest{ + RequestAddress: devices.AddressTuple{ + Address: addrs[rng.Intn(len(addrs))], + AddressSpace: sni.AddressSpace_FxPakPro, + MemoryMapping: sni.MemoryMapping_LoROM, + }, + Size: sizes[rng.Intn(len(sizes))], + } + start := time.Now() + rsp, err := d.MultiReadMemory(ctx, req) + record("MultiReadMemory(addr=$%06x, size=%d) -> %d rsp, %v [%v]", + req.RequestAddress.Address, req.Size, len(rsp), err, time.Since(start)) + if err != nil { + fail("MultiReadMemory(addr=$%06x, size=%d) failed: %v", + req.RequestAddress.Address, req.Size, err) + } + if len(rsp) == 1 && len(rsp[0].Data) != req.Size { + fail("MultiReadMemory(addr=$%06x) returned %d bytes, want %d", + req.RequestAddress.Address, len(rsp[0].Data), req.Size) + } + } + + doRm := func() { + if len(live) == 0 { + doPut() + return + } + rmFile(rng.Intn(len(live))) + } + + start := time.Now() + for i := 0; i < ops; i++ { + switch n := rng.Intn(100); { + case n < 26: + doPut() + case n < 52: + doGet() + case n < 72: + doLs() + case n < 82: + doMkdir() + case n < 88: + doRm() + case n < 96: + doMemRead() + default: + doInfo() + } + if (i+1)%25 == 0 { + t.Logf("%d/%d ops, %d live files, %d live bytes, %v elapsed", + i+1, ops, len(live), liveBytes, time.Since(start)) + } + } + t.Logf("completed %d ops in %v", ops, time.Since(start)) + + // leave the card as we found it: + for len(live) > 0 { + rmFile(len(live) - 1) + } +} From 9eeb9557281f60e51fa026cee823fc32047efd7d Mon Sep 17 00:00:00 2001 From: jsd1982 Date: Fri, 28 Aug 2026 08:40:16 -0500 Subject: [PATCH 03/12] github: update actions; remove windows/arm build --- .github/workflows/release.yml | 41 +++++++++++++++-------------------- 1 file changed, 18 insertions(+), 23 deletions(-) diff --git a/.github/workflows/release.yml b/.github/workflows/release.yml index 43365f7..23e94cd 100644 --- a/.github/workflows/release.yml +++ b/.github/workflows/release.yml @@ -12,14 +12,14 @@ jobs: runs-on: ubuntu-latest steps: - name: Set up Go - uses: actions/setup-go@v5 + uses: actions/setup-go@v7 with: go-version: '^1.23.0' - name: Set up linux dependencies run: sudo apt-get update && sudo apt-get install -y gcc - - uses: actions/checkout@v4 + - uses: actions/checkout@v7 with: fetch-depth: 0 @@ -48,11 +48,6 @@ jobs: goarch: "386" suffix: zip name: win-x86 - - os: windows-latest - goos: windows - goarch: arm - suffix: zip - name: win-arm - os: windows-latest goos: windows goarch: arm64 @@ -63,11 +58,11 @@ jobs: steps: - name: Inject slug/short variables - uses: rlespinasse/github-slug-action@v4 + uses: rlespinasse/github-slug-action@v5 - name: Set up Go if: ${{ matrix.goos != 'windows' || matrix.os-variant != '7' }} - uses: actions/setup-go@v5 + uses: actions/setup-go@v7 with: go-version: '^1.23.0' @@ -80,7 +75,7 @@ jobs: - run: echo "basename=sni-${{env.GITHUB_REF_SLUG}}-${{matrix.goos}}${{matrix.os-variant}}-${{matrix.goarch}}${{matrix.alt}}" | Out-File -FilePath $env:GITHUB_ENV -Encoding utf8 -Append - - uses: actions/checkout@v4 + - uses: actions/checkout@v7 name: Checkout with: fetch-depth: 0 @@ -130,7 +125,7 @@ jobs: run: 7z x -o"${{env.basename}}" "${{ runner.temp }}/${{ matrix.snfm }}" - name: Upload artifact - uses: actions/upload-artifact@v4 + uses: actions/upload-artifact@v7 with: name: ${{env.basename}} path: ${{env.basename}}/ @@ -163,16 +158,16 @@ jobs: steps: - name: Inject slug/short variables - uses: rlespinasse/github-slug-action@v4 + uses: rlespinasse/github-slug-action@v5 - name: Set up Go - uses: actions/setup-go@v5 + uses: actions/setup-go@v7 with: go-version: '^1.23.0' - run: echo "basename=sni-${{env.GITHUB_REF_SLUG}}-darwin-universal${{matrix.alt}}" >> $GITHUB_ENV - - uses: actions/checkout@v4 + - uses: actions/checkout@v7 name: Checkout with: fetch-depth: 0 @@ -218,7 +213,7 @@ jobs: run: 7z x -o"${{env.basename}}" "${{ runner.temp }}/${{ matrix.snfm }}" - name: Upload artifact - uses: actions/upload-artifact@v4 + uses: actions/upload-artifact@v7 with: name: ${{env.basename}} path: ${{env.basename}}/ @@ -282,10 +277,10 @@ jobs: steps: - name: Inject slug/short variables - uses: rlespinasse/github-slug-action@v4 + uses: rlespinasse/github-slug-action@v5 - name: Set up Go - uses: actions/setup-go@v5 + uses: actions/setup-go@v7 with: go-version: '^1.23.0' @@ -294,7 +289,7 @@ jobs: - run: echo "basename=sni-${{env.GITHUB_REF_SLUG}}-${{matrix.goos}}${{matrix.os-variant}}-${{matrix.goarch}}${{matrix.alt}}" >> $GITHUB_ENV - - uses: actions/checkout@v4 + - uses: actions/checkout@v7 name: Checkout with: fetch-depth: 0 @@ -336,7 +331,7 @@ jobs: run: 7z x -o"${{env.basename}}" "${{ runner.temp }}/${{ matrix.snfm }}" - name: Upload artifact - uses: actions/upload-artifact@v4 + uses: actions/upload-artifact@v7 with: name: ${{env.basename}} path: ${{env.basename}}/ @@ -361,10 +356,10 @@ jobs: name: manylinux_2_28 steps: - name: Inject slug/short variables - uses: rlespinasse/github-slug-action@v4 + uses: rlespinasse/github-slug-action@v5 - name: Set up Go - uses: actions/setup-go@v5 + uses: actions/setup-go@v7 with: go-version: '^1.23.0' @@ -375,7 +370,7 @@ jobs: - run: echo "basename=sni-${{env.GITHUB_REF_SLUG}}-manylinux_2_28-amd64" >> $GITHUB_ENV - - uses: actions/checkout@v4 + - uses: actions/checkout@v7 name: Checkout with: fetch-depth: 0 @@ -414,7 +409,7 @@ jobs: tar cJf ${{env.basename}}.tar.xz ${{env.basename}}/ - name: Upload artifact - uses: actions/upload-artifact@v4 + uses: actions/upload-artifact@v7 with: name: ${{env.basename}}.tar.xz path: ${{github.workspace}}/${{env.basename}}.tar.xz From 9834b823b82767215336fc9d48de9e449714e2d1 Mon Sep 17 00:00:00 2001 From: jsd1982 Date: Fri, 28 Aug 2026 11:22:31 -0500 Subject: [PATCH 04/12] fxpakpro: report get/put command errors as fatal Audited every command for whether a device error code leaves the protocol stream clean. What decides it is the firmware's own next-state choice, which is made by opcode before it knows whether the command succeeded: GET, VGET, LS -> HANDLE_DAT device is about to send a data phase PUT, VPUT -> HANDLE_LOCK device is waiting for a payload everything else -> IDLE nothing pending So fatality should follow whether there is a pending data phase, not how severe the error sounds. mkdir, rm, mv, boot, reset, menu_reset and info all land in IDLE and stay non-fatal, which is right: error code 1 is the device's generic "something went wrong" and for mkdir usually just means the directory already exists. Nothing is pending, the stream stays aligned, and tearing the connection down would be both wrong and risky given how poorly the firmware handles reconnects. get and put were the two that did not match. Both are only reachable from tests today -- d.get appears solely in get_test.go and d.put has no callers -- and for SpaceSNES the firmware cannot set an error code at all. SpaceCFG can, though, via cfg_get_stringvalue returning not-found, so get is genuinely reachable if it is ever wired up. get cannot drain its way out the way ls does: the data phase length comes from server_info.size, which on the error path holds whatever a previous command left in the FILINFO rather than a real length. Closing and reopening is the only reliable recovery. vget and vput are unaffected; they set FlagNORESP and never read a response block, so there is no error code to mishandle. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01ARLkt3NCnrwBMvpP8eAfDR --- devices/snes/drivers/fxpakpro/get.go | 9 ++++++++- devices/snes/drivers/fxpakpro/put.go | 8 +++++++- 2 files changed, 15 insertions(+), 2 deletions(-) diff --git a/devices/snes/drivers/fxpakpro/get.go b/devices/snes/drivers/fxpakpro/get.go index 3b4fb74..cdb7124 100644 --- a/devices/snes/drivers/fxpakpro/get.go +++ b/devices/snes/drivers/fxpakpro/get.go @@ -64,8 +64,15 @@ func (d *Device) get(ctx context.Context, space space, address uint32, size uint return } if ec := sb[5]; ec != 0 { + // usbint_handler_cmd moves to HANDLE_DAT for GET before it knows whether + // the command succeeded, so the device is about to send a data phase we + // are not going to read. Unlike LS there is no reliable way to drain it: + // the length comes from server_info.size, which on the error path holds + // whatever a previous command left behind. Report this as fatal so the + // device is closed and reopened rather than leaving the stream out of + // step for every command that follows. err = fmt.Errorf("get: %w", fxpakproError(ec)) - err = d.NonFatalError(err) + err = d.FatalError(err) return } diff --git a/devices/snes/drivers/fxpakpro/put.go b/devices/snes/drivers/fxpakpro/put.go index bce2119..d370d35 100644 --- a/devices/snes/drivers/fxpakpro/put.go +++ b/devices/snes/drivers/fxpakpro/put.go @@ -65,8 +65,14 @@ func (d *Device) put(ctx context.Context, space space, address uint32, data []by return } if ec := sb[5]; ec != 0 { + // As in putFile: usbint_recv_block sets cmdDat=1 as soon as it sees a PUT + // opcode, so the device is parked in HANDLE_LOCK waiting for the payload + // even though the command failed. We are not sending it, and whatever is + // written next would be consumed as data. Report this as fatal so the + // connection is torn down while the firmware can still recover from it -- + // usbint_check_connect() resets server_state and cmdDat on disconnect. err = fmt.Errorf("put: %w", fxpakproError(ec)) - err = d.NonFatalError(err) + err = d.FatalError(err) return } From bbde92bb98c9b6391f1ef7350f4477531a8e8686 Mon Sep 17 00:00:00 2001 From: jsd1982 Date: Fri, 28 Aug 2026 13:17:02 -0500 Subject: [PATCH 05/12] fxpakpro: do not block closing a port after abandoning a write abandonPort closed the port synchronously. A Write that is stuck because the device stopped draining its USB endpoint keeps the handle busy, and on macOS close() then blocks until that I/O completes -- so the caller hung inside Close instead of inside Write. The same deadlock the write timeout exists to prevent, one frame further down, and it triggered exactly when the timeout was supposed to rescue the caller: goroutine 23 [syscall]: fxpakpro.(*devicePort).Close fxpakpro.abandonPort fxpakpro.writeWithTimeout fxpakpro.writeExact fxpakpro.(*Device).putFile devicePort.abandon() now marks the port unusable and closes it on its own goroutine. Write refuses once the port is marked, so nothing can race the abandoned write, and Close is idempotent so autoCloseableDevice's later close cannot block behind the same stuck write either. This was missed on Windows, where the close did not block. It took a soak on macOS, sitting for minutes with no CPU time, to surface it. Test_writeWithTimeout_closeDoesNotBlock covers it with a port whose Close blocks until the write is released. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01ARLkt3NCnrwBMvpP8eAfDR --- devices/snes/drivers/fxpakpro/device.go | 37 ++++++++++++++- .../snes/drivers/fxpakpro/sendserial_test.go | 46 +++++++++++++++++++ devices/snes/drivers/fxpakpro/serial.go | 16 +++++-- 3 files changed, 94 insertions(+), 5 deletions(-) diff --git a/devices/snes/drivers/fxpakpro/device.go b/devices/snes/drivers/fxpakpro/device.go index 719c5fc..6e24282 100644 --- a/devices/snes/drivers/fxpakpro/device.go +++ b/devices/snes/drivers/fxpakpro/device.go @@ -2,8 +2,10 @@ package fxpakpro import ( "context" + "errors" "fmt" "go.bug.st/serial" + "log" "sni/devices" "sync" "sync/atomic" @@ -16,16 +18,49 @@ import ( // close does not go through Device.Close(), so without this the isClosed flag // would stay false and autoCloseableDevice would keep a device whose port is // dead in its container (it consults IsClosed() to decide whether to drop it). +var errPortAbandoned = errors.New("fxpakpro: port was abandoned after a stuck write") + type devicePort struct { serial.Port closed atomic.Bool } func (p *devicePort) Close() error { - p.closed.Store(true) + if p.closed.Swap(true) { + // Already closed, or abandoned with the real close in flight on another + // goroutine. Calling Close again could block behind a stuck write. + return nil + } return p.Port.Close() } +// Write refuses once the port has been abandoned, so a write that was given up +// on cannot be followed by another one racing it on the same port. +func (p *devicePort) Write(b []byte) (int, error) { + if p.closed.Load() { + return 0, errPortAbandoned + } + return p.Port.Write(b) +} + +// abandon marks the port unusable and closes it in the background. +// +// The close cannot be synchronous. A Write that is stuck because the device +// stopped draining its USB endpoint keeps the handle busy, and close() then +// blocks until that I/O completes -- which is the very hang being escaped. +// Marking the port closed first stops any further write from starting, and the +// real close completes whenever the stuck write finally unwinds. +func (p *devicePort) abandon() { + if p.closed.Swap(true) { + return + } + go func() { + if err := p.Port.Close(); err != nil { + log.Printf("%s: closing abandoned port: %v\n", driverName, err) + } + }() +} + type Device struct { lock sync.Mutex f *devicePort diff --git a/devices/snes/drivers/fxpakpro/sendserial_test.go b/devices/snes/drivers/fxpakpro/sendserial_test.go index 7cdd2a5..51f04ac 100644 --- a/devices/snes/drivers/fxpakpro/sendserial_test.go +++ b/devices/snes/drivers/fxpakpro/sendserial_test.go @@ -174,3 +174,49 @@ func Test_writeWithTimeout_contextCancelled(t *testing.T) { t.Errorf("writeExact() took %v; it should stop at the context deadline", elapsed) } } + +// blockingClosePort models the macOS behaviour that caused a deadlock: a close +// on a handle with a pending write blocks until that I/O completes. +type blockingClosePort struct { + blockingPort +} + +func (p *blockingClosePort) Close() error { + <-p.release // never returns while the write is still stuck + return nil +} + +// Test_writeWithTimeout_closeDoesNotBlock checks that giving up on a write does +// not block on closing the port. +// +// abandonPort used to close synchronously. A Write stuck because the device +// stopped draining keeps the handle busy, and close() then waits for that I/O, +// so the caller hung inside Close instead of inside Write -- the same deadlock, +// one frame further down. Caught by a soak that sat for minutes with the stack +// in devicePort.Close. +func Test_writeWithTimeout_closeDoesNotBlock(t *testing.T) { + old := writeTimeout + writeTimeout = 150 * time.Millisecond + defer func() { writeTimeout = old }() + + p := &blockingClosePort{ + blockingPort: blockingPort{ + release: make(chan struct{}), + started: make(chan struct{}), + }, + } + defer close(p.release) + + done := make(chan struct{}) + go func() { + defer close(done) + _, _ = writeExact(context.Background(), p, 512, make([]byte, 512)) + }() + + select { + case <-done: + case <-time.After(5 * time.Second): + t.Fatalf("writeExact() did not return: it is blocked closing the port " + + "while the abandoned write still holds it") + } +} diff --git a/devices/snes/drivers/fxpakpro/serial.go b/devices/snes/drivers/fxpakpro/serial.go index 3c96bc6..fdeea4d 100644 --- a/devices/snes/drivers/fxpakpro/serial.go +++ b/devices/snes/drivers/fxpakpro/serial.go @@ -253,12 +253,20 @@ func writeWithTimeout(ctx context.Context, w io.Writer, buf []byte) (p uint32, e // gone. Errors are logged rather than returned; the caller already has a more // useful error describing why the write was abandoned. func abandonPort(w io.Writer) { - c, ok := w.(io.Closer) - if !ok { + // devicePort marks itself unusable straight away and closes in the + // background, because a synchronous close would block behind the very write + // we just gave up on. + if a, ok := w.(interface{ abandon() }); ok { + a.abandon() return } - if err := c.Close(); err != nil { - log.Printf("%s: closing port after an abandoned write: %v\n", driverName, err) + // anything else (test doubles): close off the critical path + if c, ok := w.(io.Closer); ok { + go func() { + if err := c.Close(); err != nil { + log.Printf("%s: closing port after an abandoned write: %v\n", driverName, err) + } + }() } } From a74bfa3a75b2d07e25b27d3aa4cf5a588c362caf Mon Sep 17 00:00:00 2001 From: jsd1982 Date: Fri, 28 Aug 2026 13:17:02 -0500 Subject: [PATCH 06/12] fxpakpro: make the stress mix configurable and add memory writes SNI_TEST_WEIGHTS sets the operation mix, so a run can be shaped to match real usage. Trackers poll memory with VGET far more than they touch files, which is worth testing directly: VGET sends a 64 byte command block where every filesystem command sends 512, and the firmware only re-evaluates server_info.cmd_size when recv_buffer_offset crosses 64 from below, so mixing the two is where a framing desync would show up. Added a memory write op that VPUTs and then reads the value back. A write-only check would pass on a stream that had desynced into returning plausible but wrong data. Writes target cartridge SRAM rather than WRAM. Writes to 0xF50000-0xF70000 are not a plain VPUT: memory.go turns them into a 65816 copy routine driven through the USB EXE mechanism, which needs the SNES to be running code that services the hook. Sitting in the system menu nothing does, so they time out waiting on $2C00. SRAM is also mirrored to a per-game file on the SD card every 250ms, so these writes generate SD activity too -- useful, since that is where the firmware does FAT work inside its USB interrupt handler. Soaked at 62% VGET, 8% VPUT-with-readback and 30% filesystem operations: 8000 operations in 5m24s with no failures. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01ARLkt3NCnrwBMvpP8eAfDR --- devices/snes/drivers/fxpakpro/stress_test.go | 130 ++++++++++++++++--- 1 file changed, 114 insertions(+), 16 deletions(-) diff --git a/devices/snes/drivers/fxpakpro/stress_test.go b/devices/snes/drivers/fxpakpro/stress_test.go index 7bf3dc0..a8d28e6 100644 --- a/devices/snes/drivers/fxpakpro/stress_test.go +++ b/devices/snes/drivers/fxpakpro/stress_test.go @@ -9,6 +9,7 @@ import ( "math/rand" "os" "strconv" + "strings" "testing" "time" @@ -299,6 +300,60 @@ func TestDevice_stressMixed(t *testing.T) { } } + // doMemWrite issues a VPUT to cartridge SRAM and reads the value back. + // + // SRAM is a plain VPUT to SpaceSNES. WRAM is deliberately avoided: writes in + // 0xF50000-0xF70000 do not go out as a VPUT at all, they are turned into a + // 65816 copy routine driven through the USB EXE mechanism (memory.go), which + // needs the SNES to be running code that services the hook. In the system + // menu nothing does, so those time out waiting on $2C00. + // + // The fxpakpro mirrors SRAM to a per-game file on the SD card every 250ms, + // so these writes also generate SD activity -- useful here, since that is + // where the firmware's FAT work inside the USB interrupt handler happens. + doMemWrite := func() { + addrs := []uint32{0xE07FF0, 0xE07FF4, 0xE07FF8} + sizes := []int{1, 2, 4} + + addr := addrs[rng.Intn(len(addrs))] + n := sizes[rng.Intn(len(sizes))] + data := make([]byte, n) + rng.Read(data) + + tuple := devices.AddressTuple{ + Address: addr, + AddressSpace: sni.AddressSpace_FxPakPro, + MemoryMapping: sni.MemoryMapping_LoROM, + } + + start := time.Now() + rsp, err := d.MultiWriteMemory(ctx, devices.MemoryWriteRequest{ + RequestAddress: tuple, + Data: data, + }) + record("MultiWriteMemory(addr=$%06x, size=%d) -> %d rsp, %v [%v]", + addr, n, len(rsp), err, time.Since(start)) + if err != nil { + fail("MultiWriteMemory(addr=$%06x, size=%d) failed: %v", addr, n, err) + } + + // read it back: this catches a desync that leaves the transport working + // but the data wrong, which a write-only check would miss. + rstart := time.Now() + rrsp, err := d.MultiReadMemory(ctx, devices.MemoryReadRequest{ + RequestAddress: tuple, + Size: n, + }) + record(" readback(addr=$%06x, size=%d) -> %d rsp, %v [%v]", + addr, n, len(rrsp), err, time.Since(rstart)) + if err != nil { + fail("readback of $%06x failed: %v", addr, err) + } + if len(rrsp) != 1 || !bytes.Equal(rrsp[0].Data, data) { + fail("readback of $%06x returned %x, wrote %x", addr, rrsp[0].Data, data) + } + } + doRm := func() { if len(live) == 0 { doPut() @@ -307,24 +362,67 @@ func TestDevice_stressMixed(t *testing.T) { rmFile(rng.Intn(len(live))) } + // Operation mix as relative weights, overridable with SNI_TEST_WEIGHTS, e.g. + // "memread=60,put=8,get=8,ls=8,memwrite=6,mkdir=4,rm=4,info=2" to model a + // tracker, which polls memory with VGET far more than it touches files. + weights := map[string]int{ + "put": 26, "get": 26, "ls": 20, "mkdir": 10, + "rm": 6, "memread": 8, "memwrite": 0, "info": 4, + } + if v := os.Getenv("SNI_TEST_WEIGHTS"); v != "" { + for _, kv := range strings.Split(v, ",") { + parts := strings.SplitN(strings.TrimSpace(kv), "=", 2) + if len(parts) != 2 { + t.Fatalf("SNI_TEST_WEIGHTS: bad entry %q", kv) + } + w, err := strconv.Atoi(parts[1]) + if err != nil || w < 0 { + t.Fatalf("SNI_TEST_WEIGHTS: bad weight in %q", kv) + } + if _, ok := weights[parts[0]]; !ok { + t.Fatalf("SNI_TEST_WEIGHTS: unknown operation %q", parts[0]) + } + weights[parts[0]] = w + } + } + + type weighted struct { + name string + w int + fn func() + } + table := []weighted{ + {"put", weights["put"], doPut}, + {"get", weights["get"], doGet}, + {"ls", weights["ls"], doLs}, + {"mkdir", weights["mkdir"], doMkdir}, + {"rm", weights["rm"], doRm}, + {"memread", weights["memread"], doMemRead}, + {"memwrite", weights["memwrite"], doMemWrite}, + {"info", weights["info"], doInfo}, + } + total := 0 + for _, e := range table { + total += e.w + } + if total == 0 { + t.Fatalf("all operation weights are zero") + } + pick := func(n int) { + for _, e := range table { + if n < e.w { + e.fn() + return + } + n -= e.w + } + table[len(table)-1].fn() + } + t.Logf("operation mix: %v (total %d)", weights, total) + start := time.Now() for i := 0; i < ops; i++ { - switch n := rng.Intn(100); { - case n < 26: - doPut() - case n < 52: - doGet() - case n < 72: - doLs() - case n < 82: - doMkdir() - case n < 88: - doRm() - case n < 96: - doMemRead() - default: - doInfo() - } + pick(rng.Intn(total)) if (i+1)%25 == 0 { t.Logf("%d/%d ops, %d live files, %d live bytes, %v elapsed", i+1, ops, len(live), liveBytes, time.Since(start)) From 89d3c832f32a83d5ffd9267f9202a3ed43f578a6 Mon Sep 17 00:00:00 2001 From: jsd1982 Date: Fri, 28 Aug 2026 13:23:07 -0500 Subject: [PATCH 07/12] fxpakpro: let the stress test target WRAM as well as SRAM SNI_TEST_MEM_SPACE selects what memory writes go to. SRAM stays the default so the test is usable while the device sits in the system menu. WRAM only works with a ROM running: writes to 0xF50000-0xF70000 are not a plain VPUT, memory.go turns them into a 65816 copy routine driven through the USB EXE mechanism, which polls $2C00 waiting for the SNES to service the hook. That is what a tracker does when it injects state, so it is worth covering, but it needs a game booted. The read-back comparison is skipped for WRAM. A running game writes WRAM constantly, so a value read back can differ from what was written for entirely legitimate reasons and comparing would produce false failures. The byte count is still checked, which catches a desync even when the contents cannot be predicted. SRAM keeps the full comparison, since nothing else writes it. Soaked in-game with Super Mario World running, at 62% VGET, 8% WRAM VPUT and 30% filesystem operations: 12000 operations in 4m8s with no failures. Also worth recording: the same mix runs at roughly 100 ops/sec in-game against 25 ops/sec in the system menu. menu_main_loop sleeps 20ms per usbint_handler() call while the in-game loop in main.c has no sleep at all, so a device sitting in the menu services USB only about 50 times a second. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01ARLkt3NCnrwBMvpP8eAfDR --- devices/snes/drivers/fxpakpro/stress_test.go | 25 +++++++++++++++++++- 1 file changed, 24 insertions(+), 1 deletion(-) diff --git a/devices/snes/drivers/fxpakpro/stress_test.go b/devices/snes/drivers/fxpakpro/stress_test.go index a8d28e6..bf5159e 100644 --- a/devices/snes/drivers/fxpakpro/stress_test.go +++ b/devices/snes/drivers/fxpakpro/stress_test.go @@ -311,8 +311,22 @@ func TestDevice_stressMixed(t *testing.T) { // The fxpakpro mirrors SRAM to a per-game file on the SD card every 250ms, // so these writes also generate SD activity -- useful here, since that is // where the firmware's FAT work inside the USB interrupt handler happens. + // SNI_TEST_MEM_SPACE picks what memory writes target: "sram" (default) or + // "wram", the latter only meaningful with a ROM running. + memSpace := os.Getenv("SNI_TEST_MEM_SPACE") + if memSpace == "" { + memSpace = "sram" + } + if memSpace != "sram" && memSpace != "wram" { + t.Fatalf("SNI_TEST_MEM_SPACE=%q: want sram or wram", memSpace) + } + t.Logf("memory writes target %s", memSpace) + doMemWrite := func() { addrs := []uint32{0xE07FF0, 0xE07FF4, 0xE07FF8} + if memSpace == "wram" { + addrs = []uint32{0xF5F340, 0xF5F344, 0xF5F348} + } sizes := []int{1, 2, 4} addr := addrs[rng.Intn(len(addrs))] @@ -349,7 +363,16 @@ func TestDevice_stressMixed(t *testing.T) { if err != nil { fail("readback of $%06x failed: %v", addr, err) } - if len(rrsp) != 1 || !bytes.Equal(rrsp[0].Data, data) { + // Only SRAM can be compared. A running game writes WRAM continuously, so + // a value read back from it may legitimately differ from what was + // written -- the point of exercising WRAM is the USB EXE path, not data + // integrity. Still require the right number of bytes back, which catches + // a desync even when the contents cannot be predicted. + if len(rrsp) != 1 || len(rrsp[0].Data) != n { + fail("readback of $%06x returned %d responses / %d bytes, wanted 1 / %d", + addr, len(rrsp), len(rrsp[0].Data), n) + } + if memSpace == "sram" && !bytes.Equal(rrsp[0].Data, data) { fail("readback of $%06x returned %x, wrote %x", addr, rrsp[0].Data, data) } } From e4546e758a55b6cbd1a0ca089c02b4976f8f36c8 Mon Sep 17 00:00:00 2001 From: jsd1982 Date: Fri, 28 Aug 2026 14:05:33 -0500 Subject: [PATCH 08/12] fxpakpro: add a reset-to-menu test helper Pairs with TestDevice_bootPath for putting the device into a known state between hardware runs. The firmware polls USB very differently in the two states -- menu_main_loop sleeps 20ms per usbint_handler() call while the in-game loop does not -- so which state a soak ran in matters when reading its results. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01ARLkt3NCnrwBMvpP8eAfDR --- .../snes/drivers/fxpakpro/bootpath_test.go | 41 +++++++++++++++++++ 1 file changed, 41 insertions(+) diff --git a/devices/snes/drivers/fxpakpro/bootpath_test.go b/devices/snes/drivers/fxpakpro/bootpath_test.go index a02c1cf..280c79c 100644 --- a/devices/snes/drivers/fxpakpro/bootpath_test.go +++ b/devices/snes/drivers/fxpakpro/bootpath_test.go @@ -78,3 +78,44 @@ func TestDevice_info(t *testing.T) { t.Logf("state: IN-GAME (main.c loop, usbint_handler every iteration)") } } + +// TestDevice_resetToMenu returns the device to the system menu. Pairs with +// TestDevice_bootPath for putting the device into a known state between runs, +// since the firmware polls USB very differently in the menu than in-game. +func TestDevice_resetToMenu(t *testing.T) { + if os.Getenv("SNI_TEST_RESET_TO_MENU") == "" { + t.Skip("set SNI_TEST_RESET_TO_MENU=1 to reset the device to the menu") + } + + d := openExactDevice(t) + defer d.Close() + ctx := context.Background() + + if _, _, rom, err := d.info(ctx); err != nil { + t.Fatalf("info() before reset: %v", err) + } else { + t.Logf("before reset, running: %q", rom) + } + + if err := d.ResetToMenu(ctx); err != nil { + t.Fatalf("ResetToMenu(): %v", err) + } + + for attempt := 1; attempt <= 10; attempt++ { + time.Sleep(2 * time.Second) + + pctx, cancel := context.WithTimeout(context.Background(), 3*time.Second) + _, _, rom, err := d.info(pctx) + cancel() + if err != nil { + t.Logf("probe %d: info() -> %v", attempt, err) + continue + } + t.Logf("probe %d: running %q", attempt, rom) + if rom == "/sd2snes/menu.bin" || rom == "/sd2snes/m3nu.bin" { + t.Logf("back in the system menu") + return + } + } + t.Errorf("device did not return to the menu within 10 probes") +} From dffdaf24f964e2fae637fcdabd1ef1ec4a0b0418 Mon Sep 17 00:00:00 2001 From: jsd1982 Date: Sat, 29 Aug 2026 11:34:50 -0500 Subject: [PATCH 09/12] fxpakpro: add a configurable inter-chunk write delay fxpakpro_chunk_delay pauses after each 512-byte chunk written during a transfer. It defaults to zero, which writes as fast as the device accepts data, and exists to separate host write pacing from the logging that happens to accompany it. A user reported transfers succeeding with SNI_DEBUG=1 and failing without it, and the obvious theory was that debug logging slowed the host enough to matter. Measured on Windows, it does not: a 4 MiB upload takes 9.40s with debug against 9.51s without, because writes are paced by USB NAKs rather than by the host. This knob makes that testable directly rather than inferred from a logging side effect. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01ARLkt3NCnrwBMvpP8eAfDR --- cmd/sni/config/config.go | 7 +++++++ devices/snes/drivers/fxpakpro/driver.go | 12 ++++++++++-- devices/snes/drivers/fxpakpro/serial.go | 7 +++++++ 3 files changed, 24 insertions(+), 2 deletions(-) diff --git a/cmd/sni/config/config.go b/cmd/sni/config/config.go index efcf918..a8e308b 100644 --- a/cmd/sni/config/config.go +++ b/cmd/sni/config/config.go @@ -63,6 +63,13 @@ var ( // timeouts above) rather than being cut short mid-transfer by an // impatient client. "fxpakpro_honor_caller_deadline": true, + // Optional pause after each 512-byte chunk written during a transfer. + // Zero, the default, writes as fast as the device accepts data. This + // exists to test whether host write pacing affects reliability: setting + // SNI_DEBUG=1 slows transfers dramatically (a hex dump per chunk to a + // file and the console) and has been reported to make failing transfers + // succeed, so this isolates the timing from the logging. + "fxpakpro_chunk_delay": "0s", "retroarch_disable": false, "retroarch_hosts": "localhost:55355", diff --git a/devices/snes/drivers/fxpakpro/driver.go b/devices/snes/drivers/fxpakpro/driver.go index 2b33ad3..548c9a3 100644 --- a/devices/snes/drivers/fxpakpro/driver.go +++ b/devices/snes/drivers/fxpakpro/driver.go @@ -305,7 +305,15 @@ func loadTimeoutConfig() { if config.Config.IsSet("fxpakpro_honor_caller_deadline") { honorCallerDeadline = config.Config.GetBool("fxpakpro_honor_caller_deadline") } + if config.Config.IsSet("fxpakpro_chunk_delay") { + if v := config.Config.GetDuration("fxpakpro_chunk_delay"); v >= 0 { + chunkDelay = v + } else { + log.Printf("%s: ignoring negative fxpakpro_chunk_delay %q\n", + driverName, config.Config.GetString("fxpakpro_chunk_delay")) + } + } - log.Printf("%s: read timeout %v, write timeout %v, honor caller deadline %v\n", - driverName, noDataTimeout, writeTimeout, honorCallerDeadline) + log.Printf("%s: read timeout %v, write timeout %v, honor caller deadline %v, chunk delay %v\n", + driverName, noDataTimeout, writeTimeout, honorCallerDeadline, chunkDelay) } diff --git a/devices/snes/drivers/fxpakpro/serial.go b/devices/snes/drivers/fxpakpro/serial.go index fdeea4d..2dc3634 100644 --- a/devices/snes/drivers/fxpakpro/serial.go +++ b/devices/snes/drivers/fxpakpro/serial.go @@ -37,6 +37,10 @@ var ( // be told that a command was abandoned, so stopping midway through one // leaves the protocol out of step until the stream is drained. honorCallerDeadline = true + + // chunkDelay optionally pauses after each chunk written during a transfer. + // See fxpakpro_chunk_delay in the config defaults. + chunkDelay time.Duration ) func readExactGeneric(ctx context.Context, f io.Reader, chunkSize uint32, buf []byte) (p uint32, err error) { @@ -329,6 +333,9 @@ func sendSerialProgress(ctx context.Context, f serial.Port, chunkSize uint32, si err = fmt.Errorf("sendSerialProgress: write failed after %d of %d bytes: %w", sent, size, err) return } + if chunkDelay > 0 { + time.Sleep(chunkDelay) + } } // transfer any remainder: From 8fa68c8bf79e833cb225533cdcff825fdd75d986 Mon Sep 17 00:00:00 2001 From: jsd1982 Date: Sat, 29 Aug 2026 11:35:04 -0500 Subject: [PATCH 10/12] fxpakpro: retry opening a busy port after an abandoned write Abandoning a stuck write closes the port on another goroutine, because a synchronous close blocks behind the very write being abandoned. The orphaned write still holds the handle until it unwinds, and autoCloseableDevice reopens as soon as the fatal error propagates -- microseconds later -- so the reopen lands while the handle is still held. Seen in the field on Windows: one stalled transfer poisoned every command that followed. fxpakpro: open(name="/COM3"): Serial port busy /DeviceFilesystem/ReadDirectory: err=`... Serial port busy` openPort now retries for up to 3 seconds at 50ms intervals, but only for serial.PortBusy. Every other failure still returns immediately, so a wedged or absent device is not retried for baud rates that were never going to work. This does not help if the device has genuinely stopped draining, since the orphaned write never unwinds and the handle is never released. It fixes the common case where the close simply had not completed yet, which is what turned a single failed upload into a stream of unrelated errors. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01ARLkt3NCnrwBMvpP8eAfDR --- devices/snes/drivers/fxpakpro/driver.go | 56 ++++++++++++++++++++++--- 1 file changed, 50 insertions(+), 6 deletions(-) diff --git a/devices/snes/drivers/fxpakpro/driver.go b/devices/snes/drivers/fxpakpro/driver.go index 548c9a3..660d961 100644 --- a/devices/snes/drivers/fxpakpro/driver.go +++ b/devices/snes/drivers/fxpakpro/driver.go @@ -12,6 +12,7 @@ import ( "strconv" "strings" "sync" + "time" "go.bug.st/serial" "go.bug.st/serial/enumerator" @@ -140,12 +141,7 @@ func (d *Driver) openPort(portName string, baudRequest int) (f serial.Port, err } log.Printf("%s: open(name=\"%s\", baud=%d)\n", driverName, portName, baud) - f, err = serial.Open(portName, &serial.Mode{ - BaudRate: baud, - DataBits: 8, - Parity: serial.NoParity, - StopBits: serial.OneStopBit, - }) + f, err = openPortRetryBusy(portName, baud) if err == nil { break } @@ -195,6 +191,54 @@ func (d *Driver) openPort(portName string, baudRequest int) (f serial.Port, err return } +// openPortRetryBusy opens the port, retrying briefly while the OS reports it +// busy. +// +// After a write is abandoned the port is closed on another goroutine, because a +// synchronous close would block behind the very write we gave up on. The +// orphaned write still holds the handle until it unwinds, so a reopen attempted +// immediately afterwards fails with "Serial port busy" -- and autoCloseableDevice +// reopens as soon as the fatal error propagates, which is microseconds later. +// Observed in the field: every request after a stalled transfer failed to open +// the port even though the device itself was fine. +// +// Retry for a short while so that window closes on its own. If the device has +// genuinely stopped draining, the orphan never unwinds and this still gives up; +// no amount of retrying fixes that, but it does fix the common case where the +// close simply had not landed yet. +func openPortRetryBusy(portName string, baud int) (f serial.Port, err error) { + const busyRetryFor = 3 * time.Second + const busyRetryEvery = 50 * time.Millisecond + + deadline := time.Now().Add(busyRetryFor) + for attempt := 1; ; attempt++ { + f, err = serial.Open(portName, &serial.Mode{ + BaudRate: baud, + DataBits: 8, + Parity: serial.NoParity, + StopBits: serial.OneStopBit, + }) + if err == nil { + if attempt > 1 { + log.Printf("%s: open(name=%q) succeeded on attempt %d\n", + driverName, portName, attempt) + } + return + } + + var portErr *serial.PortError + if !errors.As(err, &portErr) || portErr.Code() != serial.PortBusy { + return + } + if time.Now().After(deadline) { + return nil, fmt.Errorf( + "%s: port %s still busy after %v; a previous transfer's write "+ + "may still be stuck: %w", driverName, portName, busyRetryFor, err) + } + time.Sleep(busyRetryEvery) + } +} + func (d *Driver) DeviceKey(uri *url.URL) (key string) { key = uri.Path // macos/linux paths: From a02cccd604d97cb0f16a6311abebd75f13b94e20 Mon Sep 17 00:00:00 2001 From: jsd1982 Date: Sat, 29 Aug 2026 11:35:22 -0500 Subject: [PATCH 11/12] fxpakpro: add a gRPC repro harness and firmware-counter tests cmd/snitest drives SNI over gRPC the way a file transfer client does: ListDevices, MakeDirectory for each path component, PutFile, ReadDirectory, GetFile with verification. Every other hardware test in this repo calls the driver in-process, which skips the gRPC server, autoCloseableDevice and the daemon's goroutine scheduling -- and the failure being investigated was reported through that stack. Flags allow isolating the upload path, and pointing it at a missing directory to exercise the LS error path deliberately. Note it raises the gRPC receive limit: a 4 MiB file plus framing exceeds the client default of 4MB, so GetFile fails with ResourceExhausted otherwise. That is a client-side default, not something SNI imposes -- SNI already allows 100MB inbound. freeze_test.go hunts for a stalled transfer using the production write path, timing the gap between chunks rather than comparing bytes, and reports the worst gap even on success so a near miss is visible. usbstat_test.go and usbstat_probe_test.go read counters written by an instrumented firmware build, and attribute dropped packets to commands rather than to bulk data. putfile_test.go now distinguishes a write that stored the wrong bytes from a read that returned them wrongly, by reading the file back twice: a single comparison cannot tell those apart, and they have different causes. device_test.go wires the SNI_* environment variables into the test binary. Test binaries never call config.Load(), so those settings were silently inert and any config-dependent result would have been meaningless. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01ARLkt3NCnrwBMvpP8eAfDR --- cmd/snitest/main.go | 173 ++++++++++++++++++ devices/snes/drivers/fxpakpro/device_test.go | 5 + devices/snes/drivers/fxpakpro/freeze_test.go | 112 ++++++++++++ devices/snes/drivers/fxpakpro/putfile_test.go | 40 +++- .../drivers/fxpakpro/usbstat_probe_test.go | 94 ++++++++++ devices/snes/drivers/fxpakpro/usbstat_test.go | 45 +++++ 6 files changed, 467 insertions(+), 2 deletions(-) create mode 100644 cmd/snitest/main.go create mode 100644 devices/snes/drivers/fxpakpro/freeze_test.go create mode 100644 devices/snes/drivers/fxpakpro/usbstat_probe_test.go create mode 100644 devices/snes/drivers/fxpakpro/usbstat_test.go diff --git a/cmd/snitest/main.go b/cmd/snitest/main.go new file mode 100644 index 0000000..402822f --- /dev/null +++ b/cmd/snitest/main.go @@ -0,0 +1,173 @@ +// Command snitest drives SNI over gRPC the way a file-transfer client does, to +// reproduce transfer failures through the whole daemon stack rather than by +// calling the driver directly. +// +// Every hardware test in this repo talks to the fxpakpro driver in-process, +// which skips the gRPC server, autoCloseableDevice, and the daemon's goroutine +// scheduling. The reported freeze happened through that stack, so this exists +// to exercise it: ListDevices, then MakeDirectory for each path component, +// PutFile, then ReadDirectory -- the sequence SNFM issues. +// +// PutFile is unary and blocking with no progress reporting, so a stalled +// transfer shows up here the same way it does for a user: the call simply does +// not return. Each call is therefore timed and reported. +package main + +import ( + "context" + "flag" + "fmt" + "log" + "os" + "strconv" + "strings" + "time" + + "google.golang.org/grpc" + "google.golang.org/grpc/credentials/insecure" + + "sni/protos/sni" +) + +func main() { + addr := flag.String("addr", "localhost:8191", "SNI gRPC address") + dir := flag.String("dir", "unittest-grpc/sub", "directory to upload into") + size := flag.Int("size", 4*1024*1024, "payload size in bytes") + iterations := flag.Int("n", 20, "iterations") + timeout := flag.Duration("timeout", 0, "per-call deadline; 0 means none") + skipGet := flag.Bool("skipget", false, "skip GetFile verification (isolate the upload path)") + skipLs := flag.Bool("skipls", false, "skip ReadDirectory") + lsMissing := flag.Bool("lsmissing", false, + "ReadDirectory a path that does not exist before each PutFile") + flag.Parse() + + // A 4 MiB file plus protobuf framing exceeds gRPC's default 4MB receive + // cap, so GetFile fails with ResourceExhausted unless this is raised. Worth + // knowing for any client that reads whole ROMs back. + const maxMsg = 64 * 1024 * 1024 + conn, err := grpc.NewClient(*addr, + grpc.WithTransportCredentials(insecure.NewCredentials()), + grpc.WithDefaultCallOptions( + grpc.MaxCallRecvMsgSize(maxMsg), + grpc.MaxCallSendMsgSize(maxMsg), + )) + if err != nil { + log.Fatalf("dial %s: %v", *addr, err) + } + defer conn.Close() + + devices := sni.NewDevicesClient(conn) + fsys := sni.NewDeviceFilesystemClient(conn) + + // find a device + ctx, cancel := context.WithTimeout(context.Background(), 10*time.Second) + list, err := devices.ListDevices(ctx, &sni.DevicesRequest{}) + cancel() + if err != nil { + log.Fatalf("ListDevices: %v", err) + } + if len(list.GetDevices()) == 0 { + log.Fatalf("no devices found; is a device connected and SNI running?") + } + uri := list.GetDevices()[0].GetUri() + log.Printf("device: %s (%s)", uri, list.GetDevices()[0].GetDisplayName()) + + // deterministic payload: each 4-byte word holds its own offset, so a + // mismatch reports how far the data shifted + payload := make([]byte, *size) + for i := 0; i+4 <= len(payload); i += 4 { + payload[i] = byte(i) + payload[i+1] = byte(i >> 8) + payload[i+2] = byte(i >> 16) + payload[i+3] = byte(i >> 24) + } + + call := func(name string, fn func(context.Context) error) time.Duration { + ctx := context.Background() + var cancel context.CancelFunc + if *timeout > 0 { + ctx, cancel = context.WithTimeout(ctx, *timeout) + defer cancel() + } + start := time.Now() + err := fn(ctx) + d := time.Since(start) + if err != nil { + log.Printf(" %-16s FAILED after %v: %v", name, d.Round(time.Millisecond), err) + os.Exit(1) + } + return d + } + + // MakeDirectory for each path component, as SNFM does + parts := strings.Split(*dir, "/") + for i := range parts { + p := strings.Join(parts[:i+1], "/") + ctx, cancel := context.WithTimeout(context.Background(), 10*time.Second) + _, err := fsys.MakeDirectory(ctx, &sni.MakeDirectoryRequest{Uri: uri, Path: p}) + cancel() + if err != nil { + log.Printf(" mkdir %-20s %v (continuing; it may already exist)", p, err) + } + } + + path := *dir + "/grpc-test.bin" + log.Printf("uploading %d bytes to %s, %d iterations", *size, path, *iterations) + + var worst time.Duration + for i := 1; i <= *iterations; i++ { + // A client that checks whether a folder exists before creating it will + // LS a missing path and get an error back. The firmware commits to a + // data phase for LS regardless, and still emits the block holding the + // 0xFF terminator on the error path, so a client that returns on the + // error code leaves it unread and every command afterwards is one block + // out of step. This reproduces that sequence deliberately. + if *lsMissing { + lctx, lcancel := context.WithTimeout(context.Background(), 20*time.Second) + _, lerr := fsys.ReadDirectory(lctx, &sni.ReadDirectoryRequest{ + Uri: uri, Path: "unittest-no-such-dir-" + strconv.Itoa(i)}) + lcancel() + if lerr == nil { + log.Printf("[%2d] ReadDirectory of a missing path unexpectedly succeeded", i) + } + } + + put := call("PutFile", func(ctx context.Context) error { + _, err := fsys.PutFile(ctx, &sni.PutFileRequest{Uri: uri, Path: path, Data: payload}) + return err + }) + var ls time.Duration + if !*skipLs { + ls = call("ReadDirectory", func(ctx context.Context) error { + _, err := fsys.ReadDirectory(ctx, &sni.ReadDirectoryRequest{Uri: uri, Path: *dir}) + return err + }) + } + var get time.Duration + if !*skipGet { + get = call("GetFile", func(ctx context.Context) error { + rsp, err := fsys.GetFile(ctx, &sni.GetFileRequest{Uri: uri, Path: path}) + if err != nil { + return err + } + data := rsp.GetData() + if len(data) != len(payload) { + return fmt.Errorf("read back %d bytes, sent %d", len(data), len(payload)) + } + for j := range payload { + if data[j] != payload[j] { + return fmt.Errorf("contents differ at offset %d: got %02x want %02x", + j, data[j], payload[j]) + } + } + return nil + }) + } + if put > worst { + worst = put + } + log.Printf("[%2d] PutFile %v ReadDirectory %v GetFile+verify %v", + i, put.Round(time.Millisecond), ls.Round(time.Millisecond), get.Round(time.Millisecond)) + } + log.Printf("completed %d iterations; slowest PutFile %v", *iterations, worst.Round(time.Millisecond)) +} diff --git a/devices/snes/drivers/fxpakpro/device_test.go b/devices/snes/drivers/fxpakpro/device_test.go index 3cb0d2c..26084b8 100644 --- a/devices/snes/drivers/fxpakpro/device_test.go +++ b/devices/snes/drivers/fxpakpro/device_test.go @@ -20,9 +20,14 @@ func init() { // settings without dragging in the rest of the config bootstrap and its // filesystem side effects. for _, key := range []string{ + // "debug" enables the driver's per-chunk hex dumps, which is what + // SNI_DEBUG=1 does in the daemon. Wired up here so its timing cost can + // be measured against the chunk-delay knob. + "debug", "fxpakpro_read_timeout", "fxpakpro_write_timeout", "fxpakpro_honor_caller_deadline", + "fxpakpro_chunk_delay", } { if v := os.Getenv("SNI_" + strings.ToUpper(key)); v != "" { config.Config.Set(key, v) diff --git a/devices/snes/drivers/fxpakpro/freeze_test.go b/devices/snes/drivers/fxpakpro/freeze_test.go new file mode 100644 index 0000000..a19940f --- /dev/null +++ b/devices/snes/drivers/fxpakpro/freeze_test.go @@ -0,0 +1,112 @@ +package fxpakpro + +import ( + "bytes" + "context" + "fmt" + "os" + "strconv" + "testing" + "time" +) + +// TestDevice_freezeHunt looks for the reported symptom: SNI hanging during a +// PutFile because the device stopped draining its USB OUT endpoint. +// +// That is what the end user saw. gRPC PutFile is unary and blocking with no +// progress reporting, so a stalled write presents simply as SNI freezing. It +// was captured once as a goroutine sitting 29 minutes inside WriteFile, but +// every reproduction so far has been on a card with no free space, which is not +// the reporter's situation. This hunts for it with space available. +// +// The write timeout now turns such a stall into an error rather than a hang, so +// what this looks for is that error, plus any chunk that took implausibly long +// without failing outright -- a near miss is as interesting as a stall. +func TestDevice_freezeHunt(t *testing.T) { + size := uint32(4 * 1024 * 1024) + if v := os.Getenv("SNI_TEST_XFER_SIZE"); v != "" { + n, err := strconv.ParseUint(v, 0, 32) + if err != nil { + t.Fatalf("SNI_TEST_XFER_SIZE=%q: %v", v, err) + } + size = uint32(n) + } + iterations := 40 + if v := os.Getenv("SNI_TEST_ITERATIONS"); v != "" { + n, err := strconv.Atoi(v) + if err != nil { + t.Fatalf("SNI_TEST_ITERATIONS=%q: %v", v, err) + } + iterations = n + } + // report any chunk slower than this; the worst seen on a healthy card is + // around 130ms, so anything far above it is heading toward a stall + stallWarn := 2 * time.Second + if v := os.Getenv("SNI_TEST_STALL_WARN"); v != "" { + d, err := time.ParseDuration(v) + if err != nil { + t.Fatalf("SNI_TEST_STALL_WARN=%q: %v", v, err) + } + stallWarn = d + } + + d := openExactDevice(t) + defer d.Close() + ctx := context.Background() + + const dir = "unittest-freeze" + if err := d.mkdir(ctx, dir); err != nil { + if _, lserr := d.listFiles(ctx, dir); lserr != nil { + t.Fatalf("mkdir(%s): %v (and it does not exist: %v)", dir, err, lserr) + } + } + path := dir + "/freeze.bin" + t.Cleanup(func() { + if err := d.rm(context.Background(), path); err != nil { + t.Logf("cleanup: rm(%s): %v", path, err) + } + }) + + payload := filePattern(0x3c3c3c3c, size) + t.Logf("%d iterations of %d bytes, warning on any chunk over %v", + iterations, size, stallWarn) + + var worst time.Duration + var worstAt uint32 + start := time.Now() + + for i := 1; i <= iterations; i++ { + // progress callback lets us time the gap between chunks without + // replacing the production write path, which is the point: this must + // exercise sendSerialProgress exactly as PutFile does. + last := time.Now() + var slow []string + progress := func(sent, total uint32) { + if gap := time.Since(last); gap > stallWarn { + slow = append(slow, fmt.Sprintf("%v at offset %d", gap.Round(time.Millisecond), sent)) + } else if gap > worst { + worst, worstAt = gap, sent + } + last = time.Now() + } + + iterStart := time.Now() + n, err := d.putFile(ctx, path, size, bytes.NewReader(payload), progress) + iterDur := time.Since(iterStart) + + if err != nil { + t.Fatalf("FROZE on iteration %d after %v (%v total): sent %d of %d: %v", + i, iterDur, time.Since(start), n, size, err) + } + for _, s := range slow { + t.Errorf("iteration %d: STALL %s", i, s) + } + if i%5 == 0 { + t.Logf("iteration %2d ok (%v, worst inter-chunk gap so far %v at offset %d)", + i, iterDur.Round(time.Millisecond), worst.Round(time.Millisecond), worstAt) + } + } + + t.Logf("survived %d iterations in %v; worst inter-chunk gap %v at offset %d", + iterations, time.Since(start).Round(time.Second), worst.Round(time.Millisecond), worstAt) +} diff --git a/devices/snes/drivers/fxpakpro/putfile_test.go b/devices/snes/drivers/fxpakpro/putfile_test.go index 28606f1..5bfa3ec 100644 --- a/devices/snes/drivers/fxpakpro/putfile_test.go +++ b/devices/snes/drivers/fxpakpro/putfile_test.go @@ -192,8 +192,36 @@ func verifyFile(t *testing.T, d *Device, ctx context.Context, path string, expec if received != uint32(len(expected)) { t.Fatalf("getFile() received %d bytes, want %d", received, len(expected)) } - if actual := w.Bytes(); !bytes.Equal(actual, expected) { - t.Fatalf("%s", describeMismatch(actual, expected)) + actual := w.Bytes() + if bytes.Equal(actual, expected) { + return + } + + first := describeMismatch(actual, expected) + + // Read it back a second time. If both reads agree with each other but differ + // from what was sent, the file on the card is genuinely wrong and the PUT + // corrupted it. If the two reads differ, the GET is what is unreliable and + // the stored file may be fine. These have very different causes, and one + // comparison cannot tell them apart. + var w2 bytes.Buffer + w2.Grow(len(expected)) + received2, err2 := d.getFile(ctx, path, &w2, nil, nil) + if err2 != nil { + t.Fatalf("%s\n (second read to classify it failed: %v)", first, err2) + } + + second := w2.Bytes() + switch { + case bytes.Equal(second, expected): + t.Fatalf("READ CORRUPTION: first read differed, second read was correct\n"+ + " first read: %s\n received %d then %d bytes", first, len(actual), received2) + case bytes.Equal(second, actual): + t.Fatalf("WRITE CORRUPTION: both reads agree with each other but differ "+ + "from what was sent, so the file on the card is wrong\n %s", first) + default: + t.Fatalf("UNSTABLE: three different results\n read 1 vs sent: %s\n"+ + " read 2 vs sent: %s", first, describeMismatch(second, expected)) } } @@ -411,11 +439,19 @@ func putFileInstrumented(t *testing.T, d *Device, ctx context.Context, path stri wStart := time.Now() for len(p) > 0 { + want := len(p) n, err := d.f.Write(p) if err != nil { t.Fatalf("write at offset %d (%d chunks in, %v elapsed): %v", off, off/512, time.Since(start), err) } + // A short write here is worth knowing about. Resuming at p[n:] + // duplicates bytes if the driver transmitted more than it reported, + // which would look exactly like the block-duplication seen in this + // test but not in the production path. + if n != want { + t.Logf("SHORT WRITE at offset %d: wrote %d of %d", off, n, want) + } p = p[n:] } timings = append(timings, chunkTiming{offset: off, dur: time.Since(wStart)}) diff --git a/devices/snes/drivers/fxpakpro/usbstat_probe_test.go b/devices/snes/drivers/fxpakpro/usbstat_probe_test.go new file mode 100644 index 0000000..689c150 --- /dev/null +++ b/devices/snes/drivers/fxpakpro/usbstat_probe_test.go @@ -0,0 +1,94 @@ +package fxpakpro + +import ( + "bytes" + "context" + "os" + "strconv" + "strings" + "testing" + "time" +) + +// TestDevice_usbstatProbe clears the firmware's counters file, runs a chosen +// workload, then reads the counters back, so drops can be attributed to +// commands rather than to bulk data. +// +// SNI_TEST_PROBE selects the workload: +// +// info - N INFO commands: pure command traffic, no data phase +// put - one PutFile of SNI_TEST_XFER_SIZE: one command, thousands of +// 512-byte data blocks +// +// If drops scale with the number of commands they happen at the command +// boundary; if they scale with data volume they happen during the transfer. +// Note the bookkeeping calls (rm, ls, get) are themselves commands and are +// included in the totals. +func TestDevice_usbstatProbe(t *testing.T) { + probe := os.Getenv("SNI_TEST_PROBE") + if probe == "" { + t.Skip("set SNI_TEST_PROBE to info or put") + } + n := 10 + if v := os.Getenv("SNI_TEST_ITERATIONS"); v != "" { + var err error + if n, err = strconv.Atoi(v); err != nil { + t.Fatalf("SNI_TEST_ITERATIONS=%q: %v", v, err) + } + } + size := uint32(4 * 1024 * 1024) + if v := os.Getenv("SNI_TEST_XFER_SIZE"); v != "" { + u, err := strconv.ParseUint(v, 0, 32) + if err != nil { + t.Fatalf("SNI_TEST_XFER_SIZE=%q: %v", v, err) + } + size = uint32(u) + } + + d := openExactDevice(t) + defer d.Close() + ctx := context.Background() + + if err := d.rm(ctx, "sd2snes/usbstat.txt"); err != nil { + t.Logf("clear counters: %v (file may not exist yet)", err) + } + + switch probe { + case "info": + t.Logf("workload: %d INFO commands (no data phase)", n) + for i := 0; i < n; i++ { + if _, _, _, err := d.info(ctx); err != nil { + t.Fatalf("info %d: %v", i, err) + } + } + case "put": + t.Logf("workload: one PutFile of %d bytes (%d data blocks)", size, size/512) + payload := filePattern(0x11223344, size) + if err := d.mkdir(ctx, "unittest"); err != nil { + t.Logf("mkdir: %v (assuming exists)", err) + } + if _, err := d.putFile(ctx, "unittest/usbstat-probe.bin", size, + bytes.NewReader(payload), nil); err != nil { + t.Fatalf("putFile: %v", err) + } + default: + t.Fatalf("SNI_TEST_PROBE=%q: want info or put", probe) + } + + // give the firmware an idle pass to flush, then read the counters + time.Sleep(500 * time.Millisecond) + for i := 0; i < 3; i++ { + _, _, _, _ = d.info(ctx) + } + + var w bytes.Buffer + if _, err := d.getFile(ctx, "sd2snes/usbstat.txt", &w, nil, nil); err != nil { + t.Logf("no counters file: %v (no drop was recorded)", err) + return + } + for _, line := range strings.Split(strings.TrimRight(w.String(), "\x00\n"), "\n") { + if line != "" { + t.Logf(" %s", line) + } + } +} diff --git a/devices/snes/drivers/fxpakpro/usbstat_test.go b/devices/snes/drivers/fxpakpro/usbstat_test.go new file mode 100644 index 0000000..487c80a --- /dev/null +++ b/devices/snes/drivers/fxpakpro/usbstat_test.go @@ -0,0 +1,45 @@ +package fxpakpro + +import ( + "bytes" + "context" + "strings" + "testing" +) + +// TestDevice_usbstat reads /sd2snes/usbstat.txt, written by the instrumented +// firmware when CDC_BulkOut drops an already-ACKed packet because the server +// was busy. The file only exists once a drop has happened: usbstat_dirty is set +// solely on the drop path, so absence means no drop has ever been recorded. +func TestDevice_usbstat(t *testing.T) { + d := openExactDevice(t) + defer d.Close() + ctx := context.Background() + + files, err := d.listFiles(ctx, "sd2snes") + if err != nil { + t.Fatalf("ls(sd2snes): %v", err) + } + var found bool + for _, f := range files { + if f.Name == "usbstat.txt" { + found = true + } + } + if !found { + t.Logf("usbstat.txt does not exist: no packet drop has been recorded") + return + } + + var w bytes.Buffer + n, err := d.getFile(ctx, "sd2snes/usbstat.txt", &w, nil, nil) + if err != nil { + t.Fatalf("getFile(usbstat.txt): %v", err) + } + t.Logf("usbstat.txt is %d bytes:", n) + for _, line := range strings.Split(strings.TrimRight(w.String(), "\x00\n"), "\n") { + if line != "" { + t.Logf(" %s", line) + } + } +} From 4c7002c53a7a969c2f3e23464ccc2a48af42f2ab Mon Sep 17 00:00:00 2001 From: CVW-HMB Date: Sun, 13 Sep 2026 19:09:29 -0700 Subject: [PATCH 12/12] macos: disable App Nap so the tray process keeps servicing USB SNI presents only a status-bar (tray) icon with no window, so macOS is free to place it under App Nap while a game is in the foreground. App Nap throttles and coalesces a background app's timers and threads; a napped SNI stops servicing the FX Pak Pro's USB serial stream promptly, so the device appears to stop responding (reads return zero bytes, writes stall) until SNI is restarted. This matches field reports of the connection dying after some minutes of play on macOS while the identical setup is stable on Windows, which has no equivalent throttling. Take a process-level NSProcessInfo activity assertion (NSActivityUserInitiatedAllowingIdleSystemSleep) for the lifetime of the process. That keeps SNI out of App Nap while still letting the machine sleep normally when the user walks away. The assertion is held in a new cmd/sni/power package behind a build tag; it is a no-op on non-darwin platforms. This complements the fxpakpro desync/timeout fixes on this branch: those let SNI survive and reconnect after the device wedges, while this keeps the background process from being throttled into that state in the first place. Co-Authored-By: Claude Opus 4.8 Claude-Session: https://claude.ai/code/session_01RVRWxcANar3DxSRTsvPPMu --- cmd/sni/main.go | 6 +++++ cmd/sni/power/appnap_darwin.go | 43 ++++++++++++++++++++++++++++++++++ cmd/sni/power/appnap_other.go | 6 +++++ 3 files changed, 55 insertions(+) create mode 100644 cmd/sni/power/appnap_darwin.go create mode 100644 cmd/sni/power/appnap_other.go diff --git a/cmd/sni/main.go b/cmd/sni/main.go index a79aacd..3bc1cde 100644 --- a/cmd/sni/main.go +++ b/cmd/sni/main.go @@ -10,6 +10,7 @@ import ( "sni/cmd/sni/appversion" "sni/cmd/sni/config" "sni/cmd/sni/logging" + "sni/cmd/sni/power" "sni/cmd/sni/tray" "sni/devices/snes/drivers/emunwa" "sni/devices/snes/drivers/fxpakpro" @@ -39,6 +40,11 @@ func main() { // keep the initial goroutine on this thread for GUI threading purposes runtime.LockOSThread() + // on macOS, keep this window-less tray process out of App Nap so it keeps + // servicing USB devices promptly instead of being throttled in the + // background (no-op on other platforms): + power.DisableAppNap("SNI maintains real-time communication with SNES devices") + // make the version info public in the appversion package because the main package cannot be imported: appversion.Init( version, diff --git a/cmd/sni/power/appnap_darwin.go b/cmd/sni/power/appnap_darwin.go new file mode 100644 index 0000000..22066c6 --- /dev/null +++ b/cmd/sni/power/appnap_darwin.go @@ -0,0 +1,43 @@ +//go:build darwin + +package power + +/* +#cgo darwin CFLAGS: -x objective-c -fobjc-arc +#cgo darwin LDFLAGS: -framework Foundation +#include +#import + +// beginActivity takes a process-level activity assertion and retains the +// returned token so the assertion lives for the entire lifetime of the +// process. The token is intentionally never released; the OS drops it when +// the process exits. +static void beginActivity(const char *reason) { + NSString *r = [NSString stringWithUTF8String:reason]; + // NSActivityUserInitiatedAllowingIdleSystemSleep disables App Nap so this + // background, window-less process keeps servicing USB promptly, while still + // allowing the machine to sleep normally when the user walks away. + NSActivityOptions opts = NSActivityUserInitiatedAllowingIdleSystemSleep; + id token = [[NSProcessInfo processInfo] beginActivityWithOptions:opts reason:r]; + CFBridgingRetain(token); +} +*/ +import "C" + +import "unsafe" + +// DisableAppNap asks macOS to keep this process out of App Nap for its entire +// lifetime. +// +// App Nap throttles and coalesces the timers and threads of a background, +// window-less application. SNI presents only a status-bar (tray) icon with no +// window, so macOS is free to nap it while a game is in the foreground. A +// napped SNI stops servicing the FX Pak Pro's USB serial stream promptly, which +// makes the device appear to stop responding (reads return zero bytes, writes +// stall) until SNI is restarted. Holding a user-initiated activity assertion +// prevents that. +func DisableAppNap(reason string) { + cReason := C.CString(reason) + defer C.free(unsafe.Pointer(cReason)) + C.beginActivity(cReason) +} diff --git a/cmd/sni/power/appnap_other.go b/cmd/sni/power/appnap_other.go new file mode 100644 index 0000000..d625126 --- /dev/null +++ b/cmd/sni/power/appnap_other.go @@ -0,0 +1,6 @@ +//go:build !darwin + +package power + +// DisableAppNap is a no-op on platforms that do not have macOS App Nap. +func DisableAppNap(reason string) {}