Details
Description
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
I also reported this @ bugs.mysql.com: http://bugs.mysql.com/bug.php?id=62557