实验:MySQL 客户端SocketTimeout 抓包分析

发布时间:2024年01月23日

实验准备

服务端环境准备
  • 服务器信息

阿里云 99 大洋白嫖机

$ cat /proc/version
Linux version 5.15.0-83-generic (buildd@lcy02-amd64-027) (gcc (Ubuntu 11.4.0-1ubuntu1~22.04) 11.4.0, GNU ld (GNU Binutils for Ubuntu) 2.38) #92-Ubuntu SMP Mon Aug 14 09:30:42 UTC 2023
  • 安装 docker,tshark
$ sudo apt-get update
$ sudo apt-get install tshark

# 文档地址:https://docs.docker.com/engine/install/ubuntu/
$ sudo apt-get install docker-ce docker-ce-cli containerd.io docker-buildx-plugin docker-compose-plugin
  • 启动 MySQL
$ docker run -it -d --net=host -e MYSQL_ROOT_PASSWORD=123 --name=plantegg mysql

$ docker exec -it 1308dd3a8093  sh
# mysql 信息
mysql> \s
--------------
mysql  Ver 8.3.0 for Linux on x86_64 (MySQL Community Server - GPL)

Connection id:		9
Current database:	mysql
Current user:		root@localhost
SSL:			Not in use
Current pager:		stdout
Using outfile:		''
Using delimiter:	;
Server version:		8.3.0 MySQL Community Server - GPL
Protocol version:	10
Connection:		Localhost via UNIX socket
Server characterset:	utf8mb4
Db     characterset:	utf8mb4
Client characterset:	latin1
Conn.  characterset:	latin1
UNIX socket:		/var/run/mysqld/mysqld.sock
Binary data as:		Hexadecimal
Uptime:			1 min 12 sec

Threads: 2  Questions: 52  Slow queries: 0  Opens: 177  Flush tables: 3  Open tables: 96  Queries per second avg: 0.722
  • 初始化 MySQL 密码、数据库
CREATE DATABASE test CHARACTER SET utf8mb4 COLLATE utf8mb4_unicode_ci;


ALTER USER 'root'@'%' IDENTIFIED WITH mysql_native_password BY '123';


CREATE USER 'test'@'%'  IDENTIFIED BY '123';  
GRANT ALL PRIVILEGES ON test.* TO test@'%';  
FLUSH PRIVILEGES;

# 创建表
create table t_user  
(  
    id        bigint(20) unsigned not null auto_increment primary key comment 'primary key',  
    name      varchar(64)         not null default '' comment 'user name',  
    age       tinyint unsigned    not null default 0 comment '年龄',  
    gender    tinyint unsigned    not null default 0 comment '性别, 0 男,1 女',  
    create_at datetime(3)         not null default current_timestamp(3) comment 'record create date',  
    update_at datetime(3)         not null default current_timestamp(3) on update current_timestamp(3) comment 'record update date'  
) engine = innodb  
  default charset = utf8mb4  
  collate = utf8mb4_unicode_ci comment '用户表';

# 插入数据
insert into t_user (id, name, age) values (1, "tom", 18);
  • 执行查询
mysql>  select sleep(10), id, name from t_user where id = 100;
Empty set (0.00 sec)

mysql>  select sleep(10), id, name from t_user where id = 1;
+-----------+----+------+
| sleep(10) | id | name |
+-----------+----+------+
|         0 |  1 | tom  |
+-----------+----+------+
1 row in set (10.00 sec)
  • 能查到数据时,sleep 生效
  • 数据不存在时,sleep 不生效
客户端环境
实验命令
  • 抓包命令
sudo tshark -i eth0   -f "port 3306"   -T fields -e frame.number -e frame.time_delta -e tcp.srcport -e tcp.dstport -e _ws.col.Info -e mysql.query

和任老板提供的命令有两处不同:

  • 过滤 3306 端口:-f "port 3306"
  • 我执行时 -e col.Info 告诉我不存在,打印 tcp 信息使用的是: -e _ws.col.Info 修改参考

