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:
None 
Category:MySQL Server: Replication Severity:S3 (Non-critical)
Version:5.6.14 OS:Any
Assigned to: CPU Architecture:Any

[23 Oct 2013 18:21] Yoshinori Matsunobu
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.
[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 Manuel Oliveira 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.