[MDEV-23605] galera_3nodes.galera_vote_rejoin_mysqldump MTR failed: WSREP_SST: [ERROR] rsync daemon port '16008' has been taken Created: 2020-08-27  Updated: 2021-10-05  Resolved: 2021-10-05

Status: Closed
Project: MariaDB Server
Component/s: Galera, Tests
Affects Version/s: 10.5.6
Fix Version/s: 10.5.12

Type: Bug Priority: Major
Reporter: Stepan Patryshev (Inactive) Assignee: Julius Goryavsky
Resolution: Fixed Votes: 0
Labels: None
Environment:

kvm-zyp-sles123-amd64


Issue Links:
Blocks
blocks MDEV-22122 Galera test failures on 10.5 Open
Problem/Incident
is caused by MDEV-23580 galera_3nodes.galera_ipv6_rsync_secti... Closed
Relates
relates to MXS-3203 Persistent connections prevents Galer... Closed
relates to MDEV-24481 galera_3nodes.galera_vote_rejoin_mysq... Closed

 Description   

galera_3nodes.galera_vote_rejoin_mysqldump failed on BB 10.5: "WSREP_SST: [ERROR] rsync daemon port '16008' has been taken".

stdio.log:

10.5.6 8f8f2aea93835899345454f87768fd649749e29c

galera_3nodes.galera_vote_rejoin_mysqldump 'innodb' w2 [ fail ]
        Test ended at 2020-08-26 07:19:26
[...]
 
Failed to start mysqld.2
 
 
worker[2] > Restart  - using different config file
worker[2] > Restart  - using different config file
worker[2] > Restart  - using different config file
 - skipping '/dev/shm/var/2/log/galera_3nodes.galera_vote_rejoin_mysqldump-innodb/'
 
Retrying test galera_3nodes.galera_vote_rejoin_mysqldump, attempt(2/3)...
 
***Warnings generated in error logs during shutdown after running tests: galera_3nodes.galera_vote_rejoin_mysqldump
 
WSREP_SST: [ERROR] rsync daemon port '16008' has been taken (20200826 07:19:26.680)
2020-08-26  7:19:26 0 [ERROR] WSREP: Failed to read 'ready <addr>' from: wsrep_sst_rsync --role 'joiner' --address '127.0.0.1:16008' --datadir '/dev/shm/var/2/mysqld.2/data/' --defaults-file '/dev/shm/var/2/my.cnf' --defaults-group-suffix '.2' --parent '2797' --binlog-index 'mysqld-bin.index' --mysqld-args --defaults-group-suffix=.2 --defaults-file=/dev/shm/var/2/my.cnf --log-output=file --innodb --innodb-cmpmem --innodb-cmp-per-index --innodb-trx --innodb-locks --innodb-lock-waits --innodb-metrics --innodb-buffer-pool-stats --innodb-buffer-page --innodb-buffer-page-lru --innodb-sys-columns --innodb-sys-fields --innodb-sys-foreign --innodb-sys-foreign-cols --innodb-sys-indexes --innodb-sys-tables --innodb-sys-virtual --core-file --loose-debug-sync-timeout=300
2020-08-26  7:19:26 0 [ERROR] WSREP: Process completed with error: wsrep_sst_rsync --role 'joiner' --address '127.0.0.1:16008' --datadir '/dev/shm/var/2/mysqld.2/data/' --defaults-file '/dev/shm/var/2/my.cnf' --defaults-group-suffix '.2' --parent '2797' --binlog-index 'mysqld-bin.index' --mysqld-args --defaults-group-suffix=.2 --defaults-file=/dev/shm/var/2/my.cnf --log-output=file --innodb --innodb-cmpmem --innodb-cmp-per-index --innodb-trx --innodb-locks --innodb-lock-waits --innodb-metrics --innodb-buffer-pool-stats --innodb-buffer-page --innodb-buffer-page-lru --innodb-sys-columns --innodb-sys-fields --innodb-sys-foreign --innodb-sys-foreign-cols --innodb-sys-indexes --innodb-sys-tables --innodb-sys-virtual --core-file --loose-debug-sync-timeout=300: 16 (Device or resource busy)
2020-08-26  7:19:26 1 [ERROR] WSREP: Failed to prepare for 'rsync' SST. Unrecoverable.
2020-08-26  7:19:26 1 [ERROR] WSREP: SST request callback failed. This is unrecoverable, restart required.
WSREP_SST: [ERROR] rsync daemon port '16011' has been taken (20200826 07:19:26.690)
2020-08-26  7:19:26 0 [ERROR] WSREP: Failed to read 'ready <addr>' from: wsrep_sst_rsync --role 'joiner' --address '127.0.0.1:16011' --datadir '/dev/shm/var/2/mysqld.3/data/' --defaults-file '/dev/shm/var/2/my.cnf' --defaults-group-suffix '.3' --parent '2800' --binlog-index 'mysqld-bin.index' --mysqld-args --defaults-group-suffix=.3 --defaults-file=/dev/shm/var/2/my.cnf --log-output=file --innodb --innodb-cmpmem --innodb-cmp-per-index --innodb-trx --innodb-locks --innodb-lock-waits --innodb-metrics --innodb-buffer-pool-stats --innodb-buffer-page --innodb-buffer-page-lru --innodb-sys-columns --innodb-sys-fields --innodb-sys-foreign --innodb-sys-foreign-cols --innodb-sys-indexes --innodb-sys-tables --innodb-sys-virtual --core-file --loose-debug-sync-timeout=300
2020-08-26  7:19:26 0 [ERROR] WSREP: Process completed with error: wsrep_sst_rsync --role 'joiner' --address '127.0.0.1:16011' --datadir '/dev/shm/var/2/mysqld.3/data/' --defaults-file '/dev/shm/var/2/my.cnf' --defaults-group-suffix '.3' --parent '2800' --binlog-index 'mysqld-bin.index' --mysqld-args --defaults-group-suffix=.3 --defaults-file=/dev/shm/var/2/my.cnf --log-output=file --innodb --innodb-cmpmem --innodb-cmp-per-index --innodb-trx --innodb-locks --innodb-lock-waits --innodb-metrics --innodb-buffer-pool-stats --innodb-buffer-page --innodb-buffer-page-lru --innodb-sys-columns --innodb-sys-fields --innodb-sys-foreign --innodb-sys-foreign-cols --innodb-sys-indexes --innodb-sys-tables --innodb-sys-virtual --core-file --loose-debug-sync-timeout=300: 16 (Device or resource busy)
2020-08-26  7:19:26 2 [ERROR] WSREP: Failed to prepare for 'rsync' SST. Unrecoverable.
2020-08-26  7:19:26 2 [ERROR] WSREP: SST request callback failed. This is unrecoverable, restart required.
 
worker[2] > Restart [mysqld.1 - pid: 2977, winpid: 2977] - running with different options '--innodb --innodb-cmpmem --innodb-cmp-per-index --innodb-trx --innodb-locks --innodb-lock-waits --innodb-metrics --innodb-buffer-pool-stats --innodb-buffer-page --innodb-buffer-page-lru --innodb-sys-columns --innodb-sys-fields --innodb-sys-foreign --innodb-sys-foreign-cols --innodb-sys-indexes --innodb-sys-tables --innodb-sys-virtual --log-slave-updates --log-bin' != '--innodb --innodb-cmpmem --innodb-cmp-per-index --innodb-trx --innodb-locks --innodb-lock-waits --innodb-metrics --innodb-buffer-pool-stats --innodb-buffer-page --innodb-buffer-page-lru --innodb-sys-columns --innodb-sys-fields --innodb-sys-foreign --innodb-sys-foreign-cols --innodb-sys-indexes --innodb-sys-tables --innodb-sys-virtual --log-bin=master-bin --log-bin --log-slave-updates --loose-galera-sr-gtid-unique'



 Comments   
Comment by Jan Lindström (Inactive) [ 2020-08-28 ]

Test case does not work even when rsync deamon port is free.

galera_3nodes.galera_vote_rejoin_mysqldump 'innodb' [ fail ]
        Test ended at 2020-08-28 07:00:53
 
CURRENT_TEST: galera_3nodes.galera_vote_rejoin_mysqldump
 
 
Server [mysqld.2 - pid: 3203783, winpid: 3203783, exit: 256] failed during test run
Server log from this test:
----------SERVER LOG START-----------
2020-08-28  7:00:34 0 [Warning] WSREP: option --wsrep-causal-reads is deprecated
2020-08-28  7:00:34 0 [Warning] WSREP: --wsrep-causal-reads=ON takes precedence over --wsrep-sync-wait=0. WSREP_SYNC_WAIT_BEFORE_READ is on
2020-08-28  7:00:34 0 [Note] /home/jan/mysql/10.5/sql/mariadbd (mysqld 10.5.6-MariaDB-debug-log) starting as process 3203784 ...
2020-08-28  7:00:34 0 [Warning] Could not increase number of max_open_files to more than 1024 (request: 32190)
2020-08-28  7:00:34 0 [Warning] Changed limits: max_open_files: 1024  max_connections: 151 (was 151)  table_cache: 421 (was 2000)
2020-08-28  7:00:34 0 [Warning] WSREP: wsrep_sst_receive_address is set to '127.0.0.1:16008' which makes it impossible for another host to reach this one. Please set it to the address which this node can be connected at by other cluster members.
2020-08-28  7:00:34 0 [Note] WSREP: Loading provider /usr/lib/libgalera_4_smm.so initial position: 00000000-0000-0000-0000-000000000000:-1
2020-08-28  7:00:34 0 [Note] WSREP: wsrep_load(): loading provider library '/usr/lib/libgalera_4_smm.so'
2020-08-28  7:00:34 0 [Note] WSREP: wsrep_load(): Galera 26.4.5(rb3764ab6) by Codership Oy <info@codership.com> loaded successfully.
2020-08-28  7:00:34 0 [Note] WSREP: CRC-32C: using hardware acceleration.
2020-08-28  7:00:34 0 [Warning] WSREP: Could not open state file for reading: '/home/jan/mysql/10.5/mysql-test/var/mysqld.2/data//grastate.dat'
2020-08-28  7:00:34 0 [Note] WSREP: Found saved state: 00000000-0000-0000-0000-000000000000:-1, safe_to_bootstrap: 1
2020-08-28  7:00:34 0 [Note] WSREP: GCache DEBUG: opened preamble:
Version: 0
UUID: 00000000-0000-0000-0000-000000000000
Seqno: -1 - -1
Offset: -1
Synced: 0
2020-08-28  7:00:34 0 [Note] WSREP: Skipped GCache ring buffer recovery: could not determine history UUID.
2020-08-28  7:00:34 0 [Note] WSREP: Passing config to GCS: base_dir = /home/jan/mysql/10.5/mysql-test/var/mysqld.2/data/; base_host = 127.0.0.1; base_port = 16006; 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 = PT30S; evs.install_timeout = PT15S; evs.join_retrans_period = PT1S; evs.max_install_timeouts = 3; evs.send_window = 4; evs.stats_report_period = PT1M; evs.suspect_timeout = PT10S; evs.user_send_window = 2; evs.view_forget_timeout = PT24H; gcache.dir = /home/jan/mysql/10.5/mysql-test/var/mysqld.2/data/; gcache.keep_pages_size = 0; gcache.mem_size = 0; gcache.name = galera.cache; gcache.page_size = 128M; gcache.recover = yes; gcache.size = 128M; gcomm.thread_prio = ; gcs.fc_debug = 0; gcs.fc_factor = 1.0; gcs.fc_limit = 16; gcs.fc_master_slave = 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.s
2020-08-28  7:00:34 0 [Note] WSREP: Start replication
2020-08-28  7:00:34 0 [Note] WSREP: Connecting with bootstrap option: 0
2020-08-28  7:00:34 0 [Note] WSREP: Setting GCS initial position to 00000000-0000-0000-0000-000000000000:-1
2020-08-28  7:00:34 0 [Note] WSREP: protonet asio version 0
2020-08-28  7:00:34 0 [Note] WSREP: Using CRC-32C for message checksums.
2020-08-28  7:00:34 0 [Note] WSREP: backend: asio
2020-08-28  7:00:34 0 [Note] WSREP: gcomm thread scheduling priority set to other:0 
2020-08-28  7:00:34 0 [Warning] WSREP: access file(/home/jan/mysql/10.5/mysql-test/var/mysqld.2/data//gvwstate.dat) failed(No such file or directory)
2020-08-28  7:00:34 0 [Note] WSREP: restore pc from disk failed
2020-08-28  7:00:34 0 [Note] WSREP: GMCast version 0
2020-08-28  7:00:34 0 [Note] WSREP: (0641bdd9-af22, 'tcp://0.0.0.0:16006') listening at tcp://0.0.0.0:16006
2020-08-28  7:00:34 0 [Note] WSREP: (0641bdd9-af22, 'tcp://0.0.0.0:16006') multicast: , ttl: 1
2020-08-28  7:00:34 0 [Note] WSREP: EVS version 1
2020-08-28  7:00:34 0 [Note] WSREP: gcomm: connecting to group 'my_wsrep_cluster', peer '127.0.0.1:16003'
2020-08-28  7:00:34 0 [Note] WSREP: (0641bdd9-af22, 'tcp://0.0.0.0:16006') connection established to 05f82ea0-8e7d tcp://127.0.0.1:16003
2020-08-28  7:00:34 0 [Note] WSREP: (0641bdd9-af22, 'tcp://0.0.0.0:16006') turning message relay requesting on, nonlive peers: 
2020-08-28  7:00:35 0 [Note] WSREP: (0641bdd9-af22, 'tcp://0.0.0.0:16006') connection established to 0646a290-9207 tcp://127.0.0.1:16009
2020-08-28  7:00:35 0 [Note] WSREP: EVS version upgrade 0 -> 1
2020-08-28  7:00:35 0 [Note] WSREP: declaring 05f82ea0-8e7d at tcp://127.0.0.1:16003 stable
2020-08-28  7:00:35 0 [Note] WSREP: PC protocol upgrade 0 -> 1
2020-08-28  7:00:35 0 [Note] WSREP: Node 05f82ea0-8e7d state prim
2020-08-28  7:00:35 0 [Note] WSREP: view(view_id(PRIM,05f82ea0-8e7d,2) memb {
	05f82ea0-8e7d,0
	0641bdd9-af22,0
} joined {
} left {
} partitioned {
})
2020-08-28  7:00:35 0 [Note] WSREP: save pc into disk
2020-08-28  7:00:35 0 [Note] WSREP: forgetting 0646a290-9207 (tcp://127.0.0.1:16009)
2020-08-28  7:00:35 0 [Note] WSREP: gcomm: connected
2020-08-28  7:00:35 0 [Note] WSREP: Changing maximum packet size to 64500, resulting msg size: 32636
2020-08-28  7:00:35 0 [Note] WSREP: Shifting CLOSED -> OPEN (TO: 0)
2020-08-28  7:00:35 0 [Note] WSREP: Opened channel 'my_wsrep_cluster'
2020-08-28  7:00:35 0 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 1, memb_num = 2
2020-08-28  7:00:35 0 [Note] WSREP: STATE EXCHANGE: Waiting for state UUID.
2020-08-28  7:00:35 0 [Note] WSREP: STATE EXCHANGE: sent state msg: 06901498-e8e3-11ea-a4a9-0a204d80f454
2020-08-28  7:00:35 0 [Note] WSREP: STATE EXCHANGE: got state msg: 06901498-e8e3-11ea-a4a9-0a204d80f454 from 0 (jan-HP-ZBook-15u-G5)
2020-08-28  7:00:35 0 [Note] WSREP: STATE EXCHANGE: got state msg: 06901498-e8e3-11ea-a4a9-0a204d80f454 from 1 (jan-HP-ZBook-15u-G5)
2020-08-28  7:00:35 0 [Note] WSREP: Quorum results:
	version    = 6,
	component  = PRIMARY,
	conf_id    = 1,
	members    = 1/2 (joined/total),
	act_id     = 1,
	last_appl. = 0,
	protocols  = 2/10/4 (gcs/repl/appl),
	vote policy= 0,
	group UUID = 05f90ed7-e8e3-11ea-8030-9e6f51337251
2020-08-28  7:00:35 0 [Note] WSREP: Flow-control interval: [23, 23]
2020-08-28  7:00:35 0 [Note] WSREP: Shifting OPEN -> PRIMARY (TO: 2)
2020-08-28  7:00:35 1 [Note] WSREP: Starting rollbacker thread 1
2020-08-28  7:00:35 2 [Note] WSREP: Starting applier thread 2
2020-08-28  7:00:35 2 [Note] WSREP: ####### processing CC 2, local, ordered
2020-08-28  7:00:35 2 [Note] WSREP: Process first view: 05f90ed7-e8e3-11ea-8030-9e6f51337251 my uuid: 0641bdd9-e8e3-11ea-af22-afc54f3298ad
2020-08-28  7:00:35 2 [Note] WSREP: Server jan-HP-ZBook-15u-G5 connected to cluster at position 05f90ed7-e8e3-11ea-8030-9e6f51337251:2 with ID 0641bdd9-e8e3-11ea-af22-afc54f3298ad
2020-08-28  7:00:35 2 [Note] WSREP: Server status change disconnected -> connected
2020-08-28  7:00:35 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2020-08-28  7:00:35 2 [Note] WSREP: ####### My UUID: 0641bdd9-e8e3-11ea-af22-afc54f3298ad
2020-08-28  7:00:35 2 [Note] WSREP: Cert index reset to 00000000-0000-0000-0000-000000000000:-1 (proto: 10), state transfer needed: yes
2020-08-28  7:00:35 0 [Note] WSREP: Service thread queue flushed.
2020-08-28  7:00:35 2 [Note] WSREP: ####### Assign initial position for certification: 00000000-0000-0000-0000-000000000000:-1, protocol version: -1
2020-08-28  7:00:35 2 [Note] WSREP: State transfer required: 
	Group state: 05f90ed7-e8e3-11ea-8030-9e6f51337251:2
	Local state: 00000000-0000-0000-0000-000000000000:-1
2020-08-28  7:00:35 2 [Note] WSREP: Server status change connected -> joiner
2020-08-28  7:00:35 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2020-08-28  7:00:35 0 [Note] WSREP: Joiner monitor thread started to monitor
2020-08-28  7:00:35 0 [Note] WSREP: Running: 'wsrep_sst_rsync --role 'joiner' --address '127.0.0.1:16008' --datadir '/home/jan/mysql/10.5/mysql-test/var/mysqld.2/data/' --defaults-file '/home/jan/mysql/10.5/mysql-test/var/my.cnf' --defaults-group-suffix '.2' --parent '3203784' --binlog-index 'mysqld-bin.index' --mysqld-args --defaults-group-suffix=.2 --defaults-file=/home/jan/mysql/10.5/mysql-test/var/my.cnf --log-output=file --innodb --innodb-cmpmem --innodb-cmp-per-index --innodb-trx --innodb-locks --innodb-lock-waits --innodb-metrics --innodb-buffer-pool-stats --innodb-buffer-page --innodb-buffer-page-lru --innodb-sys-columns --innodb-sys-fields --innodb-sys-foreign --innodb-sys-foreign-cols --innodb-sys-indexes --innodb-sys-tables --innodb-sys-virtual --core-file --loose-debug-sync-timeout=300'
2020-08-28  7:00:36 2 [Note] WSREP: Prepared SST request: rsync|127.0.0.1:16008/rsync_sst
2020-08-28  7:00:36 2 [Note] WSREP: ####### IST uuid:00000000-0000-0000-0000-000000000000 f: 0, l: 2, STRv: 3
2020-08-28  7:00:36 2 [Note] WSREP: IST receiver addr using tcp://127.0.0.1:16007
2020-08-28  7:00:36 2 [Note] WSREP: Prepared IST receiver for 0-2, listening at: tcp://127.0.0.1:16007
2020-08-28  7:00:36 0 [Note] WSREP: Member 1.0 (jan-HP-ZBook-15u-G5) requested state transfer from '*any*'. Selected 0.0 (jan-HP-ZBook-15u-G5)(SYNCED) as donor.
2020-08-28  7:00:36 0 [Note] WSREP: Shifting PRIMARY -> JOINER (TO: 2)
2020-08-28  7:00:36 2 [Note] WSREP: Requesting state transfer: success, donor: 0
2020-08-28  7:00:36 2 [Note] WSREP: Resetting GCache seqno map due to different histories.
2020-08-28  7:00:36 2 [Note] WSREP: GCache history reset: 00000000-0000-0000-0000-000000000000:0 -> 05f90ed7-e8e3-11ea-8030-9e6f51337251:2
2020-08-28  7:00:36 0 [Note] WSREP: (0641bdd9-af22, 'tcp://0.0.0.0:16006') connection established to 0646a290-9207 tcp://127.0.0.1:16009
2020-08-28  7:00:36 0 [Warning] WSREP: discarding established (time wait) 0646a290-9207 (tcp://127.0.0.1:16009) 
2020-08-28  7:00:36 0 [Note] WSREP: 0.0 (jan-HP-ZBook-15u-G5): State transfer to 1.0 (jan-HP-ZBook-15u-G5) complete.
2020-08-28  7:00:36 0 [Note] WSREP: Member 0.0 (jan-HP-ZBook-15u-G5) synced with group.
WSREP_SST: [INFO] Joiner cleanup. rsync PID: 3203852 (20200828 07:00:37.191)
WSREP_SST: [INFO] Joiner cleanup done. (20200828 07:00:37.714)
2020-08-28  7:00:37 3 [Note] WSREP: SST received
2020-08-28  7:00:37 3 [Note] WSREP: Server status change joiner -> initializing
2020-08-28  7:00:37 3 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2020-08-28  7:00:37 0 [Note] Plugin 'partition' is disabled.
2020-08-28  7:00:37 0 [Note] Plugin 'SEQUENCE' is disabled.
2020-08-28  7:00:37 0 [Note] InnoDB: Using Linux native AIO
2020-08-28  7:00:37 0 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
2020-08-28  7:00:37 0 [Note] InnoDB: Uses event mutexes
2020-08-28  7:00:37 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2020-08-28  7:00:37 0 [Note] InnoDB: Number of pools: 1
2020-08-28  7:00:37 0 [Note] InnoDB: Using SSE4.2 crc32 instructions
2020-08-28  7:00:37 0 [Note] mariadbd: O_TMPFILE is not supported on /home/jan/mysql/10.5/mysql-test/var/tmp/mysqld.2 (disabling future attempts)
2020-08-28  7:00:37 0 [Note] InnoDB: Initializing buffer pool, total size = 8388608, chunk size = 8388608
2020-08-28  7:00:37 0 [Note] InnoDB: Completed initialization of buffer pool
2020-08-28  7:00:37 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2020-08-28  7:00:37 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=47795
2020-08-28  7:00:37 0 [Note] InnoDB: Starting final batch to recover 18 pages from redo log.
2020-08-28  7:00:37 0 [Note] WSREP: (0641bdd9-af22, 'tcp://0.0.0.0:16006') connection established to 0646a290-9207 tcp://127.0.0.1:16009
2020-08-28  7:00:37 0 [Warning] WSREP: discarding established (time wait) 0646a290-9207 (tcp://127.0.0.1:16009) 
2020-08-28  7:00:37 0 [Note] WSREP:  cleaning up 0646a290-9207 (tcp://127.0.0.1:16009)
2020-08-28  7:00:37 0 [Note] InnoDB: 128 rollback segments are active.
2020-08-28  7:00:37 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2020-08-28  7:00:37 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2020-08-28  7:00:37 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2020-08-28  7:00:37 0 [Note] InnoDB: 10.5.6 started; log sequence number 55175; transaction id 40
2020-08-28  7:00:37 0 [Note] InnoDB: Loading buffer pool(s) from /home/jan/mysql/10.5/mysql-test/var/mysqld.2/data/ib_buffer_pool
2020-08-28  7:00:37 0 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
2020-08-28  7:00:37 0 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
2020-08-28  7:00:37 0 [Note] Plugin 'INNODB_CMP' is disabled.
2020-08-28  7:00:38 0 [Note] Plugin 'THREAD_POOL_WAITS' is disabled.
2020-08-28  7:00:38 0 [Note] InnoDB: Buffer pool(s) load completed at 200828  7:00:37
2020-08-28  7:00:38 0 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
2020-08-28  7:00:38 0 [Note] Plugin 'THREAD_POOL_QUEUES' is disabled.
2020-08-28  7:00:38 0 [Note] Plugin 'FEEDBACK' is disabled.
2020-08-28  7:00:38 0 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
2020-08-28  7:00:38 0 [Note] Plugin 'THREAD_POOL_GROUPS' is disabled.
2020-08-28  7:00:38 0 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
2020-08-28  7:00:38 0 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
2020-08-28  7:00:38 0 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
2020-08-28  7:00:38 0 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
2020-08-28  7:00:38 0 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
2020-08-28  7:00:38 0 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
2020-08-28  7:00:38 0 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
2020-08-28  7:00:38 0 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.
2020-08-28  7:00:38 0 [Note] Plugin 'INNODB_MUTEXES' is disabled.
2020-08-28  7:00:38 0 [Note] Plugin 'user_variables' is disabled.
2020-08-28  7:00:38 0 [Note] Plugin 'INNODB_TABLESPACES_ENCRYPTION' is disabled.
2020-08-28  7:00:38 0 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
2020-08-28  7:00:38 0 [Note] Plugin 'THREAD_POOL_STATS' is disabled.
2020-08-28  7:00:38 0 [Note] Plugin 'unix_socket' is disabled.
2020-08-28  7:00:38 0 [Warning] /home/jan/mysql/10.5/sql/mariadbd: unknown option '--loose-pam-debug'
2020-08-28  7:00:38 0 [Warning] /home/jan/mysql/10.5/sql/mariadbd: unknown option '--loose-aria'
2020-08-28  7:00:38 0 [Note] Server socket created on IP: '127.0.0.1'.
2020-08-28  7:00:38 0 [Note] WSREP: wsrep_init_schema_and_SR 0x0
2020-08-28  7:00:38 0 [Note] WSREP: Server initialized
2020-08-28  7:00:38 0 [Note] WSREP: Server status change initializing -> initialized
2020-08-28  7:00:38 0 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2020-08-28  7:00:38 3 [Note] WSREP: Server status change initialized -> joined
2020-08-28  7:00:38 3 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2020-08-28  7:00:38 0 [Note] Reading of all Master_info entries succeeded
2020-08-28  7:00:38 0 [Note] Added new Master_info '' to hash table
2020-08-28  7:00:38 0 [Note] /home/jan/mysql/10.5/sql/mariadbd: ready for connections.
Version: '10.5.6-MariaDB-debug-log'  socket: '/home/jan/mysql/10.5/mysql-test/var/tmp/mysqld.2.sock'  port: 16001  Source distribution
2020-08-28  7:00:38 3 [Note] WSREP: Recovered position from storage: 05f90ed7-e8e3-11ea-8030-9e6f51337251:2
2020-08-28  7:00:38 3 [Note] WSREP: Recovered view from SST:
  id: 05f90ed7-e8e3-11ea-8030-9e6f51337251:2
  status: primary
  protocol_version: 4
  capabilities: MULTI-MASTER, CERTIFICATION, PARALLEL_APPLYING, REPLAY, ISOLATION, PAUSE, CAUSAL_READ, INCREMENTAL_WS, UNORDERED, PREORDERED, STREAMING, NBO
  final: no
  own_index: 1
  members(2):
	0: 05f82ea0-e8e3-11ea-8e7d-5b95bfc0fb83, jan-HP-ZBook-15u-G5
	1: 0641bdd9-e8e3-11ea-af22-afc54f3298ad, jan-HP-ZBook-15u-G5
 
2020-08-28  7:00:38 3 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2020-08-28  7:00:38 7 [Note] WSREP: Recovered cluster id 05f90ed7-e8e3-11ea-8030-9e6f51337251
2020-08-28  7:00:38 3 [Note] WSREP: SST received: 05f90ed7-e8e3-11ea-8030-9e6f51337251:2
2020-08-28  7:00:38 0 [Note] WSREP: Joiner monitor thread ended with total time 3 sec
2020-08-28  7:00:38 2 [Note] WSREP: Installed new state from SST: 05f90ed7-e8e3-11ea-8030-9e6f51337251:2
2020-08-28  7:00:38 2 [Note] WSREP: Cert. index preload up to 2
2020-08-28  7:00:38 0 [Note] WSREP: ####### IST applying starts with 3
2020-08-28  7:00:38 0 [Note] WSREP: ####### IST current seqno initialized to 2
2020-08-28  7:00:38 0 [Note] WSREP: Receiving IST...  0.0% (0/1 events) complete.
2020-08-28  7:00:38 0 [Note] WSREP: IST preload starting at 2
2020-08-28  7:00:38 0 [Note] WSREP: REPL Protocols: 10 (5)
2020-08-28  7:00:38 0 [Note] WSREP: Service thread queue flushed.
2020-08-28  7:00:38 0 [Note] WSREP: ####### Assign initial position for certification: 05f90ed7-e8e3-11ea-8030-9e6f51337251:1, protocol version: 5
2020-08-28  7:00:38 0 [Note] WSREP: REPL Protocols: 10 (5)
2020-08-28  7:00:38 0 [Note] WSREP: ####### Adjusting cert position: 1 -> 2
2020-08-28  7:00:38 0 [Note] WSREP: Service thread queue flushed.
2020-08-28  7:00:38 0 [Note] WSREP: Lowest cert index boundary for CC from preload: 2
2020-08-28  7:00:38 0 [Note] WSREP: Min available from gcache for CC from preload: 2
2020-08-28  7:00:38 0 [Note] WSREP: Receiving IST...100.0% (1/1 events) complete.
2020-08-28  7:00:38 2 [Note] WSREP: IST received: 05f90ed7-e8e3-11ea-8030-9e6f51337251:2
2020-08-28  7:00:38 2 [Note] WSREP: Lowest cert index boundary for CC from sst: 2
2020-08-28  7:00:38 2 [Note] WSREP: Min available from gcache for CC from sst: 2
2020-08-28  7:00:38 0 [Note] WSREP: 1.0 (jan-HP-ZBook-15u-G5): State transfer from 0.0 (jan-HP-ZBook-15u-G5) complete.
2020-08-28  7:00:38 0 [Note] WSREP: Shifting JOINER -> JOINED (TO: 2)
2020-08-28  7:00:38 0 [Note] WSREP: Member 1.0 (jan-HP-ZBook-15u-G5) synced with group.
2020-08-28  7:00:38 0 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 2)
2020-08-28  7:00:38 2 [Note] WSREP: Server jan-HP-ZBook-15u-G5 synced with group
2020-08-28  7:00:38 2 [Note] WSREP: Server status change joined -> synced
2020-08-28  7:00:38 2 [Note] WSREP: Synchronized with group, ready for connections
2020-08-28  7:00:38 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2020-08-28  7:00:38 0 [Note] WSREP: (0641bdd9-af22, 'tcp://0.0.0.0:16006') turning message relay requesting off
2020-08-28  7:00:39 0 [Note] WSREP: (0641bdd9-af22, 'tcp://0.0.0.0:16006') connection established to 0646a290-9207 tcp://127.0.0.1:16009
2020-08-28  7:00:39 0 [Note] WSREP: (0641bdd9-af22, 'tcp://0.0.0.0:16006') turning message relay requesting on, nonlive peers: 
2020-08-28  7:00:41 0 [Note] WSREP: declaring 05f82ea0-8e7d at tcp://127.0.0.1:16003 stable
2020-08-28  7:00:41 0 [Note] WSREP: declaring 0646a290-9207 at tcp://127.0.0.1:16009 stable
2020-08-28  7:00:41 0 [Note] WSREP: Node 05f82ea0-8e7d state prim
2020-08-28  7:00:41 0 [Note] WSREP: view(view_id(PRIM,05f82ea0-8e7d,3) memb {
	05f82ea0-8e7d,0
	0641bdd9-af22,0
	0646a290-9207,0
} joined {
} left {
} partitioned {
})
2020-08-28  7:00:41 0 [Note] WSREP: save pc into disk
2020-08-28  7:00:41 0 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 1, memb_num = 3
2020-08-28  7:00:41 0 [Note] WSREP: STATE EXCHANGE: Waiting for state UUID.
2020-08-28  7:00:41 0 [Note] WSREP: STATE EXCHANGE: sent state msg: 0a23f050-e8e3-11ea-ac50-7f833b60069e
2020-08-28  7:00:41 0 [Note] WSREP: STATE EXCHANGE: got state msg: 0a23f050-e8e3-11ea-ac50-7f833b60069e from 0 (jan-HP-ZBook-15u-G5)
2020-08-28  7:00:41 0 [Note] WSREP: STATE EXCHANGE: got state msg: 0a23f050-e8e3-11ea-ac50-7f833b60069e from 1 (jan-HP-ZBook-15u-G5)
2020-08-28  7:00:41 0 [Note] WSREP: STATE EXCHANGE: got state msg: 0a23f050-e8e3-11ea-ac50-7f833b60069e from 2 (jan-HP-ZBook-15u-G5)
2020-08-28  7:00:41 0 [Note] WSREP: Quorum results:
	version    = 6,
	component  = PRIMARY,
	conf_id    = 2,
	members    = 2/3 (joined/total),
	act_id     = 2,
	last_appl. = 0,
	protocols  = 2/10/4 (gcs/repl/appl),
	vote policy= 0,
	group UUID = 05f90ed7-e8e3-11ea-8030-9e6f51337251
2020-08-28  7:00:41 0 [Note] WSREP: Flow-control interval: [28, 28]
2020-08-28  7:00:41 2 [Note] WSREP: ####### processing CC 3, local, ordered
2020-08-28  7:00:41 2 [Note] WSREP: ####### My UUID: 0641bdd9-e8e3-11ea-af22-afc54f3298ad
2020-08-28  7:00:41 2 [Note] WSREP: Skipping cert index reset
2020-08-28  7:00:41 2 [Note] WSREP: REPL Protocols: 10 (5)
2020-08-28  7:00:41 2 [Note] WSREP: ####### Adjusting cert position: 2 -> 3
2020-08-28  7:00:41 0 [Note] WSREP: Service thread queue flushed.
2020-08-28  7:00:41 2 [Note] WSREP: ================================================
View:
  id: 05f90ed7-e8e3-11ea-8030-9e6f51337251:3
  status: primary
  protocol_version: 4
  capabilities: MULTI-MASTER, CERTIFICATION, PARALLEL_APPLYING, REPLAY, ISOLATION, PAUSE, CAUSAL_READ, INCREMENTAL_WS, UNORDERED, PREORDERED, STREAMING, NBO
  final: no
  own_index: 1
  members(3):
	0: 05f82ea0-e8e3-11ea-8e7d-5b95bfc0fb83, jan-HP-ZBook-15u-G5
	1: 0641bdd9-e8e3-11ea-af22-afc54f3298ad, jan-HP-ZBook-15u-G5
	2: 0646a290-e8e3-11ea-9207-e34afafc8032, jan-HP-ZBook-15u-G5
=================================================
2020-08-28  7:00:41 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2020-08-28  7:00:41 2 [Note] WSREP: Lowest cert index boundary for CC from group: 3
2020-08-28  7:00:41 2 [Note] WSREP: Min available from gcache for CC from group: 2
2020-08-28  7:00:41 0 [Note] WSREP: Member 2.0 (jan-HP-ZBook-15u-G5) requested state transfer from '*any*'. Selected 0.0 (jan-HP-ZBook-15u-G5)(SYNCED) as donor.
2020-08-28  7:00:41 0 [Note] WSREP: 0.0 (jan-HP-ZBook-15u-G5): State transfer to 2.0 (jan-HP-ZBook-15u-G5) complete.
2020-08-28  7:00:41 0 [Note] WSREP: Member 0.0 (jan-HP-ZBook-15u-G5) synced with group.
2020-08-28  7:00:42 0 [Note] WSREP: (0641bdd9-af22, 'tcp://0.0.0.0:16006') turning message relay requesting off
2020-08-28  7:00:43 0 [Note] WSREP: 2.0 (jan-HP-ZBook-15u-G5): State transfer from 0.0 (jan-HP-ZBook-15u-G5) complete.
2020-08-28  7:00:43 0 [Note] WSREP: Member 2.0 (jan-HP-ZBook-15u-G5) synced with group.
2020-08-28  7:00:46 0 [Note] WSREP: Member 0(jan-HP-ZBook-15u-G5) initiates vote on 05f90ed7-e8e3-11ea-8030-9e6f51337251:7,b7993b506d8b95e5:  Can't DROP INDEX `PRIMARY`; check that it exists, Error_code: 1091;
2020-08-28  7:00:46 0 [Note] WSREP: Votes over 05f90ed7-e8e3-11ea-8030-9e6f51337251:7:
   b7993b506d8b95e5:   1/3
Waiting for more votes.
2020-08-28  7:00:46 0 [Note] WSREP: Member 2(jan-HP-ZBook-15u-G5) initiates vote on 05f90ed7-e8e3-11ea-8030-9e6f51337251:7,b7993b506d8b95e5:  Can't DROP INDEX `PRIMARY`; check that it exists, Error_code: 1091;
2020-08-28  7:00:46 0 [Note] WSREP: Votes over 05f90ed7-e8e3-11ea-8030-9e6f51337251:7:
   b7993b506d8b95e5:   2/3
Winner: b7993b506d8b95e5
2020-08-28  7:00:46 2 [Note] WSREP: Got vote request for seqno 05f90ed7-e8e3-11ea-8030-9e6f51337251:7
2020-08-28  7:00:46 0 [Note] WSREP: Recovering vote result from history: 05f90ed7-e8e3-11ea-8030-9e6f51337251:7,b7993b506d8b95e5
2020-08-28  7:00:46 2 [ERROR] WSREP: Vote 0 (success) on 05f90ed7-e8e3-11ea-8030-9e6f51337251:7 is inconsistent with group. Leaving cluster.
2020-08-28  7:00:46 2 [Note] WSREP: Closing send monitor...
2020-08-28  7:00:46 2 [Note] WSREP: Closed send monitor.
2020-08-28  7:00:46 2 [Note] WSREP: gcomm: terminating thread
2020-08-28  7:00:46 2 [Note] WSREP: gcomm: joining thread
2020-08-28  7:00:46 2 [Note] WSREP: gcomm: closing backend
2020-08-28  7:00:46 2 [Note] WSREP: view(view_id(NON_PRIM,05f82ea0-8e7d,3) memb {
	0641bdd9-af22,0
} joined {
} left {
} partitioned {
	05f82ea0-8e7d,0
	0646a290-9207,0
})
2020-08-28  7:00:46 2 [Note] WSREP: PC protocol downgrade 1 -> 0
2020-08-28  7:00:46 2 [Note] WSREP: view((empty))
2020-08-28  7:00:46 2 [Note] WSREP: gcomm: closed
2020-08-28  7:00:46 0 [Note] WSREP: New COMPONENT: primary = no, bootstrap = no, my_idx = 0, memb_num = 1
2020-08-28  7:00:46 0 [Note] WSREP: Flow-control interval: [16, 16]
2020-08-28  7:00:46 0 [Note] WSREP: Received NON-PRIMARY.
2020-08-28  7:00:46 0 [Note] WSREP: Shifting SYNCED -> OPEN (TO: 7)
2020-08-28  7:00:46 0 [Note] WSREP: New SELF-LEAVE.
2020-08-28  7:00:46 0 [Note] WSREP: Flow-control interval: [0, 0]
2020-08-28  7:00:46 0 [Note] WSREP: Received SELF-LEAVE. Closing connection.
2020-08-28  7:00:46 0 [Note] WSREP: Shifting OPEN -> CLOSED (TO: 7)
2020-08-28  7:00:46 0 [Note] WSREP: RECV thread exiting 0: Success
2020-08-28  7:00:46 2 [Note] WSREP: recv_thread() joined.
2020-08-28  7:00:46 2 [Note] WSREP: Closing replication queue.
2020-08-28  7:00:46 2 [Note] WSREP: Closing slave action queue.
2020-08-28  7:00:46 2 [Note] WSREP: ================================================
View:
  id: 05f90ed7-e8e3-11ea-8030-9e6f51337251:7
  status: non-primary
  protocol_version: 4
  capabilities: MULTI-MASTER, CERTIFICATION, PARALLEL_APPLYING, REPLAY, ISOLATION, PAUSE, CAUSAL_READ, INCREMENTAL_WS, UNORDERED, PREORDERED, STREAMING, NBO
  final: no
  own_index: 0
  members(1):
	0: 0641bdd9-e8e3-11ea-af22-afc54f3298ad, jan-HP-ZBook-15u-G5
=================================================
2020-08-28  7:00:46 2 [Note] WSREP: Non-primary view
2020-08-28  7:00:46 2 [Note] WSREP: Server status change synced -> connected
2020-08-28  7:00:46 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2020-08-28  7:00:46 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2020-08-28  7:00:46 2 [Note] WSREP: ================================================
View:
  id: 05f90ed7-e8e3-11ea-8030-9e6f51337251:7
  status: non-primary
  protocol_version: 4
  capabilities: MULTI-MASTER, CERTIFICATION, PARALLEL_APPLYING, REPLAY, ISOLATION, PAUSE, CAUSAL_READ, INCREMENTAL_WS, UNORDERED, PREORDERED, STREAMING, NBO
  final: yes
  own_index: -1
  members(0):
=================================================
2020-08-28  7:00:46 2 [Note] WSREP: Non-primary view
2020-08-28  7:00:46 2 [Note] WSREP: Server status change connected -> disconnected
2020-08-28  7:00:46 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2020-08-28  7:00:46 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2020-08-28  7:00:46 0 [Note] WSREP: Service thread queue flushed.
2020-08-28  7:00:46 2 [Note] WSREP: ####### Assign initial position for certification: 00000000-0000-0000-0000-000000000000:-1, protocol version: 5
2020-08-28  7:00:46 2 [Note] WSREP: Applier thread exiting ret: 0 thd: 2
2020-08-28  7:00:46 2 [Warning] Aborted connection 2 to db: 'unconnected' user: 'unauthenticated' host: '' (This connection closed normally without authentication)
2020-08-28  7:00:46 10 [Note] WSREP: Stop replication by 10
2020-08-28  7:00:46 1 [Note] WSREP: rollbacker thread exiting 1
2020-08-28  7:00:46 1 [Warning] Aborted connection 1 to db: 'unconnected' user: 'unauthenticated' host: '' (This connection closed normally without authentication)
2020-08-28  7:00:46 10 [Note] WSREP: Start replication
2020-08-28  7:00:46 10 [Note] WSREP: Connecting with bootstrap option: 0
2020-08-28  7:00:46 10 [Note] WSREP: Setting GCS initial position to 00000000-0000-0000-0000-000000000000:-1
2020-08-28  7:00:46 10 [Note] WSREP: protonet asio version 0
2020-08-28  7:00:46 10 [Note] WSREP: Using CRC-32C for message checksums.
2020-08-28  7:00:46 10 [Note] WSREP: backend: asio
2020-08-28  7:00:46 10 [Note] WSREP: gcomm thread scheduling priority set to other:0 
2020-08-28  7:00:46 10 [Warning] WSREP: access file(/home/jan/mysql/10.5/mysql-test/var/mysqld.2/data//gvwstate.dat) failed(No such file or directory)
2020-08-28  7:00:46 10 [Note] WSREP: restore pc from disk failed
2020-08-28  7:00:46 10 [Note] WSREP: GMCast version 0
2020-08-28  7:00:46 10 [Note] WSREP: (0d50e5b0-a690, 'tcp://0.0.0.0:16006') listening at tcp://0.0.0.0:16006
2020-08-28  7:00:46 10 [Note] WSREP: (0d50e5b0-a690, 'tcp://0.0.0.0:16006') multicast: , ttl: 1
2020-08-28  7:00:46 10 [Note] WSREP: EVS version 1
2020-08-28  7:00:46 10 [Note] WSREP: gcomm: connecting to group 'my_wsrep_cluster', peer '127.0.0.1:16003'
2020-08-28  7:00:46 10 [Note] WSREP: (0d50e5b0-a690, 'tcp://0.0.0.0:16006') connection established to 05f82ea0-8e7d tcp://127.0.0.1:16003
2020-08-28  7:00:46 10 [Note] WSREP: (0d50e5b0-a690, 'tcp://0.0.0.0:16006') turning message relay requesting on, nonlive peers: tcp://127.0.0.1:16009 
2020-08-28  7:00:47 10 [Note] WSREP: (0d50e5b0-a690, 'tcp://0.0.0.0:16006') connection established to 0646a290-9207 tcp://127.0.0.1:16009
2020-08-28  7:00:49 10 [Note] WSREP: EVS version upgrade 0 -> 1
2020-08-28  7:00:49 10 [Note] WSREP: declaring 05f82ea0-8e7d at tcp://127.0.0.1:16003 stable
2020-08-28  7:00:49 10 [Note] WSREP: declaring 0646a290-9207 at tcp://127.0.0.1:16009 stable
2020-08-28  7:00:49 10 [Note] WSREP: PC protocol upgrade 0 -> 1
2020-08-28  7:00:49 10 [Note] WSREP: Node 05f82ea0-8e7d state prim
2020-08-28  7:00:49 10 [Note] WSREP: view(view_id(PRIM,05f82ea0-8e7d,5) memb {
	05f82ea0-8e7d,0
	0646a290-9207,0
	0d50e5b0-a690,0
} joined {
} left {
} partitioned {
})
2020-08-28  7:00:49 10 [Note] WSREP: save pc into disk
2020-08-28  7:00:49 10 [Note] WSREP: gcomm: connected
2020-08-28  7:00:49 10 [Note] WSREP: Changing maximum packet size to 64500, resulting msg size: 32636
2020-08-28  7:00:49 10 [Note] WSREP: Shifting CLOSED -> OPEN (TO: 7)
2020-08-28  7:00:49 10 [Note] WSREP: Opened channel 'my_wsrep_cluster'
2020-08-28  7:00:49 0 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 2, memb_num = 3
2020-08-28  7:00:49 0 [Note] WSREP: STATE EXCHANGE: Waiting for state UUID.
2020-08-28  7:00:49 0 [Note] WSREP: STATE EXCHANGE: sent state msg: 0ed0df5b-e8e3-11ea-8bf3-13cb0b9c4cbc
2020-08-28  7:00:49 0 [Note] WSREP: STATE EXCHANGE: got state msg: 0ed0df5b-e8e3-11ea-8bf3-13cb0b9c4cbc from 0 (jan-HP-ZBook-15u-G5)
2020-08-28  7:00:49 0 [Note] WSREP: STATE EXCHANGE: got state msg: 0ed0df5b-e8e3-11ea-8bf3-13cb0b9c4cbc from 1 (jan-HP-ZBook-15u-G5)
2020-08-28  7:00:49 0 [Note] WSREP: STATE EXCHANGE: got state msg: 0ed0df5b-e8e3-11ea-8bf3-13cb0b9c4cbc from 2 (jan-HP-ZBook-15u-G5)
2020-08-28  7:00:49 0 [Note] WSREP: Quorum results:
	version    = 6,
	component  = PRIMARY,
	conf_id    = 4,
	members    = 2/3 (joined/total),
	act_id     = 8,
	last_appl. = 0,
	protocols  = 2/10/4 (gcs/repl/appl),
	vote policy= 0,
	group UUID = 05f90ed7-e8e3-11ea-8030-9e6f51337251
2020-08-28  7:00:49 11 [Note] WSREP: Starting rollbacker thread 11
2020-08-28  7:00:49 0 [Note] WSREP: Flow-control interval: [28, 28]
2020-08-28  7:00:49 0 [Note] WSREP: Shifting OPEN -> PRIMARY (TO: 9)
2020-08-28  7:00:49 12 [Note] WSREP: Starting applier thread 12
2020-08-28  7:00:49 12 [Note] WSREP: ####### processing CC 9, local, ordered
2020-08-28  7:00:49 12 [Note] WSREP: Process first view: 05f90ed7-e8e3-11ea-8030-9e6f51337251 my uuid: 0d50e5b0-e8e3-11ea-a690-fb341cef664b
2020-08-28  7:00:49 12 [Note] WSREP: Server jan-HP-ZBook-15u-G5 connected to cluster at position 05f90ed7-e8e3-11ea-8030-9e6f51337251:9 with ID 0d50e5b0-e8e3-11ea-a690-fb341cef664b
2020-08-28  7:00:49 12 [Note] WSREP: Server status change disconnected -> connected
2020-08-28  7:00:49 12 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2020-08-28  7:00:49 12 [Note] WSREP: ####### My UUID: 0d50e5b0-e8e3-11ea-a690-fb341cef664b
2020-08-28  7:00:49 12 [Note] WSREP: Cert index reset to 00000000-0000-0000-0000-000000000000:-1 (proto: 10), state transfer needed: yes
2020-08-28  7:00:49 0 [Note] WSREP: Service thread queue flushed.
2020-08-28  7:00:49 12 [Note] WSREP: ####### Assign initial position for certification: 00000000-0000-0000-0000-000000000000:-1, protocol version: -1
2020-08-28  7:00:49 12 [Note] WSREP: State transfer required: 
	Group state: 05f90ed7-e8e3-11ea-8030-9e6f51337251:9
	Local state: 00000000-0000-0000-0000-000000000000:-1
2020-08-28  7:00:49 12 [Note] WSREP: Server status change connected -> joiner
2020-08-28  7:00:49 12 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2020-08-28  7:00:49 12 [Note] WSREP: Prepared SST request: mysqldump|127.0.0.1:16001
2020-08-28  7:00:49 12 [Note] WSREP: ####### IST uuid:00000000-0000-0000-0000-000000000000 f: 0, l: 9, STRv: 3
2020-08-28  7:00:49 12 [Note] WSREP: IST receiver addr using tcp://127.0.0.1:16007
2020-08-28  7:00:49 12 [Note] WSREP: Prepared IST receiver for 0-9, listening at: tcp://127.0.0.1:16007
2020-08-28  7:00:49 0 [Note] WSREP: Member 2.0 (jan-HP-ZBook-15u-G5) requested state transfer from '*any*'. Selected 0.0 (jan-HP-ZBook-15u-G5)(SYNCED) as donor.
2020-08-28  7:00:49 0 [Note] WSREP: Shifting PRIMARY -> JOINER (TO: 9)
2020-08-28  7:00:49 12 [Note] WSREP: Requesting state transfer: success, donor: 0
2020-08-28  7:00:49 12 [Note] WSREP: Resetting GCache seqno map due to different histories.
2020-08-28  7:00:49 12 [Note] WSREP: GCache history reset: 05f90ed7-e8e3-11ea-8030-9e6f51337251:7 -> 05f90ed7-e8e3-11ea-8030-9e6f51337251:9
2020-08-28  7:00:49 12 [Note] WSREP: GCache DEBUG: RingBuffer::seqno_reset(): discarded 2472 bytes
2020-08-28  7:00:49 12 [Note] WSREP: GCache DEBUG: RingBuffer::seqno_reset(): found 1/2 locked buffers
2020-08-28  7:00:50 0 [Note] WSREP: (0d50e5b0-a690, 'tcp://0.0.0.0:16006') turning message relay requesting off
2020-08-28  7:00:53 0 [Warning] WSREP: 0.0 (jan-HP-ZBook-15u-G5): State transfer to 2.0 (jan-HP-ZBook-15u-G5) failed: -1 (Operation not permitted)
2020-08-28  7:00:53 0 [ERROR] WSREP: gcs/src/gcs_group.cpp:gcs_group_handle_join_msg():1178: Will never receive state. Need to abort.
2020-08-28  7:00:53 0 [Note] WSREP: gcomm: terminating thread
2020-08-28  7:00:53 0 [Note] WSREP: gcomm: joining thread
2020-08-28  7:00:53 0 [Note] WSREP: gcomm: closing backend
2020-08-28  7:00:53 0 [Note] WSREP: view(view_id(NON_PRIM,05f82ea0-8e7d,5) memb {
	0d50e5b0-a690,0
} joined {
} left {
} partitioned {
	05f82ea0-8e7d,0
	0646a290-9207,0
})
2020-08-28  7:00:53 0 [Note] WSREP: PC protocol downgrade 1 -> 0
2020-08-28  7:00:53 0 [Note] WSREP: view((empty))
2020-08-28  7:00:53 0 [Note] WSREP: gcomm: closed
2020-08-28  7:00:53 0 [Note] WSREP: /home/jan/mysql/10.5/sql/mariadbd: Terminated.
----------SERVER LOG END-------------
mysqltest failed but provided no output
The result from queries just before the failure was:
< snip >
ALTER TABLE t1 LOCK=SHARED, DROP PRIMARY KEY;
ERROR 42000: Can't DROP INDEX `PRIMARY`; check that it exists
connection node_1;
SELECT VARIABLE_VALUE AS expect_Primary FROM INFORMATION_SCHEMA.GLOBAL_STATUS WHERE VARIABLE_NAME = 'wsrep_cluster_status';
expect_Primary
Primary
connection node_3;
SELECT VARIABLE_VALUE AS expect_2 FROM INFORMATION_SCHEMA.GLOBAL_STATUS WHERE VARIABLE_NAME = 'wsrep_cluster_size';
expect_2
2
SELECT VARIABLE_VALUE AS expect_Primary FROM INFORMATION_SCHEMA.GLOBAL_STATUS WHERE VARIABLE_NAME = 'wsrep_cluster_status';
expect_Primary
Primary
connection node_2;
SET SESSION wsrep_on=OFF;
SELECT VARIABLE_VALUE AS expect_Disconnected FROM INFORMATION_SCHEMA.GLOBAL_STATUS WHERE VARIABLE_NAME = 'wsrep_cluster_status';
expect_Disconnected
Disconnected
SET SESSION wsrep_on=ON;
SET SESSION wsrep_sync_wait = 0;

Comment by Stepan Patryshev (Inactive) [ 2020-09-30 ]

It failed on BB 10.5 with the new error: "mysql_shutdown failed".

stdio.log:

10.5.6 25ede13611b3c1f736be22fc581a0c371d212f61

galera_3nodes.galera_vote_rejoin_mysqldump 'innodb' w2 [ fail ]
        Test ended at 2020-09-29 15:50:22
 
CURRENT_TEST: galera_3nodes.galera_vote_rejoin_mysqldump
mysqltest: In included file "./include/shutdown_mysqld.inc": 
included from ./include/restart_mysqld.inc at line 10:
included from /usr/share/mysql-test/suite/galera_3nodes/t/galera_vote_rejoin_mysqldump.test at line 78:
At line 50: mysql_shutdown failed
 
The result from queries just before the failure was:
< snip >
expect_Primary
Primary
connection node_2;
SET SESSION wsrep_on=OFF;
SELECT VARIABLE_VALUE AS expect_Disconnected FROM INFORMATION_SCHEMA.GLOBAL_STATUS WHERE VARIABLE_NAME = 'wsrep_cluster_status';
expect_Disconnected
Disconnected
SET SESSION wsrep_on=ON;
SELECT VARIABLE_VALUE AS expect_Primary FROM INFORMATION_SCHEMA.GLOBAL_STATUS WHERE VARIABLE_NAME = 'wsrep_cluster_status';
expect_Primary
Primary
connection node_1;
SHOW CREATE TABLE t1;
Table	Create Table
t1	CREATE TABLE `t1` (
  `f1` int(11) DEFAULT NULL
) ENGINE=InnoDB DEFAULT CHARSET=latin1
connection node_2;
SET SESSION wsrep_on=OFF;
SET SESSION wsrep_on=ON;
 
More results from queries before failure can be found in /dev/shm/var/2/log/galera_vote_rejoin_mysqldump.log
 
 - saving '/dev/shm/var/2/log/galera_3nodes.galera_vote_rejoin_mysqldump-innodb/' to '/dev/shm/var/log/galera_3nodes.galera_vote_rejoin_mysqldump-innodb/'
 
Retrying test galera_3nodes.galera_vote_rejoin_mysqldump, attempt(2/3)...
 
worker[2] > Restart  - not started
worker[2] > Restart  - not started
worker[2] > Restart  - not started
***Warnings generated in error logs during shutdown after running tests: galera_3nodes.galera_vote_rejoin_mysqldump
 
2020-09-29 15:50:18 1 [ERROR] WSREP: Vote 0 (success) on 71c48dca-026b-11eb-ac7d-af6ec2ef825a:7 is inconsistent with group. Leaving cluster.

See also MXS-3203 which may be related.

Comment by Alexey [ 2021-09-21 ]

The following commit contains a lot of changes in this direction and is likely to fix that issue: https://github.com/MariaDB/server/commit/8fef2b8667f30e4562ac006f992f859d1defdc0e
From what I understand is should be in all recent releases.

Comment by Julius Goryavsky [ 2021-10-05 ]

Fixed as part of MDEV-23580, everything else is a separate task (https://jira.mariadb.org/browse/MDEV-24481)

Generated at Thu Feb 08 09:23:39 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.