1. 引子凌晨三点十七分的陌生告警凌晨 3 点 17 分 28 秒几乎每隔一天归档日志里就会出现一次同样的告警。时间稳定得吓人前后误差不超过两秒。我在做历史日志迁移时接触到这批 2010 年的数据——sess_srv 是当时线上运行的会话状态服务维护一批 TCP 长连接上的会话连接断开时负责收尾清理。迁移本来只是把 syslog 灌进新的检索平台顺手做了一次消息模板聚类结果所有告警都能在源码对应的日志语句里找到归属唯有一条落空2010-11-02 03:17:28.304 32241:32241 WARN session.cpp:124 session_finalize: rsv not empty (count7, last_task0)我在整个代码仓库里grep -R rsv not empty零命中。git grep --all把全部分支翻遍还是零命中。可日志里明明白白写着session.cpp:124说明编译进生产二进制的这份session.cpp和源码仓库里现在的这份根本不是同一份。这就留下了一处可疑的痕迹程序运行时的行为与我手上掌握的全部源码都对不上。这篇记录的是我如何沿着这条痕迹做了一次完整的代码回溯——从二进制考古开始到反汇编、调用链回溯、git 历史翻找再到复现验证和收尾处理。整个过程下来你会发现所谓回溯代码很多时候不是在逆向所谓的恶意攻击而是在还原一段被遗忘的时间线。这是《回溯代码》系列的第二集上一集我们处理的是服务启动阶段的段错误这次则是另一类问题一段生产环境里真实运行、但源代码里完全不存在的逻辑。2. 先确认二进制身份怎么判断版本号相同产物不同2.1 版本号相同md5 不同排查这类问题时第一个容易踩的坑就是依赖版本号判断生产二进制 源码仓库状态。那台 2010 年的 sess_srv 有个启动 bannerSESS_SRV 3.2.1 BUILD_TS20100915而仓库里 3.2.1 这个 tag 对应的源码理论上构建出来的也是SESS_SRV 3.2.1。单看版本号二者一致但md5sum一对比立刻分道扬镳项目生产二进制重新构建产物md5c4e321...98a40f...版本号3.2.13.2.1构建时间字符串2010091520101120同样的版本号不同的哈希。说明生产上跑的二进制不是从当前仓库的 3.2.1 源码构建出来的甚至可能不是从任何一条已被记录的提交构建的。这一步很关键原因在于正因为版本号没有跟着代码变化团队里没有任何一个人会注意到生产行为和源码已经脱节。这是痕迹能够潜伏一年多的直接前提。如果当年构建系统把 git 修订号嵌进版本字符串这种异常会在发布对比的那一刻就被发现。2.2 没人认识的日志字符串先问二进制既然源码里找不到那个字符串下一步就要直接问生产二进制本身。老规矩先做只读侦查不急着上 gdbstrings -t x /export/servers/sess_srv/bin/sess_srv | grep rsv not empty strings -t x /export/servers/sess_srv/bin/sess_srv | grep last_task file /export/servers/sess_srv/bin/sess_srvstrings加上-t x可以拿到字符串在文件里的十六进制偏移配合 ELF 节区信息能定位到它处在.rodata的位置。file的输出确认了这是 32 位 ELF 可执行文件。接着用nm拿到函数入口用objdump反汇编出来看逻辑nm -a sess_srv | grep session_finalize objdump -d --start-address0x08054a20 --stop-address0x08054c00 sess_srv finalize.asm那个年代内部服务普遍带符号发布nm直接给了入口地址省去了从裸机器码猜函数名的功夫。readelf -n sess_srv看完两个细节我心里基本有数了这个二进制没有 build-id注释段写着GCC: (GNU) 4.4.5。没有 build-id 意味着 ELF 文件本身没有唯一身份标识厂商和构建信息缺失这让产物与源码一一对应彻底失去抓手。GCC 4.4.5 这个版本倒与 2010 年第三季度的服务器环境对得上。2.3 反汇编里多出一块不属于源码的代码拿到session_finalize的函数地址后我用addr2line做了一次地址到源码行的映射addr2line -e sess_srv 0x08054b10它吐回session.cpp:124。这个行号和告警日志里__LINE__打出来的 124 完全一致。再往外圈一小块区域映射到的源码行号一直延续到 142 行而当前源码里session_finalize只写到 96 行就结束了。把反汇编里那段多出来的代码摘出来简化一下长这样0x08054b10: 83 7d f4 00 cmpl $0x0, -0xc(%ebp) ; rsv_index 0x08054b14: 74 20 je 0x08054b36 ; 为 0 则跳过 0x08054b16: 8b 45 f8 mov -0x8(%ebp), %eax ; session 指针 0x08054b19: 8b 80 1c 04 00 00 mov 0x41c(%eax), %eax ; g_task_table ... 0x08054b30: e8 ... call log_printf ; 打印 rsv not empty 0x08054b36: c9 leave这不是编译优化产生的差异而是真正的逻辑增量函数里平白多了一个判断、一个遍历、一个日志分支。而它引用的g_task_table是个文件内的 static 全局变量符号在nm里是小写t说明这段逻辑完全没有对外导出像是被人直接塞在里面、不想让外部察觉的一样。到了这一步源码里找不到的日志已经变成源码里找不到的函数。下一步要解决的是这个函数到底在清理什么以及它为什么偏偏在凌晨三点十七分被触发。3. 顺着调用链回溯rsv 字段与一段被删掉又复活的逻辑3.1 rsv 是什么翻结构体定义才明白要读懂那段反汇编得先弄清楚rsv字段是什么。2010 年的session.h里结构体定义很朴素struct session { int fd; int state; int rsv; /* 保留的任务计数 */ task_node *tasks; /* 实际任务链表 */ int last_task; };注释写着保留的任务计数但从 3.2 分支开始rsv实际上已废弃新代码不再依赖它分配任务槽位任务的增删都走tasks链表。反汇编里那段逻辑却还在用rsv判断是否有未清理任务显然是旧设计留下的行为残影。正常会话收尾时rsv应该是 0任务链表为空所以那段多出来的逻辑会直接je跳过。只有当某些异常路径让rsv非零地进入session_finalize时警告才会炸出来。3.2 用 gdb 抓真实调用链为什么偏偏是 03:17静态反汇编只能说明存在这段代码不能说明谁在什么时机调用它。为了搞清楚 03:17 这个诡异的触发时机我在一个可控的测试环境里布置了同样的二进制按历史日志提供的线索模拟了一次上游网关的定时维护。方案是在实时系统里对session_finalize下断点等告警路径触发后直接backtrace(gdb) break session_finalize (gdb) continue Breakpoint 1, session_finalize (s0x8a4c2c0, rsv_index7) at session.cpp:124 (gdb) bt #0 session_finalize (s0x8a4c2c0, rsv_index7) at session.cpp:124 #1 0x08057b30 in abort_session_by_peer (s0x8a4c2c0) at session.cpp:177 #2 0x0805d1a0 in peer_reconnect (link_id3) at peer.cpp:340 #3 0x0806f010 in event_loop () at main.cpp:88这条调用链把时间疑点解释清楚了每天 03:17 前后上游网关做例行维护会主动断开一批旧连接并重连。peer_reconnect触发后服务要清理所有建立在这个连接上的会话走abort_session_by_peer最终进入session_finalize。正常情况下被中断的会话任务已经被事件循环提前处理完rsv归零但 2010 年新上线的一版客户端协议存在消息乱序会把任务下发和会话确认的顺序调换导致 session 状态机里rsv被加一却没有立刻减一。流程一被中断残值就留在了session_finalize的门口。这就是典型的栈回溯场景问题不在告警这一层而在调用链上方的peer_reconnect以及更上层的协议乱序。只看日志的话会一直以为session_finalize有 bug实际它只是在给上游的乱序买单。3.3 git 历史里找到了被蒸发的提交接下来是代码考古最有意思的一步既然生产二进制里有这段逻辑源码仓库里却没有那这段逻辑总有一个来源。我把注意力放到 2010 年第三季度的提交历史上git log --all --oneline -- session.cpp git reflog show --dateiso git fsck --lost-found在git reflog的一条末端记录里找到一个早已被删除的分支2010-hotfix-session其上有一个提交7e91c4d提交信息写的是drain rsv counter before finalize。git show 7e91c4d的内容和反汇编出来的逻辑几乎一一对应遍历rsv计数范围内的残留任务释放掉再打一条警告日志。时间线拼出来是这样的时间事件2010-08-12主干提交ca84201删除了旧的rsv计数路径2010-09-03有人基于旧状态拉分支写了drain_stale_tasks补丁2010-09-15生产二进制从该分支构建并部署banner 日期即BUILD_TS201009152010-09-27分支被删除补丁从未合并回主干源码从此蒸发2010-11 起新客户端协议上线乱序概率上升告警频率开始抬头也就是说那段可疑的痕迹不是攻击者埋的也不是后门而是一个没有走正规流程的线上热修复。团队里查了一圈没人记得这件事。所有人都默认生产二进制和主干源码等价这种代码漂移在长寿命服务里太常见了。3.4 先排除恶意再谈宿命当然面对一段反汇编出来的陌生逻辑第一反应必须是在良性热修复和可疑恶意代码之间做个快速排查。我当时的检查路径是是否有网络外联行为反汇编里没有socket、send、connect调用。是否有文件写入或敏感的 shell 调用只有log_printf一条日志出口。是否被导出成公共接口nm里是小写t即文件内 static外部无法按符号调用。逻辑语义是否自洽遍历rsv残留并释放符合防御式清理的动机。四条硬件排查加一条语义分析结论基本能定下来这是一段防御性质的历史补丁不是外联后门。但这个结论不能靠猜——后面必须用复现验证闭环这也是第四步要做的事。4. 复现验证让老痕迹在可控环境里再露一次面4.1 老环境的坎缺库、缺工具链、缺时代感复现的前提是我先把 2010 年那台机器的运行环境搭出来。刚开始我直接在现网开发机上跑生产二进制结果弹了这么一句error while loading shared libraries: libssl.so.0.9.8: cannot open shared object file这句和 Windows 上常见的由于找不到 msvcp140.dll无法继续执行代码本质上是同一类问题二进制依赖的运行时库已经不在当前环境里。2010 年的 sess_srv 是 32 位编译依赖老版 OpenSSL、老版运行时年代感拉满。解决办法是搭了一个基于旧发行版镜像的容器装回 GCC 4.4、binutils 2.20 和配套的 32 位运行库。这一步千万别省用新工具链强行重编老代码编译器优化行为、结构体对齐、库函数签名都可能发生变化最后对比 md5 时你会得到一堆假阴性/假阳性。4.2 把缺失源码补回去让 md5 闭环复现这件事的好处是它逼着我把猜测变成证据。我从 git 分支提交7e91c4d里拿回那段drain_stale_tasks合进当前 3.2.1 源码用老工具链重新构建。构建完第一件事就是比对md5sum sess_srv /export/servers/sess_srv/bin/sess_srv两边哈希相等。这段逻辑确实就是生产二进制里那段逻辑的来源。此时我已经不是通过反汇编猜测它可能长这样而是确认它就是长这样。然后再跑一轮带消息乱序的测试用例模拟上游网关定时维护。断点重新触发rsv not empty (count7, last_task0)的日志如期出现调用链也和反汇编、历史日志三方对上。到这里可疑的痕迹的来龙去脉已经闭环。4.3 复现暴露出的真正问题不是代码坏了是链路断了复现完成之后我再回头看那个版本号既相同又不同的尴尬意识到真正危险的并不是这段额外逻辑本身而是整个构建链路上缺少了可追溯性。2010 年的构建脚本没有嵌入 git 修订号发布流程里没有源码树必须干净的检查合并纪律也允许热修复走野路子。生产二进制的BUILD_TS只能告诉我们什么时候构建的不能告诉我们从什么代码构建的。这个结论直接决定了第五步的处理方案——不是简单删掉那段代码而是把追溯能力补回来。5. 处理方案与给后来人的排查手册5.1 三路取舍入库、回滚、还是归档面对生产有、源码无的差异通常有三条路可走方案适用场景我的取舍把热修复正式合入源码行为对线上稳定有实质帮助选择此方案用干净源码重建并覆盖生产行为属于历史包袱否因为缺少清理会导致任务残留保留二进制、写清差异归档案无法确认行为来源否因为 md5 已闭环最终我选择的不是回到源码的干净状态而是让源码长成和生产一致的样子——把drain_stale_tasks正式合回同时补上边界检查、注释和测试用例记录它存在的业务原因。对已经稳定运行多年的线上服务宁可让代码库明明白白地丑也不要让线上行为悄悄地和代码库分家。5.2 代码审计中的快速检查清单整理一下这次排查沉淀出的动作以后遇到类似找不到日志来源的痕迹可以按这个顺序推进先在消息模板层聚类列出所有源码中无归属的日志模板。对比线上二进制与 CI/发版产物md5sum、build-id、strings里的编译时间。检查二进制调试信息里的源码路径addr2line指到的源码行号若与日志里不一致立刻集中关注。用git log --all、git fsck --lost-found、git reflog把孤儿分支和已删提交捞出来。用 gdb 在触发条件上打断点拿backtrace把何时调用与为何触发钉死。先做恶意代码排除网络、文件、shell、导出符号再做良性热修复定性。5.3 一点个人体会代码考古做到最后收获往往不只在某一处 bug。这台服务提醒我的事很简单构建系统里一定要记录从哪个提交构建-Wl,--build-id必须开启动日志里要打出完整修订号版本号字符串不能只写3.2.1这三个字。那条凌晨三点十七分的告警之所以能潜伏一年多不是因为它藏得深而是因为我们没有给它留下一把能对上号的钥匙。至于那段被蒸发的代码后来我给它补了充分的注释和单测正式合并回主干。它从一个没有身份的野补丁变成了有史可查的正常代码。代码里最可疑的痕迹往往不是别人故意留下的陷阱而是一个团队忘了收尾的半成品——只要沿着调用链和提交历史认真回溯总能找到它原本的主人。