[MDEV-10892] rpl.rpl_semi_sync_uninstall_plugin fails with Assertion `0' failure in buildbot Created: 2016-09-26  Updated: 2019-06-28  Resolved: 2017-10-13

Status: Closed
Project: MariaDB Server
Component/s: Replication, Tests
Affects Version/s: 5.5, 10.0, 10.1, 10.2
Fix Version/s: 5.5.58, 10.0.33, 10.1.29, 10.2.10, 10.3.3

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Sergey Vojtovich
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
Blocks
blocks MDEV-7069 Fix buildbot failures in main server ... Stalled
Relates
relates to MDEV-7140 Sporadic buildbot failures in rpl.rpl... Closed
relates to MDEV-19904 rpl_semi_sync_uninstall_plugin fails ... Closed

 Description   

http://buildbot.askmonty.org/buildbot/builders/kvm-fulltest2/builds/5987/steps/test_7/logs/stdio

rpl.rpl_semi_sync_uninstall_plugin 'stmt' w3 [ fail ]
        Test ended at 2016-09-25 18:18:26
 
CURRENT_TEST: rpl.rpl_semi_sync_uninstall_plugin
mysqltest: In included file "./include/wait_condition.inc": 
included from /mnt/buildbot/build/mariadb-10.2.2/mysql-test/suite/rpl/t/rpl_semi_sync_uninstall_plugin.test at line 115:
At line 43: query 'let $success= `$wait_condition`' failed with wrong errno 2013: 'Lost connection to MySQL server during query', instead of 0...
 
The result from queries just before the failure was:
< snip >
show status like "Rpl_semi_sync_slave_status";
Variable_name	Value
Rpl_semi_sync_slave_status	ON
connection master;
show status like "Rpl_semi_sync_master_status";
Variable_name	Value
Rpl_semi_sync_master_status	ON
show status like "Rpl_semi_sync_master_clients";
Variable_name	Value
Rpl_semi_sync_master_clients	1
select plugin_name,plugin_status from information_schema.plugins where plugin_name like 'rpl_%';
plugin_name	plugin_status
rpl_semi_sync_master	DELETED
connection slave;
include/stop_slave.inc
select plugin_name,plugin_status from information_schema.plugins where plugin_name like 'rpl_%';
plugin_name	plugin_status
connection master;
create table t2 (a int);
drop table t2;

mysqld: /home/buildbot/buildbot/build/mariadb-10.2.2/sql/sql_show.cc:178: my_bool show_plugins(THD*, plugin_ref, void*): Assertion `0' failed.
2016-09-25 18:18:17 2970310464 [Note] unregister_replicator OK
160925 18:18:17 [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.2.2-MariaDB-debug-log
key_buffer_size=1048576
read_buffer_size=131072
max_used_connections=7
max_threads=153
thread_count=9
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 61859 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
 
Thread pointer: 0x0xb1429de8
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 = 0xb126ae80 thread_stack 0x48c00
/mnt/buildbot/build/mariadb-10.2.2/sql/mysqld(my_print_stacktrace+0x32)[0x8cde4b1]
/mnt/buildbot/build/mariadb-10.2.2/sql/mysqld(handle_fatal_signal+0x3c8)[0x85889d0]
[0xeec400]
[0xeec416]
/lib/i386-linux-gnu/libc.so.6(gsignal+0x4f)[0xd4f1ef]
/lib/i386-linux-gnu/libc.so.6(abort+0x175)[0xd52835]
/lib/i386-linux-gnu/libc.so.6(+0x27095)[0xd48095]
/lib/i386-linux-gnu/libc.so.6(+0x27147)[0xd48147]
/mnt/buildbot/build/mariadb-10.2.2/sql/mysqld[0x83b18ac]
/mnt/buildbot/build/mariadb-10.2.2/sql/mysqld(_Z24plugin_foreach_with_maskP3THDPFcS0_PP13st_plugin_intPvEijS4_+0x2af)[0x83493e2]
/mnt/buildbot/build/mariadb-10.2.2/sql/mysqld(_Z12fill_pluginsP3THDP10TABLE_LISTP4Item+0x6f)[0x83b1e3f]
/mnt/buildbot/build/mariadb-10.2.2/sql/mysqld(_Z24get_schema_tables_resultP4JOIN23enum_schema_table_state+0x312)[0x83ccdad]
/mnt/buildbot/build/mariadb-10.2.2/sql/mysqld(_ZN4JOIN10exec_innerEv+0x853)[0x8372777]
/mnt/buildbot/build/mariadb-10.2.2/sql/mysqld(_ZN4JOIN4execEv+0xcd)[0x8371e81]
/mnt/buildbot/build/mariadb-10.2.2/sql/mysqld(_Z12mysql_selectP3THDP10TABLE_LISTjR4ListI4ItemEPS4_jP8st_orderS9_S7_S9_yP13select_resultP18st_select_lex_unitP13st_select_lex+0x35a)[0x837308d]
/mnt/buildbot/build/mariadb-10.2.2/sql/mysqld(_Z13handle_selectP3THDP3LEXP13select_resultm+0x1e4)[0x8369418]
/mnt/buildbot/build/mariadb-10.2.2/sql/mysqld[0x833844a]
/mnt/buildbot/build/mariadb-10.2.2/sql/mysqld(_Z21mysql_execute_commandP3THD+0x182c)[0x832d2e4]
/mnt/buildbot/build/mariadb-10.2.2/sql/mysqld(_Z11mysql_parseP3THDPcjP12Parser_statebb+0x288)[0x833bb7c]
/mnt/buildbot/build/mariadb-10.2.2/sql/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcjbb+0xee0)[0x8328e5e]
/mnt/buildbot/build/mariadb-10.2.2/sql/mysqld(_Z10do_commandP3THD+0x77f)[0x83278a7]
/mnt/buildbot/build/mariadb-10.2.2/sql/mysqld(_Z24do_handle_one_connectionP7CONNECT+0x1bf)[0x8460751]
/mnt/buildbot/build/mariadb-10.2.2/sql/mysqld(handle_one_connection+0x38)[0x84604df]
/mnt/buildbot/build/mariadb-10.2.2/sql/mysqld[0x877fb6d]
/lib/i386-linux-gnu/libpthread.so.0(+0x6d4c)[0x116d4c]
/lib/i386-linux-gnu/libc.so.6(clone+0x5e)[0xe0bace]
 
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0xb1431958): select count(*) = 0 from information_schema.plugins where plugin_name like 'rpl_%'
Connection ID (thread ID): 8
Status: NOT_KILLED



 Comments   
