one user unable to use zimbra

[marcmac]

Since this happens only to this account, regardless of the client machine used to access it, or the method (web, imap, etc) can we get some details on the account?

How much mail is in the account?
How many tags/folders/saved searches?
How many appointments in the calendar (how many recurring?)
Is this user subscribed to multiple calendars?

Exact numbers not necessary, I just want to get a feel for the user's usage profile.

[adobrin]

i'm not exactly sure how to find everything you are looking for. here's some db stats:

mysql> select type,count(*) from mail_item group by type;
+------+----------+
| type | count(*) |
+------+----------+
|    1 |       47 |
|    4 |     1227 |
|    5 |     5605 |
|    6 |       19 |
|   11 |        2 |
+------+----------+

select subject,count(*) from mail_item where type not in (5,4) group by subject;
is giving me what looks like 48 folders.

2 records in "appointment"

open_conversation has 2600 recordsish
and tombstone has 18.

[adobrin]

no saved searches, no tags.


incidentally.. i don't seem to have a problem reading his mail in thunderbird.

[adobrin]

well. this user stopped complaining a few days ago, and then we tried the Outlook Connector for him; everything seems to be working smoothly on his machine.

In an unfortuante turn of events, it appears that I am having a similar problem now. I recently switched from Blackberry to Treo, and tried using ChatterMail (as i read in another post); and shortly after doing that got the same symptoms as he was having.

Chattermail became unable to login to the server; and after getting home, my web client hangs on login like his did.

If i had to guess, it seems like this is related to persistent IMAP connections; as Chatter and (i'm guessing) Outlook IMAP keep the connection open for extended periods of time. (of course, just a guess.)

Anyway.. reading in the logs (/opt/zimbra/zimbra.log) it appears that the problem is related to :

2005-12-10 12:24:18,227 INFO  [Convertd-369] [] 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.InputStream.read(InputStream.java:89)
        at sun.nio.ch.ChannelInputStream.read(ChannelInputStream.java:64)
        at java.io.FilterInputStream.read(FilterInputStream.java:66)
        at com.zimbra.cs.convertd.TransformationHandler.processCommand(TransformationHandler.java:95)
        at com.zimbra.cs.tcpserver.ProtocolHandler.processConnection(ProtocolHandler.java:230)
        at com.zimbra.cs.tcpserver.ProtocolHandler.run(ProtocolHandler.java:197)
        at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(Unknown Source)
        at java.lang.Thread.run(Thread.java:595)

restarting tomcat has fixed the problem for now.

[KevinH]

Originally Posted by adobrin

restarting tomcat has fixed the problem for now.

This would indicate a deadlock or hang. Next time you get in this condition before you restart tomcat run this:

kill -QUIT <tomcat pid>


This will dump a stack trace of each thread into /opt/zimbra/tomcat/logs/catalina.out Please attach this thread dump here. It may help us determine what is hung up.

[adobrin]

heres some kill -QUIT info

Full thread dump Java HotSpot(TM) Client VM (1.5.0_05-b05 mixed mode):

"ImapSSLServer-19" prio=1 tid=0x0828e540 nid=0x29aa runnable [0x7e57c000..0x7e57d0b0]
        at java.net.SocketInputStream.socketRead0(Native Method)
        at java.net.SocketInputStream.read(SocketInputStream.java:129)
        at com.sun.net.ssl.internal.ssl.InputRecord.readFully(InputRecord.java:284)
        at com.sun.net.ssl.internal.ssl.InputRecord.read(InputRecord.java:319)
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:720)
        - locked <0x939bcc40> (a java.lang.Object)
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:677)
        at com.sun.net.ssl.internal.ssl.AppInputStream.read(AppInputStream.java:75)
        - locked <0x939bcc50> (a com.sun.net.ssl.internal.ssl.AppInputStream)
        at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
        at java.io.BufferedInputStream.read(BufferedInputStream.java:235)
        - locked <0x8a3ec9f8> (a com.zimbra.cs.tcpserver.TcpServerInputStream)
        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:480)
        at com.zimbra.cs.imap.ImapRequest.continuation(ImapRequest.java:129)
        at com.zimbra.cs.imap.ImapHandler.processCommand(ImapHandler.java:480)
        at com.zimbra.cs.tcpserver.ProtocolHandler.processConnection(ProtocolHandler.java:230)
        at com.zimbra.cs.tcpserver.ProtocolHandler.run(ProtocolHandler.java:197)
        at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(Unknown Source)
        at java.lang.Thread.run(Thread.java:595)

