[Shib-Dev] derefAliases broken in 2.2.x

[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.

[Dan McLaughlin]

I think I found it. derefAliases is now derefLinkFlag

...testing now.

--

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.

[Peter Schober]

* Dan McLaughlin <dmcla...@tech-consortium.com> [2011-06-03 17:44]:

> We upgraded from 2.1.5 to 2.2.1 this weekend

Since there's quite a bit of weekend left, you can then continue to
upgarde to the latest release 2.3 ;)
-peter

[Dan McLaughlin]

No luck.

--

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.

On Fri, Jun 3, 2011 at 10:53 AM, Dan McLaughlin

[Dan McLaughlin]

That's in the works, but we have a few more weeks of testing before we
can move to 2.3.

--

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.

[Dan McLaughlin]

Setting countLimit="1" (replacement for maxResultSize that we tried in
https://bugs.internet2.edu/jira/browse/SIDP-347) seems to be a
workaround, but it still doesn't explain why dereference of aliases is
broken. Still looking.

--

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.

On Fri, Jun 3, 2011 at 10:58 AM, Dan McLaughlin

[Dan McLaughlin]

I see that the new version of VT-ldap includes a userFilter property.
Which should avoid returning any aliases if I search on
objectclass=person.

Trying the settings below now, but since I'm not sure how these
properties match to the VT-ldap properties, I'm not entirely sure if
this will map
userFilter to edu.vt.middleware.ldap.auth.userFilter.

edu.vt.middleware.ldap.jaas.LdapLoginModule sufficient
host="ldap://ldap01:636"
port="636"
base="T=MYBASEDN"
ssl="true"
//userField="cn"
subtreeSearch="true"
// countLimit="1"
//derefLinkFlag="true"
//derefAliases="never"
userFilter=(&(cn={0})(objectclass=person));

--

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.

On Fri, Jun 3, 2011 at 11:04 AM, Dan McLaughlin

[Dan McLaughlin]

It looks like the bug is more of a documentation issue. The LDAP
example in the login.config in the 2.2.x & 2.3.0 is out of sync with
the IdP documentation
https://wiki.shibboleth.net/confluence/display/SHIB2/IdPAuthUserPass.

After fixing the ldap connection settings to match the documentation
instead of the example in the login.config, the derefAliases="never"
property is working again.

// Example LDAP authentication
// See: https://spaces.internet2.edu/display/SHIB2/IdPAuthUserPass
/*
edu.vt.middleware.ldap.jaas.LdapLoginModule required
host="ldap.example.org"
base="ou=people,dc=example,dc=org"
ssl="true"
userField="uid";
*/

/*
edu.vt.middleware.ldap.jaas.LdapLoginModule required

host="ldap://ldap01:636"
port="636"
base="T=MYBASEDN"
ssl="true"

userField="cn"
subtreeSearch="true"
derefAliases="never";
*/

edu.vt.middleware.ldap.jaas.LdapLoginModule required
ldapUrl="ldap://ldap01:636"
ssl="true"
baseDn="T=MYBASEDN"
subtreeSearch="true"
derefAliases="never"
userFilter="(&(cn={0})(objectclass=person))";

--

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.

On Fri, Jun 3, 2011 at 11:27 AM, Dan McLaughlin

[Chad La Joie]

What in the example do you think is out of synch with the documentation?

--
Chad La Joie
www.itumi.biz
trusted identities, delivered

[Dan McLaughlin]

If I leave my ldap settings has documented in the example in
login.config, then derefAliases="never" is broken. If I change the
ldap settings to follow the documentation at
https://wiki.shibboleth.net/confluence/display/SHIB2/IdPAuthUserPass
and stop using "host", "base", & "userField", and instead use
"ldapUrl", "baseDn", & "userFilter", then derefAliases="never" works
again. For some reason using "host", "base", & "userField" as shown
in the example causes derefAliases to be ignored...not sure why, but
it does. There still could be a bug in the VT-ldap code that is
responsible for the problem, but seeing as how fixing my config to
match the documentation example fixes it, I'm not sure if filing a bug
when I wasn't following the documentation is relevant. If the example
in the login.config was updated to match the documentation I probably
would have caught the issue before deployment.

--

Thanks,

Dan McLaughlin

[Chad La Joie]

I'll check with the vt-ldap author. While the new ldapUrl property is
preferred over host+port+baseDN the use of the old properties
shouldn't cause a problem. So, I think it's probably a bug with
vt-ldap.

[Daniel Fisher]

I ran some regression tests and didn't see any problems with the
library versions you mentioned.
From your logs:

> 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}

it appears the derefAliases property is set.

The interesting thing here is that using that property should produce
the opposite result than what you are looking for. Using 'always' (the
default) will have the server dereference and you won't be returned
any aliases. Using 'never' will return aliases and thus cause problems
in DN resolution. I'm assuming this is an eDirectory bug you're
working around?

Regardless the login.config packaged in the distro should be updated
to reflect the newer properties.

--Daniel Fisher

[Chad La Joie]

Yeah, will you file a bug for that so I don't forget?

On Fri, Jun 3, 2011 at 17:20, Daniel Fisher <dfi...@vt.edu> wrote:
> Regardless the login.config packaged in the distro should be updated
> to reflect the newer properties.

--

[Daniel Fisher]

https://issues.shibboleth.net/jira/browse/SIDP-494

[Chad La Joie]

Thanks Dan.

--
Chad La Joie
http://itumi.biz
trusted identities, delivered

[Dan McLaughlin]

Hi Daniel,

Actually dereference alias "never" means "Never dereferences aliases".
So if you have an alias it will not be returned. When we leave the
default "always" then the alias and the object is references is
returned and we get the exception about too many results returned.

The documentation from Sun/Oracle confirms my understanding.
http://download.oracle.com/javase/jndi/tutorial/ldap/misc/aliases.html

--

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.

[Daniel Fisher]

On Tue, Jun 7, 2011 at 9:26 AM, Dan McLaughlin
<dmcla...@tech-consortium.com> wrote:
> Hi Daniel,
>
> Actually dereference alias "never" means "Never dereferences aliases".

Correct. This is a server side directive. You're telling the server
not to dereference.

>  So if you have an alias it will not be returned.

Incorrect. Aliases will be returned if they are found by your search
filter. Since the server is *not* dereferencing the aliases, they will
be returned as entries.

> When we leave the default "always" then the alias and the object is references is
> returned and we get the exception about too many results returned.

You should not receive any aliases entries when using that setting. If
you are, the server is not dereferencing them and something is wrong.

> The documentation from Sun/Oracle confirms my understanding.
> http://download.oracle.com/javase/jndi/tutorial/ldap/misc/aliases.html

Those docs really need a few more examples. I can see why they are confusing.

--Daniel Fisher

[Dan McLaughlin]

Hi Daniel,

I don't have a test eDir server on the outside, but I'd be surprised
if I couldn't reproduce it with OpenLDAP.

I can setup a WebEx at anytime and look directly at the systems if you'd like.

By the way... after upgrading to 2.3.0 in our Development environment.
LDAP authentication fails unless I roll back to the vt-ldap jar to
the 3.3.2 release.

18:34:46.911 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:144]
- Begin initialize
18:34:46.911 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:180]
- useFirstPass = false
18:34:46.911 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:181]
- tryFirstPass = false
18:34:46.912 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:182]
- storePass = false
18:34:46.912 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:183]
- clearPass = false
18:34:46.912 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:184]
- setLdapPrincipal = true
18:34:46.912 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:185]
- setLdapDnPrincipal = false
18:34:46.912 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:186]
- setLdapCredential = true
18:34:46.912 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:187]
- defaultRole = []
18:34:46.913 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:188]
- principalGroupName = null
18:34:46.913 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:189]
- roleGroupName = null
18:34:46.913 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:77]
- userRoleAttribute = []
18:34:46.913 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1385] - setting
searchScope: ONELEVEL

18:34:46.913 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:427] - setting
subtreeSearch: true

18:34:46.914 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1385] - setting
searchScope: SUBTREE

18:34:46.914 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1370] - setting
baseDn: T=MYBASEDN

18:34:46.914 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1834] - setting ssl:
true

18:34:46.914 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1168] - setting
ldapUrl: ldap://ldap01:636

18:34:46.914 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1651] - setting
derefAliases: never

18:34:46.915 - TRACE
[edu.vt.middleware.ldap.auth.AuthenticatorConfig:290] - setting
userFilter: (&(cn={0})(objectclass=person))
18:34:46.915 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:83]
- Created authenticator:
edu.vt.middleware.ldap.auth.AuthenticatorConfig@20797601::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}
18:34:46.915 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:412]
- Begin getCredentials
18:34:46.915 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:413]
- useFistPass = false
18:34:46.915 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:414]
- tryFistPass = false
18:34:46.916 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:415]
- useCallback = false
18:34:46.916 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:416]

- callbackhandler class =
javax.security.auth.login.LoginContext$SecureCallbackHandler

18:34:46.916 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:419]

- name callback class = javax.security.auth.callback.NameCallback

18:34:46.916 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:421]

- password callback class =
javax.security.auth.callback.PasswordCallback

18:34:46.916 - DEBUG
[edu.vt.middleware.ldap.auth.SearchDnResolver:173] - User input was
empty or null
18:34:46.917 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:136]
- Authentication failed
javax.naming.AuthenticationException: Cannot authenticate dn, invalid credential
at edu.vt.middleware.ldap.auth.AbstractAuthenticator.authenticateAndAuthorize(AbstractAuthenticator.java:154)
~[vt-ldap-3.3.3.jar:na]
at edu.vt.middleware.ldap.jaas.JaasAuthenticator.authenticate(JaasAuthenticator.java:74)
~[vt-ldap-3.3.3.jar:na]
at edu.vt.middleware.ldap.auth.Authenticator.authenticate(Authenticator.java:320)
~[vt-ldap-3.3.3.jar:na]
at edu.vt.middleware.ldap.auth.Authenticator.authenticate(Authenticator.java:277)
~[vt-ldap-3.3.3.jar:na]
at edu.vt.middleware.ldap.jaas.JaasAuthenticator.authenticate(JaasAuthenticator.java:60)
~[vt-ldap-3.3.3.jar:na]
at edu.vt.middleware.ldap.jaas.LdapLoginModule.login(LdapLoginModule.java:103)
~[vt-ldap-3.3.3.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.3.0.jar:na]
at edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet.service(UsernamePasswordLoginServlet.java:106)
[shibboleth-identityprovider-2.3.0.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.3.0.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:80)
[shibboleth-identityprovider-2.3.0.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.3.0.jar:na]

18:34:46.918 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:264]
- Begin abort

If I roll back only the vt-ldap.jar to the 3.3.2 release and change
nothing else, then the same exact login works fine...

18:45:58.042 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:138]
- Begin initialize
18:45:58.043 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:172]
- useFirstPass = false
18:45:58.043 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:173]
- tryFirstPass = false
18:45:58.043 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:174]
- storePass = false
18:45:58.044 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:175]
- setLdapPrincipal = true
18:45:58.044 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:176]
- setLdapDnPrincipal = false
18:45:58.044 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:177]
- setLdapCredential = true
18:45:58.044 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:178]
- defaultRole = []
18:45:58.044 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:179]
- principalGroupName = null
18:45:58.045 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:180]
- roleGroupName = null
18:45:58.045 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:77]
- userRoleAttribute = []
18:45:58.058 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1385] - setting
searchScope: ONELEVEL

18:45:58.060 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:427] - setting
subtreeSearch: true

18:45:58.060 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1385] - setting
searchScope: SUBTREE

