Bug #81660 Replication err "Cannot replicate anonymous transaction when AUTO_POSITION = 1"
Submitted: 31 May 2016 15:38
Reporter: Amit Bhansali Email Updates:
Status: Open Impact on me:
None 
Category:MySQL Server: Replication Severity:S1 (Critical)
Version:5.7.11 OS:CentOS (2.6.32-431.29.2.el6.x86_64)
Assigned to: CPU Architecture:Any
Tags: Multi channel, multi master replication

[31 May 2016 15:38] Amit Bhansali
Description:
Environment Description:

We have a DB server stack that has 2 servers in our primary data center ( in Salt lake city ) &  2 in AWS ( total 4 servers) . All of these are running Percona MySQL 5.7 .11-4  binary. We followed the documented steps for enabling gtid using http://mysqlhighavailability.com/enabling-gtids-without-downtime-in-mysql-5-7-6/ 

The stack setup looks like this:
 
 1 <--> 2 
^       ^
|       |
V       V
 3 <--> 4 

The  first machine acts as master & replicates to the three machines.  The other machines  ( slaves) are to be configured as master of other  3 machines making them as a MM in every pair. 

NOTE: We setup 2 different stacks (setup like the above diagram). The first we setup using method A, the second we setup using method B.
A)   Fresh install of Percona MySQL 5.7.11-4 & then loading of data from the MySQL dump file of version 5.5  or 5.6.x .
B)   Take a 5.6 slave xtradb backup, restore on a new machine & upgrade the box to MySQL 5.7 .

* NOTE: Problem #1 noted below is seen on  both stacks.

 
PROBLEM # 1   What is the Error Seen : 
 
On server no #3 we get the following error shown in channel #1
mysql> show slave status for channel ‘channel_name’ \G
*************************** 1. row ***************************
                     Master_Host: x.x.x.y
                   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 /data/logs/log-bin.000035, position 57764192.; the first event '' at 4, the last event read from '/data/logs/log-bin.000035' at 57764257, the last byte read from '/data/logs/log-bin.000035' at 57764257.'
               Last_SQL_Errno: 0
 
 
 
We ran the mysqlbinlog using the file name & host found on server 3  as seen in the show slave status output . This error occurs replicating from either #2 or #4.

However a deeper look shows that this txn originated on the parent server #1. ( whose server id is 1)   
 
[root@ip-10-83-205-36 data]# grep -a5 -b5 57764192 35.txt
112576719-#160520  5:45:13 server id 1  end_log_pos 57764123 CRC32 0xc7fda6f1   Query   thread_id=945041        exec_time=4294967287    error_code=0
112576845-SET TIMESTAMP=1463744713/*!*/;
112576876-DELETE FROM `database_name`.`table_name`
112576921-/*!*/;
112576928-# at 57764123
112576942:#160520  5:45:13 server id 1  end_log_pos 57764192 CRC32 0x290bde9e   Query   thread_id=945041        exec_time=4294967287    error_code=0
112577068-SET TIMESTAMP=1463744713/*!*/;
112577099-COMMIT
112577106-/*!*/;
112577113:# at 57764192
112577127-#160520  5:45:13 server id 1  (this is serverid of server #1 )  end_log_pos 57764257 CRC32 0x0e4cde04   Anonymous_GTID  last_committed=22371    sequence_number=22372
112577254-SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
112577297-# at 57764257
112577311-#160520  5:45:13 server id 1  end_log_pos 57764325 CRC32 0xd09bb41f   Query   thread_id=945041        exec_time=4294967287    error_code=0
112577437-SET TIMESTAMP=1463744713/*!*/;
 
 
Here is the error also seen in channel #2. 
*************************** 2. row ***************************
               Master_Host: x.x.x.Z
              Master_Log_File: log-bin.000012
          Read_Master_Log_Pos: 1318378
                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 /data/logs/log-bin.000012, position 1318378.; the first event '' at 4, the last event read from '/data/logs/log-bin.000012' at 1318443, the last byte read from '/data/logs/log-bin.000012' at 1318443.'
 
 
# mysqlbinlog -v --base64-output=DECODE-ROWS log-bin.000012 > /data/12.txt
# grep -a5 -b5 1318378 /data/12.txt
2542386-#160520  7:02:32 server id 1  end_log_pos 1318309 CRC32 0x1c2f9975      Query   thread_id=948879        exec_time=4294967287    error_code=0
2542511-SET TIMESTAMP=1463749352/*!*/;
2542542- DELETE FROM `database_name`.`table_name`
2542587-/*!*/;
2542594-# at 1318309
2542607:#160520  7:02:32 server id 1  end_log_pos 1318378 CRC32 0x25daeb57      Query   thread_id=948879        exec_time=4294967287    error_code=0
2542732-SET TIMESTAMP=1463749352/*!*/;
2542763-COMMIT
2542770-/*!*/;
2542777:# at 1318378
2542790-#160520  7:02:32 server id 1  end_log_pos 1318443 CRC32 0xc13be282      Anonymous_GTID  last_committed=494      sequence_number=495
2542912-SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
2542955-# at 1318443
2542968-#160520  7:02:32 server id 1  end_log_pos 1318511 CRC32 0xe0976986      Query   thread_id=948879        exec_time=4294967287    error_code=0
2543093-SET TIMESTAMP=1463749352/*!*/;
 
 
NOTE: There is no such txn that can be found in the bin log of the server having 'server-id = 1'
  
The only channel on server #3, that did not display this replication error was the channel directly to main master server #1 (having server id 1).

We aren’t sure what is causing the Anonymous_GTID statement. Replication will be running for a while without any problems and then it will just brake. We did find that on both stack’s when we saw this Anonymous_GTID statement it was proceeded by the exact same DELETE FROM `database_name`.`table_name` statement. Not sure if that has anything to do with it or not.  

 
PROBLEM # 2 
 
When we do change master  to add the second channel name  for replication the first channel name is retained & second channel name is lost 
 
mysql>  CHANGE MASTER TO MASTER_HOST='x.y.z.80', MASTER_PORT=3306,MASTER_USER='XXX', MASTER_PASSWORD='XXX', MASTER_AUTO_POSITION = 1 for channel 'aws-slave-1';
mysql>  start slave for  channel  'aws-slave-1';
show slave status \G  | grep Channel – does not 2 channel names. 
 
mysql> show slave status for channel  'aws-slave-1' \G
                 Channel_Name: slc-master-1  (This is a problem) 
 
Mysql> select * from mysql.slave_master_info \G 
~~ does not show all 3 channels. 
 

Appendix 1 :  Here is our my.cnf on the servers . 
 
## cat /etc/my.cnf

[mysqld]
datadir=/data/mysql
socket=/data/mysql/mysql.sock
user=mysql
 
#gtid settings
enforce-gtid-consistency=ON
gtid_mode=ON
 
auto-increment-offset = 1 # other servers have 2, 3, 4 
auto-increment-increment = 10
master-info-repository=TABLE
relay-log-info-repository=TABLE
server-id = 12345678  # other servers have diff server-id 
 
max_connections = 2000
key_buffer_size = 200M
low_priority_updates = 1
sort_buffer_size = 1M
read_buffer_size = 4M
table_open_cache = 80000
table_definition_cache = 40400
query_cache_size = 0
query_cache_type = 0
query_cache_limit = 1M
binlog_cache_size = 32768
thread_cache_size = 100
slow_query_log = 1
slow_query_log_file = /data/mysql-slow.log
long_query_time = 3
wait_timeout = 28800
expire_logs_days = 14
tmpdir=/data/mysqltmp
max_allowed_packet = 1073741824
skip_name_resolve = ON
 
# character sets
character_set_filesystem = binary
character_set_server = utf8mb4
 
# files
innodb_file_per_table
innodb_log_file_size = 512M
innodb_log_files_in_group = 3
innodb_open_files = 3000
 
