Bug #46324 Crash during repeated INSERT ... SELECT if falcon debug mask includes 4
Submitted: 21 Jul 2009 15:42 Modified: 26 May 2010 17:40
Reporter: John Embretsen Email Updates:
Status: Unsupported Impact on me:
None 
Category:MySQL Server: Falcon storage engine Severity:S1 (Critical)
Version:6.0.12-bzr OS:Any
Assigned to: Kevin Lewis CPU Architecture:Any
Tags: F_CHILL THAW
Triage: Triaged: D1 (Critical)

[21 Jul 2009 15:42] John Embretsen
Description:
MySQL/Falcon crashes (segmentation fault) if the contents of a table is duplicated a number of times and Falcon is run with a debug mask (falcon_debug_mask) where the bit for value 4 set. 

According to http://dev.mysql.com/doc/refman/6.0/en/se-falcon-configuration.html#sysvar_falcon_debug_ma... value 4 is the mask for LogInfo messages.

Stack trace:

Thread 1 (process 8964):
#0  0x00007f5dfd7db1f6 in pthread_kill () from /lib/libpthread.so.0
#1  0x0000000000cb7138 in my_write_core (sig=11) at stacktrace.c:309
#2  0x00000000006f8a85 in handle_segfault (sig=11) at mysqld.cc:2711
#3  <signal handler called>
#4  0x00007f5dfc6ddc60 in strlen () from /lib/libc.so.6
#5  0x00007f5dfc6a675e in vfprintf () from /lib/libc.so.6
#6  0x00007f5dfc6ce39a in vsnprintf () from /lib/libc.so.6
#7  0x0000000000a5a06d in Log::log (mask=4, text=0xead520 "%d: Record chill: transaction %ld, %ld records, %ld bytes  %s\n",
    args=0x7f5dfdc7c520) at Log.cpp:219
#8  0x0000000000a5a191 in Log::log (mask=4, txt=0xead520 "%d: Record chill: transaction %ld, %ld records, %ld bytes  %s\n") at Log.cpp:149
#9  0x00000000009f6765 in Transaction::chillRecords (this=0x7f5dfbe2d7f8) at Transaction.cpp:553
#10 0x00000000009f68b1 in Transaction::addRecord (this=0x7f5dfbe2d7f8, record=0x308f5a8) at Transaction.cpp:628
#11 0x00000000009e88fc in Table::insert (this=0x7f5dfbe11650, transaction=0x7f5dfbe2d7f8, stream=0x7f5dfbe111d0) at Table.cpp:3076
#12 0x00000000009cc485 in StorageDatabase::insert (this=0x7f5dfba5a210, connection=0x7f5dfba9a780, table=0x7f5dfbe11650,
    stream=0x7f5dfbe111d0) at StorageDatabase.cpp:269
#13 0x00000000009d3b54 in StorageTable::insert (this=0x7f5dfbe0bc90) at StorageTable.cpp:112
#14 0x00000000009c4cb9 in StorageInterface::write_row (this=0x2597760, buff=0x2496860 "þ\001h") at ha_falcon.cpp:1186
#15 0x00000000008566f1 in handler::ha_write_row (this=0x2597760, buf=0x2496860 "þ\001h") at handler.cc:5514
#16 0x00000000007b6d48 in write_record (thd=0x25153a8, table=0x24bc318, info=0x24551a8) at sql_insert.cc:1596
#17 0x00000000007b7132 in select_insert::send_data (this=0x2455170, values=@0x24f60e8) at sql_insert.cc:3178
#18 0x000000000077b92b in end_send (join=0x24f04d0, join_tab=0x2456008, end_of_records=false) at sql_select.cc:17276
#19 0x0000000000787053 in evaluate_join_record (join=0x24f04d0, join_tab=0x2455d68, error=0) at sql_select.cc:16548
#20 0x0000000000787496 in sub_select (join=0x24f04d0, join_tab=0x2455d68, end_of_records=false) at sql_select.cc:16315
#21 0x0000000000795099 in do_select (join=0x24f04d0, fields=0x24f60e8, table=0x0, procedure=0x0) at sql_select.cc:15844
#22 0x00000000007af081 in JOIN::exec (this=0x24f04d0) at sql_select.cc:2886
#23 0x00000000007a9a5b in mysql_select (thd=0x25153a8, rref_pointer_array=0x2517358, tables=0x2454ba8, wild_num=0, fields=@0x2517278,
    conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=3489942016, result=0x2455170, unit=0x2516d08,
    select_lex=0x2517170) at sql_select.cc:3067
#24 0x00000000007af39f in handle_select (thd=0x25153a8, lex=0x2516c68, result=0x2455170, setup_tables_done_option=1073741824)
    at sql_select.cc:310
#25 0x000000000070ddba in mysql_execute_command (thd=0x25153a8) at sql_parse.cc:3316
#26 0x0000000000713321 in mysql_parse (thd=0x25153a8, inBuf=0x2454090 "INSERT INTO ftest(col1) SELECT col1 FROM ftest", length=46,
    found_semicolon=0x7f5dfdc7eb30) at sql_parse.cc:5979
#27 0x0000000000713f1a in dispatch_command (command=COM_QUERY, thd=0x25153a8,
    packet=0x2450039 "INSERT INTO ftest(col1) SELECT col1 FROM ftest", packet_length=46) at sql_parse.cc:1064

Any debug mask including the 2^2 bit of the bitmask (e.g. 4, 7, 12, ..., 1023, ...) seems to trigger the crash. 

The crash seems to happen after a few iterations of the "INSERT INTO .. SELECT ..." construct.

Observed against mysql-6.0-falcon-team branch, revid john.embretsen@sun.com-20090717133849-zrrnf5yrm3h6um2f.

How to repeat:
Method 1:
-------------

./mtr --big-test --suite=falcon --testcase-timeout=1400 --suite-timeout=1400 --mysqld=--falcon_debug_mask=4 falcon_bug_36294-big

Method 2:
-------------

1. Initialize server (mysql_install_db).

2. Start server with option --falcon_debug_mask=4 in addition to the mandatory ones.

3. In a mysql client, do:

CREATE TABLE t1 (id int, name varchar(500)) ENGINE=Falcon;
INSERT INTO t1 VALUES (null,repeat("a",500));
INSERT INTO t1(name) SELECT name FROM t1;

-- repeat last statement 14 times more...
[21 Jul 2009 18:10] Kevin Lewis
The call stack indicates that the thread was in strlen() when the crash happened.  So it looks like either Transaction::connection was not set or the pointer to connection->currentStatement was no longer useable.

I'll add a check for the validity of these before using them in the log statement.
[24 Jul 2009 17:56] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/79270

2758 Kevin Lewis	2009-07-24
      Bug#46324 - Crash in log statement is avoided by checking the vilidity of connection pointer and connection->currentStatement.
[28 Aug 2009 8:32] John Embretsen
It appears that I can still reproduce the issue with the latest patch, so I am setting this bug back to Verified status. Tested revision kevin.lewis@sun.com-20090827171320-xmkz8vqxfsjr1cxz of mysql-6.0-falcon-team.