Distributed | From dble log analysis to MySQL source code learning

Author: Yuan Linzhu

A development member of the DBLE team of Axon, mainly responsible for DBLE requirements development, troubleshooting and community question answering.

Source of this article: original contribution

*The original content is produced by the open source community of Aikesheng, and the original content shall not be used without authorization. For reprinting, please contact the editor and indicate the source.

---

background

In the customer's production environment, dble.log often shows no handler log. Although it does not affect the normal use of the customer's business, it is necessary to investigate the reason for this log printing and what kind of scenarios will print the log.

analyze

First, analyze the logs of dble and mysql to see if you can find available information from the logs

dble log

There are no handler logs and stream closed by peer logs printed by dble when dble receives the fin packet sent by mysql, and there are no other exceptions.

 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 log

There is a log of the connection timed out and the connection is closed, and there are no other exceptions

 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 related logic

Sent statement

• dble receives the statement sent by the client
• dble selects the connection processing the statement from the connection pool
• Select the appropriate responseHandler according to the statement type dble (responseHandler is used to - process the message sent by mysql, the responseHandler of the idle connection is null)
• Send a statement to mysql

Process mysql messages

• dble receives messages sent by mysql
• The connection of dble uses the responseHandler set when issuing the statement to process the message (end here when the responseHandler is found)
• The connection of dble cannot find the responseHandler, cannot process the message, print no handler log

Backend connection close processing

• dble receives a fin packet or detects an abnormality in the connection
• Print information about the connection close (close reason, information about the connection being closed)
• Clear the content of the connection binding (such as responseHandler, service and other information)
• Make this connection unavailable
• remove the connection from the connection pool

In theory, only the back-end connection of the dble execution statement is closed, and dble is still using the closed back-end connection to process the data sent by mysql, and the no handler log will appear. From the log, it can be found that dble processes the no handler log first. Close the connection, and then receive the fin packet sent by mysql, which is inconsistent with the logic of dble (the no handler log should not be printed first), which is a point of confusion that needs to be checked. Then start looking through the source code of dble to see if you can debug with the naked eye to create a scene that matches the log printing and explain the doubts in the log.

At this time, you can use arthas to go to the client environment to see the dble call chain and the information of the dble back-end connection at that time when printing the log, and then try to analyze the problem.

arthas analysis

• arthas command

 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

• From closeNoHandler_stack.log, you can see that dble received the error message from mysql, called the error method, and then called the closeNohander method to print the no handler log.

• From closeNoHandler.log, it can be seen that an idle connection has received the error message sent by mysql

There are only two possibilities for responseHandler = null in dble: 1. The connection that executes the sql statement will set the responseHandler to null after executing close 2. The responseHandler of the idle connection is null by default, because the close-related log will be printed in the log when the connection executes close, and There is no print in the dble log so exclude possible 1

Combined with the above log analysis, it seems that mysql closed the connection because of the connection timeout. At this time, dble not only received the fin packet sent by mysql but also received the error message sent by mysql, and then dble processed the error message and printed the no handler log. Try it out by guesswork using the same mysql version (8.0.25) as the client.

experiment

• mysql set timeout

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

• Start capturing packets on the MySQL server

 tcpdump  port 3312 -w time_wait.cap

• Start dble, then wait for the connection timeout in the connection pool to stop capturing packets
• Retrieve the backend connection that prints the no handler log in the dble log, and check the mysqlid (667 in this experiment) and localPort (51886 in this experiment)
• Retrieve the mysqlid in the mysql error log, and confirm that mysql actively closed the connection because of the connection timeout.
• Use tcp.port == 51886 to filter information in the packet capture file

Wireshark analyzes the captured file

From the content of the captured packets, we can see that after the connection of mysql times out, mysql first sends an error message to the client (dble) and then sends a fin package, which is in line with our guess.

Here I can't help but want to see what the Server Greeting Error 4031 in this packet capture result is and then find the relevant information in the mysql documentation

• Error 4031 message details

• It was found that it was added in mysql8.0.24, and then go to the 8.0.24 Release Notes of mysql to see if there are detailed instructions. It can be seen in the Release Notes that the connection mysql closed because of wait_timeout will send a message to the client containing the detailed reason for closing the connection before closing the connection.

• Look at the specific code processing

Source code brief description

• Logic before pr commit (red and gray)

  • Send the content of last_errno directly to the client (here the psh packet is sent to the client, not the mysql protocol message)
  • net->last_errno is set to ER_NET_WAIT_ERROR
  • Use the LogErr method to write the content of ER_NET_WAIT_ERROR to the error log
  • The connection is closed after writing log and sending data such as connection

• Logic after pr commit (green and gray)

  • net->last_errno is set to ER_CLIENT_INTERACTION_TIMEOUT
  • Use the LogErr method to write the content of ER_NET_WAIT_ERROR to the error log
  • Send the content of last_errno to the client (Error 4031)
  • The connection is closed after writing log and sending data such as connection

in conclusion

mysql8.0.24 and later versions will first send an error message to the client to close the connection when the mysql connection times out. If mysql closes the idle connection in the dble connection pool, the idle connection of dble will process the message, because there is no responseHandler for the idle connection (responseHandler is used by dble to process the message sent by mysql, so only the connection that executes the statement will process the message. There is a responseHandler, and the default responseHandler for idle connections is null), so dble directly prints the no handler log, which is a normal phenomenon. Of course, dble will adjust the connection timeout error message later.

refer to

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

https://dev.mysql.com/doc/relnotes/mysql/8.0/en/news-8-0-24.html

https://dev.mysql.com/doc/mysql-errors/8.0/en/server-error-reference.html

https://github.com/mysql/mysql-server/commit/14508bbb1790697c28659dd051fbc855cd3b5da9