Secondary node lost consistency and subsequently restarted full SST. Logs attached...

[Freejack]

Hi.  During a large transaction of a few million rows on our primary node, it seems the secondary node became inconsistent somehow.  We only read/write from/to the primary node.  We are using the following:

Percona-XtraDB-Cluster-client-5.5.27-23.6.356.rhel5

Percona-XtraDB-Cluster-shared-5.5.27-23.6.356.rhel5

Percona-XtraDB-Cluster-server-5.5.27-23.6.356.rhel5

Percona-XtraDB-Cluster-galera-2.0-1.114.rhel5

This is the second time this has happened.  A full SST was also initiated immediately after this error happened which eventually brought down the primary node due to another error I'm trying to troubleshoot.

Thanks for any assistance!

------------------------------------------------------------------------------------

Here is the log file from the PRIMARY node:

------------------------------------------------------------------------------------

121109  8:12:38 [Note] WSREP: Created page /var/lib/mysql/gcache.page.000022 of size 134217728 bytes

121109  8:12:43 [Note] WSREP: Deleted page /var/lib/mysql/gcache.page.000022

121109  8:12:43 [Note] WSREP: view(view_id(PRIM,c23bca00-1fb1-11e2-0800-306a616525db,6) memb {

        c23bca00-1fb1-11e2-0800-306a616525db,

} joined {

} left {

} partitioned {

        364f0c86-1fd5-11e2-0800-bab6a4443916,

})

