记录cava_teu断线重连失败问题排查过程

一、问题背景

最近在检查cava的teu在线节点时，发现节点数只剩1个，此前作者部署了多个节点。于是本着“teu为啥离线，我之前明明开发了可用的teu断线重连功能”的好奇心，展开了艰难的问题排查和修复过程。

备注：cava云服务详细介绍见： 花了“7”年时间，把Robot Framework打造成了微服务

首先找到离线的teu_003的日志，查看最近的服务日志，如下图：

teu一直在断线重试，但都未完全成功，从日志看像是重连成功又立马断开，然后1分钟后重试

印象中teu断线重连的功能此前自测是ok的，首先确认了teu程序是最新版本，而smu服务端也是好的(teu_001节点功能正常在线)，于是决定把teu停掉重启再试试，重启teu后，teu重连成功。好家伙，敢情感觉是teu在某次断线后，断线重连功能陷入瘫痪的死循环，就像人被沉重的打击后变得一蹶不振，彻底废了。那么我们就要通过日志，找到并分析那次断线后，重连变得不生效的具体过程。

幸亏笔者开发的程序，日志留存归档都很完善(自夸下)。grep “client connect succeed” *.log，然后按照你对时间熟悉的排序，找出首次重连的上下文关键日志：

 

从上图日志中，我们得出以下几个关键信息：

1、2022-10-26 09:07:48 首次断线重连失败了，接着都是重连失败？接连重连失败的原因是什么呢？

2、重连前的旧链路是52902这路，且此前执行任务的消息，收发走的都是这条链路

3、大约在2022-10-26 09:06:57 乃至更早，52902链路断了，断开的原因后续可以再看下

4、2022-10-26 09:06:57 teu仍通过52902链路，尝试向smu发送任务报告消息，但没发出去，websocket报错：failed to get writer: WebSocket closed

翻阅更多上下文，再找找信息：

5、2022-10-26 09:06:48 teu接受数据出错，链接断开，主协程退出。

6、2022-10-26 09:06:54 尝试发送保活消息，但因为链接关闭，保活协程退出。

7、这个任务是9:00出发的，但到9:06左右才结束。任务耗时久的原因是什么？

8、09:00:19发送给smu的保活请求，09:06:57才收到响应：

 teu日志显示保活消息耗时久，查看smu日志显示响应及时，所以teu里为什么显示保活耗时久？

二、排查过程

针对上述三个主要的困惑，我们来一一排查：

2.1 任务耗时久

我们在teu_003上找到2022-10-26 09:00这次任务的日志(cava html log)。

cd /usr/local/bin/CAVA3/CAVA_SPACE3/outputs/Log，找到如下目录：

cd CavaSvrProxy_Api_src_20221026090006 && sz CavaSvrProxy_Api_src_log.html，然后浏览器打开，我们发现：

 任务用例里：用户注册、登录、转成成html等用例耗时久。如下图：

注册用例中是用户注册这个api接口耗时久，如下图：

 我们根据这次注册的时间点和用户名等关键信息，在cava3svrproxy、mysql日志上找到这次注册请求的日志上下文，如下图：

cava3svrproxy日志显示，服务收到请求是在09:05:13，响应时间是09:05:39，cost是38秒，期间查询数据库耗时花了几秒，虽然全程不至于耗时5分钟，但也是很慢了，不正常，但是上个接口耗时还是毫秒级的。9:00:11~9:06:00期间系统、服务发生了什么，没更多信息可以深入排查。看来定时采集主机/进程的cpu、内存和IO等指标信息也得提上议程了。

2.2 teu保活耗时久

关于teu保活耗时久，这个现象是初看teu日志日志得出的结论，但看smu日志，保活响应是及时回复了的，如下图：

所以我们得看teu当时保活请求、响应的上下文日志，进一步排查。从上图日志看出，收到保活消息前，几乎同时刻，打印了cava任务报告html的路径，结合代码看：

是如下流程：processData()->doTaskReqMsg()->doTaskForLinux()

根据以上可以确认下收到保活消息，程序当前协程在执行任务，且耗时5~6分钟，导致同协程中处理/打印保活响应消息阻塞(还没轮到它)。上述流程代码第1张截图也可以佐证，收到执行任务消息，会先在当前协程在执行任务，还没到再次读取channel，取出保活响应消息并处理。对于执行任务这个操作，耗时可能比较久，每次从channel中取出执行任务的消息，应当另起一个协程去处理任务，避免阻塞当前协程，这是一个多线程业务设计时应当注意的地方。

2.3 断线重连总是失败

这个现象的原因是最值得深究的，因为tcp链接对于客户端而言，可能会因为网络抖动或者服务端异常宕机等而被动关闭，所以断线重连这个功能很有必要。笔者当时在teu代码main主函数里设计断线重连，主要是为了在不重启进程的前提上，让业务本身做到牺牲最小(主要考虑的是teu不可用时期的时长)的重连。试想，如果是一当断线，进程就退出，然后依靠k8s或者supervisord等守护方式重启进程进行重连，虽然降低了teu断线重连逻辑的实现难度，但进程重启，程序启动本身就要占用一些时间，如果起来过程中还要连接数据库等中间件，会让teu不可用的时期变得相对更长，这种牺牲时间来降低程序实现难度的方法，并不太好。当时这个断线重连功能开发好，自测也是OK的。言归正传，让我们来深入排查下断线重连失效的原因。

