[MDEV-15355] upgrade to 10.1.31 break Galera SST/IST transfer Created: 2018-02-19  Updated: 2019-05-20  Resolved: 2019-05-20

Status: Closed
Project: MariaDB Server
Component/s: Galera
Affects Version/s: 10.1.31
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Matthias Crauwels Assignee: Jan Lindström (Inactive)
Resolution: Duplicate Votes: 1
Labels: None
Environment:

Linux observed on both Ubuntu and CentOS

Issue Links:
Problem/Incident
is caused by MDEV-13789 mariabackup galera SST fail Closed
Relates
relates to MDEV-15254 10.1.31 does not join an existing clu... Closed

 Description   

upgrading to mariadb-server 10.1.31 break the Galera SST/IST transfer.

The joiner node script gets executed but the donor never starts:
Joiner side:

2018-02-19 18:07:09 140541460941568 [Note] WSREP: State transfer required:
 
	Group state: ba08f7ac-1589-11e8-8944-27e143bb408f:285676
 
	Local state: ba08f7ac-1589-11e8-8944-27e143bb408f:273759
 
2018-02-19 18:07:09 140541460941568 [Note] WSREP: New cluster view: global state: ba08f7ac-1589-11e8-8944-27e143bb408f:285676, view# 33: Primary, number of nodes: 3, my index: 0, protocol version 3
 
2018-02-19 18:07:09 140541460941568 [Warning] WSREP: Gap in state sequence. Need state transfer.
 
2018-02-19 18:07:09 140541165565696 [Note] WSREP: Running: 'wsrep_sst_xtrabackup-v2 --role 'joiner' --address '192.168.55.101' --datadir '/var/lib/mysql/'   --parent '4754'  '' '
 
WSREP_SST: [INFO] Streaming with xbstream (20180219 18:07:09.327)
 
WSREP_SST: [INFO] Using socat as streamer (20180219 18:07:09.329)
 
WSREP_SST: [INFO] Stale sst_in_progress file: /var/lib/mysql//sst_in_progress (20180219 18:07:09.332)
 
WSREP_SST: [INFO] Evaluating timeout -k 110 100 socat -u TCP-LISTEN:4444,reuseaddr stdio | xbstream -x; RC=( ${PIPESTATUS[@]} ) (20180219 18:07:09.354)
 
2018-02-19 18:07:11 140541190731520 [Note] WSREP: (b2ffafb5, 'tcp://0.0.0.0:4567') connection to peer b2ffafb5 with addr tcp://192.168.55.101:4567 timed out, no messages seen in PT3S
 
2018-02-19 18:07:11 140541190731520 [Note] WSREP: (b2ffafb5, 'tcp://0.0.0.0:4567') turning message relay requesting off
 
WSREP_SST: [ERROR] Possible timeout in receving first data from donor in gtid stage (20180219 18:08:49.362)
 
WSREP_SST: [ERROR] Cleanup after exit with status:32 (20180219 18:08:49.364)
 
2018-02-19 18:08:49 140541165565696 [ERROR] WSREP: Failed to read 'ready <addr>' from: wsrep_sst_xtrabackup-v2 --role 'joiner' --address '192.168.55.101' --datadir '/var/lib/mysql/'   --parent '4754'  ''
 
	Read: '(null)'
 
2018-02-19 18:08:49 140541165565696 [ERROR] WSREP: Process completed with error: wsrep_sst_xtrabackup-v2 --role 'joiner' --address '192.168.55.101' --datadir '/var/lib/mysql/'   --parent '4754'  '' : 32 (Broken pipe)
 
2018-02-19 18:08:49 140541460941568 [ERROR] WSREP: Failed to prepare for 'xtrabackup-v2' SST. Unrecoverable.
 
2018-02-19 18:08:49 140541460941568 [ERROR] Aborting

Donor side:

2018-02-19 18:07:08 139902381455104 [Note] WSREP: (c9241678, ‘tcp://0.0.0.0:4567’) connection established to b2ffafb5 tcp://192.168.55.101:4567
 
2018-02-19 18:07:08 139902381455104 [Note] WSREP: (c9241678, ‘tcp://0.0.0.0:4567’) turning message relay requesting on, nonlive peers:
 
2018-02-19 18:07:08 139902381455104 [Note] WSREP: declaring b2ffafb5 at tcp://192.168.55.101:4567 stable
 
2018-02-19 18:07:08 139902381455104 [Note] WSREP: declaring b91cf7da at tcp://192.168.55.102:4567 stable
 
2018-02-19 18:07:08 139902381455104 [Note] WSREP: Node b91cf7da state prim
 
2018-02-19 18:07:08 139902381455104 [Note] WSREP: view(view_id(PRIM,b2ffafb5,33) memb {
 
	b2ffafb5,0
 
	b91cf7da,0
 
	c9241678,0
 
} joined {
 
} left {
 
} partitioned {
 
})
 
2018-02-19 18:07:08 139902381455104 [Note] WSREP: save pc into disk
 
2018-02-19 18:07:08 139902373062400 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 2, memb_num = 3
 
2018-02-19 18:07:08 139902373062400 [Note] WSREP: STATE EXCHANGE: Waiting for state UUID.
 
2018-02-19 18:07:09 139902373062400 [Note] WSREP: STATE EXCHANGE: sent state msg: b3995870-159f-11e8-8bdd-c675484f2591
 
2018-02-19 18:07:09 139902373062400 [Note] WSREP: STATE EXCHANGE: got state msg: b3995870-159f-11e8-8bdd-c675484f2591 from 0 (galera2)
 
2018-02-19 18:07:09 139902373062400 [Note] WSREP: STATE EXCHANGE: got state msg: b3995870-159f-11e8-8bdd-c675484f2591 from 1 (galera3)
 
2018-02-19 18:07:09 139902373062400 [Note] WSREP: STATE EXCHANGE: got state msg: b3995870-159f-11e8-8bdd-c675484f2591 from 2 (galera1)
 
2018-02-19 18:07:09 139902373062400 [Note] WSREP: Quorum results:
 
	version    = 4,
 
	component  = PRIMARY,
 
	conf_id    = 32,
 
	members    = 2/3 (joined/total),
 
	act_id     = 285676,
 
	last_appl. = 0,
 
	protocols  = 0/7/3 (gcs/repl/appl),
 
	group UUID = ba08f7ac-1589-11e8-8944-27e143bb408f
 
2018-02-19 18:07:09 139902373062400 [Note] WSREP: Flow-control interval: [28, 28]
 
2018-02-19 18:07:09 139902373062400 [Note] WSREP: Trying to continue unpaused monitor
 
2018-02-19 18:07:09 139902653332224 [Note] WSREP: New cluster view: global state: ba08f7ac-1589-11e8-8944-27e143bb408f:285676, view# 33: Primary, number of nodes: 3, my index: 2, protocol version 3
 
2018-02-19 18:07:09 139902653332224 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
 
2018-02-19 18:07:09 139902653332224 [Note] WSREP: REPL Protocols: 7 (3, 2)
 
2018-02-19 18:07:09 139902653332224 [Note] WSREP: Assign initial position for certification: 285676, protocol version: 3
 
2018-02-19 18:07:09 139902431176448 [Note] WSREP: Service thread queue flushed.
 
2018-02-19 18:07:11 139902381455104 [Note] WSREP: (c9241678, ‘tcp://0.0.0.0:4567’) turning message relay requesting off
 
2018-02-19 18:08:51 139902381455104 [Note] WSREP: declaring b91cf7da at tcp://192.168.55.102:4567 stable
 
2018-02-19 18:08:51 139902381455104 [Note] WSREP: forgetting b2ffafb5 (tcp://192.168.55.101:4567)
 
2018-02-19 18:08:51 139902381455104 [Note] WSREP: Node b91cf7da state prim
 
2018-02-19 18:08:51 139902381455104 [Note] WSREP: view(view_id(PRIM,b91cf7da,34) memb {
 
	b91cf7da,0
 
	c9241678,0
 
} joined {
 
} left {
 
} partitioned {
 
	b2ffafb5,0
 
})
 
2018-02-19 18:08:51 139902381455104 [Note] WSREP: save pc into disk
 
2018-02-19 18:08:51 139902373062400 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 1, memb_num = 2
 
2018-02-19 18:08:51 139902373062400 [Note] WSREP: STATE EXCHANGE: Waiting for state UUID.
 
2018-02-19 18:08:51 139902381455104 [Note] WSREP: forgetting b2ffafb5 (tcp://192.168.55.101:4567)
 
2018-02-19 18:08:51 139902373062400 [Note] WSREP: STATE EXCHANGE: sent state msg: f080587a-159f-11e8-ad75-9fb8ddac3bd7
 
2018-02-19 18:08:51 139902373062400 [Note] WSREP: STATE EXCHANGE: got state msg: f080587a-159f-11e8-ad75-9fb8ddac3bd7 from 0 (galera3)
 
2018-02-19 18:08:51 139902373062400 [Note] WSREP: STATE EXCHANGE: got state msg: f080587a-159f-11e8-ad75-9fb8ddac3bd7 from 1 (galera1)
 
2018-02-19 18:08:51 139902373062400 [Note] WSREP: Quorum results:
 
	version    = 4,
 
	component  = PRIMARY,
 
	conf_id    = 33,
 
	members    = 2/2 (joined/total),
 
	act_id     = 285676,
 
	last_appl. = 0,
 
	protocols  = 0/7/3 (gcs/repl/appl),
 
	group UUID = ba08f7ac-1589-11e8-8944-27e143bb408f
 
2018-02-19 18:08:51 139902373062400 [Note] WSREP: Flow-control interval: [23, 23]
 
2018-02-19 18:08:51 139902373062400 [Note] WSREP: Trying to continue unpaused monitor
 
2018-02-19 18:08:51 139902653332224 [Note] WSREP: New cluster view: global state: ba08f7ac-1589-11e8-8944-27e143bb408f:285676, view# 34: Primary, number of nodes: 2, my index: 1, protocol version 3
 
2018-02-19 18:08:51 139902653332224 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
 
2018-02-19 18:08:51 139902653332224 [Note] WSREP: REPL Protocols: 7 (3, 2)
 
2018-02-19 18:08:51 139902653332224 [Note] WSREP: Assign initial position for certification: 285676, protocol version: 3
 
2018-02-19 18:08:51 139902431176448 [Note] WSREP: Service thread queue flushed.
 
2018-02-19 18:08:56 139902381455104 [Note] WSREP:  cleaning up b2ffafb5 (tcp://192.168.55.101:4567)

I traced it back to the function wait_for_listen in the wsrep_sst_xtrabackup-v2 script
v10.1.30 that works is

# waits ~1 minute for nc/socat to open the port and then reports ready
 
# (regardless of timeout)
 
wait_for_listen()
 
{
 
    local HOST=$1
 
    local PORT=$2
 
    local MODULE=$3
 
 
 
    for i in {1..300}
 
    do
 
        ss -p state listening "( sport = :$PORT )" | grep -qE 'socat|nc' && break
 
        sleep 0.2
 
    done
 
 
 
    echo "ready ${HOST}:${PORT}/${MODULE}//$sst_ver"
 
}

v10.1.31 that is broken

# waits ~1 minute for nc/socat to open the port and then reports ready
 
# (regardless of timeout)
 
wait_for_listen()
 
{
 
    local HOST=$1
 
    local PORT=$2
 
    local MODULE=$3
 
    local LSOF_OUT
 
 
 
    for i in {1..300}
 
    do
 
        LSOF_OUT=$(lsof -sTCP:LISTEN -i TCP:${PORT} -a -c nc -c socat -F c)
 
        [ -n "${LSOF_OUT}" ] && break
 
        sleep 0.2
 
    done
 
 
 
    echo "ready ${HOST}:${PORT}/${MODULE}//${WSREP_SST_OPT_SST_VER:-1}"
 
}



 Comments   
Comment by Matthias Crauwels [ 2018-02-19 ]

injecting the loop in the 10.1.30 function into the 10.1.31 script fixes it in my test lab...

Comment by Zdravelina Sokolovska (Inactive) [ 2018-02-20 ]

hello mcrauwel,what wsrep_sst_method have you used ?

Comment by Matthias Crauwels [ 2018-02-20 ]

Hey @winstone

This is the config I used: 

# cat /etc/mysql/conf.d/cluster.cnf
 
#########################################################
 
# Galera config
 
#########################################################
 
 
 
[mysqld]
 
wsrep_on                                  = ON
 
wsrep_provider                            = /usr/lib/libgalera_smm.so
 
wsrep_provider_options                    =
 
wsrep_cluster_name                        = galera
 
wsrep_cluster_address                     = gcomm://192.168.55.100,192.168.55.101,192.168.55.102
 
wsrep_node_address                        = 192.168.55.101
 
wsrep_log_conflicts                       = 1
 
wsrep_sst_method                          = xtrabackup-v2
 
wsrep_sst_auth                            = sstuser:sstpass
 
 
 
# Galera overrides
 
binlog_format                             = ROW
 
innodb_autoinc_lock_mode                  = 2

Comment by Zdravelina Sokolovska (Inactive) [ 2018-02-20 ]

mcrauwel what's the percona-xtrabackup version you have installed ?

Comment by Matthias Crauwels [ 2018-02-20 ] 

# xtrabackup --version
 
xtrabackup version 2.4.9 based on MySQL server 5.7.13 Linux (x86_64) (revision id: a467167cdd4)

Comment by Claudio Nanni [ 2018-02-20 ]

Duplicate of: https://jira.mariadb.org/browse/MDEV-15254

Generated at Thu Feb 08 08:20:40 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.