OpenFUT/fifa17-recon/tools/futlog.py

#!/usr/bin/env python3
"""Read the UTAS request log, FILTERED TO THE REAL CLIENT BY DEFAULT.

    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

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.

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.

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()