How To Fix MySQL Replication After an Incompatible DDL Command

Let's take a look at a tutorial that explains how to fix MySQL replication after an incompatible DDL command.

Jaime Sicam

Oct. 06, 18 · Tutorial

Likes (2)

Comment

Save

10.0K Views

MySQL supports replicating to a slave that is one release higher. This allows us to easily upgrade our MySQL setup to a new version by promoting the slave and pointing the application to it. However, though unsupported, there are times when the MySQL version of slave deployed is one release lower. In this scenario, if your application has been performing much better on an older version of MySQL, you would like to have a convenient option to downgrade. You can simply promote the slave to get the old performance back.

The MySQL manual says that ROW based replication can be used to replicate to a lower version, provided that no DDLs replicated are incompatible with the slave. One such incompatible command is ALTER USER , which is a new feature in MySQL 5.7 and not available on 5.6. :

ALTER USER 'testuser'@'localhost' IDENTIFIED BY 'testuser';

Executing that command would break replication. Here is an example of a broken slave in non-GTID replication:

*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: 127.0.0.1
                  Master_User: repl
                  Master_Port: 5723
                Connect_Retry: 60
              Master_Log_File: mysql-bin.000002
          Read_Master_Log_Pos: 36915649
               Relay_Log_File: mysql_sandbox5641-relay-bin.000006
                Relay_Log_Pos: 36174552
        Relay_Master_Log_File: mysql-bin.000002
             Slave_IO_Running: Yes
            Slave_SQL_Running: No
*** redacted ***
                   Last_Errno: 1064
                   Last_Error: Error 'You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near 'IDENTIFIED WITH 'mysql_native_password' AS '*3A2EB9C80F7239A4DE3933AE266DB76A784' at line 1' on query. Default database: ''. Query: 'ALTER USER 'testuser'@'localhost' IDENTIFIED WITH 'mysql_native_password' AS '*3A2EB9C80F7239A4DE3933AE266DB76A7846BCB8''
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 36174373
              Relay_Log_Space: 36916179
              Until_Condition: None
               Until_Log_File:
                Until_Log_Pos: 0
           Master_SSL_Allowed: No
*** redacted ***
        Seconds_Behind_Master: NULL
Master_SSL_Verify_Server_Cert: No
                Last_IO_Errno: 0
                Last_IO_Error:
               Last_SQL_Errno: 1064
               Last_SQL_Error: Error 'You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near 'IDENTIFIED WITH 'mysql_native_password' AS '*3A2EB9C80F7239A4DE3933AE266DB76A784' at line 1' on query. Default database: ''. Query: 'ALTER USER 'testuser'@'localhost' IDENTIFIED WITH 'mysql_native_password' AS '*3A2EB9C80F7239A4DE3933AE266DB76A7846BCB8''
  Replicate_Ignore_Server_Ids:
             Master_Server_Id: 1
                  Master_UUID: 00005723-0000-0000-0000-000000005723
*** redacted ***
      Last_IO_Error_Timestamp:
     Last_SQL_Error_Timestamp: 180918 22:03:40
*** redacted ***
                Auto_Position: 0
1 row in set (0.00 sec)

Skipping the statement does not resume replication:

mysql> STOP SLAVE;
Query OK, 0 rows affected (0.02 sec)
mysql> SET GLOBAL sql_slave_skip_counter=1;
Query OK, 0 rows affected (0.00 sec)
mysql> START SLAVE;
Query OK, 0 rows affected (0.01 sec)
mysql> SHOW SLAVE STATUS\G

Fixing Non-GTID Replication

When you check slave status, replication still isn't fixed. To fix it, you must manually skip to the next binary log position. The current binary log (Relay_Master_Log_File) and position (Exec_Master_Log_Pos) executed are mysql-bin.000002 and 36174373 respectively. We can use mysqlbinlog on the master to determine the next position:

mysqlbinlog -v --base64-output=DECODE-ROWS --start-position=36174373 /ssd/sandboxes/msb_5_7_23/data/mysql-bin.000002 | head -n 30
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 36174373
#180918 22:03:40 server id 1  end_log_pos 36174438 CRC32 0xc7e1e553 Anonymous_GTIDlast_committed=19273sequence_number=19277rbr_only=no
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 36174438
#180918 22:03:40 server id 1  end_log_pos 36174621 CRC32 0x2e5bb235 Querythread_id=563exec_time=0error_code=0
SET TIMESTAMP=1537279420/*!*/;
SET @@session.pseudo_thread_id=563/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1436549152/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C latin1 *//*!*/;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
ALTER USER 'testuser'@'localhost' IDENTIFIED WITH 'mysql_native_password' AS '*3A2EB9C80F7239A4DE3933AE266DB76A7846BCB8'
/*!*/;
# at 36174621
#180918 22:03:40 server id 1  end_log_pos 36174686 CRC32 0x86756b3f Anonymous_GTIDlast_committed=19275sequence_number=19278rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 36174686
#180918 22:03:40 server id 1  end_log_pos 36174760 CRC32 0x30e663f9 Querythread_id=529exec_time=0error_code=0
SET TIMESTAMP=1537279420/*!*/;
BEGIN
/*!*/;
# at 36174760
#180918 22:03:40 server id 1  end_log_pos 36174819 CRC32 0x48054daf Table_map: `sbtest`.`sbtest1` mapped to number 226