实验一:查询到数据

客户端日志

在这里插入图片描述

服务端日志

在这里插入图片描述

$ sudo tshark -i eth0 -f "port 3306"   -T fields -e frame.number -e frame.time_delta -e tcp.srcport -e tcp.dstport -e _ws.col.Info -e mysql.query -w /tmp/test01.pcapng

Running as user "root" and group "root". This could be dangerous.
Capturing on 'eth0'
 ** (tshark:218561) 12:22:47.706536 [Main MESSAGE] -- Capture started.
 ** (tshark:218561) 12:22:47.706635 [Main MESSAGE] -- File: "/tmp/test01.pcapng"
1	0.000000000	54488	3306	544883306 [SYN] Seq=0 Win=65535 Len=0 MSS=1380 WS=64 TSval=1267692360 TSecr=0 SACK_PERM=1
2	0.000049702	3306	54488	330654488 [SYN, ACK] Seq=0 Ack=1 Win=65160 Len=0 MSS=1460 SACK_PERM=1 TSval=937995438 TSecr=1267692360 WS=128
3	0.039986759	54488	3306	544883306 [ACK] Seq=1 Ack=1 Win=131328 Len=0 TSval=1267692412 TSecr=937995438
4	0.000318587	3306	54488	Server Greeting  proto=10 version=8.3.0
5	0.035079732	54488	3306	544883306 [ACK] Seq=1 Ack=78 Win=131200 Len=0 TSval=1267692444 TSecr=937995478
6	0.042406937	54488	3306	Login Request user=test db=test
7	0.000024975	3306	54488	330654488 [ACK] Seq=78 Ack=243 Win=65152 Len=0 TSval=937995556 TSecr=1267692479
8	0.000120879	3306	54488	Auth Switch Request
9	0.041719056	54488	3306	544883306 [ACK] Seq=243 Ack=126 Win=131200 Len=0 TSval=1267692524 TSecr=937995556
10	0.008455727	54488	3306	Auth Switch Response
11	0.000214608	3306	54488	Response  OK
12	0.051355477	54488	3306	544883306 [ACK] Seq=267 Ack=137 Win=131136 Len=0 TSval=1267692574 TSecr=937995606
13	0.007896109	54488	3306	Request Query	/* mysql-connector-java-5.1.45 ( Revision: 9131eefa398531c7dc98776e8a3fe839e544c5b2 ) */SELECT  @@session.auto_increment_increment AS auto_increment_increment, @@character_set_client AS character_set_client, @@character_set_connection AS character_set_connection, @@character_set_results AS character_set_results, @@character_set_server AS character_set_server, @@collation_server AS collation_server, @@init_connect AS init_connect, @@interactive_timeout AS interactive_timeout, @@license AS license, @@lower_case_table_names AS lower_case_table_names, @@max_allowed_packet AS max_allowed_packet, @@net_buffer_length AS net_buffer_length, @@net_write_timeout AS net_write_timeout, @@have_query_cache AS have_query_cache, @@sql_mode AS sql_mode, @@system_time_zone AS system_time_zone, @@time_zone AS time_zone, @@transaction_isolation AS transaction_isolation, @@wait_timeout AS wait_timeout
14	0.000274155	3306	54488	Response TABULAR Response  OK
15	0.031818314	54488	3306	544883306 [ACK] Seq=1164 Ack=1208 Win=130112 Len=0 TSval=1267692633 TSecr=937995666
16	0.039941641	54488	3306	Request Query	SHOW WARNINGS
17	0.000146182	3306	54488	Response TABULAR Response  OK
18	0.036652518	54488	3306	544883306 [ACK] Seq=1182 Ack=1411 Win=130816 Len=0 TSval=1267692704 TSecr=937995738
19	0.003256273	54488	3306	Request Query	SET NAMES utf8mb4
20	0.000150310	3306	54488	Response  OK
21	0.039927195	54488	3306	544883306 [ACK] Seq=1204 Ack=1422 Win=131008 Len=0 TSval=1267692745 TSecr=937995778
22	0.006934971	54488	3306	Request Query	SET character_set_results = NULL
23	0.000130213	3306	54488	Response  OK
24	0.042973818	54488	3306	544883306 [ACK] Seq=1241 Ack=1433 Win=131008 Len=0 TSval=1267692800 TSecr=937995825
25	0.007007438	54488	3306	Request Query	SET autocommit=1
26	0.000137131	3306	54488	Response  OK
27	0.042772784	54488	3306	544883306 [ACK] Seq=1262 Ack=1444 Win=131008 Len=0 TSval=1267692845 TSecr=937995875
28	0.027224826	54488	3306	Request Prepare Statement	select sleep(10), id from t_user where id = ?
29	0.000209866	3306	54488	Response
30	0.049384269	54488	3306	544883306 [ACK] Seq=1312 Ack=1568 Win=130944 Len=0 TSval=1267692917 TSecr=937995945
31	0.000024961	54488	3306	Request Execute Statement
32	0.043205059	3306	54488	330654488 [ACK] Seq=1568 Ack=1332 Win=64256 Len=0 TSval=937996038 TSecr=1267692918
33	1.699961343	54488	3306	544883306 [FIN, ACK] Seq=1332 Ack=1568 Win=131072 Len=0 TSval=1267694649 TSecr=937996038
34	0.044208960	3306	54488	330654488 [ACK] Seq=1568 Ack=1333 Win=64256 Len=0 TSval=937997782 TSecr=1267694649
35	3.213033715	3306	54488	Response TABULAR Response  OK Response  OK
36	0.000053494	3306	54488	Response  Error 1158
37	0.000061370	3306	54488	330654488 [FIN, ACK] Seq=1742 Ack=1333 Win=64256 Len=0 TSval=938000995 TSecr=1267694649
38	0.032613195	54488	3306	544883306 [RST] Seq=1333 Win=0 Len=0
包分析
  1. 三次握手成功后,MySQL Server 向客户端发送 Greeting 请求,除了基本的版本、状态信息,还有 salt 字段,用于后续的密码校验。

