姚章浩
8a3aa800a3
v4 判据（都带作业身份，且时间戳必须晚于杀点）： - `scripts/takeover_log_contract.py` 是唯一判据：认领行 + 决策行都要有本作业 id、 target/backup 一致；只有汇总行、别的作业的认领行、杀之前的旧日志三种一律红； `--self-test` 11 条（正例 2 / 负例 9）进 `make verify`（新增第 16 项必需检查）； - `prebackup` 不再强制 `skipped`：真实接管是复用后重跑整条链路，阶段记 succeeded。 但**不取消备份校验**，改为证明复用同一份——快照 id、清单字节与 mtime、 版本行首次登记时刻都不变，且证据里有 `backup_reused=true`； - 杀之前把预备份清单 sha256/mtime 与版本行登记时刻拍进 evidence； - summary.json 增加 takeover_decision / claim_at / backup_registered_at。 verify: 判据自检 11 条全过；用真实 Go 输出行形状的正例日志 rc=0；旧形状（只有 汇总行）rc=2 且理由点名"汇总"；`--check` 前置体检 13 项全 pass（含新增 preflight_log_contract）；make verify overall success。
295 lines
15 KiB
Python
Executable File
295 lines
15 KiB
Python
Executable File
#!/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 <id> resumed after worker restart`
|
||
只在"新建队列行"那条路径打印，真实走的却是"队列行已存在"那条 ⇒ 判据与实现各说一套，
|
||
演练 exit 5。这里把契约固化成可执行判据。
|
||
|
||
判据（三条缺一不可）：
|
||
1. 一行 `library job <id> takeover claimed ... key=value ...`，且 target/backup 与本次作业一致；
|
||
2. 一行 `library job <id> takeover decision=<d> ...`，且 <d> 等于期望决策；
|
||
3. 两行的时间戳都 >= 杀点（取自 `docker logs -t` 的行首时间戳）：杀之前的旧日志不算。
|
||
只接受**带本作业 id** 的行：汇总行（takeover sweep / 没有 id 的 resume 统计）一律不算证据；
|
||
别的作业的认领行也不算。
|
||
|
||
用法：
|
||
python3 scripts/takeover_log_contract.py --log worker.log --job <id> \
|
||
--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>…`" % 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:])) |