Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-606

LP:860910 - SHOW SLAVE STATUS gives wrong output with master-master and using SET uservars

    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

        Attachments

          Activity

            People

            • Assignee:
              Unassigned
              Reporter:
              kennygryp Kenny Gryp (Inactive)
            • Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: