生产事故的排查

10.15 生产事故复盘

1. 10.14发版

10.14 18:05分，清结算系统正常发版，上的是“福建工行保证金需求”和“线下佣金结算”需求。发版内容本身经过测试，无问题。

git中的提交记录比对

发布的重启过程，是杀掉已有线程，并用新包启动线程。 在杀的过程中“重发机制”的一个锁正好没有释放，锁自然存在时间为24小时，锁在redis中，因为业务情况，锁没有释放的情况也很常见。

工具类中redis默认设置为24小时

2. 重发机制的BUG

“重发机制”正常过程是，每10分钟查重发任务，循环发送。一旦遇到有锁的任务正常应对是不处理或抛异常，然后执行下一个任务。

但这里有个严重BUG，遇到redis锁，跳出循环，后面的任务都不执行。

循环中直接return

3. 10.14晚的停卡

10.14晚22:00的停卡定时任务查询到需要停卡的客户号，存入“重发队列”，就因为有一个锁的存在，一条停卡任务都没有推送到ETC。这样持续到了10.15。

10.14应该停卡的用户，是10.13账单没结清的用户。

4. 10.15白天

运营收到很多客户反馈说账单没结清也没有停卡，反馈到IT，其中有些客户赶在白天把应该要停卡的对应的10.13的账单结清了。

数据分析发现10.14的停卡率无法统计，反馈给徐总。

IT在10.15下午17:00左右得知这个问题，开始排查数据和代码。

5. 问题排查期间出现新问题

一开始检查10.14清结算发版引起的，比对代码后没发现任何异常，验证了不是版本迭代引起的。

那只能看停卡任务和重发机制的代码，一行一行地检查逻辑。

傍晚18:25左右，忽然发现804名客户推送的停卡指令发送到了ETC，包含10.14所有的停卡用户，但时隔一天用户状态已经不一样，其中有些已经完成账单结清的客户不该再推送停卡。

重发任务和任务成功时间

6. 问题定位

最终定位到了是重发机制代码24小时锁的Bug。

而重推停卡指令在18:25这个时间点也解释了两个问题：

a） 这个异常的时间点减去24小时，正好是14日发版后的一段时间。18:05加锁未释放，任务调动间隔10分钟一次，算上启动发版和队列中任务执行的时间，这个时间非常吻合。

b） 遇到异常跳出循环，停卡的任务这么巧第一个就遇到锁，导致一个10.14的停卡都没有发送到ETC。

这是因为锁住的任务并不是停卡任务，而所有任务中排在停卡任务队列以前的任务，时间上锁住的任务是14日晚上18:05的任务，而停卡任务是在14日晚上22:00才进入队列的。

由于在15日18:25分，锁已经释放，因此也无法找到当时锁住的具体是哪个任务了。

7. 问题处理

修改循环跳出的BUG，发版。

对804名停卡客户，找到13日、14日账单已经结清的客户，重推复卡指令。

总结：

1. 重发机制异常退出整个循环是个严重的问题

2. 重发机制对锁的使用不合理，锁的时间应当适中，调整在2小时左右。

3. 发版过程中不关注运行情况直接kill有风险，需要优化发版的流程。

4. 停卡复卡这种流程中重要的任务，必须有监控和预警机制。而不是业务部门发现。

5. 批量停卡、批量复卡类似这种后门需要预留，提高修复数据的效率。