socket处于close_wait状态无法关闭

[rangercyh]

skynet更新到最新代码遇到了一个问题。

之前版本我经常使用 ehco "help" | nc localhost port 这样的命令来执行一些 debug 命令。因为 nc 运行完会自动退出，所以socket也就断开了，skynet那边也能正常的关闭掉这条连接。但新的skynet代码运行后，发现通过这样的命令开启的socket连接无法正确断开了。nc的端口这边处于 FIN_WAIT2 状态，skynet的端口处于 CLOSE_WAIT 状态，说明 nc 这边发送了 FIN，skynet 收到了FIN，但是 nc 这边没有收到 skynet 回发的 FIN。怀疑是新加的半连接状态哪里处理的有问题。我是用 debug_console 测试的。其他类型服务开启的端口应该也会有类似问题。

[cloudwu]

尝试改了一下。这里有多个问题，其中 1, 2 是遗留问题，之前的版本处理关闭比较简单粗暴，掩盖了它们。3 是最近的修改考虑不周的地方。

1. lua 层面在 socket.close() 时，必须调用 driver.close ，让底层知道需要关闭 fd 。之前，这个步骤不是必要的。因为之前无论是我方主动关闭还是对方关闭，都会在底层删除 socket 对象，不依赖主动调用 driver.close 。而现在，需要把 driver.close() 移到条件外，保证一定能调用到。因为，若是对方关闭，会因为收到 CLOSED 消息，而将 .connected 设置为 false ，阻止 driver.close 的调用。
2. 发送数据时，不应该检查 type == SOCKET_TYPE_CONNECTED ，因为现在多了半关闭状态。之前加这个判断是因为不想在关闭过程中重新 enable epoll 的 write 事件，且认为关闭过程中需要对外写的数据都可以丢弃。但现在，即使是半关闭过程中，还是需要写数据的。
3. close_socket() 必须设置 ->closing 为 true 。此标志表示处于我方主动关闭过程中，和是否处于半关闭过程是两个独立的状态 。

[rangercyh]

经过简单的测试，发现通过 socket api 正常在一个服务内处理的关闭流程是 ok 的，但是如果通过 skynet.core 的 redirect 重定向接口交给别的服务处理后续流程包括关闭，依然有概率出现上述无法关闭的情况。暂时没有详细跟踪。等后续有时间了再跟踪看看是不是哪里不一样。谢谢云大。

[cloudwu]

无法关闭的情况，还需要核查 lua 层面最终有没有调用到 socket.close 。过去的版本可以不调用，底层会自动关闭；现在的版本必须调用。ps . 如果服务本身关闭，会由 gc 触发。

[cloudwu]

如果 fd 的所有权在不同服务间传递，需要保证最终被关闭。这部分还需要仔细检查。

[cloudwu]

@rangercyh 想了一下。可能是因为 socket fd 的所有权在服务间转移是一个异步过程，所以可能存在已经转移出去的 fd 收到了 CLOSED / ERR 消息（正好在转移期间发生）。所以库有责任关闭这些 fd 。而转移目标服务，会在 socket.start 时发现 error 。这个时候它也会关闭 fd 。多次关闭同一个 fd ，目前的实现是安全的。（和标准库的行为不同，fd 几乎不会复用）

[iwifigame]

运行./skynet ./examples/config，再运行客户端./3rd/lua/lua ./examples/client.lua(nc也一样出现), 关闭后，还是出现相同的现象: 客户端端口处于 FIN_WAIT2 状态，skynet的端口处于 CLOSE_WAIT 状态。
应该是gateserver.lua也要像上面处理一下才行。

function gateserver.closeclient(fd)
	local c = connection[fd]
	socketdriver.close(fd)
	if c then
		connection[fd] = false
	end
end

[rangercyh]

运行./skynet ./examples/config，再运行客户端./3rd/lua/lua ./examples/client.lua(nc也一样出现), 关闭后，还是出现相同的现象: 客户端端口处于 FIN_WAIT2 状态，skynet的端口处于 CLOSE_WAIT 状态。
应该是gateserver.lua也要像上面处理一下才行。

