MariaDB Galera Cluster – SST Not Starting on a New Node

I have two MariaDB servers I want to use to create a new MariaDB Galera Cluster:

• Server mysql1, with some data and configured as a donor
• Server mysql2, with no data and /var/lib/mysql empty, which I want to join the new cluster as a new node
• MariaDB version: 10.2.13
• SST method: xtrabackup-v2

MariaDB on mysql1 is up and running, I can browse databases and everything seems good:

root@mysql1:/etc/mysql/conf.d# ps ax|grep mysql
21494 pts/0    Sl     0:03 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib/mysql/plugin --user=mysql --wsrep_on=ON --wsrep_provider=/usr/lib/galera/libgalera_smm.so --skip-log-error --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/run/mysqld/mysqld.sock --port=3306 --wsrep_start_position=580c1d7d-293a-11e8-bbc6-73374d41b35e:77

The problem is that if I start MariaDB on the new node mysql2 the SST process does not start and the new node does not join the cluster.

This is the error on mysql2 when trying to join the cluster:

Mar 17 16:26:55 mysql2 mysqld_safe: Starting mysqld daemon with databases from /var/lib/mysql
Mar 17 16:26:55 mysql2 mysqld_safe: WSREP: Running position recovery with --disable-log-error  --pid-file='/var/lib/mysql/mysql2-recover.pid'
Mar 17 16:26:57 mysql2 mysqld_safe: WSREP: Recovered position 00000000-0000-0000-0000-000000000000:-1
Mar 17 16:26:57 mysql2 mysqld: 2018-03-17 16:26:57 140176298686240 [Note] /usr/sbin/mysqld (mysqld 10.2.13-MariaDB-10.2.13+maria~wheezy-log) starting as process 7237 ...
Mar 17 16:26:57 mysql2 mysqld: 2018-03-17 16:26:57 140176298686240 [Note] WSREP: Read nil XID from storage engines, skipping position init
Mar 17 16:26:57 mysql2 mysqld: 2018-03-17 16:26:57 140176298686240 [Note] WSREP: wsrep_load(): loading provider library '/usr/lib/galera/libgalera_smm.so'
Mar 17 16:26:57 mysql2 mysqld: 2018-03-17 16:26:57 140176298686240 [Note] WSREP: wsrep_load(): Galera 25.3.23(r3789) by Codership Oy <info@codership.com> loaded successfully.
Mar 17 16:26:57 mysql2 mysqld: 2018-03-17 16:26:57 140176298686240 [Note] WSREP: CRC-32C: using "slicing-by-8" algorithm.
Mar 17 16:26:57 mysql2 mysqld: 2018-03-17 16:26:57 140176298686240 [Warning] WSREP: Could not open state file for reading: '/var/lib/mysql//grastate.dat'
Mar 17 16:26:57 mysql2 mysqld: 2018-03-17 16:26:57 140176298686240 [Note] WSREP: Found saved state: 00000000-0000-0000-0000-000000000000:-1, safe_to_bootstrap: 1
Mar 17 16:26:57 mysql2 mysqld: 2018-03-17 16:26:57 140176298686240 [Note] WSREP: Passing config to GCS: base_dir = /var/lib/mysql/; base_host = 192.168.70.27; base_port = 4567; cert.log_conflicts = no; debug = no; evs.auto_evict = 0; evs.delay_margin = PT1S; evs.delayed_keep_period = PT30S; evs.inactive_check_period = PT0.5S; evs.inactive_timeout = PT15S; evs.join_retrans_period = PT1S; evs.max_install_timeouts = 3; evs.send_window = 4; evs.stats_report_period = PT1M; evs.suspect_timeout = PT5S; evs.user_send_window = 2; evs.view_forget_timeout = PT24H; gcache.dir = /var/lib/mysql/; gcache.keep_pages_size = 0; gcache.mem_size = 0; gcache.name = /var/lib/mysql//galera.cache; gcache.page_size = 128M; gcache.recover = no; gcache.size = 128M; gcomm.thread_prio = ; gcs.fc_debug = 0; gcs.fc_factor = 1.0; gcs.fc_limit = 16; gcs.fc_master_slave = no; gcs.max_packet_size = 64500; gcs.max_throttle = 0.25; gcs.recv_q_hard_limit = 9223372036854775807; gcs.recv_q_soft_limit = 0.25; gcs.sync_donor = no; gmcast.segment = 0; gmcast.version = 0; pc.announ
Mar 17 16:26:57 mysql2 mysqld: ce_timeout = PT3S; pc.checksum = false; pc.
Mar 17 16:26:57 mysql2 mysqld: 2018-03-17 16:26:57 140176298686240 [Note] WSREP: GCache history reset: 00000000-0000-0000-0000-000000000000:0 -> 00000000-0000-0000-0000-000000000000:-1
Mar 17 16:26:57 mysql2 mysqld: 2018-03-17 16:26:57 140176298686240 [Note] WSREP: Assign initial position for certification: -1, protocol version: -1
Mar 17 16:26:57 mysql2 mysqld: 2018-03-17 16:26:57 140176298686240 [Note] WSREP: wsrep_sst_grab()
Mar 17 16:26:57 mysql2 mysqld: 2018-03-17 16:26:57 140176298686240 [Note] WSREP: Start replication
Mar 17 16:26:57 mysql2 mysqld: 2018-03-17 16:26:57 140176298686240 [Note] WSREP: Setting initial position to 00000000-0000-0000-0000-000000000000:-1
Mar 17 16:26:57 mysql2 mysqld: 2018-03-17 16:26:57 140176298686240 [Note] WSREP: protonet asio version 0
Mar 17 16:26:57 mysql2 mysqld: 2018-03-17 16:26:57 140176298686240 [Note] WSREP: Using CRC-32C for message checksums.
Mar 17 16:26:57 mysql2 mysqld: 2018-03-17 16:26:57 140176298686240 [Note] WSREP: backend: asio
Mar 17 16:26:57 mysql2 mysqld: 2018-03-17 16:26:57 140176298686240 [Note] WSREP: gcomm thread scheduling priority set to other:0 
Mar 17 16:26:57 mysql2 mysqld: 2018-03-17 16:26:57 140176298686240 [Warning] WSREP: access file(/var/lib/mysql//gvwstate.dat) failed(No such file or directory)
Mar 17 16:26:57 mysql2 mysqld: 2018-03-17 16:26:57 140176298686240 [Note] WSREP: restore pc from disk failed
Mar 17 16:26:57 mysql2 mysqld: 2018-03-17 16:26:57 140176298686240 [Note] WSREP: GMCast version 0
Mar 17 16:26:57 mysql2 mysqld: 2018-03-17 16:26:57 140176298686240 [Note] WSREP: (a143e2cb, 'tcp://0.0.0.0:4567') listening at tcp://0.0.0.0:4567
Mar 17 16:26:57 mysql2 mysqld: 2018-03-17 16:26:57 140176298686240 [Note] WSREP: (a143e2cb, 'tcp://0.0.0.0:4567') multicast: , ttl: 1
Mar 17 16:26:57 mysql2 mysqld: 2018-03-17 16:26:57 140176298686240 [Note] WSREP: EVS version 0
Mar 17 16:26:57 mysql2 mysqld: 2018-03-17 16:26:57 140176298686240 [Note] WSREP: gcomm: connecting to group 'ems_wsrep_cluster', peer 'mysql1:,mysql2:'
Mar 17 16:26:57 mysql2 mysqld: 2018-03-17 16:26:57 140176298686240 [Note] WSREP: (a143e2cb, 'tcp://0.0.0.0:4567') connection established to a143e2cb tcp://192.168.70.27:4567
Mar 17 16:26:57 mysql2 mysqld: 2018-03-17 16:26:57 140176298686240 [Warning] WSREP: (a143e2cb, 'tcp://0.0.0.0:4567') address 'tcp://192.168.70.27:4567' points to own listening address, blacklisting
Mar 17 16:26:57 mysql2 mysqld: 2018-03-17 16:26:57 140176298686240 [Note] WSREP: (a143e2cb, 'tcp://0.0.0.0:4567') connection established to a087d8bb tcp://192.168.70.26:4567
Mar 17 16:26:57 mysql2 mysqld: 2018-03-17 16:26:57 140176298686240 [Note] WSREP: (a143e2cb, 'tcp://0.0.0.0:4567') turning message relay requesting on, nonlive peers: 
Mar 17 16:26:57 mysql2 mysqld: 2018-03-17 16:26:57 140176298686240 [Note] WSREP: declaring a087d8bb at tcp://192.168.70.26:4567 stable
Mar 17 16:26:57 mysql2 mysqld: 2018-03-17 16:26:57 140176298686240 [Note] WSREP: Node a087d8bb state prim
Mar 17 16:26:57 mysql2 mysqld: 2018-03-17 16:26:57 140176298686240 [Note] WSREP: view(view_id(PRIM,a087d8bb,6) memb {
Mar 17 16:26:57 mysql2 mysqld: #011a087d8bb,0
Mar 17 16:26:57 mysql2 mysqld: #011a143e2cb,0
Mar 17 16:26:57 mysql2 mysqld: } joined {
Mar 17 16:26:57 mysql2 mysqld: } left {
Mar 17 16:26:57 mysql2 mysqld: } partitioned {
Mar 17 16:26:57 mysql2 mysqld: })
Mar 17 16:26:57 mysql2 mysqld: 2018-03-17 16:26:57 140176298686240 [Note] WSREP: save pc into disk
Mar 17 16:26:58 mysql2 mysqld: 2018-03-17 16:26:58 140176298686240 [Note] WSREP: gcomm: connected
Mar 17 16:26:58 mysql2 mysqld: 2018-03-17 16:26:58 140176298686240 [Note] WSREP: Changing maximum packet size to 64500, resulting msg size: 32636
Mar 17 16:26:58 mysql2 mysqld: 2018-03-17 16:26:58 140176298686240 [Note] WSREP: Shifting CLOSED -> OPEN (TO: 0)
Mar 17 16:26:58 mysql2 mysqld: 2018-03-17 16:26:58 140176298686240 [Note] WSREP: Opened channel 'ems_wsrep_cluster'
Mar 17 16:26:58 mysql2 mysqld: 2018-03-17 16:26:58 140176044816128 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 1, memb_num = 2
Mar 17 16:26:58 mysql2 mysqld: 2018-03-17 16:26:58 140176044816128 [Note] WSREP: STATE EXCHANGE: Waiting for state UUID.
Mar 17 16:26:58 mysql2 mysqld: 2018-03-17 16:26:58 140176298686240 [Note] WSREP: Waiting for SST to complete.
Mar 17 16:26:58 mysql2 mysqld: 2018-03-17 16:26:58 140176044816128 [Note] WSREP: STATE EXCHANGE: sent state msg: a0b9a1ef-29f7-11e8-aee4-9be20db2eead
Mar 17 16:26:58 mysql2 mysqld: 2018-03-17 16:26:58 140176044816128 [Note] WSREP: STATE EXCHANGE: got state msg: a0b9a1ef-29f7-11e8-aee4-9be20db2eead from 0 (mysql1)
Mar 17 16:26:58 mysql2 mysqld: 2018-03-17 16:26:58 140176044816128 [Note] WSREP: STATE EXCHANGE: got state msg: a0b9a1ef-29f7-11e8-aee4-9be20db2eead from 1 (mysql2)
Mar 17 16:26:58 mysql2 mysqld: 2018-03-17 16:26:58 140176044816128 [Note] WSREP: Quorum results:
Mar 17 16:26:58 mysql2 mysqld: #011version    = 4,
Mar 17 16:26:58 mysql2 mysqld: #011component  = PRIMARY,
Mar 17 16:26:58 mysql2 mysqld: #011conf_id    = 5,
Mar 17 16:26:58 mysql2 mysqld: #011members    = 1/2 (joined/total),
Mar 17 16:26:58 mysql2 mysqld: #011act_id     = 77,
Mar 17 16:26:58 mysql2 mysqld: #011last_appl. = -1,
Mar 17 16:26:58 mysql2 mysqld: #011protocols  = 0/8/3 (gcs/repl/appl),
Mar 17 16:26:58 mysql2 mysqld: #011group UUID = 580c1d7d-293a-11e8-bbc6-73374d41b35e
Mar 17 16:26:58 mysql2 mysqld: 2018-03-17 16:26:58 140176044816128 [Note] WSREP: Flow-control interval: [23, 23]
Mar 17 16:26:58 mysql2 mysqld: 2018-03-17 16:26:58 140176044816128 [Note] WSREP: Trying to continue unpaused monitor
Mar 17 16:26:58 mysql2 mysqld: 2018-03-17 16:26:58 140176044816128 [Note] WSREP: Shifting OPEN -> PRIMARY (TO: 77)
Mar 17 16:26:58 mysql2 mysqld: 2018-03-17 16:26:58 140176036120320 [Note] WSREP: State transfer required: 
Mar 17 16:26:58 mysql2 mysqld: #011Group state: 580c1d7d-293a-11e8-bbc6-73374d41b35e:77
Mar 17 16:26:58 mysql2 mysqld: #011Local state: 00000000-0000-0000-0000-000000000000:-1
Mar 17 16:26:58 mysql2 mysqld: 2018-03-17 16:26:58 140176036120320 [Note] WSREP: New cluster view: global state: 580c1d7d-293a-11e8-bbc6-73374d41b35e:77, view# 6: Primary, number of nodes: 2, my index: 1, protocol version 3
Mar 17 16:26:58 mysql2 mysqld: 2018-03-17 16:26:58 140176036120320 [Warning] WSREP: Gap in state sequence. Need state transfer.
Mar 17 16:26:58 mysql2 mysqld: 2018-03-17 16:26:58 140176035354368 [Note] WSREP: Running: 'wsrep_sst_xtrabackup-v2 --role 'joiner' --address '192.168.70.27' --datadir '/var/lib/mysql/'   --parent '7237' --binlog '/var/log/mysql/mariadb-bin' '
Mar 17 16:26:58 mysql2 mysqld: WSREP_SST: [INFO] Logging all stderr of SST/Innobackupex to syslog (20180317 16:26:58.601)
Mar 17 16:26:58 mysql2 -wsrep-sst-joiner: Streaming with xbstream
Mar 17 16:26:58 mysql2 -wsrep-sst-joiner: Using socat as streamer
Mar 17 16:26:58 mysql2 -wsrep-sst-joiner: Evaluating timeout -k 110 100 socat -u TCP-LISTEN:4444,reuseaddr stdio | pv -f  -i 10 -N joiner  2>>/var/log/mysql/xtrabackup-progress.log | xbstream -x; RC=( ${PIPESTATUS[@]} )
Mar 17 16:27:00 mysql2 mysqld: 2018-03-17 16:27:00 140176053208832 [Note] WSREP: (a143e2cb, 'tcp://0.0.0.0:4567') connection to peer a143e2cb with addr tcp://192.168.70.27:4567 timed out, no messages seen in PT3S
Mar 17 16:27:00 mysql2 mysqld: 2018-03-17 16:27:00 140176053208832 [Note] WSREP: (a143e2cb, 'tcp://0.0.0.0:4567') turning message relay requesting off
Mar 17 16:27:26 mysql2 /etc/init.d/mysql[7755]: 0 processes alive and '/usr/bin/mysqladmin --defaults-file=/etc/mysql/debian.cnf ping' resulted in
Mar 17 16:27:26 mysql2 /etc/init.d/mysql[7755]: #007/usr/bin/mysqladmin: connect to server at 'localhost' failed
Mar 17 16:27:26 mysql2 /etc/init.d/mysql[7755]: error: 'Can't connect to local MySQL server through socket '/var/run/mysqld/mysqld.sock' (111)'
Mar 17 16:27:26 mysql2 /etc/init.d/mysql[7755]: Check that mysqld is running and that the socket: '/var/run/mysqld/mysqld.sock' exists!
Mar 17 16:27:26 mysql2 /etc/init.d/mysql[7755]:

This is the log on the donor mysql1:

Mar 17 16:26:55 mysql1 mysqld: 2018-03-17 16:26:55 140097807628032 [Note] WSREP: (a087d8bb, 'tcp://0.0.0.0:4567') connection established to a143e2cb tcp://192.168.70.27:4567
Mar 17 16:26:55 mysql1 mysqld: 2018-03-17 16:26:55 140097807628032 [Note] WSREP: (a087d8bb, 'tcp://0.0.0.0:4567') turning message relay requesting on, nonlive peers: 
Mar 17 16:26:56 mysql1 mysqld: 2018-03-17 16:26:56 140097807628032 [Note] WSREP: declaring a143e2cb at tcp://192.168.70.27:4567 stable
Mar 17 16:26:56 mysql1 mysqld: 2018-03-17 16:26:56 140097807628032 [Note] WSREP: Node a087d8bb state prim
Mar 17 16:26:56 mysql1 mysqld: 2018-03-17 16:26:56 140097807628032 [Note] WSREP: view(view_id(PRIM,a087d8bb,6) memb {
Mar 17 16:26:56 mysql1 mysqld: #011a087d8bb,0
Mar 17 16:26:56 mysql1 mysqld: #011a143e2cb,0
Mar 17 16:26:56 mysql1 mysqld: } joined {
Mar 17 16:26:56 mysql1 mysqld: } left {
Mar 17 16:26:56 mysql1 mysqld: } partitioned {
Mar 17 16:26:56 mysql1 mysqld: })
Mar 17 16:26:56 mysql1 mysqld: 2018-03-17 16:26:56 140097807628032 [Note] WSREP: save pc into disk
Mar 17 16:26:56 mysql1 mysqld: 2018-03-17 16:26:56 140097799235328 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 0, memb_num = 2
Mar 17 16:26:56 mysql1 mysqld: 2018-03-17 16:26:56 140097799235328 [Note] WSREP: STATE_EXCHANGE: sent state UUID: a0b9a1ef-29f7-11e8-aee4-9be20db2eead
Mar 17 16:26:56 mysql1 mysqld: 2018-03-17 16:26:56 140097799235328 [Note] WSREP: STATE EXCHANGE: sent state msg: a0b9a1ef-29f7-11e8-aee4-9be20db2eead
Mar 17 16:26:56 mysql1 mysqld: 2018-03-17 16:26:56 140097799235328 [Note] WSREP: STATE EXCHANGE: got state msg: a0b9a1ef-29f7-11e8-aee4-9be20db2eead from 0 (mysql1)
Mar 17 16:26:56 mysql1 mysqld: 2018-03-17 16:26:56 140097799235328 [Note] WSREP: STATE EXCHANGE: got state msg: a0b9a1ef-29f7-11e8-aee4-9be20db2eead from 1 (mysql2)
Mar 17 16:26:56 mysql1 mysqld: 2018-03-17 16:26:56 140097799235328 [Note] WSREP: Quorum results:
Mar 17 16:26:56 mysql1 mysqld: #011version    = 4,
Mar 17 16:26:56 mysql1 mysqld: #011component  = PRIMARY,
Mar 17 16:26:56 mysql1 mysqld: #011conf_id    = 5,
Mar 17 16:26:56 mysql1 mysqld: #011members    = 1/2 (joined/total),
Mar 17 16:26:56 mysql1 mysqld: #011act_id     = 77,
Mar 17 16:26:56 mysql1 mysqld: #011last_appl. = 0,
Mar 17 16:26:56 mysql1 mysqld: #011protocols  = 0/8/3 (gcs/repl/appl),
Mar 17 16:26:56 mysql1 mysqld: #011group UUID = 580c1d7d-293a-11e8-bbc6-73374d41b35e
Mar 17 16:26:56 mysql1 mysqld: 2018-03-17 16:26:56 140097799235328 [Note] WSREP: Flow-control interval: [23, 23]
Mar 17 16:26:56 mysql1 mysqld: 2018-03-17 16:26:56 140097799235328 [Note] WSREP: Trying to continue unpaused monitor
Mar 17 16:26:56 mysql1 mysqld: 2018-03-17 16:26:56 140097790539520 [Note] WSREP: New cluster view: global state: 580c1d7d-293a-11e8-bbc6-73374d41b35e:77, view# 6: Primary, number of nodes: 2, my index: 0, protocol version 3
Mar 17 16:26:56 mysql1 mysqld: 2018-03-17 16:26:56 140097790539520 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
Mar 17 16:26:56 mysql1 mysqld: 2018-03-17 16:26:56 140097790539520 [Note] WSREP: REPL Protocols: 8 (3, 2)
Mar 17 16:26:56 mysql1 mysqld: 2018-03-17 16:26:56 140097790539520 [Note] WSREP: Assign initial position for certification: 77, protocol version: 3
Mar 17 16:26:56 mysql1 mysqld: 2018-03-17 16:26:56 140097841202944 [Note] WSREP: Service thread queue flushed.
Mar 17 16:26:59 mysql1 mysqld: 2018-03-17 16:26:59 140097807628032 [Note] WSREP: (a087d8bb, 'tcp://0.0.0.0:4567') turning message relay requesting off

This is the configuration on the donor mysql1:

root@mysql1:/etc/mysql/conf.d# cat /etc/mysql/conf.d/galera.cnf 
[mysqld]
#mysql settings
binlog_format=ROW
default-storage-engine=innodb
innodb_autoinc_lock_mode=2
query_cache_size=0
query_cache_type=0
bind-address=0.0.0.0
#galera settings
wsrep_on=ON
wsrep_provider=/usr/lib/galera/libgalera_smm.so
wsrep_cluster_name="ems_wsrep_cluster"
wsrep_cluster_address="gcomm://"
wsrep_sst_method=xtrabackup-v2
wsrep_sst_auth="cluster_sst:[password]
#innoDB settings
innodb_flush_log_at_trx_commit=2
innodb_data_file_path = ibdata1:100M:autoextend
innodb_read_io_threads=4
innodb_write_io_threads=4
innodb_doublewrite=1
innodb_buffer_pool_instances=8
innodb_log_files_in_group=2
innodb_thread_concurrency=64
innodb_autoinc_lock_mode=2
key_buffer_size = 24M
tmp_table_size = 64M
max_heap_table_size = 64M
max_allowed_packet = 512M
skip_name_resolve
memlock=0
sysdate_is_now=1
max_connections=200
thread_cache_size=512
query_cache_type = 0
query_cache_size = 0
table_open_cache=1024
lower_case_table_names=0
explicit_defaults_for_timestamp=1
wsrep_slave_threads=8
wsrep_certify_nonPK=1
wsrep_max_ws_rows=131072
wsrep_max_ws_size=1073741824
wsrep_convert_LOCK_to_trx=0
wsrep_retry_autocommit=1
wsrep_auto_increment_control=1
wsrep_causal_reads=0
[sst]
progress=/var/log/mysql/xtrabackup-progress.log

And this is the configugration on the joiner mysql2:

root@mysql2:~# cat /etc/mysql/conf.d/galera.cnf 
[mysqld]
#mysql settings
binlog_format=ROW
default-storage-engine=innodb
innodb_autoinc_lock_mode=2
query_cache_size=0
query_cache_type=0
bind-address=0.0.0.0
#galera settings
wsrep_on=ON
wsrep_provider=/usr/lib/galera/libgalera_smm.so
wsrep_cluster_name="ems_wsrep_cluster"
wsrep_cluster_address="gcomm://mysql1,mysql2"
wsrep_sst_method=xtrabackup-v2
wsrep_sst_auth="cluster_sst:[password]
#innoDB settings
innodb_flush_log_at_trx_commit=2
innodb_data_file_path = ibdata1:100M:autoextend
innodb_read_io_threads=4
innodb_write_io_threads=4
innodb_doublewrite=1
innodb_buffer_pool_instances=8
innodb_log_files_in_group=2
innodb_thread_concurrency=64
innodb_autoinc_lock_mode=2
key_buffer_size = 24M
tmp_table_size = 64M
max_heap_table_size = 64M
max_allowed_packet = 512M
skip_name_resolve
memlock=0
sysdate_is_now=1
max_connections=200
thread_cache_size=512
query_cache_type = 0
query_cache_size = 0
table_open_cache=1024
lower_case_table_names=0
explicit_defaults_for_timestamp=1
wsrep_slave_threads=8
wsrep_certify_nonPK=1
wsrep_max_ws_rows=131072
wsrep_max_ws_size=1073741824
wsrep_convert_LOCK_to_trx=0
wsrep_retry_autocommit=1
wsrep_auto_increment_control=1
wsrep_causal_reads=0
[sst]
progress=/var/log/mysql/xtrabackup-progress.log

Both servers can connect each other and there are no firewall rules on them which could limit traffic.

Could you help me please?

Thank you very much!