fxpakpro: fix protocol desyncs and unbounded I/O that wedge the device by JamesDunne · Pull Request #57 · alttpo/sni

JamesDunne · 2026-08-28T19:05:44Z

Summary

Chasing a user report of a 4 MiB PutFile failing part way through — with SNI
then appearing to freeze — turned up several distinct problems in the fxpakpro
driver. All were confirmed against real hardware (sd2snes Mk.III) on Windows, where the
failures reproduce; macOS ran ~13,000 operations clean throughout. Every finding
was then re-confirmed on stock firmware 1.11.2, and the firmware source
cited below is the v1.11.2 tag.

The original theory was that the host was outrunning the device and needed
sleeps between chunks. That turned out to be wrong and the measurements
ruled it out early: throughput is identical whether SNI writes 512 bytes or
64 KiB per call (445 KiB/s either way), because the host is already blocked on
USB NAKs. Inter-chunk sleeps would have changed nothing on the wire.

Root cause

The firmware commits to a data phase before it knows whether the command
succeeded, and SNI returned the moment it saw an error code — abandoning the
device mid-transaction.

trigger	firmware behaviour	fixable in SNI?
`LS` of a missing directory	still emits a block holding the `0xFF` terminator	yes — drain it
`PUT` to a missing directory	`cmdDat=1` set before `f_open`; parks in `HANDLE_LOCK` awaiting the payload, then eats the next command as file data	yes — fatal error forces a reconnect in the one command of slack the firmware allows
`GET` of a missing file	spins in `usbint_handler_dat` on a size read from a `FILINFO` a failed `f_stat` never wrote	no — firmware hang
`PUT` onto a full card	`f_write` returns `FR_OK` with zero bytes written; `bytesRecv`/`count` never advance, spinning inside the USB ISR	no — but now reported promptly

The last one is the user's bug, reproduced deterministically: filling the card
and then writing a 4 MiB file stalls at 3719680 of 4194304 bytes, with no
error code for the host to see, and needs a physical power cycle.

Changes

ls.go — drain the terminator block on a failed listing
putfile.go — command errors are fatal, so autoCloseableDevice
reconnects before the device consumes the next command as file data
(verified: 46 ms recovery for a sequence that previously bricked the pak)
getfile.go — fatal with an explanatory message; not recoverable
serial.go — writes are bounded (they were not: go.bug.st/serial sets
WriteTotalTimeoutConstant: 0 on Windows and exposes no SetWriteTimeout,
so a device that stopped draining hung the caller while holding d.lock —
caught in a goroutine dump sitting 29 minutes inside WriteFile). Abandoning
a write closes the port so the orphaned goroutine cannot interleave with the
next command. Also fixes sendSerialProgress discarding writeExact's error,
and replaces the read attempt-counter with an elapsed-time budget.
driver.go — flush stale buffers on open; stop walking all 14 baud rates
on errors unrelated to speed (~8 minutes → 35 s against a wedged device)
device.go — any port close marks the device closed; Init's hardcoded
2 s budget follows the configured read timeout now that it bounds writes too
config.go — fxpakpro_read_timeout, fxpakpro_write_timeout,
fxpakpro_honor_caller_deadline
get.go / put.go — audited every command for whether an error code
leaves the stream clean. What decides it is the firmware's own next-state
choice, made by opcode before it knows the outcome: GET/VGET/LS →
HANDLE_DAT, PUT/VPUT → HANDLE_LOCK, everything else → IDLE. So
fatality follows whether a data phase is pending, not how severe the error
sounds. mkdir, rm, mv, boot, reset, menu_reset and info all land
in IDLE and correctly stay non-fatal — error code 1 from mkdir usually
just means the directory already exists. get and put were the two that
did not match and are now fatal.

A bug in the fix, caught by soaking

abandonPort originally closed the port synchronously. A Write stuck because
the device stopped draining 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, triggering exactly when the timeout was meant to rescue it:

goroutine 23 [syscall]:
  fxpakpro.(*devicePort).Close
  fxpakpro.abandonPort
  fxpakpro.writeWithTimeout
  fxpakpro.writeExact
  fxpakpro.(*Device).putFile

Windows never showed this, because the close there did not block. It took a
macOS soak sitting for minutes on 0.04s of CPU to surface it. devicePort now
marks itself unusable and closes in the background, refuses writes once marked,
and has an idempotent Close so ensureOpened cannot block behind the same
stuck write.

Validation on hardware

	system menu	in-game
macOS	8,000 ops (SRAM writes)	12,000 ops (WRAM writes via USB EXE)
Windows	soaked	soaked

Re-verified on stock 1.11.2 after updating from a customised build, to rule out
the local modifications being involved. Identical behaviour in all three:

	custom 1.11.0-iovm6	stock 1.11.2
menu soak, 8000 ops	PASS 5m24s	PASS 5m46s
failed PUT, with the fix	recovered in 46ms	recovered in 46ms
failed PUT, without it	desyncs, then wedges	desyncs, then wedges
disk full mid-transfer	stalled at 3719680/4194304	stalled at 4096/4194304

Every command exercised against a real sd2snes Mk.III:
GET/PUT/LS/MKDIR/RM/INFO/BOOT, VGET at tracker polling rates, and VPUT to both
SRAM (direct) and WRAM (through the 65816 copy routine driven over the USB EXE
hook, which only works with a game running).

Incidental measurement worth recording: the same mix runs at ~100 ops/sec
in-game against ~25 ops/sec in the system menu, because menu_main_loop sleeps
20ms per usbint_handler() call while the in-game loop does not. A pak sitting
in the menu — where SNFM users upload from — services USB only about 50 times a
second.

Tests

Unit tests need no hardware; the rest skip when no fxpakpro is attached.
stress_test.go interleaves filesystem and memory operations in a seeded random
order at sizes off the 512-byte block boundary, replayable via SNI_TEST_SEED.
errorpath_test.go checks each error path leaves the stream aligned.
diskfull_test.go reproduces the mid-transfer stall on demand. The mix is
configurable via SNI_TEST_WEIGHTS, and memory writes can target SRAM or WRAM
via SNI_TEST_MEM_SPACE.

What this does not do

It does not stop the device wedging. The two firmware hangs are not
preventable from the host; these changes convert a silent indefinite freeze into
a prompt error naming the byte offset, and stop one dead device blocking every
other request for it.

Measured with instrumented firmware

A build of 1.11.2 with counters in CDC_BulkOut was used to test whether the
firmware silently discards packets, which was the leading suspect for the
freeze while this branch was being written. It does not:

	macOS	Windows
`CDC_BulkOut` calls	255,937	4,261,344
bytes	13.4 MB	272.7 MB
packets dropped	3,236	0
zero-length packets	43,168	0
dropped packets containing data	0	0

CDC_BulkOut() returns without reading the endpoint when the server is busy,
and since the endpoint interrupt is already cleared and CMD_CLR_BUF only runs
inside USB_ReadEP(), such a packet is discarded. That path is real, but it is
benign: it only ever fires at a command boundary and only ever on the
zero-length packet that follows a command write. Not one dropped packet has
ever contained data, and on Windows it never fires at all because that stack
does not emit the trailing ZLPs macOS does.

So the freeze is not caused by the firmware discarding data, and none of the
fixes here depend on that being the mechanism.

A separate firmware bug found along the way

A slow reader stalls GetFile: the device sends a partial block and stops. It
is intermittent rather than debug-only -- roughly 1 failure in 48 downloads with
SNI_DEBUG=0, and about 1 in 2 with SNI_DEBUG=1, which slows the reader by
hex-dumping every 512-byte read. Seen on both v0.0.103 and this branch, in menu
and in-game. The improved error message is what localises it -- no data from device for 15.1s after reading 384 of 512 bytes, where the old wording could
only say "timed out after 9 attempts of reading zero bytes". Not fixable from
the host; recorded here because the diagnostics are what make it visible.

Worth reporting upstream to the firmware, all small in principle: the
f_write/f_read loops should break when zero bytes move (note FatFs signals a
full card as FR_OK with a zero byte count, so checking only the FRESULT never
catches it); fi is a global
shared between f_stat in GET and f_readdir in LS; and recv_buffer_offset
is never reset in usbint_check_connect().

What this does not explain

The report that prompted the work was a PutFile that never returned, with SNI
appearing frozen. That specific failure was not reproduced, despite ~92
uploads of 4 MiB files across every configuration available: production
v0.0.103 and this branch, SNI_DEBUG on and off, system menu and in-game, with
and without the leading / that SNFM prepends to device paths, driven through
the real daemon over gRPC rather than by calling the driver directly.

SNI_DEBUG=1 also does not measurably change upload timing here (9.40s against
9.51s for 4 MiB), because writes are paced by USB NAKs rather than by the host,
so the reporter's observation that it made their transfers succeed has no
mechanism we have been able to measure.

What this branch does for that user is turn an indefinite hang into a prompt,
specific error naming the byte offset, and stop one stuck device from blocking
every other request for it. It does not claim to have fixed the trigger.

Caveat on one claim

The disk-full mechanism is solidly demonstrated. That it caused every earlier
intermittent wedge is not established — that rests on one clean 6000-op soak
with free space against a noisy full-card baseline (failures at ops 5, 330 and
2075, plus three clean runs). A few more soaks on a cleared card would settle it.

🤖 Generated with Claude Code

https://claude.ai/code/session_01ARLkt3NCnrwBMvpP8eAfDR

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 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01ARLkt3NCnrwBMvpP8eAfDR

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 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01ARLkt3NCnrwBMvpP8eAfDR

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 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01ARLkt3NCnrwBMvpP8eAfDR

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 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01ARLkt3NCnrwBMvpP8eAfDR

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 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01ARLkt3NCnrwBMvpP8eAfDR

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 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01ARLkt3NCnrwBMvpP8eAfDR

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 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01ARLkt3NCnrwBMvpP8eAfDR

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 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01ARLkt3NCnrwBMvpP8eAfDR

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 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01ARLkt3NCnrwBMvpP8eAfDR

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 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01ARLkt3NCnrwBMvpP8eAfDR

JamesDunne and others added 11 commits August 27, 2026 21:52

github: update actions; remove windows/arm build

9eeb955

Navigation Menu

Uh oh!

fxpakpro: fix protocol desyncs and unbounded I/O that wedge the device - #57

fxpakpro: fix protocol desyncs and unbounded I/O that wedge the device#57
JamesDunne wants to merge 11 commits into
mainfrom
fxpakpro-desync-and-timeout-fixes

JamesDunne commented Aug 28, 2026 •

edited

Loading

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

1 participant

Uh oh!

Conversation

JamesDunne commented Aug 28, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Summary

Root cause

Changes

A bug in the fix, caught by soaking

Validation on hardware

Tests

What this does not do

Measured with instrumented firmware

A separate firmware bug found along the way

What this does not explain

Caveat on one claim

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

1 participant

JamesDunne commented Aug 28, 2026 •

edited

Loading