Monday, July 6, 2020

Tech Notes:- Got fatal error 1236 from master when reading data from binary log: 'Cannot replicate anonymous transaction when AUTO_POSITION = 1


 Last_IO_Errno: 1236
                Last_IO_Error: Got fatal error 1236 from master when reading data from binary log: 'Cannot replicate anonymous transaction when AUTO_POSITION = 1, at file ../binlogs/mysql-bin.000006, position 194.; the first event '' at 4, the last event read from '../binlogs/mysql-bin.000006' at 259, the last byte read from '../binlogs/mysql-bin.000006' at 259.'
               Last_SQL_Errno: 1396
 Master_UUID: ab7c6739-be64-11ea-b478-080027fd2c56
Retrieved_Gtid_Set: ab7c6739-be64-11ea-b478-080027fd2c56:1-29
            Executed_Gtid_Set: 846dc749-bf34-11ea-852d-08002749f9b4:1-1032,
ab7c6739-be64-11ea-b478-080027fd2c56:1-4:30-114202

On master check the binary log 'mysql-bin.000006' at position 194

mysql> show binlog events in 'mysql-bin.000006' from 4 limit 5;
+------------------+-----+----------------+-----------+-------------+---------------------------------------------------------------------------------------------------------------+
| Log_name         | Pos | Event_type     | Server_id | End_log_pos | Info                                                                                                          |
+------------------+-----+----------------+-----------+-------------+---------------------------------------------------------------------------------------------------------------+
| mysql-bin.000006 |   4 | Format_desc    |        55 |         123 | Server ver: 5.7.30-33-log, Binlog ver: 4                                                                      |
| mysql-bin.000006 | 123 | Previous_gtids |        55 |         194 | ab7c6739-be64-11ea-b478-080027fd2c56:1-29                                                                                                    |

+------------------+-----+----------------+-----------+-------------+---------------------------------------------------------------------------------------------------------------+
The solution is to skip the transactions associated with GTID ab7c6739-be64-11ea-b478-080027fd2c56:1-29 
after making sure that this has been replicated already if not, we need to find and apply the transactions manually.

SET GTID_NEXT='ab7c6739-be64-11ea-b478-080027fd2c56:1';
BEGIN;COMMIT;
SET GTID_NEXT='ab7c6739-be64-11ea-b478-080027fd2c56:2';
BEGIN;COMMIT;
SET GTID_NEXT='ab7c6739-be64-11ea-b478-080027fd2c56:3';
BEGIN;COMMIT;
SET GTID_NEXT='ab7c6739-be64-11ea-b478-080027fd2c56:4';
BEGIN;COMMIT;
SET GTID_NEXT='ab7c6739-be64-11ea-b478-080027fd2c56:5';
BEGIN;COMMIT;
SET GTID_NEXT='ab7c6739-be64-11ea-b478-080027fd2c56:6';
BEGIN;COMMIT;
SET GTID_NEXT='ab7c6739-be64-11ea-b478-080027fd2c56:7';
BEGIN;COMMIT;
SET GTID_NEXT='ab7c6739-be64-11ea-b478-080027fd2c56:8';
BEGIN;COMMIT;
SET GTID_NEXT='ab7c6739-be64-11ea-b478-080027fd2c56:9';
BEGIN;COMMIT;
SET GTID_NEXT='ab7c6739-be64-11ea-b478-080027fd2c56:10';
BEGIN;COMMIT;
SET GTID_NEXT='ab7c6739-be64-11ea-b478-080027fd2c56:11';
BEGIN;COMMIT;
SET GTID_NEXT='ab7c6739-be64-11ea-b478-080027fd2c56:12';
BEGIN;COMMIT;
SET GTID_NEXT='ab7c6739-be64-11ea-b478-080027fd2c56:13';
BEGIN;COMMIT;
SET GTID_NEXT='ab7c6739-be64-11ea-b478-080027fd2c56:14';
BEGIN;COMMIT;
SET GTID_NEXT='ab7c6739-be64-11ea-b478-080027fd2c56:15';
BEGIN;COMMIT;
SET GTID_NEXT='ab7c6739-be64-11ea-b478-080027fd2c56:16';
BEGIN;COMMIT;
SET GTID_NEXT='ab7c6739-be64-11ea-b478-080027fd2c56:17';
BEGIN;COMMIT;
SET GTID_NEXT='ab7c6739-be64-11ea-b478-080027fd2c56:18';
BEGIN;COMMIT;
SET GTID_NEXT='ab7c6739-be64-11ea-b478-080027fd2c56:19';
BEGIN;COMMIT;
SET GTID_NEXT='ab7c6739-be64-11ea-b478-080027fd2c56:20';
BEGIN;COMMIT;
SET GTID_NEXT='ab7c6739-be64-11ea-b478-080027fd2c56:21';
BEGIN;COMMIT;
SET GTID_NEXT='ab7c6739-be64-11ea-b478-080027fd2c56:22';
BEGIN;COMMIT;
SET GTID_NEXT='ab7c6739-be64-11ea-b478-080027fd2c56:23';
BEGIN;COMMIT;
SET GTID_NEXT='ab7c6739-be64-11ea-b478-080027fd2c56:24';
BEGIN;COMMIT;
SET GTID_NEXT='ab7c6739-be64-11ea-b478-080027fd2c56:25';
BEGIN;COMMIT;
SET GTID_NEXT='ab7c6739-be64-11ea-b478-080027fd2c56:26';
BEGIN;COMMIT;
SET GTID_NEXT='ab7c6739-be64-11ea-b478-080027fd2c56:27';
BEGIN;COMMIT;
SET GTID_NEXT='ab7c6739-be64-11ea-b478-080027fd2c56:28';
BEGIN;COMMIT;
SET GTID_NEXT='ab7c6739-be64-11ea-b478-080027fd2c56:29';
BEGIN;COMMIT;
SET GTID_NEXT='AUTOMATIC';

