tomcat crash: mailbox - Unable to commit database transaction. Forcing server to abo

[kyle]

Hi All,

Sorry if this has been posted before, I've spent the better part of 3 hours searching for anything relating to this problem in the wiki and the forum.

At about 5:00 cst last night my server went down under a very quick power outage. When it came back up, everything seemed fine, but I get the following error message in /opt/zimbra/log/mailbox.log when trying to restart 'mailbox' with zmmailboxctl start:

2007-06-21 09:07:08,933 INFO  [NOTIFY-7035-Server] [] misc - starting server loop
2007-06-21 09:07:09,069 INFO  [LmtpServer] [] TcpServer/7025 - starting accept loop
2007-06-21 09:07:09,110 INFO  [PostStartupCrashRecovery] [] cache - Initializing folder and tag caches for mailbox 5
2007-06-21 09:07:09,374 INFO  [Pop3Server] [] TcpServer/995 - starting accept loop
2007-06-21 09:07:09,467 FATAL [PostStartupCrashRecovery] [] mailbox - Unable to commit database transaction.  Forcing server to abort.
com.zimbra.common.service.ServiceException: system failure: committing database transaction
        at com.zimbra.common.service.ServiceException.FAILURE(ServiceException.java:175)
        at com.zimbra.cs.db.DbPool$Connection.commit(DbPool.java:162)
        at com.zimbra.cs.mailbox.Mailbox.endTransaction(Mailbox.java:5024)
        at com.zimbra.cs.mailbox.Mailbox.getConfig(Mailbox.java:941)
        at com.zimbra.cs.mailbox.Mailbox.(Mailbox.java:386)
        at com.zimbra.cs.mailbox.MailboxManager.instantiateMailbox(MailboxManager.java:355)
        at com.zimbra.cs.mailbox.MailboxManager.getMailboxById(MailboxManager.java:306)
        at com.zimbra.cs.mailbox.MailboxManager.getMailboxById(MailboxManager.java:239)
        at com.zimbra.cs.redolog.op.IndexItem.redo(IndexItem.java:99)
        at com.zimbra.cs.redolog.RedoLogManager$PostStartupCrashRecoveryThread.run(RedoLogManager.java:291)
Caused by: com.mysql.jdbc.exceptions.MySQLNonTransientConnectionException: Communications link failure during commit(). Transaction resolution unknown.
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:888)
        at com.mysql.jdbc.Connection.commit(Connection.java:2246)
        at org.apache.commons.dbcp.DelegatingConnection.commit(DelegatingConnection.java:248)
        at org.apache.commons.dbcp.PoolingDataSource$PoolGuardConnectionWrapper.commit(PoolingDataSource.java:244)
        at com.zimbra.cs.db.DbPool$Connection.commit(DbPool.java:160)
        ... 8 more
2007-06-21 09:07:09,484 INFO  [ImapServer] [] TcpServer/143 - starting accept loop
2007-06-21 09:07:09,492 INFO  [ImapSSLServer] [] TcpServer/993 - starting accept loop

I'm at my witt's end. I'd appreciate any help I can get.

TIA

Kyle Hall

[phoenix]

What operating system and filesystem are you using?

Are you also having any hard drive problems?

[kyle]

The machine is running Fedora Core 5. I started having this issue with zimbra 4.5.3 (open source) but upgraded to 4.5.5 hoping it would resolve the issue. The filesystem is ext3

[phoenix]

I'm afraid I edited my last post just as you were posting. I added the question: are you having any HD problems as well?

Is this on a RAID setup? Have you rebooted this server? Is this a production server?

[kyle]

The machine is not set up for raid and fsck comes up clean. It's set up with the default LVMs from a standard fedora install.

[phoenix]

Have you rebooted the server yet? If not, do so. Are there any other errors in the log apart from this?

[kyle]

I've just rebooted now (as well as multiple times before) with no change. There are no other error messages that I can find. The previous error message remained the same after reboot.

[kyle]

Also, I should point out that up until this power outage, this installation had been performing flawlessly for months.

[kyle]

OK, after digging around, it looks like tomcat is quitting when it attempts to read or write from the mysql database mboxgroup5/mail_item (the error message from MySQL InnoDB is below). I'm guessing that this table may have been corrupted during the power outage. Any ideas as to how I would go about restoring this table?

070622 11:52:03  InnoDB: Started; log sequence number 0 92293929
070622 11:52:03 [Note] /opt/zimbra/mysql/libexec/mysqld: ready for connections.
Version: '5.0.33-log'  socket: '/opt/zimbra/db/mysql.sock'  port: 7306  Source distribution
InnoDB: Database page corruption on disk or a failed
InnoDB: file read of page 55.
InnoDB: You may have to recover from a backup.
070622 11:52:18  InnoDB: Page dump in ascii and hex (16384 bytes):
 len 16384; hex 6b679bfb00000037ffffffff0000035400000000057fc48745bf000000 [snip]
070622 11:52:18  InnoDB: Page checksum 1801952251, prior-to-4.0.14-form checksum 2219588811
InnoDB: stored checksum 1801952251, prior-to-4.0.14-form stored checksum 44941139
InnoDB: Page lsn 0 92259463, low 4 bytes of lsn at page end 92292521
InnoDB: Page number (if stored to page already) 55,
InnoDB: space id (if created with >= MySQL-4.1.1 and stored already) 36
InnoDB: Page may be an index page where index id is 0 130
InnoDB: (index i_folder_id_date of table mboxgroup5/mail_item)
InnoDB: Database page corruption on disk or a failed
InnoDB: file read of page 55.
InnoDB: You may have to recover from a backup.
InnoDB: It is also possible that your operating
InnoDB: system has corrupted its own file cache
InnoDB: and rebooting your computer removes the
InnoDB: error.
InnoDB: If the corrupt page is an index page
InnoDB: you can also try to fix the corruption
InnoDB: by dumping, dropping, and reimporting
InnoDB: the corrupt table. You can use CHECK
InnoDB: TABLE to scan your table for corruption.
InnoDB: See also InnoDB: http://dev.mysql.com/doc/refman/5.0/en/forcing-recovery.html
InnoDB: about forcing recovery.
InnoDB: Ending processing because of a corrupt database page.

Number of processes running now: 0
070622 11:52:18  mysqld restarted
070622 11:52:18  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...
070622 11:52:18  InnoDB: Starting log scan based on checkpoint at
InnoDB: log sequence number 0 92293939.
InnoDB: Doing recovery: scanned up to log sequence number 0 92293949
070622 11:52:19  InnoDB: Started; log sequence number 0 92293949
070622 11:52:19 [Note] /opt/zimbra/mysql/libexec/mysqld: ready for connections.
Version: '5.0.33-log'  socket: '/opt/zimbra/db/mysql.sock'  port: 7306  Source distribution

[kyle]

OK, I've resolved the issue by adding innodb_force_recovery = 1 to my.cnf and restarting.