ImapServer ProtocolHandler Exception & AsynchronousCloseException & Broken pipe

[papaya74]

Hello Zimbra nerds out there !

i installed ZIMBRA 3.0.0_GA_156.DEBIAN3.1 06.02.2006 on an IBM Netvista P4 1,8 Ghz, 768MB RAM, with a Debian-31r1a-i386-netinst.
Installation was like a charme, i added user, and put some Mails (~400MB) via imapsync into a user account = no problem.

Now i wanted to simulate an "normal" office user, which keeps the WebClient open all day ! So i made some appointments, share some calendars -- and went to bed...sleeping ;-)

Next morning i wanted to check, if the system is stable up & running...

Unfortunatly ZIMBRA freezed...so i had to hard reboot...then i disabled:
- Logger
- Antispam
- SNMP

i thought maybe there were some problems with that and i really don't need it.

Okay..same procedure....next morning:
The user could login into the WebClient, BUT if he wants to move/edit appointments OR emails, Zimbra show the pop-up window with "..slow response...do you want to cancel request.."

Analysis:

less /opt/zimbra/log/zimbra.log shows:

2006-02-13 01:55:12,011 INFO  [ImapServer-2] [] imap - [192.168.1.100] connected
2006-02-13 03:38:46,321 INFO  [Timer-0] [] SessionCache - Removed 2 idle sessions (ImapSession: 1, SoapSession: 1).  0 active sessions remain.
2006-02-13 03:38:46,324 INFO  [Thread-160] [] im - Executing IMEvent: IMPresenceUpdateEvent: From: harry@mydomain.domain  Presence: OFFLINE pri=1 st=null
2006-02-13 03:38:46,324 INFO  [ImapServer-2] [] ProtocolHandler - Exception occurred while handling connection
java.nio.channels.AsynchronousCloseException
        at java.nio.channels.spi.AbstractInterruptibleChannel.end(AbstractInterruptibleChannel.java:185)
        at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:236)
        at sun.nio.ch.SocketAdaptor$SocketInputStream.read(SocketAdaptor.java:171)
        at sun.nio.ch.ChannelInputStream.read(ChannelInputStream.java:86)
        at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
        at java.io.BufferedInputStream.read(BufferedInputStream.java:235)
        at com.zimbra.cs.tcpserver.TcpServerInputStream.readLine(TcpServerInputStream.java:81)
        at com.zimbra.cs.imap.ImapRequest.continuation(ImapRequest.java:129)
        at com.zimbra.cs.imap.ImapHandler.processCommand(ImapHandler.java:507)
        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)
2006-02-13 03:38:46,334 INFO  [ImapServer-2] [] ProtocolHandler - Handler exiting normally

After nearly 2 hours of inactivity Zimbra seems to have problems with holding the connection to the client.

2 minutes later the logs shows:

2006-02-13 03:40:57,024 INFO  [ImapServer-3] [] ProtocolHandler - Exception occurred while handling connection
java.io.IOException: Broken pipe
        at sun.nio.ch.FileDispatcher.write0(Native Method)
        at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:29)
        at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:104)
        at sun.nio.ch.IOUtil.write(IOUtil.java:75)
        at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:302)
        at java.nio.channels.Channels.write(Channels.java:60)
        at java.nio.channels.Channels.access$000(Channels.java:47)
        at java.nio.channels.Channels$1.write(Channels.java:134)
        at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:65)
        at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:123)
        at com.zimbra.cs.imap.ImapHandler.sendLine(ImapHandler.java:1980)
        at com.zimbra.cs.imap.ImapHandler.sendResponse(ImapHandler.java:1970)
        at com.zimbra.cs.imap.ImapHandler.sendOK(ImapHandler.java:1956)
        at com.zimbra.cs.imap.ImapHandler.doCLOSE(ImapHandler.java:1414)
        at com.zimbra.cs.imap.ImapHandler$ImapCommand.execute(ImapHandler.java:458)
        at com.zimbra.cs.imap.ImapHandler.processCommand(ImapHandler.java:529)
        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)
2006-02-13 03:40:57,026 INFO  [ImapServer-3] [] ProtocolHandler - Handler exiting normally

Okay...i know, if i will make a reboot or Zimbra-restart now, then everything will work again, BUT i can't !

BECAUSE WEIRD is, that Debian is not working "normal" anymore, which means, that i have to wait extremly long for e.g. 'top', 'ps auxw' and so on.
This causes that 'zmcontrol stop' or 'init 6' is not working anymore, last exit = power off !

My hint is JAVA & tomcat, but what exactly is going wrong there ?!?
Could "keeping the WebClient open and doing nothing" cause this problem ?

Any ideas ?

Thanks,
Harry

[KevinH]

Are you running in a virtual machine? If tomct hangs it's best to run:


kill -QUIT <tomct pid>


This will dump the threads to catalina.out

[papaya74]

NO, i don't use a virtual machine --> Zimbra runs on a plain fresh Debain install !

Meanwhile i tried the 2nd approach closing all (Web-)Clients and leave Zimbra alone running for 6 hours...

Now:

