MySQL Bugs: #52609: InnoDB: Assertion failure leading to crash

Bug #52609	InnoDB: Assertion failure leading to crash
Submitted:	5 Apr 2010 23:55	Modified:	24 May 2010 17:52
Reporter:	Sean Jenkins	Email Updates:
Status:	Can't repeat	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S1 (Critical)
Version:	5.1.45	OS:	Linux
Assigned to:		CPU Architecture:	Any
Tags:	5.1.45, assertion failure, ha_innodb.cc, innodb

Description:
MySQL crashes with assertion failure after being "Unable to find the AUTOINC column".  With Innodb recovery level set to 4+, crash doesn't happen.  This seems to be causing the opposite behavior as bug #46193.  Was not happening with 5.1.44, but started with 5.1.45.

How to repeat:
Show create table c_members without innodb recovery level set to 4+ and MySQL will crash with AUTOINC assertion failure errors.  With InnoDB recovery level 4+ set, it will not.

From /var/log/mysqd.log:

Apr  5 17:44:30 box542 mysqld: InnoDB: Unable to find the AUTOINC column member_id in the InnoDB table comeback_zenhome/c_members.
Apr  5 17:44:30 box542 mysqld: InnoDB: We set the next AUTOINC column value to 0,
Apr  5 17:44:30 box542 mysqld: InnoDB: in effect disabling the AUTOINC next value generation.
Apr  5 17:44:30 box542 mysqld: InnoDB: You can either set the next AUTOINC value explicitly using ALTER TABLE
Apr  5 17:44:30 box542 mysqld: InnoDB: or fix the data dictionary by recreating the table.
Apr  5 17:44:30 box542 mysqld: 100405 17:44:30  InnoDB: MySQL and InnoDB data dictionaries are out of sync.
Apr  5 17:44:30 box542 mysqld: InnoDB: Unable to find the AUTOINC column member_id in the InnoDB table comeback_zenhome/c_members.
Apr  5 17:44:30 box542 mysqld: InnoDB: We set the next AUTOINC column value to 0,
Apr  5 17:44:30 box542 mysqld: InnoDB: in effect disabling the AUTOINC next value generation.
Apr  5 17:44:30 box542 mysqld: InnoDB: You can either set the next AUTOINC value explicitly using ALTER TABLE
Apr  5 17:44:30 box542 mysqld: InnoDB: or fix the data dictionary by recreating the table.
Apr  5 17:44:30 box542 mysqld: 100405 17:44:30  InnoDB: Assertion failure in thread 1159784768 in file handler/ha_innodb.cc line 7938
Apr  5 17:44:30 box542 mysqld: InnoDB: Failing assertion: auto_inc > 0
Apr  5 17:44:30 box542 mysqld: InnoDB: We intentionally generate a memory trap.
Apr  5 17:44:30 box542 mysqld: InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
Apr  5 17:44:30 box542 mysqld: InnoDB: If you get repeated assertion failures or crashes, even
Apr  5 17:44:30 box542 mysqld: InnoDB: immediately after the mysqld startup, there may be
Apr  5 17:44:30 box542 mysqld: InnoDB: corruption in the InnoDB tablespace. Please refer to
Apr  5 17:44:30 box542 mysqld: InnoDB: http://dev.mysql.com/doc/refman/5.1/en/forcing-recovery.html
Apr  5 17:44:30 box542 mysqld: InnoDB: about forcing recovery.
Apr  5 17:44:30 box542 mysqld: 100405 17:44:30 - mysqld got signal 6 ;
Apr  5 17:44:30 box542 mysqld: This could be because you hit a bug. It is also possible that this binary
Apr  5 17:44:30 box542 mysqld: or one of the libraries it was linked against is corrupt, improperly built,
Apr  5 17:44:30 box542 mysqld: or misconfigured. This error can also be caused by malfunctioning hardware.
Apr  5 17:44:30 box542 mysqld: We will try our best to scrape up some info that will hopefully help diagnose
Apr  5 17:44:30 box542 mysqld: the problem, but since we have already crashed, something is definitely wrong
Apr  5 17:44:30 box542 mysqld: and this may fail.
Apr  5 17:44:30 box542 mysqld:
Apr  5 17:44:30 box542 mysqld: key_buffer_size=268435456
Apr  5 17:44:30 box542 mysqld: read_buffer_size=16777216
Apr  5 17:44:30 box542 mysqld: max_used_connections=21
Apr  5 17:44:30 box542 mysqld: max_threads=1500
Apr  5 17:44:30 box542 mysqld: threads_connected=12
Apr  5 17:44:30 box542 mysqld: It is possible that mysqld could use up to
Apr  5 17:44:30 box542 mysqld: key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 30997788 K
Apr  5 17:44:30 box542 mysqld: bytes of memory
Apr  5 17:44:30 box542 mysqld: Hope that's ok; if not, decrease some variables in the equation.
Apr  5 17:44:30 box542 mysqld:
Apr  5 17:44:30 box542 mysqld: thd: 0x7f64804d6a80
Apr  5 17:44:30 box542 mysqld: Attempting backtrace. You can use the following information to find out
Apr  5 17:44:30 box542 mysqld: where mysqld died. If you see no messages after this, something went
Apr  5 17:44:30 box542 mysqld: terribly wrong...
Apr  5 17:44:30 box542 mysqld: stack_bottom = 0x4520df40 thread_stack 0x40000
Apr  5 17:44:30 box542 mysqld: /usr/sbin/mysqld(my_print_stacktrace+0x2e)[0x85582e]
Apr  5 17:44:30 box542 mysqld: /usr/sbin/mysqld(handle_segfault+0x322)[0x5c3ae2]
Apr  5 17:44:30 box542 mysqld: /lib64/libpthread.so.0[0x3154a0e930]
Apr  5 17:44:30 box542 mysqld: /lib64/libc.so.6(gsignal+0x35)[0x3153e30265]
Apr  5 17:44:30 box542 mysqld: /lib64/libc.so.6(abort+0x110)[0x3153e31d10]
Apr  5 17:44:30 box542 mysqld: /usr/sbin/mysqld(_ZN11ha_innobase20innobase_get_autoincEPy+0x0)[0x739fc0]
Apr  5 17:44:30 box542 mysqld: /usr/sbin/mysqld(_ZN11ha_innobase4infoEj+0x1d7)[0x7402f7]
Apr  5 17:44:30 box542 mysqld: /usr/sbin/mysqld[0x6c7824]
Apr  5 17:44:30 box542 mysqld: /usr/sbin/mysqld(_Z14get_all_tablesP3THDP10TABLE_LISTP4Item+0x871)[0x6cbed1]
Apr  5 17:44:30 box542 mysqld: /usr/sbin/mysqld(_Z24get_schema_tables_resultP4JOIN23enum_schema_table_state+0x1d0)[0x6c3570]
Apr  5 17:44:30 box542 mysqld: /usr/sbin/mysqld(_ZN4JOIN4execEv+0x439)[0x63d289]
Apr  5 17:44:30 box542 mysqld: /usr/sbin/mysqld(_Z12mysql_selectP3THDPPP4ItemP10TABLE_LISTjR4ListIS1_ES2_jP8st_orderSB_S2_SB_yP13select_resultP18st_select_lex_unitP13st_select_lex+0x16e)[0x63f21e]
Apr  5 17:44:30 box542 mysqld: /usr/sbin/mysqld(_Z13handle_selectP3THDP6st_lexP13select_resultm+0x169)[0x63fb39]
Apr  5 17:44:30 box542 mysqld: /usr/sbin/mysqld[0x5cf1a4]
Apr  5 17:44:30 box542 mysqld: /usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x450)[0x5d2480]
Apr  5 17:44:30 box542 mysqld: /usr/sbin/mysqld(_Z11mysql_parseP3THDPKcjPS2_+0x90a)[0x5d821a]
Apr  5 17:44:30 box542 mysqld: /usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x100b)[0x5d952b]
Apr  5 17:44:30 box542 mysqld: /usr/sbin/mysqld(_Z10do_commandP3THD+0x136)[0x5d9b46]
Apr  5 17:44:30 box542 mysqld: /usr/sbin/mysqld(handle_one_connection+0x735)[0x5ca825]
Apr  5 17:44:30 box542 mysqld: /lib64/libpthread.so.0[0x3154a06617]
Apr  5 17:44:30 box542 mysqld: /lib64/libc.so.6(clone+0x6d)[0x3153ed3c2d]
Apr  5 17:44:30 box542 mysqld: Trying to get some variables.
Apr  5 17:44:30 box542 mysqld: Some pointers may be invalid and cause the dump to abort...
Apr  5 17:44:30 box542 mysqld: thd->query at 0x86d6b40 = show table status like 'c\_members'
Apr  5 17:44:30 box542 mysqld: thd->thread_id=2048
Apr  5 17:44:30 box542 mysqld: thd->killed=NOT_KILLED
Apr  5 17:44:30 box542 mysqld: The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
Apr  5 17:44:30 box542 mysqld: information that should help you find out what is causing the crash.
Apr  5 17:44:30 box542 mysqld_safe: Number of processes running now: 0
Apr  5 17:44:30 box542 mysqld_safe: mysqld restarted

