[SOLVED] Mailbox won't start after power outage

[ajm716]

I'm running FOSS version 5.0.6 on Ubuntu 8.04 and we had a power outage last night. This morning, the server was running, but mail delivery was broken. I couldn't access the either web interface (user or administrative).

I found a few forum threads describing similar problems, but nothing suggested in them has fixed my problem.

I did find an entry in /opt/zimbra/logger/db/data/mail.err indicating corruption on a table - I repaired the table using the mysql console (just the REPAIR TABLE command). Here's the log entry for that:

080711  8:51:36 [ERROR] /opt/zimbra/logger/mysql/libexec/mysqld: Table './zimbra_logger/raw_logs' is marked as crashed and should be repaired
080711  8:51:42 [Note] Found 233 of 247 rows when repairing './zimbra_logger/raw_logs'

I've tried toggling innodb_force_recover=3 in my.cnf (& stopping & restarting mysql/zimbra on changes) & that didn't fix the problem.

The output from `zmcontrol status`:

zimbra@mail:~$ zmcontrol status
Host mail.union.k12.ga.us
        antispam                Running
        antivirus               Running
        ldap                    Running
        logger                  Running
        mailbox                 Stopped
                zmmailboxdctl is not running
        mta                     Running
        snmp                    Running
        spell                   Running
        stats                   Running

Here's the last portion of /opt/zimbra/log/mailbox.log:

2008-07-11 12:34:27,482 INFO  [IndexWritersSweeperThread] [] index - IndexWritersSweeperThread thread starting
2008-07-11 12:34:27,482 INFO  [IndexReadersCache-Sweeper] [] IndexReadersCache - IndexReadersCache-Sweeper thread starting
2008-07-11 12:34:27,515 INFO  [main] [] RedoLogManager - Starting pre-startup crash recovery
2008-07-11 12:34:27,564 INFO  [main] [] RedoPlayer - Redoing 1 uncommitted transactions
2008-07-11 12:34:27,565 INFO  [main] [] RedoPlayer - Deferring crash recovery to after startup: txn 1215793563.316 [IndexItem] ver=1.22, tstamp=1215793597223, mailbox=116, id=601, type=5
2008-07-11 12:34:27,592 INFO  [main] [] RedoLogManager - Finished pre-startup crash recovery
2008-07-11 12:34:27,644 INFO  [PostStartupCrashRecovery] [] RedoLogManager - Starting post-startup crash recovery
2008-07-11 12:34:27,644 INFO  [PostStartupCrashRecovery] [] RedoLogManager - REDOING: txn 1215793563.316 [IndexItem] ver=1.22, tstamp=1215793597223, mailbox=116, id=601, type=5
2008-07-11 12:34:27,695 INFO  [main] [] im - Setting default XMPP domain to: union.k12.ga.us
2008-07-11 12:34:28,046 INFO  [PostStartupCrashRecovery] [] MailboxIndex - Initialized Index for mailbox 116 directory: Lucene23Index at com.zimbra.cs.index.Z23FSDirectory@/opt/zimbra/index/0/116/index/0 Analyzer=com.zimbra.cs.index.ZimbraAnalyzer@181b3d4
2008-07-11 12:34:28,047 INFO  [PostStartupCrashRecovery] [] cache - Initializing folder and tag caches for mailbox 116
2008-07-11 12:34:28,328 INFO  [IncomingDirectorySweeper] [] FileBlobStore - IncomingDirectorySweeper thread starting
2008-07-11 12:34:28,510 INFO  [PostStartupCrashRecovery] [] JMSession - SMTP Server: mail.union.k12.ga.us
2008-07-11 12:34:29,180 INFO  [PostStartupCrashRecovery] [] zimlet - Loaded class com.zimbra.cs.zimlet.handler.NANPHandler
2008-07-11 12:34:29,212 INFO  [PostStartupCrashRecovery] [] zimlet - Loaded class com.zimbra.cs.zimlet.handler.RegexHandler
2008-07-11 12:34:29,564 FATAL [PostStartupCrashRecovery] [] system - Unable to commit database transaction.  Forcing server to abort.
com.zimbra.common.service.ServiceException: system failure: committing database transaction
ExceptionId:PostStartupCrashRecovery:1215794069562:f8c9e03db48d6af5
Code:service.FAILURE
    at com.zimbra.common.service.ServiceException.FAILURE(ServiceException.java:253)
    at com.zimbra.cs.db.DbPool$Connection.commit(DbPool.java:144)
    at com.zimbra.cs.mailbox.Mailbox.endTransaction(Mailbox.java:6728)
    at com.zimbra.cs.mailbox.Mailbox.reanalyze(Mailbox.java:1862)
    at com.zimbra.cs.mailbox.Message.generateIndexData(Message.java:547)
    at com.zimbra.cs.redolog.op.IndexItem.redo(IndexItem.java:109)
    at com.zimbra.cs.redolog.RedoLogManager$PostStartupCrashRecoveryThread.run(RedoLogManager.java:306)
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:142)
    ... 5 more

If anyone has any help to offer, I would greatly appreciate it.

Thanks.

[praveen25]

hi did u find any solution for this error message i am also having the same, please share your thoughts if u have already sorted out.

[mcevoys]

Perhaps you could copy your /opt/* directory to a safe place, then try an in-place upgrade install.

That has put things right for me during a previous issue.

[ajm716]

It turns out the problem was corruption in the MySQL database. The database would start, but update/drop commits would cause the database connection to drop & restart. I verified this by logging in to the zimbra database & manually executing queries. I was able to execute insert & select queries, but if I tried to delete a record I had just inserted, the query would fail with the following error message: mysql error: Lost connection to MySQL server during query.

I believe the system would have run normally until someone did something that caused a update/delete on an affected table, but the redoplayer was running a purge command on startup, crashing the database.

I backed up all the data in the zimbra/mboxgroup* databases using mysqldump, then I attempted to drop the databases using SQL commands - the drop commands failed with the same mysql error: Lost connection to MySQL server during query error. So I shut down the database & renamed the /opt/zimbra/db/data/ibdata & ib_logfile* files & deleted the /opt/zimbra/db/data/mboxgroup* & zimbra directories.

I then started the MySQL server & batched in the zimbra & mboxgroup databases. I started zimbra back up & everything was back to normal.

So it seems it was entirely a MySQL issue.

Note: Before I started poking around in the system, I shut down zimbra & backed up the entire /opt/zimbra directory, and I shut down zimbra before I did anything with the database.

Also, I attempted several different database repair techniques before I manually deleted the database files.