1. I recognized that the system time is incorrect !
While after a fresh reboot time & date were in correct sync (when i leaved) time now jumped back for more than 5 hours.
Logfiles are showing that... it seems that Zimbra stops logging after 2 hours !

look at this also:

zimbra-01:~# date 
Mo Feb 13 18:24:09 CET 2006
zimbra-01:~# less /opt/zimbra/log/zimbra.log
zimbra-01:~# date
Mo Feb 13 17:12:41 CET 2006

2. I CAN login to a user's mailbox, read mail & appointments BUT CANNOT edit or move them --> "The server is to slow to responding..."

3. If i want to login as ADMIN, my Firefox 1.5.0.1 (Windows2000) freezes completly, i have to kill it with ctrl+alt+del

kill -QUIT <tomct pid>

Okay:

zimbra-01:~# less /opt/zimbra/log/tomcat.pid
zimbra-01:~# kill -QUIT 25902

Nothing happens:

catalina.out shows NO reaction:

"Finalizer" daemon prio=1 tid=0x080b9b18 nid=0x6546 in Object.wait() [0x57fa0000..0x57fa0640]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x4a520768> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)
        - locked <0x4a520768> (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=0x080b8ea0 nid=0x6545 in Object.wait() [0x57f20000..0x57f204c0]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x4a520690> (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 <0x4a520690> (a java.lang.ref.Reference$Lock)

"main" prio=1 tid=0x0805beb0 nid=0x652e runnable [0xbfffd000..0xbfffd978]
        at java.net.PlainSocketImpl.socketAccept(Native Method)
        at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384)
        - locked <0x4aa7a000> (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=0x080b6270 nid=0x6544 runnable

"VM Periodic Task Thread" prio=1 tid=0x080c7768 nid=0x6558 waiting on condition

tomcat is still running:

ps ax | grep tomcat
25902 ?        S      0:06 /opt/zimbra/jdk1.5.0_05/bin/java -Xms227m -Xmx227m -client -XX:NewRatio=2 -Dcatalina.base=/opt/zimbra/jakarta-tomcat-5.5.7 -Dcatalina.home=/opt/zimbra/jakarta-tomcat-5.5.7 -Djava.io.tmpdir=/opt/zimbra/jakarta-tomcat-5.5.7/temp -Djava.library.path=/opt/zimbra/lib/jars -Djava.endorsed.dirs=/opt/zimbra/jakarta-tomcat-5.5.7/common/endorsed -classpath /opt/zimbra/jakarta-tomcat-5.5.7/bin/bootstrap.jar:/opt/zimbra/jakarta-tomcat-5.5.7/bin/commons-logging-api.jar org.apache.catalina.startup.Bootstrap start

Hmm.. i have no idea what's going on there BECAUSE EVERYTHING is working fine, if i am working with Zimbra...if i leave it and do nothing it crashes...

Maybe RAM-failure ?!? It doesn't look like ;-)

Thanks,
Harry

[KevinH]

Is that the entire stack trace. Looks like it's missing some parts.

[papaya74]

No, sorry it was just the end of catalina.out...

Here is the full catalina.out attached:

[KevinH]

Hmm seems pretty idle. I don't see at least off hand don't see an obvious deadlock.

[papaya74]

yes i agree, but what can i do, to come closer to the problem, where do i have to search or analyse additionally ?

The logfiles are looking fine..everythings seems to be up and running, but there is definitely something wrong. It looks like something is slowing the whole system down, but i cannot find the malefactor !

What else can i do ?

Thanks & Best regards,

/harry

[KevinH]

What does top show?

[papaya74]

'top' needs 30 (!!) seconds to start !

..and is not refreshing...so it's hard to catch the evil process...

ah..i get something:

top - 21:16:14 up  3:35,  1 user,  load average: 0.40, 0.31, 0.28
Tasks:  61 total,   1 running,  60 sleeping,   0 stopped,   0 zombie
Cpu(s): 100.0% us,  0.0% sy,  0.0% ni,  0.0% id,  0.0% wa,  0.0% hi,  0.0% si
Mem:    775104k total,   350072k used,   425032k free,    15924k buffers
Swap:  1510068k total,        0k used,  1510068k free,   122568k cached

But 'top' is not showing the evil pid....

That's strange --> WHY IS THE TIME CHANGING ??
It seems like the system is switching between two different times in realtime !

And indicates also his uptime different...

21:16:14 --> 20:04:48...

top - 20:04:48 up  2:24,  1 user,  load average: 0.26, 0.28, 0.27
Tasks:  61 total,   1 running,  60 sleeping,   0 stopped,   0 zombie
Cpu(s):  0.0% us,  0.0% sy,  0.0% ni,  0.0% id,  0.0% wa,  0.0% hi,  0.0% si
Mem:    775104k total,   350088k used,   425016k free,    15936k buffers
Swap:  1510068k total,        0k used,  1510068k free,   122568k cached

Do i missed something in the installing procedure regarding time ??

Thanks,

/harry

[KevinH]

Hard to say seems something is taking up 100% cpu so if you can't figure it out with top you may need to try something else.