在这里插入图片描述

  1. 连接建立成功后,客户端发送 Login 请求,可以看到数据库、用户名、密码信息。密码基于 md5、sha1 算法以及 greeting 请求的盐进行了加密。

在这里插入图片描述

校验成功后就会执行后续的查询;失败的话就会报 1045 错误。下图是一个失败的抓包示例:

在这里插入图片描述

  1. 登录校验成功,会开始执行查询,在 Prepare Statement 前会执行一系列的准备语句。

在这里插入图片描述

  1. 接着就是执行 Prepare Statement 了,会向 MySQL 发 prepareStatement 请求

在这里插入图片描述

然后是执行阶段,可以看到传的 ID = 1 的参数

在这里插入图片描述

看代码是分别执行了两次 conn.prepareStatement(sql);stmt2.executeQuery(); ,但抓包只看了一次 prepareStatement 请求,应该是客户端缓存了。翻了下代码应该是下面这段:

if (this.cachePrepStmts.getValue()) {  
    ParseInfo pStmtInfo = this.cachedPreparedStatementParams.get(nativeSql);  
  
    if (pStmtInfo == null) {  
        pStmt = ClientPreparedStatement.getInstance(getMultiHostSafeProxy(), nativeSql, this.database);  
  
        this.cachedPreparedStatementParams.put(nativeSql, pStmt.getParseInfo());  
    } else {  
        pStmt = ClientPreparedStatement.getInstance(getMultiHostSafeProxy(), nativeSql, this.database, pStmtInfo);  
    }  
}

在这里插入图片描述

  1. 查询超时

客户端设置了 1.7s 的 socket timeout,可以看到在 0.59 秒 MySQL 确认了 execute 语句,然后在 2.29 秒客户端向服务端发送终止连接的请求。

在这里插入图片描述

实验二:查询不到数据

