From e5bfe58fc8af5f399bb5a18f162c78292bc0f09d Mon Sep 17 00:00:00 2001 From: funman300 Date: Tue, 4 Aug 2026 11:28:42 -0700 Subject: [PATCH] fifa17-recon: futlog.py -- client-filtered log reader, and a correction it caught Implements the standing requirement recorded in priority-2026-08 S5: the User-Agent filter is now the DEFAULT in the log tooling, not an option. The real client sends ProtoHttp; our own probes send curl/* or Python-urllib/*. Reading the log unfiltered gave this project a materially wrong picture of itself (/clubUser and /user/list had 93 and 180 hits, none from the game). The old futlog.py was a one-off with a hardcoded path and no notion of who made the request. Replaced with a real tool: timeline or summary, body/response display, path regex, time window, status filter, and an --unmapped view that lists the endpoints the client wants and we catch-all. --all and --probes exist for when you deliberately want our own traffic. Over the full 3044-request history: 486 requests came from the game. IT IMMEDIATELY CAUGHT ME OVERSTATING SOMETHING. Yesterday's commit called the PUT /item request shape "captured for the first time (the client had never successfully reached this path)". False. There are NINE client PUT /item requests in the log, eight of them during the failed attempts, every one carrying swap and tradeId: 08:45:11 08:51:13 08:55:21 08:58:19 09:10:52 09:15:26 09:22:31 09:37:12 | 11:15:48 The request was on the wire and in the log the whole time. What was new was reading it. Same class of error as the truncated decompile in S16: evidence already collected and not looked at. REBUILD_RESEARCH S17 corrected. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01VUT92pz6RWKih9dSr8ZpxW --- fifa17-recon/docs/REBUILD_RESEARCH.md | 24 ++- fifa17-recon/tools/futlog.py | 252 +++++++++++++++++++++----- 2 files changed, 220 insertions(+), 56 deletions(-) diff --git a/fifa17-recon/docs/REBUILD_RESEARCH.md b/fifa17-recon/docs/REBUILD_RESEARCH.md index 1d12378..e1d78a9 100644 --- a/fifa17-recon/docs/REBUILD_RESEARCH.md +++ b/fifa17-recon/docs/REBUILD_RESEARCH.md @@ -679,17 +679,29 @@ wrong, and §16 explains exactly which truncated decompile produced it. Both defaults are flipped in `utas_server.py`: `FUT_MOVE_BODY=ack`, and `FUT_PACK_AUTOCLUB` now defaults **off**. -### New intel: the request shape - -Captured for the first time (the client had never successfully reached this path): +### The request shape ```json {"itemData":[{"id":100000125,"pile":"club","swap":0,"tradeId":0}, ...]} ``` -`swap` and `tradeId` accompany `id` and `pile`. We ignore both and the move -succeeded, so neither is load-bearing for a pending-pile-to-club move. `TODO/CONFIRM` -what `swap` means for a squad-slot exchange, where it plausibly is. +`swap` and `tradeId` accompany `id` and `pile`. We ignore both and the move succeeded, +so neither is load-bearing for a pending-pile-to-club move. `TODO/CONFIRM` what `swap` +means for a squad-slot exchange, where it plausibly is. + +**Correction to the first version of this section**, which called this shape "captured +for the first time" because "the client had never successfully reached this path". That +is wrong. `futlog.py` over the full history shows **nine** client `PUT /item` requests, +eight of them before today, all carrying `swap` and `tradeId`: + +``` +08:45:11 08:51:13 08:55:21 08:58:19 09:10:52 09:15:26 09:22:31 09:37:12 11:15:48 + the seven failed attempts the fix +``` + +The request was on the wire and in the log the entire time. What was new today was not +the capture, it was reading it. That is the same class of error as the truncated +decompile in §16: evidence already collected, not looked at. ### Process note, and it is not a small one diff --git a/fifa17-recon/tools/futlog.py b/fifa17-recon/tools/futlog.py index 009c4b5..3fa5c25 100644 --- a/fifa17-recon/tools/futlog.py +++ b/fifa17-recon/tools/futlog.py @@ -1,55 +1,207 @@ #!/usr/bin/env python3 -"""Summarise /tmp/utas_server.log since the last MARKER line: one row per request -(verb, path, status), plus the squad/massinfo detail lines. Keeps the transcript -small instead of dumping the raw log.""" -import re, sys, collections +"""Read the UTAS request log, FILTERED TO THE REAL CLIENT BY DEFAULT. -LOG = "/tmp/utas_server.log" -raw = open(LOG, errors="replace").read().splitlines() -# start after the last marker (or the last server banner) -start = 0 -for i, l in enumerate(raw): - if "=== MARKER" in l or "=== utas_server" in l: - start = i -lines = raw[start:] + futlog.py what the game asked for, one line each + futlog.py -v ... with request bodies and responses + futlog.py --all include our own curl/python probes + futlog.py --probes only our probes + futlog.py -s summary: request counts per endpoint + futlog.py --unmapped only requests that fell through to the catch-all + futlog.py -p item -v only paths matching a regex + futlog.py --since 11:15 only from that clock time onward -REQ = re.compile(r"^\[[\d:]+\] (GET|PUT|POST|DELETE|HEAD|PATCH) (\S+)") -RESP = re.compile(r"^\[[\d:]+\] -> (\d+) (.*)") -rows, counts, pending = [], collections.Counter(), None -notes = [] -for l in lines: - m = REQ.match(l) - if m: - pending = (m.group(1), m.group(2).split("?")[0], m.group(2)) - continue - m = RESP.match(l) - if m and pending: - rows.append((pending[0], pending[1], m.group(1), len(m.group(2)))) - counts[(pending[0], pending[1])] += 1 - pending = None - continue - if "UNMAPPED" in l or "SQUAD:" in l or "STORE:" in l or "MARKET:" in l or "ITEM:" in l: - notes.append(l.strip()) +WHY THE FILTER IS THE DEFAULT, and why every future analysis tool here should do the +same. The log records User-Agent. The real client sends ProtoHttp; this project's own +probes send curl/* or Python-urllib/*. Reading the log unfiltered gave the project a +materially wrong picture of itself: /clubUser and /user/list had 93 and 180 recorded +hits and NOT ONE came from the game, while endpoints assumed to be exercised turned out +to be exercised only by us. Any claim of the form "the client asks for X" made before +this distinction existed is unsupported until re-checked with the filter on. -print(f"{len(rows)} requests since marker\n") -print("verb path n") -for (v, p), n in counts.most_common(): - print(f"{v:6} {p:48} {n}") +The corollary matters just as much: do NOT probe the live server while the client is +running. It pollutes the evidence you are collecting. Probe a scratch instance on +another port instead. -squad = [r for r in rows if "/squad" in r[1]] -print(f"\n--- squad family ({len(squad)}) ---") -for r in squad: - print(" ", r[0], r[1], "->", r[2], f"({r[3]}b)") -# the live URL is /squad/ (e.g. /squad/0), not a bare /squad -- match on the -# segment, not endswith, or the headline result reads as a false negative. -print("\nPUT /squad seen:", any(r[0] == "PUT" and "/squad" in r[1] for r in rows)) -mi = [r for r in rows if "userMassInfo" in r[1]] -print("userMassInfo requests:", len(mi), [r[2] for r in mi]) -if notes: - print("\n--- notes ---") - for n in notes[-25:]: - print(" ", n) -last = rows[-6:] -print("\n--- last 6 requests (where it stopped) ---") -for r in last: - print(" ", r[0], r[1], "->", r[2]) +The log defaults to utas_server.py's own LOG path and can be pointed elsewhere with +FUT_LOG or a positional argument, because the harness has been started both ways. +""" +import argparse +import collections +import os +import re +import sys + +LOG = os.environ.get("FUT_LOG", "/tmp/utas_server.log") +FALLBACKS = ("/tmp/utas_server.log", "/tmp/utas.log") + +# The game. Everything else in this log is us. +CLIENT_UA = "ProtoHttp" + +REQ_RE = re.compile(r"^\[(\d\d:\d\d:\d\d)\] (GET|POST|PUT|DELETE|HEAD|PATCH) (\S+)") +RES_RE = re.compile(r"^\[\d\d:\d\d:\d\d\]\s+-> (\d{3}) ?(.*)$") +HDR_RE = re.compile(r"^\[\d\d:\d\d:\d\d\]\s+([A-Za-z-]+): (.*)$") +BODY_RE = re.compile(r"^\[\d\d:\d\d:\d\d\]\s+body: (.*)$") +NOTE_RE = re.compile(r"^\[\d\d:\d\d:\d\d\]\s+([A-Z]{3,}): (.*)$") + + +class Req(object): + __slots__ = ("t", "method", "path", "ua", "body", "status", "resp", "notes", "unmapped") + + def __init__(self, t, method, path): + self.t, self.method, self.path = t, method, path + self.ua = "" + self.body = "" + self.status = "" + self.resp = "" + self.notes = [] + self.unmapped = False + + @property + def is_client(self): + return CLIENT_UA in self.ua + + @property + def base(self): + """Path without the query string, for grouping.""" + return self.path.split("?", 1)[0] + + +def resolve(path): + if path or os.path.exists(LOG): + return path or LOG + for f in FALLBACKS: + if os.path.exists(f): + return f + return LOG + + +def parse(path): + """Log lines to Req objects. Tolerates a truncated final entry.""" + out = [] + cur = None + try: + fh = open(path, errors="replace") + except IOError as e: + sys.exit("cannot read %s: %s" % (path, e)) + with fh: + for line in fh: + line = line.rstrip("\n") + m = REQ_RE.match(line) + if m: + cur = Req(*m.groups()) + out.append(cur) + continue + if cur is None: + continue + m = RES_RE.match(line) + if m: + cur.status, cur.resp = m.group(1), m.group(2) + continue + m = BODY_RE.match(line) + if m: + cur.body = m.group(1) + continue + if "UNMAPPED" in line: + cur.unmapped = True + continue + m = HDR_RE.match(line) + if m and m.group(1).lower() == "user-agent": + cur.ua = m.group(2) + continue + m = NOTE_RE.match(line) + if m: + cur.notes.append(line.split("] ", 1)[1].strip()) + return out + + +def select(reqs, a): + """Apply the filters. Client-only unless told otherwise.""" + if a.probes: + reqs = [r for r in reqs if not r.is_client] + elif not a.all: + reqs = [r for r in reqs if r.is_client] + if a.since: + reqs = [r for r in reqs if r.t >= a.since] + if a.until: + reqs = [r for r in reqs if r.t <= a.until] + if a.path: + rx = re.compile(a.path) + reqs = [r for r in reqs if rx.search(r.path)] + if a.unmapped: + reqs = [r for r in reqs if r.unmapped] + if a.status: + reqs = [r for r in reqs if r.status == a.status] + return reqs + + +def cut(s, n): + return s if len(s) <= n else s[: n - 1] + "\u2026" + + +def main(): + p = argparse.ArgumentParser(description=__doc__.split("\n\n")[0], + formatter_class=argparse.RawDescriptionHelpFormatter) + p.add_argument("logfile", nargs="?", default="") + g = p.add_mutually_exclusive_group() + g.add_argument("--all", action="store_true", help="include our own probes (default: client only)") + g.add_argument("--probes", action="store_true", help="show ONLY our probes") + p.add_argument("-v", "--verbose", action="store_true", help="show request bodies and responses") + p.add_argument("-s", "--summary", action="store_true", help="counts per endpoint instead of a timeline") + p.add_argument("-p", "--path", help="regex the path must match") + p.add_argument("--unmapped", action="store_true", help="only catch-all fallthroughs") + p.add_argument("--status", help="only this HTTP status") + p.add_argument("--since", help="HH:MM or HH:MM:SS lower bound") + p.add_argument("--until", help="HH:MM or HH:MM:SS upper bound") + p.add_argument("-w", "--width", type=int, default=150, help="truncate bodies to this width") + a = p.parse_args() + + for attr in ("since", "until"): + v = getattr(a, attr) + if v and len(v) == 5: + setattr(a, attr, v + (":00" if attr == "since" else ":59")) + + logfile = resolve(a.logfile) + everything = parse(logfile) + reqs = select(everything, a) + + n_client = sum(1 for r in everything if r.is_client) + scope = "our probes" if a.probes else ("client + probes" if a.all else "client only") + print("%s: %d requests total, %d from the game (%s), showing %d [%s]" + % (logfile, len(everything), n_client, CLIENT_UA, len(reqs), scope)) + + if not reqs: + if not a.all and not a.probes and n_client == 0 and everything: + print("\nNothing from the game in this log. Every request here is ours.") + print("If you expected client traffic, the client never reached the server:") + print("check that it got past auth, and that the server was up the whole time.") + return + + if a.summary: + by = collections.Counter(r.base for r in reqs) + unmapped = collections.Counter(r.base for r in reqs if r.unmapped) + print() + for path, n in by.most_common(): + flag = " UNMAPPED" if unmapped.get(path) else "" + print(" %5d %s%s" % (n, path, flag)) + if unmapped: + print("\n%d request(s) fell through to the catch-all. Those are endpoints the" + % sum(unmapped.values())) + print("client wants and we do not serve, and the binary's URL template table") + print("does not list them: four such suffix endpoints have been found this way.") + return + + print() + for r in reqs: + mark = " !!UNMAPPED" if r.unmapped else "" + print(" %s %-6s %-3s %s%s" % (r.t, r.method, r.status or "?", cut(r.path, a.width), mark)) + if a.verbose: + if r.body: + print(" req: %s" % cut(r.body, a.width)) + for n in r.notes: + print(" log: %s" % cut(n, a.width)) + if r.resp: + print(" res: %s" % cut(r.resp, a.width)) + + +if __name__ == "__main__": + main()