[mariadb-galera] Passwords seemingly get changed after some time, access denied for user 'root'@'localhost' puts pods in CrashLoop

jakuzure commented 1 year ago

Name and Version

bitnami/mariadb-galera 9.0.4

What architecture are you using?

amd64

What steps will reproduce the bug?

This issue is probably hard to reproduce, but here's how it's been happening for us on multiple clusters (RKE2 clusters on vSphere):

deploy 3 node cluster
everything works fine for days or even weeks
one or multiple pods can't connect to root on localhost anymore, which results in probes failing and the pods being stuck in a CrashLoop
connecting to another pod's DB with the credentials mounted in the secret works
when a previously still working pod gets restarted, it starts having the same error

Are you using any custom parameters or values?

image:
  tag: 10.7.7-debian-11-r30

serviceAccount:
  create: true
  automountServiceAccountToken: true

rbac:
  create: true

podManagementPolicy: Parallel

replicaCount: 3

db:
  user: technical
  name: ""

persistence:
  size: 20Gi

existingSecret: mariadb-credentials

What is the expected behavior?

No response

What do you see instead?

The user passwords of the DB seemingly get changed after a while, even though we declared them all in a secret and the cluster works fine for a while.

I got a failing cluster working again like this:

Scaled down to one node, with diagnosticMode enabled
Followed this guide to set the root password to the one we use in the existingSecret: https://docs.bitnami.com/aws/infrastructure/lamp/administration/change-reset-password-mariadb/
Initiated bootstrap from Node 0 and the pod started running again
Scaled back up to 3 nodes, but the other pods couldn't sync up
- Set the password of the mariabackup user directly on the working pod. Then the remaining pods became ready again

It seems like not only the root user, but also mariabackup get their passwords changed to something else.

I don't know what could be causing this after the cluster has been working fine for quite a while.

Did this mayb happen to anybody else as well?

Additional information

No response

Mauraza commented 1 year ago

Hi @jakuzure,

Which version of Kubernetes are you using? Did your secret or service account have any issues?

jakuzure commented 1 year ago

Hi, we're on 1.22.13 and didn't notice any secret or service account problems as of yet

Mauraza commented 1 year ago

Hi @jakuzure,

Could you check the logs if appears something strange especially when the node goes up? Do you do something with the nodes of the cluster?

jakuzure commented 1 year ago

Hi @jakuzure,

Could you check the logs if appears something strange especially when the node goes up? Do you do something with the nodes of the cluster?

Startup logs pasted below, I don't notice anything strange, but the problem is not happening currently.

