Crash after SST donation

[Danny Gueta]

Hi,

I've encountered a strange issue today which I believe is a bug.

We are running version 5.6.30-76.3-56-log Release rel76.3, Revision aa929cb, WSREP version 25.16.

We've had a node crash today right after it finished giving an SST donation.

I.e node 03 was donating to node 01, it finished successfully and then crashed with a strange error, here the logs.

2016-08-10 05:18:16 15533 [Note] WSREP: Running: 'wsrep_sst_xtrabackup-v2 --role 'donor' --address '192.168.1.24:4444/xtrabackup_sst//1' --socket '/var/lib/mysql/mysql.sock' --datadir '/data/mysql/databases/' --defaults-file '/etc/my.cnf' --defaults-group-suffix '' --binlog '/data/mysql-bin/mysql-bin' --gtid '83e07a6f-96f8-11e3-b8f4-679cb41d96f9:36534791772''
2016-08-10 05:18:16 15533 [Note] WSREP: sst_donor_thread signaled with 0
WSREP_SST: [INFO] Streaming with xbstream (20160810 05:18:18.470)
WSREP_SST: [INFO] Using socat as streamer (20160810 05:18:18.474)
WSREP_SST: [INFO] Using /tmp/tmp.qJd6p81xmJ as innobackupex temporary directory (20160810 05:18:18.568)
WSREP_SST: [INFO] Streaming GTID file before SST (20160810 05:18:18.578)
WSREP_SST: [INFO] Evaluating xbstream -c ${INFO_FILE} | socat -u stdio TCP:192.168.1.24:4444; RC=( ${PIPESTATUS[@]} ) (20160810 05:18:18.601)
2016-08-10 05:18:18 15533 [Note] WSREP: (35e1aeed, 'ssl://0.0.0.0:4567') turning message relay requesting off
WSREP_SST: [INFO] Sleeping before data transfer for SST (20160810 05:18:18.682)
WSREP_SST: [INFO] Streaming the backup to joiner at 192.168.1.24 4444 (20160810 05:18:28.690)
WSREP_SST: [INFO] Evaluating innobackupex --defaults-file=/etc/my.cnf --defaults-group=mysqld --no-version-check --no-backup-locks $tmpopts $INNOEXTRA --galera-info --stream=$sfmt $itmpdir 2>${DATA}/innobackup.backup.log | socat -u stdio TCP:192.168.1.24:4444; RC=( ${PIPESTATUS[@]} ) (20160810 05:18:28.695)
2016-08-10 06:20:25 15533 [Note] WSREP: Provider paused at 83e07a6f-96f8-11e3-b8f4-679cb41d96f9:36537107651 (1081311812)
2016-08-10 06:25:33 15533 [Note] WSREP: resuming provider at 1081311812
2016-08-10 06:25:33 15533 [Note] WSREP: Provider resumed.
2016-08-10 06:25:33 15533 [Note] WSREP: 0.0 (dbm03): State transfer to 1.0 (dbm01) complete.
2016-08-10 06:25:33 15533 [Note] WSREP: Shifting DONOR/DESYNCED -> JOINED (TO: 36537262238)
WSREP_SST: [INFO] Total time on donor: 0 seconds (20160810 06:25:35.361)
2016-08-10 06:25:35 15533 [Note] WSREP: 0.0 (dbm03): State transfer to 1.0 (dbm01) complete.
WSREP_SST: [INFO] Cleaning up temporary directories (20160810 06:25:35.411)
2016-08-10 06:25:59 15533 [ERROR] WSREP: FSM: no such a transition JOINED -> JOINED
10:25:59 UTC - mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed,
something is definitely wrong and this may fail.
Please help us make Percona XtraDB Cluster better by reporting any
bugs at https://bugs.launchpad.net/percona-xtradb-cluster

key_buffer_size=8388608
read_buffer_size=131072
max_used_connections=21
max_threads=1002
thread_count=11
connection_count=0
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 407388 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x7fe070000990
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 7ffb3c2f59d8 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x35)[0x906e45]
/usr/sbin/mysqld(handle_fatal_signal+0x4b4)[0x66ac44]
/lib64/libpthread.so.0(+0xf100)[0x7ffe3b559100]
/lib64/libc.so.6(gsignal+0x37)[0x7ffe396e75f7]
/lib64/libc.so.6(abort+0x148)[0x7ffe396e8ce8]
/usr/lib64/libgalera_smm.so(_ZN6galera3FSMINS_10Replicator5StateENS_13ReplicatorSMM10TransitionENS_10EmptyGuardENS3_11StateActionEE8shift_toES2_+0x212)[0x7ffdc7bab302]
/usr/lib64/libgalera_smm.so(_ZN6galera13ReplicatorSMM12process_joinEll+0x178)[0x7ffdc7ba6478]
/usr/lib64/libgalera_smm.so(_ZN6galera15GcsActionSource8dispatchEPvRK10gcs_actionRb+0x21d)[0x7ffdc7b8187d]
/usr/lib64/libgalera_smm.so(_ZN6galera15GcsActionSource7processEPvRb+0x63)[0x7ffdc7b81ed3]
/usr/lib64/libgalera_smm.so(_ZN6galera13ReplicatorSMM10async_recvEPv+0x73)[0x7ffdc7ba68a3]
/usr/lib64/libgalera_smm.so(galera_recv+0x24)[0x7ffdc7bb6e14]
/usr/sbin/mysqld[0x5a20f1]
/usr/sbin/mysqld(start_wsrep_THD+0x36e)[0x58b73e]
/lib64/libpthread.so.0(+0x7dc5)[0x7ffe3b551dc5]
/lib64/libc.so.6(clone+0x6d)[0x7ffe397a8c9d]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.

[Danny Gueta (danny-gueta)]

This has just occurred again, it seems as if the donating node is stuck in 'Joined' state after the donation has already been completed.

I.e : wsrep_local_state_comment | Joined

[Danny Gueta (danny-gueta)]

Sorry, forgot to add log snippet:

2016-08-10 07:52:25 15775 [Note] WSREP: 0.0 (dbm02): State transfer to 1.0 (dbm01) complete.
2016-08-10 07:52:25 15775 [Note] WSREP: Shifting DONOR/DESYNCED -> JOINED (TO: 36537395115)
2016-08-10 07:52:25 15775 [Note] WSREP: SYNC message ignored as node 0.0 (dbm02) was re-transitioned to DONOR mode before it synced.
2016-08-10 07:52:26 15775 [ERROR] WSREP: sst sent called when not SST donor, state JOINED
WSREP_SST: [INFO] Total time on donor: 0 seconds (20160810 07:52:26.375)
WSREP_SST: [INFO] Cleaning up temporary directories (20160810 07:52:26.381)
2016-08-10 07:54:24 15775 [Note] WSREP: 1.0 (dbm01): State transfer from 0.0 (dbm02) complete.
2016-08-10 07:54:25 15775 [Note] WSREP: Member 1.0 (dbm01) synced with group.
2016-08-10 07:55:51 7f53c1ffb700 InnoDB: Buffer pool(s) load completed at 160810 7:55:51

[Krunal Bauskar (krunal-bauskar)]

Hi Danny,

Wondering if u have active workload given that we see node moving to pause state and then resuming.

2016-08-10 06:20:25 15533 [Note] WSREP: Provider paused at 83e07a6f-96f8-11e3-b8f4-679cb41d96f9:36537107651 (1081311812)
2016-08-10 06:25:33 15533 [Note] WSREP: resuming provider at 1081311812
2016-08-10 06:25:33 15533 [Note] WSREP: Provider resumed.

Can you confirm this out ?

Regards,
Krunal

[Danny Gueta (danny-gueta)]

Hi Krunal,

this has already occurred 3 times today after an SST.

on all times the donating node had zero work-load on it, the scenario is nodes are up, 1 has active workload on it, 2nd is siting 'idle' meaning only receiving replication events.

we then add node 3 which is receiving a donation from node 2 which has no workload on it.

The SST finishes successfully and node 3 starts preparing the backup then all of sudden the donating node crashes resulting, node 3 which has finish preparing the backup also doesn't start since it cannot communicate anymore with the donating node, end result is 2 dead nodes out of 3 resulting is node 1 thinking its in split brain and pushing itself to 'initializing' mode as its alone in the cluster.

Here are the logs from the donating node, as you can see SST started at 08:17.