Thank you for the report.

I can not repeat described behavior with test for bug #46193. Please provide output of SHOW CREATE TABLE c_members.

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".

Unfortunately I don't have this database anymore, as the customer whom was hosting the database, later dropped it.  However, here's another example with exactly the same behavior.  I have several hundred examples of these occurances:

mysql> use iridiumf_maadmin;
Database changed
mysql> SHOW TABLE STATUS;
ERROR 2013 (HY000): Lost connection to MySQL server during query

Then I get this:

May  7 10:51:06 box306 mysqld: 100507 10:51:06  InnoDB: MySQL and InnoDB data dictionaries are out of sync.
May  7 10:51:06 box306 mysqld: InnoDB: Unable to find the AUTOINC column file_extensions_id in the InnoDB table iridiumf_maadmin/c_file_extensions.
May  7 10:51:06 box306 mysqld: InnoDB: We set the next AUTOINC column value to 0,
May  7 10:51:06 box306 mysqld: InnoDB: in effect disabling the AUTOINC next value generation.
May  7 10:51:06 box306 mysqld: InnoDB: You can either set the next AUTOINC value explicitly using ALTER TABLE
May  7 10:51:06 box306 mysqld: InnoDB: or fix the data dictionary by recreating the table.
May  7 10:51:06 box306 mysqld: 100507 10:51:06  InnoDB: Assertion failure in thread 1100278080 in file handler/ha_innodb.cc line 7938
May  7 10:51:06 box306 mysqld: InnoDB: Failing assertion: auto_inc > 0
May  7 10:51:06 box306 mysqld: InnoDB: We intentionally generate a memory trap.
May  7 10:51:06 box306 mysqld: InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
May  7 10:51:06 box306 mysqld: InnoDB: If you get repeated assertion failures or crashes, even
May  7 10:51:06 box306 mysqld: InnoDB: immediately after the mysqld startup, there may be
May  7 10:51:06 box306 mysqld: InnoDB: corruption in the InnoDB tablespace. Please refer to
May  7 10:51:06 box306 mysqld: InnoDB: http://dev.mysql.com/doc/refman/5.1/en/forcing-recovery.html
May  7 10:51:06 box306 mysqld: InnoDB: about forcing recovery.
May  7 10:51:06 box306 mysqld: 100507 10:51:06 - mysqld got signal 6 ;
May  7 10:51:06 box306 mysqld: This could be because you hit a bug. It is also possible that this binary
May  7 10:51:06 box306 mysqld: or one of the libraries it was linked against is corrupt, improperly built,
May  7 10:51:06 box306 mysqld: or misconfigured. This error can also be caused by malfunctioning hardware.
May  7 10:51:06 box306 mysqld: We will try our best to scrape up some info that will hopefully help diagnose
May  7 10:51:06 box306 mysqld: the problem, but since we have already crashed, something is definitely wrong
May  7 10:51:06 box306 mysqld: and this may fail.
May  7 10:51:06 box306 mysqld: 
May  7 10:51:06 box306 mysqld: key_buffer_size=268435456
May  7 10:51:06 box306 mysqld: read_buffer_size=16777216
May  7 10:51:06 box306 mysqld: max_used_connections=6
May  7 10:51:06 box306 mysqld: max_threads=1500
May  7 10:51:06 box306 mysqld: threads_connected=1
May  7 10:51:06 box306 mysqld: It is possible that mysqld could use up to 
May  7 10:51:06 box306 mysqld: key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 30997788 K
May  7 10:51:06 box306 mysqld: bytes of memory
May  7 10:51:06 box306 mysqld: Hope that's ok; if not, decrease some variables in the equation.
May  7 10:51:06 box306 mysqld: 
May  7 10:51:06 box306 mysqld: thd: 0x7fac3123b690
May  7 10:51:06 box306 mysqld: Attempting backtrace. You can use the following information to find out
May  7 10:51:06 box306 mysqld: where mysqld died. If you see no messages after this, something went
May  7 10:51:06 box306 mysqld: terribly wrong...
May  7 10:51:06 box306 mysqld: stack_bottom = 0x4194df40 thread_stack 0x40000
May  7 10:51:06 box306 mysqld: /usr/sbin/mysqld(my_print_stacktrace+0x2e)[0x85582e]
May  7 10:51:06 box306 mysqld: /usr/sbin/mysqld(handle_segfault+0x322)[0x5c3ae2]
May  7 10:51:06 box306 mysqld: /lib64/libpthread.so.0[0x395b20e930]
May  7 10:51:06 box306 mysqld: /lib64/libc.so.6(gsignal+0x35)[0x395a630265]
May  7 10:51:06 box306 mysqld: /lib64/libc.so.6(abort+0x110)[0x395a631d10]
May  7 10:51:06 box306 mysqld: /usr/sbin/mysqld(_ZN11ha_innobase20innobase_get_autoincEPy+0x0)[0x739fc0]
May  7 10:51:06 box306 mysqld: /usr/sbin/mysqld(_ZN11ha_innobase4infoEj+0x1d7)[0x7402f7]
May  7 10:51:06 box306 mysqld: /usr/sbin/mysqld[0x6c7824]
May  7 10:51:06 box306 mysqld: /usr/sbin/mysqld(_Z14get_all_tablesP3THDP10TABLE_LISTP4Item+0x871)[0x6cbed1]
May  7 10:51:06 box306 mysqld: /usr/sbin/mysqld(_Z24get_schema_tables_resultP4JOIN23enum_schema_table_state+0x1d0)[0x6c3570]
May  7 10:51:06 box306 mysqld: /usr/sbin/mysqld(_ZN4JOIN4execEv+0x439)[0x63d289]
May  7 10:51:06 box306 mysqld: /usr/sbin/mysqld(_Z12mysql_selectP3THDPPP4ItemP10TABLE_LISTjR4ListIS1_ES2_jP8st_orderSB_S2_SB_yP13select_resultP18st_select_lex_unitP13st_select_lex+0x16e)[0x63f21e]
May  7 10:51:06 box306 mysqld: /usr/sbin/mysqld(_Z13handle_selectP3THDP6st_lexP13select_resultm+0x169)[0x63fb39]
May  7 10:51:06 box306 mysqld: /usr/sbin/mysqld[0x5cf1a4]
May  7 10:51:06 box306 mysqld: /usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x450)[0x5d2480]
May  7 10:51:06 box306 mysqld: /usr/sbin/mysqld(_Z11mysql_parseP3THDPKcjPS2_+0x90a)[0x5d821a]
May  7 10:51:06 box306 mysqld: /usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x100b)[0x5d952b]
May  7 10:51:06 box306 mysqld: /usr/sbin/mysqld(_Z10do_commandP3THD+0x136)[0x5d9b46]
May  7 10:51:06 box306 mysqld: /usr/sbin/mysqld(handle_one_connection+0x735)[0x5ca825]
May  7 10:51:06 box306 mysqld: /lib64/libpthread.so.0[0x395b206617]
May  7 10:51:06 box306 mysqld: /lib64/libc.so.6(clone+0x6d)[0x395a6d3c2d]
May  7 10:51:06 box306 mysqld: Trying to get some variables.
May  7 10:51:06 box306 mysqld: Some pointers may be invalid and cause the dump to abort...
May  7 10:51:06 box306 mysqld: thd->query at 0x32572f0 = SHOW TABLE STATUS
May  7 10:51:06 box306 mysqld: thd->thread_id=138
May  7 10:51:06 box306 mysqld: thd->killed=NOT_KILLED
May  7 10:51:06 box306 mysqld: The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
May  7 10:51:06 box306 mysqld: information that should help you find out what is causing the crash.
May  7 10:51:06 box306 mysqld_safe: Number of processes running now: 0
May  7 10:51:06 box306 mysqld_safe: mysqld restarted
May  7 10:51:06 box306 mysqld: 100507 10:51:06 [Warning] Changed limits: max_open_files: 65535  max_connections: 1500  table_cache: 32012
May  7 10:51:06 box306 mysqld: 100507 10:51:06 [Note] setsockopt expanded send buffer to 4194304 in socket /ramdisk/mysql/cpud_socket
May  7 10:51:06 box306 mysqld: 100507 10:51:06 [Note] Plugin 'FEDERATED' is disabled.
May  7 10:51:06 box306 mysqld: InnoDB: The log sequence number in ibdata files does not match
May  7 10:51:06 box306 mysqld: InnoDB: the log sequence number in the ib_logfiles!
May  7 10:51:06 box306 mysqld: 100507 10:51:06  InnoDB: Database was not shut down normally!
May  7 10:51:06 box306 mysqld: InnoDB: Starting crash recovery.
May  7 10:51:06 box306 mysqld: InnoDB: Reading tablespace information from the .ibd files...
May  7 10:51:07 box306 mysqld: InnoDB: Restoring possible half-written data pages from the doublewrite
May  7 10:51:07 box306 mysqld: InnoDB: buffer...
May  7 10:51:07 box306 mysqld: 100507 10:51:07  InnoDB: Started; log sequence number 15 650653663
May  7 10:51:07 box306 mysqld: 100507 10:51:07 [Warning] Found invalid password for user: 'cabrenna_cbrenn@192.168.1.%'; Ignoring user
May  7 10:51:07 box306 mysqld: 100507 10:51:07 [Warning] Found invalid password for user: 'cabrenna_cbrenn@localhost'; Ignoring user
May  7 10:51:07 box306 mysqld: 100507 10:51:07 [Note] Event Scheduler: Loaded 0 events
May  7 10:51:07 box306 mysqld: 100507 10:51:07 [Note] /usr/sbin/mysqld: ready for connections.
May  7 10:51:07 box306 mysqld: Version: '5.1.45-log'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MySQL Community Server (GPL)

`show create table c_file_extensions` or any similar request to get information beyond a "SHOW TABLES" generates the aforementioned assertion failure.  Even with 5.1.46, the same assertion failure arises.

You can go ahead and close this ticket.  I'm still looking into all the crashes, but thus far all indications point to the assertion failures being corruption in the database itself, leading to the thread termination or mysql to restart.  If I find evidence otherwise, I'll post it.

Thank you for the feedback.

Closing as "Can't repeat" because last comment.