Details
-
Bug
-
Status: Open (View Workflow)
-
Major
-
Resolution: Unresolved
-
10.5.15
-
None
-
None
Description
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'
|
...
|