Based on the output above, the next binary log position is 36174621. To fix the slave, run:

STOP SLAVE;
CHANGE MASTER TO MASTER_LOG_FILE='mysql-bin.000002', MASTER_LOG_POS=36174621;
START SLAVE;

Verify if the slave threads are now running by executing SHOW SLAVE STATUS\G

               Slave_IO_State: Waiting for master to send event
                  Master_Host: 127.0.0.1
                  Master_User: repl
                  Master_Port: 5723
                Connect_Retry: 60
              Master_Log_File: mysql-bin.000002
          Read_Master_Log_Pos: 306841423
               Relay_Log_File: mysql_sandbox5641-relay-bin.000002
                Relay_Log_Pos: 190785290
        Relay_Master_Log_File: mysql-bin.000002
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
*** redacted ***
                   Last_Errno: 0
                   Last_Error:
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 226959625
              Relay_Log_Space: 270667273
              Until_Condition: None
               Until_Log_File:
                Until_Log_Pos: 0
           Master_SSL_Allowed: No
*** redacted ***
        Seconds_Behind_Master: 383
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: 00005723-0000-0000-0000-000000005723
             Master_Info_File: /ssd/sandboxes/msb_5_6_41/data/master.info
                    SQL_Delay: 0
          SQL_Remaining_Delay: NULL
      Slave_SQL_Running_State: Opening tables
           Master_Retry_Count: 86400
*** redacted ***
                Auto_Position: 0

To make the slave consistent with the master, execute the compatible query on the slave.

SET SESSION sql_log_bin = 0;
GRANT USAGE ON *.* TO 'testuser'@'localhost' IDENTIFIED BY 'testuser';

Done.

GTID Replication

For GTID replication, in addition to injecting an empty transaction for the offending statement, you'll need to skip it by using the non-GTID solution provided above. Once running, flip it back to GTID.

Here's an example of a broken GTID slave:

mysql> SHOW SLAVE STATUS\G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: 127.0.0.1
                  Master_User: repl
                  Master_Port: 5723
                Connect_Retry: 60
              Master_Log_File: mysql-bin.000003
          Read_Master_Log_Pos: 14364967
               Relay_Log_File: mysql_sandbox5641-relay-bin.000002
                Relay_Log_Pos: 8630318
        Relay_Master_Log_File: mysql-bin.000003
             Slave_IO_Running: Yes
            Slave_SQL_Running: No
*** redacted ***
                   Last_Errno: 1064
                   Last_Error: Error 'You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near 'IDENTIFIED WITH 'mysql_native_password' AS '*3A2EB9C80F7239A4DE3933AE266DB76A784' at line 1' on query. Default database: ''. Query: 'ALTER USER 'testuser'@'localhost' IDENTIFIED WITH 'mysql_native_password' AS '*3A2EB9C80F7239A4DE3933AE266DB76A7846BCB8''
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 12468343
              Relay_Log_Space: 10527158
              Until_Condition: None
               Until_Log_File:
                Until_Log_Pos: 0
           Master_SSL_Allowed: No
*** redacted ***
        Seconds_Behind_Master: NULL
Master_SSL_Verify_Server_Cert: No
                Last_IO_Errno: 0
                Last_IO_Error:
               Last_SQL_Errno: 1064
               Last_SQL_Error: Error 'You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near 'IDENTIFIED WITH 'mysql_native_password' AS '*3A2EB9C80F7239A4DE3933AE266DB76A784' at line 1' on query. Default database: ''. Query: 'ALTER USER 'testuser'@'localhost' IDENTIFIED WITH 'mysql_native_password' AS '*3A2EB9C80F7239A4DE3933AE266DB76A7846BCB8''
  Replicate_Ignore_Server_Ids:
             Master_Server_Id: 1
                  Master_UUID: 00005723-0000-0000-0000-000000005723
             Master_Info_File: /ssd/sandboxes/msb_5_6_41/data/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: 180918 22:32:28
               Master_SSL_Crl:
           Master_SSL_Crlpath:
           Retrieved_Gtid_Set: 00005723-0000-0000-0000-000000005723:2280-8530
            Executed_Gtid_Set: 00005723-0000-0000-0000-000000005723:1-7403
                Auto_Position: 1
1 row in set (0.00 sec)
mysql> SHOW GLOBAL VARIABLES LIKE 'gtid_executed';
+---------------+---------------------------------------------+
| Variable_name | Value                                       |
+---------------+---------------------------------------------+
| gtid_executed | 00005723-0000-0000-0000-000000005723:1-7403 |
+---------------+---------------------------------------------+
1 row in set (0.00 sec)

Since the last position executed is 7403, so you'll need to create an empty transaction for the offending sequence 7404.

