Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

fast_forward=1 breaks failover handling #2590

Closed
d-rupp opened this issue Mar 5, 2020 · 12 comments
Closed

fast_forward=1 breaks failover handling #2590

d-rupp opened this issue Mar 5, 2020 · 12 comments

Comments

@d-rupp
Copy link

d-rupp commented Mar 5, 2020

Issue: When using fast_forward=1 and switching the backend-master (setting the old to read only and making a new one writeable) existing connections still talk to the old master and hit a read-only error.

RHEL7.6 / Proxysql 2.x (tested 2.0.3 up to 2.0.10)

Reproduce:

  1. Master-Slave replication setup
  2. some form of topology management (for us: Orchestrator from github)
  3. proxysql with a read host group and a write host group
  4. some application that writes to the database (here: pt-heartbeat)
  5. user in proxysql configured with fast_forward=1
  6. perform a graceful takeover on Orchestrator
    -> Orchestrator sets old master to read_only, makes new master writeable
  7. pt-heartbeat throws errors about read only server until it is restarted

Expected behavior (this works in 1.x): application talks to new master.

Output & Logs:

Admin> select * from runtime_mysql_replication_hostgroups;
+------------------+------------------+------------+----------+
| writer_hostgroup | reader_hostgroup | check_type | comment  |
+------------------+------------------+------------+----------+
| 1                | 2                | read_only  | tst_test |
+------------------+------------------+------------+----------+
1 row in set (0.02 sec)
Admin> select * from runtime_mysql_servers;
+--------------+----------------------+-------+-----------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
| hostgroup_id | hostname             | port  | gtid_port | status | weight | compression | max_connections | max_replication_lag | use_ssl | max_latency_ms | comment  |
+--------------+----------------------+-------+-----------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
| 2            | db4.test             | 33572 | 0         | ONLINE | 1      | 0           | 1000            | 3                   | 0       | 0              | tst_test |
| 1            | db5.test             | 33572 | 0         | ONLINE | 1      | 0           | 1000            | 3                   | 0       | 0              | tst_test |
| 2            | db6.test             | 33572 | 0         | ONLINE | 1      | 0           | 1000            | 3                   | 0       | 0              | tst_test |
| 2            | db5.test             | 33572 | 0         | ONLINE | 1      | 0           | 1000            | 3                   | 0       | 0              | tst_test |
+--------------+----------------------+-------+-----------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
4 rows in set (0.04 sec)
Admin> select * from runtime_mysql_users;
+----------+----------+--------+---------+-------------------+----------------+---------------+------------------------+--------------+---------+----------+-----------------+---------+
| username | password | active | use_ssl | default_hostgroup | default_schema | schema_locked | transaction_persistent | fast_forward | backend | frontend | max_connections | comment |
+----------+----------+--------+---------+-------------------+----------------+---------------+------------------------+--------------+---------+----------+-----------------+---------+
| tst_test | *        | 1      | 0       | 1                 |                | 0             | 1                      | 1            | 0       | 1        | 240             |         |
| monitor  | *        | 1      | 0       | 1                 |                | 0             | 1                      | 0            | 0       | 1        | 10              |         |
| tst_test | *        | 1      | 0       | 1                 |                | 0             | 1                      | 1            | 1       | 0        | 240             |         |
| monitor  | *        | 1      | 0       | 1                 |                | 0             | 1                      | 0            | 1       | 0        | 10              |         |
+----------+----------+--------+---------+-------------------+----------------+---------------+------------------------+--------------+---------+----------+-----------------+---------+
4 rows in set (0.00 sec)
Admin> show processlist;
+-----------+----------+---------+-----------+--------------+---------+------+
| SessionID | user     | db      | hostgroup | command      | time_ms | info |
+-----------+----------+---------+-----------+--------------+---------+------+
| 694       | tst_test | percona | 1         | Fast forward | 10      | NULL |
+-----------+----------+---------+-----------+--------------+---------+------+
1 row in set (0.03 sec)

Everything running fine. Now we perform a graceful takeover with orchestrator.

pt-heartbeat output

Mar  5 10:21:16 test pt-heartbeat: The MySQL server is running with the --read-only option so it cannot execute this statement [for Statement "REPLACE INTO `percona`.`heartbeat` (ts, server_id, file, position, relay_master_log_file, exec_master_log_pos) VALUES (?, '5', ?, ?, ?, ?)" with ParamValues: 0='2020-03-05T10:21:16.011600', 1='mysql-bin.000014', 2='55302012', 3=undef, 4=undef]
Mar  5 10:21:17 test pt-heartbeat: The MySQL server is running with the --read-only option so it cannot execute this statement [for Statement "REPLACE INTO `percona`.`heartbeat` (ts, server_id, file, position, relay_master_log_file, exec_master_log_pos) VALUES (?, '5', ?, ?, ?, ?)" with ParamValues: 0='2020-03-05T10:21:17.058320', 1='mysql-bin.000014', 2='55302012', 3=undef, 4=undef]
Mar  5 10:21:18 test pt-heartbeat: The MySQL server is running with the --read-only option so it cannot execute this statement [for Statement "REPLACE INTO `percona`.`heartbeat` (ts, server_id, file, position, relay_master_log_file, exec_master_log_pos) VALUES (?, '5', ?, ?, ?, ?)" with ParamValues: 0='2020-03-05T10:21:18.043960', 1='mysql-bin.000014', 2='55302012', 3='', 4='0']
Mar  5 10:21:19 test pt-heartbeat: The MySQL server is running with the --read-only option so it cannot execute this statement [for Statement "REPLACE INTO `percona`.`heartbeat` (ts, server_id, file, position, relay_master_log_file, exec_master_log_pos) VALUES (?, '5', ?, ?, ?, ?)" with ParamValues: 0='2020-03-05T10:21:19.051550', 1='mysql-bin.000014', 2='55302012', 3='', 4='0']
Mar  5 10:21:20 test pt-heartbeat: The MySQL server is running with the --read-only option so it cannot execute this statement [for Statement "REPLACE INTO `percona`.`heartbeat` (ts, server_id, file, position, relay_master_log_file, exec_master_log_pos) VALUES (?, '5', ?, ?, ?, ?)" with ParamValues: 0='2020-03-05T10:21:20.027740', 1='mysql-bin.000014', 2='55302012', 3='mysql-bin.000019', 4='232978557']
Mar  5 10:21:21 test pt-heartbeat: The MySQL server is running with the --read-only option so it cannot execute this statement [for Statement "REPLACE INTO `percona`.`heartbeat` (ts, server_id, file, position, relay_master_log_file, exec_master_log_pos) VALUES (?, '5', ?, ?, ?, ?)" with ParamValues: 0='2020-03-05T10:21:21.009170', 1='mysql-bin.000014', 2='55302012', 3='mysql-bin.000019', 4='232978557']

and this continues endlessly.

proxysql shows

