Cluster does not start

[jsobrier]

I have Percona-XtraDB-Cluster-server 5.6.21 installed on 3 nodes. The cluster used to work on 2 nodes, but I cannot bring it back up.

I have bootstrapped the cluster on node1. But node2 fails:

WSREP_SST: [INFO] Evaluating socat -u TCP-LISTEN:4444,reuseaddr stdio | xbstream -x; RC=( ${PIPESTATUS[@]} ) (20150209 02:15:30.956)
grep: /var/lib/mysql//xtrabackup_checkpoints: No such file or directory
WSREP_SST: [INFO] Preparing the backup at /var/lib/mysql/ (20150209 02:15:41.121)
WSREP_SST: [INFO] Evaluating innobackupex --no-version-check --apply-log $rebuildcmd ${DATA} &>${DATA}/innobackup.prepare.log (20150209 02:15:41.122)
2015-02-09 02:15:41 2672050 [Warning] WSREP: 1.0 (node1.com): State transfer to 0.0 (node2.com) failed: -22 (Invalid argument)
2015-02-09 02:15:41 2672050 [ERROR] WSREP: gcs/src/gcs_group.cpp:int gcs_group_handle_join_msg(gcs_group_t*, const gcs_recv_msg_t*)():722: Will never receive state. Need to abort.
2015-02-09 02:15:41 2672050 [Note] WSREP: gcomm: terminating thread
2015-02-09 02:15:41 2672050 [Note] WSREP: gcomm: joining thread
2015-02-09 02:15:41 2672050 [Note] WSREP: gcomm: closing backend
WSREP_SST: [ERROR] Cleanup after exit with status:1 (20150209 02:15:41.489)
2015-02-09 02:15:41 2672050 [ERROR] WSREP: Process completed with error: wsrep_sst_xtrabackup-v2 --role ‘joiner’ --address ‘node2.com’ --auth user:pass’ --datadir ‘/var/lib/mysql/’ --defaults-file ‘/etc/my.cnf’ --parent ‘2672050’ ‘’ : 1 (Operation not permitted)
2015-02-09 02:15:41 2672050 [ERROR] WSREP: Failed to read uuid:seqno from joiner script.
2015-02-09 02:15:41 2672050 [ERROR] WSREP: SST failed: 1 (Operation not permitted)
2015-02-09 02:15:41 2672050 [ERROR] Aborting

I don’t know how to debug this issue. Any idea?

[werebear73]

I am having a similar issue with 5.6.21-70 on CentOS 7

NODE 1 - mysql-error.log

WSREP_SST: [ERROR] innobackupex finished with error: 1. Check /var/lib/mysql//innobackup.backup.log (20150219 18:01:58.157)
WSREP_SST: [ERROR] Cleanup after exit with status:22 (20150219 18:01:58.158)
WSREP_SST: [INFO] Cleaning up temporary directories (20150219 18:01:58.161)
2015-02-19 18:01:58 10231 [ERROR] WSREP: Failed to read from: wsrep_sst_xtrabackup-v2 --role 'donor' --address '192.168.88.181:4444/xtrabackup_sst//1' --auth 'sstuser:xxxxx' --socket '/var/lib/mysql/mysql.sock' --datadir '/var/lib/mysql/' --defaults-file '/etc/my.cnf' '' --gtid '7cac0fcf-b83b-11e4-a754-ba12038dc0d4:2'
2015-02-19 18:01:58 10231 [ERROR] WSREP: Process completed with error: wsrep_sst_xtrabackup-v2 --role 'donor' --address '192.168.88.181:4444/xtrabackup_sst//1' --auth 'sstuser:xxxxx' --socket '/var/lib/mysql/mysql.sock' --datadir '/var/lib/mysql/' --defaults-file '/etc/my.cnf' '' --gtid '7cac0fcf-b83b-11e4-a754-ba12038dc0d4:2': 22 (Invalid argument)
2015-02-19 18:01:58 10231 [ERROR] WSREP: Command did not run: wsrep_sst_xtrabackup-v2 --role 'donor' --address '192.168.88.181:4444/xtrabackup_sst//1' --auth 'sstuser:xxxxx' --socket '/var/lib/mysql/mysql.sock' --datadir '/var/lib/mysql/' --defaults-file '/etc/my.cnf' '' --gtid '7cac0fcf-b83b-11e4-a754-ba12038dc0d4:2'

NODE 1 - innobackup.backup.log

150219 18:01:58 innobackupex: Connecting to MySQL server with DSN 'dbi:mysql:;mysql_read_default_file=/etc/my.cnf;mysql_read_default_group=xtrabackup;mysql_socket=/var/lib/mysql/mysql.sock' as 'sstuser' (using password: YES).
innobackupex: got a fatal error with the following stacktrace: at /usr//bin/innobackupex line 3004.
main::mysql_connect('abort_on_error', 1) called at /usr//bin/innobackupex line 1539
innobackupex: Error: Failed to connect to MySQL server: DBI connect(';mysql_read_default_file=/etc/my.cnf;mysql_read_default_group=xtrabackup;mysql_socket=/var/lib/mysql/mysql.sock','sstuser',...) failed: Access denied for user 'sstuser'@'localhost' (using password: YES) at /usr//bin/innobackupex line 2988.

NODE 2 - mysql-error.log

WSREP_SST: [INFO] Cleaning the binlog directory /var/lib/mysql as well (20150219 18:01:48.073)
rm: cannot remove ‘/var/lib/mysql/*.index’: No such file or directory
WSREP_SST: [INFO] Evaluating socat -u TCP-LISTEN:4444,reuseaddr stdio | xbstream -x; RC=( ${PIPESTATUS[@]} ) (20150219 18:01:48.079)
2015-02-19 18:01:49 11547 [Note] WSREP: (5e5687d2, 'tcp://0.0.0.0:4567') turning message relay requesting off
grep: /var/lib/mysql//xtrabackup_checkpoints: No such file or directory
WSREP_SST: [INFO] Preparing the backup at /var/lib/mysql/ (20150219 18:01:58.162)
2015-02-19 18:01:58 11547 [Warning] WSREP: 1.0 (Node1): State transfer to 0.0 (Node2) failed: -22 (Invalid argument)
2015-02-19 18:01:58 11547 [ERROR] WSREP: gcs/src/gcs_group.cpp:int gcs_group_handle_join_msg(gcs_group_t*, const gcs_recv_msg_t*)():722: Will never receive state. Need to abort.
2015-02-19 18:01:58 11547 [Note] WSREP: gcomm: terminating thread
2015-02-19 18:01:58 11547 [Note] WSREP: gcomm: joining thread
2015-02-19 18:01:58 11547 [Note] WSREP: gcomm: closing backend
WSREP_SST: [INFO] Evaluating innobackupex --no-version-check --apply-log $rebuildcmd ${DATA} &>${DATA}/innobackup.prepare.log (20150219 18:01:58.165)
WSREP_SST: [ERROR] Cleanup after exit with status:1 (20150219 18:01:58.344)
2015-02-19 18:01:58 11547 [ERROR] WSREP: Process completed with error: wsrep_sst_xtrabackup-v2 --role 'joiner' --address '192.168.88.181' --auth 'sstuser:xxxxx' --datadir '/var/lib/mysql/' --defaults-file '/etc/my.cnf' --parent '11547' '' : 1 (Operation not permitted)
2015-02-19 18:01:58 11547 [ERROR] WSREP: Failed to read uuid:seqno from joiner script.
2015-02-19 18:01:58 11547 [ERROR] WSREP: SST failed: 1 (Operation not permitted)
2015-02-19 18:01:58 11547 [ERROR] Aborting

[mirfan]

As you can see it errors “Access denied for user ‘sstuser’@‘localhost’”
Is “sstuser” created ? Can you please share my.cnf on failed node. You may found this useful [url]Percona XtraDB Cluster

[Keyur_Makwana]

Hi,

I am facing similar error as posted by jsobrier in intial post.

• I am using below version of Percona XtraDB Cluster

rpm -qa | grep -i percona

percona-xtrabackup-2.2.9-5067.el6.x86_64
Percona-XtraDB-Cluster-galera-3-3.9-1.3494.rhel6.x86_64
Percona-XtraDB-Cluster-server-56-5.6.22-25.8.978.el6.x86_64
Percona-Server-shared-51-5.1.73-rel14.12.624.rhel6.x86_64
Percona-XtraDB-Cluster-shared-56-5.6.22-25.8.978.el6.x86_64
Percona-XtraDB-Cluster-client-56-5.6.22-25.8.978.el6.x86_64
Percona-XtraDB-Cluster-56-5.6.22-25.8.978.el6.x86_64
percona-release-0.1-3.noarch

• sstuser has proper grants

mysql> show grants for sstuser@localhost;
±-------------------------------------------------------------------------------------------------------------------------------------------------+
| Grants for sstuser@localhost |
±-------------------------------------------------------------------------------------------------------------------------------------------------+
| GRANT RELOAD, LOCK TABLES, REPLICATION CLIENT ON . TO ‘sstuser’@‘localhost’ IDENTIFIED BY PASSWORD ‘*BD7D7##########27D4E3DD’ |
±-------------------------------------------------------------------------------------------------------------------------------------------------+
1 row in set (0.00 sec)

mysql>

• Below is the error seen on 2nd node which I am trying to join with first donor node.

2015-03-27 21:03:35 19495 [Note] WSREP: 0.0 (t_jd_pxc1): State transfer to 1.0 (t_jd_pxc2) complete.
2015-03-27 21:03:35 19495 [Note] WSREP: Member 0.0 (t_jd_pxc1) synced with group.
WSREP_SST: [INFO] Preparing the backup at /var/lib/SAN/SQL/mysql//.sst (20150327 21:03:35.790)
WSREP_SST: [INFO] Evaluating innobackupex --no-version-check --apply-log $rebuildcmd ${DATA} &>${DATA}/innobackup.prepare.log (20150327 21:03:35.793)
WSREP_SST: [ERROR] Cleanup after exit with status:1 (20150327 21:03:49.314)
2015-03-27 21:03:49 19495 [ERROR] WSREP: Process completed with error: wsrep_sst_xtrabackup-v2 --role ‘joiner’ --address ‘192.168.1.14’ --auth ‘sstuser:somepassword’ --datadir ‘/var/lib/SAN/SQL/mysql/’ --defaults-file ‘/etc/my.cnf’ --parent ‘19495’ ‘’ : 1 (Operation not permitted)
2015-03-27 21:03:49 19495 [ERROR] WSREP: Failed to read uuid:seqno from joiner script.
2015-03-27 21:03:49 19495 [ERROR] WSREP: SST failed: 1 (Operation not permitted)
2015-03-27 21:03:49 19495 [ERROR] Aborting

2015-03-27 21:03:51 19495 [Note] WSREP: Closing send monitor…
2015-03-27 21:03:51 19495 [Note] WSREP: Closed send monitor.
2015-03-27 21:03:51 19495 [Note] WSREP: gcomm: terminating thread
2015-03-27 21:03:51 19495 [Note] WSREP: gcomm: joining thread
2015-03-27 21:03:51 19495 [Note] WSREP: gcomm: closing backend
2015-03-27 21:03:52 19495 [Note] WSREP: view(view_id(NON_PRIM,77a9e035,6) memb {
a5793a87,0
} joined {
} left {
} partitioned {
77a9e035,0
})
2015-03-27 21:03:52 19495 [Note] WSREP: view((empty))
2015-03-27 21:03:52 19495 [Note] WSREP: New COMPONENT: primary = no, bootstrap = no, my_idx = 0, memb_num = 1
2015-03-27 21:03:52 19495 [Note] WSREP: gcomm: closed
2015-03-27 21:03:52 19495 [Note] WSREP: Flow-control interval: [16, 16]
2015-03-27 21:03:52 19495 [Note] WSREP: Received NON-PRIMARY.
2015-03-27 21:03:52 19495 [Note] WSREP: Shifting JOINER → OPEN (TO: 488602)
2015-03-27 21:03:52 19495 [Note] WSREP: Received self-leave message.
2015-03-27 21:03:52 19495 [Note] WSREP: Flow-control interval: [0, 0]
2015-03-27 21:03:52 19495 [Note] WSREP: Received SELF-LEAVE. Closing connection.
2015-03-27 21:03:52 19495 [Note] WSREP: Shifting OPEN → CLOSED (TO: 488602)
2015-03-27 21:03:52 19495 [Note] WSREP: RECV thread exiting 0: Success
2015-03-27 21:03:52 19495 [Note] WSREP: recv_thread() joined.
2015-03-27 21:03:52 19495 [Note] WSREP: Closing replication queue.
2015-03-27 21:03:52 19495 [Note] WSREP: Closing slave action queue.
2015-03-27 21:03:52 19495 [Note] WSREP: Service disconnected.
2015-03-27 21:03:52 19495 [Note] WSREP: rollbacker thread exiting
2015-03-27 21:03:53 19495 [Note] WSREP: Some threads may fail to exit.
2015-03-27 21:03:53 19495 [Note] Binlog end
2015-03-27 21:03:53 19495 [Note] /usr/sbin/mysqld: Shutdown complete

Error in my_thread_global_end(): 1 threads didn’t exit
150327 21:03:58 mysqld_safe mysqld from pid file /var/lib/SAN/SQL/mysql/hostname.pid ended

• Log files on DONOR server shows

** innobackup.backup.log

log scanned up to (585254827608)
log scanned up to (585254827608)
innobackupex: Backing up files ‘/var/lib/SAN/SQL/mysql//performance_schema/*.{frm,isl,MYD,MYI,MAD,MAI,MRG,TRG,TRN,ARM,ARZ,CSM,CSV,opt,par}’ (53 files)
innobackupex: Backing up file ‘/var/lib/SAN/SQL/mysql//perconatest/employees.frm’
innobackupex: Backing up file ‘/var/lib/SAN/SQL/mysql//perconatest/employees1.frm’
innobackupex: Backing up file ‘/var/lib/SAN/SQL/mysql//perconatest/db.opt’
innobackupex: Backing up file ‘/var/lib/SAN/SQL/mysql//perconatest/employees.MYD’
innobackupex: Backing up file ‘/var/lib/SAN/SQL/mysql//perconatest/employees.MYI’
innobackupex: Backing up file ‘/var/lib/SAN/SQL/mysql//percona/checksums.frm’
innobackupex: Backing up file ‘/var/lib/SAN/SQL/mysql//percona/db.opt’
150327 21:03:34 innobackupex: Finished backing up non-InnoDB tables and files

150327 21:03:34 innobackupex: Executing LOCK BINLOG FOR BACKUP…
150327 21:03:34 innobackupex: Executing FLUSH NO_WRITE_TO_BINLOG ENGINE LOGS…
150327 21:03:34 innobackupex: Waiting for log copying to finish

log scanned up to (585254827608)
xtrabackup: The latest check point (for incremental): ‘585254827608’
xtrabackup: Stopping log copying thread.
.>> log scanned up to (585254827608)

xtrabackup: Creating suspend file ‘/tmp/tmp.V2pOoaughI/xtrabackup_log_copied’ with pid ‘4364’
xtrabackup: Transaction log of lsn (585188196236) to (585254827608) was copied.
150327 21:03:35 innobackupex: Executing UNLOCK BINLOG
150327 21:03:35 innobackupex: Executing UNLOCK TABLES
150327 21:03:35 innobackupex: All tables unlocked

innobackupex: Backup created in directory ‘/tmp/tmp.H3UsCgCUbj’
innobackupex: MySQL binlog position: filename ‘mysql-bin.000789’, position 297004215
150327 21:03:35 innobackupex: Connection to database server closed
150327 21:03:35 innobackupex: completed OK!

** mysqld.log

2015-03-27 21:03:35 20563 [Note] WSREP: 0.0 (t_jd_pxc1): State transfer to 1.0 (t_jd_pxc2) complete.
2015-03-27 21:03:35 20563 [Note] WSREP: Shifting DONOR/DESYNCED → JOINED (TO: 486111)
2015-03-27 21:03:35 20563 [Note] WSREP: Member 0.0 (t_jd_pxc1) synced with group.
2015-03-27 21:03:35 20563 [Note] WSREP: Shifting JOINED → SYNCED (TO: 486111)
2015-03-27 21:03:35 20563 [Note] WSREP: Synchronized with group, ready for connections
2015-03-27 21:03:35 20563 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
WSREP_SST: [INFO] Total time on donor: 0 seconds (20150327 21:03:35.785)
WSREP_SST: [INFO] Cleaning up temporary directories (20150327 21:03:35.789)
2015-03-27 21:03:52 20563 [Note] WSREP: forgetting a5793a87 (tcp://192.168.1.14:4567)
2015-03-27 21:03:52 20563 [Note] WSREP: Node 77a9e035 state prim
2015-03-27 21:03:52 20563 [Note] WSREP: view(view_id(PRIM,77a9e035,7) memb {
77a9e035,0
} joined {
} left {
} partitioned {
a5793a87,0
})
2015-03-27 21:03:52 20563 [Note] WSREP: save pc into disk
2015-03-27 21:03:52 20563 [Note] WSREP: forgetting a5793a87 (tcp://192.168.1.14:4567)
2015-03-27 21:03:52 20563 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 0, memb_num = 1
2015-03-27 21:03:52 20563 [Note] WSREP: STATE_EXCHANGE: sent state UUID: abfa7343-d496-11e4-b392-e7d84f9dbee8
2015-03-27 21:03:52 20563 [Note] WSREP: STATE EXCHANGE: sent state msg: abfa7343-d496-11e4-b392-e7d84f9dbee8
2015-03-27 21:03:52 20563 [Note] WSREP: STATE EXCHANGE: got state msg: abfa7343-d496-11e4-b392-e7d84f9dbee8 from 0 (t_jd_pxc1)
2015-03-27 21:03:52 20563 [Note] WSREP: Quorum results:
version = 3,
component = PRIMARY,
conf_id = 6,
members = 1/1 (joined/total),
act_id = 488602,
last_appl. = 488493,
protocols = 0/7/3 (gcs/repl/appl),
group UUID = 77aa765d-d46d-11e4-87da-876501f74653
2015-03-27 21:03:52 20563 [Note] WSREP: Flow-control interval: [16, 16]
2015-03-27 21:03:52 20563 [Note] WSREP: New cluster view: global state: 77aa765d-d46d-11e4-87da-876501f74653:488602, view# 7: Primary, number of nodes: 1, my index: 0, protocol version 3
2015-03-27 21:03:52 20563 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2015-03-27 21:03:52 20563 [Note] WSREP: REPL Protocols: 7 (3, 2)
2015-03-27 21:03:52 20563 [Note] WSREP: Service thread queue flushed.
2015-03-27 21:03:52 20563 [Note] WSREP: Assign initial position for certification: 488602, protocol version: 3
2015-03-27 21:03:52 20563 [Note] WSREP: Service thread queue flushed.
2015-03-27 21:03:57 20563 [Note] WSREP: cleaning up a5793a87 (tcp://192.168.1.14:4567)

What could be the issue here ?