Zimbra dies after some time

[czaveri]

Hello All,

I am stuck with a very weird problem. I have Zimbra running on Centos 4.2, AMD Sempron 2600, and 2 GB RAM. (No virtual machine). And Zimbra was running smoothly on this system since 4 days. It has suddenly been experiencing problems. It simply dies. (even after I reboot the system it does not stay up).

Here is what happens:

[root@parshwanath ~]# /etc/rc.d/init.d/zimbra stop
Host domain.net
        Stopping antispam...Done
        Stopping antivirus...Done
        Stopping ldap...Done
        Stopping logger...Done
        Stopping mailbox...Done
        Stopping mta...Done
        Stopping snmp...Done
        Stopping spell...Done
[root@parshwanath ~]# ps ax | grep zimbra
 7081 ?        S      0:00 initlog -q -c /etc/rc3.d/S99zimbra start
 7082 ?        S      0:00 /bin/bash /etc/rc3.d/S99zimbra start
 7083 ?        S      0:00 su - zimbra -c zmcontrol startup
 7968 pts/0    S+     0:00 grep zimbra
[root@parshwanath ~]# kill 7081 7082 7083
[root@parshwanath ~]# ps ax | grep zimbra
 8352 pts/0    R+     0:00 grep zimbra
[root@parshwanath ~]# /etc/rc.d/init.d/zimbra start
Host domain.net
        Starting ldap...Done.
[root@parshwanath ~]# /etc/rc.d/init.d/zimbra status
Cannot determine services - exiting[root@parshwanath ~]#
[root@parshwanath ~]# ps ax | grep zimbra
 8453 ?        Ssl    0:00 /opt/zimbra/openldap-2.2.28/libexec/slapd -l LOCAL0 -4 -u zimbra -h ldaps:// ldap://:389/ -f /opt/zimbra/conf/slapd.conf
 8602 ?        Ss     0:00 /usr/bin/perl /opt/zimbra/bin/zmstatuslog
 8609 ?        S      0:00 /usr/bin/perl /opt/zimbra/bin/zmcontrol status
 8610 ?        Sl     0:00 /opt/zimbra/java/bin/java -client -Dzimbra.home=/opt/zimbra -cp /opt/zimbra/lib/jars/zimbrastore.jar:/opt/zimbra/lib/jars/commons-logging.jar:/opt/zimbra/lib/jars/commons-cli-2.0.jar:/opt/zimbra/lib/jars/dom4j-1.5.jar:/opt/zimbra/lib/jars/log4j-1.2.8.jar:/opt/zimbra/lib/jars/commons-httpclient-2.0.1.jar com.zimbra.cs.localconfig.Main -q -m shell
 8622 pts/0    S+     0:00 grep zimbra
[root@parshwanath ~]# ps ax | grep zimbra
 8453 ?        Ssl    0:00 /opt/zimbra/openldap-2.2.28/libexec/slapd -l LOCAL0 -4 -u zimbra -h ldaps:// ldap://:389/ -f /opt/zimbra/conf/slapd.conf
 8637 pts/0    S+     0:00 grep zimbra

Here is how the last few lines of catalina.out look:

"http-7080-Processor45" daemon prio=1 tid=0x08760638 nid=0x75ad in Object.wait() [0x87224000..0x87224eb0]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x965e5b68> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable)
        at java.lang.Object.wait(Object.java:474)
        at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:656)
        - locked <0x965e5b68> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable)
        at java.lang.Thread.run(Thread.java:595)

"http-7080-Processor44" daemon prio=1 tid=0x0875f700 nid=0x75ac in Object.wait() [0x872a5000..0x872a5e30]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x965e5908> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable)
        at java.lang.Object.wait(Object.java:474)
        at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:656)
        - locked <0x965e5908> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable)
        at java.lang.Thread.run(Thread.java:595)