"ImapSSLServer-17" prio=1 tid=0x0826cf08 nid=0x5b80 waiting for monitor entry [0x7dc6a000..0x7dc6af30]
        at com.zimbra.cs.mailbox.Mailbox.addListener(Mailbox.java:363)
        - waiting to lock <0x9660c6a0> (a com.zimbra.cs.mailbox.Mailbox)
        at com.zimbra.cs.session.Session.<init>(Session.java:62)
        at com.zimbra.cs.imap.ImapSession.<init>(ImapSession.java:70)
        at com.zimbra.cs.session.SessionCache.getNewSession(SessionCache.java:79)
        at com.zimbra.cs.imap.ImapHandler.doLOGIN(ImapHandler.java:683)
        at com.zimbra.cs.imap.ImapHandler$ImapCommand.execute(ImapHandler.java:424)
        at com.zimbra.cs.imap.ImapHandler.processCommand(ImapHandler.java:502)
        at com.zimbra.cs.tcpserver.ProtocolHandler.processConnection(ProtocolHandler.java:230)
        at com.zimbra.cs.tcpserver.ProtocolHandler.run(ProtocolHandler.java:197)
        at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(Unknown Source)
        at com.zimbra.cs.tcpserver.ProtocolHandler.run(ProtocolHandler.java:197)
        at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(Unknown Source)
        at java.lang.Thread.run(Thread.java:595)
"ImapSSLServer-9" prio=1 tid=0x08969548 nid=0x7410 waiting for monitor entry [0x7e903000..0x7e903fb0]
        at com.zimbra.cs.mailbox.Mailbox.addListener(Mailbox.java:363)
        - waiting to lock <0x9660c6a0> (a com.zimbra.cs.mailbox.Mailbox)
        at com.zimbra.cs.session.Session.<init>(Session.java:62)
        at com.zimbra.cs.imap.ImapSession.<init>(ImapSession.java:70)
        at com.zimbra.cs.session.SessionCache.getNewSession(SessionCache.java:79)
        at com.zimbra.cs.imap.ImapHandler.doLOGIN(ImapHandler.java:683)
        at com.zimbra.cs.imap.ImapHandler$ImapCommand.execute(ImapHandler.java:424)
        at com.zimbra.cs.imap.ImapHandler.processCommand(ImapHandler.java:502)
        at com.zimbra.cs.tcpserver.ProtocolHandler.processConnection(ProtocolHandler.java:230)
        at com.zimbra.cs.tcpserver.ProtocolHandler.run(ProtocolHandler.java:197)
        at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(Unknown Source)
        at com.zimbra.cs.tcpserver.ProtocolHandler.run(ProtocolHandler.java:197)
        at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(Unknown Source)
        at java.lang.Thread.run(Thread.java:595)
