Bug #71695 Concatenation of mysqlbinlog output does not work with GTID
Submitted: 13 Feb 2014 1:09 Modified: 8 Jul 2014 10:13
Reporter: Sadao Hiratsuka Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Replication Severity:S3 (Non-critical)
Version:5.6.16, 5.6.17 OS:Any
Assigned to: CPU Architecture:Any
Tags: mysqlbinlog

[13 Feb 2014 1:09] Sadao Hiratsuka
Description:
Concatenation of mysqlbinlog output does not work with GTID.

7.5. Point-in-Time (Incremental) Recovery Using the Binary Log
https://dev.mysql.com/doc/refman/5.6/en/point-in-time-recovery.html

shell> mysqlbinlog binlog.000001 >  /tmp/statements.sql
shell> mysqlbinlog binlog.000002 >> /tmp/statements.sql
shell> mysql -u root -p -e "source /tmp/statements.sql"

ERROR 1837 (HY000) at line 1989402: When @@SESSION.GTID_NEXT is set to a GTID,
you must explicitly set it to a different value after a COMMIT or ROLLBACK.
Please check GTID_NEXT variable manual page for detailed explanation.
Current @@SESSION.GTID_NEXT is 'e47797d2-8fac-11e3-abbd-525400184ffd:17797'.

How to repeat:
Here is a sample binlog dump.

# at 125293193
#140207 17:13:48 server id 15  end_log_pos 125293241 CRC32 0xccbea9fd   GTID [commit=yes]
SET @@SESSION.GTID_NEXT= 'e47797d2-8fac-11e3-abbd-525400184ffd:17797'/*!*/;
# at 125293241
#140207 17:13:48 server id 15  end_log_pos 125293315 CRC32 0x96252f37   Query   thread_id=13    exec_time=0     error_code=0
SET TIMESTAMP=1391760828/*!*/;
BEGIN
/*!*/;
...
# at 125304764
#140207 17:13:48 server id 15  end_log_pos 125304795 CRC32 0x0c4fcd72   Xid = 872585
COMMIT/*!*/;
# at 125304795
#140207 17:20:52 server id 15  end_log_pos 125304818 CRC32 0x38c1943f   Stop
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!32316 SET SQL_LOG_BIN=@OLD_SQL_LOG_BIN*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

********** File Boundary **********

/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!32316 SET @OLD_SQL_LOG_BIN=@@SQL_LOG_BIN, SQL_LOG_BIN=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#140207 17:20:55 server id 15  end_log_pos 120 CRC32 0x6df9dce9         Start: binlog v 4, server v 5.6.15-log created 140207 17:20:55 at startup
ROLLBACK/*!*/;
BINLOG '
Z5f0Ug8PAAAAdAAAAHgAAAAAAAQANS42LjE1LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAABnl/RSEzgNAAgAEgAEBAQEEgAAXAAEGggAAAAICAgCAAAACgoKGRkAAenc
+W0=
'/*!*/;

Suggested fix:
I think --skip-gtids is necessary.

shell> mysqlbinlog --skip-gtids binlog.000001 >  /tmp/statements.sql
shell> mysqlbinlog --skip-gtids binlog.000002 >> /tmp/statements.sql
shell> mysql -u root -p -e "source /tmp/statements.sql"
[17 Feb 2014 9:29] MySQL Verification Team
Hello Sadao,

Thank you for the bug report.
Verified as described.

Thanks,
Umesh
[17 Feb 2014 18:52] Jon Stephens
Thank you for your bug report. This issue has been addressed in the documentation. The updated documentation will appear on our website shortly, and will be included in the next release of the relevant products.

Fixed in mysqldoc rev 37744.