"http-7080-Processor43" daemon prio=1 tid=0x085e5358 nid=0x75ab in Object.wait() [0x87327000..0x873271b0]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x965e56a8> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable)
        at java.lang.Object.wait(Object.java:474)
        at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:656)
        - locked <0x965e56a8> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable)
        at java.lang.Thread.run(Thread.java:595)

"http-7080-Processor42" daemon prio=1 tid=0x085e4420 nid=0x75aa in Object.wait() [0x873a7000..0x873a8130]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x965e5448> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable)
        at java.lang.Object.wait(Object.java:474)
        at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:656)
        - locked <0x965e5448> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable)
        at java.lang.Thread.run(Thread.java:595)

.
.
. (there are many similar lines here which I have edited out because it exceeded number of characters)
.
.

"http-7080-Processor2" daemon prio=1 tid=0x085bf788 nid=0x7582 in Object.wait() [0x88e3f000..0x88e40130]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x965df548> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable)
        at java.lang.Object.wait(Object.java:474)
        at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:656)
        - locked <0x965df548> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable)
        at java.lang.Thread.run(Thread.java:595)

"http-7080-Processor1" daemon prio=1 tid=0x085bf3a0 nid=0x7581 in Object.wait() [0x88ec0000..0x88ec10b0]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x965df2e8> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable)
        at java.lang.Object.wait(Object.java:474)
        at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:656)
        - locked <0x965df2e8> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable)
        at java.lang.Thread.run(Thread.java:595)

"ContainerBackgroundProcessor[StandardEngine[Catalina]]" daemon prio=1 tid=0x081535c0 nid=0x7580 waiting on condition [0x88f41000..0x88f42030]
        at java.lang.Thread.sleep(Native Method)
        at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1539)
        at java.lang.Thread.run(Thread.java:595)

"Thread-10" daemon prio=1 tid=0x08255af8 nid=0x757e waiting on condition [0x88244000..0x88244fb0]
        at java.lang.Thread.sleep(Native Method)
        at org.apache.log4j.helpers.FileWatchdog.run(FileWatchdog.java:95)

"ImapSSLServer" prio=1 tid=0x0824cc40 nid=0x757d runnable [0x882c5000..0x882c5f30]
        at java.net.PlainSocketImpl.socketAccept(Native Method)
        at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384)
        - locked <0x9644dd08> (a java.net.SocksSocketImpl)
        at java.net.ServerSocket.implAccept(ServerSocket.java:450)
        at com.sun.net.ssl.internal.ssl.SSLServerSocketImpl.accept(SSLServerSocketImpl.java:259)
        at com.zimbra.cs.tcpserver.TcpServer.run(TcpServer.java:185)
        at java.lang.Thread.run(Thread.java:595)

"ImapServer" prio=1 tid=0x0824c810 nid=0x757c runnable [0x88346000..0x88346eb0]
        at sun.nio.ch.ServerSocketChannelImpl.accept0(Native Method)
        at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:145)
        - locked <0x9644dad8> (a java.lang.Object)
        at sun.nio.ch.ServerSocketAdaptor.accept(ServerSocketAdaptor.java:84)
        - locked <0x9644dad0> (a java.lang.Object)
        at com.zimbra.cs.tcpserver.TcpServer.run(TcpServer.java:185)
        at java.lang.Thread.run(Thread.java:595)

"Pop3Server" prio=1 tid=0x083f3ae0 nid=0x757a runnable [0x883c7000..0x883c7e30]
        at java.net.PlainSocketImpl.socketAccept(Native Method)
        at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384)
        - locked <0x9644d938> (a java.net.SocksSocketImpl)
        at java.net.ServerSocket.implAccept(ServerSocket.java:450)
        at com.sun.net.ssl.internal.ssl.SSLServerSocketImpl.accept(SSLServerSocketImpl.java:259)
        at com.zimbra.cs.tcpserver.TcpServer.run(TcpServer.java:185)
        at com.zimbra.cs.pop3.Pop3Server.run(Pop3Server.java:75)
        at java.lang.Thread.run(Thread.java:595)

