Node 2 mysql log (node 3 is off atm)
2022-10-13T15:48:28.911098Z 0 [Note] [MY-000000] [WSREP-SST] Streaming the backup to joiner at 10.10.10.95 4444
2022-10-13T15:48:28.962277Z 3339 [Warning] [MY-013712] [Server] No suitable 'keyring_component_metadata_query' service implementation found to fulfill the request.
2022-10-13T15:48:29.080958Z 0 [ERROR] [MY-000000] [WSREP-SST] ******************* FATAL ERROR **********************
2022-10-13T15:48:29.081030Z 0 [ERROR] [MY-000000] [WSREP-SST] xtrabackup finished with error: 1. Check /var/lib/mysql//innobackup.backup.log
2022-10-13T15:48:29.081056Z 0 [ERROR] [MY-000000] [WSREP-SST] Line 1966
2022-10-13T15:48:29.082565Z 0 [ERROR] [MY-000000] [WSREP-SST] ------------ innobackup.backup.log (START) ------------
2022-10-13T16:48:28.933371+01:00 0 [Note] [MY-011825] [Xtrabackup] recognized server arguments: --server-id=96 --datadir=/var/lib/mysql --open_files_limit=65535 --innodb_buffer_pool_size=5G --innodb_
log_file_size=512M --innodb_flush_method=O_DIRECT --log_bin=ON --defaults_group=mysqld
2022-10-13T16:48:28.933666+01:00 0 [Note] [MY-011825] [Xtrabackup] recognized client arguments: --ssl-ca=/etc/mysql/certs/ca.pem --ssl-cert=/etc/mysql/certs/client-cert.pem --ssl-key=/etc/mysql/certs
/client-key.pem --no-version-check=1 --parallel=4 --user=mysql.pxc.sst.user --password=* --socket=/var/lib/mysql/mysql.sock --lock-ddl=1 --backup=1 --galera-info=1 --stream=xbstream --xtrabackup-plugin-dir=/
usr/bin/pxc_extra/pxb-8.0/lib/plugin --target-dir=/tmp/pxc_sst_Wp3P/donor_xb_WprR
/usr/bin/pxc_extra/pxb-8.0/bin/xtrabackup version 8.0.29-22 based on MySQL server 8.0.29 Linux (x86_64) (revision id: c31e7ddcce3)
2022-10-13T16:48:28.933710+01:00 0 [Note] [MY-011825] [Xtrabackup] Connecting to MySQL server host: localhost, user: mysql.pxc.sst.user, password: set, port: not set, socket: /var/lib/mysql/mysql.soc
k
2022-10-13T16:48:28.954829+01:00 0 [Note] [MY-011825] [Xtrabackup] Using server version 8.0.29-21.1
2022-10-13T16:48:28.958720+01:00 0 [Note] [MY-011825] [Xtrabackup] Executing LOCK TABLES FOR BACKUP ...
2022-10-13T16:48:28.961032+01:00 0 [Note] [MY-011825] [Xtrabackup] uses posix_fadvise().
2022-10-13T16:48:28.961077+01:00 0 [Note] [MY-011825] [Xtrabackup] cd to /var/lib/mysql
2022-10-13T16:48:28.961102+01:00 0 [Note] [MY-011825] [Xtrabackup] open files limit requested 65535, set to 16364
2022-10-13T16:48:28.961164+01:00 0 [Note] [MY-011825] [Xtrabackup] using the following InnoDB configuration:
2022-10-13T16:48:28.961179+01:00 0 [Note] [MY-011825] [Xtrabackup] innodb_data_home_dir = .
2022-10-13T16:48:28.961189+01:00 0 [Note] [MY-011825] [Xtrabackup] innodb_data_file_path = ibdata1:12M:autoextend
2022-10-13T16:48:28.961238+01:00 0 [Note] [MY-011825] [Xtrabackup] innodb_log_group_home_dir = ./
2022-10-13T16:48:28.961250+01:00 0 [Note] [MY-011825] [Xtrabackup] innodb_log_files_in_group = 2
2022-10-13T16:48:28.961265+01:00 0 [Note] [MY-011825] [Xtrabackup] innodb_log_file_size = 536870912
2022-10-13T16:48:28.961289+01:00 0 [Note] [MY-011825] [Xtrabackup] using O_DIRECT
2022-10-13T16:48:28.962028+01:00 0 [Note] [MY-013251] [InnoDB] Number of pools: 1
2022-10-13T16:48:28.962980+01:00 0 [Note] [MY-011825] [Xtrabackup] inititialize_service_handles suceeded
2022-10-13T16:48:29.070302+01:00 0 [ERROR] [MY-011825] [Xtrabackup] log file ./ib_logfile0 is of different size 4194304 bytes than specified in the .cnf file 536870912 bytes!
2022-10-13T15:48:29.082648Z 0 [ERROR] [MY-000000] [WSREP-SST] ------------ innobackup.backup.log (END) ------------
2022-10-13T15:48:29.082673Z 0 [ERROR] [MY-000000] [WSREP-SST] ******************************************************
2022-10-13T15:48:29.082690Z 0 [ERROR] [MY-000000] [WSREP-SST] Cleanup after exit with status:22
2022-10-13T15:48:29.107976Z 0 [ERROR] [MY-000000] [WSREP] Process completed with error: wsrep_sst_xtrabackup-v2 --role 'donor' --address '10.10.10.95:4444/xtrabackup_sst//1' --socket '/var/lib/mysql/mysql.so
ck' --datadir '/var/lib/mysql/' --basedir '/usr/' --defaults-file '/etc/my.cnf' --defaults-group-suffix '' --mysqld-version '8.0.29-21.1' '' --gtid '4ab2da3b-3cc2-11ed-b34d-7aa6ac77c226:218756' : 22 (Inval
id argument)
2022-10-13T15:48:29.115812Z 0 [Note] [MY-000000] [Galera] SST sending failed: -22
2022-10-13T15:48:29.115937Z 0 [Note] [MY-000000] [WSREP] Server status change donor -> joined
2022-10-13T15:48:29.115994Z 0 [Note] [MY-000000] [WSREP] wsrep_notify_cmd is not defined, skipping notification.
2022-10-13T15:48:29.116125Z 0 [ERROR] [MY-000000] [WSREP] Command did not run: wsrep_sst_xtrabackup-v2 --role 'donor' --address '10.10.10.95:4444/xtrabackup_sst//1' --socket '/var/lib/mysql/mysql.sock' --dat
adir '/var/lib/mysql/' --basedir '/usr/' --defaults-file '/etc/my.cnf' --defaults-group-suffix '' --mysqld-version '8.0.29-21.1' '' --gtid '4ab2da3b-3cc2-11ed-b34d-7aa6ac77c226:218756'
2022-10-13T15:48:29.116978Z 0 [Warning] [MY-000000] [Galera] 1.0 (dev-pxc-cluster-node-2): State transfer to 0.0 (dev-pxc-cluster-node-1) failed: -22 (Invalid argument)
2022-10-13T15:48:29.117057Z 0 [Note] [MY-000000] [Galera] Shifting DONOR/DESYNCED -> JOINED (TO: 218756)
2022-10-13T15:48:29.117233Z 0 [Note] [MY-000000] [Galera] Processing event queue:... -nan% (0/0 events) complete.
2022-10-13T15:48:30.117987Z 0 [Note] [MY-000000] [Galera] Deferred close timer started for socket with remote endpoint: ssl://10.10.10.95:60206
2022-10-13T15:48:30.118005Z 0 [Note] [MY-000000] [Galera] Member 1.0 (dev-pxc-cluster-node-2) synced with group.
2022-10-13T15:48:30.118095Z 0 [Note] [MY-000000] [Galera] forgetting 73a53376-aaee (ssl://10.10.10.95:4567)
2022-10-13T15:48:30.118169Z 0 [Note] [MY-000000] [Galera] Processing event queue:...100.0% (1/1 events) complete.
2022-10-13T15:48:30.118207Z 0 [Note] [MY-000000] [Galera] Shifting JOINED -> SYNCED (TO: 218756)
2022-10-13T15:48:30.118265Z 13 [Note] [MY-000000] [Galera] Server dev-pxc-cluster-node-2 synced with group
2022-10-13T15:48:30.118298Z 13 [Note] [MY-000000] [WSREP] Server status change joined -> synced
2022-10-13T15:48:30.118318Z 13 [Note] [MY-000000] [WSREP] Synchronized with group, ready for connections
2022-10-13T15:48:30.118336Z 13 [Note] [MY-000000] [WSREP] wsrep_notify_cmd is not defined, skipping notification.
2022-10-13T15:48:30.118206Z 0 [Note] [MY-000000] [Galera] Node e620af4c-93b0 state primary
2022-10-13T15:48:30.118436Z 0 [Note] [MY-000000] [Galera] Current view of cluster as seen by this node
view (view_id(PRIM,e620af4c-93b0,32)
memb {
e620af4c-93b0,0
}
joined {
}
left {
}
partitioned {
73a53376-aaee,0
}
)
2022-10-13T15:48:30.118471Z 0 [Note] [MY-000000] [Galera] Save the discovered primary-component to disk
2022-10-13T15:48:30.121014Z 0 [Note] [MY-000000] [Galera] forgetting 73a53376-aaee (ssl://10.10.10.95:4567)
2022-10-13T15:48:30.121063Z 0 [Note] [MY-000000] [Galera] New COMPONENT: primary = yes, bootstrap = no, my_idx = 0, memb_num = 1
2022-10-13T15:48:30.121530Z 0 [Note] [MY-000000] [Galera] STATE_EXCHANGE: sent state UUID: 7c0d1634-4b0e-11ed-9a05-135f365469e8
2022-10-13T15:48:30.121648Z 0 [Note] [MY-000000] [Galera] Deferred close timer handle_wait Operation aborted. for 0x7f4f3002ce80
2022-10-13T15:48:30.121672Z 0 [Note] [MY-000000] [Galera] STATE EXCHANGE: sent state msg: 7c0d1634-4b0e-11ed-9a05-135f365469e8
2022-10-13T15:48:30.121700Z 0 [Note] [MY-000000] [Galera] Deferred close timer destruct
2022-10-13T15:48:30.121823Z 0 [Note] [MY-000000] [Galera] STATE EXCHANGE: got state msg: 7c0d1634-4b0e-11ed-9a05-135f365469e8 from 0 (dev-pxc-cluster-node-2)
2022-10-13T15:48:30.121886Z 0 [Note] [MY-000000] [Galera] Quorum results:
version = 6,
component = PRIMARY,
conf_id = 30,
members = 1/1 (primary/total),
act_id = 218756,
last_appl. = 218706,
protocols = 2/10/4 (gcs/repl/appl),
vote policy= 0,
group UUID = 4ab2da3b-3cc2-11ed-b34d-7aa6ac77c226
2022-10-13T15:48:30.121983Z 0 [Note] [MY-000000] [Galera] Flow-control interval: [100, 100]
2022-10-13T15:48:30.122170Z 16 [Note] [MY-000000] [Galera] ####### processing CC 218757, local, ordered
2022-10-13T15:48:30.122210Z 16 [Note] [MY-000000] [Galera] Maybe drain monitors from 218756 upto current CC event 218757 upto:218756
2022-10-13T15:48:30.122236Z 16 [Note] [MY-000000] [Galera] Drain monitors from 218756 up to 218756
2022-10-13T15:48:30.122269Z 16 [Note] [MY-000000] [Galera] ####### My UUID: e620af4c-4aef-11ed-93b0-bb059439be2b
2022-10-13T15:48:30.122294Z 16 [Note] [MY-000000] [Galera] Skipping cert index reset
2022-10-13T15:48:30.122317Z 16 [Note] [MY-000000] [Galera] REPL Protocols: 10 (5)
2022-10-13T15:48:30.122340Z 16 [Note] [MY-000000] [Galera] ####### Adjusting cert position: 218756 -> 218757
2022-10-13T15:48:30.122430Z 0 [Note] [MY-000000] [Galera] Service thread queue flushed.
2022-10-13T15:48:30.124838Z 16 [Note] [MY-000000] [Galera] ================================================
View:
id: 4ab2da3b-3cc2-11ed-b34d-7aa6ac77c226:218757
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: 0
members(1):
0: e620af4c-4aef-11ed-93b0-bb059439be2b, dev-pxc-cluster-node-2
=================================================
2022-10-13T15:48:30.124918Z 16 [Note] [MY-000000] [WSREP] wsrep_notify_cmd is not defined, skipping notification.
2022-10-13T15:48:30.129539Z 16 [Note] [MY-000000] [Galera] Recording CC from group: 218757
2022-10-13T15:48:30.129613Z 16 [Note] [MY-000000] [Galera] Lowest cert index boundary for CC from group: 218717
2022-10-13T15:48:30.129642Z 16 [Note] [MY-000000] [Galera] Min available from gcache for CC from group: 210374
2022-10-13T15:48:30.135672Z 0 [Note] [MY-000000] [Galera] async IST sender served
2022-10-13T15:48:35.552177Z 0 [Note] [MY-000000] [Galera] cleaning up 73a53376-aaee (ssl://10.10.10.95:4567)
Node 2 innodb backup log
2022-10-13T16:48:28.933371+01:00 0 [Note] [MY-011825] [Xtrabackup] recognized server arguments: --server-id=96 --datadir=/var/lib/mysql --open_files_limit=65535 --innodb_buffer_pool_size=5G --innodb_log_file_size=512M --innodb_flush_method=O_DIRECT --log_bin=ON --defaults_group=mysqld
2022-10-13T16:48:28.933666+01:00 0 [Note] [MY-011825] [Xtrabackup] recognized client arguments: --ssl-ca=/etc/mysql/certs/ca.pem --ssl-cert=/etc/mysql/certs/client-cert.pem --ssl-key=/etc/mysql/certs/client-key.pem --no-version-check=1 --parallel=4 --user=mysql.pxc.sst.user --password=* --socket=/var/lib/mysql/mysql.sock --lock-ddl=1 --backup=1 --galera-info=1 --stream=xbstream --xtrabackup-plugin-dir=/usr/bin/pxc_extra/pxb-8.0/lib/plugin --target-dir=/tmp/pxc_sst_Wp3P/donor_xb_WprR
/usr/bin/pxc_extra/pxb-8.0/bin/xtrabackup version 8.0.29-22 based on MySQL server 8.0.29 Linux (x86_64) (revision id: c31e7ddcce3)
2022-10-13T16:48:28.933710+01:00 0 [Note] [MY-011825] [Xtrabackup] Connecting to MySQL server host: localhost, user: mysql.pxc.sst.user, password: set, port: not set, socket: /var/lib/mysql/mysql.sock
2022-10-13T16:48:28.954829+01:00 0 [Note] [MY-011825] [Xtrabackup] Using server version 8.0.29-21.1
2022-10-13T16:48:28.958720+01:00 0 [Note] [MY-011825] [Xtrabackup] Executing LOCK TABLES FOR BACKUP ...
2022-10-13T16:48:28.961032+01:00 0 [Note] [MY-011825] [Xtrabackup] uses posix_fadvise().
2022-10-13T16:48:28.961077+01:00 0 [Note] [MY-011825] [Xtrabackup] cd to /var/lib/mysql
2022-10-13T16:48:28.961102+01:00 0 [Note] [MY-011825] [Xtrabackup] open files limit requested 65535, set to 16364
2022-10-13T16:48:28.961164+01:00 0 [Note] [MY-011825] [Xtrabackup] using the following InnoDB configuration:
2022-10-13T16:48:28.961179+01:00 0 [Note] [MY-011825] [Xtrabackup] innodb_data_home_dir = .
2022-10-13T16:48:28.961189+01:00 0 [Note] [MY-011825] [Xtrabackup] innodb_data_file_path = ibdata1:12M:autoextend
2022-10-13T16:48:28.961238+01:00 0 [Note] [MY-011825] [Xtrabackup] innodb_log_group_home_dir = ./
2022-10-13T16:48:28.961250+01:00 0 [Note] [MY-011825] [Xtrabackup] innodb_log_files_in_group = 2
2022-10-13T16:48:28.961265+01:00 0 [Note] [MY-011825] [Xtrabackup] innodb_log_file_size = 536870912
2022-10-13T16:48:28.961289+01:00 0 [Note] [MY-011825] [Xtrabackup] using O_DIRECT
2022-10-13T16:48:28.962028+01:00 0 [Note] [MY-013251] [InnoDB] Number of pools: 1
2022-10-13T16:48:28.962980+01:00 0 [Note] [MY-011825] [Xtrabackup] inititialize_service_handles suceeded
2022-10-13T16:48:29.070302+01:00 0 [ERROR] [MY-011825] [Xtrabackup] log file ./ib_logfile0 is of different size 4194304 bytes than specified in the .cnf file 536870912 bytes!
my.cnf file
[client]
#socket=/var/lib/mysql/mysql.sock
protocol=TCP
# SSL certificates
ssl_ca=/etc/mysql/certs/ca.pem
ssl_cert=/etc/mysql/certs/client-cert.pem
ssl_key=/etc/mysql/certs/client-key.pem
[mysqld]
server_id=95
datadir=/var/lib/mysql
#tmpdir=/mnt/disk2/tmp
socket=/var/lib/mysql/mysql.sock
log_error=/var/log/mysqld.log
pid_file=/var/run/mysqld/mysqld.pid
######## wsrep ###############
# Path to Galera library
wsrep_provider=/usr/lib64/galera4/libgalera_smm.so
# Cluster connection URL contains IPs of nodes
#If no IP is found, this implies that a new cluster needs to be created,
#in order to do that you need to bootstrap this node
#wsrep_cluster_address=gcomm://
#wsrep_cluster_address=gcomm://192.168.164.95,192.168.164.96,192.168.164.97
#wsrep_cluster_address=gcomm://192.168.164.95,192.168.164.96,10.168.164.97
#wsrep_cluster_address=gcomm://10.2.2.95,10.2.2.96,10.168.164.97
wsrep_cluster_address=gcomm://10.10.10.95,10.10.10.96,10.168.164.97
# In order for Galera to work correctly binlog format should be ROW
binlog_format=ROW
# Slave threads to use - start with four slave threads per CPU core
#wsrep_slave_threads=8
wsrep_applier_threads=8
# Log additional information about node conflicts
wsrep_log_conflicts=ON
# This changes how InnoDB autoincrement locks are managed and is a requirement for Galera
innodb_autoinc_lock_mode=2
# Node IP address
#wsrep_node_address=192.168.164.95
#wsrep_node_address=10.2.2.95
wsrep_node_address=10.10.10.95
# Cluster name
wsrep_cluster_name=dev-pxc-cluster
#If wsrep_node_name is not specified, then system hostname will be used
wsrep_node_name=dev-pxc-cluster-node-1
#pxc_strict_mode allowed values: DISABLED,PERMISSIVE,ENFORCING,MASTER
pxc_strict_mode=ENFORCING
# SSL certificates for pxc_encrypt_cluster_traffic
ssl_ca=/etc/mysql/certs/ca.pem
ssl_cert=/etc/mysql/certs/server-cert.pem
ssl_key=/etc/mysql/certs/server-key.pem
pxc_encrypt_cluster_traffic=ON
# SST method
wsrep_sst_method=xtrabackup-v2
#wsrep_sst_method=rsync
#wsrep_sst_method=skip
# Increasing the cache size inceases the chance of IST rather than SST
wsrep_provider_options="gcache.size=5G"
# This is best placed on a fast IO disk rather than in the /var/lib/mysql directory
#wsrep_provider_options="gcache.dir=/mnt/disk3/cache"
# Bind all network cards
bind_address=0.0.0.0
# Event scheduler
event_scheduler=ON
# Necessary for Percona
default_storage_engine=InnoDB
# Security issue
symbolic_links=0
# All tables names are lower case
lower_case_table_names=1
# Default SQl mode
#sql_mode=""
#sql_mode="ONLY_FULL_GROUP_BY,STRICT_TRANS_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_ENGINE_SUBSTITUTION"
# Enable federated engine
federated
# Allow import local files
local_infile=ON
# Fine Tuning
key_buffer_size=2048M
#sort_buffer_size=2M
#join_buffer_size=2M
#tmp_table_size=10M
max_allowed_packet=1G
#table_open_cache=4000
#table_definition_cache=2000
# Connections
max_connections=250
max_user_connections=20
thread_cache_size=100
# Logging and Replication
#log_error=/var/log/mysql/error.log
log_output=FILE
#general_log=ON
#general_log_file=/var/log/mysql/general.log
slow_query_log=ON
#slow_query_log_file=/var/log/mysql/slow.log
log_slow_rate_type=QUERY
log_slow_verbosity=FULL
log_slow_rate_limit=1
slow_query_log_always_write_time=1
log_slow_admin_statements=ON
log_queries_not_using_indexes=ON
long_query_time=0
min_examined_row_limit=0
userstat=1
slow_query_log_use_global_control=all
# Enabling the InnoDB Lock Monitor
innodb_status_output=ON
innodb_status_output_locks=ON
# timeouts and limits
wait_timeout=1200
interactive_timeout=1200
open_files_limit=65535
# InnoDB Parameters
# buffer pool should be sized to 50% to 75% of system memory
innodb_buffer_pool_size=5G
#innodb_buffer_pool_instances=1
#innodb_buffer_pool_chunk_size=128M
#innodb_log_buffer_size=16M
innodb_log_file_size=512M
#innodb_file_per_table=ON
#innodb_data_file_path=ibdata1:12M:autoextend
#innodb_io_capacity=200
#innodb_flush_log_at_trx_commit=1
innodb_flush_method=O_DIRECT
#innodb_write_io_threads=4
#innodb_read_io_threads=4
# Binlogs
log_bin=ON
#log_bin_basename=/var/log/mysql/binlog
# 7 days binlogs
#expire_logs_days=7
binlog_expire_logs_seconds=604800
# 30 days binlogs
#expire_logs_days=30
#binlog_expire_logs_seconds=2592000
#max_binlog_size=100M
#binlog_do_db = include_database_name
#binlog_ignore_db = include_database_name
Earlier today, before the wsrep error, I had uncommented the innodb_log_file_size=512M line in my.cnf. I had restarted all the nodes and the cluster was working so I hadn’t noticed the innodb error until just now.
After commenting the line out on the 3 nodes, node 1 seems to be joining again. Why is it always when you tell someone the error that you spot it 