121109  8:12:43 [Note] WSREP: forgetting 364f0c86-1fd5-11e2-0800-bab6a4443916 (tcp://10.7.25.110:4567)

121109  8:12:43 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 0, memb_num = 1

121109  8:12:43 [Note] WSREP: STATE_EXCHANGE: sent state UUID: 25992e04-2a6f-11e2-0800-351b63128070

121109  8:12:43 [Warning] WSREP: Last Applied Action message in non-primary configuration from member 0

121109  8:12:43 [Note] WSREP: STATE EXCHANGE: sent state msg: 25992e04-2a6f-11e2-0800-351b63128070

121109  8:12:43 [Note] WSREP: STATE EXCHANGE: got state msg: 25992e04-2a6f-11e2-0800-351b63128070 from 0 (maindb-node0)

121109  8:12:43 [Note] WSREP: Quorum results:

        version    = 2,

        component  = PRIMARY,

        conf_id    = 5,

        members    = 1/1 (joined/total),

        act_id     = 10182391,

        last_appl. = 10182382,

        protocols  = 0/4/2 (gcs/repl/appl),

        group UUID = e459a41e-19ed-11e2-0800-28913924bd33

121109  8:12:43 [Note] WSREP: Flow-control interval: [253, 256]

121109  8:12:43 [Note] WSREP: New cluster view: global state: e459a41e-19ed-11e2-0800-28913924bd33:10182391, view# 6: Primary, number of nodes: 1, my index: 0, protocol version 2

121109  8:12:43 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.

121109  8:12:44 [Note] WSREP: Assign initial position for certification: 10182391, protocol version: 2

121109  8:12:44 [Note] WSREP: remote endpoint tcp://10.7.25.110:4567 changed identity 364f0c86-1fd5-11e2-0800-bab6a4443916 -> 261706d0-2a6f-11e2-0800-48fc91a1cea0

121109  8:12:44 [Note] WSREP: declaring 261706d0-2a6f-11e2-0800-48fc91a1cea0 stable

121109  8:12:44 [Note] WSREP: view(view_id(PRIM,261706d0-2a6f-11e2-0800-48fc91a1cea0,7) memb {

        261706d0-2a6f-11e2-0800-48fc91a1cea0,

        c23bca00-1fb1-11e2-0800-306a616525db,

} joined {

} left {

} partitioned {

})

121109  8:12:44 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 1, memb_num = 2

121109  8:12:44 [Note] WSREP: STATE EXCHANGE: Waiting for state UUID.

121109  8:12:44 [Note] WSREP: STATE EXCHANGE: sent state msg: 26649fda-2a6f-11e2-0800-e7466d8051c6

121109  8:12:44 [Note] WSREP: STATE EXCHANGE: got state msg: 26649fda-2a6f-11e2-0800-e7466d8051c6 from 0 (mysql-db1-standby)

121109  8:12:44 [Note] WSREP: STATE EXCHANGE: got state msg: 26649fda-2a6f-11e2-0800-e7466d8051c6 from 1 (maindb-node0)

121109  8:12:44 [Note] WSREP: Quorum results:

        version    = 2,

        component  = PRIMARY,

        conf_id    = 6,

        members    = 1/2 (joined/total),

        act_id     = 10182393,

        last_appl. = 10182382,

        protocols  = 0/4/2 (gcs/repl/appl),

        group UUID = e459a41e-19ed-11e2-0800-28913924bd33

121109  8:12:44 [Note] WSREP: Flow-control interval: [253, 256]

121109  8:12:44 [Note] WSREP: New cluster view: global state: e459a41e-19ed-11e2-0800-28913924bd33:10182393, view# 7: Primary, number of nodes: 2, my index: 1, protocol version 2

121109  8:12:44 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.

121109  8:12:44 [Note] WSREP: Assign initial position for certification: 10182393, protocol version: 2

------------------------------------------------------------------------------------

SECONDARY node:

------------------------------------------------------------------------------------

121109  8:12:38 [Note] WSREP: Created page /var/lib/mysql/gcache.page.000022 of size 134217728 bytes

121109  8:12:42 [ERROR] Slave SQL: Could not execute Delete_rows event on table p1.pos; Can't find record in 'pos', Error_code: 1032; handler error HA_ERR_KEY_NOT_FOUND; the event's master log FIRST, end_log_pos 978, Error_code: 1032

121109  8:12:42 [Warning] WSREP: RBR event 2 Delete_rows apply warning: 120, 10182390

121109  8:12:43 [ERROR] WSREP: Failed to apply trx: source: c23bca00-1fb1-11e2-0800-306a616525db version: 2 local: 0 state: APPLYING flags: 1 conn_id: 1219339 trx_id: 45372703 seqnos (l: 1396875, g: 10182390, s: 10182389, d: 10182380, ts: 1352466709844062000)

121109  8:12:43 [ERROR] WSREP: Failed to apply app buffer: ^U^A<9d>P^Sö¦£, seqno: 10182390, status: WSREP_FATAL

         at galera/src/replicator_smm.cpp:apply_wscoll():49

         at galera/src/replicator_smm.cpp:apply_trx_ws():120

121109  8:12:43 [ERROR] WSREP: Node consistency compromized, aborting...

121109  8:12:43 [Note] WSREP: Closing send monitor...

121109  8:12:43 [Note] WSREP: Closed send monitor.

121109  8:12:43 [Note] WSREP: gcomm: terminating thread

121109  8:12:43 [Note] WSREP: gcomm: joining thread

121109  8:12:43 [Note] WSREP: gcomm: closing backend

121109  8:12:43 [Note] WSREP: view(view_id(NON_PRIM,364f0c86-1fd5-11e2-0800-bab6a4443916,5) memb {

        364f0c86-1fd5-11e2-0800-bab6a4443916,

} joined {

} left {

} partitioned {

        c23bca00-1fb1-11e2-0800-306a616525db,

})

121109  8:12:43 [Note] WSREP: New COMPONENT: primary = no, bootstrap = no, my_idx = 0, memb_num = 1

121109  8:12:43 [Note] WSREP: view((empty))

121109  8:12:43 [Note] WSREP: gcomm: closed

121109  8:12:43 [Note] WSREP: Flow-control interval: [253, 256]

121109  8:12:43 [Note] WSREP: Received NON-PRIMARY.

121109  8:12:43 [Note] WSREP: Shifting SYNCED -> OPEN (TO: 10182391)

121109  8:12:43 [Note] WSREP: Received self-leave message.

121109  8:12:43 [Note] WSREP: Flow-control interval: [253, 256]

121109  8:12:43 [Note] WSREP: Received SELF-LEAVE. Closing connection.

121109  8:12:43 [Note] WSREP: Shifting OPEN -> CLOSED (TO: 10182391)

121109  8:12:43 [Note] WSREP: RECV thread exiting 0: Success

121109  8:12:43 [Note] WSREP: recv_thread() joined.

121109  8:12:43 [Note] WSREP: Closing slave action queue.

121109  8:12:43 [Note] WSREP: /usr/sbin/mysqld: Terminated.

121109 08:12:43 mysqld_safe Number of processes running now: 0

121109 08:12:43 mysqld_safe mysqld restarted

121109  8:12:44 [Note] Flashcache bypass: disabled

121109  8:12:44 [Note] Flashcache setup error is : ioctl failed

121109  8:12:44 [Note] WSREP: Read nil XID from storage engines, skipping position init

121109  8:12:44 [Note] WSREP: wsrep_load(): loading provider library '/usr/lib64/libgalera_smm.so'

121109  8:12:44 [Note] WSREP: wsrep_load(): Galera 2.2(r114) by Codership Oy <in...@codership.com> loaded succesfully.

121109  8:12:44 [Note] WSREP: Found saved state: 00000000-0000-0000-0000-000000000000:-1

121109  8:12:44 [Note] WSREP: Reusing existing '/var/lib/mysql//galera.cache'.

121109  8:12:44 [Note] WSREP: Passing config to GCS: base_host = 10.7.25.110; gcache.dir = /var/lib/mysql/; gcache.keep_pages_size = 0; gcache.mem_size = 0; gcache.name = /var/lib/mysql//galera.cache; gcache.page_size = 128M; gcache.size = 128M; gcs.fc_debug = 0; gcs.fc_factor = 0.99; gcs.fc_limit = 256; gcs.fc_master_slave = yes; gcs.max_packet_size = 64500; gcs.max_throttle = 0.25; gcs.recv_q_hard_limit = 9223372036854775807; gcs.recv_q_soft_limit = 0.25; gcs.sync_donor = NO; replicator.causal_read_timeout = PT30S; replicator.commit_order = 3

121109  8:12:44 [Note] WSREP: Assign initial position for certification: -1, protocol version: -1

121109  8:12:44 [Note] WSREP: wsrep_sst_grab()

121109  8:12:44 [Note] WSREP: Start replication

121109  8:12:44 [Note] WSREP: Setting initial position to 00000000-0000-0000-0000-000000000000:-1

121109  8:12:44 [Note] WSREP: protonet asio version 0

121109  8:12:44 [Note] WSREP: backend: asio

121109  8:12:44 [Note] WSREP: GMCast version 0

121109  8:12:44 [Note] WSREP: (261706d0-2a6f-11e2-0800-48fc91a1cea0, 'tcp://0.0.0.0:4567') listening at tcp://0.0.0.0:4567

121109  8:12:44 [Note] WSREP: (261706d0-2a6f-11e2-0800-48fc91a1cea0, 'tcp://0.0.0.0:4567') multicast: , ttl: 1

121109  8:12:44 [Note] WSREP: EVS version 0

121109  8:12:44 [Note] WSREP: PC version 0

121109  8:12:44 [Note] WSREP: gcomm: connecting to group 'maindb', peer '10.7.25.111:'

121109  8:12:44 [Note] WSREP: declaring c23bca00-1fb1-11e2-0800-306a616525db stable

121109  8:12:44 [Note] WSREP: view(view_id(PRIM,261706d0-2a6f-11e2-0800-48fc91a1cea0,7) memb {

        261706d0-2a6f-11e2-0800-48fc91a1cea0,

        c23bca00-1fb1-11e2-0800-306a616525db,

} joined {

} left {

} partitioned {

})

121109  8:12:44 [Note] WSREP: gcomm: connected

121109  8:12:44 [Note] WSREP: Changing maximum packet size to 64500, resulting msg size: 32636

121109  8:12:44 [Note] WSREP: Shifting CLOSED -> OPEN (TO: 0)

121109  8:12:44 [Note] WSREP: Opened channel 'maindb'

121109  8:12:44 [Note] WSREP: Waiting for SST to complete.

121109  8:12:44 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 0, memb_num = 2

121109  8:12:44 [Note] WSREP: STATE_EXCHANGE: sent state UUID: 26649fda-2a6f-11e2-0800-e7466d8051c6

121109  8:12:44 [Note] WSREP: STATE EXCHANGE: sent state msg: 26649fda-2a6f-11e2-0800-e7466d8051c6

121109  8:12:44 [Note] WSREP: STATE EXCHANGE: got state msg: 26649fda-2a6f-11e2-0800-e7466d8051c6 from 0 (mysql-db1-standby)

121109  8:12:44 [Note] WSREP: STATE EXCHANGE: got state msg: 26649fda-2a6f-11e2-0800-e7466d8051c6 from 1 (maindb-node0)

121109  8:12:44 [Note] WSREP: Quorum results:

        version    = 2,

        component  = PRIMARY,

        conf_id    = 6,

        members    = 1/2 (joined/total),

        act_id     = 10182393,

        last_appl. = -1,

        protocols  = 0/4/2 (gcs/repl/appl),

        group UUID = e459a41e-19ed-11e2-0800-28913924bd33

121109  8:12:44 [Note] WSREP: Flow-control interval: [253, 256]

121109  8:12:44 [Note] WSREP: Shifting OPEN -> PRIMARY (TO: 10182393)

121109  8:12:44 [Note] WSREP: State transfer required:

        Group state: e459a41e-19ed-11e2-0800-28913924bd33:10182393

        Local state: 00000000-0000-0000-0000-000000000000:-1

121109  8:12:44 [Note] WSREP: New cluster view: global state: e459a41e-19ed-11e2-0800-28913924bd33:10182393, view# 7: Primary, number of nodes: 2, my index: 0, protocol version 2

121109  8:12:44 [Warning] WSREP: Gap in state sequence. Need state transfer.

121109  8:12:46 [Note] WSREP: Running: 'wsrep_sst_xtrabackup 'joiner' '10.7.25.110' 'root:ft7' '/var/lib/mysql/' '/etc/mysql/wsrep.cnf' '20119' 2>sst.err'

[Freejack]

I'm a bit confused with the versioning of galera between codership and percona.  Am I correct that the version of galera I'm using with Percona is 2.0 and that the latest from codership is 2.2?

If so, I may consider switching back to the codership version for the bug fixes.

[Jay Janssen]

PXC will always lag the latest Codership release because they are independent.  A new PXC release is in the works.  

On Nov 9, 2012, at 11:51 AM, Freejack <free...@gmail.com> wrote:

I'm a bit confused with the versioning of galera between codership and percona.  Am I correct that the version of galera I'm using with Percona is 2.0 and that the latest from codership is 2.2?

If so, I may consider switching back to the codership version for the bug fixes.

--
 
 

Jay Janssen, Senior MySQL Consultant, Percona Inc.

http://about.me/jay.janssen

Percona Live in London, UK Dec 3-4th: http://www.percona.com/live/london-2012/

[Ilias Bertsimas]

Hi FreeJack,

As it is reported on the secondary's node log:

121109  8:12:42 [ERROR] Slave SQL: Could not execute Delete_rows event on table p1.pos; Can't find record in 'pos', Error_code: 1032; handler error HA_ERR_KEY_NOT_FOUND; the event's master log FIRST, end_log_pos 978, Error_code: 1032

That means a delete failed as the record could not be found on the secondary node.. and the consistency of the node considered compromised making it abort the cluster and when restarted needs a full SST to get back to a consistent state.

If you look into your secondary's node mysql datadir you should find files named GRA_X_xxxxxx.log where the RBR statement that failed to apply will be written and so you can use it to debug.

Kind Regards,

Ilias.

[Ilias Bertsimas]

Hi Jay,

Are you going to include the newest 2.2 version in the next PXC release or just the latest 2.1 version ?

Kind Regards,

Ilias.

[Jay Janssen]

I don't do the builds for PXC, Vadim is the right guy to ask, but I think it's 2.2.

On Nov 9, 2012, at 1:35 PM, Ilias Bertsimas <awar...@gmail.com> wrote:

Are you going to include the newest 2.2 version in the next PXC release or just the latest 2.1 version ?

[Vadim Tkachenko]

We use 2.2rc for several last releases.

In PXC 5.5.28 we will include 2.2-release.

> --
>
>



--
Vadim Tkachenko, CTO, Percona Inc.
Phone +1-925-400-7377, Skype: vadimtk153
Schedule meeting: http://meetme.so/VadimTkachenko

Looking for Replication with Data Consistency?
Try Percona XtraDB Cluster!

[Alex Yurchenko]

Hi,

1) It may or may not relate to that huge transaction, but not to its
size