2016-08-10 08:17:41 44480 [Note] WSREP: New cluster view: global state: 83e07a6f-96f8-11e3-b8f4-679cb41d96f9:36537410774, view# 5: Primary, number of nodes: 3, my index: 1, protocol version 3
2016-08-10 08:17:41 44480 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2016-08-10 08:17:41 44480 [Note] WSREP: REPL Protocols: 7 (3, 2)
2016-08-10 08:17:41 44480 [Note] WSREP: Service thread queue flushed.
2016-08-10 08:17:41 44480 [Note] WSREP: Assign initial position for certification: 36537410774, protocol version: 3
2016-08-10 08:17:41 44480 [Note] WSREP: Service thread queue flushed.
2016-08-10 08:17:41 44480 [Note] WSREP: Member 0.0 (dbm03) requested state transfer from 'dbm01'. Selected 1.0 (dbm01)(SYNCED) as donor.
2016-08-10 08:17:41 44480 [Note] WSREP: Shifting SYNCED -> DONOR/DESYNCED (TO: 36537410786)
2016-08-10 08:17:41 44480 [Note] WSREP: IST request: 83e07a6f-96f8-11e3-b8f4-679cb41d96f9:36537262283-36537410774|ssl://192.168.3.72:4568
2016-08-10 08:17:41 44480 [Note] WSREP: IST first seqno 36537262284 not found from cache, falling back to SST
2016-08-10 08:17:41 44480 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2016-08-10 08:17:41 44480 [Note] WSREP: Running: 'wsrep_sst_xtrabackup-v2 --role 'donor' --address '192.168.3.72:4444/xtrabackup_sst//1' --socket '/var/lib/mysql/mysql.sock' --datadir '/data/mysql/databases/' --defaults-file '/etc/my.cnf' --defaults-group-suffix '' --binlog '/data/mysql-bin/mysql-bin' --gtid '83e07a6f-96f8-11e3-b8f4-679cb41d96f9:36537410786''
2016-08-10 08:17:41 44480 [Note] WSREP: sst_donor_thread signaled with 0
WSREP_SST: [INFO] Streaming with xbstream (20160810 08:17:41.878)
WSREP_SST: [INFO] Using socat as streamer (20160810 08:17:41.881)
WSREP_SST: [INFO] Using /tmp/tmp.5BxMILbRlr as innobackupex temporary directory (20160810 08:17:41.898)
WSREP_SST: [INFO] Streaming GTID file before SST (20160810 08:17:41.906)
WSREP_SST: [INFO] Evaluating xbstream -c ${INFO_FILE} | socat -u stdio TCP:192.168.3.72:4444; RC=( ${PIPESTATUS[@]} ) (20160810 08:17:41.920)
WSREP_SST: [INFO] Sleeping before data transfer for SST (20160810 08:17:41.927)
2016-08-10 08:17:43 44480 [Note] WSREP: (5e4347dd, 'ssl://0.0.0.0:4567') turning message relay requesting off
WSREP_SST: [INFO] Streaming the backup to joiner at 192.168.3.72 4444 (20160810 08:17:51.934)
WSREP_SST: [INFO] Eval...

[Krunal Bauskar (krunal-bauskar)]

Hi Danny,

What is interesting to understand are the following lines in the donor-log ?

2016-08-10 06:20:25 15533 [Note] WSREP: Provider paused at 83e07a6f-96f8-11e3-b8f4-679cb41d96f9:36537107651 (1081311812)
2016-08-10 06:25:33 15533 [Note] WSREP: resuming provider at 1081311812
2016-08-10 06:25:33 15533 [Note] WSREP: Provider resumed.

It suggest that node was paused and then resumed and we trying to understand what can cause it if there is no workload running on donor-node.

We are trying to reproduce the scenario locally but if you have a reproducible use-case that would help us hunt this quicker.

Regards,
Krunal

[Danny Gueta (danny-gueta)]

Krunal,

I ended up doing a manual xtrabackup and rsyncing to nodes 1+3 of course it finished with an IST, it seemed to have worked fine so now i have all 3 nodes up.

I believe i can re-create this scenario but let me know what further information you require before i do so.

Thanks,
Danny.

[Krunal Bauskar (krunal-bauskar)]

Hi Danny,

I was able to reproduce something similar which hints toward the problem you are facing.

For sure you are using XB with backup locks disabled either by use of --no-backup-locks or FORCE_FTWRL=1 and I see we hit this scenario only when XB tries to do full FLUSH TABLE WITH READ LOCK.

(As per the updated FLUSH TABLE WITH READ LOCK desync+pause the node which is already done as part of SST flow and there probably is some race in that code path)

-------------------------------
From your log snippet:

WSREP_SST: [INFO] Evaluating innobackupex --defaults-file=/etc/my.cnf --defaults-group=mysqld --no-version-check ***********--no-backup-locks************ $tmpopts $INNOEXTRA --galera-info --stream=$sfmt $itmpdir 2>${DATA}/innobackup.backup.log | socat -u stdio TCP:192.168.1.24:4444; RC=( ${PIPESTATUS[@]} ) (20160810 05:18:28.695)
------------------------------

What is the quick workaround:
* Avoid suppressing backup-lock. As I understand backup locks were unstable before but they are good now. I am still running some local test to ensure that we can get rid of the limitation added to PXC documents.

"Backup locks used during SST or with Xtrabackup can crash, on donor, either use inno-backup-opts=’–no-backup-locks’ under [sst] in my.cnf or set FORCE_FTWRL=1 in /etc/sysconfig/mysql (or /etc/sysconfig/mysql.%i for corresponding unit/service) for CentOS/RHEL or /etc/default/mysql in debian/ubuntu. You can also use rsync as the alternate SST method if those don’t work."

[Danny Gueta (danny-gueta)]

Hi Krunal,

You are correct, i am using the following option under my.cnf file:

[sst]
inno-backup-opts='--no-backup-locks'

So I'll just go ahead and temporarily remove that option.

Thanks for the help, highly appreciated!

[Shahriyar Rzayev (rzayev-sehriyar)]

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