Roflin/rebbarb
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

fsp-server: log the transaction id and retry counter, add --trace

Browse Source 
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 <noreply@anthropic.com>
This commit is contained in:
Dennis Brentjes
2026-10-10 16:20:23 +02:00
parent cb0df55699
commit e56f21341a
1 changed files with 38 additions and 15 deletions
Download Patch File Download Diff File Expand all files Collapse all files
scripts/fsp-server.py
+38 -15
View File
@@ -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__":