IMAP goes down 2-3 times a week, tomcat restart necessary

[shanson]

(I've submitted this as a support ticket, but this doesn't seem specific to the Network Edition, and maybe someone in the forums is having similar problems :-)

We've been having problems with ZCS not accepting new IMAP connections 2 or 3 times a week. The existing connections stay up, but no new connections are accepted until we do a "tomcat restart".

We've started monitoring the service with nagios, and when the problem occurs the imap_check reports a "socket timeout after 10 seconds"

I haven't been able to find a consistent error message in /opt/zimbra/log/zimbra.log. Today it was:

2006-05-26 09:20:46,776 WARN [ImapServer-1183] [ip=xx.xxx.x.xxx;name=xxxxx@nu2m.de;] imap - error checking account status; dropping connection
com.zimbra.cs.service.ServiceException: system failure: getDirectContext
at com.zimbra.cs.service.ServiceException.FAILURE(ServiceException.java:131)
at com.zimbra.cs.account.ldap.LdapUtil.getDirContext(LdapUtil.java:179)
at com.zimbra.cs.account.ldap.LdapUtil.getDirContext(LdapUtil.java:163)
at com.zimbra.cs.account.ldap.LdapProvisioning.getAccountByQuery(LdapProvisioning.java:297)
at com.zimbra.cs.account.ldap.LdapProvisioning.getAccountById(LdapProvisioning.java:325)
at com.zimbra.cs.account.ldap.LdapProvisioning.getAccountById(LdapProvisioning.java:336)
at com.zimbra.cs.mailbox.Mailbox.getAccount(Mailbox.java:359)
at com.zimbra.cs.mailbox.Mailbox.getAccount(Mailbox.java:346)
at com.zimbra.cs.imap.ImapHandler.processCommand(ImapHandler.java:521)
at com.zimbra.cs.tcpserver.ProtocolHandler.processConnection(ProtocolHandler.java:231)
at com.zimbra.cs.tcpserver.ProtocolHandler.run(ProtocolHandler.java:198)
at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(Unknown Source)
at java.lang.Thread.run(Thread.java:595)
Caused by: javax.naming.CommunicationException: zimbra.nu2m.de:389 [Root exception is java.net.ConnectException: Connection refused]
at com.sun.jndi.ldap.Connection.<init>(Connection.java:194)
at com.sun.jndi.ldap.LdapClient.<init>(LdapClient.java:118)
at com.sun.jndi.ldap.LdapClientFactory.createPooledConnection(LdapClientFactory.java:44)
at com.sun.jndi.ldap.pool.Connections.<init>(Connections.java:97)
at com.sun.jndi.ldap.pool.Pool.getPooledConnection(Pool.java:114)
at com.sun.jndi.ldap.LdapPoolManager.getLdapClient(LdapPoolManager.java:310)
at com.sun.jndi.ldap.LdapClient.getInstance(LdapClient.java:1572)
at com.sun.jndi.ldap.LdapCtx.connect(LdapCtx.java:2596)
at com.sun.jndi.ldap.LdapCtx.<init>(LdapCtx.java:283)
at com.sun.jndi.ldap.LdapCtxFactory.getUsingURL(LdapCtxFactory.java:175)
at com.sun.jndi.ldap.LdapCtxFactory.getUsingURLs(LdapCtxFactory.java:193)
at com.sun.jndi.ldap.LdapCtxFactory.getLdapCtxInstance(LdapCtxFactory.java:136)
at com.sun.jndi.ldap.LdapCtxFactory.getInitialContext(LdapCtxFactory.java:66)
at javax.naming.spi.NamingManager.getInitialContext(NamingManager.java:667)
at javax.naming.InitialContext.getDefaultInitCtx(InitialContext.java:247)
at javax.naming.InitialContext.init(InitialContext.java:223)
at javax.naming.ldap.InitialLdapContext.<init>(InitialLdapContext.java:134)
at com.zimbra.cs.account.ldap.LdapUtil.getDirContext(LdapUtil.java:174)
... 11 more
Caused by: java.net.ConnectException: Connection refused
at java.net.PlainSocketImpl.socketConnect(Native Method)
at java.net.PlainSocketImpl.doConnect(PlainSocketImpl.java:333)
at java.net.PlainSocketImpl.connectToAddress(PlainSocketImpl.java:195)
at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:182)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:366)
at java.net.Socket.connect(Socket.java:507)
at sun.reflect.GeneratedMethodAccessor32.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:585)
at com.sun.jndi.ldap.Connection.createSocket(Connection.java:333)
at com.sun.jndi.ldap.Connection.<init>(Connection.java:181)
... 28 more

We're running 3.1.1_GA_394 (2006-05-08) under RHEL 4, Dual Xeon with 4GB RAM an 350GB 3ware RAID.

[jholder]

hmm,
Can you post your most recent stacktrace?
/opt/zimbra/tomcat/logs/(stacktrace with the newest datestamp)

From here it looks like an LDAP problem:

Caused by: javax.naming.CommunicationException: zimbra.nu2m.de:389 [Root exception is java.net.ConnectException: Connection refused]

I think your LDAP password may have gotten out of sync, perhaps. When it crashes, try telneting to the machine on port 389, and see what happens.

john

[shanson]

The error message I posted is bogus. After cross-checking my /var/logs/zimbra.log, I realized that this error occured while I was running "/etc/init.d/zimbra restart", so of course LDAP was down for about a minute. The IMAP outage had acutally started 10 minutes earlier, and there are no obvious errors in /opt/zimbra/logs/zimbra.log.

I'm attaching the appropriate tomcat stacktrace.

[KevinH]

Scott,

Can you try getting a thread dump when IMAP is unavailable.

kill -QUIT <tomcat pid>

[shanson]

Thanks, I'll do that next time we have problems.

I've also turned on the imapproxy. Back when I worked with Lotus Notes, I found that using a proxy helped getting various IMAP clients to play nicely with Domino. Maybe it will help here as well. :-)

[dillera]

For what its worth- I have the same problem.

ZCS 3.1.1, open-source, on a RH FC4 system. Imap just stops responding- watching the process via Top, and all the ZCS processes are sleeping and are never woken. I just stop and start every hour.

[shanson]

Turning on the imapproxy seems to have helped. It's been on now for 5 days, and we haven't had any problems (except that /var/log/zimbra.log is full of perdition entries, how can I turn debug mode off? :-) ).

It may also be 3.1.1 is better than 3.1.0. We just updated to 3.1.1 last week, a couple of days before the incident I mentioned above.

[KevinH]

It's on by default, syslog facility mail:

from perdition.conf.in:
C <-- connection logging
d <--- debug logging
F mail <--- syslog facility

[shanson]

The IMAP port was just down again. IMAPS and HTTP were still up. zmcontrol status showed all services running. I took a stacktrace as KevinH requested... the output is in catalina.out, correct? That's what I've attached.

Additional information: we're running IMAP behind the imapproxy, but not IMAPS. So it could have been a perdition problem.

[KevinH]

I don't see any dead locks in this dump so not sure what caused the outage. Maybe as you said it was perdition, since IMAP/IMAPS should be up/down together.