[MDEV-10837] Crash after node desync Created: 2016-09-20  Updated: 2019-12-12  Resolved: 2019-12-12

Status: Closed
Project: MariaDB Server
Component/s: Galera, Galera SST, Platform Debian, Storage Engine - InnoDB
Affects Version/s: 10.0.27-galera
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Fabian Meyer Assignee: Jan Lindström (Inactive)
Resolution: Won't Fix Votes: 0
Labels: galera, innodb, replication


 Description   

One node (master) in a master-slave setup (gcs.fc_master_slave = YES; pc.ignore_sb = TRUE") crashed after it desynced itself from the cluster.
Iam using Xtrabackub to do Backups on the slave node.

Maybe it corresbonds with the bug, which i've already found:
https://bugs.launchpad.net/percona-xtradb-cluster/+bug/1611728
The only thing which dont fit to my setup is, that i don't use the option
inno-backup-opts='--no-backup-locks' in the config.

Here are the corresponding log lines:

160920 0:00:01 [Note] WSREP: Member 0.0 (aletheia) desyncs itself from group
160920 0:00:01 [Note] WSREP: Shifting SYNCED -> DONOR/DESYNCED (TO: 64409986)
160920 0:00:01 [Note] WSREP: Provider paused at e9f93a90-6927-11e5-a267-ce9ade7c14b0:64409986 (7023)
160920 0:00:10 [Note] WSREP: resuming provider at 7023
160920 0:00:10 [Note] WSREP: Provider resumed.
160920 0:00:10 [Note] WSREP: Member 0.0 (aletheia) resyncs itself to group
160920 0:00:10 [Note] WSREP: Shifting DONOR/DESYNCED -> JOINED (TO: 64410083)
160920 0:00:10 [Note] WSREP: Member 0.0 (aletheia) synced with group.
160920 0:00:10 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 64410083)
160920 0:00:11 [Note] WSREP: Member 0.0 (aletheia) desyncs itself from group
160920 0:00:11 [Note] WSREP: Shifting SYNCED -> DONOR/DESYNCED (TO: 64410123)
160920 0:00:15 [Note] WSREP: Synchronized with group, ready for connections
160920 0:00:18 [Note] WSREP: Provider paused at e9f93a90-6927-11e5-a267-ce9ade7c14b0:64410207 (7249)
160920 0:00:22 [Note] WSREP: resuming provider at 7249
160920 0:00:22 [Note] WSREP: Provider resumed.
160920 0:00:22 [Note] WSREP: Member 0.0 (aletheia) resyncs itself to group
160920 0:00:22 [Note] WSREP: Shifting DONOR/DESYNCED -> JOINED (TO: 64410793)
160920 0:00:23 [Note] WSREP: Member 0.0 (aletheia) desyncs itself from group
160920 0:00:23 [Note] WSREP: Shifting JOINED -> DONOR/DESYNCED (TO: 64410793)
160920 0:00:24 [ERROR] WSREP: FSM: no such a transition JOINED -> DONOR
160920 0:00:24 [ERROR] 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.

To report this bug, see https://mariadb.com/kb/en/reporting-bugs

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.

Server version: 10.0.27-MariaDB-1~trusty-wsrep
key_buffer_size=268435456
read_buffer_size=131072
max_used_connections=5
max_threads=102
thread_count=3
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 486142 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x0x7f1627a52008
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 = 0x7f1672ed5df0 thread_stack 0x30000
/usr/sbin/mysqld(my_print_stacktrace+0x2e)[0x7f16728d3dae]
/usr/sbin/mysqld(handle_fatal_signal+0x433)[0x7f16723ff573]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x10330)[0x7f1670b9d330]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x37)[0x7f16701f4c37]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x148)[0x7f16701f8028]
/usr/lib/galera/libgalera_smm.so(ZN6galera3FSMINS_10Replicator5StateENS_13ReplicatorSMM10TransitionENS_10EmptyGuardENS_11EmptyActionEE8shift_toES2+0x17c)[0x7f165e994f2c]
/usr/lib/galera/libgalera_smm.so(_ZN6galera13ReplicatorSMM6desyncEv+0x70)[0x7f165e98eaf0]
/usr/lib/galera/libgalera_smm.so(galera_desync+0x19)[0x7f165e99d4d9]
/usr/sbin/mysqld(_ZN16Global_read_lock34make_global_read_lock_block_commitEP3THD+0x3c8)[0x7f16724dae18]
/usr/sbin/mysqld(_Z20reload_acl_and_cacheP3THDyP10TABLE_LISTPi+0x37f)[0x7f167236954f]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0xb36)[0x7f167226ebb6]
/usr/sbin/mysqld(+0x415f8b)[0x7f1672278f8b]
/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x1fcd)[0x7f167227b59d]
/usr/sbin/mysqld(_Z10do_commandP3THD+0x2fd)[0x7f167227c36d]
/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x34b)[0x7f167234ce4b]
/usr/sbin/mysqld(handle_one_connection+0x40)[0x7f167234cf30]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x8184)[0x7f1670b95184]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7f16702b837d]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0x7f1621013020): is an invalid pointer
Connection ID (thread ID): 381
Status: NOT_KILLED

Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_co$

