Replication error 1302 (GTID replication)

MySQL & MariaDB Percona Server for MySQL 5.6
1

Hi,

I’m using Percona Server 5.6.21-70.1 on Ubuntu 12.04 LTS, and my replication broke (anonymized):


mysql> show slave status\G
*************************** 1. row ***************************
Slave_IO_State: Waiting for master to send event
Master_Host: 127.0.0.1
Master_User: schaduw
Master_Port: 3307
Connect_Retry: 10
Master_Log_File: mysql-bin.000182
Read_Master_Log_Pos: 469336089
Relay_Log_File: relay-bin.001073
Relay_Log_Pos: 408
Relay_Master_Log_File: mysql-bin.000176
Slave_IO_Running: Yes
Slave_SQL_Running: No
Replicate_Do_DB: 
Replicate_Ignore_DB: 
Replicate_Do_Table: 
Replicate_Ignore_Table: 
Replicate_Wild_Do_Table: 
Replicate_Wild_Ignore_Table: 
Last_Errno: 1032
Last_Error: Could not execute Update_rows event on table DATABASE.TABLE; Can't find record in 'TABLE', Error_code: 1032; handler error HA_ERR_KEY_NOT_FOUND; the event's master log mysql-bin.000176, end_log_pos 833933307
Skip_Counter: 0
Exec_Master_Log_Pos: 816823387
Relay_Log_Space: 3425877976
Until_Condition: None
Until_Log_File: 
Until_Log_Pos: 0
Master_SSL_Allowed: No
Master_SSL_CA_File: 
Master_SSL_CA_Path: 
Master_SSL_Cert: 
Master_SSL_Cipher: 
Master_SSL_Key: 
Seconds_Behind_Master: NULL
Master_SSL_Verify_Server_Cert: No
Last_IO_Errno: 0
Last_IO_Error: 
Last_SQL_Errno: 1032
Last_SQL_Error: Could not execute Update_rows event on table DATABASE.TABLE; Can't find record in 'TABLE', Error_code: 1032; handler error HA_ERR_KEY_NOT_FOUND; the event's master log mysql-bin.000176, end_log_pos 833933307
Replicate_Ignore_Server_Ids: 
Master_Server_Id: 3
Master_UUID: 497de104-1697-11e4-9b81-00163e943835
Master_Info_File: mysql.slave_master_info
SQL_Delay: 0
SQL_Remaining_Delay: NULL
Slave_SQL_Running_State: 
Master_Retry_Count: 86400
Master_Bind: 
Last_IO_Error_Timestamp: 
Last_SQL_Error_Timestamp: 141201 14:35:03
Master_SSL_Crl: 
Master_SSL_Crlpath: 
Retrieved_Gtid_Set: e3bd03cc-e98f-11e3-b5e0-00163e943836:14528432-14839710
Executed_Gtid_Set: 060affc4-2c58-11e4-a959-00163e910310:1-18,
497de104-1697-11e4-9b81-00163e943835:1-3,
7c3ce949-e7ed-11e3-ab38-00163e943835:1-21376:21393-42453,
e3bd03cc-e98f-11e3-b5e0-00163e943836:1-6153708:6153725-14528431
Auto_Position: 1
1 row in set (0.00 sec)

My MySQL setup is as follows:
[LIST]
[]two MySQL servers in Master/Master replication, with a virtual IP managed by Pacemaker, so only on master is the real master
[]one offsite MySQL server as a slave of one of the two servers mentioned above. This is the MySQL with the replication problem.
[/LIST] I read the following blog posts, for a possible solution:
[LIST]
[][url]http://tips.kaali.co.uk/2013/09/26/inject-empty-transactions-in-mysql-5-6-gtid-based-replication/[/url]
[][url]http://sql.dzone.com/articles/repair-mysql-56-gtid[/url]
[*][url]http://www.percona.com/blog/2013/03/26/repair-mysql-5-6-gtid-replication-by-injecting-empty-transactions/[/url]
[/LIST] The problem is that my ‘Executed_Gtid_Set:’ is really different from the examples in the blog posts, so I don’t now what to put in ‘SET GTID_NEXT=’

Who can help me? If you need more info, please let me know.

2

What is on master (127.0.0.1:3307) in binlog mysql-bin.000182 on position 816823387 ?

