[#MDEV-30070] After failed IST Galera lost proper receiver's sequence and follows up with SST instead

Problem: after failed IST Galera lost proper receiver's sequence and follows up with SST instead.

There is also other issue in this case; why would be IST still relying on mariabackup (likely because of ?(undocumented) dependency on wsrep_sst_method=mariabackup),
when the method selection in case of IST have no apparent benefit over rsync or other commonly used operation system's tools.

Example:
Receiver node is trying to sync with cluster. Requested IST sequence is 47183780-47271256. This attempt failed with error -42 (at that point, cause was still unknown)

2022-11-17 17:58:31 0 [Note] WSREP: Service thread queue flushed.

2022-11-17 17:58:31 0 [Note] WSREP: ####### Assign initial position for certification: a39c0363-6504-11ed-aece-7f680ced2e93:47183779, protocol version: -1

2022-11-17 17:58:31 0 [Note] WSREP: Start replication

2022-11-17 17:58:31 0 [Note] WSREP: Connecting with bootstrap option: 0

2022-11-17 17:58:31 0 [Note] WSREP: Setting GCS initial position to a39c0363-6504-11ed-aece-7f680ced2e93:47183779

2022-11-17 17:58:31 0 [Note] WSREP: protonet asio version 0

2022-11-17 17:58:31 0 [Note] WSREP: Using CRC-32C for message checksums.

2022-11-17 17:58:31 0 [Note] WSREP: backend: asio

2022-11-17 17:58:31 0 [Note] WSREP: gcomm thread scheduling priority set to other:0

2022-11-17 17:58:31 0 [Warning] WSREP: access file(/var/lib/mysql-data/gvwstate.dat) failed(No such file or directory)

2022-11-17 17:58:31 0 [Note] WSREP: restore pc from disk failed

2022-11-17 17:58:31 0 [Note] WSREP: GMCast version 0

2022-11-17 17:58:31 0 [Note] WSREP: (10d22ccf-ac57, 'tcp://x.x.x.x:4567') listening at tcp://x.x.x.x:4567

2022-11-17 17:58:31 0 [Note] WSREP: (10d22ccf-ac57, 'tcp://x.x.x.x:4567') multicast: , ttl: 1

2022-11-17 17:58:31 0 [Note] WSREP: EVS version 1

2022-11-17 17:58:31 0 [Note] WSREP: gcomm: connecting to group 'xxx', peer 'x.x.x.x:,x.x.x.x:,x.x.x.x:'

2022-11-17 17:58:31 0 [Note] WSREP: (10d22ccf-ac57, 'tcp://x.x.x.x:4567') Found matching local endpoint for a connection, blacklisting address tcp://x.x.x.x:4567

2022-11-17 17:58:31 0 [Note] WSREP: (10d22ccf-ac57, 'tcp://x.x.x.x:4567') connection established to faf13cda-b959 tcp://x.x.x.x:4567

2022-11-17 17:58:31 0 [Note] WSREP: (10d22ccf-ac57, 'tcp://x.x.x.x:4567') turning message relay requesting on, nonlive peers:

2022-11-17 17:58:31 0 [Note] WSREP: (10d22ccf-ac57, 'tcp://x.x.x.x:4567') connection established to 0471cb54-9588 tcp://x.x.x.x:4567

2022-11-17 17:58:33 0 [Note] WSREP: EVS version upgrade 0 -> 1

2022-11-17 17:58:33 0 [Note] WSREP: declaring 0471cb54-9588 at tcp://x.x.x.x:4567 stable

2022-11-17 17:58:33 0 [Note] WSREP: declaring faf13cda-b959 at tcp://x.x.x.x:4567 stable

2022-11-17 17:58:33 0 [Note] WSREP: PC protocol upgrade 0 -> 1

2022-11-17 17:58:33 0 [Note] WSREP: Node 0471cb54-9588 state prim

2022-11-17 17:58:33 0 [Note] WSREP: view(view_id(PRIM,0471cb54-9588,62) memb {

        0471cb54-9588,0

        10d22ccf-ac57,0

        faf13cda-b959,0

} joined {

} left {

} partitioned {

})

2022-11-17 17:58:33 0 [Note] WSREP: save pc into disk

2022-11-17 17:58:33 0 [Note] WSREP: gcomm: connected

2022-11-17 17:58:33 0 [Note] WSREP: Changing maximum packet size to 64500, resulting msg size: 32636

2022-11-17 17:58:33 0 [Note] WSREP: Shifting CLOSED -> OPEN (TO: 0)

2022-11-17 17:58:33 0 [Note] WSREP: Opened channel 'xxx'

2022-11-17 17:58:33 0 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 1, memb_num = 3

2022-11-17 17:58:33 0 [Note] WSREP: STATE EXCHANGE: Waiting for state UUID.

2022-11-17 17:58:33 0 [Note] WSREP: STATE EXCHANGE: sent state msg: 11bbead7-6699-11ed-8ef1-42434da4c162

2022-11-17 17:58:33 0 [Note] WSREP: STATE EXCHANGE: got state msg: 11bbead7-6699-11ed-8ef1-42434da4c162 from 0 (xxx-n1)

2022-11-17 17:58:33 0 [Note] WSREP: STATE EXCHANGE: got state msg: 11bbead7-6699-11ed-8ef1-42434da4c162 from 2 (xxx-n2)

2022-11-17 17:58:33 1 [Note] WSREP: Starting rollbacker thread 1

2022-11-17 17:58:33 2 [Note] WSREP: Starting applier thread 2

2022-11-17 17:58:33 0 [Note] WSREP: STATE EXCHANGE: got state msg: 11bbead7-6699-11ed-8ef1-42434da4c162 from 1 (xxx-n3)

2022-11-17 17:58:33 0 [Note] WSREP: Quorum results:

        version    = 6,

        component  = PRIMARY,

        conf_id    = 12,

        members    = 2/3 (joined/total),

        act_id     = 47271255,

        last_appl. = 47183723,

        protocols  = 2/10/4 (gcs/repl/appl),

        vote policy= 0,

        group UUID = a39c0363-6504-11ed-aece-7f680ced2e93

2022-11-17 17:58:33 0 [Note] WSREP: Flow-control interval: [443, 443]

2022-11-17 17:58:33 0 [Note] WSREP: Shifting OPEN -> PRIMARY (TO: 47271256)

2022-11-17 17:58:33 2 [Note] WSREP: ####### processing CC 47271256, local, ordered

2022-11-17 17:58:33 2 [Note] WSREP: Process first view: a39c0363-6504-11ed-aece-7f680ced2e93 my uuid: 10d22ccf-6699-11ed-ac57-820fbea36f17

2022-11-17 17:58:33 2 [Note] WSREP: Server xxx-n3 connected to cluster at position a39c0363-6504-11ed-aece-7f680ced2e93:47271256 with ID 10d22ccf-6699-11ed-ac57-820fbea36f17

2022-11-17 17:58:33 2 [Note] WSREP: Server status change disconnected -> connected

2022-11-17 17:58:33 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.

2022-11-17 17:58:33 2 [Note] WSREP: ####### My UUID: 10d22ccf-6699-11ed-ac57-820fbea36f17

2022-11-17 17:58:33 2 [Note] WSREP: Cert index reset to 00000000-0000-0000-0000-000000000000:-1 (proto: 10), state transfer needed: yes

2022-11-17 17:58:33 0 [Note] WSREP: Service thread queue flushed.

2022-11-17 17:58:33 2 [Note] WSREP: ####### Assign initial position for certification: 00000000-0000-0000-0000-000000000000:-1, protocol version: -1

2022-11-17 17:58:33 2 [Note] WSREP: State transfer required:

        Group state: a39c0363-6504-11ed-aece-7f680ced2e93:47271256

        Local state: a39c0363-6504-11ed-aece-7f680ced2e93:47183779

2022-11-17 17:58:33 2 [Note] WSREP: Server status change connected -> joiner

2022-11-17 17:58:33 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.

2022-11-17 17:58:33 0 [Note] WSREP: Joiner monitor thread started to monitor

2022-11-17 17:58:33 0 [Note] WSREP: Running: 'wsrep_sst_mariabackup --role 'joiner' --address 'x.x.x.x' --datadir '/var/lib/mysql-data/' --parent '51596' --binlog '/var/lib/mysql-binlogs/mysql-bin' --mysqld-args --wsrep_start_position=a39c0363-6504-11ed-aece-7f680ced2e93:47183779'

WSREP_SST: [INFO] SSL configuration: CA='', CAPATH='', CERT='', KEY='', MODE='DISABLED', encrypt='0' (20221117 17:58:33.750)

WSREP_SST: [INFO] Moving '/var/lib/mysql-data/mariabackup.prepare.log' to '/tmp/sst_log_archive/mariabackup.prepare.log.2022.11.17-x.x.x.x112516' (20221117 17:58:33.867)

WSREP_SST: [INFO] Moving '/var/lib/mysql-data/mariabackup.move.log' to '/tmp/sst_log_archive/mariabackup.move.log.2022.11.17-x.x.x.x112516' (20221117 17:58:33.908)

WSREP_SST: [INFO] Streaming with mbstream (20221117 17:58:33.931)

WSREP_SST: [INFO] Using socat as streamer (20221117 17:58:33.935)

WSREP_SST: [INFO] Evaluating timeout -k 310 300 socat -u TCP-LISTEN:4444,reuseaddr stdio | '/usr//bin/mbstream' -x; RC=( ${PIPESTATUS[@]} ) (20221117 17:58:34.639)

2022-11-17 17:58:34 2 [Note] WSREP: ####### IST uuid:a39c0363-6504-11ed-aece-7f680ced2e93 f: 47183780, l: 47271256, STRv: 3

2022-11-17 17:58:34 2 [Note] WSREP: IST receiver addr using tcp://x.x.x.x:4568

2022-11-17 17:58:34 2 [Note] WSREP: Prepared IST receiver for 47183780-47271256, listening at: tcp://x.x.x.x:4568

2022-11-17 17:58:34 0 [Note] WSREP: Member 1.0 (xxx-n3) requested state transfer from '*any*'. Selected 0.0 (xxx-n1)(SYNCED) as donor.

2022-11-17 17:58:34 0 [Note] WSREP: Shifting PRIMARY -> JOINER (TO: 47271681)

2022-11-17 17:58:34 2 [Note] WSREP: Requesting state transfer: success, donor: 0

2022-11-17 17:58:34 0 [Warning] WSREP: 0.0 (xxx-n1): State transfer to 1.0 (xxx-n3) failed: -42 (No message of desired type)

2022-11-17 17:58:34 0 [ERROR] WSREP: /home/buildbot/buildbot/build/gcs/src/gcs_group.cpp:gcs_group_handle_join_msg():1205: Will never receive state. Need to abort.

2022-11-17 17:58:34 0 [Note] WSREP: gcomm: terminating thread

2022-11-17 17:58:34 0 [Note] WSREP: gcomm: joining thread

2022-11-17 17:58:34 0 [Note] WSREP: gcomm: closing backend

2022-11-17 17:58:34 0 [Note] WSREP: view(view_id(NON_PRIM,0471cb54-9588,62) memb {

        10d22ccf-ac57,0

} joined {

} left {

} partitioned {

        0471cb54-9588,0

        faf13cda-b959,0

})

2022-11-17 17:58:34 0 [Note] WSREP: (10d22ccf-ac57, 'tcp://x.x.x.x:4567') turning message relay requesting off

2022-11-17 17:58:34 0 [Note] WSREP: PC protocol downgrade 1 -> 0

2022-11-17 17:58:34 0 [Note] WSREP: view((empty))

2022-11-17 17:58:34 0 [Note] WSREP: gcomm: closed

2022-11-17 17:58:34 0 [Note] WSREP: /usr/sbin/mariadbd: Terminated.

WSREP_SST: [ERROR] Removing /tmp/tmp.EjHFGwFbei/xtrabackup_galera_info file due to signal (20221117 17:58:37.083)

WSREP_SST: [ERROR] Error while getting data from donor node: exit codes: 143 143 (20221117 17:58:37.087)

WSREP_SST: [ERROR] Cleanup after exit with status: 32 (20221117 17:58:37.091)

WSREP_SST: [INFO] Removing the sst_in_progress file (20221117 17:58:37.095)

WSREP_SST: [INFO] Cleaning up temporary directories (20221117 17:58:37.101)

Next iteration is run automatically (systemd) shortly after the previous failure, however the IST sequence begin interval is reset to 0-47303965 (failed again, as cause of previous failure is still not known)

2022-11-17 17:58:57 0 [Note] WSREP: Loading provider /usr/lib/galera/libgalera_smm.so initial position: a39c0363-6504-11ed-aece-7f680ced2e93:47183779

2022-11-17 17:58:57 0 [Note] WSREP: wsrep_load(): loading provider library '/usr/lib/galera/libgalera_smm.so'

2022-11-17 17:58:57 0 [Note] WSREP: wsrep_load(): Galera 26.4.11(r67341d07) by Codership Oy <info@codership.com> loaded successfully.

2022-11-17 17:58:57 0 [Note] WSREP: CRC-32C: using 64-bit x86 acceleration.

2022-11-17 17:58:57 0 [Note] WSREP: Found saved state: 00000000-0000-0000-0000-000000000000:-1, safe_to_bootstrap: 0

2022-11-17 17:58:57 0 [Note] WSREP: GCache DEBUG: opened preamble:

Version: 2

UUID: a39c0363-6504-11ed-aece-7f680ced2e93

Seqno: -1 - -1

Offset: -1

Synced: 0

2022-11-17 17:58:57 0 [Note] WSREP: Recovering GCache ring buffer: version: 2, UUID: a39c0363-6504-11ed-aece-7f680ced2e93, offset: -1

2022-11-17 17:58:57 0 [Note] WSREP: GCache::RingBuffer initial scan...  0.0% (           0/107374182424 bytes) complete.

2022-11-17 17:59:07 0 [Note] WSREP: GCache::RingBuffer initial scan... 23.6% ( 25354706296/107374182424 bytes) complete.

2022-11-17 17:59:17 0 [Note] WSREP: GCache::RingBuffer initial scan... 45.4% ( 48702113912/107374182424 bytes) complete.

2022-11-17 17:59:27 0 [Note] WSREP: GCache::RingBuffer initial scan... 62.6% ( 67172551328/107374182424 bytes) complete.

2022-11-17 17:59:38 0 [Note] WSREP: GCache::RingBuffer initial scan... 68.4% ( 73490987632/107374182424 bytes) complete.

2022-11-17 17:59:48 0 [Note] WSREP: GCache::RingBuffer initial scan... 69.5% ( 74642774704/107374182424 bytes) complete.

2022-11-17 17:59:58 0 [Note] WSREP: GCache::RingBuffer initial scan... 69.7% ( 74806890664/107374182424 bytes) complete.

2022-11-17 18:00:08 0 [Note] WSREP: GCache::RingBuffer initial scan... 70.2% ( 75422948256/107374182424 bytes) complete.

2022-11-17 18:00:18 0 [Note] WSREP: GCache::RingBuffer initial scan... 71.1% ( 76296902576/107374182424 bytes) complete.

2022-11-17 18:00:28 0 [Note] WSREP: GCache::RingBuffer initial scan... 72.7% ( 78021955472/107374182424 bytes) complete.

2022-11-17 18:00:31 0 [Note] WSREP: GCache::RingBuffer initial scan...100.0% (107374182424/107374182424 bytes) complete.

2022-11-17 18:00:32 0 [Note] WSREP: Recovering GCache ring buffer: found gapless sequence 1151831-47183779

2022-11-17 18:00:32 0 [Note] WSREP: GCache::RingBuffer unused buffers scan...  0.0% (          0/78724433432 bytes) complete.

2022-11-17 18:00:42 0 [Note] WSREP: GCache DEBUG: RingBuffer::recover(): found 16244812/62276761 locked buffers

2022-11-17 18:00:42 0 [Note] WSREP: GCache DEBUG: RingBuffer::recover(): free space: 48946928888/107374182400

2022-11-17 18:00:42 0 [Note] WSREP: GCache::RingBuffer unused buffers scan...100.0% (78724433432/78724433432 bytes) complete.

2022-11-17 18:00:42 0 [Warning] WSREP: Option 'gcs.fc_master_slave' is deprecated and will be removed in the future versions, please use 'gcs.fc_single_primary' instead.

2022-11-17 18:00:42 0 [Note] WSREP: Passing config to GCS: base_dir = /var/lib/mysql-data; base_host = x.x.x.x; base_port = 4567; cert.log_conflicts = no; cert.optimistic_pa = yes; 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-data; gcache.keep_pages_size = 0; gcache.keep_plaintext_size = 128M; gcache.mem_size = 0; gcache.name = galera.cache; gcache.page_size = 128M; gcache.recover = 1; gcache.size = 100G; gcomm.thread_prio = ; gcs.fc_debug = 0; gcs.fc_factor = 1.0; gcs.fc_limit = 256; gcs.fc_master_slave = no; gcs.fc_single_primary = 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.segmen

2022-11-17 18:00:42 0 [Note] WSREP: Start replication

2022-11-17 18:00:42 0 [Note] WSREP: Connecting with bootstrap option: 0

2022-11-17 18:00:42 0 [Note] WSREP: Setting GCS initial position to 00000000-0000-0000-0000-000000000000:-1

2022-11-17 18:00:42 0 [Note] WSREP: protonet asio version 0

2022-11-17 18:00:42 0 [Note] WSREP: Using CRC-32C for message checksums.

2022-11-17 18:00:42 0 [Note] WSREP: backend: asio

2022-11-17 18:00:42 0 [Note] WSREP: gcomm thread scheduling priority set to other:0

2022-11-17 18:00:42 0 [Warning] WSREP: access file(/var/lib/mysql-data/gvwstate.dat) failed(No such file or directory)

2022-11-17 18:00:42 0 [Note] WSREP: restore pc from disk failed

2022-11-17 18:00:42 0 [Note] WSREP: GMCast version 0

2022-11-17 18:00:42 0 [Note] WSREP: (5eb6c502-bf96, 'tcp://x.x.x.x:4567') listening at tcp://x.x.x.x:4567

2022-11-17 18:00:42 0 [Note] WSREP: (5eb6c502-bf96, 'tcp://x.x.x.x:4567') multicast: , ttl: 1

2022-11-17 18:00:42 0 [Note] WSREP: EVS version 1

2022-11-17 18:00:42 0 [Note] WSREP: gcomm: connecting to group 'xxx', peer 'x.x.x.x:,x.x.x.x:,x.x.x.x:'

2022-11-17 18:00:42 0 [Note] WSREP: (5eb6c502-bf96, 'tcp://x.x.x.x:4567') Found matching local endpoint for a connection, blacklisting address tcp://x.x.x.x:4567

2022-11-17 18:00:42 0 [Note] WSREP: (5eb6c502-bf96, 'tcp://x.x.x.x:4567') connection established to faf13cda-b959 tcp://x.x.x.x:4567

2022-11-17 18:00:42 0 [Note] WSREP: (5eb6c502-bf96, 'tcp://x.x.x.x:4567') turning message relay requesting on, nonlive peers:

2022-11-17 18:00:42 0 [Note] WSREP: (5eb6c502-bf96, 'tcp://x.x.x.x:4567') connection established to 0471cb54-9588 tcp://x.x.x.x:4567

2022-11-17 18:00:42 0 [Note] WSREP: EVS version upgrade 0 -> 1

2022-11-17 18:00:42 0 [Note] WSREP: declaring 0471cb54-9588 at tcp://x.x.x.x:4567 stable

2022-11-17 18:00:42 0 [Note] WSREP: declaring faf13cda-b959 at tcp://x.x.x.x:4567 stable

2022-11-17 18:00:42 0 [Note] WSREP: PC protocol upgrade 0 -> 1

2022-11-17 18:00:42 0 [Note] WSREP: Node 0471cb54-9588 state prim

2022-11-17 18:00:42 0 [Note] WSREP: view(view_id(PRIM,0471cb54-9588,64) memb {

        0471cb54-9588,0

        5eb6c502-bf96,0

        faf13cda-b959,0

} joined {

} left {

} partitioned {

})

2022-11-17 18:00:42 0 [Note] WSREP: save pc into disk

2022-11-17 18:00:43 0 [Note] WSREP: gcomm: connected

2022-11-17 18:00:43 0 [Note] WSREP: Changing maximum packet size to 64500, resulting msg size: 32636

2022-11-17 18:00:43 0 [Note] WSREP: Shifting CLOSED -> OPEN (TO: 0)

2022-11-17 18:00:43 0 [Note] WSREP: Opened channel 'xxx'

2022-11-17 18:00:43 0 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 1, memb_num = 3

2022-11-17 18:00:43 0 [Note] WSREP: STATE EXCHANGE: Waiting for state UUID.

2022-11-17 18:00:43 0 [Note] WSREP: STATE EXCHANGE: sent state msg: 5f07ae70-6699-11ed-a8a2-ef6a90b7e027

2022-11-17 18:00:43 0 [Note] WSREP: STATE EXCHANGE: got state msg: 5f07ae70-6699-11ed-a8a2-ef6a90b7e027 from 0 (xxx-n1)

2022-11-17 18:00:43 0 [Note] WSREP: STATE EXCHANGE: got state msg: 5f07ae70-6699-11ed-a8a2-ef6a90b7e027 from 2 (xxx-n2)

2022-11-17 18:00:43 1 [Note] WSREP: Starting rollbacker thread 1

2022-11-17 18:00:43 2 [Note] WSREP: Starting applier thread 2

2022-11-17 18:00:43 0 [Note] WSREP: STATE EXCHANGE: got state msg: 5f07ae70-6699-11ed-a8a2-ef6a90b7e027 from 1 (xxx-n3)

2022-11-17 18:00:43 0 [Note] WSREP: Quorum results:

        version    = 6,

        component  = PRIMARY,

        conf_id    = 14,

        members    = 2/3 (joined/total),

        act_id     = 47303964,

        last_appl. = 47271653,

        protocols  = 2/10/4 (gcs/repl/appl),

        vote policy= 0,

        group UUID = a39c0363-6504-11ed-aece-7f680ced2e93

2022-11-17 18:00:43 0 [Note] WSREP: Flow-control interval: [443, 443]

2022-11-17 18:00:43 0 [Note] WSREP: Shifting OPEN -> PRIMARY (TO: 47303965)

2022-11-17 18:00:43 2 [Note] WSREP: ####### processing CC 47303965, local, ordered

2022-11-17 18:00:43 2 [Note] WSREP: Process first view: a39c0363-6504-11ed-aece-7f680ced2e93 my uuid: 5eb6c502-6699-11ed-bf96-a6420418b669

2022-11-17 18:00:43 2 [Note] WSREP: Server xxx-n3 connected to cluster at position a39c0363-6504-11ed-aece-7f680ced2e93:47303965 with ID 5eb6c502-6699-11ed-bf96-a6420418b669

2022-11-17 18:00:43 2 [Note] WSREP: Server status change disconnected -> connected

2022-11-17 18:00:43 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.

2022-11-17 18:00:43 2 [Note] WSREP: ####### My UUID: 5eb6c502-6699-11ed-bf96-a6420418b669

2022-11-17 18:00:43 2 [Note] WSREP: Cert index reset to 00000000-0000-0000-0000-000000000000:-1 (proto: 10), state transfer needed: yes

2022-11-17 18:00:43 0 [Note] WSREP: Service thread queue flushed.

2022-11-17 18:00:43 2 [Note] WSREP: ####### Assign initial position for certification: 00000000-0000-0000-0000-000000000000:-1, protocol version: -1

2022-11-17 18:00:43 2 [Note] WSREP: State transfer required:

        Group state: a39c0363-6504-11ed-aece-7f680ced2e93:47303965

        Local state: 00000000-0000-0000-0000-000000000000:-1

2022-11-17 18:00:43 2 [Note] WSREP: Server status change connected -> joiner

2022-11-17 18:00:43 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.

2022-11-17 18:00:43 0 [Note] WSREP: Joiner monitor thread started to monitor

2022-11-17 18:00:43 0 [Note] WSREP: Running: 'wsrep_sst_mariabackup --role 'joiner' --address 'x.x.x.x' --datadir '/var/lib/mysql-data/' --parent '55685' --binlog '/var/lib/mysql-binlogs/mysql-bin' --mysqld-args --wsrep_start_position=a39c0363-6504-11ed-aece-7f680ced2e93:47183779'

WSREP_SST: [INFO] SSL configuration: CA='', CAPATH='', CERT='', KEY='', MODE='DISABLED', encrypt='0' (20221117 18:00:43.424)

WSREP_SST: [INFO] Streaming with mbstream (20221117 18:00:43.583)

WSREP_SST: [INFO] Using socat as streamer (20221117 18:00:43.586)

WSREP_SST: [INFO] Evaluating timeout -k 310 300 socat -u TCP-LISTEN:4444,reuseaddr stdio | '/usr//bin/mbstream' -x; RC=( ${PIPESTATUS[@]} ) (20221117 18:00:43.616)

2022-11-17 18:00:43 2 [Note] WSREP: ####### IST uuid:00000000-0000-0000-0000-000000000000 f: 0, l: 47303965, STRv: 3

2022-11-17 18:00:43 2 [Note] WSREP: IST receiver addr using tcp://x.x.x.x:4568

2022-11-17 18:00:43 2 [Note] WSREP: Prepared IST receiver for 0-47303965, listening at: tcp://x.x.x.x:4568

2022-11-17 18:00:43 0 [Note] WSREP: Member 1.0 (xxx-n3) requested state transfer from '*any*'. Selected 0.0 (xxx-n1)(SYNCED) as donor.

2022-11-17 18:00:43 0 [Note] WSREP: Shifting PRIMARY -> JOINER (TO: 47304194)

2022-11-17 18:00:43 2 [Note] WSREP: Requesting state transfer: success, donor: 0

2022-11-17 18:00:43 2 [Note] WSREP: Resetting GCache seqno map due to different histories.

2022-11-17 18:00:43 2 [Note] WSREP: GCache history reset: a39c0363-6504-11ed-aece-7f680ced2e93:47183779 -> a39c0363-6504-11ed-aece-7f680ced2e93:47303965

2022-11-17 18:00:45 0 [Note] WSREP: (5eb6c502-bf96, 'tcp://x.x.x.x:4567') turning message relay requesting off

2022-11-17 18:01:08 2 [Note] WSREP: GCache DEBUG: RingBuffer::seqno_reset(): discarded 58427253328 bytes

2022-11-17 18:01:08 2 [Note] WSREP: GCache DEBUG: RingBuffer::seqno_reset(): found 1/231 locked buffers

2022-11-17 18:01:08 0 [Warning] WSREP: 0.0 (xxx-n1): State transfer to 1.0 (xxx-n3) failed: -42 (No message of desired type)

2022-11-17 18:01:08 0 [ERROR] WSREP: /home/buildbot/buildbot/build/gcs/src/gcs_group.cpp:gcs_group_handle_join_msg():1205: Will never receive state. Need to abort.

2022-11-17 18:01:08 0 [Note] WSREP: gcomm: terminating thread

2022-11-17 18:01:08 0 [Note] WSREP: gcomm: joining thread

2022-11-17 18:01:08 0 [Note] WSREP: gcomm: closing backend

2022-11-17 18:01:08 0 [Note] WSREP: view(view_id(NON_PRIM,0471cb54-9588,64) memb {

        5eb6c502-bf96,0

} joined {

} left {

} partitioned {

        0471cb54-9588,0

        faf13cda-b959,0

})

2022-11-17 18:01:08 0 [Note] WSREP: PC protocol downgrade 1 -> 0

2022-11-17 18:01:08 0 [Note] WSREP: view((empty))

2022-11-17 18:01:08 0 [Note] WSREP: gcomm: closed

2022-11-17 18:01:08 0 [Note] WSREP: /usr/sbin/mariadbd: Terminated.

...

Once the issue was identified and fixed (wsrep_sst_method=mariabackup; mariabackup binary was missing on donor node), the node is indeed synced via full SST, instead of IST. Requested sequence was 0-48117803.

2022-11-17 18:44:48 0 [Note] WSREP: Loading provider /usr/lib/galera/libgalera_smm.so initial position: a39c0363-6504-11ed-aece-7f680ced2e93:47183779

2022-11-17 18:44:48 0 [Note] WSREP: wsrep_load(): loading provider library '/usr/lib/galera/libgalera_smm.so'

2022-11-17 18:44:48 0 [Note] WSREP: wsrep_load(): Galera 26.4.11(r67341d07) by Codership Oy <info@codership.com> loaded successfully.

2022-11-17 18:44:48 0 [Note] WSREP: CRC-32C: using 64-bit x86 acceleration.

2022-11-17 18:44:48 0 [Note] WSREP: Found saved state: 00000000-0000-0000-0000-000000000000:-1, safe_to_bootstrap: 0

2022-11-17 18:44:48 0 [Note] WSREP: GCache DEBUG: opened preamble:

Version: 2

UUID: a39c0363-6504-11ed-aece-7f680ced2e93

Seqno: -1 - -1

Offset: -1

Synced: 0

2022-11-17 18:44:48 0 [Note] WSREP: Recovering GCache ring buffer: version: 2, UUID: a39c0363-6504-11ed-aece-7f680ced2e93, offset: -1

2022-11-17 18:44:48 0 [Note] WSREP: GCache::RingBuffer initial scan...  0.0% (           0/107374182424 bytes) complete.

2022-11-17 18:44:48 0 [Note] WSREP: GCache::RingBuffer initial scan...100.0% (107374182424/107374182424 bytes) complete.

2022-11-17 18:44:48 0 [Note] WSREP: Recovering GCache ring buffer: didn't recover any events.

2022-11-17 18:44:48 0 [Warning] WSREP: Option 'gcs.fc_master_slave' is deprecated and will be removed in the future versions, please use 'gcs.fc_single_primary' instead.

2022-11-17 18:44:48 0 [Note] WSREP: Passing config to GCS: base_dir = /var/lib/mysql-data; base_host = x.x.x.x; base_port = 4567; cert.log_conflicts = no; cert.optimistic_pa = yes; 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-data; gcache.keep_pages_size = 0; gcache.keep_plaintext_size = 128M; gcache.mem_size = 0; gcache.name = galera.cache; gcache.page_size = 128M; gcache.recover = 1; gcache.size = 100G; gcomm.thread_prio = ; gcs.fc_debug = 0; gcs.fc_factor = 1.0; gcs.fc_limit = 256; gcs.fc_master_slave = no; gcs.fc_single_primary = 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.segmen

2022-11-17 18:44:48 0 [Note] WSREP: Start replication

2022-11-17 18:44:48 0 [Note] WSREP: Connecting with bootstrap option: 0

2022-11-17 18:44:48 0 [Note] WSREP: Setting GCS initial position to 00000000-0000-0000-0000-000000000000:-1

2022-11-17 18:44:48 0 [Note] WSREP: protonet asio version 0

2022-11-17 18:44:48 0 [Note] WSREP: Using CRC-32C for message checksums.

2022-11-17 18:44:48 0 [Note] WSREP: backend: asio

2022-11-17 18:44:48 0 [Note] WSREP: gcomm thread scheduling priority set to other:0

2022-11-17 18:44:48 0 [Warning] WSREP: access file(/var/lib/mysql-data/gvwstate.dat) failed(No such file or directory)

2022-11-17 18:44:48 0 [Note] WSREP: restore pc from disk failed

2022-11-17 18:44:48 0 [Note] WSREP: GMCast version 0

2022-11-17 18:44:48 0 [Note] WSREP: (87c51892-846c, 'tcp://x.x.x.x:4567') listening at tcp://x.x.x.x:4567

2022-11-17 18:44:48 0 [Note] WSREP: (87c51892-846c, 'tcp://x.x.x.x:4567') multicast: , ttl: 1

2022-11-17 18:44:48 0 [Note] WSREP: EVS version 1

2022-11-17 18:44:48 0 [Note] WSREP: gcomm: connecting to group 'xxx', peer 'x.x.x.x:,x.x.x.x:,x.x.x.x:'

2022-11-17 18:44:48 0 [Note] WSREP: (87c51892-846c, 'tcp://x.x.x.x:4567') Found matching local endpoint for a connection, blacklisting address tcp://x.x.x.x:4567

2022-11-17 18:44:48 0 [Note] WSREP: (87c51892-846c, 'tcp://x.x.x.x:4567') connection established to faf13cda-b959 tcp://x.x.x.x:4567

2022-11-17 18:44:48 0 [Note] WSREP: (87c51892-846c, 'tcp://x.x.x.x:4567') turning message relay requesting on, nonlive peers:

2022-11-17 18:44:48 0 [Note] WSREP: (87c51892-846c, 'tcp://x.x.x.x:4567') connection established to 30822780-a131 tcp://x.x.x.x:4567

2022-11-17 18:44:48 0 [Note] WSREP: EVS version upgrade 0 -> 1

2022-11-17 18:44:48 0 [Note] WSREP: declaring 30822780-a131 at tcp://x.x.x.x:4567 stable

2022-11-17 18:44:48 0 [Note] WSREP: declaring faf13cda-b959 at tcp://x.x.x.x:4567 stable

2022-11-17 18:44:48 0 [Note] WSREP: PC protocol upgrade 0 -> 1

2022-11-17 18:44:48 0 [Note] WSREP: Node 30822780-a131 state prim

2022-11-17 18:44:48 0 [Note] WSREP: view(view_id(PRIM,30822780-a131,106) memb {

        30822780-a131,0

        87c51892-846c,0

        faf13cda-b959,0

} joined {

} left {

} partitioned {

})

2022-11-17 18:44:48 0 [Note] WSREP: save pc into disk

2022-11-17 18:44:49 0 [Note] WSREP: gcomm: connected

2022-11-17 18:44:49 0 [Note] WSREP: Changing maximum packet size to 64500, resulting msg size: 32636

2022-11-17 18:44:49 0 [Note] WSREP: Shifting CLOSED -> OPEN (TO: 0)

2022-11-17 18:44:49 0 [Note] WSREP: Opened channel 'xxx'

2022-11-17 18:44:49 0 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 1, memb_num = 3

2022-11-17 18:44:49 0 [Note] WSREP: STATE EXCHANGE: Waiting for state UUID.

2022-11-17 18:44:49 0 [Note] WSREP: STATE EXCHANGE: sent state msg: 88169a2c-669f-11ed-9e4c-078c8f95bc76

2022-11-17 18:44:49 0 [Note] WSREP: STATE EXCHANGE: got state msg: 88169a2c-669f-11ed-9e4c-078c8f95bc76 from 0 (xxx-n1)

2022-11-17 18:44:49 0 [Note] WSREP: STATE EXCHANGE: got state msg: 88169a2c-669f-11ed-9e4c-078c8f95bc76 from 2 (xxx-n2)

2022-11-17 18:44:49 1 [Note] WSREP: Starting rollbacker thread 1

2022-11-17 18:44:49 2 [Note] WSREP: Starting applier thread 2

2022-11-17 18:44:49 0 [Note] WSREP: STATE EXCHANGE: got state msg: 88169a2c-669f-11ed-9e4c-078c8f95bc76 from 1 (xxx-n3)

2022-11-17 18:44:49 0 [Note] WSREP: Quorum results:

        version    = 6,

        component  = PRIMARY,

        conf_id    = 56,

        members    = 2/3 (joined/total),

        act_id     = 48117802,

        last_appl. = 48117762,

        protocols  = 2/10/4 (gcs/repl/appl),

        vote policy= 0,

        group UUID = a39c0363-6504-11ed-aece-7f680ced2e93

2022-11-17 18:44:49 0 [Note] WSREP: Flow-control interval: [443, 443]

2022-11-17 18:44:49 0 [Note] WSREP: Shifting OPEN -> PRIMARY (TO: 48117803)

2022-11-17 18:44:49 2 [Note] WSREP: ####### processing CC 48117803, local, ordered

2022-11-17 18:44:49 2 [Note] WSREP: Process first view: a39c0363-6504-11ed-aece-7f680ced2e93 my uuid: 87c51892-669f-11ed-846c-4fc2c738aa01

2022-11-17 18:44:49 2 [Note] WSREP: Server xxx-n3 connected to cluster at position a39c0363-6504-11ed-aece-7f680ced2e93:48117803 with ID 87c51892-669f-11ed-846c-4fc2c738aa01

2022-11-17 18:44:49 2 [Note] WSREP: Server status change disconnected -> connected

2022-11-17 18:44:49 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.

2022-11-17 18:44:49 2 [Note] WSREP: ####### My UUID: 87c51892-669f-11ed-846c-4fc2c738aa01

2022-11-17 18:44:49 2 [Note] WSREP: Cert index reset to 00000000-0000-0000-0000-000000000000:-1 (proto: 10), state transfer needed: yes

2022-11-17 18:44:49 0 [Note] WSREP: Service thread queue flushed.

2022-11-17 18:44:49 2 [Note] WSREP: ####### Assign initial position for certification: 00000000-0000-0000-0000-000000000000:-1, protocol version: -1

2022-11-17 18:44:49 2 [Note] WSREP: State transfer required:

        Group state: a39c0363-6504-11ed-aece-7f680ced2e93:48117803

        Local state: 00000000-0000-0000-0000-000000000000:-1

2022-11-17 18:44:49 2 [Note] WSREP: Server status change connected -> joiner

2022-11-17 18:44:49 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.

2022-11-17 18:44:49 0 [Note] WSREP: Joiner monitor thread started to monitor

2022-11-17 18:44:49 0 [Note] WSREP: Running: 'wsrep_sst_mariabackup --role 'joiner' --address 'x.x.x.x' --datadir '/var/lib/mysql-data/' --parent '47985' --binlog '/var/lib/mysql-binlogs/mysql-bin' --mysqld-args --wsrep_start_position=a39c0363-6504-11ed-aece-7f680ced2e93:47183779'

WSREP_SST: [INFO] SSL configuration: CA='', CAPATH='', CERT='', KEY='', MODE='DISABLED', encrypt='0' (20221117 18:44:49.284)

WSREP_SST: [INFO] Streaming with mbstream (20221117 18:44:49.406)

WSREP_SST: [INFO] Using socat as streamer (20221117 18:44:49.409)

WSREP_SST: [INFO] Evaluating timeout -k 310 300 socat -u TCP-LISTEN:4444,reuseaddr stdio | '/usr//bin/mbstream' -x; RC=( ${PIPESTATUS[@]} ) (20221117 18:44:49.447)

2022-11-17 18:44:49 2 [Note] WSREP: ####### IST uuid:00000000-0000-0000-0000-000000000000 f: 0, l: 48117803, STRv: 3

2022-11-17 18:44:49 2 [Note] WSREP: IST receiver addr using tcp://x.x.x.x:4568

2022-11-17 18:44:49 2 [Note] WSREP: Prepared IST receiver for 0-48117803, listening at: tcp://x.x.x.x:4568

2022-11-17 18:44:49 0 [Note] WSREP: Member 1.0 (xxx-n3) requested state transfer from '*any*'. Selected 0.0 (xxx-n1)(SYNCED) as donor.

2022-11-17 18:44:49 0 [Note] WSREP: Shifting PRIMARY -> JOINER (TO: 48118026)

2022-11-17 18:44:49 2 [Note] WSREP: Requesting state transfer: success, donor: 0

2022-11-17 18:44:49 2 [Note] WSREP: Resetting GCache seqno map due to different histories.

2022-11-17 18:44:49 2 [Note] WSREP: GCache history reset: a39c0363-6504-11ed-aece-7f680ced2e93:0 -> a39c0363-6504-11ed-aece-7f680ced2e93:48117803

WSREP_SST: [INFO] Evaluating socat -u TCP-LISTEN:4444,reuseaddr stdio | '/usr//bin/mbstream' -x; RC=( ${PIPESTATUS[@]} ) (20221117 18:44:49.905)

WSREP_SST: [INFO] Proceeding with SST (20221117 18:44:49.943)

WSREP_SST: [INFO] Cleaning the existing datadir and innodb-data/log directories (20221117 18:44:49.990)

2022-11-17 18:44:51 0 [Note] WSREP: (87c51892-846c, 'tcp://x.x.x.x:4567') turning message relay requesting off

removed 'xxx.ibd'

removed 'xxx.ibd'

...

[MDEV-30070] After failed IST Galera lost proper receiver's sequence and follows up with SST instead Created: 2022-11-22 Updated: 2022-11-22
Status:	Open
Project:	MariaDB Server
Component/s:	Galera
Affects Version/s:	10.5.15
Fix Version/s:	None

[MDEV-30070] After failed IST Galera lost proper receiver's sequence and follows up with SST instead Created: 2022-11-22 Updated: 2022-11-22