MySQL Bugs: #37284: Crash in Field

Bug #37284	Crash in Field_string::type()
Submitted:	9 Jun 2008 15:05	Modified:	8 Dec 2008 16:53
Reporter:	Zardosht Kasheff (OCA)	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: General	Severity:	S3 (Non-critical)
Version:	5.1.23, 5.1.28	OS:	Linux
Assigned to:	Sergei Glukhov	CPU Architecture:	Any

Description:
I have only hit this with storage engines that implement add_index.

When executing the SELECT call, I get a crash in opt_range.cc:5724:
  if (value->real_item()->type() == Item::STRING_ITEM &&
      (field->type() == MYSQL_TYPE_DATE ||
       field->type() == MYSQL_TYPE_DATETIME))

What happens is that the field->type() does the following:
    return ((can_alter_field_type && orig_table &&
             orig_table->s->db_create_options & HA_OPTION_PACK_RECORD &&
             field_length >= 4) &&
            orig_table->s->frm_version < FRM_VER_TRUE_VARCHAR ?
            MYSQL_TYPE_VAR_STRING : MYSQL_TYPE_STRING);

It turns out that orig_table is a bogus value. Here is why.

During the adding of the index, a call is made to reopen_table in
sql_base.cc. In that function, the following code is executed:
  for (field=table->field ; *field ; field++)
  {
    (*field)->table= (*field)->orig_table= table;
    (*field)->table_name= &table->alias;
  }
  for (key=0 ; key < table->s->keys ; key++)
  {
    for (part=0 ; part < table->key_info[key].usable_key_parts ; part++)
      table->key_info[key].key_part[part].field->table= table;
  }

The problem that I see is that the orig_table field (and alias field) is
not set in the bottom loop as it is set in the top loop. As a result, when
field->type() eventually gets called, the orig_table value is bogus. If
this issue is unknown, the likely reason is that others have not run this
scenario.

In all other scenarios I run, the fields set in the second loop
are a subset of the fields set in the first loop, thus making the second
loop redundant. In this test, however, the fields of the second loop are
NOT a part of the fields in the first loop, and thus we hit this issue.

How to repeat:
For a storage engine that implements add_index, put these commands in a mysqltest:

CREATE TABLE t1 (a char(50));
CREATE INDEX i1 on t1 (a(3));
SELECT * FROM t1 WHERE a = 'abcde';

The crash occurs on the SELECT * statement.

Suggested fix:
Although the crash is only due to orig_table not being set, my suggested fix sets both orig_table and alias.

In sql_base.cc, in the function reopen_table, add two lines in the second for loop:

  for (field=table->field ; *field ; field++)
  {
    (*field)->table= (*field)->orig_table= table;
    (*field)->table_name= &table->alias;
  }
  for (key=0 ; key < table->s->keys ; key++)
  {
    for (part=0 ; part < table->key_info[key].usable_key_parts ; part++) {
      table->key_info[key].key_part[part].field->table= table;
      //
      // add these two lines
      //
      table->key_info[key].key_part[part].field->orig_table= table;
      table->key_info[key].key_part[part].field->table_name = &table->alias;
    }
  }

"storage engine that implements add_index" -> only NDB Cluster and Falcon implement this as far as i can tell, right?

I tried your example statements with ENGINE=ndb and ENGINE=falcon,
using both ONLINE and OFFLINE index creation where possible, with
5.1.23, 5.1.24-ndb-6.3.14 and 6.0dev builds but couldn't reproduce
this anywhere.

So i'm afraid i have to ask you for more detailed "how to reproduce" 
instructions

Perhaps the flags passed in alter_table_flags need to be: 
HA_ONLINE_ADD_INDEX_NO_WRITES
HA_ONLINE_DROP_INDEX_NO_WRITES 
HA_ONLINE_ADD_UNIQUE_INDEX_NO_WRITES
HA_ONLINE_DROP_UNIQUE_INDEX_NO_WRITES

What I see in falcon storage engine and NDB is that the alter_table_flags either are commented out (falcon) or do not have "NO_WRITE" appended to them

Does this get the bug to reproduce?

Thank you for the feedback.

Bug is not repeatable if add NO_WRITE flags to NDB storage engine with current development sources. Could you please try with current version which is 5.1.28 now and if problem still exists provide more details about what can be cause of such behavior.

I do see this on 5.1.28.

Here is a stack trace:
Program received signal SIGSEGV, Segmentation fault.
[Switching to Thread 1147701568 (LWP 12918)]
0x000000000060731f in Field_string::type (this=0x1731120) at field.h:1462
1462                MYSQL_TYPE_VAR_STRING : MYSQL_TYPE_STRING);
(gdb) bt
#0  0x000000000060731f in Field_string::type (this=0x1731120) at field.h:1462
#1  0x0000000000606c36 in Field::eq (this=0x172ea60, field=0x1731120)
    at field.h:150
#2  0x0000000000685b58 in add_key_part (keyuse_array=0x1770768,
    key_field=0x171efa8) at sql_select.cc:3486
