crash-safe slaves: relay_log_recovery breaks replication

[Matthew Kent]

Per

https://www.percona.com/blog/2013/09/13/enabling-crash-safe-slaves-with-mysql-5-6/
http://dev.mysql.com/doc/refman/5.6/en/slave-logs.html

I've configured our PXC cluster with:

relay_log_info_repository = TABLE
master_info_repository = TABLE
relay_log_recovery = 1

to increase our resiliency to a crash during replication.

Currently we have one cluster node replicating from a standalone vanilla percona db master. The cluster is read_only.

Replication works fine initially, but if I do a normal shutdown of the cluster node, I get some weird errors on startup about the log configuration, and some noise from WSREP:

<snip>
2015-09-10 16:25:41 101751 [Note] InnoDB: 128 rollback segment(s) are active.
2015-09-10 16:25:41 101751 [Note] InnoDB: Waiting for purge to start
2015-09-10 16:25:41 101751 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.24-72.2 started; log sequence number 6476752566
2015-09-10 16:25:41 7ee225f80700 InnoDB: Loading buffer pool(s) from /u/mysql/a/data/ib_buffer_pool
2015-09-10 16:25:41 101751 [Note] RSA private key file not found: /u/mysql/a/data//private_key.pem. Some authentication plugins will not work.
2015-09-10 16:25:41 101751 [Note] RSA public key file not found: /u/mysql/a/data//public_key.pem. Some authentication plugins will not work.
2015-09-10 16:25:41 101751 [Note] Server hostname (bind-address): '*'; port: 3330
2015-09-10 16:25:41 101751 [Note] IPv6 is available.
2015-09-10 16:25:41 101751 [Note] - '::' resolves to '::';
2015-09-10 16:25:41 101751 [Note] Server socket created on IP: '::'.
2015-09-10 16:25:41 101751 [Warning] Neither --relay-log nor --relay-log-index were used; so replication may break when this MySQL server acts as a slave and has his hostname changed!! Please use '--relay-log=mysql-relay-bin' to avoid this problem.
2015-09-10 16:25:41 101751 [Warning] Recovery from master pos 168358716 and file binlog.000002.
2015-09-10 16:25:41 101751 [Warning] WSREP: unsupported key version: -1 (FATAL)
  at galera/src/key_os.hpp:KeyOS():140
2015-09-10 16:25:41 101751 [Warning] WSREP: Appending row key failed: void, 6
2015-09-10 16:25:41 101751 [ERROR] Error writing relay log configuration.
2015-09-10 16:25:41 101751 [ERROR] Error reading relay log configuration.
2015-09-10 16:25:41 101751 [ERROR] Failed to initialize the master info structure
2015-09-10 16:25:41 101751 [Note] Check error log for additional messages. You will not be able to start replication until the issue is resolved and the server restarted.
2015-09-10 16:25:41 101751 [Note] Event Scheduler: Loaded 0 events
2015-09-10 16:25:41 101751 [Note] WSREP: Initialized wsrep sidno 3
2015-09-10 16:25:41 101751 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2015-09-10 16:25:41 101751 [Note] WSREP: REPL Protocols: 7 (3, 2)
2015-09-10 16:25:41 101751 [Note] WSREP: Service thread queue flushed.
2015-09-10 16:25:41 101751 [Note] WSREP: Assign initial position for certification: 370, protocol version: 3
2015-09-10 16:25:41 101751 [Note] WSREP: Service thread queue flushed.
2015-09-10 16:25:41 101751 [Note] WSREP: Synchronized with group, ready for connections
2015-09-10 16:25:41 101751 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2015-09-10 16:25:41 101751 [Note] /u/mysql/server/5.6.24-72.2-percona-xtradb-cluster/bin/mysqld: ready for connections.
Version: '5.6.24-72.2-25.11-log' socket: '/tmp/mysql.a.sock' port: 3330 Percona XtraDB Cluster binary (GPL) 5.6.24-25.11, Revision, wsrep_25.11
2015-09-10 16:25:50 7ee225f80700 InnoDB: Buffer pool(s) load completed at 150910 16:25:50

and as expected the slave won't start:

MySQL [a_production]> start slave;
ERROR 1872 (HY000): Slave failed to initialize relay log info structure from the repository

But if I shut it down and set relay_log_recovery=0, we get a normal startup:

