Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-30070

After failed IST Galera lost proper receiver's sequence and follows up with SST instead

    XMLWordPrintable

Details

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

      Attachments

        Activity

          People

            Unassigned Unassigned
            sumark Marek Hlavka
            Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

            Dates

              Created:
              Updated:

              Git Integration

                Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.