All nodes but one closes down

[Daniel Ylitalo]

A few times in a week our cluster experiences something like a "last man standing" situation, where all nodes except the one where the delete query is originating from is closed down

The situation only seems to be happening during delete queries and here's the error:
131010 1:56:55 [ERROR] Slave SQL: Could not execute Delete_rows event on table mytaste_se.blog_top; Can't find record in 'blog_top', Error_code: 1032; handler error HA_ERR_KEY_NOT_FOUND; the event's master log FIRST, end_log_pos 1096, Error_code: 1032
131010 1:56:55 [Warning] WSREP: RBR event 2 Delete_rows apply warning: 120, 1408063004
131010 1:56:55 [ERROR] WSREP: Failed to apply trx: source: d2d40980-30de-11e3-86d7-43f3e3363655 version: 2 local: 0 state: APPLYING flags: 1 conn_id: 844727 trx_id: 6422274089 seqnos (l: 93953259, g: 1408063004, s: 1408063003, d: 1408062624, ts: 1381363015763698458)
131010 1:56:55 [ERROR] WSREP: Failed to apply app buffer: seqno: 1408063004, status: WSREP_FATAL
         at galera/src/replicator_smm.cpp:apply_wscoll():52
         at galera/src/replicator_smm.cpp:apply_trx_ws():118
131010 1:56:55 [ERROR] WSREP: Node consistency compromized, aborting...
131010 1:56:55 [Note] WSREP: Closing send monitor...
131010 1:56:55 [Note] WSREP: Closed send monitor.
131010 1:56:55 [Note] WSREP: gcomm: terminating thread
131010 1:56:55 [Note] WSREP: gcomm: joining thread
131010 1:56:55 [Note] WSREP: gcomm: closing backend

I don't see why a node would go offline due to inconsistency during a delete, if a row doesn't exist, just continue? The row is supposed to be gone anyway. On update queries the node should obviously go offline, but delete queries?

I also noted that when this happens, the wsrep_notify_cmd isn't executed on the node that goes offline.

[Alex Yurchenko (ayurchen)]

I would agree about DELETE, and in general inconsistency policy should be configurable.

Having said that, such inconsistency is likely to be a result of a bug and not isolated, so ignoring this error on DELETE may not buy you much operational time. Upgrading to the latest release is more likely to solve your problem.

[Jason Bryan (jbryan)]

Hi,

Our Bugzilla app is on a 3 node multi-master cluster and having the same issue. Can you provide a bit more understanding as to why this happens?

131231 18:16:43 [ERROR] Slave SQL: Could not execute Update_rows event on table bugzilla.attachments; Can't find record in 'attachments', Error_code: 1032; handler error HA_ERR_KEY_NOT_FOUND; the event's master log FIRST, end_log_pos 279, Error_code: 1032
131231 18:16:43 [Warning] WSREP: RBR event 2 Update_rows apply warning: 120, 1593958
131231 18:16:43 [Note] WSREP: declaring 62a92d9f-7179-11e3-b4ca-de001387c324 stable
131231 18:16:43 [ERROR] WSREP: Failed to apply trx: source: 62a92d9f-7179-11e3-b4ca-de001387c324 version: 2 local: 0 state: APPLYING flags: 1 conn_id: 32030272 trx_id: 8936786 seqnos (l: 550435, g: 1593958, s: 1593957, d: 1593718, ts: 1388535403140834735)
131231 18:16:43 [ERROR] WSREP: Failed to apply app buffer: seqno: 1593958, status: WSREP_FATAL
         at galera/src/replicator_smm.cpp:apply_wscoll():52
         at galera/src/replicator_smm.cpp:apply_trx_ws():118
131231 18:16:43 [ERROR] WSREP: Node consistency compromized, aborting...

On the front, there is a 4 node web cluster serving BZ. I had made a config change and restarted httpd on each node when the inconsistency occurred. I can't help to think that was a contributor.

MariaDB-Galera-server-5.5.34-1.x86_64
wsrep_provider_name Galera
wsrep_provider_vendor Codership Oy <email address hidden>
wsrep_provider_version 23.2.7(r157)

wsrep_replicate_myisam ON (all BZ tables InnoDB)
wsrep_retry_autocommit 1
wsrep_slave_threads 1
wsrep_sst_auth
wsrep_sst_donor
wsrep_sst_donor_rejects_queries OFF
wsrep_sst_method rsync
wsrep_sst_receive_address AUTO

Is this caused by some app race condition some other factor? I am also load balancing :3306 with haproxy on each of the 4 web nodes. haproxy.cfg:

listen mysql_proxy 127.0.0.1:3306
   timeout connect 5s
   timeout client 1m
   timeout server 1m
   mode tcp
   balance roundrobin
   option tcpka
   option mysql-check user haproxy
   server web-db1 10.0.0.1:3306 check weight 1
   server web-db2 10.0.0.2:3306 check weight 1
   server web-db3 10.0.0.3:3306 check weight 1

Thank you.

[Alex Yurchenko (ayurchen)]

Hi Jason,

As follows from the log, the node was missing a row to update. Assuming that all nodes but one had this situation it is logical to assume that the remaining node was inconsistent with the rest of the cluster.

It could happen for many reasons and arbitrarily long ago. But the most likely cause is human error when restarting the cluster. If you could carefully recall EXACTLY how you did it you may find a clue.

Restarting http servers and ha-proxy load balancing is not a CAUSE of inconsistency, unless there is some nasty bug. Such bugs proved to be rather rare (1 or 2 through the history), so you should look into how you restarted the nodes first. ha-proxy balancing could CONTRIBUTE to it if you start the nodes in wrong order.

[Ivan Pantovic (ivan-pantovicc)]

Hi Alex, i've been strugling with a very similar problem on 5.6 for a month now.

so far, it is usually a delete statement like this:

Apr 28 17:24:48 vm-gotc-prod-mysql1 mysqld: Retrying 4th time
Apr 28 17:24:48 vm-gotc-prod-mysql1 mysqld: 2014-04-28 17:24:48 28224 [ERROR] Slave SQL: Could not execute Delete_rows event on table gotcourts.Exception_Courts; Can't find record in 'Exception_Courts', Error_code: 1032; handler error HA_ERR_KEY_NOT_FOUND; the event's master log FIRST, end_log_pos 176, Error_code: 1032
Apr 28 17:24:48 vm-gotc-prod-mysql1 mysqld: 2014-04-28 17:24:48 28224 [Warning] WSREP: RBR event 3 Delete_rows apply warning: 120, 593017
Apr 28 17:24:48 vm-gotc-prod-mysql1 mysqld: 2014-04-28 17:24:48 28224 [ERROR] WSREP: Failed to apply trx: source: 4ba1d787-ceb4-11e3-a510-5fed256959fa version: 3 local: 0 state: APPLYING flags: 129 conn_id: 28595 trx_id: 59111915 seqnos (l: 1654, g: 593017, s: 593016, d: 593016, ts: 94625220425952)
Apr 28 17:24:48 vm-gotc-prod-mysql1 mysqld: 2014-04-28 17:24:48 28224 [ERROR] WSREP: Failed to apply trx 593017 4 times
Apr 28 17:24:48 vm-gotc-prod-mysql1 mysqld: 2014-04-28 17:24:48 28224 [ERROR] WSREP: Node consistency compromized, aborting...
Apr 28 17:24:48 vm-gotc-prod-mysql1 mysqld: 2014-04-28 17:24:48 28224 [Note] WSREP: Closing send monitor...
Apr 28 17:24:48 vm-gotc-prod-mysql1 mysqld: 2014-04-28 17:24:48 28224 [Note] WSREP: Closed send monitor.
Apr 28 17:24:48 vm-gotc-prod-mysql1 mysqld: 2014-04-28 17:24:48 28224 [Note] WSREP: gcomm: terminating thread
Apr 28 17:24:48 vm-gotc-prod-mysql1 mysqld: 2014-04-28 17:24:48 28224 [Note] WSREP: gcomm: joining thread
Apr 28 17:24:48 vm-gotc-prod-mysql1 mysqld: 2014-04-28 17:24:48 28224 [Note] WSREP: gcomm: closing backend
Apr 28 17:24:49 vm-gotc-prod-mysql1 mysqld: 2014-04-28 17:24:49 28224 [Note] WSREP: view(view_id(NON_PRIM,4ba1d787-ceb4-11e3-a510-5fed256959fa,172) memb {
Apr 28 17:24:49 vm-gotc-prod-mysql1 mysqld: #011c980479d-ceb3-11e3-961f-9bc7520e933a,0
Apr 28 17:24:49 vm-gotc-prod-mysql1 mysqld: } joined {
Apr 28 17:24:49 vm-gotc-prod-mysql1 mysqld: } left {
Apr 28 17:24:49 vm-gotc-prod-mysql1 mysqld: } partitioned {
Apr 28 17:24:49 vm-gotc-prod-mysql1 mysqld: #0114ba1d787-ceb4-11e3-a510-5fed256959fa,0
Apr 28 17:24:49 vm-gotc-prod-mysql1 mysqld: #011e2745e2c-ceb3-11e3-95dc-daaca2f50d15,0
Apr 28 17:24:49 vm-gotc-prod-mysql1 mysqld: })
Apr 28 17:24:49 vm-gotc-prod-mysql1 mysqld: 2014-04-28 17:24:49 28224 [Note] WSREP: view((empty))
Apr 28 17:24:49 vm-gotc-prod-mysql1 mysqld: 2014-04-28 17:24:49 28224 [Note] WSREP: New COMPONENT: primary = no, bootstrap = no, my_idx = 0, memb_num = 1
Apr 28 17:24:49 vm-gotc-prod-mysql1 mysqld: 2014-04-28 17:24:49 28224 [Note] WSREP: gcomm: closed
Apr 28 17:24:49 vm-gotc-prod-mysql1 mysqld: 2014-04-28 17:24:49 28224 [Note] WSREP: Flow-control interval: [16, 16]
Apr 28 17:24:49 vm-gotc-prod-mysql1 mysqld: 2014-04-28 17:24:49 28224 [Note] WSREP: Received NON-PRIMARY.
Apr 28 17:24:49 vm-gotc-prod-mysql1 mysqld: 2014-04-28 17:24:49 28224 [Note] WSREP: Shifting SYNCED -> OPEN (TO: 593017)
Apr 28 17:24:49 vm-gotc-prod-mysql1 mysqld: 2014-04-28 17:24:49 28224 [Note] WSREP: Received self-leave message.
Apr 28 17:24:49 vm-gotc-...

