MySQL Bugs: #36541: Query event with BEGIN has different size on master and slave

Bug #36541	Query event with BEGIN has different size on master and slave
Submitted:	6 May 2008 17:01	Modified:	3 Dec 2010 10:25
Reporter:	Sascha Curth	Email Updates:
Status:	In progress	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S2 (Serious)
Version:	5.0.51a-log, 5.1	OS:	Linux
Assigned to:	Assigned Account	CPU Architecture:	Any
Tags:	regression

Description:
The binlog contents of replication slave are not the same as on the Master if transactions are used.

How to repeat:
Setup MySQL Replication. 

CREATE TABLE `testtable` (
  `col` int(11) default NULL
) ENGINE=InnoDB DEFAULT CHARSET=latin1

Synchronise Binlogfilename and Position of Master and Slave.

On slave:
show master status\G
*************************** 1. row ***************************
            File: master-bin.000007
        Position: 882344
    Binlog_Do_DB: 
Binlog_Ignore_DB: 

On Master:
show master status; 
*************************** 1. row ***************************
            File: master-bin.000007
        Position: 11244
    Binlog_Do_DB: 
Binlog_Ignore_DB: 

On Slave:
stop slave sql_thread;
start slave sql_thread until master_log_file='master-bin.000008', master_log_pos=98

On Master:
flush logs;

On Slave:
wait until replication has finished
flush logs; start slave;

Master and Slave are now writing to a binlog with the same filename and the statements are written at the same binlog position. 

Open a mysql connection on the Master:
mysql> set autocommit =0;
Query OK, 0 rows affected (0.00 sec)
mysql> use test
Database changed
mysql> insert into test.testtable set col=5;
Query OK, 1 row affected (0.00 sec)
mysql> commit;
show binlog events in 'master-bin.000009';
+-------------------+-----+-------------+-----------+-------------+--------------------------------------------------+
| Log_name          | Pos | Event_type  | Server_id | End_log_pos | Info                                             |
+-------------------+-----+-------------+-----------+-------------+--------------------------------------------------+
| master-bin.000009 |   4 | Format_desc | 738854184 |          98 | Server ver: 5.0.51a-log, Binlog ver: 4           | 
| master-bin.000009 |  98 | Query       | 738854184 |         166 | use `test`; BEGIN                                | 
| master-bin.000009 | 166 | Query       | 738854184 |         265 | use `test`; insert into test.testtable set col=5 | 
| master-bin.000009 | 265 | Xid         | 738854184 |         292 | COMMIT /* xid=99 */                              | 
+-------------------+-----+-------------+-----------+-------------+--------------------------------------------------+

On the slave:
mysql>show binlog events in 'master-bin.000009';
+-------------------+-----+-------------+-----------+-------------+--------------------------------------------------+
| Log_name          | Pos | Event_type  | Server_id | End_log_pos | Info                                             |
+-------------------+-----+-------------+-----------+-------------+--------------------------------------------------+
| master-bin.000009 |   4 | Format_desc | 738854440 |          98 | Server ver: 5.0.51a-log, Binlog ver: 4           | 
| master-bin.000009 |  98 | Query       | 738854184 |         157 | BEGIN                                            | 
| master-bin.000009 | 157 | Query       | 738854184 |         256 | use `test`; insert into test.testtable set col=5 | 
| master-bin.000009 | 256 | Xid         | 738854184 |         283 | COMMIT /* xid=89 */                              | 
+-------------------+-----+-------------+-----------+-------------+--------------------------------------------------+

On the Master an additional "use" will be written in front  of the "BEGIN" statement, although this "use" will be written to the transaction statement itself.

Even if no "use database" will be invoked, the binlog positions are not equal. 

(First synchronise binlogs)
Master:
mysql> set autocommit =0;
Query OK, 0 rows affected (0.00 sec)
mysql> insert into test.testtable set col=5;
Query OK, 1 row affected (0.00 sec)
mysql> commit;
Query OK, 0 rows affected (0.06 sec)
mysql> show binlog events in 'master-bin.000010';
+-------------------+-----+-------------+-----------+-------------+----------------------------------------+
| Log_name          | Pos | Event_type  | Server_id | End_log_pos | Info                                   |
+-------------------+-----+-------------+-----------+-------------+----------------------------------------+
| master-bin.000010 |   4 | Format_desc | 738854184 |          98 | Server ver: 5.0.51a-log, Binlog ver: 4 | 
| master-bin.000010 |  98 | Query       | 738854184 |         162 | BEGIN                                  | 
| master-bin.000010 | 162 | Query       | 738854184 |         257 | insert into test.testtable set col=5   | 
| master-bin.000010 | 257 | Xid         | 738854184 |         284 | COMMIT /* xid=109 */                   | 
+-------------------+-----+-------------+-----------+-------------+----------------------------------------+

