早上十点我照例连上服务器跑了那条每晚都会跑的 SQL查一下过去 12 小时的成交账本。结果很干脆支出合计 ¥0.00。看到这个数我心里咯噔一下——这套常驻循环是我自己维护的行情盯盘程序挂在 WebSocket 长连接上收实时行情命中策略就自动下单每笔成交写进 SQLite 账本同时每 30 秒写一次心跳。按它一贯的脾气市场再清淡一夜下来三四笔小单总是有的。零支出只有两种可能要么真的没机会要么系统压根没在跑。我顺手又查了心跳表最后一次心跳停在昨晚 22:31:07。也就是说从 22:31 到今天早上 10 点整整 11.5 小时这个常驻循环既没有成交也没有心跳日志安静得可怕。更诡异的是进程还在TCP 连接看着也在。这篇就是完整的事故复盘我是怎么从账本里那串零出发一层层查到根因再把这个隐患彻底修掉的。如果你手上也跑着爬虫、监控、自动任务、交易机器人这类常驻循环服务这套排查思路和修复方案可以直接抄作业。1. 事故现场一条 ¥0.00 查询记录里的异常信号1.1 这个常驻循环本来在干什么先交代这台机器的背景。程序本身不复杂跑在一台 2C4G 的云主机上技术栈是 Python 3.10 加websocket-client库本地落一个 SQLite 数据库用 systemd 托管。逻辑一句话就能说清主进程开一个while True通过 WebSocket 长连接订阅交易所的实时成交频道每收到一条 tick 就解析并跑一遍策略判断命中条件就下一笔单成交回调里把金额写进trades表每处理完一轮更新一次heartbeat表的时间戳。为什么当初选 WebSocket 长连接而不是轮询因为行情这类数据实时性要求高同样延迟下长连接省去反复握手开销而且对连上就持续推的消息模型来说长连接是最自然的选择。但长连接有一个隐形成本它是有状态的。轮询接口的话这次请求失败了下一次请求自然就恢复了长连接一旦中间某一个状态没接上后面可能就一直处于看似正常、实则残废的状态。这个取舍现在回头看就是事故的伏笔。事发前这套程序已经连续跑了快两个月中间重启过两三次都是因为服务器例行维护。我一度觉得它很皮实稳定到让我放松了对它会以什么姿势挂掉的想象力。1.2 ¥0.00 的两种解释真的没机会 vs 系统根本没跑例行检查用的 SQL 很简单就是想看看昨晚有没有成交SELECT COUNT(*), COALESCE(SUM(amount), 0) AS total_expense FROM trades WHERE created_at datetime(now, -12 hours);结果自然是0, 0.00。但我没有被这个零直接吓到。零本身不代表故障策略是条件触发行情窄幅震荡的时候条件长期不满足、一单都不成交完全是正常状态。要区分没机会和没在跑得看另一个信号——心跳。我把两件事放到一起看trades表过去 12 小时 0 条记录支出合计 0.00heartbeat表最后一次updated_at是 22:31:07距今 11.5 小时。这个组合就很不对劲了。哪怕一个策略条件都没满足主循环每 30 秒也该写一次心跳。心跳断了说明主循环在正常跑这件事本身已经不存在了。所以真正的异常信号不是 ¥0.00而是成交为零 心跳过期同时出现。提示判断系统有没有在干活不要只盯业务结果成交/支出。结果为零可以有无数合理原因但进程级信号心跳、最后处理时间戳过期一定有问题。1.3 三类故障模式崩溃、挂起、静默假死在动工具之前我在脑子里把常驻循环可能挂掉的姿势过了一遍列了个对照表方便后面按图索骥故障模式进程状态日志表现典型原因发现难度崩溃进程直接消失大概率有 traceback未捕获异常、OOM 被杀低systemd 能发现并重启挂起进程还在突然无新日志阻塞在无超时的 I/O、死锁高进程看着还活着静默假死进程还在且循环照转日志正常但业务不执行条件永远不满足、continue 路径错误最高只有业务信号能暴露这次的症状组合是进程在、日志停了、心跳停了。这不属于崩溃更像挂起但挂起也有好几种挂法。我先记下这个分类然后在排查过程中时刻提醒自己不能上来就下结论要用证据一层层排除。2. 层层取证日志、进程、网络栈的交叉验证2.1 第一层业务日志的戛然而止排查第一步永远是看日志。我直接打开程序日志看尾部tail -200 /var/log/market_bot/app.log时间线还原出来是这样的22:30:55 及以前正常输出有 tick 日志、有心跳日志22:31:03出现一行ERROR 连接被关闭正在重连...之后什么都没有了既没有重连成功也没有后续的心跳。日志戛然而止本身就是超高价值的线索。程序用的 Python 标准logging级别是 INFO文件加控制台双输出。如果进程还在正常循环哪怕什么都没做心跳写入的动作也会留下痕迹。整条日志从某个时间点彻底消失说明执行流卡死在某个位置根本没有走完一轮。这里有个经验我后来跟同事也强调过没有日志不等于没有事情发生。对常驻循环来说日志从哪个时间点彻底消失那个时间点前后通常就是事故发生的窗口。所以我没有盯着日志继续猜而是立刻去看进程这一刻到底在等什么。2.2 第二层进程活着但线程状态出卖了它先确认进程状态ps aux | grep market_bot top -p $(pgrep -f market_bot)结果进程还在PID 没变启动时间两个月前CPU 占用 0.0%内存正常没有明显的泄漏迹象。CPU 为 0 不代表死了也可能是在等 I/O。我把 strace 挂上去看系统调用strace -p $(pgrep -f market_bot) -tt -f输出里一个接一个的是同一类东西进程阻塞在recvfrom(6, ...)这类系统调用上fd6 正是它当前的 socket。说明进程不是死了而是停在socket 读操作上等一个数据包——而这个数据包一直没有来。这一步基本确认主进程活着执行流卡在 socket 读等待上。接下来的问题是是服务器没发数据还是这个连接本身已经废了。这两个原因的处理方式完全不同必须进一步取证。2.3 第三层网络连接 ESTABLISHED数据却一滴都不来查看 TCP 连接状态ss -tnp | grep market_bot结果很有意思ESTAB 0 0 172.16.8.10:51430 203.0.113.7:443 users:((market_bot,pid1234,fd6))TCP 层是 ESTABLISHED客户端端口 51430对端是行情服务器的 443。fd6 正好和 strace 里的 socket 对上了。第一反应是连接还在可能是行情服务器停推了。但可能不能当结论。我写了一个最小测试脚本在同一台机器上重新连一次走标准的连接 订阅流程from websocket import create_connection import json ws create_connection(wss://api.example-market.com/v1/market, timeout5) ws.send(json.dumps({op: subscribe, topic: btcusdt.trade})) print(ws.recv()) # 立刻就能收到一条行情或 ack运行结果数据秒到。这个测试直接排除了服务器故障和市场无行情的可能——服务器好端端的数据也一直在推唯独我这边的常驻进程收不到。两边交叉一对比结论开始清晰不是网络断了不是服务器不推了而是我这个连接的业务会话上下文丢了。2.4 最小复现把 bug 从怀疑变成实锤到了这一步我已经有明确怀疑方向重连逻辑有问题。但排查不能停在我怀疑得用最小化代码把问题稳定复现出来才算实锤。我照着原程序的主循环抽了一个最小版本连接 → 订阅 → 收到数据 → 遇到断开异常就重连 → 继续读数据。然后手动触发一次连接断开观察重连后的表现。结果非常干净手动断开后客户端日志打出连接被关闭正在重连重连成功TCP 显示 ESTABLISHED但之后recv()一直阻塞一条数据都没有在循环重连逻辑里补上重新发送订阅消息这一句数据立刻恢复。复现成功。原程序在重连之后确实漏掉了重新订阅。22:31 那一次连接被关闭大概率是网络抖动或对端主动断链触发重连本身是成功的但少了订阅这个动作新连接就成了通而不话的空壳。之后 11.5 小时程序一直泡在recv()里等一个永远不会来的数据包。提示没有最小复现闭环的根因分析都只能算猜测。哪怕方向再对也一定要用一段能稳定复现问题的代码去验证再动手改。不然改完了你都不知道是改对的还是撞对的。3. 根因复盘重连成功却忘了重新订阅3.1 代码缺陷重连分支里少了一行根因落在主循环的异常处理分支。原始代码逻辑大概是这样的def run(): ws create_connection(WS_URL, timeout5) ws.send(SUB_MSG) # 只有首次连接时订阅了 log.info(connected and subscribed) while True: try: data ws.recv() process_tick(data) except WebSocketConnectionClosedException: log.error(连接被关闭正在重连...) ws create_connection(WS_URL, timeout5) # 重连之后直接回到 while 头部 recv() # 没有重新 send(SUB_MSG) —— 就是这一行的缺失create_connection成功返回只代表 TCP 握手和 WebSocket 升级都完成了。对行情服务器来说一个新连接默认不订阅任何频道必须显式发送订阅消息服务器才会把对应频道的数据推过来。原代码把订阅放在了重连分支之外等于重连一次就多一条空连接。更深一层的设计缺陷是recv()没有设置业务级的数据超时。连接建立时虽然传了timeout5但那是建连握手阶段的超时进入正常读循环后recv()在没有数据时会无限期等下去。正常行情下不会暴露问题一旦进入连接活着但没数据的状态它就会永远卡住连报错的机会都没有。3.2 为什么连接状态检查救不了这个场景很多人遇到这种问题第一时间会想到加连接检查比如定时 ping、或者查询 WebSocket 连接状态。但这个场景恰恰是连接检查通过也没用。打个比方你给客服中心打电话号码拨通了信号满格但你始终没说你要找谁、办什么事。电话那头线路是通的只是两边都没人说话就这么干耗着。TCP 的 ESTABLISHED 只表示通话建立订阅消息才是你说出了需求。服务器不是你的聊天对象它只是个守规矩的接线员你不说要什么它就永远等你开口。所以长连接的健康检查必须分两层看传输层TCP 连接在不在、WebSocket 握手完成没有——这层只能证明线路通业务层频道订阅还在不在、鉴权 token 是否有效、会话要不要续约——这层才能证明业务通。只检查第一层就像那句信号满格永远兜不住业务层的静默失败。3.3 疏忽链条从代码到监控缺了哪几环代码少一行是直接原因但 11.5 小时没被人发现说明从代码到监控整条链路上还有好几个洞。复盘时我把它们列成了表环节事发时状态本应起到的作用实际缺了什么代码健壮性recv()无业务级超时长时间收不到数据应主动报错并重连缺等不到数据就判死的机制进程守护systemdRestartalways进程崩溃时自动拉起进程没崩守护完全没触发业务心跳每 30 秒写一次给外部留一个活没活着的信号写了但没有任何人读取和监控告警系统无心跳过期时立刻通知人完全没有日志监控日志落盘错误关键字触发告警只有落盘没有消费这几个环节但凡有一个堵上事故窗口都不会被拉到 11.5 小时。最讽刺的是第三环心跳表明明每 30 秒写一次但它的存在只有写入者知道没有读取者。等于你每天都给自己设了闹钟但闹钟从来没装电池。4. 修复三件套业务心跳、进程守护与主动告警4.1 第一板斧代码层加入业务超时与完整重连流程先修代码这是根子。改动有四个要点recv()设置业务级超时比如 30 秒超时后不主动重连也要打日志把订阅封装成独立函数重连成功后必须调用连接成功后等一条 ack确认业务会话真的建立心跳写入放到每轮循环的末尾用finally保证即使某次迭代异常心跳也能更新。修复后的主循环import json import logging import time import sqlite3 from websocket import ( create_connection, WebSocketTimeoutException, WebSocketConnectionClosedException, ) WS_URL wss://api.example-market.com/v1/market SUB_MSG json.dumps({op: subscribe, topic: btcusdt.trade}) DATA_TIMEOUT_SECONDS 30 log logging.getLogger(market_bot) def record_heartbeat(): conn sqlite3.connect(/opt/market_bot/data.db) conn.execute( INSERT INTO heartbeat(updated_at) VALUES (?), (int(time.time()),), ) conn.commit() conn.close() def subscribe(ws): 连接后必须调用订阅频道并等一条 ack 确认业务会话建立。 ws.send(SUB_MSG) # 多数服务器会回一条订阅确认或者立刻推第一条行情 # 这里做一次短超时 recv确保订阅真正生效 ws.settimeout(5) ack ws.recv() log.info(subscribe ok, first message: %s, ack[:80]) def ensure_connection(ws): if ws is None: ws create_connection(WS_URL, timeout5) subscribe(ws) return ws def run(): ws None while True: try: ws ensure_connection(ws) ws.settimeout(DATA_TIMEOUT_SECONDS) data ws.recv() process_tick(data) except WebSocketTimeoutException: log.warning(%s 秒未收到行情判定链路异常主动重连, DATA_TIMEOUT_SECONDS) ws.close() ws None except WebSocketConnectionClosedException: log.error(连接被关闭准备重连) ws None except Exception: log.exception(未知异常本次迭代跳过) # 堆栈必须打出来 finally: record_heartbeat() # 心跳独立于业务是否成功只代表主循环还活着改动的逻辑recv()超过 30 秒没有数据就认定为链路异常主动断开重连重连后一定走subscribe()把订阅补上finally保证无论这次迭代有没有异常心跳照写。外部监控拿到的信号始终是主循环到底还转不转。提示except Exception里一定要用log.exception而不是log.error(...)。两者差别是前者自带堆栈后者只有一行字。静默失败事故里很多根因线索就是被.error(报错)这种写法吞掉的。4.2 第二板斧systemd 的 Watchdog 让假活也能被发现代码修好后进程如果崩溃systemd 的Restartalways会自动拉起。但更隐蔽的是进程活着、业务死了——systemd 默认认为进程在就等于服务在。要堵住这个洞用 systemd 自带的WatchdogSec让进程主动向 systemd 汇报健康状态。服务单元文件如下[Unit] DescriptionMarket Bot Service Afternetwork-online.target [Service] ExecStart/usr/bin/python3 /opt/market_bot/main.py Restartalways RestartSec5 WatchdogSec60 [Install] WantedBymulti-user.target进程内每轮循环用sd_notify喂狗import systemd.daemon def run(): while True: try: ... finally: record_heartbeat() systemd.daemon.notify(WATCHDOG1) # 告诉 systemd我还活着且工作正常WatchdogSec60的含义是如果 60 秒内 systemd 没收到WATCHDOG1就判定服务卡死按失败处理触发Restartalways重启。这样recv()静默阻塞这类假活也能被进程级守护兜住。如果没在用 systemdsupervisord 也有类似方案autorestarttrue配合进程内部状态上报或者干脆用外部检查脚本代替思路完全一致。4.3 第三板斧外部看门狗 群机器人告警进程级守护能解决进程没死但不干活的自动恢复问题但它解决不了人被通知到的问题。真正把 11.5 小时压缩到几分钟的是业务级看门狗加告警。我在机器上加了一个每 60 秒跑一次的外部脚本读心跳表如果心跳过期超过 180 秒就向企业群机器人发告警并可以顺势触发一次systemctl restart market_bot#!/usr/bin/env python3 heartbeat_guard.py —— 业务级看门狗异常时告警并可选重启。 import sqlite3 import time import requests DB_PATH /opt/market_bot/data.db ALERT_WEBHOOK https://open.feishu.cn/open-apis/bot/v2/hook/xxxx MAX_IDLE_SECONDS 180 def main(): conn sqlite3.connect(DB_PATH) row conn.execute(SELECT MAX(updated_at) FROM heartbeat).fetchone() conn.close() if not row or row[0] is None: return idle_seconds int(time.time()) - int(row[0]) if idle_seconds MAX_IDLE_SECONDS: return message { msg_type: text, content: { text: [market_bot] 心跳中断 {} 秒超过阈值 {} 秒请检查。.format( idle_seconds, MAX_IDLE_SECONDS ) }, } requests.post(ALERT_WEBHOOK, jsonmessage, timeout5) if __name__ __main__: main()配合 crontab* * * * * python3 /opt/market_bot/heartbeat_guard.py告警渠道不管是钉钉、企微还是飞书群机器人原理都一样——把带时间线的文本推到群里让人第一时间看见。我个人的建议是告警文案至少包含三样东西服务名、故障持续了多久、下一步能做什么。别只发服务异常四个字收到告警的人还得再查半天。另外我还加了一个每日账本摘要任务每天早上 10 点把过去 24 小时的成交笔数、支出合计、心跳最近时间发到群里。哪怕实时告警有覆盖不到的地方每天一份体检报告也能把静默失败的最坏暴露时间压到 24 小时以内。4.4 修复后的验证过程改完代码、上了 systemd 和看门狗之后不能直接宣布完工得做一次故障演练。我在测试环境里手动制造了几种故障观察整条自愈链路用防火墙规则丢包模拟网络中断iptables -A OUTPUT -d 203.0.113.7 -j DROP30 秒后recv()超时代码主动断开并重连重连后自动重新订阅第一时间收到行情心跳恢复把heartbeat_guard.py的阈值临时调低模拟心跳中断确认告警消息真的推到了群里直接 kill 进程模拟崩溃确认 systemd 在 5 秒内拉起服务并且新进程完整走了一遍连接 → 订阅 → 出数据的启动流程。三条链路全部验证通过。之后在线上跑满 24 小时观察心跳连续、账本正常、无异常日志。修复闭环。5. 沉淀成规范常驻任务上线前的默认检查项5.1 五个默认配置缺一不可这次事故之后我把常驻循环类服务的上线标准定成了五条。任何新项目都要先过这一遍不过不许上线检查项具体要求防住的是什么I/O 超时所有外部请求、socket 读都必须有超时阻塞挂起会话重建重连后必须重新完成鉴权/订阅/握手连接通了但业务不通业务心跳每轮循环都写心跳独立于业务成败假活无法被外部感知进程守护systemd/supervisord 兜底崩溃拉起进程消失无人管主动告警心跳过期必须通知到人人不知道事故窗口无限拉长这五条看着都很基础但基础和默认配置是两码事。基础是一句话默认配置是骨架代码已经写好了新项目直接继承就行。比如 I/O 超时这一条我现在写requests.get()一定会带timeout()写 socket 一定会settimeout成了肌肉记忆。不是因为我多自律是因为吃过亏。5.2 排查静默失败最快的切入点是最后一次有用动作如果你手上现在就有一个说不清哪里不对的常驻任务我的建议是别急着读代码。先问自己一个问题它最后一次做有用的事是什么时候这个时间点前后十分钟内的日志、状态变化、异常记录就是案发现场。这次事故里22:31:07 是最后一次心跳22:31:03 是最后一条连接错误日志。两个时间点紧紧挨着等于把案发过程直接写在了脸上连接异常 → 触发重连 → 重连成功 → 业务会话没建立 → 从此沉默。如果没有最后一次有用动作这个锚点对着两个月的日志翻线索效率要低一个量级。这个方法论后来帮我处理过一次类似的采集任务假死同样是先找最后一条有效日志五分钟就锁定了出问题的上游接口。5.3 一点个人体会说实话这次最让我警醒的不是代码 bug 本身——少写一行订阅属于典型的手滑。真正让我反思的是事情发生之前我花了不少时间做进程级稳定性工作开机自启、崩溃重启、日志轮转做了很多但全都是在围着别死做文章几乎没有围绕别假活做任何设计。而常驻循环这类程序假活比死危险得多真的死了会有人管假活是全世界都以为它好端端地跑着。现在我在启动流程里还加了一件事服务起来之后先做一次连通性自检订阅成功且等到第一条数据才对外报告就绪否则主动退出让 systemd 重试。这样一来从进程拉起到业务可用之间的那段时间也是可验证的而不是进程起来了就等于好了。这套心跳 看门狗 告警三件套我现在连爬个网页的小脚本都会默认装上。多花二十分钟省下的可能是一个通宵排查加一整天客户投诉。这笔账怎么算都划算。
