Mailbox service will not start

[lecrucious]

Zimbra went hard-down when we had a power outage today. After power was restored server was powered back on.

Mailbox service starts then crashes shortly after including HTTP(s) interface. I have been through a number of logs including:

/var/log/zimbra.log
/opt/zimbra/log/sql_error.log
/opt/zimbra/log/zmmailboxd.out

The only one to provide a hit of a problem is /opt/zimbra/log/mailbox.log


2011-12-15 14:13:15,552 INFO [main] [] soap - Servlet SoapServlet starting up
2011-12-15 14:13:15,582 INFO [main] [] soap - Adding service AccountService to SoapServlet
2011-12-15 14:13:15,653 INFO [main] [] soap - Adding service MailService to SoapServlet
2011-12-15 14:13:15,768 INFO [main] [] soap - Adding service IMService to SoapServlet
2011-12-15 14:13:15,776 INFO [main] [] misc - version=7.1.3_GA_3346 release=20110928134610 builddate=20110928-1350 buildhost=zre-ubuntu10-64
2011-12-15 14:13:15,777 INFO [main] [] misc - LANG environment is set to: en_US.UTF-8
2011-12-15 14:13:15,777 INFO [main] [] misc - System property java.home=/opt/zimbra/jdk1.6.0_26/jre
2011-12-15 14:13:15,777 INFO [main] [] misc - System property java.runtime.version=1.6.0_26-b03
2011-12-15 14:13:15,778 INFO [main] [] misc - System property java.version=1.6.0_26
2011-12-15 14:13:15,778 INFO [main] [] misc - System property java.vm.info=mixed mode
2011-12-15 14:13:15,778 INFO [main] [] misc - System property java.vm.name=Java HotSpot(TM) 64-Bit Server VM
2011-12-15 14:13:15,778 INFO [main] [] misc - System property java.vm.version=20.1-b02
2011-12-15 14:13:15,778 INFO [main] [] misc - System property os.arch=amd64
2011-12-15 14:13:15,778 INFO [main] [] misc - System property os.name=Linux
2011-12-15 14:13:15,778 INFO [main] [] misc - System property os.version=2.6.32-35-server
2011-12-15 14:13:15,778 INFO [main] [] misc - System property sun.arch.data.model=64
2011-12-15 14:13:15,778 INFO [main] [] misc - System property sun.cpu.endian=little
2011-12-15 14:13:15,778 INFO [main] [] misc - System property sun.cpu.isalist=
2011-12-15 14:13:15,778 INFO [main] [] misc - System property sun.os.patch.level=unknown
2011-12-15 14:13:15,796 INFO [main] [] system - Setting mysql connector property: maxActive=100
2011-12-15 14:13:15,804 INFO [main] [] system - Setting mysql connector property: maxActive=100
2011-12-15 14:13:16,904 INFO [main] [] sqltrace - Setting slow SQL threshold to 2000ms.
2011-12-15 14:13:18,727 INFO [main] [] ZimbraHttpConnectionManager - Starting http client idle connection reaper thread for Internal http client connection$
2011-12-15 14:13:18,728 INFO [main] [] ZimbraHttpConnectionManager - Starting http client idle connection reaper thread for External http client connection$
2011-12-15 14:13:18,742 INFO [IncomingDirectorySweeper] [] store - IncomingDirectorySweeper thread starting
2011-12-15 14:13:18,750 INFO [main] [] FileDescriptorCache - Loading settings: zimbraMailFileDescriptorCacheSize=1000.
2011-12-15 14:13:18,761 INFO [main] [] extensions - Loading extensions from /opt/zimbra/lib/ext
2011-12-15 14:13:18,762 INFO [main] [] extensions - extension com.zimbra.cs.nginx.NginxLookupExtension found in /opt/zimbra/lib/ext/nginx-lookup/nginx-look$
2011-12-15 14:13:18,762 INFO [main] [] extensions - extension com.zimbra.ldaputils.ZimbraLDAPUtilsExtension found in /opt/zimbra/lib/ext/zimbraldaputils/zi$
2011-12-15 14:13:18,763 INFO [main] [] extensions - extension com.zimbra.cert.ZimbraCertMgrExt found in /opt/zimbra/lib/ext/com_zimbra_cert_manager/com_zim$
2011-12-15 14:13:18,763 INFO [main] [] extensions - extension com.zimbra.bp.ZimbraBulkProvisionExt found in /opt/zimbra/lib/ext/com_zimbra_bulkprovision/co$
2011-12-15 14:13:18,763 INFO [main] [] extensions - extension com.zimbra.cs.versioncheck.VersionCheckExtension found in /opt/zimbra/lib/ext/zimbraadminvers$
2011-12-15 14:13:18,764 INFO [main] [] extensions - extension com.zimbra.clam.ClamScanner found in /opt/zimbra/lib/ext/clamscanner/clamscanner.jar
2011-12-15 14:13:18,764 INFO [main] [] extensions - Initializing extensions
2011-12-15 14:13:18,772 INFO [main] [] extensions - registered handler at /nginx-lookup
2011-12-15 14:13:18,773 INFO [main] [] extensions - Initialized extension nginx-lookup: com.zimbra.cs.nginx.NginxLookupExten...s.extension.Zi$
2011-12-15 14:13:18,777 INFO [main] [] extensions - Initialized extension zimbrasamba: com.zimbra.ldaputils.ZimbraLDAPUtils...mbra.cs.extensio$
2011-12-15 14:13:18,782 INFO [main] [] extensions - Initialized extension com_zimbra_cert_manager: com.zimbra.cert.ZimbraCertMgrExt@com.zimbra.cs.ext ension$
2011-12-15 14:13:18,792 INFO [main] [] extensions - Initialized extension com_zimbra_bulkprovision: com.zimbra.bp.ZimbraBulkProvisionExt...mbra.cs .exte$
2011-12-15 14:13:18,796 INFO [main] [] extensions - Initialized extension versioncheck: com.zimbra.cs.versioncheck.VersionCh...zimbra.cs.exte$
2011-12-15 14:13:18,799 INFO [main] [] ClamScanner - attachment scan is disabled

2011-12-15 14:13:18,799 INFO [main] [] extensions - Initialized extension clamscanner: com.zimbra.clam.ClamScanner@com.zimb...nsio n.ZimbraExtensionC$
2011-12-15 14:13:18,814 INFO [IndexReadersCache-Sweeper] [] IndexReadersCache - IndexReadersCache-Sweeper thread starting
2011-12-15 14:13:18,824 INFO [main] [] redolog - Starting pre-startup crash recovery
2011-12-15 14:13:19,494 FATAL [main] [] redolog - Exception during crash recovery
2011-12-15 14:13:19,494 FATAL [main] [] system - Aborting process
java.lang.NullPointerException
at com.zimbra.cs.mailbox.calendar.Invite.decodeMetada ta(Invite.java:743)
at com.zimbra.cs.redolog.op.CreateInvite.deserializeD ata(CreateInvite.java:121)
at com.zimbra.cs.redolog.op.RedoableOp.deserialize(Re doableOp.java:470)
at com.zimbra.cs.redolog.op.RedoableOp.deserializeOp( RedoableOp.java:587)
at com.zimbra.cs.redolog.op.RedoableOp.deserializeOp( RedoableOp.java:540)
at com.zimbra.cs.redolog.logger.FileLogReader.getNext Op(FileLogReader.java:96)
at com.zimbra.cs.redolog.RedoPlayer.scanLog(RedoPlaye r.java:122)
at com.zimbra.cs.redolog.RedoPlayer.runCrashRecovery( RedoPlayer.java:388)
at com.zimbra.cs.redolog.RedoLogManager.start(RedoLog Manager.java:229)
at com.zimbra.cs.redolog.DefaultRedoLogProvider.start up(DefaultRedoLogProvider.java:41)
at com.zimbra.cs.util.Zimbra.startup(Zimbra.java:215)
at com.zimbra.cs.util.Zimbra.startup(Zimbra.java:123)
at com.zimbra.soap.SoapServlet.init(SoapServlet.java: 128)
at javax.servlet.GenericServlet.init(GenericServlet.j ava:241)
at org.mortbay.jetty.servlet.ServletHolder.initServle t(ServletHolder.java:440)
at org.mortbay.jetty.servlet.ServletHolder.doStart(Se rvletHolder.java:263)
at org.mortbay.component.AbstractLifeCycle.start(Abst ractLifeCycle.java:50)
at org.mortbay.jetty.servlet.ServletHandler.initializ e(ServletHandler.java:685)
at org.mortbay.jetty.servlet.Context.startContext(Con text.java:140)
at org.mortbay.jetty.webapp.WebAppContext.startContex t(WebAppContext.java:1254)
at org.mortbay.jetty.handler.ContextHandler.doStart(C ontextHandler.java:517)
at org.mortbay.jetty.webapp.WebAppContext.doStart(Web AppContext.java:471)
at org.mortbay.component.AbstractLifeCycle.start(Abst ractLifeCycle.java:50)