#3  0x0000000000696942 in make_join_statistics (join=0x176f1a8,
    tables=<value optimized out>, conds=0x171e9a8, keyuse_array=0x1770768)
    at sql_select.cc:3718
#4  0x000000000069aa1a in JOIN::optimize (this=0x176f1a8) at sql_select.cc:945
#5  0x00000000006a664d in mysql_select (thd=0x16be228,
    rref_pointer_array=0x16c0268, tables=0x171e130, wild_num=1,
    fields=@0x16c0100, conds=0x171e600, og_num=0, order=0x0, group=0x0,
    having=0x0, proc_param=0x0, select_options=2147764736, result=0x171e7f0,
    unit=0x16bfc68, select_lex=0x16c0098) at sql_select.cc:2347
#6  0x00000000006a6bd4 in handle_select (thd=0x16be228, lex=0x16bfbc8,
    result=0x171e7f0, setup_tables_done_option=0) at sql_select.cc:269
#7  0x000000000062d207 in execute_sqlcom_select (thd=0x16be228,
    all_tables=0x171e130) at sql_parse.cc:4826
#8  0x00000000006301ff in mysql_execute_command (thd=0x16be228)
    at sql_parse.cc:2134
#9  0x00000000006366f7 in mysql_parse (thd=0x16be228,
    inBuf=0x171df48 "SELECT * FROM t1 WHERE a = 'abcde'", length=34,
    found_semicolon=0x44687de0) at sql_parse.cc:5717
#10 0x0000000000637804 in dispatch_command (command=COM_QUERY, thd=0x16be228,
    packet=0x17129f9 "SELECT * FROM t1 WHERE a = 'abcde'",
    packet_length=<value optimized out>) at sql_parse.cc:1152
#11 0x00000000006386f2 in do_command (thd=0x16be228) at sql_parse.cc:809
#12 0x0000000000628cc4 in handle_one_connection (arg=<value optimized out>)
    at sql_connect.cc:1115
#13 0x0000003aaec062f7 in start_thread () from /lib64/libpthread.so.0
#14 0x00000035eecce86d in clone () from /lib64/libc.so.6
#15 0x0000000000000000 in ?? ()
(gdb)

Here is some more info on the problem. The bug is exposed when running the "select *" statement, but the cause is during add_index, at this point of the stack:

(gdb) bt
#0  reopen_table (table=0x1713468) at sql_base.cc:3090
#1  0x000000000073e3ae in mysql_alter_table (thd=0x16ecdd8,
    new_db=0x1723b60 "test", new_name=0x17237f0 "t1", create_info=0x45a88910,
    table_list=0x1723828, alter_info=0x45a89210, order_num=0, order=0x0,
    ignore=false) at sql_table.cc:6896
#2  0x0000000000631052 in mysql_execute_command (thd=0x16ecdd8)
    at sql_parse.cc:2634
#3  0x00000000006366f7 in mysql_parse (thd=0x16ecdd8,
    inBuf=0x1723738 "CREATE INDEX i1 on t1 (a(3))", length=28,
    found_semicolon=0x45a89de0) at sql_parse.cc:5717
#4  0x0000000000637804 in dispatch_command (command=COM_QUERY, thd=0x16ecdd8,
    packet=0x171b6a9 "CREATE INDEX i1 on t1 (a(3))",
    packet_length=<value optimized out>) at sql_parse.cc:1152
#5  0x00000000006386f2 in do_command (thd=0x16ecdd8) at sql_parse.cc:809
#6  0x0000000000628cc4 in handle_one_connection (arg=<value optimized out>)
    at sql_connect.cc:1115
#7  0x0000003aaec062f7 in start_thread () from /lib64/libpthread.so.0
#8  0x00000035eecce86d in clone () from /lib64/libc.so.6
#9  0x0000000000000000 in ?? ()

The problem is that in the second for loop, orig_table is not being set. That is what causes the crash. The reason this is hit infrequently, is that in most cases table->field[0] == table->key_info[0].key_part[0].field, but not here:

(gdb) inspect table->field[0]
$4 = (class Field *) 0x1714040
(gdb) inspect table->key_info[key].key_part[part].field
$5 = (class Field *) 0x17228d0

Thank you for the feedback.

Please try to port implementation from add_index for your storage engine to example storage engine so is possible to repeat this bug and prove this is MySQL problem.

I was able to reproduce it with latest 5.1 bzr source and InnoDB plugin on Windows:

C:\dbs\plugin>c:\dbs\plugin\5.1\bin\mysqld --defaults-file=c:\dbs\plugin\5.1\my.ini --standalone --console
081027 14:40:48  InnoDB: highest supported file format is Barracuda.
InnoDB: The log sequence number in ibdata files does not match
InnoDB: the log sequence number in the ib_logfiles!
081027 14:40:48  InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
081027 14:40:48 InnoDB Plugin 1.0.1 started; log sequence number 53662
081027 14:40:48 [Note] Recovering after a crash using server51
081027 14:40:48 [Note] Starting crash recovery...
081027 14:40:48 [Note] Crash recovery finished.
081027 14:40:48 [Note] Event Scheduler: Loaded 0 events
081027 14:40:48 [Note] c:\dbs\plugin\5.1\bin\mysqld: ready for connections.
Version: '5.1.30-nt-debug-log'  socket: ''  port: 3510  Source distribution
InnoDB: VirtualFree(03930000, 3145728) failed; Windows error 87
081027 14:45:30 - mysqld got exception 0xc0000005 ;
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=8388572
read_buffer_size=131072
max_used_connections=1
max_threads=151
threads_connected=1
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 337709 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd: 0x26a0060
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...
0044C913    mysqld.exe!Field_string::type()[field.h:1456]
00446F37    mysqld.exe!Field::eq()[field.h:150]
006B9CF6    mysqld.exe!add_key_part()[sql_select.cc:3486]
006B80F9    mysqld.exe!update_ref_and_keys()[sql_select.cc:3718]
006B6CBA    mysqld.exe!make_join_statistics()[sql_select.cc:2596]
006B1863    mysqld.exe!JOIN::optimize()[sql_select.cc:946]
006B61D5    mysqld.exe!mysql_select()[sql_select.cc:2347]
006AFD79    mysqld.exe!handle_select()[sql_select.cc:269]
006765B9    mysqld.exe!execute_sqlcom_select()[sql_parse.cc:4828]
0066F1CC    mysqld.exe!mysql_execute_command()[sql_parse.cc:2136]
00678661    mysqld.exe!mysql_parse()[sql_parse.cc:5727]
0066D31E    mysqld.exe!dispatch_command()[sql_parse.cc:1152]
0066CA07    mysqld.exe!do_command()[sql_parse.cc:809]
0077D154    mysqld.exe!handle_one_connection()[sql_connect.cc:1115]
00845F16    mysqld.exe!pthread_start()[my_winthread.c:85]
009D2D87    mysqld.exe!_threadstart()[thread.c:196]
7C80B713    kernel32.dll!GetModuleFileNameA()
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort...
thd->query at 026ED210=SELECT * FROM t1 WHERE a = 'abcde'
thd->thread_id=1
thd->killed=NOT_KILLED
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.

C:\dbs\plugin>

Zardosht, thank you for the feedback.

Miguel, thank you for testing. Bug is verified, although I could not repeat described behavior with debug static build of InnoDB plugin on Linux.

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/59229

2716 Sergey Glukhov	2008-11-19
      Bug#37284 Crash in Field_string::type()
      The bug is repeatable with latest(1.0.1) InnoDB plugin on Linux, Win,
      If MySQL is compiled with valgrind there are errors about
      using of uninitialized variable(orig_table).
      The fix is to set field->orig_table correct value.

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/60063

2718 Sergey Glukhov	2008-11-27
      Bug#37284 Crash in Field_string::type()
      The bug is repeatable with latest(1.0.1) InnoDB plugin on Linux, Win,
      If MySQL is compiled with valgrind there are errors about
      using of uninitialized variable(orig_table).
      The fix is to set field->orig_table correct value.

Pushed into 5.0.74  (revid:sergey.glukhov@sun.com-20081127145423-cqyzso9cu8uzz85v) (version source revid:matthias.leich@sun.com-20081128184708-uyjg2dfrj2va5o3d) (pib:5)

Noted in 5.0.74 changelog.

CREATE INDEX could crash with InnoDB plugin 1.0.1.

Resetting report to NDI pending push into 5.1.x.

Pushed into 5.1.31  (revid:sergey.glukhov@sun.com-20081127145423-cqyzso9cu8uzz85v) (version source revid:ingo.struewing@sun.com-20081127152850-iwzy1vh9gqpg3s3x) (pib:5)

Pushed into 6.0.9-alpha  (revid:sergey.glukhov@sun.com-20081127145423-cqyzso9cu8uzz85v) (version source revid:ingo.struewing@sun.com-20081127214152-x1avx1b1cyfshx1a) (pib:5)

Noted in 5.1.31 changelog.

Not noted in 6.0.x because the bug does not affect 6.0.

Pushed into 5.1.31-ndb-6.2.17 (revid:tomas.ulin@sun.com-20090119095303-uwwvxiibtr38djii) (version source revid:tomas.ulin@sun.com-20090108105244-8opp3i85jw0uj5ib) (merge vers: 5.1.31-ndb-6.2.17) (pib:6)

Pushed into 5.1.31-ndb-6.3.21 (revid:tomas.ulin@sun.com-20090119104956-guxz190n2kh31fxl) (version source revid:tomas.ulin@sun.com-20090119104956-guxz190n2kh31fxl) (merge vers: 5.1.31-ndb-6.3.21) (pib:6)

Pushed into 5.1.31-ndb-6.4.1 (revid:tomas.ulin@sun.com-20090119144033-4aylstx5czzz88i5) (version source revid:tomas.ulin@sun.com-20090119144033-4aylstx5czzz88i5) (merge vers: 5.1.31-ndb-6.4.1) (pib:6)