Admin> select * from runtime_mysql_servers;
+--------------+----------------------+-------+-----------+--------------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
| hostgroup_id | hostname             | port  | gtid_port | status       | weight | compression | max_connections | max_replication_lag | use_ssl | max_latency_ms | comment  |
+--------------+----------------------+-------+-----------+--------------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
| 2            | db4.test             | 33572 | 0         | ONLINE       | 1      | 0           | 1000            | 3                   | 0       | 0              | tst_test |
| 1            | db4.test             | 33572 | 0         | ONLINE       | 1      | 0           | 1000            | 3                   | 0       | 0              | tst_test |
| 1            | db5.test             | 33572 | 0         | OFFLINE_HARD | 1      | 0           | 1000            | 3                   | 0       | 0              | tst_test |
| 2            | db6.test             | 33572 | 0         | ONLINE       | 1      | 0           | 1000            | 3                   | 0       | 0              | tst_test |
| 2            | db5.test             | 33572 | 0         | ONLINE       | 1      | 0           | 1000            | 3                   | 0       | 0              | tst_test |
+--------------+----------------------+-------+-----------+--------------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
5 rows in set (0.00 sec)

proxysql logfile:

2020-03-05 10:21:16 [INFO] read_only_action RO=1 phase 1 : Dumping mysql_servers for db5.test            :33572
+--------------+----------------------+-------+-----------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
| hostgroup_id | hostname             | port  | gtid_port | status | weight | compression | max_connections | max_replication_lag | use_ssl | max_latency_ms | comment  |
+--------------+----------------------+-------+-----------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
| 1            | db5.test             | 33572 | 0         | ONLINE | 1      | 0           | 1000            | 3                   | 0       | 0              | tst_test |
| 2            | db5.test             | 33572 | 0         | ONLINE | 1      | 0           | 1000            | 3                   | 0       | 0              | tst_test |
+--------------+----------------------+-------+-----------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
2020-03-05 10:21:16 [INFO] Dumping current MySQL Servers structures for hostgroup ALL
HID: 2 , address: db4.test             , port: 33572 , gtid_port: 0 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
HID: 2 , address: db5.test             , port: 33572 , gtid_port: 0 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
HID: 2 , address: db6.test             , port: 33572 , gtid_port: 0 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
HID: 1 , address: db5.test             , port: 33572 , gtid_port: 0 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
2020-03-05 10:21:16 [INFO] Dumping mysql_servers: ALL
+-----+----------------------+-------+------+--------+--------+-----+-----------+---------+-----+---------+----------+-----------------+
| hid | hostname             | port  | gtid | weight | status | cmp | max_conns | max_lag | ssl | max_lat | comment  | mem_pointer     |
+-----+----------------------+-------+------+--------+--------+-----+-----------+---------+-----+---------+----------+-----------------+
| 2   | db4.test             | 33572 | 0    | 1      | 0      | 0   | 1000      | 3       | 0   | 0       | tst_test | 139627577060992 |
| 1   | db5.test             | 33572 | 0    | 1      | 0      | 0   | 1000      | 3       | 0   | 0       | tst_test | 139627615884320 |
| 2   | db6.test             | 33572 | 0    | 1      | 0      | 0   | 1000      | 3       | 0   | 0       | tst_test | 139627577061312 |
| 2   | db5.test             | 33572 | 0    | 1      | 0      | 0   | 1000      | 3       | 0   | 0       | tst_test | 139627577061152 |
+-----+----------------------+-------+------+--------+--------+-----+-----------+---------+-----+---------+----------+-----------------+
2020-03-05 10:21:16 [INFO] read_only_action RO=1 phase 2 : Dumping mysql_servers for db5.test            :33572
+--------------+----------------------+-------+-----------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
| hostgroup_id | hostname             | port  | gtid_port | status | weight | compression | max_connections | max_replication_lag | use_ssl | max_latency_ms | comment  |
+--------------+----------------------+-------+-----------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
| 1            | db5.test             | 33572 | 0         | ONLINE | 1      | 0           | 1000            | 3                   | 0       | 0              | tst_test |
| 2            | db5.test             | 33572 | 0         | ONLINE | 1      | 0           | 1000            | 3                   | 0       | 0              | tst_test |
+--------------+----------------------+-------+-----------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
2020-03-05 10:21:16 [INFO] read_only_action RO=1 phase 3 : Dumping mysql_servers for db5.test            :33572
+--------------+----------------------+-------+-----------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
| hostgroup_id | hostname             | port  | gtid_port | status | weight | compression | max_connections | max_replication_lag | use_ssl | max_latency_ms | comment  |
+--------------+----------------------+-------+-----------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
| 2            | db5.test             | 33572 | 0         | ONLINE | 1      | 0           | 1000            | 3                   | 0       | 0              | tst_test |
+--------------+----------------------+-------+-----------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
2020-03-05 10:21:16 [INFO] Dumping current MySQL Servers structures for hostgroup ALL
HID: 2 , address: db4.test             , port: 33572 , gtid_port: 0 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
HID: 2 , address: db5.test             , port: 33572 , gtid_port: 0 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
HID: 2 , address: db6.test             , port: 33572 , gtid_port: 0 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
HID: 1 , address: db5.test             , port: 33572 , gtid_port: 0 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
2020-03-05 10:21:16 [INFO] Dumping mysql_servers: ALL
+-----+----------------------+-------+------+--------+--------+-----+-----------+---------+-----+---------+----------+-----------------+
| hid | hostname             | port  | gtid | weight | status | cmp | max_conns | max_lag | ssl | max_lat | comment  | mem_pointer     |
+-----+----------------------+-------+------+--------+--------+-----+-----------+---------+-----+---------+----------+-----------------+
| 2   | db4.test             | 33572 | 0    | 1      | 0      | 0   | 1000      | 3       | 0   | 0       | tst_test | 139627577060992 |
| 1   | db5.test             | 33572 | 0    | 1      | 0      | 0   | 1000      | 3       | 0   | 0       | tst_test | 139627615884320 |
| 2   | db6.test             | 33572 | 0    | 1      | 0      | 0   | 1000      | 3       | 0   | 0       | tst_test | 139627577061312 |
| 2   | db5.test             | 33572 | 0    | 1      | 0      | 0   | 1000      | 3       | 0   | 0       | tst_test | 139627577061152 |
+-----+----------------------+-------+------+--------+--------+-----+-----------+---------+-----+---------+----------+-----------------+
2020-03-05 10:21:16 [INFO] Dumping mysql_servers_incoming
+--------------+----------------------+-------+-----------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
| hostgroup_id | hostname             | port  | gtid_port | weight | status | compression | max_connections | max_replication_lag | use_ssl | max_latency_ms | comment  |
+--------------+----------------------+-------+-----------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
| 2            | db4.test             | 33572 | 0         | 1      | 0      | 0           | 1000            | 3                   | 0       | 0              | tst_test |
| 2            | db6.test             | 33572 | 0         | 1      | 0      | 0           | 1000            | 3                   | 0       | 0              | tst_test |
| 2            | db5.test             | 33572 | 0         | 1      | 0      | 0           | 1000            | 3                   | 0       | 0              | tst_test |
+--------------+----------------------+-------+-----------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
2020-03-05 10:21:16 [INFO] Dumping mysql_servers LEFT JOIN mysql_servers_incoming
+-----------------+--------------+----------------------+-------+
| mem_pointer     | hostgroup_id | hostname             | port  |
+-----------------+--------------+----------------------+-------+
| 139627615884320 | 1            | db5.test             | 33572 |
+-----------------+--------------+----------------------+-------+
2020-03-05 10:21:16 MySQL_HostGroups_Manager.cpp:1250:commit(): [WARNING] Removed server at address 139627615884320, hostgroup 1, address db5.test             port 33572. Setting status OFFLINE HARD and immediately dropping all free connections. Used connections will be dropped when trying to use them
2020-03-05 10:21:16 [INFO] Dumping mysql_servers JOIN mysql_servers_incoming
+--------------+----------+------+-----------+--------+--------+-------------+-----------------+---------------------+---------+----------------+---------+-------------+-----------+--------+--------+-------------+-----------------+---------------------+---------+----------------+---------+
| hostgroup_id | hostname | port | gtid_port | weight | status | compression | max_connections | max_replication_lag | use_ssl | max_latency_ms | comment | mem_pointer | gtid_port | weight | status | compression | max_connections | max_replication_lag | use_ssl | max_latency_ms | comment |
+--------------+----------+------+-----------+--------+--------+-------------+-----------------+---------------------+---------+----------------+---------+-------------+-----------+--------+--------+-------------+-----------------+---------------------+---------+----------------+---------+
+--------------+----------+------+-----------+--------+--------+-------------+-----------------+---------------------+---------+----------------+---------+-------------+-----------+--------+--------+-------------+-----------------+---------------------+---------+----------------+---------+
2020-03-05 10:21:16 [INFO] New mysql_replication_hostgroups table
writer_hostgroup: 1 , reader_hostgroup: 2, check_type read_only, comment: tst_test
2020-03-05 10:21:16 [INFO] New mysql_group_replication_hostgroups table
2020-03-05 10:21:16 [INFO] New mysql_galera_hostgroups table
2020-03-05 10:21:16 [INFO] New mysql_aws_aurora_hostgroups table
2020-03-05 10:21:16 [INFO] Dumping current MySQL Servers structures for hostgroup ALL
HID: 2 , address: db4.test             , port: 33572 , gtid_port: 0 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
HID: 2 , address: db5.test             , port: 33572 , gtid_port: 0 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
HID: 2 , address: db6.test             , port: 33572 , gtid_port: 0 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
HID: 1 , address: db5.test             , port: 33572 , gtid_port: 0 , weight: 1 , status: OFFLINE_HARD , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
2020-03-05 10:21:16 [INFO] Dumping mysql_servers: ALL
+-----+----------------------+-------+------+--------+--------+-----+-----------+---------+-----+---------+----------+-----------------+
| hid | hostname             | port  | gtid | weight | status | cmp | max_conns | max_lag | ssl | max_lat | comment  | mem_pointer     |
+-----+----------------------+-------+------+--------+--------+-----+-----------+---------+-----+---------+----------+-----------------+
| 2   | db4.test             | 33572 | 0    | 1      | 0      | 0   | 1000      | 3       | 0   | 0       | tst_test | 139627577060992 |
| 1   | db5.test             | 33572 | 0    | 1      | 3      | 0   | 1000      | 3       | 0   | 0       | tst_test | 139627615884320 |
| 2   | db6.test             | 33572 | 0    | 1      | 0      | 0   | 1000      | 3       | 0   | 0       | tst_test | 139627577061312 |
| 2   | db5.test             | 33572 | 0    | 1      | 0      | 0   | 1000      | 3       | 0   | 0       | tst_test | 139627577061152 |
+-----+----------------------+-------+------+--------+--------+-----+-----------+---------+-----+---------+----------+-----------------+
2020-03-05 10:21:16 [INFO] MySQL_HostGroups_Manager::commit() locked for 32us
2020-03-05 10:21:18 [INFO] read_only_action RO=0 phase 1 : Dumping mysql_servers for db4.test            :33572
+--------------+----------------------+-------+-----------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
| hostgroup_id | hostname             | port  | gtid_port | status | weight | compression | max_connections | max_replication_lag | use_ssl | max_latency_ms | comment  |
+--------------+----------------------+-------+-----------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
| 2            | db4.test             | 33572 | 0         | ONLINE | 1      | 0           | 1000            | 3                   | 0       | 0              | tst_test |
+--------------+----------------------+-------+-----------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
2020-03-05 10:21:18 [INFO] Dumping current MySQL Servers structures for hostgroup ALL
HID: 2 , address: db4.test             , port: 33572 , gtid_port: 0 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
HID: 2 , address: db5.test             , port: 33572 , gtid_port: 0 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
HID: 2 , address: db6.test             , port: 33572 , gtid_port: 0 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
HID: 1 , address: db5.test             , port: 33572 , gtid_port: 0 , weight: 1 , status: OFFLINE_HARD , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
2020-03-05 10:21:18 [INFO] Dumping mysql_servers: ALL
+-----+----------------------+-------+------+--------+--------+-----+-----------+---------+-----+---------+----------+-----------------+
| hid | hostname             | port  | gtid | weight | status | cmp | max_conns | max_lag | ssl | max_lat | comment  | mem_pointer     |
+-----+----------------------+-------+------+--------+--------+-----+-----------+---------+-----+---------+----------+-----------------+
| 2   | db4.test             | 33572 | 0    | 1      | 0      | 0   | 1000      | 3       | 0   | 0       | tst_test | 139627577060992 |
| 1   | db5.test             | 33572 | 0    | 1      | 3      | 0   | 1000      | 3       | 0   | 0       | tst_test | 139627615884320 |
| 2   | db6.test             | 33572 | 0    | 1      | 0      | 0   | 1000      | 3       | 0   | 0       | tst_test | 139627577061312 |
| 2   | db5.test             | 33572 | 0    | 1      | 0      | 0   | 1000      | 3       | 0   | 0       | tst_test | 139627577061152 |
+-----+----------------------+-------+------+--------+--------+-----+-----------+---------+-----+---------+----------+-----------------+
2020-03-05 10:21:18 [INFO] read_only_action RO=0 phase 2 : Dumping mysql_servers for db4.test            :33572
+--------------+----------------------+-------+-----------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
| hostgroup_id | hostname             | port  | gtid_port | status | weight | compression | max_connections | max_replication_lag | use_ssl | max_latency_ms | comment  |
+--------------+----------------------+-------+-----------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
| 2            | db4.test             | 33572 | 0         | ONLINE | 1      | 0           | 1000            | 3                   | 0       | 0              | tst_test |
+--------------+----------------------+-------+-----------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
2020-03-05 10:21:18 [INFO] read_only_action RO=0 phase 3 : Dumping mysql_servers for db4.test            :33572
+--------------+----------------------+-------+-----------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
| hostgroup_id | hostname             | port  | gtid_port | status | weight | compression | max_connections | max_replication_lag | use_ssl | max_latency_ms | comment  |
+--------------+----------------------+-------+-----------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
| 1            | db4.test             | 33572 | 0         | ONLINE | 1      | 0           | 1000            | 3                   | 0       | 0              | tst_test |
| 2            | db4.test             | 33572 | 0         | ONLINE | 1      | 0           | 1000            | 3                   | 0       | 0              | tst_test |
+--------------+----------------------+-------+-----------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
2020-03-05 10:21:18 [INFO] Dumping current MySQL Servers structures for hostgroup ALL
HID: 2 , address: db4.test             , port: 33572 , gtid_port: 0 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
HID: 2 , address: db5.test             , port: 33572 , gtid_port: 0 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
HID: 2 , address: db6.test             , port: 33572 , gtid_port: 0 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
HID: 1 , address: db5.test             , port: 33572 , gtid_port: 0 , weight: 1 , status: OFFLINE_HARD , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
2020-03-05 10:21:18 [INFO] Dumping mysql_servers: ALL
+-----+----------------------+-------+------+--------+--------+-----+-----------+---------+-----+---------+----------+-----------------+
| hid | hostname             | port  | gtid | weight | status | cmp | max_conns | max_lag | ssl | max_lat | comment  | mem_pointer     |
+-----+----------------------+-------+------+--------+--------+-----+-----------+---------+-----+---------+----------+-----------------+
| 2   | db4.test             | 33572 | 0    | 1      | 0      | 0   | 1000      | 3       | 0   | 0       | tst_test | 139627577060992 |
| 1   | db5.test             | 33572 | 0    | 1      | 3      | 0   | 1000      | 3       | 0   | 0       | tst_test | 139627615884320 |
| 2   | db6.test             | 33572 | 0    | 1      | 0      | 0   | 1000      | 3       | 0   | 0       | tst_test | 139627577061312 |
| 2   | db5.test             | 33572 | 0    | 1      | 0      | 0   | 1000      | 3       | 0   | 0       | tst_test | 139627577061152 |
+-----+----------------------+-------+------+--------+--------+-----+-----------+---------+-----+---------+----------+-----------------+
2020-03-05 10:21:18 [INFO] Dumping mysql_servers_incoming
+--------------+----------------------+-------+-----------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
| hostgroup_id | hostname             | port  | gtid_port | weight | status | compression | max_connections | max_replication_lag | use_ssl | max_latency_ms | comment  |
+--------------+----------------------+-------+-----------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
| 1            | db4.test             | 33572 | 0         | 1      | 0      | 0           | 1000            | 3                   | 0       | 0              | tst_test |
| 1            | db5.test             | 33572 | 0         | 1      | 3      | 0           | 1000            | 3                   | 0       | 0              | tst_test |
| 2            | db6.test             | 33572 | 0         | 1      | 0      | 0           | 1000            | 3                   | 0       | 0              | tst_test |
| 2            | db5.test             | 33572 | 0         | 1      | 0      | 0           | 1000            | 3                   | 0       | 0              | tst_test |
| 2            | db4.test             | 33572 | 0         | 1      | 0      | 0           | 1000            | 3                   | 0       | 0              | tst_test |
+--------------+----------------------+-------+-----------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
2020-03-05 10:21:18 [INFO] Dumping mysql_servers LEFT JOIN mysql_servers_incoming
+-------------+--------------+----------+------+
| mem_pointer | hostgroup_id | hostname | port |
+-------------+--------------+----------+------+
+-------------+--------------+----------+------+
2020-03-05 10:21:18 [INFO] Dumping mysql_servers JOIN mysql_servers_incoming
+--------------+----------------------+-------+-----------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+-------------+-----------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
| hostgroup_id | hostname             | port  | gtid_port | weight | status | compression | max_connections | max_replication_lag | use_ssl | max_latency_ms | comment  | mem_pointer | gtid_port | weight | status | compression | max_connections | max_replication_lag | use_ssl | max_latency_ms | comment  |
+--------------+----------------------+-------+-----------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+-------------+-----------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
| 1            | db4.test             | 33572 | 0         | 1      | 0      | 0           | 1000            | 3                   | 0       | 0              | tst_test | 0           | 0         | 1      | 0      | 0           | 1000            | 3                   | 0       | 0              | tst_test |
+--------------+----------------------+-------+-----------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+-------------+-----------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
2020-03-05 10:21:18 [INFO] Creating new server in HG 1 : db4.test            :33572 , gtid_port=0, weight=1, status=0
2020-03-05 10:21:18 [INFO] New mysql_replication_hostgroups table
writer_hostgroup: 1 , reader_hostgroup: 2, check_type read_only, comment: tst_test
2020-03-05 10:21:18 [INFO] New mysql_group_replication_hostgroups table
2020-03-05 10:21:18 [INFO] New mysql_galera_hostgroups table
2020-03-05 10:21:18 [INFO] New mysql_aws_aurora_hostgroups table
2020-03-05 10:21:18 [INFO] Dumping current MySQL Servers structures for hostgroup ALL
HID: 2 , address: db4.test             , port: 33572 , gtid_port: 0 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
HID: 2 , address: db5.test             , port: 33572 , gtid_port: 0 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
HID: 2 , address: db6.test             , port: 33572 , gtid_port: 0 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
HID: 1 , address: db5.test             , port: 33572 , gtid_port: 0 , weight: 1 , status: OFFLINE_HARD , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
HID: 1 , address: db4.test             , port: 33572 , gtid_port: 0 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
2020-03-05 10:21:18 [INFO] Dumping mysql_servers: ALL
+-----+----------------------+-------+------+--------+--------+-----+-----------+---------+-----+---------+----------+-----------------+
| hid | hostname             | port  | gtid | weight | status | cmp | max_conns | max_lag | ssl | max_lat | comment  | mem_pointer     |
+-----+----------------------+-------+------+--------+--------+-----+-----------+---------+-----+---------+----------+-----------------+
| 2   | db4.test             | 33572 | 0    | 1      | 0      | 0   | 1000      | 3       | 0   | 0       | tst_test | 139627577060992 |
| 1   | db4.test             | 33572 | 0    | 1      | 0      | 0   | 1000      | 3       | 0   | 0       | tst_test | 139627582515008 |
| 1   | db5.test             | 33572 | 0    | 1      | 3      | 0   | 1000      | 3       | 0   | 0       | tst_test | 139627615884320 |
| 2   | db6.test             | 33572 | 0    | 1      | 0      | 0   | 1000      | 3       | 0   | 0       | tst_test | 139627577061312 |
| 2   | db5.test             | 33572 | 0    | 1      | 0      | 0   | 1000      | 3       | 0   | 0       | tst_test | 139627577061152 |
+-----+----------------------+-------+------+--------+--------+-----+-----------+---------+-----+---------+----------+-----------------+
2020-03-05 10:21:18 [INFO] MySQL_HostGroups_Manager::commit() locked for 11us
@d-rupp
Copy link
Author

