SST: Joiner stuck in 'joining', but error log reports 'synced'
Affects | Status | Importance | Assigned to | Milestone | ||
---|---|---|---|---|---|---|
MySQL patches by Codership | Status tracked in 5.6 | |||||
5.5 |
New
|
Undecided
|
Unassigned | |||
5.6 |
New
|
Undecided
|
Unassigned | |||
Percona XtraDB Cluster moved to https://jira.percona.com/projects/PXC | Status tracked in 5.6 | |||||
5.5 |
New
|
High
|
David Bennett | |||
5.6 |
Fix Released
|
High
|
David Bennett |
Bug Description
Environment:
* PXC 5.6.20-68.0-56
* Galera provider: 3.7(r7f44a18)
* xtrabackup 2.2.4
* EC2, m3.medium, ubuntu-
Galera nodes, all are 'synced':
10.0.0.24
10.0.0.25
10.0.0.26
ssh 10.0.0.24
sudo killall -9 mysqld mysqld_safe
# remove mysql data files to have an SST:
sudo rm -rf /mnt/data/mysql/*
sudo mysqld_safe &
10.0.0.24 is now the JOINER and writes this in the mysql error log:
140925 07:53:55 mysqld_safe Starting mysqld daemon with databases from /mnt/data/mysql/
140925 07:53:55 mysqld_safe Skipping wsrep-recover for empty datadir: /mnt/data/mysql/
140925 07:53:55 mysqld_safe Assigning 00000000-
2014-09-25 07:53:56 0 [Note] WSREP: wsrep_start_
2014-09-25 07:53:56 28987 [Note] WSREP: Read nil XID from storage engines, skipping position init
2014-09-25 07:53:56 28987 [Note] WSREP: wsrep_load(): loading provider library '/usr/lib/
2014-09-25 07:53:56 28987 [Note] WSREP: wsrep_load(): Galera 3.7(r7f44a18) by Codership Oy <email address hidden> loaded successfully.
2014-09-25 07:53:56 28987 [Note] WSREP: CRC-32C: using hardware acceleration.
2014-09-25 07:53:56 28987 [Warning] WSREP: Could not open saved state file for reading: /mnt/data/
2014-09-25 07:53:56 28987 [Note] WSREP: Found saved state: 00000000-
2014-09-25 07:53:56 28987 [Note] WSREP: Passing config to GCS: base_host = 10.0.0.24; base_port = 4567; cert.log_conflicts = no; debug = no; evs.inactive_
2014-09-25 07:53:56 28987 [Note] WSREP: Service thread queue flushed.
2014-09-25 07:53:56 28987 [Note] WSREP: Assign initial position for certification: -1, protocol version: -1
2014-09-25 07:53:56 28987 [Note] WSREP: wsrep_sst_grab()
2014-09-25 07:53:56 28987 [Note] WSREP: Start replication
2014-09-25 07:53:56 28987 [Note] WSREP: Setting initial position to 00000000-
2014-09-25 07:53:56 28987 [Note] WSREP: protonet asio version 0
2014-09-25 07:53:56 28987 [Note] WSREP: Using CRC-32C for message checksums.
2014-09-25 07:53:56 28987 [Note] WSREP: backend: asio
2014-09-25 07:53:56 28987 [Warning] WSREP: access file(gvwstate.dat) failed(No such file or directory)
2014-09-25 07:53:56 28987 [Note] WSREP: restore pc from disk failed
2014-09-25 07:53:56 28987 [Note] WSREP: GMCast version 0
2014-09-25 07:53:56 28987 [Note] WSREP: (1a021a43, 'tcp://
2014-09-25 07:53:56 28987 [Note] WSREP: (1a021a43, 'tcp://
2014-09-25 07:53:56 28987 [Note] WSREP: EVS version 0
2014-09-25 07:53:56 28987 [Note] WSREP: PC version 0
2014-09-25 07:53:56 28987 [Note] WSREP: gcomm: connecting to group 'my_wsrep_cluster', peer '10.0.0.
2014-09-25 07:53:56 28987 [Warning] WSREP: (1a021a43, 'tcp://
2014-09-25 07:53:56 28987 [Note] WSREP: (1a021a43, 'tcp://
2014-09-25 07:53:56 28987 [Note] WSREP: (1a021a43, 'tcp://
2014-09-25 07:53:56 28987 [Note] WSREP: (1a021a43, 'tcp://
2014-09-25 07:53:56 28987 [Note] WSREP: (1a021a43, 'tcp://
2014-09-25 07:53:56 28987 [Note] WSREP: declaring 1076e92e at tcp://10.
2014-09-25 07:53:56 28987 [Note] WSREP: declaring 35b8b436 at tcp://10.
2014-09-25 07:53:56 28987 [Note] WSREP: Node 1076e92e state prim
2014-09-25 07:53:56 28987 [Note] WSREP: save pc into disk
2014-09-25 07:53:57 28987 [Note] WSREP: gcomm: connected
2014-09-25 07:53:57 28987 [Note] WSREP: Changing maximum packet size to 64500, resulting msg size: 32636
2014-09-25 07:53:57 28987 [Note] WSREP: Shifting CLOSED -> OPEN (TO: 0)
2014-09-25 07:53:57 28987 [Note] WSREP: Opened channel 'my_wsrep_cluster'
2014-09-25 07:53:57 28987 [Note] WSREP: Waiting for SST to complete.
2014-09-25 07:53:57 28987 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 1, memb_num = 3
2014-09-25 07:53:57 28987 [Note] WSREP: STATE EXCHANGE: Waiting for state UUID.
2014-09-25 07:53:57 28987 [Note] WSREP: STATE EXCHANGE: sent state msg: 1a372f69-
2014-09-25 07:53:57 28987 [Note] WSREP: STATE EXCHANGE: got state msg: 1a372f69-
2014-09-25 07:53:57 28987 [Note] WSREP: STATE EXCHANGE: got state msg: 1a372f69-
2014-09-25 07:53:57 28987 [Note] WSREP: STATE EXCHANGE: got state msg: 1a372f69-
2014-09-25 07:53:57 28987 [Note] WSREP: Quorum results:
version = 3,
component = PRIMARY,
conf_id = 20,
members = 2/3 (joined/total),
act_id = 10,
last_appl. = -1,
protocols = 0/6/3 (gcs/repl/appl),
group UUID = f7d5ff68-
2014-09-25 07:53:57 28987 [Note] WSREP: Flow-control interval: [28, 28]
2014-09-25 07:53:57 28987 [Note] WSREP: Shifting OPEN -> PRIMARY (TO: 10)
2014-09-25 07:53:57 28987 [Note] WSREP: State transfer required:
Group state: f7d5ff68-
Local state: 00000000-
2014-09-25 07:53:57 28987 [Note] WSREP: New cluster view: global state: f7d5ff68-
2014-09-25 07:53:57 28987 [Warning] WSREP: Gap in state sequence. Need state transfer.
2014-09-25 07:53:57 28987 [Note] WSREP: Running: 'wsrep_
WSREP_SST: [INFO] Streaming with xbstream (20140925 07:53:57.315)
WSREP_SST: [INFO] Using socat as streamer (20140925 07:53:57.329)
WSREP_SST: [INFO] Evaluating timeout -k 110 100 socat -u TCP-LISTEN:
2014-09-25 07:53:57 28987 [Note] WSREP: Prepared SST request: xtrabackup-
2014-09-25 07:53:57 28987 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2014-09-25 07:53:57 28987 [Note] WSREP: REPL Protocols: 6 (3, 2)
2014-09-25 07:53:57 28987 [Note] WSREP: Service thread queue flushed.
2014-09-25 07:53:57 28987 [Note] WSREP: Assign initial position for certification: 10, protocol version: 3
2014-09-25 07:53:57 28987 [Note] WSREP: Service thread queue flushed.
2014-09-25 07:53:57 28987 [Warning] WSREP: Failed to prepare for incremental state transfer: Local state UUID (00000000-
at galera/
2014-09-25 07:53:57 28987 [Note] WSREP: Member 1.0 (10.0.0.24) requested state transfer from '*any*'. Selected 0.0 (10.0.0.25)(SYNCED) as donor.
2014-09-25 07:53:57 28987 [Note] WSREP: Shifting PRIMARY -> JOINER (TO: 10)
2014-09-25 07:53:57 28987 [Note] WSREP: Requesting state transfer: success, donor: 0
WSREP_SST: [INFO] Proceeding with SST (20140925 07:53:58.763)
WSREP_SST: [INFO] Cleaning the existing datadir (20140925 07:53:58.765)
removed ‘/mnt/data/
WSREP_SST: [INFO] Evaluating socat -u TCP-LISTEN:
2014-09-25 07:53:59 28987 [Note] WSREP: (1a021a43, 'tcp://
2014-09-25 07:54:12 28987 [Note] WSREP: 0.0 (10.0.0.25): State transfer to 1.0 (10.0.0.24) complete.
2014-09-25 07:54:12 28987 [Note] WSREP: Member 0.0 (10.0.0.25) synced with group.
WSREP_SST: [INFO] Preparing the backup at /mnt/data/mysql/ (20140925 07:54:12.694)
WSREP_SST: [INFO] Evaluating innobackupex --no-version-check --apply-log $rebuildcmd ${DATA} &>${DATA}
WSREP_SST: [INFO] Total time on joiner: 0 seconds (20140925 07:54:23.226)
WSREP_SST: [INFO] Removing the sst_in_progress file (20140925 07:54:23.229)
2014-09-25 07:54:23 28987 [Note] WSREP: SST complete, seqno: 7
2014-09-25 07:54:23 28987 [Note] Plugin 'FEDERATED' is disabled.
2014-09-25 07:54:23 28987 [Note] InnoDB: Using atomics to ref count buffer pool pages
2014-09-25 07:54:23 28987 [Note] InnoDB: The InnoDB memory heap is disabled
2014-09-25 07:54:23 28987 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2014-09-25 07:54:23 28987 [Note] InnoDB: Memory barrier is not used
2014-09-25 07:54:23 28987 [Note] InnoDB: Compressed tables use zlib 1.2.8
2014-09-25 07:54:23 28987 [Note] InnoDB: Using Linux native AIO
2014-09-25 07:54:23 28987 [Note] InnoDB: Using CPU crc32 instructions
2014-09-25 07:54:23 28987 [Note] InnoDB: Initializing buffer pool, size = 2.4G
2014-09-25 07:54:23 28987 [Note] InnoDB: Completed initialization of buffer pool
2014-09-25 07:54:23 28987 [Note] InnoDB: Highest supported file format is Barracuda.
2014-09-25 07:54:23 28987 [Note] InnoDB: 128 rollback segment(s) are active.
2014-09-25 07:54:23 28987 [Note] InnoDB: Waiting for purge to start
2014-09-25 07:54:23 28987 [Note] InnoDB: Percona XtraDB (http://
2014-09-25 07:54:23 28987 [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: 2a2ea9d3-
2014-09-25 07:54:23 28987 [Note] RSA private key file not found: /mnt/data/
2014-09-25 07:54:23 28987 [Note] RSA public key file not found: /mnt/data/
2014-09-25 07:54:23 28987 [Note] Server hostname (bind-address): '*'; port: 3306
2014-09-25 07:54:23 28987 [Note] IPv6 is available.
2014-09-25 07:54:23 28987 [Note] - '::' resolves to '::';
2014-09-25 07:54:23 28987 [Note] Server socket created on IP: '::'.
2014-09-25 07:54:23 28987 [Warning] 'proxies_priv' entry '@ root@ip-10-0-0-24' ignored in --skip-name-resolve mode.
2014-09-25 07:54:23 28987 [Note] Event Scheduler: Loaded 0 events
2014-09-25 07:54:23 28987 [Note] WSREP: Signalling provider to continue.
2014-09-25 07:54:23 28987 [Note] WSREP: inited wsrep sidno 1
2014-09-25 07:54:23 28987 [Note] WSREP: SST received: f7d5ff68-
2014-09-25 07:54:23 28987 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.6.20-68.0-56' socket: '/var/run/
2014-09-25 07:54:23 28987 [Note] WSREP: 1.0 (10.0.0.24): State transfer from 0.0 (10.0.0.25) complete.
2014-09-25 07:54:23 28987 [Note] WSREP: Shifting JOINER -> JOINED (TO: 10)
2014-09-25 07:54:23 28987 [Note] WSREP: Member 1.0 (10.0.0.24) synced with group.
2014-09-25 07:54:23 28987 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 10)
mysql> SHOW GLOBAL STATUS LIKE 'wsrep%';
+------
| Variable_name | Value |
+------
| wsrep_local_
| wsrep_protocol_
| wsrep_last_
| wsrep_replicated | 0 |
| wsrep_replicate
| wsrep_repl_keys | 0 |
| wsrep_repl_
| wsrep_repl_
| wsrep_repl_
| wsrep_received | 3 |
| wsrep_received_
| wsrep_local_commits | 0 |
| wsrep_local_
| wsrep_local_replays | 0 |
| wsrep_local_
| wsrep_local_
| wsrep_local_
| wsrep_local_
| wsrep_local_
| wsrep_local_
| wsrep_local_
| wsrep_local_
| wsrep_local_
| wsrep_flow_
| wsrep_flow_
| wsrep_flow_
| wsrep_flow_
| wsrep_cert_
| wsrep_apply_oooe | 0.000000 |
| wsrep_apply_oool | 0.000000 |
| wsrep_apply_window | 0.000000 |
| wsrep_commit_oooe | 0.000000 |
| wsrep_commit_oool | 0.000000 |
| wsrep_commit_window | 0.000000 |
| wsrep_local_state | 1 |
| wsrep_local_
| wsrep_cert_
| wsrep_causal_reads | 0 |
| wsrep_cert_interval | 0.000000 |
| wsrep_incoming_
| wsrep_evs_
| wsrep_cluster_
| wsrep_cluster_size | 3 |
| wsrep_cluster_
| wsrep_cluster_
| wsrep_connected | ON |
| wsrep_local_
| wsrep_local_index | 1 |
| wsrep_provider_name | Galera |
| wsrep_provider_
| wsrep_provider_
| wsrep_ready | OFF |
+------
52 rows in set (0.00 sec)
**** There are no traces of xtrabackup still running:
ubuntu@
ubuntu 29349 28112 0 07:55 pts/0 00:00:00 grep --color=auto inno
ubuntu@
root 28143 28112 0 07:53 pts/0 00:00:00 sudo mysqld_safe
root 28144 28143 0 07:53 pts/0 00:00:00 /bin/sh /usr/bin/
mysql 28987 28144 1 07:53 pts/0 00:00:01 /usr/sbin/mysqld --basedir=/usr/ --datadir=
**** Looking at the innobackup prepare log:
ubuntu@
sudo: unable to resolve host ip-10-0-0-24
InnoDB Backup Utility v1.5.1-xtrabackup; Copyright 2003, 2009 Innobase Oy
and Percona LLC and/or its affiliates 2009-2013. All Rights Reserved.
This software is published under
the GNU GENERAL PUBLIC LICENSE Version 2, June 1991.
Get the latest version of Percona XtraBackup, documentation, and help resources:
http://
IMPORTANT: Please check that the apply-log run completes successfully.
At the end of a successful apply-log run innobackupex
prints "completed OK!".
140925 07:54:13 innobackupex: Starting ibbackup with command: xtrabackup --defaults-
xtrabackup version 2.2.4 based on MySQL server 5.6.17 Linux (x86_64) (revision id: )
xtrabackup: cd to /mnt/data/mysql
xtrabackup: This target seems to be not prepared yet.
xtrabackup: xtrabackup_logfile detected: size=2097152, start_lsn=(1627118)
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup: innodb_
xtrabackup: innodb_
xtrabackup: innodb_
xtrabackup: innodb_
xtrabackup: innodb_
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup: innodb_
xtrabackup: innodb_
xtrabackup: innodb_
xtrabackup: innodb_
xtrabackup: innodb_
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
InnoDB: Using atomics to ref count buffer pool pages
InnoDB: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Compressed tables use zlib 1.2.8
InnoDB: Using CPU crc32 instructions
InnoDB: Initializing buffer pool, size = 100.0M
InnoDB: Completed initialization of buffer pool
InnoDB: Highest supported file format is Barracuda.
InnoDB: The log sequence numbers 1626646 and 1626646 in ibdata files do not match the log sequence number 1627118 in the ib_logfiles!
InnoDB: Database was not shutdown normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages
InnoDB: from the doublewrite buffer...
InnoDB: 128 rollback segment(s) are active.
InnoDB: Waiting for purge to start
InnoDB: 5.6.17 started; log sequence number 1627118
[notice (again)]
If you use binary log and don't use any hack of group commit,
the binary log position seems to be:
xtrabackup: Recovered WSREP position: f7d5ff68-
xtrabackup: starting shutdown with innodb_
InnoDB: FTS optimize thread exiting.
InnoDB: Starting shutdown...
InnoDB: Shutdown completed; log sequence number 1627128
140925 07:54:14 innobackupex: Restarting xtrabackup with command: xtrabackup --defaults-
for creating ib_logfile*
xtrabackup version 2.2.4 based on MySQL server 5.6.17 Linux (x86_64) (revision id: )
xtrabackup: cd to /mnt/data/mysql
xtrabackup: This target seems to be already prepared.
xtrabackup: notice: xtrabackup_logfile was already used to '--prepare'.
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup: innodb_
xtrabackup: innodb_
xtrabackup: innodb_
xtrabackup: innodb_
xtrabackup: innodb_
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup: innodb_
xtrabackup: innodb_
xtrabackup: innodb_
xtrabackup: innodb_
xtrabackup: innodb_
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
InnoDB: Using atomics to ref count buffer pool pages
InnoDB: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Compressed tables use zlib 1.2.8
InnoDB: Using CPU crc32 instructions
InnoDB: Initializing buffer pool, size = 100.0M
InnoDB: Completed initialization of buffer pool
InnoDB: Setting log file ./ib_logfile101 size to 512 MB
InnoDB: Progress in MB: 100 200 300 400 500
InnoDB: Setting log file ./ib_logfile1 size to 512 MB
InnoDB: Progress in MB: 100 200 300 400 500
InnoDB: Renaming log file ./ib_logfile101 to ./ib_logfile0
InnoDB: New log files created, LSN=1627128
InnoDB: Highest supported file format is Barracuda.
InnoDB: 128 rollback segment(s) are active.
InnoDB: Waiting for purge to start
InnoDB: 5.6.17 started; log sequence number 1627148
[notice (again)]
If you use binary log and don't use any hack of group commit,
the binary log position seems to be:
xtrabackup: Recovered WSREP position: f7d5ff68-
xtrabackup: starting shutdown with innodb_
InnoDB: FTS optimize thread exiting.
InnoDB: Starting shutdown...
InnoDB: Shutdown completed; log sequence number 1627158
140925 07:54:23 innobackupex: completed OK!
**** Looking at the DONOR (i hope i have got the most parts of the error log):
2014-09-25 07:53:47 10525 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2014-09-25 07:53:47 10525 [Note] WSREP: REPL Protocols: 6 (3, 2)
2014-09-25 07:53:47 10525 [Note] WSREP: Service thread queue flushed.
2014-09-25 07:53:47 10525 [Note] WSREP: Assign initial position for certification: 10, protocol version: 3
2014-09-25 07:53:47 10525 [Note] WSREP: Service thread queue flushed.
2014-09-25 07:53:50 10525 [Note] WSREP: cleaning up 9aced1b3 (tcp://
2014-09-25 07:53:56 10525 [Note] WSREP: (1076e92e, 'tcp://
2014-09-25 07:53:56 10525 [Note] WSREP: (1076e92e, 'tcp://
2014-09-25 07:53:56 10525 [Note] WSREP: (1076e92e, 'tcp://
2014-09-25 07:53:56 10525 [Note] WSREP: (1076e92e, 'tcp://
2014-09-25 07:53:56 10525 [Note] WSREP: (1076e92e, 'tcp://
2014-09-25 07:53:56 10525 [Note] WSREP: (1076e92e, 'tcp://
2014-09-25 07:53:56 10525 [Note] WSREP: (1076e92e, 'tcp://
2014-09-25 07:53:56 10525 [Note] WSREP: declaring 1a021a43 at tcp://10.
2014-09-25 07:53:56 10525 [Note] WSREP: declaring 35b8b436 at tcp://10.
2014-09-25 07:53:56 10525 [Note] WSREP: Node 1076e92e state prim
2014-09-25 07:53:56 10525 [Note] WSREP: save pc into disk
2014-09-25 07:53:56 10525 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 0, memb_num = 3
2014-09-25 07:53:56 10525 [Note] WSREP: STATE_EXCHANGE: sent state UUID: 1a372f69-
2014-09-25 07:53:56 10525 [Note] WSREP: STATE EXCHANGE: sent state msg: 1a372f69-
2014-09-25 07:53:56 10525 [Note] WSREP: STATE EXCHANGE: got state msg: 1a372f69-
2014-09-25 07:53:56 10525 [Note] WSREP: STATE EXCHANGE: got state msg: 1a372f69-
2014-09-25 07:53:57 10525 [Note] WSREP: STATE EXCHANGE: got state msg: 1a372f69-
2014-09-25 07:53:57 10525 [Note] WSREP: Quorum results:
version = 3,
component = PRIMARY,
conf_id = 20,
members = 2/3 (joined/total),
act_id = 10,
last_appl. = 0,
protocols = 0/6/3 (gcs/repl/appl),
group UUID = f7d5ff68-
2014-09-25 07:53:57 10525 [Note] WSREP: Flow-control interval: [28, 28]
2014-09-25 07:53:57 10525 [Note] WSREP: New cluster view: global state: f7d5ff68-
2014-09-25 07:53:57 10525 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2014-09-25 07:53:57 10525 [Note] WSREP: REPL Protocols: 6 (3, 2)
2014-09-25 07:53:57 10525 [Note] WSREP: Service thread queue flushed.
2014-09-25 07:53:57 10525 [Note] WSREP: Assign initial position for certification: 10, protocol version: 3
2014-09-25 07:53:57 10525 [Note] WSREP: Service thread queue flushed.
2014-09-25 07:53:57 10525 [Note] WSREP: Member 1.0 (10.0.0.24) requested state transfer from '*any*'. Selected 0.0 (10.0.0.25)(SYNCED) as donor.
2014-09-25 07:53:57 10525 [Note] WSREP: Shifting SYNCED -> DONOR/DESYNCED (TO: 10)
2014-09-25 07:53:57 10525 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2014-09-25 07:53:57 10525 [Note] WSREP: Running: 'wsrep_
2014-09-25 07:53:57 10525 [Note] WSREP: sst_donor_thread signaled with 0
WSREP_SST: [INFO] Streaming with xbstream (20140925 07:53:58.240)
WSREP_SST: [INFO] Using socat as streamer (20140925 07:53:58.250)
WSREP_SST: [INFO] Using /tmp/tmp.nnC6BnypNz as xtrabackup temporary directory (20140925 07:53:58.702)
WSREP_SST: [INFO] Using /tmp/tmp.o9h80diUhb as innobackupex temporary directory (20140925 07:53:58.704)
WSREP_SST: [INFO] Streaming GTID file before SST (20140925 07:53:58.716)
WSREP_SST: [INFO] Evaluating xbstream -c ${INFO_FILE} | socat -u stdio TCP:10.0.0.24:4444; RC=( ${PIPESTATUS[@]} ) (20140925 07:53:58.718)
WSREP_SST: [INFO] Sleeping before data transfer for SST (20140925 07:53:58.723)
2014-09-25 07:53:59 10525 [Note] WSREP: (1076e92e, 'tcp://
WSREP_SST: [INFO] Streaming the backup to joiner at 10.0.0.24 4444 (20140925 07:54:08.734)
WSREP_SST: [INFO] Evaluating innobackupex --defaults-
2014-09-25 07:54:11 10525 [Note] WSREP: Provider paused at f7d5ff68-
2014-09-25 07:54:12 10525 [Note] WSREP: resuming provider at 70
2014-09-25 07:54:12 10525 [Note] WSREP: Provider resumed.
2014-09-25 07:54:12 10525 [Note] WSREP: 0.0 (10.0.0.25): State transfer to 1.0 (10.0.0.24) complete.
2014-09-25 07:54:12 10525 [Note] WSREP: Shifting DONOR/DESYNCED -> JOINED (TO: 10)
2014-09-25 07:54:12 10525 [Note] WSREP: Member 0.0 (10.0.0.25) synced with group.
2014-09-25 07:54:12 10525 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 10)
2014-09-25 07:54:12 10525 [Note] WSREP: Synchronized with group, ready for connections
2014-09-25 07:54:12 10525 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
WSREP_SST: [INFO] Total time on donor: 0 seconds (20140925 07:54:12.670)
WSREP_SST: [INFO] Cleaning up temporary directories (20140925 07:54:12.672)
2014-09-25 07:54:23 10525 [Note] WSREP: 1.0 (10.0.0.24): State transfer from 0.0 (10.0.0.25) complete.
2014-09-25 07:54:23 10525 [Note] WSREP: Member 1.0 (10.0.0.24) synced with group.
mysql> show global status like 'wsrep%';
+------
| Variable_name | Value |
+------
| wsrep_local_
| wsrep_protocol_
| wsrep_last_
| wsrep_replicated | 3 |
| wsrep_replicate
| wsrep_repl_keys | 5 |
| wsrep_repl_
| wsrep_repl_
| wsrep_repl_
| wsrep_received | 58 |
| wsrep_received_
| wsrep_local_commits | 0 |
| wsrep_local_
| wsrep_local_replays | 0 |
| wsrep_local_
| wsrep_local_
| wsrep_local_
| wsrep_local_
| wsrep_local_
| wsrep_local_
| wsrep_local_
| wsrep_local_
| wsrep_local_
| wsrep_flow_
| wsrep_flow_
| wsrep_flow_
| wsrep_flow_
| wsrep_cert_
| wsrep_apply_oooe | 0.000000 |
| wsrep_apply_oool | 0.000000 |
| wsrep_apply_window | 1.000000 |
| wsrep_commit_oooe | 0.000000 |
| wsrep_commit_oool | 0.000000 |
| wsrep_commit_window | 1.000000 |
| wsrep_local_state | 4 |
| wsrep_local_
| wsrep_cert_
| wsrep_causal_reads | 0 |
| wsrep_cert_interval | 0.000000 |
| wsrep_incoming_
| wsrep_evs_
| wsrep_cluster_
| wsrep_cluster_size | 3 |
| wsrep_cluster_
| wsrep_cluster_
| wsrep_connected | ON |
| wsrep_local_
| wsrep_local_index | 0 |
| wsrep_provider_name | Galera |
| wsrep_provider_
| wsrep_provider_
| wsrep_ready | ON |
+------
52 rows in set (0.00 sec)
**** No traces of xtrabackup on the Donor:
ubuntu@
ubuntu 18975 18945 0 07:59 pts/0 00:00:00 grep --color=auto inno
ubuntu@
ubuntu 18977 18945 0 07:59 pts/0 00:00:00 grep --color=auto xtra
ubuntu@
root 9682 1 0 07:10 ? 00:00:00 /bin/sh /usr/bin/
mysql 10525 9682 0 07:10 ? 00:00:04 /usr/sbin/mysqld --basedir=/usr/ --datadir=
*** innobackup.
ubuntu@
sudo: unable to resolve host ip-10-0-0-25
InnoDB Backup Utility v1.5.1-xtrabackup; Copyright 2003, 2009 Innobase Oy
and Percona LLC and/or its affiliates 2009-2013. All Rights Reserved.
This software is published under
the GNU GENERAL PUBLIC LICENSE Version 2, June 1991.
Get the latest version of Percona XtraBackup, documentation, and help resources:
http://
140925 07:54:09 innobackupex: Connecting to MySQL server with DSN 'dbi:mysql:
140925 07:54:09 innobackupex: Connected to MySQL server
IMPORTANT: Please check that the backup run completes successfully.
At the end of a successful backup run innobackupex
prints "completed OK!".
innobackupex: Using mysql server version 5.6.20-68.0-56
innobackupex: Created backup directory /tmp/tmp.o9h80diUhb
140925 07:54:09 innobackupex: Starting ibbackup with command: xtrabackup --defaults-
innobackupex: Waiting for ibbackup (pid=18437) to suspend
innobackupex: Suspend file '/tmp/tmp.
xtrabackup version 2.2.4 based on MySQL server 5.6.17 Linux (x86_64) (revision id: )
xtrabackup: uses posix_fadvise().
xtrabackup: cd to /mnt/data/mysql/
xtrabackup: open files limit requested 0, set to 5000
xtrabackup: using the following InnoDB configuration:
xtrabackup: innodb_
xtrabackup: innodb_
xtrabackup: innodb_
xtrabackup: innodb_
xtrabackup: innodb_
xtrabackup: using O_DIRECT
>> log scanned up to (1627118)
[01] Streaming ./ibdata1
[01] ...done
[01] Streaming ./mysql/
[01] ...done
[01] Streaming ./mysql/
[01] ...done
[01] Streaming ./mysql/
[01] ...done
[01] Streaming ./mysql/
[01] ...done
[01] Streaming ./mysql/
[01] ...done
>> log scanned up to (1627118)
xtrabackup: Creating suspend file '/tmp/tmp.
140925 07:54:11 innobackupex: Continuing after ibbackup has suspended
140925 07:54:11 innobackupex: Executing FLUSH TABLES WITH READ LOCK...
140925 07:54:11 innobackupex: All tables locked and flushed to disk
140925 07:54:11 innobackupex: Starting to backup non-InnoDB tables and files
innobackupex: in subdirectories of '/mnt/data/mysql/'
innobackupex: Backing up files '/mnt/data/
>> log scanned up to (1627118)
innobackupex: Backing up files '/mnt/data/
140925 07:54:11 innobackupex: Finished backing up non-InnoDB tables and files
140925 07:54:11 innobackupex: Executing FLUSH ENGINE LOGS...
140925 07:54:11 innobackupex: Waiting for log copying to finish
xtrabackup: The latest check point (for incremental): '1627118'
xtrabackup: Stopping log copying thread.
.>> log scanned up to (1627118)
xtrabackup: Creating suspend file '/tmp/tmp.
xtrabackup: Transaction log of lsn (1627118) to (1627118) was copied.
140925 07:54:12 innobackupex: All tables unlocked
innobackupex: Backup created in directory '/tmp/tmp.
140925 07:54:12 innobackupex: Connection to database server closed
140925 07:54:12 innobackupex: completed OK!
ubuntu@
*********** Workaround: *************
- downgrade all nodes to percona xtrabackup 2.2.3, the additional message written in the mysql error log is the following when using xtrabackup 2.2.3:
2014-09-25 08:02:06 30369 [Note] WSREP: Synchronized with group, ready for connections
- use wsrep_sst_
****** If it helps i can facilitate remote login (ssh), it is just simple test servers.
I should also say, that when using xtrabackup 2.2.4, and having writes on the 10.0.0.26 node (not the donor, not the joiner), then the joiner joins correctly.
BR
johan