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 diff --git a/cmd/sni/config/config.go b/cmd/sni/config/config.go index e186718..a8e308b 100644 --- a/cmd/sni/config/config.go +++ b/cmd/sni/config/config.go @@ -50,6 +50,27 @@ 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, + // 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", "retroarch_detect_log": false, @@ -64,8 +85,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 +112,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/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) {} 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/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/bootpath_test.go b/devices/snes/drivers/fxpakpro/bootpath_test.go new file mode 100644 index 0000000..280c79c --- /dev/null +++ b/devices/snes/drivers/fxpakpro/bootpath_test.go @@ -0,0 +1,121 @@ +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)") + } +} + +// 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") +} 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/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/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.go b/devices/snes/drivers/fxpakpro/device.go index c73f347..6e24282 100644 --- a/devices/snes/drivers/fxpakpro/device.go +++ b/devices/snes/drivers/fxpakpro/device.go @@ -2,18 +2,68 @@ package fxpakpro import ( "context" + "errors" "fmt" "go.bug.st/serial" + "log" "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). +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 { + 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 serial.Port - - isClosed bool + f *devicePort } func (d *Device) FatalError(cause error) devices.DeviceError { @@ -25,7 +75,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 +111,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/device_test.go b/devices/snes/drivers/fxpakpro/device_test.go index 4edd7cb..26084b8 100644 --- a/devices/snes/drivers/fxpakpro/device_test.go +++ b/devices/snes/drivers/fxpakpro/device_test.go @@ -2,12 +2,38 @@ 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{ + // "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) + } + } + DriverInit() } @@ -155,3 +181,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.go b/devices/snes/drivers/fxpakpro/driver.go index 307ccdc..660d961 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" @@ -11,6 +12,7 @@ import ( "strconv" "strings" "sync" + "time" "go.bug.st/serial" "go.bug.st/serial/enumerator" @@ -139,16 +141,24 @@ 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 } 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,9 +172,73 @@ 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 } +// 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: @@ -199,7 +273,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 +314,50 @@ 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") + } + 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, chunk delay %v\n", + driverName, noDataTimeout, writeTimeout, honorCallerDeadline, chunkDelay) +} 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/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/get.go b/devices/snes/drivers/fxpakpro/get.go index 5109608..cdb7124 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 @@ -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/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/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/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/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/put.go b/devices/snes/drivers/fxpakpro/put.go index c4fd041..d370d35 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 @@ -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 } 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/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..5bfa3ec 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,459 @@ 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)) + } + 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)) + } +} + +// 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 { + 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)}) + } + 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/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/sendserial_test.go b/devices/snes/drivers/fxpakpro/sendserial_test.go new file mode 100644 index 0000000..51f04ac --- /dev/null +++ b/devices/snes/drivers/fxpakpro/sendserial_test.go @@ -0,0 +1,222 @@ +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) + } +} + +// 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 1b6a4d6..2dc3634 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,34 @@ 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 + + // 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) { ctx, task := trace.NewTask(ctx, "readExactGeneric") defer task.End() @@ -57,12 +86,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 +109,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 +143,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 +163,138 @@ 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) { + // 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 + } + // 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) + } + }() + } +} + +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 +302,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 +326,16 @@ 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 + } + if chunkDelay > 0 { + time.Sleep(chunkDelay) + } } // transfer any remainder: @@ -228,6 +360,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: diff --git a/devices/snes/drivers/fxpakpro/stress_test.go b/devices/snes/drivers/fxpakpro/stress_test.go new file mode 100644 index 0000000..bf5159e --- /dev/null +++ b/devices/snes/drivers/fxpakpro/stress_test.go @@ -0,0 +1,460 @@ +package fxpakpro + +import ( + "bytes" + "context" + "encoding/binary" + "encoding/hex" + "fmt" + "math/rand" + "os" + "strconv" + "strings" + "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) + } + } + + // 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. + // 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))] + 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) + } + // 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) + } + } + + doRm := func() { + if len(live) == 0 { + doPut() + return + } + 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++ { + 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)) + } + } + 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) + } +} 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) + } + } +}