From 8a66f9c7ee0a48c29967079013a32a1af45d1987 Mon Sep 17 00:00:00 2001 From: rays Date: Fri, 6 Nov 2026 23:44:51 +0000 Subject: [PATCH] prod-check names each trace's service and an event's fields (#387) Two 10 s error traces named `poll` read as unexplained in a check: they are hnopml's, a Hacker News fetch timing out, which the event's own `error` field said all along. `traces` now prints the root service, `trace` marks where the service changes and prints an event's fields, and the skill's error-trace search keeps to ipx's three services. Co-Authored-By: Claude Opus 5.5 --- .claude/skills/ipx-prod-check/SKILL.md | 6 ++++-- .claude/skills/ipx-prod-check/query.py | 22 +++++++++++++++++----- 2 files changed, 21 insertions(+), 7 deletions(-) diff --git a/.claude/skills/ipx-prod-check/SKILL.md b/.claude/skills/ipx-prod-check/SKILL.md index d37386e..0b35c44 100644 --- a/.claude/skills/ipx-prod-check/SKILL.md +++ b/.claude/skills/ipx-prod-check/SKILL.md @@ -185,10 +185,12 @@ a count says something happened, the lines and traces say why. R='resource.deployment.environment.name="production" && resource.service.name="ipx"' $Q spans "{$R && span.http.route != \"\" && span.http.route != \"/api/events\" && span.http.route !~ \"/media/.*\" && duration > 1s} | select(span.http.route)" $Q spans "{$R && name=\"step\" && duration > 500ms} | select(span.of)" - $Q traces '{resource.deployment.environment.name="production" && status = error}' + $Q traces '{resource.deployment.environment.name="production" && resource.service.name=~"ipx|ipx-web|ipx-directory" && status = error}' $Q trace ``` - Tempo keeps about two weeks. A trace id from a log line that Tempo answers 404 for, or a + Other services on Tower send production traces too (hnopml's `poll`, a Hacker News fetch that + times out now and then): `traces` names each trace's service and `trace` prints an event's + fields (its `error`), so say whose a failure is before reading on. Tempo keeps about two weeks. A trace id from a log line that Tempo answers 404 for, or a search that finds only the last quarter of an hour, is Tempo not reading its stored blocks: see the monitoring section. diff --git a/.claude/skills/ipx-prod-check/query.py b/.claude/skills/ipx-prod-check/query.py index 326ecdc..475252e 100755 --- a/.claude/skills/ipx-prod-check/query.py +++ b/.claude/skills/ipx-prod-check/query.py @@ -157,7 +157,8 @@ def main(): when = time.strftime("%m-%d %H:%M:%S", time.gmtime(int(t["startTimeUnixNano"]) / 1e9)) # No root name: its root span is a tap in the page, which the browser never sends. name = t.get("rootTraceName") or "(from the page)" - print(f"{t.get('durationMs', 0):>8}ms {when}Z {t['traceID']} {name}") + # Production holds other services' traces too (hnopml's `poll`); say whose. + print(f"{t.get('durationMs', 0):>8}ms {when}Z {t['traceID']} {t.get('rootServiceName', '?')} {name}") print(f"-- {len(traces)} trace(s)", file=sys.stderr) elif kind == "spans": # The spans that matched, each with its own time: a trace's length says nothing about a @@ -199,7 +200,12 @@ def main(): f.write(flame_svg(stacks, n, q)) print(f"-- {len(roots)} span(s) in {len(found)} trace(s): {out}, {out}.folded", file=sys.stderr) elif kind == "trace": - spans = trace_spans(fetch(f"http://tempo:3200/api/traces/{q}")) + tr = fetch(f"http://tempo:3200/api/traces/{q}") + spans = trace_spans(tr) + service = {sp["spanId"]: next((a["value"].get("stringValue") for a in b.get("resource", {}).get("attributes", []) + if a["key"] == "service.name"), "?") + for b in tr.get("batches", tr.get("resourceSpans", [])) + for ss in b.get("scopeSpans", b.get("instrumentationLibrarySpans", [])) for sp in ss["spans"]} kids = {} for sp in spans: kids.setdefault(sp.get("parentSpanId", ""), []).append(sp) @@ -209,13 +215,19 @@ def main(): attrs = {a["key"]: next(iter(a["value"].values()), None) for a in sp.get("attributes", []) if not a["key"].startswith(("code.", "thread.")) and a["key"] not in ("busy_ns", "idle_ns", "target")} err = " ERROR" if sp.get("status", {}).get("code") in (2, "STATUS_CODE_ERROR") else "" - print(f"{' ' * depth}{sp['name']} {ms:.0f}ms{err} {json.dumps(attrs) if attrs else ''}") + parent = next((p for p in spans if p["spanId"] == sp.get("parentSpanId")), None) + # The service where it changes: a root, or a hop from ipx-web to ipx to the directory. + svc = f"[{service.get(sp['spanId'])}] " if parent is None or service.get(parent["spanId"]) != service.get(sp["spanId"]) else "" + print(f"{' ' * depth}{svc}{sp['name']} {ms:.0f}ms{err} {json.dumps(attrs) if attrs else ''}") for e in sp.get("events", []): - msg = next((a["value"].get("stringValue") for a in e.get("attributes", []) if a["key"] == "message"), e.get("name")) + fields = {a["key"]: next(iter(a["value"].values()), None) for a in e.get("attributes", [])} + msg = fields.pop("message", None) or e.get("name") + # An event's own fields carry the why: `poll failed` alone hid hnopml's timeout. + extra = {k: v for k, v in fields.items() if not k.startswith(("code.", "thread.")) and k not in ("level", "target")} # A scan logs a skip for every feed not due; they bury what happened. if '"ev":"feed_skip"' in (msg or ""): continue - print(f"{' ' * depth} - {msg}") + print(f"{' ' * depth} - {msg}{' ' + json.dumps(extra) if extra else ''}") for k in sorted(kids.get(sp["spanId"], []), key=lambda s: int(s["startTimeUnixNano"])): show(k, depth + 1)