[MDEV-28669] Cannot join second node to new cluster WSREP: Application received wrong state Created: 2022-05-25  Updated: 2023-04-18  Resolved: 2023-04-04

Status: Closed
Project: MariaDB Server
Component/s: Galera, Galera SST
Affects Version/s: 10.6.8, 10.6.9, 10.8.4
Fix Version/s: 10.6.11, 10.7.7, 10.8.6, 10.9.4, 10.10.2, 10.11.0

Type: Bug Priority: Critical
Reporter: Rick Tuk Assignee: Julius Goryavsky
Resolution: Fixed Votes: 2
Labels: None
Environment:

Ubuntu 20.04 LTS

Attachments: Text File donor.log     File node01-extra.conf     File node01-galera.conf     File node02-extra.conf     File node02-galera.conf    
Issue Links:
Duplicate
is duplicated by MDEV-30157 Galera SST doesn't properly handle un... Closed
Issue split
split to MDEV-29591 nesting innodb subdirectories in data... Stalled
split to MDEV-29592 SST via rsync fails with innodb_undo_... Closed
Relates
relates to MDEV-31074 Galera SST fails when datadir / logdi... Closed

 Description   

When setting up a new mariadb cluster I've bootstrapped the first node with `galera_new_cluster`
When I stat the second node it starts receiving the state transfer, and then logs a message that it received the wrong state transfer. mariadb on node 2 is than stopped.

Logs from trying to join the new cluster on the second node:

May 25 16:43:19 node02 systemd[1]: Starting MariaDB 10.6.8 database server...
 
May 25 16:43:20 node02 sh[34993]: WSREP: Recovered position 00000000-0000-0000-0000-000000000000:-1
 
May 25 16:43:20 node02 mariadbd[35259]: 2022-05-25 16:43:20 0 [Note] /usr/sbin/mariadbd (server 10.6.8-MariaDB-1:10.6.8+maria~focal-log) starting as process 35259 ...
 
May 25 16:43:20 node02 mariadbd[35259]: 2022-05-25 16:43:20 0 [Warning] Could not increase number of max_open_files to more than 196608 (request: 1048851)
 
May 25 16:43:20 node02 mariadbd[35259]: 2022-05-25 16:43:20 0 [Note] WSREP: Loading provider /usr/lib/galera/libgalera_smm.so initial position: 00000000-0000-0000-0000-000000000000:-1
 
May 25 16:43:20 node02 mariadbd[35259]: 2022-05-25 16:43:20 0 [Note] WSREP: wsrep_load(): loading provider library '/usr/lib/galera/libgalera_smm.so'
 
May 25 16:43:20 node02 mariadbd[35259]: 2022-05-25 16:43:20 0 [Note] WSREP: wsrep_load(): Galera 26.4.11(r67341d07) by Codership Oy <info@codership.com> loaded successfully.
 
May 25 16:43:20 node02 mariadbd[35259]: 2022-05-25 16:43:20 0 [Note] WSREP: CRC-32C: using "slicing-by-8" algorithm.
 
May 25 16:43:20 node02 mariadbd[35259]: 2022-05-25 16:43:20 0 [Note] WSREP: SSL cipher list set to 'TLS-AES-256-GCM-SHA384:TLS-CHACHA20-POLY1305-SHA256:ECDHE-ECDSA-AES256-GCM-SHA384:ECDHE-RSA-AES256-GCM-SHA384:ECDHE-ECDSA-CHACHA20-POLY1305:ECDHE-RSA-CHACHA20-POLY1305:DHE-RSA-AES256-GCM-SHA384:DHE-RSA-CHACHA20-POLY1305'
 
May 25 16:43:20 node02 mariadbd[35259]: 2022-05-25 16:43:20 0 [Note] WSREP: Found saved state: 00000000-0000-0000-0000-000000000000:-1, safe_to_bootstrap: 1
 
May 25 16:43:20 node02 mariadbd[35259]: 2022-05-25 16:43:20 0 [Note] WSREP: GCache DEBUG: opened preamble:
 
May 25 16:43:20 node02 mariadbd[35259]: Version: 2
 
May 25 16:43:20 node02 mariadbd[35259]: UUID: 49eb1ff3-dc36-11ec-9725-6f6bb4d72609
 
May 25 16:43:20 node02 mariadbd[35259]: Seqno: -1 - -1
 
May 25 16:43:20 node02 mariadbd[35259]: Offset: -1
 
May 25 16:43:20 node02 mariadbd[35259]: Synced: 0
 
May 25 16:43:20 node02 mariadbd[35259]: 2022-05-25 16:43:20 0 [Note] WSREP: Recovering GCache ring buffer: version: 2, UUID: 49eb1ff3-dc36-11ec-9725-6f6bb4d72609, offset: -1
 
May 25 16:43:20 node02 mariadbd[35259]: 2022-05-25 16:43:20 0 [Note] WSREP: GCache::RingBuffer initial scan...  0.0% (         0/1073741848 bytes) complete.
 
May 25 16:43:21 node02 mariadbd[35259]: 2022-05-25 16:43:21 0 [Note] WSREP: GCache::RingBuffer initial scan...100.0% (1073741848/1073741848 bytes) complete.
 
May 25 16:43:21 node02 mariadbd[35259]: 2022-05-25 16:43:21 0 [Note] WSREP: Recovering GCache ring buffer: didn't recover any events.
 
May 25 16:43:21 node02 mariadbd[35259]: 2022-05-25 16:43:21 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.
 
May 25 16:43:21 node02 mariadbd[35259]: 2022-05-25 16:43:21 0 [Note] WSREP: Passing config to GCS: base_dir = /var/lib/mysql/; base_host = 10.96.53.2; 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/; gcache.keep_pages_size = 0; gcache.keep_plaintext_size = 128M; gcache.mem_size = 0; gcache.name = galera.cache; gcache.page_size = 128M; gcache.recover = yes; gcache.size = 1G; gcomm.thread_prio = ; gcs.fc_debug = 0; gcs.fc_factor = 0.8; gcs.fc_limit = 20; 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.segment = 0; gmc
 
May 25 16:43:21 node02 mariadbd[35259]: 2022-05-25 16:43:21 0 [Note] WSREP: SSL cipher list set to 'TLS-AES-256-GCM-SHA384:TLS-CHACHA20-POLY1305-SHA256:ECDHE-ECDSA-AES256-GCM-SHA384:ECDHE-RSA-AES256-GCM-SHA384:ECDHE-ECDSA-CHACHA20-POLY1305:ECDHE-RSA-CHACHA20-POLY1305:DHE-RSA-AES256-GCM-SHA384:DHE-RSA-CHACHA20-POLY1305'
 
May 25 16:43:21 node02 mariadbd[35259]: 2022-05-25 16:43:21 0 [Note] WSREP: Start replication
 
