 data loss and log stop correlation
I believe we have found the correlation between the data loss and the log problems but have not yet found the root cause. I believe data is being lost from the database because the logs are not being written after 4:02AM, specifically the innodb log file.
I am guessing that when mysql restarts and finds the data in the database does not match the data in the innodb log file (because we have ceased writing to it), it rolls back the database. I am deducing this from this mysql_error.log message:
090605 06:32:19 mysqld started
InnoDB: The log sequence number in ibdata files does not match
InnoDB: the log sequence number in the ib_logfiles!
090605 6:32:20 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...
090605 6:32:23 InnoDB: Started; log sequence number 0 19382319
090605 6:32:23 [Note] /opt/zimbra/mysql/libexec/mysqld: ready for connections.
Version: '5.0.67-log' socket: '/opt/zimbra/db/mysql.sock' port: 7306 Source distribution
090605 6:53:05 [Note] /opt/zimbra/mysql/libexec/mysqld: Normal shutdown
This is after recovering the database and waiting for another 4:02 to pass. Our challenge is still to find out why logging stops and stops only for zimbra. All other logging is working fine past 4:02 AM.
Would it be the case that mysql would roll back to 4:02AM if the innodb log contained no data later than 4:02?
We have not verified that innodb is not updated after 4:02 as we just put these issues together. We'll verify that in the morning. 4:02 is the exact time the cron.daily jobs start. Any clues as to why our logging stops at 4:02AM and stays disabled until Zimbra is restarted? Thanks - John |