Bug #56373 InnoDB Plugin : DROP TABLE on a corrupt table crashes server
Submitted: 30 Aug 2010 14:49 Modified: 10 Sep 2010 9:55
Reporter: Leandro Morgado Email Updates:
Status: Duplicate Impact on me:
None 
Category:MySQL Server: InnoDB Plugin storage engine Severity:S3 (Non-critical)
Version:5.1.48 OS:Any
Assigned to: Assigned Account CPU Architecture:Any

[30 Aug 2010 14:49] Leandro Morgado
Description:
When starting, InnoDB complains about unsynced tablespace and .frm/.ibd files (with innodb_file_per_table enabled). 

InnoDB: in InnoDB data dictionary has tablespace id 20236,
InnoDB: but tablespace with that id or name does not exist. Have
InnoDB: you deleted or moved .ibd files?
InnoDB: This may also be a table created with CREATE TEMPORARY TABLE
InnoDB: whose .ibd and .frm files MySQL automatically removed, but the
InnoDB: table still exists in the InnoDB internal data dictionary.
InnoDB: Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.1/en/innodb-troubleshooting-datadict.html
InnoDB: for how to resolve the issue.

When we DROP TABLE to fix the issue, InnoDB will raise an assertion and crash, due to possible corruption on the table being dropped. However, if the table is going to be dropped, we don't care if it is corrupt. No check is needed and the table should just be dropped.

How to repeat:
I haven't got a corrupt tablespace with me here, but look at the error log to see what's happening:

100830 11:25:17 mysqld_safe Starting mysqld daemon with databases from /var/database/mysql51
100830 11:25:17 [Warning] '--skip-locking' is deprecated and will be removed in a future release. Please use '--skip-external-locking' instead.
100830 11:25:17 [Warning] '--log_slow_queries' is deprecated and will be removed in a future release. Please use ''--slow_query_log'/'--slow_query_log_file'' instead.
100830 11:25:17 [Note] Plugin 'FEDERATED' is disabled.
InnoDB: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Compressed tables use zlib 1.2.3
100830 11:25:19  InnoDB: highest supported file format is Barracuda.
100830 11:25:20  InnoDB: Warning: allocated tablespace 14572, old maximum was 0
100830 11:25:20  InnoDB: Operating system error number 2 in a file operation.
InnoDB: The error means the system cannot find the path specified.
InnoDB: If you are installing InnoDB, remember that you must create
InnoDB: directories yourself, InnoDB does not create them.
100830 11:25:20  InnoDB: Error: trying to open a table, but could not
InnoDB: open the tablespace file './CRA_PULL_VM/CRA_TMP.ibd'!
InnoDB: Have you moved InnoDB .ibd files around without using the
InnoDB: commands DISCARD TABLESPACE and IMPORT TABLESPACE?
InnoDB: It is also possible that this is a temporary table #sql...,
InnoDB: and MySQL removed the .ibd file for this.
InnoDB: Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.1/en/innodb-troubleshooting-datadict.html
InnoDB: for how to resolve the issue.
100830 11:25:20 InnoDB Plugin 1.0.9 started; log sequence number 14747692251479
100830 11:25:21 [Note] Event Scheduler: Loaded 2 events
100830 11:25:21 [Note] Event Scheduler: scheduler thread started with id 1
100830 11:25:21 [Note] /usr/local/mysql/bin/mysqld: ready for connections.
Version: '5.1.48-enterprise-gpl-advanced-log'  socket: '/var/database/tmp/mysql.sock'  port: 3306  MySQL Enterprise Server - Advanced Edition (GPL)
100830 11:25:40  InnoDB: error: space object of table'CRA_PULL_VM/CRA_TMP',
InnoDB: space id 20236 did not exist in memory. Retrying an open.
100830 11:25:40  InnoDB: Assertion failure in thread 1095231824 in file fil/fil0fil.c line 2982
InnoDB: Failing assertion: flags != DICT_TF_COMPACT
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.
100830 11:25:40 - 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=134217728
read_buffer_size=262144
max_used_connections=6
max_threads=500
threads_connected=4
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 8456224 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd: 0x26c4c120
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 = 0x4147e110 thread_stack 0x40000
/usr/local/mysql/bin/mysqld(my_print_stacktrace+0x2e)[0x8b10be]
/usr/local/mysql/bin/mysqld(handle_segfault+0x322)[0x5e29e2]
/lib/libpthread.so.0[0x7fb106b2ea80]
/lib/libc.so.6(gsignal+0x35)[0x7fb105f27ed5]
/lib/libc.so.6(abort+0x183)[0x7fb105f293f3]
/usr/local/mysql-advanced-gpl-5.1.48-linux-x86_64-glibc23/lib/plugin/ha_innodb_plugin.so[0x7fb0faaf6905]
/usr/local/mysql-advanced-gpl-5.1.48-linux-x86_64-glibc23/lib/plugin/ha_innodb_plugin.so[0x7fb0faaea5b0]
/usr/local/mysql-advanced-gpl-5.1.48-linux-x86_64-glibc23/lib/plugin/ha_innodb_plugin.so[0x7fb0fab6aae8]
/usr/local/mysql-advanced-gpl-5.1.48-linux-x86_64-glibc23/lib/plugin/ha_innodb_plugin.so[0x7fb0fab0bce6]
/usr/local/mysql/bin/mysqld(_Z15ha_delete_tableP3THDP10handlertonPKcS4_S4_b+0x13d)[0x6d6f5d]
/usr/local/mysql/bin/mysqld(_Z20mysql_rm_table_part2P3THDP10TABLE_LISTbbbb+0x5f5)[0x6e8455]
/usr/local/mysql/bin/mysqld(_Z14mysql_rm_tableP3THDP10TABLE_LISTcc+0x77)[0x6e8927]
/usr/local/mysql/bin/mysqld(_Z21mysql_execute_commandP3THD+0xb79)[0x5f3b39]
/usr/local/mysql/bin/mysqld(_Z11mysql_parseP3THDPKcjPS2_+0x35e)[0x5f8a4e]
/usr/local/mysql/bin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0xe76)[0x5f98d6]
/usr/local/mysql/bin/mysqld(_Z10do_commandP3THD+0xe6)[0x5fa256]
/usr/local/mysql/bin/mysqld(handle_one_connection+0x246)[0x5ecb76]
/lib/libpthread.so.0[0x7fb106b26fc7]
/lib/libc.so.6(clone+0x6d)[0x7fb105fc55ad]
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort...
thd->query at 0x26c52a90 = drop table CRA_TMP
thd->thread_id=14
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.
100830 11:25:41 mysqld_safe Number of processes running now: 0
100830 11:25:41 mysqld_safe mysqld restarted
100830 11:25:41 [Warning] '--skip-locking' is deprecated and will be removed in a future release. Please use '--skip-external-locking' instead.
100830 11:25:41 [Warning] '--log_slow_queries' is deprecated and will be removed in a future release. Please use ''--slow_query_log'/'--slow_query_log_file'' instead.
100830 11:25:41 [Note] Plugin 'FEDERATED' is disabled.
InnoDB: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Compressed tables use zlib 1.2.3
100830 11:25:42  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!
100830 11:25:42  InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
100830 11:25:42  InnoDB: Warning: allocated tablespace 14667, old maximum was 0
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
InnoDB: Last MySQL binlog file position 0 932, file name /var/database/bin-log/mysql-bin.000143
100830 11:25:44  InnoDB: Error: table 'CRA_PULL_VM/CRA_TMP'
InnoDB: in InnoDB data dictionary has tablespace id 20236,
InnoDB: but tablespace with that id or name does not exist. Have
InnoDB: you deleted or moved .ibd files?
InnoDB: This may also be a table created with CREATE TEMPORARY TABLE
InnoDB: whose .ibd and .frm files MySQL automatically removed, but the
InnoDB: table still exists in the InnoDB internal data dictionary.
InnoDB: Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.1/en/innodb-troubleshooting-datadict.html
InnoDB: for how to resolve the issue.
...

Suggested fix:
Do not check table format or other consistency values when we want to DROP TABLE, instead print a warning:

2976         /* The tablespace flags (FSP_SPACE_FLAGS) should be 0 for
2977         ROW_FORMAT=COMPACT
2978         ((table->flags & ~(~0 << DICT_TF_BITS)) == DICT_TF_COMPACT) and
2979         ROW_FORMAT=REDUNDANT (table->flags == 0).  For any other
2980         format, the tablespace flags should equal
2981         (table->flags & ~(~0 << DICT_TF_BITS)). */
2982         ut_a(flags != DICT_TF_COMPACT);
2983         ut_a(!(flags & (~0UL << DICT_TF_BITS)));
2984
[8 Sep 2010 15:50] Mark Callaghan
I have recently hit this issue. I think the sequence is:
1) take hot backup from master using xtrabackup
2) restore on slave -- slave crashes