Closed.
[16 Mar 2014 6:27] Yoshinori Matsunobu
My understanding is this issue happens only when any binlog files except the latest one was not closed properly (mysqld crash&restart). When binlog file is closed properly, "SET @@SESSION.GTID_NEXT= 'AUTOMATIC'" is added to the end of the file output, so GTID error doesn't happen.
Though I think the issue rarely happens, it should be addressed somehow, not by --skip-gtids.
[10 Jun 2014 13:17] MySQL Verification Team
## How to repeat(baby steps)
## Version used MySQL version 5.6.17
## Start MySQLD by (pls change values as per your environment)

bin/mysqld_safe --defaults-file=./master.cnf --basedir=/data/ushastry/server/mysql-5.6.17/ --datadir=/tmp/master  --skip-name-resolve --port=3306 --server-id=1 --gtid_mode=ON --log-bin=master-bin --log-slave-updates --enforce-gtid-consistency  --socket=/tmp/master/mysqld.sock  --tmpdir=/tmp/master --user=root &

// Schema to create

create database if not exists test;
use test;
drop table if exists keyvalue;
CREATE TABLE `keyvalue` (
  `id` bigint(20) unsigned NOT NULL AUTO_INCREMENT,
  `name` varchar(250),
  PRIMARY KEY (`id`)
) ENGINE=innodb;

delimiter //
CREATE PROCEDURE insertD() 
     BEGIN
		
	set @id:=0;

   REPEAT
 	insert into test.`keyvalue` values (@id:=@id+1,md5(rand()*1000000)),(@id:=@id+1,md5(rand()*1000000)),(@id:=@id+1,md5(rand()*1000000)),(@id:=@id+1,md5(rand()*1000000));
        SET @id = @id + 1;
   UNTIL @id > 5000 END REPEAT;
    

     END//
delimiter ;

// before calling sp, note down mysqld pid(process id), and in another session prepare to kill it on will kill -9 <pid> <pid>

[root@cluster-repo mysql-5.6.17]# ps aux|grep mysqld
root     11082  0.0  0.0 106232  1400 pts/5    S    09:04   0:00 /bin/sh bin/mysqld_safe --defaults-file=./master.cnf --basedir=/data/ushastry/server/mysql-5.6.17/ --datadir=/tmp/master --skip-name-resolve --port=3306 --server-id=1 --gtid_mode=ON --log-bin=master-bin --log-slave-updates --enforce-gtid-consistency --socket=/tmp/master/mysqld.sock --tmpdir=/tmp/master --user=root
root     11464  0.6  7.3 1036200 450692 pts/5  Sl   09:04   0:01 /data/ushastry/server/mysql-5.6.17/bin/mysqld --defaults-file=./master.cnf --basedir=/data/ushastry/server/mysql-5.6.17/ --datadir=/tmp/master --plugin-dir=/data/ushastry/server/mysql-5.6.17//lib/plugin --user=root --skip-name-resolve --server-id=1 --gtid-mode=ON --log-bin=master-bin --log-slave-updates --enforce-gtid-consistency --tmpdir=/tmp/master --log-error=/tmp/master/cluster-repo.err --pid-file=/tmp/master/mysqld.pid --socket=/tmp/master/mysqld.sock --port=3306
root     11490  0.0  0.0 200812  3200 pts/5    S+   09:05   0:00 bin/mysql -u root -p -S /tmp/master/mysqld.sock
root     11500  0.0  0.0 103252   820 pts/4    S+   09:07   0:00 grep mysqld

mysql> call insertD();

^^ When above sp is executing, kill mysqld(middle or at the end of)

[root@cluster-repo mysql-5.6.17]# kill -9 11082 11464

//Again, bring up mysqld

[root@cluster-repo mysql-5.6.17]# bin/mysqld_safe --defaults-file=./master.cnf --basedir=/data/ushastry/server/mysql-5.6.17/ --datadir=/tmp/master  --skip-name-resolve --port=3306 --server-id=1 --gtid_mode=ON --log-bin=master-bin --log-slave-updates --enforce-gtid-consistency  --socket=/tmp/master/mysqld.sock  --tmpdir=/tmp/master --user=root &
[1] 11506
[root@cluster-repo mysql-5.6.17]# 140612 09:08:57 mysqld_safe Logging to '/tmp/master/cluster-repo.err'.
140612 09:08:57 mysqld_safe Starting mysqld daemon with databases from /tmp/master

