[MDEV-13677] rpl.rpl_domain_id_filter_io_crash failed in buildbot, server crash Created: 2017-08-30  Updated: 2023-11-29  Resolved: 2023-11-29

Status: Closed
Project: MariaDB Server
Component/s: Tests
Affects Version/s: 10.2
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Alice Sherepa Assignee: Andrei Elkin
Resolution: Won't Fix Votes: 0
Labels: None

Issue Links:
Relates
relates to MDEV-12729 rpl.rpl_domain_id_filter_io_crash fai... Closed

 Description   

http://buildbot.askmonty.org/buildbot/builders/kvm-fulltest2/builds/9405/steps/test_3/logs/stdioj

rpl.rpl_domain_id_filter_io_crash 'innodb,row' w2 [ fail ]
 
        Test ended at 2017-08-30 02:06:40
 
 
 
CURRENT_TEST: rpl.rpl_domain_id_filter_io_crash
 
mysqltest: In included file "./include/wait_for_slave_param.inc": 
included from ./include/wait_for_slave_sql_to_start.inc at line 32:
 
included from ./include/wait_for_slave_to_start.inc at line 27:
 
included from ./include/start_slave.inc at line 35:
 
included from /mnt/buildbot/build/mariadb-10.2.9/mysql-test/suite/rpl/t/rpl_domain_id_filter_io_crash.test at line 296:
 
At line 75: query 'let $_slave_check_configured= query_get_value("SHOW SLAVE STATUS", Slave_IO_Running, 1)' failed: 2013: Lost connection to MySQL server during query
 
 
 
The result from queries just before the failure was:
 
< snip >
 
23
 
connection slave;
 
include/wait_for_slave_io_error.inc [errno=1595]
 
SELECT * FROM t1;
 
i
 
1
 
2
 
3
 
10
 
11
 
14
 
15
 
16
 
17
 
SET @@global.debug_dbug="-d";
 
include/stop_slave.inc
 
DO_DOMAIN_IDS (BEFORE)     : 
IGNORE_DOMAIN_IDS (BEFORE) : 1
 
CHANGE MASTER TO IGNORE_DOMAIN_IDS=(), MASTER_USE_GTID=slave_pos;
 
include/start_slave.inc
 
 
 
More results from queries before failure can be found in /mnt/buildbot/build/mariadb-10.2.9/mysql-test/var/2/log/rpl_domain_id_filter_io_crash.log
 
 
 
 
 
Server [mysqld.2 - pid: 5721, winpid: 5721, exit: 256] failed during test run
 
Server log from this test:
 
----------SERVER LOG START-----------
 
2017-08-30  2:06:37 2843691840 [Note] Deleted Master_info file '/run/shm/var_auto_i2r9/2/mysqld.2/data/master.info'.
 
2017-08-30  2:06:37 2843691840 [Note] Deleted Master_info file '/run/shm/var_auto_i2r9/2/mysqld.2/data/relay-log.info'.
 
2017-08-30  2:06:37 2843691840 [Note] Master connection name: ''  Master_info_file: 'master.info'  Relay_info_file: 'relay-log.info'
 
2017-08-30  2:06:37 2843691840 [Note] 'CHANGE MASTER TO executed'. Previous state master_host='127.0.0.1', master_port='16020', master_log_file='', master_log_pos='4'. New state master_host='127.0.0.1', master_port='16020', master_log_file='master-bin.000001', master_log_pos='4'.
 
2017-08-30  2:06:37 2843388736 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000001' at position 4, relay log './slave-relay-bin.000001' position: 4
 
2017-08-30  2:06:37 2843085632 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:16020',replication started in log 'master-bin.000001' at position 4
 
2017-08-30  2:06:37 2843388736 [Note] Error reading relay log event: slave SQL thread was killed
 
2017-08-30  2:06:37 2843388736 [Note] Slave SQL thread exiting, replication stopped in log 'master-bin.000001' at position 677
 
2017-08-30  2:06:37 2843085632 [Note] Slave I/O thread exiting, read up to log 'master-bin.000001', position 677
 
2017-08-30  2:06:37 2897668928 [Note] Master connection name: ''  Master_info_file: 'master.info'  Relay_info_file: 'relay-log.info'
 
