[SOLVED] {Live System} Tomcat Fails to start, and thus wailing and gnashing of teeth

[jmensel]

Hi all. We've run into a bit of trouble with our Zimbra install. Many thanks in advance to anyone who can help me get this up and running, as we've a number of users who are clamoring for Zimbra's return!

Tomcat fails to start, and thus the admin and user pages are unavailable. Here's the background:

Tomcat was working fine yesterday. I had to stop and restart Zimbra several times while dealing with some performance issues, and tomcat stopped running.

I have executed zmfixperms -extended to tidy up permissions

lsof -i with Zimbra shut down returns no output - it isn't fighting over ports.

To ensure that imapproxy isn't running (this is a single server environment) I have run "zmperditionctl stop", "tomcat stop", "tomcat start".

Here's what zmperditionctl says:

imap4 is not running
imap4s is not running
pop3 is not running
pop3s is not running

Interesting errors in catalina.out:

SEVERE: Error starting static Resources
java.lang.IllegalArgumentException: Document base /opt/zimbra/apache-tomcat-5.5.15/server/webapps/host-manager does not exist or is not a re
adable directory

SEVERE: Error starting static Resources
java.lang.IllegalArgumentException: Document base /opt/zimbra/apache-tomcat-5.5.15/server/webapps/manager does not exist or is not a readabl
e directory

WARNING: A docBase /opt/zimbra/apache-tomcat-5.5.15/webapps/zimbra inside the host appBase has been specified, and will be ignored

log4j:WARN No appenders could be found for logger (org.apache.catalina.startup.TldConfig).
log4j:WARN Please initialize the log4j system properly.

Appended below is full startup output from catalina.out:

Apr 9, 2009 11:08:02 AM org.apache.coyote.http11.Http11BaseProtocol init
INFO: Initializing Coyote HTTP/1.1 on http-443
Apr 9, 2009 11:08:02 AM org.apache.coyote.http11.Http11BaseProtocol init
INFO: Initializing Coyote HTTP/1.1 on http-7071
Apr 9, 2009 11:08:02 AM org.apache.catalina.startup.Catalina load
INFO: Initialization processed in 5274 ms
Apr 9, 2009 11:08:02 AM org.apache.catalina.core.StandardService start
INFO: Starting service Catalina
Apr 9, 2009 11:08:02 AM org.apache.catalina.core.StandardEngine start
INFO: Starting Servlet Engine: Apache Tomcat/5.5.15
Apr 9, 2009 11:08:02 AM org.apache.catalina.core.StandardHost start
INFO: XML validation disabled
log4j:WARN No appenders could be found for logger (org.apache.catalina.startup.TldConfig).
log4j:WARN Please initialize the log4j system properly.
Apr 9, 2009 11:08:05 AM org.apache.catalina.core.StandardContext resourcesStart
SEVERE: Error starting static Resources
java.lang.IllegalArgumentException: Document base /opt/zimbra/apache-tomcat-5.5.15/server/webapps/host-manager does not exist or is not a readable directory
        at org.apache.naming.resources.FileDirContext.setDocBase(FileDirContext.java:140)
        at org.apache.catalina.core.StandardContext.resourcesStart(StandardContext.java:3812)
        at org.apache.catalina.core.StandardContext.start(StandardContext.java:3983)
        at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:759)
        at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:739)
        at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:524)
        at org.apache.catalina.startup.HostConfig.deployDescriptor(HostConfig.java:603)
        at org.apache.catalina.startup.HostConfig.deployDescriptors(HostConfig.java:535)
        at org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:470)
        at org.apache.catalina.startup.HostConfig.start(HostConfig.java:1118)
        at org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java:310)
        at org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent(LifecycleSupport.java:119)
        at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:1020)
        at org.apache.catalina.core.StandardHost.start(StandardHost.java:718)
        at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:1012)
        at org.apache.catalina.core.StandardEngine.start(StandardEngine.java:442)
        at org.apache.catalina.core.StandardService.start(StandardService.java:450)
        at org.apache.catalina.core.StandardServer.start(StandardServer.java:700)
        at org.apache.catalina.startup.Catalina.start(Catalina.java:551)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:275)
        at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:406)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at com.zimbra.cs.launcher.TomcatLauncher.start(TomcatLauncher.java:42)
        at com.zimbra.cs.launcher.TomcatLauncher.main(TomcatLauncher.java:64)
