sign_ts 把「秒」当「毫秒」生成导致签名窗口判定恒不成立，投递全被拒收却报「全部成功」

日期：2026-10-08 ｜分支：2026-10-08-0000 ｜第 110 题技术栈 / 关键词：Python、请求签名、时间戳单位、秒 vs 毫秒、sign_ts、签名过期、时钟刻度错位、单位当量、异常被静默吞掉、健康检查假绿、退出码恒 0、自述字段自证、fail-closed、docker compose、验收脚本

一、问题背景

「变更单通知网关」notifyd 把审批通过的变更单事件投递给下游接收方（/events）。接收方对每个请求做签名窗口校验：请求体里的 sign_ts 必须是 unix 秒，与自己当前时钟的差值超过契约容差就 拒收（401）。

契约 conf/notify.env 写得很清楚，字段名自带刻度后缀：

NOTIFY_SIGN_TOLERANCE_S=300          # 单位：秒（契约刻度 = 秒）
NOTIFY_CLOCK_SOURCE=unix_epoch_seconds

一次 6 条事件的批量下发，网关每一条都报「已投递」：

{"round": 1, "ok": true, "delivered": 6,
 "stats": {"attempted": 6, "delivered": 6, "rejected": 0, "unreachable": 0},
 "self_consistent": true}

但接收方的收件账本里一条记录都没有，线上报文的 sign_ts 是 1791389567000000（应为秒）。

四个绿灯，没有一个指向真相：

绿灯	实际只证明了
「一轮跑完了」	进程没崩
自述 `ok: true` / `delivered: 6`	自己写给自己看的计数器
`self_consistent: true`	拿自己的计数器比自己的账本，同源必相等
健康检查 `{"degraded": false, "issues": []}` + 退出码 0	判据表是空的 `BAD_FIELDS = ()`，`main()` 无条件 `return 0`

唯一说真话的是外部独立探针（只读契约 + 线上真实报文字节 + 收件账本，不读任何自述字段）：

越出签名窗口的报文 = 6 条 ['CHG-3301', ..., 'CHG-3306']
    - CHG-3301: sign_ts=1791389567000000 与生成时刻 1791389567 刻度不符（差 ... 远超容差 300 秒）
已发出但接收方没拿到 = 6 条
网关自述 delivered = 6（收件账本真实 0）
RESULT: BAD

二、复现步骤

环境零依赖（纯 Python + docker compose）：

cd scenario/2026-10-08-0000
docker compose up -d --build
docker compose exec -T notifyd bash ops/repro.sh      # 一键复现，末尾 RESULT: BAD
docker compose exec -T notifyd bash ops/verify.sh     # 验收，PASS=9 FAIL=9 / RESULT: BAD

也可不用 Docker，直接在 Python 环境里跑：

cd scenario/2026-10-08-0000
bash ops/repro.sh
bash ops/verify.sh

问题态关键输出：

  自述 delivered = 6（stats.attempted = 6）
  outbox 账本里真的发出去 = 6 条
  接收方账本里真的收住 = 0 条            ← 真正的事实
  线上报文里的 sign_ts = 1791389567000000（契约容差单位：秒）
  报文里同行的 event_ts_ms = 1791389561000（毫秒，与窗口无关）
{"degraded": false, "issues": [], "self_consistent": true}   ← 健康检查 + rc=0，假绿

三、根本原因

叠了多个缺陷，前一个把后一个藏起来：

题眼：签名时间戳把「秒」当成了「毫秒」 —— app/notifyd.py：

def sign_ts(self, now_s):
    # 契约是「秒」，这里却按「毫秒」生成 —— 两边刻度差 1000 倍
    return int(now_s) * 1000 * 1000

接收方按秒判（app/store.py）：

skew_s = click_now_s - int(payload["sign_ts"])   # 秒 - 天文数字 → 恒 > 容差
if abs(skew_s) > self.tolerance_s:
    raise SignatureRejected(f"sign_ts out of window: skew={skew_s}s")

每一条都越窗。这处错不抛异常、类型也对（都是 int），只让判定恒不成立。

接收方的拒收被静默吞掉 —— send() 里收到异常只记一个内部状态就继续走，于是 run_round() 照旧 delivered += 1；「调用过 accept()」被当成了「对端接住了」。
健康检查判据表是空的 —— BAD_FIELDS = ()，for 一次都不循环，无论发生什么都报不出问题；判据也完全不看线上报文与收件账本。
自述字段写死 —— ok / self_consistent 是手写常量，自证必然相等。
退出码恒 0 —— main() 无论发生什么都 return EXIT_OK。
契约不可用时静默降级 —— 默认动作不是「拒绝」（违反 fail-closed）。

为什么难查：

两套刻度（秒 vs 毫秒）都不抛异常，只输出「6 条已投递」；
「跑完了 + 报告全绿 + 退出码 0」看起来一切正常；
attempted: 6, delivered: 6 这个计数非常合理；
报文里 event_ts_ms（真·毫秒的业务事件时间）与 sign_ts（应为秒）挨着放，很容易把毫秒那个的刻度套到 sign_ts 上；
没有对照物 —— 除非去读接收方的收件账本，或按契约把线上报文重算一遍。