<snip>
2015-09-10 16:28:04 104263 [Note] InnoDB: 128 rollback segment(s) are active.
2015-09-10 16:28:04 104263 [Note] InnoDB: Waiting for purge to start
2015-09-10 16:28:04 104263 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.24-72.2 started; log sequence number 6476757221
2015-09-10 16:28:04 7f2cb9f80700 InnoDB: Loading buffer pool(s) from /u/mysql/a/data/ib_buffer_pool
2015-09-10 16:28:04 104263 [Note] RSA private key file not found: /u/mysql/a/data//private_key.pem. Some authentication plugins will not work.
2015-09-10 16:28:04 104263 [Note] RSA public key file not found: /u/mysql/a/data//public_key.pem. Some authentication plugins will not work.
2015-09-10 16:28:04 104263 [Note] Server hostname (bind-address): '*'; port: 3330
2015-09-10 16:28:04 104263 [Note] IPv6 is available.
2015-09-10 16:28:04 104263 [Note] - '::' resolves to '::';
2015-09-10 16:28:04 104263 [Note] Server socket created on IP: '::'.
2015-09-10 16:28:04 104263 [Warning] Neither --relay-log nor --relay-log-index were used; so replication may break when this MySQL server acts as a slave and has his hostname changed!! Please use '--relay-log=mysql-relay-bin' to avoid this problem.
2015-09-10 16:28:04 104263 [Note] Event Scheduler: Loaded 0 events
2015-09-10 16:28:04 104263 [Note] WSREP: Initialized wsrep sidno 3
2015-09-10 16:28:04 104263 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2015-09-10 16:28:04 104263 [Note] WSREP: REPL Protocols: 7 (3, 2)
2015-09-10 16:28:04 104263 [Note] WSREP: Service thread queue flushed.
2015-09-10 16:28:04 104263 [Note] WSREP: Assign initial position for certification: 370, protocol version: 3
2015-09-10 16:28:04 104263 [Note] WSREP: Service thread queue flushed.
2015-09-10 16:28:04 104263 [Note] WSREP: Synchronized with group, ready for connections
2015-09-10 16:28:04 104263 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2015-09-10 16:28:04 104263 [Note] /u/mysql/server/5.6.24-72.2-percona-xtradb-cluster/bin/mysqld: ready for connections.
Version: '5.6.24-72.2-25.11-log' socket: '/tmp/mysql.a.sock' port: 3330 Percona XtraDB Cluster binary (GPL) 5.6.24-25.11, Revision, wsrep_25.11
2015-09-10 16:28:13 7f2cb9f80700 InnoDB: Buffer pool(s) load completed at 150910 16:28:13
<snip>

and I'm able to start slave just fine.

[markus_albe (markus-albe)]

Verified with Server version: 5.6.26-74.0-56 Percona XtraDB Cluster (GPL), Release rel74.0, Revision 1, WSREP version 25.12, wsrep_25.12

[markus_albe (markus-albe)]

To reproduce:
1) setup two PXC nodes

2) setup regular PS node

3) make one PXC node "A" have these in the my.cnf:
relay_log_info_repository = TABLE
master_info_repository = TABLE
relay_log_recovery = 1

4) make PXC node "A" slave of regular PS node

5) stop PXC node "A" cleanly and start it again, without doing any writes on the opposite PXC node "B"

6) START SLAVE on PXC node "A"; this will fail

Previous to START SLAVE:
mysql> show slave status\G
*************************** 1. row ***************************
               Slave_IO_State:
                  Master_Host: 10.0.3.238
                  Master_User: root
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File: centos3-bin.000001
          Read_Master_Log_Pos: 320
               Relay_Log_File: centos2-relay-bin.000003
                Relay_Log_Pos: 4
        Relay_Master_Log_File: centos3-bin.000001
             Slave_IO_Running: No
            Slave_SQL_Running: No
              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: 320
              Relay_Log_Space: 0
              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: NULL
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: 0
                  Master_UUID: 7e721d54-9a43-11e5-bb73-fe75f703db01
             Master_Info_File: mysql.slave_master_info
                    SQL_Delay: 0
          SQL_Remaining_Delay: NULL
      Slave_SQL_Running_State:
           Master_Retry_Count: 86400
                  Master_Bind:
      Last_IO_Error_Timestamp:
     Last_SQL_Error_Timestamp:
               Master_SSL_Crl:
           Master_SSL_Crlpath:
           Retrieved_Gtid_Set:
            Executed_Gtid_Set:
                Auto_Position: 0
1 row in set (0.00 sec)

But in the relay log info table there's a different value:
mysql> select * from slave_relay_log_info;
+-----------------+----------------------------+---------------+--------------------+----------------+-----------+-------------------+----+
| Number_of_lines | Relay_log_name | Relay_log_pos | Master_log_name | Master_log_pos | Sql_delay | Number_of_workers | Id |
+-----------------+----------------------------+---------------+--------------------+----------------+-----------+-------------------+----+
| 7 | ./centos2-relay-bin.000002 | 485 | centos3-bin.000001 | 320 | 0 | 0 | 1 |
+-----------------+----------------------------+---------------+--------------------+--...

