Mysql – InnoDB “log sequence in the future!” crashing, won’t start

innodbMySQL

I stopped mysql only to find that it wouldn't come back up, /etc/init.d/mysql start only outputs . . . . . . failed. I've narrowed it down to an issue with InnoDB. The database starts when innodb_force_recovery = 5 and nothing lower. When I "check table" for my MyISAM tables, they check fine, but the connection is dropped when I attempt to do so for my InnoDB tables with force_recovery set. mysql.err and mysql.log are empty.

Here are the relevant logs from syslog when I attempt to start with innodb_force_recovery set to zero:

Nov  6 04:20:33 kevmo314 mysqld: 111106  4:20:33  InnoDB: Error: page 245802 log sequence number 61 3499737721
Nov  6 04:20:33 kevmo314 mysqld: InnoDB: is in the future! Current system log sequence number 0 8204.
Nov  6 04:20:33 kevmo314 mysqld: InnoDB: Your database may be corrupt or you may have copied the InnoDB
Nov  6 04:20:33 kevmo314 mysqld: InnoDB: tablespace but not the InnoDB log files. See
Nov  6 04:20:33 kevmo314 mysqld: InnoDB: http://dev.mysql.com/doc/refman/5.1/en/forcing-recovery.html
Nov  6 04:20:33 kevmo314 mysqld: InnoDB: for more information.
Nov  6 04:20:33 kevmo314 mysqld: 111106  4:20:33  InnoDB: Error: page 245788 log sequence number 61 3499737613
Nov  6 04:20:33 kevmo314 mysqld: InnoDB: is in the future! Current system log sequence number 0 8204.
Nov  6 04:20:33 kevmo314 mysqld: InnoDB: Your database may be corrupt or you may have copied the InnoDB
Nov  6 04:20:33 kevmo314 mysqld: InnoDB: tablespace but not the InnoDB log files. See
Nov  6 04:20:33 kevmo314 mysqld: InnoDB: http://dev.mysql.com/doc/refman/5.1/en/forcing-recovery.html
Nov  6 04:20:33 kevmo314 mysqld: InnoDB: for more information.
Nov  6 04:20:33 kevmo314 mysqld: 111106  4:20:33  InnoDB: Error: page 245816 log sequence number 61 3180676464
Nov  6 04:20:33 kevmo314 mysqld: InnoDB: is in the future! Current system log sequence number 0 8204.
Nov  6 04:20:33 kevmo314 mysqld: InnoDB: Your database may be corrupt or you may have copied the InnoDB
Nov  6 04:20:33 kevmo314 mysqld: InnoDB: tablespace but not the InnoDB log files. See
Nov  6 04:20:33 kevmo314 mysqld: InnoDB: http://dev.mysql.com/doc/refman/5.1/en/forcing-recovery.html
Nov  6 04:20:33 kevmo314 mysqld: InnoDB: for more information.
Nov  6 04:20:33 kevmo314 mysqld: 111106  4:20:33  InnoDB: Error: page 327684 log sequence number 61 3587218257
Nov  6 04:20:33 kevmo314 mysqld: InnoDB: is in the future! Current system log sequence number 0 8204.
Nov  6 04:20:33 kevmo314 mysqld: InnoDB: Your database may be corrupt or you may have copied the InnoDB
Nov  6 04:20:33 kevmo314 mysqld: InnoDB: tablespace but not the InnoDB log files. See
Nov  6 04:20:33 kevmo314 mysqld: InnoDB: http://dev.mysql.com/doc/refman/5.1/en/forcing-recovery.html
Nov  6 04:20:33 kevmo314 mysqld: InnoDB: for more information.
Nov  6 04:20:33 kevmo314 mysqld: 111106  4:20:33  InnoDB: Error: page 8 log sequence number 5 3253003088
Nov  6 04:20:33 kevmo314 mysqld: InnoDB: is in the future! Current system log sequence number 0 8204.
Nov  6 04:20:33 kevmo314 mysqld: InnoDB: Your database may be corrupt or you may have copied the InnoDB
Nov  6 04:20:33 kevmo314 mysqld: InnoDB: tablespace but not the InnoDB log files. See
Nov  6 04:20:33 kevmo314 mysqld: InnoDB: http://dev.mysql.com/doc/refman/5.1/en/forcing-recovery.html
Nov  6 04:20:33 kevmo314 mysqld: InnoDB: for more information.
Nov  6 04:20:33 kevmo314 mysqld: 111106  4:20:33  InnoDB: Error: page 0 log sequence number 61 3590235012
Nov  6 04:20:33 kevmo314 mysqld: InnoDB: is in the future! Current system log sequence number 0 8204.
Nov  6 04:20:33 kevmo314 mysqld: InnoDB: Your database may be corrupt or you may have copied the InnoDB
Nov  6 04:20:33 kevmo314 mysqld: InnoDB: tablespace but not the InnoDB log files. See
Nov  6 04:20:33 kevmo314 mysqld: InnoDB: http://dev.mysql.com/doc/refman/5.1/en/forcing-recovery.html
Nov  6 04:20:33 kevmo314 mysqld: InnoDB: for more information.
Nov  6 04:20:33 kevmo314 mysqld: 111106  4:20:33  InnoDB: Error: page 10 log sequence number 5 3253004335
Nov  6 04:20:33 kevmo314 mysqld: InnoDB: is in the future! Current system log sequence number 0 8204.
Nov  6 04:20:33 kevmo314 mysqld: InnoDB: Your database may be corrupt or you may have copied the InnoDB
Nov  6 04:20:33 kevmo314 mysqld: InnoDB: tablespace but not the InnoDB log files. See
Nov  6 04:20:33 kevmo314 mysqld: InnoDB: http://dev.mysql.com/doc/refman/5.1/en/forcing-recovery.html
Nov  6 04:20:33 kevmo314 mysqld: InnoDB: for more information.
Nov  6 04:20:33 kevmo314 mysqld: 111106  4:20:33  InnoDB: Error: page 9 log sequence number 5 3253003136
Nov  6 04:20:33 kevmo314 mysqld: InnoDB: is in the future! Current system log sequence number 0 8204.
Nov  6 04:20:33 kevmo314 mysqld: InnoDB: Your database may be corrupt or you may have copied the InnoDB
Nov  6 04:20:33 kevmo314 mysqld: InnoDB: tablespace but not the InnoDB log files. See
Nov  6 04:20:33 kevmo314 mysqld: InnoDB: http://dev.mysql.com/doc/refman/5.1/en/forcing-recovery.html
Nov  6 04:20:33 kevmo314 mysqld: InnoDB: for more information.
Nov  6 04:20:36 kevmo314 kernel: [ 6553.720679] ata3.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0
Nov  6 04:20:36 kevmo314 kernel: [ 6553.720708] ata3.00: BMDMA stat 0x24
Nov  6 04:20:36 kevmo314 kernel: [ 6553.720728] ata3.00: failed command: READ DMA
Nov  6 04:20:36 kevmo314 kernel: [ 6553.720752] ata3.00: cmd c8/00:08:60:d5:89/00:00:00:00:00/e2 tag 0 dma 4096 in
Nov  6 04:20:36 kevmo314 kernel: [ 6553.720753]          res 51/40:00:61:d5:89/00:00:00:00:00/02 Emask 0x9 (media error)
Nov  6 04:20:36 kevmo314 kernel: [ 6553.720828] ata3.00: status: { DRDY ERR }
Nov  6 04:20:36 kevmo314 kernel: [ 6553.720848] ata3.00: error: { UNC }
Nov  6 04:20:36 kevmo314 kernel: [ 6553.940262] ata3.00: configured for UDMA/133
Nov  6 04:20:36 kevmo314 kernel: [ 6553.940274] ata3: EH complete
Nov  6 04:20:39 kevmo314 kernel: [ 6556.860948] ata3.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0
Nov  6 04:20:39 kevmo314 kernel: [ 6556.860977] ata3.00: BMDMA stat 0x24
Nov  6 04:20:39 kevmo314 kernel: [ 6556.860998] ata3.00: failed command: READ DMA
Nov  6 04:20:39 kevmo314 kernel: [ 6556.861021] ata3.00: cmd c8/00:08:60:d5:89/00:00:00:00:00/e2 tag 0 dma 4096 in
Nov  6 04:20:39 kevmo314 kernel: [ 6556.861022]          res 51/40:00:61:d5:89/00:00:00:00:00/02 Emask 0x9 (media error)
Nov  6 04:20:39 kevmo314 kernel: [ 6556.861097] ata3.00: status: { DRDY ERR }
Nov  6 04:20:39 kevmo314 kernel: [ 6556.861118] ata3.00: error: { UNC }
Nov  6 04:20:39 kevmo314 kernel: [ 6557.080548] ata3.00: configured for UDMA/133
Nov  6 04:20:39 kevmo314 kernel: [ 6557.080565] ata3: EH complete
Nov  6 04:20:42 kevmo314 kernel: [ 6560.025988] ata3.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0
Nov  6 04:20:42 kevmo314 kernel: [ 6560.026017] ata3.00: BMDMA stat 0x24
Nov  6 04:20:42 kevmo314 kernel: [ 6560.026038] ata3.00: failed command: READ DMA
Nov  6 04:20:42 kevmo314 kernel: [ 6560.026061] ata3.00: cmd c8/00:08:60:d5:89/00:00:00:00:00/e2 tag 0 dma 4096 in
Nov  6 04:20:42 kevmo314 kernel: [ 6560.026062]          res 51/40:00:61:d5:89/00:00:00:00:00/02 Emask 0x9 (media error)
Nov  6 04:20:42 kevmo314 kernel: [ 6560.026137] ata3.00: status: { DRDY ERR }
Nov  6 04:20:42 kevmo314 kernel: [ 6560.026158] ata3.00: error: { UNC }
Nov  6 04:20:42 kevmo314 kernel: [ 6560.245443] ata3.00: configured for UDMA/133
Nov  6 04:20:42 kevmo314 kernel: [ 6560.245458] ata3: EH complete
Nov  6 04:20:45 kevmo314 kernel: [ 6563.232517] ata3.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0
Nov  6 04:20:45 kevmo314 kernel: [ 6563.232545] ata3.00: BMDMA stat 0x24
Nov  6 04:20:45 kevmo314 kernel: [ 6563.232566] ata3.00: failed command: READ DMA
Nov  6 04:20:45 kevmo314 kernel: [ 6563.232590] ata3.00: cmd c8/00:08:60:d5:89/00:00:00:00:00/e2 tag 0 dma 4096 in
Nov  6 04:20:45 kevmo314 kernel: [ 6563.232591]          res 51/40:00:61:d5:89/00:00:00:00:00/02 Emask 0x9 (media error)
Nov  6 04:20:45 kevmo314 kernel: [ 6563.232666] ata3.00: status: { DRDY ERR }
Nov  6 04:20:45 kevmo314 kernel: [ 6563.232686] ata3.00: error: { UNC }
Nov  6 04:20:46 kevmo314 kernel: [ 6563.469023] ata3.00: configured for UDMA/133
Nov  6 04:20:46 kevmo314 kernel: [ 6563.469039] ata3: EH complete
Nov  6 04:20:46 kevmo314 /etc/init.d/mysql[11095]: 0 processes alive and '/usr/bin/mysqladmin --defaults-file=/etc/mysql/debian.cnf ping' resulted in
Nov  6 04:20:46 kevmo314 /etc/init.d/mysql[11095]: #007/usr/bin/mysqladmin: connect to server at 'localhost' failed
Nov  6 04:20:46 kevmo314 /etc/init.d/mysql[11095]: error: 'Can't connect to local MySQL server through socket '/var/run/mysqld/mysqld.sock' (2)'
Nov  6 04:20:46 kevmo314 /etc/init.d/mysql[11095]: Check that mysqld is running and that the socket: '/var/run/mysqld/mysqld.sock' exists!
Nov  6 04:20:46 kevmo314 /etc/init.d/mysql[11095]:
Nov  6 04:20:49 kevmo314 kernel: [ 6566.439445] ata3.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0
Nov  6 04:20:49 kevmo314 kernel: [ 6566.439473] ata3.00: BMDMA stat 0x24
Nov  6 04:20:49 kevmo314 kernel: [ 6566.439494] ata3.00: failed command: READ DMA
Nov  6 04:20:49 kevmo314 kernel: [ 6566.439518] ata3.00: cmd c8/00:08:60:d5:89/00:00:00:00:00/e2 tag 0 dma 4096 in
Nov  6 04:20:49 kevmo314 kernel: [ 6566.439519]          res 51/40:00:61:d5:89/00:00:00:00:00/02 Emask 0x9 (media error)
Nov  6 04:20:49 kevmo314 kernel: [ 6566.439594] ata3.00: status: { DRDY ERR }
Nov  6 04:20:49 kevmo314 kernel: [ 6566.439614] ata3.00: error: { UNC }
Nov  6 04:20:49 kevmo314 kernel: [ 6566.667239] ata3.00: configured for UDMA/133
Nov  6 04:20:49 kevmo314 kernel: [ 6566.667253] ata3: EH complete
Nov  6 04:20:52 kevmo314 kernel: [ 6569.637871] ata3.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0
Nov  6 04:20:52 kevmo314 kernel: [ 6569.637901] ata3.00: BMDMA stat 0x24
Nov  6 04:20:52 kevmo314 kernel: [ 6569.637924] ata3.00: failed command: READ DMA
Nov  6 04:20:52 kevmo314 kernel: [ 6569.637949] ata3.00: cmd c8/00:08:60:d5:89/00:00:00:00:00/e2 tag 0 dma 4096 in
Nov  6 04:20:52 kevmo314 kernel: [ 6569.637951]          res 51/40:00:61:d5:89/00:00:00:00:00/02 Emask 0x9 (media error)
Nov  6 04:20:52 kevmo314 kernel: [ 6569.639649] ata3.00: status: { DRDY ERR }
Nov  6 04:20:52 kevmo314 kernel: [ 6569.639687] ata3.00: error: { UNC }
Nov  6 04:20:52 kevmo314 mysqld: InnoDB: Error: tried to read 786432 bytes at offset 0 196608.
Nov  6 04:20:52 kevmo314 mysqld: InnoDB: Was only able to read 364544.
Nov  6 04:20:52 kevmo314 mysqld: 111106  4:20:52  InnoDB: Operating system error number 0 in a file operation.
Nov  6 04:20:52 kevmo314 mysqld: InnoDB: Error number 0 means 'Success'.
Nov  6 04:20:52 kevmo314 mysqld: InnoDB: Some operating system error numbers are described at
Nov  6 04:20:52 kevmo314 mysqld: InnoDB: http://dev.mysql.com/doc/refman/5.1/en/operating-system-error-codes.html
Nov  6 04:20:52 kevmo314 mysqld: InnoDB: File operation call: 'read'.
Nov  6 04:20:52 kevmo314 mysqld: InnoDB: Cannot continue operation.
Nov  6 04:20:52 kevmo314 kernel: [ 6569.857513] ata3.00: configured for UDMA/133
Nov  6 04:20:52 kevmo314 kernel: [ 6569.857525] sd 2:0:0:0: [sda] Unhandled sense code
Nov  6 04:20:52 kevmo314 kernel: [ 6569.857526] sd 2:0:0:0: [sda] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
Nov  6 04:20:52 kevmo314 kernel: [ 6569.857529] sd 2:0:0:0: [sda] Sense Key : Medium Error [current] [descriptor]
Nov  6 04:20:52 kevmo314 kernel: [ 6569.857532] Descriptor sense data with sense descriptors (in hex):
Nov  6 04:20:52 kevmo314 kernel: [ 6569.857534]         72 03 11 04 00 00 00 0c 00 0a 80 00 00 00 00 00
Nov  6 04:20:52 kevmo314 kernel: [ 6569.857539]         02 89 d5 61
Nov  6 04:20:52 kevmo314 kernel: [ 6569.857542] sd 2:0:0:0: [sda] Add. Sense: Unrecovered read error - auto reallocate failed
Nov  6 04:20:52 kevmo314 kernel: [ 6569.857546] sd 2:0:0:0: [sda] CDB: Read(10): 28 00 02 89 d5 60 00 00 08 00
Nov  6 04:20:52 kevmo314 kernel: [ 6569.857551] end_request: I/O error, dev sda, sector 42587489
Nov  6 04:20:52 kevmo314 kernel: [ 6569.857590] ata3: EH complete
Nov  6 04:20:52 kevmo314 mysqld_safe: mysqld from pid file /var/run/mysqld/mysqld.pid ended