at org.mortbay.component.AbstractLifeCycle.start(Abst ractLifeCycle.java:50)
at org.mortbay.jetty.handler.HandlerCollection.doStar t(HandlerCollection.java:152)
at org.mortbay.jetty.handler.ContextHandlerCollection .doStart(ContextHandlerCollection.java:156)
at org.mortbay.component.AbstractLifeCycle.start(Abst ractLifeCycle.java:50)
at org.mortbay.jetty.handler.HandlerCollection.doStar t(HandlerCollection.java:152)
at org.mortbay.component.AbstractLifeCycle.start(Abst ractLifeCycle.java:50)
at org.mortbay.jetty.handler.HandlerWrapper.doStart(H andlerWrapper.java:130)
at org.mortbay.component.AbstractLifeCycle.start(Abst ractLifeCycle.java:50)
at org.mortbay.jetty.handler.HandlerWrapper.doStart(H andlerWrapper.java:130)
at org.mortbay.jetty.handler.DebugHandler.doStart(Deb ugHandler.java:127)
at org.mortbay.component.AbstractLifeCycle.start(Abst ractLifeCycle.java:50)
at org.mortbay.jetty.handler.HandlerWrapper.doStart(H andlerWrapper.java:130)
at org.mortbay.jetty.Server.doStart(Server.java:224)
at org.mortbay.setuid.SetUIDServer.doStart(SetUIDServ er.java:158)
at org.mortbay.component.AbstractLifeCycle.start(Abst ractLifeCycle.java:50)
at org.mortbay.xml.XmlConfiguration.main(XmlConfigura tion.java:985)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Nativ e Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(Native MethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(De legatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.mortbay.start.Main.invokeMain(Main.java:194)
at org.mortbay.start.Main.start(Main.java:534)
at org.mortbay.start.Main.start(Main.java:441)
at org.mortbay.start.Main.main(Main.java:119)


Thanks in advance for the assistance.

[vavai]

mailbox failed to start usually related to MySQL problem, CMIIW. Are you sure there was nothing problem with MySQL?

What is zmcontrol status report?

[lecrucious]

I think you are right as the log seems to indicate a problem with playing back the redo log. I have added a few entries from the mysql_error.log. Unless I am reading it wrong it says everything was fine.


InnoDB: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Compressed tables use zlib 1.2.3.3
111215 14:12:09 InnoDB: Initializing buffer pool, size = 602.0M
111215 14:12:09 InnoDB: Completed initialization of buffer pool
111215 14:12:09 InnoDB: highest supported file format is Barracuda.
111215 14:12:09 InnoDB Plugin 1.0.17 started; log sequence number 7882017
111215 14:12:09 [Note] Event Scheduler: Loaded 0 events
111215 14:12:09 [Note] /opt/zimbra/mysql/libexec/mysqld: ready for connections.
Version: '5.1.58-log' socket: '/opt/zimbra/db/mysql.sock' port: 7306 Source distribution
111215 15:34:35 [Note] /opt/zimbra/mysql/libexec/mysqld: Normal shutdown

111215 15:34:35 [Note] Event Scheduler: Purging the queue. 0 events
111215 15:34:35 InnoDB: Starting shutdown...
111215 15:34:39 InnoDB: Shutdown completed; log sequence number 7882027
111215 15:34:39 [Note] /opt/zimbra/mysql/libexec/mysqld: Shutdown complete

111215 15:34:39 mysqld_safe mysqld from pid file /opt/zimbra/db/mysql.pid ended
111215 15:35:43 mysqld_safe Starting mysqld daemon with databases from /opt/zimbra/db/data
InnoDB: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Compressed tables use zlib 1.2.3.3
111215 15:35:43 InnoDB: Initializing buffer pool, size = 602.0M
111215 15:35:43 InnoDB: Completed initialization of buffer pool
111215 15:35:43 InnoDB: highest supported file format is Barracuda.
111215 15:35:44 InnoDB Plugin 1.0.17 started; log sequence number 7882027
111215 15:35:44 [Note] Event Scheduler: Loaded 0 events
111215 15:35:44 [Note] /opt/zimbra/mysql/libexec/mysqld: ready for connections.
Version: '5.1.58-log' socket: '/opt/zimbra/db/mysql.sock' port: 7306 Source distribution



My biggest problem with this was I didn't care if I lost the one or two messages I just needed to get mail back online.

I say was because I fixed it. Once I realize how the product works I was able to bypass this problem. I found a ZImbra wiki explaining Redo logs as follows:

Each Zimbra server generates redo logs that contain every transaction processed by that server. If an unexpected shutdown occurs to the server, the redo logs are used for the following:
•
To ensure that no uncommitted transactions remain, the server rereads the redo logs upon startup.

I then found the redo log at /opt/zimbra/redolog/redo.log. As zimbra user renames the log file to redo.log.old and created a new empty redo.log. This fixed the problem.