[markus_albe (markus-albe)]

And in the error log we see it's actually trying to use centos2-relay-bin.000001, so seems to be totally wrong:

2015-12-04 00:12:59 29053 [Note] InnoDB: Using atomics to ref count buffer pool pages
2015-12-04 00:12:59 29053 [Note] InnoDB: The InnoDB memory heap is disabled
2015-12-04 00:12:59 29053 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2015-12-04 00:12:59 29053 [Note] InnoDB: Memory barrier is not used
2015-12-04 00:12:59 29053 [Note] InnoDB: Compressed tables use zlib 1.2.3
2015-12-04 00:12:59 29053 [Note] InnoDB: Using Linux native AIO
2015-12-04 00:12:59 29053 [Note] InnoDB: Using CPU crc32 instructions
2015-12-04 00:12:59 29053 [Note] InnoDB: Initializing buffer pool, size = 128.0M
2015-12-04 00:12:59 29053 [Note] InnoDB: Completed initialization of buffer pool
2015-12-04 00:12:59 29053 [Note] InnoDB: Highest supported file format is Barracuda.
2015-12-04 00:12:59 29053 [Note] InnoDB: 128 rollback segment(s) are active.
2015-12-04 00:12:59 29053 [Note] InnoDB: Waiting for purge to start
2015-12-04 00:12:59 29053 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.26-74.0 started; log sequence number 1647228
2015-12-04 00:12:59 29053 [Note] RSA private key file not found: /var/lib/mysql//private_key.pem. Some authentication plugins will not work.
2015-12-04 00:12:59 29053 [Note] RSA public key file not found: /var/lib/mysql//public_key.pem. Some authentication plugins will not work.
2015-12-04 00:12:59 29053 [Note] Server hostname (bind-address): '0.0.0.0'; port: 3306
2015-12-04 00:12:59 29053 [Note] - '0.0.0.0' resolves to '0.0.0.0';
2015-12-04 00:12:59 29053 [Note] Server socket created on IP: '0.0.0.0'.
2015-12-04 00:12:59 29053 [Warning] Neither --relay-log nor --relay-log-index were used; so replication may break when this MySQL server acts as a slave and has his hostname changed!! Please use '--relay-log=centos2-relay-bin' to avoid this problem.
2015-12-04 00:12:59 29053 [Warning] Recovery from master pos 320 and file centos3-bin.000001.
2015-12-04 00:12:59 29053 [Warning] WSREP: unsupported key version: -1 (FATAL)
         at galera/src/key_os.hpp:KeyOS():140
2015-12-04 00:12:59 29053 [Warning] WSREP: Appending row key failed: void, 6
2015-12-04 00:12:59 29053 [ERROR] Error writing relay log configuration.
2015-12-04 00:12:59 29053 [ERROR] Error reading relay log configuration.
2015-12-04 00:12:59 29053 [ERROR] Failed to initialize the master info structure
2015-12-04 00:12:59 29053 [Note] Check error log for additional messages. You will not be able to start replication until the issue is resolved and the server restarted.
2015-12-04 00:12:59 29053 [Note] Event Scheduler: Loaded 0 events
2015-12-04 00:12:59 29053 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.6.26-74.0-56' socket: '/var/lib/mysql/mysql.sock' port: 3306 Percona XtraDB Cluster (GPL), Release rel74.0, Revision 1, WSREP version 25.12, wsrep_25.12

[markus_albe (markus-albe)]

Ooopps, missread "2015-12-04 00:12:59 29053 [Warning] Recovery from master pos 320 and file centos3-bin.000001." So this is correct; not sure why it fails to initialize the slave then.

[Fernando Laudares Camargos (fernando-laudares)]

A related problem - I've had relay_log_info_repository=TABLE configured on my cluster nodes, and only one of them is an async replica. However, whenever an SST ocurs in other nodes and the async replica node is chosen as donor, they'll get table mysql.slave_relay_log_info replicated as well:

Node1 (async replica):
------------------------------
mysql> select * from mysql.slave_relay_log_info\G
*************************** 1. row ***************************
  Number_of_lines: 7
   Relay_log_name: ./flc-node1-relay-bin.000004
    Relay_log_pos: 886
  Master_log_name: percona-bin.000003
   Master_log_pos: 1489
        Sql_delay: 0
Number_of_workers: 0
               Id: 1
1 row in set (0.00 sec)

Node 2 (rebuilt with SST from Node 1):
-----------------------------------------------------
mysql> select * from mysql.slave_relay_log_info\G
*************************** 1. row ***************************
  Number_of_lines: 7
   Relay_log_name: ./flc-node1-relay-bin.000004
    Relay_log_pos: 886
  Master_log_name: percona-bin.000003
   Master_log_pos: 1489
        Sql_delay: 0