A script may be programmed to generate the above statements
Now we should be able to start the slave
start slave;

Tech Notes:- Enabling back GTID based replication on-line on a server which was started with GTID mode on , did some transactions and then switched it to GTID mode off

This is a special scenario were two  MySQL 5.7 servers were started with GTID_MODE=ON, executed some transactions like creating users and granting privileges, and then the GTID_MODE was switched off on both.

Now we want to configure these servers as master-slave, enable the traditional method of replication and then later switch to GTID based replication.

Here are the challenges.

1. We already created some transactions(creating users) on the master which means we have some GTID based transactions already logged in the binary logs as you can see below from the master binary logs
mysql> show binary logs;
+------------------+-----------+
| Log_name         | File_size |
+------------------+-----------+
| mysql-bin.000001 |       177 |
| mysql-bin.000002 |      1037 |
| mysql-bin.000003 |      6798 |
| mysql-bin.000004 |       217 |
| mysql-bin.000005 |       217 |
| mysql-bin.000006 |       825 |
| mysql-bin.000007 |       217 |
| mysql-bin.000008 |       378 |
| mysql-bin.000009 |  11592653 |
| mysql-bin.000010 |  36338956 |
| mysql-bin.000011 |  68473681 |
| mysql-bin.000012 | 198652424 |
+------------------+-----------+
12 rows in set (0.04 sec)

mysql> show binlog events in 'mysql-bin.000001';
+------------------+-----+----------------+-----------+-------------+------------------------------------------+
| Log_name         | Pos | Event_type     | Server_id | End_log_pos | Info                                     |
+------------------+-----+----------------+-----------+-------------+------------------------------------------+
| mysql-bin.000001 |   4 | Format_desc    |        55 |         123 | Server ver: 5.7.30-33-log, Binlog ver: 4 |
| mysql-bin.000001 | 123 | Previous_gtids |        55 |         154 |                                          |
| mysql-bin.000001 | 154 | Stop           |        55 |         177 |                                          |
+------------------+-----+----------------+-----------+-------------+------------------------------------------+
3 rows in set (0.02 sec)

mysql> show binlog events in 'mysql-bin.000002';
+------------------+------+----------------+-----------+-------------+-------------------------------------------------------------------+
| Log_name         | Pos  | Event_type     | Server_id | End_log_pos | Info                                                              |
+------------------+------+----------------+-----------+-------------+-------------------------------------------------------------------+
| mysql-bin.000002 |    4 | Format_desc    |        55 |         123 | Server ver: 5.7.30-33-log, Binlog ver: 4                          |
| mysql-bin.000002 |  123 | Previous_gtids |        55 |         154 |                                                                   |
| mysql-bin.000002 |  154 | Gtid           |        55 |         219 | SET @@SESSION.GTID_NEXT= 'ab7c6739-be64-11ea-b478-080027fd2c56:1' |
| mysql-bin.000002 |  219 | Query          |        55 |         287 | BEGIN                                                             |
| mysql-bin.000002 |  287 | Table_map      |        55 |         459 | table_id: 99 (mysql.user)                                         |
| mysql-bin.000002 |  459 | Update_rows    |        55 |         793 | table_id: 99 flags: STMT_END_F                                    |
| mysql-bin.000002 |  793 | Query          |        55 |         862 | COMMIT                                                            |
| mysql-bin.000002 |  862 | Gtid           |        55 |         927 | SET @@SESSION.GTID_NEXT= 'ab7c6739-be64-11ea-b478-080027fd2c56:2' |
| mysql-bin.000002 |  927 | Query          |        55 |        1014 | FLUSH PRIVILEGES                                                  |
| mysql-bin.000002 | 1014 | Stop           |        55 |        1037 |                                                                   |
+------------------+------+----------------+-----------+-------------+-------------------------------------------------------------------+
10 rows in set (0.00 sec)

mysql> show binlog events in 'mysql-bin.000003';
+------------------+------+----------------+-----------+-------------+--------------------------------------------------------------------------------------------------------------------------------------------------------+
| Log_name         | Pos  | Event_type     | Server_id | End_log_pos | Info                                                                                                                                                   |
+------------------+------+----------------+-----------+-------------+--------------------------------------------------------------------------------------------------------------------------------------------------------+
| mysql-bin.000003 |    4 | Format_desc    |        55 |         123 | Server ver: 5.7.30-33-log, Binlog ver: 4                                                                                                               |
| mysql-bin.000003 |  123 | Previous_gtids |        55 |         194 | ab7c6739-be64-11ea-b478-080027fd2c56:1-2                                                                                                               |
| mysql-bin.000003 |  194 | Gtid           |        55 |         259 | SET @@SESSION.GTID_NEXT= 'ab7c6739-be64-11ea-b478-080027fd2c56:3'                                                                                      |
| mysql-bin.000003 |  259 | Query          |        55 |         464 | CREATE USER 'slave'@'db-%.example.com' IDENTIFIED WITH 'mysql_native_password' AS '*B60C3C82CCEBA73F2BDC69601B65DFBAB435A2DA'                 |
| mysql-bin.000003 |  464 | Gtid           |        55 |         529 | SET @@SESSION.GTID_NEXT= 'ab7c6739-be64-11ea-b478-080027fd2c56:4'                                                                                      |
| mysql-bin.000003 |  529 | Query          |        55 |         685 | GRANT REPLICATION SLAVE ON *.* TO 'slave'@'db-%.example.com'                                                                                  |

2. After we switched the GTID mode to off, we have anonymous transactions in the binlogs on master

mysql> show binlog events in 'mysql-bin.000006';
+------------------+-----+----------------+-----------+-------------+---------------------------------------------------------------------------------------------------------------+
| Log_name         | Pos | Event_type     | Server_id | End_log_pos | Info                                                                                                          |
+------------------+-----+----------------+-----------+-------------+---------------------------------------------------------------------------------------------------------------+
| mysql-bin.000006 |   4 | Format_desc    |        55 |         123 | Server ver: 5.7.30-33-log, Binlog ver: 4                                                                      |
| mysql-bin.000006 | 123 | Previous_gtids |        55 |         194 | ab7c6739-be64-11ea-b478-080027fd2c56:1-29                                                                     |
| mysql-bin.000006 | 194 | Anonymous_Gtid |        55 |         259 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS'                                                                          |
| mysql-bin.000006 | 259 | Query          |        55 |         444 | CREATE USER 'repl'@'%' IDENTIFIED WITH 'mysql_native_password' AS '*0E840B1E4D3B2DDE222EA13524CA92099785A3E4' |
| mysql-bin.000006 | 444 | Anonymous_Gtid |        55 |         509 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS'                                                                          |
| mysql-bin.000006 | 509 | Query          |        55 |         645 | GRANT REPLICATION SLAVE ON *.* TO 'repl'@'%'                                                                  |
| mysql-bin.000006 | 645 | Anonymous_Gtid |        55 |         710 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS'                                                                          |
| mysql-bin.000006 | 710 | Query          |        55 |         802 | flush privileges                                                                                              |
| mysql-bin.000006 | 802 | Stop           |        55 |         825 |    
                                                                                                           |