"LmtpServer-20" prio=1 tid=0x08180ab0 nid=0x292 waiting for monitor entry [0x80472000..0x804731b0]
        at com.zimbra.cs.mailbox.Mailbox.getAccount(Mailbox.java:340)
        - waiting to lock <0x9660c6a0> (a com.zimbra.cs.mailbox.Mailbox)
        at com.zimbra.cs.mailbox.Mailbox.attachmentsIndexingEnabled(Mailbox.java:4046)
        at com.zimbra.cs.lmtpserver.ZimbraLmtpBackend.deliverMessageToLocalMailboxes(ZimbraLmtpBackend.ja$
        at com.zimbra.cs.lmtpserver.ZimbraLmtpBackend.deliver(ZimbraLmtpBackend.java:107)
        at com.zimbra.cs.lmtpserver.LmtpHandler.doDATA(LmtpHandler.java:419)
        at com.zimbra.cs.lmtpserver.LmtpHandler.processCommand(LmtpHandler.java:196)
        at com.zimbra.cs.tcpserver.ProtocolHandler.processConnection(ProtocolHandler.java:230)
        at com.zimbra.cs.tcpserver.ProtocolHandler.run(ProtocolHandler.java:197)
        at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(Unknown Source)
        at com.zimbra.cs.tcpserver.ProtocolHandler.run(ProtocolHandler.java:197)
        at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(Unknown Source)
        at java.lang.Thread.run(Thread.java:595)

"LmtpServer-19" prio=1 tid=0x084b8cd0 nid=0x291 waiting for monitor entry [0x803f1000..0x803f2030]
        at java.nio.channels.Channels.write(Channels.java:58)
        - waiting to lock <0x9694f540> (a java.lang.Object)
        at java.nio.channels.Channels.access$000(Channels.java:47)
        at java.nio.channels.Channels$1.write(Channels.java:134)
        - locked <0x9694f5e8> (a java.nio.channels.Channels$1)
        at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:65)
        at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:123)
        - locked <0x96951610> (a java.io.BufferedOutputStream)
        at com.zimbra.cs.imap.ImapHandler.flushOutput(ImapHandler.java:1943)
        at com.zimbra.cs.imap.ImapHandler.sendNotifications(ImapHandler.java:1903)
        - locked <0x9660c6a0> (a com.zimbra.cs.mailbox.Mailbox)
        at com.zimbra.cs.imap.ImapSession.notifyPendingChanges(ImapSession.java:327)
        at com.zimbra.cs.mailbox.Mailbox.commitCache(Mailbox.java:3890)
        at com.zimbra.cs.mailbox.Mailbox.endTransaction(Mailbox.java:3880)
        at com.zimbra.cs.mailbox.Mailbox.commitCache(Mailbox.java:3890)
        at com.zimbra.cs.mailbox.Mailbox.endTransaction(Mailbox.java:3880)
        - locked <0x9660c6a0> (a com.zimbra.cs.mailbox.Mailbox)
        at com.zimbra.cs.mailbox.Mailbox.addMessageInternal(Mailbox.java:2886)
        - locked <0x9660c6a0> (a com.zimbra.cs.mailbox.Mailbox)
        at com.zimbra.cs.mailbox.Mailbox.addMessage(Mailbox.java:2651)
        - locked <0x9660c6a0> (a com.zimbra.cs.mailbox.Mailbox)
        at com.zimbra.cs.mailbox.Mailbox.addMessage(Mailbox.java:2641)
        - locked <0x9660c6a0> (a com.zimbra.cs.mailbox.Mailbox)
        at com.zimbra.cs.filter.ZimbraMailAdapter.addMessage(ZimbraMailAdapter.java:338)
        at com.zimbra.cs.filter.ZimbraMailAdapter.doDefaultFiling(ZimbraMailAdapter.java:292)
        at com.zimbra.cs.filter.ZimbraMailAdapter.executeActions(ZimbraMailAdapter.java:221)
        at org.apache.jsieve.SieveFactory.evaluate(SieveFactory.java:151)
        at com.zimbra.cs.filter.RuleManager.applyRules(RuleManager.java:175)
        at com.zimbra.cs.lmtpserver.ZimbraLmtpBackend.deliverMessageToLocalMailboxes(ZimbraLmtpBackend.ja$
        at com.zimbra.cs.lmtpserver.ZimbraLmtpBackend.deliver(ZimbraLmtpBackend.java:107)
        at com.zimbra.cs.lmtpserver.LmtpHandler.doDATA(LmtpHandler.java:419)
        at com.zimbra.cs.lmtpserver.LmtpHandler.processCommand(LmtpHandler.java:196)
        at com.zimbra.cs.tcpserver.ProtocolHandler.processConnection(ProtocolHandler.java:230)
        at com.zimbra.cs.lmtpserver.LmtpHandler.processCommand(LmtpHandler.java:196)
        at com.zimbra.cs.tcpserver.ProtocolHandler.processConnection(ProtocolHandler.java:230)
        at com.zimbra.cs.tcpserver.ProtocolHandler.run(ProtocolHandler.java:197)
        at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(Unknown Source)
        at java.lang.Thread.run(Thread.java:595)

"http-7071-Processor50" daemon prio=1 tid=0x085285a8 nid=0x52d1 runnable [0x805f5000..0x805f5e30]
        at java.net.PlainSocketImpl.socketAccept(Native Method)
        at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384)
        - locked <0x960cee20> (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 org.apache.tomcat.util.net.jsse.JSSESocketFactory.acceptSocket(JSSESocketFactory.java:110)
        at org.apache.tomcat.util.net.PoolTcpEndpoint.acceptSocket(PoolTcpEndpoint.java:406)
        at org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:70)
        at org.apache.tomcat.util.net.PoolTcpEndpoint.acceptSocket(PoolTcpEndpoint.java:406)
        at org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:70)
        at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:684)
        at java.lang.Thread.run(Thread.java:595)


