SST with empty /var/vcap/store/mysql doesn't work with 36.12.0 - Error: Move file ib_logfile0 to /var/vcap/store/mysql/ib_logfile0 failed: Destination file exists

[GETandSELECT]

Hello

the procedure to trigger SST with emptying /var/vcap/store/mysql worked with previous releases.

How to reproduce issue:

rm -rf /var/vcap/store/mysql

/var/vcap/packages/mariadb/scripts/mysql_install_db \
         --basedir=/var/vcap/packages/mariadb \
         --user=vcap \
         --datadir=/var/vcap/store/mysql

monit start mariadb_ctrl

ls -lrt
total 524300
-rw-rw---- 1 vcap vcap       113 Apr 12 11:53 grastate.dat
-rw-rw---- 1 vcap vcap         0 Apr 12 11:53 sst_in_progress
-rw-rw---- 1 vcap vcap 536872232 Apr 12 11:53 galera.cache

(..later..)

# ls -lrt
total 2633768
-rw-rw---- 1 vcap vcap        113 Apr 12 11:53 grastate.dat
-rw-rw---- 1 vcap vcap          0 Apr 12 11:53 sst_in_progress
-rw-rw---- 1 vcap vcap  536872232 Apr 12 11:53 galera.cache
-rw-rw---- 1 vcap vcap         52 Apr 12 11:56 aria_log_control
-rw-rw---- 1 vcap vcap       8192 Apr 12 11:56 aria_log.00000001
-rw-rw---- 1 vcap vcap 1073741824 Apr 12 11:56 ib_logfile1
-rw-rw---- 1 vcap vcap   12582912 Apr 12 11:56 ibdata1
-rw-rw---- 1 vcap vcap 1073741824 Apr 12 11:56 ib_logfile0
-rw-rw---- 1 vcap vcap        313 Apr 12 11:56 mysql-bin.000001
-rw-rw---- 1 vcap vcap         19 Apr 12 11:56 mysql-bin.index

# ps -ef | grep mysql
vcap      9510     1  0 11:50 ?        00:00:00 /var/vcap/packages/mariadb_ctrl/bin/mariadb_ctrl -configPath=/var/vcap/jobs/mysql/config/mariadb_ctl_config.yml
vcap     10101     1  0 11:53 ?        00:00:00 /var/vcap/packages/mariadb_ctrl/bin/mariadb_ctrl -configPath=/var/vcap/jobs/mysql/config/mariadb_ctl_config.yml
vcap     10595  9510  0 11:53 ?        00:00:00 /bin/sh /var/vcap/packages/mariadb/bin/mysqld_safe --defaults-file=/var/vcap/jobs/mysql/config/my.cnf
vcap     10946 10595  0 11:53 ?        00:00:00 /var/vcap/packages/mariadb/bin/mysqld --defaults-file=/var/vcap/jobs/mysql/config/my.cnf --basedir=/var/vcap/packages/mariadb --datadir=/var/vcap/store/mysql --plugin-dir=/var/vcap/packages/mariadb/lib/plugin --wsrep_on=ON --wsrep_provider=/var/vcap/packages/mariadb/lib/plugin/libgalera_smm.so --log-error=/var/vcap/sys/log/mysql/mysql.err.log --pid-file=/var/vcap/sys/run/mysql/mysql.pid --socket=/var/vcap/sys/run/mysql/mysqld.sock --port=3306 --wsrep_start_position=00000000-0000-0000-0000-000000000000:-1
vcap     10955 10946  0 11:53 ?        00:00:00 sh -c wsrep_sst_xtrabackup-v2 --role 'joiner' --address 'xx.xx.xx.xx' --datadir '/var/vcap/store/mysql/'  --defaults-file '/var/vcap/jobs/mysql/config/my.cnf'  --parent '10946' --binlog 'mysql-bin'
vcap     10956 10955  0 11:53 ?        00:00:00 /bin/bash -ue /var/vcap/data/packages/mariadb/48af95b4c875a5388f4b46076c487f3e683bf8be//bin/wsrep_sst_xtrabackup-v2 --role joiner --address xx.xx.xx.xx --datadir /var/vcap/store/mysql/ --defaults-file /var/vcap/jobs/mysql/config/my.cnf --parent 10946 --binlog mysql-bin
vcap     11162 10956  0 11:53 ?        00:00:00 /bin/bash -ue /var/vcap/data/packages/mariadb/48af95b4c875a5388f4b46076c487f3e683bf8be//bin/wsrep_sst_xtrabackup-v2 --role joiner --address xx.xx.xx.xx --datadir /var/vcap/store/mysql/ --defaults-file /var/vcap/jobs/mysql/config/my.cnf --parent 10946 --binlog mysql-bin
vcap     11256     1  0 11:56 ?        00:00:00 /var/vcap/packages/mariadb_ctrl/bin/mariadb_ctrl -configPath=/var/vcap/jobs/mysql/config/mariadb_ctl_config.yml
root     11648  8949  0 11:57 pts/0    00:00:00 grep --color=auto mysql

