From e56f21341a2b26a2c87da4dd7381a2a78afa95b7 Mon Sep 17 00:00:00 2001 From: Dennis Brentjes Date: Sat, 10 Oct 2026 16:20:23 +0200 Subject: [PATCH] fsp-server: log the transaction id and retry counter, add --trace Swiss is still stuck on "setting up device" and the log shows five identical GET_PRO lines -- but there was no way to tell whether that is ONE transaction being retried (our reply rejected or lost) or five separate transactions (Swiss looping at a higher level). Those have completely different causes and the log could not distinguish them. fsp_transaction puts a random value in seq & 0xfff8 per transaction and the retry counter in seq & 0x7: p->seq = (s->seq) | (retry & 0x7); so the split is the diagnostic. Every request now logs seq=0x.... [txn 0x.... try N]: same txn with climbing try means our reply is being rejected; different txn each time means the client gave up and restarted. --trace additionally hexdumps every request and reply with key/pos/len/xlen, so a reply can be verified by hand against fsp_pkt_read instead of trusted. All replies now go through one reply() helper rather than scattered sendto calls, which is what makes tracing them possible at all. Co-Authored-By: Claude Opus 5 --- scripts/fsp-server.py | 53 +++++++++++++++++++++++++++++++------------ 1 file changed, 38 insertions(+), 15 deletions(-) diff --git a/scripts/fsp-server.py b/scripts/fsp-server.py index e7fe4ec..884d732 100755 --- a/scripts/fsp-server.py +++ b/scripts/fsp-server.py @@ -167,6 +167,9 @@ def main(): ap.add_argument("--port", type=int, default=21) ap.add_argument("--quiet-reads", action="store_true", help="only log the rate, not every read") + ap.add_argument("--trace", action="store_true", + help="hexdump every request and reply, with the sequence " + "split into transaction id and retry counter") ap.add_argument("--claim-owner", action="store_true", help="report FSP_DIR_OWNER on GET_PRO, which makes Swiss " "enable FEAT_PATCHES and EMU_ETHERNET on this device. " @@ -187,6 +190,12 @@ def main(): print(f" password {'set' if a.password else 'NONE'}") print(f" point Swiss's FSP device at this host and port\n") + def reply(peer_, pkt_, what): + s.sendto(pkt_, peer_) + if a.trace: + print(f" -> {len(pkt_):4d} B {what}") + print(f" {pkt_[:48].hex()}") + served = 0 t_first = None t_report = time.time() @@ -203,14 +212,27 @@ def main(): print(f" ⚠️ bad checksum from {peer[0]}, cmd {r['cmd']:#04x}") cmd, seq, pos = r["cmd"], r["seq"], r["pos"] + # fsp_transaction puts a RANDOM value in seq & 0xfff8 per transaction + # and the RETRY COUNTER in seq & 0x7. So repeated requests with the + # same high bits and climbing low bits mean our reply was rejected or + # lost; different high bits mean the client gave up and started a new + # transaction. Without this you cannot tell those apart, which is + # exactly the hole that made "stuck on setting up device" opaque. + txn, try_n = seq & 0xFFF8, seq & 0x7 + tag = f"seq={seq:#06x}[txn {txn:#06x} try {try_n}]" + if a.trace: + print(f" <- {len(pkt):4d} B cmd {cmd:#04x} {tag} " + f"key={r['key']:#06x} pos={pos} len={len(r['data'])} " + f"xlen={len(r['extra'])} from {peer[0]}:{peer[1]}") + print(f" {pkt[:48].hex()}") if cmd == CC_VERSION: - s.sendto(pack(CC_VERSION, SERVER_KEY, seq, 0, - b"fsp-server (rebbarb)\0"), peer) + reply(peer, pack(CC_VERSION, SERVER_KEY, seq, 0, + b"fsp-server (rebbarb)\0"), "VERSION") print(f"[{peer[0]}] VERSION") continue if cmd == CC_BYE: - s.sendto(pack(CC_BYE, SERVER_KEY, seq, 0), peer) + reply(peer, pack(CC_BYE, SERVER_KEY, seq, 0), "BYE") print(f"[{peer[0]}] BYE") continue @@ -218,10 +240,10 @@ def main(): real = safe_join(root, path) if not pw_ok: print(f"[{peer[0]}] {cmd:#04x} {path!r} -> WRONG PASSWORD") - s.sendto(pack(CC_ERR, SERVER_KEY, seq, pos, b"bad password\0"), peer) + reply(peer, pack(CC_ERR, SERVER_KEY, seq, pos, b"bad password\0"), "ERR") continue if real is None: - s.sendto(pack(CC_ERR, SERVER_KEY, seq, pos, b"bad path\0"), peer) + reply(peer, pack(CC_ERR, SERVER_KEY, seq, pos, b"bad path\0"), "ERR") continue if cmd == CC_STAT: @@ -235,7 +257,7 @@ def main(): else: body = struct.pack("!IIB", 0, 0, 0) # type 0 == ENOENT print(f"[{peer[0]}] STAT {path!r} -> not found") - s.sendto(pack(CC_STAT, SERVER_KEY, seq, pos, body), peer) + reply(peer, pack(CC_STAT, SERVER_KEY, seq, pos, body), "STAT") continue if cmd == CC_GET_PRO: @@ -245,27 +267,28 @@ def main(): # A non-existent directory must be CC_ERR so fsplib reports # ENOENT: Swiss probes "swiss/patches", then "swiss", then "". if not os.path.isdir(real): - s.sendto(pack(CC_ERR, SERVER_KEY, seq, pos, b"no such dir\0"), peer) - print(f"[{peer[0]}] GET_PRO {path!r} -> ENOENT (expected; " + reply(peer, pack(CC_ERR, SERVER_KEY, seq, pos, b"no such dir\0"), "ERR") + print(f"[{peer[0]}] GET_PRO {path!r} {tag} -> ENOENT (expected; " f"Swiss falls back)") continue pro = PRO_GET | PRO_LIST | (PRO_OWNER if a.claim_owner else 0) - s.sendto(pack(CC_GET_PRO, SERVER_KEY, seq, PRO_BYTES, - path.encode("latin-1", "replace"), bytes([pro])), peer) - print(f"[{peer[0]}] GET_PRO {path!r} -> {pro:#04x}" + reply(peer, pack(CC_GET_PRO, SERVER_KEY, seq, PRO_BYTES, + path.encode("latin-1", "replace"), + bytes([pro])), "GET_PRO") + print(f"[{peer[0]}] GET_PRO {path!r} {tag} -> {pro:#04x}" + (" (OWNER: Swiss will enable patches)" if a.claim_owner else " (read-only: Swiss disables patches here)")) continue if cmd == CC_GET_DIR: if not os.path.isdir(real): - s.sendto(pack(CC_ERR, SERVER_KEY, seq, pos, b"not a dir\0"), peer) + reply(peer, pack(CC_ERR, SERVER_KEY, seq, pos, b"not a dir\0"), "ERR") continue blk = dir_block(real) # The client reads blocks until one comes back shorter than the # first; so the whole listing, then an empty reply. out = blk if pos == 0 else b"" - s.sendto(pack(CC_GET_DIR, SERVER_KEY, seq, pos, out), peer) + reply(peer, pack(CC_GET_DIR, SERVER_KEY, seq, pos, out), "GET_DIR") print(f"[{peer[0]}] GET_DIR {path!r} pos={pos} -> {len(out)} B") continue @@ -284,7 +307,7 @@ def main(): continue fh.seek(pos) data = fh.read(want) - s.sendto(pack(CC_GET_FILE, SERVER_KEY, seq, pos, data), peer) + reply(peer, pack(CC_GET_FILE, SERVER_KEY, seq, pos, data), "GET_FILE") served += len(data) reads += 1 now = time.time() @@ -303,7 +326,7 @@ def main(): continue print(f"[{peer[0]}] unsupported command {cmd:#04x} {path!r}") - s.sendto(pack(CC_ERR, SERVER_KEY, seq, pos, b"unsupported\0"), peer) + reply(peer, pack(CC_ERR, SERVER_KEY, seq, pos, b"unsupported\0"), "ERR") if __name__ == "__main__":