During a migration with imapsync, Zimbra seems to be dropping the IMAP connection.
When this happens, users can no longer log in to their mailboxes and the web administration interface can not be launched. Restarting the services corrects the issue for a while, but it always comes back. Sometime it will start working again without a restart, sometimes it will not. I have a single large mailbox that I have been trying to migrate for three full workdays (a week if you include time off for holidays) and if this server were in production I would have a lot of very unhappy users.
imapsync looks like this when it happens:
At the same time in /opt/zimbra/log/mailbox.log:Code:msg INBOX/Stuff/10 copied to INBOX/Stuff/50622 msg INBOX/Stuff/11 couldn't append (Subject:[Stuff]) to folder INBOX: 50623 NO must be in AUTHENTICATED or SELECTED state
If I try to use the administation interface at this time, I get:Code:2010-11-29 09:43:48,191 WARN [ImapSSLServer-1] [name=lotsamail@mydomain.com;mid=4;ip=10.1.0.35;] imap - error checking account status; dropping connection com.zimbra.common.service.ServiceException: system failure: ZimbraLdapContext ExceptionId:ImapSSLServer-1:1291041828184:ae9680020b3c2016 Code:service.FAILURE at com.zimbra.common.service.ServiceException.FAILURE(ServiceException.java:248) at com.zimbra.cs.account.ldap.ZimbraLdapContext.<init>(ZimbraLdapContext.java:416) at com.zimbra.cs.account.ldap.ZimbraLdapContext.<init>(ZimbraLdapContext.java:366) at com.zimbra.cs.account.ldap.LdapProvisioning.getDomainByQuery(LdapProvisioning.java:1829) at com.zimbra.cs.account.ldap.LdapProvisioning.getDomainByAsciiNameInternal(LdapProvisioning.java:1934) at com.zimbra.cs.account.ldap.LdapProvisioning.getDomainByNameInternal(LdapProvisioning.java:1919) at com.zimbra.cs.account.ldap.LdapProvisioning.getDomain(LdapProvisioning.java:1868) at com.zimbra.cs.account.Provisioning.getDomain(Provisioning.java:360) at com.zimbra.cs.account.Provisioning.getCOS(Provisioning.java:396) at com.zimbra.cs.account.ldap.LdapProvisioning.setAccountDefaults(LdapProvisioning.java:4169) at com.zimbra.cs.account.ldap.LdapProvisioning.makeAccount(LdapProvisioning.java:4157) at com.zimbra.cs.account.ldap.LdapProvisioning.makeAccount(LdapProvisioning.java:4140) at com.zimbra.cs.account.ldap.LdapProvisioning.getAccountByQuery(LdapProvisioning.java:617) at com.zimbra.cs.account.ldap.LdapProvisioning.getAccountById(LdapProvisioning.java:640) at com.zimbra.cs.account.ldap.LdapProvisioning.get(LdapProvisioning.java:664) at com.zimbra.cs.account.ldap.LdapProvisioning.get(LdapProvisioning.java:653) at com.zimbra.cs.imap.ImapCredentials.getAccount(ImapCredentials.java:88) at com.zimbra.cs.imap.ImapHandler.checkAccountStatus(ImapHandler.java:244) at com.zimbra.cs.imap.TcpImapHandler.processCommand(TcpImapHandler.java:91) at com.zimbra.cs.tcpserver.ProtocolHandler.processConnection(ProtocolHandler.java:196) at com.zimbra.cs.tcpserver.ProtocolHandler.run(ProtocolHandler.java:139) at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(Unknown Source) at java.lang.Thread.run(Thread.java:662) Caused by: javax.naming.CommunicationException: Bad file descriptor [Root exception is java.net.SocketException: Bad file descriptor] at com.sun.jndi.ldap.LdapCtx.extendedOperation(LdapCtx.java:3213) at javax.naming.ldap.InitialLdapContext.extendedOperation(InitialLdapContext.java:164) at com.zimbra.cs.account.ldap.ZimbraLdapContext.<init>(ZimbraLdapContext.java:406) ... 21 more Caused by: java.net.SocketException: Bad file descriptor at java.net.SocketOutputStream.socketWrite0(Native Method) at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:92) at java.net.SocketOutputStream.write(SocketOutputStream.java:136) at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:65) at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:123) at com.sun.jndi.ldap.Connection.writeRequest(Connection.java:396) at com.sun.jndi.ldap.LdapClient.extendedOp(LdapClient.java:1172) at com.sun.jndi.ldap.LdapCtx.extendedOperation(LdapCtx.java:3160) ... 23 more 2010-11-29 09:43:48,194 INFO [ImapSSLServer-1] [] ProtocolHandler - Handler exiting normally 2010-11-29 09:43:48,214 INFO [ImapSSLServer-2] [] imap - [10.1.0.35] connected 2010-11-29 09:43:48,284 WARN [ImapSSLServer-2] [ip=10.1.0.35;] imap - LOGIN failed com.zimbra.common.service.ServiceException: system failure: ZimbraLdapContext ExceptionId:ImapSSLServer-2:1291041828283:ae9680020b3c2016 Code:service.FAILURE at com.zimbra.common.service.ServiceException.FAILURE(ServiceException.java:248) at com.zimbra.cs.account.ldap.ZimbraLdapContext.<init>(ZimbraLdapContext.java:416) at com.zimbra.cs.account.ldap.ZimbraLdapContext.<init>(ZimbraLdapContext.java:366) at com.zimbra.cs.account.ldap.LdapProvisioning.getDomainByQuery(LdapProvisioning.java:1829) at com.zimbra.cs.account.ldap.LdapProvisioning.getDomainByAsciiNameInternal(LdapProvisioning.java:1934) at com.zimbra.cs.account.ldap.LdapProvisioning.getDomainByNameInternal(LdapProvisioning.java:1919) at com.zimbra.cs.account.ldap.LdapProvisioning.getDomain(LdapProvisioning.java:1868) at com.zimbra.cs.account.Provisioning.getDomain(Provisioning.java:360) at com.zimbra.cs.account.Provisioning.getCOS(Provisioning.java:396) at com.zimbra.cs.account.ldap.LdapProvisioning.setAccountDefaults(LdapProvisioning.java:4169) at com.zimbra.cs.account.ldap.LdapProvisioning.makeAccount(LdapProvisioning.java:4157) at com.zimbra.cs.account.ldap.LdapProvisioning.makeAccount(LdapProvisioning.java:4140) at com.zimbra.cs.account.ldap.LdapProvisioning.getAccountByQuery(LdapProvisioning.java:617) at com.zimbra.cs.account.ldap.LdapProvisioning.getAccountByNameInternal(LdapProvisioning.java:776) at com.zimbra.cs.account.ldap.LdapProvisioning.getAccountByName(LdapProvisioning.java:757) at com.zimbra.cs.account.ldap.LdapProvisioning.get(LdapProvisioning.java:668) at com.zimbra.cs.account.ldap.LdapProvisioning.get(LdapProvisioning.java:653) at com.zimbra.cs.security.sasl.PlainAuthenticator.authenticate(PlainAuthenticator.java:85) at com.zimbra.cs.imap.ImapHandler.authenticate(ImapHandler.java:1146) at com.zimbra.cs.imap.ImapHandler.doLOGIN(ImapHandler.java:1109) at com.zimbra.cs.imap.ImapHandler.executeRequest(ImapHandler.java:443) at com.zimbra.cs.imap.TcpImapHandler.processCommand(TcpImapHandler.java:98) at com.zimbra.cs.tcpserver.ProtocolHandler.processConnection(ProtocolHandler.java:196) at com.zimbra.cs.tcpserver.ProtocolHandler.run(ProtocolHandler.java:139) at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(Unknown Source) at java.lang.Thread.run(Thread.java:662) Caused by: javax.naming.CommunicationException: Bad file descriptor [Root exception is java.net.SocketException: Bad file descriptor] at com.sun.jndi.ldap.LdapCtx.extendedOperation(LdapCtx.java:3213) at javax.naming.ldap.InitialLdapContext.extendedOperation(InitialLdapContext.java:164) at com.zimbra.cs.account.ldap.ZimbraLdapContext.<init>(ZimbraLdapContext.java:406) ... 24 more Caused by: java.net.SocketException: Bad file descriptor at java.net.SocketOutputStream.socketWrite0(Native Method) at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:92) at java.net.SocketOutputStream.write(SocketOutputStream.java:136) at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:65) at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:123) at com.sun.jndi.ldap.Connection.writeRequest(Connection.java:396) at com.sun.jndi.ldap.LdapClient.extendedOp(LdapClient.java:1172) at com.sun.jndi.ldap.LdapCtx.extendedOperation(LdapCtx.java:3160) ... 26 more 2010-11-29 09:45:07,070 INFO [ImapSSLServer-2] [ip=10.1.0.35;] ProtocolHandler - Exception occurred while handling connection java.io.EOFException: Unexpected end of stream at com.zimbra.cs.imap.Literal$BlobLiteral.copy(Literal.java:169) at com.zimbra.cs.imap.TcpImapRequest.continueLiteral(TcpImapRequest.java:109) at com.zimbra.cs.imap.TcpImapRequest.continuation(TcpImapRequest.java:48) at com.zimbra.cs.imap.TcpImapHandler.processCommand(TcpImapHandler.java:83) at com.zimbra.cs.tcpserver.ProtocolHandler.processConnection(ProtocolHandler.java:196) at com.zimbra.cs.tcpserver.ProtocolHandler.run(ProtocolHandler.java:139) at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(Unknown Source) at java.lang.Thread.run(Thread.java:662) 2010-11-29 09:45:07,072 INFO [ImapSSLServer-2] [] ProtocolHandler - Handler exiting normally
Any ideas?Code:2010-11-29 09:56:11,359 INFO [btpool0-0://mail.mydomain.com:7071/service/admin/soap/AuthRequest] [ip=10.1.0.189;ua=ZimbraWebClient - FF3.0 (Win);] soap - AuthRequest 2010-11-29 09:56:11,405 INFO [btpool0-0://mail.mydomain.com:7071/service/admin/soap/AuthRequest] [name=admin@mydomain.com;ip=10.1.0.189;ua=ZimbraWebClient - FF3.0 (Win);] index - Initialized Index for mailbox 2 directory: LuceneIndex at com.zimbra.cs.index.Z23FSDirectory@/opt/zimbra/index/0/2/index/0 Analyzer=com.zimbra.cs.index.ZimbraAnalyzer@6c5bdfae 2010-11-29 09:56:11,405 INFO [btpool0-0://mail.mydomain.com:7071/service/admin/soap/AuthRequest] [name=admin@mydomain.com;ip=10.1.0.189;ua=ZimbraWebClient - FF3.0 (Win);] cache - initializing folder and tag caches for mailbox 2 2010-11-29 09:56:11,471 INFO [btpool0-0://mail.mydomain.com:7071/service/admin/soap/AuthRequest] [name=admin@mydomain.com;ip=10.1.0.189;ua=ZimbraWebClient - FF3.0 (Win);] mbxmgr - Mailbox 2 account a066ecab-4f89-4d03-bed5-987d0380d91d LOADED 2010-11-29 09:56:11,486 INFO [btpool0-0://mail.mydomain.com:7071/service/admin/soap/GetInfoRequest] [name=admin@mydomain.com;mid=2;ip=10.1.0.189;ua=ZimbraWebClient - FF3.0 (Win);] soap - GetInfoRequest 2010-11-29 09:56:12,044 INFO [btpool0-8://localhost:7071/service/admin/soap/GetDomainInfoRequest] [ip=127.0.0.1;] soap - GetDomainInfoRequest 2010-11-29 09:56:12,051 INFO [btpool0-0://mail.mydomain.com:7071/service/zimlet/res/Zimlets-nodev_all.js.zgz.js?v=101115230502] [] zimlet - unable to get list of zimlets 2010-11-29 09:56:12,065 INFO [btpool0-0://mail.mydomain.com:7071/service/admin/soap/GetEffectiveRightsRequest] [name=admin@mydomain.com;mid=2;ip=10.1.0.189;ua=ZimbraWebClient - FF3.0 (Win);] soap - GetEffectiveRightsRequest 2010-11-29 09:56:12,117 INFO [btpool0-0://mail.mydomain.com:7071/service/admin/soap/BatchRequest] [name=admin@mydomain.com;mid=2;ip=10.1.0.189;ua=ZimbraWebClient - FF3.0 (Win);] soap - BatchRequest 2010-11-29 09:56:12,117 INFO [btpool0-0://mail.mydomain.com:7071/service/admin/soap/BatchRequest] [name=admin@mydomain.com;mid=2;ip=10.1.0.189;ua=ZimbraWebClient - FF3.0 (Win);] soap - (batch) GetAccountRequest 2010-11-29 09:56:12,118 INFO [btpool0-0://mail.mydomain.com:7071/service/admin/soap/BatchRequest] [name=admin@mydomain.com;mid=2;ip=10.1.0.189;ua=ZimbraWebClient - FF3.0 (Win);] misc - delegated access: doc=GetAccount, authenticated account=admin@mydomain.com, target account=admin@mydomain.com 2010-11-29 09:56:12,119 INFO [btpool0-0://mail.mydomain.com:7071/service/admin/soap/BatchRequest] [name=admin@mydomain.com;mid=2;ip=10.1.0.189;ua=ZimbraWebClient - FF3.0 (Win);] soap - (batch) GetAccountMembershipRequest 2010-11-29 09:56:12,119 INFO [btpool0-0://mail.mydomain.com:7071/service/admin/soap/BatchRequest] [name=admin@mydomain.com;mid=2;ip=10.1.0.189;ua=ZimbraWebClient - FF3.0 (Win);] misc - delegated access: doc=GetAccountMembership, authenticated account=admin@mydomain.com, target account=admin@mydomain.com 2010-11-29 09:56:12,122 INFO [btpool0-0://mail.mydomain.com:7071/service/admin/soap/BatchRequest] [name=admin@mydomain.com;mid=2;ip=10.1.0.189;ua=ZimbraWebClient - FF3.0 (Win);] SoapEngine - handler exception com.zimbra.common.service.ServiceException: system failure: ZimbraLdapContext ExceptionId:btpool0-0://mail.mydomain.com:7071/service/admin/soap/BatchRequest:1291042572121:ae9680020b3c2016 Code:service.FAILURE at com.zimbra.common.service.ServiceException.FAILURE(ServiceException.java:248) at com.zimbra.cs.account.ldap.ZimbraLdapContext.<init>(ZimbraLdapContext.java:416) at com.zimbra.cs.account.ldap.ZimbraLdapContext.<init>(ZimbraLdapContext.java:381) at com.zimbra.cs.account.ldap.LdapProvisioning.searchObjects(LdapProvisioning.java:1263) at com.zimbra.cs.account.ldap.LdapProvisioning.searchObjects(LdapProvisioning.java:1244) at com.zimbra.cs.account.ldap.LdapProvisioning.searchObjects(LdapProvisioning.java:1161) at com.zimbra.cs.account.ldap.LdapProvisioning.searchAccountsInternal(LdapProvisioning.java:1101) at com.zimbra.cs.account.ldap.LdapProvisioning.getAllDistributionListsForAddresses(LdapProvisioning.java:4302) at com.zimbra.cs.account.ldap.LdapProvisioning.getAllDirectGroups(LdapProvisioning.java:4369) at com.zimbra.cs.account.ldap.LdapProvisioning.getGroupsInternal(LdapProvisioning.java:4475) at com.zimbra.cs.account.ldap.LdapProvisioning.getGroups(LdapProvisioning.java:4314) at com.zimbra.cs.account.ldap.LdapProvisioning.getDistributionLists(LdapProvisioning.java:4552) at com.zimbra.cs.account.ldap.LdapProvisioning.getDistributionLists(LdapProvisioning.java:4547) at com.zimbra.cs.service.admin.GetAccountMembership.handle(GetAccountMembership.java:70) at com.zimbra.soap.SoapEngine.dispatchRequest(SoapEngine.java:420) at com.zimbra.soap.SoapEngine.dispatch(SoapEngine.java:264) at com.zimbra.soap.SoapEngine.dispatch(SoapEngine.java:158) at com.zimbra.soap.SoapServlet.doWork(SoapServlet.java:291) at com.zimbra.soap.SoapServlet.doPost(SoapServlet.java:212) at javax.servlet.http.HttpServlet.service(HttpServlet.java:727) at com.zimbra.cs.servlet.ZimbraServlet.service(ZimbraServlet.java:181) at javax.servlet.http.HttpServlet.service(HttpServlet.java:820) at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:511) at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1166) at com.zimbra.cs.servlet.SetHeaderFilter.doFilter(SetHeaderFilter.java:79) at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157) at org.mortbay.servlet.UserAgentFilter.doFilter(UserAgentFilter.java:81) at org.mortbay.servlet.GzipFilter.doFilter(GzipFilter.java:132) at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157) at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:388) at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:218) at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:182) at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:765) at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:418) at org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:230) at org.mortbay.jetty.handler.HandlerCollection.handle(HandlerCollection.java:114) at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152) at org.mortbay.jetty.handler.rewrite.RewriteHandler.handle(RewriteHandler.java:230) at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152) at org.mortbay.jetty.handler.DebugHandler.handle(DebugHandler.java:77) at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152) at org.mortbay.jetty.Server.handle(Server.java:326) at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:543) at org.mortbay.jetty.HttpConnection$RequestHandler.content(HttpConnection.java:939) at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:755) at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:218) at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:405) at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:413) at org.mortbay.thread.BoundedThreadPool$PoolThread.run(BoundedThreadPool.java:451) Caused by: javax.naming.CommunicationException: Bad file descriptor [Root exception is java.net.SocketException: Bad file descriptor] at com.sun.jndi.ldap.LdapCtx.extendedOperation(LdapCtx.java:3213) at javax.naming.ldap.InitialLdapContext.extendedOperation(InitialLdapContext.java:164) at com.zimbra.cs.account.ldap.ZimbraLdapContext.<init>(ZimbraLdapContext.java:406) ... 47 more Caused by: java.net.SocketException: Bad file descriptor at java.net.SocketOutputStream.socketWrite0(Native Method) at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:92) at java.net.SocketOutputStream.write(SocketOutputStream.java:136) at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:65) at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:123) at com.sun.jndi.ldap.Connection.writeRequest(Connection.java:396) at com.sun.jndi.ldap.LdapClient.extendedOp(LdapClient.java:1172) at com.sun.jndi.ldap.LdapCtx.extendedOperation(LdapCtx.java:3160) ... 49 more 2010-11-29 09:56:12,123 INFO [btpool0-0://mail.mydomain.com:7071/service/admin/soap/BatchRequest] [name=admin@mydomain.com;mid=2;ip=10.1.0.189;ua=ZimbraWebClient - FF3.0 (Win);] soap - (batch) GetAccountInfoRequest 2010-11-29 09:56:12,123 INFO [btpool0-0://mail.mydomain.com:7071/service/admin/soap/BatchRequest] [name=admin@mydomain.com;mid=2;ip=10.1.0.189;ua=ZimbraWebClient - FF3.0 (Win);] misc - delegated access: doc=GetAccountInfo, authenticated account=admin@mydomain.com, target account=admin@mydomain.com 2010-11-29 09:56:12,123 INFO [btpool0-0://mail.mydomain.com:7071/service/admin/soap/BatchRequest] [name=admin@mydomain.com;mid=2;ip=10.1.0.189;ua=ZimbraWebClient - FF3.0 (Win);] soap - (batch) GetDataSourcesRequest 2010-11-29 09:56:12,124 INFO [btpool0-0://mail.mydomain.com:7071/service/admin/soap/BatchRequest] [name=admin@mydomain.com;mid=2;ip=10.1.0.189;ua=ZimbraWebClient - FF3.0 (Win);] misc - delegated access: doc=GetDataSources, authenticated account=admin@mydomain.com, target account=admin@mydomain.com


LinkBack URL
About LinkBacks