# buffers
innodb_buffer_pool_size = 2750M
innodb_buffer_pool_instances = 2
innodb_log_buffer_size = 128M
 
# tune
innodb_checksums = 0
innodb_doublewrite = 0
innodb_support_xa = 0
innodb_thread_concurrency = 0
innodb_flush_log_at_trx_commit = 0
innodb_flush_method = O_DIRECT
innodb_max_dirty_pages_pct = 5
 
 
# disk IO
innodb_adaptive_flushing = 1
innodb_read_io_threads = 8
innodb_write_io_threads = 8
innodb_io_capacity = 2000
innodb_purge_threads = 9
 
transaction-isolation = READ-COMMITTED
port                    = 3306
old_passwords=0
replicate-same-server-id = 0
log-bin = /data/logs/log-bin
binlog-format = row
max_connect_errors = 1000
 
 
[mysqld_safe]
log-error=/var/log/mysqld.log
pid-file=/var/run/mysqld/mysqld.pid
 
[client]
socket=/data/mysql/mysql.sock
 

How to repeat:
Follow the procedure http://mysqlhighavailability.com/enabling-gtids-without-downtime-in-mysql-5-7-6/ to setup  multi master replication and let the deletes come from multiple masters. These masters have   

auto-increment-offset = 1 # other servers have 2, 3, 4 
auto-increment-increment = 10
server-id = 12345678  # other servers have diff server-id 

PROBLEM # 1   What is the Error Seen : 
 
On server no #3 we get the following error shown in channel #1
mysql> show slave status for channel ‘channel_name’ \G
*************************** 1. row ***************************
                     Master_Host: x.x.x.y
                   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 /data/logs/log-bin.000035, position 57764192.; the first event '' at 4, the last event read from '/data/logs/log-bin.000035' at 57764257, the last byte read from '/data/logs/log-bin.000035' at 57764257.'
               Last_SQL_Errno: 0
 
 
 
We ran the mysqlbinlog using the file name & host found on server 3  as seen in the show slave status output . This error occurs replicating from either #2 or #4.

However a deeper look shows that this txn originated on the parent server #1. ( whose server id is 1)   
 
[root@ip-10-83-205-36 data]# grep -a5 -b5 57764192 35.txt
112576719-#160520  5:45:13 server id 1  end_log_pos 57764123 CRC32 0xc7fda6f1   Query   thread_id=945041        exec_time=4294967287    error_code=0
112576845-SET TIMESTAMP=1463744713/*!*/;
112576876-DELETE FROM `database_name`.`table_name`
112576921-/*!*/;
112576928-# at 57764123
112576942:#160520  5:45:13 server id 1  end_log_pos 57764192 CRC32 0x290bde9e   Query   thread_id=945041        exec_time=4294967287    error_code=0
112577068-SET TIMESTAMP=1463744713/*!*/;
112577099-COMMIT
112577106-/*!*/;
112577113:# at 57764192
112577127-#160520  5:45:13 server id 1  (this is serverid of server #1 )  end_log_pos 57764257 CRC32 0x0e4cde04   Anonymous_GTID  last_committed=22371    sequence_number=22372
112577254-SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
112577297-# at 57764257
112577311-#160520  5:45:13 server id 1  end_log_pos 57764325 CRC32 0xd09bb41f   Query   thread_id=945041        exec_time=4294967287    error_code=0
112577437-SET TIMESTAMP=1463744713/*!*/;
 
 
Here is the error also seen in channel #2. 
*************************** 2. row ***************************
               Master_Host: x.x.x.Z
              Master_Log_File: log-bin.000012
          Read_Master_Log_Pos: 1318378
                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 /data/logs/log-bin.000012, position 1318378.; the first event '' at 4, the last event read from '/data/logs/log-bin.000012' at 1318443, the last byte read from '/data/logs/log-bin.000012' at 1318443.'
 
 
