MySQL Bugs: #39304: mysql stopped working

Bug #39304	mysql stopped working
Submitted:	8 Sep 2008 9:26	Modified:	17 Sep 2008 15:35
Reporter:	Ole Albers	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S1 (Critical)
Version:	5.0.67-1	OS:	Linux (Debian Linux 4.0)
Assigned to:		CPU Architecture:	Any
Tags:	crash, daemon, recovery, start

Description:
Suddenly my mysql stopped working. I user an automated apt-get so that *might* be a reason for that. I just did a apt-get update to get the newest avaylable version.

When I try to start the daemon I get the following message:

s15219803:/etc/mysql# mysqld
080908  9:14:23  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...
080908  9:14:23  InnoDB: Starting log scan based on checkpoint at
InnoDB: log sequence number 0 750517461.
InnoDB: Doing recovery: scanned up to log sequence number 0 750528132
InnoDB: Transaction 0 1152262 was in the XA prepared state.
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 0 row operations to undo
InnoDB: Trx id counter is 0 1152768
080908  9:14:23  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 16 17 18 19 20 21 22 23 24 25 26 27 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
InnoDB: Last MySQL binlog file position 0 597983, file name /var/log/mysql/mysql-bin.000218
080908  9:14:23  InnoDB: Started; log sequence number 0 750528132
080908  9:14:23  InnoDB: Starting recovery for XA transactions...
080908  9:14:23  InnoDB: Transaction 0 1152262 in prepared state after recovery
080908  9:14:23  InnoDB: Transaction contains changes to 1 rows
080908  9:14:23  InnoDB: 1 transactions in prepared state after recovery
080908  9:14:23 [Note] Found 1 prepared transaction(s) in InnoDB
InnoDB: Starting in background the rollback of uncommitted transactions
080908  9:14:23  InnoDB: Rollback of non-prepared transactions completed
InnoDB: Error: trying to access page number 809772508 in space 0,
InnoDB: space name ./ibdata1,
InnoDB: which is outside the tablespace bounds.
InnoDB: Byte offset 0, len 16384, i/o type 10.
InnoDB: If you get this error at mysqld startup, please check that
InnoDB: your my.cnf matches the ibdata files that you have in the
InnoDB: MySQL server.
080908  9:14:23InnoDB: Assertion failure in thread 3083983520 in file fil0fil.c line 3959
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.0/en/forcing-recovery.html
InnoDB: about forcing recovery.
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=0
read_buffer_size=131072
max_used_connections=0
max_connections=100
threads_connected=0
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_connections = 217599 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd=(nil)
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...
Cannot determine thread, fp=0xbfffcb9c, backtrace may not be correct.
Stack range sanity check OK, backtrace follows:
0x81c06b9
0x83aa961
0x83885a5
0x8388bb5
0x837c667
0x83a3f05
0x83a44bf
0x83616c7
0x8373dd4
0x8372a12
0x8369b23
0x8309ecf
0x836b566
0x836b9ee
0x827c708
0x826f82f
0x81bf80e
0x81c2d85
0xb7d32ea8
0x8139de1
New value of fp=(nil) failed sanity check, terminating stack trace!
Please read http://dev.mysql.com/doc/mysql/en/using-stack-trace.html and follow instructions on how to resolve the stack trace. Resolved
stack trace is much more helpful in diagnosing the problem, so please do
resolve it
The manual page at http://www.mysql.com/doc/en/Crashing.html contains
information that should help you find out what is causing the crash.

Any clue?

How to repeat:
(try to) start daemon

Thank you for the report.

But version 5.0.32 is old and many bugs were fixed since. Please upgrade to current version 5.0.67, try with it and inform us if problem still exists.

Thanks for your fast response. 

Just updated mysql from 5.0.67-1 deb-packages. Same issue still there

Please, send your my.cnf and the results of

ls -l 

in the data directory. I want to compare sizes of the InnoDB data files.

Listing of Data Directory

Attachment: datadir.txt (text/plain), 970 bytes.

Files are attached

I managed to restart my DBMS with the parameter "innodb_force_recovery=3".
After that it starts that way:

