Receiving unexplained Max connect timeout reached while reaching hostgroup 10 after 10000ms

5,177 views

Skip to first unread message

Todd Bryant

unread,

May 31, 2018, 1:35:22 AM5/31/18

to proxysql

Hi There,

We are running a number of ProxySQL servers in front of 2 Percona Clusters (1 running 5.5 and the other 5.7)

Due to issues with LAST_INSERT_ID on ProxySQL 1.4.5 we recently turned off multiplexing which resolved the issue, since then we have begun receiving 'Max connect timeout reached while reaching hostgroup 10 after 10000ms'

So we updated to ProxySQL 1.4.8 and tuned the TCP/IP stack in CentOS on our Percona nodes and ProxySQL in case connections were taking too long due to threads etc.

But as it turns out this made no difference either.

I have checked over our config and have been unable to find the cause, all backend servers in the pool are online, the stats for the pool show 0 ConnERR and none of the servers are under any particular load.

mysql> select * from stats_mysql_connection_pool;

+-----------+---------------+----------+--------+----------+----------+--------+---------+---------+-----------------+-----------------+------------+

+-----------+---------------+----------+--------+----------+----------+--------+---------+---------+-----------------+-----------------+------------+

| 10 | xxx.xxx.xxx.1 | 3306 | ONLINE | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 16573 |

| 10 | xxx.xxx.xxx.2 | 3306 | ONLINE | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 16593 |

| 10 | xxx.xxx.xxx.3 | 3306 | ONLINE | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 670 |

| 10 | xxx.xxx.xxx.4 | 3306 | ONLINE | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 550 |

| 10 | xxx.xxx.xxx.5 | 3306 | ONLINE | 23 | 8 | 31 | 0 | 108970 | 17898893 | 41559620 | 450 |

| 20 | xxx.xxx.xxx.6 | 3306 | ONLINE | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 20531 |

| 20 | xxx.xxx.xxx.7 | 3306 | ONLINE | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 16547 |

| 20 | xxx.xxx.xxx.8 | 3306 | ONLINE | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 182 |

| 20 | xxx.xxx.xxx.9 | 3306 | ONLINE | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 382 |

| 20 | xxx.xxx.xxx.10| 3306 | ONLINE | 6 | 4 | 10 | 0 | 3646 | 1508679 | 1789823 | 305 |

+-----------+---------------+----------+--------+----------+----------+--------+---------+---------+-----------------+-----------------+------------+

10 rows in set (0.00 sec)

mysql> select * from runtime_mysql_servers;

+--------------+---------------+------+--------+------------+-------------+-----------------+---------------------+---------+----------------+---------+

+--------------+---------------+------+--------+------------+-------------+-----------------+---------------------+---------+----------------+---------+

| 10 | xxx.xxx.xxx.1 | 3306 | ONLINE | 100 | 0 | 1000 | 0 | 0 | 0 | |

| 20 | xxx.xxx.xxx.2 | 3306 | ONLINE | 1000000000 | 0 | 1000 | 0 | 0 | 0 | |

| 20 | xxx.xxx.xxx.3 | 3306 | ONLINE | 1000 | 0 | 1000 | 0 | 0 | 0 | |

| 20 | xxx.xxx.xxx.4 | 3306 | ONLINE | 1000000 | 0 | 1000 | 0 | 0 | 0 | |

| 20 | xxx.xxx.xxx.5 | 3306 | ONLINE | 1 | 0 | 1000 | 0 | 0 | 0 | |

| 20 | xxx.xxx.xxx.6 | 3306 | ONLINE | 100 | 0 | 1000 | 0 | 0 | 0 | |

| 10 | xxx.xxx.xxx.7 | 3306 | ONLINE | 1000000000 | 0 | 1000 | 0 | 0 | 0 | |

| 10 | xxx.xxx.xxx.8 | 3306 | ONLINE | 1000 | 0 | 1000 | 0 | 0 | 0 | |

| 10 | xxx.xxx.xxx.9 | 3306 | ONLINE | 1000000 | 0 | 1000 | 0 | 0 | 0 | |

| 10 | xxx.xxx.xxx.10 | 3306 | ONLINE | 1 | 0 | 1000 | 0 | 0 | 0 | |

+--------------+---------------+------+--------+------------+-------------+-----------------+---------------------+---------+----------------+---------+

10 rows in set (0.00 sec)

mysql> select * from mysql_users;

+------------------------+-------------------------------------------+--------+---------+-------------------+----------------+---------------+------------------------+--------------+---------+----------+-----------------+

| user1 | ************************************ | 1 | 0 | 10 | NULL | 0 | 0 | 0 | 1 | 1 | 10000 |

| user2 | ************************************ | 1 | 0 | 10 | NULL | 0 | 0 | 0 | 1 | 1 | 10000 |

| user3 | ************************************ | 1 | 0 | 20 | NULL | 0 | 0 | 0 | 1 | 1 | 10000