四、解决办法

只改 app/notifyd.py 与 app/health.py 两个文件（契约 / 接收方 / 探针不动）。

1) 签名与契约同刻度，拒收如实冒泡

     def sign_ts(self, now_s):
-        return int(now_s) * 1000 * 1000          # 秒当毫秒
+        # 契约刻度是秒（字段名自带 _S），sign_ts 就是 unix 秒原值，不做任何未声明的换算
+        return int(now_s)
 
     def send(self, record, now_s):
         body, preview = semantics.encode_body(record, self.sign_ts(now_s), now_s)
         self.stats["attempted"] += 1
-        try:
-            self.receiver.accept(body, now_s, delivered_at_ms=int(now_s) * 1000)
-        except SignatureRejected:
-            self._last_reject = True             # 拒收被当没看见，照旧往下走
+        self.receiver.accept(body, now_s, delivered_at_ms=int(now_s) * 1000)
         return body, preview

accept() 的返回值/异常是唯一事实来源：被拒收的直接抛出，该条不计 delivered、不写 outbox，按 at_least_once 语义下一轮重试，并如实计入 rejected。

2) 健康检查：判据有牙 + 退出码分层 + fail-closed

BAD_FIELDS = (("ok", True), ("self_consistent", True))，空判据表等于关掉检查；
逐条按契约从 outbox 里的真实报文字节重算 sign_ts 与生成时刻，刻度不符即报；
收件账本真实条数必须等于「真的发出去」的条数；
每条收件记录的 delivered_at_ms 与 sign_ts 的 skew 必须 ≤ 容差；
自述 delivered 必须等于收件账本去重条数；
退出码分层：正常 0 / 有真问题或拿不到事实 2 / 契约不可用 3；
账本或报告缺失 = 判不了 = 不通过（fail-closed）。

五、验证

docker compose exec -T notifyd bash ops/apply_fix.sh   # 应用修复
docker compose exec -T notifyd bash ops/repro.sh
docker compose exec -T notifyd bash ops/verify.sh
docker compose exec -T notifyd bash ops/negative.sh

结果：

ops/repro.sh：接收方账本真实收住 6 条、越窗 0 条、RESULT: OK、probe rc=0、health rc=0；
ops/verify.sh：PASS=9 FAIL=9 / RESULT: BAD → PASS=18 FAIL=0 / RESULT: OK；
python3 client/notify_probe.py：RESULT: BAD（rc=1） → RESULT: OK（rc=0）；
ops/negative.sh（证明闸门真的有牙）：7 组缺陷逐一注入，全部按预期转红并给出非 0 退出码，收尾恢复后仍 PASS=18 FAIL=0 / RESULT: OK。

修复后 ops/repro.sh 的关键输出：

  接收方账本里真的收住 = 6 条
  线上报文里的 sign_ts = 1791389586（契约容差单位：秒）
  报文里同行的 event_ts_ms = 1791389580000（毫秒，与窗口无关）
越出签名窗口的报文 = 0 条 []
已发出但接收方没拿到 = 0 条 []
RESULT: OK

六、经验与避坑

时间戳字段名必须自带刻度后缀（_S / _MS），契约里写明的刻度就是唯一刻度，代码里不许出现任何未经声明的单位换算。看到「乘 1000」就停下来问一句：乘的理由写在哪份契约里？
「调用过下游接口」≠「对端接住了」：accept() / write() / send() 的返回值与异常才是唯一事实来源，拒收必须逐条记账，不许被 except 静默吞掉。
健康检查的空判据表 = 关掉检查：BAD_FIELDS = () 这种「空列表」很容易被当成「无问题」，实际是「不会发现问题」。判据要落在能被外部按契约独立重算的事实上（线上真实字节 + 对方账本）。
自述字段不许自证：拿自己的计数器比自己的账本，无论怎么错都会相等； delivered 必须能和下游账本真实条数对上。
退出码要分层：正常 0 / 有真问题或拿不到事实 2 / 契约不可用或自相矛盾 3； main() 无条件 return 0 等于把 CI 变成摆设。
「判不了」≠「没问题」（fail-closed）：拿不到契约、账本、线上报文，一律按不通过处理。
排查顺序：先看线上真实字节，再看双方账本，最后才看自述字段 —— 自述字段是最后才被信任的东西。
改完 Python 记得 rm -rf app/__pycache__，旧字节码会把「已改」掩盖成「没改」。
一条自查口诀：sign_ts 拿来比较的那个数，和契约里的容差，是同一个时间刻度吗？

七、可复现命令速查

git checkout 2026-10-08-0000
cd scenario/2026-10-08-0000
docker compose up -d --build
docker compose exec -T notifyd bash ops/apply_fix.sh --restore   # 打回问题态
docker compose exec -T notifyd bash ops/repro.sh                 # RESULT: BAD
docker compose exec -T notifyd bash ops/verify.sh                # PASS=9 FAIL=9
docker compose exec -T notifyd bash ops/apply_fix.sh             # 应用修复
docker compose exec -T notifyd bash ops/verify.sh                # PASS=18 FAIL=0 / RESULT: OK
docker compose exec -T notifyd python3 client/notify_probe.py    # RESULT: OK