GTID holes created on cluster peers of async slave node
Affects | Status | Importance | Assigned to | Milestone | ||
---|---|---|---|---|---|---|
Percona XtraDB Cluster moved to https://jira.percona.com/projects/PXC | Status tracked in 5.6 | |||||
5.6 |
Fix Released
|
Undecided
|
Krunal Bauskar |
Bug Description
In a replication topology like this:
async master -> node1<->nodeN...
when node1 slave ignores some row updates, for example due to slave_skip_
-- async master:
db1 {root} (test) > create table test.g1 (id int auto_increment primary key);
Query OK, 0 rows affected (0.06 sec)
db1 {root} (test) > insert into test.g1 values (null),
Query OK, 3 rows affected (0.03 sec)
Records: 3 Duplicates: 0 Warnings: 0
db1 {root} (test) > select * from test.g1;
+----+
| id |
+----+
| 1 |
| 2 |
| 3 |
+----+
3 rows in set (0.00 sec)
-- async slave node:
percona1 mysql> select * from test.g1;
+----+
| id |
+----+
| 1 |
| 2 |
| 3 |
+----+
3 rows in set (0.00 sec)
percona1 mysql> delete from test.g1 where id=2;
Query OK, 1 row affected (0.12 sec)
percona1 mysql> flush logs;
Query OK, 0 rows affected (0.07 sec)
-- async master:
db1 {root} (test) > flush logs;
Query OK, 0 rows affected (0.07 sec)
db1 {root} (test) > delete from test.g1 where id=2;
Query OK, 1 row affected (0.02 sec)
db1 {root} (test) > delete from test.g1 where id=3;
Query OK, 1 row affected (0.00 sec)
db1 {root} (test) > show binlog events in 'binlog.000014';
+------
| Log_name | Pos | Event_type | Server_id | End_log_pos | Info |
+------
| binlog.000014 | 4 | Format_desc | 1 | 120 | Server ver: 5.6.24-72.2-log, Binlog ver: 4 |
| binlog.000014 | 120 | Previous_gtids | 1 | 191 | 12446bf7-
| binlog.000014 | 191 | Gtid | 1 | 239 | SET @@SESSION.
| binlog.000014 | 239 | Query | 1 | 311 | BEGIN |
| binlog.000014 | 311 | Table_map | 1 | 356 | table_id: 90 (test.g1) |
| binlog.000014 | 356 | Delete_rows | 1 | 396 | table_id: 90 flags: STMT_END_F |
| binlog.000014 | 396 | Xid | 1 | 427 | COMMIT /* xid=1114262 */ |
| binlog.000014 | 427 | Gtid | 1 | 475 | SET @@SESSION.
| binlog.000014 | 475 | Query | 1 | 547 | BEGIN |
| binlog.000014 | 547 | Table_map | 1 | 592 | table_id: 90 (test.g1) |
| binlog.000014 | 592 | Delete_rows | 1 | 632 | table_id: 90 flags: STMT_END_F |
| binlog.000014 | 632 | Xid | 1 | 663 | COMMIT /* xid=1114265 */ |
+------
12 rows in set (0.00 sec)
db1 {root} (test) > show global variables like 'gtid_executed';
+------
| Variable_name | Value |
+------
| gtid_executed | 12446bf7-
+------
1 row in set (0.00 sec)
-- async slave node:
percona1 mysql> show binlog events in 'binlog.000004';
+------
| Log_name | Pos | Event_type | Server_id | End_log_pos | Info |
+------
| binlog.000004 | 4 | Format_desc | 3 | 120 | Server ver: 5.6.26-74.0-56-log, Binlog ver: 4 |
| binlog.000004 | 120 | Previous_gtids | 3 | 231 | 052077a5-
12446bf7-
| binlog.000004 | 231 | Gtid | 1 | 279 | SET @@SESSION.
| binlog.000004 | 279 | Query | 1 | 347 | BEGIN |
| binlog.000004 | 347 | Query | 1 | 416 | COMMIT |
| binlog.000004 | 416 | Gtid | 1 | 464 | SET @@SESSION.
| binlog.000004 | 464 | Query | 1 | 532 | BEGIN |
| binlog.000004 | 532 | Table_map | 1 | 577 | table_id: 86 (test.g1) |
| binlog.000004 | 577 | Delete_rows | 1 | 617 | table_id: 86 flags: STMT_END_F |
| binlog.000004 | 617 | Xid | 1 | 648 | COMMIT /* xid=1441296 */ |
+------
10 rows in set (0.00 sec)
percona1 mysql> show global variables like 'gtid%';
+------
| Variable_name | Value |
+------
| gtid_deployment
| gtid_executed | 052077a5-
12446bf7-
| gtid_mode | ON |
| gtid_owned | |
| gtid_purged | 052077a5-
12446bf7-
+------
5 rows in set (0.00 sec)
-- Galera peer node:
percona2 mysql> show global variables like 'gtid%';
+------
| Variable_name | Value |
+------
| gtid_deployment
| gtid_executed | 052077a5-
12446bf7-
| gtid_mode | ON |
| gtid_owned | |
| gtid_purged | 052077a5-
12446bf7-
+------
5 rows in set (0.01 sec)
So the 963127 trx is missing on the cluster peers, making the GTID numeration inconsistent within the cluster.
tags: | added: i62896 |
Scenario-1: updates= true gtid-consistenc y=true updates= true gtid-consistenc y=true 9fdc-11e5- 9ff6-340286b888 be:1-5 9fdc-11e5- 9ff6-340286b888 be:4-5 6023-ee1a- 7a64-f545ef74c7 ac:1, 9fdc-11e5- 9ff6-340286b888 be:4-5 9fdc-11e5- 9ff6-340286b888 be:1-6 ------- ------- ------- ------- ------- ------- ------- ------- ------- ------- ------- ------- ------- ------- ------- ------- ----...
=========
I tried reproducing the issue and found some interesting observation.
Let me list them down.
1. Started master server. Some important configuration to note.
[mysqld]
log-bin=mysql-bin
server-id=1
log-slave-
gtid-mode=on
enforce-
-------------
2. Started pxc-node-1 and 2.
[mysqld]
log-bin=mysql-bin
server-id=2
log-slave-
gtid-mode=on
enforce-
-------------
3. Select one of the pxc-node (node-1 in my case) and make it an async slave
point to master that we started in step-1
------------
4. Execute following workload on master
create table t (i int) engine=innodb;
insert into t values (1), (2), (3), (4);
select * from t;
As expected I gtid has been properly captured to cover the needed actions:
mysql> show global variables like 'gtid_executed';
gtid_executed e20191fe-
------------
5. Moving to slave. Check if the async-replication was done.
(Same can be confirmed out even on node-2 which is replicting from node-1 using galera)
mysql> show global variables like 'gtid_executed';
gtid_executed e20191fe-
mysql> select * from t;
------
i
------
1
2
3
4
------
4 rows in set (0.00 sec)
------------
6. Execute following workload on node-1.
delete from t where i = 2;
This action too is reflected as expected (on node-2 also)
mysql> show global variables like 'gtid_executed';
gtid_executed 122fdc30-
e20191fe-
Note: There are 2 uuid. One is GTID from MySQL other is GTID/UUID from Galera and both has different
seqno to follow. Also, note that by directly modifying slave we have put slave and master out of sync.
------------
7. Run the same delete statement on master. Statement will pass on master and seqno will increment
as expected.
mysql> show global variables like 'gtid_executed';
gtid_executed e20191fe-
But when this stmt is replicated on async slave then the record is not found which will cause
slave thrd to generate following error and stop SQL slave thread.
<snippet>
2015-12-11 13:31:32 8881 [ERROR] Slave SQL: Could not execute Delete_rows event on table test.t; Can't find record in 't', Error_code: 1032; handler error HA_ERR_END_OF_FILE; the event's master log mysql-bin.000001, end_log_pos 1645, Error_code: 1032
2015-12-11 13:31:32 8881 [Warning] Slave: Can't find record in 't' Error_code: 1032
2015-12-11 13:31:32 8881 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'mysql-bin.000001' position 1441
</snippet>
This is expected as user has maliciously madde them inconsistent.
-------------
Now onwards master and slave are out of sync.
Master ops can continues and seqno increases but doesn't affect async slave which in this case is galera-node-1.
Operation on galera-node-1 are logged using separate uuid which are replicated as expected.
This behavior looks perfectly fine and inline with understanding.
-------