[MDEV-19616] Galera test failure on galera_sr.galera_sr_cc_master wrong mutex usage Created: 2019-05-28  Updated: 2019-12-23  Resolved: 2019-12-23

Status: Closed
Project: MariaDB Server
Component/s: Galera, Tests
Fix Version/s: 10.4.12

Type: Task Priority: Major
Reporter: Jan Lindström (Inactive) Assignee: Jan Lindström (Inactive)
Resolution: Duplicate Votes: 0
Labels: None

Issue Links:
Duplicate
is duplicated by MDEV-20899 Galera test failure on galera_sr.gale... Closed
Relates
relates to MDEV-20899 Galera test failure on galera_sr.gale... Closed

 Description   

galera_sr.galera_sr_cc_master 'innodb'   w3 [ fail ]
        Test ended at 2019-05-28 11:40:30
 
CURRENT_TEST: galera_sr.galera_sr_cc_master
mysqltest: At line 44: query 'SET GLOBAL wsrep_cluster_address = ''' failed: 2013: Lost connection to MySQL server during query
 
The result from queries just before the failure was:
< snip >
SET AUTOCOMMIT=OFF;
START TRANSACTION;
INSERT INTO t1 VALUES (1);
INSERT INTO t1 VALUES (2);
INSERT INTO t1 VALUES (3);
INSERT INTO t1 VALUES (4);
INSERT INTO t1 VALUES (5);
SELECT COUNT(*) FROM mysql.wsrep_streaming_log;
COUNT(*)
5
connection node_1;
SELECT COUNT(*) FROM mysql.wsrep_streaming_log;
COUNT(*)
5
connect node_2a, 127.0.0.1, root, , test, $NODE_MYPORT_2;
connection node_2a;
SET SESSION wsrep_sync_wait=0;
SET GLOBAL wsrep_cluster_address = '';
 
