[regression] MySQL may fail to SST because of a ./ib* files race condition

[Bogdan Dobrelya]

When a Percona MySQL 3.6 node is starting by OCF RA, it may fail to finish an xtrabackup-v2 SST because there is a race condition with accessing and removing the ./ib* files. A logs snippet example:

2016-04-26 07:21:57 5036 [Note] WSREP: Requesting state transfer: success, donor: 3
WSREP_SST: [INFO] Proceeding with SST (20160426 07:21:58.143)
WSREP_SST: [INFO] Cleaning the existing datadir (20160426 07:21:58.144)
removed '/var/lib/mysql/ib_logfile0'
removed '/var/lib/mysql/ib_logfile1'
removed '/var/lib/mysql/ibdata1'
removed '/var/lib/mysql/backup-my.cnf'
removed '/var/lib/mysql/auto.cnf'
WSREP_SST: [INFO] Cleaning the binlog directory /var/log/mysql as well (20160426 07:21:58.178)
WSREP_SST: [INFO] Evaluating socat -u TCP-LISTEN:4444,reuseaddr stdio | xbstream -x; RC=( ${PIPESTATUS[@]} ) (20160426 07:21:58.183)
2016-04-26 07:22:00 5036 [Note] WSREP: (8efee881, 'tcp://10.10.10.4:4567') turning message relay requesting off
^Gxbstream: Can't create/write to file './ibdata1' (Errcode: 17 - File exists)

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

How to reproduce:
* deploy an env
* unmanage the mysql clone resource
* pick a node and kill -9 myslqd
* Run mysqld binary for the node manually:
/usr/sbin/mysqld --verbose --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib/mysql/plugin --user=mysql --log-error=/var/log/mysql/error.log --open-files-limit=102400 --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/run/mysqld/mysqld.sock --port=3306
* issue kill -STOP `pgrep xbstream` a couple of times
* touch /var/lib/mysql/ibdata1
* kill -CONT `pgrep xbstream`

This happens as the SST-time /var/lib/mysql/.sst dir is not managed by the xtrabackup-v2 as appropriate, if there is no innodb-data-home-dir set in mysql conf. Once it configured, the ibdata1 file will go into that .sst dir and the race will disappear.

Another race condition is reported in the duplicated bug https://bugs.launchpad.net/fuel/+bug/1576073

[Bogdan Dobrelya (bogdando)]

Similar issue https://groups.google.com/forum/#!topic/codership-team/UEuWLDtCqh8

[Bogdan Dobrelya (bogdando)]

Upstream bug https://bugs.launchpad.net/percona-server/+bug/1575051

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/310524

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/310524
Committed: https://git.openstack.org/cgit/openstack/fuel-library/commit/?id=3061ef0b584f9e43bc4f6139cf798558b77392ee
Submitter: Jenkins
Branch: master

commit 3061ef0b584f9e43bc4f6139cf798558b77392ee
Author: Bogdan Dobrelya <email address hidden>
Date: Wed Apr 27 17:44:35 2016 +0200

    Fix a race for the xtrabackup-v2 SST

    Set innodb-data-home-dir to make the xtrabackup-v2
    script to manage the /var/lib/mysql/.sst dir as appropriate.
    This leaves the race condition with the ./ibdata1 file behind.

    Closes-bug:#1574999

    Change-Id: I9c9c979264cf592cd9411a9ed5d2a26bd090421e
    Signed-off-by: Bogdan Dobrelya <email address hidden>

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/mitaka
Review: https://review.openstack.org/310684

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/310684
Committed: https://git.openstack.org/cgit/openstack/fuel-library/commit/?id=db6d56e60e18ea717db85c37a80dafcf9fbb6194
Submitter: Jenkins
Branch: stable/mitaka

commit db6d56e60e18ea717db85c37a80dafcf9fbb6194
Author: Bogdan Dobrelya <email address hidden>
Date: Wed Apr 27 17:44:35 2016 +0200

    Fix a race for the xtrabackup-v2 SST

    Set innodb-data-home-dir to make the xtrabackup-v2
    script to manage the /var/lib/mysql/.sst dir as appropriate.
    This leaves the race condition with the ./ibdata1 file behind.

    Closes-bug:#1574999

    Change-Id: I9c9c979264cf592cd9411a9ed5d2a26bd090421e
    Signed-off-by: Bogdan Dobrelya <email address hidden>
    (cherry picked from commit 3061ef0b584f9e43bc4f6139cf798558b77392ee)

[Bogdan Dobrelya (bogdando)]

The fix was not complete, here is a continuation of the story http://pastebin.com/WBE7ZjPB

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/312471

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/mitaka
Review: https://review.openstack.org/312835

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/312471
Committed: https://git.openstack.org/cgit/openstack/fuel-library/commit/?id=590a3f13f3fee83ae971e4c5d69d33a6487196d1
Submitter: Jenkins
Branch: master