May 25 16:43:21 node02 mariadbd[35259]: 2022-05-25 16:43:21 0 [Note] WSREP: Connecting with bootstrap option: 0
 
May 25 16:43:21 node02 mariadbd[35259]: 2022-05-25 16:43:21 0 [Note] WSREP: Setting GCS initial position to 00000000-0000-0000-0000-000000000000:-1
 
May 25 16:43:21 node02 mariadbd[35259]: 2022-05-25 16:43:21 0 [Note] WSREP: protonet asio version 0
 
May 25 16:43:21 node02 mariadbd[35259]: 2022-05-25 16:43:21 0 [Note] WSREP: SSL cipher list set to 'TLS-AES-256-GCM-SHA384:TLS-CHACHA20-POLY1305-SHA256:ECDHE-ECDSA-AES256-GCM-SHA384:ECDHE-RSA-AES256-GCM-SHA384:ECDHE-ECDSA-CHACHA20-POLY1305:ECDHE-RSA-CHACHA20-POLY1305:DHE-RSA-AES256-GCM-SHA384:DHE-RSA-CHACHA20-POLY1305'
 
May 25 16:43:21 node02 mariadbd[35259]: 2022-05-25 16:43:21 0 [Note] WSREP: Using CRC-32C for message checksums.
 
May 25 16:43:21 node02 mariadbd[35259]: 2022-05-25 16:43:21 0 [Note] WSREP: backend: asio
 
May 25 16:43:21 node02 mariadbd[35259]: 2022-05-25 16:43:21 0 [Note] WSREP: gcomm thread scheduling priority set to other:0
 