Here's my my.cnf file:

#
# The MySQL database server configuration file.
#
# You can copy this to one of:
# - "/etc/mysql/my.cnf" to set global options,
# - "~/.my.cnf" to set user-specific options.
#
# One can use all long options that the program supports.
# Run program with --help to get a list of available options and with
# --print-defaults to see which it would actually understand and use.
#
# For explanations see
# http://dev.mysql.com/doc/mysql/en/server-system-variables.html

# This will be passed to all mysql clients
# It has been reported that passwords should be enclosed with ticks/quotes
# escpecially if they contain "#" chars...
# Remember to edit /etc/mysql/debian.cnf when changing the socket location.
[client]
port            = 3306
socket          = /var/run/mysqld/mysqld.sock

# Here is entries for some specific programs
# The following values assume you have at least 32M ram

# This was formally known as [safe_mysqld]. Both versions are currently parsed.
[mysqld_safe]
socket          = /var/run/mysqld/mysqld.sock
nice            = 0

[mysqld]
#
# * Basic Settings
#
user            = mysql
pid-file        = /var/run/mysqld/mysqld.pid
socket          = /var/run/mysqld/mysqld.sock
port            = 3306
basedir         = /usr
datadir         = /var/lib/mysql
tmpdir          = /tmp
language        = /usr/share/mysql/english
skip-external-locking
#
# Instead of skip-networking the default is now to listen only on
# localhost which is more compatible and is not less secure.
#bind-address           = 127.0.0.1
#
# * Fine Tuning
#
key_buffer              = 256M
join_buffer_size        = 4M
max_allowed_packet      = 32M
myisam_sort_buffer_size = 128M
sort_buffer_size        = 4M
read_buffer_size        = 4M
read_rnd_buffer_size    = 4M
thread_stack            = 192K
thread_cache_size       = 8
# This replaces the startup script and checks MyISAM tables if needed
# the first time they are touched
myisam-recover         = BACKUP
#max_connections        = 100
#table_cache            = 64
#thread_concurrency     = 10
#
# * Query Cache Configuration
#
query_cache_limit       = 1M
query_cache_size        = 64M
#
# * Logging and Replication
#
# Both location gets rotated by the cronjob.
# Be aware that this log type is a performance killer.
# As of 5.1 you can enable the log at runtime!
#general_log_file        = /var/log/mysql/mysql.log
#general_log             = 1
#
# Error logging goes to syslog due to /etc/mysql/conf.d/mysqld_safe_syslog.cnf.
#
# Here you can see queries with especially long duration
#log_slow_queries       = /var/log/mysql/mysql-slow.log
#long_query_time = 2
#log-queries-not-using-indexes
#
# The following can be used as easy to replay backup logs or for replication.
# note: if you are setting up a replication slave, see README.Debian about
#       other settings you may need to change.
#server-id              = 1
#log_bin                        = /var/log/mysql/mysql-bin.log
expire_logs_days        = 10
max_binlog_size         = 100M
#binlog_do_db           = include_database_name
#binlog_ignore_db       = include_database_name
#
# * InnoDB
#
# InnoDB is enabled by default with a 10MB datafile in /var/lib/mysql/.
# Read the manual for more InnoDB related options. There are many!
#
# * Security Features
#
# Read the manual, too, if you want chroot!
# chroot = /var/lib/mysql/
#
# For generating SSL certificates I recommend the OpenSSL GUI "tinyca".
#
# ssl-ca=/etc/mysql/cacert.pem
# ssl-cert=/etc/mysql/server-cert.pem
# ssl-key=/etc/mysql/server-key.pem
innodb_buffer_pool_size = 3G

[mysqldump]
quick
quote-names
max_allowed_packet      = 16M

[mysql]
#no-auto-rehash # faster start of mysql but no tab completition

[isamchk]
key_buffer              = 256M
sort_buffer             = 256M
read_buffer             = 64M
write_buffer            = 64M

#
# * IMPORTANT: Additional settings that can override those from this file!
#   The files must end with '.cnf', otherwise they'll be ignored.
#
!includedir /etc/mysql/conf.d/

As an aside, mysqldump crashes as well. I'm running on Debian Squeeze as well and can provide any more logs if needed.

Best Answer

try move somewhere your ib_logfile0 and ib_logfile1 in your filesystem, and then start mysql server. It will create new logfiles, and propably it will work, because I didn't seen 'innodb_fast_shutdown' in your my.cnf, and you said the server was stopped properly.

Related Topic