2017-08-30  2:06:37 2897668928 [Note] 'CHANGE MASTER TO executed'. Previous state master_host='127.0.0.1', master_port='16020', master_log_file='master-bin.000001', master_log_pos='677'. New state master_host='127.0.0.1', master_port='16020', master_log_file='master-bin.000001', master_log_pos='677'.
 
2017-08-30  2:06:37 2897668928 [Note] Previous Using_Gtid=No. New Using_Gtid=Slave_Pos
 
2017-08-30  2:06:37 2843085632 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:16020',replication starts at GTID position '1-1-2'
 
2017-08-30  2:06:37 2843388736 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000001' at position 677, relay log './slave-relay-bin.000001' position: 4; GTID position '1-1-2'
 
2017-08-30  2:06:37 2843085632 [ERROR] Slave I/O: Relay log write failure: could not queue event from master, Internal MariaDB error code: 1595
 
2017-08-30  2:06:37 2843085632 [Note] Slave I/O thread exiting, read up to log 'master-bin.000001', position 979; GTID position 1-1-2
 
2017-08-30  2:06:37 2843085632 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:16020',replication starts at GTID position '1-1-2'
 
2017-08-30  2:06:37 2843388736 [Note] Error reading relay log event: slave SQL thread was killed
 
2017-08-30  2:06:37 2843388736 [Note] Slave SQL thread exiting, replication stopped in log 'master-bin.000001' at position 1010; GTID position '1-1-3'
 
2017-08-30  2:06:37 2843085632 [Note] Slave I/O thread exiting, read up to log 'master-bin.000001', position 1010; GTID position 1-1-3
 
2017-08-30  2:06:37 2897668928 [Note] Master connection name: ''  Master_info_file: 'master.info'  Relay_info_file: 'relay-log.info'
 
2017-08-30  2:06:37 2897668928 [Note] 'CHANGE MASTER TO executed'. Previous state master_host='127.0.0.1', master_port='16020', master_log_file='master-bin.000001', master_log_pos='1010'. New state master_host='127.0.0.1', master_port='16020', master_log_file='master-bin.000001', master_log_pos='1010'.
 
2017-08-30  2:06:37 2897668928 [Note] Previous Using_Gtid=Slave_Pos. New Using_Gtid=Slave_Pos
 
2017-08-30  2:06:37 2843085632 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:16020',replication starts at GTID position '1-1-3'
 
2017-08-30  2:06:37 2843388736 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000001' at position 1010, relay log './slave-relay-bin.000001' position: 4; GTID position '1-1-3'
 
2017-08-30  2:06:37 2843085632 [ERROR] Slave I/O: Relay log write failure: could not queue event from master, Internal MariaDB error code: 1595
 
2017-08-30  2:06:37 2843085632 [Note] Slave I/O thread exiting, read up to log 'master-bin.000001', position 1312; GTID position 1-1-3
 
2017-08-30  2:06:37 2843085632 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:16020',replication starts at GTID position '1-1-3'
 
2017-08-30  2:06:37 2843388736 [Note] Error reading relay log event: slave SQL thread was killed
 
2017-08-30  2:06:37 2843388736 [Note] Slave SQL thread exiting, replication stopped in log 'master-bin.000001' at position 1343; GTID position '1-1-4'
 
2017-08-30  2:06:37 2843085632 [Note] Slave I/O thread exiting, read up to log 'master-bin.000001', position 1343; GTID position 1-1-4
 
2017-08-30  2:06:38 2897668928 [Note] Master connection name: ''  Master_info_file: 'master.info'  Relay_info_file: 'relay-log.info'
 
2017-08-30  2:06:38 2897668928 [Note] 'CHANGE MASTER TO executed'. Previous state master_host='127.0.0.1', master_port='16020', master_log_file='master-bin.000001', master_log_pos='1343'. New state master_host='127.0.0.1', master_port='16020', master_log_file='master-bin.000001', master_log_pos='1343'.
 
2017-08-30  2:06:38 2897668928 [Note] Previous Using_Gtid=Slave_Pos. New Using_Gtid=Slave_Pos
 
2017-08-30  2:06:38 2843085632 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:16020',replication starts at GTID position '1-1-4'
 
2017-08-30  2:06:38 2843388736 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000001' at position 1343, relay log './slave-relay-bin.000001' position: 4; GTID position '1-1-4'
 
