#!/usr/bin/env python3 """接管日志契约:从真实 worker 日志里证明"这个作业被认领了、并且做了哪个接管决策"。 为什么要有这份独立判据 ---------------------- 2026-10-29T19:56Z 的 `after:database` 演练里,worker 只打印了汇总行 `library job takeover sweep: 1 resumed, 0 failed without backup`:汇总既没说 是**哪个**作业,也没说它是不是真的被本进程认领(被别的 worker 抢走、attach 失败 都只影响计数)。演练脚本当时要求的老文案 `library job resumed after worker restart` 只在"新建队列行"那条路径打印,真实走的却是"队列行已存在"那条 ⇒ 判据与实现各说一套, 演练 exit 5。这里把契约固化成可执行判据。 判据(三条缺一不可): 1. 一行 `library job takeover claimed ... key=value ...`,且 target/backup 与本次作业一致; 2. 一行 `library job takeover decision= ...`,且 等于期望决策; 3. 两行的时间戳都 >= 杀点(取自 `docker logs -t` 的行首时间戳):杀之前的旧日志不算。 只接受**带本作业 id** 的行:汇总行(takeover sweep / 没有 id 的 resume 统计)一律不算证据; 别的作业的认领行也不算。 用法: python3 scripts/takeover_log_contract.py --log worker.log --job \ --target <快照> --backup <预备份快照> --since 2026-10-29T19:56:49Z python3 scripts/takeover_log_contract.py --self-test # 正负例自检(门禁 CI 里跑) 退出码:0 成立 / 2 判据不成立(原因逐条打印)/ 3 日志读不到 / 64 参数不合法 """ from __future__ import annotations import argparse import datetime as dt import re import sys from dataclasses import dataclass, field from pathlib import Path LINE_TS = re.compile(r"^(\d{4}-\d\d-\d\dT\d\d:\d\d:\d\d(?:\.\d+)?Z) (.*)$") # Go 的 log 默认带 LstdFlags(`2026/10/29 19:57:21 `),`docker logs -t` 又在最前面加 # 自己的 RFC3339 时间戳 ⇒ 行体里还有一层"年/月/日 时:分:秒"。判据只认行首那一个。 GO_TS = re.compile(r"^\d{4}/\d\d/\d\d \d\d:\d\d:\d\d(?:\.\d+)? ") CLAIM_PREFIX = "library job {job} takeover claimed " DECISION_PREFIX = "library job {job} takeover decision=" ANY_CLAIM = re.compile(r"library job (\S+) takeover claimed ") ANY_DECISION = re.compile(r"library job (\S+) takeover decision=(\S+)") REQUIRED_CLAIM_KEYS = ("at", "kind", "scope", "target", "backup", "queue", "path") TAKEOVER_DECISIONS = ("fresh", "pending_final", "superseded", "foreign_effective", "unknown") def parse_ts(value: str) -> dt.datetime | None: """解析 `docker logs -t` 的 RFC3339(可能带纳秒)时间戳;解析不了就是 None。""" text = value.strip() if text.endswith("Z"): text = text[:-1] + "+00:00" if "." in text: head, tail = text.split(".", 1) # 纳秒 → 微秒:Python 只认 6 位,直接截断(比较用,不需要更高精度) frac = re.match(r"(\d+)", tail) zone = tail[frac.end():] if frac else "" text = head + "." + (frac.group(1)[:6].ljust(6, "0") if frac else "000000") + zone try: parsed = dt.datetime.fromisoformat(text) except ValueError: return None return parsed if parsed.tzinfo else parsed.replace(tzinfo=dt.timezone.utc) def key_values(body: str) -> dict[str, str]: """按 key=value 取字段(不按位置猜):Go 侧改字段名会让演练直接红,而不是静默放过。""" out: dict[str, str] = {} for token in body.split(): if "=" in token: key, _, value = token.partition("=") if key and value: out[key] = value return out @dataclass class Result: ok: bool reasons: list[str] = field(default_factory=list) info: dict[str, str] = field(default_factory=dict) @dataclass class Entry: ts: dt.datetime | None body: str def split_lines(lines: list[str]) -> list[Entry]: entries: list[Entry] = [] for raw in lines: line = raw.rstrip("\n") if not line.strip(): continue match = LINE_TS.match(line) if match: entries.append(Entry(parse_ts(match.group(1)), GO_TS.sub("", match.group(2), count=1))) else: # 没有 docker -t 前缀就无法证明"这是杀之后的日志":仍然保留(去掉内层 # Go 时间戳后照常识别),由判据显式判红,而不是当成通过。 entries.append(Entry(None, GO_TS.sub("", line, count=1))) return entries def evaluate(lines: list[str], job: str, target: str, backup: str, since: dt.datetime, expect_decision: str = "fresh") -> Result: entries = split_lines(lines) claim_prefix = CLAIM_PREFIX.format(job=job) decision_prefix = DECISION_PREFIX.format(job=job) claims = [e for e in entries if e.body.startswith(claim_prefix)] decisions = [e for e in entries if e.body.startswith(decision_prefix)] after = lambda e: e.ts is not None and e.ts >= since # noqa: E731 fresh_claims = [e for e in claims if after(e)] fresh_decisions = [e for e in decisions if after(e)] aggregate = [e for e in entries if "takeover sweep" in e.body or re.search( r"library job resume: \d+ resumed", e.body)] other_claims = [(m.group(1), e) for e in entries for m in [ANY_CLAIM.search(e.body)] if m and m.group(1) != job] other_decisions = [(m.group(1), m.group(2), e) for e in entries for m in [ANY_DECISION.search(e.body)] if m and m.group(1) != job] reasons: list[str] = [] info: dict[str, str] = {} if not fresh_claims: if claims: reasons.append("本作业的认领行全都出现在杀点 %s 之前:杀之前的日志不能证明这次接管" % since.isoformat()) elif other_claims: reasons.append("只有别的作业的认领行(%s):不是本作业被认领" % ", ".join(sorted({j for j, _ in other_claims}))) elif aggregate: reasons.append("只看到汇总行(%s):汇总既不说哪个作业,也不说它是否被认领" % aggregate[0].body.strip()[:120]) else: reasons.append("日志里没有本作业的认领行 `%s…`" % claim_prefix.strip()) else: kv = key_values(fresh_claims[-1].body) info["claim_at"] = kv.get("at", "") info["claim_path"] = kv.get("path", "") info["claim_queue"] = kv.get("queue", "") missing = [k for k in REQUIRED_CLAIM_KEYS if not kv.get(k)] if missing: reasons.append("认领行缺字段 %s(key=value 契约):%s" % (",".join(missing), fresh_claims[-1].body.strip())) if kv.get("target") and kv["target"] != target: reasons.append("认领行的 target=%s 不是本次目标 %s(别的作业/别的快照的认领)" % (kv["target"], target)) if kv.get("backup") and backup and kv["backup"] != backup: reasons.append("认领行的 backup=%s 不是崩溃前登记的那份预备份 %s(换了基线)" % (kv["backup"], backup)) if not fresh_decisions: if decisions: reasons.append("本作业的决策行全都出现在杀点之前:不能证明这次接管的决策") else: reasons.append("日志里没有本作业的接管决策行 `%s…`" % decision_prefix) else: decision = fresh_decisions[-1].body[len(decision_prefix):].split()[0] info["decision"] = decision if decision not in TAKEOVER_DECISIONS: reasons.append("未知的接管决策 %r(期望 %s)" % (decision, expect_decision)) elif decision != expect_decision: reasons.append("接管决策是 %s,期望 %s(在 after:database 之后不可能是" "「只差收尾」,同快照收尾=上一轮的假完成)" % (decision, expect_decision)) kv = key_values(fresh_decisions[-1].body) if kv.get("target") and kv["target"] != target: reasons.append("决策行的 target=%s 不是本次目标 %s" % (kv["target"], target)) return Result(ok=not reasons, reasons=reasons, info=info) def read_log(path: Path) -> list[str] | None: if not path.is_file(): return None return path.read_text(encoding="utf-8", errors="replace").splitlines() # ── 自检:正例必须先绿,负例必须逐条红(否则判据是死的)────────────────── FIXTURE_JOB = "librestore-internal-1793303791259342087" FIXTURE_TARGET = "0d982f7667be35227c18b89ca08e83d37a44e5d08a1582a8874be08eee5b61e7" FIXTURE_BACKUP = "69eb5a90f303b3fb9e0ebffececb92dcf2f62701fd459d58871ac305053bd510" FIXTURE_SINCE = "2026-10-29T19:56:49Z" FIXTURE_AGGREGATE = ("2026-10-29T19:57:20.123456789Z 2026/10/29 19:57:20 " "library job takeover sweep: 1 resumed, 0 failed without backup") FIXTURE_CLAIM = ("2026-10-29T19:57:20.500000000Z 2026/10/29 19:57:20 library job %s takeover claimed " "at=2026-10-29T19:57:20Z kind=restore scope=internal target=%s backup=%s " "queue=q65e9fd4d932b262659cdb0dcbedb92ce path=existing-queue" % (FIXTURE_JOB, FIXTURE_TARGET, FIXTURE_BACKUP)) FIXTURE_DECISION = ("2026-10-29T19:57:22.000000000Z 2026/10/29 19:57:22 library job %s takeover decision=fresh " "at=2026-10-29T19:57:22Z kind=restore scope=internal target=%s backup=%s " "finalize_only=false" % (FIXTURE_JOB, FIXTURE_TARGET, FIXTURE_BACKUP)) PRE_KILL_CLAIM = FIXTURE_CLAIM.replace("2026-10-29T19:57:20.500000000Z", "2026-10-29T19:56:40.000000000Z") PRE_KILL_DECISION = FIXTURE_DECISION.replace("2026-10-29T19:57:22.000000000Z", "2026-10-29T19:56:41.000000000Z") def self_test() -> int: since = parse_ts(FIXTURE_SINCE) assert since is not None cases: list[tuple[str, list[str], bool, str, str]] = [ ("正例:认领+决策都在杀之后", [FIXTURE_AGGREGATE, FIXTURE_CLAIM, FIXTURE_DECISION], True, "fresh", ""), ("负例:只有汇总行(上一轮的真实形状)", [FIXTURE_AGGREGATE, FIXTURE_DECISION], False, "fresh", "汇总"), ("负例:认领属于别的作业", [FIXTURE_CLAIM.replace(FIXTURE_JOB, "libsync-internal-other"), FIXTURE_DECISION], False, "fresh", "别的作业"), ("负例:认领/决策都在杀之前(杀前日志伪通过)", [PRE_KILL_CLAIM, PRE_KILL_DECISION], False, "fresh", "杀点"), ("负例:有认领没决策", [FIXTURE_CLAIM], False, "fresh", "决策行"), ("负例:有决策没认领", [FIXTURE_DECISION], False, "fresh", "认领行"), ("负例:认领的 target 不是本次目标", [FIXTURE_CLAIM.replace(FIXTURE_TARGET, "fc595511c7388d8e6cab3de37af8a2b6a64ede47241918684e81f2fb5d0e1f16"), FIXTURE_DECISION], False, "fresh", "target="), ("负例:认领的 backup 换了(重做了备份)", [FIXTURE_CLAIM.replace(FIXTURE_BACKUP, "0fea01923a7c6073d06d7310588e737359f44ecee5ab1fd8f5892eba8e208b63"), FIXTURE_DECISION], False, "fresh", "backup="), ("负例:决策是 pending_final(同快照收尾)", [FIXTURE_CLAIM, FIXTURE_DECISION.replace("decision=fresh", "decision=pending_final")], False, "fresh", "pending_final"), ("负例:没有 docker -t 时间戳(无法证明在杀之后)", [FIXTURE_CLAIM.split(" ", 1)[1], FIXTURE_DECISION.split(" ", 1)[1]], False, "fresh", "杀点"), ("正例:期望决策可显式放宽为 pending_final", [FIXTURE_CLAIM, FIXTURE_DECISION.replace("decision=fresh", "decision=pending_final")], True, "pending_final", ""), ] failed = 0 for name, lines, want_ok, expect, want_reason in cases: result = evaluate(lines, FIXTURE_JOB, FIXTURE_TARGET, FIXTURE_BACKUP, since, expect) if result.ok != want_ok: print("❌ %s:期望 ok=%s,实际 ok=%s(%s)" % (name, want_ok, result.ok, ";".join(result.reasons)), file=sys.stderr) failed += 1 continue if not want_ok and want_reason not in ";".join(result.reasons): print("❌ %s:红了但理由不对(期望含 %r,实际 %r)" % (name, want_reason, result.reasons), file=sys.stderr) failed += 1 continue if want_ok and want_reason: print("❌ 自检夹具写错了:正例不该要求失败理由 %r" % want_reason, file=sys.stderr) failed += 1 if failed: print("❌ 接管日志契约自检:%d 条不成立" % failed, file=sys.stderr) return 1 print("✅ 接管日志契约自检通过:%d 条(正例 %d / 负例 %d),负例逐条红" % (len(cases), sum(1 for c in cases if c[2]), sum(1 for c in cases if not c[2]))) return 0 def main(argv: list[str]) -> int: parser = argparse.ArgumentParser(description="接管日志契约判据") parser.add_argument("--log", type=Path, help="docker logs -t 的输出") parser.add_argument("--job", help="业务作业 id") parser.add_argument("--target", help="目标快照(作业的 target_snapshot_id)") parser.add_argument("--backup", default="", help="崩溃前登记的预备份快照(可省略)") parser.add_argument("--since", help="杀点时刻(RFC3339);早于它的日志不算证据") parser.add_argument("--expect-decision", default="fresh", choices=TAKEOVER_DECISIONS, help="期望的接管决策(默认 fresh)") parser.add_argument("--self-test", action="store_true", help="只跑正负例自检") args = parser.parse_args(argv) if args.self_test: return self_test() if not (args.log and args.job and args.target and args.since): print("必须给 --log/--job/--target/--since(或用 --self-test)", file=sys.stderr) return 64 since = parse_ts(args.since) if since is None: print("--since 不是 RFC3339:%r" % args.since, file=sys.stderr) return 64 lines = read_log(args.log) if lines is None: print("读不到日志:%s" % args.log, file=sys.stderr) return 3 result = evaluate(lines, args.job, args.target, args.backup, since, args.expect_decision) if not result.ok: for reason in result.reasons: print("❌ " + reason, file=sys.stderr) return 2 print("OK claim_at=%s path=%s queue=%s decision=%s target=%s backup=%s" % (result.info.get("claim_at", "?"), result.info.get("claim_path", "?"), result.info.get("claim_queue", "?"), result.info.get("decision", "?"), args.target, args.backup or "?")) return 0 if __name__ == "__main__": sys.exit(main(sys.argv[1:]))