// Initial start had created 3 binlogs(master-bin.000001...master-bin.000003), later restart created master-bin.000004.
// using mysqlbinlog - concatenating and importing...

[root@cluster-repo mysql-5.6.17]# bin/mysqlbinlog /tmp/master/master-bin.000003 > /tmp/L.sql
[root@cluster-repo mysql-5.6.17]# bin/mysqlbinlog /tmp/master/master-bin.000004 >> /tmp/L.sql
[root@cluster-repo mysql-5.6.17]#  bin/mysql -u root -p -S /tmp/master/mysqld.sock test < /tmp/L.sql
Enter password:
ERROR 1837 (HY000) at line 22098: When @@SESSION.GTID_NEXT is set to a GTID, you must explicitly set it to a different value after a COMMIT or ROLLBACK. Please check GTID_NEXT variable manual page for detailed explanation. Current @@SESSION.GTID_NEXT is '76d2d95f-f1e2-11e3-ac25-00163e44510c:1004'.
[10 Jun 2014 13:32] MySQL Verification Team
// Since this is no longer doc bug, changing back to "verified" and category to replication
[8 Jul 2014 10:13] Jon Stephens
Thank you for your bug report. This issue has been committed to our source repository of that product and will be incorporated into the next release.

Documented fix as follows in the MySQL 5.6.21 and 5.7.5 changelogs:
    When mysqlbinlog processed multiple binary log files into a
    single output file, this file was not in a useful state for
    point-in-time recovery, when it failed with the error, "When
    @@SESSION.GTID_NEXT is set to a GTID, you must explicitly set it
    to a different value after a COMMIT or ROLLBACK. Please check
    GTID_NEXT variable manual page for detailed explanation. Current
    @@SESSION.GTID_NEXT is 'xyz'". When mysqlbinlog processes a
    binary log containing GTIDs, it outputs SET gtid_next
    statements, but gtid_next is set to undefined whenever a commit
    occurs; this left gtid_next undefined when the server had
    finished processing the output from mysqlbinlog. When the next
    binary log file started with one or more anonymous statements or
    transactions, the combination of gtid_next being left undefined
    at the end of the first binary log and the second binary log
    containing anonymous transactions to the error described
    previously (Error 1837, ER_GTID_NEXT_TYPE_UNDEFINED_GROUP).
    
    To fix this issue, now, whenever mysqlbinlog encounters this
    situation, it inserts SET gtid_next = AUTOMATIC if required to
    avoid leaving the previous binary log with gtid_next undefined.

    In addition, as a result of this fix, mysqlbinlog no longer
    outputs session variable information for every binary log; now,
    this value is printed only once, unless it changes.

Closed.

If necessary, you can access the source repository and build the latest available version, including the bug fix. More information about accessing the source trees is available at

    http://dev.mysql.com/doc/en/installing-source.html
[15 Jul 2014 2:44] Venkatesh Duggirala
Here is a preview of the patch. Feel free to give it a spin and let us know if you find any issues in your environment.

Attachment: patch_for_bug_18258933.diff (text/x-patch), 42.24 KiB.