2017-08-30  2:06:38 2843085632 [ERROR] Slave I/O: Relay log write failure: could not queue event from master, Internal MariaDB error code: 1595
 
2017-08-30  2:06:38 2843085632 [Note] Slave I/O thread exiting, read up to log 'master-bin.000001', position 1645; GTID position 1-1-4
 
2017-08-30  2:06:38 2843388736 [Note] Error reading relay log event: slave SQL thread was killed
 
2017-08-30  2:06:38 2843388736 [Note] Slave SQL thread exiting, replication stopped in log 'master-bin.000001' at position 1343; GTID position '1-1-4'
 
2017-08-30  2:06:38 2897668928 [Note] Master connection name: ''  Master_info_file: 'master.info'  Relay_info_file: 'relay-log.info'
 
2017-08-30  2:06:38 2897668928 [Note] 'CHANGE MASTER TO executed'. Previous state master_host='127.0.0.1', master_port='16020', master_log_file='master-bin.000001', master_log_pos='1645'. New state master_host='127.0.0.1', master_port='16020', master_log_file='master-bin.000001', master_log_pos='1343'.
 
2017-08-30  2:06:38 2897668928 [Note] Previous Using_Gtid=Slave_Pos. New Using_Gtid=Slave_Pos
 
2017-08-30  2:06:38 2843388736 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:16020',replication starts at GTID position '1-1-4'
 
2017-08-30  2:06:38 2843085632 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000001' at position 1343, relay log './slave-relay-bin.000001' position: 4; GTID position '1-1-4'
 
2017-08-30  2:06:38 2843085632 [Note] Error reading relay log event: slave SQL thread was killed
 
2017-08-30  2:06:38 2843085632 [Note] Slave SQL thread exiting, replication stopped in log 'master-bin.000001' at position 2344; GTID position '1-1-6,2-1-1'
 
2017-08-30  2:06:38 2843388736 [Note] Slave I/O thread exiting, read up to log 'master-bin.000001', position 2344; GTID position 1-1-6,2-1-1
 
2017-08-30  2:06:38 2897668928 [Note] Master connection name: ''  Master_info_file: 'master.info'  Relay_info_file: 'relay-log.info'
 
2017-08-30  2:06:38 2897668928 [Note] 'CHANGE MASTER TO executed'. Previous state master_host='127.0.0.1', master_port='16020', master_log_file='master-bin.000001', master_log_pos='2344'. New state master_host='127.0.0.1', master_port='16020', master_log_file='master-bin.000001', master_log_pos='2344'.
 
2017-08-30  2:06:38 2897668928 [Note] Previous Using_Gtid=Slave_Pos. New Using_Gtid=Slave_Pos
 
2017-08-30  2:06:38 2843388736 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:16020',replication starts at GTID position '1-1-6,2-1-1'
 
2017-08-30  2:06:38 2843085632 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000001' at position 2344, relay log './slave-relay-bin.000001' position: 4; GTID position '1-1-6,2-1-1'
 
2017-08-30  2:06:38 2843388736 [ERROR] Slave I/O: Relay log write failure: could not queue event from master, Internal MariaDB error code: 1595
 
2017-08-30  2:06:38 2843388736 [Note] Slave I/O thread exiting, read up to log 'master-bin.000001', position 2648; GTID position 1-1-6,2-1-1
 
2017-08-30  2:06:38 2843085632 [Note] Error reading relay log event: slave SQL thread was killed
 
2017-08-30  2:06:38 2843085632 [Note] Slave SQL thread exiting, replication stopped in log 'master-bin.000001' at position 2648; GTID position '1-1-7,2-1-1'
 
2017-08-30  2:06:38 2897668928 [Note] Master connection name: ''  Master_info_file: 'master.info'  Relay_info_file: 'relay-log.info'
 
2017-08-30  2:06:38 2897668928 [Note] 'CHANGE MASTER TO executed'. Previous state master_host='127.0.0.1', master_port='16020', master_log_file='master-bin.000001', master_log_pos='2648'. New state master_host='127.0.0.1', master_port='16020', master_log_file='master-bin.000001', master_log_pos='2648'.
 
2017-08-30  2:06:38 2897668928 [Note] Previous Using_Gtid=Slave_Pos. New Using_Gtid=Slave_Pos
 
