Preface
Yesterday I implemented a three-nodes PXC,but there were some errors when proceeding it.So I decide to research what's wrong with it.The operations and evidences shows below.
Procedure
Fisrt of all,I find out that yesterday's error is due to lack of "socat" package on first node zlm2.
1 //Here's the error log of it. 2 2018-08-08T08:48:18.198487+01:00 0 [Note] WSREP: Initiating SST/IST transfer on DONOR side (wsrep_sst_xtrabackup-v2 --role 'donor' --address '192.168.1.102:4444/xtrabackup_sst//1' --socket '/tmp/mysql3308.sock' --datadir '/data/mysql/mysql3308/data/' --defaults-file '/data/mysql/mysql3308/my3308.cnf' --defaults-group-suffix '' --binlog '/data/mysql/mysql3308/logs/mysql-bin' --gtid 'bd5525ab-9a15-11e8-aa0f-4b830c783fc7:21') 3 2018-08-08T08:48:18.200272+01:00 2 [Note] WSREP: DONOR thread signaled with 0 4 which: no socat in (/usr/sbin:/sbin:/opt/mysql/Percona-XtraDB-Cluster-5.7.22-rel22-29.26.1.Linux.x86_64.ssl102/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/root/bin:/usr/local/mysql/bin:/usr/local/zabbix/bin:/usr/local/zabbix/sbin) 5 2018-08-08T06:48:18.782344Z WSREP_SST: [ERROR] ******************* FATAL ERROR ********************** 6 2018-08-08T06:48:18.784043Z WSREP_SST: [ERROR] socat not found in path: /usr/sbin:/sbin:/opt/mysql/Percona-XtraDB-Cluster-5.7.22-rel22-29.26.1.Linux.x86_64.ssl102/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/root/bin:/usr/local/mysql/bin:/usr/local/zabbix/bin:/usr/local/zabbix/sbin 7 2018-08-08T06:48:18.785926Z WSREP_SST: [ERROR] ****************************************************** 8 2018-08-08T08:48:18.786496+01:00 0 [ERROR] WSREP: Process completed with error: wsrep_sst_xtrabackup-v2 --role 'donor' --address '192.168.1.102:4444/xtrabackup_sst//1' --socket '/tmp/mysql3308.sock' --datadir '/data/mysql/mysql3308/data/' --defaults-file '/data/mysql/mysql3308/my3308.cnf' --defaults-group-suffix '' --binlog '/data/mysql/mysql3308/logs/mysql-bin' --gtid 'bd5525ab-9a15-11e8-aa0f-4b830c783fc7:21': 2 (No such file or directory) 9 2018-08-08T08:48:18.786587+01:00 0 [ERROR] WSREP: Command did not run: wsrep_sst_xtrabackup-v2 --role 'donor' --address '192.168.1.102:4444/xtrabackup_sst//1' --socket '/tmp/mysql3308.sock' --datadir '/data/mysql/mysql3308/data/' --defaults-file '/data/mysql/mysql3308/my3308.cnf' --defaults-group-suffix '' --binlog '/data/mysql/mysql3308/logs/mysql-bin' --gtid 'bd5525ab-9a15-11e8-aa0f-4b830c783fc7:21' 10 2018-08-08T08:48:18.787610+01:00 0 [Warning] WSREP: 1.0 (zlm2): State transfer to 0.0 (zlm3) failed: -2 (No such file or directory) 11 12 [root@zlm2 08:53:31 /data/mysql/mysql3308/data] 13 #rpm -qa|grep socat 14 15 [root@zlm2 09:11:08 /data/mysql/mysql3308/data] 16 #yum install socat 17 ... //Omitted. 18 19 Installed: 20 socat.x86_64 0:1.7.3.2-2.el7 21 22 Complete!
Restart the PXC mysqld on zlm2.
1 [root@zlm2 09:21:38 /data/mysql/mysql3308/data] 2 #mysqladmin -P3308 shutdown 3 4 [root@zlm2 09:22:10 /data/mysql/mysql3308/data] 5 #ps aux|grep mysqld 6 mysql 6295 0.1 22.4 1565212 227920 pts/0 Sl 08:47 0:02 mysqld --defaults-file=/data/mysql/mysql3308/my3308.cnf --wsrep-new-cluster 7 root 6835 0.0 0.0 112640 956 pts/3 R+ 09:22 0:00 grep --color=auto mysqld 8 9 [root@zlm2 09:22:15 /data/mysql/mysql3308/data] 10 #ps aux|grep mysqld 11 root 6841 0.0 0.0 112640 960 pts/3 R+ 09:22 0:00 grep --color=auto mysqld 12 13 [root@zlm2 09:30:04 /data/mysql/mysql3308/data] 14 #mysqld --defaults-file=/data/mysql/mysql3308/my3308.cnf --wsrep-new-cluster & 15 [1] 7055 16 17 [root@zlm2 09:30:20 /data/mysql/mysql3308/data] 18 #ps aux|grep mysqld 19 mysql 7055 0.4 22.1 1564952 224900 pts/3 Sl 09:30 0:02 mysqld --defaults-file=/data/mysql/mysql3308/my3308.cnf --wsrep-new-cluster 20 root 7583 0.0 0.0 112640 956 pts/3 R+ 09:39 0:00 grep --color=auto mysqld
It still show the ERROR output when node zlm3 startup.
1 2018-08-08T09:32:14.789691+01:00 0 [Note] WSREP: (e783b5a9, 'tcp://0.0.0.0:4567') connection established to 2bcb8dba tcp://192.168.1.102:4567 2 2018-08-08T09:32:14.790669+01:00 0 [Note] WSREP: (e783b5a9, 'tcp://0.0.0.0:4567') turning message relay requesting on, nonlive peers: 3 2018-08-08T09:32:15.289238+01:00 0 [Note] WSREP: declaring 2bcb8dba at tcp://192.168.1.102:4567 stable 4 2018-08-08T09:32:15.290161+01:00 0 [Note] WSREP: Node e783b5a9 state primary 5 2018-08-08T09:32:15.291214+01:00 0 [Note] WSREP: Current view of cluster as seen by this node 6 view (view_id(PRIM,2bcb8dba,2) 7 memb { 8 2bcb8dba,0 9 e783b5a9,0 10 } 11 joined { 12 } 13 left { 14 } 15 partitioned { 16 } 17 ) 18 2018-08-08T09:32:15.291254+01:00 0 [Note] WSREP: Save the discovered primary-component to disk 19 2018-08-08T09:32:15.291707+01:00 0 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 1, memb_num = 2 20 2018-08-08T09:32:15.291726+01:00 0 [Note] WSREP: STATE EXCHANGE: Waiting for state UUID. 21 2018-08-08T09:32:15.791844+01:00 0 [Note] WSREP: STATE EXCHANGE: sent state msg: 2c64cc25-9add-11e8-bdeb-67bbb141911b 22 2018-08-08T09:32:15.793169+01:00 0 [Note] WSREP: STATE EXCHANGE: got state msg: 2c64cc25-9add-11e8-bdeb-67bbb141911b from 0 (zlm3) 23 2018-08-08T09:32:15.793198+01:00 0 [Note] WSREP: STATE EXCHANGE: got state msg: 2c64cc25-9add-11e8-bdeb-67bbb141911b from 1 (zlm2) 24 2018-08-08T09:32:15.793205+01:00 0 [Note] WSREP: Quorum results: 25 version = 4, 26 component = PRIMARY, 27 conf_id = 1, 28 members = 1/2 (primary/total), 29 act_id = 21, 30 last_appl. = 0, 31 protocols = 0/8/3 (gcs/repl/appl), 32 group UUID = bd5525ab-9a15-11e8-aa0f-4b830c783fc7 33 2018-08-08T09:32:15.793211+01:00 0 [Note] WSREP: Flow-control interval: [141, 141] 34 2018-08-08T09:32:15.793213+01:00 0 [Note] WSREP: Trying to continue unpaused monitor 35 2018-08-08T09:32:15.793314+01:00 2 [Note] WSREP: REPL Protocols: 8 (3, 2) 36 2018-08-08T09:32:15.793324+01:00 2 [Note] WSREP: New cluster view: global state: bd5525ab-9a15-11e8-aa0f-4b830c783fc7:21, view# 2: Primary, number of nodes: 2, my index: 1, protocol version 3 37 2018-08-08T09:32:15.793327+01:00 2 [Note] WSREP: Setting wsrep_ready to true 38 2018-08-08T09:32:15.793330+01:00 2 [Note] WSREP: Auto Increment Offset/Increment re-align with cluster membership change (Offset: 1 -> 2) (Increment: 1 -> 2) 39 2018-08-08T09:32:15.793332+01:00 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification. 40 2018-08-08T09:32:15.793337+01:00 2 [Note] WSREP: Assign initial position for certification: 21, protocol version: 3 41 2018-08-08T09:32:15.793351+01:00 0 [Note] WSREP: Service thread queue flushed. 42 2018-08-08T09:32:16.392574+01:00 0 [Note] WSREP: Member 0.0 (zlm3) requested state transfer from '*any*'. Selected 1.0 (zlm2)(SYNCED) as donor. 43 2018-08-08T09:32:16.392599+01:00 0 [Note] WSREP: Shifting SYNCED -> DONOR/DESYNCED (TO: 21) 44 2018-08-08T09:32:16.392659+01:00 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification. 45 2018-08-08T09:32:16.392879+01:00 0 [Note] WSREP: Initiating SST/IST transfer on DONOR side (wsrep_sst_xtrabackup-v2 --role 'donor' --address '192.168.1.102:4444/xtrabackup_sst//1' --socket '/tmp/mysql3308.sock' --datadir '/data/mysql/mysql3308/data/' --defaults-file '/data/mysql/mysql3308/my3308.cnf' --defaults-group-suffix '' --binlog '/data/mysql/mysql3308/logs/mysql-bin' --gtid 'bd5525ab-9a15-11e8-aa0f-4b830c783fc7:21') 46 2018-08-08T09:32:16.396838+01:00 2 [Note] WSREP: DONOR thread signaled with 0 47 2018-08-08T09:32:17.917352+01:00 0 [Note] WSREP: (e783b5a9, 'tcp://0.0.0.0:4567') turning message relay requesting off 48 2018-08-08T07:32:27.003790Z WSREP_SST: [INFO] Streaming the backup to joiner at 192.168.1.102 4444 49 2018-08-08T09:32:27.124206+01:00 4 [Note] Access denied for user 'sst'@'192.168.1.101' (using password: YES) 50 2018-08-08T09:32:27.138281+01:00 5 [Note] Aborted connection 5 to db: 'unconnected' user: 'sst' host: 'localhost' (Got an error reading communication packets) 51 2018-08-08T07:32:27.139336Z WSREP_SST: [ERROR] ******************* FATAL ERROR ********************** 52 2018-08-08T07:32:27.140923Z WSREP_SST: [ERROR] xtrabackup finished with error: 1. Check /data/mysql/mysql3308/data//innobackup.backup.log 53 --------------- innobackup.backup.log (START) -------------------- 54 xtrabackup: recognized server arguments: --datadir=/data/mysql/mysql3308/data --server-id=1013308 --open_files_limit=65536 --log_bin=/data/mysql/mysql3308/logs/mysql-bin --innodb_data_file_path=ibdata1:100M:autoextend --innodb_buffer_pool_filename=ib_buffer_pool --innodb_log_group_home_dir=./ --innodb_log_files_in_group=3 --innodb_log_file_size=100M --innodb_file_per_table=1 --innodb_open_files=65535 --innodb_page_size=16k --innodb_read_io_threads=4 --innodb_write_io_threads=4 --innodb_io_capacity=200 --innodb_doublewrite=1 --innodb_log_buffer_size=128M --innodb_flush_log_at_trx_commit=1 --innodb_buffer_pool_size=100M --innodb_flush_method=O_DIRECT --defaults_group=mysqld --parallel=4 55 xtrabackup: recognized client arguments: --datadir=/data/mysql/mysql3308/data --server-id=1013308 --open_files_limit=65536 --log_bin=/data/mysql/mysql3308/logs/mysql-bin --innodb_data_file_path=ibdata1:100M:autoextend --innodb_buffer_pool_filename=ib_buffer_pool --innodb_log_group_home_dir=./ --innodb_log_files_in_group=3 --innodb_log_file_size=100M --innodb_file_per_table=1 --innodb_open_files=65535 --innodb_page_size=16k --innodb_read_io_threads=4 --innodb_write_io_threads=4 --innodb_io_capacity=200 --innodb_doublewrite=1 --innodb_log_buffer_size=128M --innodb_flush_log_at_trx_commit=1 --innodb_buffer_pool_size=100M --innodb_flush_method=O_DIRECT --defaults_group=mysqld --parallel=4 --port=3308 --user=sst --password=* --socket=/tmp/mysql3308.sock --lock-ddl=1 --backup=1 --galera-info=1 --binlog-info=ON --stream=xbstream --target-dir=/tmp/pxc_sst_sn2p/donor_xb_qh5x 56 180808 09:32:27 version_check Connecting to MySQL server with DSN 'dbi:mysql:;mysql_read_default_group=xtrabackup;port=3308;mysql_socket=/tmp/mysql3308.sock' as 'sst' (using password: YES). 57 Failed to connect to MySQL server: DBI connect(';mysql_read_default_group=xtrabackup;port=3308;mysql_socket=/tmp/mysql3308.sock','sst',...) failed: Access denied for user 'sst'@'192.168.1.101' (using password: YES) at - line 1314. 58 180808 09:32:27 Connecting to MySQL server host: localhost, user: sst, password: set, port: 3308, socket: /tmp/mysql3308.sock 59 Using server version 5.7.22-22-29.26-log 60 180808 09:32:27 Executing LOCK TABLES FOR BACKUP... 61 Error: failed to execute query SHOW ENGINE INNODB STATUS: Access denied; you need (at least one of) the PROCESS privilege(s) for this operation 62 --------------- innobackup.backup.log (END) ---------------------- 63 2018-08-08T07:32:27.143691Z WSREP_SST: [ERROR] ****************************************************** 64 2018-08-08T07:32:27.145779Z WSREP_SST: [ERROR] Cleanup after exit with status:22 65 2018-08-08T09:32:27.158932+01:00 0 [ERROR] WSREP: Process completed with error: wsrep_sst_xtrabackup-v2 --role 'donor' --address '192.168.1.102:4444/xtrabackup_sst//1' --socket '/tmp/mysql3308.sock' --datadir '/data/mysql/mysql3308/data/' --defaults-file '/data/mysql/mysql3308/my3308.cnf' --defaults-group-suffix '' --binlog '/data/mysql/mysql3308/logs/mysql-bin' --gtid 'bd5525ab-9a15-11e8-aa0f-4b830c783fc7:21': 22 (Invalid argument) 66 2018-08-08T09:32:27.159041+01:00 0 [ERROR] WSREP: Command did not run: wsrep_sst_xtrabackup-v2 --role 'donor' --address '192.168.1.102:4444/xtrabackup_sst//1' --socket '/tmp/mysql3308.sock' --datadir '/data/mysql/mysql3308/data/' --defaults-file '/data/mysql/mysql3308/my3308.cnf' --defaults-group-suffix '' --binlog '/data/mysql/mysql3308/logs/mysql-bin' --gtid 'bd5525ab-9a15-11e8-aa0f-4b830c783fc7:21' 67 2018-08-08T09:32:27.160430+01:00 0 [Warning] WSREP: 1.0 (zlm2): State transfer to 0.0 (zlm3) failed: -22 (Invalid argument) 68 69 //Error: failed to execute query SHOW ENGINE INNODB STATUS: Access denied; you need (at least one of) the PROCESS privilege(s) for this operation. 70 //It seams the user sst@localhost is lack of privilege of "PROCESS".
Modify the privilege of user sst@localhost.
1 (zlm@192.168.1.101 3308)[(none)]>select user,host from mysql.user; 2 +---------------+-------------+ 3 | user | host | 4 +---------------+-------------+ 5 | zlm | 192.168.1.% | 6 | mysql.session | localhost | 7 | mysql.sys | localhost | 8 | root | localhost | 9 | sst | localhost | 10 +---------------+-------------+ 11 5 rows in set (0.02 sec) 12 13 (zlm@192.168.1.101 3308)[(none)]>show grants for sst@localhost; 14 +---------------------------------------------------------------------------+ 15 | Grants for sst@localhost | 16 +---------------------------------------------------------------------------+ 17 | GRANT RELOAD, LOCK TABLES, REPLICATION CLIENT ON *.* TO 'sst'@'localhost' | 18 +---------------------------------------------------------------------------+ 19 1 row in set (0.00 sec) 20 21 (zlm@192.168.1.101 3308)[(none)]>grant process on *.* to 'sst'@'localhost'; 22 ERROR 1045 (28000): Access denied for user 'zlm'@'192.168.1.%' (using password: YES) 23 (zlm@192.168.1.101 3308)[(none)]>exit 24 Bye 25 26 [root@zlm2 10:07:32 ~] 27 #mysql -uroot -pPassw0rd -hlocalhost -S /tmp/mysql3308.sock 28 mysql: [Warning] Using a password on the command line interface can be insecure. 29 Welcome to the MySQL monitor. Commands end with ; or g. 30 Your MySQL connection id is 9 31 Server version: 5.7.22-22-29.26-log Percona XtraDB Cluster binary (GPL) 5.7.22-29.26, Revision da86071, wsrep_29.26 32 33 Copyright (c) 2009-2018 Percona LLC and/or its affiliates 34 Copyright (c) 2000, 2018, Oracle and/or its affiliates. All rights reserved. 35 36 Oracle is a registered trademark of Oracle Corporation and/or its 37 affiliates. Other names may be trademarks of their respective 38 owners. 39 40 Type 'help;' or 'h' for help. Type 'c' to clear the current input statement. 41 42 (root@localhost mysql3308.sock)[(none)]>grant process on *.* to sst@localhost; 43 Query OK, 0 rows affected, 1 warning (0.01 sec) 44 45 (root@localhost mysql3308.sock)[(none)]>show grants for sst@localhost; 46 +------------------------------------------------------------------------------------+ 47 | Grants for sst@localhost | 48 +------------------------------------------------------------------------------------+ 49 | GRANT RELOAD, PROCESS, LOCK TABLES, REPLICATION CLIENT ON *.* TO 'sst'@'localhost' | 50 +------------------------------------------------------------------------------------+ 51 1 row in set (0.00 sec)
Restart PXC again on zlm2.
[root@zlm2 10:11:10 ~] #ps aux|grep mysqld mysql 7055 0.1 22.2 1564952 225952 pts/3 Sl 09:30 0:04 mysqld --defaults-file=/data/mysql/mysql3308/my3308.cnf --wsrep-new-cluster root 7661 0.0 0.0 112640 960 pts/0 R+ 10:11 0:00 grep --color=auto mysqld [root@zlm2 10:11:28 ~] #mysqladmin -uzlm -pzlmzlm -h192.168.1.101 -P3308 shutdown mysqladmin: [Warning] Using a password on the command line interface can be insecure. [root@zlm2 10:11:50 ~] #ps aux|grep mysqld root 7672 0.0 0.0 112640 960 pts/0 R+ 10:12 0:00 grep --color=auto mysqld [root@zlm2 09:39:30 /data/mysql/mysql3308/data] #mysqld --defaults-file=/data/mysql/mysql3308/my3308.cnf --wsrep-new-cluster & [2] 7690 [1] Done mysqld --defaults-file=/data/mysql/mysql3308/my3308.cnf --wsrep-new-cluster [root@zlm2 10:12:44 /data/mysql/mysql3308/data] #ps aux|grep mysqld mysql 7690 5.8 20.6 1556488 210296 pts/3 Sl 10:12 0:01 mysqld --defaults-file=/data/mysql/mysql3308/my3308.cnf --wsrep-new-cluster root 7729 0.0 0.0 112640 960 pts/3 R+ 10:13 0:00 grep --color=auto mysqld //No ERROR messages were found in error log.
Restart PXC again on zlm3 and check the output of error log.
1 [root@zlm3 10:27:10 ~] 2 #ps aux|grep mysqld 3 root 6694 0.0 0.0 112640 960 pts/1 R+ 10:43 0:00 grep --color=auto mysqld 4 [2]+ Exit 1 mysqld --defaults-file=/data/mysql/mysql3308/my3308.cnf 5 6 [root@zlm3 10:30:01 /data/mysql/mysql3308/data] 7 #cat error.log |grep ERROR 8 2018-08-08T08:27:19.819918Z WSREP_SST: [ERROR] Cleanup after exit with status:1 9 2018-08-08T10:27:19.826527+01:00 0 [ERROR] WSREP: Process completed with error: wsrep_sst_xtrabackup-v2 --role 'joiner' --address '192.168.1.102' --datadir '/data/mysql/mysql3308/data/' --defaults-file '/data/mysql/mysql3308/my3308.cnf' --defaults-group-suffix '' --parent '6021' --binlog '/data/mysql/mysql3308/logs/mysql-bin' : 1 (Operation not permitted) 10 2018-08-08T10:27:19.826557+01:00 0 [ERROR] WSREP: Failed to read uuid:seqno from joiner script. 11 2018-08-08T10:27:19.826565+01:00 0 [ERROR] WSREP: SST script aborted with error 1 (Operation not permitted) 12 2018-08-08T10:27:19.826592+01:00 0 [ERROR] WSREP: SST failed: 1 (Operation not permitted) 13 2018-08-08T10:27:19.826595+01:00 0 [ERROR] Aborting
Check the error log on donor node zlm2 begin with the time of starting mysqld on joiner zlm3.
1 2018-08-08T10:54:47.539174+01:00 0 [Note] WSREP: (d4006db4, 'tcp://0.0.0.0:4567') connection established to b3de093b tcp://192.168.1.102:4567 2 2018-08-08T10:54:47.539620+01:00 0 [Note] WSREP: (d4006db4, 'tcp://0.0.0.0:4567') turning message relay requesting on, nonlive peers: 3 2018-08-08T10:54:48.038167+01:00 0 [Note] WSREP: declaring b3de093b at tcp://192.168.1.102:4567 stable 4 2018-08-08T10:54:48.038656+01:00 0 [Note] WSREP: Node d4006db4 state primary 5 2018-08-08T10:54:48.039842+01:00 0 [Note] WSREP: Current view of cluster as seen by this node 6 view (view_id(PRIM,b3de093b,8) 7 memb { 8 b3de093b,0 9 d4006db4,0 10 } 11 joined { 12 } 13 left { 14 } 15 partitioned { 16 } 17 ) 18 2018-08-08T10:54:48.039890+01:00 0 [Note] WSREP: Save the discovered primary-component to disk 19 2018-08-08T10:54:48.040138+01:00 0 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 1, memb_num = 2 20 2018-08-08T10:54:48.040154+01:00 0 [Note] WSREP: STATE EXCHANGE: Waiting for state UUID. 21 2018-08-08T10:54:48.540351+01:00 0 [Note] WSREP: STATE EXCHANGE: sent state msg: b47737d3-9ae8-11e8-81e0-7bfd4d57e067 22 2018-08-08T10:54:48.540644+01:00 0 [Note] WSREP: STATE EXCHANGE: got state msg: b47737d3-9ae8-11e8-81e0-7bfd4d57e067 from 0 (zlm3) 23 2018-08-08T10:54:48.541101+01:00 0 [Note] WSREP: STATE EXCHANGE: got state msg: b47737d3-9ae8-11e8-81e0-7bfd4d57e067 from 1 (zlm2) 24 2018-08-08T10:54:48.541140+01:00 0 [Note] WSREP: Quorum results: 25 version = 4, 26 component = PRIMARY, 27 conf_id = 7, 28 members = 1/2 (primary/total), 29 act_id = 22, 30 last_appl. = 0, 31 protocols = 0/8/3 (gcs/repl/appl), 32 group UUID = bd5525ab-9a15-11e8-aa0f-4b830c783fc7 33 2018-08-08T10:54:48.541150+01:00 0 [Note] WSREP: Flow-control interval: [141, 141] 34 2018-08-08T10:54:48.541155+01:00 0 [Note] WSREP: Trying to continue unpaused monitor 35 2018-08-08T10:54:48.541224+01:00 2 [Note] WSREP: REPL Protocols: 8 (3, 2) 36 2018-08-08T10:54:48.541234+01:00 2 [Note] WSREP: New cluster view: global state: bd5525ab-9a15-11e8-aa0f-4b830c783fc7:22, view# 8: Primary, number of nodes: 2, my index: 1, protocol version 3 37 2018-08-08T10:54:48.541238+01:00 2 [Note] WSREP: Setting wsrep_ready to true 38 2018-08-08T10:54:48.541241+01:00 2 [Note] WSREP: Auto Increment Offset/Increment re-align with cluster membership change (Offset: 1 -> 2) (Increment: 1 -> 2) 39 2018-08-08T10:54:48.541245+01:00 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification. 40 2018-08-08T10:54:48.541252+01:00 2 [Note] WSREP: Assign initial position for certification: 22, protocol version: 3 41 2018-08-08T10:54:48.541264+01:00 0 [Note] WSREP: Service thread queue flushed. 42 2018-08-08T10:54:49.007421+01:00 0 [Note] WSREP: Member 0.0 (zlm3) requested state transfer from '*any*'. Selected 1.0 (zlm2)(SYNCED) as donor. 43 2018-08-08T10:54:49.007441+01:00 0 [Note] WSREP: Shifting SYNCED -> DONOR/DESYNCED (TO: 22) 44 2018-08-08T10:54:49.007480+01:00 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification. 45 2018-08-08T10:54:49.007626+01:00 0 [Note] WSREP: Initiating SST/IST transfer on DONOR side (wsrep_sst_xtrabackup-v2 --role 'donor' --address '192.168.1.102:4444/xtrabackup_sst//1' --socket '/tmp/mysql3308.sock' --datadir '/data/mysql/mysql3308/data/' --defaults-file '/data/mysql/mysql3308/my3308.cnf' --defaults-group-suffix '' --binlog '/data/mysql/mysql3308/logs/mysql-bin' --gtid 'bd5525ab-9a15-11e8-aa0f-4b830c783fc7:22') 46 2018-08-08T10:54:49.012384+01:00 2 [Note] WSREP: DONOR thread signaled with 0 47 2018-08-08T10:54:50.911071+01:00 0 [Note] WSREP: (d4006db4, 'tcp://0.0.0.0:4567') turning message relay requesting off 48 2018-08-08T08:54:59.535108Z WSREP_SST: [INFO] Streaming the backup to joiner at 192.168.1.102 4444 49 2018-08-08T10:54:59.626864+01:00 8 [Note] Access denied for user 'sst'@'192.168.1.101' (using password: YES) 50 2018-08-08T10:55:05.537365+01:00 0 [Note] WSREP: 1.0 (zlm2): State transfer to 0.0 (zlm3) complete. 51 2018-08-08T10:55:05.537399+01:00 0 [Note] WSREP: Shifting DONOR/DESYNCED -> JOINED (TO: 22) 52 2018-08-08T10:55:05.542864+01:00 0 [Note] WSREP: Member 1.0 (zlm2) synced with group. 53 2018-08-08T10:55:05.542949+01:00 0 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 22) 54 2018-08-08T10:55:05.543015+01:00 2 [Note] WSREP: Synchronized with group, ready for connections 55 2018-08-08T10:55:05.543022+01:00 2 [Note] WSREP: Setting wsrep_ready to true 56 2018-08-08T10:55:05.543027+01:00 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification. 57 2018-08-08T10:55:22.477724+01:00 0 [Note] WSREP: forgetting b3de093b (tcp://192.168.1.102:4567) 58 2018-08-08T10:55:22.479542+01:00 0 [Note] WSREP: Node d4006db4 state primary 59 2018-08-08T10:55:22.479612+01:00 0 [Note] WSREP: Current view of cluster as seen by this node 60 view (view_id(PRIM,d4006db4,9) 61 memb { 62 d4006db4,0 63 } 64 joined { 65 } 66 left { 67 } 68 partitioned { 69 b3de093b,0 70 } 71 ) 72 2018-08-08T10:55:22.479621+01:00 0 [Note] WSREP: Save the discovered primary-component to disk 73 2018-08-08T10:55:22.479763+01:00 0 [Note] WSREP: forgetting b3de093b (tcp://192.168.1.102:4567) 74 2018-08-08T10:55:22.479875+01:00 0 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 0, memb_num = 1 75 2018-08-08T10:55:22.479976+01:00 0 [Note] WSREP: STATE_EXCHANGE: sent state UUID: c8aef280-9ae8-11e8-80c9-d74e514aa266 76 2018-08-08T10:55:22.479976+01:00 0 [Note] WSREP: STATE EXCHANGE: sent state msg: c8aef280-9ae8-11e8-80c9-d74e514aa266 77 2018-08-08T10:55:22.479976+01:00 0 [Note] WSREP: STATE EXCHANGE: got state msg: c8aef280-9ae8-11e8-80c9-d74e514aa266 from 0 (zlm2) 78 2018-08-08T10:55:22.479978+01:00 0 [Note] WSREP: Quorum results: 79 version = 4, 80 component = PRIMARY, 81 conf_id = 8, 82 members = 1/1 (primary/total), 83 act_id = 22, 84 last_appl. = 0, 85 protocols = 0/8/3 (gcs/repl/appl), 86 group UUID = bd5525ab-9a15-11e8-aa0f-4b830c783fc7 87 2018-08-08T10:55:22.479983+01:00 0 [Note] WSREP: Flow-control interval: [100, 100] 88 2018-08-08T10:55:22.480000+01:00 0 [Note] WSREP: Trying to continue unpaused monitor 89 2018-08-08T10:55:22.480032+01:00 2 [Note] WSREP: REPL Protocols: 8 (3, 2) 90 2018-08-08T10:55:22.480037+01:00 2 [Note] WSREP: New cluster view: global state: bd5525ab-9a15-11e8-aa0f-4b830c783fc7:22, view# 9: Primary, number of nodes: 1, my index: 0, protocol version 3 91 2018-08-08T10:55:22.480040+01:00 2 [Note] WSREP: Setting wsrep_ready to true 92 2018-08-08T10:55:22.480043+01:00 2 [Note] WSREP: Auto Increment Offset/Increment re-align with cluster membership change (Offset: 2 -> 1) (Increment: 2 -> 1) 93 2018-08-08T10:55:22.480046+01:00 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification. 94 2018-08-08T10:55:22.480051+01:00 2 [Note] WSREP: Assign initial position for certification: 22, protocol version: 3 95 2018-08-08T10:55:22.480060+01:00 0 [Note] WSREP: Service thread queue flushed. 96 2018-08-08T10:55:26.085271+01:00 0 [Note] WSREP: (d4006db4, 'tcp://0.0.0.0:4567') connection established to b3de093b tcp://192.168.1.102:4567 97 2018-08-08T10:55:26.085306+01:00 0 [Warning] WSREP: discarding established (time wait) b3de093b (tcp://192.168.1.102:4567) 98 2018-08-08T10:55:27.948973+01:00 0 [Note] WSREP: cleaning up b3de093b (tcp://192.168.1.102:4567) 99 100 //There's no ERROR messages at all this time.
Suplemented on August 9.
The error above was due to the parameter of "innodb_log_group_home_dir",after I omitted it,there was no error message any more.
Evidence on node zlm2.
1 //Start the PCX on node zlm2. 2 [root@zlm2 04:06:43 ~] 3 #mysqld --defaults-file=/data/mysql/mysql3308/my3308.cnf --wsrep-new-cluster & 4 [1] 4116 5 6 //The error log of node zlm2 when node zlm3 is joining the cluster. 7 2018-08-09T04:08:43.185049+01:00 0 [Note] WSREP: (13eae368, 'tcp://0.0.0.0:4567') connection established to 23fb8f7a tcp://192.168.1.102:4567 8 2018-08-09T04:08:43.185703+01:00 0 [Note] WSREP: (13eae368, 'tcp://0.0.0.0:4567') turning message relay requesting on, nonlive peers: 9 2018-08-09T04:08:43.683941+01:00 0 [Note] WSREP: declaring 23fb8f7a at tcp://192.168.1.102:4567 stable 10 2018-08-09T04:08:43.684321+01:00 0 [Note] WSREP: Node 13eae368 state primary 11 2018-08-09T04:08:43.684954+01:00 0 [Note] WSREP: Current view of cluster as seen by this node 12 view (view_id(PRIM,13eae368,2) 13 memb { 14 13eae368,0 15 23fb8f7a,0 16 } 17 joined { 18 } 19 left { 20 } 21 partitioned { 22 } 23 ) 24 2018-08-09T04:08:43.684992+01:00 0 [Note] WSREP: Save the discovered primary-component to disk 25 2018-08-09T04:08:43.685286+01:00 0 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 0, memb_num = 2 26 2018-08-09T04:08:43.685750+01:00 0 [Note] WSREP: STATE_EXCHANGE: sent state UUID: 24481910-9b79-11e8-b078-6a52474ad103 27 2018-08-09T04:08:43.688438+01:00 0 [Note] WSREP: STATE EXCHANGE: sent state msg: 24481910-9b79-11e8-b078-6a52474ad103 28 2018-08-09T04:08:43.688976+01:00 0 [Note] WSREP: STATE EXCHANGE: got state msg: 24481910-9b79-11e8-b078-6a52474ad103 from 0 (zlm2) 29 2018-08-09T04:08:44.194166+01:00 0 [Note] WSREP: STATE EXCHANGE: got state msg: 24481910-9b79-11e8-b078-6a52474ad103 from 1 (zlm3) 30 2018-08-09T04:08:44.194203+01:00 0 [Note] WSREP: Quorum results: 31 version = 4, 32 component = PRIMARY, 33 conf_id = 1, 34 members = 1/2 (primary/total), 35 act_id = 22, 36 last_appl. = 0, 37 protocols = 0/8/3 (gcs/repl/appl), 38 group UUID = bd5525ab-9a15-11e8-aa0f-4b830c783fc7 39 2018-08-09T04:08:44.194210+01:00 0 [Note] WSREP: Flow-control interval: [141, 141] 40 2018-08-09T04:08:44.194213+01:00 0 [Note] WSREP: Trying to continue unpaused monitor 41 2018-08-09T04:08:44.194278+01:00 2 [Note] WSREP: REPL Protocols: 8 (3, 2) 42 2018-08-09T04:08:44.194285+01:00 2 [Note] WSREP: New cluster view: global state: bd5525ab-9a15-11e8-aa0f-4b830c783fc7:22, view# 2: Primary, number of nodes: 2, my index: 0, protocol version 3 43 2018-08-09T04:08:44.194288+01:00 2 [Note] WSREP: Setting wsrep_ready to true 44 2018-08-09T04:08:44.194315+01:00 2 [Note] WSREP: Auto Increment Offset/Increment re-align with cluster membership change (Offset: 1 -> 1) (Increment: 1 -> 2) 45 2018-08-09T04:08:44.194320+01:00 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification. 46 2018-08-09T04:08:44.194327+01:00 2 [Note] WSREP: Assign initial position for certification: 22, protocol version: 3 47 2018-08-09T04:08:44.194337+01:00 0 [Note] WSREP: Service thread queue flushed. 48 2018-08-09T04:08:44.870138+01:00 0 [Note] WSREP: Member 1.0 (zlm3) requested state transfer from '*any*'. Selected 0.0 (zlm2)(SYNCED) as donor. 49 2018-08-09T04:08:44.870160+01:00 0 [Note] WSREP: Shifting SYNCED -> DONOR/DESYNCED (TO: 22) 50 2018-08-09T04:08:44.870209+01:00 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification. 51 2018-08-09T04:08:44.870406+01:00 0 [Note] WSREP: Initiating SST/IST transfer on DONOR side (wsrep_sst_xtrabackup-v2 --role 'donor' --address '192.168.1.102:4444/xtrabackup_sst//1' --socket '/tmp/mysql3308.sock' --datadir '/data/mysql/mysql3308/data/' --defaults-file '/data/mysql/mysql3308/my3308.cnf' --defaults-group-suffix '' --binlog '/data/mysql/mysql3308/logs/mysql-bin' --gtid 'bd5525ab-9a15-11e8-aa0f-4b830c783fc7:22') 52 2018-08-09T04:08:44.872063+01:00 2 [Note] WSREP: DONOR thread signaled with 0 53 2018-08-09T04:08:46.270023+01:00 0 [Note] WSREP: (13eae368, 'tcp://0.0.0.0:4567') turning message relay requesting off 54 2018-08-09T02:08:55.527214Z WSREP_SST: [INFO] Streaming the backup to joiner at 192.168.1.102 4444 55 2018-08-09T04:08:55.751008+01:00 4 [Note] Access denied for user 'sst'@'192.168.1.101' (using password: YES) 56 2018-08-09T04:09:03.636264+01:00 0 [Note] WSREP: 0.0 (zlm2): State transfer to 1.0 (zlm3) complete. 57 2018-08-09T04:09:03.636295+01:00 0 [Note] WSREP: Shifting DONOR/DESYNCED -> JOINED (TO: 22) 58 2018-08-09T04:09:03.647735+01:00 0 [Note] WSREP: Member 0.0 (zlm2) synced with group. 59 2018-08-09T04:09:03.647805+01:00 0 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 22) 60 2018-08-09T04:09:03.647828+01:00 2 [Note] WSREP: Synchronized with group, ready for connections 61 2018-08-09T04:09:03.647833+01:00 2 [Note] WSREP: Setting wsrep_ready to true 62 2018-08-09T04:09:03.647837+01:00 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification. 63 2018-08-09T04:09:23.739120+01:00 0 [Note] WSREP: 1.0 (zlm3): State transfer from 0.0 (zlm2) complete. 64 2018-08-09T04:09:23.739901+01:00 0 [Note] WSREP: Member 1.0 (zlm3) synced with group.
Evidence on node zlm3(using xtrabackup-v2 mothed of sst).
1 //Start the PCX on node zlm3. 2 [root@zlm3 04:08:37 /data/mysql/mysql3308] 3 #mysqld --defaults-file=/data/mysql/mysql3308/my3308.cnf & 4 [1] 3893 5 6 [root@zlm3 04:08:42 /data/mysql/mysql3308] 7 #ps aux|grep mysqld 8 mysql 3893 3.1 21.1 1574664 215668 pts/0 Sl 04:08 0:02 mysqld --defaults-file=/data/mysql/mysql3308/my3308.cnf 9 root 4537 0.0 0.0 112640 956 pts/0 R+ 04:09 0:00 grep --color=auto mysqld 10 11 //The intact error log of node zlm3 when joining the cluster. 12 [root@zlm3 04:08:31 /data/mysql/mysql3308/data] 13 #tail -f error.log 14 15 2018-08-09T04:08:43.084230+01:00 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details). 16 2018-08-09T04:08:43.089848+01:00 0 [Warning] Insecure configuration for --secure-file-priv: Location is accessible to all OS users. Consider choosing a different directory. 17 2018-08-09T04:08:43.089906+01:00 0 [Note] mysqld (mysqld 5.7.22-22-29.26-log) starting as process 3893 ... 18 2018-08-09T04:08:43.109751+01:00 0 [Note] WSREP: Setting wsrep_ready to false 19 2018-08-09T04:08:43.109768+01:00 0 [Note] WSREP: No pre-stored wsrep-start position found. Skipping position initialization. 20 2018-08-09T04:08:43.109772+01:00 0 [Note] WSREP: wsrep_load(): loading provider library '/usr/local/mysql/lib/libgalera_smm.so' 21 2018-08-09T04:08:43.129981+01:00 0 [Note] WSREP: wsrep_load(): Galera 3.26(r) by Codership Oy <info@codership.com> loaded successfully. 22 2018-08-09T04:08:43.130124+01:00 0 [Note] WSREP: CRC-32C: using hardware acceleration. 23 2018-08-09T04:08:43.130414+01:00 0 [Note] WSREP: Found saved state: 00000000-0000-0000-0000-000000000000:-1, safe_to_bootstrap: 1 24 2018-08-09T04:08:43.141875+01:00 0 [Note] WSREP: Passing config to GCS: base_dir = /data/mysql/mysql3308/data/; base_host = 192.168.1.102; base_port = 4567; cert.log_conflicts = no; debug = no; evs.auto_evict = 0; evs.delay_margin = PT1S; evs.delayed_keep_period = PT30S; evs.inactive_check_period = PT0.5S; evs.inactive_timeout = PT15S; evs.join_retrans_period = PT1S; evs.max_install_timeouts = 3; evs.send_window = 10; evs.stats_report_period = PT1M; evs.suspect_timeout = PT5S; evs.user_send_window = 4; evs.view_forget_timeout = PT24H; gcache.dir = /data/mysql/mysql3308/data/; gcache.freeze_purge_at_seqno = -1; gcache.keep_pages_count = 0; gcache.keep_pages_size = 0; gcache.mem_size = 0; gcache.name = /data/mysql/mysql3308/data//galera.cache; gcache.page_size = 128M; gcache.recover = no; gcache.size = 128M; gcomm.thread_prio = ; gcs.fc_debug = 0; gcs.fc_factor = 1; gcs.fc_limit = 100; gcs.fc_master_slave = no; gcs.max_packet_size = 64500; gcs.max_throttle = 0.25; gcs.recv_q_hard_limit = 9223372036854775807; gcs.recv_q_soft_limit = 0.25; gcs.sync_donor = no; gmcast.segment = 0; gmcast.version = 0; pc.announce_timeout = PT3S; pc.checksum = false; pc.ignore_quorum = false; pc.ignore_sb = false; pc.npvo = false; pc.recovery = 1; pc.version = 0; pc.wait_prim = true; pc.wait_prim_timeout = PT30S; pc.weight = 1; protonet.backend = asio; protonet.version = 0; repl.causal_read_timeout = PT30S; repl.commit_order = 3; repl.key_format = FLAT8; repl.max_ws_size = 2147483647; repl.proto_max = 8; socket.checksum = 2; socket.recv_buf_size = 212992; 25 2018-08-09T04:08:43.179573+01:00 0 [Note] WSREP: GCache history reset: bd5525ab-9a15-11e8-aa0f-4b830c783fc7:0 -> 00000000-0000-0000-0000-000000000000:-1 26 2018-08-09T04:08:43.183306+01:00 0 [Note] WSREP: Assign initial position for certification: -1, protocol version: -1 27 2018-08-09T04:08:43.183338+01:00 0 [Note] WSREP: Preparing to initiate SST/IST 28 2018-08-09T04:08:43.183342+01:00 0 [Note] WSREP: Starting replication 29 2018-08-09T04:08:43.183355+01:00 0 [Note] WSREP: Setting initial position to 00000000-0000-0000-0000-000000000000:-1 30 2018-08-09T04:08:43.183507+01:00 0 [Note] WSREP: Using CRC-32C for message checksums. 31 2018-08-09T04:08:43.183568+01:00 0 [Note] WSREP: gcomm thread scheduling priority set to other:0 32 2018-08-09T04:08:43.183674+01:00 0 [Warning] WSREP: Fail to access the file (/data/mysql/mysql3308/data//gvwstate.dat) error (No such file or directory). It is possible if node is booting for first time or re-booting after a graceful shutdown 33 2018-08-09T04:08:43.183679+01:00 0 [Note] WSREP: Restoring primary-component from disk failed. Either node is booting for first time or re-booting after a graceful shutdown 34 2018-08-09T04:08:43.184132+01:00 0 [Note] WSREP: GMCast version 0 35 2018-08-09T04:08:43.184337+01:00 0 [Note] WSREP: (23fb8f7a, 'tcp://0.0.0.0:4567') listening at tcp://0.0.0.0:4567 36 2018-08-09T04:08:43.184344+01:00 0 [Note] WSREP: (23fb8f7a, 'tcp://0.0.0.0:4567') multicast: , ttl: 1 37 2018-08-09T04:08:43.184483+01:00 0 [Note] WSREP: EVS version 0 38 2018-08-09T04:08:43.184957+01:00 0 [Note] WSREP: gcomm: connecting to group 'pxc_wubx', peer '192.168.1.101:,192.168.1.102:,192.168.103:' 39 2018-08-09T04:08:43.186863+01:00 0 [Note] WSREP: (23fb8f7a, 'tcp://0.0.0.0:4567') connection established to 23fb8f7a tcp://192.168.1.102:4567 40 2018-08-09T04:08:43.186895+01:00 0 [Warning] WSREP: (23fb8f7a, 'tcp://0.0.0.0:4567') address 'tcp://192.168.1.102:4567' points to own listening address, blacklisting 41 2018-08-09T04:08:43.188042+01:00 0 [Note] WSREP: (23fb8f7a, 'tcp://0.0.0.0:4567') connection established to 13eae368 tcp://192.168.1.101:4567 42 2018-08-09T04:08:43.188190+01:00 0 [Note] WSREP: (23fb8f7a, 'tcp://0.0.0.0:4567') turning message relay requesting on, nonlive peers: 43 2018-08-09T04:08:43.686789+01:00 0 [Note] WSREP: declaring 13eae368 at tcp://192.168.1.101:4567 stable 44 2018-08-09T04:08:43.687321+01:00 0 [Note] WSREP: Node 13eae368 state primary 45 2018-08-09T04:08:43.690123+01:00 0 [Note] WSREP: Current view of cluster as seen by this node 46 view (view_id(PRIM,13eae368,2) 47 memb { 48 13eae368,0 49 23fb8f7a,0 50 } 51 joined { 52 } 53 left { 54 } 55 partitioned { 56 } 57 ) 58 2018-08-09T04:08:43.690159+01:00 0 [Note] WSREP: Save the discovered primary-component to disk 59 2018-08-09T04:08:43.690256+01:00 0 [Note] WSREP: discarding pending addr without UUID: tcp://192.168.0.103:4567 60 2018-08-09T04:08:43.690263+01:00 0 [Note] WSREP: discarding pending addr proto entry 0x28b0b70 61 2018-08-09T04:08:44.185955+01:00 0 [Note] WSREP: gcomm: connected 62 2018-08-09T04:08:44.186036+01:00 0 [Note] WSREP: Shifting CLOSED -> OPEN (TO: 0) 63 2018-08-09T04:08:44.186098+01:00 0 [Note] WSREP: Waiting for SST/IST to complete. 64 2018-08-09T04:08:44.186339+01:00 0 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 1, memb_num = 2 65 2018-08-09T04:08:44.186355+01:00 0 [Note] WSREP: STATE EXCHANGE: Waiting for state UUID. 66 2018-08-09T04:08:44.186383+01:00 0 [Note] WSREP: STATE EXCHANGE: sent state msg: 24481910-9b79-11e8-b078-6a52474ad103 67 2018-08-09T04:08:44.186388+01:00 0 [Note] WSREP: STATE EXCHANGE: got state msg: 24481910-9b79-11e8-b078-6a52474ad103 from 0 (zlm2) 68 2018-08-09T04:08:44.189234+01:00 0 [Note] WSREP: STATE EXCHANGE: got state msg: 24481910-9b79-11e8-b078-6a52474ad103 from 1 (zlm3) 69 2018-08-09T04:08:44.189263+01:00 0 [Note] WSREP: Quorum results: 70 version = 4, 71 component = PRIMARY, 72 conf_id = 1, 73 members = 1/2 (primary/total), 74 act_id = 22, 75 last_appl. = -1, 76 protocols = 0/8/3 (gcs/repl/appl), 77 group UUID = bd5525ab-9a15-11e8-aa0f-4b830c783fc7 78 2018-08-09T04:08:44.189270+01:00 0 [Note] WSREP: Flow-control interval: [141, 141] 79 2018-08-09T04:08:44.189273+01:00 0 [Note] WSREP: Trying to continue unpaused monitor 80 2018-08-09T04:08:44.189277+01:00 0 [Note] WSREP: Shifting OPEN -> PRIMARY (TO: 22) 81 2018-08-09T04:08:44.189468+01:00 2 [Note] WSREP: State transfer required: 82 Group state: bd5525ab-9a15-11e8-aa0f-4b830c783fc7:22 83 Local state: 00000000-0000-0000-0000-000000000000:-1 84 2018-08-09T04:08:44.189478+01:00 2 [Note] WSREP: REPL Protocols: 8 (3, 2) 85 2018-08-09T04:08:44.189485+01:00 2 [Note] WSREP: New cluster view: global state: bd5525ab-9a15-11e8-aa0f-4b830c783fc7:22, view# 2: Primary, number of nodes: 2, my index: 1, protocol version 3 86 2018-08-09T04:08:44.189489+01:00 2 [Note] WSREP: Setting wsrep_ready to true 87 2018-08-09T04:08:44.189491+01:00 2 [Warning] WSREP: Gap in state sequence. Need state transfer. 88 2018-08-09T04:08:44.189493+01:00 2 [Note] WSREP: Setting wsrep_ready to false 89 2018-08-09T04:08:44.192795+01:00 0 [Note] WSREP: Initiating SST/IST transfer on JOINER side (wsrep_sst_xtrabackup-v2 --role 'joiner' --address '192.168.1.102' --datadir '/data/mysql/mysql3308/data/' --defaults-file '/data/mysql/mysql3308/my3308.cnf' --defaults-group-suffix '' --parent '3893' --binlog '/data/mysql/mysql3308/logs/mysql-bin' ) 90 2018-08-09T02:08:44.755132Z WSREP_SST: [WARNING] Found a stale sst_in_progress file: /data/mysql/mysql3308/data//sst_in_progress 91 2018-08-09T04:08:44.870937+01:00 2 [Note] WSREP: Prepared SST/IST request: xtrabackup-v2|192.168.1.102:4444/xtrabackup_sst//1 92 2018-08-09T04:08:44.871047+01:00 2 [Note] WSREP: Auto Increment Offset/Increment re-align with cluster membership change (Offset: 1 -> 2) (Increment: 1 -> 2) 93 2018-08-09T04:08:44.871090+01:00 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification. 94 2018-08-09T04:08:44.871140+01:00 2 [Note] WSREP: Assign initial position for certification: 22, protocol version: 3 95 2018-08-09T04:08:44.871282+01:00 0 [Note] WSREP: Service thread queue flushed. 96 2018-08-09T04:08:44.871758+01:00 2 [Note] WSREP: Check if state gap can be serviced using IST 97 2018-08-09T04:08:44.871782+01:00 2 [Note] WSREP: Local UUID: 00000000-0000-0000-0000-000000000000 != Group UUID: bd5525ab-9a15-11e8-aa0f-4b830c783fc7 98 2018-08-09T04:08:44.871834+01:00 2 [Note] WSREP: State gap can't be serviced using IST. Switching to SST 99 2018-08-09T04:08:44.871842+01:00 2 [Note] WSREP: Failed to prepare for incremental state transfer: Local state UUID (00000000-0000-0000-0000-000000000000) does not match group state UUID (bd5525ab-9a15-11e8-aa0f-4b830c783fc7): 1 (Operation not permitted) 100 at galera/src/replicator_str.cpp:prepare_for_IST():538. IST will be unavailable. 101 2018-08-09T04:08:44.872523+01:00 0 [Note] WSREP: Member 1.0 (zlm3) requested state transfer from '*any*'. Selected 0.0 (zlm2)(SYNCED) as donor. 102 2018-08-09T04:08:44.872545+01:00 0 [Note] WSREP: Shifting PRIMARY -> JOINER (TO: 22) 103 2018-08-09T04:08:44.872679+01:00 2 [Note] WSREP: Requesting state transfer: success, donor: 0 104 2018-08-09T04:08:44.872720+01:00 2 [Note] WSREP: GCache history reset: 00000000-0000-0000-0000-000000000000:0 -> bd5525ab-9a15-11e8-aa0f-4b830c783fc7:22 105 2018-08-09T02:08:45.589512Z WSREP_SST: [INFO] WARNING: Stale temporary SST directory: /data/mysql/mysql3308/data//.sst from previous state transfer. Removing 106 2018-08-09T02:08:45.608370Z WSREP_SST: [INFO] Proceeding with SST......... 107 removed ‘/data/mysql/mysql3308/logs/mysql-bin.000015’ 108 2018-08-09T02:08:45.637863Z WSREP_SST: [INFO] ............Waiting for SST streaming to complete! 109 2018-08-09T04:08:46.189014+01:00 0 [Note] WSREP: (23fb8f7a, 'tcp://0.0.0.0:4567') turning message relay requesting off 110 2018-08-09T02:09:03.636108Z WSREP_SST: [INFO] Preparing the backup at /data/mysql/mysql3308/data//.sst 111 2018-08-09T04:09:03.649250+01:00 0 [Note] WSREP: 0.0 (zlm2): State transfer to 1.0 (zlm3) complete. 112 2018-08-09T04:09:03.659780+01:00 0 [Note] WSREP: Member 0.0 (zlm2) synced with group. 113 2018-08-09T02:09:21.887135Z WSREP_SST: [INFO] Moving the backup to /data/mysql/mysql3308/data/ 114 2018-08-09T02:09:22.003073Z WSREP_SST: [INFO] Galera co-ords from recovery: bd5525ab-9a15-11e8-aa0f-4b830c783fc7:22 115 2018-08-09T04:09:22.015642+01:00 0 [Note] WSREP: SST complete, seqno: 22 116 2018-08-09T04:09:22.020459+01:00 0 [Warning] InnoDB: Using innodb_locks_unsafe_for_binlog is DEPRECATED. This option may be removed in future releases. Please use READ COMMITTED transaction isolation level instead; Please refer to http://dev.mysql.com/doc/refman/5.7/en/set-transaction.html 117 2018-08-09T04:09:22.020620+01:00 0 [Note] InnoDB: PUNCH HOLE support available 118 2018-08-09T04:09:22.020665+01:00 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins 119 2018-08-09T04:09:22.020674+01:00 0 [Note] InnoDB: Uses event mutexes 120 2018-08-09T04:09:22.020679+01:00 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier 121 2018-08-09T04:09:22.020684+01:00 0 [Note] InnoDB: Compressed tables use zlib 1.2.7 122 2018-08-09T04:09:22.020688+01:00 0 [Note] InnoDB: Using Linux native AIO 123 2018-08-09T04:09:22.020708+01:00 0 [Note] InnoDB: Adjusting innodb_buffer_pool_instances from 4 to 1 since innodb_buffer_pool_size is less than 1024 MiB 124 2018-08-09T04:09:22.021332+01:00 0 [Note] InnoDB: Number of pools: 1 125 2018-08-09T04:09:22.021561+01:00 0 [Note] InnoDB: Using CPU crc32 instructions 126 2018-08-09T04:09:22.024636+01:00 0 [Note] InnoDB: Initializing buffer pool, total size = 100M, instances = 1, chunk size = 100M 127 2018-08-09T04:09:22.027579+01:00 0 [Note] InnoDB: Completed initialization of buffer pool 128 2018-08-09T04:09:22.031734+01:00 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority(). 129 2018-08-09T04:09:22.056548+01:00 0 [Note] InnoDB: Crash recovery did not find the parallel doublewrite buffer at /data/mysql/mysql3308/data/xb_doublewrite 130 2018-08-09T04:09:22.058938+01:00 0 [Note] InnoDB: Highest supported file format is Barracuda. 131 2018-08-09T04:09:22.176951+01:00 0 [Note] InnoDB: Created parallel doublewrite buffer at /data/mysql/mysql3308/data/xb_doublewrite, size 3932160 bytes 132 2018-08-09T04:09:22.311846+01:00 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1" 133 2018-08-09T04:09:22.311867+01:00 0 [Note] InnoDB: Creating shared tablespace for temporary tables 134 2018-08-09T04:09:22.311914+01:00 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ... 135 2018-08-09T04:09:22.753228+01:00 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB. 136 2018-08-09T04:09:22.753891+01:00 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active. 137 2018-08-09T04:09:22.753902+01:00 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active. 138 2018-08-09T04:09:22.754607+01:00 0 [Note] InnoDB: Waiting for purge to start 139 2018-08-09T04:09:22.805815+01:00 0 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.7.22-rel22 started; log sequence number 2605608 140 2018-08-09T04:09:22.806243+01:00 0 [Note] Plugin 'FEDERATED' is disabled. 141 2018-08-09T04:09:22.808992+01:00 0 [Note] InnoDB: Loading buffer pool(s) from /data/mysql/mysql3308/data/ib_buffer_pool 142 2018-08-09T04:09:22.854750+01:00 0 [Note] InnoDB: Buffer pool(s) load completed at 180809 4:09:22 143 2018-08-09T04:09:22.865970+01:00 0 [Note] Recovering after a crash using /data/mysql/mysql3308/logs/mysql-bin 144 2018-08-09T04:09:22.866002+01:00 0 [Note] WSREP: Before binlog recovery (wsrep position bd5525ab-9a15-11e8-aa0f-4b830c783fc7:22) 145 2018-08-09T04:09:22.866021+01:00 0 [Note] Starting crash recovery... 146 2018-08-09T04:09:22.866046+01:00 0 [Note] Crash recovery finished. 147 2018-08-09T04:09:22.866057+01:00 0 [Note] WSREP: After binlog recovery (wsrep position bd5525ab-9a15-11e8-aa0f-4b830c783fc7:22) 148 2018-08-09T04:09:22.875798+01:00 0 [Note] Salting uuid generator variables, current_pid: 3893, server_start_time: 1533780523, bytes_sent: 0, 149 2018-08-09T04:09:22.875871+01:00 0 [Note] Generated uuid: '3ba41aa7-9b79-11e8-ad75-080027de0e0e', server_start_time: 1095782085868368224, bytes_sent: 46954208 150 2018-08-09T04:09:22.875894+01:00 0 [Warning] No existing UUID has been found, so we assume that this is the first time that this server has been started. Generating a new UUID: 3ba41aa7-9b79-11e8-ad75-080027de0e0e. 151 2018-08-09T04:09:23.579815+01:00 0 [Note] Auto generated SSL certificates are placed in data directory. 152 2018-08-09T04:09:23.580319+01:00 0 [Warning] CA certificate ca.pem is self signed. 153 2018-08-09T04:09:23.708603+01:00 0 [Note] Auto generated RSA key files are placed in data directory. 154 2018-08-09T04:09:23.708726+01:00 0 [Note] Server hostname (bind-address): '*'; port: 3308 155 2018-08-09T04:09:23.708750+01:00 0 [Note] IPv6 is available. 156 2018-08-09T04:09:23.708759+01:00 0 [Note] - '::' resolves to '::'; 157 2018-08-09T04:09:23.708775+01:00 0 [Note] Server socket created on IP: '::'. 158 2018-08-09T04:09:23.715377+01:00 0 [Warning] 'user' entry 'root@localhost' ignored in --skip-name-resolve mode. 159 2018-08-09T04:09:23.715477+01:00 0 [Warning] 'user' entry 'mysql.session@localhost' ignored in --skip-name-resolve mode. 160 2018-08-09T04:09:23.715490+01:00 0 [Warning] 'user' entry 'mysql.sys@localhost' ignored in --skip-name-resolve mode. 161 2018-08-09T04:09:23.715499+01:00 0 [Warning] 'user' entry 'sst@localhost' ignored in --skip-name-resolve mode. 162 2018-08-09T04:09:23.715539+01:00 0 [Warning] 'db' entry 'performance_schema mysql.session@localhost' ignored in --skip-name-resolve mode. 163 2018-08-09T04:09:23.715548+01:00 0 [Warning] 'db' entry 'sys mysql.sys@localhost' ignored in --skip-name-resolve mode. 164 2018-08-09T04:09:23.715559+01:00 0 [Warning] 'proxies_priv' entry '@ root@localhost' ignored in --skip-name-resolve mode. 165 2018-08-09T04:09:23.716731+01:00 0 [Warning] 'tables_priv' entry 'user mysql.session@localhost' ignored in --skip-name-resolve mode. 166 2018-08-09T04:09:23.716749+01:00 0 [Warning] 'tables_priv' entry 'sys_config mysql.sys@localhost' ignored in --skip-name-resolve mode. 167 2018-08-09T04:09:23.739950+01:00 0 [Note] Event Scheduler: Loaded 0 events 168 2018-08-09T04:09:23.740507+01:00 0 [Note] WSREP: Signalling provider to continue on SST completion. 169 2018-08-09T04:09:23.740531+01:00 0 [Note] WSREP: Initialized wsrep sidno 2 170 2018-08-09T04:09:23.740553+01:00 0 [Note] WSREP: SST received: bd5525ab-9a15-11e8-aa0f-4b830c783fc7:22 171 2018-08-09T04:09:23.740631+01:00 0 [Note] mysqld: ready for connections. 172 Version: '5.7.22-22-29.26-log' socket: '/tmp/mysql3308.sock' port: 3308 Percona XtraDB Cluster binary (GPL) 5.7.22-29.26, Revision da86071, wsrep_29.26 173 2018-08-09T04:09:23.741168+01:00 0 [Note] WSREP: 1.0 (zlm3): State transfer from 0.0 (zlm2) complete. 174 2018-08-09T04:09:23.741191+01:00 0 [Note] WSREP: SST leaving flow control 175 2018-08-09T04:09:23.741196+01:00 0 [Note] WSREP: Shifting JOINER -> JOINED (TO: 22) 176 2018-08-09T04:09:23.742029+01:00 0 [Note] WSREP: Member 1.0 (zlm3) synced with group. 177 2018-08-09T04:09:23.742059+01:00 0 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 22) 178 2018-08-09T04:09:23.742077+01:00 2 [Note] WSREP: Synchronized with group, ready for connections 179 2018-08-09T04:09:23.742082+01:00 2 [Note] WSREP: Setting wsrep_ready to true 180 2018-08-09T04:09:23.742087+01:00 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
Evidence on node zlm4(using rsync mothed of sst).
1 //Change the parameter "wsrep_sst_method" into "rysnc" in my3308.cnf file. 2 #loose-wsrep_sst_method=xtrabackup-v2 3 loose-wsrep_sst_method=rsync 4 5 [root@zlm4 07:51:38 /data/mysql/mysql3308/data] 6 #tail -f error.log 7 2018-08-09T07:52:21.038606+01:00 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details). 8 2018-08-09T07:52:21.041387+01:00 0 [Warning] Insecure configuration for --secure-file-priv: Location is accessible to all OS users. Consider choosing a different directory. 9 2018-08-09T07:52:21.041490+01:00 0 [Note] mysqld (mysqld 5.7.22-22-29.26-log) starting as process 5205 ... 10 2018-08-09T07:52:21.044740+01:00 0 [Note] WSREP: Setting wsrep_ready to false 11 2018-08-09T07:52:21.044761+01:00 0 [Note] WSREP: No pre-stored wsrep-start position found. Skipping position initialization. 12 2018-08-09T07:52:21.044767+01:00 0 [Note] WSREP: wsrep_load(): loading provider library '/usr/local/mysql/lib/libgalera_smm.so' 13 2018-08-09T07:52:21.050035+01:00 0 [Note] WSREP: wsrep_load(): Galera 3.26(r) by Codership Oy <info@codership.com> loaded successfully. 14 2018-08-09T07:52:21.050186+01:00 0 [Note] WSREP: CRC-32C: using hardware acceleration. 15 2018-08-09T07:52:21.050565+01:00 0 [Warning] WSREP: Could not open state file for reading: '/data/mysql/mysql3308/data//grastate.dat' 16 2018-08-09T07:52:21.050585+01:00 0 [Warning] WSREP: No persistent state found. Bootstraping with default state 17 2018-08-09T07:52:21.050637+01:00 0 [Note] WSREP: Found saved state: 00000000-0000-0000-0000-000000000000:-1, safe_to_bootstrap: 1 18 2018-08-09T07:52:21.055209+01:00 0 [Note] WSREP: Passing config to GCS: base_dir = /data/mysql/mysql3308/data/; base_host = 192.168.1.103; base_port = 4567; cert.log_conflicts = no; debug = no; evs.auto_evict = 0; evs.delay_margin = PT1S; evs.delayed_keep_period = PT30S; evs.inactive_check_period = PT0.5S; evs.inactive_timeout = PT15S; evs.join_retrans_period = PT1S; evs.max_install_timeouts = 3; evs.send_window = 10; evs.stats_report_period = PT1M; evs.suspect_timeout = PT5S; evs.user_send_window = 4; evs.view_forget_timeout = PT24H; gcache.dir = /data/mysql/mysql3308/data/; gcache.freeze_purge_at_seqno = -1; gcache.keep_pages_count = 0; gcache.keep_pages_size = 0; gcache.mem_size = 0; gcache.name = /data/mysql/mysql3308/data//galera.cache; gcache.page_size = 128M; gcache.recover = no; gcache.size = 128M; gcomm.thread_prio = ; gcs.fc_debug = 0; gcs.fc_factor = 1; gcs.fc_limit = 100; gcs.fc_master_slave = no; gcs.max_packet_size = 64500; gcs.max_throttle = 0.25; gcs.recv_q_hard_limit = 9223372036854775807; gcs.recv_q_soft_limit = 0.25; gcs.sync_donor = no; gmcast.segment = 0; gmcast.version = 0; pc.announce_timeout = PT3S; pc.checksum = false; pc.ignore_quorum = false; pc.ignore_sb = false; pc.npvo = false; pc.recovery = 1; pc.version = 0; pc.wait_prim = true; pc.wait_prim_timeout = PT30S; pc.weight = 1; protonet.backend = asio; protonet.version = 0; repl.causal_read_timeout = PT30S; repl.commit_order = 3; repl.key_format = FLAT8; repl.max_ws_size = 2147483647; repl.proto_max = 8; socket.checksum = 2; socket.recv_buf_size = 212992; 19 2018-08-09T07:52:21.069257+01:00 0 [Note] WSREP: GCache history reset: 00000000-0000-0000-0000-000000000000:0 -> 00000000-0000-0000-0000-000000000000:-1 20 2018-08-09T07:52:21.071550+01:00 0 [Note] WSREP: Assign initial position for certification: -1, protocol version: -1 21 2018-08-09T07:52:21.071584+01:00 0 [Note] WSREP: Preparing to initiate SST/IST 22 2018-08-09T07:52:21.071589+01:00 0 [Note] WSREP: Starting replication 23 2018-08-09T07:52:21.071606+01:00 0 [Note] WSREP: Setting initial position to 00000000-0000-0000-0000-000000000000:-1 24 2018-08-09T07:52:21.071812+01:00 0 [Note] WSREP: Using CRC-32C for message checksums. 25 2018-08-09T07:52:21.071888+01:00 0 [Note] WSREP: gcomm thread scheduling priority set to other:0 26 2018-08-09T07:52:21.072021+01:00 0 [Warning] WSREP: Fail to access the file (/data/mysql/mysql3308/data//gvwstate.dat) error (No such file or directory). It is possible if node is booting for first time or re-booting after a graceful shutdown 27 2018-08-09T07:52:21.072030+01:00 0 [Note] WSREP: Restoring primary-component from disk failed. Either node is booting for first time or re-booting after a graceful shutdown 28 2018-08-09T07:52:21.072800+01:00 0 [Note] WSREP: GMCast version 0 29 2018-08-09T07:52:21.072942+01:00 0 [Note] WSREP: (61aad7a7, 'tcp://0.0.0.0:4567') listening at tcp://0.0.0.0:4567 30 2018-08-09T07:52:21.072942+01:00 0 [Note] WSREP: (61aad7a7, 'tcp://0.0.0.0:4567') multicast: , ttl: 1 31 2018-08-09T07:52:21.073357+01:00 0 [Note] WSREP: EVS version 0 32 2018-08-09T07:52:21.073926+01:00 0 [Note] WSREP: gcomm: connecting to group 'pxc_wubx', peer '192.168.1.101:,192.168.1.102:,192.168.1.103:' 33 2018-08-09T07:52:21.076189+01:00 0 [Note] WSREP: (61aad7a7, 'tcp://0.0.0.0:4567') connection established to 61aad7a7 tcp://192.168.1.103:4567 34 2018-08-09T07:52:21.076220+01:00 0 [Warning] WSREP: (61aad7a7, 'tcp://0.0.0.0:4567') address 'tcp://192.168.1.103:4567' points to own listening address, blacklisting 35 2018-08-09T07:52:21.078146+01:00 0 [Note] WSREP: (61aad7a7, 'tcp://0.0.0.0:4567') connection established to 13eae368 tcp://192.168.1.101:4567 36 2018-08-09T07:52:21.078312+01:00 0 [Note] WSREP: (61aad7a7, 'tcp://0.0.0.0:4567') turning message relay requesting on, nonlive peers: 37 2018-08-09T07:52:21.080311+01:00 0 [Note] WSREP: (61aad7a7, 'tcp://0.0.0.0:4567') connection established to 23fb8f7a tcp://192.168.1.102:4567 38 2018-08-09T07:52:21.583579+01:00 0 [Note] WSREP: declaring 13eae368 at tcp://192.168.1.101:4567 stable 39 2018-08-09T07:52:21.583614+01:00 0 [Note] WSREP: declaring 23fb8f7a at tcp://192.168.1.102:4567 stable 40 2018-08-09T07:52:21.584818+01:00 0 [Note] WSREP: Node 13eae368 state primary 41 2018-08-09T07:52:21.589478+01:00 0 [Note] WSREP: Current view of cluster as seen by this node 42 view (view_id(PRIM,13eae368,9) 43 memb { 44 13eae368,0 45 23fb8f7a,0 46 61aad7a7,0 47 } 48 joined { 49 } 50 left { 51 } 52 partitioned { 53 } 54 ) 55 2018-08-09T07:52:21.589519+01:00 0 [Note] WSREP: Save the discovered primary-component to disk 56 2018-08-09T07:52:22.075191+01:00 0 [Note] WSREP: gcomm: connected 57 2018-08-09T07:52:22.075272+01:00 0 [Note] WSREP: Shifting CLOSED -> OPEN (TO: 0) 58 2018-08-09T07:52:22.075348+01:00 0 [Note] WSREP: Waiting for SST/IST to complete. 59 2018-08-09T07:52:22.075642+01:00 0 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 2, memb_num = 3 60 2018-08-09T07:52:22.075658+01:00 0 [Note] WSREP: STATE EXCHANGE: Waiting for state UUID. 61 2018-08-09T07:52:22.075689+01:00 0 [Note] WSREP: STATE EXCHANGE: sent state msg: 61f621e1-9b98-11e8-a772-bfae300f8d05 62 2018-08-09T07:52:22.075697+01:00 0 [Note] WSREP: STATE EXCHANGE: got state msg: 61f621e1-9b98-11e8-a772-bfae300f8d05 from 0 (zlm2) 63 2018-08-09T07:52:22.075704+01:00 0 [Note] WSREP: STATE EXCHANGE: got state msg: 61f621e1-9b98-11e8-a772-bfae300f8d05 from 1 (zlm3) 64 2018-08-09T07:52:22.077812+01:00 0 [Note] WSREP: STATE EXCHANGE: got state msg: 61f621e1-9b98-11e8-a772-bfae300f8d05 from 2 (zlm4) 65 2018-08-09T07:52:22.077845+01:00 0 [Note] WSREP: Quorum results: 66 version = 4, 67 component = PRIMARY, 68 conf_id = 8, 69 members = 2/3 (primary/total), 70 act_id = 22, 71 last_appl. = -1, 72 protocols = 0/8/3 (gcs/repl/appl), 73 group UUID = bd5525ab-9a15-11e8-aa0f-4b830c783fc7 74 2018-08-09T07:52:22.077853+01:00 0 [Note] WSREP: Flow-control interval: [173, 173] 75 2018-08-09T07:52:22.077858+01:00 0 [Note] WSREP: Trying to continue unpaused monitor 76 2018-08-09T07:52:22.077864+01:00 0 [Note] WSREP: Shifting OPEN -> PRIMARY (TO: 22) 77 2018-08-09T07:52:22.077926+01:00 2 [Note] WSREP: State transfer required: 78 Group state: bd5525ab-9a15-11e8-aa0f-4b830c783fc7:22 79 Local state: 00000000-0000-0000-0000-000000000000:-1 80 2018-08-09T07:52:22.077935+01:00 2 [Note] WSREP: REPL Protocols: 8 (3, 2) 81 2018-08-09T07:52:22.077943+01:00 2 [Note] WSREP: New cluster view: global state: bd5525ab-9a15-11e8-aa0f-4b830c783fc7:22, view# 9: Primary, number of nodes: 3, my index: 2, protocol version 3 82 2018-08-09T07:52:22.077948+01:00 2 [Note] WSREP: Setting wsrep_ready to true 83 2018-08-09T07:52:22.077951+01:00 2 [Warning] WSREP: Gap in state sequence. Need state transfer. 84 2018-08-09T07:52:22.077954+01:00 2 [Note] WSREP: Setting wsrep_ready to false 85 2018-08-09T07:52:22.078033+01:00 0 [Note] WSREP: Initiating SST/IST transfer on JOINER side (wsrep_sst_rsync --role 'joiner' --address '192.168.1.103' --datadir '/data/mysql/mysql3308/data/' --defaults-file '/data/mysql/mysql3308/my3308.cnf' --defaults-group-suffix '' --parent '5205' --binlog '/data/mysql/mysql3308/logs/mysql-bin' ) 86 which: no lsof in (/usr/sbin:/sbin:/opt/mysql/Percona-XtraDB-Cluster-5.7.22-rel22-29.26.1.Linux.x86_64.ssl102/bin:/root/perl5/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/root/bin:/usr/local/mysql/bin:/usr/local/zabbix/bin:/usr/local/zabbix/sbin) 87 2018-08-09T07:52:22.254544+01:00 0 [ERROR] WSREP: Failed to read 'ready <addr>' from: wsrep_sst_rsync --role 'joiner' --address '192.168.1.103' --datadir '/data/mysql/mysql3308/data/' --defaults-file '/data/mysql/mysql3308/my3308.cnf' --defaults-group-suffix '' --parent '5205' --binlog '/data/mysql/mysql3308/logs/mysql-bin' 88 Read: ''lsof' not found in PATH' //Here's the important message of error but has not "ERROR" keyword in the same line.So I've almost missed it. 89 2018-08-09T07:52:22.254571+01:00 0 [ERROR] WSREP: Process completed with error: wsrep_sst_rsync --role 'joiner' --address '192.168.1.103' --datadir '/data/mysql/mysql3308/data/' --defaults-file '/data/mysql/mysql3308/my3308.cnf' --defaults-group-suffix '' --parent '5205' --binlog '/data/mysql/mysql3308/logs/mysql-bin' : 2 (No such file or directory) 90 2018-08-09T07:52:22.254631+01:00 2 [ERROR] WSREP: Failed to prepare for 'rsync' SST. Unrecoverable. 91 2018-08-09T07:52:22.254639+01:00 2 [ERROR] Aborting 92 93 2018-08-09T07:52:22.254643+01:00 2 [Note] Giving 2 client threads a chance to die gracefully 94 2018-08-09T07:52:24.254907+01:00 2 [Note] WSREP: Closing send monitor... 95 2018-08-09T07:52:24.254992+01:00 2 [Note] WSREP: Closed send monitor. 96 2018-08-09T07:52:24.255028+01:00 2 [Note] WSREP: gcomm: terminating thread 97 2018-08-09T07:52:24.255042+01:00 2 [Note] WSREP: gcomm: joining thread 98 2018-08-09T07:52:24.255061+01:00 1 [Note] WSREP: rollbacker thread exiting 99 2018-08-09T07:52:24.255377+01:00 2 [Note] WSREP: gcomm: closing backend 100 2018-08-09T07:52:24.260692+01:00 2 [Note] WSREP: Current view of cluster as seen by this node 101 view (view_id(NON_PRIM,13eae368,9) 102 memb { 103 61aad7a7,0 104 } 105 joined { 106 } 107 left { 108 } 109 partitioned { 110 13eae368,0 111 23fb8f7a,0 112 } 113 ) 114 2018-08-09T07:52:24.260770+01:00 2 [Note] WSREP: (61aad7a7, 'tcp://0.0.0.0:4567') turning message relay requesting off 115 2018-08-09T07:52:24.260814+01:00 2 [Note] WSREP: Current view of cluster as seen by this node 116 view ((empty)) 117 2018-08-09T07:52:24.261439+01:00 2 [Note] WSREP: gcomm: closed 118 2018-08-09T07:52:24.261690+01:00 0 [Note] WSREP: New COMPONENT: primary = no, bootstrap = no, my_idx = 0, memb_num = 1 119 2018-08-09T07:52:24.261741+01:00 0 [Note] WSREP: Flow-control interval: [100, 100] 120 2018-08-09T07:52:24.261746+01:00 0 [Note] WSREP: Trying to continue unpaused monitor 121 2018-08-09T07:52:24.261753+01:00 0 [Note] WSREP: Received NON-PRIMARY. 122 2018-08-09T07:52:24.261758+01:00 0 [Note] WSREP: Shifting PRIMARY -> OPEN (TO: 22) 123 2018-08-09T07:52:24.261767+01:00 0 [Note] WSREP: Received self-leave message. 124 2018-08-09T07:52:24.261774+01:00 0 [Note] WSREP: Flow-control interval: [0, 0] 125 2018-08-09T07:52:24.261777+01:00 0 [Note] WSREP: Trying to continue unpaused monitor 126 2018-08-09T07:52:24.261780+01:00 0 [Note] WSREP: Received SELF-LEAVE. Closing connection. 127 2018-08-09T07:52:24.261784+01:00 0 [Note] WSREP: Shifting OPEN -> CLOSED (TO: 22) 128 2018-08-09T07:52:24.261794+01:00 0 [Note] WSREP: RECV thread exiting 0: Success 129 2018-08-09T07:52:24.262101+01:00 2 [Note] WSREP: recv_thread() joined. 130 2018-08-09T07:52:24.262113+01:00 2 [Note] WSREP: Closing replication queue. 131 2018-08-09T07:52:24.262117+01:00 2 [Note] WSREP: Closing slave action queue. 132 2018-08-09T07:52:24.262162+01:00 0 [Note] WSREP: Waiting for active wsrep applier to exit 133 2018-08-09T07:52:24.262170+01:00 0 [Note] WSREP: Service disconnected. 134 2018-08-09T07:52:24.262173+01:00 0 [Note] WSREP: Waiting to close threads...... 135 2018-08-09T07:52:29.262290+01:00 0 [Note] WSREP: Some threads may fail to exit. 136 2018-08-09T07:52:29.262337+01:00 0 [Note] Binlog end 137 2018-08-09T07:52:29.262596+01:00 0 [Note] mysqld: Shutdown complete 138 139 //Install lsof tool. 140 [root@zlm4 07:58:19 /data/mysql/mysql3308] 141 #yum -y install lsof 142 ... //Omitted. 143 144 Installed: 145 lsof.x86_64 0:4.87-5.el7 146 147 Complete! 148 149 //Start the node again. 150 [root@zlm4 07:59:47 /data/mysql/mysql3308] 151 #mysqld --defaults-file=/data/mysql/mysql3308/my3308.cnf & 152 [1] 5367 153 154 [root@zlm4 08:00:02 /data/mysql/mysql3308] 155 #jobs 156 [1]+ Running mysqld --defaults-file=/data/mysql/mysql3308/my3308.cnf & 157 158 //Check the error log again. 159 [root@zlm4 08:59:38 /data/mysql/mysql3308/data] 160 #tail -f error.log 161 2018-08-09T08:00:02.899495+01:00 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details). 162 2018-08-09T08:00:02.900253+01:00 0 [Warning] Insecure configuration for --secure-file-priv: Location is accessible to all OS users. Consider choosing a different directory. 163 2018-08-09T08:00:02.900326+01:00 0 [Note] mysqld (mysqld 5.7.22-22-29.26-log) starting as process 5367 ... 164 2018-08-09T08:00:02.902758+01:00 0 [Note] WSREP: Setting wsrep_ready to false 165 2018-08-09T08:00:02.902772+01:00 0 [Note] WSREP: No pre-stored wsrep-start position found. Skipping position initialization. 166 2018-08-09T08:00:02.902776+01:00 0 [Note] WSREP: wsrep_load(): loading provider library '/usr/local/mysql/lib/libgalera_smm.so' 167 2018-08-09T08:00:02.906503+01:00 0 [Note] WSREP: wsrep_load(): Galera 3.26(r) by Codership Oy <info@codership.com> loaded successfully. 168 2018-08-09T08:00:02.906567+01:00 0 [Note] WSREP: CRC-32C: using hardware acceleration. 169 2018-08-09T08:00:02.906904+01:00 0 [Note] WSREP: Found saved state: 00000000-0000-0000-0000-000000000000:-1, safe_to_bootstrap: 1 170 2018-08-09T08:00:02.911237+01:00 0 [Note] WSREP: Passing config to GCS: base_dir = /data/mysql/mysql3308/data/; base_host = 192.168.1.103; base_port = 4567; cert.log_conflicts = no; debug = no; evs.auto_evict = 0; evs.delay_margin = PT1S; evs.delayed_keep_period = PT30S; evs.inactive_check_period = PT0.5S; evs.inactive_timeout = PT15S; evs.join_retrans_period = PT1S; evs.max_install_timeouts = 3; evs.send_window = 10; evs.stats_report_period = PT1M; evs.suspect_timeout = PT5S; evs.user_send_window = 4; evs.view_forget_timeout = PT24H; gcache.dir = /data/mysql/mysql3308/data/; gcache.freeze_purge_at_seqno = -1; gcache.keep_pages_count = 0; gcache.keep_pages_size = 0; gcache.mem_size = 0; gcache.name = /data/mysql/mysql3308/data//galera.cache; gcache.page_size = 128M; gcache.recover = no; gcache.size = 128M; gcomm.thread_prio = ; gcs.fc_debug = 0; gcs.fc_factor = 1; gcs.fc_limit = 100; gcs.fc_master_slave = no; gcs.max_packet_size = 64500; gcs.max_throttle = 0.25; gcs.recv_q_hard_limit = 9223372036854775807; gcs.recv_q_soft_limit = 0.25; gcs.sync_donor = no; gmcast.segment = 0; gmcast.version = 0; pc.announce_timeout = PT3S; pc.checksum = false; pc.ignore_quorum = false; pc.ignore_sb = false; pc.npvo = false; pc.recovery = 1; pc.version = 0; pc.wait_prim = true; pc.wait_prim_timeout = PT30S; pc.weight = 1; protonet.backend = asio; protonet.version = 0; repl.causal_read_timeout = PT30S; repl.commit_order = 3; repl.key_format = FLAT8; repl.max_ws_size = 2147483647; repl.proto_max = 8; socket.checksum = 2; socket.recv_buf_size = 212992; 171 2018-08-09T08:00:02.921480+01:00 0 [Note] WSREP: GCache history reset: 00000000-0000-0000-0000-000000000000:0 -> 00000000-0000-0000-0000-000000000000:-1 172 2018-08-09T08:00:02.923600+01:00 0 [Note] WSREP: Assign initial position for certification: -1, protocol version: -1 173 2018-08-09T08:00:02.923636+01:00 0 [Note] WSREP: Preparing to initiate SST/IST 174 2018-08-09T08:00:02.923639+01:00 0 [Note] WSREP: Starting replication 175 2018-08-09T08:00:02.923652+01:00 0 [Note] WSREP: Setting initial position to 00000000-0000-0000-0000-000000000000:-1 176 2018-08-09T08:00:02.923845+01:00 0 [Note] WSREP: Using CRC-32C for message checksums. 177 2018-08-09T08:00:02.923912+01:00 0 [Note] WSREP: gcomm thread scheduling priority set to other:0 178 2018-08-09T08:00:02.923991+01:00 0 [Warning] WSREP: Fail to access the file (/data/mysql/mysql3308/data//gvwstate.dat) error (No such file or directory). It is possible if node is booting for first time or re-booting after a graceful shutdown 179 2018-08-09T08:00:02.923996+01:00 0 [Note] WSREP: Restoring primary-component from disk failed. Either node is booting for first time or re-booting after a graceful shutdown 180 2018-08-09T08:00:02.924673+01:00 0 [Note] WSREP: GMCast version 0 181 2018-08-09T08:00:02.924779+01:00 0 [Note] WSREP: (74f3db69, 'tcp://0.0.0.0:4567') listening at tcp://0.0.0.0:4567 182 2018-08-09T08:00:02.924779+01:00 0 [Note] WSREP: (74f3db69, 'tcp://0.0.0.0:4567') multicast: , ttl: 1 183 2018-08-09T08:00:02.925300+01:00 0 [Note] WSREP: EVS version 0 184 2018-08-09T08:00:02.925433+01:00 0 [Note] WSREP: gcomm: connecting to group 'pxc_wubx', peer '192.168.1.101:,192.168.1.102:,192.168.1.103:' 185 2018-08-09T08:00:02.928124+01:00 0 [Note] WSREP: (74f3db69, 'tcp://0.0.0.0:4567') connection established to 74f3db69 tcp://192.168.1.103:4567 186 2018-08-09T08:00:02.928158+01:00 0 [Warning] WSREP: (74f3db69, 'tcp://0.0.0.0:4567') address 'tcp://192.168.1.103:4567' points to own listening address, blacklisting 187 2018-08-09T08:00:02.928505+01:00 0 [Note] WSREP: (74f3db69, 'tcp://0.0.0.0:4567') connection established to 13eae368 tcp://192.168.1.101:4567 188 2018-08-09T08:00:02.929670+01:00 0 [Note] WSREP: (74f3db69, 'tcp://0.0.0.0:4567') turning message relay requesting on, nonlive peers: 189 2018-08-09T08:00:02.929755+01:00 0 [Note] WSREP: (74f3db69, 'tcp://0.0.0.0:4567') connection established to 23fb8f7a tcp://192.168.1.102:4567 190 2018-08-09T08:00:03.429892+01:00 0 [Note] WSREP: declaring 13eae368 at tcp://192.168.1.101:4567 stable 191 2018-08-09T08:00:03.429916+01:00 0 [Note] WSREP: declaring 23fb8f7a at tcp://192.168.1.102:4567 stable 192 2018-08-09T08:00:03.431850+01:00 0 [Note] WSREP: Node 13eae368 state primary 193 2018-08-09T08:00:03.434752+01:00 0 [Note] WSREP: Current view of cluster as seen by this node 194 view (view_id(PRIM,13eae368,11) 195 memb { 196 13eae368,0 197 23fb8f7a,0 198 74f3db69,0 199 } 200 joined { 201 } 202 left { 203 } 204 partitioned { 205 } 206 ) 207 2018-08-09T08:00:03.434779+01:00 0 [Note] WSREP: Save the discovered primary-component to disk 208 2018-08-09T08:00:03.927902+01:00 0 [Note] WSREP: gcomm: connected 209 2018-08-09T08:00:03.927980+01:00 0 [Note] WSREP: Shifting CLOSED -> OPEN (TO: 0) 210 2018-08-09T08:00:03.928042+01:00 0 [Note] WSREP: Waiting for SST/IST to complete. 211 2018-08-09T08:00:03.928251+01:00 0 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 2, memb_num = 3 212 2018-08-09T08:00:03.928261+01:00 0 [Note] WSREP: STATE EXCHANGE: Waiting for state UUID. 213 2018-08-09T08:00:03.928285+01:00 0 [Note] WSREP: STATE EXCHANGE: sent state msg: 753e350b-9b99-11e8-be59-b7e1945f65e8 214 2018-08-09T08:00:03.928290+01:00 0 [Note] WSREP: STATE EXCHANGE: got state msg: 753e350b-9b99-11e8-be59-b7e1945f65e8 from 0 (zlm2) 215 2018-08-09T08:00:03.928294+01:00 0 [Note] WSREP: STATE EXCHANGE: got state msg: 753e350b-9b99-11e8-be59-b7e1945f65e8 from 1 (zlm3) 216 2018-08-09T08:00:03.929335+01:00 0 [Note] WSREP: STATE EXCHANGE: got state msg: 753e350b-9b99-11e8-be59-b7e1945f65e8 from 2 (zlm4) 217 2018-08-09T08:00:03.929361+01:00 0 [Note] WSREP: Quorum results: 218 version = 4, 219 component = PRIMARY, 220 conf_id = 10, 221 members = 2/3 (primary/total), 222 act_id = 22, 223 last_appl. = -1, 224 protocols = 0/8/3 (gcs/repl/appl), 225 group UUID = bd5525ab-9a15-11e8-aa0f-4b830c783fc7 226 2018-08-09T08:00:03.929366+01:00 0 [Note] WSREP: Flow-control interval: [173, 173] 227 2018-08-09T08:00:03.929369+01:00 0 [Note] WSREP: Trying to continue unpaused monitor 228 2018-08-09T08:00:03.929372+01:00 0 [Note] WSREP: Shifting OPEN -> PRIMARY (TO: 22) 229 2018-08-09T08:00:03.929413+01:00 2 [Note] WSREP: State transfer required: 230 Group state: bd5525ab-9a15-11e8-aa0f-4b830c783fc7:22 231 Local state: 00000000-0000-0000-0000-000000000000:-1 232 2018-08-09T08:00:03.929419+01:00 2 [Note] WSREP: REPL Protocols: 8 (3, 2) 233 2018-08-09T08:00:03.929425+01:00 2 [Note] WSREP: New cluster view: global state: bd5525ab-9a15-11e8-aa0f-4b830c783fc7:22, view# 11: Primary, number of nodes: 3, my index: 2, protocol version 3 234 2018-08-09T08:00:03.929428+01:00 2 [Note] WSREP: Setting wsrep_ready to true 235 2018-08-09T08:00:03.929430+01:00 2 [Warning] WSREP: Gap in state sequence. Need state transfer. 236 2018-08-09T08:00:03.929432+01:00 2 [Note] WSREP: Setting wsrep_ready to false 237 2018-08-09T08:00:03.929496+01:00 0 [Note] WSREP: Initiating SST/IST transfer on JOINER side (wsrep_sst_rsync --role 'joiner' --address '192.168.1.103' --datadir '/data/mysql/mysql3308/data/' --defaults-file '/data/mysql/mysql3308/my3308.cnf' --defaults-group-suffix '' --parent '5367' --binlog '/data/mysql/mysql3308/logs/mysql-bin' ) 238 2018-08-09T06:00:04.047845Z WSREP_SST: [INFO] Waiting for data-dir through rsync................ //Begin to transfer data using rsync mode. 239 2018-08-09T08:00:04.319479+01:00 2 [Note] WSREP: Prepared SST/IST request: rsync|192.168.1.103:4444/rsync_sst 240 2018-08-09T08:00:04.319504+01:00 2 [Note] WSREP: Auto Increment Offset/Increment re-align with cluster membership change (Offset: 1 -> 3) (Increment: 1 -> 3) 241 2018-08-09T08:00:04.319510+01:00 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification. 242 2018-08-09T08:00:04.319527+01:00 2 [Note] WSREP: Assign initial position for certification: 22, protocol version: 3 243 2018-08-09T08:00:04.319546+01:00 0 [Note] WSREP: Service thread queue flushed. 244 2018-08-09T08:00:04.319558+01:00 2 [Note] WSREP: Check if state gap can be serviced using IST 245 2018-08-09T08:00:04.319566+01:00 2 [Note] WSREP: Local UUID: 00000000-0000-0000-0000-000000000000 != Group UUID: bd5525ab-9a15-11e8-aa0f-4b830c783fc7 246 2018-08-09T08:00:04.319598+01:00 2 [Note] WSREP: State gap can't be serviced using IST. Switching to SST 247 2018-08-09T08:00:04.319602+01:00 2 [Note] WSREP: Failed to prepare for incremental state transfer: Local state UUID (00000000-0000-0000-0000-000000000000) does not match group state UUID (bd5525ab-9a15-11e8-aa0f-4b830c783fc7): 1 (Operation not permitted) 248 at galera/src/replicator_str.cpp:prepare_for_IST():538. IST will be unavailable. 249 2018-08-09T08:00:04.321186+01:00 0 [Note] WSREP: Member 2.0 (zlm4) requested state transfer from '*any*'. Selected 0.0 (zlm2)(SYNCED) as donor. 250 2018-08-09T08:00:04.321208+01:00 0 [Note] WSREP: Shifting PRIMARY -> JOINER (TO: 22) 251 2018-08-09T08:00:04.321275+01:00 2 [Note] WSREP: Requesting state transfer: success, donor: 0 252 2018-08-09T08:00:04.321291+01:00 2 [Note] WSREP: GCache history reset: 00000000-0000-0000-0000-000000000000:0 -> bd5525ab-9a15-11e8-aa0f-4b830c783fc7:22 253 2018-08-09T08:00:05.939711+01:00 0 [Note] WSREP: (74f3db69, 'tcp://0.0.0.0:4567') turning message relay requesting off 254 2018-08-09T08:00:26.343649+01:00 0 [Note] WSREP: 0.0 (zlm2): State transfer to 2.0 (zlm4) complete. 255 2018-08-09T08:00:26.344408+01:00 0 [Note] WSREP: Member 0.0 (zlm2) synced with group. 256 2018-08-09T06:00:26.399740Z WSREP_SST: [INFO] ..............rsync completed //Finished rsync transfer. 257 2018-08-09T08:00:26.929160+01:00 0 [Note] WSREP: SST complete, seqno: 22 258 2018-08-09T08:00:27.003561+01:00 0 [Warning] InnoDB: Using innodb_locks_unsafe_for_binlog is DEPRECATED. This option may be removed in future releases. Please use READ COMMITTED transaction isolation level instead; Please refer to http://dev.mysql.com/doc/refman/5.7/en/set-transaction.html 259 2018-08-09T08:00:27.003682+01:00 0 [Note] InnoDB: PUNCH HOLE support available 260 2018-08-09T08:00:27.003696+01:00 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins 261 2018-08-09T08:00:27.003701+01:00 0 [Note] InnoDB: Uses event mutexes 262 2018-08-09T08:00:27.003705+01:00 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier 263 2018-08-09T08:00:27.003710+01:00 0 [Note] InnoDB: Compressed tables use zlib 1.2.7 264 2018-08-09T08:00:27.003715+01:00 0 [Note] InnoDB: Using Linux native AIO 265 2018-08-09T08:00:27.003734+01:00 0 [Note] InnoDB: Adjusting innodb_buffer_pool_instances from 4 to 1 since innodb_buffer_pool_size is less than 1024 MiB 266 2018-08-09T08:00:27.004212+01:00 0 [Note] InnoDB: Number of pools: 1 267 2018-08-09T08:00:27.004325+01:00 0 [Note] InnoDB: Using CPU crc32 instructions 268 2018-08-09T08:00:27.010477+01:00 0 [Note] InnoDB: Initializing buffer pool, total size = 100M, instances = 1, chunk size = 100M 269 2018-08-09T08:00:27.019767+01:00 0 [Note] InnoDB: Completed initialization of buffer pool 270 2018-08-09T08:00:27.023312+01:00 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority(). 271 2018-08-09T08:00:27.066815+01:00 0 [Note] InnoDB: Crash recovery did not find the parallel doublewrite buffer at /data/mysql/mysql3308/data/xb_doublewrite 272 2018-08-09T08:00:27.070460+01:00 0 [Note] InnoDB: Highest supported file format is Barracuda. 273 2018-08-09T08:00:27.071136+01:00 0 [Note] InnoDB: Log scan progressed past the checkpoint lsn 2605210 274 2018-08-09T08:00:27.071168+01:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 2605219 275 2018-08-09T08:00:27.071185+01:00 0 [Note] InnoDB: Database was not shutdown normally! 276 2018-08-09T08:00:27.071190+01:00 0 [Note] InnoDB: Starting crash recovery. 277 2018-08-09T08:00:27.306683+01:00 0 [Note] InnoDB: Created parallel doublewrite buffer at /data/mysql/mysql3308/data/xb_doublewrite, size 3932160 bytes 278 2018-08-09T08:00:27.558968+01:00 0 [Note] InnoDB: Last MySQL binlog file position 0 194, file name mysql-bin.000022 279 2018-08-09T08:00:27.575777+01:00 0 [Note] InnoDB: Creating shared tablespace for temporary tables 280 2018-08-09T08:00:27.575872+01:00 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ... 281 2018-08-09T08:00:28.063310+01:00 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB. 282 2018-08-09T08:00:28.064352+01:00 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active. 283 2018-08-09T08:00:28.064370+01:00 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active. 284 2018-08-09T08:00:28.065740+01:00 0 [Note] InnoDB: Waiting for purge to start 285 2018-08-09T08:00:28.116905+01:00 0 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.7.22-rel22 started; log sequence number 2605219 286 2018-08-09T08:00:28.117131+01:00 0 [Note] Plugin 'FEDERATED' is disabled. 287 2018-08-09T08:00:28.123701+01:00 0 [Note] InnoDB: Loading buffer pool(s) from /data/mysql/mysql3308/data/ib_buffer_pool 288 2018-08-09T08:00:28.123749+01:00 0 [ERROR] InnoDB: Cannot open '/data/mysql/mysql3308/data/ib_buffer_pool' for reading: No such file or directory 289 2018-08-09T08:00:28.126137+01:00 0 [Note] Recovering after a crash using /data/mysql/mysql3308/logs/mysql-bin 290 2018-08-09T08:00:28.126167+01:00 0 [Note] WSREP: Before binlog recovery (wsrep position bd5525ab-9a15-11e8-aa0f-4b830c783fc7:22) 291 2018-08-09T08:00:28.128885+01:00 0 [Note] Starting crash recovery... 292 2018-08-09T08:00:28.128936+01:00 0 [Note] Crash recovery finished. 293 2018-08-09T08:00:28.128955+01:00 0 [Note] WSREP: After binlog recovery (wsrep position bd5525ab-9a15-11e8-aa0f-4b830c783fc7:22) 294 2018-08-09T08:00:28.135097+01:00 0 [Note] Salting uuid generator variables, current_pid: 5367, server_start_time: 1533794402, bytes_sent: 0, 295 2018-08-09T08:00:28.135163+01:00 0 [Note] Generated uuid: '83fac5b7-9b99-11e8-9f3a-080027de0e0e', server_start_time: 1510676201539890521, bytes_sent: 51827952 296 2018-08-09T08:00:28.135180+01:00 0 [Warning] No existing UUID has been found, so we assume that this is the first time that this server has been started. Generating a new UUID: 83fac5b7-9b99-11e8-9f3a-080027de0e0e. 297 2018-08-09T08:00:28.649143+01:00 0 [Note] Auto generated SSL certificates are placed in data directory. 298 2018-08-09T08:00:28.651737+01:00 0 [Warning] CA certificate ca.pem is self signed. 299 2018-08-09T08:00:28.812659+01:00 0 [Note] Auto generated RSA key files are placed in data directory. 300 2018-08-09T08:00:28.812836+01:00 0 [Note] Server hostname (bind-address): '*'; port: 3308 301 2018-08-09T08:00:28.812866+01:00 0 [Note] IPv6 is available. 302 2018-08-09T08:00:28.816928+01:00 0 [Note] - '::' resolves to '::'; 303 2018-08-09T08:00:28.821691+01:00 0 [Note] Server socket created on IP: '::'. 304 2018-08-09T08:00:28.846925+01:00 0 [Warning] 'user' entry 'root@localhost' ignored in --skip-name-resolve mode. 305 2018-08-09T08:00:28.846986+01:00 0 [Warning] 'user' entry 'mysql.session@localhost' ignored in --skip-name-resolve mode. 306 2018-08-09T08:00:28.847001+01:00 0 [Warning] 'user' entry 'mysql.sys@localhost' ignored in --skip-name-resolve mode. 307 2018-08-09T08:00:28.847028+01:00 0 [Warning] 'user' entry 'sst@localhost' ignored in --skip-name-resolve mode. 308 2018-08-09T08:00:28.847089+01:00 0 [Warning] 'db' entry 'performance_schema mysql.session@localhost' ignored in --skip-name-resolve mode. 309 2018-08-09T08:00:28.847097+01:00 0 [Warning] 'db' entry 'sys mysql.sys@localhost' ignored in --skip-name-resolve mode. 310 2018-08-09T08:00:28.847124+01:00 0 [Warning] 'proxies_priv' entry '@ root@localhost' ignored in --skip-name-resolve mode. 311 2018-08-09T08:00:28.858902+01:00 0 [Warning] 'tables_priv' entry 'user mysql.session@localhost' ignored in --skip-name-resolve mode. 312 2018-08-09T08:00:28.858929+01:00 0 [Warning] 'tables_priv' entry 'sys_config mysql.sys@localhost' ignored in --skip-name-resolve mode. 313 2018-08-09T08:00:28.873861+01:00 0 [Note] Event Scheduler: Loaded 0 events 314 2018-08-09T08:00:28.874109+01:00 0 [Note] WSREP: Signalling provider to continue on SST completion. 315 2018-08-09T08:00:28.874133+01:00 0 [Note] WSREP: Initialized wsrep sidno 2 316 2018-08-09T08:00:28.874156+01:00 0 [Note] WSREP: SST received: bd5525ab-9a15-11e8-aa0f-4b830c783fc7:22 317 2018-08-09T08:00:28.874266+01:00 0 [Note] mysqld: ready for connections. 318 Version: '5.7.22-22-29.26-log' socket: '/tmp/mysql3308.sock' port: 3308 Percona XtraDB Cluster binary (GPL) 5.7.22-29.26, Revision da86071, wsrep_29.26 319 2018-08-09T08:00:28.875367+01:00 0 [Note] WSREP: 2.0 (zlm4): State transfer from 0.0 (zlm2) complete. 320 2018-08-09T08:00:28.875409+01:00 0 [Note] WSREP: SST leaving flow control 321 2018-08-09T08:00:28.875418+01:00 0 [Note] WSREP: Shifting JOINER -> JOINED (TO: 22) 322 2018-08-09T08:00:28.876587+01:00 0 [Note] WSREP: Member 2.0 (zlm4) synced with group. 323 2018-08-09T08:00:28.876618+01:00 0 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 22) 324 2018-08-09T08:00:28.876639+01:00 2 [Note] WSREP: Synchronized with group, ready for connections 325 2018-08-09T08:00:28.876645+01:00 2 [Note] WSREP: Setting wsrep_ready to true 326 2018-08-09T08:00:28.876649+01:00 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification. 327 328 //It's okay now.No error is found this time.