d-rupp commented Mar 5, 2020

Forgot to add: After pt-heartbeat is cycled the OFFLINE_HARD server is removed from the hostgroup.

Also pt-heartbeat is just a simple example, our application behaves the same way.

@renecannao
Copy link
Contributor

This behavior is expected when using fast_forward=1 , no matter if 1.x or 2.x .
Are you sure 1.4 behaves differently?

@renecannao
Copy link
Contributor

To be clear, when fast_forward=1 , there is a 1-to-1 mapping between a frontend connection and a backend connection, traffic is not analyzed, routing doesn't work, and multiplexing doesn't work. By design

@d-rupp
Copy link
Author

d-rupp commented Mar 5, 2020

Yes, on 1.4 it switches the connection to the new master once it becomes available. I reproduced that yesterday to figure out why we started seeing read-only errors after the switch to 2.x last weekend.

Ok, then we have to figure out why we are getting that one error once we turn fast_forward off. The reason we turned it on was we were getting this:

org.hibernate.HibernateException: More than one row with the given identifier was found

Even though there was only one result row in the database. Development insists that this is a proxysql error because it only happens with the proxy but i have a different opinion...

Thank you for the quick comment and let me tell you that you are doing awesome work on this :)

@renecannao
Copy link
Contributor

Not 1.4 or 2.0 can switch existing connections in fast_forward from a server to another.

