Failed with result 'signal'- Failed to start Percona XtraDB Cluster - mysql may be already dead

Hi
Facing the below error when starting the mysql (node3),node 1 and node 2 are online.

> root@Node3:/etc/mysql/mysql.conf.d# `service mysql start`
> Job for mysql.service failed because a fatal signal was delivered to the control process.
> See "systemctl status mysql.service" and "journalctl -xe" for details.
> root@Node3:/etc/mysql/mysql.conf.d#` systemctl status mysql.service`
> ● mysql.service - Percona XtraDB Cluster
>    Loaded: loaded (/lib/systemd/system/mysql.service; enabled; vendor preset: enabled)
>    Active: failed (Result: signal) since Fri 2021-04-02 02:10:06 IST; 9s ago
>   Process: 9172 ExecStopPost=/usr/bin/mysql-systemd stop-post (code=exited, status=0/SUCCESS)
>   Process: 4621 ExecStop=/usr/bin/mysql-systemd stop (code=exited, status=0/SUCCESS)
>   Process: 2865 ExecStartPost=/usr/bin/mysql-systemd start-post $MAINPID (code=exited, status=0/SUCCESS)
>   Process: 2863 ExecStartPost=/bin/sh -c systemctl unset-environment _WSREP_START_POSITION (code=exited, status=0/SUCCESS)
>   Process: 8555 ExecStart=/usr/sbin/mysqld $_WSREP_START_POSITION (code=killed, signal=ABRT)
>   Process: 8462 ExecStartPre=/bin/sh -c VAR=`bash /usr/bin/mysql-systemd galera-recovery`; [ $? -eq 0 ] && systemctl set-environment _WSREP_START_POSITION=$VAR || exit 1 (code=exited, s
>   Process: 8458 ExecStartPre=/bin/sh -c systemctl unset-environment _WSREP_START_POSITION (code=exited, status=0/SUCCESS)
>   Process: 8428 ExecStartPre=/usr/bin/mysql-systemd check-grastate (code=exited, status=0/SUCCESS)
>   Process: 8327 ExecStartPre=/usr/bin/mysql-systemd start-pre (code=exited, status=0/SUCCESS)
>  Main PID: 8555 (code=killed, signal=ABRT)
>    Status: "Server startup in progress"
> 
> Apr 02 02:09:34 Node3 systemd[1]: Starting Percona XtraDB Cluster...
> Apr 02 02:10:06 Node3 systemd[1]: mysql.service: Main process exited, code=killed, status=6/ABRT
> Apr 02 02:10:06 Node3 mysql-systemd[9172]:  WARNING: mysql pid file /var/run/mysqld/mysqld.pid empty or not readable
> Apr 02 02:10:06 Node3 mysql-systemd[9172]:  WARNING: mysql may be already dead
> Apr 02 02:10:06 Node3 systemd[1]: mysql.service: Failed with result 'signal'.
> Apr 02 02:10:06 Node3 systemd[1]: Failed to start Percona XtraDB Cluster.
> lines 1-21/21 (END)
> [4]+  Stopped                 systemctl status mysql.service

Error Log file

> root@Node3:/etc/mysql/mysql.conf.d# tail -n 100 /var/log/mysql/error.log
> 2021-04-02T01:59:15.184556+05:30 0 [Note] [MY-000000] [Galera] Quorum results:
>         version    = 6,
>         component  = PRIMARY,
>         conf_id    = 50,
>         members    = 2/3 (primary/total),
>         act_id     = 89369,
>         last_appl. = 540,
>         protocols  = 2/10/4 (gcs/repl/appl),
>         vote policy= 0,
>         group UUID = 3788d9c7-141e-11eb-969b-da352344b906
> 2021-04-02T01:59:15.184792+05:30 0 [Note] [MY-000000] [Galera] Votes over 3788d9c7-141e-11eb-969b-da352344b906:653:
>    0000000000000000:   1/2
> Winner: 0000000000000000
> 2021-04-02T01:59:15.185051+05:30 0 [Note] [MY-000000] [Galera] Flow-control interval: [173, 173]
> 2021-04-02T01:59:15.185308+05:30 0 [Note] [MY-000000] [Galera] Shifting OPEN -> PRIMARY (TO: 89370)
> 2021-04-02T01:59:15.185587+05:30 1 [Note] [MY-000000] [Galera] ####### processing CC 89370, local, ordered
> 2021-04-02T01:59:15.185819+05:30 1 [Note] [MY-000000] [Galera] Maybe drain monitors from -1 upto current CC event 89370 upto:-1
> 2021-04-02T01:59:15.186045+05:30 1 [Note] [MY-000000] [Galera] Drain monitors from -1 up to -1
> 2021-04-02T01:59:15.186281+05:30 1 [Note] [MY-000000] [Galera] Process first view: 3788d9c7-141e-11eb-969b-da352344b906 my uuid: ec8ff475-9328-11eb-8575-c69fd0443f0c
> 2021-04-02T01:59:15.186543+05:30 1 [Note] [MY-000000] [Galera] Server pxc3 connected to cluster at position 3788d9c7-141e-11eb-969b-da352344b906:89370 with ID ec8ff475-9328-11eb-8575-c69fd0443f0c
> 2021-04-02T01:59:15.186811+05:30 1 [Note] [MY-000000] [WSREP] Server status change disconnected -> connected
> 2021-04-02T01:59:15.187089+05:30 1 [Note] [MY-000000] [WSREP] wsrep_notify_cmd is not defined, skipping notification.
> 2021-04-02T01:59:15.187400+05:30 1 [Note] [MY-000000] [Galera] ####### My UUID: ec8ff475-9328-11eb-8575-c69fd0443f0c
> 2021-04-02T01:59:15.187709+05:30 1 [Note] [MY-000000] [Galera] Cert index reset to 00000000-0000-0000-0000-000000000000:-1 (proto: 10), state transfer needed: yes
> 2021-04-02T01:59:15.188039+05:30 0 [Note] [MY-000000] [Galera] Service thread queue flushed.
> 2021-04-02T01:59:15.188347+05:30 1 [Note] [MY-000000] [Galera] ####### Assign initial position for certification: 00000000-0000-0000-0000-000000000000:-1, protocol version: -1
> 2021-04-02T01:59:15.188631+05:30 1 [Note] [MY-000000] [Galera] State transfer required:
>         Group state: 3788d9c7-141e-11eb-969b-da352344b906:89370
>         Local state: 00000000-0000-0000-0000-000000000000:-1
> 2021-04-02T01:59:15.188919+05:30 1 [Note] [MY-000000] [WSREP] Server status change connected -> joiner
> 2021-04-02T01:59:15.189215+05:30 1 [Note] [MY-000000] [WSREP] wsrep_notify_cmd is not defined, skipping notification.
> 2021-04-02T01:59:15.189609+05:30 0 [Note] [MY-000000] [WSREP] Initiating SST/IST transfer on JOINER side (wsrep_sst_xtrabackup-v2 --role 'joiner' --address '192.168.0.3' --datadir '/var/lib/mysql/' --basedir '/usr/' --plugindir '/usr/lib/mysql/plugin/' --defaults-file '/etc/mysql/my.cnf' --defaults-group-suffix '' --parent '7591' --mysqld-version '8.0.22-13.1'   '' )
> 2021-04-02T01:59:15.965002+05:30 1 [Note] [MY-000000] [WSREP] Prepared SST request: xtrabackup-v2|192.168.0.3:4444/xtrabackup_sst//1
> 2021-04-02T01:59:15.965361+05:30 1 [Note] [MY-000000] [Galera] Check if state gap can be serviced using IST
> 2021-04-02T01:59:15.965637+05:30 1 [Note] [MY-000000] [Galera] Local UUID: 00000000-0000-0000-0000-000000000000 != Group UUID: 3788d9c7-141e-11eb-969b-da352344b906
> 2021-04-02T01:59:15.965940+05:30 1 [Note] [MY-000000] [Galera] ####### IST uuid:00000000-0000-0000-0000-000000000000 f: 0, l: 89370, STRv: 3
> 2021-04-02T01:59:15.966330+05:30 1 [Note] [MY-000000] [Galera] IST receiver addr using ssl://192.168.0.3:4568
> 2021-04-02T01:59:15.966657+05:30 1 [Note] [MY-000000] [Galera] IST receiver using ssl
> 2021-04-02T01:59:15.967183+05:30 1 [Note] [MY-000000] [Galera] Prepared IST receiver for 0-89370, listening at: ssl://192.168.0.3:4568
> 2021-04-02T01:59:15.968661+05:30 0 [Note] [MY-000000] [Galera] Member 2.0 (pxc3) requested state transfer from '*any*'. Selected 0.0 (pxc1)(SYNCED) as donor.
> 2021-04-02T01:59:15.968959+05:30 0 [Note] [MY-000000] [Galera] Shifting PRIMARY -> JOINER (TO: 89370)
> 2021-04-02T01:59:15.969307+05:30 1 [Note] [MY-000000] [Galera] Requesting state transfer: success, donor: 0
> 2021-04-02T01:59:15.969629+05:30 1 [Note] [MY-000000] [Galera] Resetting GCache seqno map due to different histories.
> 2021-04-02T01:59:15.969939+05:30 1 [Note] [MY-000000] [Galera] GCache history reset: 00000000-0000-0000-0000-000000000000:0 -> 3788d9c7-141e-11eb-969b-da352344b906:89370
> 2021-04-02T01:59:16.775144+05:30 0 [Note] [MY-000000] [WSREP-SST] Proceeding with SST.........
> 2021-04-02T01:59:16.805555+05:30 0 [Note] [MY-000000] [WSREP-SST] ............Waiting for SST streaming to complete!
> 2021-04-02T01:59:17.681195+05:30 0 [Note] [MY-000000] [Galera] (ec8ff475-8575, 'ssl://0.0.0.0:4567') turning message relay requesting off
> 2021-04-02T01:59:35.875754+05:30 0 [Note] [MY-000000] [Galera] 0.0 (pxc1): State transfer to 2.0 (pxc3) complete.
> 2021-04-02T01:59:35.876978+05:30 0 [Note] [MY-000000] [Galera] Member 0.0 (pxc1) synced with group.
> 2021-04-02T01:59:35.879180+05:30 0 [Note] [MY-000000] [WSREP-SST] Preparing the backup at /var/lib/mysql//sst-xb-tmpdir
> 2021-04-02T01:59:37.565068+05:30 0 [ERROR] [MY-000000] [WSREP-SST] Cleanup after exit with status:1
> 2021-04-02T01:59:37.573895+05:30 0 [ERROR] [MY-000000] [WSREP] Process completed with error: wsrep_sst_xtrabackup-v2 --role 'joiner' --address '192.168.0.3' --datadir '/var/lib/mysql/' --basedir '/usr/' --plugindir '/usr/lib/mysql/plugin/' --defaults-file '/etc/mysql/my.cnf' --defaults-group-suffix '' --parent '7591' --mysqld-version '8.0.22-13.1'   '' : 1 (Operation not permitted)
> 2021-04-02T01:59:37.574019+05:30 0 [ERROR] [MY-000000] [WSREP] Failed to read uuid:seqno from joiner script.
> 2021-04-02T01:59:37.574044+05:30 0 [ERROR] [MY-000000] [WSREP] SST script aborted with error 1 (Operation not permitted)
> 2021-04-02T01:59:37.574147+05:30 3 [Note] [MY-000000] [Galera] Processing SST received
> 2021-04-02T01:59:37.574189+05:30 3 [Note] [MY-000000] [Galera] SST received: 00000000-0000-0000-0000-000000000000:-1
> 2021-04-02T01:59:37.574214+05:30 3 [System] [MY-000000] [WSREP] SST completed
> 2021-04-02T01:59:37.574353+05:30 1 [Note] [MY-000000] [Galera]  str_proto_ver_: 3 sst_seqno_: -1 cc_seqno: 89370 req->ist_len(): 71
> 2021-04-02T01:59:37.574396+05:30 1 [ERROR] [MY-000000] [Galera] Application received wrong state:
>         Received: 00000000-0000-0000-0000-000000000000
>         Required: 3788d9c7-141e-11eb-969b-da352344b906
> 2021-04-02T01:59:37.574415+05:30 1 [ERROR] [MY-000000] [Galera] Application state transfer failed. This is unrecoverable condition, restart required.
> 2021-04-02T01:59:37.574434+05:30 1 [Note] [MY-000000] [Galera] ReplicatorSMM::abort()
> 2021-04-02T01:59:37.574456+05:30 1 [Note] [MY-000000] [Galera] Closing send monitor...
> 2021-04-02T01:59:37.574475+05:30 1 [Note] [MY-000000] [Galera] Closed send monitor.
> 2021-04-02T01:59:37.574495+05:30 1 [Note] [MY-000000] [Galera] gcomm: terminating thread
> 2021-04-02T01:59:37.574519+05:30 1 [Note] [MY-000000] [Galera] gcomm: joining thread
> 2021-04-02T01:59:37.574589+05:30 1 [Note] [MY-000000] [Galera] gcomm: closing backend
> 2021-04-02T01:59:37.575792+05:30 1 [Note] [MY-000000] [Galera] Current view of cluster as seen by this node
> view (view_id(NON_PRIM,cf998aae-89f2,82)
> memb {
>         ec8ff475-8575,0
>         }
> joined {
>         }
> left {
>         }
> partitioned {
>         cf998aae-89f2,0
>         d49cc289-8504,0
>         }
> )
> 2021-04-02T01:59:37.575883+05:30 1 [Note] [MY-000000] [Galera] PC protocol downgrade 1 -> 0
> 2021-04-02T01:59:37.575908+05:30 1 [Note] [MY-000000] [Galera] Current view of cluster as seen by this node
> view ((empty))
> 2021-04-02T01:59:37.576237+05:30 1 [Note] [MY-000000] [Galera] gcomm: closed
> 2021-04-02T01:59:37.576278+05:30 0 [Note] [MY-000000] [Galera] New COMPONENT: primary = no, bootstrap = no, my_idx = 0, memb_num = 1
> 2021-04-02T01:59:37.576342+05:30 0 [Note] [MY-000000] [Galera] Flow-control interval: [100, 100]
> 2021-04-02T01:59:37.576365+05:30 0 [Note] [MY-000000] [Galera] Received NON-PRIMARY.
> 2021-04-02T01:59:37.576421+05:30 0 [Note] [MY-000000] [Galera] Shifting JOINER -> OPEN (TO: 89370)
> 2021-04-02T01:59:37.576444+05:30 0 [Note] [MY-000000] [Galera] New SELF-LEAVE.
> 2021-04-02T01:59:37.576498+05:30 0 [Note] [MY-000000] [Galera] Flow-control interval: [0, 0]
> 2021-04-02T01:59:37.576517+05:30 0 [Note] [MY-000000] [Galera] Received SELF-LEAVE. Closing connection.
> 2021-04-02T01:59:37.576558+05:30 0 [Note] [MY-000000] [Galera] Shifting OPEN -> CLOSED (TO: 89370)
> 2021-04-02T01:59:37.576579+05:30 0 [Note] [MY-000000] [Galera] RECV thread exiting 0: Success
> 2021-04-02T01:59:37.576649+05:30 1 [Note] [MY-000000] [Galera] recv_thread() joined.
> 2021-04-02T01:59:37.576684+05:30 1 [Note] [MY-000000] [Galera] Closing replication queue.
> 2021-04-02T01:59:37.576700+05:30 1 [Note] [MY-000000] [Galera] Closing slave action queue.
> 2021-04-02T01:59:37.576733+05:30 1 [Note] [MY-000000] [Galera] /usr/sbin/mysqld: Terminated.
> 2021-04-02T01:59:37.576751+05:30 1 [Note] [MY-000000] [WSREP] Initiating SST cancellation
1 Like

it looks like SST failed during xtrabackup process.
Can you check innobackup* logs on all nodes?

1 Like

Hi @vadimtk
only below files are present,all files are deleted. how do i recover…?
FYI - node 1 and 2 are online.

-rw-r-----  1 mysql mysql 134219032 Apr  5 10:32 galera.cache
-rw-r-----  1 mysql mysql         0 Apr  5 10:32 grastate.dat
-rw-------  1 mysql mysql      1676 Apr  5 10:31 private_key.pem
-rw-r--r--  1 mysql mysql       452 Apr  5 10:31 public_key.pem
drwxr-x--x 27 mysql mysql      4096 Apr  5 10:32 sst-xb-tmpdir/
-rw-r-----  1 mysql mysql         0 Apr  5 10:32 sst_in_progress
1 Like

This looks like logs from a JOINER node.
Do you have logs from other nodes (DONOR ? )

Hi @vadimtk
Yes,I do i have the logs of other nodes.