| Bug #70711 | mysqlbinlog prints invalid SQL from relay logs when GTID is enabled | ||
|---|---|---|---|
| Submitted: | 23 Oct 2013 18:21 | Modified: | 22 Apr 2015 17:06 |
| Reporter: | Yoshinori Matsunobu (OCA) | Email Updates: | |
| Status: | Closed | Impact on me: | |
| Category: | MySQL Server: Replication | Severity: | S3 (Non-critical) |
| Version: | 5.6.14 | OS: | Any |
| Assigned to: | CPU Architecture: | Any | |
[7 Feb 2014 0:29]
Ben Krug
Hello Yoshi - We are having trouble reproducing this bug. Are you able to reproduce it on Oracle MySQL 5.6?
[17 May 2014 1:00]
Bugs System
No feedback was provided for this bug for over a month, so it is being suspended automatically. If you are able to provide the information that was originally requested, please do so and change the status of the bug back to "Open".
[11 Jul 2014 7:41]
Luis Soares
Venkat was able to reproduce it. Reopening.
[22 Apr 2015 17:06]
David Moss
Thanks for your report, this has been fixed in upcoming versions and the following text has been added to the changelog: Using mysqlbinlog to replay a relay log which ended with GTID_LOG_EVENT could cause the following error: ERROR 1790 (HY000) @@SESSION.GTID_NEXT cannot be changed by a client that owns a GTID. The client owns UUID:GTID. Ownership is released on COMMIT or ROLLBACK. If a relay log rotate happens (either through a receiver thread restart or after issuing the ROTATE command) exactly after writing a GTID_LOG_EVENT, when replaying such a relay log's end ROTATE_EVENT, it was mistakenly identified as being inside a transaction, whereas the transaction was actually started after GTID_LOG_EVENT. This caused mysqlbinlog to append SET @@SESSION.GTID_NEXT='AUTOMATIC', resulting in two GTID_NEXT statements one after the other. The fix ensures that mysqlbinlog generates SET @@SESSION.GTID_NEXT='AUTOMATIC' only outside of a transaction and when there has not been a previous GTID_LOG_EVENT. Similarly, using mysqlbinlog to concatenate and replay a relay log which contained a partial GTID transaction caused the above error. A relay log can contain a partial GTID transaction when AUTO_POSITION is enabled if a receiver thread is restarted when it is in the middle of transferring a transaction from a master. On restart the slave retrieves the full transaction again. In this case, the first relay log contains a partial GTID transaction and the second relay log contains the full GTID transaction again. When using mysqlbinlog to concatenate such a relay log, the partial transaction was not being correctly detected and therefore a ROLLBACK was not being correctly generated. The fix identifies partial GTID transactions using the format description event of the second relay log, ensuring that a ROLLBACK is correctly added.
[24 Jun 2015 4:30]
Laurynas Biveinis
commit 44a901a0d5fbfa765b463ebefdad8b29b8522bc4
Author: Venkatesh Duggirala <venkatesh.duggirala@oracle.com>
Date: Thu Apr 16 11:40:48 2015 +0530
BUG#17650326 MYSQLBINLOG PRINTS INVALID SQL FROM RELAY LOGS WHEN GTID IS ENABLED
Problem (1) : Replaying a relaylog which ends with GTID_LOG_EVENT causes
error "ERROR 1790 (HY000) @@SESSION.GTID_NEXT cannot be changed by a client
that owns a GTID. The client owns <UUID:GTID> Ownership is released on
COMMIT or ROLLBACK."
Analysis: mysqlbinlog tool appends SET @@SESSION.GTID_NEXT='AUTOMATIC'
to output when it finds a rotate log event and if it is not inside
a transaction which is the right thing to do. The tool has in_transaction
flag which will be set true upon processing any transaction event.
But a GTID_LOG_EVENT is not treated as a transaction event,
hence in_transaction is false even after processing GTID_LOG_EVENT.
If a relaylog rotate happens (either through IO thread restart/ROTATE
command), exactly after writing GTID_LOG_EVENT and if we are replaying such a
relaylog's end ROTATE_EVENT, logic was mistakenly thinking that it was not
inside a transaction but actually the transaction was started after
GTID_LOG_EVENT. Hence tool generates SET @@SESSION.GTID_NEXT='AUTOMATIC'.
This issue resulted in having two GTID_NEXT statements next to each other and
replaying such output against 'mysql' client tool was causing above specified
error (ERROR:1790).
Fix: One way to fix this issue is to set in_transaction flag to true when it
encounters GTID_LOG_EVENT. But this change will disturb DDL transaction
detection logic (mysqlbinlog tool logic assumes that DDL transactions will
have only one event per transaction). So instead of disturbing that logic,
we have followed another approach to solve the issue. 'mysqlbinlog' tool
generates "SET @@SESSION.GTID_NEXT='AUTOMATIC'" only when in_transaction
is false and is_gtid_next_valid is false (which represents that we are
not in transaction and did not even see GTID_LOG_EVENT.
Problem (2): 'ROLLBACK' is not getting generated by mysqlbinlog tool
when concatenating and replaying two consecutive relaylogs
(the first relaylog contains partial transaction and second relaylog
contains full transaction again).
Analysis: If IO thread is restarted when it is in the middle of
transferring a tranasction from Master then it will retrieve the
full transaction again upon restart. In that case, the first relaylog
contains partial GTID transaction and the second relaylog will
contain full GTID transaction again. If mysqlbinlog tool is used
to merge such two relaylogs it should generate a 'ROLLBACK' statement
after partial transaction. Otherwise it will cause above said error
(ERROR:1790).
Fix: If IO thread is restarted, the new generated relaylog will have
FD event received from Master and will have log_pos greater than zero
if the AUTO_POSITION is true i.e., this will indicate that if we
were in transaction in first relaylog, Master would have sent the
transaction again from the beginning. In this case, upon reading such
a FD event, generate 'ROLLBACK' statement in generated output. If
we have seen only GTID_LOG_EVENT of the transaction and not seen
'BEGIN' statement, then generate BEGIN and ROLLBACK statements
in generated output.
Description: Relay log file may end with GTID_NEXT event + non-fake ROTATE event. In that case, mysqlbinlog prints SQL statements that cause errors. Example: --- # at 7946 #131022 22:57:03 server id 1 end_log_pos 808603 CRC32 0x188a6963 Query thread_id=13 exec_time=0 error_code=0 SET TIMESTAMP=1382507823/*!*/; BEGIN /*!*/; # at 8025 #131022 22:57:03 server id 1 end_log_pos 808725 CRC32 0x4f970c04 Query thread_id=13 exec_time=0 error_code=0 SET TIMESTAMP=1382507823/*!*/; INSERT INTO t1 VALUES('2881', '2881', 'aaaaaaa') /*!*/; # at 8147 #131022 22:57:03 server id 1 end_log_pos 808756 CRC32 0x28efbe9f Xid = 3290 COMMIT/*!*/; # at 8178 #131022 22:57:03 server id 1 end_log_pos 808804 CRC32 0x7a330c09 GTID [commit=yes] SET @@SESSION.GTID_NEXT= 'df58b62b-3ba7-11e3-87dd-78e3b50880fc:2898'/*!*/; SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/; --- The last two consecutive SET statements can not be executed. ---- ERROR 1790 (HY000) @@SESSION.GTID_NEXT cannot be changed by a client that owns a GTID. The client owns df58b62b-3ba7-11e3-87dd-78e3b50880fc:1028. Ownership is released on COMMIT or ROLLBACK. ---- How to repeat: Set smaller binlog size (i.e. set global max_binlog_size=8192), setup master/slave replication, run io thread only (or set relay_log_purge=0 so that relay logs are not removed), run many update statements on master (many relay log files are generated), run mysqlbinlog on some relay log files. Suggested fix: In mysqlbinlog.cc, ------ case ROTATE_EVENT: { Rotate_log_event *rev= (Rotate_log_event *) ev; /* no transaction context, gtids seen and not a fake rotate */ if (seen_gtids) { /* Fake rotate events have 'when' set to zero. @c fake_rotate_event(...). */ bool is_fake= (rev->when.tv_sec == 0); if (!in_transaction && !is_fake) { /* If processing multiple files, we must reset this flag, since there may be no gtids on the next one. */ seen_gtids= false; fprintf(result_file, "SET @@SESSION.GTID_NEXT= 'AUTOMATIC' " "/* added by mysqlbinlog */ %s\n", print_event_info->delimiter); } } ------ If binlog(relaylog) ends with GTID event, in_transaction is false so SET @@SESSION.GTID_NEXT= 'AUTOMATIC' is added. This has to be avoided.