Apr 9, 2009 11:08:05 AM org.apache.catalina.core.StandardContext start
SEVERE: Error in resourceStart()
Apr 9, 2009 11:08:05 AM org.apache.catalina.core.StandardContext start
SEVERE: Error getConfigured
Apr 9, 2009 11:08:05 AM org.apache.catalina.core.StandardContext start
SEVERE: Context [/host-manager] startup failed due to previous errors
Apr 9, 2009 11:08:05 AM org.apache.catalina.core.StandardContext stop
INFO: Container org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/host-manager] has not been started
Apr 9, 2009 11:08:05 AM org.apache.catalina.startup.ContextConfig applicationWebConfig
INFO: Missing application web.xml, using defaults only StandardEngine[Catalina].StandardHost[localhost].StandardContext[/manager]
Apr 9, 2009 11:08:05 AM org.apache.catalina.startup.HostConfig deployDescriptor
WARNING: A docBase /opt/zimbra/apache-tomcat-5.5.15/webapps/zimbra inside the host appBase has been specified, and will be ignored
log4j:WARN No appenders could be found for logger (org.apache.catalina.session.ManagerBase).
log4j:WARN Please initialize the log4j system properly.
log4j:WARN No appenders could be found for logger (org.apache.catalina.session.ManagerBase).
log4j:WARN Please initialize the log4j system properly.
Zimbra server reserving server socket port=110 bindaddr=null ssl=false
Zimbra server reserving server socket port=995 bindaddr=null ssl=true
Zimbra server reserving server socket port=143 bindaddr=null ssl=false
Zimbra server reserving server socket port=993 bindaddr=null ssl=true
Zimbra server process is running as root, changing to user=zimbra uid=502 gid=506
Zimbra server process, after change, is running with uid=502 euid=502 gid=506 egid=506
Apr 9, 2009 11:08:20 AM org.apache.coyote.http11.Http11BaseProtocol init
INFO: Initializing Coyote HTTP/1.1 on http-443
Apr 9, 2009 11:08:20 AM org.apache.coyote.http11.Http11BaseProtocol init
INFO: Initializing Coyote HTTP/1.1 on http-7071
Apr 9, 2009 11:08:20 AM org.apache.catalina.startup.Catalina load
INFO: Initialization processed in 3807 ms
Apr 9, 2009 11:08:20 AM org.apache.catalina.core.StandardService start
INFO: Starting service Catalina
Apr 9, 2009 11:08:20 AM org.apache.catalina.core.StandardEngine start
INFO: Starting Servlet Engine: Apache Tomcat/5.5.15
Apr 9, 2009 11:08:21 AM org.apache.catalina.core.StandardHost start
INFO: XML validation disabled
log4j:WARN No appenders could be found for logger (org.apache.catalina.startup.TldConfig).
log4j:WARN Please initialize the log4j system properly.
Apr 9, 2009 11:08:26 AM org.apache.catalina.core.StandardContext resourcesStart
SEVERE: Error starting static Resources
java.lang.IllegalArgumentException: Document base /opt/zimbra/apache-tomcat-5.5.15/server/webapps/host-manager does not exist or is not a readable directory
        at org.apache.naming.resources.FileDirContext.setDocBase(FileDirContext.java:140)
        at org.apache.catalina.core.StandardContext.resourcesStart(StandardContext.java:3812)
        at org.apache.catalina.core.StandardContext.start(StandardContext.java:3983)
        at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:759)
        at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:739)
        at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:524)
        at org.apache.catalina.startup.HostConfig.deployDescriptor(HostConfig.java:603)
        at org.apache.catalina.startup.HostConfig.deployDescriptors(HostConfig.java:535)
        at org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:470)
        at org.apache.catalina.startup.HostConfig.start(HostConfig.java:1118)
        at org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java:310)
        at org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent(LifecycleSupport.java:119)
        at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:1020)
        at org.apache.catalina.core.StandardHost.start(StandardHost.java:718)
        at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:1012)
        at org.apache.catalina.core.StandardEngine.start(StandardEngine.java:442)
        at org.apache.catalina.core.StandardService.start(StandardService.java:450)
        at org.apache.catalina.core.StandardServer.start(StandardServer.java:700)
        at org.apache.catalina.startup.Catalina.start(Catalina.java:551)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:275)
        at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:406)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at com.zimbra.cs.launcher.TomcatLauncher.start(TomcatLauncher.java:42)
        at com.zimbra.cs.launcher.TomcatLauncher.main(TomcatLauncher.java:64)