> 121109 8:12:42 [ERROR] Slave SQL: Could not execute Delete_rows
> event on
> table p1.pos; Can't find record in 'pos', Error_code: 1032; handler
> error
> HA_ERR_KEY_NOT_FOUND; the event's master log FIRST, end_log_pos 978,

Can you identify this DELETE to be a part of transaction?

2) This error is characteristic of a table without primary key. Galera
does not support DELETEs on tables without primary keys AND parallel
applying. Make sure that all of your tables have primary keys. Not only
it will make your database Galera compliant, it will also significantly
improve SQL performance. (Just adding an autoincrement column using
alter won't work, you first need to disable autoincrement control
(different autoincrement offsets on different nodes) - if you're using
only one node as a master it makes sense to permanently disable it)

3) Since the node became inconsistent, there is no other way but to
perform a complete state dump from the donor. You can replay missing
transactions only on a consistent database.

4) Galera is a dlopenable library, as long as interface version matches
you can change it without even stopping the server.

> Percona-XtraDB-Cluster-client-5.5.27-23.6.356.rhel5

Here 23 is an interface version.

galera-23.2.2-1.rhel5.x86_64.rpm

same here. So you can just update it. This however won't protect you
from the DELETE issue. You need primary keys.

Regards,
Alex

--
Alexey Yurchenko,
Codership Oy, www.codership.com
Skype: alexey.yurchenko, Phone: +358-400-516-011

