CTAS processing can assert with debug build

[Seppo Jaakola]

CREATE TABLE AS SELECT... processing can hit an assert with debug build. The problem happens, if CTAS processing resulted in certification failure during insert...select cycle, and client was OK status was already sent for client before the cert failure was about to be communicated back to client.

Here's the error log:

130330 18:05:05 [Note] WSREP: commit failed for reason: 3
130330 18:05:05 [Note] WSREP: conflict state: 0
130330 18:05:05 [Note] WSREP: cluster conflict due to certification failure for threads:
130330 18:05:05 [Note] WSREP: Victim thread:
   THD: 14, mode: local, state: executing, conflict: cert failure, seqno: 124699
   SQL: CREATE TABLE x SELECT * FROM `comm00`
mysqld: /home/seppo/work/wsrep/wsrep-5.5-23-new/wsrep-5.5-23/sql/sql_error.cc:422: void Diagnostics_area::set_error_status(THD*, uint, const char*, const char*): Assertion `! is_set() || can_overwrite_status' failed.
16:05:05 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.

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

Thread pointer: 0x7feabda5eb60
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 = 7feac0c09e68 thread_stack 0x40000
/home/seppo/work/testing/node1-5.5/mysql/sbin/mysqld(my_print_stacktrace+0x35)[0x8fb4af]
/home/seppo/work/testing/node1-5.5/mysql/sbin/mysqld(handle_fatal_signal+0x406)[0x7818c6]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x10060)[0x7feb1066e060]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x35)[0x7feb102f13e5]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x17b)[0x7feb102f4b4b]
/lib/x86_64-linux-gnu/libc.so.6(__assert_fail+0xdd)[0x7feb102e9d8d]
/home/seppo/work/testing/node1-5.5/mysql/sbin/mysqld(_ZN16Diagnostics_area16set_error_statusEP3THDjPKcS3_+0x78)[0x5e0250]
/home/seppo/work/testing/node1-5.5/mysql/sbin/mysqld(_ZN3THD15raise_conditionEjPKcN11MYSQL_ERROR18enum_warning_levelES1_+0x2c7)[0x5cb6b7]
/home/seppo/work/testing/node1-5.5/mysql/sbin/mysqld(my_message_sql+0x129)[0x55be82]
/home/seppo/work/testing/node1-5.5/mysql/sbin/mysqld(my_error+0x22b)[0x8efa77]
/home/seppo/work/testing/node1-5.5/mysql/sbin/mysqld(_Z15ha_commit_transP3THDb+0x4b7)[0x783ec0]
/home/seppo/work/testing/node1-5.5/mysql/sbin/mysqld(_Z17trans_commit_stmtP3THD+0x91)[0x6fa568]
/home/seppo/work/testing/node1-5.5/mysql/sbin/mysqld(_ZN13select_create8send_eofEv+0x62)[0x5eedf2]
/home/seppo/work/testing/node1-5.5/mysql/sbin/mysqld[0x64e588]
/home/seppo/work/testing/node1-5.5/mysql/sbin/mysqld(_ZN4JOIN4execEv+0x2471)[0x637531]
/home/seppo/work/testing/node1-5.5/mysql/sbin/mysqld(_Z12mysql_selectP3THDPPP4ItemP10TABLE_LISTjR4ListIS1_ES2_jP8st_orderSB_S2_SB_yP13select_resultP18st_select_lex_unitP13st_select_lex+0x369)[0x637d47]
/home/seppo/work/testing/node1-5.5/mysql/sbin/mysqld(_Z13handle_selectP3THDP3LEXP13select_resultm+0x199)[0x62fca6]
/home/seppo/work/testing/node1-5.5/mysql/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x1ae3)[0x6007f3]
/home/seppo/work/testing/node1-5.5/mysql/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x210)[0x60ae51]
/home/seppo/work/testing/node1-5.5/mysql/sbin/mysqld[0x60a690]
/home/seppo/work/testing/node1-5.5/mysql/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0xced)[0x5fcb84]
/home/seppo/work/testing/node1-5.5/mysql/sbin/mysqld(_Z10do_commandP3THD+0x643)[0x5fba45]
/home/seppo/work/testing/node1-5.5/mysql/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x1a1)[0x6e85d6]
/home/seppo/work/testing/node1-5.5/mysql/sbin/mysqld(handle_one_connection+0x33)[0x6e7ff7]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x7efc)[0x7feb10665efc]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7feb1039ff8d]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (65f87f0): CREATE TABLE x SELECT * FROM `comm00`
Connection ID (thread ID): 14
Status: NOT_KILLED

Here's stack trace of the asserting thread:

(gdb) bt
#0 __pthread_kill (threadid=<optimized out>, signo=6) at ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c:63
#1 0x00000000008fb531 in my_write_core (sig=6) at /home/seppo/work/wsrep/wsrep-5.5-23-new/wsrep-5.5-23/mysys/stacktrace.c:433
#2 0x0000000000781ade in handle_fatal_signal (sig=6) at /home/seppo/work/wsrep/wsrep-5.5-23-new/wsrep-5.5-23/sql/signal_handler.cc:247
#3 <signal handler called>
#4 0x00007feb102f13e5 in __GI_raise (sig=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:64
#5 0x00007feb102f4b4b in __GI_abort () at abort.c:92
#6 0x00007feb102e9d8d in __GI___assert_fail (assertion=0xb38fd8 "! is_set() || can_overwrite_status", file=<optimized out>, line=422, function=<optimized out>) at assert.c:81
#7 0x00000000005e0250 in Diagnostics_area::set_error_status (this=0x7feabda61d70, thd=0x7feabda5eb60, sql_errno_arg=1213, message_arg=0x7feac0c06f30 "Deadlock found when trying to get lock; try restarting transaction", sqlstate=0xb4bd28 "40001") at /home/seppo/work/wsrep/wsrep-5.5-23-new/wsrep-5.5-23/sql/sql_error.cc:422
#8 0x00000000005cb6b7 in THD::raise_condition (this=0x7feabda5eb60, sql_errno=1213, sqlstate=0xb4bd28 "40001", level=MYSQL_ERROR::WARN_LEVEL_ERROR, msg=0x7feac0c06f30 "Deadlock found when trying to get lock; try restarting transaction") at /home/seppo/work/wsrep/wsrep-5.5-23-new/wsrep-5.5-23/sql/sql_class.cc:1335
#9 0x000000000055be82 in my_message_sql (error=1213, str=0x7feac0c06f30 "Deadlock found when trying to get lock; try restarting transaction", MyFlags=0) at /home/seppo/work/wsrep/wsrep-5.5-23-new/wsrep-5.5-23/sql/mysqld.cc:2930
#10 0x00000000008efa77 in my_error (nr=1213, MyFlags=0) at /home/seppo/work/wsrep/wsrep-5.5-23-new/wsrep-5.5-23/mysys/my_error.c:96
#11 0x0000000000783ec0 in ha_commit_trans (thd=0x7feabda5eb60, all=false) at /home/seppo/work/wsrep/wsrep-5.5-23-new/wsrep-5.5-23/sql/handler.cc:1326
#12 0x00000000006fa568 in trans_commit_stmt (thd=0x7feabda5eb60) at /home/seppo/work/wsrep/wsrep-5.5-23-new/wsrep-5.5-23/sql/transaction.cc:325
#13 0x00000000005eedf2 in select_create::send_eof (this=0x65f9660) at /home/seppo/work/wsrep/wsrep-5.5-23-new/wsrep-5.5-23/sql/sql_insert.cc:4061
#14 0x000000000064e588 in do_select (join=0x6a4f6e0, fields=0x7feabda61330, table=0x0, procedure=0x0) at /home/seppo/work/wsrep/wsrep-5.5-23-new/wsrep-5.5-23/sql/sql_select.cc:11575
#15 0x0000000000637531 in JOIN::exec (this=0x6a4f6e0) at /home/seppo/work/wsrep/wsrep-5.5-23-new/wsrep-5.5-23/sql/sql_select.cc:2385
#16 0x0000000000637d47 in mysql_select (thd=0x7feabda5eb60, rref_pointer_array=0x7feabda613f8, tables=0x65f8f68, wild_num=1, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2416184064, result=0x65f9660, unit=0x7feabda60c00, select_lex=0x7feabda61220) at /home/seppo/work/wsrep/wsrep-5.5-23-new/wsrep-5.5-23/sql/sql_select.cc:2604
#17 0x000000000062fca6 in handle_select (thd=0x7feabda5eb60, lex=0x7feabda60b50, result=0x65f9660, setup_tables_done_option=0) at /home/seppo/work/wsrep/wsrep-5.5-23-new/wsrep-5.5-23/sql/sql_select.cc:297
#18 0x00000000006007f3 in mysql_execute_command (thd=0x7feabda5eb60) at /home/seppo/work/wsrep/wsrep-5.5-23-new/wsrep-5.5-23/sql/sql_parse.cc:2830
#19 0x000000000060ae51 in mysql_parse (thd=0x7feabda5eb60, rawbuf=0x65f87f0 "CREATE TABLE x SELECT * FROM `comm00`", length=38, parser_state=0x7feac0c091c0) at /home/seppo/work/wsrep/wsrep-5.5-23-new/wsrep-5.5-23/sql/sql_parse.cc:6203
#20 0x000000000060a690 in wsrep_mysql_parse (thd=0x7feabda5eb60, rawbuf=0x65f87f0 "CREATE TABLE x SELECT * FROM `comm00`", length=38, parser_state=0x7feac0c091c0) at /home/seppo/work/wsrep/wsrep-5.5-23-new/wsrep-5.5-23/sql/sql_parse.cc:6036
#21 0x00000000005fcb84 in dispatch_command (command=COM_QUERY, thd=0x7feabda5eb60, packet=0x7feabdb43a91 " CREATE TABLE x SELECT * FROM `comm00`", packet_length=39) at /home/seppo/work/wsrep/wsrep-5.5-23-new/wsrep-5.5-23/sql/sql_parse.cc:1212
#22 0x00000000005fba45 in do_command (thd=0x7feabda5eb60) at /home/seppo/work/wsrep/wsrep-5.5-23-new/wsrep-5.5-23/sql/sql_parse.cc:869
#23 0x00000000006e85d6 in do_handle_one_connection (thd_arg=0x7feabda5eb60) at /home/seppo/work/wsrep/wsrep-5.5-23-new/wsrep-5.5-23/sql/sql_connect.cc:878
#24 0x00000000006e7ff7 in handle_one_connection (arg=0x7feabda5eb60) at /home/seppo/work/wsrep/wsrep-5.5-23-new/wsrep-5.5-23/sql/sql_connect.cc:790
#25 0x00007feb10665efc in start_thread (arg=0x7feac0c0a700) at pthread_create.c:304
#26 0x00007feb1039ff8d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#27 0x0000000000000000 in ?? ()

How to reproduce:

This can happen with only one node, running RQG with percona_qa grammar. Here's the command line I used in the test:

perl runall.pl --queries=100000000 --seed=1101 --duration=300 --querytimeout=60 --short_column_names --sqltrace --reporter=Shutdown,Backtrace,QueryTimeout,ErrorLog,ErrorLogAlarm --grammar=conf/percona_qa/percona_qa.yy --gendata=conf/percona_qa/percona_qa.zz > /tmp/percona_qa.log 2>&1

[Seppo Jaakola (seppo-jaakola)]

certification failure was not acknowledged after select..insert phase. Fix for this was pushed in revision: http://bazaar.launchpad.net/~codership/codership-mysql/5.5-23/revision/3860

[Seppo Jaakola (seppo-jaakola)]

Merged fix into wsrep-5.6 from wsrep-5.5-23 in revision: http://bazaar.launchpad.net/~codership/codership-mysql/5.6/revision/3976

[Shahriyar Rzayev (rzayev-sehriyar)]

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