3 
root@MASTER:~# mysqlbinlog --start-position=816823386 /var/log/mysql/mysql-bin.000182
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#141201 6:25:04 server id 3 end_log_pos 120 CRC32 0x8798598a Start: binlog v 4, server v 5.6.19-67.0-log created 141201 6:25:04
BINLOG '
sPt7VA8DAAAAdAAAAHgAAAAAAAQANS42LjE5LTY3LjAtbG9nAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAXAAEGggAAAAICAgCAAAACgoKGRkAAYpZ
mIc=
'/*!*/;
ERROR: Error in Log_event::read_log_event(): 'read error', data_len: 959590963, event_type: 92
ERROR: Could not read entry at offset 816823386: Error in log format or read error.
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

Is this the correct way for retrieving query’s from binlog files?

4

Syntax is correct, but position before 816823387 musn’t (and probably isnt) 816823386.

Try

mysqlbinlog --start-datetime="2014-12-01 6:24:54" --stop-datetime="2014-12-01 6:25:14" /var/log/mysql/mysql-bin.000182

or something like this.

5

Part 1:


root@MASTER:~# mysqlbinlog --start-datetime="2014-12-01 6:24:54" --stop-datetime="2014-12-01 6:25:14" /var/log/mysql/mysql-bin.000182 | sed "s/anwb/xxxxx/g"
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#141201 6:25:04 server id 3 end_log_pos 120 CRC32 0x8798598a Start: binlog v 4, server v 5.6.19-67.0-log created 141201 6:25:04
BINLOG '
sPt7VA8DAAAAdAAAAHgAAAAAAAQANS42LjE5LTY3LjAtbG9nAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAXAAEGggAAAAICAgCAAAACgoKGRkAAYpZ
mIc=
'/*!*/;
# at 120
#141201 6:25:04 server id 3 end_log_pos 303 CRC32 0x161ca6a3 Previous-GTIDs
# 497de104-1697-11e4-9b81-00163e943835:1-3,
# 7c3ce949-e7ed-11e3-ab38-00163e943835:1-21376:21393-42453,
# e3bd03cc-e98f-11e3-b5e0-00163e943836:1-6153708:6153725-14790400
# at 303
#141201 6:25:05 server id 4 end_log_pos 351 CRC32 0x8bb88f01 GTID [commit=yes]
SET @@SESSION.GTID_NEXT= 'e3bd03cc-e98f-11e3-b5e0-00163e943836:14790401'/*!*/;
# at 351
#141201 6:25:05 server id 4 end_log_pos 464 CRC32 0x9b0717e2 Query thread_id=101937269 exec_time=0 error_code=0
SET TIMESTAMP=1417411505/*!*/;
SET @@session.pseudo_thread_id=101937269/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=0/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=8/*!*/;
SET @@session.time_zone='SYSTEM'/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
BEGIN
/*!*/;
# at 464
#141201 6:25:05 server id 4 end_log_pos 870 CRC32 0x820aefda Query thread_id=101937269 exec_time=0 error_code=0
use `xxxxx_prod_magento`/*!*/;
SET TIMESTAMP=1417411505/*!*/;
UPDATE `xxxxx_cron_schedule` SET `job_code` = 'ops_clean_up_old_cc_data', `status` = 'success', `messages` = NULL, `created_at` = '2014-12-01 05:20:12', `scheduled_at` = '2014-12-01 05:25:00', `executed_at` = '2014-12-01 05:25:01', `finished_at` = '2014-12-01 05:25:05' WHERE (schedule_id='3366298')
/*!*/;
# at 870
#141201 6:25:05 server id 4 end_log_pos 901 CRC32 0x519832e2 Xid = 180608126
COMMIT/*!*/;
# at 901
#141201 6:25:05 server id 4 end_log_pos 949 CRC32 0x01a28cff GTID [commit=yes]
SET @@SESSION.GTID_NEXT= 'e3bd03cc-e98f-11e3-b5e0-00163e943836:14790402'/*!*/;
# at 949
#141201 6:25:05 server id 4 end_log_pos 1054 CRC32 0x2f31ff2b Query thread_id=101937269 exec_time=0 error_code=0
SET TIMESTAMP=1417411505/*!*/;
BEGIN
/*!*/;
# at 1054
#141201 6:25:05 server id 4 end_log_pos 1263 CRC32 0xc0bceed6 Query thread_id=101937269 exec_time=0 error_code=0
SET TIMESTAMP=1417411505/*!*/;
UPDATE `xxxxx_cron_schedule` SET `status` = 'running' WHERE (schedule_id = '3366301') AND (status = 'pending')
/*!*/;
# at 1263
#141201 6:25:05 server id 4 end_log_pos 1294 CRC32 0xd7d73f48 Xid = 180608128
COMMIT/*!*/;
# at 1294
#141201 6:25:05 server id 4 end_log_pos 1342 CRC32 0x3e6dc82e GTID [commit=yes]
SET @@SESSION.GTID_NEXT= 'e3bd03cc-e98f-11e3-b5e0-00163e943836:14790403'/*!*/;
# at 1342
#141201 6:25:05 server id 4 end_log_pos 1455 CRC32 0x82136c1f Query thread_id=101937269 exec_time=0 error_code=0
SET TIMESTAMP=1417411505/*!*/;
BEGIN
/*!*/;
# at 1455
#141201 6:25:05 server id 4 end_log_pos 1842 CRC32 0x7b0feead Query thread_id=101937269 exec_time=0 error_code=0
SET TIMESTAMP=1417411505/*!*/;
UPDATE `xxxxx_cron_schedule` SET `job_code` = 'xxxxxsales_export_order', `status` = 'running', `messages` = NULL, `created_at` = '2014-12-01 05:20:13', `scheduled_at` = '2014-12-01 05:25:00', `executed_at` = '2014-12-01 05:25:05', `finished_at` = NULL WHERE (schedule_id='3366301')
/*!*/;
# at 1842
#141201 6:25:05 server id 4 end_log_pos 1873 CRC32 0x8431f215 Xid = 180608130
COMMIT/*!*/;
# at 1873
#141201 6:25:05 server id 4 end_log_pos 1921 CRC32 0xe4233b6d GTID [commit=yes]
SET @@SESSION.GTID_NEXT= 'e3bd03cc-e98f-11e3-b5e0-00163e943836:14790404'/*!*/;
# at 1921
#141201 6:25:05 server id 4 end_log_pos 2034 CRC32 0x9132ca9b Query thread_id=101937269 exec_time=0 error_code=0
SET TIMESTAMP=1417411505/*!*/;
BEGIN
/*!*/;
# at 2034
#141201 6:25:05 server id 4 end_log_pos 2438 CRC32 0x38f27891 Query thread_id=101937269 exec_time=0 error_code=0
SET TIMESTAMP=1417411505/*!*/;
UPDATE `xxxxx_cron_schedule` SET `job_code` = 'xxxxxsales_export_order', `status` = 'success', `messages` = NULL, `created_at` = '2014-12-01 05:20:13', `scheduled_at` = '2014-12-01 05:25:00', `executed_at` = '2014-12-01 05:25:05', `finished_at` = '2014-12-01 05:25:05' WHERE (schedule_id='3366301')
/*!*/;
# at 2438
#141201 6:25:05 server id 4 end_log_pos 2469 CRC32 0xc808249e Xid = 180608132
COMMIT/*!*/;
# at 2469
#141201 6:25:05 server id 4 end_log_pos 2517 CRC32 0x43447954 GTID [commit=yes]
SET @@SESSION.GTID_NEXT= 'e3bd03cc-e98f-11e3-b5e0-00163e943836:14790405'/*!*/;
# at 2517
#141201 6:25:05 server id 4 end_log_pos 2622 CRC32 0xe264ae58 Query thread_id=101937269 exec_time=0 error_code=0
SET TIMESTAMP=1417411505/*!*/;
BEGIN
/*!*/;
# at 2622
#141201 6:25:05 server id 4 end_log_pos 2831 CRC32 0x51155de3 Query thread_id=101937269 exec_time=0 error_code=0
SET TIMESTAMP=1417411505/*!*/;
UPDATE `xxxxx_cron_schedule` SET `status` = 'running' WHERE (schedule_id = '3366304') AND (status = 'pending')
/*!*/;
# at 2831
#141201 6:25:05 server id 4 end_log_pos 2862 CRC32 0x263a42a7 Xid = 180608134
COMMIT/*!*/;
# at 2862
#141201 6:25:05 server id 4 end_log_pos 2910 CRC32 0xcf2db6d8 GTID [commit=yes]
SET @@SESSION.GTID_NEXT= 'e3bd03cc-e98f-11e3-b5e0-00163e943836:14790406'/*!*/;
# at 2910
#141201 6:25:05 server id 4 end_log_pos 3023 CRC32 0x71302d2a Query thread_id=101937269 exec_time=0 error_code=0
SET TIMESTAMP=1417411505/*!*/;
BEGIN
/*!*/;
# at 3023
#141201 6:25:05 server id 4 end_log_pos 3419 CRC32 0xb34a03a1 Query thread_id=101937269 exec_time=0 error_code=0
SET TIMESTAMP=1417411505/*!*/;
UPDATE `xxxxx_cron_schedule` SET `job_code` = 'xxxxxsales_export_complete_order', `status` = 'running', `messages` = NULL, `created_at` = '2014-12-01 05:20:13', `scheduled_at` = '2014-12-01 05:25:00', `executed_at` = '2014-12-01 05:25:05', `finished_at` = NULL WHERE (schedule_id='3366304')
/*!*/;
# at 3419
#141201 6:25:05 server id 4 end_log_pos 3450 CRC32 0xadf2cbce Xid = 180608136
COMMIT/*!*/;
# at 3450
#141201 6:25:05 server id 4 end_log_pos 3498 CRC32 0x49808705 GTID [commit=yes]
SET @@SESSION.GTID_NEXT= 'e3bd03cc-e98f-11e3-b5e0-00163e943836:14790407'/*!*/;
# at 3498
#141201 6:25:05 server id 4 end_log_pos 3611 CRC32 0x28f875ea Query thread_id=101937269 exec_time=0 error_code=0
SET TIMESTAMP=1417411505/*!*/;
BEGIN
/*!*/;
# at 3611
#141201 6:25:05 server id 4 end_log_pos 4024 CRC32 0x9077f2fc Query thread_id=101937269 exec_time=0 error_code=0
SET TIMESTAMP=1417411505/*!*/;
UPDATE `xxxxx_cron_schedule` SET `job_code` = 'xxxxxsales_export_complete_order', `status` = 'success', `messages` = NULL, `created_at` = '2014-12-01 05:20:13', `scheduled_at` = '2014-12-01 05:25:00', `executed_at` = '2014-12-01 05:25:05', `finished_at` = '2014-12-01 05:25:05' WHERE (schedule_id='3366304')
/*!*/;
# at 4024
#141201 6:25:05 server id 4 end_log_pos 4055 CRC32 0x76669e99 Xid = 180608138
COMMIT/*!*/;
# at 4055
#141201 6:25:05 server id 4 end_log_pos 4103 CRC32 0x4e22b87a GTID [commit=yes]
SET @@SESSION.GTID_NEXT= 'e3bd03cc-e98f-11e3-b5e0-00163e943836:14790408'/*!*/;
# at 4103
#141201 6:25:05 server id 4 end_log_pos 4208 CRC32 0x01047359 Query thread_id=101937269 exec_time=0 error_code=0
SET TIMESTAMP=1417411505/*!*/;
BEGIN
/*!*/;
# at 4208
#141201 6:25:05 server id 4 end_log_pos 4417 CRC32 0x7788ed81 Query thread_id=101937269 exec_time=0 error_code=0
SET TIMESTAMP=1417411505/*!*/;
UPDATE `xxxxx_cron_schedule` SET `status` = 'running' WHERE (schedule_id = '3366307') AND (status = 'pending')
/*!*/;
# at 4417
#141201 6:25:05 server id 4 end_log_pos 4448 CRC32 0xb3803ce2 Xid = 180608140
COMMIT/*!*/;
# at 4448
#141201 6:25:05 server id 4 end_log_pos 4496 CRC32 0x66113d4f GTID [commit=yes]
SET @@SESSION.GTID_NEXT= 'e3bd03cc-e98f-11e3-b5e0-00163e943836:14790409'/*!*/;
# at 4496
#141201 6:25:05 server id 4 end_log_pos 4609 CRC32 0x8999ff46 Query thread_id=101937269 exec_time=0 error_code=0
SET TIMESTAMP=1417411505/*!*/;
BEGIN
/*!*/;
# at 4609
#141201 6:25:05 server id 4 end_log_pos 5011 CRC32 0xb56a79a0 Query thread_id=101937269 exec_time=0 error_code=0
SET TIMESTAMP=1417411505/*!*/;
UPDATE `xxxxx_cron_schedule` SET `job_code` = 'xxxxxsales_async_decrease_booked_stock', `status` = 'running', `messages` = NULL, `created_at` = '2014-12-01 05:20:13', `scheduled_at` = '2014-12-01 05:25:00', `executed_at` = '2014-12-01 05:25:05', `finished_at` = NULL WHERE (schedule_id='3366307')
/*!*/;
6