客户端日志
$ java -cp .:./mysql-connector-java-5.1.45.jar Test "jdbc:mysql://123.57.2.39:3306/test?useSSL=false&useServerPrepStmts=true&cachePrepStmts=true&connectTimeout=500&socketTimeout=1700" test 123 "select sleep(10), id from t_user where id = ?" 10
服务端日志
$ sudo tshark -i eth0 -f "port 3306"   -T fields -e frame.number -e frame.time_delta -e tcp.srcport -e tcp.dstport -e _ws.col.Info -e mysql.query -w /tmp/test02.pcapng

Running as user "root" and group "root". This could be dangerous.
Capturing on 'eth0'
 ** (tshark:218654) 12:24:27.002498 [Main MESSAGE] -- Capture started.
 ** (tshark:218654) 12:24:27.002581 [Main MESSAGE] -- File: "/tmp/test02.pcapng"
1	0.000000000	4612	3306	46123306 [SYN] Seq=0 Win=65535 Len=0 MSS=1380 WS=64 TSval=1205035536 TSecr=0 SACK_PERM=1
2	0.000058342	3306	4612	33064612 [SYN, ACK] Seq=0 Ack=1 Win=65160 Len=0 MSS=1460 SACK_PERM=1 TSval=938094158 TSecr=1205035536 WS=128
3	0.039938068	4612	3306	46123306 [ACK] Seq=1 Ack=1 Win=131328 Len=0 TSval=1205035575 TSecr=938094158
4	0.000330231	3306	4612	Server Greeting  proto=10 version=8.3.0
5	0.110430727	4612	3306	46123306 [ACK] Seq=1 Ack=78 Win=131200 Len=0 TSval=1205035637 TSecr=938094198
6	0.007077249	4612	3306	Login Request user=test db=test
7	0.000025041	3306	4612	33064612 [ACK] Seq=78 Ack=243 Win=65152 Len=0 TSval=938094316 TSecr=1205035674
8	0.000140115	3306	4612	Auth Switch Request
9	0.039862066	4612	3306	46123306 [ACK] Seq=243 Ack=126 Win=131200 Len=0 TSval=1205035732 TSecr=938094316
10	0.008360335	4612	3306	Auth Switch Response
11	0.000192880	3306	4612	Response  OK
12	0.054352994	4612	3306	46123306 [ACK] Seq=267 Ack=137 Win=131136 Len=0 TSval=1205035783 TSecr=938094365
13	0.008302588	4612	3306	Request Query	/* mysql-connector-java-5.1.45 ( Revision: 9131eefa398531c7dc98776e8a3fe839e544c5b2 ) */SELECT  @@session.auto_increment_increment AS auto_increment_increment, @@character_set_client AS character_set_client, @@character_set_connection AS character_set_connection, @@character_set_results AS character_set_results, @@character_set_server AS character_set_server, @@collation_server AS collation_server, @@init_connect AS init_connect, @@interactive_timeout AS interactive_timeout, @@license AS license, @@lower_case_table_names AS lower_case_table_names, @@max_allowed_packet AS max_allowed_packet, @@net_buffer_length AS net_buffer_length, @@net_write_timeout AS net_write_timeout, @@have_query_cache AS have_query_cache, @@sql_mode AS sql_mode, @@system_time_zone AS system_time_zone, @@time_zone AS time_zone, @@transaction_isolation AS transaction_isolation, @@wait_timeout AS wait_timeout
14	0.000349999	3306	4612	Response TABULAR Response  OK
15	0.037027110	4612	3306	46123306 [ACK] Seq=1164 Ack=1208 Win=130112 Len=0 TSval=1205035843 TSecr=938094428
16	0.034611889	4612	3306	Request Query	SHOW WARNINGS
17	0.000158468	3306	4612	Response TABULAR Response  OK
18	0.049715364	4612	3306	46123306 [ACK] Seq=1182 Ack=1411 Win=130816 Len=0 TSval=1205035916 TSecr=938094499
19	0.006872693	4612	3306	Request Query	SET NAMES utf8mb4
20	0.000147500	3306	4612	Response  OK
21	0.044582956	4612	3306	46123306 [ACK] Seq=1204 Ack=1422 Win=131008 Len=0 TSval=1205035971 TSecr=938094556
22	0.007435888	4612	3306	Request Query	SET character_set_results = NULL
23	0.000169693	3306	4612	Response  OK
24	0.040867725	4612	3306	46123306 [ACK] Seq=1241 Ack=1433 Win=131008 Len=0 TSval=1205036024 TSecr=938094608
25	0.006848669	4612	3306	Request Query	SET autocommit=1
26	0.000146285	3306	4612	Response  OK
27	0.053149480	4612	3306	46123306 [ACK] Seq=1262 Ack=1444 Win=131008 Len=0 TSval=1205036072 TSecr=938094656
28	0.028069029	4612	3306	Request Prepare Statement	select sleep(10), id from t_user where id = ?
29	0.000247868	3306	4612	Response
30	0.041648584	4612	3306	46123306 [ACK] Seq=1312 Ack=1568 Win=130944 Len=0 TSval=1205036153 TSecr=938094738
31	0.006910927	4612	3306	Request Execute Statement
32	0.000296156	3306	4612	Response TABULAR Response  OK
33	0.039407443	4612	3306	46123306 [ACK] Seq=1333 Ack=1665 Win=130944 Len=0 TSval=1205036202 TSecr=938094786
34	0.000800578	4612	3306	Request Execute Statement
35	0.000286834	3306	4612	Response TABULAR Response  OK
36	0.052320713	4612	3306	46123306 [ACK] Seq=1352 Ack=1762 Win=130944 Len=0 TSval=1205036244 TSecr=938094827
37	0.006926131	4612	3306	[TCP Previous segment not captured] 46123306 [FIN, ACK] Seq=1357 Ack=1762 Win=131072 Len=0 TSval=1205036257 TSecr=938094827
38	0.000055496	3306	4612	[TCP Dup ACK 35#1] 3306 → 4612 [ACK] Seq=1762 Ack=1352 Win=64256 Len=0 TSval=938094886 TSecr=1205036244 SLE=1357 SRE=1358
39	0.006790060	4612	3306	[TCP Out-Of-Order] 46123306 [PSH, ACK] Seq=1352 Ack=1762 Win=131072 Len=5 TSval=1205036257 TSecr=938094827
40	0.000034601	3306	4612	33064612 [ACK] Seq=1762 Ack=1358 Win=64256 Len=0 TSval=938094893 TSecr=1205036257
41	0.000098597	3306	4612	33064612 [FIN, ACK] Seq=1762 Ack=1358 Win=64256 Len=0 TSval=938094893 TSecr=1205036257
42	0.035847690	4612	3306	46123306 [ACK] Seq=1358 Ack=1763 Win=131072 Len=0 TSval=1205036308 TSecr=938094893
43	0.006935677	4612	3306	[TCP Spurious Retransmission] 46123306 [FIN, PSH, ACK] Seq=1352 Ack=1762 Win=131072 Len=5 TSval=1205036301 TSecr=938094886
44	0.000032567	3306	4612	33064612 [RST] Seq=1762 Win=0 Len=0

测试了好几次,并没有看到另一位老铁看到的 MySQL 的 Command Quit 包。

在这里插入图片描述

简要总结

  • 中间件连接问题,本质上都是 TCP/IP 的通信问题,抓包之下一切无所遁形。

  • 做技术当然要对很多具体的知识点做掌握,但更重要的是底层内功的修炼,可以提高自己在不熟悉的问题场景下蹚出一条路的能力。

文章来源:https://blog.csdn.net/Ahri_J/article/details/135758317
本文来自互联网用户投稿,该文观点仅代表作者本人,不代表本站立场。本站仅提供信息存储空间服务,不拥有所有权,不承担相关法律责任。