记录一次重连风暴的排查（2026-09-09）

心跳超时说的从来不是"连接断了"，而是"没人告诉它还活着"

smart_money_trader 的日志里堆着几千次心跳超时。表面看是网络不稳，但一台机器如果真烂到每两分钟断一次，它早该被停掉了——交易进程却一直在跑，仓位也没乱。所以这次不猜，先把它拆开看。

这一天的活，从头到尾只有一件事：把"到底是谁在超时"查清楚。 修不修得好是第二步。

先看清风暴的形状

先把原始日志预解析了一遍，而不是凭印象判断。

reconnect_preanalysis.json 记录的这场风暴，时间跨度是 2026-08-18T22:00:00 到 2026-09-05T13:57:21。进程侧的 _HEARTBEAT_TIMEOUT 是 120.0 秒，stall_profile.jsonl 里的分析确认了一件事：重连的节奏大约是 每 130 秒一次——正好对上"超时阈值 + 重连周期"。

预解析里还埋着一个更早的坑。第一次统计出来的心跳数是 4355，但这个数字是错的：它把 470 次 [SIGNAL] 守护进程的心跳超时，和 3885 次 [sm_trader] 的心跳超时混在了一起。两个是完全不同的进程，各有各的超时逻辑。混在一起数，等于一开始就把问题看歪了。

这一步没什么技术含量，但它决定了后面所有判断的口径。先把数拆对，再谈根因。 几千次真超时里只要有一小撮来自另一条路径，你按总量去猜，方向就是错的。

三份假设，和一条"不许重启"的规矩

诊断没有直接上手改代码，而是先委托出去跑了一轮。用免费档的 hy3 跑了一个 10 轮的任务，端到端大约 270 秒，要求它只做一件事：产出按置信度排序、带代码引用、且能用只读方式验证的假设。

这一步卡了两条硬规矩：

日志里的错误计数、时间戳、代码行号，必须从源码和原始日志里核实，不许推断
每条假设的确认测试必须是只读的，不许重启进程、不许改运行状态

理由是交易进程当时还活着。在活的进程上动手验证根因，是拿实盘仓位当实验品。规矩定死：没确认根因之前，一行运行中的代码都不碰。

最后拿到 3 条排序过的假设，每一条都配了一个不用重启就能验证的测试。这个约束比它看起来重要——**它逼着每一条假设都必须"可被证伪"**，而不是"听起来有理"。一个说得出口、却验不了的假设，在活着的进程面前等于零。

H1：缺符号的空响应

第一条假设落在 _get_mid_price 的第 485 行：

all_mids() 返回是成功的，但这次查询的那个 symbol 恰好不在响应里——这个分支没有调用 record_success()。

后果很直接：_last_success_ts 不刷新，于是 should_reconnect() 每约 120 秒就会自己触发一次，把好好的连接掐掉重连。这不是网络问题，是记账问题。

修复也简单：在这个"响应成功但符号缺失"的分支里补上 record_success()，让这种"健康但为空"的响应也能刷新成功时间戳。改完之后我把 diff 对着基线文件核了一遍，确认只动了预期的那 7 行，其它逻辑一行没碰。

H1 之后：数字没动

改完代码，进程下次自然重启就会带上这个修复。但没有立刻宣布胜利，而是先做了一轮 30 分钟的观察。结果很难看：

结论是 FIX_NO_EFFECT
修复后的心跳超时率 0.4333/min（13/30min），对比修复前 0.0702/min（3335/48912min），比值 6.17x
风暴节奏一点没变：中位间隔修复前 127 秒，修复后 130 秒
但有一条路径确实被干掉了：mid_price_error 在 30 分钟里从 364 降到 0
坏消息是，signal_daemon_timeout_count 反而从 0.0099/min 跳到 1.83/min

翻译一下：H1 修的是真的、确实消除了一条错误路径，但它根本不是风暴的主因。 主因还压在上面，节奏该 130 秒还是 130 秒。

这件事我想记久一点——**"改完有效果"和"改完解决了问题"，是两回事。** 只看 diff 会觉得逻辑天衣无缝，只有把 30 分钟的数字摆出来，才知道自己刚擦掉的是角落里的一小块灰。

真正在跑的那条路

既然 H1 不是主因，就回到证据本身。真正的根因在第 1454 行这一带，答案是"调用位置"，不是函数本身。

_get_mid_price() 只在 if signals: 这个分支里被调用。而当时信号守护进程的心跳已经 停滞了 484 分钟以上——也就是说 signals 一直是空的，于是 _get_mid_price() 从来没被走到过，_last_success_ts 永远不会刷新。连接一直好好的，但计时器不知道，于是每隔约 130 秒就误报一次心跳超时，触发一次重连。

数字完全支持这个判断：3885/3885 次心跳超时，全部由"静默停滞"驱动；真正由 mid-price-error 路径触发的重连，只占 41/3335。也就是说，H1 修的那条路，本来就不是大头——这也解释了为什么它修得对，风暴却照样跑。

方向随之明确：让心跳的刷新不再依赖 signals 是否为空。这就是 H1 和根因的区别——H1 修的是"符号缺失"这一种空响应，而根因是"整段逻辑根本没被执行到"。

当天晚上把带这个心跳补丁的进程起了起来：新的交易进程 PID 21840 跑的就是补丁版，旧的 PID 42924 作废；改之前先把原文件备份成 smart_money_trader.py.hb2.bak.<ts>。

但补丁生效，和风暴停下，是两件事。 这一点 H1 刚教过一遍，所以这一天的记录到"补丁已上线"为止，不再往前写。

顺带查了信号守护进程

排查时被反复提到的一件事是信号守护进程的"停滞"。它和交易进程是两个独立进程，用的是两套独立的超时逻辑，这一点很容易搞混——预解析阶段就已经混过一次。

查它的方法是单独走一遍：看它最新输出的那个 signal 文件修改时间，判断新鲜度；再翻历史日志，看过去有没有停滞后自己恢复过——确认过，历史上确实出现过停滞后自动恢复、不需要人工介入的情况。

规矩也定死了：信号守护进程的心跳超时日志，不能和交易进程的心跳超时日志混在一起谈；也不能因为过去它停滞过，就默认它一定是当前交易进程超时的原因，除非有明确的关联证据。

这一天的排查落了三份记录：wb_runs/stall_profile_verdict.md、wb_runs/post-h1-verdict.md、wb_runs/hb_ping_fix_verdict.md。

最后

这天的排查分三层。

最表面的是那条被修掉的路径——H1 让 mid_price_error 从 364 降到 0，但它单独扛不动这场风暴。

中间一层是"拆开看"的方法：先预解析、再定只读验证的规矩、最后让每一条假设都能在不重启的前提下被确认或否掉。这套打法本身是可复用的——换任何一个长跑的有状态服务，都是同一套流程。

最里面一层，是 H1 那次 FIX_NO_EFFECT 教给我的东西。

H1 的逻辑当时看是天衣无缝的，改完也确实消除了一条真实存在的错误路径。但风暴没停。如果我只看 diff，我会以为自己修好了；只有把 30 分钟的数字摆出来，才看得见真正的主因还压在上面。修好一个 bug，不等于修好了你遇到的那个现象。

所以这天我没有把话说完。补丁起在了新进程上，但它到底有没有让那条 130 秒的节奏停下来，得等下一轮观察才有答案——那是第二天凌晨的事，也是下一篇的事。