MySQL Bugs: #62557: SHOW SLAVE STATUS gives wrong output with master-master and using SET uservars

Bug #62557	SHOW SLAVE STATUS gives wrong output with master-master and using SET uservars
Submitted:	27 Sep 2011 20:52	Modified:	7 Sep 2012 13:59
Reporter:	Kenny Gryp	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S2 (Serious)
Version:	5.1, 5.5	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	replication, set uservariables, show slave status

Description:
In a master-master setup, a master can show a wrong 'SHOW SLAVE STATUS' output.

Requirements:
- master-master
- log_slave_updates

This is caused when using SET user-variables. and then using it to perform writes.
From then on the master that performed the insert will have a SHOW SLAVE STATUS that is wrong and it will never update again until a write happens on the other master.

How to repeat:

### set up a masterA(serverid 1)<->masterB(serverid 2) with 2 way replication
### enable log-slave-updates on both databasegs
### execute on masterA:

create database test;
use test;
create table test3 (a int);
set @`test`:=0;
insert into test3 values (@test);

### To make it clearer, run the insert statement multiple times. You can even do any other write you want! doesn't have to be related to test or use a variable.

### run 'show master status' on masterB
masterB> show master status;
+--------------------+----------+--------------+------------------+
| File | Position | Binlog_Do_DB | Binlog_Ignore_DB |
+--------------------+----------+--------------+------------------+
| masterB .000004 | 540 | | |
+--------------------+----------+--------------+------------------+

### run 'show slave status' on masterA
masterA> SHOW SLAVE STATUS\G
*************************** 1. row ***************************
Slave_IO_State: Waiting for master to send event
Master_Host: localhost
Master_User: r
Master_Port: 3309
Connect_Retry: 60
Master_Log_File: masterB.000004
Read_Master_Log_Pos: 540
Relay_Log_File: masterA-relay.000011
Relay_Log_Pos: 255
Relay_Master_Log_File: masterB.000004
Slave_IO_Running: Yes
Slave_SQL_Running: Yes
Replicate_Do_DB:
Replicate_Ignore_DB:
Replicate_Do_Table:
Replicate_Ignore_Table:
Replicate_Wild_Do_Table:
Replicate_Wild_Ignore_Table:
Last_Errno: 0
Last_Error:
Skip_Counter: 0
Exec_Master_Log_Pos: 313
Relay_Log_Space: 606
Until_Condition: None
Until_Log_File:
Until_Log_Pos: 0
Master_SSL_Allowed: No
Master_SSL_CA_File:
Master_SSL_CA_Path:
Master_SSL_Cert:
Master_SSL_Cipher:
Master_SSL_Key:
Seconds_Behind_Master: 0
Master_SSL_Verify_Server_Cert: No
Last_IO_Errno: 0
Last_IO_Error:
Last_SQL_Errno: 0
Last_SQL_Error:
Replicate_Ignore_Server_Ids:
Master_Server_Id: 1

==> masterA displays that it's waiting for master to send events on an old exec_master_log_pos

### cat relay-log.info and master.info on masterA
Example:

$ cat masterA/master.info
18
masterB.000004
5261
localhost
r
r
3309
60

0.000

$ cat masterA/relay-log.info
./masterB-relay.000011
255
masterB.000004
313

$ stat masterA/relay-log.info
File: `2/relay-log.info'
Size: 54 Blocks: 8 IO Block: 4096 regular file
Device: 801h/2049d Inode: 796981 Links: 1
Access: (0660/-rw-rw----) Uid: ( 1000/ gryp) Gid: ( 1000/ gryp)
Access: 2011-09-27 16:59:45.863435966 +0200
Modify: 2011-09-27 16:53:06.874040990 +0200
Change: 2011-09-27 16:53:06.874040990 +0200

$ stat masterA/master.info
File: `2/master.info'
Size: 67 Blocks: 8 IO Block: 4096 regular file
Device: 801h/2049d Inode: 796979 Links: 1
Access: (0660/-rw-rw----) Uid: ( 1000/ gryp) Gid: ( 1000/ gryp)
Access: 2011-09-27 16:59:44.222616027 +0200
Modify: 2011-09-27 16:58:06.323690973 +0200
Change: 2011-09-27 16:58:06.323690973 +0200

==> masterA it's relay-log.info file is not updated anymore but master.info is.

### select * from test.test3 and you can see that all writes will be in there.

masterA> select * from test3;
+------+
| a |
+------+
| 0 |
+------+
1 row in set (0.00 sec)

### Actually the relay log should be empty as it should filter out it's own writes, but the SET commands are in there, with the masterB serverid: 1
#110927 16:53:06 server id 1 end_log_pos 418 User_var
SET @`test`:=0/*!*/;

### The binary log of masterB will contain something like this,you can see that the SET commands have changed to it's own serverid:
DROP TABLE IF EXISTS `test3` /* generated by server */
/*!*/;
# at 224
#110927 16:53:06 server id 2 end_log_pos 313 Query thread_id=3 exec_time=0 error_code=0
SET TIMESTAMP=1317135186/*!*/;
create table test3 (a int)
/*!*/;
# at 313
#110927 16:53:06 server id 2 end_log_pos 372 Query thread_id=3 exec_time=0 error_code=0
SET TIMESTAMP=1317135186/*!*/;
BEGIN
/*!*/;
# at 372
#110927 16:53:06 server id 1 end_log_pos 418 User_var
SET @`test`:=0/*!*/;
# at 418
#110927 16:53:06 server id 2 end_log_pos 513 Query thread_id=3 exec_time=0 error_code=0
SET TIMESTAMP=1317135186/*!*/;
insert into test3 values (@test)
/*!*/;
# at 513
#110927 16:53:06 server id 2 end_log_pos 540 Xid = 22
COMMIT/*!*/;
# at 540
#110927 16:57:56 server id 2 end_log_pos 599 Query thread_id=3 exec_time=0 error_code=0
SET TIMESTAMP=1317135476/*!*/;
BEGIN
/*!*/;
# at 599
#110927 16:57:56 server id 1 end_log_pos 645 User_var
SET @`test`:=0/*!*/;
# at 645
#110927 16:57:56 server id 2 end_log_pos 740 Query thread_id=3 exec_time=0 error_code=0
SET TIMESTAMP=1317135476/*!*/;
insert into test3 values (@test)
/*!*/;
# at 740
#110927 16:57:56 server id 2 end_log_pos 767 Xid = 30
COMMIT/*!*/;

I have verified this under the following mysql versions:
- mysql-5.1.59
- mysql-5.5.16
- Percona Server 5.1.57-rel12.8
- MariaDB 5.2.7
- MariaDB 5.2.8

Suggested fix:
fixit (-:

Thank you for the report.

I can not repeat described behavior with version 5.1.60. Please try with this current version and if problem still exists provide name of the package you use (filename you downloaded), full configuration files and inform us how reliable problem is (e.g. if you see it for every SET query or you have to repeat them for some time).

Sveta, I can repeat it on the current 5.1 branch from Launchpad which has 5.1.62 as its version. I'm attaching an mtr test case, you can put those files in mysql-test/suite/rpl/t/ and then run as "./mtr percona_bug860910". It passes in Percona Server, but hangs when trying to sync servers on MySQL due to corrupted Exec_Master_Log_Pos.

percona_bug860910.test

Attachment: percona_bug860910.test (application/octet-stream, text), 1.02 KiB.

percona_bug860910.cnf

Attachment: percona_bug860910.cnf (application/octet-stream, text), 80 bytes.

Thank you for the feedback.

Verified as described.

The bug of the wrong server_id in the binlog when log_slave_updates is set, is also mentioned in (closed) bug #51942 and has a patch attached to fix it.

No idea if this patch will 'automatically' fix the wrong SHOW SLAVE STATUS Exec_master_log_pos value. Maybe these are separate bugs.

The status recovers not only after a write, also after a new binlog file is started.

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.

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

Fixed in 5.1.66 and 5.5.28. (Issue does not occur in 5.6.)