| 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: | |
| 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
[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/*!*/;