Comment by Elena Stepanova [ 2016-10-31 ]

Variation with a crash instead of assertion failure:
http://buildbot.askmonty.org/buildbot/builders/kvm-deb-precise-amd64/builds/7271/steps/test_5/logs/stdio

rpl.rpl_semi_sync_uninstall_plugin 'stmt' w4 [ fail ]
        Test ended at 2016-10-27 07:43:11
 
CURRENT_TEST: rpl.rpl_semi_sync_uninstall_plugin
mysqltest: In included file "./include/wait_condition.inc": 
included from /usr/share/mysql/mysql-test/suite/rpl/t/rpl_semi_sync_uninstall_plugin.test at line 115:
At line 43: query 'let $success= `$wait_condition`' failed with wrong errno 2013: 'Lost connection to MySQL server during query', instead of 0...
 
The result from queries just before the failure was:
< snip >
show status like "Rpl_semi_sync_slave_status";
Variable_name	Value
Rpl_semi_sync_slave_status	ON
connection master;
show status like "Rpl_semi_sync_master_status";
Variable_name	Value
Rpl_semi_sync_master_status	ON
show status like "Rpl_semi_sync_master_clients";
Variable_name	Value
Rpl_semi_sync_master_clients	1
select plugin_name,plugin_status from information_schema.plugins where plugin_name like 'rpl_%';
plugin_name	plugin_status
rpl_semi_sync_master	DELETED
connection slave;
include/stop_slave.inc
select plugin_name,plugin_status from information_schema.plugins where plugin_name like 'rpl_%';
plugin_name	plugin_status
connection master;
create table t2 (a int);
drop table t2;
 
