Sunday, August 16, 2015

Skip MySQL transactions on Slave when GTID configured

Symptoms:

server2> show slave status \G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: localhost
                  Master_User: repl_user
                  Master_Port: 5001
                Connect_Retry: 60
              Master_Log_File: bin-log.000012
          Read_Master_Log_Pos: 2255
               Relay_Log_File: relay-bin.000016
                Relay_Log_Pos: 1902
        Relay_Master_Log_File: bin-log.000012
             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: Worker 0 failed executing transaction 'e645f6c4-428d-11e5-bf83-08002702dadb:20' at master log bin-log.000012, end_log_pos 1939; Could not execute Delete_rows event on table appdb.a; Can't find record in 'a', Error_code: 1032; handler error HA_ERR_END_OF_FILE; the event's master log bin-log.000012, end_log_pos 1939
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 1696
              Relay_Log_Space: 2860
              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: Worker 0 failed executing transaction 'e645f6c4-428d-11e5-bf83-08002702dadb:20' at master log bin-log.000012, end_log_pos 1939; Could not execute Delete_rows event on table appdb.a; Can't find record in 'a', Error_code: 1032; handler error HA_ERR_END_OF_FILE; the event's master log bin-log.000012, end_log_pos 1939
  Replicate_Ignore_Server_Ids:
             Master_Server_Id: 1
                  Master_UUID: e645f6c4-428d-11e5-bf83-08002702dadb
             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: 150816 22:53:41
               Master_SSL_Crl:
           Master_SSL_Crlpath:
           Retrieved_Gtid_Set: e645f6c4-428d-11e5-bf83-08002702dadb:5-21
            Executed_Gtid_Set: b8ac4b6b-428f-11e5-bf8f-08002702dadb:1-5,
e645f6c4-428d-11e5-bf83-08002702dadb:5-19
                Auto_Position: 0
1 row in set (0.00 sec)

Check the failed statements:

[mysql@localhost script]$ mysqlbinlog /mysql/server1/repl/bin-log.000012 --start-position=1939 --stop-position=1939
/*!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
#150816 22:41:17 server id 1  end_log_pos 120 CRC32 0xa5f1c472  Start: binlog v 4, server v 5.6.26-enterprise-commercial-advanced-log created 150816 22:41:17 at startup
# Warning: this binlog is either in use or was not closed properly.
ROLLBACK/*!*/;
BINLOG '
DaHQVQ8BAAAAdAAAAHgAAAABAAQANS42LjI2LWVudGVycHJpc2UtY29tbWVyY2lhbC1hZHZhbmNl
ZC1sb2cAAAAAAAAAAAANodBVEzgNAAgAEgAEBAQEEgAAXAAEGggAAAAICAgCAAAACgoKGRkAAXLE
8aU=
'/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;


[mysql@localhost script]$ mysqlbinlog /mysql/server1/repl/bin-log.000012 -v
SET @@SESSION.GTID_NEXT= 'e645f6c4-428d-11e5-bf83-08002702dadb:20'/*!*/;
# at 1744
#150816 22:53:41 server id 1  end_log_pos 1817 CRC32 0x96f22726         Query   thread_id=7     exec_time=0     error_code=0
SET TIMESTAMP=1439736821/*!*/;
BEGIN
/*!*/;
# at 1817
# at 1854
#150816 22:53:41 server id 1  end_log_pos 1899 CRC32 0x384ad943         Table_map: `appdb`.`a` mapped to number 71
# at 1899
#150816 22:53:41 server id 1  end_log_pos 1939 CRC32 0xb9074e0e         Delete_rows: table id 71 flags: STMT_END_F

BINLOG '
9aPQVRMBAAAALQAAAGsHAAAAAEcAAAAAAAEABWFwcGRiAAFhAAEDAAFD2Uo4
9aPQVSABAAAAKAAAAJMHAAAAAEcAAAAAAAEAAgAB//4AAAAADk4HuQ==
'/*!*/;
### DELETE FROM `appdb`.`a`
### WHERE
###   @1=0
# at 1939

#150816 22:53:41 server id 1  end_log_pos 1970 CRC32 0xf10570bc         Xid = 62
COMMIT/*!*/;
# at 1970
#150816 22:55:06 server id 1  end_log_pos 2018 CRC32 0x839b9136         GTID [commit=yes]

Fix the replication:

server2> stop slave;
Query OK, 0 rows affected (0.00 sec)

server2> set gtid_next='e645f6c4-428d-11e5-bf83-08002702dadb:20';
Query OK, 0 rows affected (0.00 sec)

server2> begin;commit;
Query OK, 0 rows affected (0.00 sec)

Query OK, 0 rows affected (0.04 sec)

server2> set gtid_next="automatic";
Query OK, 0 rows affected (0.00 sec)

server2> start slave;
Query OK, 0 rows affected, 1 warning (0.01 sec)

server2> show slave status \G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: localhost
                  Master_User: repl_user
                  Master_Port: 5001
                Connect_Retry: 60
              Master_Log_File: bin-log.000012
          Read_Master_Log_Pos: 2255
               Relay_Log_File: relay-bin.000017
                Relay_Log_Pos: 352
        Relay_Master_Log_File: bin-log.000012
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
              Replicate_Do_DB:
          Replicate_Ignore_DB:
           Replicate_Do_Table:
       Replicate_Ignore_Table:
      Replicate_Wild_Do_Table:
  Replicate_Wild_Ignore_Table:
                   Last_Errno: 0
                   Last_Error:
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 2255
              Relay_Log_Space: 2860
              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: 0
Master_SSL_Verify_Server_Cert: No
                Last_IO_Errno: 0
                Last_IO_Error:
               Last_SQL_Errno: 0
               Last_SQL_Error:
  Replicate_Ignore_Server_Ids:
             Master_Server_Id: 1
                  Master_UUID: e645f6c4-428d-11e5-bf83-08002702dadb
             Master_Info_File: mysql.slave_master_info
                    SQL_Delay: 0
          SQL_Remaining_Delay: NULL
      Slave_SQL_Running_State: Slave has read all relay log; waiting for the slave I/O thread to update it
           Master_Retry_Count: 86400
                  Master_Bind:
      Last_IO_Error_Timestamp:
     Last_SQL_Error_Timestamp:
               Master_SSL_Crl:
           Master_SSL_Crlpath:
           Retrieved_Gtid_Set: e645f6c4-428d-11e5-bf83-08002702dadb:5-21
            Executed_Gtid_Set: b8ac4b6b-428f-11e5-bf8f-08002702dadb:1-5,
e645f6c4-428d-11e5-bf83-08002702dadb:5-21
                Auto_Position: 0
1 row in set (0.00 sec)

 

Alternative method:

server2> stop slave;
Query OK, 0 rows affected (0.01 sec)

server2> CHANGE MASTER TO MASTER_HOST='localhost', MASTER_PORT=5001, MASTER_USER='repluser', MASTER_PASSWORD='compexpassword’, MASTER_LOG_FILE='bin-log.000012', MASTER_LOG_POS=2555;
Query OK, 0 rows affected, 2 warnings (0.02 sec)

server2> start slave;
Query OK, 0 rows affected, 1 warning (0.00 sec)

Reference: https://www.percona.com/blog/2013/03/26/repair-mysql-5-6-gtid-replication-by-injecting-empty-transactions/