stats_mysql_users shows nothing above 12 front end connections

The only thing which seems strange is that the ConnPool_get_conn_failure count in stats_mysql_global grows alot, but all other stats such as Server_Connections_aborted etc are all at 0

Currently our solution is simply to restart ProxySQL but lately it is happening every few hours

René Cannaò

unread,

May 31, 2018, 1:41:57 AM5/31/18

to Todd Bryant, proxysql

Hi Todd,

Did you check error log?

Thanks

--
You received this message because you are subscribed to the Google Groups "proxysql" group.
To unsubscribe from this group and stop receiving emails from it, send an email to proxysql+unsubscribe@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

Message has been deleted

Todd Bryant

unread,

May 31, 2018, 2:12:58 AM5/31/18

to proxysql

Hi Rene,

Thanks for the quick response, I had done on 1.4.5 when the error was occurring and it was always blank but interestingly I am now getting all sorts of errors.

The proxysql_galera_checker errors are interesting, my scheduler is setup as follows

mysql> select * from scheduler;

+----+--------+-------------+-------------------------------------------+-------------------------------------------+------+------+------+----------------------------------------------------+---------------------------+

| id | active | interval_ms | filename | arg1 | arg2 | arg3 | arg4 | arg5 | comment |

| 5 | 1 | 5000 | /usr/bin/proxysql_galera_checker | 10 | -1 | 0 | 1 | /var/lib/proxysql/proxysql_galera_checker_hg10.log | HG10 Every 5s |

| 6 | 1 | 5000 | /usr/bin/proxysql_galera_checker | 20 | -1 | 0 | 1 | /var/lib/proxysql/proxysql_galera_checker_hg20.log | HG20Every 5s |

| 10 | 0 | 5000 | /var/lib/proxysql/proxysql_galera_checker | 10 | 10 | 5 | 1 | /dev/null | Legacy Rule To Be Removed |

| 11 | 1 | 900000 | /usr/bin/php | /var/lib/proxysql/proxysql_sync_users.php | sync | | | | Every 15m |

4 rows in set (0.00 sec)

I can run /usr/bin/proxysql_galera_checker 10 10 0 1 /var/lib/proxysql/proxysql_galera_checker_hg10.log from command line and receive the same error

My proxysql-admin.cnf file is basically the default, it has the appropriate accounts but as we run 2 R/W HostGroups it cant do much with the config other than get the credentials required to run checks.

There are many many many lines of the below warning

2018-05-31 17:15:01 MySQL_Session.cpp:2863:handler(): [WARNING] Error during query on (10,xxx.xxx.9.180,3306): 1062, Duplicate entry '2bea087c-cfb3-4fa4-ba48-ffb08e0ff508' for key 'PRIMARY

I am now receiving the following

2018-05-31 17:14:06 [INFO] Shutdown angel process

2018-05-31 17:14:06 [INFO] ProxySQL version 1.4.8-1.1

2018-05-31 17:14:06 [INFO] Detected OS: Linux fe01-pdb.qst.vygr.net 3.10.0-862.3.2.el7.x86_64 #1 SMP Mon May 21 23:36:36 UTC 2018 x86_64

2018-05-31 17:14:06 [INFO] Starting ProxySQL

2018-05-31 17:14:06 [INFO] Sucessfully started

2018-05-31 17:14:06 [INFO] Angel process started ProxySQL process 30122

Standard ProxySQL Cluster rev. 0.1.0702 -- ProxySQL_Cluster.cpp -- Tue May 22 14:05:10 2018

Standard ProxySQL Statistics rev. 1.4.1027 -- ProxySQL_Statistics.cpp -- Tue May 22 14:05:10 2018

Standard ProxySQL HTTP Server Handler rev. 1.4.1031 -- ProxySQL_HTTP_Server.cpp -- Tue May 22 14:05:10 2018

2018-05-31 17:14:06 ProxySQL_Admin.cpp:3885:flush_mysql_variables___database_to_runtime(): [WARNING] Impossible to set not existing variable ping_interval_server with value "120000". Deleting. If the varia

ble name is correct, this version doesn't support it

Standard ProxySQL Admin rev. 0.2.0902 -- ProxySQL_Admin.cpp -- Tue May 22 14:05:11 2018

Standard MySQL Threads Handler rev. 0.2.0902 -- MySQL_Thread.cpp -- Tue May 22 14:05:11 2018

Standard MySQL Authentication rev. 0.2.0902 -- MySQL_Authentication.cpp -- Tue May 22 14:05:11 2018

2018-05-31 17:14:06 [INFO] Dumping current MySQL Servers structures for hostgroup ALL

2018-05-31 17:14:06 [INFO] Dumping mysql_servers

+--------------+----------+------+--------+--------+-------------+-----------------+---------------------+---------+----------------+---------+-------------+

+--------------+----------+------+--------+--------+-------------+-----------------+---------------------+---------+----------------+---------+-------------+