function gateserver.closeclient(fd)
	local c = connection[fd]
	socketdriver.close(fd)
	if c then
		connection[fd] = false
	end
end

我后来也仔细看了下我写的服务为什么会出现无法close的情况。就像云风说的，在fd从一个服务转移到另一个服务的期间，socket收到了FIN信号，而我的服务写法类似gateserver，也是注册了socket类型协议，自己处理socket的那7种类型的消息，我发现以前因为skynet对于关闭的粗暴对待，我使用socketdriver这类api处理起来比较容易，现在因为存在半关闭状态了，直接使用socketdriver接口来编写处理socket类型协议的响应函数就很要小心，一不留神可能就遗漏了。所以我现在都改成直接使用skynet在lua层封装的socket api来处理，至于socket的网络开启收发关闭流程就让这个封装自己处理了。

另外我也思考了一下，像skynet现在这种半关闭的处理流程，其实在大部分网络应用中并不太常见，主要原因还是因为这其实可能造成关闭发起方的资源泄漏，变相成为一种反向的ddos攻击，如果skynet一直不给对方回发FIN包，让对方处于FIN_WAIT2状态，就很容易形成泄漏，而skynet这边自身如何处理自己的端口状态，就看skynet自己的考虑了。我观察大部分的网络应用一般对待tcp连接的关闭还是很谨慎粗暴的，基本是收到FIN包就双向关闭释放资源，类似skynet之前的处理流程。云风因为要应对一些web那种类似long polling的应用想做这种半关闭，总感觉有点危险。。。。如果可能希望能够有个开关来屏蔽掉这个特性。。毕竟大部分skynet应用对面的还是游戏：D

[cloudwu]

运行./skynet ./examples/config，再运行客户端./3rd/lua/lua ./examples/client.lua(nc也一样出现), 关闭后，还是出现相同的现象: 客户端端口处于 FIN_WAIT2 状态，skynet的端口处于 CLOSE_WAIT 状态。
应该是gateserver.lua也要像上面处理一下才行。

function gateserver.closeclient(fd)
	local c = connection[fd]
	socketdriver.close(fd)
	if c then
		connection[fd] = false
	end
end

之前 gateserver 模板做的不完善，我认为需要更妥善的处理。在上一个提交中，我修改为：

1. connection[] 分三个状态：true 为建立了连接，nil 为我方主动关闭，false 为检测到对方关闭，但我方尚未主动关闭。
2. 连接计数通过 OPEN 和 CLOSED 事件做。
3. 收到 ERR （通常是 epipe），强制关闭 socket ，底层在之前或之后会发送 CLOSED 事件（这部分最近已经完善，保证了连接断开后一定会产生该事件）。
4. 收到 CLOSED ，如果已经是 nil （主动关闭）就忽略；否则仅仅设置为 false ，等待业务层关闭。如果没注册 handler.disconnect ，则主动关闭。

[cloudwu]

我观察大部分的网络应用一般对待tcp连接的关闭还是很谨慎粗暴的，基本是收到FIN包就双向关闭释放资源，类似skynet之前的处理流程。云风因为要应对一些web那种类似long polling的应用想做这种半关闭，总感觉有点危险。。。。如果可能希望能够有个开关来屏蔽掉这个特性。。毕竟大部分skynet应用对面的还是游戏：D

目前如果不是深度定制的话，还是比较安全的。

假设是使用 gate 模板，那么基本上不会漏掉。模板会兜底。
如果是使用 socket 库，至少在服务自己退出的时候，以及 write error ，都会关闭连接。

在使用的时候，只要遵循常规的原则：read 到 0 （收到 FIN) 后，就调用 socket.close 应该就不会出错。

[cloudwu]

"如果没注册 handler.disconnect ，则主动关闭" 这条有点画蛇添足。在 037c3a5 中去掉。

1. 绝大多数情况都会注册 handler.disconnnect 关心对方关闭连接事件。
2. 通常是短连接请求（一个连接只提一两个请求）可以不关心 disconnect ，此时，在处理完请求，或请求未完成超时后自动关闭。

如果是情况 2 ，不应该越俎代庖去关闭连接。因为这种情况下，可能有复杂业务要处理，或者是 long polling 模式，需要等待到可以回应时再关闭。而发起请求方则可以先发送 FIN ，半关闭连接。

[xuzhenyu2020]

使用新版代码，连接网易云的TDSQL-C(mysql兼容版)，会大概率出现sql语句执行无限期阻塞等待的情况，看到的现象是：数据库这边看连接已经断开了，skynet断打印的日志看，socket还没断开，所以就等待回包阻塞住了。不知道是不是同个原因，求帮助，游戏卡在这个问题不能上线。

[xuzhenyu2020]

目前的办法是每隔30分钟调用一下db:disconnect()，然后再次mysql.connect出一个新的，暂时解决，但是很别扭，不知道会不会有影响

[cloudwu]

tcpdump 看看断开过程的握手情况，两边的 FIN 和 ACK 的交换情况？

[cloudwu]

根据描述，是远端(TDSQL-C) 主动断开了连接。如果在 lua 里测试，看看
https://github.com/cloudwu/skynet/blob/master/lualib/skynet/socket.lua#L118
https://github.com/cloudwu/skynet/blob/master/lualib/skynet/socket.lua#L139
有没有触发 SKYNET_SOCKET_TYPE_CLOSE 或 SKYNET_SOCKET_TYPE_ERROR 消息。

阻塞住的地方是，提起一个请求长时间没有回应；还是长时间没有提请求，再提请求时没有检测到连接已经断开？
还可以看看，有没有主动调用过 socket.close (https://github.com/cloudwu/skynet/blob/master/lualib/skynet/socket.lua#L274) 而后续的处理没有对？

[xuzhenyu2020]

好的，我再测试一下，之前的现象是：远端断开了连接，但是skynet这边认为还没断开，实际上连接不存在了，在调用mysql:query接口的时候，看到socket.lua中的socket.disconnected返回的是还没断开，所以mysql这边就一直阻塞。
游戏业务层没有控制过mysql内的socket，所以业务层不存在调用socket.close的现象。这个问题卡了四五天了。感谢云大。

[cloudwu]

我给 socketchannel 增加了收到对端关闭消息（如果无正在处理的请求）就立刻主动把 fd 关闭的机制 4fdf28d 。
之前会推迟到下一个请求时才检查连接，再 close 已经断开的 fd 。

@xuzhenyu2020 这并不会修复无法收到对方 FIN 消息的问题，只是提前了收到 FIN 后 close fd 的时机。

你这个问题最好能排查一下对端服务器是否有发送 FIN ，以及底层是否收到。(用 tcpdump)

如果有条件，可以在 C 代码中增加 log 帮助排查问题：

https://github.com/cloudwu/skynet/blob/master/skynet-src/socket_server.c#L1801 (epoll 报告断开)
https://github.com/cloudwu/skynet/blob/master/skynet-src/socket_server.c#L1489 (收到了 FIN)

还可以在 Lua 中增加 log：

https://github.com/cloudwu/skynet/blob/master/lualib/skynet/socket.lua#L119 (收到底层的 CLOSED 消息)
https://github.com/cloudwu/skynet/blob/master/lualib/skynet/socket.lua#L140 (收到底层的 ERR 消息)

[xuzhenyu2020]

好的，我打日志看一下，每一次测试都需要一天，因为不是马上必现，但是一个晚上过后肯定会出现。我先拉到最新的代码，然后按你说的方式打日志看看。

[xuzhenyu2020]

云大，最新代码不能运行：

[:0000000c] lua call [0 to :c : 0 msgsz = 24] error : ../skynet/lualib/skynet.lua:859: ../skynet/lualib/skynet.lua:330: ../skynet/lualib/skynet/socket.lua:374: assertion failed!
stack traceback:
[C]: in function 'assert'
../skynet/lualib/skynet/socket.lua:374: in function 'skynet.socket.block'
../skynet/lualib/skynet/socketchannel.lua:128: in upvalue 'f'
../skynet/lualib/skynet.lua:280: in function <../skynet/lualib/skynet.lua:252>
stack traceback:
[C]: in function 'assert'
../skynet/lualib/skynet.lua:859: in function 'skynet.dispatch_message'

[cloudwu]

我暂时先 reset 回去，想个更好的方法来实现。

[cloudwu]

@xuzhenyu2020 https://github.com/cloudwu/skynet/tree/onclose 我把相关修改放在 onclose 分支上，你可以试试。

增加了 socket.onclose 可以注册一个 callback 监控 socket 关闭事件。
socketchannel 利用 socket.onclose 在对端关闭连接，但自己长时间不提新的请求的情况下，可以及时关闭 fd 。

[xuzhenyu2020]

好的，我试一下，感谢云大。游戏现在还没正式部署，如果有需要，我可以提供服务器权限给云大帮助排查问题。

[cloudwu]

注：今天的修改只是为了可以即时关闭对端断开的连接 fd ，避免连接长期处于半关闭状态。但如果是无法检测到对方关闭，那么还是可能： 1. 底层存在 bug 2. 对方的确没有发送 FIN 。

[xuzhenyu2020]

用了onclose版本，观察到现在为止，一切正常(目前看到的都是有FIN的，所以不确定如果没有会怎么样)。将会持续观察，到明天再反馈一下结果。在这之前的测试，因为知识匮乏，不知道tcpdump，所以也没有获取到一手信息，不清楚前面几次出问题的时候到底有没有FIN.

[xuzhenyu2020]

云大，问题依旧，以下是抓包数据：
23:56:24.460079 IP 172.17.0.16.mysql > VM-0-11-centos.43114: Flags [F.], seq 105, ack 113955, win 1385, length 0
23:56:24.499992 IP VM-0-11-centos.43114 > 172.17.0.16.mysql: Flags [.], ack 106, win 229, length 0
23:56:43.125626 IP 172.17.0.16.mysql > VM-0-11-centos.44712: Flags [.], ack 122368, win 1451, length 0
23:56:43.125652 IP VM-0-11-centos.44712 > 172.17.0.16.mysql: Flags [.], ack 105, win 229, length 0
23:56:56.479145 IP 172.17.0.16.mysql > VM-0-11-centos.43718: Flags [F.], seq 105, ack 120128, win 1441, length 0
23:56:56.518990 IP VM-0-11-centos.43718 > 172.17.0.16.mysql: Flags [.], ack 106, win 229, length 0
23:57:28.420168 IP 172.17.0.16.mysql > VM-0-11-centos.43724: Flags [F.], seq 105, ack 120503, win 1005, length 0
23:57:28.459993 IP VM-0-11-centos.43724 > 172.17.0.16.mysql: Flags [.], ack 106, win 229, length 0
23:59:32.512805 IP 172.17.0.16.mysql > VM-0-11-centos.44090: Flags [F.], seq 105, ack 120494, win 999, length 0
23:59:32.551990 IP VM-0-11-centos.44090 > 172.17.0.16.mysql: Flags [.], ack 106, win 876, length 0
00:00:04.488632 IP 172.17.0.16.mysql > VM-0-11-centos.44122: Flags [F.], seq 105, ack 120563, win 1437, length 0
00:00:04.527991 IP VM-0-11-centos.44122 > 172.17.0.16.mysql: Flags [.], ack 106, win 229, length 0
00:00:07.932282 IP 172.17.0.16.mysql > VM-0-11-centos.43052: Flags [.], ack 114000, win 1389, length 0
00:00:07.932302 IP VM-0-11-centos.43052 > 172.17.0.16.mysql: Flags [.], ack 47657, win 972, length 0
00:00:36.496174 IP 172.17.0.16.mysql > VM-0-11-centos.44712: Flags [F.], seq 105, ack 122368, win 1451, length 0
00:00:36.535991 IP VM-0-11-centos.44712 > 172.17.0.16.mysql: Flags [.], ack 106, win 229, length 0

有看到这个时间段有[F.]标记，但是skynet没有打印"socket closed by peer : 172.17.0.16 3306"，我的理解是mysql这边在这个时间段集中将几个连接断开了，但是不知道什么原因，skynet端依然没有感知到。

[xuzhenyu2020]

对了，补充一点，第一次被mysql断开后正常，第二次断开就不正常了。
以下是第一次断开的时候打印出来的日志：
03/14/21 19:13:05.53 [:0000000c] socket closed by peer : 172.17.0.16 3306
03/14/21 19:13:05.53 [:0000000c] close fd:7
03/14/21 19:13:05.53 [:0000000c] socket closed by peer : 172.17.0.16 3306
03/14/21 19:13:05.53 [:0000000c] close fd:6
03/14/21 19:13:05.53 [:0000000c] socket closed by peer : 172.17.0.16 3306
03/14/21 19:13:05.53 [:0000000c] close fd:8
03/14/21 19:13:05.53 [:0000000c] socket closed by peer : 172.17.0.16 3306
03/14/21 19:13:05.53 [:0000000c] close fd:5
03/14/21 19:13:05.58 [:0000000c] socket closed by peer : 172.17.0.16 3306
03/14/21 19:13:05.58 [:0000000c] close fd:9
03/14/21 19:13:05.58 [:0000000c] socket closed by peer : 172.17.0.16 3306
03/14/21 19:13:05.58 [:0000000c] close fd:10
03/14/21 19:13:05.58 [:0000000c] socket closed by peer : 172.17.0.16 3306
03/14/21 19:13:05.58 [:0000000c] close fd:12
03/14/21 19:13:05.58 [:0000000c] socket closed by peer : 172.17.0.16 3306
03/14/21 19:13:05.58 [:0000000c] close fd:11
03/14/21 19:13:05.58 [:0000000c] socket closed by peer : 172.17.0.16 3306
03/14/21 19:13:05.58 [:0000000c] close fd:13
03/14/21 19:13:05.59 [:0000000c] socket closed by peer : 172.17.0.16 3306
03/14/21 19:13:05.59 [:0000000c] close fd:4

晚上看电影回来后，测试了一下，发现能重连回mysql，然后第二次被断后就没有感知到socket的断开了。

[cloudwu]

建议在 C 里面加两行 log 帮助排查问题：

1. https://github.com/cloudwu/skynet/blob/master/skynet-src/socket_server.c#L1801 (epoll 报告断开)
2. https://github.com/cloudwu/skynet/blob/master/skynet-src/socket_server.c#L1489 (收到了 FIN)
   https://github.com/cloudwu/skynet/blob/master/skynet-src/socket_server.c#L1507

主要是看 C 层是否工作正常。其中 1 应该是在交换了 FIN 完全断开时触发，以上情况应该到不了；但 2 收到了 FIN 后，recv 就应该返回 0 。此处若正常工作，应该在对方断开后进入。 到 1489 行后，第一次会继续运行到 1507 ，返回 CLOSED 消息。

[cloudwu]

另外，虽然我觉得可能性不大，但还是需要考虑：

如果 socket 上有大量数据待读，但是服务处理不过来。这个时候底层会暂停(pause) 监听可读事件。

即：处理 mysql 请求的服务特别忙。那么也是可能无法及时处理关闭的。log 中会出现 Pause socket 。

[xuzhenyu2020]

好的，我今天在c层打印一下看看。另外针对你说的大量数据待读的问题：我们是一个开放世界生存游戏，玩家可以改变世界中的任何东西，世界的数据是用sproto协议编码存储在blob中，需要落地数据的时候，大概需要写入100k左右的数据，不知道这算不算大。

[xuzhenyu2020]

今天处理业务问题太晚了，没时间做测试，先休息了，c层打日志的测试结果睡醒后再弄。抱歉。

[xuzhenyu2020]

云大，咨询一下，如何使得在c里面打印的内容出现在skynet的日志中？

[cloudfreexiao]

skynet_error fprintf

[xuzhenyu2020]

现在使用的是fprintf，前台运行能打印，后台运行不能到日志中。请问skynet_error这个函数如何使用，非常感谢。

[xuzhenyu2020]

结果反馈：
在socket_server.c中增加了4个打印，分别是：
1801行附近
if(e->eof) {
fprintf(stderr, "socket_server.c line 1801\n");
1489行附近
if (n==0) {
fprintf(stderr, "before if s->closing\n");
if (s->closing) {
fprintf(stderr, "s->closing\n");
1507行附近
fprintf(stderr, "SOCKET_CLOSE\n");
return SOCKET_CLOSE;

第一次mysql端断开，分别打印出10对信息(一共启动了10个mysql连接)，日志如下。
[:00000018] KILL self
before if s->closing
SOCKET_CLOSE
before if s->closing
SOCKET_CLOSE
before if s->closing
SOCKET_CLOSE
before if s->closing
SOCKET_CLOSE
before if s->closing
SOCKET_CLOSE
before if s->closing
SOCKET_CLOSE
before if s->closing
SOCKET_CLOSE
before if s->closing
SOCKET_CLOSE
before if s->closing
SOCKET_CLOSE
before if s->closing
SOCKET_CLOSE
[:00000010] [DEBUG][1615907757903][./server/dwrh/webgate.lua:125] handle_socket:21

第二次mysql端断开连接好像有点不正常(貌似之前也都是第一次ok，后面可能会出问题)：
mysql端看，已经没有任何连接了，但是skynet打印出的信息只有5对，日志如下：
[:0000001c] KILL self
before if s->closing
SOCKET_CLOSE
before if s->closing
SOCKET_CLOSE
before if s->closing
SOCKET_CLOSE
before if s->closing
SOCKET_CLOSE
before if s->closing
SOCKET_CLOSE
[:00000010] [DEBUG][1615912622909][./server/dwrh/webgate.lua:125] handle_socket:27

此时再次触发sql指令，10个连接均能正常连接回mysql，没有出现之前的阻塞现象，只是就打印了5个信息，不知道这是否属于异常。
继续观察中。。。

[cloudwu]

skynet_error 第一个参数传 NULL 后面和 printf 一样。

1. 有一个罕见的情况在 https://github.com/cloudwu/skynet/blob/master/skynet-src/socket_server.c#L1446 read_socket 中。这里可以把 n 打印出来。当它是 0 但是 buffer->sz 不等于 0 的时候，会返回 SOCKET_DATA ；期待下一次 epoll_wait 拿到消息后再返回 SOCKET_CLOSE 。有可能 epoll_wait 后续再没有了 EPOLLIN 事件，这样就会漏掉 FIN 包的处理。

2. 另外，还有一种情况是没有处理到 read 0 的情况，但是向外写数据出错（收到 RST），这样会产生 SOCKET_ERR ，最终也会断开连接。https://github.com/cloudwu/skynet/blob/master/skynet-src/socket_server.c#L720 send_list_tcp 中可以加一行 log 记录这种情况。

少了 5 个 SOCKET_CLOSE 就会 lua 层少 5 个关闭事件。应该是有问题的。但你描述 10 个连接均重新建立连接，我猜测是情况 2 由 SOCKET_ERR 让 lua 层关闭了 fd 。如果只看 C 的 log ，那么还应该在https://github.com/cloudwu/skynet/blob/master/skynet-src/socket_server.c#L1135 close_socket 中记录一下是否有调用 socket.close 。ps. 上面的 log 的同时期 skynet 正常输出的 log 中有关 socket 的 log 信息是怎样的？

[cloudwu]

@xuzhenyu2020 我刚才提交了一个 patch ，用来处理上面提到的情况 2 。你可以更新试试。

它回滚了之前的 forward_message_tcp 的实现，改成增加 SOCKET_MORE 状态，让外层继续处理数据包。。

[xuzhenyu2020]

收到，我再跑一晚上，看结果。

[xuzhenyu2020]

辛苦云大，感谢🙏

[xuzhenyu2020]

纠正一下，有个乌龙，日志打出5对是正常对，刚刚仔细分析了一下日志，出现这个情况是因为：
1.第一次断开了10个连接，所以有10个close日志，
2.断开后，有5个连接重连了，所以第二次断开实际上只断开了5个连接，所以只有5个close日志。

有关socket的正常日志有看到，mysql重连的时候打印出：socket: disconnect detected 172.17.0.16 3306。除此外没有看到其他的socket关键字的日志。
很奇怪，昨晚这一晚是保持skynet前台运行的，没有再次出现mysql阻塞现象，从日志看，10个连接也都顺利连接回mysql——这是这一周多时间来，唯一一次没有阻塞住。今晚会用最新代码，在所有上述点位打上日志，后台运行再跑一晚看结果。

[xuzhenyu2020]

03/18/21 13:57:14.33 [:00000022] KILL self
03/18/21 14:42:51.07 [:00000000] before s->closing
03/18/21 14:42:51.07 [:00000000] SOCKET_CLOSE
03/18/21 14:42:51.07 [:0000000c] socket closed by peer : 172.17.0.16 3306
03/18/21 14:42:51.07 [:00000000] close_socket
03/18/21 14:43:23.09 [:00000000] before s->closing
03/18/21 14:43:23.09 [:00000000] SOCKET_CLOSE
03/18/21 14:43:23.09 [:0000000c] socket closed by peer : 172.17.0.16 3306
03/18/21 14:43:23.09 [:00000000] close_socket
03/18/21 14:43:55.10 [:00000000] before s->closing
03/18/21 14:43:55.10 [:00000000] SOCKET_CLOSE
03/18/21 14:43:55.10 [:0000000c] socket closed by peer : 172.17.0.16 3306
03/18/21 14:43:55.10 [:00000000] close_socket
03/18/21 14:44:27.10 [:00000000] before s->closing
03/18/21 14:44:27.10 [:00000000] SOCKET_CLOSE
03/18/21 14:44:27.10 [:0000000c] socket closed by peer : 172.17.0.16 3306
03/18/21 14:44:27.10 [:00000000] close_socket
03/18/21 14:44:59.06 [:00000000] before s->closing
03/18/21 14:44:59.06 [:00000000] SOCKET_CLOSE
03/18/21 14:44:59.06 [:0000000c] socket closed by peer : 172.17.0.16 3306
03/18/21 14:44:59.06 [:00000000] close_socket
03/18/21 14:45:31.07 [:00000000] before s->closing
03/18/21 14:45:31.07 [:00000000] SOCKET_CLOSE
03/18/21 14:45:31.07 [:0000000c] socket closed by peer : 172.17.0.16 3306
03/18/21 14:45:31.07 [:00000000] close_socket
03/18/21 14:46:03.09 [:00000000] before s->closing
03/18/21 14:46:03.09 [:00000000] SOCKET_CLOSE
03/18/21 14:46:03.09 [:0000000c] socket closed by peer : 172.17.0.16 3306
03/18/21 14:46:03.09 [:00000000] close_socket
03/18/21 14:46:35.10 [:00000000] before s->closing
03/18/21 14:46:35.10 [:00000000] SOCKET_CLOSE
03/18/21 14:46:35.10 [:0000000c] socket closed by peer : 172.17.0.16 3306
03/18/21 14:46:35.10 [:00000000] close_socket
03/18/21 14:57:03.00 [:00000000] before s->closing
03/18/21 14:57:03.00 [:00000000] SOCKET_CLOSE
03/18/21 14:57:03.00 [:0000000c] socket closed by peer : 172.17.0.16 3306
03/18/21 14:57:03.00 [:00000000] close_socket
03/18/21 14:57:14.40 [:00000000] before s->closing
03/18/21 14:57:14.40 [:00000000] SOCKET_CLOSE
03/18/21 14:57:14.40 [:0000000c] socket closed by peer : 172.17.0.16 3306
03/18/21 14:57:14.40 [:00000000] close_socket
03/18/21 16:54:15.31 [:0000000c] socket: error on unknown 45 Connection timed out
03/18/21 16:54:15.31 [:00000000] close_socket
03/18/21 16:54:48.07 [:0000000c] socket: error on unknown 46 Connection timed out
03/18/21 16:54:48.07 [:00000000] close_socket
03/18/21 16:55:20.84 [:0000000c] socket: error on unknown 47 Connection timed out
03/18/21 16:55:20.84 [:00000000] close_socket
03/18/21 16:55:53.61 [:00000000] close_socket
03/18/21 16:55:53.61 [:0000000c] socket: error on unknown 48 Connection timed out
03/18/21 16:56:26.38 [:0000000c] socket: error on unknown 49 Connection timed out
03/18/21 16:56:26.38 [:00000000] close_socket
03/18/21 16:56:59.14 [:0000000c] socket: error on unknown 50 Connection timed out
03/18/21 16:56:59.14 [:00000000] close_socket
03/18/21 16:57:31.91 [:00000000] close_socket
03/18/21 16:57:31.91 [:0000000c] socket: error on unknown 51 Connection timed out
03/18/21 16:58:04.68 [:00000000] close_socket
03/18/21 16:58:04.68 [:0000000c] socket: error on unknown 42 Connection timed out
03/18/21 17:08:27.27 [:00000000] close_socket
03/18/21 17:08:27.27 [:0000000c] socket: error on unknown 43 Connection timed out
03/18/21 17:08:43.66 [:0000000c] socket: error on unknown 44 Connection timed out
03/18/21 17:08:43.66 [:00000000] close_socket

用了最新的onclose分支，目前位置，一切正常，以上是断开的日志。

[xuzhenyu2020]

今天出了大量的以下这种日志(有好接近500条)，不知有没有问题，除此之外，mysql连接依然正常，mysql连接不正常的问题好像已经解决。
03/19/21 17:23:51.80 [:00000000] socket-server: EAGAIN capture.
03/19/21 17:23:51.84 [:00000000] socket-server: EAGAIN capture.
03/19/21 17:23:53.73 [:00000000] socket-server: EAGAIN capture.
03/19/21 17:23:53.84 [:00000000] socket-server: EAGAIN capture.
03/19/21 17:23:53.93 [:00000000] socket-server: EAGAIN capture.
03/19/21 17:23:53.97 [:00000000] socket-server: EAGAIN capture.
03/19/21 17:23:54.04 [:00000000] socket-server: EAGAIN capture.
03/19/21 17:23:54.10 [:00000000] socket-server: EAGAIN capture.
03/19/21 17:23:54.20 [:00000000] socket-server: EAGAIN capture.
03/19/21 17:23:54.30 [:00000000] socket-server: EAGAIN capture.
03/19/21 17:23:54.40 [:00000000] socket-server: EAGAIN capture.
03/19/21 17:23:54.51 [:00000000] socket-server: EAGAIN capture.
03/19/21 17:23:54.60 [:00000000] socket-server: EAGAIN capture.

[cloudwu]

我把这行 log 删掉了。因为现在的处理方式是 "如果 read 刚好是 n 就返回 SOCKET_MORE 再读一次”。如果恰好读完了，那么再读一次就会触发这行 log 。

以前之所以没有，是因为之前的逻辑是等 epoll 再次触发。

看 log ，虽然有 500 条这个 log ，但时间上并不连续，不像是死循环导致的输出。所以我判断新加的 SOCKET_MORE 的流程工作正常（每次 epoll 报告可读后，之多额外尝试一次，进入之前的 EAGAIN 分支）。

ps. 这个 log 是 500 条集中在一起么？

[xuzhenyu2020]

目前为止mysql依然正常，应该是解决了。EAGAIN这个日志不是连续的，是分散在一些时间段内的(间隔有好几个小时)，每次出现集中在1分钟左右时间内，连续报出十几到上百条之间。