18:45:58.061 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1370] - setting
baseDn: T=MYBASEDN

18:45:58.062 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1834] - setting ssl:
true

18:45:58.063 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1168] - setting
ldapUrl: ldap://ldap01:636

18:45:58.064 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1651] - setting
derefAliases: never

18:45:58.065 - TRACE
[edu.vt.middleware.ldap.auth.AuthenticatorConfig:290] - setting
userFilter: (&(cn={0})(objectclass=person))
18:45:58.068 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:83]
- Created authenticator:
edu.vt.middleware.ldap.auth.AuthenticatorConfig@7889295::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}
18:45:58.068 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:368]
- Begin getCredentials
18:45:58.068 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:369]
- useFistPass = false
18:45:58.069 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:370]
- tryFistPass = false
18:45:58.069 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:371]
- useCallback = false
18:45:58.069 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:372]

- callbackhandler class =
javax.security.auth.login.LoginContext$SecureCallbackHandler

18:45:58.069 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:375]

- name callback class = javax.security.auth.callback.NameCallback

18:45:58.069 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:377]

- password callback class =
javax.security.auth.callback.PasswordCallback

18:45:58.070 - DEBUG
[edu.vt.middleware.ldap.auth.SearchDnResolver:102] - Looking up DN
using userFilter
18:45:58.071 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:193] - Search with the
following parameters:

18:45:58.071 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:194] - dn = T=MYBASEDN

18:45:58.071 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:195] - filter =

(&(cn={0})(objectclass=person))
18:45:58.071 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:196] - filterArgs =
[jdoe]

18:45:58.071 - DEBUG
[edu.vt.middleware.ldap.auth.SearchDnResolver:197] - searchControls
= javax.naming.directory.SearchControls@1c101ac
18:45:58.072 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:198] - handler =

[edu.vt.middleware.ldap.handler.FqdnSearchResultHandler@54c72e]
18:45:58.072 - 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}

18:45:58.072 - TRACE

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:93] - setting
connectionStrategy: DEFAULT

18:45:58.076 - TRACE

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:110] -
setting connectionRetryExceptions: [class
javax.naming.NamingException]

18:45:58.077 - TRACE

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:152] - {0}
Attempting connection to ldap://ldap01:636 for strategy DEFAULT

18:45:58.077 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:73] - Bind
with the following parameters:

18:45:58.078 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:74] -
authtype = simple

18:45:58.078 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:75] - dn =
null

18:45:58.079 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:82] -
credential = <suppressed>

18:45:58.079 - 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}

18:45:58.329 - TRACE

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:93] - setting
connectionStrategy: DEFAULT

18:45:58.329 - TRACE

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:110] -
setting connectionRetryExceptions: [class
javax.naming.NamingException]

18:45:58.330 - TRACE
[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:152] - {1}

Attempting connection to ldap://ldap01:636 for strategy DEFAULT

18:45:58.330 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:73] - Bind
with the following parameters:

18:45:58.330 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:74] -
authtype = simple

18:45:58.330 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:75] - dn =

cn=JDOE,ou=FOO,ou=BAR,o=DIV
18:45:58.330 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:82] -
credential = <suppressed>

18:45:58.331 - 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}

18:45:58.556 - INFO
[edu.vt.middleware.ldap.jaas.JaasAuthenticator:176] - Authentication
succeeded for dn: cn=JDOE,ou=FOO,ou=BAR,o=DIV
18:45:58.563 - DEBUG
[edu.vt.middleware.ldap.auth.SearchDnResolver:102] - Looking up DN
using userFilter
18:45:58.563 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:193] - Search with the
following parameters:

18:45:58.563 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:194] - dn = T=MYBASEDN

18:45:58.564 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:195] - filter =

(&(cn={0})(objectclass=person))
18:45:58.564 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:196] - filterArgs =
[jdoe]

18:45:58.564 - DEBUG
[edu.vt.middleware.ldap.auth.SearchDnResolver:197] - searchControls
= javax.naming.directory.SearchControls@282ae6
18:45:58.564 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:198] - handler =

[edu.vt.middleware.ldap.handler.FqdnSearchResultHandler@54c72e]
18:45:58.564 - 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}

18:45:58.576 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:199]
- Begin commit
18:45:58.577 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:207]
- Committed the following principals: [jdoe[]]
18:45:58.577 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:213]
- Committed the following roles: []
18:45:58.849 - INFO [Shibboleth-Access:73] -
20110607T234558Z|144.45.7.139|www.mydomain.com:443|/profile/SAML2/Redirect/SSO|
18:45:58.872 - TRACE
[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:93] - setting
connectionStrategy: ACTIVE_PASSIVE
18:45:58.873 - TRACE

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:110] -
setting connectionRetryExceptions: [class
javax.naming.NamingException]

18:45:58.873 - TRACE
[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:152] - {1}
Attempting connection to ldaps://ldap01:636 for strategy
ACTIVE_PASSIVE
18:45:58.873 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:73] - Bind
with the following parameters:

18:45:58.873 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:74] -
authtype = simple

18:45:58.874 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:75] - dn =
null

18:45:58.874 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:82] -
credential = <suppressed>

18:45:58.874 - TRACE

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:86] - env =
{java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory,

java.naming.provider.url=ldaps://ldap01:636,
java.naming.ldap.derefAliases=never,
java.naming.ldap.attributes.binary=GUID}
18:45:59.091 - DEBUG [edu.vt.middleware.ldap.Ldap:193] - Search with
the following parameters:
18:45:59.092 - DEBUG [edu.vt.middleware.ldap.Ldap:194] - dn = T=MYBASEDN
18:45:59.092 - DEBUG [edu.vt.middleware.ldap.Ldap:195] - filter =
(&(cn=jdoe)(objectclass=person))
18:45:59.092 - DEBUG [edu.vt.middleware.ldap.Ldap:196] - filterArgs = []
18:45:59.092 - DEBUG [edu.vt.middleware.ldap.Ldap:197] -
searchControls = javax.naming.directory.SearchControls@f8a786
18:45:59.093 - DEBUG [edu.vt.middleware.ldap.Ldap:198] - handler =
[edu.vt.middleware.ldap.handler.FqdnSearchResultHandler@f1f2cc,
edu.vt.middleware.ldap.handler.EntryDnSearchResultHandler@7b6d1c,
edu.vt.middleware.ldap.handler.BinarySearchResultHandler@1387498]
18:45:59.093 - TRACE [edu.vt.middleware.ldap.Ldap:200] - config =
{java.naming.provider.url=ldaps://ldap01:636,
java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory,
java.naming.ldap.derefAliases=never,
java.naming.ldap.attributes.binary=GUID}
18:45:59.110 - TRACE
[edu.vt.middleware.ldap.pool.DefaultLdapFactory:123] - destroyed ldap
object: edu.vt.middleware.ldap.Ldap@384082::config=edu.vt.middleware.ldap.LdapConfig@22594860::env={java.naming.provider.url=ldaps://ldap01:636,
java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory,
java.naming.ldap.derefAliases=never,
java.naming.ldap.attributes.binary=GUID}
18:45:59.286 - INFO [Shibboleth-Audit:969] -
20110607T234559Z|urn:oasis:names:tc:SAML:2.0:bindings:HTTP-Redirect|_716f56e410da222075ca48a33b078b0c|https://www.mydomain.com/shibboleth|urn:mace:shibboleth:2.0:profiles:saml2:sso|https://www.mydomain.com/idp/shibboleth|urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST|_1f5cb388a646bcaa8434576f8150cc94|jdoe|urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport|cn,email,telephoneNumber,HexGUID,transientId,surname,givenName,IsCRISUser,AgencyID,|_c126abb8f0f0deba081bb6a496ef6ddf||

--

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.

[Daniel Fisher]

On Tue, Jun 7, 2011 at 8:08 PM, Dan McLaughlin
<dmcla...@tech-consortium.com> wrote:
> Hi Daniel,
>

> I don't have a test eDir server on the outside, but I'd be surprised
> if I couldn't reproduce it with OpenLDAP.
>

Post an LDIF that's representative of your data.

> By the way... after upgrading to 2.3.0 in our Development environment.
>  LDAP authentication fails unless I roll back to the vt-ldap jar to
> the 3.3.2 release.
>

> 18:34:46.916 - DEBUG
> [edu.vt.middleware.ldap.auth.SearchDnResolver:173] - User input was
> empty or null

The username was either empty or null, and

> 18:34:46.917 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:136]
> - Authentication failed
> javax.naming.AuthenticationException: Cannot authenticate dn, invalid credential
>        at edu.vt.middleware.ldap.auth.AbstractAuthenticator.authenticateAndAuthorize(AbstractAuthenticator.java:154)
>

the password was also either empty or null.

> If I roll back only the vt-ldap.jar  to the 3.3.2 release and change
> nothing else, then the same exact login works fine...
>

This time the login module received jdoe with a correct password.

--Daniel Fisher

[Dan McLaughlin]

Hi Daniel,

I tried everything to get the 3.3.3 vt-ldap to work in 2.3.0 but it
failed every time and even with TRACE level logging it gives me
nothing to go on. I was able to attach with a debugger and step
through the code enough to tell it was failing due to change #1877.
After reverting FqdnSearchResultHandler.java to revision #1330
everything is working again.

"1877 4/5/11 9:42 AM 4 dfisher SearchResult#getName() returns a string
representing a composite name, not necessarily an LDAP DN. Use a
CompositeName to parse it correctly. Add test case for entries with
special characters. Fixes vt-ldap 109."

So now I'm running the latest vt-ldap 3.3.3 (minus change #1877) and IdP 2.3.0.

Everything I'm reading on dereferencing of aliases stats that to
"deference" means "To access the thing to which a pointer points, i.e.
to follow the pointer." I don't want aliases to be followed or
searches will return the alias and the person (which is too many
results). (BTW... countLimit=1 is another workaround I've found).

In Novell the alias,aliasObject schema allows and uses the cn
attribute as the RDN, the same attribute person is using for the RDN.

Here is an example of what an alias looks like in eDir. Notice how an
alias also has a cn attribute like person, I think this is key to
explaining by you can't reproduce this. I would think if you where to
customize the schema for OpenLDAP to allow a cn attribute for the
objectclass alias, then you might be able to see the issue there as
well.

objectClass: alias
objectClass: top
aliasedObjectName: cn=JDOE-C,ou=MYNEW,ou=DEPARTMENT,o=DIV
cn: JDOE-C
name: JDOE-C
createTimestamp: 20110603142023Z
creatorsName: cn=JANEDOE,ou=FOO,ou=BAR,o=DIV
entryDN: cn=JDOE-C,ou=FOO,ou=BAR,o=DIV
entryFlags: 1
federationBoundary: t=MYBASEDN
GUID:: gO1fnuyN4BGxMgddfecjjA==
localEntryID: 345548
modifiersName: cn=JANEDOE,ou=FOO,ou=BAR,o=DIV
modifyTimestamp: 20110603142023Z
revision: 1
structuralObjectClass: alias
subordinateCount: 0
subschemaSubentry: cn=schema

So a search for with dereference alias=always for
(&(cn=jdoe-c)(objectclass=person)) will return both the person that
the alias jdoe-c points to and the actual person jdoe-c.

This returns more than one result an the following error occurs:

23:10:40.018 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:144]
- Begin initialize
23:10:40.019 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:180]
- useFirstPass = false
23:10:40.019 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:181]
- tryFirstPass = false
23:10:40.019 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:182]
- storePass = false
23:10:40.019 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:183]
- clearPass = false
23:10:40.020 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:184]
- setLdapPrincipal = true
23:10:40.020 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:185]
- setLdapDnPrincipal = false
23:10:40.020 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:186]
- setLdapCredential = true
23:10:40.020 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:187]
- defaultRole = []
23:10:40.020 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:188]
- principalGroupName = null
23:10:40.020 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:189]
- roleGroupName = null
23:10:40.021 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:77]
- userRoleAttribute = []
23:10:40.026 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1385] - setting
searchScope: ONELEVEL

23:10:40.028 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:427] - setting
subtreeSearch: true

23:10:40.028 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1385] - setting
searchScope: SUBTREE

23:10:40.029 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1370] - setting
baseDn: T=MYBASEDN

23:10:40.029 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1834] - setting ssl:
true

23:10:40.029 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1168] - setting
ldapUrl: ldap://ldap01:636

23:10:40.029 - TRACE
[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1651] - setting
derefAliases: always
23:10:40.029 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:290] - setting
userFilter: (&(cn={0})(objectclass=person))

23:10:40.031 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:83]
- Created authenticator:
edu.vt.middleware.ldap.auth.AuthenticatorConfig@28414668::env={java.naming.provider.url=ldap://ldap01:636,
java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory,
java.naming.ldap.derefAliases=always,
java.naming.security.protocol=ssl}
23:10:40.031 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:412]
- Begin getCredentials
23:10:40.032 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:413]
- useFistPass = false
23:10:40.032 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:414]
- tryFistPass = false
23:10:40.032 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:415]
- useCallback = false
23:10:40.032 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:416]

- callbackhandler class =
javax.security.auth.login.LoginContext$SecureCallbackHandler

23:10:40.032 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:419]

- name callback class = javax.security.auth.callback.NameCallback

23:10:40.032 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:421]

- password callback class =
javax.security.auth.callback.PasswordCallback

23:10:40.034 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:102] - Looking up DN
using userFilter

23:10:40.034 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:193] - Search with the
following parameters:

23:10:40.034 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:194] - dn = T=MYBASEDN

23:10:40.034 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:195] - filter =
(&(cn={0})(objectclass=person))

23:10:40.034 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:196] - filterArgs =

[jdoe-c]
23:10:40.035 - DEBUG
[edu.vt.middleware.ldap.auth.SearchDnResolver:197] - searchControls
= javax.naming.directory.SearchControls@cb9b8f
23:10:40.035 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:198] - handler =

[edu.vt.middleware.ldap.handler.FqdnSearchResultHandler@151dc28]
23:10:40.035 - 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=always,
java.naming.security.protocol=ssl}
23:10:40.035 - TRACE

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:93] - setting
connectionStrategy: DEFAULT

23:10:40.035 - TRACE

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:110] -
setting connectionRetryExceptions: [class
javax.naming.NamingException]

23:10:40.036 - TRACE

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:152] - {0}
Attempting connection to ldap://ldap01:636 for strategy DEFAULT

23:10:40.036 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:73] - Bind
with the following parameters:

23:10:40.036 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:74] -
authtype = simple

23:10:40.036 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:75] - dn =
null

23:10:40.036 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:82] -
credential = <suppressed>

23:10:40.036 - 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=always,
java.naming.security.protocol=ssl}
23:10:40.458 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:151] - Multiple results

found for user: jdoe-c using filter:
filter=(&(cn={0})(objectclass=person)),filterArgs=[]
23:10:40.465 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:164]

- Error occured attempting authentication

javax.naming.NamingException: Found more than (1) DN for: jdoe-c
at edu.vt.middleware.ldap.auth.SearchDnResolver.resolve(SearchDnResolver.java:156)
~[vt-ldap-3.3.3.jar:na]
at edu.vt.middleware.ldap.auth.Authenticator.getDn(Authenticator.java:106)

23:10:40.466 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:264]
- Begin abort

Once I go back and set dereference aliasing back to never, then the
aliases no longer return and login is successful...

00:00:46.293 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:144]
- Begin initialize
00:00:46.294 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:180]
- useFirstPass = false
00:00:46.294 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:181]
- tryFirstPass = false
00:00:46.294 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:182]
- storePass = false
00:00:46.294 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:183]
- clearPass = false
00:00:46.294 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:184]
- setLdapPrincipal = true
00:00:46.294 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:185]
- setLdapDnPrincipal = false
00:00:46.295 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:186]
- setLdapCredential = true
00:00:46.295 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:187]
- defaultRole = []
00:00:46.295 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:188]
- principalGroupName = null
00:00:46.295 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:189]
- roleGroupName = null
00:00:46.295 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:77]
- userRoleAttribute = []
00:00:46.301 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1385] - setting
searchScope: ONELEVEL

00:00:46.303 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:427] - setting
subtreeSearch: true

00:00:46.303 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1385] - setting
searchScope: SUBTREE

00:00:46.303 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1370] - setting
baseDn: T=MYBASEDN

00:00:46.303 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1834] - setting ssl:
true

00:00:46.303 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1168] - setting
ldapUrl: ldap://ldap01:636

00:00:46.304 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1651] - setting
derefAliases: never

00:00:46.304 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:290] - setting
userFilter: (&(cn={0})(objectclass=person))

00:00:46.305 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:83]
- Created authenticator:
edu.vt.middleware.ldap.auth.AuthenticatorConfig@22419002::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}
00:00:46.306 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:412]
- Begin getCredentials
00:00:46.306 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:413]
- useFistPass = false
00:00:46.306 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:414]
- tryFistPass = false
00:00:46.306 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:415]
- useCallback = false
00:00:46.306 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:416]

- callbackhandler class =
javax.security.auth.login.LoginContext$SecureCallbackHandler

00:00:46.307 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:419]

- name callback class = javax.security.auth.callback.NameCallback

00:00:46.307 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:421]

- password callback class =
javax.security.auth.callback.PasswordCallback

00:00:46.308 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:102] - Looking up DN
using userFilter

00:00:46.308 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:193] - Search with the
following parameters:

00:00:46.308 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:194] - dn = T=MYBASEDN

00:00:46.309 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:195] - filter =
(&(cn={0})(objectclass=person))

00:00:46.309 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:196] - filterArgs =

[JDOE-C]
00:00:46.309 - DEBUG
[edu.vt.middleware.ldap.auth.SearchDnResolver:197] - searchControls
= javax.naming.directory.SearchControls@82d811
00:00:46.309 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:198] - handler =

[edu.vt.middleware.ldap.handler.FqdnSearchResultHandler@374c8e]
00:00:46.310 - 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}

00:00:46.310 - TRACE

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:93] - setting
connectionStrategy: DEFAULT

00:00:46.310 - TRACE

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:110] -
setting connectionRetryExceptions: [class
javax.naming.NamingException]

00:00:46.310 - TRACE

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:152] - {0}
Attempting connection to ldap://ldap01:636 for strategy DEFAULT

00:00:46.310 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:73] - Bind
with the following parameters:

00:00:46.311 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:74] -
authtype = simple

00:00:46.311 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:75] - dn =
null

00:00:46.311 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:82] -
credential = <suppressed>

00:00:46.311 - 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}

00:00:46.550 - TRACE

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:93] - setting
connectionStrategy: DEFAULT

00:00:46.551 - TRACE

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:110] -
setting connectionRetryExceptions: [class
javax.naming.NamingException]

00:00:46.552 - TRACE

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:152] - {1}
Attempting connection to ldap://ldap01:636 for strategy DEFAULT

00:00:46.552 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:73] - Bind
with the following parameters:

00:00:46.552 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:74] -
authtype = simple

00:00:46.552 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:75] - dn =

cn=JDOE-C,ou=MYNEW,ou=DEPARTMENT,o=DIV
00:00:46.552 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:82] -
credential = <suppressed>

00:00:46.552 - 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}

00:00:46.777 - INFO
[edu.vt.middleware.ldap.jaas.JaasAuthenticator:176] - Authentication
succeeded for dn: cn=JDOE-C,ou=MYNEW,ou=DEPARTMENT,o=DIV
00:00:46.787 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:102] - Looking up DN
using userFilter

00:00:46.787 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:193] - Search with the
following parameters:

00:00:46.788 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:194] - dn = T=MYBASEDN

00:00:46.788 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:195] - filter =
(&(cn={0})(objectclass=person))

00:00:46.788 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:196] - filterArgs =

[JDOE-C]
00:00:46.789 - DEBUG
[edu.vt.middleware.ldap.auth.SearchDnResolver:197] - searchControls
= javax.naming.directory.SearchControls@9ebd53
00:00:46.789 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:198] - handler =

[edu.vt.middleware.ldap.handler.FqdnSearchResultHandler@374c8e]
00:00:46.789 - 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}

00:00:46.800 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:208]
- Begin commit
00:00:46.801 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:223]
- Committed the following principals: [JDOE-C[]]
00:00:46.801 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:229]

- Committed the following roles: []

00:00:46.858 - INFO [Shibboleth-Access:73] -
20110608T050046Z|144.45.7.139|www.mydomain.com:443|/profile/SAML2/Redirect/SSO|
00:00:46.893 - TRACE

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:93] - setting
connectionStrategy: ACTIVE_PASSIVE

00:00:46.893 - TRACE

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:110] -
setting connectionRetryExceptions: [class
javax.naming.NamingException]

00:00:46.893 - TRACE

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:152] - {1}
Attempting connection to ldaps://ldap01:636 for strategy
ACTIVE_PASSIVE

00:00:46.894 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:73] - Bind
with the following parameters:

00:00:46.894 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:74] -
authtype = simple

00:00:46.894 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:75] - dn =
null

00:00:46.894 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:82] -
credential = <suppressed>

00:00:46.894 - TRACE

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:86] - env =
{java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory,
java.naming.provider.url=ldaps://ldap01:636,
java.naming.ldap.derefAliases=never,
java.naming.ldap.attributes.binary=GUID}

00:00:47.114 - DEBUG [edu.vt.middleware.ldap.Ldap:193] - Search with
the following parameters:
00:00:47.114 - DEBUG [edu.vt.middleware.ldap.Ldap:194] - dn = T=MYBASEDN
00:00:47.114 - DEBUG [edu.vt.middleware.ldap.Ldap:195] - filter =
(&(cn=JDOE-C)(objectclass=person))
00:00:47.115 - DEBUG [edu.vt.middleware.ldap.Ldap:196] - filterArgs = []
00:00:47.115 - DEBUG [edu.vt.middleware.ldap.Ldap:197] -
searchControls = javax.naming.directory.SearchControls@bf3adc
00:00:47.115 - DEBUG [edu.vt.middleware.ldap.Ldap:198] - handler =
[edu.vt.middleware.ldap.handler.FqdnSearchResultHandler@1f66f50,
edu.vt.middleware.ldap.handler.EntryDnSearchResultHandler@61947,
edu.vt.middleware.ldap.handler.BinarySearchResultHandler@6597d1]
00:00:47.115 - TRACE [edu.vt.middleware.ldap.Ldap:200] - config =

{java.naming.provider.url=ldaps://ldap01:636,
java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory,
java.naming.ldap.derefAliases=never,
java.naming.ldap.attributes.binary=GUID}

00:00:47.132 - TRACE

[edu.vt.middleware.ldap.pool.DefaultLdapFactory:123] - destroyed ldap

object: edu.vt.middleware.ldap.Ldap@6304462::config=edu.vt.middleware.ldap.LdapConfig@13440889::env={java.naming.provider.url=ldaps://ldap01:636,
java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory,
java.naming.ldap.derefAliases=never,
java.naming.ldap.attributes.binary=GUID}
00:00:47.521 - INFO [Shibboleth-Audit:969] -
20110608T050047Z|urn:oasis:names:tc:SAML:2.0:bindings:HTTP-Redirect|_e2c6d19bdeebd8e666415e7b2b1fae09|https://www.mydomain.com/shibboleth|urn:mace:shibboleth:2.0:profiles:saml2:sso|https://www.mydomain.com/idp/shibboleth|urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST|_2bfff3f6b80fa10b46242720b0e20127|JDOE-C|urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport|cn,email,telephoneNumber,HexGUID,transientId,surname,givenName,IsCRISUser,AgencyID,|_0dd78a45e9f33fff0498713295b29af7||

But here is the odd thing, which is what originally caused me to post
to this thread...

Simply reverting the ldap properties in the login config so they match
the example, has the same affect as if I had set dereference aliases
to always.

New way works...

edu.vt.middleware.ldap.jaas.LdapLoginModule required
ldapUrl="ldap://ldap01:636"
ssl="true"
baseDn="T=MYBASEDN"
subtreeSearch="true"
derefAliases="never"
userFilter="(&(cn={0})(objectclass=person))";

Old way doesn't work...

edu.vt.middleware.ldap.jaas.LdapLoginModule required
host="ldap://ldap01:636"
port="636"

base="T=MYBASDN"

ssl="true"
userField="cn"
subtreeSearch="true"
derefAliases="never";

Note that in both cases I have derefAliases = never, but using the old
parameters fails because the alias is followed and I get 2 results.
The exact same properties work just fine with the old version of
vt-ldap that shipped in IdP 2.2.1. I still haven't been able to
explain this behavior, but like I stated earlier, I'm not sure this is
even valid since the old properties aren't even mentioned in the docs
anymore.

00:12:11.242 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:144]
- Begin initialize
00:12:11.243 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:180]
- useFirstPass = false
00:12:11.243 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:181]
- tryFirstPass = false
00:12:11.243 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:182]
- storePass = false
00:12:11.243 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:183]
- clearPass = false
00:12:11.243 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:184]
- setLdapPrincipal = true
00:12:11.243 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:185]
- setLdapDnPrincipal = false
00:12:11.244 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:186]
- setLdapCredential = true
00:12:11.244 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:187]
- defaultRole = []
00:12:11.244 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:188]
- principalGroupName = null
00:12:11.244 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:189]
- roleGroupName = null
00:12:11.244 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:77]
- userRoleAttribute = []
00:12:11.249 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1385] - setting
searchScope: ONELEVEL

00:12:11.251 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:427] - setting
subtreeSearch: true

00:12:11.251 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1385] - setting
searchScope: SUBTREE

00:12:11.252 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1834] - setting ssl:
true

00:12:11.252 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1168] - setting
ldapUrl: ldap://ldap01:636

00:12:11.252 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:274] - setting
userField: [cn]

00:12:11.252 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1651] - setting
derefAliases: never

00:12:11.253 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1370] - setting
baseDn: T=MYBASEDN

00:12:11.254 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:83]
- Created authenticator:
edu.vt.middleware.ldap.auth.AuthenticatorConfig@15257019::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}
00:12:11.254 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:412]
- Begin getCredentials
00:12:11.255 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:413]
- useFistPass = false
00:12:11.255 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:414]
- tryFistPass = false
00:12:11.255 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:415]
- useCallback = false
00:12:11.255 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:416]

- callbackhandler class =
javax.security.auth.login.LoginContext$SecureCallbackHandler

00:12:11.255 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:419]

- name callback class = javax.security.auth.callback.NameCallback

00:12:11.255 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:421]

- password callback class =
javax.security.auth.callback.PasswordCallback

00:12:11.256 - DEBUG
[edu.vt.middleware.ldap.auth.SearchDnResolver:108] - Looking up DN
using userField
00:12:11.257 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:193] - Search with the
following parameters:

00:12:11.257 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:194] - dn = T=MYBASEDN

00:12:11.257 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:195] - filter =

(cn={0})
00:12:11.257 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:196] - filterArgs =

[jdoe-c]
00:12:11.257 - DEBUG
[edu.vt.middleware.ldap.auth.SearchDnResolver:197] - searchControls
= javax.naming.directory.SearchControls@172978f
00:12:11.258 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:198] - handler =

[edu.vt.middleware.ldap.handler.FqdnSearchResultHandler@3c591c]
00:12:11.258 - 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}

00:12:11.258 - TRACE

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:93] - setting
connectionStrategy: DEFAULT

00:12:11.258 - TRACE

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:110] -
setting connectionRetryExceptions: [class
javax.naming.NamingException]

00:12:11.259 - TRACE

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:152] - {0}
Attempting connection to ldap://ldap01:636 for strategy DEFAULT

00:12:11.259 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:73] - Bind
with the following parameters:

00:12:11.259 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:74] -
authtype = simple

00:12:11.259 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:75] - dn =
null

00:12:11.259 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:82] -
credential = <suppressed>

00:12:11.260 - 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}

00:12:11.496 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:151] - Multiple results

found for user: jdoe-c using filter: filter=(cn={0}),filterArgs=[]
00:12:11.502 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:164]

- Error occured attempting authentication

javax.naming.NamingException: Found more than (1) DN for: jdoe-c
at edu.vt.middleware.ldap.auth.SearchDnResolver.resolve(SearchDnResolver.java:156)
~[vt-ldap-3.3.3.jar:na]
at edu.vt.middleware.ldap.auth.Authenticator.getDn(Authenticator.java:106)

00:12:11.504 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:264]
- Begin abort

--

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.

On Tue, Jun 7, 2011 at 7:08 PM, Dan McLaughlin

[Dan McLaughlin]

Hi Daniel,

What allowed me to get past the invalid credential error in vt-ldap
3.3.3 was to revert...

"1877 4/5/11 9:42 AM 4 dfisher SearchResult#getName() returns a string
representing a composite name, not necessarily an LDAP DN. Use a
CompositeName to parse it correctly. Add test case for entries with
special characters. Fixes vt-ldap 109."

There was a problem parsing the fqdn url and then things died from
there... I didn't spend too much time trying to figure out why b/c I
have to get IdP 2.3.0 up and running by the morning.

--

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.

[Daniel Fisher]

Yes, if you follow the pointer the alias is not returned. Whatever
entry it points to is returned.

> I don't want aliases to be followed or
> searches will return the alias and the person (which is too many
> results).

No, if aliases are followed they are not returned. Based on your
comments below we seem to have a semantic issue. When you say 'alias'
I assume you mean the entry with objectClass=alias. What you really
mean is the entry the alias points to?

> (BTW... countLimit=1 is another workaround I've found).

That could produce indeterminate results since LDAP result sets are
not ordered. You couldn't guarantee which entry you are getting.
(unless eDir has some support for ordering)

> So a search for with dereference alias=always for
> (&(cn=jdoe-c)(objectclass=person)) will return both the person that
> the alias jdoe-c points to and the actual person jdoe-c.
>

Ok, I think I'm starting to understand your schema. jdoe-c actually
has (3) entries in your directory. The one you want, an alias to one
you don't want, and the one you don't want. Could you post the LDIF
for the two entries with objectclass=person just so I'm clear on this?

> This returns more than one result an the following error occurs:
>

> 23:10:40.458 - DEBUG
> [edu.vt.middleware.ldap.auth.SearchDnResolver:151] - Multiple results
> found for user: jdoe-c using filter:
> filter=(&(cn={0})(objectclass=person)),filterArgs=[]
> 23:10:40.465 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:164]
> - Error occured attempting authentication
> javax.naming.NamingException: Found more than (1) DN for: jdoe-c
>        at edu.vt.middleware.ldap.auth.SearchDnResolver.resolve(SearchDnResolver.java:156)
>

Ok, this makes sense now. The alias was followed and you got back the
entry you want and the entry you don't want. I've been working under
the assumption that the alias pointed to the entry you want.

> Once I go back and set dereference aliasing back to never, then the
> aliases no longer return and login is successful...
>

Yes, the aliasedObject is not dereferenced. We may actually be on the
same page now.

>
> But here is the odd thing, which is what originally caused me to post
> to this thread...
>
> Simply reverting the ldap properties in the login config so they match
> the example, has the same affect as if I had set dereference aliases
> to always.
>
> New way works...
>
>   edu.vt.middleware.ldap.jaas.LdapLoginModule required
>     ldapUrl="ldap://ldap01:636"
>     ssl="true"
>     baseDn="T=MYBASEDN"
>     subtreeSearch="true"
>     derefAliases="never"
>     userFilter="(&(cn={0})(objectclass=person))";
>
> Old way doesn't work...
>
>  edu.vt.middleware.ldap.jaas.LdapLoginModule required
>      host="ldap://ldap01:636"
>      port="636"
>      base="T=MYBASDN"
>      ssl="true"
>      userField="cn"
>      subtreeSearch="true"
>      derefAliases="never";
>
> Note that in both cases I have derefAliases = never, but using the old
> parameters fails because the alias is followed and I get 2 results.

This alias isn't followed since you've set derefAliases to never. The
only difference here is the (objectclass=person) filter. So in this
case you are getting the entry you want and the alias entry, since the
filter doesn't exclude it. Based on what I know about your schema, I
can't think of any reason this would have worked in 2.2.1. Do you mean
2.1.x? Do your LDAP logs shed any light on this?

> The exact same properties work just fine with the old version of
> vt-ldap that shipped in IdP 2.2.1.  I still haven't been able to
> explain this behavior, but like I stated earlier, I'm not sure this is
> even valid since the old properties aren't even mentioned in the docs
> anymore.

The properties are valid, they are just deprecated.

--Daniel Fisher

[Daniel Fisher]

On Wed, Jun 8, 2011 at 2:07 AM, Dan McLaughlin
<dmcla...@tech-consortium.com> wrote:
> Hi Daniel,
>

> What allowed me to get past the invalid credential error in vt-ldap
> 3.3.3 was to revert...
>

This change has nothing to do with the credential (password). If
you're seeing that error the password is either null or empty.

> "1877   4/5/11 9:42 AM  4       dfisher SearchResult#getName() returns a string
> representing a composite name, not necessarily an LDAP DN. Use a
> CompositeName to parse it correctly. Add test case for entries with
> special characters. Fixes vt-ldap 109."
>
> There was a problem parsing the fqdn url and then things died from
> there...  I didn't spend too much time trying to figure out why b/c I
> have to get IdP 2.3.0 up and running by the morning.

Died how? Was there an exception? Post the trace log and I'll try to
decipher it.

--Daniel Fisher

[Dan McLaughlin]

Hi Daniel,

Sorry, you are right about it being a semantic issue. :)

I only have one alias that points to a single person object.  We are
searching from the base of the LDAP tree, so I don't care about
aliases and I don't want them or the object they point returned, ever.
If deferenceAlias = always then two users with (cn=joe-c) are
returned; the user that the alias references and the user.

This is one too many, so I get the exception:

found for user: jdoe-c using filter: filter=(cn={0}),filterArgs=[]

00:12:11.502 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:164]

- Error occured attempting authentication
javax.naming.NamingException: Found more than (1) DN for: jdoe-c
       at edu.vt.middleware.ldap.auth.SearchDnResolver.resolve(SearchDnResolver.java:156)

~[vt-ldap-3.3.3.jar:na]
       at edu.vt.middleware.ldap.auth.Authenticator.getDn(Authenticator.java:106)

I agree the old properties are valid, but there is some bug that is
causing aliases to be dereference regardless. I think you would agree
the following two configuration examples should NEVER dereference
aliases. If dereference aliases is set to never and I search the
entire tree and I have one alias that points to one user, then only
the one user should be returned.  Correct?

I still have the old config running on several 2.2.1 IdP's and it
works fine.  If I try and use the same old config settings below and
copy them to a 2.3.0 IdP get the exception
"javax.naming.NamingException: Found more than (1) DN for: jdoe-c".
If I simply change out the old properties for the new ones then
everything starts working again and the aliases are never deferenced.

New way works...
>   edu.vt.middleware.ldap.jaas.LdapLoginModule required
>     ldapUrl="ldap://ldap01:636"
>     ssl="true"
>     baseDn="T=MYBASEDN"
>     subtreeSearch="true"
>     derefAliases="never"
>     userFilter="(&(cn={0})(objectclass=person))";
>

Old way doesn't work...
>
>  edu.vt.middleware.ldap.jaas.LdapLoginModule required
>      host="ldap://ldap01:636"
>      port="636"
>      base="T=MYBASDN"
>      ssl="true"
>      userField="cn"
>      subtreeSearch="true"
>      derefAliases="never";
>

--

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.

[Dan McLaughlin]

You are correct that FqdnSearchResultHandler.java should have nothing
to do with the credential exception. Unless there is an exception
being swallowed somewhere. My theory until I have a second to step
through it with the debugger is that there is some other exception
that occurs in FqdnSearchResultHandler.java when it is trying to read
the composite name that is eating an exception and things eventually
bubble up as a missing credential exception.

--

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.

[Dan McLaughlin]

After enabling DEBUG for shibboleth I'm seeing another exception that
only shows up if DEBUG logging is enabled... I've been stepping
through the code with a debugger and I keep seeing it loop through
readCompositeName multiple times returning the string "ldap:" for name
(line 109) over and over again. This code is all new to me, so I'm
still trying to make since of what's going on. Does any of this make
since to you?

19:19:30.237 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:264]
- Begin abort
19:19:30.301 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:176]
- User authentication for joe-c failed
javax.security.auth.login.LoginException: java.lang.IllegalArgumentException
at java.net.URI.create(URI.java:842)
at edu.vt.middleware.ldap.handler.FqdnSearchResultHandler.processDn(FqdnSearchResultHandler.java:80)
at edu.vt.middleware.ldap.handler.CopySearchResultHandler.processResult(CopySearchResultHandler.java:64)
at edu.vt.middleware.ldap.handler.CopySearchResultHandler.processResult(CopySearchResultHandler.java:27)
at edu.vt.middleware.ldap.handler.AbstractResultHandler.process(AbstractResultHandler.java:84)
at edu.vt.middleware.ldap.AbstractLdap.search(AbstractLdap.java:231)
at edu.vt.middleware.ldap.auth.SearchDnResolver.resolve(SearchDnResolver.java:139)
at edu.vt.middleware.ldap.auth.Authenticator.getDn(Authenticator.java:106)
at edu.vt.middleware.ldap.jaas.JaasAuthenticator.authenticate(JaasAuthenticator.java:74)
at edu.vt.middleware.ldap.auth.Authenticator.authenticate(Authenticator.java:320)
at edu.vt.middleware.ldap.auth.Authenticator.authenticate(Authenticator.java:277)
at edu.vt.middleware.ldap.jaas.JaasAuthenticator.authenticate(JaasAuthenticator.java:60)
at edu.vt.middleware.ldap.jaas.LdapLoginModule.login(LdapLoginModule.java:103)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at javax.security.auth.login.LoginContext.invoke(LoginContext.java:769)
at javax.security.auth.login.LoginContext.access$000(LoginContext.java:186)
at javax.security.auth.login.LoginContext$4.run(LoginContext.java:683)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.login.LoginContext.invokePriv(LoginContext.java:680)
at javax.security.auth.login.LoginContext.login(LoginContext.java:579)
at edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet.authenticateUser(UsernamePasswordLoginServlet.java:160)
at edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet.service(UsernamePasswordLoginServlet.java:106)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at edu.internet2.middleware.shibboleth.idp.util.NoCacheFilter.doFilter(NoCacheFilter.java:49)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter.doFilter(IdPSessionFilter.java:80)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at edu.internet2.middleware.shibboleth.common.log.SLF4JMDCCleanupFilter.doFilter(SLF4JMDCCleanupFilter.java:51)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:219)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
at com.googlecode.psiprobe.Tomcat60AgentValve.invoke(Tomcat60AgentValve.java:30)
at org.apache.catalina.ha.session.JvmRouteBinderValve.invoke(JvmRouteBinderValve.java:227)
at org.apache.catalina.ha.tcp.ReplicationValve.invoke(ReplicationValve.java:347)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
at org.apache.catalina.valves.RemoteIpValve.invoke(RemoteIpValve.java:647)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:298)
at org.apache.coyote.ajp.AjpAprProcessor.process(AjpAprProcessor.java:429)
at org.apache.coyote.ajp.AjpAprProtocol$AjpConnectionHandler.process(AjpAprProtocol.java:384)
at org.apache.tomcat.util.net.AprEndpoint$Worker.run(AprEndpoint.java:1665)
at java.lang.Thread.run(Thread.java:662)
Caused by: java.net.URISyntaxException: Expected scheme-specific part
at index 5: ldap:
at java.net.URI$Parser.fail(URI.java:2809)
at java.net.URI$Parser.failExpecting(URI.java:2815)
at java.net.URI$Parser.parse(URI.java:3018)
at java.net.URI.<init>(URI.java:578)
at java.net.URI.create(URI.java:840)
... 50 more

at javax.security.auth.login.LoginContext.invoke(LoginContext.java:872)
~[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]

19:19:30.302 - TRACE
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:332] -
Looking up LoginContext with key 31608d9c-762f-4830-a836-2555b6e24cc9
from StorageService parition: loginContexts
19:19:30.302 - TRACE
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:338] -
Retrieved LoginContext with key 31608d9c-762f-4830-a836-2555b6e24cc9
from StorageService parition: loginContexts
19:19:30.303 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:133]
- Redirecting to login page /login.jsp
19:21:45.381 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:264]
- Begin abort

--

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.

[Daniel Fisher]

Try adding this to your jaas config:

searchResultHandlers="edu.vt.middleware.ldap.handler.FqdnSearchResultHandler{{removeUrls=false}}"

and then post your logs.

--Daniel Fisher

On Wed, Jun 8, 2011 at 8:31 PM, Dan McLaughlin

[Dan McLaughlin]

20:35:36.857 - TRACE
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:108]
- Attempting to retrieve IdP session cookie.
20:35:36.858 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:153]
- Attempting to authenticate user jdoe-c
20:35:36.858 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:144]
- Begin initialize
20:35:36.858 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:180]
- useFirstPass = false
20:35:36.858 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:181]
- tryFirstPass = false
20:35:36.858 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:182]
- storePass = false
20:35:36.859 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:183]
- clearPass = false
20:35:36.859 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:184]
- setLdapPrincipal = true
20:35:36.859 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:185]
- setLdapDnPrincipal = false
20:35:36.859 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:186]
- setLdapCredential = true
20:35:36.859 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:187]
- defaultRole = []
20:35:36.859 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:188]
- principalGroupName = null
20:35:36.860 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:189]
- roleGroupName = null
20:35:36.860 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:77]
- userRoleAttribute = []
20:35:36.860 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1385] - setting
searchScope: ONELEVEL

20:35:36.861 - TRACE
[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1683] - setting
searchResultsHandlers:
[edu.vt.middleware.ldap.handler.FqdnSearchResultHandler@74f334]
20:35:36.861 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:427] - setting
subtreeSearch: true

20:35:36.861 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1385] - setting
searchScope: SUBTREE

20:35:36.861 - TRACE
[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1370] - setting
baseDn: T=MAYBASEDN
20:35:36.862 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1834] - setting ssl:
true

20:35:36.862 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1168] - setting
ldapUrl: ldap://ldap01:636

20:35:36.862 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1651] - setting
derefAliases: never

20:35:36.862 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:290] - setting
userFilter: (&(cn={0})(objectclass=person))

20:35:36.862 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:83]
- Created authenticator:
edu.vt.middleware.ldap.auth.AuthenticatorConfig@718554::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}
20:35:36.863 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:412]
- Begin getCredentials
20:35:36.863 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:413]
- useFistPass = false
20:35:36.863 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:414]
- tryFistPass = false
20:35:36.863 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:415]
- useCallback = false
20:35:36.863 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:416]

- callbackhandler class =
javax.security.auth.login.LoginContext$SecureCallbackHandler

20:35:36.863 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:419]

- name callback class = javax.security.auth.callback.NameCallback

20:35:36.864 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:421]

- password callback class =
javax.security.auth.callback.PasswordCallback

20:35:36.864 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:102] - Looking up DN
using userFilter

20:35:36.864 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:193] - Search with the
following parameters:

20:35:36.864 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:194] - dn =

T=MAYBASEDN
20:35:36.864 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:195] - filter =
(&(cn={0})(objectclass=person))

20:35:36.865 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:196] - filterArgs =

[jdoe-c]
20:35:36.865 - DEBUG
[edu.vt.middleware.ldap.auth.SearchDnResolver:197] - searchControls
= javax.naming.directory.SearchControls@1d47ef4
20:35:36.865 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:198] - handler =

[edu.vt.middleware.ldap.handler.FqdnSearchResultHandler@74f334]
20:35:36.865 - 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}

20:35:36.865 - TRACE

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:93] - setting
connectionStrategy: DEFAULT

20:35:36.865 - TRACE

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:110] -
setting connectionRetryExceptions: [class
javax.naming.NamingException]

20:35:36.866 - TRACE

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:152] - {0}
Attempting connection to ldap://ldap01:636 for strategy DEFAULT

20:35:36.866 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:73] - Bind
with the following parameters:

20:35:36.866 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:74] -
authtype = simple

20:35:36.866 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:75] - dn =
null

20:35:36.866 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:82] -
credential = <suppressed>

20:35:36.867 - 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}

20:35:37.120 - TRACE

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:93] - setting
connectionStrategy: DEFAULT

20:35:37.121 - TRACE

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:110] -
setting connectionRetryExceptions: [class
javax.naming.NamingException]

20:35:37.121 - TRACE

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:152] - {1}
Attempting connection to ldap://ldap01:636 for strategy DEFAULT

20:35:37.121 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:73] - Bind
with the following parameters:

20:35:37.122 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:74] -
authtype = simple

20:35:37.122 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:75] - dn =

ldap:
20:35:37.122 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:82] -
credential = <suppressed>

20:35:37.122 - 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}

20:35:37.339 - DEBUG
[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:163] - Error
connecting to LDAP URL: ldap://ldap01:636
javax.naming.InvalidNameException: [LDAP: error code 34 - Invalid DN Syntax]
at com.sun.jndi.ldap.LdapCtx.processReturnCode(LdapCtx.java:2982)
~[na:1.6.0_24]
at com.sun.jndi.ldap.LdapCtx.processReturnCode(LdapCtx.java:2789)
~[na:1.6.0_24]
at com.sun.jndi.ldap.LdapCtx.connect(LdapCtx.java:2703) ~[na:1.6.0_24]
at com.sun.jndi.ldap.LdapCtx.<init>(LdapCtx.java:293) ~[na:1.6.0_24]
at com.sun.jndi.ldap.LdapCtxFactory.getUsingURL(LdapCtxFactory.java:175)
~[na:1.6.0_24]
at com.sun.jndi.ldap.LdapCtxFactory.getUsingURLs(LdapCtxFactory.java:193)
~[na:1.6.0_24]
at com.sun.jndi.ldap.LdapCtxFactory.getLdapCtxInstance(LdapCtxFactory.java:136)
~[na:1.6.0_24]
at com.sun.jndi.ldap.LdapCtxFactory.getInitialContext(LdapCtxFactory.java:66)
~[na:1.6.0_24]
at javax.naming.spi.NamingManager.getInitialContext(NamingManager.java:667)
~[na:1.6.0_24]
at javax.naming.InitialContext.getDefaultInitCtx(InitialContext.java:288)
~[na:1.6.0_24]
at javax.naming.InitialContext.init(InitialContext.java:223) ~[na:1.6.0_24]
at javax.naming.ldap.InitialLdapContext.<init>(InitialLdapContext.java:134)
~[na:1.6.0_24]
at edu.vt.middleware.ldap.handler.DefaultConnectionHandler.connectInternal(DefaultConnectionHandler.java:102)
~[vt-ldap-3.3.3.jar:na]
at edu.vt.middleware.ldap.handler.AbstractConnectionHandler.connect(AbstractConnectionHandler.java:156)
~[vt-ldap-3.3.3.jar:na]
at edu.vt.middleware.ldap.auth.handler.BindAuthenticationHandler.authenticate(BindAuthenticationHandler.java:53)
[vt-ldap-3.3.3.jar:na]
at edu.vt.middleware.ldap.auth.AbstractAuthenticator.authenticateAndAuthorize(AbstractAuthenticator.java:174)

[vt-ldap-3.3.3.jar:na]
at edu.vt.middleware.ldap.jaas.JaasAuthenticator.authenticate(JaasAuthenticator.java:74)

[vt-ldap-3.3.3.jar:na]
at edu.vt.middleware.ldap.auth.Authenticator.authenticate(Authenticator.java:320)

[vt-ldap-3.3.3.jar:na]
at edu.vt.middleware.ldap.auth.Authenticator.authenticate(Authenticator.java:277)

[vt-ldap-3.3.3.jar:na]
at edu.vt.middleware.ldap.jaas.JaasAuthenticator.authenticate(JaasAuthenticator.java:60)

[vt-ldap-3.3.3.jar:na]
at edu.vt.middleware.ldap.jaas.LdapLoginModule.login(LdapLoginModule.java:103)

[vt-ldap-3.3.3.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)

20:35:37.340 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:164]

- Error occured attempting authentication

javax.naming.InvalidNameException: [LDAP: error code 34 - Invalid DN Syntax]
at com.sun.jndi.ldap.LdapCtx.processReturnCode(LdapCtx.java:2982)
~[na:1.6.0_24]
at com.sun.jndi.ldap.LdapCtx.processReturnCode(LdapCtx.java:2789)
~[na:1.6.0_24]
at com.sun.jndi.ldap.LdapCtx.connect(LdapCtx.java:2703) ~[na:1.6.0_24]
at com.sun.jndi.ldap.LdapCtx.<init>(LdapCtx.java:293) ~[na:1.6.0_24]
at com.sun.jndi.ldap.LdapCtxFactory.getUsingURL(LdapCtxFactory.java:175)
~[na:1.6.0_24]
at com.sun.jndi.ldap.LdapCtxFactory.getUsingURLs(LdapCtxFactory.java:193)
~[na:1.6.0_24]
at com.sun.jndi.ldap.LdapCtxFactory.getLdapCtxInstance(LdapCtxFactory.java:136)
~[na:1.6.0_24]
at com.sun.jndi.ldap.LdapCtxFactory.getInitialContext(LdapCtxFactory.java:66)
~[na:1.6.0_24]
at javax.naming.spi.NamingManager.getInitialContext(NamingManager.java:667)
~[na:1.6.0_24]
at javax.naming.InitialContext.getDefaultInitCtx(InitialContext.java:288)
~[na:1.6.0_24]
at javax.naming.InitialContext.init(InitialContext.java:223) ~[na:1.6.0_24]
at javax.naming.ldap.InitialLdapContext.<init>(InitialLdapContext.java:134)
~[na:1.6.0_24]
at edu.vt.middleware.ldap.handler.DefaultConnectionHandler.connectInternal(DefaultConnectionHandler.java:102)
~[vt-ldap-3.3.3.jar:na]
at edu.vt.middleware.ldap.handler.AbstractConnectionHandler.connect(AbstractConnectionHandler.java:156)
~[vt-ldap-3.3.3.jar:na]
at edu.vt.middleware.ldap.auth.handler.BindAuthenticationHandler.authenticate(BindAuthenticationHandler.java:53)
~[vt-ldap-3.3.3.jar:na]
at edu.vt.middleware.ldap.auth.AbstractAuthenticator.authenticateAndAuthorize(AbstractAuthenticator.java:174)

~[vt-ldap-3.3.3.jar:na]
at edu.vt.middleware.ldap.jaas.JaasAuthenticator.authenticate(JaasAuthenticator.java:74)
~[vt-ldap-3.3.3.jar:na]
at edu.vt.middleware.ldap.auth.Authenticator.authenticate(Authenticator.java:320)
~[vt-ldap-3.3.3.jar:na]
at edu.vt.middleware.ldap.auth.Authenticator.authenticate(Authenticator.java:277)
~[vt-ldap-3.3.3.jar:na]
at edu.vt.middleware.ldap.jaas.JaasAuthenticator.authenticate(JaasAuthenticator.java:60)
~[vt-ldap-3.3.3.jar:na]
at edu.vt.middleware.ldap.jaas.LdapLoginModule.login(LdapLoginModule.java:103)
~[vt-ldap-3.3.3.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)

20:35:37.341 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:264]
- Begin abort
20:35:37.342 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:176]
- User authentication for jdoe-c failed
javax.security.auth.login.LoginException: [LDAP: error code 34 -
Invalid DN Syntax]
at edu.vt.middleware.ldap.jaas.LdapLoginModule.login(LdapLoginModule.java:167)

~[vt-ldap-3.3.3.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)

20:35:37.344 - TRACE
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:332] -
Looking up LoginContext with key c9f9399e-104b-4ede-a584-e22b60591e5d
from StorageService parition: loginContexts
20:35:37.344 - TRACE
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:338] -
Retrieved LoginContext with key c9f9399e-104b-4ede-a584-e22b60591e5d
from StorageService parition: loginContexts
20:35:37.344 - DEBUG

[edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:133]
- Redirecting to login page /login.jsp

--

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.

[Daniel Fisher]

Hmmm....ok now now use the same jaas config with vt-ldap 3.3.2.
Thanks for indulging me on all these tests.

--Daniel Fisher

On Wed, Jun 8, 2011 at 9:41 PM, Dan McLaughlin

[Dan McLaughlin]

Here are the results with 3.3.2...

As long as I comment out the searchResultsHandlers you had me add,
then 3.3.2 works fine.

edu.vt.middleware.ldap.jaas.LdapLoginModule sufficient

ldapUrl="ldap://ldap01:636"
ssl="true"
baseDn="T=MYBASEDN"
subtreeSearch="true"
derefAliases="never"
userFilter="(&(cn={0})(objectclass=person))";

// searchResultHandlers="edu.vt.middleware.ldap.handler.FqdnSearchResultHandler{{removeUrls=false}}";

21:52:44.258 - DEBUG

[edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:133]
- Redirecting to login page /login.jsp

21:52:52.066 - TRACE

[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:108]
- Attempting to retrieve IdP session cookie.

21:52:52.066 - TRACE
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:114]
- Found IdP session cookie.
21:52:52.066 - DEBUG
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:159]
- No session associated with session ID
NTUzNGEwY2RlYTA2ODY1YjZjOTMzNDU4ZmM5YTBkZTU5ZTljNThkYWQxMTlkNjEwMTYyMWJiMWY2Yzc1MmQ1Nw==
- session must have timed out
21:52:52.068 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:153]
- Attempting to authenticate user JDOE-C
21:52:52.078 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:138]
- Begin initialize
21:52:52.079 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:172]
- useFirstPass = false
21:52:52.079 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:173]
- tryFirstPass = false
21:52:52.079 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:174]
- storePass = false
21:52:52.079 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:175]
- setLdapPrincipal = true
21:52:52.079 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:176]
- setLdapDnPrincipal = false
21:52:52.080 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:177]
- setLdapCredential = true
21:52:52.080 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:178]
- defaultRole = []
21:52:52.080 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:179]
- principalGroupName = null
21:52:52.080 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:180]
- roleGroupName = null
21:52:52.080 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:77]
- userRoleAttribute = []
21:52:52.086 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1385] - setting
searchScope: ONELEVEL

21:52:52.088 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:427] - setting
subtreeSearch: true

21:52:52.089 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1385] - setting
searchScope: SUBTREE

21:52:52.089 - TRACE
[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1370] - setting
baseDn: T=MYBASEDN
21:52:52.089 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1834] - setting ssl:
true

21:52:52.089 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1168] - setting
ldapUrl: ldap://ldap01:636

21:52:52.090 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1651] - setting
derefAliases: never

21:52:52.090 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:290] - setting
userFilter: (&(cn={0})(objectclass=person))

21:52:52.092 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:83]
- Created authenticator:
edu.vt.middleware.ldap.auth.AuthenticatorConfig@19286893::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}
21:52:52.093 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:368]
- Begin getCredentials
21:52:52.093 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:369]
- useFistPass = false
21:52:52.093 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:370]
- tryFistPass = false
21:52:52.093 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:371]
- useCallback = false
21:52:52.093 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:372]

- callbackhandler class =
javax.security.auth.login.LoginContext$SecureCallbackHandler

21:52:52.094 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:375]

- name callback class = javax.security.auth.callback.NameCallback

21:52:52.094 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:377]

- password callback class =
javax.security.auth.callback.PasswordCallback

21:52:52.095 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:102] - Looking up DN
using userFilter

21:52:52.096 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:193] - Search with the
following parameters:

21:52:52.096 - DEBUG
[edu.vt.middleware.ldap.auth.SearchDnResolver:194] - dn = T=MYBASEDN
21:52:52.096 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:195] - filter =
(&(cn={0})(objectclass=person))

21:52:52.097 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:196] - filterArgs =

[JDOE-C]
21:52:52.097 - DEBUG
[edu.vt.middleware.ldap.auth.SearchDnResolver:197] - searchControls
= javax.naming.directory.SearchControls@1380be8
21:52:52.097 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:198] - handler =

[edu.vt.middleware.ldap.handler.FqdnSearchResultHandler@95ec91]
21:52:52.097 - 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}

21:52:52.098 - TRACE

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:93] - setting
connectionStrategy: DEFAULT

21:52:52.098 - TRACE

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:110] -
setting connectionRetryExceptions: [class
javax.naming.NamingException]

21:52:52.098 - TRACE

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:152] - {0}
Attempting connection to ldap://ldap01:636 for strategy DEFAULT

21:52:52.098 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:73] - Bind
with the following parameters:

21:52:52.099 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:74] -
authtype = simple

21:52:52.099 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:75] - dn =
null

21:52:52.099 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:82] -
credential = <suppressed>

21:52:52.099 - 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}

21:52:52.346 - TRACE

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:93] - setting
connectionStrategy: DEFAULT

21:52:52.346 - TRACE

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:110] -
setting connectionRetryExceptions: [class
javax.naming.NamingException]

21:52:52.347 - TRACE

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:152] - {1}
Attempting connection to ldap://ldap01:636 for strategy DEFAULT

21:52:52.347 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:73] - Bind
with the following parameters:

21:52:52.347 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:74] -
authtype = simple

21:52:52.347 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:75] - dn =

cn=JDOE-C,ou=FOO,ou=BAR,o=DIV
21:52:52.348 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:82] -
credential = <suppressed>

21:52:52.348 - 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}

21:52:52.572 - INFO
[edu.vt.middleware.ldap.jaas.JaasAuthenticator:176] - Authentication
succeeded for dn: cn=JDOE-C,ou=FOO,ou=BAR,o=DIV
21:52:52.580 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:102] - Looking up DN
using userFilter

21:52:52.580 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:193] - Search with the
following parameters:

21:52:52.580 - DEBUG
[edu.vt.middleware.ldap.auth.SearchDnResolver:194] - dn = T=MYBASEDN
21:52:52.580 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:195] - filter =
(&(cn={0})(objectclass=person))

21:52:52.580 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:196] - filterArgs =

[JDOE-C]
21:52:52.580 - DEBUG
[edu.vt.middleware.ldap.auth.SearchDnResolver:197] - searchControls
= javax.naming.directory.SearchControls@1676b1e
21:52:52.581 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:198] - handler =

[edu.vt.middleware.ldap.handler.FqdnSearchResultHandler@95ec91]
21:52:52.581 - 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}

21:52:52.594 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:199]
- Begin commit
21:52:52.594 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:207]
- Committed the following principals: [JDOE-C[]]
21:52:52.594 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:213]

- Committed the following roles: []

21:52:52.595 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:161]
- Successfully authenticated user JDOE-C
21:52:52.597 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:143]
- Returning control to authentication engine
21:52:52.597 - TRACE
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:332] -
Looking up LoginContext with key 82a67795-fd9c-4dd3-8ec4-c84bcbb544bc
from StorageService parition: loginContexts
21:52:52.597 - TRACE
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:338] -
Retrieved LoginContext with key 82a67795-fd9c-4dd3-8ec4-c84bcbb544bc
from StorageService parition: loginContexts
21:52:52.597 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:201]
- Processing incoming request
21:52:52.598 - TRACE
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:332] -
Looking up LoginContext with key 82a67795-fd9c-4dd3-8ec4-c84bcbb544bc
from StorageService parition: loginContexts
21:52:52.598 - TRACE
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:338] -
Retrieved LoginContext with key 82a67795-fd9c-4dd3-8ec4-c84bcbb544bc
from StorageService parition: loginContexts
21:52:52.598 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:509]
- Completing user authentication process
21:52:52.598 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:576]
- Validating authentication was performed successfully
21:52:52.598 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:681]
- Updating session information for principal JDOE-C
21:52:52.598 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:685]
- Creating shibboleth session for principal JDOE-C
21:52:52.601 - TRACE
[edu.internet2.middleware.shibboleth.idp.session.impl.SessionManagerImpl:97]
- Created session
93b138564b63f5786b7e0e0918ac065116310355028e9253b4728ff290eae1df
21:52:52.601 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:791]
- Adding IdP session cookie to HTTP response
21:52:52.602 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:700]
- Recording authentication and service information in Shibboleth
session for principal: JDOE-C
21:52:52.603 - TRACE
[edu.internet2.middleware.shibboleth.idp.session.impl.SessionManagerImpl:172]
- Added index JDOE-C to session
93b138564b63f5786b7e0e0918ac065116310355028e9253b4728ff290eae1df
21:52:52.604 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:551]
- User JDOE-C authenticated with method

urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport

21:52:52.604 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:160]
- Returning control to profile handler
21:52:52.605 - TRACE
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:332] -
Looking up LoginContext with key 82a67795-fd9c-4dd3-8ec4-c84bcbb544bc
from StorageService parition: loginContexts
21:52:52.605 - TRACE
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:338] -
Retrieved LoginContext with key 82a67795-fd9c-4dd3-8ec4-c84bcbb544bc
from StorageService parition: loginContexts
21:52:52.605 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:169]
- Redirecting user to profile handler at
https://www.mydomain.com:443/idp/profile/SAML2/Redirect/SSO
21:52:52.780 - TRACE

[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:108]
- Attempting to retrieve IdP session cookie.

21:52:52.781 - TRACE
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:114]
- Found IdP session cookie.
21:52:52.781 - TRACE
[edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:74]
- Updating IdP session activity time and adding session object to the
request
21:52:52.781 - INFO [Shibboleth-Access:73] -
20110609T025252Z|144.45.7.139|www.mydomain.com:443|/profile/SAML2/Redirect/SSO|
21:52:52.782 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:85]
- shibboleth.HandlerManager: Looking up profile handler for request
path: /SAML2/Redirect/SSO
21:52:52.782 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:96]
- shibboleth.HandlerManager: Located profile handler of the following
type for the request path:
edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler
21:52:52.782 - TRACE
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:332] -
Looking up LoginContext with key 82a67795-fd9c-4dd3-8ec4-c84bcbb544bc
from StorageService parition: loginContexts
21:52:52.782 - TRACE
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:338] -
Retrieved LoginContext with key 82a67795-fd9c-4dd3-8ec4-c84bcbb544bc
from StorageService parition: loginContexts
21:52:52.782 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:162]
- Incoming request contains a login context, processing as second leg
of request
21:52:52.782 - DEBUG
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:571] -
Unbinding LoginContext
21:52:52.783 - DEBUG
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:597] -
Expiring LoginContext cookie
21:52:52.783 - DEBUG
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:606] -
Removing LoginContext, with key 82a67795-fd9c-4dd3-8ec4-c84bcbb544bc,
from StorageService partition loginContexts
21:52:52.783 - DEBUG
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:126]
- Looking up relying party configuration for
https://www.mydomain.com/shibboleth
21:52:52.783 - DEBUG
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:132]
- No custom relying party configuration found for
https://www.mydomain.com/shibboleth, looking up configuration based on
metadata groups.
21:52:52.784 - DEBUG
[edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:155]
- No custom or group-based relying party configuration found for
https://www.mydomain.com/shibboleth. Using default relying party
configuration.
21:52:52.788 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.saml2.AbstractSAML2ProfileHandler:471]
- Resolving attributes for principal 'JDOE-C' for SAML request from
relying party 'https://www.mydomain.com/shibboleth'
21:52:52.791 - DEBUG
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:118]
- shibboleth.AttributeResolver resolving attributes for principal
JDOE-C
21:52:52.791 - DEBUG
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:274]
- Specific attributes for principal JDOE-C were not requested,
resolving all attributes.
21:52:52.791 - DEBUG
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:313]
- Resolving attribute email for principal JDOE-C
21:52:52.792 - DEBUG
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:353]
- Resolving data connector NOVELLEDIR for principal JDOE-C
21:52:52.793 - TRACE
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.TemplateEngine:113]
- Populating velocity context

21:52:52.796 - TRACE

[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.TemplateEngine:87]
- Populating the following shibboleth.resolver.dc.NOVELLEDIR template
21:52:52.812 - DEBUG
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:307]
- Search filter: (&(cn=JDOE-C)(objectclass=person))
21:52:52.812 - DEBUG
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:362]
- LDAP data connector NOVELLEDIR - Retrieving attributes from LDAP
21:52:52.812 - TRACE
[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:93] - setting
connectionStrategy: ACTIVE_PASSIVE
21:52:52.812 - TRACE

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:110] -
setting connectionRetryExceptions: [class
javax.naming.NamingException]

21:52:52.812 - TRACE
[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:152] - {1}

Attempting connection to ldaps://ldap01:636 for strategy
ACTIVE_PASSIVE

21:52:52.813 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:73] - Bind
with the following parameters:

21:52:52.813 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:74] -
authtype = simple

21:52:52.813 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:75] - dn =
null

21:52:52.813 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:82] -
credential = <suppressed>

21:52:52.813 - TRACE

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:86] - env =
{java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory,

java.naming.provider.url=ldaps://ldap01:636,
java.naming.ldap.derefAliases=never,
java.naming.ldap.attributes.binary=GUID}

21:52:53.033 - DEBUG [edu.vt.middleware.ldap.Ldap:193] - Search with
the following parameters:
21:52:53.034 - DEBUG [edu.vt.middleware.ldap.Ldap:194] - dn = T=MYBASEDN
21:52:53.034 - DEBUG [edu.vt.middleware.ldap.Ldap:195] - filter =
(&(cn=JDOE-C)(objectclass=person))
21:52:53.034 - DEBUG [edu.vt.middleware.ldap.Ldap:196] - filterArgs = []
21:52:53.034 - DEBUG [edu.vt.middleware.ldap.Ldap:197] -
searchControls = javax.naming.directory.SearchControls@189f687
21:52:53.034 - DEBUG [edu.vt.middleware.ldap.Ldap:198] - handler =
[edu.vt.middleware.ldap.handler.FqdnSearchResultHandler@47efe7,
edu.vt.middleware.ldap.handler.EntryDnSearchResultHandler@d7373f,
edu.vt.middleware.ldap.handler.BinarySearchResultHandler@16c3396]
21:52:53.034 - TRACE [edu.vt.middleware.ldap.Ldap:200] - config =

{java.naming.provider.url=ldaps://ldap01:636,
java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory,
java.naming.ldap.derefAliases=never,
java.naming.ldap.attributes.binary=GUID}

21:52:53.052 - TRACE

[edu.vt.middleware.ldap.pool.DefaultLdapFactory:123] - destroyed ldap

object: edu.vt.middleware.ldap.Ldap@22015903::config=edu.vt.middleware.ldap.LdapConfig@27723935::env={java.naming.provider.url=ldaps://ldap01:636,
java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory,
java.naming.ldap.derefAliases=never,
java.naming.ldap.attributes.binary=GUID}

But 3.3.2 with the searchResultHandlers setting fails the same as it
did on 3.3.3...

edu.vt.middleware.ldap.jaas.LdapLoginModule sufficient

ldapUrl="ldap://ldap01:636"
ssl="true"
baseDn="T=MYBASEDN"
subtreeSearch="true"
derefAliases="never"
userFilter="(&(cn={0})(objectclass=person))"

searchResultHandlers="edu.vt.middleware.ldap.handler.FqdnSearchResultHandler{{removeUrls=false}}";

21:47:05.687 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:138]
- Begin initialize
21:47:05.687 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:172]
- useFirstPass = false
21:47:05.688 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:173]
- tryFirstPass = false
21:47:05.688 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:174]
- storePass = false
21:47:05.688 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:175]
- setLdapPrincipal = true
21:47:05.688 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:176]
- setLdapDnPrincipal = false
21:47:05.688 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:177]
- setLdapCredential = true
21:47:05.688 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:178]
- defaultRole = []
21:47:05.689 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:179]
- principalGroupName = null
21:47:05.689 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:180]
- roleGroupName = null
21:47:05.689 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:77]
- userRoleAttribute = []
21:47:05.694 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1385] - setting
searchScope: ONELEVEL

21:47:05.699 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1683] - setting
searchResultsHandlers:

[edu.vt.middleware.ldap.handler.FqdnSearchResultHandler@1f18776]
21:47:05.699 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:427] - setting
subtreeSearch: true

21:47:05.700 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1385] - setting
searchScope: SUBTREE

21:47:05.700 - TRACE
[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1370] - setting
baseDn: T=MYBASEDN
21:47:05.700 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1834] - setting ssl:
true

21:47:05.700 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1168] - setting
ldapUrl: ldap://ldap01:636

21:47:05.700 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1651] - setting
derefAliases: never

21:47:05.700 - TRACE

[edu.vt.middleware.ldap.auth.AuthenticatorConfig:290] - setting
userFilter: (&(cn={0})(objectclass=person))

