ProxySQL 排错 Max connect timeout reached while reaching hostgroup 10 after 10000ms

ProxySQL 排错

• 问题分析:
  在ProxySQL在集群下,因未知原因导致误测到所有节点OFFLINE_HARD,并runtime_mysql_servers表清空,从而导致前端查询无法传递到后端对应的servers上,重新load mysql servers to runtime可以暂时解决,但没有找到长期解决办法,只好退回单节点模式。如有解决的兄弟希望你分享给我(k2865#qq.com,或讨论区留言 )
• 版本和环境

ProxySQL:
admin@127.0.0.1 [(none)]> select @@Version;
+--------------------+
| @@version          |
+--------------------+
| v1.4.10-1-g5eb0f3e |
+--------------------+
1 row in set (0.00 sec)
admin@127.0.0.1 [(none)]>select * from disk.proxysql_servers;
+----------+------+--------+-----------+
| hostname | port | weight | comment   |
+----------+------+--------+-----------+
| db211    | 6032 | 1      | secondary |
| db210    | 6032 | 1      | primary   |
+----------+------+--------+-----------+
2 rows in set (0.00 sec)
--
--
MGR:
root@localhost [sysbench_testdata]>select version();
+------------+
| version()  |
+------------+
| 5.7.23-log |
+------------+
1 row in set (0.00 sec)
root@localhost [sysbench_testdata]>select * from performance_schema.replication_group_members;
+---------------------------+--------------------------------------+-------------+-------------+--------------+
| CHANNEL_NAME              | MEMBER_ID                            | MEMBER_HOST | MEMBER_PORT | MEMBER_STATE |
+---------------------------+--------------------------------------+-------------+-------------+--------------+
| group_replication_applier | 33a6c4f8-a67a-11e8-b7f6-0050568beaf6 | db211       |        3507 | ONLINE       |
| group_replication_applier | 951678d2-91a2-11e8-be71-0050568be82c | db210       |        3507 | ONLINE       |
| group_replication_applier | abac4f08-a683-11e8-9447-0050568b744a | db212       |        3507 | ONLINE       |
+---------------------------+--------------------------------------+-------------+-------------+--------------+
3 rows in set (0.00 sec)

• 故障现像:
  ProxySQL 开始最先是正常的.可以读写,通过sysbench 也能正常压测,但随后报以下错误:

FATAL: MySQL error: 9001 "Max connect timeout reached while reaching hostgroup 10 after 10000ms"
(last message repeated 1 times)
FATAL: `thread_init' function failed: /usr/share/sysbench/oltp_common.lua:273: SQL API error
(last message repeated 1 times)
FATAL: mysql_stmt_prepare() failed
FATAL: MySQL error: 9001 "Max connect timeout reached while reaching hostgroup 10 after 10000ms"
FATAL: mysql_stmt_prepare() failed
FATAL: MySQL error: 9001 "Max connect timeout reached while reaching hostgroup 10 after 10000ms"
FATAL: mysql_stmt_prepare() failed
FATAL: MySQL error: 9001 "Max connect timeout reached while reaching hostgroup 10 after 10001ms"
FATAL: mysql_stmt_prepare() failed

• 手工连接,发现直接连接MGR节点是可以正常连接并查询的,连接proxysql,可以登录但无法查询:

wyz@db210 [(none)]>select * from wenyz.t2;
ERROR 9001 (HY000): Max connect timeout reached while reaching hostgroup 11 after 10000ms
wyz@db210 [(none)]>select * from wenyz.t2;
ERROR 9001 (HY000): Max connect timeout reached while reaching hostgroup 11 after 10000ms

查看官方问题库,得以下解释:

11. No Hostgroup 0 has been configured , then why we get "Max connect timeout reached while reaching hostgroup 0 after 10000ms" ?
This is how MySQL Query Rules work while selecting hostgroups.

When you set any query rules inside table mysql_query_rules , Then your query get analyzed by the Query Processor to decide which destination hostgroup it should forward. (according to mysql_query_rules.destination_hostgroup)

When your Query Processor doesn't find any query matching to query rule then the default hostgroup for the specific user is applied (according to mysql_users.default_hostgroup)

Example : Default Hostgroup for User

根据这一信息,查看ProxySQL状态,发现runtime_mysql_servers没有记录.

admin@127.0.0.1 [(none)]>select * from mysql_servers;
+--------------+----------+------+--------+--------+-------------+-----------------+---------------------+---------+----------------+---------+
| hostgroup_id | hostname | port | status | weight | compression | max_connections | max_replication_lag | use_ssl | max_latency_ms | comment |
+--------------+----------+------+--------+--------+-------------+-----------------+---------------------+---------+----------------+---------+
| 10           | db212    | 3507 | ONLINE | 1      | 0           | 1000            | 0                   | 0       | 0              |         |
| 11           | db210    | 3507 | ONLINE | 1      | 0           | 1000            | 0                   | 0       | 0              |         |
| 11           | db212    | 3507 | ONLINE | 1      | 0           | 1000            | 0                   | 0       | 0              |         |
| 11           | db211    | 3507 | ONLINE | 1      | 0           | 1000            | 0                   | 0       | 0              |         |
| 13           | db211    | 3507 | ONLINE | 1      | 0           | 1000            | 0                   | 0       | 0              |         |
| 13           | db210    | 3507 | ONLINE | 1      | 0           | 1000            | 0                   | 0       | 0              |         |
+--------------+----------+------+--------+--------+-------------+-----------------+---------------------+---------+----------------+---------+
6 rows in set (0.00 sec)

admin@127.0.0.1 [(none)]>select * from runtime_mysql_servers;
Empty set (0.00 sec)

admin@127.0.0.1 [(none)]>

• 重新执行load mysql servers to runtime后恢复正常

admin@127.0.0.1 [(none)]>load mysql servers to runtime;
Query OK, 0 rows affected (0.00 sec)

• 问题重现时proxysql.log中出现以下信息:

2018-08-25 23:33:06 MySQL_Session.cpp:2884:handler(): [WARNING] Error during query on (10,db212,3507): 1295, This command is not supported in the prepared statement protocol yet
2018-08-25 23:33:06 MySQL_Session.cpp:2884:handler(): [WARNING] Error during query on (10,db212,3507): 1295, This command is not supported in the prepared statement protocol yet
2018-08-25 23:33:06 MySQL_Session.cpp:2884:handler(): [WARNING] Error during query on (10,db212,3507): 1295, This command is not supported in the prepared statement protocol yet
2018-08-25 23:33:06 mysql_connection.cpp:634:handler(): [ERROR] Failed to mysql_real_connect() on db212:3507 , FD (Conn:308 , MyDS:308) , 1040: Too many connections.
2018-08-25 23:33:06 mysql_connection.cpp:634:handler(): [ERROR] Failed to mysql_real_connect() on db212:3507 , FD (Conn:311 , MyDS:311) , 1040: Too many connections.
2018-08-25 23:33:06 mysql_connection.cpp:634:handler(): [ERROR] Failed to mysql_real_connect() on db212:3507 , FD (Conn:312 , MyDS:312) , 1040: Too many connections.
2018-08-25 23:33:06 mysql_connection.cpp:634:handler(): [ERROR] Failed to mysql_real_connect() on db212:3507 , FD (Conn:315 , MyDS:315) , 1040: Too many connections.
2018-08-25 23:33:06 mysql_connection.cpp:634:handler(): [ERROR] Failed to mysql_real_connect() on db212:3507 , FD (Conn:320 , MyDS:320) , 1040: Too many connections.
2018-08-25 23:33:06 MySQL_HostGroups_Manager.cpp:303:connect_error(): [ERROR] Shunning server db212:3507 with 5 errors/sec. Shunning for 10 seconds
2018-08-25 23:33:06 mysql_connection.cpp:634:handler(): [ERROR] Failed to mysql_real_connect() on db212:3507 , FD (Conn:322 , MyDS:322) , 1040: Too many connections.
2018-08-25 23:33:06 mysql_connection.cpp:634:handler(): [ERROR] Failed to mysql_real_connect() on db212:3507 , FD (Conn:309 , MyDS:309) , 1040: Too many connections.
2018-08-25 23:33:06 mysql_connection.cpp:634:handler(): [ERROR] Failed to mysql_real_connect() on db212:3507 , FD (Conn:326 , MyDS:326) , 1040: Too many connections.
2018-08-25 23:33:06 mysql_connection.cpp:634:handler(): [ERROR] Failed to mysql_real_connect() on db212:3507 , FD (Conn:313 , MyDS:313) , 1040: Too many connections.
2018-08-25 23:33:06 mysql_connection.cpp:634:handler(): [ERROR] Failed to mysql_real_connect() on db212:3507 , FD (Conn:328 , MyDS:328) , 1040: Too many connections.
2018-08-25 23:33:06 mysql_connection.cpp:634:handler(): [ERROR] Failed to mysql_real_connect() on db212:3507 , FD (Conn:317 , MyDS:317) , 1040: Too many connections.
2018-08-25 23:33:06 mysql_connection.cpp:634:handler(): [ERROR] Failed to mysql_real_connect() on db212:3507 , FD (Conn:325 , MyDS:325) , 1040: Too many connections.
2018-08-25 23:33:06 mysql_connection.cpp:634:handler(): [ERROR] Failed to mysql_real_connect() on db212:3507 , FD (Conn:334 , MyDS:334) , 1040: Too many connections.
2018-08-25 23:33:06 mysql_connection.cpp:634:handler(): [ERROR] Failed to mysql_real_connect() on db212:3507 , FD (Conn:332 , MyDS:332) , 1040: Too many connections.
2018-08-25 23:33:06 mysql_connection.cpp:634:handler(): [ERROR] Failed to mysql_real_connect() on db212:3507 , FD (Conn:331 , MyDS:331) , 1040: Too many connections.
2018-08-25 23:33:06 mysql_connection.cpp:634:handler(): [ERROR] Failed to mysql_real_connect() on db212:3507 , FD (Conn:307 , MyDS:307) , 1040: Too many connections.
2018-08-25 23:33:06 mysql_connection.cpp:634:handler(): [ERROR] Failed to mysql_real_connect() on db212:3507 , FD (Conn:310 , MyDS:310) , 1040: Too many connections.
2018-08-25 23:33:06 mysql_connection.cpp:634:handler(): [ERROR] Failed to mysql_real_connect() on db212:3507 , FD (Conn:314 , MyDS:314) , 1040: Too many connections.
2018-08-25 23:33:06 mysql_connection.cpp:634:handler(): [ERROR] Failed to mysql_real_connect() on db212:3507 , FD (Conn:316 , MyDS:316) , 1040: Too many connections.
2018-08-25 23:33:06 mysql_connection.cpp:634:handler(): [ERROR] Failed to mysql_real_connect() on db212:3507 , FD (Conn:318 , MyDS:318) , 1040: Too many connections.
2018-08-25 23:33:06 mysql_connection.cpp:634:handler(): [ERROR] Failed to mysql_real_connect() on db212:3507 , FD (Conn:321 , MyDS:321) , 1040: Too many connections.
2018-08-25 23:33:06 mysql_connection.cpp:634:handler(): [ERROR] Failed to mysql_real_connect() on db212:3507 , FD (Conn:324 , MyDS:324) , 1040: Too many connections.
2018-08-25 23:33:06 mysql_connection.cpp:634:handler(): [ERROR] Failed to mysql_real_connect() on db212:3507 , FD (Conn:327 , MyDS:327) , 1040: Too many connections.
2018-08-25 23:33:06 MySQL_Session.cpp:2884:handler(): [WARNING] Error during query on (10,db212,3507): 1295, This command is not supported in the prepared statement protocol yet
2018-08-25 23:33:06 mysql_connection.cpp:634:handler(): [ERROR] Failed to mysql_real_connect() on db212:3507 , FD (Conn:330 , MyDS:330) , 1040: Too many connections.
2018-08-25 23:33:06 mysql_connection.cpp:634:handler(): [ERROR] Failed to mysql_real_connect() on db212:3507 , FD (Conn:333 , MyDS:333) , 1040: Too many connections.
2018-08-25 23:33:06 MySQL_Session.cpp:2884:handler(): [WARNING] Error during query on (10,db212,3507): 1295, This command is not supported in the prepared statement protocol yet
2018-08-25 23:33:06 MySQL_Session.cpp:2884:handler(): [WARNING] Error during query on (10,db212,3507): 1295, This command is not supported in the prepared statement protocol yet
2018-08-25 23:33:06 mysql_connection.cpp:634:handler(): [ERROR] Failed to mysql_real_connect() on db212:3507 , FD (Conn:335 , MyDS:335) , 1040: Too many connections.
2018-08-25 23:33:06 MySQL_Session.cpp:2884:handler(): [WARNING] Error during query on (10,db212,3507): 1295, This command is not supported in the prepared statement protocol yet
2018-08-25 23:33:06 MySQL_Session.cpp:2884:handler(): [WARNING] Error during query on (10,db212,3507): 1295, This command is not supported in the prepared statement protocol yet
2018-08-25 23:33:06 MySQL_Session.cpp:2884:handler(): [WARNING] Error during query on (10,db212,3507): 1295, This command is not supported in the prepared statement protocol yet
2018-08-25 23:33:06 MySQL_Session.cpp:2884:handler(): [WARNING] Error during query on (10,db212,3507): 1295, This command is not supported in the prepared statement protocol yet
2018-08-25 23:33:06 mysql_connection.cpp:634:handler(): [ERROR] Failed to mysql_real_connect() on db212:3507 , FD (Conn:336 , MyDS:336) , 1040: Too many connections.
2018-08-25 23:33:06 mysql_connection.cpp:634:handler(): [ERROR] Failed to mysql_real_connect() on db212:3507 , FD (Conn:337 , MyDS:337) , 1040: Too many connections.
2018-08-25 23:33:06 MySQL_Session.cpp:2884:handler(): [WARNING] Error during query on (10,db212,3507): 1295, This command is not supported in the prepared statement protocol yet
2018-08-25 23:33:06 MySQL_Session.cpp:2884:handler(): [WARNING] Error during query on (10,db212,3507): 1295, This command is not supported in the prepared statement protocol yet
2018-08-25 23:33:06 MySQL_Session.cpp:2884:handler(): [WARNING] Error during query on (10,db212,3507): 1295, This command is not supported in the prepared statement protocol yet
2018-08-25 23:33:06 MySQL_Session.cpp:2884:handler(): [WARNING] Error during query on (10,db212,3507): 1295, This command is not supported in the prepared statement protocol yet
2018-08-25 23:33:06 [INFO] Dumping current MySQL Servers structures for hostgroup ALL
HID: 10 , address: db212 , port: 3507 , weight: 1 , status: SHUNNED , max_connections: 1000 , max_replication_lag: 0 , use_ssl: 0 , max_latency_ms: 0 , comment: 
HID: 11 , address: db210 , port: 3507 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 0 , use_ssl: 0 , max_latency_ms: 0 , comment: 
HID: 11 , address: db212 , port: 3507 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 0 , use_ssl: 0 , max_latency_ms: 0 , comment: 
HID: 11 , address: db211 , port: 3507 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 0 , use_ssl: 0 , max_latency_ms: 0 , comment: 
HID: 13 , address: db211 , port: 3507 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 0 , use_ssl: 0 , max_latency_ms: 0 , comment: 
HID: 13 , address: db210 , port: 3507 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 0 , use_ssl: 0 , max_latency_ms: 0 , comment: 
2018-08-25 23:33:06 [INFO] Dumping mysql_servers
+--------------+----------+------+--------+--------+-------------+-----------------+---------------------+---------+----------------+---------+-----------------+
| hostgroup_id | hostname | port | weight | status | compression | max_connections | max_replication_lag | use_ssl | max_latency_ms | comment | mem_pointer     |
+--------------+----------+------+--------+--------+-------------+-----------------+---------------------+---------+----------------+---------+-----------------+
| 10           | db212    | 3507 | 1      | 1      | 0           | 1000            | 0                   | 0       | 0              |         | 140420659150080 |
| 13           | db210    | 3507 | 1      | 0      | 0           | 1000            | 0                   | 0       | 0              |         | 140420659545088 |
| 13           | db211    | 3507 | 1      | 0      | 0           | 1000            | 0                   | 0       | 0              |         | 140420659544960 |
| 11           | db211    | 3507 | 1      | 0      | 0           | 1000            | 0                   | 0       | 0              |         | 140420659544832 |
| 11           | db212    | 3507 | 1      | 0      | 0           | 1000            | 0                   | 0       | 0              |         | 140420659548032 |
| 11           | db210    | 3507 | 1      | 0      | 0           | 1000            | 0                   | 0       | 0              |         | 140420659549696 |
+--------------+----------+------+--------+--------+-------------+-----------------+---------------------+---------+----------------+---------+-----------------+
2018-08-25 23:33:11 MySQL_HostGroups_Manager.cpp:2580:update_group_replication_set_writer(): [WARNING] Group Replication: setting host db211:3507 as writer
2018-08-25 23:33:11 MySQL_HostGroups_Manager.cpp:2580:update_group_replication_set_writer(): [WARNING] Group Replication: setting host db210:3507 as writer
2018-08-25 23:33:11 [INFO] Dumping current MySQL Servers structures for hostgroup ALL
HID: 10 , address: db212 , port: 3507 , weight: 1 , status: SHUNNED , max_connections: 1000 , max_replication_lag: 0 , use_ssl: 0 , max_latency_ms: 0 , comment: 
HID: 11 , address: db210 , port: 3507 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 0 , use_ssl: 0 , max_latency_ms: 0 , comment: 
HID: 11 , address: db212 , port: 3507 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 0 , use_ssl: 0 , max_latency_ms: 0 , comment: 
HID: 11 , address: db211 , port: 3507 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 0 , use_ssl: 0 , max_latency_ms: 0 , comment: 
HID: 13 , address: db211 , port: 3507 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 0 , use_ssl: 0 , max_latency_ms: 0 , comment: 
HID: 13 , address: db210 , port: 3507 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 0 , use_ssl: 0 , max_latency_ms: 0 , comment: 
2018-08-25 23:33:11 [INFO] Dumping mysql_servers

• 出现以上信息时,sysbench端报ERROR 9001 (HY000): Max connect timeout reached while reaching hostgroup 11 after 10000ms了.但proxysql的runtime_mysql_server中还是正常的.在proxysql.log中有大量的deadlock 或lock timeout,输出的runtime_mysql_server信息是全的.但到第二天早上才有如下:

2018-08-26 08:16:27 [INFO] Dumping current MySQL Servers structures for hostgroup ALL
HID: 10 , address: db212 , port: 3507 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 0 , use_ssl: 0 , max_latency_ms: 0 , comment: 
HID: 11 , address: db210 , port: 3507 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 0 , use_ssl: 0 , max_latency_ms: 0 , comment: 
HID: 11 , address: db212 , port: 3507 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 0 , use_ssl: 0 , max_latency_ms: 0 , comment: 
HID: 11 , address: db211 , port: 3507 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 0 , use_ssl: 0 , max_latency_ms: 0 , comment: 
HID: 13 , address: db211 , port: 3507 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 0 , use_ssl: 0 , max_latency_ms: 0 , comment: 
HID: 13 , address: db210 , port: 3507 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 0 , use_ssl: 0 , max_latency_ms: 0 , comment: 
2018-08-26 08:16:27 [INFO] Dumping mysql_servers
+--------------+----------+------+--------+--------+-------------+-----------------+---------------------+---------+----------------+---------+-----------------+
| hostgroup_id | hostname | port | weight | status | compression | max_connections | max_replication_lag | use_ssl | max_latency_ms | comment | mem_pointer     |
+--------------+----------+------+--------+--------+-------------+-----------------+---------------------+---------+----------------+---------+-----------------+
| 10           | db212    | 3507 | 1      | 0      | 0           | 1000            | 0                   | 0       | 0              |         | 140420659150080 |
| 13           | db210    | 3507 | 1      | 0      | 0           | 1000            | 0                   | 0       | 0              |         | 140420659545088 |
| 13           | db211    | 3507 | 1      | 0      | 0           | 1000            | 0                   | 0       | 0              |         | 140420789185920 |
| 11           | db211    | 3507 | 1      | 0      | 0           | 1000            | 0                   | 0       | 0              |         | 140420659544832 |
| 11           | db212    | 3507 | 1      | 0      | 0           | 1000            | 0                   | 0       | 0              |         | 140420659548032 |
| 11           | db210    | 3507 | 1      | 0      | 0           | 1000            | 0                   | 0       | 0              |         | 140420659549696 |
+--------------+----------+------+--------+--------+-------------+-----------------+---------------------+---------+----------------+---------+-----------------+
2018-08-26 08:16:27 [INFO] Dumping current MySQL Servers structures for hostgroup ALL
HID: 10 , address: db212 , port: 3507 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 0 , use_ssl: 0 , max_latency_ms: 0 , comment: 
HID: 11 , address: db210 , port: 3507 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 0 , use_ssl: 0 , max_latency_ms: 0 , comment: 
HID: 11 , address: db212 , port: 3507 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 0 , use_ssl: 0 , max_latency_ms: 0 , comment: 
HID: 11 , address: db211 , port: 3507 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 0 , use_ssl: 0 , max_latency_ms: