干我们这行的,总有几个凌晨会特别难忘。不是赶版本上线那种如期而至的忙,而是出了故障,一切正常看起来却又不正常,日志翻来覆去也查不出个所以然,只有监控图上那条夸张的曲线在提醒你:事情确实发生了。我习惯把这种事故叫技术的“鬼故事”,因为它们的共同点是:按常理不应该发生,但偏偏在深夜精准地砸到你头上。
这篇不是灵异志怪,是几个我真实熬过大夜、最后靠一点点排查逻辑才找着原因的事故复盘。涉及业务系统、消息队列、网络设备和构建发布流程,每个故事我都会保留完整的排查链路,把你可能在文档里看不到的细节也写出来。不管你是后端、运维还是偏业务的研发,大概率能从里面看到自己环境的影子。重点不是抱怨技术有多坑,而是下次再撞见类似“鬼”,你能有一套镇得住的打法。
1. 满屏告警里最像“鬼”的一次:500毫秒消失在全局的请求
先说一个让整个团队第二天顶着黑眼圈开晨会的事故。现象特别邪门:核心接口的P99延迟从正常的80毫秒左右,突然跳到500毫秒以上,但P50几乎纹丝不动。线上告警半夜两点触发,等我把监控面板打开,故障已经自己恢复了,仿佛什么都没发生过。更离谱的是,这个现象没有任何规律,有时候一天出现两三次,有时候两三天不出现,而且每次持续几分钟到半小时不等。
这种“灵异”指标是最烦人的,因为问题不在的时候,你根本没法抓现场。我们最初怀疑是不是数据库慢查询在作祟,因为这类接口后半段有两三个SQL查询,看起来嫌疑最大。于是我给数据库监控加了更细的等待事件采集,专门盯慢日志,可等了整整一个晚上,数据库那边没有一条超过100毫秒的查询。接着怀疑是Redis热Key问题,查完发现访问量虽然不低,但并没有倾斜到单个分片上的情况。一度以为是同事线上做了配置变更导致的,翻了一遍发布记录和配置中心历史,也没有任何操作。
最后让我找到突破口的是一张全链路调用拓扑图。细看之后发现,那段异常时间里,某个内部基础服务的耗时曲线和对外接口的P99曲线几乎完全重合。这个内部服务本身没多少逻辑,就是拿一个配置项,按理说耗时应该稳定在个位数毫秒。我顺着调用链往里点,才看见这个服务依赖了另一个老旧的配置中心客户端,而客户端在特定条件下会触发一次全量配置拉取。那次拉取没有走本地缓存,而是同步请求远端的配置中心,赶上配置中心那边在做持久化快照,响应就慢了。
这种问题的狡猾之处在于,它不会报错,不会产生慢日志,甚至请求量也没变。表象是业务接口慢了,实际是底层某个大家默认“永远很快”的基础组件偶尔抽风。排查过程里最容易踩的坑就是只看业务服务自身指标,不往链路深处钻。我后来把所有核心接口的依赖都做了分位数耗时监控,不再只看某个中间件整体健康度,这起事故之后就再也没让我们半夜爬起来过。
提示:看到P99涨但P50没动,先别急着怀疑业务代码。优先看依赖项的分位数曲线是否同步畸变,尤其是那些平时连看都不看一眼的内部基础服务。
2. 我亲历的“数据复活”:从MQ位移重置到凌晨两点的重复扣款
第二个故事比延迟问题可怕多了,因为它不声不响,等我们发现时已经产生了线上资损。
背景很简单:我们有个订单系统,用户支付成功后,支付回调通过消息队列通知下游积分、账单等系统。平时跑得好好的,直到一次半夜的定时任务误操作,把某个消费组的偏移量重置到了几个小时之前。本意是想让这段时间内一条处理失败的消息重新消费一遍,结果忘了这个消费组里还堆着大量正常的通知消息。偏移量一朝前拨,消费者组哗啦一下把过去几小时的几千条消息全部重新拉起来,下游每个系统都收到了重复的支付成功通知。
最狠的是,消息内容里带的是“支付成功”这个语义事件,而我们下游积分服务的消费逻辑当时只做了单条消息维度的状态判断,没有做全局幂等。于是部分用户的积分被加了两遍,甚至有三遍的。用户不会深夜立刻反馈,但等第二天对账发现积分变动数目对不上时,后台已经累积了相当多的脏数据。
我们排查的第一步是找到重复数据范围:把消息表的消息ID和业务流水号关联起来,查询出所有重复处理的业务流水,数量不小。接着追查为什么会重复消费,打开消息中间件的消费组状态一看,发现某个消费组的当前位移确实比消息队列里的最新位移小了一大截,等于把一批老消息重新读了一遍。继续看操作记录,果然有人在夜里执行过位移重置的脚本,而且重置粒度是整个消费组,不是单条异常消息。
这类问题技术上不算难,难在数据修补。当时修补方案里最稳妥的,是根据原始业务流水号做去重,只保留第一条成功记录。但“哪条算第一条”本身并不好判断,因为各系统接收消息的顺序可能不一样。我们最后只能挨个下游系统按业务主键写清理脚本,把重复加分的记录回滚,再配合人工抽验,前前后后忙到第二天下午才算完全收口。
这个事故给我的教训特别深:消息系统里真正要命的不是消息丢失,而是重复消费。丢失还能用对账补,重复消费可能直接造成脏数据甚至资损。现在所有消费逻辑里,要么在数据库层建唯一业务键做幂等,要么在下游接口入参里带全局唯一消息ID做滤重。与此同时,位移重置类操作我在流程上加了一道审批和二次确认,必须填写完整的“影响消费组、重置范围、预估消息量”,否则不允许执行。
提示:任何消息队列的位移重置,本质上是把历史重放一遍,你永远不知道这期间有多少异步链路会被触发。没有幂等保护的消费逻辑,禁止轻易做整组位移回退。
3. 一台“隐身”三年的旧跳板机,在凌晨送上了停机大礼
第三个故事和网络有关,先描述一下现场:我们某个机房里的应用半夜报了一堆连接超时,影响范围不大,只有几台机器上的实例,而且日志里的报错指向的上游IP还不是同一个。你敢信,同一个服务,调用同一个下游,有的机器正常,有的机器超时,超时还随机分布。我们最初的判断是网络抖动,因为现象实在太像哪里有瞬时拥塞了。
然而等我们尝试在故障机器上手动模拟调用时,发现大部分时候居然都是通的,只有极少数几次会卡住几秒钟再断掉。这个“看运气”的特征最折磨人,所有常规的连通性测试都正常,你又不能指着网络部门让他们排查一个复现不了的问题。于是我们在问题机器上挂了持续的TCP连接监控,把每次成功、失败、耗时都记下来。熬到凌晨四点多,终于发现超时请求都指向同一个目标端口,而正常请求几乎不碰那个端口。
顺着端口去查负载均衡后端的服务器清单,我愣了半天。这份清单里居然有一台状态标注为“维护中”的老旧机器,按记录早该在三年前退役了。它没有从负载均衡里摘除,而是被某个系统自动同步任务加了回来,加上健康检查的路径在老机器上恰好返回200,负载均衡就认为它一直活着,持续把流量分给它。那台机器的网络配置本身有冲突,处理能力又差,大部分连接会直接卡死。少量请求侥幸透过它返回,延迟也高得离谱。
这台“僵尸节点”在集群里藏了三年,平时没什么流量到它头上,一旦负载均衡策略调整或权重分配变化,流量才开始偶尔扫到它。因为不是每台机器都会中招,问题看起来就格外随机。我后来做了一件事:把负载均衡节点列表和云平台的资产记录每周做一次交叉比对,凡是标记下线的机器必须从所有转发规则里清除,同时健康检查不再只看HTTP状态码,还加上了响应时间阈值。这样一来,即使有老机器被自动同步任务加回来,也会因为响应不达标被强制摘除。
这类网络层的“鬼故事”讲起来不复杂,但找到那台机器确实费了太多时间。如果你也遇到类似“一部分机器随机超时、网络设备看起来又没异常”的现象,千万别只在业务层反复打转,先看看流量调度链路上有没有成员节点和实际资产记录不一致。
提示:负载均衡的健康检查只能告诉你节点“还活着”,无法告诉你它“够不够格活着”。定期把转发节点清单与实际资产记录对一遍,能省掉后半夜无数冤枉路。
4. 比“磁盘满”更坑的是日志先于磁盘满了:一次清理脚本的反噬
很多人觉得磁盘告警最好处理,清一清日志,删一删旧备份就够了。但有一回,磁盘满了整整一个晚上,我差点把服务器里的日志都翻穿了,才找到真凶。而且真凶不是某个大文件,是一条每隔几十秒就来一次的日志。
事件发生得很突然:某台应用服务器的磁盘使用率从60%一路冲到97%,告警响起来的时候,服务已经因为写不了日志开始频繁报错。我上去先看大文件,按大小排序,发现最大的文件不过几个GB,这对于动辄几百GB的数据盘来说根本不至于打满。再看日志目录,某业务模块的日志文件数量多得不正常,每秒都有一堆新文件被创建,每个文件又很小。直觉告诉我,是日志滚动配置出了岔子。
查配置才发现框架里的日志滚动策略用的是“按文件大小触发”,但某个同事为了临时排查问题,在代码里对特定路径错误地调用了日志追加器,导致每来一条消息就触发一次滚动,旧文件还没来得及清理,新文件已经哗哗地生成了。如果只是这样倒还好,真正的灾难是我们的一条清理任务过度激进——正则在匹配文件名时写得太宽,把保留最近三天的备份误伤成了“只保留最近三小时”。等到磁盘告警时,历史日志其实早就被删光了,剩下的全是短时间内疯狂滚动出来的碎文件。
那晚我学到的最重要的一件事是,日志清理任务本身就是一把双刃剑。正则是保护机制,也可能是销毁机制。任何自动清理脚本上线前,必须先在测试目录里用真实文件跑一遍模拟,确认匹配范围只覆盖目标前缀,不要图省事用“前缀加星号”这种过于宽泛的写法。日志滚动策略也要加一个每秒文件创建速率的上限,一旦超过阈值立刻停止写入并告警,防止一个误配置在十分钟内把整个盘写满。
现在我们的日志方案是:所有模块写日志走统一的日志框架配置,不允许业务代码临时指定文件路径;清理任务保留策略放在配置中心统一管理,触发时先计算匹配文件总数和总大小,超过预设值就自动终止,不执行删除。日志目录的inode使用率也被我加进了监控,因为那个晚上我真正理解的不是“磁盘空间不足”,而是“文件数量爆炸同样能让服务卡死”。
提示:清理日志的脚本要优先防呆。在正则后面加个总数限制,比任何权限控制都管用。日志系统追求的是可控,不是跑得快。
5. 构建产物里的“定时炸弹”:一次灰度发布引发的整点惊吓
最后一个故事发生在发布流程上,尤其适合容易忽略构建环节的团队参考。现象是某个服务每天固定整点会有一小波报错,错误信息清一色是上游返回的JSON解析失败。按说如果上游接口返回结构变了,应该是所有时间点都报错,不可能只在整点出现。所以我们一开始都以为是定时任务在整点请求量突增,导致上游接口在高并发下偶尔返回了不完整的数据。
为了验证这个猜测,我们给错误日志加了上下文,记录当时请求的参数、响应前200个字节,还有耗时。等下一个整点来临,日志里果然抓到了几条响应内容被截断的记录。看上去像是上游的网关在传输过程中把响应体截断了,但奇怪的是,我们手动用同样的参数请求上游接口,返回内容却完整无缺。这种矛盾让我们折腾了差不多几个小时,最后有人提出把发布到灰度环境的构建产物和当前仓库代码做一次二进制对比,结果发现灰度环境跑的jar包根本不是最新代码构建出来的。
真正的元凶浮出水面:发布系统上配置了一个“整点自动构建”的定时任务,但这个任务构建时拿到的代码来自一个缓存目录,而缓存目录里的代码是三天前的旧版本。旧版本里上游接口返回结构字段名叫user_name,而新接口已经改为userName。平时没人触发旧包运行,偏偏整点的定时任务会调用一次旧包里的逻辑,导致后续链路全按老字段解析,自然报错。灰度的流量是逐步放量的,大部分请求打到了新包上,只有那一点点漏到旧包上的流量在整点暴露出来。
这个问题看似是构建缓存导致的,实际暴露的是发布链路缺少“产物可追溯性”校验。现在我们的CI流程里强制要求构建产物必须携带git commit哈希,发布系统在启动前先比对产物中的commit和当前预期commit,不一致就直接拒绝启动。构建缓存目录也加了文件校验,任何超过固定时长的中间文件一律自动清除,不再默默留着。那次之后,我养成了一个习惯:遇到只在特定时间点出现的报错,第一反应不是盯着业务代码猜,而是先确认线上跑的包和你想的包,是不是同一个东西。
提示:灰度发布中最危险的往往不是新代码有bug,而是旧代码没被清干净。任何半夜出现的诡异报错,都值得先把“实际运行版本”列为头号嫌疑人。
6. 熬过这些夜之后,我给自己定下的排查铁律
说了这么多故事,梳理一下我现在的排查思路。技术世界的“鬼故事”没有一次是真正的超自然现象,每一个看起来无解的故障背后,都有一条没被看见的依赖链、一段被自动任务悄悄改动的状态、一个版本不一致的产物。我能熬过那些通宵,靠的不是运气,而是把排查节奏从“猜哪里有问题”改成了“先圈定数据,再定位逻辑”。
哪怕再急,我也不会跳过这几步。先把告警时间前后的完整时间线拉出来,日志、监控、变更记录三者对齐,很多时候光看时间线就已经能排除掉一半的错误猜测。然后确认当前运行版本和配置是不是预期状态,这一步能拦截掉像第五个故事那种“跑着旧包”的低级问题。接着看核心依赖项的分位数指标,而不是只看平均值和成功率,延迟类灵异事件大多隐藏在长尾分位数里。最后才是动代码层面的排查,而且每做一次修改,都要留一个可验证的观察窗口,不能连发几个版本然后干等着。
回顾那些真正让我熬夜的问题日志,其实每个技术环节都有或多或少的先兆:旧跳板机在被流量扫到之前就已经多次健康检查超时,日志清理任务在测试环境就扫出过错误路径,位移重置脚本在操作前也有足够多的提示弹窗。这些先兆最后都因为“看着不严重”被略过了。我现在宁愿在白天为这些不起眼的点多花半小时,也不愿在凌晨为它们花上六个小时。排查技巧能帮你从坑里爬出来,但真正可持续的路,是把那些坑提前填上。