More results from queries before failure can be found in /run/shm/var/4/log/rpl_semi_sync_uninstall_plugin.log
 
 
Server [mysqld.1 - pid: 17942, winpid: 17942, exit: 256] failed during test run
Server log from this test:
----------SERVER LOG START-----------
2016-10-27  7:43:00 140215602993024 [Note] /usr/sbin/mysqld (mysqld 10.2.3-MariaDB-1~precise-log) starting as process 17943 ...
2016-10-27  7:43:00 140215602993024 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4162)
2016-10-27  7:43:00 140215602993024 [Note] Plugin 'partition' is disabled.
2016-10-27  7:43:00 140215602993024 [Note] Plugin 'InnoDB' is disabled.
2016-10-27  7:43:00 140215602993024 [Note] Plugin 'SEQUENCE' is disabled.
2016-10-27  7:43:00 140215602993024 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
2016-10-27  7:43:00 140215602993024 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
2016-10-27  7:43:00 140215602993024 [Note] Plugin 'INNODB_LOCKS' is disabled.
2016-10-27  7:43:00 140215602993024 [Note] Plugin 'INNODB_TABLESPACES_SCRUBBING' is disabled.
2016-10-27  7:43:00 140215602993024 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
2016-10-27  7:43:00 140215602993024 [Note] Plugin 'INNODB_CMP_PER_INDEX' is disabled.
2016-10-27  7:43:00 140215602993024 [Note] Plugin 'INNODB_CMP' is disabled.
2016-10-27  7:43:00 140215602993024 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
2016-10-27  7:43:00 140215602993024 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
2016-10-27  7:43:00 140215602993024 [Note] Plugin 'INNODB_LOCK_WAITS' is disabled.
2016-10-27  7:43:00 140215602993024 [Note] Plugin 'INNODB_TABLESPACES_ENCRYPTION' is disabled.
2016-10-27  7:43:00 140215602993024 [Note] Plugin 'INNODB_BUFFER_PAGE_LRU' is disabled.
2016-10-27  7:43:00 140215602993024 [Note] Plugin 'INNODB_SYS_FIELDS' is disabled.
2016-10-27  7:43:00 140215602993024 [Note] Plugin 'INNODB_TRX' is disabled.
2016-10-27  7:43:00 140215602993024 [Note] Plugin 'FEEDBACK' is disabled.
2016-10-27  7:43:00 140215602993024 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
2016-10-27  7:43:00 140215602993024 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
2016-10-27  7:43:00 140215602993024 [Note] Plugin 'INNODB_TEMP_TABLE_INFO' is disabled.
2016-10-27  7:43:00 140215602993024 [Note] Plugin 'INNODB_MUTEXES' is disabled.
2016-10-27  7:43:00 140215602993024 [Note] Plugin 'INNODB_SYS_TABLES' is disabled.
2016-10-27  7:43:00 140215602993024 [Note] Plugin 'INNODB_SYS_FOREIGN_COLS' is disabled.
2016-10-27  7:43:00 140215602993024 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
2016-10-27  7:43:00 140215602993024 [Note] Plugin 'INNODB_BUFFER_POOL_STATS' is disabled.
2016-10-27  7:43:00 140215602993024 [Note] Plugin 'INNODB_METRICS' is disabled.
2016-10-27  7:43:00 140215602993024 [Note] Plugin 'INNODB_SYS_FOREIGN' is disabled.
2016-10-27  7:43:00 140215602993024 [Note] Plugin 'INNODB_CMPMEM' is disabled.
2016-10-27  7:43:00 140215602993024 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
2016-10-27  7:43:00 140215602993024 [Note] Plugin 'INNODB_SYS_COLUMNS' is disabled.
2016-10-27  7:43:00 140215602993024 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
2016-10-27  7:43:00 140215602993024 [Note] Plugin 'INNODB_SYS_INDEXES' is disabled.
2016-10-27  7:43:00 140215602993024 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
2016-10-27  7:43:00 140215602993024 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
2016-10-27  7:43:00 140215602993024 [Note] Plugin 'INNODB_SYS_VIRTUAL' is disabled.
2016-10-27  7:43:00 140215602993024 [Note] Plugin 'INNODB_BUFFER_PAGE' is disabled.
2016-10-27  7:43:00 140215602993024 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.
2016-10-27  7:43:00 140215602993024 [Warning] /usr/sbin/mysqld: unknown variable 'loose-feedback-debug-startup-interval=20'
2016-10-27  7:43:00 140215602993024 [Warning] /usr/sbin/mysqld: unknown variable 'loose-feedback-debug-first-interval=60'
2016-10-27  7:43:00 140215602993024 [Warning] /usr/sbin/mysqld: unknown variable 'loose-feedback-debug-interval=60'
2016-10-27  7:43:00 140215602993024 [Warning] /usr/sbin/mysqld: unknown option '--loose-pam-debug'
2016-10-27  7:43:00 140215602993024 [Warning] /usr/sbin/mysqld: unknown variable 'loose-debug-sync-timeout=300'
2016-10-27  7:43:00 140215602993024 [Note] Server socket created on IP: '127.0.0.1'.
2016-10-27  7:43:00 140215602993024 [Note] /usr/sbin/mysqld: ready for connections.
Version: '10.2.3-MariaDB-1~precise-log'  socket: '/run/shm/var/tmp/4/mysqld.1.sock'  port: 16020  mariadb.org binary distribution
2016-10-27  7:43:00 140215564063488 [Note] unregister_replicator OK
2016-10-27  7:43:00 140215564063488 [Note] Semi-sync replication initialized for transactions.
2016-10-27  7:43:00 140215564063488 [Note] Semi-sync replication enabled on the master.
2016-10-27  7:43:00 140215564366592 [Note] Stop asynchronous binlog_dump to slave (server_id: 2)
2016-10-27  7:43:00 140215563457280 [Note] Start semi-sync binlog_dump to slave (server_id: 2), pos(master-bin.000001, 1457)
2016-10-27  7:43:00 140215563457280 [ERROR] Read semi-sync reply network error:  (errno: 1158)
2016-10-27  7:43:00 140215563457280 [Note] Stop semi-sync binlog_dump to slave (server_id: 2)
2016-10-27  7:43:10 140215564063488 [Warning] Timeout waiting for reply of binlog (file: master-bin.000001, pos: 2077), semi-sync up to file master-bin.000001, position 1945.
2016-10-27  7:43:10 140215564063488 [Note] Semi-sync replication switched OFF.
2016-10-27  7:43:10 140215563457280 [Note] unregister_replicator OK
161027  7:43:10 [ERROR] mysqld got signal 11 ;
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.2.3-MariaDB-1~precise-log
key_buffer_size=1048576
read_buffer_size=131072
max_used_connections=7
max_threads=153
thread_count=9
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 62973 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
 
