MySQL patches by Codership

Comment 5 for bug 1237816

Revision history for this message

fabe (fabe-e) wrote on 2014-07-15:

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 0: Success
140713 20:34:53 [Note] WSREP: recv_thread() joined.
140713 20:34:53 [Note] WSREP: Closing replication queue.
140713 20:34:53 [Note] WSREP: Closing slave action queue.
140713 20:34:53 [Note] WSREP: /usr/sbin/mysqld: Terminated.
140713 20:34:54 mysqld_safe Number of processes running now: 0
140713 20:34:54 mysqld_safe WSREP: not restarting wsrep node automatically
140713 20:34:54 mysqld_safe mysqld from pid file /var/lib/mysql/mysql.pid ended
140713 21:30:19 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql

installed packages:
Percona-XtraDB-Cluster-server-5.5.34-23.7.6.565.rhel6.x86_64.rpm
Percona-XtraDB-Cluster-galera-2.8-1.162.rhel6.x86_64.rpm
Percona-XtraDB-Cluster-shared-5.5.34-23.7.6.565.rhel6.x86_64.rpm
Percona-XtraDB-Cluster-client-5.5.34-23.7.6.565.rhel6.x86_64.rpm
percona-xtrabackup-2.1.5-680.rhel6.x86_64.rpm
Percona-Server-shared-51-5.1.72-rel14.10.597.rhel6.x86_64.rpm

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 0: Success
140713 20:34:53 [Note] WSREP: recv_thread() joined.
140713 20:34:53 [Note] WSREP: Closing replication queue.
140713 20:34:53 [Note] WSREP: Closing slave action queue.
140713 20:34:53 [Note] WSREP: /usr/sbin/mysqld: Terminated.
140713 20:34:54 mysqld_safe Number of processes running now: 0
140713 20:34:54 mysqld_safe WSREP: not restarting wsrep node automatically
140713 20:34:54 mysqld_safe mysqld from pid file /var/lib/mysql/mysql.pid ended
140713 21:30:19 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql