Percona XtraDB Cluster moved to https://jira.percona.com/projects/PXC

  1. Series 5.6
  2. Bug #1281124
  3. Comment #2

Comment 2 for bug 1281124

Revision history for this message
Muhammad Irfan (muhammad-irfan) wrote :

I tried to reproduce with lastest PXC version 5.6.22-72.0-56 ercona XtraDB Cluster (GPL), Release rel72.0, Revision 978, WSREP version 25.8, wsrep_25.8.r4150. After deleting record on master i.e. writer node I got below error on other nodes of the cluster

2015-06-09 05:49:25 21598 [ERROR] Slave SQL: Could not execute Delete_rows event on table test.a; Can't find record in 'a', Error_code: 1032; handler error HA_ERR_END_OF_FILE; the event's master log FIRST, end_log_pos 149, Error_code: 1032
2015-06-09 05:49:25 21598 [Warning] WSREP: RBR event 3 Delete_rows apply warning: 137, 48483717
2015-06-09 05:49:25 21598 [Warning] WSREP: Failed to apply app buffer: seqno: 48483717, status: 1
         at galera/src/trx_handle.cpp:apply():351
Retrying 2th time
2015-06-09 05:49:25 21598 [ERROR] Slave SQL: Could not execute Delete_rows event on table test.a; Can't find record in 'a', Error_code: 1032; handler error HA_ERR_END_OF_FILE; the event's master log FIRST, end_log_pos 149, Error_code: 1032
2015-06-09 05:49:25 21598 [Warning] WSREP: RBR event 3 Delete_rows apply warning: 137, 48483717
2015-06-09 05:49:25 21598 [Warning] WSREP: Failed to apply app buffer: seqno: 48483717, status: 1
         at galera/src/trx_handle.cpp:apply():351
Retrying 3th time
2015-06-09 05:49:25 21598 [ERROR] Slave SQL: Could not execute Delete_rows event on table test.a; Can't find record in 'a', Error_code: 1032; handler error HA_ERR_END_OF_FILE; the event's master log FIRST, end_log_pos 149, Error_code: 1032
2015-06-09 05:49:25 21598 [Warning] WSREP: RBR event 3 Delete_rows apply warning: 137, 48483717
2015-06-09 05:49:25 21598 [Warning] WSREP: Failed to apply app buffer: seqno: 48483717, status: 1
         at galera/src/trx_handle.cpp:apply():351
Retrying 4th time
2015-06-09 05:49:25 21598 [ERROR] Slave SQL: Could not execute Delete_rows event on table test.a; Can't find record in 'a', Error_code: 1032; handler error HA_ERR_END_OF_FILE; the event's master log FIRST, end_log_pos 149, Error_code: 1032
2015-06-09 05:49:25 21598 [Warning] WSREP: RBR event 3 Delete_rows apply warning: 137, 48483717
2015-06-09 05:49:25 21598 [ERROR] WSREP: Failed to apply trx: source: 6697faad-0e8b-11e5-b4d9-3f7722481adf version: 3 local: 0 state: APPLYING flags: 1 conn_id: 13 trx_id: 141946374 seqnos (l: 5, g: 48483717, s: 48483716, d: 48483716, ts: 5046077371079801)
2015-06-09 05:49:25 21598 [ERROR] WSREP: Failed to apply trx 48483717 4 times
2015-06-09 05:49:25 21598 [ERROR] WSREP: Node consistency compromized, aborting...
2015-06-09 05:49:25 21598 [Note] WSREP: Closing send monitor...
2015-06-09 05:49:25 21598 [Note] WSREP: Closed send monitor.
2015-06-09 05:49:25 21598 [Note] WSREP: gcomm: terminating thread
2015-06-09 05:49:25 21598 [Note] WSREP: gcomm: joining thread
2015-06-09 05:49:25 21598 [Note] WSREP: gcomm: closing backend
2015-06-09 05:49:25 21598 [Note] WSREP: view(view_id(NON_PRIM,6697faad,3) memb {
        be72198a,0
} joined {
} left {
} partitioned {
        6697faad,102
        9a8c7599,0
})
2015-06-09 05:49:25 21598 [Note] WSREP: view((empty))
2015-06-09 05:49:25 21598 [Note] WSREP: New COMPONENT: primary = no, bootstrap = no, my_idx = 0, memb_num = 1
2015-06-09 05:49:25 21598 [Note] WSREP: gcomm: closed
2015-06-09 05:49:25 21598 [Note] WSREP: Flow-control interval: [16, 16]
2015-06-09 05:49:25 21598 [Note] WSREP: Received NON-PRIMARY.
2015-06-09 05:49:25 21598 [Note] WSREP: Shifting SYNCED -> OPEN (TO: 48483717)
2015-06-09 05:49:25 21598 [Note] WSREP: Received self-leave message.
2015-06-09 05:49:25 21598 [Note] WSREP: Flow-control interval: [0, 0]
2015-06-09 05:49:25 21598 [Note] WSREP: Received SELF-LEAVE. Closing connection.
2015-06-09 05:49:25 21598 [Note] WSREP: Shifting OPEN -> CLOSED (TO: 48483717)
2015-06-09 05:49:25 21598 [Note] WSREP: RECV thread exiting 0: Success
2015-06-09 05:49:25 21598 [Note] WSREP: recv_thread() joined.
2015-06-09 05:49:25 21598 [Note] WSREP: Closing replication queue.
2015-06-09 05:49:25 21598 [Note] WSREP: Closing slave action queue.
2015-06-09 05:49:25 21598 [Note] WSREP: /usr/sbin/mysqld: Terminated.
Aborted
150609 05:49:25 mysqld_safe Number of processes running now: 0
150609 05:49:25 mysqld_safe WSREP: not restarting wsrep node automatically
150609 05:49:25 mysqld_safe mysqld from pid file /var/run/mysqld/mysqld.pid ended

