We have dealed with some problems regarding logging and other strage behaviours, but fortunately all of them have been solved.
However, there is a problem that we cannot address.
When sending an email from main server vÃÂa SMTP (auth) we ramdonly get an error form saslauth.
It appears that our main server (serverA) is trying to authenticate via soap in serverB, and in serverB there is no account for thist user. After retrying once or twice, user authenticate and email is sent properly.
Nov 2 11:02:19 serverA postfix/smtpd[8397]: connect from V0000261.foo.bar[XX.XX.XX.24]
Nov 2 11:02:19 serverA postfix/smtpd[8397]: setting up TLS connection from V0000261.foo.bar[XX.XX.XX.24]
Nov 2 11:02:19 serverA postfix/smtpd[8397]: Anonymous TLS connection established from V0000261.foo.bar[XX.XX.XX.24]: TLSv1 with cipher AES256-SHA (256/256 bits)
Nov 2 11:02:20 serverA saslauthd[12188]: zmauth: authenticating against elected url 'https://serverB.foo.bar:7071/service/admin/soap">https://serverB.foo.bar:7071/service/admin/soap">https://serverB.foo.bar:7071/service/admin/soap">https://serverB.foo.bar:7071/service/admin/soap">https://serverB.foo.bar:7071/service/admin/soap">https://serverB.foo.bar:7071/service/admin/soap">https://serverB.foo.bar:7071/service/admin/soap">https://serverB.foo.bar:7071/service/admin/soap/' ...
Nov 2 11:02:20 serverA slapd[3961]: slap_queue_csn: queing 0x44005320 20101102100224.133680Z#000000#000#000000
Nov 2 11:02:20 serverA slapd[3961]: slap_queue_csn: queing 0xa074650 20101102100224.133680Z#000000#000#000000
Nov 2 11:02:20 serverB slapd[1103]: do_syncrep2: rid=100 cookie=rid=100,csn=20101102100224.133680Z#000000#000#000000
Nov 2 11:02:20 serverB slapd[1103]: slap_queue_csn: queing 0x6fd1b5b 20101102100224.133680Z#000000#000#000000
Nov 2 11:02:20 serverA slapd[3961]: syncprov_sendresp: cookie=rid=100,csn=20101102100224.133680Z#000000#000#000000
Nov 2 11:02:20 serverA slapd[3961]: slap_graduate_commit_csn: removing 0x8bc94e0 20101102100224.133680Z#000000#000#000000
Nov 2 11:02:20 serverB slapd[1103]: slap_graduate_commit_csn: removing 0x8405300 20101102100224.133680Z#000000#000#000000
Nov 2 11:02:20 serverB slapd[1103]: syncrepl_message_to_op: rid=100 be_modify uid=csaiz,ou=people,dc=vectorsf,dc=com (0)
Nov 2 11:02:20 serverB slapd[1103]: slap_queue_csn: queing 0x85de510 20101102100224.133680Z#000000#000#000000
Nov 2 11:02:20 serverB slapd[1103]: slap_graduate_commit_csn: removing 0x8823750 20101102100224.133680Z#000000#000#000000
Nov 2 11:02:20 serverA slapd[3961]: slap_graduate_commit_csn: removing 0x8aa3a50 20101102100224.133680Z#000000#000#000000
Nov 2 11:02:20 serverA saslauthd[12188]: zmpost: url='https://serverB.foo.bar:7071/service/admin/soap">https://serverB.foo.bar:7071/service/admin/soap">https://serverB.foo.bar:7071/service/admin/soap">https://serverB.foo.bar:7071/service/admin/soap">https://serverB.foo.bar:7071/service/admin/soap">https://serverB.foo.bar:7071/service/admin/soap">https://serverB.foo.bar:7071/service/admin/soap">https://serverB.foo.bar:7071/service/admin/soap/' returned buffer->data='http://www.w3.org/2003/05/soap-envelope">">http://www.w3.org/2003/05/soap-envelope"> xmlns="urn:zimbra"/>soap:Senderauthentication failed for csaizaccount.AUTH_FAILEDcom.zimbra.cs.account.AccountServiceException$AuthFailedServiceException: authentication failed for csaiz ExceptionId:btpool0-6://serverB.foo.bar:7071/service/admin/soap/:1288692140148:d5cfb0002ea62c49 Code:account.AUTH_FAILED #011at com.zimbra.cs.account.AccountServiceException$AuthFailedServiceException.AUTH_FAILED(AccountServiceException.java:130) #011at com.zimbra.cs.account.AccountServiceException$AuthFailedServiceException.AUTH_FAILED(AccountServiceException.java:126) #011at com.zimbra.cs.account.auth.AuthMechanism$ZimbraAuth.do
Nov 2 11:02:20 serverA saslauthd[12188]: auth_zimbra: csaiz auth failed: authentication failed for csaiz
Nov 2 11:02:20 serverA saslauthd[12188]: do_auth : auth failure: [user=csaiz] [service=smtp] [realm=] [mech=zimbra] [reason=Unknown]
Nov 2 11:02:20 serverA postfix/smtpd[8397]: warning: SASL authentication failure: Password verification failed
Nov 2 11:02:20 serverA postfix/smtpd[8397]: warning: V0000261.foo.bar[XX.XX.XX.24]: SASL PLAIN authentication failed: authentication failure
Nov 2 11:02:20 serverA saslauthd[12187]: zmauth: authenticating against elected url 'https://serverB.foo.bar:7071/service/admin/soap">https://serverB.foo.bar:7071/service/admin/soap">https://serverB.foo.bar:7071/service/admin/soap">https://serverB.foo.bar:7071/service/admin/soap">https://serverB.foo.bar:7071/service/admin/soap">https://serverB.foo.bar:7071/service/admin/soap">https://serverB.foo.bar:7071/service/admin/soap">https://serverB.foo.bar:7071/service/admin/soap/' ...
Nov 2 11:02:20 serverA saslauthd[12187]: zmpost: url='https://serverB.foo.bar:7071/service/admin/soap">https://serverB.foo.bar:7071/service/admin/soap">https://serverB.foo.bar:7071/service/admin/soap">https://serverB.foo.bar:7071/service/admin/soap">https://serverB.foo.bar:7071/service/admin/soap">https://serverB.foo.bar:7071/service/admin/soap">https://serverB.foo.bar:7071/service/admin/soap">https://serverB.foo.bar:7071/service/admin/soap/' returned buffer->data='http://www.w3.org/2003/05/soap-envelope">">http://www.w3.org/2003/05/soap-envelope"> xmlns="urn:zimbra"/>soap:Senderauthentication failed for csaizaccount.AUTH_FAILEDcom.zimbra.cs.account.AccountServiceException$AuthFailedServiceException: authentication failed for csaiz ExceptionId:btpool0-6://serverB.foo.bar:7071/service/admin/soap/:1288692140468:d5cfb0002ea62c49 Code:account.AUTH_FAILED #011at com.zimbra.cs.account.AccountServiceException$AuthFailedServiceException.AUTH_FAILED(AccountServiceException.java:130) #011at com.zimbra.cs.account.AccountServiceException$AuthFailedServiceException.AUTH_FAILED(AccountServiceException.java:126) #011at com.zimbra.cs.account.auth.AuthMechanism$ZimbraAuth.do
Nov 2 11:02:20 serverA saslauthd[12187]: auth_zimbra: csaiz auth failed: authentication failed for csaiz
Nov 2 11:02:20 serverA saslauthd[12187]: do_auth : auth failure: [user=csaiz] [service=smtp] [realm=] [mech=zimbra] [reason=Unknown]
Nov 2 11:02:20 serverA postfix/smtpd[8397]: warning: V0000261.foo.bar[XX.XX.XX.24]: SASL LOGIN authentication failed: authentication failure
And mailbox.log
2010-11-02 11:02:20,067 INFO [btpool0-6://serverB.foo.bar:7071/service/admin/soap/] [ip=XX.XX.XX.30;] soap - AuthRequest
2010-11-02 11:02:20,147 WARN [btpool0-6://serverB.foo.bar:7071/service/admin/soap/] [name=csaiz@foo.bar;ip=XX.XX.XX.30;] account - ldap auth for domain foo.bar failed, fall back to zimbra default auth mechanism
com.zimbra.common.service.ServiceException: system failure: sun.security.validator.ValidatorException: PKIX path building failed: sun.security.provider.certpath.SunCertPathBuilderException: unable to find valid certification path to requested target
ExceptionId:btpool0-6://serverB.foo.bar:7071/service/admin/soap/:1288692140147:d5cfb0002ea62c49
Code:service.FAILURE
at com.zimbra.common.service.ServiceException.FAILURE(ServiceException.java:248)
at com.zimbra.cs.account.ldap.LdapProvisioning.externalLdapAuth(LdapProvisioning.java:3556)
at com.zimbra.cs.account.auth.AuthMechanism$LdapAuth.doAuth(AuthMechanism.java:165)
at com.zimbra.cs.account.ldap.LdapProvisioning.verifyPasswordInternal(LdapProvisioning.java:3600)
at com.zimbra.cs.account.ldap.LdapProvisioning.verifyPassword(LdapProvisioning.java:3573)
at com.zimbra.cs.account.ldap.LdapProvisioning.authAccount(LdapProvisioning.java:3439)
at com.zimbra.cs.account.ldap.LdapProvisioning.authAccount(LdapProvisioning.java:3418)
at com.zimbra.cs.service.account.Auth.handle(Auth.java:118)
at com.zimbra.soap.SoapEngine.dispatchRequest(SoapEngine.java:420)
at com.zimbra.soap.SoapEngine.dispatch(SoapEngine.java:274)
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:155)
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:216)
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.net.ssl.SSLHandshakeException: sun.security.validator.ValidatorException: PKIX path building failed: sun.security.provider.certpath.SunCertPathBuilderException: unable to find valid certification path to requested target
at com.sun.net.ssl.internal.ssl.Alerts.getSSLException(Alerts.java:174)
at com.sun.net.ssl.internal.ssl.SSLSocketImpl.fatal(SSLSocketImpl.java:1623)
at com.sun.net.ssl.internal.ssl.Handshaker.fatalSE(Handshaker.java:198)
at com.sun.net.ssl.internal.ssl.Handshaker.fatalSE(Handshaker.java:192)
at com.sun.net.ssl.internal.ssl.ClientHandshaker.serverCertificate(ClientHandshaker.java:1074)
at com.sun.net.ssl.internal.ssl.ClientHandshaker.processMessage(ClientHandshaker.java:128)
at com.sun.net.ssl.internal.ssl.Handshaker.processLoop(Handshaker.java:529)
at com.sun.net.ssl.internal.ssl.Handshaker.process_record(Handshaker.java:465)
at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:884)
at com.sun.net.ssl.internal.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1120)
at com.sun.net.ssl.internal.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1147)
at com.sun.net.ssl.internal.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1131)
at com.sun.jndi.ldap.ext.StartTlsResponseImpl.startHandshake(StartTlsResponseImpl.java:344)
at com.sun.jndi.ldap.ext.StartTlsResponseImpl.negotiate(StartTlsResponseImpl.java:208)
at com.sun.jndi.ldap.ext.StartTlsResponseImpl.negotiate(StartTlsResponseImpl.java:161)
at com.zimbra.cs.account.ldap.ZimbraLdapContext.tlsNegotiate(ZimbraLdapContext.java:359)
at com.zimbra.cs.account.ldap.ZimbraLdapContext.(ZimbraLdapContext.java:492)
at com.zimbra.cs.account.ldap.ZimbraLdapContext.(ZimbraLdapContext.java:426)
at com.zimbra.cs.account.ldap.LdapUtil.ldapAuthenticate(LdapUtil.java:120)
at com.zimbra.cs.account.ldap.LdapProvisioning.externalLdapAuth(LdapProvisioning.java:3537)
... 41 more
Caused by: sun.security.validator.ValidatorException: PKIX path building failed: sun.security.provider.certpath.SunCertPathBuilderException: unable to find valid certification path to requested target
at sun.security.validator.PKIXValidator.doBuild(PKIXValidator.java:325)
at sun.security.validator.PKIXValidator.engineValidate(PKIXValidator.java:219)
at sun.security.validator.Validator.validate(Validator.java:218)
at com.sun.net.ssl.internal.ssl.X509TrustManagerImpl.validate(X509TrustManagerImpl.java:126)
at com.sun.net.ssl.internal.ssl.X509TrustManagerImpl.checkServerTrusted(X509TrustManagerImpl.java:209)
at com.sun.net.ssl.internal.ssl.X509TrustManagerImpl.checkServerTrusted(X509TrustManagerImpl.java:249)
at com.sun.net.ssl.internal.ssl.ClientHandshaker.serverCertificate(ClientHandshaker.java:1053)
... 56 more
Caused by: sun.security.provider.certpath.SunCertPathBuilderException: unable to find valid certification path to requested target
at sun.security.provider.certpath.SunCertPathBuilder.engineBuild(SunCertPathBuilder.java:174)
at java.security.cert.CertPathBuilder.build(CertPathBuilder.java:238)
at sun.security.validator.PKIXValidator.doBuild(PKIXValidator.java:320)
... 62 more
2010-11-02 11:02:20,513 INFO [btpool0-6://serverB.foo.bar:7071/service/admin/soap/] [name=csaiz@foo.bar;ip=XX.XX.XX.30;] SoapEngine - handler exception: authentication failed for csaiz, invalid password
2010-11-02 11:02:20,515 WARN [btpool0-6] [] log - SSL renegotiate denied: java.nio.channels.SocketChannel[connected local=/XX.XX.XX.130:7071 remote=/XX.XX.XX.30:50901]
2