[code]s15219803:/var/lib/mysql/makikoblog# mysqld
080911 12:46:50  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...
080911 12:46:50  InnoDB: Starting log scan based on checkpoint at
InnoDB: log sequence number 0 750517461.
InnoDB: Doing recovery: scanned up to log sequence number 0 750528132
InnoDB: Transaction 0 1152262 was in the XA prepared state.
InnoDB: Since innodb_force_recovery > 0, we will rollback it anyway.
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 1 row operations to undo
InnoDB: Trx id counter is 0 1152768
080911 12:46:50  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 16 17 18 19 20 21 22 23 24 25 26 27 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
InnoDB: Last MySQL binlog file position 0 597983, file name /var/log/mysql/mysql-bin.000218
080911 12:46:51  InnoDB: Started; log sequence number 0 750528132
InnoDB: !!! innodb_force_recovery is set to 3 !!!
080911 12:46:51 [Warning] Found an entry in the 'db' table with empty database name; Skipped
080911 12:46:51 [Note] mysqld: ready for connections.
Version: '5.0.32-Debian_7etch6-log'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  Debian etch distribution[/code]

After that a lot of messages that kind appeared:
[code][ERROR] mysqld: Table './blog/wp_useronline' is marked as crashed and should be repaired[/code]

mysqlcheck did not find any errors, myisamchk told me it repaired some tables, but i still cannot start my deamon without the "innodb_force_recovery"-Parameter.

Output of myisamchk for one table was:
[code]recovering (with sort) MyISAM-table 'wp_wassup.MYI'
Data records: 36331
- Fixing index 1
Wrong bytesec:   0-  0-  0 at    9936032; Skipped
- Fixing index 2
- Fixing index 3
- Fixing index 4
- Fixing index 5
[/code]

any hints?

with "innodb_force_recovery=4" I can even work quite normally on my DB. But that surely is not typical "going live"-parameter, right?

So I finally try to backup the Database(s) as complete as possible but get an Error when running mysqldump:

mysqldump: Couldn't execute 'SELECT /*!40001 SQL_NO_CACHE */ * FROM `g2_AccessMap`': Incorrect key file for table 'g2_AccessMap'; try to repair it (1034)

Repair does not work as it is an InnoDB-Table. When I try to drop the primary key of that table the mysql-daemon crashes:

InnoDB: Error: trying to access page number 809772508 in space 0,
InnoDB: space name ./ibdata1,
InnoDB: which is outside the tablespace bounds.
InnoDB: Byte offset 0, len 16384, i/o type 10.
InnoDB: If you get this error at mysqld startup, please check that
InnoDB: your my.cnf matches the ibdata files that you have in the
InnoDB: MySQL server.
080917 14:02:09InnoDB: Assertion failure in thread 2974735280 in file fil0fil.c line 3959
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.0/en/forcing-recovery.html
InnoDB: about forcing recovery.
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=4
max_connections=100
threads_connected=2
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_connections = 233983 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd=0x8b59828
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...
Cannot determine thread, fp=0xb14e936c, backtrace may not be correct.
Stack range sanity check OK, backtrace follows:
0x81c06b9
0x83aa961
0x83885a5
0x8388bb5
0x837c667
0x83a3f05
0x83a44bf
0x83616c7
0x8373dd4
0x8372a12
0x83735d1
0x8309ea6
0x8320e41
0x827a4f1
0x826e9be
0x829065b
0x829636e
0x81d8509
0x81dbdf7
0x81dc2b0
0x81dd578
0x81ddf84
0xb7faf0bd
0xb7dea01e
New value of fp=(nil) failed sanity check, terminating stack trace!
Please read http://dev.mysql.com/doc/mysql/en/using-stack-trace.html and follow instructions on how to resolve the stack trace. Resolved
stack trace is much more helpful in diagnosing the problem, so please do
resolve it
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort...
thd->query at 0x8b4dca0 = ALTER TABLE `g2_AccessMap` DROP PRIMARY KEY
thd->thread_id=36
The manual page at http://www.mysql.com/doc/en/Crashing.html contains
information that should help you find out what is causing the crash.

Anyone still listening?

OK. Backuped the few working DBs, created a new datadir an restored from older backup. So problem is solved for me now. Hopefully it won't crash again