2018-05-31 17:14:06 [INFO] Dumping mysql_servers_incoming

+--------------+---------------+------+------------+--------+-------------+-----------------+---------------------+---------+----------------+---------+

+--------------+---------------+------+------------+--------+-------------+-----------------+---------------------+---------+----------------+---------+

| 10 | xxx.xxx.40.139 | 3306 | 100 | 0 | 0 | 1000 | 0 | 0 | 0 | |

| 10 | xxx.xxx.40.147 | 3306 | 1 | 0 | 0 | 1000 | 0 | 0 | 0 | |

| 10 | xxx.xxx.9.150 | 3306 | 1000000 | 0 | 0 | 1000 | 0 | 0 | 0 | |

| 10 | xxx.xxx.9.151 | 3306 | 1000 | 0 | 0 | 1000 | 0 | 0 | 0 | |

| 10 | xxx.xxx.9.180 | 3306 | 1000000000 | 0 | 0 | 1000 | 0 | 0 | 0 | |

| 20 | xxx.xxx.40.140 | 3306 | 100 | 0 | 0 | 1000 | 0 | 0 | 0 | |

| 20 | xxx.xxx.40.148 | 3306 | 1 | 0 | 0 | 1000 | 0 | 0 | 0 | |

| 20 | xxx.xxx.9.86 | 3306 | 1000000 | 0 | 0 | 1000 | 0 | 0 | 0 | |

| 20 | xxx.xxx.9.92 | 3306 | 1000 | 0 | 0 | 1000 | 0 | 0 | 0 | |

| 20 | xxx.xxx.9.85 | 3306 | 1000000000 | 0 | 0 | 1000 | 0 | 0 | 0 | |

+--------------+---------------+------+------------+--------+-------------+-----------------+---------------------+---------+----------------+---------+

2018-05-31 17:14:06 [INFO] New mysql_replication_hostgroups table

2018-05-31 17:14:06 [INFO] New mysql_group_replication_hostgroups table

2018-05-31 17:14:06 [INFO] Dumping current MySQL Servers structures for hostgroup ALL

HID: 10 , address: xxx.xxx.40.139 , port: 3306 , weight: 100 , status: ONLINE , max_connections: 1000 , max_replication_lag: 0 , use_ssl: 0 , max_latency_ms: 0 , comment:

HID: 10 , address: xxx.xxx.40.147 , port: 3306 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 0 , use_ssl: 0 , max_latency_ms: 0 , comment:

HID: 10 , address: xxx.xxx.9.150 , port: 3306 , weight: 1000000 , status: ONLINE , max_connections: 1000 , max_replication_lag: 0 , use_ssl: 0 , max_latency_ms: 0 , comment:

HID: 10 , address: xxx.xxx.9.151 , port: 3306 , weight: 1000 , status: ONLINE , max_connections: 1000 , max_replication_lag: 0 , use_ssl: 0 , max_latency_ms: 0 , comment:

HID: 10 , address: xxx.xxx.9.180 , port: 3306 , weight: 1000000000 , status: ONLINE , max_connections: 1000 , max_replication_lag: 0 , use_ssl: 0 , max_latency_ms: 0 , comment:

HID: 20 , address: xxx.xxx.40.140 , port: 3306 , weight: 100 , status: ONLINE , max_connections: 1000 , max_replication_lag: 0 , use_ssl: 0 , max_latency_ms: 0 , comment:

HID: 20 , address: xxx.xxx.40.148 , port: 3306 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 0 , use_ssl: 0 , max_latency_ms: 0 , comment:

HID: 20 , address: xxx.xxx.9.86 , port: 3306 , weight: 1000000 , status: ONLINE , max_connections: 1000 , max_replication_lag: 0 , use_ssl: 0 , max_latency_ms: 0 , comment:

HID: 20 , address: xxx.xxx.9.92 , port: 3306 , weight: 1000 , status: ONLINE , max_connections: 1000 , max_replication_lag: 0 , use_ssl: 0 , max_latency_ms: 0 , comment:

HID: 20 , address: xxx.xxx.9.85 , port: 3306 , weight: 1000000000 , status: ONLINE , max_connections: 1000 , max_replication_lag: 0 , use_ssl: 0 , max_latency_ms: 0 , comment:

2018-05-31 17:14:06 [INFO] Dumping mysql_servers

+--------------+---------------+------+------------+--------+-------------+-----------------+---------------------+---------+----------------+---------+-----------------+

+--------------+---------------+------+------------+--------+-------------+-----------------+---------------------+---------+----------------+---------+-----------------+

| 10 | xxx.xxx.40.139 | 3306 | 100 | 0 | 0 | 1000 | 0 | 0 | 0 | | 139841922797696 |

| 20 | xxx.xxx.9.85 | 3306 | 1000000000 | 0 | 0 | 1000 | 0 | 0 | 0 | | 139841922798976 |