2017-08-30  2:06:38 2843085632 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:16020',replication starts at GTID position '1-1-7,2-1-1'
 
2017-08-30  2:06:38 2843388736 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000001' at position 2648, relay log './slave-relay-bin.000001' position: 4; GTID position '1-1-7,2-1-1'
 
2017-08-30  2:06:38 2843388736 [Note] Error reading relay log event: slave SQL thread was killed
 
2017-08-30  2:06:38 2843388736 [Note] Slave SQL thread exiting, replication stopped in log 'master-bin.000001' at position 3349; GTID position '1-1-8,2-1-2'
 
2017-08-30  2:06:38 2843085632 [Note] Slave I/O thread exiting, read up to log 'master-bin.000001', position 3349; GTID position 1-1-8,2-1-2
 
2017-08-30  2:06:38 2897668928 [Note] Master connection name: ''  Master_info_file: 'master.info'  Relay_info_file: 'relay-log.info'
 
2017-08-30  2:06:38 2897668928 [Note] 'CHANGE MASTER TO executed'. Previous state master_host='127.0.0.1', master_port='16020', master_log_file='master-bin.000001', master_log_pos='3349'. New state master_host='127.0.0.1', master_port='16020', master_log_file='master-bin.000001', master_log_pos='3349'.
 
2017-08-30  2:06:38 2897668928 [Note] Previous Using_Gtid=Slave_Pos. New Using_Gtid=Slave_Pos
 
2017-08-30  2:06:38 2843085632 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000001' at position 3349, relay log './slave-relay-bin.000001' position: 4; GTID position '1-1-8,2-1-2'
 
2017-08-30  2:06:38 2843388736 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:16020',replication starts at GTID position '1-1-8,2-1-2'
 
2017-08-30  2:06:38 2843388736 [ERROR] Slave I/O: Relay log write failure: could not queue event from master, Internal MariaDB error code: 1595
 
2017-08-30  2:06:38 2843388736 [Note] Slave I/O thread exiting, read up to log 'master-bin.000001', position 3570; GTID position 1-1-8,2-1-2
 
