Uploaded image for project: 'Percona XtraDB Cluster'
  1. Percona XtraDB Cluster
  2. PXC-2965

[Percona-XtraDB-Cluster-57-5.7.18-29.20.1.el7.x86_64] wsrep failure causing mysqld to stall at start

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Done
    • Priority: High
    • Resolution: Invalid
    • Affects Version/s: None
    • Fix Version/s: None
    • Component/s: None
    • Labels:

      Description

      CentOS 7 with Percona-XtraDB-Cluster installed from percona-release-x86_64 CentOS 7 repo. Versions:
      rpm -qa Percona*
      Percona-XtraDB-Cluster-client-57-5.7.18-29.20.1.el7.x86_64
      Percona-XtraDB-Cluster-shared-compat-57-5.7.18-29.20.1.el7.x86_64
      Percona-XtraDB-Cluster-57-debuginfo-5.7.18-29.20.1.el7.x86_64
      Percona-XtraDB-Cluster-57-5.7.18-29.20.1.el7.x86_64
      Percona-XtraDB-Cluster-server-57-5.7.18-29.20.1.el7.x86_64
      Percona-XtraDB-Cluster-shared-57-5.7.18-29.20.1.el7.x86_64
      Had a deadlock I had to deal with and, after restarting mysqld service on the affected node, "systemctl start mysql" stalls. In /var/log/mysqld.log I see:

      [...]
      2020-02-05T12:36:59.992112+10:00 1 [Note] WSREP: New cluster view: global state: 04acf6f6-8150-11e6-88a1-2eb0fc313bfe:231233102, view# 290: Primary, number of nodes: 3, my index: 0, protocol version 3
      2020-02-05T12:36:59.992120+10:00 1 [Warning] WSREP: Gap in state sequence. Need state transfer.
      2020-02-05T12:36:59.992248+10:00 0 [Note] WSREP: Initiating SST/IST transfer on JOINER side (wsrep_sst_xtrabackup-v2 --role 'joiner' --address '192.168.1.21' --datadir '/var/lib/mysql/' --defaults-file '/etc/my.cnf' --defaults-group-suffix '' --parent '168601'  '' )
      2020-02-05T12:37:00.497836+10:00 1 [Note] WSREP: Prepared SST/IST request: xtrabackup-v2|192.168.1.21:4444/xtrabackup_sst//1
      2020-02-05T12:37:00.497887+10:00 1 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
      2020-02-05T12:37:00.497918+10:00 1 [Note] WSREP: REPL Protocols: 7 (3, 2)
      2020-02-05T12:37:00.497931+10:00 1 [Note] WSREP: Assign initial position for certification: 231233102, protocol version: 3
      2020-02-05T12:37:00.498042+10:00 0 [Note] WSREP: Service thread queue flushed.
      2020-02-05T12:37:00.498093+10:00 1 [Note] WSREP: Check if state gap can be serviced using IST
      2020-02-05T12:37:00.498116+10:00 1 [Note] WSREP: Local UUID: 00000000-0000-0000-0000-000000000000 != Group UUID: 04acf6f6-8150-11e6-88a1-2eb0fc313bfe
      2020-02-05T12:37:00.498195+10:00 1 [Note] WSREP: State gap can't be serviced using IST. Switching to SST
      2020-02-05T12:37:00.498909+10:00 0 [Note] WSREP: Member 0.0 (ddns-px-cluster-node1) requested state transfer from '*any*'. Selected 1.0 (ddns-px-cluster-node2)(SYNCED) as donor.
      2020-02-05T12:37:00.498930+10:00 0 [Note] WSREP: Shifting PRIMARY -> JOINER (TO: 231233102)
      2020-02-05T12:37:00.498997+10:00 1 [Note] WSREP: Requesting state transfer: success, donor: 1
      2020-02-05T12:37:00.499029+10:00 1 [Note] WSREP: GCache history reset: old(00000000-0000-0000-0000-000000000000:0) -> new(04acf6f6-8150-11e6-88a1-2eb0fc313bfe:231233102)
              2020-02-05T12:37:01.081982+11:00 WSREP_SST: [INFO] Proceeding with SST.........
      [...]
      2020-02-05T12:37:02.990062+10:00 0 [Note] WSREP: (006c6fd1, 'tcp://0.0.0.0:4567') connection to peer 006c6fd1 with addr tcp://192.168.1.21:4567 timed out, no messages seen in PT3S
      2020-02-05T12:37:02.990190+10:00 0 [Note] WSREP: (006c6fd1, 'tcp://0.0.0.0:4567') turning message relay requesting off
              2020-02-05T12:37:08.092285+11:00 WSREP_SST: [ERROR] Cleanup after exit with status:1
      2020-02-05T12:41:20.742226+10:00 0 [Note] WSREP: 1.0 (ddns-px-cluster-node2): State transfer to 0.0 (ddns-px-cluster-node1) complete.
      2020-02-05T12:41:20.742736+10:00 0 [Note] WSREP: Member 1.0 (ddns-px-cluster-node2) synced with group.
      2020-02-05T12:41:20.817002+10:00 0 [ERROR] WSREP: Process completed with error: wsrep_sst_xtrabackup-v2 --role 'joiner' --address '192.168.1.21' --datadir '/var/lib/mysql/' --defaults-file '/etc/my.cnf' --defaults-group-suffix '' --parent '168601'  '' : 1 (Operation not permitted)
      2020-02-05T12:41:20.817055+10:00 0 [ERROR] WSREP: Failed to read uuid:seqno from joiner script.
      2020-02-05T12:41:20.817066+10:00 0 [ERROR] WSREP: SST script aborted with error 1 (Operation not permitted)
      2020-02-05T12:41:20.817120+10:00 0 [ERROR] WSREP: SST failed: 1 (Operation not permitted)
      2020-02-05T12:41:20.817142+10:00 0 [ERROR] Aborting
      
      2020-02-05T12:41:20.817159+10:00 0 [Note] WSREP: Signalling cancellation of the SST request.
      2020-02-05T12:41:20.817182+10:00 0 [Note] WSREP: SST request was cancelled
      2020-02-05T12:41:20.817196+10:00 0 [Note] Giving 2 client threads a chance to die gracefully
      2020-02-05T12:41:20.817258+10:00 1 [Note] WSREP: Closing send monitor...
      2020-02-05T12:41:20.817283+10:00 1 [Note] WSREP: Closed send monitor.
      2020-02-05T12:41:20.817299+10:00 1 [Note] WSREP: gcomm: terminating thread
      2020-02-05T12:41:20.817312+10:00 1 [Note] WSREP: gcomm: joining thread
      2020-02-05T12:41:20.817371+10:00 1 [Note] WSREP: gcomm: closing backend
      2020-02-05T12:41:20.818180+10:00 1 [Note] WSREP: Current view of cluster as seen by this node
      view (view_id(NON_PRIM,006c6fd1,306)
      memb {
              006c6fd1,0
              }
      joined {
              }
      left {
              }
      partitioned {
              107431e3,0
              5782448c,0
              }
      )
      2020-02-05T12:41:20.818251+10:00 1 [Note] WSREP: Current view of cluster as seen by this node
      view ((empty))
      2020-02-05T12:41:20.818502+10:00 1 [Note] WSREP: gcomm: closed
      2020-02-05T12:41:20.818528+10:00 0 [Note] WSREP: New COMPONENT: primary = no, bootstrap = no, my_idx = 0, memb_num = 1
      2020-02-05T12:41:20.818557+10:00 0 [Note] WSREP: Flow-control interval: [100, 100]
      2020-02-05T12:41:20.818564+10:00 0 [Note] WSREP: Received NON-PRIMARY.
      2020-02-05T12:41:20.818570+10:00 0 [Note] WSREP: Shifting JOINER -> OPEN (TO: 231233443)
      2020-02-05T12:41:20.818583+10:00 0 [Note] WSREP: Received self-leave message.
      2020-02-05T12:41:20.818591+10:00 0 [Note] WSREP: Flow-control interval: [0, 0]
      2020-02-05T12:41:20.818596+10:00 0 [Note] WSREP: Received SELF-LEAVE. Closing connection.
      2020-02-05T12:41:20.818602+10:00 0 [Note] WSREP: Shifting OPEN -> CLOSED (TO: 231233443)
      2020-02-05T12:41:20.818609+10:00 0 [Note] WSREP: RECV thread exiting 0: Success
      2020-02-05T12:41:20.818638+10:00 1 [Note] WSREP: recv_thread() joined.
      2020-02-05T12:41:20.818645+10:00 1 [Note] WSREP: Closing replication queue.
      2020-02-05T12:41:20.818650+10:00 1 [Note] WSREP: Closing slave action queue.
      2020-02-05T12:41:22.817266+10:00 0 [Note] WSREP: Waiting for active wsrep applier to exit
      2020-02-05T12:41:22.817324+10:00 2 [Note] WSREP: rollbacker thread exiting
      

      And nothing else. mysqld process is still running, I've attached a gdb backtrace.

        Smart Checklist

          Attachments

            Activity

              People

              Assignee:
              Unassigned
              Reporter:
              burnley Adi Pircalabu
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved: