Shibboleth Developers

[Dan McLaughlin <>]

We upgraded from 2.1.5 to 2.2.1 this weekend and are finding that the
derefAliases="never" property that we set in 2.1.5 as a workaround to
(https://bugs.internet2.edu/jira/browse/SIDP-347) has stopped working
in 2.2.0 & 2.2.1.

I'm starting to step through the VT/Shibb source now to see if I can
figure out why aliases have stopped being deferenced.  I'm not seeing
any reports of issues in JIRA or the newsgroups.

As soon as I can figure it out I will open a JIRA ticket with the
details, but it might save me some time if anyone can remember any
code changes other then the move from VT 2.8.4 to VT 3.3.x (I tried
rolling back to 3.3.1 and the problem still exists, but couldn't roll
back to the 2.8.4 release b/c of missing classes).


10:16:51.785 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:138]
- Begin initialize
10:16:51.786 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:172]
- useFirstPass = false
10:16:51.786 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:173]
- tryFirstPass = false
10:16:51.786 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:174]
- storePass = false
10:16:51.786 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:175]
- setLdapPrincipal = true
10:16:51.786 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:176]
- setLdapDnPrincipal = false
10:16:51.787 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:177]
- setLdapCredential = true
10:16:51.787 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:178]
- defaultRole = []
10:16:51.787 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:179]
- principalGroupName = null
10:16:51.787 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:180]
- roleGroupName = null
10:16:51.787 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:77]
- userRoleAttribute = []
10:16:51.787 - TRACE
[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1385] - setting
searchScope: ONELEVEL
10:16:51.788 - TRACE
[edu.vt.middleware.ldap.auth.AuthenticatorConfig:427] - setting
subtreeSearch: true
10:16:51.788 - TRACE
[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1385] - setting
searchScope: SUBTREE
10:16:51.789 - TRACE
[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1834] - setting ssl:
true
10:16:51.789 - TRACE
[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1168] - setting
ldapUrl: ldap://ldap01:636
10:16:51.789 - TRACE
[edu.vt.middleware.ldap.auth.AuthenticatorConfig:274] - setting
userField: [cn]
10:16:51.789 - TRACE
[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1651] - setting
derefAliases: never
10:16:51.789 - TRACE
[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1370] - setting
baseDn: T=MYBASEDN
10:16:51.790 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:83]
- Created authenticator:
edu.vt.middleware.ldap.auth.AuthenticatorConfig@26451219::env={java.naming.provider.url=ldap://ldap01:636,
java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory,
java.naming.ldap.derefAliases=never,
java.naming.security.protocol=ssl}
10:16:51.790 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:368]
- Begin getCredentials
10:16:51.790 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:369]
-   useFistPass = false
10:16:51.790 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:370]
-   tryFistPass = false
10:16:51.790 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:371]
-   useCallback = false
10:16:51.790 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:372]
-   callbackhandler class =
javax.security.auth.login.LoginContext$SecureCallbackHandler
10:16:51.791 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:375]
-   name callback class = javax.security.auth.callback.NameCallback
10:16:51.791 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:377]
-   password callback class =
javax.security.auth.callback.PasswordCallback
10:16:51.791 - DEBUG
[edu.vt.middleware.ldap.auth.SearchDnResolver:108] - Looking up DN
using userField
10:16:51.791 - DEBUG
[edu.vt.middleware.ldap.auth.SearchDnResolver:193] - Search with the
following parameters:
10:16:51.791 - DEBUG
[edu.vt.middleware.ldap.auth.SearchDnResolver:194] -   dn = T=MYBASEDN
10:16:51.791 - DEBUG
[edu.vt.middleware.ldap.auth.SearchDnResolver:195] -   filter =
(cn={0})
10:16:51.792 - DEBUG
[edu.vt.middleware.ldap.auth.SearchDnResolver:196] -   filterArgs =
[jdoe]
10:16:51.792 - DEBUG
[edu.vt.middleware.ldap.auth.SearchDnResolver:197] -   searchControls
= 
javax.naming.directory.SearchControls@2d4e47
10:16:51.792 - DEBUG
[edu.vt.middleware.ldap.auth.SearchDnResolver:198] -   handler =
[edu.vt.middleware.ldap.handler.FqdnSearchResultHandler@6e4ecd]
10:16:51.792 - TRACE
[edu.vt.middleware.ldap.auth.SearchDnResolver:200] -   config =
{java.naming.provider.url=ldap://ldap01:636,
java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory,
java.naming.ldap.derefAliases=never,
java.naming.security.protocol=ssl}
10:16:51.792 - TRACE
[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:93] - setting
connectionStrategy: DEFAULT
10:16:51.792 - TRACE
[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:110] -
setting connectionRetryExceptions: [class
javax.naming.NamingException]
10:16:51.793 - TRACE
[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:152] - {0}
Attempting connection to ldap://ldap01:636 for strategy DEFAULT
10:16:51.793 - DEBUG
[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:73] - Bind
with the following parameters:
10:16:51.793 - DEBUG
[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:74] -
authtype = simple
10:16:51.793 - DEBUG
[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:75] -   dn =
null
10:16:51.793 - DEBUG
[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:82] -
credential = <suppressed>
10:16:51.794 - TRACE
[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:86] -   env =
{java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory,
java.naming.provider.url=ldap://ldap01:636,
java.naming.ldap.derefAliases=never,
java.naming.security.protocol=ssl}
10:16:52.049 - DEBUG
[edu.vt.middleware.ldap.auth.SearchDnResolver:151] - Multiple results
found for user: jdoe using filter: filter=(cn={0}),filterArgs=[]
10:16:52.051 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:164]
- Error occured attempting authentication
javax.naming.NamingException: Found more than (1) DN for: jdoe
at 
edu.vt.middleware.ldap.auth.SearchDnResolver.resolve(SearchDnResolver.java:156)
~[vt-ldap-3.3.2.jar:na]
at edu.vt.middleware.ldap.auth.Authenticator.getDn(Authenticator.java:106)
~[vt-ldap-3.3.2.jar:na]
at 
edu.vt.middleware.ldap.jaas.JaasAuthenticator.authenticate(JaasAuthenticator.java:74)
~[vt-ldap-3.3.2.jar:na]
at 
edu.vt.middleware.ldap.auth.Authenticator.authenticate(Authenticator.java:320)
~[vt-ldap-3.3.2.jar:na]
at 
edu.vt.middleware.ldap.auth.Authenticator.authenticate(Authenticator.java:277)
~[vt-ldap-3.3.2.jar:na]
at 
edu.vt.middleware.ldap.jaas.JaasAuthenticator.authenticate(JaasAuthenticator.java:60)
~[vt-ldap-3.3.2.jar:na]
at edu.vt.middleware.ldap.jaas.LdapLoginModule.login(LdapLoginModule.java:103)
~[vt-ldap-3.3.2.jar:na]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.6.0_24]
at 
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
~[na:1.6.0_24]
at 
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
~[na:1.6.0_24]
at java.lang.reflect.Method.invoke(Method.java:597) ~[na:1.6.0_24]
at javax.security.auth.login.LoginContext.invoke(LoginContext.java:769)
[na:1.6.0_24]
at javax.security.auth.login.LoginContext.access$000(LoginContext.java:186)
[na:1.6.0_24]
at javax.security.auth.login.LoginContext$4.run(LoginContext.java:683)
[na:1.6.0_24]
at java.security.AccessController.doPrivileged(Native Method) [na:1.6.0_24]
at javax.security.auth.login.LoginContext.invokePriv(LoginContext.java:680)
[na:1.6.0_24]
at javax.security.auth.login.LoginContext.login(LoginContext.java:579)
[na:1.6.0_24]
at 
edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet.authenticateUser(UsernamePasswordLoginServlet.java:160)
[shibboleth-identityprovider-2.2.1.jar:na]
at 
edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet.service(UsernamePasswordLoginServlet.java:106)
[shibboleth-identityprovider-2.2.1.jar:na]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
[servlet-api.jar:na]
at 
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
[catalina.jar:6.0.32]
at 
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
[catalina.jar:6.0.32]
at 
edu.internet2.middleware.shibboleth.idp.util.NoCacheFilter.doFilter(NoCacheFilter.java:49)
[shibboleth-identityprovider-2.2.1.jar:na]
at 
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
[catalina.jar:6.0.32]
at 
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
[catalina.jar:6.0.32]
at 
edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter.doFilter(IdPSessionFilter.java:77)
[shibboleth-identityprovider-2.2.1.jar:na]
at 
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
[catalina.jar:6.0.32]
at 
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
[catalina.jar:6.0.32]
at 
edu.internet2.middleware.shibboleth.common.log.SLF4JMDCCleanupFilter.doFilter(SLF4JMDCCleanupFilter.java:51)
[shibboleth-common-1.2.1.jar:na]
at 
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
[catalina.jar:6.0.32]
at 
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
[catalina.jar:6.0.32]
at 
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:219)
[catalina.jar:6.0.32]
at 
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
[catalina.jar:6.0.32]
at 
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
[catalina.jar:6.0.32]
at 
com.googlecode.psiprobe.Tomcat60AgentValve.invoke(Tomcat60AgentValve.java:30)
[tomcat60adaptor-2.2.1.jar:2.2.1]
at 
org.apache.catalina.ha.session.JvmRouteBinderValve.invoke(JvmRouteBinderValve.java:227)
[catalina-ha.jar:6.0.32]
at 
org.apache.catalina.ha.tcp.ReplicationValve.invoke(ReplicationValve.java:347)
[catalina-ha.jar:6.0.32]
at 
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
[catalina.jar:6.0.32]
at 
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
[catalina.jar:6.0.32]
at org.apache.catalina.valves.RemoteIpValve.invoke(RemoteIpValve.java:647)
[catalina.jar:6.0.32]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:298)
[catalina.jar:6.0.32]
at org.apache.coyote.ajp.AjpAprProcessor.process(AjpAprProcessor.java:429)
[tomcat-coyote.jar:6.0.32]
at 
org.apache.coyote.ajp.AjpAprProtocol$AjpConnectionHandler.process(AjpAprProtocol.java:384)
[tomcat-coyote.jar:6.0.32]
at org.apache.tomcat.util.net.AprEndpoint$Worker.run(AprEndpoint.java:1665)
[tomcat-coyote.jar:6.0.32]
at java.lang.Thread.run(Thread.java:662) [na:1.6.0_24]
10:16:52.051 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:248]
- Begin abort
10:16:52.052 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:260]
- Begin logout


--

Thanks,

Dan McLaughlin

NOTICE: This e-mail message and all attachments transmitted with it
are for the sole use of the intended recipient(s) and may contain
confidential and privileged information. Any unauthorized review, use,
disclosure or distribution is strictly prohibited. The contents of
this e-mail are confidential and may be subject to work product
privileges. If you are not the intended recipient, please contact the
sender by reply e-mail and destroy all copies of the original message.