| 20 | xxx.xxx.9.92 | 3306 | 1000 | 0 | 0 | 1000 | 0 | 0 | 0 | | 139841922798848 |

| 20 | xxx.xxx.9.86 | 3306 | 1000000 | 0 | 0 | 1000 | 0 | 0 | 0 | | 139841922798720 |

| 20 | xxx.xxx.40.148 | 3306 | 1 | 0 | 0 | 1000 | 0 | 0 | 0 | | 139841922798592 |

| 20 | xxx.xxx.40.140 | 3306 | 100 | 0 | 0 | 1000 | 0 | 0 | 0 | | 139841922798464 |

| 10 | xxx.xxx.9.180 | 3306 | 1000000000 | 0 | 0 | 1000 | 0 | 0 | 0 | | 139841922798336 |

| 10 | xxx.xxx.9.151 | 3306 | 1000 | 0 | 0 | 1000 | 0 | 0 | 0 | | 139841922798208 |

| 10 | xxx.xxx.9.150 | 3306 | 1000000 | 0 | 0 | 1000 | 0 | 0 | 0 | | 139841922798080 |

| 10 | xxx.xxx.40.147 | 3306 | 1 | 0 | 0 | 1000 | 0 | 0 | 0 | | 139841922797952 |

+--------------+---------------+------+------------+--------+-------------+-----------------+---------------------+---------+----------------+---------+-----------------+

Standard Query Processor rev. 0.2.0902 -- Query_Processor.cpp -- Tue May 22 14:05:10 2018

In memory Standard Query Cache (SQC) rev. 1.2.0905 -- Query_Cache.cpp -- Tue May 22 14:05:10 2018

2018-05-31 17:14:06 network.cpp:84:listen_on_unix(): [ERROR] Error unlink Unix Socket /tmp/proxysql.sock

Standard MySQL Monitor (StdMyMon) rev. 1.2.0723 -- MySQL_Monitor.cpp -- Tue May 22 14:05:10 2018

2018-05-31 17:14:07 network.cpp:84:listen_on_unix(): [ERROR] Error unlink Unix Socket /tmp/proxysql_admin.sock

/usr/bin/proxysql_galera_checker: line 126: ${PROXYSQL_DATADIR}/${CLUSTER_NAME}_mode: ambiguous redirect

cat: /var/lib/proxysql/HG10: No such file or directory

cat: Every: No such file or directory

cat: 5s: No such file or directory

cat: Legacy: No such file or directory

cat: Rule: No such file or directory

cat: To: No such file or directory

cat: Be: No such file or directory

cat: Removed_mode: No such file or directory

