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) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01VUT92pz6RWKih9dSr8ZpxW
This commit is contained in:
funman300
@@ -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
|
||||
|
||||
|
||||
+202
-50
@@ -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/<id> (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()
|
||||
|
||||
Reference in New Issue
Block a user