I think the call stack on the slave is:
dict_load_table -> fil_open_single_table_tablespace

Note that dict_load_table may set DICT_TF_COMPACT in flags prior to passing that to fil_open_single_table_tablespace

Also note that the call to fil_open_single_table_tablespace from dict_load_table is probably infrequently done as it only occurs when the ibd file is not found in the InnoDB dictionary

I don't have a core file. Core files are harder to get with large innodb buffer pool size and mysqld did not write a call stack in this case.

Contents of the error log:

InnoDB: Doing recovery: scanned up to log sequence number 1407792966957
InnoDB: 22 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 47 row operations to undo
InnoDB: Trx id counter is 10CA2DC00
100907 22:32:53  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95
 96 97 98 99 
InnoDB: Apply batch completed
100907 22:33:46 InnoDB: reading slave state from the transaction system header
                InnoDB: relay-log - filename , position (4294967295)
                InnoDB: master-log - filename , position (4294967295)
 InnoDB: recv_recovery_from_checkpoint_finish() - recovery is needed.
InnoDB: Last MySQL binlog file position 0 175128008, file name /binlogs/binary-logs.001160
100907 22:33:46  InnoDB: Rolling back trx with id 10CA2DAB8, 21 rows to undo
InnoDB: Dropping table with id 0 4486 in recovery if it exists
100907 22:33:46  InnoDB: error: space object of table'hs23670/__osc_old_assoc_info',
InnoDB: space id 4474 did not exist in memory. Retrying an open.
100907 22:33:46  InnoDB: Assertion failure in thread 46924329626544 in file fil/fil0fil.c line 2832
InnoDB: Failing assertion: flags != DICT_TF_COMPACT
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.
100907 22:33:46 - 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=16777216
read_buffer_size=1048576
max_used_connections=0
max_threads=5000
threads_connected=0
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 15429352 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd: 0x0
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 = (nil) thread_stack 0x30000
/usr/libexec/mysqld(my_print_stacktrace+0x2e) [0x8b352e]
/usr/libexec/mysqld(handle_segfault+0x33d) [0x5e1a3d]
/lib64/libpthread.so.0 [0x320b00de70]
/lib64/libc.so.6(gsignal+0x35) [0x36fe430155]
/lib64/libc.so.6(abort+0x110) [0x36fe431bf0]
/usr/libexec/mysqld [0x846def]
/usr/libexec/mysqld [0x8380ad]
/usr/libexec/mysqld [0x838dbb]
/usr/libexec/mysqld [0x7f0955]
/usr/libexec/mysqld [0x7e1d85]
/usr/libexec/mysqld [0x772bd8]
/usr/libexec/mysqld(ha_initialize_handlerton(st_plugin_int*)+0x36) [0x6d2216]
/usr/libexec/mysqld [0x75653d]
/usr/libexec/mysqld(plugin_init(int*, char**, int)+0x77d) [0x758fed]
/usr/libexec/mysqld [0x5e3ed5]
/usr/libexec/mysqld(main+0x825) [0x5e5615]

I am trying to figure out what was in progress on the master during the hot backup. It was likely one of:
* long running create table
* long running drop [temp] table
* long running create index
[8 Sep 2010 15:55] Mark Callaghan
Note that the fix for http://bugs.mysql.com/bug.php?id=54009 probably fixes this as it masks DICT_TF_COMPACT
[9 Sep 2010 11:12] Marko Mäkelä
This is a special case of Bug #10132 (I would say a duplicate of it).
[10 Sep 2010 9:55] Calvin Sun
dup of bug#10132.
[27 Sep 2010 9:57] Marko Mäkelä
I meant my comment "special case of Bug #10132" on the conceptual level, meaning that we should avoid crashing on corrupted data.

Upon closer investigation, this appears to be a duplicate of Bug #54009.

All callers now pass the tablespace flags to fil_open_single_table_tablespace() as 0 for REDUNDANT and COMPACT tables, and as SYS_TABLES.TYPE for DYNAMIC and COMPRESSED tables.