The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.

We think the query pointer is invalid, but we will try to print it anyway.
Query: FLUSH TABLES WITH READ LOCK

160920 00:00:24 mysqld_safe Number of processes running now: 0
160920 00:00:24 mysqld_safe WSREP: not restarting wsrep node automatically
160920 00:00:24 mysqld_safe mysqld from pid file /var/run/mysqld/mysqld.pid ended

 Comments   
Comment by Fabian Meyer [ 2016-09-21 ]

It now happened twice. Like the last time it happened at 0:00h when there is a dump of alle databases at the slave-node. Till the last update evereything went fine.

Comment by Fabian Meyer [ 2016-11-04 ]

On the master, until now, the crash didn't appear again.
Now the slave crashed obviously due to the same reason

Note: The desync every five minutes is because of a incremental backup via xtrabackup every minutes.

161102 17:25:12 [Note] WSREP: Member 1.0 (apollon) desyncs itself from group
161102 17:25:12 [Note] WSREP: Shifting SYNCED -> DONOR/DESYNCED (TO: 68399070)
161102 17:25:12 [Note] WSREP: Provider paused at e9f93a90-6927-11e5-a267-ce9ade7c14b0:68399070 (3667938)
161102 17:25:14 [Note] WSREP: resuming provider at 3667938
161102 17:25:14 [Note] WSREP: Provider resumed.
161102 17:25:14 [Note] WSREP: Member 1.0 (apollon) resyncs itself to group
161102 17:25:14 [Note] WSREP: Shifting DONOR/DESYNCED -> JOINED (TO: 68399115)
161102 17:25:14 [Note] WSREP: Member 1.0 (apollon) synced with group.
161102 17:25:14 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 68399115)
161102 17:25:14 [Note] WSREP: Synchronized with group, ready for connections
161102 17:30:11 [Note] WSREP: Member 1.0 (apollon) desyncs itself from group
161102 17:30:11 [Note] WSREP: Shifting SYNCED -> DONOR/DESYNCED (TO: 68403400)
161102 17:30:11 [Note] WSREP: Provider paused at e9f93a90-6927-11e5-a267-ce9ade7c14b0:68403400 (3672340)
161102 17:30:13 [Note] WSREP: resuming provider at 3672340
161102 17:30:13 [Note] WSREP: Provider resumed.
161102 17:30:13 [Note] WSREP: Member 1.0 (apollon) resyncs itself to group
161102 17:30:13 [Note] WSREP: Shifting DONOR/DESYNCED -> JOINED (TO: 68403509)
161102 17:35:10 [Note] WSREP: Member 1.0 (apollon) desyncs itself from group
161102 17:35:10 [Note] WSREP: Shifting JOINED -> DONOR/DESYNCED (TO: 68413819)
161102 17:35:10 [ERROR] WSREP: FSM: no such a transition JOINED -> DONOR
161102 17:35:10 [ERROR] 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.

To report this bug, see https://mariadb.com/kb/en/reporting-bugs

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.

Server version: 10.0.27-MariaDB-1~trusty-wsrep
key_buffer_size=16777216
read_buffer_size=131072
max_used_connections=4
max_threads=153
thread_count=3
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 352392 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x0x7f77fb694008
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 = 0x7f7822bf9df0 thread_stack 0x30000
/usr/sbin/mysqld(my_print_stacktrace+0x2e)[0x7f78225f7dae]
/usr/sbin/mysqld(handle_fatal_signal+0x433)[0x7f7822123573]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x10330)[0x7f78208c1330]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x37)[0x7f781ff18c37]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x148)[0x7f781ff1c028]
/usr/lib/galera/libgalera_smm.so(ZN6galera3FSMINS_10Replicator5StateENS_13ReplicatorSMM10TransitionENS_10EmptyGuardENS_11EmptyActionEE8shift_toES2+0x17c)[0x7f781d594f2c]
/usr/lib/galera/libgalera_smm.so(_ZN6galera13ReplicatorSMM6desyncEv+0x70)[0x7f781d58eaf0]
/usr/lib/galera/libgalera_smm.so(galera_desync+0x19)[0x7f781d59d4d9]
/usr/sbin/mysqld(_ZN16Global_read_lock34make_global_read_lock_block_commitEP3THD+0x3c8)[0x7f78221fee18]
/usr/sbin/mysqld(_Z20reload_acl_and_cacheP3THDyP10TABLE_LISTPi+0x37f)[0x7f782208d54f]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0xb36)[0x7f7821f92bb6]
/usr/sbin/mysqld(+0x415f8b)[0x7f7821f9cf8b]
/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x1fcd)[0x7f7821f9f59d]
/usr/sbin/mysqld(_Z10do_commandP3THD+0x2fd)[0x7f7821fa036d]
/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x34b)[0x7f7822070e4b]
/usr/sbin/mysqld(handle_one_connection+0x40)[0x7f7822070f30]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x8184)[0x7f78208b9184]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7f781ffdc37d]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0x7f77ef01f020): is an invalid pointer
Connection ID (thread ID): 88223
Status: NOT_KILLED

Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=off,table_elimination=on,extended_keys=on,exists_to_in=on