从断线后首次重连(2022-10-26T09:07:48)失败日志入手，断线首次重连过程就下图红框标注的4行日志：

 2022-10-26T09:07:48断线重连，认为失败，立马退出，那我们就看下business.go:726行，打印退出(重连后的)主协程的条件。

从上图代码中可以得知，退出(重连后的)主协程的条件是：从closeCh这个chan bool类型、size=1的缓冲通道中，读到链接关闭的消息。那么从日志反推，这次重连失败退出，必然是读到了这个消息。有个疑问，这个消息是什么场景，什么时候写到channel里的呢？场景我们可以通过查看代码知道：
场景1、读数据协程对应的方法readDataLoop中(business.go:665行)，从websocket读数据错误时，会往closeCh写入1个链接关闭的消息，关键代码如下图：

场景2、发送消息协程sendDataLoop()->sendMsgToRemote(business.go:124行)，向websocket写入待发送的数据失败时，会往closeCh写入1个链接关闭的消息，关键代码如下图：

以上两个场景触发时，teu会打印相应的日志，所以我们在当时的teu日志上下文里去找寻，看下有没有这些日志，business.go 66、125行日志打印，总共有以下三处：

{"level":"ERROR","ts":"2022-10-26T09:06:48.681+0800","caller":"com.business/business.go:666","msg":"err:failed to read JSON message: failed to get reader: received close frame: status = StatusNormalClosure and reason = \"\""}
{"level":"ERROR","ts":"2022-10-26T09:06:54.926+0800","caller":"com.business/business.go:125","msg":"TraceID=c967708be54d|client addr=180.76.144.58:52902, err:failed to write JSON message: failed to get writer: WebSocket closed: received close frame: status = StatusNormalClosure and reason = \"\""}
{"level":"ERROR","ts":"2022-10-26T09:06:57.213+0800","caller":"com.business/business.go:125","msg":"TraceID=89f8bfa35653|client addr=180.76.144.58:52902, err:failed to write JSON message: failed to get writer: WebSocket closed: received close frame: status = StatusNormalClosure and reason = \"\""}

上述场景日志，2022-10-26T09:06:48.681这次写入closeCh，查看日志，读取链路数据失败，我们发现同时期随后打印了business.go:726行的日志，exit go routinue: true，结合代码看，也就是随后退出了主协程。

2022-10-26T09:06:54.926这次写入closeCh，查看日志，尝试通过链路向smu发送保活消息失败，发现同时期紧接着打印了conn closed, exit keep alive，也就是随后退出了保活协程。

而2022-10-26T09:06:57.213这次写入closeCh，查看日志，尝试通过链路向smu发送报告通知消息失败，同时期紧接着没有看到随后立马有退出协程的迹象(closeCh中的消息被取出被消费掉)。

但过了一分钟左右，即2022-10-26T09:07:48.714断线重连过程，倒是有exit go routinue: true退出主协程，那么很有可能第三次closeCh中写入的消息，是被这次给消费掉。因为从代码中得知，closeCh是个全局变量，并非每个链路所独有，前后所有链路，用的都是这个channel来通知协程退出。结合2022-10-26T09:07:48断线重连的日志看，退出主线程在前，说明closeCh此前就存在未被消费的消息，而同时期紧接着因为读取链路数据失败(因为重连的链路被关闭了)，又写入了一个消息到closeCh，但通过日志确认，closeCh里的消息没被消费掉，应该是攒着留个1分钟后的重连了。

所以closeCh的消息被错位延后消费了，导致一直重连失败。那错位的原因是什么呢？是因为上面分析的第3次往closeCh写了一个消息，这个消息是多余的，后面被错位延后消费了。这个消息的产生是因为：当时teu尝试通过链路向smu发送报告通知消息失败，所以往closeCh写了一个消息，这种写/生产消息的场景我们无法或者说没有理由去阻断，链路发送区写失败，当时意味着这个链路不可用(断开了)。

我们看看能不能从消费的角度来规避/解决这个问题，通过代码，我们确认了closeCh的消息，只有两处消费场景：

1、退出主协程(business.go:726行)

2、退出保活协程(business.go:556行)

 如果这两处场景都已经消费了(退出了协程)，那么多余产生的closeCh能不能是和链路一一对应的，有多余的/是其他链路的断开消息就不消费了？如果用一个全局map来记录哪些链路被关闭了，也不太好，维护起来麻烦，多协程加锁。后来想到一个办法，把closeCh由 chan bool类型改为chan string，string是链路的客户端端口号，这个是唯一短期内不会重复的。每当从closeCh中读取到断开消息，取出判断是否是当前链路的(和当前链路客户端端口号相同)，不同直接扔了，不根据该消息退出对应协程，这样关闭消息就不会错位消费了，问题完美解决。