STOP SLAVE;
SET GTID_NEXT='00005723-0000-0000-0000-000000005723:7404';
BEGIN;
COMMIT;
SET GTID_NEXT=AUTOMATIC;
START SLAVE;

Note: If you have MTS enabled, you can also get the offending GTID coordinates from Last_SQL_Error of SHOW SLAVE STATUS\G

The next step is to find the next binary log position. The current binary log(Relay_Master_Log_File) and position(Exec_Master_Log_Pos) executed are mysql-bin.000003 and 12468343 respectively. We can again use on the master to determine the next position:

mysqlbinlog -v --base64-output=DECODE-ROWS --start-position=12468343 /ssd/sandboxes/msb_5_7_23/data/mysql-bin.000003 | head -n 30
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 12468343
#180918 22:32:19 server id 1  end_log_pos 12468408 CRC32 0x259ee085 GTIDlast_committed=7400sequence_number=7404rbr_only=no
SET @@SESSION.GTID_NEXT= '00005723-0000-0000-0000-000000005723:7404'/*!*/;
# at 12468408
#180918 22:32:19 server id 1  end_log_pos 12468591 CRC32 0xb349ad80 Querythread_id=142exec_time=0error_code=0
SET TIMESTAMP=1537281139/*!*/;
SET @@session.pseudo_thread_id=142/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1436549152/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C latin1 *//*!*/;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
ALTER USER 'testuser'@'localhost' IDENTIFIED WITH 'mysql_native_password' AS '*3A2EB9C80F7239A4DE3933AE266DB76A7846BCB8'
/*!*/;
# at 12468591
#180918 22:32:19 server id 1  end_log_pos 12468656 CRC32 0xb2019f3f GTIDlast_committed=7400sequence_number=7405rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= '00005723-0000-0000-0000-000000005723:7405'/*!*/;
# at 12468656
#180918 22:32:19 server id 1  end_log_pos 12468730 CRC32 0x76b5ea6c Querythread_id=97exec_time=0error_code=0
SET TIMESTAMP=1537281139/*!*/;
BEGIN
/*!*/;
# at 12468730
#180918 22:32:19 server id 1  end_log_pos 12468789 CRC32 0x48f0ba6d Table_map: `sbtest`.`sbtest8` mapped to number 115

The next binary log position is 36174621. To fix the slave, run:

STOP SLAVE;
CHANGE MASTER TO MASTER_LOG_FILE='mysql-bin.000003', MASTER_LOG_POS=12468591, MASTER_AUTO_POSITION=0;
START SLAVE;

Notice that I added MASTER_AUTO_POSITION=0 above to disable GTID replication for now. You can run SHOW SLAVE STATUS\G to determine that MySQL is running fine:

mysql> SHOW SLAVE STATUS\G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: 127.0.0.1
                  Master_User: repl
                  Master_Port: 5723
                Connect_Retry: 60
              Master_Log_File: mysql-bin.000003
          Read_Master_Log_Pos: 446194575
               Relay_Log_File: mysql_sandbox5641-relay-bin.000002
                Relay_Log_Pos: 12704248
        Relay_Master_Log_File: mysql-bin.000003
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
*** redacted ***
                   Last_Errno: 0
                   Last_Error:
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 25172522
              Relay_Log_Space: 433726939
              Until_Condition: None
               Until_Log_File:
                Until_Log_Pos: 0
           Master_SSL_Allowed: No
*** redacted ***
        Seconds_Behind_Master: 2018
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: 00005723-0000-0000-0000-000000005723
             Master_Info_File: /ssd/sandboxes/msb_5_6_41/data/master.info
                    SQL_Delay: 0
          SQL_Remaining_Delay: NULL
      Slave_SQL_Running_State: Reading event from the relay log
           Master_Retry_Count: 86400
*** redacted ***
           Retrieved_Gtid_Set: 00005723-0000-0000-0000-000000005723:7405-264930
            Executed_Gtid_Set: 00005723-0000-0000-0000-000000005723:1-14947
                Auto_Position: 0

Since it's running fine you can now revert back to GTID replication:

STOP SLAVE;
CHANGE MASTER TO MASTER_AUTO_POSITION=1;
START SLAVE;

Finally, to make the slave consistent with the master, execute the compatible query on the slave.

SET SESSION sql_log_bin = 0;
GRANT USAGE ON *.* TO 'testuser'@'localhost' IDENTIFIED BY 'testuser';

Summary

In this article, I've shared how to fix replication when it breaks due to an incompatible command being replicated to the slave. In fact, I've only identified ALTER USER as an incompatible command for 5.6. If there are other incompatible commands, please share them in the comment section. Thanks in advance.

Update

I filed a bug at https://bugs.mysql.com/bug.php?id=92629 to verify if the errors I've encountered here is a bug or undocumented behavior.

Replication (computing) MySQL Command (computing) Data definition language

Published at DZone with permission of Jaime Sicam, DZone MVB. See the original article here.

Opinions expressed by DZone contributors are their own.

Related

Trending