Bug #64512 error 56 upon abnormal disconnect when temporary tables exist, crash
Submitted: 1 Mar 2012 10:48 Modified: 16 May 2012 18:23
Reporter: Russell Levy Email Updates:
Status: No Feedback Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S1 (Critical)
Version:5.6.4 OS:Linux
Assigned to: CPU Architecture:Any
Tags: crash, tables, temporary

[1 Mar 2012 10:48] Russell Levy
Description:
I cannot replicate this on demand, but the log files are the same every time.

 * There is a line in the log file that a connection was aborted
 * The next line is error 56, but doesn't give the table name that it could not drop
 * The server then crashes on an assertion, and the last function name in the traceback is rm_temporary_table

120301  3:03:40 [Warning] Aborted connection 155 to db: 'xxx' user: 'xxx' host: '68.xxx.xxx.xxx' (Got an error reading communication packets)
120301  3:03:40InnoDB: unknown error code 56 while dropping table:120301  3:03:40 [Warning] Invalid (old?) table or database name '#sql2177_9b_0'
`tmp`.<result 2 when explaining filename '#sql2177_9b_0'>.
120301  3:03:40  InnoDB: Assertion failure in thread 47798292130128 in file trx0trx.cc line 714
InnoDB: Failing assertion: ib_vector_is_empty(trx->lock.table_locks)
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.6/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
120301  3:03: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=268435456
read_buffer_size=1048576
max_used_connections=5
max_threads=500
thread_count=2
connection_count=2
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 1292167 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x23cdd30
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 = 0x2b78e83920b0 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x39)[0x869279]
/usr/sbin/mysqld(handle_segfault+0x3c7)[0x55ca77]
/lib64/libpthread.so.0[0x3b1300f0f0]
/lib64/libc.so.6(gsignal+0x35)[0x3b12832f05]
/lib64/libc.so.6(abort+0x183)[0x3b12834a73]
/usr/sbin/mysqld[0x973955]
/usr/sbin/mysqld[0x97505c]
/usr/sbin/mysqld[0x93b02e]
/usr/sbin/mysqld[0x8ce4e2]
/usr/sbin/mysqld(_Z18rm_temporary_tableP10handlertonPc+0xe4)[0x658c94]
/usr/sbin/mysqld(_Z15close_temporaryP5TABLEbb+0xaa)[0x6598ba]
/usr/sbin/mysqld(_Z22close_temporary_tablesP3THD+0x5fc)[0x65c1bc]
/usr/sbin/mysqld(_ZN3THD7cleanupEv+0x88)[0x672cf8]
/usr/sbin/mysqld(_Z10unlink_thdP3THD+0x20)[0x55f830]
/usr/sbin/mysqld(_Z29one_thread_per_connection_endP3THDb+0x23)[0x55f8e3]
/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x127)[0x676ec7]
/usr/sbin/mysqld(handle_one_connection+0x45)[0x676f95]
/lib64/libpthread.so.0[0x3b130073da]
/lib64/libc.so.6(clone+0x6d)[0x3b128e62bd]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query ((nil)): is an invalid pointer
Connection ID (thread ID): 155
Status: KILL_CONNECTION

How to repeat:
 1. Connect to database through C API
 2. create temporary tables
 3. Disconnect WITHOUT issuing mysql_close

Suggested fix:
Do not assert fail when dropping a table that was already dropped (?)
[1 Mar 2012 11:31] Russell Levy
Hi,

I just noticed that it happened again. It may be that this happens on connections that time out (which is why it was hard for me to reproduce it).
[1 Mar 2012 11:31] Russell Levy
Changed severity to critical, as it crashes the server.
[6 Mar 2012 16:49] Sveta Smirnova
Thank you for the report.