Although, what is possible is that you were experiencing something else in 1.4 , let me make some hypothesis...
You have some users using fast_forward=1 , and other users that do not.
Because the connections from users not using fast_forward=1 generate a lot of 1290 errors (read-only) proxysql will temporary shun the node, killing all the backend connections. Because all the backend connections are terminated, frontend connections using fast_forward=1 are terminated too, and the clients reconnect.
The behavior of handling error 1290 changed in 2.0.9 , and errors 1290 are send to the application.
So proxysql may not terminate all the backend connections, and thus frontend connections stay still active.
To highlight: proxysql cannot redirect connections, but if it kills them all, new client connections will connect to new backends.

Something relevant in the error log is this line:

2020-03-05 10:21:16 MySQL_HostGroups_Manager.cpp:1250:commit(): [WARNING] Removed server at address 139627615884320, hostgroup 1, address db5.test port 33572. Setting status OFFLINE HARD and immediately dropping all free connections. Used connections will be dropped when trying to use them

To highlight the important part:

immediately dropping all free connections. Used connections will be dropped when trying to use them

There is also the probability that "Used connections will be dropped when trying to use them" is handled differently in 1.4 and 2.0 .
Before we continue the investigation (I was already checking the code), can you please verify that 1.4 really behave differently?

====

About:

