MySQL Bugs: #35641: Accidental rsync of data directory caused innodb data loss, but not myisam

Bug #35641	Accidental rsync of data directory caused innodb data loss, but not myisam
Submitted:	28 Mar 2008 13:04	Modified:	11 May 2008 18:08
Reporter:	Basil Revelas	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S4 (Feature request)
Version:	5.0.27	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	innodb, rsync, running, server

Description:
This is purely an observation of how InnoDB behaved compared to MyISAM after I accidentally corrupted a mysql data directory, so please don't take this the wrong way. At most, this is a feature request for behavior which is only needed if someone does something as stupid as I did.

I rsync'ed the data directory of a shut-down mysql instance into the data directory of a running mysql server. Both data directories were pretty much identical prior to the rsync. Six days after the rsync, the running server was restarted. When it came up again, all data that had been committed to InnoDB tables was lost. Data in the MyISAM tables (which luckily was the bulk of it) managed to survive.

Here is a snip from the server log over the restart:

080327 10:53:35 [Note] /usr/libexec/mysqld: Normal shutdown

080327 10:53:35 InnoDB: Starting shutdown...
080327 10:53:38 InnoDB: Shutdown completed; log sequence number 0 102547116
080327 10:53:38 [Note] /usr/libexec/mysqld: Shutdown complete

080327 10:53:38 mysqld ended

080327 11:03:49 mysqld started
080327 11:03:50 InnoDB: Started; log sequence number 0 101960840
080327 11:03:50 [Note] /usr/libexec/mysqld: ready for connections.

I noticed that the log sequence number that the server started up on (101960840) was lower than the sequence that it shut down on (102547116). The 101960840 startup log sequence is actually the shutdown log sequence number of the data directory that was rsynced.

How to repeat:
You need two MySQL servers with identical (or close to identical) data directories. Shut down the one, and then rsync its the data directory with the data directory of the running mysql server. Run a few inserts on the running mysql server. On restart, this data will have been lost if it was inserted into an InnoDB table.

Suggested fix:
As I said before, the accidental rsync was a stupid mistake and my suggestion for a 'fix' is simply a recommendation for a possible enhancement.

However, it might be worthwhile adding some sort of check to InnoDB that would spot this sort of inconsistency. There was no sign from the server that anything was wrong, i.e. all inserts were completing successfully. Even in a corrupted or inconsistent data directory, I don't think inserts should succeed if they're going to disappear later.

Many thanks for writing a feature request.

MySQL 5.0.27 is very old. Please could you test it with newer version. Our newest version is MySQL 5.0.51a.

Let us now if you still get these problems with newer version or if all will work fine there.

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

Sorry for the delay in submitting this feedback. I just tested the scenario I originally described with MySQL 5.0.51a. It does in fact appear that InnoDB now checks for this inconsistency and preserves the data. Too bad I wasn't using the latest version when I corrupted my data directory!

For anyone interested, this is what now appears in the logs:

InnoDB: ##########################################################
InnoDB: WARNING!
InnoDB: The log sequence number in ibdata files is higher
InnoDB: than the log sequence number in the ib_logfiles! Are you sure
InnoDB: you are using the right ib_logfiles to start up the database?
InnoDB: Log sequence number in ib_logfiles is 0 45395, log
InnoDB: sequence numbers stamped to ibdata file headers are between
InnoDB: 0 45624 and 0 45624.
InnoDB: ##########################################################
InnoDB: The log sequence number in ibdata files does not match
InnoDB: the log sequence number in the ib_logfiles!
080511 20:56:11 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...
080511 20:56:11 InnoDB: Error: page 5 log sequence number 0 45405
InnoDB: is in the future! Current system log sequence number 0 45395.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: http://dev.mysql.com/doc/refman/5.0/en/forcing-recovery.html
InnoDB: for more information.
080511 20:56:11 InnoDB: Error: page 45 log sequence number 0 45624
InnoDB: is in the future! Current system log sequence number 0 45395.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: http://dev.mysql.com/doc/refman/5.0/en/forcing-recovery.html
InnoDB: for more information.
080511 20:56:12 InnoDB: Started; log sequence number 0 45395
080511 20:56:12 [Note] /home/basil/download/mysql-5.0.51a-linux-i686-glibc23/bin/mysqld: ready for connections.
Version: '5.0.51a' socket: '/tmp/mysql.sock' port: 3306 MySQL Community Server (GPL)

Thanks,
Basil