# mysqlbinlog -v --base64-output=DECODE-ROWS log-bin.000012 > /data/12.txt
# grep -a5 -b5 1318378 /data/12.txt
2542386-#160520  7:02:32 server id 1  end_log_pos 1318309 CRC32 0x1c2f9975      Query   thread_id=948879        exec_time=4294967287    error_code=0
2542511-SET TIMESTAMP=1463749352/*!*/;
2542542- DELETE FROM `database_name`.`table_name`
2542587-/*!*/;
2542594-# at 1318309
2542607:#160520  7:02:32 server id 1  end_log_pos 1318378 CRC32 0x25daeb57      Query   thread_id=948879        exec_time=4294967287    error_code=0
2542732-SET TIMESTAMP=1463749352/*!*/;
2542763-COMMIT
2542770-/*!*/;
2542777:# at 1318378
2542790-#160520  7:02:32 server id 1  end_log_pos 1318443 CRC32 0xc13be282      Anonymous_GTID  last_committed=494      sequence_number=495
2542912-SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
2542955-# at 1318443
2542968-#160520  7:02:32 server id 1  end_log_pos 1318511 CRC32 0xe0976986      Query   thread_id=948879        exec_time=4294967287    error_code=0
2543093-SET TIMESTAMP=1463749352/*!*/;
 
 
NOTE: There is no such txn that can be found in the bin log of the server having 'server-id = 1'
  
The only channel on server #3, that did not display this replication error was the channel directly to main master server #1 (having server id 1).

We aren’t sure what is causing the Anonymous_GTID statement. Replication will be running for a while without any problems and then it will just brake. We did find that on both stack’s when we saw this Anonymous_GTID statement it was proceeded by the exact same DELETE FROM `database_name`.`table_name` statement. Not sure if that has anything to do with it or not.  

 
PROBLEM # 2 
 
When we do change master  to add the second channel name  for replication the first channel name is retained & second channel name is lost 
 
mysql>  CHANGE MASTER TO MASTER_HOST='x.y.z.80', MASTER_PORT=3306,MASTER_USER='XXX', MASTER_PASSWORD='XXX', MASTER_AUTO_POSITION = 1 for channel 'aws-slave-1';
mysql>  start slave for  channel  'aws-slave-1';
show slave status \G  | grep Channel – does not 2 channel names. 
 
mysql> show slave status for channel  'aws-slave-1' \G
                 Channel_Name: slc-master-1  (This is a problem) 
 
Mysql> select * from mysql.slave_master_info \G 
~~ does not show all 3 channels.
[7 Sep 2018 6:47] Andrey Golodyaev
Hi.
I have the same problem.

I have a topology like this: 40 (master) -> 50 (slave) -> 51 (slave)

40: server_uuid: a716608f-b1d4-11e8-a520-005056814b41
50: server_uuid: ac3bd429-b02e-11e8-8fbb-00505681e932
51: server_uuid: c50cbcc0-b041-11e8-b0e3-005056812f16

Step to reproduse:
1) Create memory table on master server (40)
2) Stop intermediate server (50)
3) Put some data on master server (40)
4) Start intermediate server (50)
5) Replication is breaks down on slave (51) behind intermediate server (50)

