Galera Cluster でデータの同期中に mysqld が停止・開始を繰り返す事象への対処方法！

環境

Lubuntu 16.04 LTS / Ubuntu 16.04 による 3 ノード Galera Cluster v10.1

事象

クラスタノードを再構成した場合に、初回サービス起動時に他のノードから rsync によるデータの同期がおこなわれますが、データ量が多くなるとサービスのタイムアウト時間内に同期が完了しないことがあります。その結果、wsrep が起動したまま mysqld の停止 → 開始が繰り返され rsync が完了しない状態のままループする事象を確認しました。Lubuntu 16.04 / Ubuntu 16.04 のサービスタイムアウト(DefaultTimeoutStartSec) は 90 秒であるためその時間内で同期が完了しないと同一事象が発生する可能性があります。

/var/log/syslog への出力内容は以下のような内容で、06:56:43 まで rsync が順調に進んでいますが、06:57:54 に node3 で mariadb.service: Start operation timed out. Terminating.のようなログを systemd が出力し、それに起因して rsync error となり、mysqld で　WSREP_SST の処理が中断され、MariaDB 停止 → 開始している状況が確認できます。

Apr  6 06:56:35 node3 rsyncd[8211]: rsync to rsync_sst/./xn@002d@002dekrp43n@002ecom from node1 (192.168.202.91)
Apr  6 06:56:35 node rsyncd[8211]: receiving file list
Apr  6 06:56:36 node3 rsyncd[8211]: sent 504 bytes  received 16243930 bytes  total size 16238193
Apr  6 06:56:42 node3 rsyncd[8193]: sent 580 bytes  received 216640740 bytes  total size 216585783
Apr  6 06:56:43 node3 rsyncd[8158]: sent 694 bytes  received 815991203 bytes  total size 815789488
Apr  6 06:57:54 node3 systemd[1]: mariadb.service: Start operation timed out. Terminating.
Apr  6 06:57:54 node3 mysqld[8082]: Terminated
Apr  6 06:57:54 node3 mysqld[8082]: WSREP_SST: [INFO] Joiner cleanup. rsync PID: 8129 (20180406 06:57:54.089)
Apr  6 06:57:54 node3 rsyncd[8159]: rsync error: received SIGINT, SIGTERM, or SIGHUP (code 20) at io.c(504) [generator=3.1.1]
Apr  6 06:57:54 node3 rsyncd[8129]: sent 0 bytes  received 0 bytes  total size 0
Apr  6 06:57:54 node3 mysqld[8082]: WSREP_SST: [INFO] Joiner cleanup done. (20180406 06:57:54.604)
Apr  6 06:57:54 node3 mysqld[8082]: 2018-04-06  6:57:54 139703177180928 [ERROR] WSREP: Process was aborted.
Apr  6 06:57:54 node3 mysqld[8082]: 2018-04-06  6:57:54 139703177180928 [ERROR] WSREP: Process completed with error: wsrep_sst_rsync --role 'joiner' --address '192.168.202.93' --datadir '/var/lib/mysql/'   --parent '8082'  '' : 2 (No such file or directory)
Apr  6 06:57:54 node3 mysqld[8082]: 2018-04-06  6:57:54 139703177180928 [ERROR] WSREP: Failed to read uuid:seqno and wsrep_gtid_domain_id from joiner script.
Apr  6 06:57:54 node3 mysqld[8082]: 2018-04-06  6:57:54 139703492159744 [ERROR] WSREP: SST failed: 2 (No such file or directory)
Apr  6 06:57:54 node3 mysqld[8082]: 2018-04-06  6:57:54 139703492159744 [ERROR] Aborting
Apr  6 06:57:54 node3 mysqld[8082]: 2018-04-06  6:57:54 139703206536960 [Warning] WSREP: 1.0 (node1): State transfer to 0.0 (node3) failed: -255 (Unknown error 255)
Apr  6 06:57:54 node3 mysqld[8082]: 2018-04-06  6:57:54 139703206536960 [ERROR] WSREP: gcs/src/gcs_group.cpp:gcs_group_handle_join_msg():737: Will never receive state. Need to abort.
Apr  6 06:58:00 node3 systemd[1]: mariadb.service: Main process exited, code=killed, status=6/ABRT
Apr  6 06:58:00 node3 systemd[1]: Failed to start MariaDB 10.1.32 database server.
Apr  6 06:58:00 node3 systemd[1]: mariadb.service: Unit entered failed state.
Apr  6 06:58:00 node3 systemd[1]: mariadb.service: Failed with result 'signal'.
Apr  6 06:58:05 node3 systemd[1]: mariadb.service: Service hold-off time over, scheduling restart.
Apr  6 06:58:05 node3 systemd[1]: Stopped MariaDB 10.1.32 database server.
Apr  6 06:58:05 node3 systemd[1]: Starting MariaDB 10.1.32 database server...

対処方法

要は systemd のサービス開始についてタイムアウト値を伸ばすことで rsync によるデータ同期が完了するのを待てばいいのですが、どのくらい待てばいいのかちょっと悩むところです。既定値が 90 秒なのでひとまず 300 秒に伸ばしてみます。まず設定を変更するまえに現在の systemd の設定を確認しておきます。

現在のタイムアウト値を確認

# systemctl show mariadb | grep Timeout
TimeoutStartUSec=1min 30s
TimeoutStopUSec=1min 30s
JobTimeoutUSec=infinity
JobTimeoutAction=none

systemd のサービス開始タイムアウト値の設定を変更

変更対象の設定値は、DefaultTimeoutStartSec です。デフォルトではコメントされている状態のため、コメントを外して 300 を設定します。この例では、34 行目のコメントを外して DefaultTimeoutStartSec=300s に変更します。
もしかすると、mysqld だけタイムアウト値を伸ばすこともできるのかもしれませんがやり方がわかりませんでした（ご存知の方教えてください）

# vi /etc/systemd/system.conf
...
     14 [Manager]
     15 #LogLevel=info
     16 #LogTarget=journal-or-kmsg
     17 #LogColor=yes
     18 #LogLocation=no
     19 #DumpCore=yes
     20 #ShowStatus=yes
     21 #CrashChangeVT=no
     22 #CrashShell=no
     23 #CrashReboot=no
     24 #CPUAffinity=1 2
     25 #JoinControllers=cpu,cpuacct net_cls,net_prio
     26 #RuntimeWatchdogSec=0
     27 #ShutdownWatchdogSec=10min
     28 #CapabilityBoundingSet=
     29 #SystemCallArchitectures=
     30 #TimerSlackNSec=
     31 #DefaultTimerAccuracySec=1min
     32 #DefaultStandardOutput=journal
     33 #DefaultStandardError=inherit
     34 #DefaultTimeoutStartSec=90s

sytem.conf への設定変更を反映

これを忘れると設定が反映されませんので、ココ重要です。
# systemctl daemon-reexec

systemd のサービス開始タイムアウト値の設定が変更されたことを確認

300 秒にしたので 5min と表示されていれば OK です。

# systemctl show service -p TimeoutStartUSec
TimeoutStartUSec=5min

結果

以下のような感じで同期が完了していれば OK かと思います。データ量が多くなることが想定される場合はあらかじめタイムアウト値を増やしておいた方がいいかもしれません。以上です。おつかれさまでした＾＾

Apr  6 07:17:56 node3 mysqld[11658]: WSREP_SST: [INFO] Joiner cleanup. rsync PID: 11703 (20180406 07:17:56.393)
Apr  6 07:17:56 node3 mysqld[11658]: 2018-04-06  7:17:56 140399595218688 [Note] WSREP: 0.0 (node1): State transfer to 1.0 (node3) complete.
Apr  6 07:17:56 node3 mysqld[11658]: 2018-04-06  7:17:56 140399595218688 [Note] WSREP: Member 0.0 (node1) synced with group.