记一次伪并发引起的bug

一次较典型的问题排查过程, 分享一下, 欢迎指正和交流.

相关背景

内网有两个应用A和B, 其中B提供两个服务化接口B1和B2, 外网有一个应用W提供两个HTTP接口W1和W2.
内网的A通过RPC与B通信、B通过HTTP与W通信. 画了个简图如下

应用A：A首先调用B1(设置了一定的超时时间), 若超时则调用B2.
应用B：B1调用W1(设置了一定的超时时间), 调用W1成功后写入记录供B2调用W2时需要.

问题表象

观察应用B的日志发现, 有少量的B2被调用的 “记录不存在的” 业务异常日志. 根据这些异常日志分析出可能的一种情况: B1与B2 “同时” 由A发起调用, B2先行到达被处理, 引起这个异常. 从日志中也确实发现了 “记录不存在的” 的异常日志与B1的被调用日志在同一秒钟被记录到. 真的是并发引起的么?

问题追踪

理论上来说, A发起调用B1与B2, 即使是同一秒钟, 也不大可能是同一时刻. 这是因为A的逻辑决定的, 在调用B1超时后才会调用B2, 至少也是相隔了个超时时间段.
而后与A的负责人沟通得知, 调用B1的超时时间是300ms, 且找了几条异常日志对应的B1调用记录发现, 都存在同一个共同点: 耗时较长超过了300ms. 从这里可以分析出来, B2的调用至少隔了300ms才会被调用.
再次观察对应的B1调用链发现: 耗在调用W1的时间基本都在300ms以上. 这样疑问就很清晰了: A发起调用B1(超时500ms), B1发起调用W1(超时300ms). W1响应时间超过约300ms后A认定超时继而发起调用B2, 而此时B还在等待W1的响应因而没有写入记录导致A调用B2引发 “记录不存在的” 业务异常日志.

解决方案

为避免外网系统对接的超时问题, 其实内部已经有了一套较为完善的隔离方案, 这个隔离方案简单来说就是在白名单内的走单独一套超时限制较宽松的系统. 因为上面说的案例比这个隔离方案出来的时间早且比较仓促, 没有设计隔离方案且一直没有进行接入.
B2接口的实时要求不高, 可以异步处理, 暂时把B2的逻辑处理延迟1s后处理.

欢迎留言交流~