while on master node i.e. writer node:
2015-06-09 05:49:25 21452 [Note] WSREP: declaring 9a8c7599 at tcp://10.0.3.10:4567 stable
2015-06-09 05:49:25 21452 [Note] WSREP: forgetting be72198a (tcp://10.0.3.169:4567)
2015-06-09 05:49:25 21452 [Note] WSREP: Node 6697faad state prim
2015-06-09 05:49:25 21452 [Warning] WSREP: 6697faad sending install message failed: Resource temporarily unavailable
2015-06-09 05:49:25 21452 [Note] WSREP: view(view_id(NON_PRIM,6697faad,4) memb {
        6697faad,102
} joined {
} left {
} partitioned {
        9a8c7599,0
        be72198a,0
})
2015-06-09 05:49:25 21452 [Note] WSREP: forgetting 9a8c7599 (tcp://10.0.3.10:4567)
2015-06-09 05:49:25 21452 [Note] WSREP: New COMPONENT: primary = no, bootstrap = no, my_idx = 0, memb_num = 1
2015-06-09 05:49:25 21452 [Note] WSREP: view(view_id(NON_PRIM,6697faad,5) memb {
        6697faad,102
} joined {
} left {
} partitioned {
        9a8c7599,0
        be72198a,0
})
2015-06-09 05:49:25 21452 [Note] WSREP: Flow-control interval: [16, 16]
2015-06-09 05:49:25 21452 [Note] WSREP: Received NON-PRIMARY.
2015-06-09 05:49:25 21452 [Note] WSREP: Shifting SYNCED -> OPEN (TO: 48483717)
2015-06-09 05:49:25 21452 [Note] WSREP: New COMPONENT: primary = no, bootstrap = no, my_idx = 0, memb_num = 1
2015-06-09 05:49:25 21452 [Note] WSREP: Flow-control interval: [16, 16]
2015-06-09 05:49:25 21452 [Note] WSREP: Received NON-PRIMARY.
2015-06-09 05:49:25 21452 [Note] WSREP: New cluster view: global state: 51476e75-5313-11e4-a0c8-c21460d01a80:48483717, view# -1: non-Primary, number of nodes: 1, my index: 0, protocol version 3
2015-06-09 05:49:25 21452 [Note] WSREP: Setting wsrep_ready to 0
2015-06-09 05:49:25 21452 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2015-06-09 05:49:25 21452 [Note] WSREP: New cluster view: global state: 51476e75-5313-11e4-a0c8-c21460d01a80:48483717, view# -1: non-Primary, number of nodes: 1, my index: 0, protocol version 3
2015-06-09 05:49:25 21452 [Note] WSREP: Setting wsrep_ready to 0
2015-06-09 05:49:25 21452 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.

I think it seems normal as after deleting record on writer node remaining nodes of cluster loosing quorum and writer node can't operate any more alone. As far as data inconsistency concerned all needed message and GRA files are logged on the slave nodes (non-writer nodes). You have more messages on writer node because of debug messages enabled.