+------------------+-----+----------------+-----------+-------------+---------------------------------------------------------------------------------------------------------------+
9 rows in set (0.00 sec)

3. At this point, we are adding a slave which will connect and replicate using the traditional approach (MASTER_AUTO_POSITION = 0)

4. Now on both master and slave, we enable GTID mode
mysql> show slave status\G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: db-55.example.com
                  Master_User: repl
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File: mysql-bin.000011
          Read_Master_Log_Pos: 16689209
               Relay_Log_File: mysqld-relay-bin.000001
                Relay_Log_Pos: 4
        Relay_Master_Log_File: mysql-bin.000011
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
Please note that the slave is now at mysql-bin.000011

5.Switch the method of replication to use GTID(MASTER_AUTO_POSITION = 1)
At this stage, we get an error in the slave
 Last_IO_Errno: 1236
                Last_IO_Error: Got fatal error 1236 from master when reading data from binary log: 'Cannot replicate anonymous transaction when AUTO_POSITION = 1, at file ../binlogs/mysql-bin.000006, position 194.; the first event '' at 4, the last event read from '../binlogs/mysql-bin.000006' at 259, the last byte read from '../binlogs/mysql-bin.000006' at 259.'
               Last_SQL_Errno: 1396
               Last_SQL_Error: Error 'Operation CREATE USER failed for 'test@'127.0.0.1'' on query. Default database: ''. Query: 'CREATE USER 'test'@'127.0.0.1' IDENTIFIED WITH 'mysql_native_password' AS '*47FFA1D679CD8C02395ED76C3640A48AA3C3411C''