Apr 9, 2009 11:08:26 AM org.apache.catalina.core.StandardContext start
SEVERE: Error in resourceStart()
Apr 9, 2009 11:08:26 AM org.apache.catalina.core.StandardContext start
SEVERE: Error getConfigured
Apr 9, 2009 11:08:26 AM org.apache.catalina.core.StandardContext start
SEVERE: Context [/host-manager] startup failed due to previous errors
Apr 9, 2009 11:08:26 AM org.apache.catalina.core.StandardContext stop
INFO: Container org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/host-manager] has not been started
Apr 9, 2009 11:08:27 AM org.apache.catalina.startup.ContextConfig applicationWebConfig
INFO: Missing application web.xml, using defaults only StandardEngine[Catalina].StandardHost[localhost].StandardContext[/manager]
Apr 9, 2009 11:08:27 AM org.apache.catalina.startup.HostConfig deployDescriptor
WARNING: A docBase /opt/zimbra/apache-tomcat-5.5.15/webapps/zimbra inside the host appBase has been specified, and will be ignored
log4j:WARN No appenders could be found for logger (org.apache.catalina.session.ManagerBase).
log4j:WARN Please initialize the log4j system properly.
log4j:WARN No appenders could be found for logger (org.apache.catalina.session.ManagerBase).
log4j:WARN Please initialize the log4j system properly.
Zimbra server reserving server socket port=110 bindaddr=null ssl=false
Zimbra server reserving server socket port=995 bindaddr=null ssl=true
Zimbra server reserving server socket port=143 bindaddr=null ssl=false
Zimbra server reserving server socket port=993 bindaddr=null ssl=true
Zimbra server process is running as root, changing to user=zimbra uid=502 gid=506
Zimbra server process, after change, is running with uid=502 euid=502 gid=506 egid=506

zimbra]$ zmcontrol status
Host mail01.musiccitynetworks.com
        antispam                Running
        antivirus               Running
        ldap                    Running
        logger                  Running
        mailbox                 Stopped
                tomcat is not running
        mta                     Running
        snmp                    Running
        stats                   Stopped

zimbra]$ zmcontrol -v


Release 4.5.10_GA_1575.RHEL4_20071117152457 CentOS5 FOSS edition

[mmorse]

Welcome to the forums John,

You can create the following empty directories if you want, we didn't rely on the host manager function and actually removed it due to vulnerabilities.

su - zimbra
mkdir -p /opt/zimbra/tomcat/server/webapps/host-manager
mkdir -p /opt/zimbra/tomcat/server/webapps/manager
mkdir -p /opt/zimbra/tomcat/work/Catalina/localhost/host-manager
mkdir -p /opt/zimbra/tomcat/work/Catalina/localhost/manager
tomcat stop
tomcat start

