| 2016-04-28 08:09:36 |
Bogdan Dobrelya |
description |
The bug is similar to the https://bugs.launchpad.net/fuel/+bug/1574999, although this one may happen a step down the road.
When an SST finished streaming data to a joiner, the "innobackupex--move-back" command may randomly fail because of a race /var/lib/mysql/ib_logfile0 failed: Destination file exists , with the following log /var/log/mysql/error.log:
WSREP_SST: [INFO] Evaluating socat -u TCP-LISTEN:4444,reuseaddr stdio | xbstream -x; RC=( ${PIPESTATUS[@]} ) (20160427 14:21:09.268)
2016-04-27 14:21:21 22037 [Note] WSREP: 0.0 (n1): State transfer to 3.0 (n3) complete.
2016-04-27 14:21:21 22037 [Note] WSREP: Member 0.0 (n1) synced with group.
2016-04-27 14:21:21 22037 [Note] WSREP: 1.0 (n5): State transfer to 2.0 (n4) complete.
2016-04-27 14:21:21 22037 [Note] WSREP: Member 1.0 (n5) synced with group.
WSREP_SST: [INFO] Preparing the backup at /var/lib/mysql//.sst (20160427 14:21:27.817)
WSREP_SST: [INFO] Evaluating innobackupex --no-version-check --apply-log $rebuildcmd ${DATA} &>${DATA}/innobackup.prepare.log (20160427 14:21:27.819)
WSREP_SST: [INFO] Moving the backup to /var/lib/mysql/ (20160427 14:21:33.597)
WSREP_SST: [INFO] Evaluating innobackupex --defaults-file=/etc/mysql/my.cnf --no-version-check --move-back --force-non-empty-directories ${DATA} &>${DATA}/innobackup.move.log (20160427 14:21:33.598)
WSREP_SST: [ERROR] Cleanup after exit with status:1 (20160427 14:21:33.602)
2016-04-27 14:21:33 22037 [ERROR] WSREP: Process completed with error: wsrep_sst_xtrabackup-v2 --role 'joiner' --address '10.10.10.4' --auth 'root:root' --datadir '/var/lib/mysql/' --defaults-file '/etc/mysql/my.cnf' --parent '22037' '' : 1 (Operation not permitted)
2016-04-27 14:21:33 22037 [ERROR] WSREP: Failed to read uuid:seqno from joiner script.
2016-04-27 14:21:33 22037 [ERROR] WSREP: SST failed: 1 (Operation not permitted)
2016-04-27 14:21:33 22037 [ERROR] Aborting
And here is the innobackup log with straces:
execve("/usrbin/innobackupex", ["innobackupex", "--defaults-file=/etc/mysql/my.cn"..., "--no-version-check", "--move-back", "--force-non-empty-directories", "/var/lib/mysql.sst"], [/
* 55 vars */]) = 0
(... snip ...)
write(2, "160428 07:43:06 innobackupex: St"..., 236160428 07:43:06 innobackupex: Starting the move-back operation
IMPORTANT: Please check that the move-back run completes successfully.
At the end of a successful move-back run innobackupex
prints "completed OK!".
) = 236
write(2, "innobackupex version 2.3.4 based"..., 94innobackupex version 2.3.4 based on MySQL server 5.6.24 Linux (x86_64) (revision id: e80c779)
) = 94
stat("/var/lib/mysql", {st_mode=S_IFDIR|0700, st_size=4096, ...}) = 0
openat(AT_FDCWD, "/var/lib/mysql", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 3
close(3) = 0
stat("/var/lib/mysql", {st_mode=S_IFDIR|0700, st_size=4096, ...}) = 0
openat(AT_FDCWD, "/var/lib/mysql", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 3
close(3) = 0
chdir("/var/lib/mysql//.sst") = 0
brk(0x25a5000) = 0x25a5000
mkdir("/var/lib/mysql", 0700) = -1 EEXIST (File exists)
stat("ib_logfile0", {st_mode=S_IFREG|0660, st_size=83886080, ...}) = 0
stat("/var/lib/mysql/", {st_mode=S_IFDIR|0700, st_size=4096, ...}) = 0
openat(AT_FDCWD, "/var/lib/mysql/", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 3
close(3) = 0
stat("/var/lib/mysql/ib_logfile0", {st_mode=S_IFREG|0660, st_size=83886080, ...}) = 0
write(2, "Error: Move file ib_logfile0 to "..., 91Error: Move file ib_logfile0 to /var/lib/mysql/ib_logfile0 failed: Destination file exists
) = 91
exit_group(1) = ?
+++ exited with 1 +++
____
Note, to get strace debugs, I applied the patch to the
--- a/wsrep_sst_xtrabackup-v2
+++ b/wsrep_sst_xtrabackup-v2
@@ -578,8 +578,8 @@ fi
INNOEXTRA=""
INNOAPPLY="${INNOBACKUPEX_BIN} $disver $iapts --apply-log \$rebuildcmd \${DATA} &>\${DATA}/innobackup.prepare.log"
-INNOMOVE="${INNOBACKUPEX_BIN} --defaults-file=${WSREP_SST_OPT_CONF} $disver $impts --move-back --force-non-empty-directories \${DATA} &>\${DATA}/innobackup.move.log"
-INNOBACKUP="${INNOBACKUPEX_BIN} --defaults-file=${WSREP_SST_OPT_CONF} $disver $iopts \$tmpopts \$INNOEXTRA --galera-info --stream=\$sfmt \$itmpdir 2>\${DATA}/innobackup.backup.log"
+INNOMOVE="strace -f ${INNOBACKUPEX_BIN} --defaults-file=${WSREP_SST_OPT_CONF} $disver $impts --move-back --force-non-empty-directories \${DATA} &>\${DATA}/innobackup.move.log"
+INNOBACKUP="strace -f ${INNOBACKUPEX_BIN} --defaults-file=${WSREP_SST_OPT_CONF} $disver $iopts \$tmpopts \$INNOEXTRA --galera-info --stream=\$sfmt \$itmpdir 2>\${DATA}/innobackup.backup.log"
if [ "$WSREP_SST_OPT_ROLE" = "donor" ]
then |
The bug is similar to the https://bugs.launchpad.net/fuel/+bug/1574999, although this one may happen a step down the road.
When an SST finished streaming data to a joiner, the "innobackupex--move-back" command may randomly fail because of a race /var/lib/mysql/ib_logfile0 failed: Destination file exists , with the following log /var/log/mysql/error.log:
WSREP_SST: [INFO] Evaluating socat -u TCP-LISTEN:4444,reuseaddr stdio | xbstream -x; RC=( ${PIPESTATUS[@]} ) (20160427 14:21:09.268)
2016-04-27 14:21:21 22037 [Note] WSREP: 0.0 (n1): State transfer to 3.0 (n3) complete.
2016-04-27 14:21:21 22037 [Note] WSREP: Member 0.0 (n1) synced with group.
2016-04-27 14:21:21 22037 [Note] WSREP: 1.0 (n5): State transfer to 2.0 (n4) complete.
2016-04-27 14:21:21 22037 [Note] WSREP: Member 1.0 (n5) synced with group.
WSREP_SST: [INFO] Preparing the backup at /var/lib/mysql//.sst (20160427 14:21:27.817)
WSREP_SST: [INFO] Evaluating innobackupex --no-version-check --apply-log $rebuildcmd ${DATA} &>${DATA}/innobackup.prepare.log (20160427 14:21:27.819)
WSREP_SST: [INFO] Moving the backup to /var/lib/mysql/ (20160427 14:21:33.597)
WSREP_SST: [INFO] Evaluating innobackupex --defaults-file=/etc/mysql/my.cnf --no-version-check --move-back --force-non-empty-directories ${DATA} &>${DATA}/innobackup.move.log (20160427 14:21:33.598)
WSREP_SST: [ERROR] Cleanup after exit with status:1 (20160427 14:21:33.602)
2016-04-27 14:21:33 22037 [ERROR] WSREP: Process completed with error: wsrep_sst_xtrabackup-v2 --role 'joiner' --address '10.10.10.4' --auth 'root:root' --datadir '/var/lib/mysql/' --defaults-file '/etc/mysql/my.cnf' --parent '22037' '' : 1 (Operation not permitted)
2016-04-27 14:21:33 22037 [ERROR] WSREP: Failed to read uuid:seqno from joiner script.
2016-04-27 14:21:33 22037 [ERROR] WSREP: SST failed: 1 (Operation not permitted)
2016-04-27 14:21:33 22037 [ERROR] Aborting
And here is the innobackup log with straces:
execve("/usrbin/innobackupex", ["innobackupex", "--defaults-file=/etc/mysql/my.cn"..., "--no-version-check", "--move-back", "--force-non-empty-directories", "/var/lib/mysql.sst"], [/
* 55 vars */]) = 0
(... snip ...)
write(2, "160428 07:43:06 innobackupex: St"..., 236160428 07:43:06 innobackupex: Starting the move-back operation
IMPORTANT: Please check that the move-back run completes successfully.
At the end of a successful move-back run innobackupex
prints "completed OK!".
) = 236
write(2, "innobackupex version 2.3.4 based"..., 94innobackupex version 2.3.4 based on MySQL server 5.6.24 Linux (x86_64) (revision id: e80c779)
) = 94
stat("/var/lib/mysql", {st_mode=S_IFDIR|0700, st_size=4096, ...}) = 0
openat(AT_FDCWD, "/var/lib/mysql", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 3
close(3) = 0
stat("/var/lib/mysql", {st_mode=S_IFDIR|0700, st_size=4096, ...}) = 0
openat(AT_FDCWD, "/var/lib/mysql", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 3
close(3) = 0
chdir("/var/lib/mysql//.sst") = 0
brk(0x25a5000) = 0x25a5000
mkdir("/var/lib/mysql", 0700) = -1 EEXIST (File exists)
stat("ib_logfile0", {st_mode=S_IFREG|0660, st_size=83886080, ...}) = 0
stat("/var/lib/mysql/", {st_mode=S_IFDIR|0700, st_size=4096, ...}) = 0
openat(AT_FDCWD, "/var/lib/mysql/", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 3
close(3) = 0
stat("/var/lib/mysql/ib_logfile0", {st_mode=S_IFREG|0660, st_size=83886080, ...}) = 0
write(2, "Error: Move file ib_logfile0 to "..., 91Error: Move file ib_logfile0 to /var/lib/mysql/ib_logfile0 failed: Destination file exists
) = 91
exit_group(1) = ?
+++ exited with 1 +++
____
Note, to get strace debugs, I applied the patch to the
--- a/wsrep_sst_xtrabackup-v2
+++ b/wsrep_sst_xtrabackup-v2
@@ -578,8 +578,8 @@ fi
INNOEXTRA=""
INNOAPPLY="${INNOBACKUPEX_BIN} $disver $iapts --apply-log \$rebuildcmd \${DATA} &>\${DATA}/innobackup.prepare.log"
-INNOMOVE="${INNOBACKUPEX_BIN} --defaults-file=${WSREP_SST_OPT_CONF} $disver $impts --move-back --force-non-empty-directories \${DATA} &>\${DATA}/innobackup.move.log"
-INNOBACKUP="${INNOBACKUPEX_BIN} --defaults-file=${WSREP_SST_OPT_CONF} $disver $iopts \$tmpopts \$INNOEXTRA --galera-info --stream=\$sfmt \$itmpdir 2>\${DATA}/innobackup.backup.log"
+INNOMOVE="strace -f ${INNOBACKUPEX_BIN} --defaults-file=${WSREP_SST_OPT_CONF} $disver $impts --move-back --force-non-empty-directories \${DATA} &>\${DATA}/innobackup.move.log"
+INNOBACKUP="strace -f ${INNOBACKUPEX_BIN} --defaults-file=${WSREP_SST_OPT_CONF} $disver $iopts \$tmpopts \$INNOEXTRA --galera-info --stream=\$sfmt \$itmpdir 2>\${DATA}/innobackup.backup.log"
if [ "$WSREP_SST_OPT_ROLE" = "donor" ]
then
Packages used:
percona-xtradb-cluster-server-5.6 5.6.21-25.8-0ubuntu2, percona-xtrabackup 2.2.3-2.1build1 / 2.3.4-1.wily |
|