"Pop3Server" prio=1 tid=0x08516df8 nid=0x7579 runnable [0x88448000..0x884491b0]
        at sun.nio.ch.ServerSocketChannelImpl.accept0(Native Method)
        at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:145)
        - locked <0x9644bc68> (a java.lang.Object)
        at sun.nio.ch.ServerSocketAdaptor.accept(ServerSocketAdaptor.java:84)
        - locked <0x9644bc60> (a java.lang.Object)
        at com.zimbra.cs.tcpserver.TcpServer.run(TcpServer.java:185)
        at com.zimbra.cs.pop3.Pop3Server.run(Pop3Server.java:75)
        at java.lang.Thread.run(Thread.java:595)

"LmtpServer" prio=1 tid=0x08250f08 nid=0x7578 runnable [0x884c9000..0x884ca130]
        at sun.nio.ch.ServerSocketChannelImpl.accept0(Native Method)
        at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:145)
        - locked <0x96519530> (a java.lang.Object)
        at sun.nio.ch.ServerSocketAdaptor.accept(ServerSocketAdaptor.java:84)
        - locked <0x96519528> (a java.lang.Object)
        at com.zimbra.cs.tcpserver.TcpServer.run(TcpServer.java:185)
        at com.zimbra.cs.lmtpserver.LmtpServer.run(LmtpServer.java:60)
        at java.lang.Thread.run(Thread.java:595)

"FileLogWriter.FsyncThread" prio=1 tid=0x085c0df8 nid=0x7577 sleeping[0x8854a000..0x8854b0b0]
        at java.lang.Thread.sleep(Native Method)
        at com.zimbra.cs.redolog.logger.FileLogWriter$FsyncThread.run(FileLogWriter.java:471)

"IndexWritersSweeper" prio=1 tid=0x083f54d8 nid=0x756e in Object.wait() [0x885cb000..0x885cbfb0]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x965152b8> (a com.zimbra.cs.index.MailboxIndex$IndexWritersSweeperThread)
        at com.zimbra.cs.index.MailboxIndex$IndexWritersSweeperThread.run(MailboxIndex.java:538)
        - locked <0x965152b8> (a com.zimbra.cs.index.MailboxIndex$IndexWritersSweeperThread)

"Thread-4" daemon prio=1 tid=0x08188678 nid=0x7528 waiting on condition [0x8864c000..0x8864cf30]
        at java.lang.Thread.sleep(Native Method)
        at org.apache.log4j.helpers.FileWatchdog.run(FileWatchdog.java:95)

"Thread-2" daemon prio=1 tid=0x08768aa8 nid=0x7526 in Object.wait() [0x8875f000..0x8875fe30]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x963f75e8> (a com.sun.jndi.ldap.pool.PoolCleaner)
        at com.sun.jndi.ldap.pool.PoolCleaner.run(PoolCleaner.java:36)
        - locked <0x963f75e8> (a com.sun.jndi.ldap.pool.PoolCleaner)

"Timer-0" daemon prio=1 tid=0x08740078 nid=0x7525 in Object.wait() [0x887e1000..0x887e11b0]
        at java.lang.Object.wait(Native Method)
        at java.util.TimerThread.mainLoop(Timer.java:509)
        - locked <0x963f6090> (a java.util.TaskQueue)
        at java.util.TimerThread.run(Timer.java:462)

"Low Memory Detector" daemon prio=1 tid=0x080c62a0 nid=0x73f5 runnable [0x00000000..0x00000000]

"CompilerThread0" daemon prio=1 tid=0x080c4d08 nid=0x73f4 waiting on condition [0x00000000..0x8964da18]

"Signal Dispatcher" daemon prio=1 tid=0x080c3e50 nid=0x73f3 runnable [0x00000000..0x00000000]

"Finalizer" daemon prio=1 tid=0x080b9590 nid=0x73f2 in Object.wait() [0x8994f000..0x8994ff30]
        at java.lang.Object.wait(Native Method)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)
        - locked <0x96080768> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132)
        at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

"Reference Handler" daemon prio=1 tid=0x080b8880 nid=0x73f1 in Object.wait() [0x899d0000..0x899d0eb0]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x96080690> (a java.lang.ref.Reference$Lock)
        at java.lang.Object.wait(Object.java:474)
        at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
        - locked <0x96080690> (a java.lang.ref.Reference$Lock)

"main" prio=1 tid=0x0805beb0 nid=0x73df runnable [0xbfffd000..0xbfffd7b8]
        at java.net.PlainSocketImpl.socketAccept(Native Method)
        at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384)
        - locked <0x966166f8> (a java.net.SocksSocketImpl)
        at java.net.ServerSocket.implAccept(ServerSocket.java:450)
        at java.net.ServerSocket.accept(ServerSocket.java:421)
        at org.apache.catalina.core.StandardServer.await(StandardServer.java:362)
        at org.apache.catalina.startup.Catalina.await(Catalina.java:600)
        at org.apache.catalina.startup.Catalina.start(Catalina.java:560)
        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:585)
        at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:271)
        at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:409)

"VM Thread" prio=1 tid=0x080b5c18 nid=0x73ec runnable

"VM Periodic Task Thread" prio=1 tid=0x080c7778 nid=0x73f6 waiting on condition

Apr 5, 2006 8:41:10 AM org.apache.coyote.http11.Http11Protocol pause
INFO: Pausing Coyote HTTP/1.1 on http-7080
Apr 5, 2006 8:41:10 AM org.apache.coyote.http11.Http11Protocol pause
INFO: Pausing Coyote HTTP/1.1 on http-7443
Apr 5, 2006 8:41:10 AM org.apache.coyote.http11.Http11Protocol pause
INFO: Pausing Coyote HTTP/1.1 on http-7071
Apr 5, 2006 8:41:11 AM org.apache.catalina.core.StandardService stop
INFO: Stopping service Catalina
Apr 5, 2006 8:41:11 AM org.apache.coyote.http11.Http11Protocol destroy
INFO: Stopping Coyote HTTP/1.1 on http-7080
Apr 5, 2006 8:41:11 AM org.apache.coyote.http11.Http11Protocol destroy
INFO: Stopping Coyote HTTP/1.1 on http-7443
Apr 5, 2006 8:41:11 AM org.apache.coyote.http11.Http11Protocol destroy
INFO: Stopping Coyote HTTP/1.1 on http-7071

I must also add that zimbra admin port is 7071, http port is 7080 and https port is 7443.

Sincerely,

Chintan.

[KevinH]

Does it die right after you start it? Or after some time?

[czaveri]

Actually when I start Zimbra, it is only the LDAP that starts. No other services are started. But when I rebooted the server, I noticed the following:

[root@parshwanath ~]# ps ax | grep zimbra
7081 ? S 0:00 initlog -q -c /etc/rc3.d/S99zimbra start
7082 ? S 0:00 /bin/bash /etc/rc3.d/S99zimbra start
7083 ? S 0:00 su - zimbra -c zmcontrol startup
7270 pts/0 S+ 0:00 grep zimbra
[root@parshwanath ~]#

and this does not change ... even after 5 mins or more

Editing this message to add the below output:

[root@parshwanath ~]# /etc/rc.d/init.d/zimbra restart
Host domain.net
        Stopping antispam...Done
        Stopping antivirus...Done
        Stopping ldap...Done
        Stopping logger...Done
        Stopping mailbox...Done
        Stopping mta...Done
        Stopping snmp...Done
        Stopping spell...Done
Host domain.net
        Starting ldap...Done.
[root@parshwanath ~]#

[czaveri]

It dies after some time.

Now, when I restarted Zimbra, it shows (after 15 mins), the following processes:

[root@parshwanath ~]# ps ax | grep zimbra
 7081 ?        S      0:00 initlog -q -c /etc/rc3.d/S99zimbra start
 7082 ?        S      0:00 /bin/bash /etc/rc3.d/S99zimbra start
 7083 ?        S      0:00 su - zimbra -c zmcontrol startup
 8065 ?        Ssl    0:00 /opt/zimbra/openldap-2.2.28/libexec/slapd -l LOCAL0 -4 -u zimbra -h ldaps:// ldap://:389/ -f /opt/zimbra/conf/slapd.conf
 9169 ?        Ss     0:00 /usr/bin/perl /opt/zimbra/bin/zmstatuslog
 9176 ?        S      0:00 /usr/bin/perl /opt/zimbra/bin/zmcontrol status
 9188 ?        S      0:00 sh -c /opt/zimbra/bin/zmprov gs domain.net 2>/dev/null
 9189 ?        Sl     0:00 /opt/zimbra/java/bin/java -client -Xmx256m -Dzimbra.home=/opt/zimbra -Djava.library.path=/opt/zimbra/lib/jars -Djava.ext.dirs=/opt/zimbra/java/jre/lib/ext:/opt/zimbra/lib/jars com.zimbra.cs.account.ProvUtil gs domain.net
 9204 pts/0    S+     0:00 grep zimbra
[root@parshwanath ~]#

But I cannot access the web interface - neither Admin nor User.

[phoenix]

My questions would be, what happened four days ago? Did you install anything new or does your system do an automatic update?

[KevinH]

Do you have a firewall, iptables, or SELinux enabled? This behaviour I've seen before when zimbra can't contact LDAP.

Try these commands:

host `hostname`
zmhostname
telnet `hostname` 389

[czaveri]

Thank-you for your reply Kevin. Here is the result:

[zimbra@parshwanath ~]$ host `hostname`
parshwanath.domain.net has address 192.168.1.12
parshwanath.domain.net mail is handled by 0 parshwanath.domain.net.
[zimbra@parshwanath ~]$ zmhostname
domain.net
[zimbra@parshwanath ~]$ telnet `hostname` 389
Trying 192.168.1.12...
Connected to parshwanath.domain.net (192.168.1.12).
Escape character is '^]'.
Connection closed by foreign host.
[zimbra@parshwanath ~]$

Yes, I have iptables, but they aren't blocking these ports. I haven't made any changes to rules in many days. (I checked this again right now). Telnet to port 389 works. I haven't done any thing new except adding 4 more domains yesterday - so, in all I have 7 domains and 20 users spread over these domains.

phoenix: This problem is not 4 days old - this instance of Zimbra was installed 4 days back and it was functioning well until today afternoon... when nothing happened... and I noticed that my connection to mail server was refused. So, I decided to check and noticed, Zimbra had died.

[KevinH]

Let's get a stack of the running ProvUtil command. Can you try:

kill -QUIT 9189

Or whatever the pid is of the java process calling ProvUtil.

[czaveri]

Hello Kevin,

It works! I think it could be something like this...

I installed Zimbra 4 days back. Then I setup firewall while Zimbra was running. I had kept port 636 open but not 389. And, I think due to some reason Zimbra crashed today afternoon. I tried to start it but didn't start because I think Zimbra might be needing the port 389 open when it starts and probably can do with port 636 when running... am I right here? Also, when I did telnet to 389 it was from inside the firewall so it worked.

Am I guessing it correctly?

Thank-you very much for your time and support,

I am confident, Zimbra is at the pinnacle of Open Source Email Systems, today.

Sincerely,

Chintan Zaveri.

[KevinH]

It makes sense. I think there are some hard coded 389 LDAP port refs. If you'd like file a bugzilla issue and we'll add it to the stack to take a deeper look.

Glad your back running.