org.hibernate.HibernateException: More than one row with the given identifier was found

I am not sure what was causing this without much context, but I can make an educated guess and make the hypothesis that your application was relying on CLIENT_FOUND_ROWS being disabled (see mysql-affected-rows for more details), and in 1.4.x this flag is set to true by default, see mysql-client_found_rows.
From ProxySQL 2.0.0 till 2.0.5 the variable mysql-client_found_rows is still relevant, and you may need to configure it correctly based on your application need.
From ProxySQL 2.0.6 this variable becomes useless, because CLIENT_FOUND_ROWS is tracked (among other variables) and ProxySQL ensures that frontend and backend connections use the same flag.
I am making an hypothesis without much context, but I think it makes sense :)

@d-rupp
Copy link
Author

d-rupp commented Mar 5, 2020

Thanks for taking a look at this.

One thing against your hypothesis is that all this happens with only one process accessing proxysql - that is the pt-heartbeat process. Also that i was able to reproduce this with versions 2.0.3 up to 2.0.10.

About the hibernate thing - we started using proxysql 2 with 2.0.7 so i only after the behavior was changed and we still see the same thing. It´s pretty difficult to analyze this. I´ll try messing around with the query logging later to check if i can see something.

These are my results of reproducing with a 1.4.13 version. Complete removal and resetup, so no old proxysql data files were used. Everything else was the same.

pt-heartbeat log

Mar  5 12:11:37 test pt-heartbeat: The MySQL server is running with the --read-only option so it cannot execute this statement [for Statement "REPLACE INTO `percona`.`heartbeat` (ts, server_id, file, position, relay_master_log_file, exec_master_log_pos) VALUES (?, '4', ?, ?, ?, ?)" with ParamValues: 0='2020-03-05T12:11:37.003880', 1='mysql-bin.000019', 2='235400058', 3=undef, 4=undef]
Mar  5 12:11:38 test pt-heartbeat: The MySQL server is running with the --read-only option so it cannot execute this statement [for Statement "REPLACE INTO `percona`.`heartbeat` (ts, server_id, file, position, relay_master_log_file, exec_master_log_pos) VALUES (?, '4', ?, ?, ?, ?)" with ParamValues: 0='2020-03-05T12:11:38.003350', 1='mysql-bin.000019', 2='235400058', 3=undef, 4=undef]

after that nothing and pt-heartbeat is updating the heartbeat table on the new server.

Proxysql log