"ImapSSLServer-4" prio=1 tid=0x08437ad0 nid=0x1102 runnable [0x8006a000..0x8006aeb0]
        at java.net.SocketInputStream.socketRead0(Native Method)
        at java.net.SocketInputStream.read(SocketInputStream.java:129)
        at com.sun.net.ssl.internal.ssl.InputRecord.readFully(InputRecord.java:284)
        at com.sun.net.ssl.internal.ssl.InputRecord.read(InputRecord.java:319)
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:720)
        - locked <0x937b8458> (a java.lang.Object)
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:677)
        at com.sun.net.ssl.internal.ssl.AppInputStream.read(AppInputStream.java:75)
        - locked <0x937b84e0> (a com.sun.net.ssl.internal.ssl.AppInputStream)
        at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
        at java.io.BufferedInputStream.read(BufferedInputStream.java:235)
        - locked <0x937ba508> (a com.zimbra.cs.tcpserver.TcpServerInputStream)
        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:480)
        at com.zimbra.cs.tcpserver.ProtocolHandler.processConnection(ProtocolHandler.java:230)
        at com.zimbra.cs.tcpserver.ProtocolHandler.run(ProtocolHandler.java:197)
        at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(Unknown Source)
        at com.zimbra.cs.tcpserver.ProtocolHandler.run(ProtocolHandler.java:197)
        at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(Unknown Source)
        at java.lang.Thread.run(Thread.java:595)

"ImapServer-9" prio=1 tid=0x087896f8 nid=0x979 waiting for monitor entry [0x800eb000..0x800ebe30]
        at com.zimbra.cs.mailbox.Mailbox.addListener(Mailbox.java:363)
        - waiting to lock <0x9660c6a0> (a com.zimbra.cs.mailbox.Mailbox)
        at com.zimbra.cs.session.Session.<init>(Session.java:62)
        at com.zimbra.cs.imap.ImapSession.<init>(ImapSession.java:70)
        at com.zimbra.cs.session.SessionCache.getNewSession(SessionCache.java:79)
        at com.zimbra.cs.imap.ImapHandler.doLOGIN(ImapHandler.java:683)
        at com.zimbra.cs.imap.ImapHandler$ImapCommand.execute(ImapHandler.java:424)
        at com.zimbra.cs.imap.ImapHandler.processCommand(ImapHandler.java:502)
        at com.zimbra.cs.tcpserver.ProtocolHandler.processConnection(ProtocolHandler.java:230)
        at com.zimbra.cs.tcpserver.ProtocolHandler.run(ProtocolHandler.java:197)
        at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(Unknown Source)
        at java.lang.Thread.run(Thread.java:595)


"VM Thread" prio=1 tid=0x080b5c58 nid=0x51bf runnable

"VM Periodic Task Thread" prio=1 tid=0x080c7aa8 nid=0x51c5 waiting on condition

I um, removed some stuff that looked very similar.. hope this is good.

[dkarp]

Looks like we may have some lock contention issues. Unfortunately, I think you've snipped the info we need. Please attach the whole stack dump as a file -- when composing a message, go to Additional Options > Manage Attachments > Upload File.

[adobrin]

this problem is increasing in frequency dramatically.

attached are two -QUIT logs.

[adobrin]

as an update,

we've stopped using the outlook connector and i've set the treo to "offline".. the problem seems to have stopped.

i think i'm going to start using the treo again, see if we can narrow this down

[dkarp]

The problem (at least in the second dump) is that we're doing new-message notification to an IMAP connection running the IDLE command, and the write is blocking for some reason. Unfortunately, the lock on the Mailbox is being held by this thread, so everything else backs up waiting for the write to finish and the lock to be released. And the write never finishes.

This will almost certainly go away when we switch to our new IMAP/POP/LMTP framework, as it does network writes from a different thread pool. For now, we'll see what we can do to figure out a temporary workaround.

Thanks very much for the full thread dump!