MySQL Bugs: #55039: Failing assertion: space_id

Bug #55039	Failing assertion: space_id > 0 in fil0fil.c line 2618
Submitted:	6 Jul 2010 23:01	Modified:	15 Oct 2010 13:41
Reporter:	Elena Stepanova	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S2 (Serious)
Version:	5.1.49, 5.5.5-m3, 5.5.6-m3	OS:	Any
Assigned to:	Jimmy Yang	CPU Architecture:	Any
Tags:	regression

Description:
On concurrent DDL, e.g. CREATE TEMPORARY TABLE, and changing innodb_file_format/innodb_file_per_table:

Thread 1 (process 17971):
#0  0x00002adc653f5ea3 in pthread_kill () from /lib64/libpthread.so.0
#1  0x000000000050c1dc in handle_segfault (sig=6) at mysql-5.5.6-m3/sql/mysqld.cc:2791
#2  <signal handler called>
#3  0x00002adc659cfbb5 in raise () from /lib64/libc.so.6
#4  0x00002adc659d0fb0 in abort () from /lib64/libc.so.6
#5  0x0000000000855d20 in fil_create_new_single_table_tablespace (space_id=0, tablename=0x14a83c0 "/tmp/B6MyC9QDTR/mysqld.1/#sql461a_3_6", is_temp=1, flags=0, size=4)
    at mysql-5.5.6-m3/storage/innobase/fil/fil0fil.c:2628
#6  0x000000000083a8f4 in dict_create_table_step (thr=0x14cbd50)
    at mysql-5.5.6-m3/storage/innobase/dict/dict0crea.c:282
#7  0x00000000008a92ad in que_run_threads (thr=0x14cbd50) at mysql-5.5.6-m3/storage/innobase/que/que0que.c:1255
#8  0x00000000007c8a54 in row_create_table_for_mysql (table=0x14dc388, trx=0x14da988)
    at mysql-5.5.6-m3/storage/innobase/row/row0mysql.c:1847
#9  0x00000000007af47c in ha_innobase::create (this=<value optimized out>, name=<value optimized out>, form=0x450c8320, create_info=0x450ca230)
    at mysql-5.5.6-m3/storage/innobase/handler/ha_innodb.cc:6266
#10 0x00000000006930c9 in ha_create_table (thd=<value optimized out>, path=<value optimized out>, db=0x14bd440 "test", table_name=0x14bcef0 "operations",
    create_info=0x450ca230, update_create_info=false) at mysql-5.5.6-m3/sql/handler.cc:3609
#11 0x000000000060733b in rea_create_table (thd=0x14b2160, path=0x450c9250 "/tmp/B6MyC9QDTR/mysqld.1/#sql461a_3_6", db=0x14bd440 "test",
    table_name=0x14bcef0 "operations", create_info=0x450ca230, create_fields=@0x450ca1d8, keys=0, key_info=0x14bd7d8, file=0x14bd5d8)
    at mysql-5.5.6-m3/sql/unireg.cc:463
#12 0x00000000005de7a3 in mysql_create_table_no_lock (thd=0x14b2160, db=0x14bd440 "test", table_name=0x14bcef0 "operations", create_info=0x450ca230,
    alter_info=0x450ca190, internal_tmp_table=false, select_field_count=0) at mysql-5.5.6-m3/sql/sql_table.cc:4179
#13 0x00000000005e4534 in mysql_create_table (thd=0x14b2160, create_table=0x14bcf38, create_info=0x450ca230, alter_info=0x450ca190)
    at mysql-5.5.6-m3/sql/sql_table.cc:4255
#14 0x00000000005839d9 in mysql_execute_command (thd=0x14b2160) at mysql-5.5.6-m3/sql/sql_parse.cc:2769
#15 0x0000000000583f7d in mysql_parse (thd=0x14b2160, inBuf=0x14bcdf0 "CREATE TEMPORARY TABLE operations ( op VARCHAR(16) ) ENGINE = InnoDB",
    length=<value optimized out>, parser_state=0x450cb7e0) at mysql-5.5.6-m3/sql/sql_parse.cc:5911