2020-03-05 12:11:37 [INFO] read_only_action RO=1 phase 1 : Dumping mysql_servers for db4.test            :33572
+--------------+----------------------+-------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
| hostgroup_id | hostname             | port  | status | weight | compression | max_connections | max_replication_lag | use_ssl | max_latency_ms | comment  |
+--------------+----------------------+-------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
| 1            | db4.test             | 33572 | ONLINE | 1      | 0           | 1000            | 3                   | 0       | 0              | tst_test |
| 2            | db4.test             | 33572 | ONLINE | 1      | 0           | 1000            | 3                   | 0       | 0              | tst_test |
+--------------+----------------------+-------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
2020-03-05 12:11:37 [INFO] Dumping current MySQL Servers structures for hostgroup ALL
HID: 2 , address: db4.test             , port: 33572 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
HID: 2 , address: db5.test             , port: 33572 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
HID: 2 , address: db6.test             , port: 33572 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
HID: 1 , address: db4.test             , port: 33572 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
2020-03-05 12:11:37 [INFO] Dumping mysql_servers
+--------------+----------------------+-------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+-----------------+
| hostgroup_id | hostname             | port  | weight | status | compression | max_connections | max_replication_lag | use_ssl | max_latency_ms | comment  | mem_pointer     |
+--------------+----------------------+-------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+-----------------+
| 2            | db4.test             | 33572 | 1      | 0      | 0           | 1000            | 3                   | 0       | 0              | tst_test | 140340757699328 |
| 1            | db4.test             | 33572 | 1      | 0      | 0           | 1000            | 3                   | 0       | 0              | tst_test | 140340733333632 |
| 2            | db6.test             | 33572 | 1      | 0      | 0           | 1000            | 3                   | 0       | 0              | tst_test | 140340757699584 |
| 2            | db5.test             | 33572 | 1      | 0      | 0           | 1000            | 3                   | 0       | 0              | tst_test | 140340757699456 |
+--------------+----------------------+-------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+-----------------+
2020-03-05 12:11:37 [INFO] read_only_action RO=1 phase 2 : Dumping mysql_servers for db4.test            :33572
+--------------+----------------------+-------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
| hostgroup_id | hostname             | port  | status | weight | compression | max_connections | max_replication_lag | use_ssl | max_latency_ms | comment  |
+--------------+----------------------+-------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
| 2            | db4.test             | 33572 | ONLINE | 1      | 0           | 1000            | 3                   | 0       | 0              | tst_test |
| 1            | db4.test             | 33572 | ONLINE | 1      | 0           | 1000            | 3                   | 0       | 0              | tst_test |
+--------------+----------------------+-------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
2020-03-05 12:11:37 [INFO] read_only_action RO=1 phase 3 : Dumping mysql_servers for db4.test            :33572
+--------------+----------------------+-------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
| hostgroup_id | hostname             | port  | status | weight | compression | max_connections | max_replication_lag | use_ssl | max_latency_ms | comment  |
+--------------+----------------------+-------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
| 2            | db4.test             | 33572 | ONLINE | 1      | 0           | 1000            | 3                   | 0       | 0              | tst_test |
+--------------+----------------------+-------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
2020-03-05 12:11:37 [INFO] Dumping current MySQL Servers structures for hostgroup ALL
HID: 2 , address: db4.test             , port: 33572 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
HID: 2 , address: db5.test             , port: 33572 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
HID: 2 , address: db6.test             , port: 33572 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
HID: 1 , address: db4.test             , port: 33572 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
2020-03-05 12:11:37 [INFO] Dumping mysql_servers
+--------------+----------------------+-------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+-----------------+
| hostgroup_id | hostname             | port  | weight | status | compression | max_connections | max_replication_lag | use_ssl | max_latency_ms | comment  | mem_pointer     |
+--------------+----------------------+-------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+-----------------+
| 2            | db4.test             | 33572 | 1      | 0      | 0           | 1000            | 3                   | 0       | 0              | tst_test | 140340757699328 |
| 1            | db4.test             | 33572 | 1      | 0      | 0           | 1000            | 3                   | 0       | 0              | tst_test | 140340733333632 |
| 2            | db6.test             | 33572 | 1      | 0      | 0           | 1000            | 3                   | 0       | 0              | tst_test | 140340757699584 |
| 2            | db5.test             | 33572 | 1      | 0      | 0           | 1000            | 3                   | 0       | 0              | tst_test | 140340757699456 |
+--------------+----------------------+-------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+-----------------+
2020-03-05 12:11:37 [INFO] Dumping mysql_servers_incoming
+--------------+----------------------+-------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
| hostgroup_id | hostname             | port  | weight | status | compression | max_connections | max_replication_lag | use_ssl | max_latency_ms | comment  |
+--------------+----------------------+-------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
| 2            | db4.test             | 33572 | 1      | 0      | 0           | 1000            | 3                   | 0       | 0              | tst_test |
| 2            | db6.test             | 33572 | 1      | 0      | 0           | 1000            | 3                   | 0       | 0              | tst_test |
| 2            | db5.test             | 33572 | 1      | 0      | 0           | 1000            | 3                   | 0       | 0              | tst_test |
+--------------+----------------------+-------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
2020-03-05 12:11:37 MySQL_HostGroups_Manager.cpp:602:commit(): [WARNING] Removed server at address 140340733333632, hostgroup 1, address db4.test             port 33572. Setting status OFFLINE HARD and immediately dropping all free connections. Used connections will be dropped when trying to use them
2020-03-05 12:11:37 [INFO] New mysql_replication_hostgroups table
writer_hostgroup: 1 , reader_hostgroup: 2, tst_test
2020-03-05 12:11:37 [INFO] New mysql_group_replication_hostgroups table
2020-03-05 12:11:37 [INFO] Dumping current MySQL Servers structures for hostgroup ALL
HID: 2 , address: db4.test             , port: 33572 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
HID: 2 , address: db5.test             , port: 33572 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
HID: 2 , address: db6.test             , port: 33572 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
HID: 1 , address: db4.test             , port: 33572 , weight: 1 , status: OFFLINE_HARD , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
2020-03-05 12:11:37 [INFO] Dumping mysql_servers
+--------------+----------------------+-------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+-----------------+
| hostgroup_id | hostname             | port  | weight | status | compression | max_connections | max_replication_lag | use_ssl | max_latency_ms | comment  | mem_pointer     |
+--------------+----------------------+-------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+-----------------+
| 2            | db4.test             | 33572 | 1      | 0      | 0           | 1000            | 3                   | 0       | 0              | tst_test | 140340757699328 |
| 1            | db4.test             | 33572 | 1      | 3      | 0           | 1000            | 3                   | 0       | 0              | tst_test | 140340733333632 |
| 2            | db6.test             | 33572 | 1      | 0      | 0           | 1000            | 3                   | 0       | 0              | tst_test | 140340757699584 |
| 2            | db5.test             | 33572 | 1      | 0      | 0           | 1000            | 3                   | 0       | 0              | tst_test | 140340757699456 |
+--------------+----------------------+-------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+-----------------+
2020-03-05 12:11:40 [INFO] read_only_action RO=0 phase 1 : Dumping mysql_servers for db5.test            :33572
+--------------+----------------------+-------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
| hostgroup_id | hostname             | port  | status | weight | compression | max_connections | max_replication_lag | use_ssl | max_latency_ms | comment  |
+--------------+----------------------+-------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
| 2            | db5.test             | 33572 | ONLINE | 1      | 0           | 1000            | 3                   | 0       | 0              | tst_test |
+--------------+----------------------+-------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
2020-03-05 12:11:40 [INFO] Dumping current MySQL Servers structures for hostgroup ALL
HID: 2 , address: db4.test             , port: 33572 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
HID: 2 , address: db5.test             , port: 33572 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
HID: 2 , address: db6.test             , port: 33572 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
2020-03-05 12:11:40 [INFO] Dumping mysql_servers
+--------------+----------------------+-------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+-----------------+
| hostgroup_id | hostname             | port  | weight | status | compression | max_connections | max_replication_lag | use_ssl | max_latency_ms | comment  | mem_pointer     |
+--------------+----------------------+-------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+-----------------+
| 2            | db4.test             | 33572 | 1      | 0      | 0           | 1000            | 3                   | 0       | 0              | tst_test | 140340757699328 |
| 2            | db6.test             | 33572 | 1      | 0      | 0           | 1000            | 3                   | 0       | 0              | tst_test | 140340757699584 |
| 2            | db5.test             | 33572 | 1      | 0      | 0           | 1000            | 3                   | 0       | 0              | tst_test | 140340757699456 |
+--------------+----------------------+-------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+-----------------+
2020-03-05 12:11:40 [INFO] read_only_action RO=0 phase 2 : Dumping mysql_servers for db5.test            :33572
+--------------+----------------------+-------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
| hostgroup_id | hostname             | port  | status | weight | compression | max_connections | max_replication_lag | use_ssl | max_latency_ms | comment  |
+--------------+----------------------+-------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
| 2            | db5.test             | 33572 | ONLINE | 1      | 0           | 1000            | 3                   | 0       | 0              | tst_test |
+--------------+----------------------+-------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
2020-03-05 12:11:40 [INFO] read_only_action RO=0 phase 3 : Dumping mysql_servers for db5.test            :33572
+--------------+----------------------+-------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
| hostgroup_id | hostname             | port  | status | weight | compression | max_connections | max_replication_lag | use_ssl | max_latency_ms | comment  |
+--------------+----------------------+-------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
| 1            | db5.test             | 33572 | ONLINE | 1      | 0           | 1000            | 3                   | 0       | 0              | tst_test |
| 2            | db5.test             | 33572 | ONLINE | 1      | 0           | 1000            | 3                   | 0       | 0              | tst_test |
+--------------+----------------------+-------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
2020-03-05 12:11:40 [INFO] Dumping current MySQL Servers structures for hostgroup ALL
HID: 2 , address: db4.test             , port: 33572 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
HID: 2 , address: db5.test             , port: 33572 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
HID: 2 , address: db6.test             , port: 33572 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
2020-03-05 12:11:40 [INFO] Dumping mysql_servers
+--------------+----------------------+-------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+-----------------+
| hostgroup_id | hostname             | port  | weight | status | compression | max_connections | max_replication_lag | use_ssl | max_latency_ms | comment  | mem_pointer     |
+--------------+----------------------+-------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+-----------------+
| 2            | db4.test             | 33572 | 1      | 0      | 0           | 1000            | 3                   | 0       | 0              | tst_test | 140340757699328 |
| 2            | db6.test             | 33572 | 1      | 0      | 0           | 1000            | 3                   | 0       | 0              | tst_test | 140340757699584 |
| 2            | db5.test             | 33572 | 1      | 0      | 0           | 1000            | 3                   | 0       | 0              | tst_test | 140340757699456 |
+--------------+----------------------+-------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+-----------------+
2020-03-05 12:11:40 [INFO] Dumping mysql_servers_incoming
+--------------+----------------------+-------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
| hostgroup_id | hostname             | port  | weight | status | compression | max_connections | max_replication_lag | use_ssl | max_latency_ms | comment  |
+--------------+----------------------+-------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
| 2            | db4.test             | 33572 | 1      | 0      | 0           | 1000            | 3                   | 0       | 0              | tst_test |
| 2            | db6.test             | 33572 | 1      | 0      | 0           | 1000            | 3                   | 0       | 0              | tst_test |
| 1            | db5.test             | 33572 | 1      | 0      | 0           | 1000            | 3                   | 0       | 0              | tst_test |
| 2            | db5.test             | 33572 | 1      | 0      | 0           | 1000            | 3                   | 0       | 0              | tst_test |
+--------------+----------------------+-------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+
2020-03-05 12:11:40 [INFO] New mysql_replication_hostgroups table
writer_hostgroup: 1 , reader_hostgroup: 2, tst_test
2020-03-05 12:11:40 [INFO] New mysql_group_replication_hostgroups table
2020-03-05 12:11:40 [INFO] Dumping current MySQL Servers structures for hostgroup ALL
HID: 2 , address: db4.test             , port: 33572 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
HID: 2 , address: db5.test             , port: 33572 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
HID: 2 , address: db6.test             , port: 33572 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
HID: 1 , address: db5.test             , port: 33572 , weight: 1 , status: ONLINE , max_connections: 1000 , max_replication_lag: 3 , use_ssl: 0 , max_latency_ms: 0 , comment: tst_test
2020-03-05 12:11:40 [INFO] Dumping mysql_servers
+--------------+----------------------+-------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+-----------------+
| hostgroup_id | hostname             | port  | weight | status | compression | max_connections | max_replication_lag | use_ssl | max_latency_ms | comment  | mem_pointer     |
+--------------+----------------------+-------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+-----------------+
| 2            | db4.test             | 33572 | 1      | 0      | 0           | 1000            | 3                   | 0       | 0              | tst_test | 140340757699328 |
| 1            | db5.test             | 33572 | 1      | 0      | 0           | 1000            | 3                   | 0       | 0              | tst_test | 140340709380096 |
| 2            | db6.test             | 33572 | 1      | 0      | 0           | 1000            | 3                   | 0       | 0              | tst_test | 140340757699584 |
| 2            | db5.test             | 33572 | 1      | 0      | 0           | 1000            | 3                   | 0       | 0              | tst_test | 140340757699456 |
+--------------+----------------------+-------+--------+--------+-------------+-----------------+---------------------+---------+----------------+----------+-----------------+