[25 Sep 2014 11:34] Laurynas Biveinis
revno: 6053
committer: Venkatesh Duggirala<venkatesh.duggirala@oracle.com>
branch nick: mysql-5.6
timestamp: Tue 2014-07-01 17:18:58 +0530
message:
    Bug#18258933 CONCATENATION OF MYSQLBINLOG OUTPUT DOES NOT
                 WORK WITH GTID
  
    Problem:  When mysqlbinlog processes and concatenates
    multiple binary log files into one output file, this
    output file is not in useful state. When it is later
    used for point-in-time recovery, it is producing
    ER_GTID_NEXT_TYPE_UNDEFINED_GROUP "ERROR 1837: When
    @@SESSION.GTID_NEXT is set to a GTID, you must explicitly
    set it to a different value after a COMMIT or ROLLBACK.
    Please check GTID_NEXT variable manual page for detailed
    explanation. Current @@SESSION.GTID_NEXT is 'xyz'".
  
    Analysis: When mysqlbinlog processes a GTID enabled
    binary log, it outputs SET GTID_NEXT statements. As
    GTID_NEXT is set to 'undefined' when a transaction
    commits (or DDL commits implicitly), this will leave
    GTID_NEXT as 'undefined' when the server has processed
    all output from mysqlbinlog. Also, there can be some
    anonymous statements/transactions at the beginning of
    binary log (i.e., without SET GTID_NEXT statements).   
    When mysqlbinlog processes and concatenates two (or more)
    binary log files into one output file, the combination
    (GTID_NEXT is undefined at the end of first binary log
    and second binary log can contain anonymous transactions)
    will not work and will result in ERROR 1837
    (ER_GTID_NEXT_TYPE_UNDEFINED_GROUP).
   
    Fix: When mysqlbinlog processes second binary log's
         start_log_event, it can output
         "SET GTID_NEXT=AUTOMATIC" if required i.e., if
         previous binary log is leaving the GTID_NEXT state
         in 'undefined' state. In the old code (before this
         patch), when mysqlbinlog processes multiple binary
         log files from multiple command line arguments, it
         used a new PRINT_EVENT_INFO object for each file,
         so the state at the end of the previous file is lost.
         To solve this problem, this patch changes the logic
         to use the same PRINT_EVENT_INFO structure for all
         command line arguments. And to keep track of
         gtid_next state, we are introducing
         is_gtid_next_valid and is_gtid_next_set variables.
         At the beginning of mysqlbinlog process
         is_gtid_next_set is set to false and
         is_gtid_next_valid is set to true.
         When mysqlbinlog encounters a
           i) GTID_LOG_EVENT: it sets is_gtid_next_set to
                              true and is_gtid_next_valid to
                              true.
          ii) XID_LOG_EVENT
               /end_group() : it sets is_gtid_next_valid to
                              false if is_gtid_next_set to
                              true.
         And when mysqlbinlog is processing start_log_event,
         if it finds gtid_next is not valid (i.e., undefined)
         then it produces "SET GTID_NEXT=AUTOMATIC" in the
         output file to avoid mentioned
         ER_GTID_NEXT_TYPE_UNDEFINED_GROUP error and it resets
         is_gtid_next_set to false and is_gtid_next_valid to
         true (the initial values). mysqlbinlog also produces
         'SET GTID_NEXT=AUTOMATIC' in the output file at the
         end of processing all the command line arguments if
         it finds GTID_NEXT is in invalid state.
  
         After this patch, if you are merging two or more
         binary log files, you will see two differences in
         the output when compared to the before the patch
  
         a) When mysqlbinlog start processing the second
            binary log file, if required (i.e., if the 
            previous binary log left gtid_next in a invalid
            state), it generates SET GTID_NEXT=AUTOMATIC.
         b) Before the patch, mysqlbinlog outputs session
            variable information for every binary log.
            Now that we will have only one print_event_info
            per run, this session variables value will be
            printed only once *unless there is a change*.
            Example of session variables:
              SET @@session.pseudo_thread_id=999999999/*!*/;
              SET @@session.foreign_key_checks=1
              SET @@session.sql_mode=1073741824/*!*/;
              SET @@session.auto_increment_increment=1,
              SET @@session.auto_increment_offset=1/*!*/;
              SET @@session.lc_time_names=0/*!*/;
              SET @@session.collation_database=DEFAULT/*!*/;