The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.

We think the query pointer is invalid, but we will try to print it anyway.
Query: FLUSH TABLES WITH READ LOCK

Comment by Andrew Garner [ 2017-03-03 ]

This also affects MariaDB/Galera on the latest 10.1.21 w/ wsrep_provider_version 3.19. I ran into this under similar circumstances - backing up a busy MariaDB/Galera cluster. I was able to trivially reproduce the problem with a fairly simple process:

  1. Put some write load on the cluster w/ sysbench or similar
  2. FTWRL one node, watch it desync and wait for wsrep_local_recv_queue to grow
  3. UNLOCK TABLES on that node and wait for transition from Donor/Desynced -> Joined
  4. FLUSH TABLES WITH READ LOCK again before node can transition back to Synced
  5. Watch mysqld crash

This was fixed in wsrep_provider_version 3.20 around here, I think:

https://github.com/codership/galera/commit/01678e3b58b062f068f8a267465df27df6761d17

In a test environment, I upgraded to libgalera_smm 3.20 from the codership stable release (http://galeracluster.com/downloads/) and was no longer able to reproduce the crash found under 3.19, while still running under MariaDB 10.1.21. The MariaDB repos still ship galera-3.19, of course.

You can see the clean state transition with an updated libgalera_smm.so, where with galera 3.20, the stats can now shift from JOINED -> DONOR/DESYNCED -> JOINED -> SYNCED without crashing now.

2017-03-03  1:20:02 140097436944640 [Note] WSREP: wsrep_load(): Galera 3.20(r7e383f7) by Codership Oy <info@codership.com> loaded successfully.
 
...
 
2017-03-03  1:22:09 140097338596096 [Note] WSREP: running implicit desync for node
 
2017-03-03  1:22:09 140095113918208 [Note] WSREP: Member 1.0 (galera02.global) desyncs itself from group
 
2017-03-03  1:22:09 140095113918208 [Note] WSREP: Shifting SYNCED -> DONOR/DESYNCED (TO: 2732573)
 
2017-03-03  1:22:09 140097338596096 [Note] WSREP: Provider paused at 9e791acb-f9e3-11e6-89c9-9eb41cb09bd3:2732575 (56256)
 
2017-03-03  1:23:13 140097338596096 [Note] WSREP: resuming provider at 56256
 
2017-03-03  1:23:13 140097338596096 [Note] WSREP: Provider resumed.
 
2017-03-03  1:23:13 140095113918208 [Note] WSREP: Member 1.0 (galera02.global) resyncs itself to group
 
2017-03-03  1:23:13 140095113918208 [Note] WSREP: Shifting DONOR/DESYNCED -> JOINED (TO: 2861229)
 
2017-03-03  1:23:36 140097338596096 [Note] WSREP: running implicit desync for node
 
2017-03-03  1:23:36 140095113918208 [Note] WSREP: Member 1.0 (galera02.global) desyncs itself from group
 
2017-03-03  1:23:36 140095113918208 [Note] WSREP: Shifting JOINED -> DONOR/DESYNCED (TO: 2907624)
 
2017-03-03  1:24:21 140097338596096 [Note] WSREP: resuming provider at 242016
 
2017-03-03  1:24:21 140097338596096 [Note] WSREP: Provider resumed.
 
2017-03-03  1:24:21 140095113918208 [Note] WSREP: Member 1.0 (galera02.global) resyncs itself to group
 
2017-03-03  1:24:21 140095113918208 [Note] WSREP: Shifting DONOR/DESYNCED -> JOINED (TO: 2996180)
 
2017-03-03  1:24:37 140095113918208 [Note] WSREP: Member 1.0 (galera02.global) synced with group.
 
2017-03-03  1:24:37 140095113918208 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 3028473)
 
2017-03-03  1:24:37 140097358523136 [Note] WSREP: Synchronized with group, ready for connections
 
2017-03-03  1:24:37 140097358523136 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.

Comment by Jan Lindström (Inactive) [ 2019-12-12 ]

Support for 10.0-galera has ended.

Generated at Thu Feb 08 07:45:18 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.