After having updated a Ubuntu 14.04 Trusty server, including MariaDB and Galera packages, I noticed the node wasn't able to join the Galera cluster anymore.
According to the apt history log, the versions were updated like this:
mariadb-galera-server:amd64 (10.0.31+maria-1~trusty, 10.0.34+maria-1~trusty), mariadb-client-core-10.0:amd64 (10.0.32+maria-1~trusty, 10.0.34+maria-1~trusty), mariadb-common:amd64 (10.0.32+maria-1~trusty, 10.0.34+maria-1~trusty), mariadb-galera-server-10.0:amd64 (10.0.31+maria-1~trusty, 10.0.34+maria-1~trusty), galera-3:amd64 (25.3.20-trusty, 25.3.22-trusty), mariadb-client-10.0:amd64 (10.0.32+maria-1~trusty, 10.0.34+maria-1~trusty)
I know for a fact that an automatic join after a MariaDB/MySQL start worked. But after the upgrade and an automatic MariaDB start, the Galera node wasn't able to join the Galera cluster. It appeared in the "wsrep_incoming_addresses" but then quickly disappeared again. In the logs I found the following logs when I manually launched the mysql_safe daemon:
# mysqld_safe --skip-grant-tables &
Apr 25 22:06:09 galera-node-2 mysqld_safe: WSREP: Recovered position 32c39115-8d32-11e5-9122-b6a2b3e41530:724808778
Apr 25 22:06:09 galera-node-2 mysqld: 180425 22:06:09 [Note] /usr/sbin/mysqld (mysqld 10.0.34-MariaDB-1~trusty-wsrep) starting as process 29529 ...
Apr 25 22:06:09 galera-node-2 mysqld: 180425 22:06:09 [Note] WSREP: Read nil XID from storage engines, skipping position init
Apr 25 22:06:09 galera-node-2 mysqld: 180425 22:06:09 [Note] WSREP: wsrep_load(): loading provider library '/usr/lib/galera/libgalera_smm.so'
Apr 25 22:06:09 galera-node-2 mysqld: 180425 22:06:09 [Note] WSREP: wsrep_load(): Galera 25.3.22(r3764) by Codership Oy
Apr 25 22:06:09 galera-node-2 mysqld: 180425 22:06:09 [Note] WSREP: CRC-32C: using hardware acceleration.
Apr 25 22:06:09 galera-node-2 mysqld: 180425 22:06:09 [Note] WSREP: Found saved state: 32c39115-8d32-11e5-9122-b6a2b3e41530:-1, safe_to_bootstrap: 0
Apr 25 22:06:09 galera-node-2 mysqld: 180425 22:06:09 [Note] WSREP: Passing config to GCS: base_dir = /var/lib/mysql/; base_host = 10.55.55.86; base_port = 4567; cert.log_conflicts = no; 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.mem_size = 0; gcache.name = /var/lib/mysql//galera.cache; gcache.page_size = 128M; gcache.recover = no; 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.sync_donor = no; gmcast.segment = 0; gmcast.version = 0; pc.announce_timeout = PT3S;
Apr 25 22:06:09 galera-node-2 mysqld: pc.checksum = false; pc
Apr 25 22:06:09 galera-node-2 mysqld: 180425 22:06:09 [Note] WSREP: GCache history reset: 32c39115-8d32-11e5-9122-b6a2b3e41530:0 -> 32c39115-8d32-11e5-9122-b6a2b3e41530:724808778
Apr 25 22:06:09 galera-node-2 mysqld: 180425 22:06:09 [Note] WSREP: Assign initial position for certification: 724808778, protocol version: -1
Apr 25 22:06:09 galera-node-2 mysqld: 180425 22:06:09 [Note] WSREP: wsrep_sst_grab()
Apr 25 22:06:09 galera-node-2 mysqld: 180425 22:06:09 [Note] WSREP: Start replication
Apr 25 22:06:09 galera-node-2 mysqld: 180425 22:06:09 [Note] WSREP: Setting initial position to 32c39115-8d32-11e5-9122-b6a2b3e41530:724808778
Apr 25 22:06:09 galera-node-2 mysqld: 180425 22:06:09 [Note] WSREP: protonet asio version 0
Apr 25 22:06:09 galera-node-2 mysqld: 180425 22:06:09 [Note] WSREP: Using CRC-32C for message checksums.
Apr 25 22:06:09 galera-node-2 mysqld: 180425 22:06:09 [Note] WSREP: backend: asio
Apr 25 22:06:09 galera-node-2 mysqld: 180425 22:06:09 [Note] WSREP: gcomm thread scheduling priority set to other:0
Apr 25 22:06:09 galera-node-2 mysqld: 180425 22:06:09 [Warning] WSREP: access file(/var/lib/mysql//gvwstate.dat) failed(No such file or directory)
Apr 25 22:06:09 galera-node-2 mysqld: 180425 22:06:09 [Note] WSREP: restore pc from disk failed
Apr 25 22:06:09 galera-node-2 mysqld: 180425 22:06:09 [Note] WSREP: GMCast version 0
Apr 25 22:06:09 galera-node-2 mysqld: 180425 22:06:09 [Note] WSREP: (185196d1, 'tcp://0.0.0.0:4567') listening at tcp://0.0.0.0:4567
Apr 25 22:06:09 galera-node-2 mysqld: 180425 22:06:09 [Note] WSREP: (185196d1, 'tcp://0.0.0.0:4567') multicast: , ttl: 1
Apr 25 22:06:09 galera-node-2 mysqld: 180425 22:06:09 [Note] WSREP: EVS version 0
Apr 25 22:06:09 galera-node-2 mysqld: 180425 22:06:09 [Note] WSREP: gcomm: connecting to group 'GALERACLUSTER', peer '10.55.55.85:,10.55.55.86:,10.55.55.87:'
Apr 25 22:06:09 galera-node-2 mysqld: 180425 22:06:09 [Note] WSREP: (185196d1, 'tcp://0.0.0.0:4567') connection established to 185196d1 tcp://10.55.55.86:4567
Apr 25 22:06:09 galera-node-2 mysqld: 180425 22:06:09 [Warning] WSREP: (185196d1, 'tcp://0.0.0.0:4567') address 'tcp://10.55.55.86:4567' points to own listening address, blacklisting
Apr 25 22:06:09 galera-node-2 mysqld: 180425 22:06:09 [Note] WSREP: (185196d1, 'tcp://0.0.0.0:4567') connection established to acfd2d2f tcp://10.55.55.87:4567
Apr 25 22:06:09 galera-node-2 mysqld: 180425 22:06:09 [Note] WSREP: (185196d1, 'tcp://0.0.0.0:4567') turning message relay requesting on, nonlive peers:
Apr 25 22:06:09 galera-node-2 mysqld: 180425 22:06:09 [Note] WSREP: (185196d1, 'tcp://0.0.0.0:4567') connection established to d607ef0f tcp://10.55.55.85:4567
Apr 25 22:06:09 galera-node-2 mysqld: 180425 22:06:09 [Note] WSREP: declaring acfd2d2f at tcp://10.55.55.87:4567 stable
Apr 25 22:06:09 galera-node-2 mysqld: 180425 22:06:09 [Note] WSREP: declaring d607ef0f at tcp://10.55.55.85:4567 stable
Apr 25 22:06:09 galera-node-2 mysqld: 180425 22:06:09 [Note] WSREP: Node acfd2d2f state prim
Apr 25 22:06:09 galera-node-2 mysqld: 180425 22:06:09 [Note] WSREP: view(view_id(PRIM,185196d1,12) memb {
Apr 25 22:06:09 galera-node-2 mysqld: #011185196d1,0
Apr 25 22:06:09 galera-node-2 mysqld: #011acfd2d2f,0
Apr 25 22:06:09 galera-node-2 mysqld: #011d607ef0f,0
Apr 25 22:06:09 galera-node-2 mysqld: } joined {
Apr 25 22:06:09 galera-node-2 mysqld: } left {
Apr 25 22:06:09 galera-node-2 mysqld: } partitioned {
Apr 25 22:06:09 galera-node-2 mysqld: })
Apr 25 22:06:09 galera-node-2 mysqld: 180425 22:06:09 [Note] WSREP: save pc into disk
Apr 25 22:06:10 galera-node-2 mysqld: 180425 22:06:10 [Note] WSREP: gcomm: connected
Apr 25 22:06:10 galera-node-2 mysqld: 180425 22:06:10 [Note] WSREP: Changing maximum packet size to 64500, resulting msg size: 32636
Apr 25 22:06:10 galera-node-2 mysqld: 180425 22:06:10 [Note] WSREP: Shifting CLOSED -> OPEN (TO: 0)
Apr 25 22:06:10 galera-node-2 mysqld: 180425 22:06:10 [Note] WSREP: Opened channel 'GALERACLUSTER'
Apr 25 22:06:10 galera-node-2 mysqld: 180425 22:06:10 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 0, memb_num = 3
Apr 25 22:06:10 galera-node-2 mysqld: 180425 22:06:10 [Note] WSREP: Waiting for SST to complete.
Apr 25 22:06:10 galera-node-2 mysqld: 180425 22:06:10 [Note] WSREP: STATE_EXCHANGE: sent state UUID: 18ea8d6b-48c4-11e8-8a41-0fef3fa593ed
Apr 25 22:06:10 galera-node-2 mysqld: 180425 22:06:10 [Note] WSREP: STATE EXCHANGE: sent state msg: 18ea8d6b-48c4-11e8-8a41-0fef3fa593ed
Apr 25 22:06:10 galera-node-2 mysqld: 180425 22:06:10 [Note] WSREP: STATE EXCHANGE: got state msg: 18ea8d6b-48c4-11e8-8a41-0fef3fa593ed from 0 (mysql02)
Apr 25 22:06:10 galera-node-2 mysqld: 180425 22:06:10 [Note] WSREP: STATE EXCHANGE: got state msg: 18ea8d6b-48c4-11e8-8a41-0fef3fa593ed from 1 (mysql03)
Apr 25 22:06:10 galera-node-2 mysqld: 180425 22:06:10 [Note] WSREP: STATE EXCHANGE: got state msg: 18ea8d6b-48c4-11e8-8a41-0fef3fa593ed from 2 (mysql01)
Apr 25 22:06:10 galera-node-2 mysqld: 180425 22:06:10 [Note] WSREP: Quorum results:
Apr 25 22:06:10 galera-node-2 mysqld: #011version = 4,
Apr 25 22:06:10 galera-node-2 mysqld: #011component = PRIMARY,
Apr 25 22:06:10 galera-node-2 mysqld: #011conf_id = 10,
Apr 25 22:06:10 galera-node-2 mysqld: #011members = 2/3 (joined/total),
Apr 25 22:06:10 galera-node-2 mysqld: #011act_id = 724815064,
Apr 25 22:06:10 galera-node-2 mysqld: #011last_appl. = -1,
Apr 25 22:06:10 galera-node-2 mysqld: #011protocols = 0/7/3 (gcs/repl/appl),
Apr 25 22:06:10 galera-node-2 mysqld: #011group UUID = 32c39115-8d32-11e5-9122-b6a2b3e41530
Apr 25 22:06:10 galera-node-2 mysqld: 180425 22:06:10 [Note] WSREP: Flow-control interval: [28, 28]
Apr 25 22:06:10 galera-node-2 mysqld: 180425 22:06:10 [Note] WSREP: Trying to continue unpaused monitor
Apr 25 22:06:10 galera-node-2 mysqld: 180425 22:06:10 [Note] WSREP: Shifting OPEN -> PRIMARY (TO: 724815064)
Apr 25 22:06:10 galera-node-2 mysqld: 180425 22:06:10 [Note] WSREP: State transfer required:
Apr 25 22:06:10 galera-node-2 mysqld: #011Group state: 32c39115-8d32-11e5-9122-b6a2b3e41530:724815064
Apr 25 22:06:10 galera-node-2 mysqld: #011Local state: 32c39115-8d32-11e5-9122-b6a2b3e41530:724808778
Apr 25 22:06:10 galera-node-2 mysqld: 180425 22:06:10 [Note] WSREP: New cluster view: global state: 32c39115-8d32-11e5-9122-b6a2b3e41530:724815064, view# 11: Primary, number of nodes: 3, my index: 0, protocol version 3
Apr 25 22:06:10 galera-node-2 mysqld: 180425 22:06:10 [Warning] WSREP: Gap in state sequence. Need state transfer.
Apr 25 22:06:10 galera-node-2 mysqld: 180425 22:06:10 [Note] WSREP: Running: 'wsrep_sst_xtrabackup --role 'joiner' --address '10.55.55.86' --datadir '/var/lib/mysql/' --parent '29529' --binlog '/var/log/mysql/mariadb-bin' '
Apr 25 22:06:10 galera-node-2 mysqld: /usr//bin/wsrep_sst_xtrabackup: line 397: setup_ports: command not found
Apr 25 22:06:10 galera-node-2 mysqld: 180425 22:06:10 [ERROR] WSREP: Failed to read 'ready
Apr 25 22:06:10 galera-node-2 mysqld: #011Read: '(null)'
Apr 25 22:06:10 galera-node-2 mysqld: 180425 22:06:10 [ERROR] WSREP: Process completed with error: wsrep_sst_xtrabackup --role 'joiner' --address '10.55.55.86' --datadir '/var/lib/mysql/' --parent '29529' --binlog '/var/log/mysql/mariadb-bin' : 2 (No such file or directory)
Apr 25 22:06:10 galera-node-2 mysqld: 180425 22:06:10 [ERROR] WSREP: Failed to prepare for 'xtrabackup' SST. Unrecoverable.
Apr 25 22:06:10 galera-node-2 mysqld: 180425 22:06:10 [ERROR] Aborting
Apr 25 22:06:10 galera-node-2 mysqld:
Apr 25 22:06:12 galera-node-2 mysqld: 180425 22:06:12 [Note] WSREP: Closing send monitor...
Apr 25 22:06:12 galera-node-2 mysqld: 180425 22:06:12 [Note] WSREP: Closed send monitor.
Apr 25 22:06:12 galera-node-2 mysqld: 180425 22:06:12 [Note] WSREP: gcomm: terminating thread
Apr 25 22:06:12 galera-node-2 mysqld: 180425 22:06:12 [Note] WSREP: gcomm: joining thread
Apr 25 22:06:12 galera-node-2 mysqld: 180425 22:06:12 [Note] WSREP: gcomm: closing backend
Apr 25 22:06:12 galera-node-2 mysqld: 180425 22:06:12 [Note] WSREP: view(view_id(NON_PRIM,185196d1,12) memb {
Apr 25 22:06:12 galera-node-2 mysqld: #011185196d1,0
Apr 25 22:06:12 galera-node-2 mysqld: } joined {
Apr 25 22:06:12 galera-node-2 mysqld: } left {
Apr 25 22:06:12 galera-node-2 mysqld: } partitioned {
Apr 25 22:06:12 galera-node-2 mysqld: #011acfd2d2f,0
Apr 25 22:06:12 galera-node-2 mysqld: #011d607ef0f,0
Apr 25 22:06:12 galera-node-2 mysqld: })
Apr 25 22:06:12 galera-node-2 mysqld: 180425 22:06:12 [Note] WSREP: (185196d1, 'tcp://0.0.0.0:4567') connection to peer 185196d1 with addr tcp://10.55.55.86:4567 timed out, no messages seen in PT3S
Apr 25 22:06:12 galera-node-2 mysqld: 180425 22:06:12 [Note] WSREP: (185196d1, 'tcp://0.0.0.0:4567') turning message relay requesting off
Apr 25 22:06:12 galera-node-2 mysqld: 180425 22:06:12 [Note] WSREP: view((empty))
Apr 25 22:06:12 galera-node-2 mysqld: 180425 22:06:12 [Note] WSREP: gcomm: closed
Apr 25 22:06:12 galera-node-2 mysqld: 180425 22:06:12 [Note] WSREP: New COMPONENT: primary = no, bootstrap = no, my_idx = 0, memb_num = 1
Apr 25 22:06:12 galera-node-2 mysqld: 180425 22:06:12 [Note] WSREP: Flow-control interval: [16, 16]
Apr 25 22:06:12 galera-node-2 mysqld: 180425 22:06:12 [Note] WSREP: Trying to continue unpaused monitor
Apr 25 22:06:12 galera-node-2 mysqld: 180425 22:06:12 [Note] WSREP: Received NON-PRIMARY.
Apr 25 22:06:12 galera-node-2 mysqld: 180425 22:06:12 [Note] WSREP: Shifting PRIMARY -> OPEN (TO: 724815071)
Apr 25 22:06:12 galera-node-2 mysqld: 180425 22:06:12 [Note] WSREP: Received self-leave message.
Apr 25 22:06:12 galera-node-2 mysqld: 180425 22:06:12 [Note] WSREP: Flow-control interval: [0, 0]
Apr 25 22:06:12 galera-node-2 mysqld: 180425 22:06:12 [Note] WSREP: Trying to continue unpaused monitor
Apr 25 22:06:12 galera-node-2 mysqld: 180425 22:06:12 [Note] WSREP: Received SELF-LEAVE. Closing connection.
Apr 25 22:06:12 galera-node-2 mysqld: 180425 22:06:12 [Note] WSREP: Shifting OPEN -> CLOSED (TO: 724815071)
Apr 25 22:06:12 galera-node-2 mysqld: 180425 22:06:12 [Note] WSREP: RECV thread exiting 0: Success
Apr 25 22:06:12 galera-node-2 mysqld: 180425 22:06:12 [Note] WSREP: recv_thread() joined.
Apr 25 22:06:12 galera-node-2 mysqld: 180425 22:06:12 [Note] WSREP: Closing replication queue.
Apr 25 22:06:12 galera-node-2 mysqld: 180425 22:06:12 [Note] WSREP: Closing slave action queue.
Apr 25 22:06:12 galera-node-2 mysqld: 180425 22:06:12 [Note] WSREP: Service disconnected.
Apr 25 22:06:12 galera-node-2 mysqld: 180425 22:06:12 [Note] WSREP: rollbacker thread exiting
Apr 25 22:06:13 galera-node-2 mysqld: 180425 22:06:13 [Note] WSREP: Some threads may fail to exit.
Apr 25 22:06:13 galera-node-2 mysqld: 180425 22:06:13 [Note] /usr/sbin/mysqld: Shutdown complete
Apr 25 22:06:13 galera-node-2 mysqld:
Apr 25 22:06:18 galera-node-2 mysqld: Error in my_thread_global_end(): 1 threads didn't exit
Apr 25 22:06:18 galera-node-2 mysqld_safe: mysqld from pid file /var/run/mysqld/mysqld.pid ended
After the second or third time reading through the logs, one particular line hit my eyes:
Apr 25 22:06:10 galera-node-2 mysqld: /usr//bin/wsrep_sst_xtrabackup: line 397: setup_ports: command not found
Huh? So this file has changed with the update. On a still working (and not updated yet) node:
root@galera-node-1:~# ll /usr//bin/wsrep_sst_xtrabackup
-rwxr-xr-x 1 root root 21703 Jun 1 2017 /usr//bin/wsrep_sst_xtrabackup
On the updated node 2:
root@galera-node-2:~# ll /usr//bin/wsrep_sst_xtrabackup
-rwxr-xr-x 1 root root 20658 Feb 2 08:20 /usr//bin/wsrep_sst_xtrabackup
Checking the mentioned line 397:
391 if [[ ! ${WSREP_SST_OPT_ROLE} == 'joiner' && ! ${WSREP_SST_OPT_ROLE} == 'donor' ]];then
392 wsrep_log_error "Invalid role ${WSREP_SST_OPT_ROLE}"
393 exit 22
394 fi
395
396 read_cnf
397 setup_ports
398 get_stream
399 get_transfer
400
401 INNOEXTRA=""
402 INNOAPPLY="${INNOBACKUPEX_BIN} ${WSREP_SST_OPT_CONF} --apply-log \$rebuildcmd \${DATA} &>\${DATA}/innobackup.prepare.log"
403 INNOBACKUP="${INNOBACKUPEX_BIN} ${WSREP_SST_OPT_CONF} \$INNOEXTRA --galera-info --stream=\$sfmt \${TMPDIR} 2>\${DATA}/innobackup.backup.log"
Comparing with line 397 in the old version of the script on node-1:
387 check_extra()
388 {
389 local use_socket=1
390 if [[ $uextra -eq 1 ]];then
391 if $MY_PRINT_DEFAULTS -c $WSREP_SST_OPT_CONF mysqld | tr '_' '-' | grep -- "--thread-handlin g=" | grep -q 'pool-of-threads';then
392 local eport=$($MY_PRINT_DEFAULTS -c $WSREP_SST_OPT_CONF mysqld | tr '_' '-' | grep -- "- -extra-port=" | cut -d= -f2)
393 if [[ -n $eport ]];then
394 # Xtrabackup works only locally.
395 # Hence, setting host to 127.0.0.1 unconditionally.
396 wsrep_log_info "SST through extra_port $eport"
397 INNOEXTRA+=" --host=127.0.0.1 --port=$eport "
398 use_socket=0
399 else
400 wsrep_log_error "Extra port $eport null, failing"
401 exit 1
402 fi
403 else
404 wsrep_log_info "Thread pool not set, ignore the option use_extra"
405 fi
406 fi
407 if [[ $use_socket -eq 1 ]] && [[ -n "${WSREP_SST_OPT_SOCKET}" ]];then
408 INNOEXTRA+=" --socket=${WSREP_SST_OPT_SOCKET}"
409 fi
410 }
Erm yes, that's obviously quite a big difference. Also the sizes of the two scripts (see above) differ.
By replacing the new version of the script with the old script, the node was able to join the cluster again after another MariaDB start:
root@galera-node-2:~# service mysql start
root@galera-node-2:~# tail -f /var/log/syslog
Apr 25 22:14:07 galera-node-2 mysqld_safe: WSREP: Recovered position 32c39115-8d32-11e5-9122-b6a2b3e41530:724808778
Apr 25 22:14:07 galera-node-2 mysqld: 180425 22:14:07 [Note] /usr/sbin/mysqld (mysqld 10.0.34-MariaDB-1~trusty-wsrep) starting as process 30772 ...
Apr 25 22:14:07 galera-node-2 mysqld: 180425 22:14:07 [Note] WSREP: Read nil XID from storage engines, skipping position init
Apr 25 22:14:07 galera-node-2 mysqld: 180425 22:14:07 [Note] WSREP: wsrep_load(): loading provider library '/usr/lib/galera/libgalera_smm.so'
Apr 25 22:14:07 galera-node-2 mysqld: 180425 22:14:07 [Note] WSREP: wsrep_load(): Galera 25.3.22(r3764) by Codership Oy
Apr 25 22:14:07 galera-node-2 mysqld: 180425 22:14:07 [Note] WSREP: CRC-32C: using hardware acceleration.
Apr 25 22:14:07 galera-node-2 mysqld: 180425 22:14:07 [Note] WSREP: Found saved state: 32c39115-8d32-11e5-9122-b6a2b3e41530:-1, safe_to_bootstrap: 0
Apr 25 22:14:07 galera-node-2 mysqld: 180425 22:14:07 [Note] WSREP: Passing config to GCS: base_dir = /var/lib/mysql/; base_host = 10.55.55.86; base_port = 4567; cert.log_conflicts = no; 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.mem_size = 0; gcache.name = /var/lib/mysql//galera.cache; gcache.page_size = 128M; gcache.recover = no; 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.sync_donor = no; gmcast.segment = 0; gmcast.version = 0; pc.announce_timeout = PT3S;
Apr 25 22:14:07 galera-node-2 mysqld: pc.checksum = false; pc
Apr 25 22:14:07 galera-node-2 mysqld: 180425 22:14:07 [Note] WSREP: GCache history reset: 32c39115-8d32-11e5-9122-b6a2b3e41530:0 -> 32c39115-8d32-11e5-9122-b6a2b3e41530:724808778
Apr 25 22:14:07 galera-node-2 mysqld: 180425 22:14:07 [Note] WSREP: Assign initial position for certification: 724808778, protocol version: -1
Apr 25 22:14:07 galera-node-2 mysqld: 180425 22:14:07 [Note] WSREP: wsrep_sst_grab()
Apr 25 22:14:07 galera-node-2 mysqld: 180425 22:14:07 [Note] WSREP: Start replication
Apr 25 22:14:07 galera-node-2 mysqld: 180425 22:14:07 [Note] WSREP: Setting initial position to 32c39115-8d32-11e5-9122-b6a2b3e41530:724808778
Apr 25 22:14:07 galera-node-2 mysqld: 180425 22:14:07 [Note] WSREP: protonet asio version 0
Apr 25 22:14:07 galera-node-2 mysqld: 180425 22:14:07 [Note] WSREP: Using CRC-32C for message checksums.
Apr 25 22:14:07 galera-node-2 mysqld: 180425 22:14:07 [Note] WSREP: backend: asio
Apr 25 22:14:07 galera-node-2 mysqld: 180425 22:14:07 [Note] WSREP: gcomm thread scheduling priority set to other:0
Apr 25 22:14:07 galera-node-2 mysqld: 180425 22:14:07 [Warning] WSREP: access file(/var/lib/mysql//gvwstate.dat) failed(No such file or directory)
Apr 25 22:14:07 galera-node-2 mysqld: 180425 22:14:07 [Note] WSREP: restore pc from disk failed
Apr 25 22:14:07 galera-node-2 mysqld: 180425 22:14:07 [Note] WSREP: GMCast version 0
Apr 25 22:14:07 galera-node-2 mysqld: 180425 22:14:07 [Note] WSREP: (3599655f, 'tcp://0.0.0.0:4567') listening at tcp://0.0.0.0:4567
Apr 25 22:14:07 galera-node-2 mysqld: 180425 22:14:07 [Note] WSREP: (3599655f, 'tcp://0.0.0.0:4567') multicast: , ttl: 1
Apr 25 22:14:07 galera-node-2 mysqld: 180425 22:14:07 [Note] WSREP: EVS version 0
Apr 25 22:14:07 galera-node-2 mysqld: 180425 22:14:07 [Note] WSREP: gcomm: connecting to group 'GALERACLUSTER', peer '10.55.55.85:,10.55.55.86:,10.55.55.87:'
Apr 25 22:14:07 galera-node-2 mysqld: 180425 22:14:07 [Note] WSREP: (3599655f, 'tcp://0.0.0.0:4567') connection established to 3599655f tcp://10.55.55.86:4567
Apr 25 22:14:07 galera-node-2 mysqld: 180425 22:14:07 [Warning] WSREP: (3599655f, 'tcp://0.0.0.0:4567') address 'tcp://10.55.55.86:4567' points to own listening address, blacklisting
Apr 25 22:14:07 galera-node-2 mysqld: 180425 22:14:07 [Note] WSREP: (3599655f, 'tcp://0.0.0.0:4567') connection established to acfd2d2f tcp://10.55.55.87:4567
Apr 25 22:14:07 galera-node-2 mysqld: 180425 22:14:07 [Note] WSREP: (3599655f, 'tcp://0.0.0.0:4567') turning message relay requesting on, nonlive peers:
Apr 25 22:14:07 galera-node-2 mysqld: 180425 22:14:07 [Note] WSREP: (3599655f, 'tcp://0.0.0.0:4567') connection established to d607ef0f tcp://10.55.55.85:4567
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] WSREP: declaring acfd2d2f at tcp://10.55.55.87:4567 stable
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] WSREP: declaring d607ef0f at tcp://10.55.55.85:4567 stable
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] WSREP: Node acfd2d2f state prim
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] WSREP: view(view_id(PRIM,3599655f,14) memb {
Apr 25 22:14:08 galera-node-2 mysqld: #0113599655f,0
Apr 25 22:14:08 galera-node-2 mysqld: #011acfd2d2f,0
Apr 25 22:14:08 galera-node-2 mysqld: #011d607ef0f,0
Apr 25 22:14:08 galera-node-2 mysqld: } joined {
Apr 25 22:14:08 galera-node-2 mysqld: } left {
Apr 25 22:14:08 galera-node-2 mysqld: } partitioned {
Apr 25 22:14:08 galera-node-2 mysqld: })
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] WSREP: save pc into disk
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] WSREP: gcomm: connected
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] WSREP: Changing maximum packet size to 64500, resulting msg size: 32636
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] WSREP: Shifting CLOSED -> OPEN (TO: 0)
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] WSREP: Opened channel 'GALERACLUSTER'
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 0, memb_num = 3
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] WSREP: Waiting for SST to complete.
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] WSREP: STATE_EXCHANGE: sent state UUID: 35e60dd7-48c5-11e8-ab36-b74cbcd15212
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] WSREP: STATE EXCHANGE: sent state msg: 35e60dd7-48c5-11e8-ab36-b74cbcd15212
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] WSREP: STATE EXCHANGE: got state msg: 35e60dd7-48c5-11e8-ab36-b74cbcd15212 from 0 (mysql02)
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] WSREP: STATE EXCHANGE: got state msg: 35e60dd7-48c5-11e8-ab36-b74cbcd15212 from 1 (mysql03)
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] WSREP: STATE EXCHANGE: got state msg: 35e60dd7-48c5-11e8-ab36-b74cbcd15212 from 2 (mysql01)
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] WSREP: Quorum results:
Apr 25 22:14:08 galera-node-2 mysqld: #011version = 4,
Apr 25 22:14:08 galera-node-2 mysqld: #011component = PRIMARY,
Apr 25 22:14:08 galera-node-2 mysqld: #011conf_id = 12,
Apr 25 22:14:08 galera-node-2 mysqld: #011members = 2/3 (joined/total),
Apr 25 22:14:08 galera-node-2 mysqld: #011act_id = 724818998,
Apr 25 22:14:08 galera-node-2 mysqld: #011last_appl. = -1,
Apr 25 22:14:08 galera-node-2 mysqld: #011protocols = 0/7/3 (gcs/repl/appl),
Apr 25 22:14:08 galera-node-2 mysqld: #011group UUID = 32c39115-8d32-11e5-9122-b6a2b3e41530
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] WSREP: Flow-control interval: [28, 28]
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] WSREP: Trying to continue unpaused monitor
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] WSREP: Shifting OPEN -> PRIMARY (TO: 724818998)
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] WSREP: State transfer required:
Apr 25 22:14:08 galera-node-2 mysqld: #011Group state: 32c39115-8d32-11e5-9122-b6a2b3e41530:724818998
Apr 25 22:14:08 galera-node-2 mysqld: #011Local state: 32c39115-8d32-11e5-9122-b6a2b3e41530:724808778
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] WSREP: New cluster view: global state: 32c39115-8d32-11e5-9122-b6a2b3e41530:724818998, view# 13: Primary, number of nodes: 3, my index: 0, protocol version 3
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Warning] WSREP: Gap in state sequence. Need state transfer.
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] WSREP: Running: 'wsrep_sst_xtrabackup --role 'joiner' --address '10.55.55.86' --datadir '/var/lib/mysql/' --parent '30772' --binlog '/var/log/mysql/mariadb-bin' '
Apr 25 22:14:08 galera-node-2 mysqld: WSREP_SST: [INFO] Streaming with tar (20180425 22:14:08.550)
Apr 25 22:14:08 galera-node-2 mysqld: WSREP_SST: [INFO] Using socat as streamer (20180425 22:14:08.552)
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] WSREP: Prepared SST request: xtrabackup|10.55.55.86:4444/xtrabackup_sst
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] WSREP: REPL Protocols: 7 (3, 2)
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] WSREP: Assign initial position for certification: 724818998, protocol version: 3
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] WSREP: Service thread queue flushed.
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] WSREP: IST receiver addr using tcp://10.55.55.86:4568
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] WSREP: Prepared IST receiver, listening at: tcp://10.55.55.86:4568
Apr 25 22:14:08 galera-node-2 mysqld: WSREP_SST: [INFO] Evaluating socat -u TCP-LISTEN:4444,reuseaddr stdio | tar xfi - --recursive-unlink -h; RC=( ${PIPESTATUS[@]} ) (20180425 22:14:08.561)
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] WSREP: Member 0.0 (mysql02) requested state transfer from '*any*'. Selected 2.0 (mysql01)(SYNCED) as donor.
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] WSREP: Shifting PRIMARY -> JOINER (TO: 724818998)
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] WSREP: Requesting state transfer: success, donor: 2
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] WSREP: GCache history reset: 32c39115-8d32-11e5-9122-b6a2b3e41530:0 -> 32c39115-8d32-11e5-9122-b6a2b3e41530:724818998
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] WSREP: 2.0 (mysql01): State transfer to 0.0 (mysql02) complete.
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] WSREP: Member 2.0 (mysql01) synced with group.
Apr 25 22:14:08 galera-node-2 mysqld: WSREP_SST: [INFO] xtrabackup_ist received from donor: Running IST (20180425 22:14:08.676)
Apr 25 22:14:08 galera-node-2 mysqld: WSREP_SST: [INFO] Total time on joiner: 0 seconds (20180425 22:14:08.678)
Apr 25 22:14:08 galera-node-2 mysqld: WSREP_SST: [INFO] Removing the sst_in_progress file (20180425 22:14:08.680)
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] WSREP: SST complete, seqno: 724808778
Apr 25 22:14:08 galera-node-2 mysqld: 2018-04-25 22:14:08 7f623bbb97c0 InnoDB: Warning: Using innodb_locks_unsafe_for_binlog is DEPRECATED. This option may be removed in future releases. Please use READ COMMITTED transaction isolation level instead, see http://dev.mysql.com/doc/refman/5.6/en/set-transaction.html.
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] InnoDB: Using mutexes to ref count buffer pool pages
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] InnoDB: The InnoDB memory heap is disabled
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] InnoDB: Compressed tables use zlib 1.2.8
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] InnoDB: Using Linux native AIO
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] InnoDB: Using CPU crc32 instructions
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] InnoDB: Initializing buffer pool, size = 2.0G
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] InnoDB: Completed initialization of buffer pool
Apr 25 22:14:08 galera-node-2 mysqld: 180425 22:14:08 [Note] InnoDB: Highest supported file format is Barracuda.
Apr 25 22:14:09 galera-node-2 mysqld: 180425 22:14:09 [Note] InnoDB: 128 rollback segment(s) are active.
Apr 25 22:14:09 galera-node-2 mysqld: 180425 22:14:09 [Note] InnoDB: Waiting for purge to start
Apr 25 22:14:09 galera-node-2 mysqld: 180425 22:14:09 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.36-83.0 started; log sequence number 1013752338227
Apr 25 22:14:09 galera-node-2 mysqld: 180425 22:14:09 [Note] Plugin 'FEEDBACK' is disabled.
Apr 25 22:14:09 galera-node-2 mysqld: 180425 22:14:09 [Note] Server socket created on IP: '0.0.0.0'.
Apr 25 22:14:09 galera-node-2 mysqld: 180425 22:14:09 [Note] WSREP: Signalling provider to continue.
Apr 25 22:14:09 galera-node-2 mysqld: 180425 22:14:09 [Note] WSREP: SST received: 32c39115-8d32-11e5-9122-b6a2b3e41530:724808778
Apr 25 22:14:09 galera-node-2 mysqld: 180425 22:14:09 [Note] WSREP: Receiving IST: 10220 writesets, seqnos 724808778-724818998
Apr 25 22:14:09 galera-node-2 mysqld: 180425 22:14:09 [Note] WSREP: Receiving IST... 0.0% ( 0/10220 events) complete.
Apr 25 22:14:09 galera-node-2 mysqld: 180425 22:14:09 [Note] Reading of all Master_info entries succeded
Apr 25 22:14:09 galera-node-2 mysqld: 180425 22:14:09 [Note] Added new Master_info '' to hash table
Apr 25 22:14:09 galera-node-2 mysqld: 180425 22:14:09 [Note] /usr/sbin/mysqld: ready for connections.
Apr 25 22:14:09 galera-node-2 mysqld: Version: '10.0.34-MariaDB-1~trusty-wsrep' socket: '/var/run/mysqld/mysqld.sock' port: 3306 mariadb.org binary distribution, wsrep_25.21.rc3fc46e
Apr 25 22:14:11 galera-node-2 mysqld: 180425 22:14:11 [Note] WSREP: (3599655f, 'tcp://0.0.0.0:4567') connection to peer 3599655f with addr tcp://10.55.55.86:4567 timed out, no messages seen in PT3S
Apr 25 22:14:11 galera-node-2 mysqld: 180425 22:14:11 [Note] WSREP: (3599655f, 'tcp://0.0.0.0:4567') turning message relay requesting off
Apr 25 22:14:19 galera-node-2 mysqld: 180425 22:14:19 [Note] WSREP: Receiving IST... 60.0% ( 6128/10220 events) complete.
Apr 25 22:14:26 galera-node-2 mysqld: 180425 22:14:26 [Note] WSREP: Receiving IST...100.0% (10220/10220 events) complete.
Apr 25 22:14:26 galera-node-2 mysqld: 180425 22:14:26 [Note] WSREP: IST received: 32c39115-8d32-11e5-9122-b6a2b3e41530:724818998
Apr 25 22:14:26 galera-node-2 mysqld: 180425 22:14:26 [Note] WSREP: 0.0 (mysql02): State transfer from 2.0 (mysql01) complete.
Apr 25 22:14:26 galera-node-2 mysqld: 180425 22:14:26 [Note] WSREP: Shifting JOINER -> JOINED (TO: 724819126)
Apr 25 22:14:26 galera-node-2 mysqld: 180425 22:14:26 [Note] WSREP: Member 0.0 (mysql02) synced with group.
Apr 25 22:14:26 galera-node-2 mysqld: 180425 22:14:26 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 724819126)
Apr 25 22:14:26 galera-node-2 mysqld: 180425 22:14:26 [Note] WSREP: Synchronized with group, ready for connections
Apr 25 22:14:26 galera-node-2 mysqld: 180425 22:14:26 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
There seems to be a bug already opened for this issue (https://jira.mariadb.org/browse/MDEV-15254?attachmentViewMode=list) but this is about MariaDB 10.1.x and not 10.0.x as in my case on Ubuntu 14.04 so I opened https://jira.mariadb.org/browse/MDEV-16032.
Update August 30th 2018:
The bug was fixed in MariaDB 10.0.36.
Problems in Galera Clusters are not always easy to spot. Need help troubleshooting a Galera cluster? Contact us on Infiniroot.com.
No comments yet.
AWS Android Ansible Apache Apple Atlassian BSD Backup Bash Bluecoat CMS Chef Cloud Coding Consul Containers CouchDB DB DNS Database Databases Docker ELK Elasticsearch Filebeat FreeBSD Galera Git GlusterFS Grafana Graphics HAProxy HTML Hacks Hardware Icinga Influx Internet Java KVM Kibana Kodi Kubernetes LVM LXC Linux Logstash Mac Macintosh Mail MariaDB Minio MongoDB Monitoring Multimedia MySQL NFS Nagios Network Nginx OSSEC OTRS Office OpenSearch PGSQL PHP Perl Personal PostgreSQL Postgres PowerDNS Proxmox Proxy Python Rancher Rant Redis Roundcube SSL Samba Seafile Security Shell SmartOS Solaris Surveillance Systemd TLS Tomcat Ubuntu Unix VMWare VMware Varnish Virtualization Windows Wireless Wordpress Wyse ZFS Zoneminder