If you require anything else i´m very happy to help.

@renecannao
Copy link
Contributor

Thank you for the output.
Yet it is not clear if pt-heartbeat reconnects, or if it is using the same connection (it shouldn't!!) .

@Val214 : can you please reproduce it? No need for pt-heartbeat, a simple mysql client connection would work.

@d-rupp
Copy link
Author

d-rupp commented Mar 5, 2020

Running pt-heartbeat with debug log indicates that the connection is reset on the 1.4 version.

Debug Output of 1.4

 Retry:3903 8658 Try 1 of 3
# pt_heartbeat:6175 8658 REPLACE INTO `percona`.`heartbeat` (ts, server_id, file, position, relay_master_log_file, exec_master_log_pos) VALUES (?, '5', ?, ?, ?, ?)
# Retry:3920 8658 Try code succeeded
# pt_heartbeat:6346 8658 Woke up at 2020-03-05T12:39:20.000320
# pt_heartbeat:6145 8658 DBI::db=HASH(0x31e63f8) SHOW MASTER STATUS
# pt_heartbeat:6158 8658 DBI::db=HASH(0x31e63f8) SHOW SLAVE STATUS
# pt_heartbeat:6161 8658 No row from SHOW SLAVE STATUS
# Retry:3903 8658 Try 1 of 3
# pt_heartbeat:6175 8658 REPLACE INTO `percona`.`heartbeat` (ts, server_id, file, position, relay_master_log_file, exec_master_log_pos) VALUES (?, '5', ?, ?, ?, ?)
# Retry:3920 8658 Try code succeeded
# pt_heartbeat:6346 8658 Woke up at 2020-03-05T12:39:21.004670
# pt_heartbeat:6145 8658 DBI::db=HASH(0x31e63f8) SHOW MASTER STATUS
# pt_heartbeat:6158 8658 DBI::db=HASH(0x31e63f8) SHOW SLAVE STATUS
# pt_heartbeat:6161 8658 No row from SHOW SLAVE STATUS
# Retry:3903 8658 Try 1 of 3
# Retry:3909 8658 Try code failed: DBD::mysql::st execute failed: The MySQL server is running with the --read-only option so it cannot execute this statement [for Statement "REPLACE INTO `percona`.`heartbeat` (ts, server_id, file, position, relay_master_log_file, exec_master_log_pos) VALUES (?, '5', ?, ?, ?, ?)" with ParamValues: 0='2020-03-05T12:39:21.012770', 1='mysql-bin.000014', 2='58252271', 3=undef, 4=undef] at /usr/bin/pt-heartbeat line 6174.
#
# Retry:3925 8658 Try code did not succeed
The MySQL server is running with the --read-only option so it cannot execute this statement [for Statement "REPLACE INTO `percona`.`heartbeat` (ts, server_id, file, position, relay_master_log_file, exec_master_log_pos) VALUES (?, '5', ?, ?, ?, ?)" with ParamValues: 0='2020-03-05T12:39:21.012770', 1='mysql-bin.000014', 2='58252271', 3=undef, 4=undef]
# pt_heartbeat:6346 8658 Woke up at 2020-03-05T12:39:22.000190
# DSNParser:2837 8658 DBI:mysql:percona;host=127.0.0.1;mysql_read_default_group=client
# DSNParser:2886 8658 DBI:mysql:percona;host=127.0.0.1;mysql_read_default_group=client   tst_test  sdfgh mysql_enable_utf8=>0, ShowErrorStatement=>1, AutoCommit=>1, RaiseError=>1, PrintError=>0
# DSNParser:3045 8658 DBI::db=HASH(0x3273ae8) SET SESSION wait_timeout=10000
# DSNParser:2935 8658 DBI::db=HASH(0x3273ae8) SELECT @@SQL_MODE
# DSNParser:2945 8658 DBI::db=HASH(0x3273ae8) SET @@SQL_QUOTE_SHOW_CREATE = 1/*!40101, @@SQL_MODE='NO_AUTO_VALUE_ON_ZERO,ONLY_FULL_GROUP_BY,STRICT_TRANS_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION'*/
# DSNParser:2954 8658 DBH info:  DBI::db=HASH(0x3273ae8) $VAR1 = {
#   '@@hostname' => 'db4.test.mb.riege.it',
#   'CONNECTION_ID()' => '167640',
#   'DATABASE()' => 'percona',
#   'VERSION()' => '5.7.26-29-log'
# };
#  Connection info: 127.0.0.1 via TCP/IP Character set info: $VAR1 = [
#   {
#     Value => 'utf8mb4',
#     Variable_name => 'character_set_client'
#   },
#   {
#     Value => 'utf8mb4',
#     Variable_name => 'character_set_connection'
#   },
#   {
#     Value => 'utf8mb4',
#     Variable_name => 'character_set_database'
#   },
#   {
#     Value => 'binary',
#     Variable_name => 'character_set_filesystem'
#   },
#   {
#     Value => 'utf8mb4',
#     Variable_name => 'character_set_results'
#   },
#   {
#     Value => 'utf8mb4',
#     Variable_name => 'character_set_server'
#   },
#   {
#     Value => 'utf8',
#     Variable_name => 'character_set_system'
#   },
#   {
#     Value => '/usr/share/percona-server/charsets/',
#     Variable_name => 'character_sets_dir'
#   }
# ];
#  $DBD::mysql::VERSION: 4.023 $DBI::VERSION: 1.627
# pt_heartbeat:6145 8658 DBI::db=HASH(0x3273ae8) SHOW MASTER STATUS
# pt_heartbeat:6158 8658 DBI::db=HASH(0x3273ae8) SHOW SLAVE STATUS
# pt_heartbeat:6161 8658 No row from SHOW SLAVE STATUS
# Retry:3903 8658 Try 1 of 3
# pt_heartbeat:6175 8658 REPLACE INTO `percona`.`heartbeat` (ts, server_id, file, position, relay_master_log_file, exec_master_log_pos) VALUES (?, '5', ?, ?, ?, ?)
# Retry:3920 8658 Try code succeeded
# pt_heartbeat:6342 8658 Missed last interval; next interval: 2020-03-05T12:39:24
# pt_heartbeat:6346 8658 Woke up at 2020-03-05T12:39:24.000630
# pt_heartbeat:6145 8658 DBI::db=HASH(0x3273ae8) SHOW MASTER STATUS
# pt_heartbeat:6158 8658 DBI::db=HASH(0x3273ae8) SHOW SLAVE STATUS
# pt_heartbeat:6161 8658 No row from SHOW SLAVE STATUS
# Retry:3903 8658 Try 1 of 3
# pt_heartbeat:6175 8658 REPLACE INTO `percona`.`heartbeat` (ts, server_id, file, position, relay_master_log_file, exec_master_log_pos) VALUES (?, '5', ?, ?, ?, ?)
# Retry:3920 8658 Try code succeeded

Debug output of 2.0.7

# Retry:3903 31117 Try 1 of 3
# pt_heartbeat:6175 31117 REPLACE INTO `percona`.`heartbeat` (ts, server_id, file, position, relay_master_log_file, exec_master_log_pos) VALUES (?, '4', ?, ?, ?, ?)
# Retry:3920 31117 Try code succeeded
# pt_heartbeat:6346 31117 Woke up at 2020-03-05T12:53:14.000240
# pt_heartbeat:6145 31117 DBI::db=HASH(0x1afb348) SHOW MASTER STATUS
# pt_heartbeat:6158 31117 DBI::db=HASH(0x1afb348) SHOW SLAVE STATUS
# pt_heartbeat:6161 31117 No row from SHOW SLAVE STATUS
# Retry:3903 31117 Try 1 of 3
# Retry:3909 31117 Try code failed: DBD::mysql::st execute failed: The MySQL server is running with the --read-only option so it cannot execute this statement [for Statement "REPLACE INTO `percona`.`heartbeat` (ts, server_id, file, position, relay_master_log_file, exec_master_log_pos) VALUES (?, '4', ?, ?, ?, ?)" with ParamValues: 0='2020-03-05T12:53:14.009260', 1='mysql-bin.000019', 2='236004933', 3=undef, 4=undef] at /usr/bin/pt-heartbeat line 6174.
#
# Retry:3925 31117 Try code did not succeed
The MySQL server is running with the --read-only option so it cannot execute this statement [for Statement "REPLACE INTO `percona`.`heartbeat` (ts, server_id, file, position, relay_master_log_file, exec_master_log_pos) VALUES (?, '4', ?, ?, ?, ?)" with ParamValues: 0='2020-03-05T12:53:14.009260', 1='mysql-bin.000019', 2='236004933', 3=undef, 4=undef]
# pt_heartbeat:6346 31117 Woke up at 2020-03-05T12:53:15.006160
# pt_heartbeat:6145 31117 DBI::db=HASH(0x1afb348) SHOW MASTER STATUS
# pt_heartbeat:6158 31117 DBI::db=HASH(0x1afb348) SHOW SLAVE STATUS
# pt_heartbeat:6161 31117 No row from SHOW SLAVE STATUS
# Retry:3903 31117 Try 1 of 3
# Retry:3909 31117 Try code failed: DBD::mysql::st execute failed: The MySQL server is running with the --read-only option so it cannot execute this statement [for Statement "REPLACE INTO `percona`.`heartbeat` (ts, server_id, file, position, relay_master_log_file, exec_master_log_pos) VALUES (?, '4', ?, ?, ?, ?)" with ParamValues: 0='2020-03-05T12:53:15.015930', 1='mysql-bin.000019', 2='236004933', 3=undef, 4=undef] at /usr/bin/pt-heartbeat line 6174.
#
# Retry:3925 31117 Try code did not succeed
The MySQL server is running with the --read-only option so it cannot execute this statement [for Statement "REPLACE INTO `percona`.`heartbeat` (ts, server_id, file, position, relay_master_log_file, exec_master_log_pos) VALUES (?, '4', ?, ?, ?, ?)" with ParamValues: 0='2020-03-05T12:53:15.015930', 1='mysql-bin.000019', 2='236004933', 3=undef, 4=undef]
# pt_heartbeat:6346 31117 Woke up at 2020-03-05T12:53:16.004670
# pt_heartbeat:6145 31117 DBI::db=HASH(0x1afb348) SHOW MASTER STATUS
# pt_heartbeat:6158 31117 DBI::db=HASH(0x1afb348) SHOW SLAVE STATUS
# Retry:3903 31117 Try 1 of 3
# Retry:3909 31117 Try code failed: DBD::mysql::st execute failed: The MySQL server is running with the --read-only option so it cannot execute this statement [for Statement "REPLACE INTO `percona`.`heartbeat` (ts, server_id, file, position, relay_master_log_file, exec_master_log_pos) VALUES (?, '4', ?, ?, ?, ?)" with ParamValues: 0='2020-03-05T12:53:16.011320', 1='mysql-bin.000019', 2='236004933', 3='', 4='0'] at /usr/bin/pt-heartbeat line 6174.
#
# Retry:3925 31117 Try code did not succeed
The MySQL server is running with the --read-only option so it cannot execute this statement [for Statement "REPLACE INTO `percona`.`heartbeat` (ts, server_id, file, position, relay_master_log_file, exec_master_log_pos) VALUES (?, '4', ?, ?, ?, ?)" with ParamValues: 0='2020-03-05T12:53:16.011320', 1='mysql-bin.000019', 2='236004933', 3='', 4='0']

@renecannao
Copy link
Contributor

Thank you again for the output!
So this seems to match my second hypothesis:

There is also the probability that "Used connections will be dropped when trying to use them" is handled differently in 1.4 and 2.0 .

@d-rupp
Copy link
Author

d-rupp commented Mar 6, 2020

I don´t know if you want to follow this up somehow or if we should close it. As i understood it´s actually "working as intended".

@alpes214
Copy link
Contributor

@d-rupp , @renecannao

Versions 2.0.11 and 1.4.16 behave differently when master switch with fast_forward=1.

In case of 1.4.16 mysql client disconnects from proxysql and try to re-connect. In case of proxysql v2.0.11 client does not try to reconnect.

Please have a look over detailed info here https://gist.github.com/val214/84ba9cda6ef83e6e39ae4e3fe1979727

@alpes214 alpes214 mentioned this issue Mar 12, 2020
Merged
@renecannao
Copy link
Contributor

Closing this as we are soon releasing 2.0.11 .
Thank you for the report.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@renecannao @d-rupp @alpes214