Slave:
mysql>  show binlog events in 'master-bin.000010';
+-------------------+-----+-------------+-----------+-------------+----------------------------------------+
| Log_name          | Pos | Event_type  | Server_id | End_log_pos | Info                                   |
+-------------------+-----+-------------+-----------+-------------+----------------------------------------+
| master-bin.000010 |   4 | Format_desc | 738854440 |          98 | Server ver: 5.0.51a-log, Binlog ver: 4 | 
| master-bin.000010 |  98 | Query       | 738854184 |         157 | BEGIN                                  | 
| master-bin.000010 | 157 | Query       | 738854184 |         252 | insert into test.testtable set col=5   | 
| master-bin.000010 | 252 | Xid         | 738854184 |         279 | COMMIT /* xid=104 */                   | 
+-------------------+-----+-------------+-----------+-------------+----------------------------------------+

This does not happen if no transaction will be used:

Master:
mysql> insert into test.testtable set col=5;
Query OK, 1 row affected (0.08 sec)
mysql> show binlog events in 'master-bin.000011';
+-------------------+-----+-------------+-----------+-------------+----------------------------------------+
| Log_name          | Pos | Event_type  | Server_id | End_log_pos | Info                                   |
+-------------------+-----+-------------+-----------+-------------+----------------------------------------+
| master-bin.000011 |   4 | Format_desc | 738854184 |          98 | Server ver: 5.0.51a-log, Binlog ver: 4 | 
| master-bin.000011 |  98 | Query       | 738854184 |         193 | insert into test.testtable set col=5   | 
| master-bin.000011 | 193 | Xid         | 738854184 |         220 | COMMIT /* xid=115 */                   | 
+-------------------+-----+-------------+-----------+-------------+----------------------------------------+

Slave:
show binlog events in 'master-bin.000011';
+-------------------+-----+-------------+-----------+-------------+----------------------------------------+
| Log_name          | Pos | Event_type  | Server_id | End_log_pos | Info                                   |
+-------------------+-----+-------------+-----------+-------------+----------------------------------------+
| master-bin.000011 |   4 | Format_desc | 738854440 |          98 | Server ver: 5.0.51a-log, Binlog ver: 4 | 
| master-bin.000011 |  98 | Query       | 738854184 |         193 | insert into test.testtable set col=5   | 
| master-bin.000011 | 193 | Xid         | 738854184 |         220 | COMMIT /* xid=116 */                   | 
+-------------------+-----+-------------+-----------+-------------+----------------------------------------+

Resolution of this bug is very important for us, since we have a setup where we have several replication slaves replicating from a master and a secondary master, which is actually a slave with log_slave_updates option set.
This setup is very convenient for fast failover between masters, provided that the binary logs on both masters stay in sync.

In our setup, we let our slaves replicate from a virtual IP, which is normally active on primary master. Our application writes to master through another virtual IP configured on primary master.
Then, when we do a failover, we first just move the replication virtual IP from primary to secondary master, effectively letting the slaves reconnect and just go on replicating. After that we switch the application virtual IP to secondary master, effectively making the secondary primary.
During the fail over, it is necessary that the masters replicate from each other and have both the log-slave-updates option set. Since a mysql slave will never execute events, that its own server-id tagged to it. This is no problem.
The application will never write to both masters at the same time, since the virtual IP can only be active on one of them.

Now, when we do not use transactions (keeping the default autocommit=1), there is no problem, since the binary logs of both masters stay in sync.

However, when we want to use transactions, the slave appears to write not exactly the same information to the binary log as the master did. This is very well illustrated in the bug description.

There are two reasons to why the BEGIN event is longer on the master than on the slave:

1. The database is replicated as part of the event even
   though the LOG_EVENT_SUPPRESS_USE_F is set.

2. The catalog is set to "std" on the master, but when
   replicated to the slave, the BEGIN statement is created
   at the time of the COMMIT of the entire transaction. At
   this point, the catalog set by the BEGIN event was cleared
   as part of the end-of-event cleanup.

Note that this has nothing to do with the "use" statement printed in the informational field in the SHOW BINLOG EVENTS output, which is not part of the replicated query. Rather, the database is stored in a separate field in the event.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/123725

3501 Mats Kindahl	2010-11-12
      Bug #36541: Master/Slave binlogs out of sync
      
      The master and slave binary logs go out of
      sync because the BEGIN event generated on the
      master when writing a transaction to the 
      binary log contain a database and a catalog,
      while the event on the slave does not (because
      the slave thread resets these).
      
      This patch fixes the issue by:
      - Not writing the database in the event when
        LOG_EVENT_SUPPRESS_USE_F is set, which is
        set for the generated BEGIN.
      - Setting the catalog to "std" for the
        generated BEGIN since the THD constructor
        sets the catalog to "std".
      
      The patch also makes "catalog" be a pointer
      to "const char*" be const-correct.

The added patch is a proposal for a solution.

It eliminates the database from the generated BEGIN query event and adds a catalog to the slave event explicitly.

Alternatives would be to eliminate both the database and the catalog from the BEGIN query event on the master instead.

E/R values are set for fixing this particular problem: ensuring that BEGIN events are identical on master and slave, not for the general problem of keeping positions identical on master and slave.