Can not access admin console after 5.0.2 upgrade

[wolrah]

OK, the popup blocker was what got me.

Since there's a lot of info in there that I don't exactly want to share with the public, I've stuck it all in a file and attached it to my support case (00020350).

Just in case there was any confusion, I'm stalling here:


Just to verify that none of my (many) FF extensions were messing with it, I've also tried it in FF3 and Safari, both of which are nearly stock. Same result.

[jholder]

Greeting Sean,
Can you please stop zmmailboxd
su - zimbra
zmmailboxdctl stop

and
rm -rf /opt/zimbra/jetty/work/*
zmmailboxdctl start

and install firebug and look for errors?

[wolrah]

Just did that, posted the debug log to the case. Nothing in Firebug error-wise.

[iggy]

Greg,

The SOAP trace shows it's getting hung up on ModifyAdminSavedSearchesRequest:

ModifyAdminSavedSearchesRequest

<soap:Envelope xmlns:soap="http://www.w3.org/2003/05/soap-envelope">
<soap:Header>
<context xmlns="urn:zimbra">
<userAgent name="ZimbraWebClient - FF2.0 (Mac)"/>
<sessionId id="3643"/>
<format type="js"/>
<authToken>
0_this_69643d33363a3130626636366530token230343030393233373536303b61646dfor38you03b
</authToken>
</context>
</soap:Header>
<soap:Body>
<ModifyAdminSavedSearchesRequest xmlns="urn:zimbraAdmin">
<search name="Admin Accounts">
(|(zimbraIsAdminAccount=TRUE)(zimbraIsDomainAdminAccount=TRUE))
</search>
<search name="Locked Out Accounts">
(zimbraAccountStatus=*lockout*)
</search>
<search name="Closed Accounts">
(zimbraAccountStatus=*closed*)
</search>
<search name="Maintenance Accounts">
(zimbraAccountStatus=*maintenance*)
</search>
<search name="Non-Active Accounts">
(!(zimbraAccountStatus=*active*))
</search>
<search name="Inactive Accounts (30 days)">
(zimbraLastLogonTimestamp<=###JSON:{func: ZaSearch.getTimestampByDays, args:[-30]}###)
</search>
<search name="Inactive Accounts (90 days)">
(zimbraLastLogonTimestamp<=###JSON:{func: ZaSearch.getTimestampByDays, args:[-90]}###)
</search>
</ModifyAdminSavedSearchesRequest>
</soap:Body>
</soap:Envelope>
ROUND TRIP TIME: 57
RESPONSE

Body: {
  Fault: {
    Code: {
      Value: "soap:Receiver"
     },
    Detail: {
      Error: {
        Code: "service.FAILURE",
        Trace: "com.zimbra.common.service.ServiceException: system failure: unable to modify attrs: [LDAP: error code 50 - Insufficient Access Rights]
Code:service.FAILURE
	at com.zimbra.common.service.ServiceException.FAILURE(ServiceException.java:183)
	at com.zimbra.cs.account.ldap.LdapProvisioning.modifyAttrsInternal(LdapProvisioning.java:300)
	at com.zimbra.cs.account.ldap.LdapProvisioning.modifyAttrs(LdapProvisioning.java:268)
	at com.zimbra.cs.account.ldap.LdapProvisioning.modifyAttrs(LdapProvisioning.java:249)
	at com.zimbra.cs.account.Provisioning.modifyAttrs(Provisioning.java:1473)
	at com.zimbra.cs.service.admin.ModifyAdminSavedSearches.handle(ModifyAdminSavedSearches.java:100)
	at com.zimbra.cs.service.admin.ModifyAdminSavedSearches.handle(ModifyAdminSavedSearches.java:60)
	at com.zimbra.soap.SoapEngine.dispatchRequest(SoapEngine.java:342)
	at com.zimbra.soap.SoapEngine.dispatch(SoapEngine.java:208)
	at com.zimbra.soap.SoapEngine.dispatch(SoapEngine.java:113)
	at com.zimbra.soap.SoapServlet.doPost(SoapServlet.java:272)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
	at com.zimbra.cs.servlet.ZimbraServlet.service(ZimbraServlet.java:174)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
	at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:487)
	at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1093)
	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:1084)
	at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:360)
	at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216)
	at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:181)
	at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:716)
	at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:406)
	at org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:211)
	at org.mortbay.jetty.handler.HandlerCollection.handle(HandlerCollection.java:114)
	at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:139)
	at org.mortbay.jetty.handler.RewriteHandler.handle(RewriteHandler.java:176)
	at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:139)
	at org.mortbay.jetty.Server.handle(Server.java:313)
	at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:506)
	at org.mortbay.jetty.HttpConnection$RequestHandler.content(HttpConnection.java:844)
	at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:644)
	at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:205)
	at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:381)
	at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:396)
	at org.mortbay.thread.BoundedThreadPool$PoolThread.run(BoundedThreadPool.java:442)
Caused by: javax.naming.NoPermissionException: [LDAP: error code 50 - Insufficient Access Rights]; remaining name 'uid=sharlow,ou=people,dc=medinavoip,dc=com'
	at com.sun.jndi.ldap.LdapCtx.mapErrorCode(LdapCtx.java:3013)
	at com.sun.jndi.ldap.LdapCtx.processReturnCode(LdapCtx.java:2951)
	at com.sun.jndi.ldap.LdapCtx.processReturnCode(LdapCtx.java:2758)
	at com.sun.jndi.ldap.LdapCtx.c_modifyAttributes(LdapCtx.java:1441)
	at com.sun.jndi.toolkit.ctx.ComponentDirContext.p_modifyAttributes(ComponentDirContext.java:255)
	at com.sun.jndi.toolkit.ctx.PartialCompositeDirContext.modifyAttributes(PartialCompositeDirContext.java:172)
	at javax.naming.directory.InitialDirContext.modifyAttributes(InitialDirContext.java:153)
	at com.zimbra.cs.account.ldap.LdapUtil.modifyAttributes(LdapUtil.java:1260)
	at com.zimbra.cs.account.ldap.LdapUtil.modifyAttrs(LdapUtil.java:661)
	at com.zimbra.cs.account.ldap.LdapProvisioning.modifyAttrsInternal(LdapProvisioning.java:285)
	... 35 more
",
        _jsns: "urn:zimbra"
       }
     },
    Reason: {
      Text: "system failure: unable to modify attrs: [LDAP: error code 50 - Insufficient Access Rights]"
     }
   }
 },
Header: {
  context: {
    _jsns: "urn:zimbra",
    change: {
      token: 418768
     },
    sessionId: [
      0: {
        _content: "3643",
        id: "3643",
        type: "admin"
       }
     ]
   }
 },
_jsns: "urn:zimbraSoap"

ROUND TRIP TIME: 326

We've made modifications to ACLs for slapd and I expect you're running into something there. Greg may have a good idea of what the request is doing, but you might also try setting:

$ zmlocalconfig -e ldap_log_level=256
$ ldap stop
$ ldap start

Grep for slapd and hope for smoking gun:

$ grep slapd /var/log/zimbra.log

--
Jason Bryan
Zimbra Network Support

[wolrah]

It seems the config value was ldap_log_level, but that was easy enough to figure out.

Anyways, while I'm pretty decent with SQL I couldn't do more than guess at LDAP, so here's the nice wall of text from the time period between when I hit enter in my browser to the admin page and when it stopped loading.

Feb 25 22:59:18 baal slapd[8751]: conn=8 fd=13 ACCEPT from IP=10.0.1.4:54881 (IP=10.0.1.4:389) 
Feb 25 22:59:18 baal slapd[8751]: conn=8 op=0 BIND dn="uid=zimbra,cn=admins,cn=zimbra" method=128 
Feb 25 22:59:18 baal slapd[8751]: conn=8 op=0 BIND dn="uid=zimbra,cn=admins,cn=zimbra" mech=SIMPLE ssf=0 
Feb 25 22:59:18 baal slapd[8751]: conn=8 op=0 RESULT tag=97 err=0 text= 
Feb 25 22:59:18 baal slapd[8751]: conn=8 op=1 SRCH base="cn=baal.medinavoip.com,cn=servers,cn=zimbra" scope=0 deref=3 filter="(objectClass=*)" 
Feb 25 22:59:18 baal slapd[8751]: conn=8 op=1 SEARCH RESULT tag=101 err=0 nentries=1 text= 
Feb 25 22:59:18 baal slapd[8751]: conn=9 fd=15 ACCEPT from IP=10.0.1.4:54882 (IP=10.0.1.4:389) 
Feb 25 22:59:18 baal slapd[8751]: conn=9 op=0 BIND dn="uid=zimbra,cn=admins,cn=zimbra" method=128 
Feb 25 22:59:18 baal slapd[8751]: conn=9 op=0 BIND dn="uid=zimbra,cn=admins,cn=zimbra" mech=SIMPLE ssf=0 
Feb 25 22:59:18 baal slapd[8751]: conn=9 op=0 RESULT tag=97 err=0 text= 
Feb 25 22:59:18 baal slapd[8751]: conn=9 op=1 SRCH base="cn=config,cn=zimbra" scope=0 deref=3 filter="(objectClass=*)" 
Feb 25 22:59:18 baal slapd[8751]: conn=9 op=1 SEARCH RESULT tag=101 err=0 nentries=1 text= 
Feb 25 22:59:19 baal slapd[8751]: conn=9 fd=15 closed (connection lost) 
Feb 25 22:59:19 baal slapd[8751]: conn=8 fd=13 closed (connection lost) 
Feb 25 22:59:34 baal slapd[8751]: conn=10 fd=13 ACCEPT from IP=10.0.1.4:54884 (IP=10.0.1.4:389) 
Feb 25 22:59:34 baal slapd[8751]: conn=10 op=0 BIND dn="uid=zimbra,cn=admins,cn=zimbra" method=128 
Feb 25 22:59:34 baal slapd[8751]: conn=10 op=0 BIND dn="uid=zimbra,cn=admins,cn=zimbra" mech=SIMPLE ssf=0 
Feb 25 22:59:34 baal slapd[8751]: conn=10 op=0 RESULT tag=97 err=0 text= 
Feb 25 22:59:34 baal slapd[8751]: conn=10 op=1 SRCH base="cn=com_zimbra_email,cn=zimlets,cn=zimbra" scope=0 deref=3 filter="(objectClass=*)" 
Feb 25 22:59:34 baal slapd[8751]: conn=10 op=1 SEARCH RESULT tag=101 err=0 nentries=1 text= 
Feb 25 22:59:34 baal slapd[8751]: conn=10 op=2 SRCH base="cn=com_zimbra_phone,cn=zimlets,cn=zimbra" scope=0 deref=3 filter="(objectClass=*)" 
Feb 25 22:59:34 baal slapd[8751]: conn=10 op=2 SEARCH RESULT tag=101 err=0 nentries=1 text= 
Feb 25 22:59:34 baal slapd[8751]: conn=10 op=3 SRCH base="cn=com_zimbra_date,cn=zimlets,cn=zimbra" scope=0 deref=3 filter="(objectClass=*)" 
Feb 25 22:59:34 baal slapd[8751]: conn=10 op=3 SEARCH RESULT tag=101 err=0 nentries=1 text= 
Feb 25 22:59:34 baal slapd[8751]: conn=10 op=4 SRCH base="cn=com_zimbra_search,cn=zimlets,cn=zimbra" scope=0 deref=3 filter="(objectClass=*)" 
Feb 25 22:59:34 baal slapd[8751]: conn=10 op=4 SEARCH RESULT tag=101 err=0 nentries=1 text= 
Feb 25 22:59:34 baal slapd[8751]: conn=10 op=5 SRCH base="cn=com_zimbra_url,cn=zimlets,cn=zimbra" scope=0 deref=3 filter="(objectClass=*)" 
Feb 25 22:59:34 baal slapd[8751]: conn=10 op=5 SEARCH RESULT tag=101 err=0 nentries=1 text= 
Feb 25 22:59:34 baal slapd[8751]: conn=10 op=6 SRCH base="cn=com_zimbra_amzn,cn=zimlets,cn=zimbra" scope=0 deref=3 filter="(objectClass=*)" 
Feb 25 22:59:34 baal slapd[8751]: conn=10 op=6 SEARCH RESULT tag=101 err=0 nentries=1 text= 
Feb 25 22:59:34 baal slapd[8751]: conn=10 op=7 SRCH base="cn=com_zimbra_bugz,cn=zimlets,cn=zimbra" scope=0 deref=3 filter="(objectClass=*)" 
Feb 25 22:59:34 baal slapd[8751]: conn=10 op=7 SEARCH RESULT tag=101 err=0 nentries=1 text= 
Feb 25 22:59:34 baal slapd[8751]: conn=10 op=8 SRCH base="cn=com_zimbra_collector,cn=zimlets,cn=zimbra" scope=0 deref=3 filter="(objectClass=*)" 
Feb 25 22:59:34 baal slapd[8751]: conn=10 op=8 SEARCH RESULT tag=101 err=0 nentries=1 text= 
Feb 25 22:59:34 baal slapd[8751]: conn=10 op=9 SRCH base="cn=com_zimbra_photo,cn=zimlets,cn=zimbra" scope=0 deref=3 filter="(objectClass=*)" 
Feb 25 22:59:34 baal slapd[8751]: conn=10 op=9 SEARCH RESULT tag=101 err=0 nentries=1 text= 
Feb 25 22:59:34 baal slapd[8751]: conn=10 op=10 SRCH base="cn=com_zimbra_po,cn=zimlets,cn=zimbra" scope=0 deref=3 filter="(objectClass=*)" 
Feb 25 22:59:34 baal slapd[8751]: conn=10 op=10 SEARCH RESULT tag=101 err=0 nentries=1 text= 
Feb 25 22:59:34 baal slapd[8751]: conn=10 op=11 SRCH base="cn=com_zimbra_wikipedia,cn=zimlets,cn=zimbra" scope=0 deref=3 filter="(objectClass=*)" 
Feb 25 22:59:34 baal slapd[8751]: conn=10 op=11 SEARCH RESULT tag=101 err=0 nentries=1 text= 
Feb 25 22:59:34 baal slapd[8751]: conn=10 op=12 SRCH base="cn=com_zimbra_xslt,cn=zimlets,cn=zimbra" scope=0 deref=3 filter="(objectClass=*)" 
Feb 25 22:59:34 baal slapd[8751]: conn=10 op=12 SEARCH RESULT tag=101 err=0 nentries=1 text= 
Feb 25 22:59:34 baal slapd[8751]: conn=10 op=13 SRCH base="cn=com_zimbra_local,cn=zimlets,cn=zimbra" scope=0 deref=3 filter="(objectClass=*)" 
Feb 25 22:59:34 baal slapd[8751]: conn=10 op=13 SEARCH RESULT tag=101 err=0 nentries=1 text= 
Feb 25 22:59:34 baal slapd[8751]: conn=10 op=14 SRCH base="uid=sharlow,ou=people,dc=medinavoip,dc=com" scope=2 deref=3 filter="(objectClass=zimbraIdentity)" 
Feb 25 22:59:34 baal slapd[8751]: conn=10 op=14 SEARCH RESULT tag=101 err=0 nentries=0 text= 
Feb 25 22:59:34 baal slapd[8751]: conn=10 op=15 SRCH base="uid=sharlow,ou=people,dc=medinavoip,dc=com" scope=2 deref=3 filter="(objectClass=zimbraSignature)" 
Feb 25 22:59:34 baal slapd[8751]: conn=10 op=15 SEARCH RESULT tag=101 err=0 nentries=0 text= 
Feb 25 22:59:34 baal slapd[8751]: conn=10 op=16 SRCH base="uid=sharlow,ou=people,dc=medinavoip,dc=com" scope=2 deref=3 filter="(objectClass=zimbraDataSource)" 
Feb 25 22:59:34 baal slapd[8751]: conn=10 op=16 SEARCH RESULT tag=101 err=0 nentries=0 text= 
Feb 25 22:59:35 baal slapd[8751]: conn=10 op=17 SRCH base="" scope=2 deref=3 filter="(&(|(zimbraMailDeliveryAddress=jwhite@medinavoip.com)(zimbraMailAlias=jwhite@medinavoip.com))(objectClass=zimbraAccount))" 
Feb 25 22:59:35 baal slapd[8751]: conn=10 op=17 SEARCH RESULT tag=101 err=0 nentries=1 text= 
Feb 25 22:59:35 baal slapd[8751]: conn=10 op=18 SRCH base="cn=zimbra" scope=2 deref=3 filter="(objectClass=zimbraZimletEntry)" 
Feb 25 22:59:35 baal slapd[8751]: conn=10 op=18 SEARCH RESULT tag=101 err=0 nentries=21 text=

[iggy]

Ok, that's not enough. See what ldap_log_level=128 provides.

[wolrah]

Done. It generated 7.5MB worth of data in 15 seconds, so if the information isn't in there I have no idea where it could be...

Zipped and attached to my case.

[iggy]

There is some helpful information in the slapd log this time.

Feb 26 10:56:47 baal slapd[31638]: => access_allowed: delete access to "uid=sharlow,ou=people,dc=medinavoip,dc=com" "zimbraAdminSavedSearches" requested 
Feb 26 10:56:47 baal slapd[31638]: => dn: [1] ou=people,dc=medinavoip,dc=com 
Feb 26 10:56:47 baal slapd[31638]: => acl_get: [1] matched 
Feb 26 10:56:47 baal slapd[31638]: => acl_get: [1] attr zimbraAdminSavedSearches 
Feb 26 10:56:47 baal slapd[31638]: access_allowed: no res from state (zimbraAdminSavedSearches) 
Feb 26 10:56:47 baal slapd[31638]: => acl_mask: access to entry "uid=sharlow,ou=people,dc=medinavoip,dc=com", attr "zimbraAdminSavedSearches" requested 
Feb 26 10:56:47 baal slapd[31638]: => acl_mask: to all values by "uid=zimbra,cn=admins,cn=zimbra", (=0)  
Feb 26 10:56:47 baal slapd[31638]: <= check a_dn_pat: * 
Feb 26 10:56:47 baal slapd[31638]: <= acl_mask: [1] applying read(=rscxd) (stop) 
Feb 26 10:56:47 baal slapd[31638]: <= acl_mask: [1] mask: read(=rscxd) 
Feb 26 10:56:47 baal slapd[31638]: => access_allowed: delete access denied by read(=rscxd)

There is an ACL issue somewhere. Please send us your slapd.conf and any schema files it is currently loading.

--
Jason

[wolrah]

I've stuck slapd.conf and slapd.conf.in as well as the entire contents of the schema directory in a tgz and attached it to the case.

Thanks

If I was to check my firewall rules and make sure LDAP is not exposed to the internet, then add an ACL rule that effectively disables all access control and makes it wide open, could that be a temporary workaround?

My boss is really riding me about this one since he uses the admin portal heavily.

[iggy]

Thank you for the files. Give us a moment to analyze and we'll get right back to you.

Jason