[Freejack]

Hi Alex.  There is a PK in the table but I'm not sure if the sequence of the columns could cause an issue.  The key is composed of col2, col1, col5 in that order.  Thanks.

[Alex Yurchenko]

On 2012-11-12 17:04, Freejack wrote:
> Hi Alex. There is a PK in the table but I'm not sure if the sequence
> of
> the columns could cause an issue. The key is composed of col2, col1,
> col5
> in that order. Thanks.

This should not matter, but could you please post (or mail directly to
in...@codership.com) this table definition.

Thanks,
Alex

>> > Oy <in...@codership.com <javascript:>> loaded succesfully.

[Freejack]

Emailed you the table definition.  Thanks.

[Laurent MINOST]

Hi Vadim,

May I ask if you have an ETA for PXC 5.5.28 please ?

Regards,

Laurent

[Vadim Tkachenko]

Laurent,

It was released today
http://www.mysqlperformanceblog.com/2012/11/15/announcing-percona-xtradb-cluster-5-5-28-23-7/

[Freejack]

xtrabackup SST seems to be broken in the release.  I'm doing a fresh install to confirm this.  Will post results soon.

[Vadim Tkachenko]

Freejack,

All SST scripts were updated, so there might be incompatibility .

[Laurent MINOST]

Vadim,