If that doesn't solve it (tomcat typically shouldn't halt for just that - so I kinda suspect there's something else at play) might attach some snips from the end of mailbox.log as well as a new catalina.out.

[mmorse]

Called John he's back online after reverting some of the performance tuning settings he modified. (I'm sure he'll share what not to touch.)

Of note the Performance Tuning Guidelines for Large Deployments - Zimbra :: Wiki is mainly 5.x information at present. (You have to look in the history for 4.5.x)

6.0.x material is currently held here until it's GA/will replace the main article:
Performance Tuning Guidelines for Large Deployments 6.0 - Zimbra :: Wiki LDAP has lots of changes, so have a look.
(When it flips we'll copy the 5.x somewhere for archive access.)

The new logger package is currently covered here: http://wiki.zimbra.com/index.php?title=Logger(GnR)

[mmorse]

I'm going to mark this thread solved as the crisis is over, please create another thread if you need help tracking down said 4.5.x performance issues - though there will be lots of 'upgrade to 5.0.14' comments

(We'd also love to hear what particular setting was bad to modify - I didn't have a pen handy on the phone.)

[jmensel]

As specified in Performance Tuning Guidelines for Large Deployments - Zimbra :: Wiki

...I modified the following settings in an attempt to improve IO performance. What I didn't realize is that these changes are for 5.x only. Thanks to Mike from Zimbra for pointing that one out.

OLD < table_cache = 500
---
NEW > table_cache = 2600

OLD < innodb_open_files = 500
---
NEW > innodb_open_files = 2600
NEW > innodb_max_dirty_pages_pct = 10
NEW > innodb_flush_method = 0_DIRECT

Upon initial restart, zimbra behaved normally. MySQL was behaving as expected, and mail was flowing in and out. However, I found that tomcat was failing to start correctly I did not connect the tomcat problems to the change in MySQL's caching behaviour, as MySQL was running normally.

I found the following errors in catalina.out, which is tomcat's startup log file:

Interesting errors in catalina.out:

SEVERE: Error starting static Resources
java.lang.IllegalArgumentException: Document base /opt/zimbra/apache-tomcat-5.5.15/server/webapps/host-manager does not exist or is not a readable directory

SEVERE: Error starting static Resources
java.lang.IllegalArgumentException: Document base /opt/zimbra/apache-tomcat-5.5.15/server/webapps/manager does not exist or is not a readable directory

WARNING: A docBase /opt/zimbra/apache-tomcat-5.5.15/webapps/zimbra inside the host appBase has been specified, and will be ignored

Extensive investigation of these issues turned up many false leads. I spent a good deal of time investigating permissions issues, potential imapproxy problems, and issues with zimbra's logger.

After more investigation, I found the following in zimbra's mailbox log:

2009-04-09 02:27:06,620 FATAL [main] [] system - Config initialization failed
com.zimbra.common.service.ServiceException: system failure: getting all config entries

Caused by: java.sql.SQLException: Incorrect information in file: './zimbra/config.frm'

Query being executed when exception was thrown:

SELECT * FROM config
at com.mysql.jdbc.SQLError.createSQLException(SQLErro r.java:946)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.ja va:2870)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:15 73)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java :1665)
at com.mysql.jdbc.Connection.execSQL(Connection.java: 3124)
at com.mysql.jdbc.PreparedStatement.executeInternal(P reparedStatement.java:1149)
at com.mysql.jdbc.PreparedStatement.executeQuery(Prep aredStatement.java:1262)
at org.apache.commons.dbcp.DelegatingPreparedStatemen t.executeQuery(DelegatingPreparedStatement.java:20 5)
at com.zimbra.cs.db.DbConfig.getAll(DbConfig.java:155 )
... 40 more


This pointed directly at a problem when querying MySQL. It was only at that point that I connected the innodb table cache handling change with tomcat's problems. I re-enabled the old my.cnf config, restarted all services, and tomcat fired back up.

Cheers,

JHM