170830  2:06:38 [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.9-MariaDB-debug-log
 
key_buffer_size=1048576
 
read_buffer_size=131072
 
max_used_connections=4
 
max_threads=153
 
thread_count=12
 
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 61882 K  bytes of memory
 
Hope that's ok; if not, decrease some variables in the equation.
 
 
 
Thread pointer: 0xa8c00810
 
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 = 0xa81ff28c thread_stack 0x49000
 
2017-08-30  2:06:38 2843085632 [Note] Error reading relay log event: slave SQL thread was killed
 
2017-08-30  2:06:38 2843085632 [Note] Slave SQL thread exiting, replication stopped in log 'master-bin.000001' at position 3570; GTID position '1-1-9,2-1-2'
 
/mnt/buildbot/build/mariadb-10.2.9/sql/mysqld(my_print_stacktrace+0x32)[0x8cf4706]
 
/mnt/buildbot/build/mariadb-10.2.9/sql/mysqld(handle_fatal_signal+0x3c7)[0x85a2463]
 
[0xb77ae400]
 
/lib/i386-linux-gnu/libc.so.6(+0xbd4a5)[0xb73194a5]
 
/lib/i386-linux-gnu/libc.so.6(fnmatch+0x69)[0xb731aaf9]
 
/mnt/buildbot/build/mariadb-10.2.9/sql/mysqld[0x8d1686a]
 
/mnt/buildbot/build/mariadb-10.2.9/sql/mysqld(_db_keyword_+0x79)[0x8d16d42]
 
/mnt/buildbot/build/mariadb-10.2.9/sql/mysqld(_db_pargs_+0x65)[0x8d16158]
 
/mnt/buildbot/build/mariadb-10.2.9/sql/mysqld[0x8999bf2]
 
2017-08-30  2:06:38 2897668928 [Note] Master connection name: ''  Master_info_file: 'master.info'  Relay_info_file: 'relay-log.info'
 
2017-08-30  2:06:38 2897668928 [Note] 'CHANGE MASTER TO executed'. Previous state master_host='127.0.0.1', master_port='16020', master_log_file='master-bin.000001', master_log_pos='3570'. New state master_host='127.0.0.1', master_port='16020', master_log_file='master-bin.000001', master_log_pos='3570'.
 
2017-08-30  2:06:38 2897668928 [Note] Previous Using_Gtid=Slave_Pos. New Using_Gtid=Slave_Pos
 
/mnt/buildbot/build/mariadb-10.2.9/sql/mysqld[0x899a074]
 
2017-08-30  2:06:38 2843085632 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:16020',replication starts at GTID position '1-1-9,2-1-2'
 
/mnt/buildbot/build/mariadb-10.2.9/sql/mysqld[0x899a24a]
 
/mnt/buildbot/build/mariadb-10.2.9/sql/mysqld[0x8a58737]
 
2017-08-30  2:06:38 2843388736 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000001' at position 3570, relay log './slave-relay-bin.000001' position: 4; GTID position '1-1-9,2-1-2'
 
/mnt/buildbot/build/mariadb-10.2.9/sql/mysqld[0x8a588b8]
 
/lib/i386-linux-gnu/libpthread.so.0(+0x6d4c)[0xb7536d4c]
 
/lib/i386-linux-gnu/libc.so.6(clone+0x5e)[0xb7346ace]
 
 
 
Trying to get some variables.
 
Some pointers may be invalid and cause the dump to abort.
 
Query (0x0): 
Connection ID (thread ID): 4
 
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-------------



 Comments   
Comment by Elena Stepanova [ 2017-09-06 ]

Got a decent stack trace on a local machine, presumably the same crash (at least the same line in the test):

10.3 016c35a7f2f4a2

 
#3  <signal handler called>
 
#4  0x00007f4eb7256574 in internal_fnmatch () from /lib/x86_64-linux-gnu/libc.so.6
 
#5  0x00007f4eb7257a71 in fnmatch () from /lib/x86_64-linux-gnu/libc.so.6
 
#6  0x0000558f73e7f421 in InList (linkp=0x8f8f8f8f8f8f8f8f, cp=0x558f7421c430 "enter", exact_match=0) at /data/src/10.3/dbug/dbug.c:1515
 
#7  0x0000558f73e7f8cb in _db_keyword_ (cs=0x7f4e7c000a30, keyword=0x558f7421c430 "enter", strict=0) at /data/src/10.3/dbug/dbug.c:1717
 
#8  0x0000558f73e7ec25 in _db_pargs_ (_line_=375, keyword=0x558f7421c430 "enter") at /data/src/10.3/dbug/dbug.c:1236
 
#9  0x0000558f73e46f65 in free_root (root=0x7f4e7c005cb8, MyFlags=1) at /data/src/10.3/mysys/my_alloc.c:375
 
#10 0x0000558f7337b3b3 in reset_thd (thd=0x7f4e7c000b00) at /data/src/10.3/sql/sql_class.cc:4640
 
#11 0x0000558f739a4f4c in innobase_reset_background_thd (thd=0x7f4e7c000b00) at /data/src/10.3/storage/innobase/handler/ha_innodb.cc:1674
 
#12 0x0000558f73b33c5d in row_purge_step (thr=0x558f76237e80) at /data/src/10.3/storage/innobase/row/row0purge.cc:1183
 
#13 0x0000558f73ab3aea in que_thr_step (thr=0x558f76237e80) at /data/src/10.3/storage/innobase/que/que0que.cc:1054
 
#14 0x0000558f73ab3d15 in que_run_threads_low (thr=0x558f76237e80) at /data/src/10.3/storage/innobase/que/que0que.cc:1116
 
#15 0x0000558f73ab3ef7 in que_run_threads (thr=0x558f76237e80) at /data/src/10.3/storage/innobase/que/que0que.cc:1156
 
#16 0x0000558f73b8835b in srv_task_execute () at /data/src/10.3/storage/innobase/srv/srv0srv.cc:2576
 
#17 0x0000558f73b884ac in srv_worker_thread (arg=0x0) at /data/src/10.3/storage/innobase/srv/srv0srv.cc:2623
 
#18 0x00007f4eb9107494 in start_thread (arg=0x7f4e9cff9700) at pthread_create.c:333
 
#19 0x00007f4eb727f93f in clone () from /lib/x86_64-linux-gnu/libc.so.6

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