前言
公司产品在上线运行中,有使用人员反映发起了一笔账务请求,记账100元,前端正常交易完成后,后台记了两笔100元的账务,引发了很危险的短款账务问题。
经多方核实,确认现在确实存在客户端通讯重复发送了两次,且仅接受第二次的返回信息导致了此问题发生。
凡事先从自省入手,我们先不去吐槽为啥服务端没有做好幂等性和防重功能,先分析下到底客户端是不是真的有问题,因此产生了以下的分析排查过程。
问题分析
客户端采用CEF框架,基于Chromium 76版本;发起请求基于axios框架,前端框架采用Vue.js 2.0技术。
1、总结整个网络部署架构图:
图1、网络部署架构图
2、根据上图的网络架构,依次从后到前拿到生产日志,首先分析两次请求的服务端日志是否完全一致,结论为两次服务端日志比对完全一致。
3、观察业务网关日志,发现两笔请求间隔19s,无任何其他信息。
图2、业务网关日志截图
4、观察反向代理服务器日志,发现两笔请求之间都存在websocket尝试重新握手重连的情况:
图3、反向代理服务器日志截图
该日志反映出上下两笔相同的POST请求,中间出现了网络断开的情况,因此导致了websocket进行了重连。
5、观察客户端日志,的确出现了网络断开情况,websocket尝试重连,并在后续重连成功。
图4、客户端日志截图
6、从上图此时排查客户端日志,发现客户端日志在发起通讯请求日志后,未接收到任何http异常日志记录,仅有websocket异常日志记录,从客户端视角看,只是发了一次请求,过了19s后收到200响应状态码。
综上问题分析:
我们发现客户端应用层只发起了一次http请求,此时网络出现波动,反向代理服务器记录客户端发起了两笔http请求,中间夹杂着一次websocket重连,服务端也是收到两笔请求,因此下一步需要排查客户端与反向代理服务器之前到底因为什么原因导致了问题出现。
场景重现
1、到底在客户端与反向代理服务器之间是谁进行了重发,导致了这次问题呢
2、首选怀疑的是nginx的重发机制,可以看到nginx在出现异常时,会重新请求后台服务。
nginx 重发机制 – yxy_linux – 博客园 (cnblogs.com)。但根据一开始说明的架构,对ngnix参数进行修改,测试时确实出现了重发,但网关日志中记录了一条,与本次现象不符
3、再次怀疑的是axios重发,在github上也见到相关的帖子,有人反馈过使用axios导致重复提交问题,不过由于缺少重现场景,问题关闭
查看axios源码发现,axios底层发送也是使用XMLHttpRequest实现,从axios过程来看,不存在重发代码处理
4、随着上面nginx与axios机制排除后,把目光转向了Http协议,网上搜索发现http对重发有处理,可以看到网页说明跟这次现象很像,都是中途出现了断网。HTTP请求重发 – SegmentFault 思否
根据上述场景,对问题复现。
5、断掉客户端网络,尝试重现。本地两台PC机,一台模拟客户端,一台模拟服务端,两台PC机通过路由器相连,客户端使用axios直接发post请求,服务端接收请求会睡眠几秒模拟处理业务流程再返回,使用wireshark抓包观察客户端服务端发包情况,尝试问题复现。
客户端点击按钮发送post请求,立即拔开网线,等待几秒后把网线插回,客户端立刻收到了Disconnect异常,生产环境未出现此类异常,因此此场景不正确。
图5、浏览器测试截图