两次人工排查无果的线上告警，Claude Fable 5 一晚上挖穿 60G 日志找到根因
两次人工排查无果的线上告警，Claude Fable 5 一晚上挖穿 60G 日志找到根因
TL;DR 一条数据不一致的告警连发五天：某个 IP 的 pod 在 k8s 里早就死了，数据库里却一直留着它的记录，怎么都清不掉。这个问题我此前人工排查过两次，两次都以”怀疑对象被证伪”收场。这回换了个打法——把代码仓库、告警内容和服务器日志入口交给 Claude Fable 5（Claude Code），让它自己读代码、自己登机器翻日志，我负责给方向。一晚上下来，它挖穿了三个服务约 60G 的日志，钉死了一条五个问题手拉手才凑出来的 Bug 链：起点是 pod 启动和用户配置之间 18 秒的时间差，中间是一次被内存缓存”误杀”的删除操作，结尾还有一次只删了一半的人工操作。这篇文章把完整过程摊开，包括人机怎么分工、以及一个很好用的排查技巧——反证法。
📌 本文要点
- 一条”数据残留”告警，怎么从每天 8G 的日志里还原出完整的案发过程
- 内存缓存的经典陷阱：把”我做过删除”误当成”它已经被删了”
- 用户的手速和系统的事件流赛跑：18 秒和 3 秒的两个真实案例
- 查不到”谁干的”时怎么办：反证法，查”谁没干”
- 让 AI 自己登跳板机翻 60G 日志：人机分工的几条实操经验
- 彩蛋：顺手挖出一天 5 万次的线程池报错，根因是一行
countDown()没写对地方
🧭 背景：一个 IP 要同时出现在三个名单上
先花两分钟讲清楚系统结构，不然后面的日志没法看。
我们的业务跑在容器云上。一个业务 pod 要接到线上流量，它的 IP 必须同时出现在三个地方：
- k8s 的存活名单——pod 活着就在，死了就没。这是”事实本身”，最可信
- 数据库的节点表——记录这个 IP 属于哪个集群、什么权重。这是”账本”
- consul（网关的分流表）——nginx/apisix 按这张表转发请求。IP 在这里，才有真实流量打过来
打个比方：k8s 是花名册（人在不在），数据库是工资表（该不该发钱），consul 是排班表（今天上不上岗）。三张表必须对得上，任何一张对不上都是隐患。
对齐这三张表的活儿，由一个叫 proxy 的服务来干：它盯着 k8s 的 pod 事件，pod 就绪了就把 IP 写进账本和排班表（上线），pod 死了就删掉（下线）。另外还有个定时对账任务，每隔几小时把三张表拉出来对一遍，对不上就发邮件。告警里用三个 0/1 表示三张表的状态，顺序是「k8s / 数据库 / consul」：
1 1 1 → 三张表一致，正常
0 1 0 → 人没了，工资表还有名字 → 数据库残留
0 1 1 → 人没了，工资表和排班表都有名字 → 更危险：流量还往死人身上打
1 0 0 → 人来了，两张表都没登记 → 漏注册，pod 干活但接不到流量出事的就是这条，每 8 小时发一次，连发五天：
WCloud_ai_cluster_A K8S与consul数据不存在，只有clusterIp数据存在 10.25.110.237翻译成人话：0 1 0——IP 10.25.110.237 的 pod 早就没了，排班表也没它，但工资表里一直挂着它的名字。
有人可能觉得：数据库多一行脏数据而已，不影响流量，删掉不就完了？删掉当然容易，但它说明下线链路上有个环节丢了。这次丢的是”删数据库”，下次同一个洞漏掉的可能就是”删排班表”——那就是真金白银的请求打到死 pod 上。所以必须查。
交代下前情：这条告警之前我人工查过两次。一次怀疑是 proxy 服务重启把内存缓存清了，一次怀疑是 pod 的瞬时状态被扫描抓到了——两个猜想最后都被证伪，排查不了了之，告警继续每天发。这回我换了个打法：把代码仓库、告警原文、服务器和日志路径都交给 Claude Fable 5，让它自己读代码、自己登机器翻日志，我只负责在关键节点给方向、补背景。下面的排查过程，就是这场人机配合的完整记录。
顺便说个开局的小插曲：我们的服务器要过菜单式跳板机（输 IP 加权限才能进），AI 没法直接 ssh。它自己探了两轮跳板机的交互流程，写了个 expect 脚本把登录、执行命令、回传结果全自动化了——从这一步起，翻日志这种体力活就全是它的了。
🔍 第一步：告警里的 IP，已经”改嫁”了
排查从今天的日志开始。grep 这个 IP，第一眼就很懵：
[07-07 09:35:38] handleAddPod ------ WCloud_ai_cluster_C ip 10.25.110.237
[07-07 09:36:27] warmup success. clusterName[WCloud_ai_cluster_C], ip:[10.25.110.237]今天这个 IP 属于另一个集群 cluster_C，注册、预热，一切正常。往前翻一天，它又属于 cluster_B。都不是告警里的 cluster_A。
原因很简单：容器的 IP 是循环使用的。cluster_A 的 pod 死了，IP 还回池子，第二天就分给了别的集群的新 pod。就像手机号注销后过段时间会重新放号——你按号码去查，查到的可能是三任机主的记录混在一起。
所以”今天的日志”全是别人家的事。残留的那行数据库记录，是几天前 cluster_A 用这个 IP 时留下的，得回到过去查。
排查数据残留类问题的第一课：先确认实体身份。IP、端口、连接 ID 这类资源标识都会复用，直接 grep 标识，翻出来的日志可能属于好几个”主人”。后面所有的搜索我都带上了集群名做联合过滤。
🔍 第二步：回到第一案发现场，方向居然是反的
告警从哪天开始的？AI 本来打算在两台机器上起后台任务，把三十多天的日志全量扫一遍。这时候人的价值就体现出来了——我记得这事第一次冒头是 7 月 2 日，一句话把搜索范围从 30 天压缩到了 1 天。带着「集群名 + IP」直奔 7 月 2 日的日志，找到了第一条相关记录。但诡异的是——方向和告警是反的：
[07-02 01:55:24] doCheck >>> k8s中存在，clusterName:[WCloud_ai_cluster_A]，consulDb中不存在:[[10.25.110.237, 10.25.110.8]]7 月 2 日的问题是 1 0 0：pod 活着，但账本里没登记——漏注册。而五天后的告警是 0 1 0：pod 死了，账本里反倒有记录——残留。
同一个 IP，先是漏登记，后来变成了赖着不走。中间必然发生了两件事：有人把数据补上了，然后 pod 死了但数据没跟着删。接下来就是把这两个”中间事件”找出来。
🎯 第三步：四条日志，钉死根因
把 7 月 1 日（pod 创建那天）的日志完整拉出来，四条关键记录按时间排开，整个故事就串起来了。
第一条，15:14:57，pod 还在启动中，proxy 却先执行了一次”下线”。
[07-01 15:14:57] PodWatcher:95 - 6 eventReceived podName llm-infer-A-78794kmvc status Starting
[07-01 15:14:57] EventMonitorHandler:690 - ready to handleDeletePod ------ WCloud_ai_cluster_A 10.25.110.237
[07-01 15:14:57] CacheUtil:188 - setExecCache llm-infer-A-78794kmvc WCloud_ai_cluster_A&10.25.110.237 2先解释下 Starting 这个状态：pod 的容器进程起来了（Running），但还没通过就绪检查（not Ready）——服务还没准备好接请求。
看到”pod 还没就绪就执行下线”，你可能觉得多此一举——pod 都还没上线，下什么线？其实这是个很有必要的防御设计。 线上经常有这种场景：网络抖动或者别的原因导致 pod 里的容器重启，重启期间 pod 会从 Ready 掉回 Starting。这时候 pod 在排班表里还挂着、流量还在往它身上打，但容器根本没起来——用户请求就是实打实的报错。所以 proxy 收到 Starting 事件的第一反应就是立刻把节点从流量里摘掉，等它重新 Ready 了再加回来。这个设计保护了无数次容器重启，没有它，每次网络抖动都是一波线上报错。
问题不在下线动作本身，在最后那行日志：setExecCache ... 2。下线执行完，proxy 往内存缓存里记了一笔——“这个 pod 的最后一次操作是删除（DEL）“。对一个刚出生的新 pod 来说，这次下线其实什么都没删到（三张表里本来就没有它），但这笔”删除记录”实实在在写进了缓存。
记住这笔 DEL，它是后面一切的伏笔。
第二条，15:18:47，pod 就绪了，注册流程启动，却在门口被拦下。
[07-01 15:18:47] EventMonitorHandler:273 - ready to handleAddPod ------ WCloud_ai_cluster_A ip 10.25.110.237
[07-01 15:18:47] EventMonitorHandler:297 - fluxGroup not open fluxMingle 10.25.110.237对应的代码：
// pod就绪，准备注册。但先检查它所属的流量组开没开接入开关
if (!nginxSwitch && !gatewaySwitch) {
logger.info("fluxGroup not open {} {}", fluxGroup.getFluxGroupName(), ip);
return; // ← 开关没开，直接返回：不写账本、不写排班表
// 注意：缓存里那笔 DEL 也原封不动留着
}pod 就绪时，它所属的流量组（可以理解为”这批 pod 对外提供服务的分组”）既没开 nginx 接入、也没绑定网关——因为这是个刚建的新集群，用户还没来得及在控制台配置。于是注册流程判断”这批 pod 不需要接流量”，直接 return 走人。
单看这个逻辑没毛病：开关没开，确实不该注册。毛病在于它只是离开，没有收拾——缓存里那笔 DEL 还留在原地。
第三条，15:19:05，用户的配置操作到了。只晚了 18 秒。
[07-01 15:19:05] gatewayapi - in bind request BindRequest(gatewayClusterName=ai_gateway_01, bindType=BIND, ...)
[07-01 15:19:05] gatewayapi - openGatewaySwitch 添加ip至clusterIp表成功 ClusterIp(clusterName=WCloud_ai_cluster_A, ip=10.25.110.237, ...)
[07-01 15:19:05] gatewayapi - set key apisix/ai_gateway_01/Product/6263.../10.25.110.237:8867用户在控制台把流量组绑定到了网关。绑定是另一个服务（gatewayapi）处理的，它有个贴心的兜底逻辑：绑定时把当前所有活着的 pod 直接写进账本和排班表——毕竟 pod 都已经跑起来了，不能让用户再手动加一遍节点。
于是 18 秒前 proxy 没写进去的数据，被绑定流程补上了。此刻三张表完全一致，系统处于”看起来一切正常”的状态。
但有个隐患埋下了：数据是 gatewayapi 写的，proxy 全程不知情。proxy 的内存缓存里，这个 pod 的最后一笔记录还是 DEL。 缓存和现实，从这一刻开始脱节。
第四条，两天后的 7 月 3 日 11:29，pod 寿终正寝，删除操作却被”判重”跳过了。
[07-03 11:29:16] CacheUtil:160 - NoOp: cacheOp == op podname=llm-infer-A-78794kmvc cacheOp=2pod 生命周期结束，k8s 发来删除事件。proxy 收到后先过一道去重检查——k8s 的事件经常重复推送，同一次删除可能收到好几遍，所以要靠缓存判断”这个操作是不是已经做过了”：
// CacheUtil.isExec —— 去重检查
if (cacheOp == op) { // 缓存里记的是 DEL，这次要做的也是 DEL
return false; // "删过了，跳过" ← 账本和排班表的清理就此丢失
}缓存里那笔 DEL，是 7 月 1 日 pod 启动期那次保护性下线（当时什么都没删到）；而现在这次，是 pod 真正死亡的清理性下线。去重逻辑只看”上次是 DEL、这次也是 DEL”，分不清这两者，把真删除当成了重复事件扔掉了。
从这一刻起，账本里那行记录和排班表里那个节点，再也没有人会去清理。
到这里，0 1 1（账本 + 排班表双残留）已经解释通了。但告警是 0 1 0——排班表是空的。还差最后一块拼图：排班表里的记录，是谁删的？
🕵️ 第四步：反证法——查不到谁干的，就查谁没干
gatewayapi 对排班表（consul）的每次删除都有日志。我把 7 月 3 日两台机器的日志翻了个底朝天：没有任何一条针对这个 IP 的删除记录。解绑、换绑的操作日志也都没有。
正向的线索断了。这种时候可以换个思路：既然查不到”是谁删的”，那就反过来验证”如果是某某删的，还应该留下什么痕迹”。
关键突破口是同一批写入的另一个 IP。回看 7 月 1 日 15:19:05 那次绑定，写进去的其实是两个 IP：10.25.110.237 和 10.25.110.8。那查一下：另一个 IP 现在还在排班表里吗？
listNodeByClusterFluxGroup(WCloud_ai_cluster_A, PRODUCT, fluxMingle)
Result: [{"ip":"10.25.110.8","port":8867,"weight":100}, ...]10.25.110.8 还在，权重 100，活得好好的。 就这一条查询结果，直接排除了一大片可能性：
- 如果是”解绑”删的 → 解绑会清空整个分组的所有节点，
.8不可能幸存 → 排除 - 如果是”换绑”删的 → 换绑走系统接口，有逐条的删除日志，但日志里没有 → 排除
- 剩下唯一说得通的：有人绕过系统，直接在 consul（或网关控制台）上手工删掉了
.237这一个节点
时间线也严丝合缝：7 月 3 日 13:55，系统发过一封 0 1 1 的告警（pod 没了但流量还挂着），当天下午排班表里的记录就消失了。还原一下：某位同事收到告警，手工把网关上的死节点摘了——这个操作本身没错，甚至很负责。但数据库里那行记录，他不知道、可能也没权限动。 于是 0 1 1 降级成 0 1 0，一躺就是五天，告警循环播放。
这个技巧我叫它反证法排查：正向找不到操作日志时，找一个”陪跑样本”（这里是同一批写入的
.8），看它的存活状态能排除哪些操作路径。每排除一条，剩下的可能性就浓缩一分，直到只剩一个说得通的答案。说实话，“去查同批写入的另一个 IP 还在不在”这一步是 AI 先提出来的——这也是整晚排查里最让我意外的一个瞬间：它不只是在执行 grep，是真的在推理。
🔁 第五步：第二个案例，把”巧合”变成”必然”
复盘文档写到一半，新告警进来了：另一个集群、另一个 IP，类型 0 1 1。用同样的方法拉时间线，四步几乎逐帧复刻，只有一个数字不同：
08:08:58 pod Starting，缓存无记录 → 保护性下线 → 缓存写入 DEL
08:12:57 pod Ready → 注册 → 开关没开，早退
08:13:00 用户绑定网关 → gatewayapi 兜底写入 ← 这次只差 3 秒！
（次日）
08:30 pod 真实下线 → 删除被判重跳过 → 双残留第一个案例差 18 秒，第二个差 3 秒。到这里就明白了，这根本不是巧合——这就是用户上线新集群的标准节奏：先扩容 pod，盯着控制台等 pod 变绿，然后马上去绑网关。pod 就绪事件和绑定操作之间，天然就只差几秒到几十秒，而 proxy 的注册恰好总是抢先一步撞上”开关还没开”。
换句话说：每一个按标准流程上线的新集群，第一批 pod 的首次下线都必然产生数据残留。 告警为什么反复出现？因为源头是必然事件，不是偶发故障。
🧨 Bug 链全景
把整条链摊开，五个环。单独看，每一环要么是合理设计、要么是无心之失；串在一起，才凑成了这次事故：
- DEL 缓存污染（主 Bug）：保护性下线是对的，错在它写下的缓存被去重逻辑当成了”已经删过”。缓存记的是”我做过什么动作”，却被拿来回答”这个实体是什么状态”——语义错位。
- 早退无补偿：注册因”开关未开”早退后，没有重试、没有补偿。pod 状态不再变化，就永远没有第二次机会。
- 双写无主：proxy 的事件流和 gatewayapi 的绑定流程各写各的，互不知情。兜底写入救了注册，也让 proxy 的缓存和现实脱节。
- 人工操作绕过系统：手工摘节点不联动删数据库，还没有审计日志——排查时只能靠反证法猜。
- 无对账自愈：以上任何一环漏了，系统都不会自己恢复，只能反复发邮件等人来。
🔧 修复：两处点修 + 一个兜底
点修一：早退时把缓存收拾干净。 这是斩断主链路的关键。既然早退意味着”这次注册没发生”，那启动期写下的 DEL 也应该一并作废——离开房间，随手关灯：
if (!nginxSwitch && !gatewaySwitch) {
// 早退前清掉启动期保护性下线写入的DEL缓存
// 否则开关打开后，pod真实下线会被去重逻辑误判成重复操作而跳过
CacheUtil.clearExecCache(getCacheKey(pod, clusterName, ip), getOpCacheKey(clusterName, ip));
logger.info("fluxGroup not open {} {}", fluxGroup.getFluxGroupName(), ip);
return;
}点修二：告警要对称。 排查中还发现，1 0 0（漏注册）只在 nginx 这条链路上告警，网关那条链路是静默的。所以 7 月 2 日的扫描其实三次都发现了异常，但一封邮件都没发。同一个检查逻辑、两个下游，一边大喊大叫一边默不作声——等于亲手给自己造了一个视觉盲区。
兜底：定时对账，自动修复。 点修只能防新增，已经躺在库里的残留、以及未来以其他姿势漏掉的数据，靠对账任务兜底：以 k8s 为准绳，“k8s 里确认 pod 不存在”的残留数据自动摘除。当然要配护栏——单集群一轮超过 3 个、全局超过 5 个集群就熔断转人工（大面积异常往往是数据源本身挂了，这时候批量删除等于灾难），加上二次实时校验和操作审计。
🎁 彩蛋：顺手挖出的 5 万次/天报错风暴
排查时 grep 异常关键字，还撞见另一个吓人的数字：RejectedExecutionException（线程池拒绝任务）单日 5 万条。第一反应是业务量把线程池打爆了？扒开一看，是个特别经典的”小失误滚成大风暴”的案例。
这个池子是做节点权重预热的——新节点上线不能一下子给满流量，要从权重 1 慢慢爬到 100。池子的配置：
// 核心3个线程，最多4个，排队队列只有1个位置 —— 同时最多容纳5个任务
new ThreadPoolExecutor(3, 4, 6, TimeUnit.SECONDS, new ArrayBlockingQueue<>(1), ...);提交任务的是个死循环，每轮从数据库捞出待预热的节点，切成批次丢进池子：
CountDownLatch downLatch = new CountDownLatch(warmupLists.size());
for (List<ClusterIpWarmup> warmupList : warmupLists) {
ThreadPool.WARMUP_IP_THREAD.execute(() -> { // ← 池子满了，这行会抛异常
processWarmupList(warmupList);
downLatch.countDown();
});
}
downLatch.await(50, TimeUnit.SECONDS); // 等这一轮的批次都跑完
TimeUnit.MILLISECONDS.sleep(2000); // 歇2秒，进入下一轮看出问题了吗？池子满的时候 execute() 抛异常，这个异常会直接炸出 for 循环，把后面的 await 和 sleep 全跳过。外层的 while 立刻开始下一轮：拿锁 → 查库 → 提交 → 又被拒。一圈只要 5 毫秒。
于是只要池子被慢批次占满一分钟，这个循环就能空转出一万多条异常日志。我统计了下时间分布：5 万条报错集中在全天三个时段、加起来约 10 分钟——不是有 5 万个任务失败，是同一个失败被以每秒 200 次的速度重试了 5 万遍。
修复就三处，每处都很小：
for (List<ClusterIpWarmup> warmupList : warmupLists) {
try {
ThreadPool.WARMUP_IP_THREAD.execute(() -> {
try {
processWarmupList(warmupList);
} finally {
downLatch.countDown(); // ① 干完活放行，抛异常也放行——放finally里
}
});
} catch (RejectedExecutionException e) {
downLatch.countDown(); // ② 没提交成功也放行，本轮正常走完await和sleep
logger.warn("warmup batch rejected, retry next round");
}
}外加把池子扩大一点（core 4 / max 8 / queue 16 + CallerRunsPolicy 兜底）、批次切小一点。被拒的任务不丢——预热记录在数据库里，下一轮自然重试。修完之后，同样的拥塞场景，报错从每秒 200 条降到每 2 秒 1 条。
这里有个通用的坑值得记下来：配了 CountDownLatch 的任务，countDown() 必须放 finally；而且提交失败的分支也要补一次 countDown。否则任何一个任务提交失败或者执行报错，await 就只能干等到超时，整个循环的节奏全乱。另一个反直觉的点：队列别开太大——在队列里排队久的任务，拿到的是提交那一刻的旧数据，真执行时可能把别人已经更新过的状态又写回去，比直接拒绝更难查。
🤖 这次是怎么用 AI 排查的
标题里提了 Claude Fable 5，这里把人机分工摊开讲讲，都是可复制的经验。
我提供的东西：代码仓库路径、告警原文、两台服务器 IP 和日志目录、跳板机的登录方式。外加三次关键提示：「这问题第一次出现是 2 号」「2 号之后有人工操作过」「去看下 gatewayapi 这个服务」。
它干的活：通读三个服务的代码并指出可疑点；写 expect 脚本自动化跳板机登录；每一轮生成一批 grep 命令批量执行、解析回传结果；把散落在两台机器、三个服务里的日志证据按毫秒级时间戳串成时间线；提出反证法的验证思路；最后把结论沉淀成复盘文档、顺手把两处点修代码也改了。
几条实操经验：
① 背景知识决定收敛速度。 「之后有人工操作过」这一句话，直接让它放弃了一个错误方向（它一度推断数据是某天人工补录的，实际是绑定操作写入的）。AI 不缺搜索能力，缺的是你脑子里那些没写在任何文档里的上下文——越早给，弯路越少。
② 强制要求”每个结论都贴日志原文”。 我在过程中反复确认它给出的每条时间线都有日志证据支撑。这是防幻觉最有效的手段：编造一个结论很容易，编造一条带时间戳、带线程名、能对上代码行号的日志很难。
③ 大日志先抽取、再分析。 单文件 10G 的日志，它的策略是先 grep IP > /tmp/xxx.txt 抽到临时文件，再在小文件上做多轮过滤——机器时间和上下文长度都省。这个习惯值得人类排查时借鉴。
④ 边查边沉淀。 每确认一个事实就写进复盘文档，最后文档直接变成评审材料和这篇文章的底稿。排查和写作不再是两件事。
一晚上的感受总结成一句话：AI 把”翻日志”从体力活变成了描述问题的能力测试——你能把背景讲多清楚，它就能挖多快。
如果更关心「日常写业务 / 搭项目时同一套分工怎么用」，可以看方法论短文：
👉 Java 后端在 AI 时代怎么提效：不是多会一个工具，是重新分工
💡 写在最后：三条带得走的经验
一、缓存”动作”还是缓存”状态”，想清楚再写。 这次的主 Bug，本质是拿”我上次做过删除”去回答”它现在还在不在”。就像小区保安的登记本：早上他拦下一个没刷卡的人，顺手记了笔”此人已离开”；晚上这人真要搬走来登记，保安一翻本子——“已经走过了，不用办”。动作日志和实体状态是两回事，拿动作去重没问题，拿动作判状态就会出这种事。如果你的系统里也有”操作去重缓存”，值得检查一下：那些预防性的、兜底性的、执行了但没产生实际效果的操作，会不会污染它？
二、用户操作和系统事件赛跑的窗口，永远存在。 18 秒和 3 秒两个案例说明，“pod 先起来、配置后到位”不是什么异常路径，就是用户的正常手速。设计事件驱动的系统时，“事件到达时前置条件不满足”不能一个 return 完事——要么留下重试的钩子，要么在条件满足时补偿一次，最起码，把这次处理留下的副作用（比如缓存）回滚干净。早退分支是最容易埋雷的地方，因为它看起来什么都没做——而”什么都没做”往往不等于”什么都没改”。
三、对账是分布式数据的最后一道保险。 靠事件来同步的数据，天生就会丢事件：网络、重启、时序、人工操作，每一样都可能让增量同步漏一拍。漏一拍不可怕，可怕的是漏了之后永远好不了。定时全量对账（reconcile）不是承认事件机制失败，而是给它系一根安全绳——k8s 自己的 informer 机制都要配 resync，道理是一样的。如果你的系统里有多份数据靠事件保持一致，问自己一个问题：漏掉一条事件之后，系统多久能自己恢复？如果答案是”永远不能”，那就该写对账任务了。
这次排查前后翻了两台机器、三个服务、大约 60G 的日志，工具只有 grep——和一个会自己写 grep 的 AI。但方法比工具重要：先确认实体身份，再找第一案发现场，沿时间线收敛，正向查不到就上反证法。如果你也在维护类似的服务发现或数据同步链路，希望这条 Bug 链能帮你提前排掉几颗雷。
你们有没有遇到过”缓存把正经操作当成重复操作吞掉”的案例？或者更离谱的数据残留？评论区聊聊。