【WebSocket】断连问题排查

背景

        负责的一套网页健康度拨测的系统，包含【中心节点-Master】【拨测节点-Agent】，Master和Agent通过websocket协议进行通讯。Master会定时向Agent下发拨测任务消息。Agent会对这些消息进行消费（curl、DNS拨测），返回拨测结果。Agent也会定时向拨测中心发送心跳消息，以保持连接。

        总体架构图如下：

        系统会对外暴露一个拨测接口，提供拨测服务，时序图如下：

问题

        测试发现，在批量导入大量的URL进行拨测时，有很多URL没有收到拨测结果。查看Agent日志，发现每隔一段时间websocket连接会断掉（Connection reset by peer），所以拨测任务就没有下发到agent进行处理。

分析

初步分析后，怀疑可能时以下原因造成的：

1. Master服务器load问题，导致发送消息线程未及时发出，造成堆积

2.Nginx或者Master服务器上websocket超时配置过短

3.客户端原因，消费速度太慢，严重阻塞消息的发送

排查过程

1. 中心节点-Master服务端排查

先用top查看，cpu、load都比较低，初步感觉服务器没啥问题。

日志有超时的错误

No messages received after 908445 ms

这也只是说明没有长时间没有收到Agent的消息

2.超时时间修改

Nginx配置新增websocket超时时间，设置为3600s

location /ws{
    proxy_pass http://master_server/;
    proxy_http_version 1.1;
    proxy_read_timeout   3600s;
    proxy_set_header Upgrade $http_upgrade;
    proxy_set_header Connection $connection_upgrade;
}

Nginx重启后发现问题仍然存在

尝试修改拨测中心Java服务里的超时时间

@Override
public void configureWebSocketTransport(WebSocketTransportRegistration registry) {
    //连接建立到首次收包的最长时间间隔（10min）
    registry.setTimeToFirstMessage(10 * 60 * 1000);
    //服务端发送消息的大小超过指定大小(1M）
    registry.setSendBufferSizeLimit(1024 * 1024);
    //服务端发送消息的时间超过指定时间（1min）
    registry.setSendTimeLimit(60 * 1000);
}

运行一段时间后，问题还是存在。

由此思考，这个问题应该不是超时的配置导致的。继续排查。。。

3.Nginx服务器排查

查看Nginx日志，发现有Connection reset by peer报错

2020/04/15 18:02:51 [error] 374#0: *1917238 send() failed (104: Connection reset by peer) while proxying upgraded connection, client: 172.28.25.222, server: localhost, request: "GET /ws/358/5c5d8dafac7f4586a751ff4c68fb2999/websocket HTTP/1.1", upstream: "http://172.28.72.77:8899/ws/358/5c5d8dafac7f4586a751ff4c68fb2999/websocket", host: "172.28.72.114:8443"
2020/04/15 18:03:03 [error] 374#0: *1913375 send() failed (104: Connection reset by peer) while proxying upgraded connection, client: 172.28.25.214, server: localhost, request: "GET /ws/453/60c9a5af41374f9dbaad4d5444d25c96/websocket HTTP/1.1", upstream: "http://172.28.72.77:8888/ws/453/60c9a5af41374f9dbaad4d5444d25c96/websocket", host: "172.28.72.114:8443"

netstat 查看Nginx服务器上的端口情况

[apprun@newvhost02 ~]$ netstat -anop|grep 443
tcp        0      0 0.0.0.0:443             0.0.0.0:*               LISTEN      13307/nginx: worker  off (0.00/0/0)
tcp        0 108528 172.28.72.117:443       172.28.72.119:63132     ESTABLISHED 13308/nginx: worker  probe (0.16/0/0)

引起注意的是Send-Q有100多k，Send-Q的意思是

Send-Q：在发送缓冲区实际未发送或者没有收到对端Ack的字节数

说明：应用已经把数据写到Socket缓冲区，因网络原因导致数据没有发送。

对Nginx进行抓包分析

发现Agent（119）到Nginx（117），有很多窗口大小为0（重传），如果重传次数满，比如重传8次，则是事件触发，动作是

        1）reset 或关闭TCP连接

        2）通知应用层出错

最后可以看到 Nginx（117）向Agent（119）发送了RST

说明：大致可以表明Agent消费能力不足，导致消息IO线程阻塞，没有调用recv接受消息。

所以Agent出现“Connection reset”的原因是Nginx服务器关闭了Connection

调用了Socket.close()方法

Question：服务器关闭了Connection为什么会返回“RST”而不是返回“FIN”标志。

原因在于Socket.close()方法的语义和TCP的“FIN”标志语义不一样：发送TCP的“FIN”标志表示我不再发送数据了，而Socket.close()表示我不在发送也不接受数据了。问题就出在“我不接受数据” 上，如果此时客户端还往服务器发送数据，服务器内核接收到数据，但是发现此时Socket已经close了，则会返回“RST”标志给客户端。当然，此时客户端就会提示：“Connection reset”

4.Agent客户端排查

到这里，我们已经大致清楚了问题的原因【消费端消费能力不足，导致消息积压从而断连】，可以到agent，也就是消费端，用netstat 查看一下是否有消息堆积的情况

[apprun@vhost18 ~]$ netstat -tnulpao|grep 443
tcp6  362708      0 172.28.72.119:63132     172.28.72.117:443       ESTABLISHED 32278/java           off (0.00/0/0)
tcp6       0      0 172.28.72.119:63192     172.28.72.117:443       ESTABLISHED 32278/java           off (0.00/0/0)

可以看到Recv-Q 堆积：说明Agent消费不过来，基本可以确定业务应用消息IO线程没有及时调用recv造成数据堆积。

再查看确认了Agent消息处理部分的代码，发现没有用线程池来处理任务！！！

改为用线程池处理后，问题解决

总结

通过上面的排查，该问题的原因：

消费能力不足->消息IO线程阻塞->没有调用recv->数据堆积到Recv-Q->发送窗口被置为0->满重传次数->Nginx Connection reset

Recv-Q Send-Q分别表示网络接收队列，发送队列。Q是Queue的缩写。这两个值通常应该为0，如果不为0可能是有问题的。packets在两个队列里都不应该有堆积状态。可接受短暂的非0情况。短暂的Send-Q队列发送pakets非0是正常状态。

如果接收队列Recv-Q一直处于阻塞状态，可能是遭受了拒绝服务 denial-of-service 攻击。如果发送队列Send-Q不能很快的清零，可能是有应用向外发送数据包过快，或者是对方接收数据包不够快。

Recv-Q：表示收到的数据已经在本地接收缓冲，但是还有多少没有被进程取走，recv()

Send-Q：对方没有收到的数据或者说没有Ack的,还是本地缓冲区.

通过netstat的这两个值就可以简单判断程序收不到包到底是包没到还是包没有被进程recv。

解决方法： 业务方用线程池优化消费能力