commit 590a3f13f3fee83ae971e4c5d69d33a6487196d1
Author: Bogdan Dobrelya <email address hidden>
Date: Wed May 4 14:04:34 2016 +0200

    For OCF status, match mysqld by process id

    When started and doing SST, pidfile is not created immediately.
    Fix race conditions by making action status to search by
    the pid as well. Add a dummy_test to status check, which does
    select 1.

    Co-authored-by: Sergii Golovatiuk <email address hidden>
    Closes-bug: #1574999

    Change-Id: I86fb5433d100d2ea675b259a963a0e84268fa095
    Signed-off-by: Bogdan Dobrelya <email address hidden>

[Bogdan Dobrelya (bogdando)]

The race condition's still in place:
May 5 06:28:40 n2 ocf-mysql-wss: INFO: p_mysql: mysql_start(): Starting MySQL
May 5 06:29:10 n2 ocf-mysql-wss: INFO: p_mysql: check_if_sst(): SST is in progress
May 5 06:29:10 n2 ocf-mysql-wss: INFO: p_mysql: mysql_start(): MySQL started
May 5 06:29:16 n2 ocf-mysql-wss: ERROR: p_mysql: mysql_status(): MySQL is not running
May 5 06:29:16 n2 ocf-mysql-wss: INFO: p_mysql: check_if_sst(): SST is in progress
May 5 06:29:16 n2 ocf-mysql-wss: WARNING: p_mysql: mysql_monitor(): found and purged a stale sst_in_progress file
May 5 06:29:16 n2 crmd[155]: notice: process_lrm_event: Operation p_mysql_monitor_60000: not running (node=n2, call=390, rc=7, cib-update=1943, confirmed=false)
May 5 06:29:33 n2 ocf-mysql-wss: INFO: p_mysql: mysql_start(): Starting MySQL
(a race with the SST in progress starts here)

[Bogdan Dobrelya (bogdando)]

The RC is non matching awk:
+ mysql_monitor
++ ps -C mysqld -o pid= -o args=
++ awk -v v=/var/lib/mysql '/datadir=/ { if ($1 ~ !/wsrep-recover/) print $1}'
+ pid=
+ '[' '' ']'

I'd better off using more pipes

[Bogdan Dobrelya (bogdando)]

Hm, it is matching, even though ignoring the datadir var, but it doesn't exclude the "wsrep_recover" case:
# ps -C mysqld -o pid= -o args=|grep -v defu; bash -xx test
10255 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib/mysql/plugin --user=mysql --wsrep_provider=/usr/lib/galera/libgalera_smm.so --wsrep-recover --log-error=/dev/stdout.err --open-files-limit=102400 --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/run/mysqld/mysqld.sock --port=3306 --wsrep_recover --log_error=/var/lib/mysql/wsrep_recovery.jHz8d2 --pid-file=/var/lib/mysql/n2-recover.pid
+ OCF_RESKEY_datadir=/var/lib/mysql
++ ps -C mysqld -o pid= -o args=
++ awk -v v=/var/lib/mysql '/datadir=/ { if ($1 ~ !/wsrep-recover/) print $1}'
+ pid=10255
+ echo 10255
10255

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/312839

[Bogdan Dobrelya (bogdando)]

So far so better, the "select 1" check isn't working while an xtrabackup-v2 SST is in progress. So the recent patches are still not fixing the race ...

mysql log:
WSREP_SST: [INFO] Waiting for SST streaming to complete! (20160505 07:18:39.076)
160505 7:18:41 [Note] WSREP: (962a755b, 'tcp://10.10.10.5:4567') turning message relay requesting off
160505 7:18:51 [Note] WSREP: 0.0 (n2): State transfer to 3.0 (n4) complete.
160505 7:18:51 [Note] WSREP: Member 0.0 (n2) synced with group.
WSREP_SST: [INFO] NOTE: Joiner-Recv-SST took 17 seconds (20160505 07:18:56.743)
WSREP_SST: [INFO] Preparing the backup at /var/lib/mysql//.sst (20160505 07:18:56.751)

OCF RA debug:
+ echo 'ocf-mysql-wss: 2016/05/05_07:18:42' 'ERROR: p_mysql: mysql_status(): PIDFile /var/run/mysqld/mysqld.pid of MySQL server not found. Sleeping for 2 seconds. 1 retries left'
+ sleep 2
+ '[' 1 -gt 0 ']'
+ '[' -f /var/run/mysqld/mysqld.pid ']'
++ ps -C mysqld -o pid= -o args=
++ grep /var/lib/mysql
++ awk '!/wsrep.recover/ {print $1}'
+ pid=13258
+ '[' 13258 ']'
+ dummy_test
+ /usr/bin/mysql -S /var/run/mysqld/mysqld.sock --connect_timeout=10 --user=root --password=root -s -N -e 'select 1;'
ERROR 2002 (HY000): Can't connect to local MySQL server through socket '/var/run/mysqld/mysqld.sock' (111 "Connection refused")

