Percona XtraDB Cluster SST not working using rsync: wsrep_sst_rsync

MySQL & MariaDB Percona XtraDB Cluster 5.x
1

I originally had this written up on StackOverflow, but realised Percona forums is more appropriate. I was going through the XtraDB Cluster Tutorial I took at Percona Live London step by step, checking my understanding as I go along. I encountered an SST related issue when attempting to join a third node to a cluster.

WSREP_SST: [ERROR] find/rsync returned code 123: (20141228 02:24:40.505) 2014-12-28 02:24:40 9446 [ERROR] WSREP: Failed [COLOR=#00008B]to [COLOR=#00008B]read [COLOR=#00008B]from: wsrep_sst_rsync --role ‘donor’ --address ‘192.168.70.2:4444/rsync_sst’ --auth ‘sst:sst’ --socket 2014-12-28 02:24:24 9446 [Note] WSREP: (2861d1d7, ‘tcp://0.0.0.0:4567’) turning message relay requesting [COLOR=#00008B]on, nonlive peers: 2014-12-28 02:24:24 9446 [Note] WSREP: declaring 41f79045 at tcp://192.168.70.2:4567 stable 2014-12-28 02:24:24 9446 [Note] WSREP: Node 2861d1d7 state prim 2014-12-28 02:24:24 9446 [Note] WSREP: [COLOR=#00008B]save pc [COLOR=#00008B]into [COLOR=#00008B]disk 2014-12-28 02:24:24 9446 [Note] WSREP: New COMPONENT: [COLOR=#00008B]primary = yes, bootstrap = no, my_idx = 0, memb_num = 2 2014-12-28 02:24:24 9446 [Note] WSREP: STATE_EXCHANGE: sent state UUID: 42495aba-8e30-11e4-9596-c702faf22ad0 2014-12-28 02:24:24 9446 [Note] WSREP: STATE EXCHANGE: sent state msg: 42495aba-8e30-11e4-9596-c702faf22ad0 2014-12-28 02:24:24 9446 [Note] WSREP: STATE EXCHANGE: got state msg: 42495aba-8e30-11e4-9596-c702faf22ad0 [COLOR=#00008B]from 0 (node3) 2014-12-28 02:24:24 9446 [Note] WSREP: STATE EXCHANGE: got state msg: 42495aba-8e30-11e4-9596-c702faf22ad0 [COLOR=#00008B]from 1 (node2) 2014-12-28 02:24:24 9446 [Note] WSREP: Quorum results: version = 3, component = [COLOR=#00008B]PRIMARY, conf_id = 1, members = 1/2 (joined/total), act_id = 0, last_appl. = 0, protocols = 0/6/3 (gcs/repl/appl), [COLOR=#00008B]group UUID = 48ec9889-8ddc-11e4-9efd-da6610fd24da 2014-12-28 02:24:24 9446 [Note] WSREP: Flow-control interval: [23, 23] 2014-12-28 02:24:24 9446 [Note] WSREP: New cluster [COLOR=#00008B]view: global state: 48ec9889-8ddc-11e4-9efd-da6610fd24da:0, [COLOR=#00008B]view# 2: [COLOR=#00008B]Primary, number [COLOR=#00008B]of nodes: 2, my [COLOR=#00008B]index: 0, protocol version 3 2014-12-28 02:24:24 9446 [Note] WSREP: wsrep_notify_cmd [COLOR=#00008B]is [COLOR=#00008B]not defined, skipping notification. 2014-12-28 02:24:24 9446 [Note] WSREP: REPL Protocols: 6 (3, 2) 2014-12-28 02:24:24 9446 [Note] WSREP: Service thread queue flushed. 2014-12-28 02:24:24 9446 [Note] WSREP: Assign initial position [COLOR=#00008B]for certification: 0, protocol version: 3 2014-12-28 02:24:24 9446 [Note] WSREP: Service thread queue flushed. 2014-12-28 02:24:25 9446 [Note] WSREP: Member 1.0 (node2) requested state transfer [COLOR=#00008B]from ‘any’. Selected 0.0 (node3)(SYNCED) [COLOR=#00008B]as donor. 2014-12-28 02:24:25 9446 [Note] WSREP: Shifting SYNCED → DONOR/DESYNCED ([COLOR=#00008B]TO: 0) 2014-12-28 02:24:25 9446 [Note] WSREP: wsrep_notify_cmd [COLOR=#00008B]is [COLOR=#00008B]not defined, skipping notification. 2014-12-28 02:24:25 9446 [Note] WSREP: Running: ‘wsrep_sst_rsync --role ‘donor’ --address ‘192.168.70.2:4444/rsync_sst’ --auth ‘sst:sst’ --socket ‘/var/lib/mysql/mysql.sock’ --datadir ‘/var/lib/mysql/’ --defaults-file ‘/etc/my.cnf’ --binlog ‘mysql-bin’ --gtid ‘48ec9889-8ddc-11e4-9efd-da6610fd24da:0’’ 2014-12-28 02:24:25 9446 [Note] WSREP: sst_donor_thread signaled [COLOR=#00008B]with 0 2014-12-28 02:24:25 9446 [Note] WSREP: Flushing tables [COLOR=#00008B]for SST… 2014-12-28 02:24:25 9446 [Note] WSREP: Provider paused at 48ec9889-8ddc-11e4-9efd-da6610fd24da:0 (5) 2014-12-28 02:24:25 9446 [Note] WSREP: Tables flushed. WSREP_SST: [INFO] Preparing binlog files [COLOR=#00008B]for transfer: (20141228 02:24:26.201) mysql-bin.000015 2014-12-28 02:24:27 9446 [Note] WSREP: (2861d1d7, ‘tcp://0.0.0.0:4567’) turning message relay requesting [COLOR=#00008B]off rsync: send_files failed [COLOR=#00008B]to [COLOR=#00008B]open “/var/lib/mysql/sbtest/sbtest1.ibd”: Permission denied (13) rsync: send_files failed [COLOR=#00008B]to [COLOR=#00008B]open “/var/lib/mysql/sbtest/sbtest2.ibd”: Permission denied (13) rsync: send_files failed [COLOR=#00008B]to [COLOR=#00008B]open “/var/lib/mysql/sbtest/sbtest3.ibd”: Permission denied (13) rsync: send_files failed [COLOR=#00008B]to [COLOR=#00008B]open “/var/lib/mysql/sbtest/sbtest4.ibd”: Permission denied (13) rsync: send_files failed [COLOR=#00008B]to [COLOR=#00008B]open “/var/lib/mysql/sbtest/sbtest5.ibd”: Permission denied (13) rsync: send_files failed [COLOR=#00008B]to [COLOR=#00008B]open “/var/lib/mysql/sbtest/sbtest6.ibd”: Permission denied (13) rsync: send_files failed [COLOR=#00008B]to [COLOR=#00008B]open “/var/lib/mysql/sbtest/sbtest7.ibd”: Permission denied (13) rsync: send_files failed [COLOR=#00008B]to [COLOR=#00008B]open “/var/lib/mysql/sbtest/sbtest8.ibd”: Permission denied (13) rsync error: [COLOR=#00008B]some files/attrs were [COLOR=#00008B]not transferred (see previous errors) (code 23) at main.c(1039) [sender=3.0.6] rsync: send_files failed [COLOR=#00008B]to [COLOR=#00008B]open “/var/lib/mysql/mysql/innodb_index_stats.ibd”: Permission denied (13) rsync: send_files failed [COLOR=#00008B]to [COLOR=#00008B]open “/var/lib/mysql/mysql/innodb_table_stats.ibd”: Permission denied (13) rsync: send_files failed [COLOR=#00008B]to [COLOR=#00008B]open “/var/lib/mysql/mysql/slave_master_info.ibd”: Permission denied (13) rsync: send_files failed [COLOR=#00008B]to [COLOR=#00008B]open “/var/lib/mysql/mysql/slave_relay_log_info.ibd”: Permission denied (13) rsync: send_files failed [COLOR=#00008B]to [COLOR=#00008B]open “/var/lib/mysql/mysql/slave_worker_info.ibd”: Permission denied (13) rsync error: [COLOR=#00008B]some files/attrs were [COLOR=#00008B]not transferred (see previous errors) (code 23) at main.c(1039) [sender=3.0.6] WSREP_SST: [ERROR] find/rsync returned code 123: (20141228 02:24:40.505) 2014-12-28 02:24:40 9446 [ERROR] WSREP: Failed [COLOR=#00008B]to [COLOR=#00008B]read [COLOR=#00008B]from: wsrep_sst_rsync --role ‘donor’ --address ‘192.168.70.2:4444/rsync_sst’ --auth ‘sst:sst’ --socket ‘/var/lib/mysql/mysql.sock’ --datadir ‘/var/lib/mysql/’ --defaults-file ‘/etc/my.cnf’ --binlog ‘mysql-bin’ --gtid ‘48ec9889-8ddc-11e4-9efd-da6610fd24da:0’ 2014-12-28 02:24:40 9446 [ERROR] WSREP: Process completed [COLOR=#00008B]with error: wsrep_sst_rsync --role ‘donor’ --address ‘192.168.70.2:4444/rsync_sst’ --auth ‘sst:sst’ --socket ‘/var/lib/mysql/mysql.sock’ --datadir ‘/var/lib/mysql/’ --defaults-file ‘/etc/my.cnf’ --binlog ‘mysql-bin’ --gtid ‘48ec9889-8ddc-11e4-9efd-da6610fd24da:0’: 255 (Unknown error 255) 2014-12-28 02:24:40 9446 [Note] WSREP: resuming provider at 5 2014-12-28 02:24:40 9446 [Note] WSREP: Provider resumed. 2014-12-28 02:24:40 9446 [ERROR] WSREP: Command did [COLOR=#00008B]not run: wsrep_sst_rsync --role ‘donor’ --address ‘192.168.70.2:4444/rsync_sst’ --auth ‘sst:sst’ --socket ‘/var/lib/mysql/mysql.sock’ --datadir ‘/var/lib/mysql/’ --defaults-file ‘/etc/my.cnf’ --binlog ‘mysql-bin’ --gtid ‘48ec9889-8ddc-11e4-9efd-da6610fd24da:0’ 2014-12-28 02:24:40 9446 [Warning] WSREP: 0.0 (node3): State transfer [COLOR=#00008B]to 1.0 (node2) failed: -255 (Unknown error 255) 2014-12-28 02:24:40 9446 [Note] WSREP: Shifting DONOR/DESYNCED → JOINED ([COLOR=#00008B]TO: 0) 2014-12-28 02:24:40 9446 [Note] WSREP: Member 0.0 (node3) synced [COLOR=#00008B]with [COLOR=#00008B]group. 2014-12-28 02:24:40 9446 [Note] WSREP: Shifting JOINED → SYNCED ([COLOR=#00008B]TO: 0) 2014-12-28 02:24:40 9446 [Note] WSREP: Synchronized [COLOR=#00008B]with [COLOR=#00008B]group, ready [COLOR=#00008B]for connections 2014-12-28 02:24:40 9446 [Note] WSREP: wsrep_notify_cmd [COLOR=#00008B]is [COLOR=#00008B]not defined, skipping notification. 2014-12-28 02:24:41 9446 [Note] WSREP: forgetting 41f79045 (tcp://192.168.70.2:4567) 2014-12-28 02:24:41 9446 [Note] WSREP: Node 2861d1d7 state prim 2014-12-28 02:24:41 9446 [Note] WSREP: [COLOR=#00008B]save pc [COLOR=#00008B]into [COLOR=#00008B]disk 2014-12-28 02:24:41 9446 [Note] WSREP: New COMPONENT: [COLOR=#00008B]primary = yes, bootstrap = no, my_idx = 0, memb_num = 1 2014-12-28 02:24:41 9446 [Note] WSREP: forgetting 41f79045 (tcp://192.168.70.2:4567) 2014-12-28 02:24:41 9446 [Note] WSREP: STATE_EXCHANGE: sent state UUID: 4c2e3544-8e30-11e4-a0dc-d280b597b8d2 2014-12-28 02:24:41 9446 [Note] WSREP: STATE EXCHANGE: sent state msg: 4c2e3544-8e30-11e4-a0dc-d280b597b8d2 2014-12-28 02:24:41 9446 [Note] WSREP: STATE EXCHANGE: got state msg: 4c2e3544-8e30-11e4-a0dc-d280b597b8d2 [COLOR=#00008B]from 0 (node3) 2014-12-28 02:24:41 9446 [Note] WSREP: Quorum results: version = 3, component = [COLOR=#00008B]PRIMARY, conf_id = 2, members = 1/1 (joined/total), act_id = 0, last_appl. = 0, protocols = 0/6/3 (gcs/repl/appl), [COLOR=#00008B]group UUID = 48ec9889-8ddc-11e4-9efd-da6610fd24da 2014-12-28 02:24:41 9446 [Note] WSREP: Flow-control interval: [16, 16] 2014-12-28 02:24:41 9446 [Note] WSREP: New cluster [COLOR=#00008B]view: global state: 48ec9889-8ddc-11e4-9efd-da6610fd24da:0, [COLOR=#00008B]view# 3: [COLOR=#00008B]Primary, number [COLOR=#00008B]of nodes: 1, my [COLOR=#00008B]index: 0, protocol version 3 2014-12-28 02:24:41 9446 [Note] WSREP: wsrep_notify_cmd [COLOR=#00008B]is [COLOR=#00008B]not defined, skipping notification. 2014-12-28 02:24:41 9446 [Note] WSREP: REPL Protocols: 6 (3, 2) 2014-12-28 02:24:41 9446 [Note] WSREP: Service thread queue flushed. 2014-12-28 02:24:41 9446 [Note] WSREP: Assign initial position [COLOR=#00008B]for certification: 0, protocol version: 3 2014-12-28 02:24:41 9446 [Note] WSREP: Service thread queue flushed. 2014-12-28 02:24:46 9446 [Note] WSREP: cleaning up 41f79045 (tcp://192.168.70.2:4567)

Source: [url]mysql - Percona XtraDB Cluster SST not working using rsync: wsrep_sst_rsync - Stack Overflow

2

Can you share the my.cnf files used for the first and second node?

3

Hi WB,

Here is my configuration for node3 below. This is the node where node2 is transferring from. Configuration for node 2 is directly below the configuration for node 3. I see ‘Kenny Gryp’ also placed a response on StackOverflow, I’ll consider all hints, and anything useful I will note here too.

NODE 3 my.cnf: [mysqld]
innodb_file_per_table
gtid_mode=on
enforce_gtid_consistency
log_slave_updates
skip_slave_start
log-bin=mysql-bin
server-id=3

binlog_format=ROW
wsrep_provider=/usr/lib/libgalera_smm.so
wsrep_cluster_address=gcomm://192.168.70.3
wsrep_node_address=192.168.70.3
wsrep_cluster_name=Pluk2k14
wsrep_node_name=node3

wsrep_slave_threads=2
wsrep_sst_method=rsync
wsrep_sst_auth=sst:sst

innodb_autoinc_lock_mode=2

[xtrabackup]
user=sst
password=sst

NODE 2 my.cnf:
[mysqld]
binlog_format=ROW
log_slave_updates

wsrep_provider=/usr/lib/libgalera_smm.so
wsrep_cluster_address=gcomm://192.168.70.2,192.168.70.3
wsrep_node_address=192.168.70.2
wsrep_cluster_name=Pluk2k14
wsrep_node_name=node2
wsrep_slave_threads=2
wsrep_sst_method=rsync
wsrep_sst_auth=sst:sst

innodb_autoinc_lock_mode=2
innodb_file_per_table

gtid_mode=on
enforce_gtid_consistency
skip_slave_start
server-id=2
log_bin=mysql-bin

datadir=/var/lib/mysql

[xtrabackup]
user=sst
password=sst

4

Just retracing my steps on Node2 and this is as good as it gets:

Node 2: drwxr-xr-x. 2 mysql mysql 4096 Jan 3 18:36 mysql
[root@node2 mysql]# /etc/init.d/mysql start
ERROR! MySQL (Percona XtraDB Cluster) is not running, but lock file (/var/lock/subsys/mysql) exists
Starting MySQL (Percona XtraDB Cluster)…State transfer in progress, setting sleep higher
… ERROR! The server quit without updating PID file (/var/lib/mysql/node2.pid).
ERROR! MySQL (Percona XtraDB Cluster) server startup failed!
[root@node2 mysql]# ls
backup-my.cnf galera.cache grastate.dat node2.err RPM_UPGRADE_HISTORY

P.S. Node 3 is replicating from Node 1, and removing the lock file retains the problem.

5

I just checked your post on StackOverflow and Kenny gave you an answer there. Can you check if the suggestion helped? If not kindly update this thread later.