Thanks for this update, I will update my nodes soon to check new and improved/fixed features.

Regards,

Laurent

[Freejack]

innobackupex seems to be looking for datadir in the wsrep.cnf file now.  Most of us probably don't have our data dir set there but in the my.cnf instead.  I simply added datadir to wsrep.cnf also and it works now.

[Freejack]

Actually I spoke too soon.  Here's an explanation of the issues I encountered on the Percona group:

https://groups.google.com/d/topic/percona-discussion/txpT_7X2qTA/discussion

[Michael Eklund]

I have attempted to post my findings to a new post here, but it never appears. 

Here is what I have determined:

there is a problem with assumptions made in the wsrep patch trying to determine cnf file settings,   mysys/default.c::search_default_file_with_ext makes recursive calls when !include/!includedir are used, which are not accounted for in wsrep mysql patches, so it only returns the last included cnf file.

filed a bug here:  https://bugs.launchpad.net/codership-mysql/+bug/1079892

vote it up!!!

[Ilias Bertsimas]

I have not upgraded to the latest version yet, but do you reckon as a workaround using only my.cnf for galera settings and not include anything else ?

[Michael Eklund]

That is mostly what I did, though my username/pw for innobackupex are in a separate file.  So I modified the wsrep_sst_xtrabackup to set the username/pw from this file.  

Here is the patch of my changes for those who might want it.  Nothing earth shattering here:

 # This is a reference script for Percona XtraBackup-based state snapshot tansfer

 

 TMPDIR="/tmp"

-

+MY_CNF="/etc/mysql/my.cnf.admin"

 . $(dirname $0)/wsrep_sst_common

 

 cleanup_joiner()

@@ -32,6 +32,11 @@

 #set +x

 }

 

+get_config()

+{

+    my_print_defaults --config-file="${MY_CNF}" client | grep "\-\-$1"

+}

+

 check_pid()

 {

     local pid_file=$1

@@ -106,6 +111,10 @@

 

         if [ "${AUTH[0]}" != "(null)" ]; then

            INNOBACKUPEX_ARGS="${INNOBACKUPEX_ARGS} --user=${AUTH[0]}"

+        elif [ ! -z "${MY_CNF}" ]; then

+       user=$(get_config user)

+       password=$(get_config password)

+           INNOBACKUPEX_ARGS="${INNOBACKUPEX_ARGS} ${user} ${password}"

         fi

 

         if [ ${#AUTH[*]} -eq 2 ]; then

[Alex Yurchenko]

On 2012-11-20 02:27, Michael Eklund wrote:
> I have attempted to post my findings to a new post here, but it never
> appears.

Google robot sometimes goes nuts and blocks some messages on the basis
of suspected spam - mine as well. The best thing about it is that
notification arrives like the next day or even later.

> Here is what I have determined:
>
> there is a problem with assumptions made in the wsrep patch trying to
> determine cnf file settings,
> mysys/default.c::search_default_file_with_ext
> makes recursive calls when !include/!includedir are used, which are
> not
> accounted for in wsrep mysql patches, so it only returns the last
> included
> cnf file.
>
> filed a bug here:
> https://bugs.launchpad.net/codership-mysql/+bug/1079892
>
> vote it up!!!

Pushed fix to LP, revision 3822.