I can not repeat described behavior. Please describe how you create temporary tables and what you do with them?
[7 Mar 2012 21:06] Russell Levy
Unfortunately I am not sure which temporary table crashed the system. Our code creates temporary tables in seven separate areas, and since the problem only manifested on disconnect, it was hard to figure it out. Is it possible to find it in the binary logs?

 I have had to downgrade back to 5.5 because of this issue and I can't test further.
[9 Mar 2012 17:14] Sveta Smirnova
Thank you for the feedback.

> Is it possible to find it in the binary logs?

Probably. At least we can try. If you attach binary logs, please, attach full error log also: maybe we will find something interesting in it too.
[10 Mar 2012 21:16] Russell Levy
Hi,
For security reasons I cannot attach a raw binary log (it contains other client data). When I tried to pull it out for this one database with

mysqlbinlog --database=skyview --start-datetime='2012-2-22 0:00:00' --stop-datetime='2012-3-1 3:04:00' mysql-bin.0000[678]* --base64-output=never -v

It didn't seem to have the data that was put in the database during that time. Am I doing something wrong?
[13 Mar 2012 19:17] Sveta Smirnova
Thank you for the feedback.

You specified option "--base64-output=never". This means no ROW event would be displayed. Please re-run without this option.
[13 Mar 2012 20:30] Russell Levy
Hi,
I have attached the binlog, starting with the first entry for thread 155 (the one specified in the log file) and ending with the crash. 

The first comment has a paste of the error log. If you need more (crash recovery information), I can put that in as well
[28 Mar 2012 23:22] Leo Kwan
Error can be repeat by the following steps.

mysql> use PlayGround;
Database changed

mysql> create temporary table Tmp (ID int) engine innodb;
Query OK, 0 rows affected (0.00 sec)
mysql> insert into Tmp values (1);
Query OK, 1 row affected (0.00 sec)

mysql> insert into Tmp values (2);
Query OK, 1 row affected (0.00 sec)

mysql> insert into Tmp values (3);
Query OK, 1 row affected (0.01 sec)

mysql> insert into Tmp values (4);
Query OK, 1 row affected (0.00 sec)

mysql> insert into Tmp values (5);
Query OK, 1 row affected (0.00 sec)

mysql> select * from Tmp;
+------+
| ID   |
+------+
|    1 |
|    2 |
|    3 |
|    4 |
|    5 |
+------+
5 rows in set (0.00 sec)

Then open another ssh session, and kill the mysql client

 kill -9 23725

Server will crash with the following entry in the error log.

120328 19:14:06 [Warning] Aborted connection 21 to db: 'PlayGround' user: 'leo' host: 'localhost' (Got an error reading communication packets)
120328 19:14:06InnoDB: unknown error code 56 while dropping table:120328 19:14:06 [Warning] Invalid (old?) table or database name '#sql5c35_15_0'
`tmp`.<result 2 when explaining filename '#sql5c35_15_0'>.
120328 19:14:06  InnoDB: Assertion failure in thread 139983234729728 in file trx0trx.cc line 714
InnoDB: Failing assertion: ib_vector_is_empty(trx->lock.table_locks)
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.6/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
120328 19:14:06 - 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=524288
read_buffer_size=524288
max_used_connections=13
max_threads=2000
thread_count=12
connection_count=11
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 2072605 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x88916b0
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 = 0x7f5062fafe50 thread_stack 0x40000
/usr/local/mysql/bin/mysqld(my_print_stacktrace+0x39)[0x860379]
/usr/local/mysql/bin/mysqld(handle_segfault+0x3c7)[0x559097]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x10060)[0x7f519199a060]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x35)[0x7f51906373a5]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x17b)[0x7f519063ab0b]
/usr/local/mysql/bin/mysqld[0x96917d]
/usr/local/mysql/bin/mysqld[0x96a87c]
/usr/local/mysql/bin/mysqld[0x930d1e]
/usr/local/mysql/bin/mysqld[0x8c4bd2]
/usr/local/mysql/bin/mysqld(_Z18rm_temporary_tableP10handlertonPc+0xe4)[0x653b14]
/usr/local/mysql/bin/mysqld(_Z15close_temporaryP5TABLEbb+0xaa)[0x65472a]
/usr/local/mysql/bin/mysqld(_Z22close_temporary_tablesP3THD+0x5fc)[0x656fac]
/usr/local/mysql/bin/mysqld(_ZN3THD7cleanupEv+0x88)[0x66d8f8]
/usr/local/mysql/bin/mysqld(_Z10unlink_thdP3THD+0x20)[0x55be10]
/usr/local/mysql/bin/mysqld(_Z29one_thread_per_connection_endP3THDb+0x23)[0x55bec3]
/usr/local/mysql/bin/mysqld(_Z24do_handle_one_connectionP3THD+0x127)[0x671a87]
/usr/local/mysql/bin/mysqld(handle_one_connection+0x45)[0x671b55]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x7efc)[0x7f5191991efc]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7f51906e459d]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query ((nil)): is an invalid pointer
Connection ID (thread ID): 21
Status: KILL_CONNECTION

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.
120328 19:14:06 mysqld_safe Number of processes running now: 0
120328 19:14:06 mysqld_safe mysqld restarted
120328 19:14:06 [Note] Plugin 'FEDERATED' is disabled.
120328 19:14:06 InnoDB: The InnoDB memory heap is disabled
120328 19:14:06 InnoDB: Mutexes and rw_locks use GCC atomic builtins
120328 19:14:06 InnoDB: Compressed tables use zlib 1.2.3
120328 19:14:06 InnoDB: Using Linux native AIO
120328 19:14:06 InnoDB: CPU supports crc32 instructions
120328 19:14:06 InnoDB: Initializing buffer pool, size = 4.0G
120328 19:14:06 InnoDB: Completed initialization of buffer pool
120328 19:14:06 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!
120328 19:14:06  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...
InnoDB: Last MySQL binlog file position 0 10629, file name /mysqlc/mysqld_data/log/DB12-bin.000053
InnoDB: Error: trying to load index GEN_CLUST_INDEX for table tmp/#sql16f3_4d67_1c
InnoDB: but the index tree has been freed!
InnoDB: Error: trying to load index GEN_CLUST_INDEX for table tmp/#sql53d8_15c6_2a
InnoDB: but the index tree has been freed!
InnoDB: We removed now the InnoDB internal data dictionary entry
InnoDB: of table 120328 19:14:07 [Warning] Invalid (old?) table or database name '#sql5c35_15_0'
"tmp".<result 2 when explaining filename '#sql5c35_15_0'>.
120328 19:14:07 InnoDB: 128 rollback segment(s) are active.
120328 19:14:07 InnoDB: Waiting for the background threads to start
120328 19:14:08 InnoDB: 1.2.4 started; log sequence number 43058008080
120328 19:14:08 [Note] Recovering after a crash using /mysqlc/mysqld_data/log/DB12-bin
120328 19:14:08 [Note] Starting crash recovery...
120328 19:14:08 [Note] Crash recovery finished.
120328 19:14:08 [ERROR] /usr/local/mysql/bin/mysqld: Table './mysql/event' is marked as crashed and should be repaired
120328 19:14:08 [Warning] Checking table:   './mysql/event'
120328 19:14:08 [ERROR] 1 client is using or hasn't closed the table properly
120328 19:14:08 [Note] Event Scheduler: Loaded 3 events
120328 19:14:08 [Note] /usr/local/mysql/bin/mysqld: ready for connections.
Version: '5.6.4-m7-log'  socket: '/tmp/mysql.sock'  port: 3306  MySQL Community Server (GPL)
120328 19:14:08 [Note] Event Scheduler: scheduler thread started with id 1
[16 Apr 2012 18:23] Sveta Smirnova
Leo,

thank you for the test case. I can not repeat described behavior with version 5.6.5. Please try with this current version and if problem still exists provide your configuration file.
[17 May 2012 1:00] Bugs System
No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".