Part 2:


# at 5011
#141201 6:25:05 server id 4 end_log_pos 5042 CRC32 0xd4ef6e06 Xid = 180608142
COMMIT/*!*/;
# at 5042
#141201 6:25:05 server id 4 end_log_pos 5090 CRC32 0x6b7a84ad GTID [commit=yes]
SET @@SESSION.GTID_NEXT= 'e3bd03cc-e98f-11e3-b5e0-00163e943836:14790410'/*!*/;
# at 5090
#141201 6:25:05 server id 4 end_log_pos 5203 CRC32 0xe64283eb Query thread_id=101937269 exec_time=0 error_code=0
SET TIMESTAMP=1417411505/*!*/;
BEGIN
/*!*/;
# at 5203
#141201 6:25:05 server id 4 end_log_pos 5622 CRC32 0x6dc92d2e Query thread_id=101937269 exec_time=0 error_code=0
SET TIMESTAMP=1417411505/*!*/;
UPDATE `xxxxx_cron_schedule` SET `job_code` = 'xxxxxsales_async_decrease_booked_stock', `status` = 'success', `messages` = NULL, `created_at` = '2014-12-01 05:20:13', `scheduled_at` = '2014-12-01 05:25:00', `executed_at` = '2014-12-01 05:25:05', `finished_at` = '2014-12-01 05:25:05' WHERE (schedule_id='3366307')
/*!*/;
# at 5622
#141201 6:25:05 server id 4 end_log_pos 5653 CRC32 0x8b2bc3f6 Xid = 180608144
COMMIT/*!*/;
# at 5653
#141201 6:25:05 server id 4 end_log_pos 5701 CRC32 0x5b381cc9 GTID [commit=yes]
SET @@SESSION.GTID_NEXT= 'e3bd03cc-e98f-11e3-b5e0-00163e943836:14790411'/*!*/;
# at 5701
#141201 6:25:05 server id 4 end_log_pos 5806 CRC32 0xa23d498f Query thread_id=101937269 exec_time=0 error_code=0
SET TIMESTAMP=1417411505/*!*/;
BEGIN
/*!*/;
# at 5806
#141201 6:25:05 server id 4 end_log_pos 6015 CRC32 0x75e155b3 Query thread_id=101937269 exec_time=0 error_code=0
SET TIMESTAMP=1417411505/*!*/;
UPDATE `xxxxx_cron_schedule` SET `status` = 'running' WHERE (schedule_id = '3366312') AND (status = 'pending')
/*!*/;
# at 6015
#141201 6:25:05 server id 4 end_log_pos 6046 CRC32 0xd8d3c901 Xid = 180608146
COMMIT/*!*/;
# at 6046
#141201 6:25:05 server id 4 end_log_pos 6094 CRC32 0x17baf8a7 GTID [commit=yes]
SET @@SESSION.GTID_NEXT= 'e3bd03cc-e98f-11e3-b5e0-00163e943836:14790412'/*!*/;
# at 6094
#141201 6:25:05 server id 4 end_log_pos 6207 CRC32 0x5ddc8b59 Query thread_id=101937269 exec_time=0 error_code=0
SET TIMESTAMP=1417411505/*!*/;
BEGIN
/*!*/;
# at 6207
#141201 6:25:05 server id 4 end_log_pos 6593 CRC32 0x05c3e262 Query thread_id=101937269 exec_time=0 error_code=0
SET TIMESTAMP=1417411505/*!*/;
UPDATE `xxxxx_cron_schedule` SET `job_code` = 'smile_asyncorderemail', `status` = 'running', `messages` = NULL, `created_at` = '2014-12-01 05:20:13', `scheduled_at` = '2014-12-01 05:25:00', `executed_at` = '2014-12-01 05:25:05', `finished_at` = NULL WHERE (schedule_id='3366312')
/*!*/;
# at 6593
#141201 6:25:05 server id 4 end_log_pos 6624 CRC32 0xc5ae2af3 Xid = 180608148
COMMIT/*!*/;
# at 6624
#141201 6:25:07 server id 4 end_log_pos 6672 CRC32 0xd4ec09ec GTID [commit=yes]
SET @@SESSION.GTID_NEXT= 'e3bd03cc-e98f-11e3-b5e0-00163e943836:14790413'/*!*/;
# at 6672
#141201 6:25:07 server id 4 end_log_pos 6785 CRC32 0x6ed31acf Query thread_id=101937269 exec_time=0 error_code=0
SET TIMESTAMP=1417411507/*!*/;
BEGIN
/*!*/;
# at 6785
#141201 6:25:07 server id 4 end_log_pos 7188 CRC32 0xb292add0 Query thread_id=101937269 exec_time=0 error_code=0
SET TIMESTAMP=1417411507/*!*/;
UPDATE `xxxxx_cron_schedule` SET `job_code` = 'smile_asyncorderemail', `status` = 'success', `messages` = NULL, `created_at` = '2014-12-01 05:20:13', `scheduled_at` = '2014-12-01 05:25:00', `executed_at` = '2014-12-01 05:25:05', `finished_at` = '2014-12-01 05:25:07' WHERE (schedule_id='3366312')
/*!*/;
# at 7188
#141201 6:25:07 server id 4 end_log_pos 7219 CRC32 0x9fa5a9bb Xid = 180608150
COMMIT/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;