#16 0x0000000000584ce7 in dispatch_command (command=COM_QUERY, thd=0x14b2160, packet=<value optimized out>, packet_length=68)
    at mysql-5.5.6-m3/sql/sql_class.h:724
#17 0x00000000005855ad in do_command (thd=0x14b2160) at mysql-5.5.6-m3/sql/sql_parse.cc:807
#18 0x000000000061da49 in do_handle_one_connection (thd_arg=0x14b2160) at mysql-5.5.6-m3/sql/sql_connect.cc:1196
#19 0x000000000061e534 in handle_one_connection (arg=<value optimized out>) at mysql-5.5.6-m3/sql/sql_connect.cc:1135
#20 0x000000000090b4ab in pfs_spawn_thread (arg=<value optimized out>) at mysql-5.5.6-m3/storage/perfschema/pfs.cc:1015
#21 0x00002adc653f1143 in start_thread () from /lib64/libpthread.so.0
#22 0x00002adc65a608cd in clone () from /lib64/libc.so.6

InnoDB 1.1.1 
Version: '5.5.6-m3-log'
InnoDB: Assertion failure in thread 1158465856 in file mysql-5.5.6-m3/storage/innobase/fil/fil0fil.c line 2618

thd->query at 0x14bcdf0 = CREATE TEMPORARY TABLE operations ( op VARCHAR(16) ) ENGINE = InnoDB
thd->thread_id=3
thd->killed=NOT_KILLED

I'm getting the crash on 5.5.5-m3 which is being released and on the current trunk (both release and debug), but cannot reproduce it on 5.5.4-m3 and earlier, so I'm tagging it as a regression.

How to repeat:
# MTR test case. It failed for me 18 times of 20 I tried
# Increasing number of tries or running the test case via --repeat
# does not seem to help, try just to restart it if it did not work.

--source include/have_innodb.inc

--connect(con1,localhost,root,,)
--connect(con2,localhost,root,,)

--let $try=100

while($try)
{
        --dec $try
        --connection con1
        --send CREATE TEMPORARY TABLE operations (op VARCHAR(16)) ENGINE=InnoDB
        --connection con2
        --send SET GLOBAL innodb_file_format=Antelope, innodb_file_per_table=ON
        --connection con1
        --reap
        DROP TABLE operations;
        --connection con2
        --reap
        SET GLOBAL innodb_file_format = Barracuda, innodb_file_per_table = OFF;
}

--exit

I also got the same assertion once on ALTER TABLE .. ADD PARTITION, but it is not as easily reproducible, apparently the race condition is harder to reach. 
The stack trace looks similar (although not identical), so I hope it is the same problem; if it is not, please let me know and I will try to chase it further.

005E4E59    mysqld.exe!fil_create_new_single_table_tablespace()[fil0fil.c:2719]
0063BB6D    mysqld.exe!dict_build_table_def_step()[dict0crea.c:286]
0063C58E    mysqld.exe!dict_create_table_step()[dict0crea.c:967]
0062F379    mysqld.exe!que_thr_step()[que0que.c:1255]
0062F8C3    mysqld.exe!que_run_threads_low()[que0que.c:1310]
0062FA3A    mysqld.exe!que_run_threads()[que0que.c:1349]
00603F59    mysqld.exe!row_create_table_for_mysql()[row0mysql.c:1849]
005C4BB4    mysqld.exe!create_table_def()[ha_innodb.cc:6266]
005C9FBA    mysqld.exe!ha_innobase::create()[ha_innodb.cc:6884]
0041DE31    mysqld.exe!handler::ha_create()[handler.cc:3402]
004EE4EB    mysqld.exe!ha_partition::prepare_new_partition()[ha_partition.cc:1288]
004EE9B5    mysqld.exe!ha_partition::change_partitions()[ha_partition.cc:1643]
7D61F5F1    ntdll.dll!RtlFreeHeap()
023F0000    
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort...
thd->query at 0BB58028=ALTER TABLE t_celosia_ddl_partitions ADD PARTITION PARTITIONS 4
thd->thread_id=19687
thd->killed=NOT_KILLED