/usr/bin/proxysql_galera_checker: line 145: [: too many arguments

/usr/bin/proxysql_galera_checker: line 168: $CHECKER_PIDFILE: ambiguous redirect

2018-05-31 17:15:01 MySQL_Session.cpp:2863:handler(): [WARNING] Error during query on (10,xxx.xxx.9.180,3306): 1062, Duplicate entry '1324d312-c3e9-4556-a7d4-ff8ed6b59ae2' for key 'PRIMARY'

2018-05-31 17:15:01 MySQL_Session.cpp:2863:handler(): [WARNING] Error during query on (10,xxx.xxx.9.180,3306): 1062, Duplicate entry 'ab7f8d18-3912-4800-be5f-ffa2e1c45c22' for key 'PRIMARY'

2018-05-31 17:15:01 MySQL_Session.cpp:2863:handler(): [WARNING] Error during query on (10,xxx.xxx.9.180,3306): 1062, Duplicate entry 'e14a2d2d-b016-4de8-87a1-ffa7d6416c39' for key 'PRIMARY'

2018-05-31 17:15:01 MySQL_Session.cpp:2863:handler(): [WARNING] Error during query on (10,xxx.xxx.9.180,3306): 1062, Duplicate entry '00772a58-f7b5-4686-9c3d-ffb06c218237' for key 'PRIMARY'

2018-05-31 17:15:01 MySQL_Session.cpp:2863:handler(): [WARNING] Error during query on (10,xxx.xxx.9.180,3306): 1062, Duplicate entry '2bea087c-cfb3-4fa4-ba48-ffb08e0ff508' for key 'PRIMARY'

2018-05-31 17:15:01 MySQL_Session.cpp:2863:handler(): [WARNING] Error during query on (10,xxx.xxx.9.180,3306): 1062, Duplicate entry '6c18feac-a86e-47ef-93a6-ffb4d11808cd' for key 'PRIMARY'

2018-05-31 17:15:01 MySQL_Session.cpp:2863:handler(): [WARNING] Error during query on (10,xxx.xxx.9.180,3306): 1062, Duplicate entry '4ba5e1e5-cd2f-4f30-aa0e-ffc4f35f855a' for key 'PRIMARY'

2018-05-31 17:15:01 MySQL_Session.cpp:2863:handler(): [WARNING] Error during query on (10,xxx.xxx.9.180,3306): 1062, Duplicate entry 'ba47ac81-61de-4957-a51b-ffd63a1a61f2' for key 'PRIMARY'

2018-05-31 17:15:01 MySQL_Session.cpp:2863:handler(): [WARNING] Error during query on (10,xxx.xxx.9.180,3306): 1062, Duplicate entry '3973a1e4-b37a-4abe-8704-ffe0568bba82' for key 'PRIMARY'

2018-05-31 17:15:01 MySQL_Session.cpp:2863:handler(): [WARNING] Error during query on (10,xxx.xxx.9.180,3306): 1062, Duplicate entry '2bfb234f-6a71-4aaa-b18e-fffdcb95c724' for key 'PRIMARY'

/usr/bin/proxysql_galera_checker: line 126: ${PROXYSQL_DATADIR}/${CLUSTER_NAME}_mode: ambiguous redirect

cat: /var/lib/proxysql/HG10: No such file or directory

cat: Every: No such file or directory

cat: 5s: No such file or directory

cat: Legacy: No such file or directory

cat: Rule: No such file or directory

cat: To: No such file or directory

cat: Be: No such file or directory

cat: Removed_mode: No such file or directory

/usr/bin/proxysql_galera_checker: line 145: [: too many arguments

/usr/bin/proxysql_galera_checker: line 168: $CHECKER_PIDFILE: ambiguous redirect

/usr/bin/proxysql_galera_checker: line 126: ${PROXYSQL_DATADIR}/${CLUSTER_NAME}_mode: ambiguous redirect

cat: /var/lib/proxysql/HG20Every: No such file or directory

cat: 5s_mode: No such file or directory

/usr/bin/proxysql_galera_checker: line 145: [: /var/lib/proxysql/HG20Every: binary operator expected

/usr/bin/proxysql_galera_checker: line 168: $CHECKER_PIDFILE: ambiguous redirect

/usr/bin/proxysql_galera_checker: line 126: ${PROXYSQL_DATADIR}/${CLUSTER_NAME}_mode: ambiguous redirect

cat: /var/lib/proxysql/HG10: No such file or directory

cat: Every: No such file or directory

cat: 5s: No such file or directory

cat: Legacy: No such file or directory

cat: Rule: No such file or directory

cat: To: No such file or directory

cat: Be: No such file or directory

René Cannaò

unread,

May 31, 2018, 2:15:22 AM5/31/18

to Todd Bryant, proxysql

Hi Todd,

The error log suggests some problem with proxysql_galera_checker .

Not sure what causes the problem, but these 2 errors are probably relevant:

2018-05-31 17:14:06 network.cpp:84:listen_on_unix(): [ERROR] Error unlink Unix Socket /tmp/proxysql.sock

2018-05-31 17:14:07 network.cpp:84:listen_on_unix(): [ERROR] Error unlink Unix Socket /tmp/proxysql_admin.sock

Maybe these files exist already and are owned by root, and proxysql is unable to remove them?

I am not saying this is the root cause, but if proxysql_galera_checker uses /tmp/proxysql_admin.sock to access Admin and doesn't succeed, probably it can lead to unexpected behavior.

On 31 May 2018 at 08:07, Todd Bryant <todd....@gmail.com> wrote:

Hi Rene,

Thanks for the quick response, I had done on 1.4.5 when the error was occurring and it was always blank but interestingly I am now getting all sorts of errors.
The proxysql_galera_checker errors are interesting, my scheduler is setup as follows

mysql> select * from scheduler;
+----+--------+-------------+-------------------------------------------+-------------------------------------------+------+------+------+----------------------------------------------------+---------------------------+
| id | active | interval_ms | filename | arg1 | arg2 | arg3 | arg4 | arg5 | comment |
+----+--------+-------------+-------------------------------------------+-------------------------------------------+------+------+------+----------------------------------------------------+---------------------------+
| 5 | 1 | 5000 | /usr/bin/proxysql_galera_checker | 10 | -1 | 0 | 1 | /var/lib/proxysql/proxysql_galera_checker_hg10.log | HG10 Every 5s |
| 6 | 1 | 5000 | /usr/bin/proxysql_galera_checker | 20 | -1 | 0 | 1 | /var/lib/proxysql/proxysql_galera_checker_hg20.log | HG20Every 5s |
| 10 | 0 | 5000 | /var/lib/proxysql/proxysql_galera_checker | 10 | 10 | 5 | 1 | /dev/null | Legacy Rule To Be Removed |
| 11 | 1 | 900000 | /usr/bin/php | /var/lib/proxysql/proxysql_sync_users.php | sync | | | | Every 15m |
+----+--------+-------------+-------------------------------------------+-------------------------------------------+------+------+------+----------------------------------------------------+---------------------------+
4 rows in set (0.00 sec)

I can run /usr/bin/proxysql_galera_checker 10 10 0 1 /var/lib/proxysql/proxysql_galera_checker_hg10.log from command line and receive the same error
My proxysql-admin.cnf file is basically the default, it has the appropriate accounts but as we run 2 R/W HostGroups it cant do much with the config other than get the credentials required to run checks.

I am now receiving the following

2018-05-31 17:14:06 [INFO] Shutdown angel process
2018-05-31 17:14:06 [INFO] ProxySQL version 1.4.8-1.1
2018-05-31 17:14:06 [INFO] Detected OS: Linux fe01-pdb.qst.vygr.net 3.10.0-862.3.2.el7.x86_64 #1 SMP Mon May 21 23:36:36 UTC 2018 x86_64
2018-05-31 17:14:06 [INFO] Starting ProxySQL
2018-05-31 17:14:06 [INFO] Sucessfully started
2018-05-31 17:14:06 [INFO] Angel process started ProxySQL process 30122
Standard ProxySQL Cluster rev. 0.1.0702 -- ProxySQL_Cluster.cpp -- Tue May 22 14:05:10 2018
Standard ProxySQL Statistics rev. 1.4.1027 -- ProxySQL_Statistics.cpp -- Tue May 22 14:05:10 2018
Standard ProxySQL HTTP Server Handler rev. 1.4.1031 -- ProxySQL_HTTP_Server.cpp -- Tue May 22 14:05:10 2018
2018-05-31 17:14:06 ProxySQL_Admin.cpp:3885:flush_mysql_variables___database_to_runtime(): [WARNING] Impossible to set not existing variable ping_interval_server with value "120000". Deleting. If the varia
ble name is correct, this version doesn't support it
Standard ProxySQL Admin rev. 0.2.0902 -- ProxySQL_Admin.cpp -- Tue May 22 14:05:11 2018
Standard MySQL Threads Handler rev. 0.2.0902 -- MySQL_Thread.cpp -- Tue May 22 14:05:11 2018
Standard MySQL Authentication rev. 0.2.0902 -- MySQL_Authentication.cpp -- Tue May 22 14:05:11 2018
2018-05-31 17:14:06 [INFO] Dumping current MySQL Servers structures for hostgroup ALL
2018-05-31 17:14: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 |
+--------------+----------+------+--------+--------+-------------+-----------------+---------------------+---------+----------------+---------+-------------+
+--------------+----------+------+--------+--------+-------------+-----------------+---------------------+---------+----------------+---------+-------------+
2018-05-31 17:14:06 [INFO] Dumping mysql_servers_incoming
+--------------+---------------+------+------------+--------+-------------+-----------------+---------------------+---------+----------------+---------+

| hostgroup_id | hostname | port | weight | status | compression | max_connections | max_replication_lag | use_ssl | max_latency_ms | comment |
+--------------+---------------+------+------------+--------+-------------+-----------------+---------------------+---------+----------------+---------+
| 10 | 114.23.40.139 | 3306 | 100 | 0 | 0 | 1000 | 0 | 0 | 0 | |
| 10 | 114.23.40.147 | 3306 | 1 | 0 | 0 | 1000 | 0 | 0 | 0 | |
| 10 | 114.23.9.150 | 3306 | 1000000 | 0 | 0 | 1000 | 0 | 0 | 0 | |
| 10 | 114.23.9.151 | 3306 | 1000 | 0 | 0 | 1000 | 0 | 0 | 0 | |
| 10 | 114.23.9.180 | 3306 | 1000000000 | 0 | 0 | 1000 | 0 | 0 | 0 | |
| 20 | 114.23.40.140 | 3306 | 100 | 0 | 0 | 1000 | 0 | 0 | 0 | |
| 20 | 114.23.40.148 | 3306 | 1 | 0 | 0 | 1000 | 0 | 0 | 0 | |
| 20 | 114.23.9.86 | 3306 | 1000000 | 0 | 0 | 1000 | 0 | 0 | 0 | |
| 20 | 114.23.9.92 | 3306 | 1000 | 0 | 0 | 1000 | 0 | 0 | 0 | |
| 20 | 114.23.9.85 | 3306 | 1000000000 | 0 | 0 | 1000 | 0 | 0 | 0 | |

+--------------+---------------+------+------------+--------+-------------+-----------------+---------------------+---------+----------------+---------+
2018-05-31 17:14:06 [INFO] New mysql_replication_hostgroups table
2018-05-31 17:14:06 [INFO] New mysql_group_replication_hostgroups table
2018-05-31 17:14:06 [INFO] Dumping current MySQL Servers structures for hostgroup ALL

HID: 10 , address: 114.23.40.139 , port: 3306 , weight: 100 , status: ONLINE , max_connections: 1000 , max_replication_lag: 0 , use_ssl: 0 , max_latency_ms: 0 , comment:
HID: 10 , address: 114.23.40.147 , port: 3306 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 0 , use_ssl: 0 , max_latency_ms: 0 , comment:
HID: 10 , address: 114.23.9.150 , port: 3306 , weight: 1000000 , status: ONLINE , max_connections: 1000 , max_replication_lag: 0 , use_ssl: 0 , max_latency_ms: 0 , comment:
HID: 10 , address: 114.23.9.151 , port: 3306 , weight: 1000 , status: ONLINE , max_connections: 1000 , max_replication_lag: 0 , use_ssl: 0 , max_latency_ms: 0 , comment:
HID: 10 , address: 114.23.9.180 , port: 3306 , weight: 1000000000 , status: ONLINE , max_connections: 1000 , max_replication_lag: 0 , use_ssl: 0 , max_latency_ms: 0 , comment:
HID: 20 , address: 114.23.40.140 , port: 3306 , weight: 100 , status: ONLINE , max_connections: 1000 , max_replication_lag: 0 , use_ssl: 0 , max_latency_ms: 0 , comment:
HID: 20 , address: 114.23.40.148 , port: 3306 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 0 , use_ssl: 0 , max_latency_ms: 0 , comment:
HID: 20 , address: 114.23.9.86 , port: 3306 , weight: 1000000 , status: ONLINE , max_connections: 1000 , max_replication_lag: 0 , use_ssl: 0 , max_latency_ms: 0 , comment:
HID: 20 , address: 114.23.9.92 , port: 3306 , weight: 1000 , status: ONLINE , max_connections: 1000 , max_replication_lag: 0 , use_ssl: 0 , max_latency_ms: 0 , comment:
HID: 20 , address: 114.23.9.85 , port: 3306 , weight: 1000000000 , status: ONLINE , max_connections: 1000 , max_replication_lag: 0 , use_ssl: 0 , max_latency_ms: 0 , comment:

2018-05-31 17:14: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 | 114.23.40.139 | 3306 | 100 | 0 | 0 | 1000 | 0 | 0 | 0 | | 139841922797696 |
| 20 | 114.23.9.85 | 3306 | 1000000000 | 0 | 0 | 1000 | 0 | 0 | 0 | | 139841922798976 |
| 20 | 114.23.9.92 | 3306 | 1000 | 0 | 0 | 1000 | 0 | 0 | 0 | | 139841922798848 |
| 20 | 114.23.9.86 | 3306 | 1000000 | 0 | 0 | 1000 | 0 | 0 | 0 | | 139841922798720 |
| 20 | 114.23.40.148 | 3306 | 1 | 0 | 0 | 1000 | 0 | 0 | 0 | | 139841922798592 |
| 20 | 114.23.40.140 | 3306 | 100 | 0 | 0 | 1000 | 0 | 0 | 0 | | 139841922798464 |
| 10 | 114.23.9.180 | 3306 | 1000000000 | 0 | 0 | 1000 | 0 | 0 | 0 | | 139841922798336 |
| 10 | 114.23.9.151 | 3306 | 1000 | 0 | 0 | 1000 | 0 | 0 | 0 | | 139841922798208 |
| 10 | 114.23.9.150 | 3306 | 1000000 | 0 | 0 | 1000 | 0 | 0 | 0 | | 139841922798080 |
| 10 | 114.23.40.147 | 3306 | 1 | 0 | 0 | 1000 | 0 | 0 | 0 | | 139841922797952 |

+--------------+---------------+------+------------+--------+-------------+-----------------+---------------------+---------+----------------+---------+-----------------+
Standard Query Processor rev. 0.2.0902 -- Query_Processor.cpp -- Tue May 22 14:05:10 2018
In memory Standard Query Cache (SQC) rev. 1.2.0905 -- Query_Cache.cpp -- Tue May 22 14:05:10 2018
2018-05-31 17:14:06 network.cpp:84:listen_on_unix(): [ERROR] Error unlink Unix Socket /tmp/proxysql.sock
Standard MySQL Monitor (StdMyMon) rev. 1.2.0723 -- MySQL_Monitor.cpp -- Tue May 22 14:05:10 2018
2018-05-31 17:14:07 network.cpp:84:listen_on_unix(): [ERROR] Error unlink Unix Socket /tmp/proxysql_admin.sock
/usr/bin/proxysql_galera_checker: line 126: ${PROXYSQL_DATADIR}/${CLUSTER_NAME}_mode: ambiguous redirect
cat: /var/lib/proxysql/HG10: No such file or directory
cat: Every: No such file or directory
cat: 5s: No such file or directory
cat: Legacy: No such file or directory
cat: Rule: No such file or directory
cat: To: No such file or directory
cat: Be: No such file or directory
cat: Removed_mode: No such file or directory
/usr/bin/proxysql_galera_checker: line 145: [: too many arguments
/usr/bin/proxysql_galera_checker: line 168: $CHECKER_PIDFILE: ambiguous redirect

2018-05-31 17:15:01 MySQL_Session.cpp:2863:handler(): [WARNING] Error during query on (10,114.23.9.180,3306): 1062, Duplicate entry '1324d312-c3e9-4556-a7d4-ff8ed6b59ae2' for key 'PRIMARY'
2018-05-31 17:15:01 MySQL_Session.cpp:2863:handler(): [WARNING] Error during query on (10,114.23.9.180,3306): 1062, Duplicate entry 'ab7f8d18-3912-4800-be5f-ffa2e1c45c22' for key 'PRIMARY'
2018-05-31 17:15:01 MySQL_Session.cpp:2863:handler(): [WARNING] Error during query on (10,114.23.9.180,3306): 1062, Duplicate entry 'e14a2d2d-b016-4de8-87a1-ffa7d6416c39' for key 'PRIMARY'
2018-05-31 17:15:01 MySQL_Session.cpp:2863:handler(): [WARNING] Error during query on (10,114.23.9.180,3306): 1062, Duplicate entry '00772a58-f7b5-4686-9c3d-ffb06c218237' for key 'PRIMARY'
2018-05-31 17:15:01 MySQL_Session.cpp:2863:handler(): [WARNING] Error during query on (10,114.23.9.180,3306): 1062, Duplicate entry '2bea087c-cfb3-4fa4-ba48-ffb08e0ff508' for key 'PRIMARY'
2018-05-31 17:15:01 MySQL_Session.cpp:2863:handler(): [WARNING] Error during query on (10,114.23.9.180,3306): 1062, Duplicate entry '6c18feac-a86e-47ef-93a6-ffb4d11808cd' for key 'PRIMARY'
2018-05-31 17:15:01 MySQL_Session.cpp:2863:handler(): [WARNING] Error during query on (10,114.23.9.180,3306): 1062, Duplicate entry '4ba5e1e5-cd2f-4f30-aa0e-ffc4f35f855a' for key 'PRIMARY'
2018-05-31 17:15:01 MySQL_Session.cpp:2863:handler(): [WARNING] Error during query on (10,114.23.9.180,3306): 1062, Duplicate entry 'ba47ac81-61de-4957-a51b-ffd63a1a61f2' for key 'PRIMARY'
2018-05-31 17:15:01 MySQL_Session.cpp:2863:handler(): [WARNING] Error during query on (10,114.23.9.180,3306): 1062, Duplicate entry '3973a1e4-b37a-4abe-8704-ffe0568bba82' for key 'PRIMARY'
2018-05-31 17:15:01 MySQL_Session.cpp:2863:handler(): [WARNING] Error during query on (10,114.23.9.180,3306): 1062, Duplicate entry '2bfb234f-6a71-4aaa-b18e-fffdcb95c724' for key 'PRIMARY'

To unsubscribe from this group and stop receiving emails from it, send an email to proxysql+u...@googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

Todd Bryant

unread,

May 31, 2018, 3:47:01 AM5/31/18

to proxysql

Ok the reason for those errors were because proxysql was already running, I forgot that after updating it adds a startup script to init.d whilst we are using systemd for proxysql and in my usual way I was using service ... start etc

We are back to the same behavior as 1.4.5 with an empty proxysql.log, I will wait and see if 1.4.8 fixes the error we were seeing.

I am still seeing a pile of issues with the galera_checker in its own logs so will deal with those first and see if that was causing something strange to happen.

Todd Bryant

unread,

May 31, 2018, 5:24:35 AM5/31/18

to proxysql

Hi Rene,

Thought I would quickly provide an update on the procysql_galera_checker issue as it may help others.

I modified the proxysql_galera_checker script to give me some more details in the logs the following showed up as I made it echo out the PID file path it was trying to create.

PID File2 /var/lib/proxysql/HG10 Every 5s

Legacy Rule To Be Removed_galera_checker.pid

[2018-05-31 20:56:42] Could not create galera checker PID file

The interesting part of this is that 'HG10 Every 5s' and 'Legacy Rule To Be Removed' are in the comment column of the scheduler.

So naturally I set the comment column to '' in the scheduler table and the errors immediately went away BUT this should not have worked as the runtime_scheduler table still has all the comments loaded in as I never loaded it to runtime.

So just to confirm I loaded from disk to memory again, and the error came back immediately, removed the comments from scheduler and we are good.

Ok back to the proxysql_galera_checker - https://github.com/percona/proxysql-admin-tool/blob/master/proxysql_galera_checker

Turns out on line 100, it has the below select which gets the comment column of all rows within the same HG Writer, hence receiving multiple lines and the comments passing through

CLUSTER_NAME=$(proxysql_exec "select comment from scheduler where arg1=$HOSTGROUP_WRITER_ID")

Not sure what the best process is to get the script corrected and its usage details updated as this will likely catch out others.

For now I have just modified my scheduler accordingly, although I will likely stop using the packaged version to prevent similar problems and better handle our multiple cluster config.