May 25 16:43:21 node02 mariadbd[35259]: 2022-05-25 16:43:21 0 [Warning] WSREP: access file(/var/lib/mysql//gvwstate.dat) failed(No such file or directory)
 
May 25 16:43:21 node02 mariadbd[35259]: 2022-05-25 16:43:21 0 [Note] WSREP: restore pc from disk failed
 
May 25 16:43:21 node02 mariadbd[35259]: 2022-05-25 16:43:21 0 [Note] WSREP: GMCast version 0
 
May 25 16:43:21 node02 mariadbd[35259]: 2022-05-25 16:43:21 0 [Note] WSREP: (05ff94b4-a70a, 'ssl://0.0.0.0:4567') listening at ssl://0.0.0.0:4567
 
May 25 16:43:21 node02 mariadbd[35259]: 2022-05-25 16:43:21 0 [Note] WSREP: (05ff94b4-a70a, 'ssl://0.0.0.0:4567') multicast: , ttl: 1
 
May 25 16:43:21 node02 mariadbd[35259]: 2022-05-25 16:43:21 0 [Note] WSREP: EVS version 1
 
May 25 16:43:21 node02 mariadbd[35259]: 2022-05-25 16:43:21 0 [Note] WSREP: gcomm: connecting to group 'mariadb-cluster', peer 'node01:,node02:,arbitrator:'
 
May 25 16:43:21 node02 mariadbd[35259]: 2022-05-25 16:43:21 0 [Note] WSREP: (05ff94b4-a70a, 'ssl://0.0.0.0:4567') Found matching local endpoint for a connection, blacklisting address ssl://10.96.53.2:4567
 
May 25 16:43:21 node02 mariadbd[35259]: 2022-05-25 16:43:21 0 [Note] WSREP: (05ff94b4-a70a, 'ssl://0.0.0.0:4567') connection established to a309b137-b3df ssl://10.96.53.0:4567
 
May 25 16:43:21 node02 mariadbd[35259]: 2022-05-25 16:43:21 0 [Note] WSREP: (05ff94b4-a70a, 'ssl://0.0.0.0:4567') turning message relay requesting on, nonlive peers:
 
May 25 16:43:21 node02 mariadbd[35259]: 2022-05-25 16:43:21 0 [Note] WSREP: (05ff94b4-a70a, 'ssl://0.0.0.0:4567') connection established to 49e62ffd-8229 ssl://10.96.53.1:4567
 
May 25 16:43:21 node02 mariadbd[35259]: 2022-05-25 16:43:21 0 [Note] WSREP: EVS version upgrade 0 -> 1
 
May 25 16:43:21 node02 mariadbd[35259]: 2022-05-25 16:43:21 0 [Note] WSREP: declaring 49e62ffd-8229 at ssl://10.96.53.1:4567 stable
 
May 25 16:43:21 node02 mariadbd[35259]: 2022-05-25 16:43:21 0 [Note] WSREP: declaring a309b137-b3df at ssl://10.96.53.0:4567 stable
 
May 25 16:43:21 node02 mariadbd[35259]: 2022-05-25 16:43:21 0 [Note] WSREP: PC protocol upgrade 0 -> 1
 
May 25 16:43:21 node02 mariadbd[35259]: 2022-05-25 16:43:21 0 [Note] WSREP: Node 49e62ffd-8229 state prim
 
May 25 16:43:21 node02 mariadbd[35259]: 2022-05-25 16:43:21 0 [Note] WSREP: view(view_id(PRIM,05ff94b4-a70a,17) memb {
 
May 25 16:43:21 node02 mariadbd[35259]: #01105ff94b4-a70a,0
 
May 25 16:43:21 node02 mariadbd[35259]: #01149e62ffd-8229,0
 
May 25 16:43:21 node02 mariadbd[35259]: #011a309b137-b3df,0
 
May 25 16:43:21 node02 mariadbd[35259]: } joined {
 
May 25 16:43:21 node02 mariadbd[35259]: } left {
 
May 25 16:43:21 node02 mariadbd[35259]: } partitioned {
 
May 25 16:43:21 node02 mariadbd[35259]: })
 
May 25 16:43:21 node02 mariadbd[35259]: 2022-05-25 16:43:21 0 [Note] WSREP: save pc into disk
 
May 25 16:43:22 node02 mariadbd[35259]: 2022-05-25 16:43:22 0 [Note] WSREP: gcomm: connected
 
May 25 16:43:22 node02 mariadbd[35259]: 2022-05-25 16:43:22 0 [Note] WSREP: Changing maximum packet size to 64500, resulting msg size: 32636
 
May 25 16:43:22 node02 mariadbd[35259]: 2022-05-25 16:43:22 0 [Note] WSREP: Shifting CLOSED -> OPEN (TO: 0)
 
May 25 16:43:22 node02 mariadbd[35259]: 2022-05-25 16:43:22 0 [Note] WSREP: Opened channel 'mariadb-cluster'
 
May 25 16:43:22 node02 mariadbd[35259]: 2022-05-25 16:43:22 0 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 0, memb_num = 3
 
May 25 16:43:22 node02 mariadbd[35259]: 2022-05-25 16:43:22 0 [Note] WSREP: STATE_EXCHANGE: sent state UUID: 069a76f5-dc39-11ec-9c6e-2fed0bf25da7
 
May 25 16:43:22 node02 mariadbd[35259]: 2022-05-25 16:43:22 2 [Note] WSREP: Starting rollbacker thread 2
 
May 25 16:43:22 node02 mariadbd[35259]: 2022-05-25 16:43:22 1 [Note] WSREP: Starting applier thread 1
 
May 25 16:43:22 node02 mariadbd[35259]: 2022-05-25 16:43:22 0 [Note] WSREP: STATE EXCHANGE: sent state msg: 069a76f5-dc39-11ec-9c6e-2fed0bf25da7
 
May 25 16:43:22 node02 mariadbd[35259]: 2022-05-25 16:43:22 0 [Note] WSREP: STATE EXCHANGE: got state msg: 069a76f5-dc39-11ec-9c6e-2fed0bf25da7 from 0 (node02)
 
May 25 16:43:22 node02 mariadbd[35259]: 2022-05-25 16:43:22 0 [Note] WSREP: STATE EXCHANGE: got state msg: 069a76f5-dc39-11ec-9c6e-2fed0bf25da7 from 1 (node01)
 
May 25 16:43:22 node02 mariadbd[35259]: 2022-05-25 16:43:22 0 [Note] WSREP: STATE EXCHANGE: got state msg: 069a76f5-dc39-11ec-9c6e-2fed0bf25da7 from 2 (garb)
 
May 25 16:43:22 node02 mariadbd[35259]: 2022-05-25 16:43:22 0 [Note] WSREP: Quorum results:
 
May 25 16:43:22 node02 mariadbd[35259]: #011version    = 6,
 
May 25 16:43:22 node02 mariadbd[35259]: #011component  = PRIMARY,
 
May 25 16:43:22 node02 mariadbd[35259]: #011conf_id    = 16,
 
May 25 16:43:22 node02 mariadbd[35259]: #011members    = 2/3 (joined/total),
 
May 25 16:43:22 node02 mariadbd[35259]: #011act_id     = 16,
 
May 25 16:43:22 node02 mariadbd[35259]: #011last_appl. = 0,
 
May 25 16:43:22 node02 mariadbd[35259]: #011protocols  = 2/10/4 (gcs/repl/appl),
 
May 25 16:43:22 node02 mariadbd[35259]: #011vote policy= 0,
 
May 25 16:43:22 node02 mariadbd[35259]: #011group UUID = 49eb1ff3-dc36-11ec-9725-6f6bb4d72609
 
May 25 16:43:22 node02 mariadbd[35259]: 2022-05-25 16:43:22 0 [Note] WSREP: Flow-control interval: [28, 35]
 
May 25 16:43:22 node02 mariadbd[35259]: 2022-05-25 16:43:22 0 [Note] WSREP: Shifting OPEN -> PRIMARY (TO: 17)
 
May 25 16:43:22 node02 mariadbd[35259]: 2022-05-25 16:43:22 1 [Note] WSREP: ####### processing CC 17, local, ordered
 
May 25 16:43:22 node02 mariadbd[35259]: 2022-05-25 16:43:22 1 [Note] WSREP: Process first view: 49eb1ff3-dc36-11ec-9725-6f6bb4d72609 my uuid: 05ff94b4-dc39-11ec-a70a-67bf409317a6
 
May 25 16:43:22 node02 mariadbd[35259]: 2022-05-25 16:43:22 1 [Note] WSREP: Server node02 connected to cluster at position 49eb1ff3-dc36-11ec-9725-6f6bb4d72609:17 with ID 05ff94b4-dc39-11ec-a70a-67bf409317a6
 
May 25 16:43:22 node02 mariadbd[35259]: 2022-05-25 16:43:22 1 [Note] WSREP: Server status change disconnected -> connected
 
May 25 16:43:22 node02 mariadbd[35259]: 2022-05-25 16:43:22 1 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
 
May 25 16:43:22 node02 mariadbd[35259]: 2022-05-25 16:43:22 1 [Note] WSREP: ####### My UUID: 05ff94b4-dc39-11ec-a70a-67bf409317a6
 
May 25 16:43:22 node02 mariadbd[35259]: 2022-05-25 16:43:22 1 [Note] WSREP: Cert index reset to 00000000-0000-0000-0000-000000000000:-1 (proto: 10), state transfer needed: yes
 
May 25 16:43:22 node02 mariadbd[35259]: 2022-05-25 16:43:22 0 [Note] WSREP: Service thread queue flushed.
 
May 25 16:43:22 node02 mariadbd[35259]: 2022-05-25 16:43:22 1 [Note] WSREP: ####### Assign initial position for certification: 00000000-0000-0000-0000-000000000000:-1, protocol version: -1
 
May 25 16:43:22 node02 mariadbd[35259]: 2022-05-25 16:43:22 1 [Note] WSREP: State transfer required:
 
May 25 16:43:22 node02 mariadbd[35259]: #011Group state: 49eb1ff3-dc36-11ec-9725-6f6bb4d72609:17
 
May 25 16:43:22 node02 mariadbd[35259]: #011Local state: 00000000-0000-0000-0000-000000000000:-1
 
May 25 16:43:22 node02 mariadbd[35259]: 2022-05-25 16:43:22 1 [Note] WSREP: Server status change connected -> joiner
 
May 25 16:43:22 node02 mariadbd[35259]: 2022-05-25 16:43:22 1 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
 
May 25 16:43:22 node02 mariadbd[35259]: 2022-05-25 16:43:22 0 [Note] WSREP: Joiner monitor thread started to monitor
 
May 25 16:43:22 node02 mariadbd[35259]: 2022-05-25 16:43:22 0 [Note] WSREP: Running: 'wsrep_sst_mariabackup --role 'joiner' --address '10.96.53.2' --datadir '/var/lib/mysql/' --parent '35259' --binlog '/var/log/mysql/mysql-bin' --binlog-index '/var/log/mysql/mariadb-bin.index' --mysqld-args --wsrep_start_position=00000000-0000-0000-0000-000000000000:-1'
 
May 25 16:43:22 node02 mariadbd[35270]: WSREP_SST: [INFO] mariabackup SST started on joiner (20220525 16:43:22.481)
 
May 25 16:43:22 node02 mariadbd[35270]: WSREP_SST: [INFO] SSL configuration: CA='/etc/mysql/ssl/root.rsa.crt', CAPATH='', CERT='/etc/mysql/ssl/server.rsa.crt', KEY='/etc/mysql/ssl/server.rsa.key', MODE='DISABLED', encrypt='4' (20220525 16:43:22.706)
 
May 25 16:43:22 node02 mariadbd[35270]: WSREP_SST: [INFO] Logging all stderr of SST/mariabackup to syslog (20220525 16:43:22.972)
 
May 25 16:43:22 node02 -wsrep-sst-joiner: Streaming with mbstream
 
May 25 16:43:22 node02 -wsrep-sst-joiner: Using socat as streamer
 
May 25 16:43:22 node02 -wsrep-sst-joiner: Using openssl based encryption with socat: with key and crt
 
May 25 16:43:23 node02 -wsrep-sst-joiner: Decrypting with cert='/etc/mysql/ssl/server.rsa.crt', key='/etc/mysql/ssl/server.rsa.key', ca='/etc/mysql/ssl/root.rsa.crt', capath=''
 
May 25 16:43:23 node02 -wsrep-sst-joiner: Evaluating timeout -k 310 300 socat -u openssl-listen:4444,reuseaddr,cert='/etc/mysql/ssl/server.rsa.crt',key='/etc/mysql/ssl/server.rsa.key',cafile='/etc/mysql/ssl/root.rsa.crt',commonname='' stdio | '/usr//bin/mbstream' -x; RC=( ${PIPESTATUS[@]} )
 
May 25 16:43:23 node02 mariadbd[35259]: 2022-05-25 16:43:23 1 [Note] WSREP: ####### IST uuid:00000000-0000-0000-0000-000000000000 f: 0, l: 17, STRv: 3
 
May 25 16:43:23 node02 mariadbd[35259]: 2022-05-25 16:43:23 1 [Note] WSREP: IST receiver addr using ssl://10.96.53.2:4568
 
May 25 16:43:23 node02 mariadbd[35259]: 2022-05-25 16:43:23 1 [Note] WSREP: IST receiver using ssl
 
May 25 16:43:23 node02 mariadbd[35259]: 2022-05-25 16:43:23 1 [Note] WSREP: Prepared IST receiver for 0-17, listening at: ssl://10.96.53.2:4568
 
May 25 16:43:23 node02 mariadbd[35259]: 2022-05-25 16:43:23 0 [Note] WSREP: Member 0.0 (node02) requested state transfer from '*any*'. Selected 1.0 (node01)(SYNCED) as donor.
 
May 25 16:43:23 node02 mariadbd[35259]: 2022-05-25 16:43:23 0 [Note] WSREP: Shifting PRIMARY -> JOINER (TO: 17)
 
May 25 16:43:23 node02 mariadbd[35259]: 2022-05-25 16:43:23 1 [Note] WSREP: Requesting state transfer: success, donor: 1
 
May 25 16:43:23 node02 mariadbd[35259]: 2022-05-25 16:43:23 1 [Note] WSREP: Resetting GCache seqno map due to different histories.
 
May 25 16:43:23 node02 mariadbd[35259]: 2022-05-25 16:43:23 1 [Note] WSREP: GCache history reset: 49eb1ff3-dc36-11ec-9725-6f6bb4d72609:0 -> 49eb1ff3-dc36-11ec-9725-6f6bb4d72609:17
 
May 25 16:43:24 node02 -wsrep-sst-joiner: Proceeding with SST
 
May 25 16:43:24 node02 -wsrep-sst-joiner: Evaluating socat -u openssl-listen:4444,reuseaddr,cert='/etc/mysql/ssl/server.rsa.crt',key='/etc/mysql/ssl/server.rsa.key',cafile='/etc/mysql/ssl/root.rsa.crt',commonname='' stdio | '/usr//bin/mbstream' -x; RC=( ${PIPESTATUS[@]} )
 
May 25 16:43:24 node02 -wsrep-sst-joiner: Cleaning the old binary logs
 
May 25 16:43:24 node02 -wsrep-sst-joiner: Cleaning the binlog directory '/var/log/mysql' as well
 
May 25 16:43:24 node02 -wsrep-sst-joiner: Cleaning the existing datadir and innodb-data/log directories
 
May 25 16:43:24 node02 -wsrep-sst-joiner: Waiting for SST streaming to complete!
 
May 25 16:43:24 node02 mariadbd[35259]: 2022-05-25 16:43:24 0 [Note] WSREP: (05ff94b4-a70a, 'ssl://0.0.0.0:4567') turning message relay requesting off
 
May 25 16:43:31 node02 mysqld_exporter[549]: ts=2022-05-25T14:43:31.106Z caller=exporter.go:149 level=error msg="Error pinging mysqld" err="dial tcp 10.96.53.2:3306: connect: connection refused"
 
May 25 16:43:37 node02 mariadbd[35259]: 2022-05-25 16:43:37 0 [Note] WSREP: 1.0 (node01): State transfer to 0.0 (node02) complete.
 
May 25 16:43:37 node02 mariadbd[35259]: 2022-05-25 16:43:37 0 [Note] WSREP: Member 1.0 (node01) synced with group.
 
May 25 16:43:37 node02 -wsrep-sst-joiner: Preparing the backup at /var/lib/mysql/.sst
 
May 25 16:43:37 node02 -wsrep-sst-joiner: Evaluating /usr//bin/mariabackup --prepare --no-version-check --log-bin='/var/log/mysql/mysql-bin' --target-dir='/var/lib/mysql/.sst' --datadir='/var/lib/mysql/.sst' --mysqld-args --log-bin-index='/var/log/mysql/mariadb-bin.index' '--wsrep_start_position=00000000-0000-0000-0000-000000000000:-1' 2>&1 | logger -p daemon.err -t -innobackupex-apply
 
May 25 16:43:37 node02 -innobackupex-apply: /usr//bin/mariabackup based on MariaDB server 10.6.8-MariaDB debian-linux-gnu (x86_64)
 
May 25 16:43:37 node02 -innobackupex-apply: [00] 2022-05-25 16:43:37 cd to /var/lib/mysql/.sst/
 
May 25 16:43:37 node02 -innobackupex-apply: [00] 2022-05-25 16:43:37 open files limit requested 0, set to 196608
 
May 25 16:43:37 node02 -innobackupex-apply: [00] 2022-05-25 16:43:37 Renaming ./mysql/wsrep_cluster.new to ./mysql/wsrep_cluster.ibd
 
May 25 16:43:37 node02 -innobackupex-apply: 
May 25 16:43:37 node02 -innobackupex-apply: [00] 2022-05-25 16:43:37 Renaming ./mysql/wsrep_cluster_members.new to ./mysql/wsrep_cluster_members.ibd
 
May 25 16:43:37 node02 -innobackupex-apply: 
May 25 16:43:37 node02 -innobackupex-apply: [00] 2022-05-25 16:43:37 Renaming ./mysql/wsrep_streaming_log.new to ./mysql/wsrep_streaming_log.ibd
 
May 25 16:43:37 node02 -innobackupex-apply: 
May 25 16:43:37 node02 -innobackupex-apply: [00] 2022-05-25 16:43:37 This target seems to be not prepared yet.
 
May 25 16:43:37 node02 -innobackupex-apply: [00] 2022-05-25 16:43:37 mariabackup: using the following InnoDB configuration for recovery:
 
May 25 16:43:37 node02 -innobackupex-apply: [00] 2022-05-25 16:43:37 innodb_data_home_dir = .
 
May 25 16:43:37 node02 -innobackupex-apply: [00] 2022-05-25 16:43:37 innodb_data_file_path = ibdata1:10M:autoextend
 
May 25 16:43:37 node02 -innobackupex-apply: [00] 2022-05-25 16:43:37 innodb_log_group_home_dir = .
 
May 25 16:43:37 node02 -innobackupex-apply: [00] 2022-05-25 16:43:37 InnoDB: Using Linux native AIO
 
May 25 16:43:37 node02 -innobackupex-apply: [00] 2022-05-25 16:43:37 Starting InnoDB instance for recovery.
 
May 25 16:43:37 node02 -innobackupex-apply: [00] 2022-05-25 16:43:37 mariabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
 
May 25 16:43:37 node02 -innobackupex-apply: 2022-05-25 16:43:37 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
 
May 25 16:43:37 node02 -innobackupex-apply: 2022-05-25 16:43:37 0 [Note] InnoDB: Number of pools: 1
 
May 25 16:43:37 node02 -innobackupex-apply: 2022-05-25 16:43:37 0 [Note] InnoDB: Using generic crc32 instructions
 
May 25 16:43:37 node02 -innobackupex-apply: 2022-05-25 16:43:37 0 [Note] InnoDB: Using Linux native AIO
 
May 25 16:43:37 node02 -innobackupex-apply: 2022-05-25 16:43:37 0 [Note] InnoDB: Initializing buffer pool, total size = 104857600, chunk size = 104857600
 
May 25 16:43:37 node02 -innobackupex-apply: 2022-05-25 16:43:37 0 [Note] InnoDB: Completed initialization of buffer pool
 
May 25 16:43:37 node02 -innobackupex-apply: 2022-05-25 16:43:37 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=283172,283172
 
May 25 16:43:37 node02 systemd[1]: mariadb.service: Got notification message from PID 35901, but reception only permitted for main PID 35259
 
May 25 16:43:37 node02 -innobackupex-apply: 2022-05-25 16:43:37 0 [Note] InnoDB: Starting final batch to recover 44 pages from redo log.
 
May 25 16:43:37 node02 -innobackupex-apply: [00] 2022-05-25 16:43:37 Last binlog file , position 0
 
May 25 16:43:37 node02 -innobackupex-apply: [00] 2022-05-25 16:43:37 completed OK!
 
May 25 16:43:38 node02 -wsrep-sst-joiner: Moving binary logs to /var/log/mysql
 
May 25 16:43:38 node02 -wsrep-sst-joiner: Moving the backup to /var/lib/mysql
 
May 25 16:43:38 node02 -wsrep-sst-joiner: Evaluating /usr//bin/mariabackup --move-back --no-version-check --log-bin='/var/log/mysql/mysql-bin' --force-non-empty-directories --target-dir='/var/lib/mysql/.sst' --datadir='/var/lib/mysql' 2>&1 | logger -p daemon.err -t -innobackupex-move
 
May 25 16:43:38 node02 -innobackupex-move: /usr//bin/mariabackup based on MariaDB server 10.6.8-MariaDB debian-linux-gnu (x86_64)
 
May 25 16:43:38 node02 -innobackupex-move: [00] 2022-05-25 16:43:38 Error: Move file ibdata1 to /var/lib/mysql/./ibdata1 failed: Destination file exists
 
May 25 16:43:38 node02 -wsrep-sst-joiner: Move successful, removing /var/lib/mysql/.sst
 
May 25 16:43:38 node02 -wsrep-sst-joiner: SST magic file '/var/lib/mysql/xtrabackup_galera_info' not found/readable
 
May 25 16:43:38 node02 -wsrep-sst-joiner: Cleanup after exit with status: 2
 
May 25 16:43:38 node02 -wsrep-sst-joiner: Removing /var/lib/mysql/xtrabackup_galera_info file due to signal
 
May 25 16:43:38 node02 -wsrep-sst-joiner: Removing the sst_in_progress file
 
May 25 16:43:38 node02 -wsrep-sst-joiner: Cleaning up temporary directories
 
May 25 16:43:38 node02 mariadbd[35259]: 2022-05-25 16:43:38 0 [ERROR] WSREP: Process completed with error: wsrep_sst_mariabackup --role 'joiner' --address '10.96.53.2' --datadir '/var/lib/mysql/' --parent '35259' --binlog '/var/log/mysql/mysql-bin' --binlog-index '/var/log/mysql/mariadb-bin.index' --mysqld-args --wsrep_start_position=00000000-0000-0000-0000-000000000000:-1: 2 (No such file or directory)
 
May 25 16:43:38 node02 mariadbd[35259]: 2022-05-25 16:43:38 0 [ERROR] WSREP: Failed to read uuid:seqno and wsrep_gtid_domain_id from joiner script.
 
May 25 16:43:38 node02 mariadbd[35259]: 2022-05-25 16:43:38 3 [Note] WSREP: SST received
 
May 25 16:43:38 node02 mariadbd[35259]: 2022-05-25 16:43:38 3 [Note] WSREP: SST received: 00000000-0000-0000-0000-000000000000:-1
 
May 25 16:43:38 node02 mariadbd[35259]: 2022-05-25 16:43:38 3 [Note] WSREP: SST succeeded for position 00000000-0000-0000-0000-000000000000:-1
 
May 25 16:43:38 node02 mariadbd[35259]: 2022-05-25 16:43:38 0 [Note] WSREP: Joiner monitor thread ended with total time 16 sec
 
May 25 16:43:38 node02 mariadbd[35259]: 2022-05-25 16:43:38 1 [ERROR] WSREP: Application received wrong state:
 
May 25 16:43:38 node02 mariadbd[35259]: #011Received: 00000000-0000-0000-0000-000000000000
 
May 25 16:43:38 node02 mariadbd[35259]: #011Required: 49eb1ff3-dc36-11ec-9725-6f6bb4d72609
 
May 25 16:43:38 node02 mariadbd[35259]: 2022-05-25 16:43:38 1 [ERROR] WSREP: Application state transfer failed. This is unrecoverable condition, restart required.
 
May 25 16:43:38 node02 mariadbd[35259]: 2022-05-25 16:43:38 1 [Note] WSREP: ReplicatorSMM::abort()
 
May 25 16:43:38 node02 mariadbd[35259]: 2022-05-25 16:43:38 1 [Note] WSREP: Closing send monitor...
 
May 25 16:43:38 node02 mariadbd[35259]: 2022-05-25 16:43:38 1 [Note] WSREP: Closed send monitor.
 
May 25 16:43:38 node02 mariadbd[35259]: 2022-05-25 16:43:38 1 [Note] WSREP: gcomm: terminating thread
 
May 25 16:43:38 node02 mariadbd[35259]: 2022-05-25 16:43:38 1 [Note] WSREP: gcomm: joining thread
 
May 25 16:43:38 node02 mariadbd[35259]: 2022-05-25 16:43:38 1 [Note] WSREP: gcomm: closing backend
 
May 25 16:43:38 node02 mariadbd[35259]: 2022-05-25 16:43:38 1 [Note] WSREP: view(view_id(NON_PRIM,05ff94b4-a70a,17) memb {
 
May 25 16:43:38 node02 mariadbd[35259]: #01105ff94b4-a70a,0
 
May 25 16:43:38 node02 mariadbd[35259]: } joined {
 
May 25 16:43:38 node02 mariadbd[35259]: } left {
 
May 25 16:43:38 node02 mariadbd[35259]: } partitioned {
 
May 25 16:43:38 node02 mariadbd[35259]: #01149e62ffd-8229,0
 
May 25 16:43:38 node02 mariadbd[35259]: #011a309b137-b3df,0
 
May 25 16:43:38 node02 mariadbd[35259]: })
 
May 25 16:43:38 node02 mariadbd[35259]: 2022-05-25 16:43:38 1 [Note] WSREP: PC protocol downgrade 1 -> 0
 
May 25 16:43:38 node02 mariadbd[35259]: 2022-05-25 16:43:38 1 [Note] WSREP: view((empty))
 
May 25 16:43:38 node02 mariadbd[35259]: 2022-05-25 16:43:38 1 [Note] WSREP: gcomm: closed
 
May 25 16:43:38 node02 mariadbd[35259]: 2022-05-25 16:43:38 0 [Note] WSREP: New COMPONENT: primary = no, bootstrap = no, my_idx = 0, memb_num = 1
 
May 25 16:43:38 node02 mariadbd[35259]: 2022-05-25 16:43:38 0 [Note] WSREP: Flow-control interval: [16, 20]
 
May 25 16:43:38 node02 mariadbd[35259]: 2022-05-25 16:43:38 0 [Note] WSREP: Received NON-PRIMARY.
 
May 25 16:43:38 node02 mariadbd[35259]: 2022-05-25 16:43:38 0 [Note] WSREP: Shifting JOINER -> OPEN (TO: 17)
 
May 25 16:43:38 node02 mariadbd[35259]: 2022-05-25 16:43:38 0 [Note] WSREP: New SELF-LEAVE.
 
May 25 16:43:38 node02 mariadbd[35259]: 2022-05-25 16:43:38 0 [Note] WSREP: Flow-control interval: [0, 0]
 
May 25 16:43:38 node02 mariadbd[35259]: 2022-05-25 16:43:38 0 [Note] WSREP: Received SELF-LEAVE. Closing connection.
 
May 25 16:43:38 node02 mariadbd[35259]: 2022-05-25 16:43:38 0 [Note] WSREP: Shifting OPEN -> CLOSED (TO: 17)
 
May 25 16:43:38 node02 mariadbd[35259]: 2022-05-25 16:43:38 0 [Note] WSREP: RECV thread exiting 0: Success
 
May 25 16:43:38 node02 mariadbd[35259]: 2022-05-25 16:43:38 1 [Note] WSREP: recv_thread() joined.
 
May 25 16:43:38 node02 mariadbd[35259]: 2022-05-25 16:43:38 1 [Note] WSREP: Closing replication queue.
 
May 25 16:43:38 node02 mariadbd[35259]: 2022-05-25 16:43:38 1 [Note] WSREP: Closing slave action queue.
 
May 25 16:43:38 node02 mariadbd[35259]: 2022-05-25 16:43:38 1 [Note] WSREP: /usr/sbin/mariadbd: Terminated.
 
May 25 16:43:38 node02 systemd[1]: mariadb.service: Main process exited, code=killed, status=6/ABRT
 
May 25 16:43:38 node02 systemd[1]: mariadb.service: Failed with result 'signal'.
 
May 25 16:43:38 node02 systemd[1]: Failed to start MariaDB 10.6.8 database server.



 Comments   
Comment by Ramesh Sivaraman [ 2022-05-27 ]

rtuk Could not reproduce the issue on Ubuntu 20.04. Please share the error log from the donor node and the conf files from both nodes

Comment by Rick Tuk [ 2022-05-30 ]

I've attached the logs for the donor (donor.log)
and the config files for galera and extra settings for both nodes
the default configuration files that exist after normal installation are also loaded, these 2 additional files are loaded at the end (they have prefix 60- for galera.conf and 70- for extra.conf
The config files match those of other clusters we have running. These cluster are running versions 10.6.5 and 10.6.7

Comment by Ramesh Sivaraman [ 2022-05-31 ]

rtuk Could not reproduce the issue even after using the given configuration files. Please reinitialize node2 data directory and start the server or restart node2 by removing grastate.dat file from data directory.

2022-05-30 13:37:09 0 [Note] WSREP: Running: 'wsrep_sst_mariabackup --role 'joiner' --address '192.168.100.20' --datadir '/var/lib/mysql/' --parent '255049' --binlog '/var/log/mysql/mysql-bin' --binlog-index '/var/log/mysql/mariadb-bin.index' --mysqld-args --wsrep_start_position=9fd75951-ddd1-11ec-a106-5b48f51c57cb:711'
 
2022-05-30 13:37:09 0 [Note] WSREP: Joiner monitor thread started to monitor
 
WSREP_SST: [INFO] mariabackup SST started on joiner (20220530 13:37:09.612)
 
WSREP_SST: [INFO] SSL configuration: CA='/etc/mysql/ssl/root.rsa.crt', CAPATH='', CERT='/etc/mysql/ssl/server.rsa.crt', KEY='/etc/mysql/ssl/server.rsa.key', MODE='DISABLED', encrypt='4' (20220530 13:37:09.738)
 
WSREP_SST: [INFO] Streaming with mbstream (20220530 13:37:09.842)
 
WSREP_SST: [INFO] Using socat as streamer (20220530 13:37:09.844)
 
WSREP_SST: [INFO] Using openssl based encryption with socat: with key and crt (20220530 13:37:09.849)
 
WSREP_SST: [INFO] Decrypting with cert='/etc/mysql/ssl/server.rsa.crt', key='/etc/mysql/ssl/server.rsa.key', ca='/etc/mysql/ssl/root.rsa.crt', capath='' (20220530 13:37:09.877)
 
WSREP_SST: [INFO] Evaluating timeout -k 310 300 socat -u openssl-listen:4444,reuseaddr,cert='/etc/mysql/ssl/server.rsa.crt',key='/etc/mysql/ssl/server.rsa.key',cafile='/etc/mysql/ssl/root.rsa.crt',commonname='' stdio | '/usr//bin/mbstream' -x; RC=( ${PIPESTATUS[@]} ) (20220530 13:37:09.925)
 
2022-05-30 13:37:09 1 [Note] WSREP: ####### IST uuid:00000000-0000-0000-0000-000000000000 f: 0, l: 712, STRv: 3
 
2022-05-30 13:37:09 1 [Note] WSREP: IST receiver addr using ssl://192.168.100.20:4568
 
2022-05-30 13:37:09 1 [Note] WSREP: IST receiver using ssl
 
2022-05-30 13:37:09 1 [Note] WSREP: Prepared IST receiver for 0-712, listening at: ssl://192.168.100.20:4568
 
2022-05-30 13:37:09 0 [Note] WSREP: Member 1.0 (node2) requested state transfer from '*any*'. Selected 0.0 (node1)(SYNCED) as donor.
 
2022-05-30 13:37:09 0 [Note] WSREP: Shifting PRIMARY -> JOINER (TO: 712)
 
2022-05-30 13:37:09 1 [Note] WSREP: Requesting state transfer: success, donor: 0
 
2022-05-30 13:37:09 1 [Note] WSREP: Resetting GCache seqno map due to different histories.
 
2022-05-30 13:37:09 1 [Note] WSREP: GCache history reset: 9fd75951-ddd1-11ec-a106-5b48f51c57cb:711 -> 9fd75951-ddd1-11ec-a106-5b48f51c57cb:712
 
2022-05-30 13:37:09 1 [Note] WSREP: GCache DEBUG: RingBuffer::seqno_reset(): discarded 391918672 bytes
 
2022-05-30 13:37:09 1 [Note] WSREP: GCache DEBUG: RingBuffer::seqno_reset(): found 1/2 locked buffers
 
WSREP_SST: [INFO] Proceeding with SST (20220530 13:37:10.331)
 
WSREP_SST: [INFO] Evaluating socat -u openssl-listen:4444,reuseaddr,cert='/etc/mysql/ssl/server.rsa.crt',key='/etc/mysql/ssl/server.rsa.key',cafile='/etc/mysql/ssl/root.rsa.crt',commonname='' stdio | '/usr//bin/mbstream' -x; RC=( ${PIPESTATUS[@]} ) (20220530 13:37:10.333)
 
WSREP_SST: [INFO] Cleaning the old binary logs (20220530 13:37:10.347)
 
WSREP_SST: [INFO] Cleaning the binlog directory '/var/log/mysql' as well (20220530 13:37:10.390)
 
WSREP_SST: [INFO] Cleaning the existing datadir and innodb-data/log directories (20220530 13:37:10.394)
 
WSREP_SST: [INFO] Waiting for SST streaming to complete! (20220530 13:37:10.497)
 
2022-05-30 13:37:11 0 [Note] WSREP: (9a12c0cf-b161, 'ssl://0.0.0.0:4567') turning message relay requesting off
 
2022-05-30 13:37:42 0 [Note] WSREP: 0.0 (node1): State transfer to 1.0 (node2) complete.
 
2022-05-30 13:37:42 0 [Note] WSREP: Member 0.0 (node1) synced with group.
 
WSREP_SST: [INFO] Preparing the backup at /var/lib/mysql/.sst (20220530 13:37:42.593)
 
WSREP_SST: [INFO] Evaluating /usr//bin/mariabackup --prepare --no-version-check --log-bin='/var/log/mysql/mysql-bin' --target-dir='/var/lib/mysql/.sst' --datadir='/var/lib/mysql/.sst' --mysqld-args --log-bin-index='/var/log/mysql/mariadb-bin.index' '--wsrep_start_position=9fd75951-ddd1-11ec-a106-5b48f51c57cb:711' > '/var/lib/mysql/mariabackup.prepare.log' 2>&1 (20220530 13:37:42.597)
 
WSREP_SST: [INFO] Moving binary logs to /var/log/mysql (20220530 13:37:43.482)
 
WSREP_SST: [INFO] Moving the backup to /var/lib/mysql (20220530 13:37:43.502)
 
WSREP_SST: [INFO] Evaluating /usr//bin/mariabackup --move-back --no-version-check --log-bin='/var/log/mysql/mysql-bin' --force-non-empty-directories --target-dir='/var/lib/mysql/.sst' --datadir='/var/lib/mysql' > '/var/lib/mysql/mariabackup.move.log' 2>&1 (20220530 13:37:43.506)
 
WSREP_SST: [INFO] Move successful, removing /var/lib/mysql/.sst (20220530 13:37:43.534)
 
WSREP_SST: [INFO] Galera co-ords from recovery: 9fd75951-ddd1-11ec-a106-5b48f51c57cb:712 (20220530 13:37:43.539)
 
WSREP_SST: [INFO] Total time on joiner: 0 seconds (20220530 13:37:43.541)
 
WSREP_SST: [INFO] mariabackup SST completed on joiner (20220530 13:37:43.544)
 
WSREP_SST: [INFO] Removing the sst_in_progress file (20220530 13:37:43.547)
 
WSREP_SST: [INFO] Cleaning up temporary directories (20220530 13:37:43.551)
 
2022-05-30 13:37:43 3 [Note] WSREP: SST received
 
2022-05-30 13:37:43 3 [Note] WSREP: Server status change joiner -> initializing
 
2022-05-30 13:37:43 3 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
 
2022-05-30 13:37:43 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
 
2022-05-30 13:37:43 0 [Note] InnoDB: Number of pools: 1
 
2022-05-30 13:37:43 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
 
2022-05-30 13:37:43 0 [Note] InnoDB: Using Linux native AIO
 
2022-05-30 13:37:43 0 [Note] InnoDB: Initializing buffer pool, total size = 3221225472, chunk size = 134217728
 
2022-05-30 13:37:43 0 [Note] InnoDB: Completed initialization of buffer pool
 
2022-05-30 13:37:43 0 [Note] InnoDB: Setting log file /var/lib/mysql/ib_logfile101 size to 1073741824 bytes
 
2022-05-30 13:37:43 0 [Note] InnoDB: Renaming log file /var/lib/mysql/ib_logfile101 to /var/lib/mysql/ib_logfile0
 
2022-05-30 13:37:43 0 [Note] InnoDB: New log file created, LSN=504986138
 
2022-05-30 13:37:43 0 [Note] InnoDB: 128 rollback segments are active.
 
2022-05-30 13:37:43 0 [Note] InnoDB: Creating shared tablespace for temporary tables
 
2022-05-30 13:37:43 0 [Note] InnoDB: Setting file '/var/lib/mysql/ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
 
2022-05-30 13:37:43 0 [Note] InnoDB: File '/var/lib/mysql/ibtmp1' size is now 12 MB.
 
2022-05-30 13:37:43 0 [Note] InnoDB: 10.6.8 started; log sequence number 0; transaction id 3128
 
2022-05-30 13:37:43 0 [Note] Plugin 'FEEDBACK' is disabled.
 
2022-05-30 13:37:43 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
 
2022-05-30 13:37:43 0 [Note] Zerofilling moved table:  './mysql/plugin'
 
2022-05-30 13:37:43 0 [Warning] 'innodb-buffer-pool-instances' was removed. It does nothing now and exists only for compatibility with old my.cnf files.
 
2022-05-30 13:37:43 0 [Warning] 'innodb-log-files-in-group' was removed. It does nothing now and exists only for compatibility with old my.cnf files.
 
2022-05-30 13:37:43 0 [Note] Recovering after a crash using /var/log/mysql/mysql-bin
 
2022-05-30 13:37:43 0 [Note] Starting table crash recovery...
 
2022-05-30 13:37:43 0 [Note] Crash table recovery finished.

Comment by Rick Tuk [ 2022-05-31 ]

@ramesh I have cleaned the data directory on node2, (I already tried that before) no luck unfortunately.
the arbitrator joins the cluster fine, I have also tried just bootstrapping the first node and adding the second node (without garb being part of the cluster), this also resulted in the same situation

Comment by Rick Tuk [ 2022-06-03 ]

@ramesh
I've found the cause of the issue. At least with this information it is reproducible for me.
We use a separate disk for the data directory. we than create a symlink from the /database/mysql to /var/lib/mysql and keep /var/lib/mysql in the config as the data directory
Using the symlink the above SST errors occur.

If we do the initial SST to a normal directory at /var/lib/mysql and then move the data and create the symlink all still works as expected.

The symlink approach works in previous versions, it also works fine in 10.7.2

Comment by Ramesh Sivaraman [ 2022-06-06 ]

rtuk The issue is reproduced when symlink is created for data directory.

root@node2:/home/vagrant# cat /var/lib/mysql/mariabackup.move.log
 
/usr//bin/mariabackup based on MariaDB server 10.6.8-MariaDB debian-linux-gnu (x86_64)
 
[00] 2022-06-06 12:01:05 Error: Move file ibdata1 to /var/lib/mysql/./ibdata1 failed: Destination file exists
 
root@node2:/home/vagrant# 
 
 
vagrant@node2:~$ ls -l  /var/lib/mysql
 
lrwxrwxrwx 1 root root 15 Jun  6 11:49 /var/lib/mysql -> /database/mysql
 
vagrant@node2:~$

Comment by Rick Tuk [ 2022-08-17 ]

Is there any update on the progress of this issue?
I've noticed it is still broken in 10.6.9 and 10.8.4
We are currently unable to upgrade MariaDB due to this issue

Comment by Khai Ping [ 2022-08-25 ]

@rick, we are facing the same situation as you , I have possibly over 100+ clusters affected

We are planning to "hard code" the softlink path in the /opt/bin/wsrep_sst_mariabackup script to "fix" this issue.

    if [ -n "$INNODB_DATA_HOME_DIR" -a "$INNODB_DATA_HOME_DIR" != '.' ]; then
 
        # handle both relative and absolute paths:
 
        cd "$DATA"
 
        [ ! -d "$INNODB_DATA_HOME_DIR" ] && mkdir -p "$INNODB_DATA_HOME_DIR"
 
        cd "$INNODB_DATA_HOME_DIR"
 
        ib_home_dir="$(pwd)"
 
        cd "$OLD_PWD"
 
    fi
 
    
    if [ -z "$ib_home_dir" ]; then
 
       ib_home_dir=< softlink path >
 
    fi

Comment by Jan Lindström (Inactive) [ 2022-12-21 ]

ok to push.

Please make 10.4-10.6 versions on separate branch (one is enough)!

Comment by Sergei Golubchik [ 2022-12-27 ]

https://github.com/MariaDB/server/commit/4d9f8a3c31e745943b0039cf3421f72c7f13d4cf

Comment by Khai Ping [ 2023-02-10 ]

is there a fix version for this?

Comment by Julius Goryavsky [ 2023-04-04 ]

Fixed as part of https://jira.mariadb.org/browse/MDEV-30157 changes

Comment by Rick Tuk [ 2023-04-04 ]

I've setup a test cluster with version 10.11.2:
root@node02:~# mysql --version
mysql Ver 15.1 Distrib 10.11.2-MariaDB, for debian-linux-gnu (x86_64) using readline 5.2

I'm still getting sst errors:
Apr 4 16:35:14 node02 mariadbd[6833]: 2023-04-04 16:35:14 0 [ERROR] WSREP: Failed to read uuid:seqno and wsrep_gtid_domain_id from joiner script.
Apr 4 16:35:14 node02 mariadbd[6833]: 2023-04-04 16:35:14 0 [ERROR] WSREP: Process completed with error: wsrep_sst_mariabackup --role 'joiner' --address '10.97.148.12' --datadir '/var/lib/mysql/' --parent 6833 --progress 0 --binlog '/var/log/mysql/mysql-bin' --binlog-index '/var/log/mysql/mariadb-bin.index' --mysqld-args --wsrep_start_position=00000000-0000-0000-0000-000000000000:-1: 2 (No such file or directory)
Apr 4 16:35:14 node02 mariadbd[6833]: 2023-04-04 16:35:14 3 [Note] WSREP: SST received
Apr 4 16:35:14 node02 mariadbd[6833]: 2023-04-04 16:35:14 3 [Note] WSREP: SST received: 00000000-0000-0000-0000-000000000000:-1
Apr 4 16:35:14 node02 mariadbd[6833]: 2023-04-04 16:35:14 3 [Note] WSREP: SST succeeded for position 00000000-0000-0000-0000-000000000000:-1
Apr 4 16:35:14 node02 mariadbd[6833]: 2023-04-04 16:35:14 0 [Note] WSREP: Joiner monitor thread ended with total time 15 sec
Apr 4 16:35:14 node02 mariadbd[6833]: 2023-04-04 16:35:14 2 [ERROR] WSREP: Application received wrong state:
Apr 4 16:35:14 node02 mariadbd[6833]: #011Received: 00000000-0000-0000-0000-000000000000
Apr 4 16:35:14 node02 mariadbd[6833]: #011Required: b9e3e449-d2da-11ed-ae66-72a327b8e5ab
Apr 4 16:35:14 node02 mariadbd[6833]: 2023-04-04 16:35:14 2 [ERROR] WSREP: Application state transfer failed. This is unrecoverable condition, restart required.

root@node02:~# ls -al /var/lib/mysql
lrwxrwxrwx 1 root root 15 Apr 4 16:31 /var/lib/mysql -> /database/mysql

root@node02:~# ls -al /var/log/mysql
lrwxrwxrwx 1 root root 13 Apr 4 09:19 /var/log/mysql -> /database/log

so both paths in the command that give the "no such file or directory" error do exists, they are both symlinks

Generated at Thu Feb 08 10:02:34 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.