Elena - have you tried the same tests against the plugin in 5.1? Thanks!

I have not -- since I could not get the crash even on 5.5.4 (plugin 1.1.0), I did not go to earlier versions. I will try, just in case.

Ran 10 consequent tests on each of the following versions:

5.5.5-m3 (1.1.1): 2 passed, 8 crashed, execution time (for passed) 20-22 sec
5.5.4-m3 (1.1.0): 10 passed, execution time 20-28 sec
5.5.3-m3 (1.0.6): 10 passed, execution time 7-12 sec
5.1.48   (1.0.9): 10 passed, execution time 7-12 sec

The error is due to a recent change in dict_build_table_def_step(), dict_hdr_get_new_id() is extracted out of  fil_create_new_single_table_tablespace() and added in the beginning of dict_build_table_def_step(). This expose itself to a changing srv_file_per_table value.

dict_build_table_def_step()
{

        dict_hdr_get_new_id(&table->id, NULL,
                                srv_file_per_table ? &space : NULL); <==== srv_file_per_table is 0, thus we did not fetch space, it is 0
     
        thr_get_trx(thr)->table_id = table->id;
     
        if (srv_file_per_table) {    <====srv_file_per_table switch to true, thus we hit the assertion space > 0 in fil_create_new_single_table_tablespace() 

                                 fil_create_new_single_table_tablespace

       }
}

This can be easily reproduced using a debugger.

Thanks
Jimmy

Identified the change was introduced in #53578

+++ b/storage/innobase/dict/dict0crea.c	revid:marko.makela@stripped
@@ -239,16 +239,22 @@ dict_build_table_def_step(
 	const char*	path_or_name;
 	ibool		is_path;
 	mtr_t		mtr;
+	ulint		space = 0;
 
 	ut_ad(mutex_own(&(dict_sys->mutex)));
 
 	table = node->table;
 
-	table->id = dict_hdr_get_new_id(DICT_HDR_TABLE_ID);
+	dict_hdr_get_new_id(&table->id, NULL,
+			    srv_file_per_table ? &space : NULL);
 
 	thr_get_trx(thr)->table_id = table->id;
 
 	if (srv_file_per_table) {
+		if (UNIV_UNLIKELY(space == ULINT_UNDEFINED)) {
+			return(DB_ERROR);
+		}
+

This bug can reproduced with 5.1 as well, for the same reason. 

Jere describes a simple approach to repro the assertion with help of debugger to sync two threads:

1. session A 
mysql> SET GLOBAL innodb_file_format = Barracuda, innodb_file_per_table = OFF; 
Query OK, 0 rows affected (0.00 sec)

mysql> CREATE TEMPORARY TABLE operations (op VARCHAR(16)) ENGINE=InnoDB;

2. Put break point at dict_build_table_def_step(), step through after dict_hdr_get_new_id(), since srv_file_per_table is 0, space will be 0:

    263         dict_hdr_get_new_id(&table->id, NULL,
    264                             srv_file_per_table ? &space : NULL);
    265 

(gdb) p space
$1 = 0

3. Let this thread loop, 
(gdb) call srv_debug_loop()

4. in session 2, set innodb_file_per_table to 1

mysql>  SET GLOBAL innodb_file_format=Antelope, innodb_file_per_table=ON;
Query OK, 0 rows affected (0.00 sec)

5. Free the thread from looping, and continue:

(gdb) b fil_create_new_single_table_tablespace
Breakpoint 3 at 0x84d0cc3: file fil/fil0fil.c, line 2591.
(gdb) c
Continuing.

Breakpoint 3, fil_create_new_single_table_tablespace (space_id=0, 
    tablename=0x90164b8 "/home/jy/work/mysql5.1_5/mysql-5.1/mysql-test/var/tmp/mysqld.1/#sql3c2f_1_0", is_temp=1, flags=0, size=4) at fil/fil0fil.c:2591
2591	{
(gdb) n
2600		ut_a(space_id > 0);
(gdb) 
100708  9:24:10  InnoDB: Assertion failure in thread 2817743728 in file fil/fil0fil.c line 2600
InnoDB: Failing assertion: space_id > 0
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.1/en/forcing-recovery.html
InnoDB: about forcing recovery.

Program received signal SIGABRT, Aborted.
0x0088a422 in __kernel_vsyscall ()
(gdb) c
Continuing.
100708  9:24:14 - 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.
....
Program received signal SIGABRT, Aborted.
0x0088a422 in __kernel_vsyscall ()

SRT assessment: Severity C, CVSS 2.1

As I understand this exploit demands SUPER privilege.

Pushed into 5.1.49 (revid:build@mysql.com-20100719143034-omcma40sblwmay3x) (version source revid:karen.langford@oracle.com-20100709122348-pbgrcz2zgvzlqzld) (merge vers: 5.1.49) (pib:16)

Pushed into mysql-trunk 5.5.6-m3 (revid:alik@sun.com-20100723121820-jryu2fuw3pc53q9w) (version source revid:alik@sun.com-20100723121820-jryu2fuw3pc53q9w) (merge vers: 5.5.6-m3) (pib:18)

Pushed into mysql-next-mr (revid:alik@sun.com-20100723121929-90e9zemk3jkr2ocy) (version source revid:alik@sun.com-20100723121827-3bsh51m5sj6g4oma) (pib:18)

Pushed into mysql-trunk 5.5.6-m3 (revid:alik@sun.com-20100731131027-1n61gseejyxsqk5d) (version source revid:alik@sun.com-20100731074942-o840woifuqioxxe4) (merge vers: 5.5.6-m3) (pib:18)

Pushed into mysql-trunk 5.6.1-m4 (revid:alik@ibmvm-20100804080001-bny5271e65xo34ig) (version source revid:alik@sun.com-20100731075120-qz9z8c25zum2wgmm) (merge vers: 5.6.99-m4) (pib:18)

Pushed into mysql-trunk 5.6.1-m4 (revid:alik@ibmvm-20100804081533-c1d3rbipo9e8rt1s) (version source revid:alik@sun.com-20100731075120-qz9z8c25zum2wgmm) (merge vers: 5.6.99-m4) (pib:18)

Pushed into mysql-next-mr (revid:alik@ibmvm-20100804081630-ntapn8bf9pko9vj3) (version source revid:alik@sun.com-20100731075120-qz9z8c25zum2wgmm) (pib:20)

Added to the 5.1.49 and 5.5.6 change logs:

After changing the values of the innodb_file_format or innodb_file_per_table configuration parameters, DDL statements could cause a server crash.

Pushed into mysql-5.1 5.1.51 (revid:build@mysql.com-20100819151858-muaaor6jojb5ouzj) (version source revid:build@mysql.com-20100819151858-muaaor6jojb5ouzj) (merge vers: 5.1.51) (pib:20)

Pushed into mysql-5.1-telco-7.0 5.1.51-ndb-7.0.20 (revid:martin.skold@mysql.com-20101014082627-jrmy9xbfbtrebw3c) (version source revid:martin.skold@mysql.com-20101014082627-jrmy9xbfbtrebw3c) (merge vers: 5.1.51-ndb-7.0.20) (pib:21)

Pushed into mysql-5.1-telco-6.3 5.1.51-ndb-6.3.39 (revid:martin.skold@mysql.com-20101014083757-5qo48b86d69zjvzj) (version source revid:martin.skold@mysql.com-20101014083757-5qo48b86d69zjvzj) (merge vers: 5.1.51-ndb-6.3.39) (pib:21)

Pushed into mysql-5.1-telco-6.2 5.1.51-ndb-6.2.19 (revid:martin.skold@mysql.com-20101014084420-y54ecj85j5we27oa) (version source revid:martin.skold@mysql.com-20101014084420-y54ecj85j5we27oa) (merge vers: 5.1.51-ndb-6.2.19) (pib:21)

Closing per above.

CVE-2010-3676