[38;5;6mmariadb [38;5;5m16:21:35.33 [0m
[38;5;6mmariadb [38;5;5m16:21:35.33 [0m[1mWelcome to the Bitnami mariadb-galera container[0m
[38;5;6mmariadb [38;5;5m16:21:35.34 [0mSubscribe to project updates by watching [1mhttps://github.com/bitnami/containers[0m
[38;5;6mmariadb [38;5;5m16:21:35.34 [0mSubmit issues and feature requests at [1mhttps://github.com/bitnami/containers/issues[0m
[38;5;6mmariadb [38;5;5m16:21:35.35 [0m
[38;5;6mmariadb [38;5;5m16:21:35.36 [0m[38;5;2mINFO [0m ==> ** Starting MariaDB setup **
[38;5;6mmariadb [38;5;5m16:21:35.41 [0m[38;5;2mINFO [0m ==> Validating settings in MYSQL_*/MARIADB_* env vars
[38;5;6mmariadb [38;5;5m16:21:35.50 [0m[38;5;2mINFO [0m ==> Initializing mariadb database
[38;5;6mmariadb [38;5;5m16:21:35.57 [0m[38;5;3mWARN [0m ==> This node was previouly booted, you may need to force bootstrapping in one of the nodes.
[38;5;6mmariadb [38;5;5m16:21:35.60 [0m[38;5;2mINFO [0m ==> Found mounted configuration directory
[38;5;6mmariadb [38;5;5m16:21:35.65 [0m[38;5;2mINFO [0m ==> Updating 'my.cnf' with custom configuration
[38;5;6mmariadb [38;5;5m16:21:35.66 [0m[38;5;2mINFO [0m ==> Setting user option
[38;5;6mmariadb [38;5;5m16:21:35.77 [0m[38;5;2mINFO [0m ==> Setting slow_query_log option
[38;5;6mmariadb [38;5;5m16:21:35.87 [0m[38;5;2mINFO [0m ==> Setting long_query_time option
[38;5;6mmariadb [38;5;5m16:21:36.11 [0m[38;5;2mINFO [0m ==> Setting wsrep_node_name option
[38;5;6mmariadb [38;5;5m16:21:36.14 [0m[38;5;2mINFO [0m ==> Setting wsrep_node_address option
[38;5;6mmariadb [38;5;5m16:21:36.21 [0m[38;5;2mINFO [0m ==> Setting wsrep_cluster_address option
[38;5;6mmariadb [38;5;5m16:21:36.23 [0m[38;5;2mINFO [0m ==> Setting wsrep_sst_auth option
[38;5;6mmariadb [38;5;5m16:21:36.27 [0m[38;5;2mINFO [0m ==> Persisted data detected. Restoring
find: '/docker-entrypoint-startdb.d/': No such file or directory
[38;5;6mmariadb [38;5;5m16:21:36.29 [0m[38;5;2mINFO [0m ==> ** MariaDB setup finished! **

[38;5;6mmariadb [38;5;5m16:21:36.36 [0m[38;5;2mINFO [0m ==> ** Starting MariaDB **
[38;5;6mmariadb [38;5;5m16:21:36.36 [0m[38;5;2mINFO [0m ==> Setting previous boot
2023-10-30 16:21:36 0 [Note] /opt/bitnami/mariadb/sbin/mysqld (server 10.7.7-MariaDB-log) starting as process 1 ...
2023-10-30 16:21:36 0 [Note] WSREP: Loading provider /opt/bitnami/mariadb/lib/libgalera_smm.so initial position: 00000000-0000-0000-0000-000000000000:-1
2023-10-30 16:21:36 0 [Note] WSREP: wsrep_load(): loading provider library '/opt/bitnami/mariadb/lib/libgalera_smm.so'
2023-10-30 16:21:36 0 [Note] WSREP: wsrep_load(): Galera 4.13(r0f7af31) by Codership Oy <info@codership.com> loaded successfully.
2023-10-30 16:21:36 0 [Note] WSREP: CRC-32C: using 64-bit x86 acceleration.
2023-10-30 16:21:36 0 [Note] WSREP: Found saved state: 913bb7c3-6367-11ee-adcf-7e3c73d95e68:106013, safe_to_bootstrap: 0
2023-10-30 16:21:36 0 [Note] WSREP: GCache DEBUG: opened preamble:
Version: 2
UUID: 913bb7c3-6367-11ee-adcf-7e3c73d95e68
Seqno: 105595 - 106013
Offset: 45782312
Synced: 1
2023-10-30 16:21:36 0 [Note] WSREP: Recovering GCache ring buffer: version: 2, UUID: 913bb7c3-6367-11ee-adcf-7e3c73d95e68, offset: 45782312
2023-10-30 16:21:36 0 [Note] WSREP: GCache::RingBuffer initial scan...  0.0% (        0/134217752 bytes) complete.
2023-10-30 16:21:36 0 [Note] WSREP: GCache::RingBuffer initial scan...100.0% (134217752/134217752 bytes) complete.
2023-10-30 16:21:36 0 [Note] WSREP: Recovering GCache ring buffer: found gapless sequence 105595-106013
2023-10-30 16:21:36 0 [Note] WSREP: GCache::RingBuffer unused buffers scan...  0.0% (       0/51747240 bytes) complete.
2023-10-30 16:21:36 0 [Note] WSREP: GCache::RingBuffer unused buffers scan...100.0% (51747240/51747240 bytes) complete.
2023-10-30 16:21:36 0 [Note] WSREP: Recovering GCache ring buffer: found 0/419 locked buffers
2023-10-30 16:21:36 0 [Note] WSREP: Recovering GCache ring buffer: free space: 82470488/134217728
2023-10-30 16:21:36 0 [Note] WSREP: Passing config to GCS: base_dir = /bitnami/mariadb/data/; base_host = 10.42.12.7; base_port = 4567; cert.log_conflicts = no; cert.optimistic_pa = yes; debug = no; evs.auto_evict = 0; evs.delay_margin = PT1S; evs.delayed_keep_period = PT30S; evs.inactive_check_period = PT0.5S; evs.inactive_timeout = PT15S; evs.join_retrans_period = PT1S; evs.max_install_timeouts = 3; evs.send_window = 4; evs.stats_report_period = PT1M; evs.suspect_timeout = PT5S; evs.user_send_window = 2; evs.view_forget_timeout = PT24H; gcache.dir = /bitnami/mariadb/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.fc_single_primary = no; gcs.max_packet_size = 64500; gcs.max_throttle = 0.25; gcs.recv_q_hard_limit = 9223372036854775807; gcs.recv_q_soft_limit = 0.25; gcs.sync_donor = no; gmcast.segment = 0; gmcast.version = 0; pc
2023-10-30 16:21:36 0 [Note] WSREP: Service thread queue flushed.
2023-10-30 16:21:36 0 [Note] WSREP: ####### Assign initial position for certification: 913bb7c3-6367-11ee-adcf-7e3c73d95e68:106013, protocol version: -1
2023-10-30 16:21:36 0 [Note] WSREP: Start replication
2023-10-30 16:21:36 0 [Note] WSREP: Connecting with bootstrap option: 0
2023-10-30 16:21:36 0 [Note] WSREP: Setting GCS initial position to 913bb7c3-6367-11ee-adcf-7e3c73d95e68:106013
2023-10-30 16:21:36 0 [Note] WSREP: protonet asio version 0
2023-10-30 16:21:36 0 [Note] WSREP: Using CRC-32C for message checksums.
2023-10-30 16:21:36 0 [Note] WSREP: backend: asio
2023-10-30 16:21:36 0 [Note] WSREP: gcomm thread scheduling priority set to other:0 
2023-10-30 16:21:36 0 [Note] WSREP: access file(/bitnami/mariadb/data//gvwstate.dat) failed(No such file or directory)
2023-10-30 16:21:36 0 [Note] WSREP: restore pc from disk failed
2023-10-30 16:21:36 0 [Note] WSREP: GMCast version 0
2023-10-30 16:21:36 0 [Note] WSREP: (65db3008-b99f, 'tcp://0.0.0.0:4567') listening at tcp://0.0.0.0:4567
2023-10-30 16:21:36 0 [Note] WSREP: (65db3008-b99f, 'tcp://0.0.0.0:4567') multicast: , ttl: 1
2023-10-30 16:21:36 0 [Note] WSREP: EVS version 1
2023-10-30 16:21:36 0 [Note] WSREP: gcomm: connecting to group 'galera', peer 'production-mariadb-0.production-mariadb-headless.production-common.svc.cluster.local:,production-mariadb-1.production-mariadb-headless.production-common.svc.cluster.local:,production-mariadb-2.production-mariadb-headless.production-common.svc.cluster.local:'
2023-10-30 16:21:36 0 [Note] WSREP: (65db3008-b99f, 'tcp://0.0.0.0:4567') Found matching local endpoint for a connection, blacklisting address tcp://10.42.12.7:4567
2023-10-30 16:21:36 0 [Note] WSREP: (65db3008-b99f, 'tcp://0.0.0.0:4567') connection established to 1d20059b-aa96 tcp://10.42.8.11:4567
2023-10-30 16:21:36 0 [Note] WSREP: (65db3008-b99f, 'tcp://0.0.0.0:4567') turning message relay requesting on, nonlive peers: 
2023-10-30 16:21:36 0 [Note] WSREP: (65db3008-b99f, 'tcp://0.0.0.0:4567') connection established to 390caa94-b3d9 tcp://10.42.7.27:4567
2023-10-30 16:21:37 0 [Note] WSREP: EVS version upgrade 0 -> 1
2023-10-30 16:21:37 0 [Note] WSREP: declaring 1d20059b-aa96 at tcp://10.42.8.11:4567 stable
2023-10-30 16:21:37 0 [Note] WSREP: declaring 390caa94-b3d9 at tcp://10.42.7.27:4567 stable
2023-10-30 16:21:37 0 [Note] WSREP: PC protocol upgrade 0 -> 1
2023-10-30 16:21:37 0 [Note] WSREP: Node 1d20059b-aa96 state prim
2023-10-30 16:21:37 0 [Note] WSREP: view(view_id(PRIM,1d20059b-aa96,1184) memb {
    1d20059b-aa96,0
    390caa94-b3d9,0
    65db3008-b99f,0
} joined {
} left {
} partitioned {
})
2023-10-30 16:21:37 0 [Note] WSREP: save pc into disk
2023-10-30 16:21:37 0 [Note] WSREP: gcomm: connected
2023-10-30 16:21:37 0 [Note] WSREP: Changing maximum packet size to 64500, resulting msg size: 32636
2023-10-30 16:21:37 0 [Note] WSREP: Shifting CLOSED -> OPEN (TO: 0)
2023-10-30 16:21:37 0 [Note] WSREP: Opened channel 'galera'
2023-10-30 16:21:37 0 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 2, memb_num = 3
2023-10-30 16:21:37 0 [Note] WSREP: STATE EXCHANGE: Waiting for state UUID.
2023-10-30 16:21:37 0 [Note] WSREP: STATE EXCHANGE: sent state msg: 662d48a2-7740-11ee-8572-6e6cfe954054
2023-10-30 16:21:37 0 [Note] WSREP: STATE EXCHANGE: got state msg: 662d48a2-7740-11ee-8572-6e6cfe954054 from 0 (production-mariadb-2)
2023-10-30 16:21:37 0 [Note] WSREP: STATE EXCHANGE: got state msg: 662d48a2-7740-11ee-8572-6e6cfe954054 from 1 (production-mariadb-0)
2023-10-30 16:21:37 2 [Note] WSREP: Starting rollbacker thread 2
2023-10-30 16:21:37 1 [Note] WSREP: Starting applier thread 1
2023-10-30 16:21:37 0 [Note] WSREP: STATE EXCHANGE: got state msg: 662d48a2-7740-11ee-8572-6e6cfe954054 from 2 (production-mariadb-1)
2023-10-30 16:21:37 0 [Note] WSREP: Quorum results:
    version    = 6,
    component  = PRIMARY,
    conf_id    = 1179,
    members    = 2/3 (joined/total),
    act_id     = 106014,
    last_appl. = 105973,
    protocols  = 2/10/4 (gcs/repl/appl),
    vote policy= 0,
    group UUID = 913bb7c3-6367-11ee-adcf-7e3c73d95e68
2023-10-30 16:21:37 0 [Note] WSREP: Flow-control interval: [28, 28]
2023-10-30 16:21:37 0 [Note] WSREP: Shifting OPEN -> PRIMARY (TO: 106015)
2023-10-30 16:21:37 1 [Note] WSREP: ####### processing CC 106015, local, ordered
2023-10-30 16:21:37 1 [Note] WSREP: Process first view: 913bb7c3-6367-11ee-adcf-7e3c73d95e68 my uuid: 65db3008-7740-11ee-b99f-a707f8696c6a
2023-10-30 16:21:37 1 [Note] WSREP: Server production-mariadb-1 connected to cluster at position 913bb7c3-6367-11ee-adcf-7e3c73d95e68:106015 with ID 65db3008-7740-11ee-b99f-a707f8696c6a
2023-10-30 16:21:37 1 [Note] WSREP: Server status change disconnected -> connected
2023-10-30 16:21:37 1 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2023-10-30 16:21:37 1 [Note] WSREP: ####### My UUID: 65db3008-7740-11ee-b99f-a707f8696c6a
2023-10-30 16:21:37 1 [Note] WSREP: Cert index reset to 00000000-0000-0000-0000-000000000000:-1 (proto: 10), state transfer needed: yes
2023-10-30 16:21:37 0 [Note] WSREP: Service thread queue flushed.
2023-10-30 16:21:37 1 [Note] WSREP: ####### Assign initial position for certification: 00000000-0000-0000-0000-000000000000:-1, protocol version: -1
2023-10-30 16:21:37 1 [Note] WSREP: State transfer required: 
    Group state: 913bb7c3-6367-11ee-adcf-7e3c73d95e68:106015
    Local state: 913bb7c3-6367-11ee-adcf-7e3c73d95e68:106013
2023-10-30 16:21:37 1 [Note] WSREP: Server status change connected -> joiner
2023-10-30 16:21:37 1 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2023-10-30 16:21:37 0 [Note] WSREP: Joiner monitor thread started to monitor
2023-10-30 16:21:37 0 [Note] WSREP: Running: 'wsrep_sst_mariabackup --role 'joiner' --address '10.42.12.7' --datadir '/bitnami/mariadb/data/' --defaults-file '/opt/bitnami/mariadb/conf/my.cnf' --parent 1 --progress 0 --binlog 'mysql-bin' --mysqld-args --defaults-file=/opt/bitnami/mariadb/conf/my.cnf --basedir=/opt/bitnami/mariadb --datadir=/bitnami/mariadb/data --socket=/opt/bitnami/mariadb/tmp/mysql.sock --pid-file=/opt/bitnami/mariadb/tmp/mysqld.pid'
WSREP_SST: [INFO] mariabackup SST started on joiner (20231030 16:21:37.618)
WSREP_SST: [INFO] SSL configuration: CA='', CAPATH='', CERT='', KEY='', MODE='DISABLED', encrypt='0' (20231030 16:21:37.746)
WSREP_SST: [INFO] Progress reporting tool pv not found in path: /opt/bitnami/mariadb//bin:/opt/bitnami/mariadb/sbin:/opt/bitnami/mariadb/bin:/opt/bitnami/common/bin:/opt/bitnami/mariadb/sbin:/opt/bitnami/mariadb/bin:/opt/bitnami/common/bin:/opt/bitnami/common/bin:/opt/bitnami/common/sbin:/opt/bitnami/mariadb/bin:/opt/bitnami/mariadb/sbin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/sbin:/usr/bin:/sbin:/bin (20231030 16:21:38.026)
WSREP_SST: [INFO] Disabling all progress/rate-limiting (20231030 16:21:38.036)
WSREP_SST: [INFO] Moving '/bitnami/mariadb/data/mariabackup.backup.log' to '/tmp/sst_log_archive/mariabackup.backup.log.2023.10.30-16.21.38.063089442' (20231030 16:21:38.074)
WSREP_SST: [INFO] Streaming with mbstream (20231030 16:21:38.098)
WSREP_SST: [INFO] Using socat as streamer (20231030 16:21:38.104)
WSREP_SST: [INFO] Evaluating timeout -k 310 300 socat -u TCP-LISTEN:4444,reuseaddr stdio | '/opt/bitnami/mariadb//bin/mbstream' -x; RC=( ${PIPESTATUS[@]} ) (20231030 16:21:38.186)
2023-10-30 16:21:39 1 [Note] WSREP: ####### IST uuid:913bb7c3-6367-11ee-adcf-7e3c73d95e68 f: 106014, l: 106015, STRv: 3
2023-10-30 16:21:39 1 [Note] WSREP: IST receiver addr using tcp://10.42.12.7:4568
2023-10-30 16:21:39 1 [Note] WSREP: Prepared IST receiver for 106014-106015, listening at: tcp://10.42.12.7:4568
2023-10-30 16:21:39 0 [Note] WSREP: Member 2.0 (production-mariadb-1) requested state transfer from '*any*'. Selected 1.0 (production-mariadb-0)(SYNCED) as donor.
2023-10-30 16:21:39 0 [Note] WSREP: Shifting PRIMARY -> JOINER (TO: 106015)
2023-10-30 16:21:39 1 [Note] WSREP: Requesting state transfer: success, donor: 1
2023-10-30 16:21:40 0 [Note] WSREP: (65db3008-b99f, 'tcp://0.0.0.0:4567') turning message relay requesting off
2023-10-30 16:21:41 0 [Note] WSREP: 1.0 (production-mariadb-0): State transfer to 2.0 (production-mariadb-1) complete.
2023-10-30 16:21:41 0 [Note] WSREP: Member 1.0 (production-mariadb-0) synced with group.
WSREP_SST: [INFO] 'xtrabackup_ist' received from donor: Running IST (20231030 16:21:41.084)
WSREP_SST: [INFO] Galera co-ords from recovery: 913bb7c3-6367-11ee-adcf-7e3c73d95e68:106013 0 (20231030 16:21:41.108)
WSREP_SST: [INFO] Total time on joiner: 0 seconds (20231030 16:21:41.114)
WSREP_SST: [INFO] mariabackup IST completed on joiner (20231030 16:21:41.120)
WSREP_SST: [INFO] Removing the sst_in_progress file (20231030 16:21:41.132)
WSREP_SST: [INFO] Cleaning up temporary directories (20231030 16:21:41.142)
2023-10-30 16:21:41 3 [Note] WSREP: SST received
2023-10-30 16:21:41 3 [Note] WSREP: Server status change joiner -> initializing
2023-10-30 16:21:41 3 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2023-10-30 16:21:41 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2023-10-30 16:21:41 0 [Note] InnoDB: Number of transaction pools: 1
2023-10-30 16:21:41 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
2023-10-30 16:21:41 0 [Note] mysqld: O_TMPFILE is not supported on /opt/bitnami/mariadb/tmp (disabling future attempts)
2023-10-30 16:21:41 0 [Note] InnoDB: Using Linux native AIO
2023-10-30 16:21:41 0 [Note] InnoDB: Initializing buffer pool, total size = 2147483648, chunk size = 134217728
2023-10-30 16:21:41 0 [Note] InnoDB: Completed initialization of buffer pool
2023-10-30 16:21:41 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=24983550020,24983550020
2023-10-30 16:21:42 0 [Note] InnoDB: Starting final batch to recover  64973 pages from redo log.
2023-10-30 16:21:47 0 [Note] InnoDB: Last binlog file './mysql-bin.000016', position 43590491
2023-10-30 16:21:47 0 [Note] InnoDB: 128 rollback segments are active.
2023-10-30 16:21:47 0 [Note] InnoDB: Removed temporary tablespace data file: "./ibtmp1"
2023-10-30 16:21:47 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2023-10-30 16:21:47 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2023-10-30 16:21:47 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2023-10-30 16:21:47 0 [Note] InnoDB: 10.7.7 started; log sequence number 25046087185; transaction id 221183
2023-10-30 16:21:47 0 [Note] InnoDB: Loading buffer pool(s) from /bitnami/mariadb/data/ib_buffer_pool
2023-10-30 16:21:47 0 [Note] Plugin 'FEEDBACK' is disabled.
2023-10-30 16:21:47 0 [Warning] 'innodb-log-files-in-group' was removed. It does nothing now and exists only for compatibility with old my.cnf files.
2023-10-30 16:21:47 0 [Warning] 'innodb-file-format' was removed. It does nothing now and exists only for compatibility with old my.cnf files.
2023-10-30 16:21:48 0 [Note] Server socket created on IP: '0.0.0.0'.
2023-10-30 16:21:48 0 [Warning] 'proxies_priv' entry '@% root@production-mariadb-0' ignored in --skip-name-resolve mode.
2023-10-30 16:21:48 0 [Note] WSREP: wsrep_init_schema_and_SR (nil)
2023-10-30 16:21:49 0 [Note] InnoDB: Buffer pool(s) load completed at 231030 16:21:49
2023-10-30 16:21:49 0 [Note] WSREP: Server initialized
2023-10-30 16:21:49 0 [Note] WSREP: Server status change initializing -> initialized
2023-10-30 16:21:49 0 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2023-10-30 16:21:49 3 [Note] WSREP: Recovered position from storage: 913bb7c3-6367-11ee-adcf-7e3c73d95e68:106013
2023-10-30 16:21:49 3 [Note] WSREP: Recovered view from SST:
  id: 913bb7c3-6367-11ee-adcf-7e3c73d95e68:102859
  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: 1ba569d1-6694-11ee-8731-1a261fade814, production-mariadb-1
    1: 1d20059b-6694-11ee-aa96-9acf10393188, production-mariadb-2
    2: 390caa94-7203-11ee-b3d9-b30d8dbbd80e, production-mariadb-0

2023-10-30 16:21:49 3 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2023-10-30 16:21:49 6 [Note] WSREP: Recovered cluster id 913bb7c3-6367-11ee-adcf-7e3c73d95e68
2023-10-30 16:21:49 3 [Note] WSREP: SST received: 913bb7c3-6367-11ee-adcf-7e3c73d95e68:106013
2023-10-30 16:21:49 3 [Note] WSREP: SST succeeded for position 913bb7c3-6367-11ee-adcf-7e3c73d95e68:106013
2023-10-30 16:21:49 1 [Note] WSREP: Installed new state from SST: 913bb7c3-6367-11ee-adcf-7e3c73d95e68:106013
2023-10-30 16:21:49 0 [Note] WSREP: Joiner monitor thread ended with total time 12 sec
2023-10-30 16:21:49 7 [Note] WSREP: Starting applier thread 7
2023-10-30 16:21:49 8 [Note] WSREP: Starting applier thread 8
2023-10-30 16:21:49 10 [Note] WSREP: Starting applier thread 10
2023-10-30 16:21:49 0 [Note] /opt/bitnami/mariadb/sbin/mysqld: ready for connections.
Version: '10.7.7-MariaDB-log'  socket: '/opt/bitnami/mariadb/tmp/mysql.sock'  port: 3306  Source distribution
2023-10-30 16:21:49 1 [Note] WSREP: Receiving IST: 2 writesets, seqnos 106014-106015
2023-10-30 16:21:49 0 [Note] WSREP: ####### IST applying starts with 106014
2023-10-30 16:21:49 0 [Note] WSREP: ####### IST current seqno initialized to 105974
2023-10-30 16:21:49 0 [Note] WSREP: Receiving IST...  0.0% ( 0/42 events) complete.
2023-10-30 16:21:49 0 [Note] WSREP: IST preload starting at 105974
2023-10-30 16:21:49 0 [Note] WSREP: Service thread queue flushed.
2023-10-30 16:21:49 0 [Note] WSREP: ####### Assign initial position for certification: 00000000-0000-0000-0000-000000000000:105973, protocol version: 5
2023-10-30 16:21:49 0 [Note] WSREP: REPL Protocols: 10 (5)
2023-10-30 16:21:49 0 [Note] WSREP: ####### Adjusting cert position: 106013 -> 106014
2023-10-30 16:21:49 0 [Note] WSREP: Service thread queue flushed.
2023-10-30 16:21:49 0 [Note] WSREP: Lowest cert index boundary for CC from ist: 105974
2023-10-30 16:21:49 0 [Note] WSREP: Min available from gcache for CC from ist: 105595
2023-10-30 16:21:49 7 [Note] WSREP: ================================================
View:
  id: 913bb7c3-6367-11ee-adcf-7e3c73d95e68:106014
  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: 1d20059b-6694-11ee-aa96-9acf10393188, production-mariadb-2
    1: 390caa94-7203-11ee-b3d9-b30d8dbbd80e, production-mariadb-0
=================================================
2023-10-30 16:21:49 7 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2023-10-30 16:21:49 0 [Note] WSREP: REPL Protocols: 10 (5)
2023-10-30 16:21:49 0 [Note] WSREP: ####### Adjusting cert position: 106014 -> 106015
2023-10-30 16:21:49 0 [Note] WSREP: Service thread queue flushed.
2023-10-30 16:21:49 0 [Note] WSREP: Lowest cert index boundary for CC from ist: 105974
2023-10-30 16:21:49 0 [Note] WSREP: Min available from gcache for CC from ist: 105595
2023-10-30 16:21:49 0 [Note] WSREP: Receiving IST...100.0% (42/42 events) complete.
2023-10-30 16:21:49 1 [Note] WSREP: Draining apply monitors after IST up to 106015
2023-10-30 16:21:49 7 [Note] WSREP: ================================================
View:
  id: 913bb7c3-6367-11ee-adcf-7e3c73d95e68:106015
  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: 2
  members(3):
    0: 1d20059b-6694-11ee-aa96-9acf10393188, production-mariadb-2
    1: 390caa94-7203-11ee-b3d9-b30d8dbbd80e, production-mariadb-0
    2: 65db3008-7740-11ee-b99f-a707f8696c6a, production-mariadb-1
=================================================
2023-10-30 16:21:49 7 [Note] WSREP: Server status change initialized -> joined
2023-10-30 16:21:49 7 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2023-10-30 16:21:49 7 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2023-10-30 16:21:49 1 [Note] WSREP: IST received: 913bb7c3-6367-11ee-adcf-7e3c73d95e68:106015
2023-10-30 16:21:49 1 [Note] WSREP: Lowest cert index boundary for CC from sst: 105974
2023-10-30 16:21:49 1 [Note] WSREP: Min available from gcache for CC from sst: 105595
2023-10-30 16:21:49 0 [Note] WSREP: 2.0 (production-mariadb-1): State transfer from 1.0 (production-mariadb-0) complete.
2023-10-30 16:21:49 0 [Note] WSREP: Shifting JOINER -> JOINED (TO: 106015)
2023-10-30 16:21:49 0 [Note] WSREP: Processing event queue:... -nan% (0/0 events) complete.
2023-10-30 16:21:49 0 [Note] WSREP: Member 2.0 (production-mariadb-1) synced with group.
2023-10-30 16:21:49 0 [Note] WSREP: Processing event queue:...100.0% (1/1 events) complete.
2023-10-30 16:21:49 0 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 106015)
2023-10-30 16:21:49 8 [Note] WSREP: Server production-mariadb-1 synced with group
2023-10-30 16:21:49 8 [Note] WSREP: Server status change joined -> synced
2023-10-30 16:21:49 8 [Note] WSREP: Synchronized with group, ready for connections
2023-10-30 16:21:49 8 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.

jakuzure commented 1 year ago

@Mauraza ok we just upgraded our nodes to a new VM image which went fine for pods -0 and -1, but -2 is not coming up correctly, logs below.

Previously it also happened spontaneously without any changes to nodes.

EDIT: I cordoned the node it was running on and it came up on another node just fine. I then uncordoned the node where it previously didn't work, killed the pod and it came up on the node on which it failed just before... Those are completely fresh nodes, I don't know what might be happening.

[38;5;6mmariadb [38;5;5m16:36:46.37 [0m
[38;5;6mmariadb [38;5;5m16:36:46.37 [0m[1mWelcome to the Bitnami mariadb-galera container[0m
[38;5;6mmariadb [38;5;5m16:36:46.38 [0mSubscribe to project updates by watching [1mhttps://github.com/bitnami/containers[0m
[38;5;6mmariadb [38;5;5m16:36:46.38 [0mSubmit issues and feature requests at [1mhttps://github.com/bitnami/containers/issues[0m
[38;5;6mmariadb [38;5;5m16:36:46.38 [0m
[38;5;6mmariadb [38;5;5m16:36:46.38 [0m[38;5;2mINFO [0m ==> ** Starting MariaDB setup **
[38;5;6mmariadb [38;5;5m16:36:46.42 [0m[38;5;2mINFO [0m ==> Validating settings in MYSQL_*/MARIADB_* env vars
[38;5;6mmariadb [38;5;5m16:36:46.47 [0m[38;5;2mINFO [0m ==> Initializing mariadb database
[38;5;6mmariadb [38;5;5m16:36:46.52 [0m[38;5;3mWARN [0m ==> This node was previouly booted, you may need to force bootstrapping in one of the nodes.
[38;5;6mmariadb [38;5;5m16:36:46.55 [0m[38;5;2mINFO [0m ==> Found mounted configuration directory
[38;5;6mmariadb [38;5;5m16:36:46.56 [0m[38;5;2mINFO [0m ==> Updating 'my.cnf' with custom configuration
[38;5;6mmariadb [38;5;5m16:36:46.58 [0m[38;5;2mINFO [0m ==> Setting user option
[38;5;6mmariadb [38;5;5m16:36:46.61 [0m[38;5;2mINFO [0m ==> Setting slow_query_log option
[38;5;6mmariadb [38;5;5m16:36:46.62 [0m[38;5;2mINFO [0m ==> Setting long_query_time option
[38;5;6mmariadb [38;5;5m16:36:46.64 [0m[38;5;2mINFO [0m ==> Setting wsrep_node_name option
[38;5;6mmariadb [38;5;5m16:36:46.67 [0m[38;5;2mINFO [0m ==> Setting wsrep_node_address option
[38;5;6mmariadb [38;5;5m16:36:46.72 [0m[38;5;2mINFO [0m ==> Setting wsrep_cluster_address option
[38;5;6mmariadb [38;5;5m16:36:46.74 [0m[38;5;2mINFO [0m ==> Setting wsrep_sst_auth option
[38;5;6mmariadb [38;5;5m16:36:46.75 [0m[38;5;2mINFO [0m ==> Persisted data detected. Restoring
find: '/docker-entrypoint-startdb.d/': No such file or directory
[38;5;6mmariadb [38;5;5m16:36:46.77 [0m[38;5;2mINFO [0m ==> ** MariaDB setup finished! **

[38;5;6mmariadb [38;5;5m16:36:46.82 [0m[38;5;2mINFO [0m ==> ** Starting MariaDB **
[38;5;6mmariadb [38;5;5m16:36:46.83 [0m[38;5;2mINFO [0m ==> Setting previous boot
2023-10-30 16:36:46 0 [Note] /opt/bitnami/mariadb/sbin/mysqld (server 10.7.7-MariaDB-log) starting as process 1 ...
2023-10-30 16:36:46 0 [Note] WSREP: Loading provider /opt/bitnami/mariadb/lib/libgalera_smm.so initial position: 00000000-0000-0000-0000-000000000000:-1
2023-10-30 16:36:46 0 [Note] WSREP: wsrep_load(): loading provider library '/opt/bitnami/mariadb/lib/libgalera_smm.so'
2023-10-30 16:36:46 0 [Note] WSREP: wsrep_load(): Galera 4.13(r0f7af31) by Codership Oy <info@codership.com> loaded successfully.
2023-10-30 16:36:46 0 [Note] WSREP: CRC-32C: using 64-bit x86 acceleration.
2023-10-30 16:36:46 0 [Note] WSREP: Found saved state: 913bb7c3-6367-11ee-adcf-7e3c73d95e68:106020, safe_to_bootstrap: 0
2023-10-30 16:36:46 0 [Note] WSREP: GCache DEBUG: opened preamble:
Version: 2
UUID: 913bb7c3-6367-11ee-adcf-7e3c73d95e68
Seqno: 105595 - 106020
Offset: 93340832
Synced: 1
2023-10-30 16:36:46 0 [Note] WSREP: Recovering GCache ring buffer: version: 2, UUID: 913bb7c3-6367-11ee-adcf-7e3c73d95e68, offset: 93340832
2023-10-30 16:36:46 0 [Note] WSREP: GCache::RingBuffer initial scan...  0.0% (        0/134217752 bytes) complete.
2023-10-30 16:36:46 0 [Note] WSREP: GCache::RingBuffer initial scan...100.0% (134217752/134217752 bytes) complete.
2023-10-30 16:36:46 0 [Note] WSREP: Recovering GCache ring buffer: found gapless sequence 105595-106020
2023-10-30 16:36:46 0 [Note] WSREP: GCache::RingBuffer unused buffers scan...  0.0% (       0/51755776 bytes) complete.
2023-10-30 16:36:46 0 [Note] WSREP: GCache::RingBuffer unused buffers scan...100.0% (51755776/51755776 bytes) complete.
2023-10-30 16:36:46 0 [Note] WSREP: Recovering GCache ring buffer: found 3/429 locked buffers
2023-10-30 16:36:46 0 [Note] WSREP: Recovering GCache ring buffer: free space: 82462656/134217728
2023-10-30 16:36:46 0 [Note] WSREP: Passing config to GCS: base_dir = /bitnami/mariadb/data/; base_host = 10.42.0.9; base_port = 4567; cert.log_conflicts = no; cert.optimistic_pa = yes; debug = no; evs.auto_evict = 0; evs.delay_margin = PT1S; evs.delayed_keep_period = PT30S; evs.inactive_check_period = PT0.5S; evs.inactive_timeout = PT15S; evs.join_retrans_period = PT1S; evs.max_install_timeouts = 3; evs.send_window = 4; evs.stats_report_period = PT1M; evs.suspect_timeout = PT5S; evs.user_send_window = 2; evs.view_forget_timeout = PT24H; gcache.dir = /bitnami/mariadb/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.fc_single_primary = no; gcs.max_packet_size = 64500; gcs.max_throttle = 0.25; gcs.recv_q_hard_limit = 9223372036854775807; gcs.recv_q_soft_limit = 0.25; gcs.sync_donor = no; gmcast.segment = 0; gmcast.version = 0; pc.
2023-10-30 16:36:46 0 [Note] WSREP: Service thread queue flushed.
2023-10-30 16:36:46 0 [Note] WSREP: ####### Assign initial position for certification: 913bb7c3-6367-11ee-adcf-7e3c73d95e68:106020, protocol version: -1
2023-10-30 16:36:46 0 [Note] WSREP: Start replication
2023-10-30 16:36:46 0 [Note] WSREP: Connecting with bootstrap option: 0
2023-10-30 16:36:46 0 [Note] WSREP: Setting GCS initial position to 913bb7c3-6367-11ee-adcf-7e3c73d95e68:106020
2023-10-30 16:36:46 0 [Note] WSREP: protonet asio version 0
2023-10-30 16:36:46 0 [Note] WSREP: Using CRC-32C for message checksums.
2023-10-30 16:36:46 0 [Note] WSREP: backend: asio
2023-10-30 16:36:46 0 [Note] WSREP: gcomm thread scheduling priority set to other:0 
2023-10-30 16:36:46 0 [Note] WSREP: access file(/bitnami/mariadb/data//gvwstate.dat) failed(No such file or directory)
2023-10-30 16:36:46 0 [Note] WSREP: restore pc from disk failed
2023-10-30 16:36:46 0 [Note] WSREP: GMCast version 0
2023-10-30 16:36:46 0 [Note] WSREP: (847a1087-8875, 'tcp://0.0.0.0:4567') listening at tcp://0.0.0.0:4567
2023-10-30 16:36:46 0 [Note] WSREP: (847a1087-8875, 'tcp://0.0.0.0:4567') multicast: , ttl: 1
2023-10-30 16:36:46 0 [Note] WSREP: EVS version 1
2023-10-30 16:36:46 0 [Note] WSREP: gcomm: connecting to group 'galera', peer 'production-mariadb-0.production-mariadb-headless.production-common.svc.cluster.local:,production-mariadb-1.production-mariadb-headless.production-common.svc.cluster.local:,production-mariadb-2.production-mariadb-headless.production-common.svc.cluster.local:'
2023-10-30 16:36:46 0 [Note] WSREP: (847a1087-8875, 'tcp://0.0.0.0:4567') Found matching local endpoint for a connection, blacklisting address tcp://10.42.0.9:4567
2023-10-30 16:36:46 0 [Note] WSREP: (847a1087-8875, 'tcp://0.0.0.0:4567') connection established to 65db3008-b99f tcp://10.42.12.7:4567
2023-10-30 16:36:46 0 [Note] WSREP: (847a1087-8875, 'tcp://0.0.0.0:4567') turning message relay requesting on, nonlive peers: 
2023-10-30 16:36:46 0 [Note] WSREP: (847a1087-8875, 'tcp://0.0.0.0:4567') connection established to 6267eebe-a2a4 tcp://10.42.14.12:4567
2023-10-30 16:36:47 0 [Note] WSREP: EVS version upgrade 0 -> 1
2023-10-30 16:36:47 0 [Note] WSREP: declaring 6267eebe-a2a4 at tcp://10.42.14.12:4567 stable
2023-10-30 16:36:47 0 [Note] WSREP: declaring 65db3008-b99f at tcp://10.42.12.7:4567 stable
2023-10-30 16:36:47 0 [Note] WSREP: PC protocol upgrade 0 -> 1
2023-10-30 16:36:47 0 [Note] WSREP: Node 6267eebe-a2a4 state prim
2023-10-30 16:36:47 0 [Note] WSREP: view(view_id(PRIM,6267eebe-a2a4,1190) memb {
    6267eebe-a2a4,0
    65db3008-b99f,0
    847a1087-8875,0
} joined {
} left {
} partitioned {
})
2023-10-30 16:36:47 0 [Note] WSREP: save pc into disk
2023-10-30 16:36:47 0 [Note] WSREP: gcomm: connected
2023-10-30 16:36:47 0 [Note] WSREP: Changing maximum packet size to 64500, resulting msg size: 32636
2023-10-30 16:36:47 0 [Note] WSREP: Shifting CLOSED -> OPEN (TO: 0)
2023-10-30 16:36:47 0 [Note] WSREP: Opened channel 'galera'
2023-10-30 16:36:47 0 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 2, memb_num = 3
2023-10-30 16:36:47 0 [Note] WSREP: STATE EXCHANGE: Waiting for state UUID.
2023-10-30 16:36:47 0 [Note] WSREP: STATE EXCHANGE: sent state msg: 84c9e860-7742-11ee-a1a4-479764c9fc62
2023-10-30 16:36:47 0 [Note] WSREP: STATE EXCHANGE: got state msg: 84c9e860-7742-11ee-a1a4-479764c9fc62 from 0 (production-mariadb-0)
2023-10-30 16:36:47 0 [Note] WSREP: STATE EXCHANGE: got state msg: 84c9e860-7742-11ee-a1a4-479764c9fc62 from 1 (production-mariadb-1)
2023-10-30 16:36:47 1 [Note] WSREP: Starting rollbacker thread 1
2023-10-30 16:36:47 2 [Note] WSREP: Starting applier thread 2
2023-10-30 16:36:47 0 [Note] WSREP: STATE EXCHANGE: got state msg: 84c9e860-7742-11ee-a1a4-479764c9fc62 from 2 (production-mariadb-2)
2023-10-30 16:36:47 0 [Note] WSREP: Quorum results:
    version    = 6,
    component  = PRIMARY,
    conf_id    = 1185,
    members    = 2/3 (joined/total),
    act_id     = 106021,
    last_appl. = 105973,
    protocols  = 2/10/4 (gcs/repl/appl),
    vote policy= 0,
    group UUID = 913bb7c3-6367-11ee-adcf-7e3c73d95e68
2023-10-30 16:36:47 0 [Note] WSREP: Flow-control interval: [28, 28]
2023-10-30 16:36:47 0 [Note] WSREP: Shifting OPEN -> PRIMARY (TO: 106022)
2023-10-30 16:36:47 2 [Note] WSREP: ####### processing CC 106022, local, ordered
2023-10-30 16:36:47 2 [Note] WSREP: Process first view: 913bb7c3-6367-11ee-adcf-7e3c73d95e68 my uuid: 847a1087-7742-11ee-8875-7ec548b4f54c
2023-10-30 16:36:47 2 [Note] WSREP: Server production-mariadb-2 connected to cluster at position 913bb7c3-6367-11ee-adcf-7e3c73d95e68:106022 with ID 847a1087-7742-11ee-8875-7ec548b4f54c
2023-10-30 16:36:47 2 [Note] WSREP: Server status change disconnected -> connected
2023-10-30 16:36:47 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2023-10-30 16:36:47 2 [Note] WSREP: ####### My UUID: 847a1087-7742-11ee-8875-7ec548b4f54c
2023-10-30 16:36:47 2 [Note] WSREP: Cert index reset to 00000000-0000-0000-0000-000000000000:-1 (proto: 10), state transfer needed: yes
2023-10-30 16:36:47 0 [Note] WSREP: Service thread queue flushed.
2023-10-30 16:36:47 2 [Note] WSREP: ####### Assign initial position for certification: 00000000-0000-0000-0000-000000000000:-1, protocol version: -1
2023-10-30 16:36:47 2 [Note] WSREP: State transfer required: 
    Group state: 913bb7c3-6367-11ee-adcf-7e3c73d95e68:106022
    Local state: 913bb7c3-6367-11ee-adcf-7e3c73d95e68:106020
2023-10-30 16:36:47 2 [Note] WSREP: Server status change connected -> joiner
2023-10-30 16:36:47 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2023-10-30 16:36:47 0 [Note] WSREP: Joiner monitor thread started to monitor
2023-10-30 16:36:47 0 [Note] WSREP: Running: 'wsrep_sst_mariabackup --role 'joiner' --address '10.42.0.9' --datadir '/bitnami/mariadb/data/' --defaults-file '/opt/bitnami/mariadb/conf/my.cnf' --parent 1 --progress 0 --binlog 'mysql-bin' --mysqld-args --defaults-file=/opt/bitnami/mariadb/conf/my.cnf --basedir=/opt/bitnami/mariadb --datadir=/bitnami/mariadb/data --socket=/opt/bitnami/mariadb/tmp/mysql.sock --pid-file=/opt/bitnami/mariadb/tmp/mysqld.pid'
WSREP_SST: [INFO] mariabackup SST started on joiner (20231030 16:36:47.967)
WSREP_SST: [INFO] SSL configuration: CA='', CAPATH='', CERT='', KEY='', MODE='DISABLED', encrypt='0' (20231030 16:36:48.026)
WSREP_SST: [INFO] Progress reporting tool pv not found in path: /opt/bitnami/mariadb//bin:/opt/bitnami/mariadb/sbin:/opt/bitnami/mariadb/bin:/opt/bitnami/common/bin:/opt/bitnami/mariadb/sbin:/opt/bitnami/mariadb/bin:/opt/bitnami/common/bin:/opt/bitnami/common/bin:/opt/bitnami/common/sbin:/opt/bitnami/mariadb/bin:/opt/bitnami/mariadb/sbin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/sbin:/usr/bin:/sbin:/bin (20231030 16:36:48.177)
WSREP_SST: [INFO] Disabling all progress/rate-limiting (20231030 16:36:48.181)
WSREP_SST: [INFO] Streaming with mbstream (20231030 16:36:48.213)
WSREP_SST: [INFO] Using socat as streamer (20231030 16:36:48.218)
WSREP_SST: [INFO] Evaluating timeout -k 310 300 socat -u TCP-LISTEN:4444,reuseaddr stdio | '/opt/bitnami/mariadb//bin/mbstream' -x; RC=( ${PIPESTATUS[@]} ) (20231030 16:36:48.266)
2023-10-30 16:36:48 2 [Note] WSREP: ####### IST uuid:913bb7c3-6367-11ee-adcf-7e3c73d95e68 f: 106021, l: 106022, STRv: 3
2023-10-30 16:36:48 2 [Note] WSREP: IST receiver addr using tcp://10.42.0.9:4568
2023-10-30 16:36:48 2 [Note] WSREP: Prepared IST receiver for 106021-106022, listening at: tcp://10.42.0.9:4568
2023-10-30 16:36:48 0 [Note] WSREP: Member 2.0 (production-mariadb-2) requested state transfer from '*any*'. Selected 1.0 (production-mariadb-1)(SYNCED) as donor.
2023-10-30 16:36:48 0 [Note] WSREP: Shifting PRIMARY -> JOINER (TO: 106022)
2023-10-30 16:36:48 2 [Note] WSREP: Requesting state transfer: success, donor: 1
2023-10-30 16:36:48 0 [Note] WSREP: 1.0 (production-mariadb-1): State transfer to 2.0 (production-mariadb-2) complete.
2023-10-30 16:36:48 0 [Note] WSREP: Member 1.0 (production-mariadb-1) synced with group.
WSREP_SST: [INFO] 'xtrabackup_ist' received from donor: Running IST (20231030 16:36:48.848)
WSREP_SST: [INFO] Galera co-ords from recovery: 913bb7c3-6367-11ee-adcf-7e3c73d95e68:106020 0 (20231030 16:36:48.856)
WSREP_SST: [INFO] Total time on joiner: 0 seconds (20231030 16:36:48.863)
WSREP_SST: [INFO] mariabackup IST completed on joiner (20231030 16:36:48.869)
WSREP_SST: [INFO] Removing the sst_in_progress file (20231030 16:36:48.875)
WSREP_SST: [INFO] Cleaning up temporary directories (20231030 16:36:48.882)
2023-10-30 16:36:48 3 [Note] WSREP: SST received
2023-10-30 16:36:48 3 [Note] WSREP: Server status change joiner -> initializing
2023-10-30 16:36:48 3 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2023-10-30 16:36:48 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2023-10-30 16:36:48 0 [Note] InnoDB: Number of transaction pools: 1
2023-10-30 16:36:48 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
2023-10-30 16:36:48 0 [Note] mysqld: O_TMPFILE is not supported on /opt/bitnami/mariadb/tmp (disabling future attempts)
2023-10-30 16:36:48 0 [Note] InnoDB: Using Linux native AIO
2023-10-30 16:36:48 0 [Note] InnoDB: Initializing buffer pool, total size = 2147483648, chunk size = 134217728
2023-10-30 16:36:49 0 [Note] InnoDB: Completed initialization of buffer pool
2023-10-30 16:36:49 0 [Note] InnoDB: 128 rollback segments are active.
2023-10-30 16:36:49 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2023-10-30 16:36:49 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2023-10-30 16:36:49 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2023-10-30 16:36:49 0 [Note] InnoDB: 10.7.7 started; log sequence number 24997007632; transaction id 221234
2023-10-30 16:36:49 0 [Note] InnoDB: Loading buffer pool(s) from /bitnami/mariadb/data/ib_buffer_pool
2023-10-30 16:36:49 0 [Note] Plugin 'FEEDBACK' is disabled.
2023-10-30 16:36:49 0 [Warning] 'innodb-log-files-in-group' was removed. It does nothing now and exists only for compatibility with old my.cnf files.
2023-10-30 16:36:49 0 [Warning] 'innodb-file-format' was removed. It does nothing now and exists only for compatibility with old my.cnf files.
2023-10-30 16:36:49 0 [Note] Server socket created on IP: '0.0.0.0'.
2023-10-30 16:36:49 0 [Note] WSREP: wsrep_init_schema_and_SR (nil)
2023-10-30 16:36:49 0 [Note] WSREP: Server initialized
2023-10-30 16:36:49 0 [Note] WSREP: Server status change initializing -> initialized
2023-10-30 16:36:49 0 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2023-10-30 16:36:49 3 [Note] WSREP: Recovered position from storage: 913bb7c3-6367-11ee-adcf-7e3c73d95e68:106020
2023-10-30 16:36:49 3 [Note] WSREP: Recovered view from SST:
  id: 913bb7c3-6367-11ee-adcf-7e3c73d95e68:106020
  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: 263a7bca-7742-11ee-8bc0-831557e45b64, production-mariadb-2
    1: 6267eebe-7741-11ee-a2a4-d25c487c46f1, production-mariadb-0
    2: 65db3008-7740-11ee-b99f-a707f8696c6a, production-mariadb-1

2023-10-30 16:36:49 3 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2023-10-30 16:36:49 6 [Note] WSREP: Recovered cluster id 913bb7c3-6367-11ee-adcf-7e3c73d95e68
2023-10-30 16:36:49 3 [Note] WSREP: SST received: 913bb7c3-6367-11ee-adcf-7e3c73d95e68:106020
2023-10-30 16:36:49 3 [Note] WSREP: SST succeeded for position 913bb7c3-6367-11ee-adcf-7e3c73d95e68:106020
2023-10-30 16:36:49 2 [Note] WSREP: Installed new state from SST: 913bb7c3-6367-11ee-adcf-7e3c73d95e68:106020
2023-10-30 16:36:49 0 [Note] WSREP: Joiner monitor thread ended with total time 2 sec
2023-10-30 16:36:49 0 [Note] /opt/bitnami/mariadb/sbin/mysqld: ready for connections.
Version: '10.7.7-MariaDB-log'  socket: '/opt/bitnami/mariadb/tmp/mysql.sock'  port: 3306  Source distribution
2023-10-30 16:36:49 8 [Note] WSREP: Starting applier thread 8
2023-10-30 16:36:49 7 [Note] WSREP: Starting applier thread 7
2023-10-30 16:36:49 11 [Note] WSREP: Starting applier thread 11
2023-10-30 16:36:49 2 [Note] WSREP: Receiving IST: 2 writesets, seqnos 106021-106022
2023-10-30 16:36:49 0 [Note] WSREP: ####### IST applying starts with 106021
2023-10-30 16:36:49 0 [Note] WSREP: ####### IST current seqno initialized to 105974
2023-10-30 16:36:49 0 [Note] WSREP: Receiving IST...  0.0% ( 0/49 events) complete.
2023-10-30 16:36:49 0 [Note] WSREP: IST preload starting at 105974
2023-10-30 16:36:49 0 [Note] WSREP: Service thread queue flushed.
2023-10-30 16:36:49 0 [Note] WSREP: ####### Assign initial position for certification: 00000000-0000-0000-0000-000000000000:105973, protocol version: 5
2023-10-30 16:36:49 0 [Note] WSREP: REPL Protocols: 10 (5)
2023-10-30 16:36:49 0 [Note] WSREP: ####### Adjusting cert position: 106013 -> 106014
2023-10-30 16:36:49 0 [Note] WSREP: Service thread queue flushed.
2023-10-30 16:36:49 0 [Note] WSREP: Lowest cert index boundary for CC from preload: 105974
2023-10-30 16:36:49 0 [Note] WSREP: Min available from gcache for CC from preload: 105595
2023-10-30 16:36:49 0 [Note] WSREP: REPL Protocols: 10 (5)
2023-10-30 16:36:49 0 [Note] WSREP: ####### Adjusting cert position: 106014 -> 106015
2023-10-30 16:36:49 0 [Note] WSREP: Service thread queue flushed.
2023-10-30 16:36:49 0 [Note] WSREP: Lowest cert index boundary for CC from preload: 105974
2023-10-30 16:36:49 0 [Note] WSREP: Min available from gcache for CC from preload: 105595
2023-10-30 16:36:49 0 [Note] WSREP: REPL Protocols: 10 (5)
2023-10-30 16:36:49 0 [Note] WSREP: ####### Adjusting cert position: 106015 -> 106016
2023-10-30 16:36:49 0 [Note] WSREP: Service thread queue flushed.
2023-10-30 16:36:49 0 [Note] WSREP: Lowest cert index boundary for CC from preload: 105974
2023-10-30 16:36:49 0 [Note] WSREP: Min available from gcache for CC from preload: 105595
2023-10-30 16:36:49 0 [Note] WSREP: REPL Protocols: 10 (5)
2023-10-30 16:36:49 0 [Note] WSREP: ####### Adjusting cert position: 106017 -> 106018
2023-10-30 16:36:49 0 [Note] WSREP: Service thread queue flushed.
2023-10-30 16:36:49 0 [Note] WSREP: Lowest cert index boundary for CC from preload: 105974
2023-10-30 16:36:49 0 [Note] WSREP: Min available from gcache for CC from preload: 105595
2023-10-30 16:36:49 0 [Note] WSREP: REPL Protocols: 10 (5)
2023-10-30 16:36:49 0 [Note] WSREP: ####### Adjusting cert position: 106018 -> 106019
2023-10-30 16:36:49 0 [Note] WSREP: Service thread queue flushed.
2023-10-30 16:36:49 0 [Note] WSREP: Lowest cert index boundary for CC from preload: 105974
2023-10-30 16:36:49 0 [Note] WSREP: Min available from gcache for CC from preload: 105595
2023-10-30 16:36:49 0 [Note] WSREP: REPL Protocols: 10 (5)
2023-10-30 16:36:49 0 [Note] WSREP: ####### Adjusting cert position: 106019 -> 106020
2023-10-30 16:36:49 0 [Note] WSREP: Service thread queue flushed.
2023-10-30 16:36:49 0 [Note] WSREP: Lowest cert index boundary for CC from preload: 105974
2023-10-30 16:36:49 0 [Note] WSREP: Min available from gcache for CC from preload: 105595
2023-10-30 16:36:49 0 [Note] WSREP: REPL Protocols: 10 (5)
2023-10-30 16:36:49 0 [Note] WSREP: ####### Adjusting cert position: 106020 -> 106021
2023-10-30 16:36:49 0 [Note] WSREP: Service thread queue flushed.
2023-10-30 16:36:49 0 [Note] WSREP: Lowest cert index boundary for CC from ist: 105974
2023-10-30 16:36:49 0 [Note] WSREP: Min available from gcache for CC from ist: 105595
2023-10-30 16:36:49 8 [Note] WSREP: ================================================
View:
  id: 913bb7c3-6367-11ee-adcf-7e3c73d95e68:106021
  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: 6267eebe-7741-11ee-a2a4-d25c487c46f1, production-mariadb-0
    1: 65db3008-7740-11ee-b99f-a707f8696c6a, production-mariadb-1
=================================================
2023-10-30 16:36:49 8 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2023-10-30 16:36:49 0 [Note] WSREP: REPL Protocols: 10 (5)
2023-10-30 16:36:49 0 [Note] WSREP: ####### Adjusting cert position: 106021 -> 106022
2023-10-30 16:36:49 0 [Note] WSREP: Service thread queue flushed.
2023-10-30 16:36:49 0 [Note] WSREP: Lowest cert index boundary for CC from ist: 105974
2023-10-30 16:36:49 0 [Note] WSREP: Min available from gcache for CC from ist: 105595
2023-10-30 16:36:49 0 [Note] WSREP: Receiving IST...100.0% (49/49 events) complete.
2023-10-30 16:36:49 7 [Note] WSREP: ================================================
View:
  id: 913bb7c3-6367-11ee-adcf-7e3c73d95e68:106022
  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: 2
  members(3):
    0: 6267eebe-7741-11ee-a2a4-d25c487c46f1, production-mariadb-0
    1: 65db3008-7740-11ee-b99f-a707f8696c6a, production-mariadb-1
    2: 847a1087-7742-11ee-8875-7ec548b4f54c, production-mariadb-2
=================================================
2023-10-30 16:36:49 7 [Note] WSREP: Server status change initialized -> joined
2023-10-30 16:36:49 7 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2023-10-30 16:36:49 7 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2023-10-30 16:36:49 2 [Note] WSREP: Draining apply monitors after IST up to 106022
2023-10-30 16:36:49 2 [Note] WSREP: IST received: 913bb7c3-6367-11ee-adcf-7e3c73d95e68:106022
2023-10-30 16:36:49 2 [Note] WSREP: Lowest cert index boundary for CC from sst: 105974
2023-10-30 16:36:49 2 [Note] WSREP: Min available from gcache for CC from sst: 105595
2023-10-30 16:36:49 0 [Note] WSREP: 2.0 (production-mariadb-2): State transfer from 1.0 (production-mariadb-1) complete.
2023-10-30 16:36:49 0 [Note] WSREP: Shifting JOINER -> JOINED (TO: 106022)
2023-10-30 16:36:49 0 [Note] WSREP: Processing event queue:... -nan% (0/0 events) complete.
2023-10-30 16:36:49 0 [Note] WSREP: Member 2.0 (production-mariadb-2) synced with group.
2023-10-30 16:36:49 0 [Note] WSREP: Processing event queue:...100.0% (1/1 events) complete.
2023-10-30 16:36:49 0 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 106022)
2023-10-30 16:36:49 7 [Note] WSREP: Server production-mariadb-2 synced with group
2023-10-30 16:36:49 7 [Note] WSREP: Server status change joined -> synced
2023-10-30 16:36:49 7 [Note] WSREP: Synchronized with group, ready for connections
2023-10-30 16:36:49 7 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2023-10-30 16:36:50 0 [Note] WSREP: (847a1087-8875, 'tcp://0.0.0.0:4567') turning message relay requesting off
2023-10-30 16:36:50 0 [Note] InnoDB: Buffer pool(s) load completed at 231030 16:36:50
2023-10-30 16:37:25 12 [Warning] Access denied for user 'root'@'localhost' (using password: YES)
2023-10-30 16:37:32 13 [Warning] Access denied for user 'root'@'localhost' (using password: YES)
2023-10-30 16:37:35 14 [Warning] Access denied for user 'root'@'localhost' (using password: YES)
2023-10-30 16:37:45 15 [Warning] Access denied for user 'root'@'localhost' (using password: YES)
2023-10-30 16:37:55 16 [Warning] Access denied for user 'root'@'localhost' (using password: YES)
2023-10-30 16:38:05 17 [Warning] Access denied for user 'root'@'localhost' (using password: YES)
2023-10-30 16:38:06 18 [Warning] Access denied for user 'root'@'localhost' (using password: YES)
2023-10-30 16:38:15 19 [Warning] Access denied for user 'root'@'localhost' (using password: YES)
2023-10-30 16:38:25 20 [Warning] Access denied for user 'root'@'localhost' (using password: YES)
2023-10-30 16:38:35 21 [Warning] Access denied for user 'root'@'localhost' (using password: YES)

Mauraza commented 1 year ago

Hi @jakuzure,

In both logs appear these lines:

2023-10-30 16:36:46 0 [Note] WSREP: access file(/bitnami/mariadb/data//gvwstate.dat) failed(No such file or directory)
2023-10-30 16:36:46 0 [Note] WSREP: restore pc from disk failed

It seems when the nodes are trying to access the previous data, the file doesn't appear and fails. Could you check if the node connected correctly has that file?

jakuzure commented 1 year ago

Hi @Mauraza,

I checked all pods and they have the file:

I have no name!@production-mariadb-2:/$ 1s -ahl/bitnami/mariadb/data/gwstate.dat
-rw-rw---- 1 1001 1001 267 Oct 30 16:46 /bitnami/mariadb/data/gwstate.dat

I just tried killing a pod that had the file, it also logged the error message and then apparently created the file again.

Mauraza commented 1 year ago

Hi @jakuzure,

Could you share how you deploy the chart and check if the PVC is recreated or using the same? When the pod tries to restore the data, it only checks if exists a specific folder, not the data.

jakuzure commented 1 year ago

Hi @Mauraza, we're deploying the helm chart via ArgoCD, the values we use are in the description. The same PVC is reused, the creation date is nearly a month in the past

Mauraza commented 1 year ago

Hi @jakuzure,

If you delete one pod, is it connected correctly, or show the same error? Are you using some storageClass or something with the creation of the PVC?

jakuzure commented 1 year ago

Hi @Mauraza, it then shows the same error. Sometimes a pod still works, but when it's restarted it also starts to fail. We use the default storageClass which creates a volume using the csi.vsphere.vmware.com provisioner

Mauraza commented 1 year ago

Hi @jakuzure,

Are there any events in the PVC or the deployment? I tried to reproduce it, but I couldn't.

github-actions[bot] commented 1 year ago

This Issue has been automatically marked as "stale" because it has not had recent activity (for 15 days). It will be closed if no further activity occurs. Thanks for the feedback.

jakuzure commented 12 months ago

Hi @jakuzure,

Are there any events in the PVC or the deployment? I tried to reproduce it, but I couldn't.

Hi @Mauraza, no, we can't see any events. It's seemingly happening randomly, so it's hard for us to reproduce as well, unfortunately

Mauraza commented 12 months ago

Hi @jakuzure,

As the error appears every 'x' amount of time may be related to the probe when that happens could you try to run this command and see if the environment variable is correct? https://github.com/bitnami/charts/blob/622fdb940f9bc3aef1217b71fd89f6fe1cc0c2f6/bitnami/mariadb-galera/templates/statefulset.yaml#L254-L262

github-actions[bot] commented 11 months ago

This Issue has been automatically marked as "stale" because it has not had recent activity (for 15 days). It will be closed if no further activity occurs. Thanks for the feedback.

jakuzure commented 11 months ago

Hi @Mauraza, thanks, we will try out the command next time it happens

Mauraza commented 11 months ago

I hope that gives us more information 🤞.

github-actions[bot] commented 10 months ago

This Issue has been automatically marked as "stale" because it has not had recent activity (for 15 days). It will be closed if no further activity occurs. Thanks for the feedback.

github-actions[bot] commented 10 months ago

Due to the lack of activity in the last 5 days since it was marked as "stale", we proceed to close this Issue. Do not hesitate to reopen it later if necessary.

bitnami / charts