verae-mcp-timestamping-server/scripts/transaction_log_test.py
George Lambert a6a1a70ee4 docs: Verae-Debug-Test 20-stamp log with collapsible HTML viewer
Hash of string Verae-Debug-Test; each round shows stamp request/response.
2026-09-20 10:36:00 -04:00

465 lines
17 KiB
Python

#!/usr/bin/env python3
"""20 global stamps of the same hash; write a full HTTP + function timing log."""
from __future__ import annotations
import hashlib
import html
import json
import time
from datetime import datetime, timezone
from pathlib import Path
from typing import Any
from verae_mcp_timestamping_server.global_client import (
GlobalClient,
UrllibHttp,
load_auth_token,
)
from verae_mcp_timestamping_server.ledger import validate_sha256
SOURCE = "Verae-Debug-Test"
DIGEST = hashlib.sha256(SOURCE.encode()).hexdigest()
ROOT = Path(__file__).resolve().parents[1]
OUT = ROOT / "transaction-log-test.md"
OUT_JSON = ROOT / "transaction-log-test.json"
OUT_HTML = ROOT / "transaction-log-test.html"
N = 20
def _now() -> str:
return datetime.now(timezone.utc).strftime("%Y-%m-%dT%H:%M:%S.%fZ")
def _redact(headers: dict[str, str]) -> dict[str, str]:
out = dict(headers)
auth = out.get("Authorization") or out.get("authorization")
if auth:
key = "Authorization" if "Authorization" in out else "authorization"
token = auth.split(" ", 1)[-1] if " " in auth else auth
out[key] = f"Bearer [redacted len={len(token)}]"
return out
class LoggingHttp:
def __init__(self, inner: UrllibHttp, exchanges: list[dict[str, Any]], spans: list[dict[str, Any]]):
self.inner = inner
self.exchanges = exchanges
self.spans = spans
def request(
self, method: str, url: str, payload: dict[str, Any], headers: dict[str, str]
) -> Any:
req_at = _now()
t0 = time.perf_counter()
res = self.inner.request(method, url, payload=payload, headers=headers)
ms = (time.perf_counter() - t0) * 1000
resp_at = _now()
self.exchanges.append(
{
"request_at": req_at,
"response_at": resp_at,
"method": method,
"url": url,
"request_headers": _redact(headers),
"request_body": payload if method != "GET" else None,
"status": res.status_code,
"response_headers": dict(getattr(res, "headers", {}) or {}),
"response_body": res.json() if hasattr(res, "json") else res.text,
"response_text": res.text,
"round_trip_ms": round(ms, 3),
}
)
self.spans.append(
{
"fn": f"http.{method}",
"url": url,
"ms": round(ms, 3),
"at": req_at,
}
)
return res
def _span(spans: list[dict[str, Any]], name: str, fn, **extra):
t0 = time.perf_counter()
at = _now()
try:
return fn()
finally:
spans.append({"fn": name, "ms": round((time.perf_counter() - t0) * 1000, 3), "at": at, **extra})
def run() -> dict[str, Any]:
spans: list[dict[str, Any]] = []
exchanges: list[dict[str, Any]] = []
token = _span(spans, "load_auth_token", load_auth_token)
client = _span(
spans,
"GlobalClient.from_env",
lambda: GlobalClient(
token=token,
http=LoggingHttp(UrllibHttp(), exchanges, spans),
),
)
digest = _span(spans, "validate_sha256", lambda: validate_sha256(DIGEST))
rounds: list[dict[str, Any]] = []
for i in range(1, N + 1):
t0 = time.perf_counter()
at = _now()
n_ex = len(exchanges)
try:
rec = _span(
spans,
"GlobalClient.submit",
lambda: client.submit(digest, cube_id="verae-mcp-research"),
iteration=i,
)
err = None
receipt = rec.model_dump()
except Exception as exc: # noqa: BLE001 — log live failures
err = str(exc)
receipt = None
rounds.append(
{
"n": i,
"at": at,
"ms": round((time.perf_counter() - t0) * 1000, 3),
"receipt": receipt,
"error": err,
"exchange_indexes": list(range(n_ex, len(exchanges))),
}
)
ids = [r["receipt"]["receipt_id"] for r in rounds if r["receipt"]]
unique = sorted(set(ids))
return {
"source": SOURCE,
"digest": digest,
"n": N,
"unique_receipt_ids": unique,
"same_receipt_every_time": len(unique) == 1 and len(ids) == N,
"rounds": rounds,
"exchanges": exchanges,
"spans": spans,
}
def render(data: dict[str, Any]) -> str:
lines: list[str] = []
lines.append("# transaction-log-test")
lines.append("")
lines.append("20 global `/stamp` calls of the same SHA-256 with **no local cache**.")
lines.append("Authorization bearer values are redacted (`len=` only).")
lines.append("")
lines.append(f"- Started (UTC of write): `{_now()}`")
lines.append(f"- Source string: `{data.get('source', SOURCE)}`")
lines.append(f"- Digest: `{data['digest']}` (SHA-256 of that UTF-8 string)")
lines.append(f"- Unique `receipt_id` count: **{len(data['unique_receipt_ids'])}**")
lines.append(f"- Same receipt every time: **{data['same_receipt_every_time']}**")
lines.append("")
lines.append("## Unique receipt ids")
lines.append("")
for rid in data["unique_receipt_ids"]:
lines.append(f"- `{rid}`")
if not data["unique_receipt_ids"]:
lines.append("- *(none)*")
lines.append("")
lines.append("## Rounds")
lines.append("")
lines.append("| n | at (UTC) | submit ms | receipt_id | error |")
lines.append("|---|---|---|---|---|")
for r in data["rounds"]:
rid = (r["receipt"] or {}).get("receipt_id", "")
lines.append(
f"| {r['n']} | {r['at']} | {r['ms']} | `{rid}` | {r['error'] or ''} |"
)
lines.append("")
lines.append("## Function profile")
lines.append("")
by_fn: dict[str, list[float]] = {}
for s in data["spans"]:
by_fn.setdefault(s["fn"], []).append(float(s["ms"]))
lines.append("| function | calls | total ms | min | max | mean |")
lines.append("|---|---|---|---|---|---|")
for name, vals in sorted(by_fn.items()):
total = sum(vals)
lines.append(
f"| `{name}` | {len(vals)} | {total:.3f} | {min(vals):.3f} | {max(vals):.3f} | {total/len(vals):.3f} |"
)
lines.append("")
lines.append("### Every internal span")
lines.append("")
lines.append("| at (UTC) | function | ms | extra |")
lines.append("|---|---|---|---|")
for s in data["spans"]:
extra = {k: v for k, v in s.items() if k not in ("fn", "ms", "at")}
extra_s = json.dumps(extra) if extra else ""
lines.append(f"| {s['at']} | `{s['fn']}` | {s['ms']} | {extra_s} |")
lines.append("")
lines.append("## Network exchanges")
lines.append("")
for i, ex in enumerate(data["exchanges"], 1):
lines.append(f"### Exchange {i}")
lines.append("")
lines.append("#### Request")
lines.append("")
lines.append(f"- Time/Date: `{ex['request_at']}`")
lines.append(f"- METHOD: `{ex['method']}`")
lines.append(f"- URL: `{ex['url']}`")
lines.append("- Headers:")
lines.append("")
lines.append("```json")
lines.append(json.dumps(ex["request_headers"], indent=2))
lines.append("```")
lines.append("")
lines.append("- Body:")
lines.append("")
lines.append("```json")
lines.append(json.dumps(ex["request_body"], indent=2))
lines.append("```")
lines.append("")
lines.append("#### Response")
lines.append("")
lines.append(f"- Time/Date: `{ex['response_at']}`")
lines.append(f"- Status: `{ex['status']}`")
lines.append(f"- Round-trip: `{ex['round_trip_ms']} ms`")
lines.append("- Headers:")
lines.append("")
lines.append("```json")
lines.append(json.dumps(ex["response_headers"], indent=2))
lines.append("```")
lines.append("")
lines.append("- Body:")
lines.append("")
lines.append("```json")
lines.append(json.dumps(ex["response_body"], indent=2) if not isinstance(ex["response_body"], str) else ex["response_text"])
lines.append("```")
lines.append("")
return "\n".join(lines) + "\n"
def _pre(obj: Any) -> str:
text = obj if isinstance(obj, str) else json.dumps(obj, indent=2)
return f"<pre><code>{html.escape(text)}</code></pre>"
def render_html(data: dict[str, Any]) -> str:
exchanges = data["exchanges"]
by_fn: dict[str, list[float]] = {}
for s in data["spans"]:
by_fn.setdefault(s["fn"], []).append(float(s["ms"]))
round_blocks: list[str] = []
for r in data["rounds"]:
rec = r["receipt"] or {}
idxs = r.get("exchange_indexes") or []
exs = [exchanges[i] for i in idxs if i < len(exchanges)]
stamp_req = next((e for e in exs if e["method"] == "POST" and "/api/timestamp" in e["url"]), None)
stamp_res = stamp_req
status_ex = [e for e in exs if e["method"] == "GET"]
last_status = status_ex[-1] if status_ex else None
ok = not r["error"] and rec.get("receipt_id")
cls = "ok" if ok else "bad"
summary = (
f"Round {r['n']} · {r['ms']} ms · "
f"{html.escape(str(rec.get('receipt_id') or r['error'] or 'FAILED'))}"
)
parts = [
f'<details class="round {cls}">',
f"<summary>{summary}</summary>",
'<div class="panel">',
f"<p><strong>Hash sent</strong> <code>{html.escape(data['digest'])}</code></p>",
]
if stamp_req:
parts.append("<h3>Stamp request (POST /api/timestamp)</h3>")
parts.append(f"<p>{html.escape(stamp_req['method'])} {html.escape(stamp_req['url'])}</p>")
parts.append(_pre(stamp_req["request_body"]))
parts.append(
f"<h3>Stamp response ({html.escape(str(stamp_req['status']))} in {stamp_req['round_trip_ms']} ms)</h3>"
)
parts.append(_pre(stamp_req["response_body"]))
if last_status:
parts.append(
f"<h3>Job status ({html.escape(last_status['method'])} {html.escape(last_status['url'])} → {last_status['status']})</h3>"
)
parts.append(_pre(last_status["response_body"]))
parts.append("<h3>Mapped receipt</h3>")
parts.append(_pre(rec or r["error"]))
for i, ex in enumerate(exs, 1):
parts.append(f"<details><summary>Full exchange {i}: {html.escape(ex['method'])} {html.escape(ex['url'])}</summary>")
parts.append("<h4>Request</h4>")
parts.append(f"<p>Time/Date: <time datetime='{html.escape(ex['request_at'])}'>{html.escape(ex['request_at'])}</time></p>")
parts.append("<p>Headers</p>")
parts.append(_pre(ex["request_headers"]))
parts.append("<p>Body</p>")
parts.append(_pre(ex["request_body"]))
parts.append("<h4>Response</h4>")
parts.append(f"<p>Time/Date: <time datetime='{html.escape(ex['response_at'])}'>{html.escape(ex['response_at'])}</time> · status {ex['status']} · {ex['round_trip_ms']} ms</p>")
parts.append("<p>Headers</p>")
parts.append(_pre(ex["response_headers"]))
parts.append("<p>Body</p>")
parts.append(_pre(ex["response_body"]))
parts.append("</details>")
parts.append("</div></details>")
round_blocks.append("\n".join(parts))
profile_rows = []
for name, vals in sorted(by_fn.items()):
total = sum(vals)
profile_rows.append(
f"<tr><td><code>{html.escape(name)}</code></td><td>{len(vals)}</td>"
f"<td>{total:.3f}</td><td>{min(vals):.3f}</td><td>{max(vals):.3f}</td>"
f"<td>{total/len(vals):.3f}</td></tr>"
)
span_rows = []
for s in data["spans"]:
extra = {k: v for k, v in s.items() if k not in ("fn", "ms", "at")}
span_rows.append(
f"<tr><td>{html.escape(s['at'])}</td><td><code>{html.escape(s['fn'])}</code></td>"
f"<td>{s['ms']}</td><td>{html.escape(json.dumps(extra) if extra else '')}</td></tr>"
)
ids = "\n".join(f"<li><code>{html.escape(i)}</code></li>" for i in data["unique_receipt_ids"])
return f"""<!DOCTYPE html>
<html lang="en">
<head>
<meta charset="utf-8">
<meta name="viewport" content="width=device-width, initial-scale=1.0">
<title>Verae-Debug-Test stamp log</title>
<style>
:root {{
--bg: #0f1419;
--fg: #e7ecf1;
--muted: #9aa7b4;
--ok: #3dd68c;
--bad: #ff6b6b;
--card: #1a222c;
--line: #2a3542;
--accent: #7cb7ff;
}}
* {{ box-sizing: border-box; }}
body {{
margin: 0;
font: 15px/1.45 ui-sans-serif, system-ui, sans-serif;
background: var(--bg);
color: var(--fg);
}}
header, main {{ max-width: 72rem; margin: 0 auto; padding: 1.25rem; }}
h1 {{ font-size: 1.4rem; margin: 0 0 .5rem; }}
h2 {{ font-size: 1.1rem; }}
h3 {{ font-size: 1rem; color: var(--accent); }}
code, pre {{ font-family: ui-monospace, SFMono-Regular, Menlo, monospace; font-size: .85rem; }}
pre {{
background: #0b0f14;
border: 1px solid var(--line);
padding: .75rem;
overflow: auto;
white-space: pre-wrap;
}}
.meta {{ color: var(--muted); }}
.hash {{
background: #0b0f14;
border: 1px solid var(--accent);
padding: .75rem 1rem;
margin: 1rem 0;
}}
search {{ display: flex; flex-wrap: wrap; gap: .5rem; align-items: center; margin: 1rem 0; }}
input[type="search"] {{
flex: 1 1 16rem;
padding: .5rem .75rem;
background: var(--card);
color: var(--fg);
border: 1px solid var(--line);
}}
button {{
background: var(--card);
color: var(--fg);
border: 1px solid var(--line);
padding: .45rem .8rem;
}}
details.round {{
background: var(--card);
border: 1px solid var(--line);
margin: .5rem 0;
padding: .25rem .5rem;
}}
details.round.ok > summary {{ border-left: 4px solid var(--ok); padding-left: .5rem; }}
details.round.bad > summary {{ border-left: 4px solid var(--bad); padding-left: .5rem; }}
summary {{ cursor: pointer; padding: .5rem; }}
.panel {{ padding: .25rem .5rem 1rem; }}
table {{ width: 100%; border-collapse: collapse; font-size: .85rem; }}
th, td {{ border-bottom: 1px solid var(--line); padding: .35rem .4rem; text-align: left; vertical-align: top; }}
</style>
</head>
<body>
<header>
<h1>Verae timestamp transaction log</h1>
<p class="meta">Expand a round to hunt request/response mismatches. Find-in-page searches collapsed text.</p>
<div class="hash">
<p><strong>Source string</strong> <code>{html.escape(data.get('source', SOURCE))}</code></p>
<p><strong>SHA-256 sent as stamp <code>data</code></strong><br><code>{html.escape(data['digest'])}</code></p>
<p><strong>Unique receipt ids</strong> {len(data['unique_receipt_ids'])} / {data['n']}
· same every time: <strong>{data['same_receipt_every_time']}</strong></p>
</div>
<search>
<label for="filter">Filter rounds</label>
<input type="search" id="filter" placeholder="receipt id, job id, error…">
<button type="button" id="expand">Expand all</button>
<button type="button" id="collapse">Collapse all</button>
</search>
</header>
<main>
<h2>Rounds</h2>
{''.join(round_blocks)}
<h2>Unique receipt ids</h2>
<ul>{ids}</ul>
<h2>Function profile</h2>
<table>
<thead><tr><th>function</th><th>calls</th><th>total ms</th><th>min</th><th>max</th><th>mean</th></tr></thead>
<tbody>{''.join(profile_rows)}</tbody>
</table>
<details>
<summary>Every internal span</summary>
<table>
<thead><tr><th>at</th><th>function</th><th>ms</th><th>extra</th></tr></thead>
<tbody>{''.join(span_rows)}</tbody>
</table>
</details>
</main>
<script>
const expand = document.getElementById("expand");
const collapse = document.getElementById("collapse");
const filter = document.getElementById("filter");
expand.addEventListener("click", () => {{
document.querySelectorAll("details").forEach((d) => {{ d.open = true; }});
}});
collapse.addEventListener("click", () => {{
document.querySelectorAll("details").forEach((d) => {{ d.open = false; }});
}});
filter.addEventListener("input", () => {{
const q = filter.value.toLowerCase();
document.querySelectorAll("details.round").forEach((d) => {{
d.hidden = q !== "" && !d.textContent.toLowerCase().includes(q);
}});
}});
</script>
</body>
</html>
"""
def main() -> int:
data = run()
OUT.write_text(render(data))
OUT_JSON.write_text(json.dumps(data, indent=2) + "\n")
OUT_HTML.write_text(render_html(data))
print(f"wrote {OUT}")
print(f"wrote {OUT_HTML}")
print("source", SOURCE, "digest", data["digest"])
print("unique", len(data["unique_receipt_ids"]), "same", data["same_receipt_every_time"])
return 0
if __name__ == "__main__":
raise SystemExit(main())