Results 1 to 2 of 2

Thread: Mailbox service will not start

  1. #1
    lecrucious is offline Starter Member
    Join Date
    Dec 2011
    Posts
    2
    Rep Power
    3

    Default Mailbox service will not start

    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.

  2. #2
    lecrucious is offline Starter Member
    Join Date
    Dec 2011
    Posts
    2
    Rep Power
    3

    Default

    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.

Thread Information

Users Browsing this Thread

There are currently 1 users browsing this thread. (0 members and 1 guests)

Similar Threads

  1. The installer was interrupted...
    By spiderbo in forum Zimbra Connector for Outlook
    Replies: 9
    Last Post: 05-23-2013, 06:33 AM
  2. Replies: 9
    Last Post: 10-11-2011, 05:43 AM
  3. can't you help me
    By iwan siahaan in forum Administrators
    Replies: 6
    Last Post: 12-17-2007, 06:53 PM
  4. After reboot mailbox and tomcat don't start
    By gon in forum Administrators
    Replies: 1
    Last Post: 11-02-2007, 11:50 AM
  5. Is it started or not
    By kwelipatton in forum Installation
    Replies: 10
    Last Post: 03-28-2006, 11:11 PM

Posting Permissions

  • You may not post new threads
  • You may not post replies
  • You may not post attachments
  • You may not edit your posts
  •