binlog from server 40:
===================================================
# mysqlbinlog --verbose --base64-output=decode-rows /database-logs/bin/log-bin.000001 --start-position=154
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 154
#180906 17:54:53 server id 40  end_log_pos 219 CRC32 0x52ed3b76 	GTID	last_committed=0	sequence_number=1	rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= 'a716608f-b1d4-11e8-a520-005056814b41:1'/*!*/;
# at 219
#180906 17:54:53 server id 40  end_log_pos 296 CRC32 0x236062f0 	Query	thread_id=307	exec_time=0	error_code=0
SET TIMESTAMP=1536245693/*!*/;
SET @@session.pseudo_thread_id=307/*!*/;
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=2, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8mb4 *//*!*/;
SET @@session.character_set_client=45,@@session.collation_connection=224,@@session.collation_server=8/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
BEGIN
/*!*/;
# at 296
#180906 17:54:53 server id 40  end_log_pos 344 CRC32 0xf28bf74e 	Table_map: `test`.`test` mapped to number 128
# at 344
#180906 17:54:53 server id 40  end_log_pos 388 CRC32 0xb58c6451 	Write_rows: table id 128 flags: STMT_END_F
### INSERT INTO `test`.`test`
### SET
###   @1=1
###   @2=1
# at 388
#180906 17:54:53 server id 40  end_log_pos 466 CRC32 0x759fcf23 	Query	thread_id=307	exec_time=0	error_code=0
SET TIMESTAMP=1536245693/*!*/;
COMMIT
/*!*/;
# at 466
#180906 17:55:34 server id 40  end_log_pos 531 CRC32 0xd072313b 	GTID	last_committed=1	sequence_number=2	rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= 'a716608f-b1d4-11e8-a520-005056814b41:2'/*!*/;
# at 531
#180906 17:55:34 server id 40  end_log_pos 608 CRC32 0x0dbb7475 	Query	thread_id=337	exec_time=0	error_code=0
SET TIMESTAMP=1536245734/*!*/;
BEGIN
/*!*/;
# at 608
#180906 17:55:34 server id 40  end_log_pos 656 CRC32 0x61c5e382 	Table_map: `test`.`test` mapped to number 128
# at 656
#180906 17:55:34 server id 40  end_log_pos 700 CRC32 0xf6023bbc 	Write_rows: table id 128 flags: STMT_END_F
### INSERT INTO `test`.`test`
### SET
###   @1=3
###   @2=2
# at 700
#180906 17:55:34 server id 40  end_log_pos 778 CRC32 0x1b716386 	Query	thread_id=337	exec_time=0	error_code=0
SET TIMESTAMP=1536245734/*!*/;
COMMIT
/*!*/;
SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;
DELIMITER ;
# End of log file
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
===================================================

binlog from server 50:
===================================================
# mysqlbinlog --verbose --base64-output=decode-rows /database-logs/bin/log-bin.000002 --start-position=484
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 484
#180906 17:55:34 server id 40  end_log_pos 549 CRC32 0x11e4af3a 	Anonymous_GTID	last_committed=1	sequence_number=2	rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 549
#180906 17:55:34 server id 40  end_log_pos 617 CRC32 0x446c034c 	Query	thread_id=337	exec_time=0	error_code=0
SET TIMESTAMP=1536245734/*!*/;
SET @@session.pseudo_thread_id=337/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=524288/*!*/;
SET @@session.auto_increment_increment=2, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8mb4 *//*!*/;
SET @@session.character_set_client=45,@@session.collation_connection=224,@@session.collation_server=8/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
BEGIN
/*!*/;
# at 617
#180906 17:55:34 server id 40  end_log_pos 665 CRC32 0x69827001 	Table_map: `test`.`test` mapped to number 108
# at 665
#180906 17:55:34 server id 40  end_log_pos 709 CRC32 0x7ca358da 	Write_rows: table id 108 flags: STMT_END_F
### INSERT INTO `test`.`test`
### SET
###   @1=3
###   @2=2
# at 709
#180906 17:55:34 server id 40  end_log_pos 778 CRC32 0xcba1ef0c 	Query	thread_id=337	exec_time=0	error_code=0
SET TIMESTAMP=1536245734/*!*/;
SET @@session.sql_mode=1436549152/*!*/;
COMMIT
/*!*/;
SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;
DELIMITER ;
# End of log file
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
===================================================

Error message from server 51:
===================================================
Got fatal error 1236 from master when reading data from binary log: 'Cannot replicate anonymous transaction when AUTO_POSITION = 1, at file /database-logs/bin/log-bin.000002, position 484.; the first event '' at 4, the last event read from '/database-logs/bin/log-bin.000002' at 549, the last byte read from '/database-logs/bin/log-bin.000002' at 549.'
===================================================