Bug #46140 Innodb log files deleted or not found after crash
Submitted: 12 Jul 2009 21:25 Modified: 14 Jul 2009 0:00
Reporter: Bassam Tabbara Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S1 (Critical)
Version:5.1.34 OS:Linux (Debian 5.0 lenny)
Assigned to: CPU Architecture:Any

[12 Jul 2009 21:25] Bassam Tabbara
Description:
We experienced a crash in mysql while performing a SELECT statement. What was really odd is the ib_logfiles appear to have disappeared or have been ignored when the server was restarted. New log files were created. This left our database in a corrupted state, and we were unable to recover from this. We had to resort to a backup.

The log file was as follows:
090712  1:16:41 - mysqld got signal 11 ;
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=131072
max_used_connections=28
max_threads=151
threads_connected=8
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 346497 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd: 0x2aac0c014160
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 = 0x45250100 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x29) [0x8abb99]
/usr/sbin/mysqld(handle_segfault+0x34b) [0x5f841b]
/lib/libpthread.so.0 [0x2aaaaacd6a80]
/usr/sbin/mysqld(btr_search_guess_on_hash+0x264) [0x78a1a4]
/usr/sbin/mysqld(btr_cur_search_to_nth_level+0xa99) [0x7871e9]
/usr/sbin/mysqld(row_search_for_mysql+0xc19) [0x8086b9]
/usr/sbin/mysqld(ha_innobase::index_read(unsigned char*, unsigned char const*, unsigned int, ha_rkey_function)+0x195) [0x778d65]
/usr/sbin/mysqld [0x657118]
/usr/sbin/mysqld(sub_select(JOIN*, st_join_table*, bool)+0x6b) [0x6562ab]
/usr/sbin/mysqld [0x650185]
/usr/sbin/mysqld(sub_select(JOIN*, st_join_table*, bool)+0x96) [0x6562d6]
/usr/sbin/mysqld [0x6592fd]
/usr/sbin/mysqld(JOIN::exec()+0x969) [0x66e279]
/usr/sbin/mysqld(subselect_single_select_engine::exec()+0x36c) [0x5b9dcc]
/usr/sbin/mysqld(Item_subselect::exec()+0x26) [0x5b8856]
/usr/sbin/mysqld(Item_singlerow_subselect::val_int()+0xd) [0x5b8acd]
/usr/sbin/mysqld(Item_func_case::val_int()+0x70) [0x58c120]
/usr/sbin/mysqld(Item::send(Protocol*, String*)+0x1fd) [0x550f8d]
/usr/sbin/mysqld(select_send::send_data(List<Item>&)+0x111) [0x5ea141]
/usr/sbin/mysqld [0x64e191]
/usr/sbin/mysqld [0x6593e2]
/usr/sbin/mysqld(JOIN::exec()+0x969) [0x66e279]
/usr/sbin/mysqld(mysql_select(THD*, Item***, TABLE_LIST*, unsigned int, List<Item>&, Item*, unsigned int, st_order*, st_order*,
Item*, st_order*, unsigned long long, select_result*, st_select_lex_unit*, st_select_lex*)+0x124) [0x66a0c4]
/usr/sbin/mysqld(handle_select(THD*, st_lex*, select_result*, unsigned long)+0x16c) [0x66fc2c]
/usr/sbin/mysqld [0x6044ec]
/usr/sbin/mysqld(mysql_execute_command(THD*)+0x3b60) [0x609930]
/usr/sbin/mysqld(mysql_parse(THD*, char const*, unsigned int, char const**)+0x210) [0x60b800]
/usr/sbin/mysqld(dispatch_command(enum_server_command, THD*, char*, unsigned int)+0xc6f) [0x60c48f]
/usr/sbin/mysqld(do_command(THD*)+0xe8) [0x60ce18]
/usr/sbin/mysqld(handle_one_connection+0x21e) [0x6007ae]
/lib/libpthread.so.0 [0x2aaaaaccefc7]
/lib/libc.so.6(clone+0x6d) [0x2aaaac1cf5ad]
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort...
thd->query at 0xcd61060 = SELECT [snip]
thd->thread_id=805
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.
090712 01:16:43 mysqld_safe Number of processes running now: 0
090712 01:16:43 mysqld_safe mysqld restarted
090712  1:16:44 [Warning] The syntax '--log_slow_queries' is deprecated and will be removed in MySQL 7.0. Please use '--slow_que
ry_log'/'--slow_query_log_file' instead.
090712  1:16:45  InnoDB: Log file ./ib_logfile0 did not exist: new to be created
InnoDB: Setting log file ./ib_logfile0 size to 1281 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Progress in MB: 100 200 300 400 500 600 700 800 900 1000 1100 1200
090712  1:17:11  InnoDB: Log file ./ib_logfile1 did not exist: new to be created
InnoDB: Setting log file ./ib_logfile1 size to 1281 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Progress in MB: 100 200 300 400 500 600 700 800 900 1000 1100 1200
InnoDB: The log sequence number in ibdata files does not match
InnoDB: the log sequence number in the ib_logfiles!

Note the "ib_logfile0 did not exist" after restart.

How to repeat:
Not sure how this can be repeated.
[13 Jul 2009 8:57] Sveta Smirnova
Thank you for the report.

Please provide output of `ls -la DATADIR`
[13 Jul 2009 19:57] Bassam Tabbara
And note that the mysql log files have been deleted again.

Here is the config file we are using that is pointed to from /etc/mysql/conf.d:

[mysqld]
bind-address = 0.0.0.0
thread_stack = 256K
datadir = /vol/lib/mysql
log_slow_queries = /vol/log/mysql/mysql-slow.log
long_query_time = 3
default-storage-engine=innodb
event-scheduler=ON
innodb_buffer_pool_size = 5124M
innodb_additional_mem_pool_size = 20M
innodb_log_file_size = 1281M
innodb_log_buffer_size = 16M
innodb_flush_log_at_trx_commit=1
[14 Jul 2009 0:00] Bassam Tabbara
Sorry for the false alarm. I found the culprit script that was mistakenly deleted the log files. I still don't know, however, how mysql was running fine without them.