More results from queries before failure can be found in /home/jan/mysql/10.4/mysql-test/var/3/log/galera_sr_cc_master.log
 
 
Server [mysqld.2 - pid: 18224, winpid: 18224, exit: 256] failed during test run
Server log from this test:
----------SERVER LOG START-----------
2019-05-28 11:40:25 322 [Note] WSREP: Stop replication by 322
safe_mutex: Found wrong usage of mutex 'LOCK_wsrep_cluster_config' and 'LOCK_wsrep_server_state'
Mutex currently locked (in reverse order):
LOCK_wsrep_server_state           /home/jan/mysql/10.4/sql/wsrep_mutex.h  line 34
LOCK_wsrep_cluster_config         /home/jan/mysql/10.4/sql/sys_vars_shared.h  line 56
mysqld: /home/jan/mysql/10.4/mysys/thr_mutex.c:836: print_deadlock_warning: Assertion `my_assert_on_error == 0' failed.
190528 11:40:25 [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.4.6-MariaDB-debug-log
key_buffer_size=1048576
read_buffer_size=131072
max_used_connections=2
max_threads=153
thread_count=11
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 63612 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
 
Thread pointer: 0x7f6260002190
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 = 0x7f62780aee50 thread_stack 0x49000
/home/jan/mysql/10.4/sql/mysqld(my_print_stacktrace+0x40)[0x55ad0fbd53fc]
/home/jan/mysql/10.4/sql/mysqld(handle_fatal_signal+0x3ae)[0x55ad0f422ed9]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x13f40)[0x7f628e2f1f40]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0xc7)[0x7f628dde5ed7]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x121)[0x7f628ddc7535]
/lib/x86_64-linux-gnu/libc.so.6(+0x2540f)[0x7f628ddc740f]
/lib/x86_64-linux-gnu/libc.so.6(+0x35012)[0x7f628ddd7012]
/home/jan/mysql/10.4/sql/mysqld(+0x12c7a3b)[0x55ad0fbdba3b]
/home/jan/mysql/10.4/sql/mysqld(safe_mutex_lock+0x41e)[0x55ad0fbda58b]
mysys/thr_mutex.c:837(print_deadlock_warning)[0x55ad0f07d3d3]
mysys/thr_mutex.c:362(safe_mutex_lock)[0x55ad0f093492]
psi/mysql_thread.h:710(inline_mysql_mutex_lock)[0x55ad0efd0710]
sql/wsrep_mutex.h:35(Wsrep_mutex::lock())[0x55ad0efcf56e]
/home/jan/mysql/10.4/sql/mysqld(_Z22wsrep_stop_replicationP3THD+0x9f)[0x55ad0f337f77]
/home/jan/mysql/10.4/sql/mysqld(_Z28wsrep_cluster_address_updateP7sys_varP3THD13enum_var_type+0x136)[0x55ad0f349275]
wsrep/lock.hpp:38(wsrep::unique_lock<wsrep::mutex>::unique_lock(wsrep::mutex&))[0x55ad0efe771a]
wsrep/server_state.hpp:525(wsrep::server_state::state() const)[0x55ad0efe93e4]
sql/wsrep_mysqld.cc:914(wsrep_stop_replication(THD*))[0x55ad0efe9070]
sql/wsrep_var.cc:485(wsrep_cluster_address_update(sys_var*, THD*, enum_var_type))[0x55ad0f0f97e3]
sql/set_var.cc:209(sys_var::update(THD*, set_var*))[0x55ad0f1039fd]
sql/set_var.cc:837(set_var::update(THD*))[0x55ad0f103079]
sql/set_var.cc:740(sql_set_variables(THD*, List<set_var_base>*, bool))[0x55ad0f0ef0a7]
sql/sql_parse.cc:5199(mysql_execute_command(THD*))[0x55ad0f0ed9c7]
sql/sql_parse.cc:8157(mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool))[0x55ad0f263472]
sql/sql_parse.cc:7980(wsrep_mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool))[0x55ad0f2631d6]
sql/sql_parse.cc:1813(dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool))[0x55ad0fb6d264]
nptl/pthread_create.c:487(start_thread)[0x7f628e2e7182]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x3f)[0x7f628debfb1f]
 
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0x7f6260031938): SET GLOBAL wsrep_cluster_address = ''
Connection ID (thread ID): 322
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=on,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=on,condition_pushdown_for_derived=on,split_materialized=on,condition_pushdown_for_subquery=on,rowid_filter=on,condition_pushdown_from_having=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.
Writing a core file...
Working directory at /home/jan/mysql/10.4/mysql-test/var/3/mysqld.2/data
Resource Limits:
Limit                     Soft Limit           Hard Limit           Units     
Max cpu time              unlimited            unlimited            seconds   
Max file size             unlimited            unlimited            bytes     
Max data size             unlimited            unlimited            bytes     
Max stack size            8388608              unlimited            bytes     
Max core file size        unlimited            unlimited            bytes     
Max resident set          unlimited            unlimited            bytes     
Max processes             127853               127853               processes 
Max open files            1024                 1024                 files     
Max locked memory         67108864             67108864             bytes     
Max address space         unlimited            unlimited            bytes     
Max file locks            unlimited            unlimited            locks     
Max pending signals       127853               127853               signals   
Max msgqueue size         819200               819200               bytes     
Max nice priority         0                    0                    
Max realtime priority     0                    0                    
Max realtime timeout      unlimited            unlimited            us        
Core pattern: |/usr/share/apport/apport %p %s %c %d %P
 
----------SERVER LOG END-------------
 
 
 - found 'core' (0/5)
 
Trying 'dbx' to get a backtrace
 
Trying 'gdb' to get a backtrace from coredump /home/jan/mysql/10.4/mysql-test/var/3/log/galera_sr.galera_sr_cc_master-innodb/mysqld.2/data/core
Core generated by '/home/jan/mysql/10.4/sql/mysqld'
Output from gdb follows. The first stack trace is from the failing thread.
The following stack traces are from all threads (so the failing one is
duplicated).
--------------------------
[New LWP 20138]
[New LWP 19242]
[New LWP 18718]
[New LWP 19212]
[New LWP 18229]
[New LWP 19213]
[New LWP 19247]
[New LWP 19207]
[New LWP 19244]
[New LWP 19215]
[New LWP 19250]
[New LWP 19241]
[New LWP 19255]
[New LWP 19243]
[New LWP 19246]
[New LWP 19251]
[New LWP 18228]
[New LWP 18717]
[New LWP 19248]
[New LWP 18226]
[New LWP 18230]
[New LWP 19217]
[New LWP 19218]
[New LWP 19239]
[New LWP 19240]
[New LWP 19252]
[New LWP 19253]
[New LWP 19254]
[New LWP 19258]
[New LWP 19245]
[New LWP 19216]
[New LWP 19214]
[New LWP 18716]
[New LWP 18715]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Core was generated by `/home/jan/mysql/10.4/sql/mysqld --defaults-group-suffix=.2 --defaults-file=/hom'.
Program terminated with signal SIGABRT, Aborted.
#0  __pthread_kill (threadid=<optimized out>, signo=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:56
56	../sysdeps/unix/sysv/linux/pthread_kill.c: No such file or directory.
[Current thread is 1 (Thread 0x7f62780af700 (LWP 20138))]
#0  __pthread_kill (threadid=<optimized out>, signo=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:56
#1  0x000055ad0fbd54ee in my_write_core (sig=6) at /home/jan/mysql/10.4/mysys/stacktrace.c:481
#2  0x000055ad0f423262 in handle_fatal_signal (sig=6) at /home/jan/mysql/10.4/sql/signal_handler.cc:343
#3  <signal handler called>
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#5  0x00007f628ddc7535 in __GI_abort () at abort.c:79
#6  0x00007f628ddc740f in __assert_fail_base (fmt=0x7f628df55588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55ad10080d80 "my_assert_on_error == 0", file=0x55ad10080570 "/home/jan/mysql/10.4/mysys/thr_mutex.c", line=836, function=<optimized out>) at assert.c:92
#7  0x00007f628ddd7012 in __GI___assert_fail (assertion=0x55ad10080d80 "my_assert_on_error == 0", file=0x55ad10080570 "/home/jan/mysql/10.4/mysys/thr_mutex.c", line=836, function=0x55ad10080e10 <__PRETTY_FUNCTION__.14642> "print_deadlock_warning") at assert.c:101
#8  0x000055ad0fbdba3b in print_deadlock_warning (new_mutex=0x55ad107819a0 <LOCK_wsrep_server_state>, parent_mutex=0x55ad10777200 <LOCK_wsrep_cluster_config>) at /home/jan/mysql/10.4/mysys/thr_mutex.c:836
#9  0x000055ad0fbda58b in safe_mutex_lock (mp=0x55ad107819a0 <LOCK_wsrep_server_state>, my_flags=0, file=0x55ad0fcd1cf8 "/home/jan/mysql/10.4/sql/wsrep_mutex.h", line=34) at /home/jan/mysql/10.4/mysys/thr_mutex.c:360
#10 0x000055ad0f07d3d3 in inline_mysql_mutex_lock (that=0x55ad107819a0 <LOCK_wsrep_server_state>, src_file=0x55ad0fcd1cf8 "/home/jan/mysql/10.4/sql/wsrep_mutex.h", src_line=34) at /home/jan/mysql/10.4/include/mysql/psi/mysql_thread.h:710
#11 0x000055ad0f093492 in Wsrep_mutex::lock (this=0x55ad12eab1d0) at /home/jan/mysql/10.4/sql/wsrep_mutex.h:34
#12 0x000055ad0efd0710 in wsrep::unique_lock<wsrep::mutex>::unique_lock (this=0x7f62780ac750, mutex=...) at /home/jan/mysql/10.4/wsrep-lib/include/wsrep/lock.hpp:37
#13 0x000055ad0efcf56e in wsrep::server_state::state (this=0x55ad12eaaf20) at /home/jan/mysql/10.4/wsrep-lib/include/wsrep/server_state.hpp:524
#14 0x000055ad0f337f77 in wsrep_stop_replication (thd=0x7f6260002190) at /home/jan/mysql/10.4/sql/wsrep_mysqld.cc:914
#15 0x000055ad0f349275 in wsrep_cluster_address_update (self=0x55ad1076f900 <Sys_wsrep_cluster_address>, thd=0x7f6260002190, type=SHOW_OPT_GLOBAL) at /home/jan/mysql/10.4/sql/wsrep_var.cc:483
#16 0x000055ad0efe771a in sys_var::update (this=0x55ad1076f900 <Sys_wsrep_cluster_address>, thd=0x7f6260002190, var=0x7f6260031aa0) at /home/jan/mysql/10.4/sql/set_var.cc:209
#17 0x000055ad0efe93e4 in set_var::update (this=0x7f6260031aa0, thd=0x7f6260002190) at /home/jan/mysql/10.4/sql/set_var.cc:837
#18 0x000055ad0efe9070 in sql_set_variables (thd=0x7f6260002190, var_list=0x7f6260006fb0, free=true) at /home/jan/mysql/10.4/sql/set_var.cc:740
#19 0x000055ad0f0f97e3 in mysql_execute_command (thd=0x7f6260002190) at /home/jan/mysql/10.4/sql/sql_parse.cc:5199
#20 0x000055ad0f1039fd in mysql_parse (thd=0x7f6260002190, rawbuf=0x7f6260031938 "SET GLOBAL wsrep_cluster_address = ''", length=37, parser_state=0x7f62780ae160, is_com_multi=false, is_next_command=false) at /home/jan/mysql/10.4/sql/sql_parse.cc:8157
#21 0x000055ad0f103079 in wsrep_mysql_parse (thd=0x7f6260002190, rawbuf=0x7f6260031938 "SET GLOBAL wsrep_cluster_address = ''", length=37, parser_state=0x7f62780ae160, is_com_multi=false, is_next_command=false) at /home/jan/mysql/10.4/sql/sql_parse.cc:7969
#22 0x000055ad0f0ef0a7 in dispatch_command (command=COM_QUERY, thd=0x7f6260002190, packet=0x7f6260026151 "SET GLOBAL wsrep_cluster_address = ''", packet_length=37, is_com_multi=false, is_next_command=false) at /home/jan/mysql/10.4/sql/sql_parse.cc:1813
#23 0x000055ad0f0ed9c7 in do_command (thd=0x7f6260002190) at /home/jan/mysql/10.4/sql/sql_parse.cc:1361
#24 0x000055ad0f263472 in do_handle_one_connection (connect=0x55ad1338df50) at /home/jan/mysql/10.4/sql/sql_connect.cc:1403
#25 0x000055ad0f2631d6 in handle_one_connection (arg=0x55ad1338df50) at /home/jan/mysql/10.4/sql/sql_connect.cc:1306
#26 0x000055ad0fb6d264 in pfs_spawn_thread (arg=0x55ad13393ba0) at /home/jan/mysql/10.4/storage/perfschema/pfs.cc:1862
#27 0x00007f628e2e7182 in start_thread (arg=<optimized out>) at pthread_create.c:486
#28 0x00007f628debfb1f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95



 Comments   
Comment by Stepan Patryshev (Inactive) [ 2019-12-23 ]

Closing as it is duplicated by MDEV-20899.

Generated at Thu Feb 08 08:53:02 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.