Number_of_workers: 0
               Id: 1
1 row in set (0.00 sec)

However:
[root@flc-node2 mysql]# ls -l *relay*
-rw-rw----. 1 mysql mysql 143 Dec 7 18:11 flc-node2-relay-bin.000001
-rw-rw----. 1 mysql mysql 29 Dec 7 18:11 flc-node2-relay-bin.index

I guess an SST implies a "cloning" process and thus no node-specific database info are meant to survice SSTs but does the documentation states this ?

[Przemek (pmalkowski)]

Fernando, I have created new bug report to cover what you have observed with SST: lp:1523894

Let's leave this one only for the problem of relay_log_recovery = 1 causing the replication to crash.

[Krunal Bauskar (krunal-bauskar)]

I did some investigation and here are my findings:

-----------

This is bit more involved. Here is what I tried.
1. Started master node
2. Started 2 node cluster and made of the node async slave pointing to master started in STEP-1.
(Async slave has following extra configuration
relay_log_info_repository = TABLE
master_info_repository = TABLE
relay_log_recovery = 1
3. I started hitting assert when I tried to shutdown async slave for first time itself. This is bit different from scenario reported in bug TC.
(Well because I am using debug build I am hitting assert which was safely getting ignored as part of release build).
-----------

Problem-1: Assert while shutting down the async slave ?

* While turning ON SLAVE replication lot of meta-information get written to mysql.slave_master_info, mysql.slave_relay_log_info.

* These being InnoDB tables they need trx. From Galera perspective these tables are like any other normal table so galera capture any changes to these tables and register needed trx object in Galera context.

* So far so good. After the write is complete SLAVE context will close these table which in turn will commit open trx for these tables to persist the write information. This path is different from normal commit flow and it didn't had a registration of wsrep as one of the commit handler so even though trx was open in Galera context it was never committed and so during shutdown Galera check complained about open trx that are not committed.

So I got rid of this problem by adding needed check to ensure that wsrep_commit handler is called even in this SLAVE context path and with that I could reproduce the original problem described in the bug.

-----------

Problem-2: SLAVE fails to start on restarting cluster node ?

* Given that relay_log_recovery=1 restart of slave will trigger init_recovery. This function then try to advance the Relay_log_pos and accordingly persist the new value to slave_relay_log_info. This is effectively done using update_row routine.

* By the time init_recovery is called wsrep galera::ReplicatorSMM::process_conf_change that causes assignment of initial position is not yet done. In short galera is not yet ready to process the trx but update_row try to enter galera space for appending key. Of-course Galera is going to refuse it as establish_protocol_versions (protocol version is not yet established or in short galera is in half-cooked initialized state.

This eventually leads to an error and then complete action of init_recovery fails causing SLAVE to stop working.

[Krunal Bauskar (krunal-bauskar)]

commit f6f18fc39d1a9a75dde92237c42a40422e822595
Merge: 5e0c557 6e4c2d9
Author: Krunal Bauskar <email address hidden>
Date: Mon Jan 18 14:00:49 2016 +0530

    Merge pull request #78 from kbauskar/5.6-pxc-490

    - PXC#490: crash-safe slaves: relay_log_recovery breaks replication (…

commit 6e4c2d93a9edca1e196ebf49190d419117428bc8
Author: Krunal Bauskar <email address hidden>
Date: Thu Jan 14 09:58:51 2016 +0530

    - PXC#490: crash-safe slaves: relay_log_recovery breaks replication (CID#62894)

      Issue:
      ------

      Replication info table like slave_master_info, slave_relay_log_info are
      created in InnoDB to support crash-safe replication that was introduce in
      MySQL-5.6

      Being a innodb tables they default qualify for galera replication but they
      shouldn't as per the protocol as they are meant to be kept on active
      ASYNC slave only.

      MySQL flow does block bin-logging of events performed on these tables but
      WSREP replication missed blocking its replication.
      This causes start of trx in galera cluster which was not needed.

      Infact, the condition to append_key that starts trx in the galera eco-system
      was not adequated to handle case where-in bin-logging is turned-off for
      a specific flow like update performed to replication info table.

      Solution:
      ---------

      Corrected condition that trigger start of replication in galera cluster.
      If bin-logging is turned-off then we avoid starting trx in galera eco-system.

      Note: We also explicitly allows replication when binlog-format = STATEMENT.
      This is an existing semantics so nothing new here but we made is explict
      and there-by kept the hook open only for STATEMENT and not for MIXED.
      It is interesting to learn that this hook is needed only for pt-table-checksum
      to operate that unfortunately relied on so called non-supported functionality
      of PXC cluster (replication under SBR is not supported).

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PXC-1851