[fabe (fabe-e)]

Not sure if we have the same problem, but it is in production on 3 servers and two more are coming as soon as the user count rises, this is extremely bad, any suggestion is welcome. Two servers crash at same time when this duplicate occurs and main node brain splits, perhaps a tmp sollution if this will hapen more often to disable split brain until bug is resolved or whatever is happening?

from log:
140702 3:43:07 ...
140713 20:34:53 [ERROR] Slave SQL: Could not execute Write_rows event on table r.r_s; Duplicate entry '267444' for key 'subscriber_id_UNIQUE', Error_code: 1062; handler error HA_ER
R_FOUND_DUPP_KEY; the event's master log FIRST, end_log_pos 311, Error_code: 1062
140713 20:34:53 [Warning] WSREP: RBR event 2 Write_rows apply warning: 121, 298496015
140713 20:34:53 [ERROR] WSREP: Failed to apply trx: source: b7f40923-da82-11e3-bbc0-7b766eddf37e version: 2 local: 0 state: APPLYING flags: 1 conn_id: 9243737 trx_id: 819005834 seqnos (l: 20583
3760, g: 298496015, s: 298496001, d: 298496014, ts: 1405272892721099371)
140713 20:34:53 [ERROR] WSREP: Failed to apply app buffer: seqno: 298496015, status: WSREP_FATAL
         at galera/src/replicator_smm.cpp:apply_wscoll():52
         at galera/src/replicator_smm.cpp:apply_trx_ws():118
140713 20:34:53 [ERROR] WSREP: Node consistency compromized, aborting...
140713 20:34:53 [Note] WSREP: Closing send monitor...
140713 20:34:53 [Note] WSREP: Closed send monitor.
140713 20:34:53 [Note] WSREP: gcomm: terminating thread
140713 20:34:53 [Note] WSREP: gcomm: joining thread
140713 20:34:53 [Note] WSREP: declaring b7f40923-da82-11e3-bbc0-7b766eddf37e stable
140713 20:34:53 [Note] WSREP: gcomm: closing backend
140713 20:34:53 [Warning] WSREP: Failed to report last committed 298495993, -77 (File descriptor in bad state)
140713 20:34:53 [Note] WSREP: Node 010ba639-dce3-11e3-a855-ee8794d217f0 state prim
140713 20:34:53 [Warning] WSREP: user message in state LEAVING
140713 20:34:53 [Warning] WSREP: 010ba639-dce3-11e3-a855-ee8794d217f0 sending install message failed: Transport endpoint is not connected
140713 20:34:53 [Note] WSREP: (010ba639-dce3-11e3-a855-ee8794d217f0, 'tcp://0.0.0.0:4567') turning message relay requesting on, nonlive peers: tcp://22.37.44.11:4567
140713 20:34:53 [Note] WSREP: view(view_id(NON_PRIM,010ba639-dce3-11e3-a855-ee8794d217f0,23) memb {
        010ba639-dce3-11e3-a855-ee8794d217f0,
} joined {
} left {
} partitioned {
        93536422-dcf3-11e3-a37b-1e9808fdc0f6,
        b7f40923-da82-11e3-bbc0-7b766eddf37e,
})
140713 20:34:53 [Note] WSREP: view((empty))
140713 20:34:53 [Note] WSREP: New COMPONENT: primary = no, bootstrap = no, my_idx = 0, memb_num = 1
140713 20:34:53 [Note] WSREP: gcomm: closed
140713 20:34:53 [Note] WSREP: Flow-control interval: [16, 16]
140713 20:34:53 [Note] WSREP: Received NON-PRIMARY.
140713 20:34:53 [Note] WSREP: Shifting SYNCED -> OPEN (TO: 298496134)
140713 20:34:53 [Note] WSREP: Received self-leave message.
140713 20:34:53 [Note] WSREP: Flow-control interval: [0, 0]
140713 20:34:53 [Note] WSREP: Received SELF-LEAVE. Closing connection.
140713 20:34:53 [Note] WSREP: Shifting OPEN -> CLOSED (TO: 298496134)
140713 20:34:53 [Note] WSREP: RECV thread exiting...

[Alex Yurchenko (ayurchen)]

fabe, this is likely to be a different problem, related to secondary unique keys handling. There've been a couple of such bugs fixed since last release.

[Raghavendra D Prabhu (raghavendra-prabhu)]

Marking this bug as fix released, please test with latest release and let us know.

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PXC-1083