分布式 | 从 dble 日志分析到 MySQL 源码学习

作者：袁琳铸

爱可生 DBLE 团队开发成员，主要负责 DBLE 需求开发，故障排查和社区问题解答。

本文来源：原创投稿

*爱可生开源社区出品，原创内容未经授权不得随意使用，转载请联系小编并注明来源。

背景

在客户的生产环境中，dble.log 时常出现 no handler 日志。虽然没有影响客户业务的正常使用，但是需要调查下这个日志打印的原因是什么以及什么样的场景才会打印该日志。

分析

首先对 dble 和 mysql 的日志进行分析，看看能不能从日志中找到可用信息

dble日志

日志中有 no handler 日志和 dble 收到 mysql 发送的 fin 包打印的 stream closed by peer 的日志，并无其他异常。

2022-09-02 03:25:23.450  INFO [0-backendWorker] (com.actiontech.dble.net.response.DefaultResponseHandler.closeNoHandler(DefaultResponseHandler.java:116)) - no handler bind in this service MySQLResponseService[isExecuting = false attachment = null autocommitSynced = true isolationSynced = true xaStatus = 0 isDDL = false complexQuery = false] with response handler [null] with rrs = [null]  with connection BackendConnection[id = 342 host = 10.186.62.41 port = 3312 localPort = 51886 mysqlId = 677 db config = dbInstance[name=M1,disabled=false,maxCon=1000,minCon=10]
2022-09-02 03:25:23.450  INFO [0-backendWorker] (com.actiontech.dble.net.connection.BackendConnection.close(BackendConnection.java:125)) - connection id 342 mysqlId 677 close for reason no handler
2022-09-02 03:25:23.450  INFO [1-NIOBackendRW] (com.actiontech.dble.net.service.AbstractService.beforeInsertServiceTask(AbstractService.java:170)) - prepare close for conn.conn id 342,reason [stream closed by peer]
2022-09-02 03:25:23.450  INFO [0-backendWorker] (com.actiontech.dble.net.connection.AbstractConnection.closeImmediatelyInner(AbstractConnection.java:169)) - connection id close for reason [no handler] with connection BackendConnection[id = 342 host = 10.186.62.41 port = 3312 localPort = 51886 mysqlId = 677 db config = dbInstance[name=M1,disabled=false,maxCon=1000,minCon=10]

mysql 日志

存在连接超时而关闭连接的日志，并无其他异常

2022-09-02T03:25:23.375174Z 672 [Note] [MY-013730] [Server] 'wait_timeout' period of 20 seconds was exceeded for `root`@`%`. The idle time since last command was too long.
2022-09-02T03:25:23.375252Z 677 [Note] [MY-010914] [Server] Aborted connection 677 to db: 'unconnected' user: 'root' host: '10.186.62.148' (The client was disconnected by the server because of inactivity.).

dble 相关逻辑

下发语句

• dble 收到客户端发送的语句
• dble 从连接池中选择处理语句的连接
• 根据语句类型 dble 选择合适的 responseHandler（responseHandler 用来- 处理 mysql 发送的报文，空闲连接的 responseHandler 为 null）
• 下发语句到 mysql

处理 mysql 报文

• dble 接收 mysql 发送的报文
• dble 的 connection 使用下发语句时设置的 responseHandler 处理该报文（找到 responseHandler 的情况下这里结束）
• dble 的 connection 无法找到 responseHandler ，无法处理该报文，打印 no handler 日志

后端连接 close 处理

• dble 收到 fin 包或者检测到该连接存在异常
• 打印连接 close 相关信息（close 原因，被关闭的连接的信息）
• 清空连接绑定的内容（比如 responseHandler ，service 等信息）
• 设置该连接不可用
• 从连接池中移除该连接

理论情况下只有 dble 执行语句的的后端连接进行 close 处理，dble 依旧在使用这个被 close 的后端连接处理 mysql 发送的数据才会出现 no handler 日志，从日志中可以发现 dble 先处理 no handler 日志关闭连接，然后才收到了 mysql 发送的 fin 包，这与 dble 的逻辑不符（不应该先打印 no handler 日志），这是需要排查的疑惑点。然后开始翻阅 dble 的源码看看能不能用肉眼 debug 出一个符合日志打印的场景和对日志中的疑惑点进行解释，经过翻来覆去的 review 没有发现可能场景也无法解释 dble 日志中的现象。

这时候可以换个方式，借助 arthas 去客户环境中看看打印日志时 dble 的调用链和当时 dble 后端 connection 的信息，然后在尝试分析问题。

arthas 分析

• arthas 命令

stack com.actiontech.dble.net.response.DefaultResponseHandler closeNoHandler -n 1000 >> closeNoHandler_stack.log
watch com.actiontech.dble.net.response.DefaultResponseHandler closeNoHandler '{params,returnObj,throwExp,target}' -n 1000 -x 3 -b >> closeNoHandler.log

• 从 closeNoHandler_stack.log 可以看到 dble 收到了 mysql 传过来的 error 报文，调用了 error 方法，然后再调用 closeNohander 方法打印了 no handler 日志

• 从 closeNoHandler.log 中可以看到是一个空闲连接收到了 mysql 发送的 error 报文

dble 中 responseHandler = null 只有两种可能1.执行 sql 语句的 connection 执行 close 后会把 responseHandler 置为 null 2.空闲连接的 responseHandler 默认为 null ，因为 connection 执行 close 会在日志中会打印 close 相关日志，而 dble 日志中没有打印所以排除可能1

结合上述日志分析，看起来是 mysql 因为连接超时关闭该连接，这时候 dble 不仅收到 mysql 发送的 fin 包还收到了 mysql 发送的 error 报文，然后 dble 处理 error 报文打印了 no handler 日志。使用和客户相同的 mysql 版本（8.0.25）按照猜想进行尝试。

实验

• mysql 设置超时时间

mysql> set global interactive_timeout=20;
Query OK, 0 rows affected (0.00 sec)

• 在 MySQL 服务器上开始抓包

tcpdump  port 3312 -w time_wait.cap

• 启动 dble ，然后等待连接池中的连接超时，停止抓包
• dble 日志中检索打印 no handler 日志的后端连接，查看 mysqlid（本实验中为667）和 localPort（本实验中为51886）
• 拿着 mysqlid 在 mysql error log 中检索，确认为因为连接超时 mysql 主动关闭了该连接
• 使用 tcp.port == 51886 在抓包文件中过滤信息

wireshark 分析抓包文件

从抓包内容中可以看到 mysql 的连接超时后，mysql 先向客户端（dble）发送了一个 error 报文然后在发送一个 fin 包，符合我们的猜想

这里就忍不住想看看这个抓包结果中的 Server Greeting Error 4031 是什么然后在 mysql 文档中找到了相关信息

• Error 4031 报文详细信息

• 发现是在 mysql8.0.24 中加入的，然后去 mysql 的 8.0.24 Release Notes 查看是否有详细说明。可以看到 Release Notes 中提到了因为 wait_timeout 闭的连接 mysql 在关闭该连接之前会先向客户端发送一个包含关闭该连接的详细原因的报文

• 再看看具体代码处理

源码简要说明

• pr 提交之前的逻辑（红色部分和灰色部分）

  • 直接向客户端发送 last_errno 的内容（这里向客户端发送的是 psh 包，不是 mysql 协议的报文）
  • net->last_errno 置为 ER_NET_WAIT_ERROR
  • 使用 LogErr 方法将 ER_NET_WAIT_ERROR 的内容写入 error log
  • 连接等 write 日志和发送数据结束后关闭

• pr 提交之后的逻辑（绿色部分和灰色部分）

  • net->last_errno 置为 ER_CLIENT_INTERACTION_TIMEOUT
  • 使用 LogErr 方法将 ER_NET_WAIT_ERROR 的内容写入 error log
  • 向客户端发送 last_errno 的内容（Error 4031）
  • 连接等 write 日志和发送数据结束后关闭

结论

mysql8.0.24 及其之后的版本在因为 mysql 连接超时的情况下会向客户端先发送一个 error 报文在关闭连接 。如果 mysql 关闭的是 dble 连接池中的空闲连接，dble 的空闲连接会处理这个报文，由于空闲连接不存在 responseHandler（responseHandler 是 dble 用来处理 mysql 发送的报文，所以只有执行语句的连接才会有 responseHandler ，空闲连接默认 responseHandler 为 null），所以 dble 就直接打印了 no handler 日志，这是一个正常现象，当然对连接超时的 error 报文 dble 会在之后进行调整。

参考

https://arthas.aliyun.com/doc/

https://dev.mysql.com/doc/rel...

https://dev.mysql.com/doc/mys...

https://github.com/mysql/mysq...