The reason for this error is that when we tried to switch to GTID based replication, the slave started reading all the binlogs and started with the transactions from binlogs which were already replicated using the traditional method(note that the slave was at mysql-bin.000011 before switching.

Now, how do we fix this?

First find out the UUID of the master by issuing the below command on the master which should match the master UUID in show slave status
mysql> show variables like '%uuid%';
+---------------+--------------------------------------+
| Variable_name | Value                                |
+---------------+--------------------------------------+
| server_uuid   | ab7c6739-be64-11ea-b478-080027fd2c56 |
+---------------+--------------------------------------+
1 row in set (0.01 sec)

Now, look at the show slave status
mysql> show slave status\G
*************************** 1. row ***************************
               Slave_IO_State:
                  Master_Host: db-55.example.com
                  Master_User: repl
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File: mysql-bin.000006
          Read_Master_Log_Pos: 194
               Relay_Log_File: mysqld-relay-bin.000003
                Relay_Log_Pos: 898
        Relay_Master_Log_File: mysql-bin.000003
             Slave_IO_Running: No
            Slave_SQL_Running: No
              Replicate_Do_DB:
          Replicate_Ignore_DB: mysql,information_schema
           Replicate_Do_Table:
       Replicate_Ignore_Table:
      Replicate_Wild_Do_Table:
  Replicate_Wild_Ignore_Table:
                   Last_Errno: 1396
                   Last_Error: Error 'Operation CREATE USER failed for 'test'@'127.0.0.1'' on query. Default database: ''. Query: 'CREATE USER 'test'@'127.0.0.1' IDENTIFIED WITH 'mysql_native_password' AS '*47FFA1D679CD8C02395ED76C3640A48AA3C3411C''
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 685
              Relay_Log_Space: 9652
              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: 1236
                Last_IO_Error: Got fatal error 1236 from master when reading data from binary log: 'Cannot replicate anonymous transaction when AUTO_POSITION = 1, at file ../binlogs/mysql-bin.000006, position 194.; the first event '' at 4, the last event read from '../binlogs/mysql-bin.000006' at 259, the last byte read from '../binlogs/mysql-bin.000006' at 259.'
               Last_SQL_Errno: 1396
               Last_SQL_Error: Error 'Operation CREATE USER failed for 'test@'127.0.0.1'' on query. Default database: ''. Query: 'CREATE USER 'test'@'127.0.0.1' IDENTIFIED WITH 'mysql_native_password' AS '*47FFA1D679CD8C02395ED76C3640A48AA3C3411C''
  Replicate_Ignore_Server_Ids:
             Master_Server_Id: 55
                  Master_UUID: ab7c6739-be64-11ea-b478-080027fd2c56
             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: 200706 13:19:15
     Last_SQL_Error_Timestamp: 200706 13:19:15
               Master_SSL_Crl:
           Master_SSL_Crlpath:
           Retrieved_Gtid_Set: ab7c6739-be64-11ea-b478-080027fd2c56:1-29
            Executed_Gtid_Set: 846dc749-bf34-11ea-852d-08002749f9b4:1-29, 
ab7c6739-be64-11ea-b478-080027fd2c56:1-4:30-53010
                Auto_Position: 1
         Replicate_Rewrite_DB:
                 Channel_Name:
           Master_TLS_Version:
1 row in set (0.00 sec)


mysql> show master status;
+------------------+----------+--------------+--------------------------+----------------------------------------------------------------------------------------------+
| File             | Position | Binlog_Do_DB | Binlog_Ignore_DB         | Executed_Gtid_Set                                                                            |
+------------------+----------+--------------+--------------------------+----------------------------------------------------------------------------------------------+
| mysql-bin.000010 |  2060774 |              | mysql,information_schema | 846dc749-bf34-11ea-852d-08002749f9b4:1-29,
ab7c6739-be64-11ea-b478-080027fd2c56:1-4:30-53010 |
+------------------+----------+--------------+--------------------------+----------------------------------------------------------------------------------------------+
1 row in set (0.00 sec)

Here 846dc749-bf34-11ea-852d-08002749f9b4:1-29 --> Last slave GTID executed
           ab7c6739-be64-11ea-b478-080027fd2c56:1-4:30-53010 --> Last GTID executed on master

In order to fix the problem, we need to mark these as purged in slave.so that the slave continues with the next set of GTIDs. On slave run the below commands.

Please note that running reset master on slave would also delete all binary log files listed in the index file, resets the binary log index file to be empty, and creates a new binary log file.

mysql> reset master;
Query OK, 0 rows affected (0.01 sec)

mysql> set global GTID_PURGED='846dc749-bf34-11ea-852d-08002749f9b4:1-29,ab7c6739-be64-11ea-b478-080027fd2c56:1-53010';
Query OK, 0 rows affected (0.01 sec)

mysql> start slave;
Query OK, 0 rows affected (0.00 sec)

mysql> show slave status\G
*************************** 1. row ***************************
               Slave_IO_State: Queueing master event to the relay log
                  Master_Host: db-55.example.com
                  Master_User: repl
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File: mysql-bin.000011
          Read_Master_Log_Pos: 17944864
               Relay_Log_File: mysqld-relay-bin.000007
                Relay_Log_Pos: 781024
        Relay_Master_Log_File: mysql-bin.000011
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
              Replicate_Do_DB:
          Replicate_Ignore_DB: mysql,information_schema
           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: 17469779
              Relay_Log_Space: 1256570
              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: 955
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: 55
                  Master_UUID: ab7c6739-be64-11ea-b478-080027fd2c56
             Master_Info_File: mysql.slave_master_info
                    SQL_Delay: 0
          SQL_Remaining_Delay: NULL
      Slave_SQL_Running_State: System lock
           Master_Retry_Count: 86400
                  Master_Bind:
      Last_IO_Error_Timestamp:
     Last_SQL_Error_Timestamp:
               Master_SSL_Crl:
           Master_SSL_Crlpath:
           Retrieved_Gtid_Set: ab7c6739-be64-11ea-b478-080027fd2c56:1-29:53011-56993
            Executed_Gtid_Set: 846dc749-bf34-11ea-852d-08002749f9b4:1-29,
ab7c6739-be64-11ea-b478-080027fd2c56:1-55487
                Auto_Position: 1
         Replicate_Rewrite_DB:
                 Channel_Name:
           Master_TLS_Version:
1 row in set (0.00 sec)

Related Posts Plugin for WordPress, Blogger...