21:47:05.702 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:83]
- Created authenticator:
edu.vt.middleware.ldap.auth.AuthenticatorConfig@28985299::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}
21:47:05.702 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:368]
- Begin getCredentials
21:47:05.703 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:369]
- useFistPass = false
21:47:05.703 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:370]
- tryFistPass = false
21:47:05.703 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:371]
- useCallback = false
21:47:05.703 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:372]

- callbackhandler class =
javax.security.auth.login.LoginContext$SecureCallbackHandler

21:47:05.703 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:375]

- name callback class = javax.security.auth.callback.NameCallback

21:47:05.703 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:377]

- password callback class =
javax.security.auth.callback.PasswordCallback

21:47:05.704 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:102] - Looking up DN
using userFilter

21:47:05.705 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:193] - Search with the
following parameters:

21:47:05.705 - DEBUG
[edu.vt.middleware.ldap.auth.SearchDnResolver:194] - dn = T=MYBASEDN
21:47:05.705 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:195] - filter =
(&(cn={0})(objectclass=person))

21:47:05.705 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:196] - filterArgs =
[jdoe-c]

21:47:05.705 - DEBUG
[edu.vt.middleware.ldap.auth.SearchDnResolver:197] - searchControls
= javax.naming.directory.SearchControls@8aedb7
21:47:05.706 - DEBUG

[edu.vt.middleware.ldap.auth.SearchDnResolver:198] - handler =

[edu.vt.middleware.ldap.handler.FqdnSearchResultHandler@1f18776]
21:47:05.706 - 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}

21:47:05.706 - TRACE

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:93] - setting
connectionStrategy: DEFAULT

21:47:05.706 - TRACE

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:110] -
setting connectionRetryExceptions: [class
javax.naming.NamingException]

21:47:05.706 - TRACE

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:152] - {0}
Attempting connection to ldap://ldap01:636 for strategy DEFAULT

21:47:05.707 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:73] - Bind
with the following parameters:

21:47:05.707 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:74] -
authtype = simple

21:47:05.707 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:75] - dn =
null

21:47:05.707 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:82] -
credential = <suppressed>

21:47:05.707 - 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}

21:47:05.964 - TRACE

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:93] - setting
connectionStrategy: DEFAULT

21:47:05.965 - TRACE

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:110] -
setting connectionRetryExceptions: [class
javax.naming.NamingException]

21:47:05.966 - TRACE

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:152] - {1}
Attempting connection to ldap://ldap01:636 for strategy DEFAULT

21:47:05.966 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:73] - Bind
with the following parameters:

21:47:05.966 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:74] -
authtype = simple

21:47:05.966 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:75] - dn =

ldap://ldap01:636/cn=jdoe-c,ou=FOO,ou=BAR,o=DIV
21:47:05.966 - DEBUG

[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:82] -
credential = <suppressed>

21:47:05.966 - 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}

21:47:06.193 - DEBUG

~[vt-ldap-3.3.2.jar:na]
at edu.vt.middleware.ldap.handler.AbstractConnectionHandler.connect(AbstractConnectionHandler.java:156)
~[vt-ldap-3.3.2.jar:na]
at edu.vt.middleware.ldap.auth.handler.BindAuthenticationHandler.authenticate(BindAuthenticationHandler.java:53)
[vt-ldap-3.3.2.jar:na]
at edu.vt.middleware.ldap.auth.AbstractAuthenticator.authenticateAndAuthorize(AbstractAuthenticator.java:174)

[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]

21:47:06.194 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:164]

- Error occured attempting authentication
javax.naming.InvalidNameException: [LDAP: error code 34 - Invalid DN Syntax]
at com.sun.jndi.ldap.LdapCtx.processReturnCode(LdapCtx.java:2982)
~[na:1.6.0_24]
at com.sun.jndi.ldap.LdapCtx.processReturnCode(LdapCtx.java:2789)
~[na:1.6.0_24]
at com.sun.jndi.ldap.LdapCtx.connect(LdapCtx.java:2703) ~[na:1.6.0_24]
at com.sun.jndi.ldap.LdapCtx.<init>(LdapCtx.java:293) ~[na:1.6.0_24]
at com.sun.jndi.ldap.LdapCtxFactory.getUsingURL(LdapCtxFactory.java:175)
~[na:1.6.0_24]
at com.sun.jndi.ldap.LdapCtxFactory.getUsingURLs(LdapCtxFactory.java:193)
~[na:1.6.0_24]
at com.sun.jndi.ldap.LdapCtxFactory.getLdapCtxInstance(LdapCtxFactory.java:136)
~[na:1.6.0_24]
at com.sun.jndi.ldap.LdapCtxFactory.getInitialContext(LdapCtxFactory.java:66)
~[na:1.6.0_24]
at javax.naming.spi.NamingManager.getInitialContext(NamingManager.java:667)
~[na:1.6.0_24]
at javax.naming.InitialContext.getDefaultInitCtx(InitialContext.java:288)
~[na:1.6.0_24]
at javax.naming.InitialContext.init(InitialContext.java:223) ~[na:1.6.0_24]
at javax.naming.ldap.InitialLdapContext.<init>(InitialLdapContext.java:134)
~[na:1.6.0_24]
at edu.vt.middleware.ldap.handler.DefaultConnectionHandler.connectInternal(DefaultConnectionHandler.java:102)

~[vt-ldap-3.3.2.jar:na]
at edu.vt.middleware.ldap.handler.AbstractConnectionHandler.connect(AbstractConnectionHandler.java:156)
~[vt-ldap-3.3.2.jar:na]
at edu.vt.middleware.ldap.auth.handler.BindAuthenticationHandler.authenticate(BindAuthenticationHandler.java:53)
~[vt-ldap-3.3.2.jar:na]
at edu.vt.middleware.ldap.auth.AbstractAuthenticator.authenticateAndAuthorize(AbstractAuthenticator.java:174)
~[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]

21:47:06.195 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:248]
- Begin abort
21:47:06.195 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:260]
- Begin logout
21:47:06.200 - DEBUG

[edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:176]
- User authentication for jdoe-c failed
javax.security.auth.login.LoginException: [LDAP: error code 34 -
Invalid DN Syntax]
at edu.vt.middleware.ldap.jaas.LdapLoginModule.login(LdapLoginModule.java:167)

~[vt-ldap-3.3.2.jar:na]

21:47:06.200 - TRACE
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:332] -
Looking up LoginContext with key a9a51bed-e5da-46ba-a7ce-b354a0891611
from StorageService parition: loginContexts
21:47:06.200 - TRACE
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:338] -
Retrieved LoginContext with key a9a51bed-e5da-46ba-a7ce-b354a0891611
from StorageService parition: loginContexts
21:47:06.201 - DEBUG

[edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:133]
- Redirecting to login page /login.jsp

--

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.

[Dan McLaughlin]

BTW... I haven't started to look at them yet, but my upgrades to IdP
2.3.0 using IBM Directory Server and MS Active Directory are also
failing after moving to 2.3.0. In both cases I'm getting errors
related to the bind user credentials being wrong, but I know they
aren't b/c moving back to the 3.3.2 vt jar makes things work again.

--

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.

[Dan McLaughlin]

Found the issue with IBM DS; it was a typo in the jaas config. IBM DS
and 3.3.3 are working again, but I'm not using aliases in IBM DS
either.

--

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.

On Wed, Jun 8, 2011 at 10:04 PM, Dan McLaughlin

[Daniel Fisher]

On Wed, Jun 8, 2011 at 6:24 PM, Dan McLaughlin
<dmcla...@tech-consortium.com> wrote:
> I agree the old properties are valid, but there is some bug that is
> causing aliases to be dereference regardless.  I think you would agree
> the following two configuration examples should NEVER dereference
> aliases.  If  dereference aliases is set to never and I search the
> entire tree and I have one alias that points to one user, then only
> the one user should be returned.  Correct?

I would expect the user entry and the alias entry to be returned. To
confirm this try the following:
ldapsearch -H ldaps://ldap01:636 -x -b o=org -a never "(cn=jdoe-c)"

If an alias is not dereferenced, the alias entry is returned.

then try:
ldapsearch -H ldaps://ldap01:636 -x -b o=org -a never
"(&(cn=jdoe-c)(objectclass=person))"
and confirm only the user entry is returned.

--Daniel Fisher

[Dan McLaughlin]

Correct.

ldapsearch -H ldaps://ldap01:636 -x -b o=org -a never "(cn=jdoe-c)"

returned the alias entry and the user entry

ldapsearch -H ldaps://ldap01:636 -x -b o=org -a never

"(&(cn=jdoe-c)(objectclass=person))" returned only the user entry

ldapsearch -H ldaps://ldap01:636 -x -b o=org -a always "(cn=jdoe-c)"
returned two identical user entries

ldapsearch -H ldaps://ldap01:636 -x -b o=org -a always
"(&(cn=jdoe-c)(objectclass=person))" returned two identical user
entries

--

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.

[Dan McLaughlin]

Hi Daniel,

MSAD is fine as well. Another typo... userField instead of
userFilter. It took a little bit of starring at the screen before my
eyes picked up on it. ;)

I also found the reason the eDir configuration failures. A Sun JDK
bug that was filed actually pointed me in the right direction.

http://bugs.sun.com/bugdatabase/view_bug.do;jsessionid=cd785fee3c55f87daca6ed15d2e0?bug_id=6201517

As the code entered the readCompositeName method, the string passed in
as s was "ldap://ldap01:636/cn=JDOE-C,ou=FOO,ou=BAR,o=DIV". The
problem was the cName.get(0) only retrieves a component of the
composite name, in this case the index is 0 or ldap:, so when it was
returned to URI.create it would fail. I think what you were
intending was to use the toSting() method in this case. I changed the
code to use cName.toString() in place of cName.get(0) and now
everything is working fine.

Here is the patch...

Index: src/main/java/edu/vt/middleware/ldap/handler/FqdnSearchResultHandler.java
===================================================================
--- src/main/java/edu/vt/middleware/ldap/handler/FqdnSearchResultHandler.java (revision
1993)
+++ src/main/java/edu/vt/middleware/ldap/handler/FqdnSearchResultHandler.java (working
copy)
@@ -100,7 +100,7 @@
String name = "";
try {
final CompositeName cName = new CompositeName(s);
- name = cName.get(0);
+ name = cName.toString();
} catch (InvalidNameException e) {
if (this.logger.isErrorEnabled()) {
this.logger.error("Error formatting name: " + s, e);

--

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.

[Daniel Fisher]

On Thu, Jun 9, 2011 at 8:03 PM, Dan McLaughlin
<dmcla...@tech-consortium.com> wrote:
> Here is the patch...
>
> +      name = cName.toString();

This may work for you but it won't properly format special characters.
Please create an issue for this: https://issues.shibboleth.net/
I'll see if I can get OpenLDAP to produce similar results so I can get
better test coverage on this scenario.

--Daniel Fisher

[Daniel Fisher]

Created https://issues.shibboleth.net/jira/browse/SC-158
Dan, please try out the jar linked in that issue.
Thanks.

--Daniel Fisher

[Dan McLaughlin]

I tested the fix attached to
https://issues.shibboleth.net/jira/browse/SC-158 and it works. Thanks
for the fix!

Here are the log entires...

20:40:01.867 - TRACE
[edu.vt.middleware.ldap.handler.FqdnSearchResultHandler:83] -
processing non-relative dn:
ldaps://ldap01:636/cn=JDOE-C,ou=FOO,ou=BAR,o=DIV
20:40:01.867 - TRACE
[edu.vt.middleware.ldap.handler.FqdnSearchResultHandler:95] -
processed dn: cn=JDOE-C,ou=FOO,ou=BAR,o=DIV

--

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.