error

# cat innobackup.move.log
180412 13:09:02 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!".

innobackupex version 2.4.8 based on MySQL server 5.7.13 Linux (x86_64) (revision id: 97330f7)
Error: Move file ib_logfile0 to /var/vcap/store/mysql/ib_logfile0 failed: Destination file exists

mysql error log

2018-04-12 13:08:49 140669272172288 [Note] WSREP: 1.0 (galera/2): State transfer to 0.0 (galera/3) complete.
2018-04-12 13:08:49 140669272172288 [Note] WSREP: Member 1.0 (galera/2) synced with group.
WSREP_SST: [INFO] Preparing the backup at /var/vcap/store/mysql//.sst (20180412 13:08:52.712)
WSREP_SST: [INFO] Evaluating innobackupex --no-version-check  --apply-log $rebuildcmd ${DATA} &>${DATA}/innobackup.prepare.log (20180412 13:08:52.714)
rm: cannot remove ‘/var/vcap/store/mysql//innobackup.prepare.log’: No such file or directory
rm: cannot remove ‘/var/vcap/store/mysql//innobackup.move.log’: No such file or directory
WSREP_SST: [INFO] Moving the backup to /var/vcap/store/mysql/ (20180412 13:09:02.126)
WSREP_SST: [INFO] Evaluating innobackupex --defaults-file=/var/vcap/jobs/mysql/config/my.cnf   --no-version-check   --move-back --force-non-empty-directories ${DATA} &>${DATA}/innobackup.move.log (20180412 13:09:02.128)
WSREP_SST: [ERROR] Cleanup after exit with status:1 (20180412 13:09:02.134)
2018-04-12 13:09:02 140669263779584 [ERROR] WSREP: Process completed with error: wsrep_sst_xtrabackup-v2 --role 'joiner' --address 'xx.xx.xx.xx' --datadir '/var/vcap/store/mysql/'  --defaults-file '/var/vcap/jobs/mysql/config/my.cnf'
--parent '10946' --binlog 'mysql-bin' : 1 (Operation not permitted)
2018-04-12 13:09:02 140669263779584 [ERROR] WSREP: Failed to read uuid:seqno and wsrep_gtid_domain_id from joiner script.
2018-04-12 13:09:02 140669998544768 [ERROR] WSREP: SST failed: 1 (Operation not permitted)
2018-04-12 13:09:02 140669998544768 [ERROR] Aborting

thanks and best regards GETandSELECT

[cf-gitbot]

We have created an issue in Pivotal Tracker to manage this:

https://www.pivotaltracker.com/story/show/156728063

The labels on this github issue will be updated when the story is started.

[jpalermo]

Hey @GETandSELECT, there might be some tasks that happen in the pre-start script that are required other than just mysql_install_db. Can you try this and see if it works?

monit stop mariadb_ctrl
rm -rf /var/vcap/store/mysql
/var/vcap/jobs/mysql/bin/pre-start
monit start mariadb_ctrl

[ndhanushkodi]

Closing due to inactivity, feel free to reopen if you're still having the issue!