Bug #76887 mysqlbinlog generates 'ROLLBACK' after FD event causing 1782 error
Submitted: 29 Apr 2015 13:28 Modified: 15 Sep 2015 10:34
Reporter: Venkatesh Duggirala Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Replication Severity:S2 (Serious)
Version:5.7 OS:Any
Assigned to: CPU Architecture:Any

[29 Apr 2015 13:28] Venkatesh Duggirala
Description:
mysqlbinlog is generating a ROLLBACK (in gtid terms, anonymous event) after 'FD' event.
 
In some particular case (not debugged much), applying the fd event is leaving gtid_next in "not_yet_determined" state.

After this, executing rollback causes the following error 

ERROR 1782 (HY000) at line 28: @@SESSION.GTID_NEXT cannot be set to ANONYMOUS when @@GLOBAL.GTID_MODE = ON.

Relaylog is generated when gtid mode is ON and relaylog is getting applied when relay log is ON.
There should not be any anonymous transactions.

How to repeat:
Please execute the following test (bug.test) with gtid mode on and observe the error.

======================= bug.test ========================

--source include/master-slave.inc

--connection slave
--let MYSQLD_DATADIR=`select @@datadir`
--let $relay_file1 = query_get_value( SHOW SLAVE STATUS, Relay_Log_File, 1 )
--exec $MYSQL_BINLOG --force-if-open $MYSQLD_DATADIR/$relay_file1 | $MYSQL -uroot -S$SLAVE_MYSOCK

--source include/rpl_end.inc

======================= bug.test ========================

Output: 

==============================================================================

TEST                                      RESULT   TIME (ms) or COMMENT
--------------------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 301, with reserved ports 13010..13019
rpl.rpl_gtid_replay_relaylog 'mix'       [ fail ]
        Test ended at 2015-04-29 18:36:00

CURRENT_TEST: rpl.rpl_gtid_replay_relaylog
ERROR 1782 (HY000) at line 28: @@SESSION.GTID_NEXT cannot be set to ANONYMOUS when @@GLOBAL.GTID_MODE = ON.
mysqltest: At line 6: command "$MYSQL_BINLOG --force-if-open $MYSQLD_DATADIR/$relay_file1 | $MYSQL -uroot -S$SLAVE_MYSOCK" failed

Suggested fix:

When I discussed with Sven, he says 
(04:21:30  IST) sven.sandberg: venkat: i can think of two solutions then:
1. mysqlbinlog should write ROLLBACK before fd_event.
2. don't call gtid_reacquire_ownership_if_anonymous for ROLLBACK.
i'm not sure about the exact consequences of either of these approaches, but off the top of my head i think both might work.
we have a few special cases too much already in the code, so if #1 is feasible that may be preferred
[15 Sep 2015 10:34] Jon Stephens
Documented fix in the 5.7.9 changelog as follows:

    mysqlbinlog printed a ROLLBACK at the end of the binary log
    file, which when played back caused the error
    -@@SESSION.GTID_NEXT cannot be set to ANONYMOUS when
    @@GLOBAL.GTID_MODE = ON.- This occurred when the binary log file
    did not include any data related events, or when the relay log
    file included a Format_description_log_event from the master
    that had been generated at server startup.

    The fix for this issue causes a relay log's
    Format_description_log_event to do nothing if it is applied by a
    BINLOG statement, and stops a ROLLBACK from setting gtid_next to
    ANONYMOUS when gtid_next has not yet been determined by a
    subsequent event.

Closed.
[16 Mar 2017 10:58] kfpanda kf
I found that this bug in 5.7.17 version still exist.
This occurred when the binary log file did not include any data related events.
 

#  mysqlbinlog mysql-bin.000044|mysql -uroot -p'123456' 
mysql: [Warning] Using a password on the command line interface can be insecure.
ERROR 1782 (HY000) at line 19: @@SESSION.GTID_NEXT cannot be set to ANONYMOUS when @@GLOBAL.GTID_MODE = ON.
 
 
 [Ruby@rds-0314-MySQL-1-1 data]# mysqlbinlog mysql-bin.000044
/*!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
#170316  6:37:43 server id 1  end_log_pos 123 CRC32 0x05a6a067 	Start: binlog v 4, server v 5.7.17-log created 170316  6:37:43
BINLOG '
tzLKWA8BAAAAdwAAAHsAAAAAAAQANS43LjE3LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAXwAEGggAAAAICAgCAAAACgoKKioAEjQA
AWegpgU=
'/*!*/;
# at 123
#170316  6:37:43 server id 1  end_log_pos 154 CRC32 0xcf1e1690 	Previous-GTIDs
# [empty]
# at 154
#170316  6:42:41 server id 1  end_log_pos 201 CRC32 0x3e145a4c 	Rotate to mysql-bin.000045  pos: 4
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;