[Bogdan Dobrelya (bogdando)]

Can't fix, LF ideas https://groups.google.com/forum/#!searchin/codership-team/Check$20if$20SST/codership-team/-g6JhtP0C9o/fa-HQTK1BQAJ

[OpenStack Infra (hudson-openstack)]

Change abandoned by Bogdan Dobrelya (<email address hidden>) on branch: stable/mitaka
Review: https://review.openstack.org/312835
Reason: to early to backport, let's fix all of the issues discovered in the master first

[Timur Nurlygayanov (tnurlygayanov)]

This is regression issue which reproduced in 100% of cases now after feature "v2 tasks based deploy".

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/312911

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/312839
Committed: https://git.openstack.org/cgit/openstack/fuel-library/commit/?id=43fb2ba6fb59c21542ce21204262b72672a6ba70
Submitter: Jenkins
Branch: master

commit 43fb2ba6fb59c21542ce21204262b72672a6ba70
Author: Bogdan Dobrelya <email address hidden>
Date: Thu May 5 09:02:41 2016 +0200

    Fix mysqld process matching

    Make ps -C mysqld to match the datadir and exclude
    wsrep_recover/wsrep-recover as well

    Closes-bug: #1574999

    Change-Id: I133b0c4ea3000aa896ae412591cfd5882016bcf9
    Signed-off-by: Bogdan Dobrelya <email address hidden>

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/mitaka
Review: https://review.openstack.org/313273

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/312911
Committed: https://git.openstack.org/cgit/openstack/fuel-library/commit/?id=03991059adcc99989431c27f38c5ffa4ae35b486
Submitter: Jenkins
Branch: master

commit 03991059adcc99989431c27f38c5ffa4ae35b486
Author: Bogdan Dobrelya <email address hidden>
Date: Thu May 5 13:43:24 2016 +0200

    Rework SST check, fix possible masters search

    * Fix racing of monitoring with SST
    * Fix printf multilines sorting
      Expected: printf -- '%s\n' ${a} | sort -u (returns a sorted multiline)
      Actuacl: printf -- '%s\n' "$a" | sort -u (returns a single string)
    * Fix possible masters search, by the greatest SEQNO found for a
      magority UUID
    (Those blocks each other in CI and must be fixed at once)

    Closes-bug: #1574999
    Closes-bug: #1578278
    Closes-bug: #1388779

    Change-Id: I3d0d376e6bef3ccc3e738731b71f4dd60a59e653
    Signed-off-by: Bogdan Dobrelya <email address hidden>

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/313603

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/mitaka
Review: https://review.openstack.org/313674

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/313603
Committed: https://git.openstack.org/cgit/openstack/fuel-library/commit/?id=dcde07f439b6f5a597c8fba1748fbebc151fe4a8
Submitter: Jenkins
Branch: master

commit dcde07f439b6f5a597c8fba1748fbebc151fe4a8
Author: Bogdan Dobrelya <email address hidden>
Date: Fri May 6 17:30:21 2016 +0200

    Fix OCF MySQL monitor

    Return success if SST detected, otherwise check status
    and return error if it is not OK.

    Closes-bug: #1574999

    Change-Id: I5ee7807821ae1f21bcb3c74e15338acb8bb91ea1
    Signed-off-by: Bogdan Dobrelya <email address hidden>

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/313273
Committed: https://git.openstack.org/cgit/openstack/fuel-library/commit/?id=0197b09fc6ef25657a81a8398b6da0ea1b0603af
Submitter: Jenkins
Branch: stable/mitaka

commit 0197b09fc6ef25657a81a8398b6da0ea1b0603af
Author: Bogdan Dobrelya <email address hidden>
Date: Thu May 5 13:43:24 2016 +0200

    Rework SST check, fix possible masters search

    * Fix racing of monitoring with SST
    * Fix printf multilines sorting
      Expected: printf -- '%s\n' ${a} | sort -u (returns a sorted multiline)
      Actuacl: printf -- '%s\n' "$a" | sort -u (returns a single string)
    * Fix possible masters search, by the greatest SEQNO found for a
      magority UUID
    (Those blocks each other in CI and must be fixed at once)

    Fuel-CI: disable

    Closes-bug: #1574999
    Closes-bug: #1578278
    Closes-bug: #1388779

    Change-Id: I3d0d376e6bef3ccc3e738731b71f4dd60a59e653
    Signed-off-by: Bogdan Dobrelya <email address hidden>
    (cherry picked from commit 03991059adcc99989431c27f38c5ffa4ae35b486)
    Signed-off-by: Bogdan Dobrelya <email address hidden>
    Signed-off-by: Sergii Golovatiuk <email address hidden>

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/313674
Committed: https://git.openstack.org/cgit/openstack/fuel-library/commit/?id=84263cb37ff9b47885c99170b573b84389944300
Submitter: Jenkins
Branch: stable/mitaka

commit 84263cb37ff9b47885c99170b573b84389944300
Author: Bogdan Dobrelya <email address hidden>
Date: Fri May 6 17:30:21 2016 +0200

    Fix OCF MySQL monitor

    Return success if SST detected, otherwise check status
    and return error if it is not OK.

    Closes-bug: #1574999

    Change-Id: I5ee7807821ae1f21bcb3c74e15338acb8bb91ea1
    Signed-off-by: Bogdan Dobrelya <email address hidden>

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/6.1
Review: https://review.openstack.org/315989

[Timur Nurlygayanov (tnurlygayanov)]

This issue isn't reproducing anymore on the latest 9.0 builds (checked on CI build #362), so, moved to Fix Released status.

Please reopen it if the issue will be reproduced again.

[Bogdan Dobrelya (bogdando)]

The RC summary:
This https://bugs.launchpad.net/fuel/+bug/1576073/comments/8,
This https://bugs.launchpad.net/fuel/+bug/1574999/comments/19,
and also that was given in the description:
"This happens as the SST-time /var/lib/mysql/.sst dir is not managed by the xtrabackup-v2 as appropriate, if there is no innodb-data-home-dir set in mysql conf"

The issue have started blocking mostly as far as we enabled concurrent deployment for DB nodes

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/7.0
Review: https://review.openstack.org/316802

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/8.0
Review: https://review.openstack.org/317978

[Volodymyr Shypyguzov (vshypyguzov)]

Verified on 9.0 iso #458

[OpenStack Infra (hudson-openstack)]

Change abandoned by Bogdan Dobrelya (<email address hidden>) on branch: stable/8.0
Review: https://review.openstack.org/317978

[OpenStack Infra (hudson-openstack)]

Change abandoned by Bogdan Dobrelya (<email address hidden>) on branch: stable/7.0
Review: https://review.openstack.org/316802

[OpenStack Infra (hudson-openstack)]

Change abandoned by Bogdan Dobrelya (<email address hidden>) on branch: stable/6.1
Review: https://review.openstack.org/315989

[Vitaly Sedelnik (vsedelnik)]

Won't Fix for 6.1, 7.0 and 8.0-updates as this is too big change to be accepted to stable branch.

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/7.0
Review: https://review.openstack.org/374219

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/374219
Committed: https://git.openstack.org/cgit/openstack/fuel-library/commit/?id=f9a2d479f3687157d2b17a927a09ce5f995522d6
Submitter: Jenkins
Branch: stable/7.0

commit f9a2d479f3687157d2b17a927a09ce5f995522d6
Author: Denis Puchkin <email address hidden>
Date: Wed Sep 21 17:38:54 2016 +0300

    Backport mysql OCF from stable/mitaka

    backport mysql ocf script from stable/mitaka

    Closes-bug: #1524826
    Closes-bug: #1542256
    Closes-bug: #1572239
    Closes-bug: #1572557
    Closes-bug: #1572601
    Closes-bug: #1574747
    Closes-bug: #1574497
    Closes-bug: #1576244
    Closes-bug: #1574999
    Closes-bug: #1578278
    Closes-bug: #1388779
    Closes-bug: #1574999
    Closes-bug: #1576244
    Closes-bug: #1583173
    Closes-bug: #1585125

    Change-Id: I1cc6f95884a8fbd5c3418ede89bdf9ec6864bdc8

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/8.0
Review: https://review.openstack.org/377597

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/377597
Committed: https://git.openstack.org/cgit/openstack/fuel-library/commit/?id=b3873f5f5a0bb1526b1269f163223ae48d6e21f5
Submitter: Jenkins
Branch: stable/8.0

commit b3873f5f5a0bb1526b1269f163223ae48d6e21f5
Author: Denis Puchkin <email address hidden>
Date: Tue Sep 27 13:20:25 2016 +0300

    Backport mysql OCF from stable/mitaka

    backport mysql ocf script from stable/mitaka

    Closes-bug: #1524826
    Closes-bug: #1542256
    Closes-bug: #1572239
    Closes-bug: #1572557
    Closes-bug: #1572601
    Closes-bug: #1574747
    Closes-bug: #1574497
    Closes-bug: #1576244
    Closes-bug: #1574999
    Closes-bug: #1578278
    Closes-bug: #1388779
    Closes-bug: #1574999
    Closes-bug: #1576244
    Closes-bug: #1583173
    Closes-bug: #1585125

    Change-Id: I1cc6f95884a8fbd5c3418ede89bdf9ec6864bdc8