Day01-09修复BUG。凌晨3:24监控告警群突然弹出红色消息正在处理另一个故障的我放下手头的事切到日志平台看了一眼——果然又是那个任务。上一次修复是在当天下午部署的也就是说间隔不到12小时这个Bug在线上环境就原样重现了。说实话看到它的时候我反而松了一口气。因为写代码的人都清楚一个Bug从“修完”到“真的修完”之间往往隔的不只是一次部署而是好几个失眠的夜晚。最怕的不是报错而是它悄无声息地消失然后在某个深夜再次出现并且这次它的触发条件变得更加隐蔽。这次能在短时间内重现至少说明监控链路是准确的问题路径是可以复现的剩下的就是把它彻底抠出来。这篇文章就围绕这次“修复—复发—再定位”的完整过程来写。我会先复盘第一次修复为什么失效再讲Bug复活的三种典型路径然后把我本次排查的完整步骤和最终方案展开。文章里的代码片段、排查命令和分析思路都可以直接套用到你自己的项目里尤其是那些“修了好几次仍然偶发”的顽疾看完你应该会有一个更清晰的排查框架。1. 修复之后再度重现凌晨3:24发生了什么1.1 这个Bug到底是什么先说清楚背景。我负责的是一个内部运营系统里的数据同步服务简单来说就是每天凌晨定时从多个上游数据源拉取数据经过清洗、转换之后写入下游数仓再更新一系列业务状态。整个链路是典型的批处理模型定时触发、逐批拉取、逐条处理、最终汇总。这个Bug的表象极其简单某个数据同步任务运行到一半就挂掉了没有异常堆栈日志里只有一条自定义的错误信息——task interrupted而这条信息是我上一次“修复”时自己加的。我说“上一次修复”是因为这个Bug早就有过苗头。最初的报错是偶发的空指针代码在一个对象判空逻辑上出了纰漏导致部分数据记录在缺少某个字段时直接抛异常任务中断。我当时认为问题很清楚既然空指针源于部分脏数据那在入口处加一个判空保护再包一层try-catch让异常不中断整个任务问题就解决了。逻辑听起来没什么问题但实际效果是任务不再以“抛异常”的方式崩溃而是变成了“静默中断”——代码走到一半总觉得哪里不对直接停了下来日志里只有我自己写的那句不痛不痒的task interrupted。凌晨3:24这次正是如此。任务在2点58分启动处理到第3批数据时中断错误日志里记录的时间点是3:24。也就是说从任务启动到中断之间隔了26分钟这26分钟里到底发生了什么日志里几乎是一片空白。1.2 第一次“修复”为什么没兜住现在回头看第一次修复犯了一个非常典型的错误把异常处理当成了容错把日志输出当成了诊断。我在入口处加上try-catch之后确实避免了异常向上抛导致任务整体失败。但问题在于我在catch块里只输出了自定义消息没有保留原始异常的堆栈信息。这就导致了一个很尴尬的局面任务确实没有“崩溃”但它也没有“完成”它只是停在了某个中间状态。而停下来的原因因为原始堆栈被吞掉了我根本无从得知。更麻烦的是这个中间状态不是空指针本身而是空指针发生之前的一系列操作。数据同步任务每处理一条记录都会先把对应行的业务状态改成“处理中”写一条日志然后执行校验、转换、落库。如果校验不通过代码里有一个提前返回的逻辑——这就是我为了“防止脏数据导致任务崩溃”而加的保护——它会在日志里留下task interrupted之后直接跳出当前批次继续处理下一条。凌晨这次中断就是某条记录的某个字段不符合预期触发了提前返回。但这里有个致命的问题那个字段可能之前就是存在的只是格式不对。我的判空代码只判断了“有没有”没判断“对不对”一旦遇到格式错误又不为空的字段既不会抛异常也不会进入判空保护而是直接走入了旧逻辑的某个分支造成状态错乱。这就是第一次修复失效的根本原因我修的是一棵树的叶子而问题长在根上。2. 为什么Bug会“复活”三条最容易被忽略的路径既然Bug已经复发就不能再像第一次那样只看表象就打补丁。我花了大半天时间分析为什么“修复后仍然重现”总结下来一个Bug反复出现往往逃不出下面三条路径。2.1 路径一只治标根因还在数据链路里第一种最常见也是这次踩进去的坑修复代码只处理了“当前这条路径的末端异常”而实际触发问题的脏数据或错误状态一直存在于数据链路里。举个例子一次空指针可能是某条记录里owner_id为null导致的。在入口处加一个if (ownerId ! null)的判断确实能让任务“跑下去”但owner_id为什么会为null是上游接口漏传是字段映射错误是历史数据导入时就没填这些问题不解决那批数据就会永远躺在系统里下次某个环节稍微变一下又会出问题。这次凌晨的触发条件就是这样某一条历史数据的日期字段格式是yyyy/M/d而代码里用的是yyyy-MM-dd解析。解析结果是DateTimeParseException但我的判空代码只看“字段是否为空”压根没有走到格式校验那一步。数据一直在问题也一直都在只是第一次空指针把它掩盖了第二次判空又把它绕过去了。2.2 路径二修复本身带来了新的竞态窗口第二种情况更隐蔽修复Bug的代码在修改状态或数据的顺序上引入了新的竞赛条件。大多数数据同步任务都有类似的流程先查状态再更新状态为“处理中”然后拉数据处理最后更新为“完成”。如果在某个环节里查询状态和更新状态不是原子的两个并发实例就可能同时读到“未处理”状态然后同时开始处理同一条数据最终导致重复写、锁等待、甚至死锁。上次修复时我把判空保护加在了“更新状态”之前。这样做的副作用是一旦遇到脏数据代码会提前返回而状态已经在上一步被改成了“处理中”如果后续没有一套回滚机制这条记录就会一直卡在处理中状态——下次任务启动时会被当作“正在处理”而跳过数据永远也不会被真正处理。如果说这次凌晨3:24的日志里有什么异常那就是被跳过的记录在数据库里留下了一大批“半处理”状态的数据。系统没有报错但数据是正确的这比报错更难查。2.3 路径三环境差异让修复只在“部分地区”生效第三种路径在这类凌晨任务里也极其常见尤其在多实例部署的环境里。如果你的服务部署了多个实例而且线上还残留着旧版本的实例那么你用新代码修的Bug只会在新实例上“生效”。如果负载均衡恰好把某次凌晨的定时任务分给了旧实例Bug就会原样复发。日志里排查的时候最容易被误导的地方就在这——你明明查到了异常日志可当你翻看代码时最新的代码里根本找不到对应的抛出点。凌晨3:24这次我在初期排查时也一度怀疑是这个问题。后来我专门核对了所有实例的部署时间和版本确认全部运行的是同一个版本才排除了这条路径。但这里要提醒各位只要服务存在多副本部署这条路径就必须第一个排查因为涉及发布流程排查成本最低却最容易被忽略。3. 这次我是怎么排查的从日志到根因的五步走确认是根因级别的问题之后我开始按步骤做深度排查。整个过程大概分为五步每一步都有直接的产出物最终把root cause锁定在某一个具体的数据和行为上。3.1 第一步还原时间线而不是只读日志排查Bug的第一步我从来不是直接去翻异常栈而是先把时间线梳理出来。凌晨3:24这个时间点本身就有很多信息。任务2:58启动3:24中断那说明中间26分钟里任务一直在跑。我先去把调度平台的执行记录拉了出来确认任务确实是一次性启动中间没有被kill或重启。然后按时间线去找各环节的日志启动日志、拉数日志、清洗日志、写入日志任何一个环节有输出都记录了准确的时间戳和批次号。这个阶段最有用的工具是日志可视化平台里的时间轴检索。我会把所有跟任务ID相关的日志按时间排序然后人为地划分成三段启动段、处理段、中断段。启动段重点看参数处理段重点看批次顺序中断段重点看到底是“正常退出”还是“异常退出”。凌晨这次异常时间轴看起来非常诡异——处理段的日志数量明显少于正常情况但任务并没有立即退出而是在停止产生日志之后的某个时间点突然跳出了中断记录。这说明处理线程并没有在中断点“崩溃”而是在某个更早的节点已经挂起或等待直到等不下去才被系统以异常形式释放。3.2 第二步拉线程快照找状态而不是找语句日志还原到这一步我开始怀疑处理线程本身出了问题而不是业务逻辑出了bug。于是我去看了任务所在应用服务器的线程快照thread dump重点找那个执行同步任务的线程。线程快照是排查“卡住型故障”最直接的证据。正常的业务线程栈顶上一定是方法名、锁信息、等待的条件异常的线程栈顶往往是一段循环代码或者某个同步方法的等待标记。我找到那个线程的栈信息之后看到的栈顶正是我上次修复时加的判空保护分支下面则是大批的JDBC写入调用。这说明线程不是被外部锁卡住的而是在等待数据库I/O完成。等的时间太长最终触发了超时机制被中断释放。到这一步问题已经清晰了一半不是代码逻辑异常而是数据库操作性能出了问题。换句话说这个Bug之所以凌晨复现是因为某个SQL在特定数据条件下跑得特别慢线程等超时了。3.3 第三步检查分布式锁与任务调度线程快照锁定了是等待数据库I/O但我没有急着去查SQL而是先查了分布式锁和调度状态。原因很简单如果任务多实例部署且使用了分布式锁线程快照里显示的“等待”也有可能是等锁。凌晨这个时段其他周期性任务也在运行它们之间如果有共享的锁资源完全可能导致互相等待。我查看了锁服务里该任务对应的lock key它的持锁时间恰好和任务启动时间一致说明锁在启动时成功获得之后一直没有释放。再看其他相关任务并没有占用该锁所以锁竞争这个因素可以排除。调度层面我也核对了一遍。这个任务配置的是cron表达式凌晨2点58分触发这与日志完全吻合。同时间段没有手动触发或补跑记录排除了人为干预导致的异常。3.4 第四步数据层核对锁表、慢查询、脏数据排除了锁和调度我正式回到数据库层。这步我建了一个非常直接的核对列表确认任务涉及的表结构、索引情况找出中断时间点前后是否有锁等待、慢查询定位出那条导致26分钟处理窗口异常的数据记录先说索引。我的数据同步任务每次都会按批次号、时间戳、状态三个字段查询待处理数据。而数据库表里只有主键索引没有针对状态和时间戳的联合索引。数据量小的时候全表扫描也无所谓可是当数据积累到某个量级再加上状态条件中大部分行已经是“已完成”全表扫描的代价会指数级上升。我在数据库慢查询日志里果然找到了那个SQL。它运行了将近7分钟执行计划里显示走的确实是全表扫描。那条超时中断本质上就是一次全表扫描把线程拖死导致的。再说脏数据。慢查询SQL的where条件里有一个status PENDING的过滤条件。正常来说全表扫描状态过滤结果集应该很小。但我在进一步的检查中发现表中存在大量status PROCESSING的历史记录它们卡在中间状态一直没被更新。这些记录占用了大量存储还让状态列的分布变得极度不均匀——优化器基于这个分布选了错误的执行计划进一步加剧了全表扫描。3.5 第五步代码走查重点盯异常吞掉点和状态更新顺序数据层面有了结论我回到代码里做走查。这一步看的不是“能不能跑”而是“状态更新顺序和异常处理是否安全”。我把我自己上次加的判空保护和try-catch重新读了一遍确认那两处确实把关键的异常信息吞掉了。然后我检查了状态更新的顺序先更新status PROCESSING再执行数据校验和转换最后才更新status DONE。这个顺序本身没错但它在一个关键条件下会出问题如果数据校验和转换因为任何原因失败而这个失败又被catch块静默吞掉那status就会一直停留在PROCESSING永远不会前进。结合凌晨那次中断这个链条彻底闭环了分批SQL因为全表扫描跑得巨慢线程超时被中断线程中断时正处于“先更新状态为处理中、尚未更新为完成”的时间窗口于是这条记录被永久卡在PROCESSING。第二天再来一批数据这个表中的脏数据越来越多查询越来越慢任务越来越早到达超时点最终形成了自锁式的恶性循环。4. 最终修复方案防御性改造而不是打补丁这次我决定不再做“修复后再观察”的反复试验而是对整条链路做一次防御性改造。核心原则就一条状态机永远不能被卡在半路异常永远不能被吞掉。4.1 核心改动状态机校验与幂等控制我重新设计了任务处理的核心方法。先判断当前记录状态再更新状态最后执行处理动作。更新状态和执行处理之间必须有事务保护。状态只有三种合法流转PENDING到PROCESSINGPROCESSING到DONEPROCESSING到FAILED。任何非法流转直接抛出异常不让线程继续静默。伪代码大概是这样的public void processRecord(String recordId) { Record record recordMapper.selectById(recordId); if (record null) { throw new IllegalStateException(record not found: recordId); } String currentStatus record.getStatus(); if (!PENDING.equals(currentStatus)) { // 非PENDING状态一律不重复处理避免重复消费 log.info(skip record {}, current status: {}, recordId, currentStatus); return; } boolean updated recordMapper.compareAndSetStatus(recordId, PENDING, PROCESSING); if (!updated) { // CAS失败说明已经被其他线程处理幂等兜底 log.warn(CAS update failed for record {}, recordId); return; } try { process(record); // 真正的业务逻辑 recordMapper.updateStatus(recordId, PROCESSING, DONE); } catch (Exception e) { recordMapper.updateStatus(recordId, PROCESSING, FAILED); log.error(process record failed: {}, recordId, e); // 原始堆栈必须保留 throw e; } }这个结构里有几个关键点都是经验换来的。compareAndSetStatus用的是数据库层面的原子操作比如UPDATE ... SET status PROCESSING WHERE id ? AND status PENDING这样保证了状态更新的原子性不会出现两个线程同时读到PENDING然后一起干活。多实例部署时不需要额外引入分布式锁数据层的CAS就能挡掉绝大多数并发问题。catch块里除了更新失败状态还加了throw e;。这一步至关重要——哪怕外层有兜底逻辑内层也必须把异常抛出去让运维告警、日志采集、调用链都能看到这次失败而不能像上次那样异常在某个try里被消化掉了。另外我给这个同步任务增加了一个入口级的幂等控制同一个批次ID如果已经存在处理中的记录直接拒绝重复执行。具体实现是在批处理表里加一个唯一索引批次ID作为唯一键冲突即幂等。4.2 让错误可以被看见异常透传与告警分级光有状态校验还不够因为线上系统的核心问题之一是“看不到错误”。这次排查大量的时间花在日志空白上所以第二步改造是重建异常可见性。我把日志体系做了调整。原来的统一日志格式只记录了任务ID和方法名这次加上了阶段标签START、FETCH、TRANSFORM、WRITE、FAILED。每个阶段开始时都打一条简短的Info日志结束时打一条包含行数、耗时、状态值的日志。这样再看时间线一眼就能定位是哪个阶段出了问题不用再猜。告警这边也做了分级任务失败且影响记录数小于10条属于低级别告警只推送到工作群。任务失败且影响记录数大于10条属于高级别告警同时触发电话语音通知。任何一条记录进入FAILED状态都单独发一条告警并附带原始异常摘要。这套规则最核心的意义在于它不会再让开发人员靠半夜惊醒的方式发现问题而是主动把异常推到面前。凌晨3:24这种“修完又复发”的事件很大程度上是因为第一次修复后系统主动把它隐藏得很好。4.3 回归用例为“半成功”状态写测试最后一项改造是测试。以前我对这种批处理任务的测试基本只覆盖“全成功”和“入口异常”两种场景。这次我把“半成功”状态写进了测试用例模拟第一批数据成功、第二批数据因为数据格式异常失败、第三批数据又是成功的情况验证任务是否能正确标记失败记录同时继续处理后续数据。这个测试用例看起来不起眼但它直接保证了这次修改不会再犯“吞异常”的错。具体写法是把真实的消息处理器替换成一个可控的mock处理器让它对特定批次抛异常然后断言最终状态是成功批次DONE、失败批次FAILED、剩余批次保持在PENDING等待下次重试。同时我还加了一个针对“状态卡死”的守护测试把某条记录的状态预置成PROCESSING然后重新启动同步任务断言任务不会去碰这条记录也不会把整个批次标记为异常。这些回归测试跑下来我对这次修复的底气才算是真正有了。不是那种又改了一版试试看的心态而是明明白白知道代码里的每个分支都有测试兜底即使再出问题也会以清晰可见的方式出现而不是继续在半夜3点24分诉诸日志空白。5. 修Bug的实操心得常见问题与排查技巧速查这部分我整理了这次排障过程中踩过的坑和沉淀下来的排查经验做成一个速查清单也顺带回答那些“我怎么就没想到”的瞬间。5.1 修复反复无用时的常见问题速查表现象可能原因建议排查手段任务偶发中断且没有异常堆栈try-catch吞掉了原始异常检查所有catch块保留原始异常并接入日志上下文任务在固定时间点附近频繁失败定时任务与数据库维护、备份等周期任务重合拉取数据库慢查询日志确认时间段内是否有其他作业抢占资源修复后旧Bug消失但新错误偶发状态更新顺序破坏产生了中间态检查状态流转是否为原子操作必要时引入CAS或分布式锁多实例部署时Bug只在部分实例复现旧代码实例仍在服务核对实例版本号、部署时间确认流量是否均匀打到新版本任务管理器显示“成功”但数据不一致幂等控制缺失或幂等键设计不当给唯一业务键加数据库唯一约束并检查重试策略是否幂等日志只记录了自定义错误定位不到具体代码行自定义异常信息过度包装丢失原始堆栈日志框架开启堆栈打印做到“异常栈必现”这张表背后是我最真实的体会大多数“修复后重现”的Bug都不是代码本身变复杂了而是我们处理异常的方式把原本可以快速定位的问题给藏了起来。所以在上面每一个方案里我都优先强调“不吞异常、保留堆栈、暴露状态”。5.2 几个值得长期坚持的排查习惯第一任何修复上线前必须确认事件已经全链路可见。如果修复逻辑里有catch块这个catch块里必须有一条结构化的日志且日志包含原始异常的堆栈。我曾经为了给异常信息“美化”硬是把堆栈给丢掉了结果排障时间翻了不止一倍。第二排查偶发Bug时优先怀疑数据而不是代码。代码是固定的逻辑数据却一直变化。凌晨3:24这种场景背后十有八九是数据积累到了某个阈值让原本埋藏在代码里的性能或格式问题被逼了出来。如果你重新盯着代码看了一遍觉得逻辑没有问题那大概率是你的数据出了问题。第三一定要给重要的批处理任务加上“中间状态巡检”。就像我这次发现的PROCESSING状态堆积它在业务上没有直接报错却会让系统的查询性能越来越差。天然的系统不检查这种中间状态所以要人工定时扫描统计status PROCESSING的记录数如果连续多个调度周期都是同一个数量就要告警了。第四把测试看成Bug复发问题的“最后一道防线”而不是开发流程里的一个选项。这次我花了大半天写回归用例收益远远大于成本。因为我做的改动不是简单的一行修复而是改变了整条状态流转的行为没有测试兜住下次修复可能又会引出新的隐蔽问题。5.3 对“半夜3:24”这个时间点的进阶思考最后单独说一点关于时间点的思考。以前我遇到凌晨时段的任务异常第一反应是“夜深了数据库负载低不太可能是性能问题”。但这次的经历直接颠覆了这种直觉。凌晨低峰期真正的风险恰恰在于大多数其他凌晨任务也选择在这个时段运行。系统之间共享数据库、磁盘、网络带宽凌晨反而是各种批量任务扎堆的时候。某个时段集中触发的任务会把数据库连接池打满让单个SQL的等待时间线性拉长然后引发连锁超时。所以排查线上任务故障不要只看任务本身的时间点还要把同时段运行的其他任务列出来看它们有没有资源争抢。当时我的数据库慢查询日志里同一时段还有好几个统计报表任务这些任务和数据同步任务压在同一张表的索引上互相叠加最终把一个原本500毫秒的查询拖成了7分钟。这次Bug反复出现的完整链路是脏数据未清 → 修复只覆盖表象 → 任务状态卡死 → 全表扫描变慢 → 线程超时引发中断 → 中断留下更多中间状态 → 下一次任务被更慢的查询拖垮。整个链条里的每一个环节单独看都不至于让系统崩溃但合在一起就直接逼得我在凌晨3点24分爬起来看告警。现在系统上线了新代码跑了好几个完整的调度周期没有出现一次PROCESSING卡死慢查询日志里也彻底没有了全表扫描的踪迹。更重要的是日志链路完整了异常可见了状态有守护了再出问题是能快速定位的没有什么比这个更让人在半夜感到安心。我个人在这次排障里学到的最重要的一件事是修Bug从来不应该追求“让它消失”而应该追求“让它下次出现时一眼就能知道是哪里出了问题”。一个不能自我暴露问题的系统就像一盏坏掉却不熄灭的灯——它一直在哪里你却永远不知道它坏了。这次之后我的代码风格也变了很多异常捕获一定记录完整堆栈状态流转一定设计成闭环时间线分析一定优先于代码走查。如果你也在被某个反复出现的Bug折磨希望这篇记录能帮你少走一点弯路。