Percona-xtradb-cluster-operator.v1.11.0 | MYSQL Backup failing with S3 storage

MySQL & MariaDB Percona Operator for MySQL
1

Hi Team,
Here is our environment details:
We have installed the Mysql cluster using the Percona-xtradb-cluster-operator in redhat Openshift cluster. I have configured to backup the database to S3 storage but it is failing to backup after certain time.
RedHat Openshift Version: 4.8.25
percona-xtradb-cluster-operator version: 1.11.0
MySQL DB version: mysql Ver 14.14 Distrib 5.7.35-38, for Linux (x86_64) using 7.0

Here is the Backup configuration updated in operator and which is creating job to run the backup and got executed as per the schedule and it is failed to complete.

backup:
Image: ‘percona/percona-xtradb-cluster-operator:1.11.0-pxc8.0-backup’
storages:
s3-backup:
type: s3
verifyTLS: false
s3:
bucket: mysql-staging-backup-b289c36b-a644-4e10-9c71-6494e3fbff3f
endpointUrl: ‘s3.openshift-storage.svc:443’
region: ocp1-mascot
credentialsSecret: mysql-staging-cluster-backup-s3
schedule:
- name: “daily-backup”
schedule: “0 13 * * *”
keep: 3
storageName: s3-backup
Can you please advise on this.

I am not able to attach the log file here.

Error Log:

  • GARBD_OPTS=
  • check_ssl
  • CA=/var/run/secrets/kubernetes.io/serviceaccount/ca.crt
  • ‘[’ -f /var/run/secrets/kubernetes.io/serviceaccount/service-ca.crt ‘]’
  • CA=/var/run/secrets/kubernetes.io/serviceaccount/service-ca.crt
  • SSL_DIR=/etc/mysql/ssl
  • ‘[’ -f /etc/mysql/ssl/ca.crt ‘]’
  • CA=/etc/mysql/ssl/ca.crt
  • SSL_INTERNAL_DIR=/etc/mysql/ssl-internal
  • ‘[’ -f /etc/mysql/ssl-internal/ca.crt ‘]’
  • CA=/etc/mysql/ssl-internal/ca.crt
  • KEY=/etc/mysql/ssl/tls.key
  • CERT=/etc/mysql/ssl/tls.crt
  • ‘[’ -f /etc/mysql/ssl-internal/tls.key -a -f /etc/mysql/ssl-internal/tls.crt ‘]’
  • KEY=/etc/mysql/ssl-internal/tls.key
  • CERT=/etc/mysql/ssl-internal/tls.crt
  • ‘[’ -f /etc/mysql/ssl-internal/ca.crt -a -f /etc/mysql/ssl-internal/tls.key -a -f /etc/mysql/ssl-internal/tls.crt ‘]’
  • GARBD_OPTS=‘socket.ssl_ca=/etc/mysql/ssl-internal/ca.crt;socket.ssl_cert=/etc/mysql/ssl-internal/tls.crt;socket.ssl_key=/etc/mysql/ssl-internal/tls.key;socket.ssl_cipher=;pc.weight=0;socket.ssl=YES;’
  • request_streaming
    ++ hostname -i
  • local LOCAL_IP=100.64.20.133
    ++ get_backup_source
    +++ peer-list -on-start=/usr/bin/get-pxc-state -service=mysql-staging-cluster-pxc
    +++ grep wsrep_cluster_size
    +++ sort
    +++ cut -d : -f 12
    +++ tail -1
    ++ CLUSTER_SIZE=5
    +++ peer-list -on-start=/usr/bin/get-pxc-state -service=mysql-staging-cluster-pxc
    +++ grep wsrep_ready:ON:wsrep_connected:ON:wsrep_local_state_comment:Synced:wsrep_cluster_status:Primary
    +++ sort -r
    +++ tail -1
    +++ cut -d : -f 2
    +++ cut -d . -f 1
    ++ FIRST_NODE=mysql-staging-cluster-pxc-0
    ++ SKIP_FIRST_POD=‘|’
    ++ (( 5 > 1 ))
    ++ SKIP_FIRST_POD=mysql-staging-cluster-pxc-0
    ++ peer-list -on-start=/usr/bin/get-pxc-state -service=mysql-staging-cluster-pxc
    ++ grep wsrep_ready:ON:wsrep_connected:ON:wsrep_local_state_comment:Synced:wsrep_cluster_status:Primary
    ++ grep -v mysql-staging-cluster-pxc-0
    ++ sort
    ++ tail -1
    ++ cut -d : -f 2
    ++ cut -d . -f 1
  • local NODE_NAME=mysql-staging-cluster-pxc-2
  • ‘[’ -z mysql-staging-cluster-pxc-2 ‘]’
  • set +o errexit
  • echo ‘[INFO] garbd was started’
    [INFO] garbd was started
  • garbd --address ‘gcomm://mysql-staging-cluster-pxc-2.mysql-staging-cluster-pxc?gmcast.listen_addr=tcp://0.0.0.0:4567’ --donor mysql-staging-cluster-pxc-2 --group mysql-staging-cluster-pxc --options ‘socket.ssl_ca=/etc/mysql/ssl-internal/ca.crt;socket.ssl_cert=/etc/mysql/ssl-internal/tls.crt;socket.ssl_key=/etc/mysql/ssl-internal/tls.key;socket.ssl_cipher=;pc.weight=0;socket.ssl=YES;’ --sst xtrabackup-v2:100.64.20.133:4444/xtrabackup_sst//1 --recv-script=/usr/bin/run_backup.sh
    2023-12-14 13:00:13.969 INFO: CRC-32C: using 64-bit x86 acceleration.
    2023-12-14 13:00:13.970 INFO: Read config:
    daemon: 0
    name: garb
    address: gcomm://mysql-staging-cluster-pxc-2.mysql-staging-cluster-pxc?gmcast.listen_addr=tcp://0.0.0.0:4567
    group: mysql-staging-cluster-pxc
    sst: xtrabackup-v2:100.64.20.133:4444/xtrabackup_sst//1
    donor: mysql-staging-cluster-pxc-2
    options: socket.ssl_ca=/etc/mysql/ssl-internal/ca.crt;socket.ssl_cert=/etc/mysql/ssl-internal/tls.crt;socket.ssl_key=/etc/mysql/ssl-internal/tls.key;socket.ssl_cipher=;pc.weight=0;socket.ssl=YES;; gcs.fc_limit=9999999; gcs.fc_factor=1.0; gcs.fc_master_slave=yes
    cfg:
    log:
    recv_script: /usr/bin/run_backup.sh

2023-12-14 13:00:13.970 WARN: Option ‘gcs.fc_master_slave’ is deprecated and will be removed in the future versions, please use ‘gcs.fc_single_primary’ instead.
2023-12-14 13:00:13.971 INFO: protonet asio version 0
2023-12-14 13:00:13.971 INFO: Using CRC-32C for message checksums.
2023-12-14 13:00:13.971 INFO: backend: asio
2023-12-14 13:00:13.972 INFO: gcomm thread scheduling priority set to other:0
2023-12-14 13:00:13.972 WARN: Fail to access the file (./gvwstate.dat) error (No such file or directory). It is possible if node is booting for first time or re-booting after a graceful shutdown
2023-12-14 13:00:13.972 INFO: Restoring primary-component from disk failed. Either node is booting for first time or re-booting after a graceful shutdown
2023-12-14 13:00:13.972 INFO: GMCast version 0
2023-12-14 13:00:13.973 INFO: (b8aa47c5-b446, ‘ssl://0.0.0.0:4567’) listening at ssl://0.0.0.0:4567
2023-12-14 13:00:13.973 INFO: (b8aa47c5-b446, ‘ssl://0.0.0.0:4567’) multicast: , ttl: 1
2023-12-14 13:00:13.974 INFO: EVS version 1
2023-12-14 13:00:13.974 INFO: gcomm: connecting to group ‘mysql-staging-cluster-pxc’, peer ‘mysql-staging-cluster-pxc-2.mysql-staging-cluster-pxc:’
2023-12-14 13:00:13.984 INFO: (b8aa47c5-b446, ‘ssl://0.0.0.0:4567’) connection established to 84304c2a-b522 ssl://100.64.18.184:4567
2023-12-14 13:00:13.984 INFO: (b8aa47c5-b446, ‘ssl://0.0.0.0:4567’) turning message relay requesting on, nonlive peers: ssl://100.64.20.196:4567 ssl://100.64.21.248:4567 ssl://100.64.22.41:4567 ssl://100.64.28.119:4567
2023-12-14 13:00:14.178 INFO: (b8aa47c5-b446, ‘ssl://0.0.0.0:4567’) connection established to 61364bf8-85b3 ssl://100.64.22.41:4567
2023-12-14 13:00:14.192 INFO: (b8aa47c5-b446, ‘ssl://0.0.0.0:4567’) connection established to 20433afd-be43 ssl://100.64.20.196:4567
2023-12-14 13:00:14.193 INFO: (b8aa47c5-b446, ‘ssl://0.0.0.0:4567’) connection established to a9287418-8d25 ssl://100.64.28.119:4567
2023-12-14 13:00:14.193 INFO: Deferred close timer started for socket with remote endpoint: ssl://100.64.28.119:50418
2023-12-14 13:00:14.193 INFO: (b8aa47c5-b446, ‘ssl://0.0.0.0:4567’) connection established to 20433afd-be43 ssl://100.64.20.196:4567
2023-12-14 13:00:14.193 INFO: Deferred close timer started for socket with remote endpoint: ssl://100.64.20.196:4567
2023-12-14 13:00:14.193 INFO: Deferred close timer handle_wait Operation aborted. for 0x1403c60
2023-12-14 13:00:14.194 INFO: Deferred close timer destruct
2023-12-14 13:00:14.194 INFO: Deferred close timer handle_wait Operation aborted. for 0x1402a70
2023-12-14 13:00:14.194 INFO: Deferred close timer destruct
2023-12-14 13:00:14.194 INFO: (b8aa47c5-b446, ‘ssl://0.0.0.0:4567’) connection established to a9287418-8d25 ssl://100.64.28.119:4567
2023-12-14 13:00:14.195 INFO: (b8aa47c5-b446, ‘ssl://0.0.0.0:4567’) connection established to 2f2918d7-b9dc ssl://100.64.21.248:4567
2023-12-14 13:00:14.196 INFO: (b8aa47c5-b446, ‘ssl://0.0.0.0:4567’) connection established to 2f2918d7-b9dc ssl://100.64.21.248:4567
2023-12-14 13:00:14.477 INFO: declaring 20433afd-be43 at ssl://100.64.20.196:4567 stable
2023-12-14 13:00:14.477 INFO: declaring 2f2918d7-b9dc at ssl://100.64.21.248:4567 stable
2023-12-14 13:00:14.477 INFO: declaring 61364bf8-85b3 at ssl://100.64.22.41:4567 stable
2023-12-14 13:00:14.477 INFO: declaring 84304c2a-b522 at ssl://100.64.18.184:4567 stable
2023-12-14 13:00:14.477 INFO: declaring a9287418-8d25 at ssl://100.64.28.119:4567 stable
2023-12-14 13:00:14.479 INFO: Node 20433afd-be43 state primary
2023-12-14 13:00:14.480 INFO: Current view of cluster as seen by this node
view (view_id(PRIM,20433afd-be43,47)
memb {
20433afd-be43,0
2f2918d7-b9dc,0
61364bf8-85b3,0
84304c2a-b522,0
a9287418-8d25,0
b8aa47c5-b446,0
}
joined {
}
left {
}
partitioned {
}
)
2023-12-14 13:00:14.480 INFO: Save the discovered primary-component to disk
2023-12-14 13:00:14.481 WARN: open file(./gvwstate.dat.tmp) failed(Permission denied)
2023-12-14 13:00:14.974 INFO: gcomm: connected
2023-12-14 13:00:14.974 INFO: Changing maximum packet size to 64500, resulting msg size: 32636
2023-12-14 13:00:14.975 INFO: Shifting CLOSED → OPEN (TO: 0)
2023-12-14 13:00:14.975 INFO: Opened channel ‘mysql-staging-cluster-pxc’
2023-12-14 13:00:14.975 INFO: New COMPONENT: primary = yes, bootstrap = no, my_idx = 5, memb_num = 6
2023-12-14 13:00:14.975 INFO: STATE EXCHANGE: Waiting for state UUID.
2023-12-14 13:00:17.475 INFO: (b8aa47c5-b446, ‘ssl://0.0.0.0:4567’) turning message relay requesting off
2023-12-14 13:00:17.740 INFO: (b8aa47c5-b446, ‘ssl://0.0.0.0:4567’) connection to peer 84304c2a-b522 with addr ssl://100.64.18.184:4567 timed out, no messages seen in PT3S, socket stats: rtt: 2440 rttvar: 4310 rto: 203000 lost: 0 last_data_recv: 3260 cwnd: 10 last_queued_since: 66256 last_delivered_since: 3260176680 send_queue_length: 1 send_queue_bytes: 804 segment: 0 messages: 1 (gmcast.peer_timeout)
2023-12-14 13:00:17.740 INFO: Deferred close timer started for socket with remote endpoint: ssl://100.64.18.184:4567
2023-12-14 13:00:17.740 INFO: (b8aa47c5-b446, ‘ssl://0.0.0.0:4567’) connection to peer a9287418-8d25 with addr ssl://100.64.28.119:4567 timed out, no messages seen in PT3S, socket stats: rtt: 666 rttvar: 873 rto: 201000 lost: 0 last_data_recv: 3260 cwnd: 10 last_queued_since: 43740 last_delivered_since: 3260361347 send_queue_length: 2 send_queue_bytes: 1460 segment: 0 messages: 2 (gmcast.peer_timeout)
2023-12-14 13:00:17.740 INFO: Deferred close timer started for socket with remote endpoint: ssl://100.64.28.119:4567
2023-12-14 13:00:17.740 INFO: (b8aa47c5-b446, ‘ssl://0.0.0.0:4567’) connection to peer 61364bf8-85b3 with addr ssl://100.64.22.41:4567 timed out, no messages seen in PT3S, socket stats: rtt: 2405 rttvar: 4200 rto: 203000 lost: 0 last_data_recv: 3260 cwnd: 10 last_queued_since: 21893 last_delivered_since: 3260048841 send_queue_length: 3 send_queue_bytes: 1968 segment: 0 messages: 3 (gmcast.peer_timeout)
2023-12-14 13:00:17.740 INFO: Deferred close timer started for socket with remote endpoint: ssl://100.64.22.41:48576
2023-12-14 13:00:17.740 INFO: (b8aa47c5-b446, ‘ssl://0.0.0.0:4567’) turning message relay requesting on, nonlive peers: ssl://100.64.18.184:4567 ssl://100.64.22.41:4567 ssl://100.64.28.119:4567
2023-12-14 13:00:17.741 INFO: Deferred close timer handle_wait Operation aborted. for 0x13e4770
2023-12-14 13:00:17.741 INFO: Deferred close timer destruct
2023-12-14 13:00:17.742 INFO: Deferred close timer handle_wait Operation aborted. for 0x1403600
2023-12-14 13:00:17.742 INFO: Deferred close timer destruct
2023-12-14 13:00:17.742 INFO: Deferred close timer handle_wait Operation aborted. for 0x13d1730
2023-12-14 13:00:17.742 INFO: Deferred close timer destruct
2023-12-14 13:00:18.975 INFO: (b8aa47c5-b446, ‘ssl://0.0.0.0:4567’) reconnecting to 84304c2a-b522 (ssl://100.64.18.184:4567), attempt 0
2023-12-14 13:00:18.975 INFO: (b8aa47c5-b446, ‘ssl://0.0.0.0:4567’) reconnecting to 61364bf8-85b3 (ssl://100.64.22.41:4567), attempt 0
2023-12-14 13:00:18.975 INFO: (b8aa47c5-b446, ‘ssl://0.0.0.0:4567’) reconnecting to a9287418-8d25 (ssl://100.64.28.119:4567), attempt 0
2023-12-14 13:00:19.948 INFO: (b8aa47c5-b446, ‘ssl://0.0.0.0:4567’) connection established to 61364bf8-85b3 ssl://100.64.22.41:4567
2023-12-14 13:00:19.981 INFO: declaring node with index 2 suspected, timeout PT5S (evs.suspect_timeout)
2023-12-14 13:00:19.981 INFO: declaring node with index 3 suspected, timeout PT5S (evs.suspect_timeout)
2023-12-14 13:00:19.981 INFO: declaring node with index 4 suspected, timeout PT5S (evs.suspect_timeout)
2023-12-14 13:00:19.981 INFO: evs::proto(b8aa47c5-b446, GATHER, view_id(REG,20433afd-be43,47)) suspecting node: 61364bf8-85b3
2023-12-14 13:00:19.981 INFO: evs::proto(b8aa47c5-b446, GATHER, view_id(REG,20433afd-be43,47)) suspected node without join message, declaring inactive
2023-12-14 13:00:19.981 INFO: evs::proto(b8aa47c5-b446, GATHER, view_id(REG,20433afd-be43,47)) suspecting node: 84304c2a-b522
2023-12-14 13:00:19.981 INFO: evs::proto(b8aa47c5-b446, GATHER, view_id(REG,20433afd-be43,47)) suspected node without join message, declaring inactive
2023-12-14 13:00:19.981 INFO: evs::proto(b8aa47c5-b446, GATHER, view_id(REG,20433afd-be43,47)) suspecting node: a9287418-8d25
2023-12-14 13:00:19.981 INFO: evs::proto(b8aa47c5-b446, GATHER, view_id(REG,20433afd-be43,47)) suspected node without join message, declaring inactive
2023-12-14 13:00:20.010 INFO: (b8aa47c5-b446, ‘ssl://0.0.0.0:4567’) connection established to 84304c2a-b522 ssl://100.64.18.184:4567
2023-12-14 13:00:20.482 INFO: declaring node with index 2 inactive (evs.inactive_timeout)
2023-12-14 13:00:20.482 INFO: declaring node with index 3 inactive (evs.inactive_timeout)
2023-12-14 13:00:20.482 INFO: declaring node with index 4 inactive (evs.inactive_timeout)
2023-12-14 13:00:20.483 INFO: Current view of cluster as seen by this node
view (view_id(NON_PRIM,20433afd-be43,47)
memb {
20433afd-be43,0
2f2918d7-b9dc,0
b8aa47c5-b446,0
}
joined {
}
left {
}
partitioned {
61364bf8-85b3,0
84304c2a-b522,0
a9287418-8d25,0
}
)
2023-12-14 13:00:20.483 INFO: New COMPONENT: primary = no, bootstrap = no, my_idx = 2, memb_num = 32023-12-14 13:00:20.483 INFO: EVS version upgrade 0 → 1

2023-12-14 13:00:20.483 INFO: declaring 20433afd-be43 at ssl://100.64.20.196:4567 stable
2023-12-14 13:00:20.484 INFO: declaring 2f2918d7-b9dc at ssl://100.64.21.248:4567 stable
2023-12-14 13:00:20.484 INFO: PC protocol upgrade 0 → 1
2023-12-14 13:00:20.484 INFO: Flow-control interval: [14142134, 14142134]
2023-12-14 13:00:20.484 INFO: Received NON-PRIMARY.
2023-12-14 13:00:20.488 INFO: Current view of cluster as seen by this node
view (view_id(NON_PRIM,20433afd-be43,48)
memb {
20433afd-be43,0
2f2918d7-b9dc,0
b8aa47c5-b446,0
}
joined {
}
left {
}
partitioned {
61364bf8-85b3,0
84304c2a-b522,0
a9287418-8d25,0
}
)
2023-12-14 13:00:20.488 INFO: New COMPONENT: primary = no, bootstrap = no, my_idx = 2, memb_num = 3
2023-12-14 13:00:20.488 INFO: Flow-control interval: [14142134, 14142134]
2023-12-14 13:00:20.488 INFO: Received NON-PRIMARY.
2023-12-14 13:00:20.616 INFO: (b8aa47c5-b446, ‘ssl://0.0.0.0:4567’) connection established to a9287418-8d25 ssl://100.64.28.119:4567
2023-12-14 13:00:21.487 INFO: Current view of cluster as seen by this node
view (view_id(NON_PRIM,20433afd-be43,48)
memb {
20433afd-be43,0
2f2918d7-b9dc,0
b8aa47c5-b446,0
}
joined {
}
left {
}
partitioned {
61364bf8-85b3,0
84304c2a-b522,0
a9287418-8d25,0
}
)
2023-12-14 13:00:21.487 INFO: EVS version downgrade 1 → 0
2023-12-14 13:00:21.487 INFO: declaring 20433afd-be43 at ssl://100.64.20.196:4567 stable
2023-12-14 13:00:21.487 INFO: New COMPONENT: primary = no, bootstrap = no, my_idx = 2, memb_num = 3
2023-12-14 13:00:21.487 INFO: declaring 2f2918d7-b9dc at ssl://100.64.21.248:4567 stable
2023-12-14 13:00:21.487 INFO: declaring 61364bf8-85b3 at ssl://100.64.22.41:4567 stable
2023-12-14 13:00:21.487 INFO: declaring 84304c2a-b522 at ssl://100.64.18.184:4567 stable
2023-12-14 13:00:21.487 INFO: Flow-control interval: [14142134, 14142134]
2023-12-14 13:00:21.487 INFO: Received NON-PRIMARY.
2023-12-14 13:00:21.487 INFO: PC protocol downgrade 1 → 0
2023-12-14 13:00:21.489 INFO: Current view of cluster as seen by this node
view (view_id(NON_PRIM,20433afd-be43,49)
memb {
20433afd-be43,0
2f2918d7-b9dc,0
61364bf8-85b3,0
84304c2a-b522,0
b8aa47c5-b446,0
}
joined {
}
left {
}
partitioned {
a9287418-8d25,0
}
)
2023-12-14 13:00:23.115 INFO: Save the discovered primary-component to disk
2023-12-14 13:00:23.115 WARN: open file(./gvwstate.dat.tmp) failed(Permission denied)
2023-12-14 13:00:23.115 INFO: New COMPONENT: primary = yes, bootstrap = no, my_idx = 5, memb_num = 6
2023-12-14 13:00:23.115 INFO: STATE EXCHANGE: Waiting for state UUID.
2023-12-14 13:00:23.976 INFO: (b8aa47c5-b446, ‘ssl://0.0.0.0:4567’) turning message relay requesting off
2023-12-14 13:00:24.742 INFO: STATE EXCHANGE: sent state msg: be1d7a41-9a80-11ee-8466-72ffad2d6744
2023-12-14 13:00:24.744 INFO: STATE EXCHANGE: got state msg: be1d7a41-9a80-11ee-8466-72ffad2d6744 from 0 (garb)
2023-12-14 13:00:24.744 INFO: STATE EXCHANGE: got state msg: be1d7a41-9a80-11ee-8466-72ffad2d6744 from 1 (garb)
2023-12-14 13:00:24.745 INFO: STATE EXCHANGE: got state msg: be1d7a41-9a80-11ee-8466-72ffad2d6744 from 2 (mysql-staging-cluster-pxc-0)
2023-12-14 13:00:24.745 INFO: STATE EXCHANGE: got state msg: be1d7a41-9a80-11ee-8466-72ffad2d6744 from 4 (mysql-staging-cluster-pxc-1)
2023-12-14 13:00:24.745 INFO: STATE EXCHANGE: got state msg: be1d7a41-9a80-11ee-8466-72ffad2d6744 from 5 (garb)
2023-12-14 13:00:24.745 INFO: STATE EXCHANGE: got state msg: be1d7a41-9a80-11ee-8466-72ffad2d6744 from 3 (mysql-staging-cluster-pxc-2)
2023-12-14 13:00:24.745 WARN: Quorum: No node with complete state:

Version      : 6
Flags        : 0x9
Protocols    : 2 / 127 / 127
State        : NON-PRIMARY
Desync count : 0
Prim state   : JOINER
Prim UUID    : 2f76a954-99ba-11ee-8258-822509749f6f
Prim  seqno  : 42
First seqno  : -1
Last  seqno  : 30317
Commit cut   : 0
Last vote    : -1.0
Vote policy  : 0
Prim JOINED  : 3
State UUID   : be1d7a41-9a80-11ee-8466-72ffad2d6744
Group UUID   : c8513475-cf7a-11ed-9cea-ab99bc538d2d
Name         : 'garb'
Incoming addr: ''

Version      : 6
Flags        : 0x8
Protocols    : 2 / 127 / 127
State        : NON-PRIMARY
Desync count : 0
Prim state   : JOINER
Prim UUID    : 2f76a954-99ba-11ee-8258-822509749f6f
Prim  seqno  : 42
First seqno  : -1
Last  seqno  : 30317
Commit cut   : 0
Last vote    : -1.0
Vote policy  : 0
Prim JOINED  : 3
State UUID   : be1d7a41-9a80-11ee-8466-72ffad2d6744
Group UUID   : c8513475-cf7a-11ed-9cea-ab99bc538d2d
Name         : 'garb'
Incoming addr: ''

Version      : 6
Flags        : 0x2
Protocols    : 0 / 9 / 3
State        : NON-PRIMARY
Desync count : 0
Prim state   : SYNCED
Prim UUID    : 2f76a954-99ba-11ee-8258-822509749f6f
Prim  seqno  : 42
First seqno  : -1
Last  seqno  : 30317
Commit cut   : 0
Last vote    : 0.0
Vote policy  : 1
Prim JOINED  : 3
State UUID   : be1d7a41-9a80-11ee-8466-72ffad2d6744
Group UUID   : c8513475-cf7a-11ed-9cea-ab99bc538d2d
Name         : 'mysql-staging-cluster-pxc-0'
Incoming addr: 'mysql-staging-cluster-pxc-0.mysql-staging-cluster-pxc.mysql-staging.svc.cluster.local:3306'

Version      : 6
Flags        : 0x2
Protocols    : 0 / 9 / 3
State        : NON-PRIMARY
Desync count : 0
Prim state   : SYNCED
Prim UUID    : 2f76a954-99ba-11ee-8258-822509749f6f
Prim  seqno  : 42
First seqno  : -1
Last  seqno  : 30317
Commit cut   : 0
Last vote    : 0.0
Vote policy  : 1
Prim JOINED  : 3
State UUID   : be1d7a41-9a80-11ee-8466-72ffad2d6744
Group UUID   : c8513475-cf7a-11ed-9cea-ab99bc538d2d
Name         : 'mysql-staging-cluster-pxc-2'
Incoming addr: 'mysql-staging-cluster-pxc-2.mysql-staging-cluster-pxc.mysql-staging.svc.cluster.local:3306'

Version      : 6
Flags        : 0x2
Protocols    : 0 / 9 / 3
State        : NON-PRIMARY
Desync count : 0
Prim state   : SYNCED
Prim UUID    : 2f76a954-99ba-11ee-8258-822509749f6f
Prim  seqno  : 42
First seqno  : -1
Last  seqno  : 30317
Commit cut   : 0
Last vote    : 0.0
Vote policy  : 1
Prim JOINED  : 3
State UUID   : be1d7a41-9a80-11ee-8466-72ffad2d6744
Group UUID   : c8513475-cf7a-11ed-9cea-ab99bc538d2d
Name         : 'mysql-staging-cluster-pxc-1'
Incoming addr: 'mysql-staging-cluster-pxc-1.mysql-staging-cluster-pxc.mysql-staging.svc.cluster.local:3306'

Version      : 6
Flags        : 0x8
Protocols    : 2 / 127 / 127
State        : NON-PRIMARY
Desync count : 0
Prim state   : NON-PRIMARY
Prim UUID    : 00000000-0000-0000-0000-000000000000
Prim  seqno  : -1
First seqno  : -1
Last  seqno  : -1
Commit cut   : -1
Last vote    : -1.0
Vote policy  : 0
Prim JOINED  : 0
State UUID   : be1d7a41-9a80-11ee-8466-72ffad2d6744
Group UUID   : 00000000-0000-0000-0000-000000000000
Name         : 'garb'
Incoming addr: ''

2023-12-14 13:00:24.745 INFO: Full re-merge of primary 2f76a954-99ba-11ee-8258-822509749f6f found: 3 of 3.
2023-12-14 13:00:24.745 INFO: Quorum results:
version = 6,
component = PRIMARY,
conf_id = 42,
members = 3/6 (primary/total),
act_id = 30317,
last_appl. = 0,
protocols = 0/9/3 (gcs/repl/appl),
vote policy= 1,
group UUID = c8513475-cf7a-11ed-9cea-ab99bc538d2d
2023-12-14 13:00:24.745 INFO: Flow-control interval: [17320506, 17320506]
2023-12-14 13:00:24.745 INFO: Shifting OPEN → PRIMARY (TO: 30317)
2023-12-14 13:00:24.745 INFO: Sending state transfer request: ‘xtrabackup-v2:100.64.20.133:4444/xtrabackup_sst//1’, size: 50
2023-12-14 13:00:24.746 INFO: Member 5.0 (garb) requested state transfer from ‘mysql-staging-cluster-pxc-2’. Selected 3.0 (mysql-staging-cluster-pxc-2)(SYNCED) as donor.
2023-12-14 13:00:24.747 INFO: Shifting PRIMARY → JOINER (TO: 30317)
2023-12-14 13:00:24.747 INFO: Starting SST script
2023-12-14 13:00:24.753 INFO: [SST script] + LIB_PATH=/usr/lib/pxc

2023-12-14 13:00:24.753 INFO: [SST script] + . /usr/lib/pxc/vault.sh

2023-12-14 13:00:24.753 INFO: [SST script] ++ set -o errexit

2023-12-14 13:00:24.753 INFO: [SST script] ++ keyring_vault=/etc/mysql/vault-keyring-secret/keyring_vault.conf

2023-12-14 13:00:24.753 INFO: [SST script] + SOCAT_OPTS=TCP-LISTEN:4444,reuseaddr,retry=30

2023-12-14 13:00:24.754 INFO: [SST script] + SST_INFO_NAME=sst_info

2023-12-14 13:00:24.754 INFO: [SST script] + INSECURE_ARG=

2023-12-14 13:00:24.754 INFO: [SST script] + ‘[’ -n false ‘]’

2023-12-14 13:00:24.754 INFO: [SST script] + [[ false == \f\a\l\s\e ]]

2023-12-14 13:00:24.754 INFO: [SST script] + INSECURE_ARG=–insecure

2023-12-14 13:00:24.754 INFO: [SST script] + FIRST_RECEIVED=0

2023-12-14 13:00:24.754 INFO: [SST script] + SST_FAILED=0

2023-12-14 13:00:24.755 INFO: [SST script] + check_ssl

2023-12-14 13:00:24.755 INFO: [SST script] + CA=/var/run/secrets/kubernetes.io/serviceaccount/ca.crt

2023-12-14 13:00:24.755 INFO: [SST script] + ‘[’ -f /var/run/secrets/kubernetes.io/serviceaccount/service-ca.crt ‘]’

2023-12-14 13:00:24.755 INFO: [SST script] + CA=/var/run/secrets/kubernetes.io/serviceaccount/service-ca.crt

2023-12-14 13:00:24.755 INFO: [SST script] + SSL_DIR=/etc/mysql/ssl

2023-12-14 13:00:24.755 INFO: [SST script] + ‘[’ -f /etc/mysql/ssl/ca.crt ‘]’

2023-12-14 13:00:24.755 INFO: [SST script] + CA=/etc/mysql/ssl/ca.crt

2023-12-14 13:00:24.755 INFO: [SST script] + SSL_INTERNAL_DIR=/etc/mysql/ssl-internal

2023-12-14 13:00:24.755 INFO: [SST script] + ‘[’ -f /etc/mysql/ssl-internal/ca.crt ‘]’

2023-12-14 13:00:24.755 INFO: [SST script] + CA=/etc/mysql/ssl-internal/ca.crt

2023-12-14 13:00:24.755 INFO: [SST script] + KEY=/etc/mysql/ssl/tls.key

2023-12-14 13:00:24.755 INFO: [SST script] + CERT=/etc/mysql/ssl/tls.crt

2023-12-14 13:00:24.755 INFO: [SST script] + ‘[’ -f /etc/mysql/ssl-internal/tls.key -a -f /etc/mysql/ssl-internal/tls.crt ‘]’

2023-12-14 13:00:24.755 INFO: [SST script] + KEY=/etc/mysql/ssl-internal/tls.key

2023-12-14 13:00:24.755 INFO: [SST script] + CERT=/etc/mysql/ssl-internal/tls.crt

2023-12-14 13:00:24.755 INFO: [SST script] + ‘[’ -f /etc/mysql/ssl-internal/ca.crt -a -f /etc/mysql/ssl-internal/tls.key -a -f /etc/mysql/ssl-internal/tls.crt ‘]’

2023-12-14 13:00:24.755 INFO: [SST script] + SOCAT_OPTS=openssl-listen:4444,reuseaddr,cert=/etc/mysql/ssl-internal/tls.crt,key=/etc/mysql/ssl-internal/tls.key,cafile=/etc/mysql/ssl-internal/ca.crt,verify=1,retry=30

2023-12-14 13:00:24.755 INFO: [SST script] + trap handle_sigint 2

2023-12-14 13:00:24.755 INFO: [SST script] + ‘[’ -n mysql-staging-backup-b289c36b-a644-4e10-9c71-6494e3fbff3f ‘]’

2023-12-14 13:00:24.755 INFO: [SST script] + backup_s3

2023-12-14 13:00:24.756 INFO: [SST script] + S3_BUCKET_PATH=mysql-staging-cluster-2023-12-14-13:00:00-full

2023-12-14 13:00:24.756 INFO: [SST script] + CURL_RET_ERRORS_ARG=–curl-retriable-errors=7

2023-12-14 13:00:24.756 INFO: [SST script] + echo ‘Backup to s3://mysql-staging-backup-b289c36b-a644-4e10-9c71-6494e3fbff3f/mysql-staging-cluster-2023-12-14-13:00:00-full started’

2023-12-14 13:00:24.756 INFO: [SST script] Backup to s3://mysql-staging-backup-b289c36b-a644-4e10-9c71-6494e3fbff3f/mysql-staging-cluster-2023-12-14-13:00:00-full started

2023-12-14 13:00:24.756 INFO: [SST script] + mc -C /tmp/mc --insecure config host add dest https://s3.openshift-storage.svc:443 ACCESS_KEY_ID SECRET_ACCESS_KEY

2023-12-14 13:00:24.938 INFO: [SST script] Added dest successfully.

2023-12-14 13:00:24.941 INFO: [SST script] + is_object_exist mysql-staging-backup-b289c36b-a644-4e10-9c71-6494e3fbff3f mysql-staging-cluster-2023-12-14-13:00:00-full.sst_info

2023-12-14 13:00:24.941 INFO: [SST script] + local bucket=mysql-staging-backup-b289c36b-a644-4e10-9c71-6494e3fbff3f

2023-12-14 13:00:24.941 INFO: [SST script] + local object=mysql-staging-cluster-2023-12-14-13:00:00-full.sst_info

2023-12-14 13:00:24.942 INFO: [SST script] ++ mc -C /tmp/mc --insecure --json ls dest/mysql-staging-backup-b289c36b-a644-4e10-9c71-6494e3fbff3f/mysql-staging-cluster-2023-12-14-13:00:00-full.sst_info

2023-12-14 13:00:24.942 INFO: [SST script] ++ jq .status

2023-12-14 13:00:50.171 INFO: [SST script] + [[ -n ‘’ ]]

2023-12-14 13:00:50.171 INFO: [SST script] + is_object_exist mysql-staging-backup-b289c36b-a644-4e10-9c71-6494e3fbff3f mysql-staging-cluster-2023-12-14-13:00:00-full

2023-12-14 13:00:50.171 INFO: [SST script] + local bucket=mysql-staging-backup-b289c36b-a644-4e10-9c71-6494e3fbff3f

2023-12-14 13:00:50.171 INFO: [SST script] + local object=mysql-staging-cluster-2023-12-14-13:00:00-full

2023-12-14 13:00:50.172 INFO: [SST script] ++ mc -C /tmp/mc --insecure --json ls dest/mysql-staging-backup-b289c36b-a644-4e10-9c71-6494e3fbff3f/mysql-staging-cluster-2023-12-14-13:00:00-full

2023-12-14 13:00:50.172 INFO: [SST script] ++ jq .status

2023-12-14 13:00:53.180 INFO: [SST script] + [[ -n ‘’ ]]

2023-12-14 13:00:53.180 INFO: [SST script] + socat -u openssl-listen:4444,reuseaddr,cert=/etc/mysql/ssl-internal/tls.crt,key=/etc/mysql/ssl-internal/tls.key,cafile=/etc/mysql/ssl-internal/ca.crt,verify=1,retry=30 stdio

2023-12-14 13:00:53.181 INFO: [SST script] + wait 380

2023-12-14 13:00:53.181 INFO: [SST script] + xbstream -x -C /tmp

2023-12-14 13:00:53.356 INFO: [SST script] Socat was started

2023-12-14 13:00:53.356 INFO: [SST script] + echo ‘Socat was started’

2023-12-14 13:00:53.356 INFO: [SST script] + FIRST_RECEIVED=1

2023-12-14 13:00:53.356 INFO: [SST script] + [[ 0 -ne 0 ]]

2023-12-14 13:00:53.356 INFO: [SST script] + vault_store /tmp/sst_info

2023-12-14 13:00:53.357 INFO: [SST script] + local sst_info=/tmp/sst_info

2023-12-14 13:00:53.357 INFO: [SST script] + ‘[’ ‘!’ -f /etc/mysql/vault-keyring-secret/keyring_vault.conf ‘]’

2023-12-14 13:00:53.357 INFO: [SST script] + echo ‘vault configuration not found’

2023-12-14 13:00:53.357 INFO: [SST script] vault configuration not found

2023-12-14 13:00:53.357 INFO: [SST script] + return 0

2023-12-14 13:00:53.357 INFO: [SST script] + xbstream -C /tmp -c sst_info

2023-12-14 13:00:53.358 INFO: [SST script] + xbcloud put --curl-retriable-errors=7 --insecure --storage=s3 --parallel=10 --md5 --s3-bucket=mysql-staging-backup-b289c36b-a644-4e10-9c71-6494e3fbff3f mysql-staging-cluster-2023-12-14-13:00:00-full.sst_info

2023-12-14 13:00:53.358 INFO: [SST script] + grep -v ‘error: http request failed: Couldn’'‘t resolve host name’

2023-12-14 13:00:57.293 INFO: [SST script] 231214 13:00:54 xbcloud: Successfully connected.

2023-12-14 13:00:57.293 INFO: [SST script] 231214 13:00:57 xbcloud: successfully uploaded chunk: mysql-staging-cluster-2023-12-14-13:00:00-full.sst_info/sst_info.00000000000000000001, size: 22

2023-12-14 13:00:57.293 INFO: [SST script] 231214 13:00:57 xbcloud: Upload failed: backup is incomplete.
2023-12-14 13:24:12.010 INFO: [SST script] 231214 13:24:02 xbcloud: successfully uploaded chunk: mysql-staging-cluster-2023-12-14-13:00:00-full/backup-my.cnf.00000000000000000000, size: 541

2023-12-14 13:24:12.010 INFO: [SST script] 231214 13:24:11 xbcloud: Upload failed: backup is incomplete.

2023-12-14 13:24:12.011 INFO: [SST script] ++ handle_sigint

2023-12-14 13:24:12.011 INFO: [SST script] ++ (( 0 == 0 ))

2023-12-14 13:24:12.012 INFO: [SST script] +++ ps -C socat -o pid=

2023-12-14 13:24:12.294 INFO: [SST script] +++ true

2023-12-14 13:24:12.295 INFO: [SST script] ++ pid_s=

2023-12-14 13:24:12.295 INFO: [SST script] ++ ‘[’ -n ‘’ ‘]’

2023-12-14 13:24:12.295 INFO: [SST script] ++ echo ‘SST request was finished’

2023-12-14 13:24:12.295 INFO: [SST script] + FIRST_RECEIVED=1

2023-12-14 13:24:12.295 INFO: [SST script] + echo ‘Backup finished’

2023-12-14 13:24:12.295 INFO: [SST script] + mc -C /tmp/mc stat --insecure dest/mysql-staging-backup-b289c36b-a644-4e10-9c71-6494e3fbff3f/mysql-staging-cluster-2023-12-14-13:00:00-full.md5

2023-12-14 13:24:12.295 INFO: [SST script] SST request was finished

2023-12-14 13:24:12.295 INFO: [SST script] Backup finished

2023-12-14 13:24:12.499 INFO: [SST script] mc: Unable to stat dest/mysql-staging-backup-b289c36b-a644-4e10-9c71-6494e3fbff3f/mysql-staging-cluster-2023-12-14-13:00:00-full.md5. Object does not exist.

2023-12-14 13:24:12.502 INFO: SST script ended
2023-12-14 13:24:12.502 INFO: Closing send monitor…
2023-12-14 13:24:12.502 INFO: Closed send monitor.
2023-12-14 13:24:12.502 INFO: gcomm: terminating thread
2023-12-14 13:24:12.502 INFO: gcomm: joining thread
2023-12-14 13:24:12.502 INFO: gcomm: closing backend
2023-12-14 13:24:12.504 INFO: Current view of cluster as seen by this node
view (view_id(NON_PRIM,20433afd-be43,50)
memb {
b8aa47c5-b446,0
}
joined {
}
left {
}
partitioned {
20433afd-be43,0
2f2918d7-b9dc,0
61364bf8-85b3,0
84304c2a-b522,0
a9287418-8d25,0
}
)
2023-12-14 13:24:12.504 INFO: Current view of cluster as seen by this node
view ((empty))
2023-12-14 13:24:12.504 INFO: gcomm: closed
2023-12-14 13:24:12.504 INFO: New COMPONENT: primary = no, bootstrap = no, my_idx = 0, memb_num = 1
2023-12-14 13:24:12.504 INFO: Flow-control interval: [0, 0]
2023-12-14 13:24:12.504 INFO: Received NON-PRIMARY.
2023-12-14 13:24:12.504 INFO: Shifting JOINER → OPEN (TO: 30317)
2023-12-14 13:24:12.504 INFO: New SELF-LEAVE.
2023-12-14 13:24:12.504 INFO: Flow-control interval: [0, 0]
2023-12-14 13:24:12.504 INFO: Received SELF-LEAVE. Closing connection.
2023-12-14 13:24:12.504 INFO: Shifting OPEN → CLOSED (TO: 30317)
2023-12-14 13:24:12.504 INFO: RECV thread exiting 0: Success
2023-12-14 13:24:12.505 INFO: Waiting for SST script to stop
2023-12-14 13:24:12.505 INFO: SST script stopped
2023-12-14 13:24:12.505 INFO: recv_thread() joined.
2023-12-14 13:24:12.505 INFO: Closing replication queue.
2023-12-14 13:24:12.505 INFO: Closing slave action queue.
2023-12-14 13:24:12.505 INFO: Exiting main loop
Process completed with error: /usr/bin/run_backup.sh: 1 (Operation not permitted)+ EXID_CODE=1

  • echo ‘[INFO] garbd was finished’
    [INFO] garbd was finished
  • ‘[’ -f /tmp/backup-is-completed ‘]’
  • exit 1
2

Hi @santosh240 the problem is:

2023-12-14 13:24:12.499 INFO: [SST script] mc: Unable to stat dest/mysql-staging-backup-b289c36b-a644-4e10-9c71-6494e3fbff3f/mysql-staging-cluster-2023-12-14-13:00:00-full.md5 . Object does not exist.

Can you check this bucket? Do you have “*.md5” or no?

3

Hi @Slava_Sarzhan,

There is no .md5 file in the bucket as backup is failed. We have resolved the issue.
The issue is with the image version used for backup as mysql version is 5.7 but I was using version 8 backup image.

4

Ok, thanks for info.