Thread pointer: 0x0x7f8670c12008
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 = 0x7f867ae349e0 thread_stack 0x48c00
/usr/sbin/mysqld(my_print_stacktrace+0x2b)[0x7f867df4fedb]
/usr/sbin/mysqld(handle_fatal_signal+0x485)[0x7f867d9d6315]
/lib/x86_64-linux-gnu/libpthread.so.0(+0xfcb0)[0x7f867cf35cb0]
/usr/sbin/mysqld(+0xc1ce15)[0x7f867df84e15]
/usr/sbin/mysqld(my_copy_fix_mb+0x57)[0x7f867df6fc97]
/usr/sbin/mysqld(_ZN13String_copier16well_formed_copyEPK15charset_info_stPcjS2_PKcjj+0x7f)[0x7f867d8cfcff]
/usr/sbin/mysqld(_ZN15Field_varstring5storeEPKcjPK15charset_info_st+0x5d)[0x7f867d9cb01d]
/usr/sbin/mysqld(+0x552e2e)[0x7f867d8bae2e]
/usr/sbin/mysqld(_Z24plugin_foreach_with_maskP3THDPFcS0_P13st_plugin_intPvEijS3_+0x180)[0x7f867d86d3d0]
/usr/sbin/mysqld(_Z12fill_pluginsP3THDP10TABLE_LISTP4Item+0x21)[0x7f867d8b1da1]
/usr/sbin/mysqld(_Z24get_schema_tables_resultP4JOIN23enum_schema_table_state+0x256)[0x7f867d8c3276]
/usr/sbin/mysqld(_ZN4JOIN10exec_innerEv+0x75d)[0x7f867d8ad9bd]
/usr/sbin/mysqld(_ZN4JOIN4execEv+0x3c)[0x7f867d8addec]
/usr/sbin/mysqld(_Z12mysql_selectP3THDP10TABLE_LISTjR4ListI4ItemEPS4_jP8st_orderS9_S7_S9_yP13select_resultP18st_select_lex_unitP13st_select_lex+0x12a)[0x7f867d8acd9a]
/usr/sbin/mysqld(_Z13handle_selectP3THDP3LEXP13select_resultm+0x1d4)[0x7f867d8ae004]
/usr/sbin/mysqld(+0x4eecc6)[0x7f867d856cc6]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x5163)[0x7f867d860cc3]
/usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_statebb+0x2b2)[0x7f867d864372]
/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcjbb+0x1c45)[0x7f867d866635]
/usr/sbin/mysqld(_Z10do_commandP3THD+0x180)[0x7f867d866c40]
/usr/sbin/mysqld(_Z24do_handle_one_connectionP7CONNECT+0x16f)[0x7f867d91f0cf]
/usr/sbin/mysqld(handle_one_connection+0x44)[0x7f867d91f204]
/usr/sbin/mysqld(+0xad7f9d)[0x7f867de3ff9d]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x7e9a)[0x7f867cf2de9a]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7f867b18936d]
 
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0x7f8670c40020): select count(*) = 0 from information_schema.plugins where plugin_name like 'rpl_%'
Connection ID (thread ID): 8
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,orderby_uses_equalities=on,condition_pushdown_for_derived=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
----------SERVER LOG END-------------

Comment by Lixun Peng [ 2017-01-17 ]

I don't want to fix this fails.
I will port the patch "link semisync plugin statically" into MariaDB.
So we needn't to fix this fail.

Comment by Sergey Vojtovich [ 2017-10-12 ]

serg, please review fix for this bug. I committed it to 5.5 as:

96e982b: MDEV-7140 - Sporadic buildbot failures in rpl.rpl_semi_sync_uninstall_plugin

But now I feel like MDEV-7140 may have more reasons to failures, while my fix only addresses problem described in this bug.

Comment by Sergey Vojtovich [ 2017-10-12 ]

Re-committed

06bb7ee: MDEV-10892 - rpl.rpl_semi_sync_uninstall_plugin fails with Assertion `0' failure

I believe we should exclude PLUGIN_IS_DYING from I_S.PLUGINS, since it is not protected by ref counter.

Comment by Sergey Vojtovich [ 2017-10-13 ]

Rev. 8be76a6a907ab858b4fdb5d525548aedfdb4ddf3

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