Percona XtraDB Cluster SST not working using rsync: wsrep_sst_rsync

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: http://stackoverflow.com/questions/27673059/percona-xtradb-cluster-sst-not-working-using-rsync-wsrep-sst-rsync

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

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

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.

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.