invalid dn - but admin says its not
Oleg Chaikovsky
oleg.chaikovsky at aegisidentity.com
Sun Jul 7 23:03:37 EDT 2013
Hello -
I am attempting to connect IdP 2.4 to an MSFT AD server. The LDAP admin tells me that the dn he provided is correct. However, when I connect, and try to use testshib as a basic test, I get an invalid dn error (see part of idp-process.log below.
I have tried their dn and port 389 (no ssl). I have tried shortening the dn to dc=vvc, dc=edu and using port 3268. All with the same result.
It has to be an LDAP issue - but I am trying to find an additional pointer to help debug this one. Any clues or pointers are greatly appreciated.
19:46:31.974 - INFO [Shibboleth-Access:73] - 20130708T024631Z|fe80:0:0:0:1a7:616a:c8f0:d5b3|shibboleth.vvc.edu:443|/profile/SAML2/Redirect/SSO|
19:46:31.974 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:86] - shibboleth.HandlerManager: Looking up profile handler for request path: /SAML2/Redirect/SSO
19:46:31.990 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:97] - shibboleth.HandlerManager: Located profile handler of the following type for the request path: edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler
19:46:31.990 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:339] - LoginContext key cookie was not present in request
19:46:31.990 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:188] - Incoming request does not contain a login context, processing as first leg of request
19:46:31.990 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:366] - Decoding message with decoder binding 'urn:oasis:names:tc:SAML:2.0:bindings:HTTP-Redirect'
19:46:32.115 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:128] - Looking up relying party configuration for https://sp.testshib.org/shibboleth-sp
19:46:32.115 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:134] - No custom relying party configuration found for https://sp.testshib.org/shibboleth-sp, looking up configuration based on metadata groups.
19:46:32.115 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:157] - No custom or group-based relying party configuration found for https://sp.testshib.org/shibboleth-sp. Using default relying party configuration.
19:46:32.115 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:387] - Decoded request from relying party 'https://sp.testshib.org/shibboleth-sp'
19:46:32.115 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:128] - Looking up relying party configuration for https://sp.testshib.org/shibboleth-sp
19:46:32.115 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:134] - No custom relying party configuration found for https://sp.testshib.org/shibboleth-sp, looking up configuration based on metadata groups.
19:46:32.115 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:157] - No custom or group-based relying party configuration found for https://sp.testshib.org/shibboleth-sp. Using default relying party configuration.
19:46:32.115 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:226] - Creating login context and transferring control to authentication engine
19:46:32.115 - DEBUG [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:181] - Storing LoginContext to StorageService partition loginContexts, key e68b2567053770149dd7e43a627f969d47d45c4d8cacf2ddca0d1bc878498c21
19:46:32.115 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:240] - Redirecting user to authentication engine at https://shibboleth.vvc.edu:443/idp/AuthnEngine
19:46:32.131 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:209] - Processing incoming request
19:46:32.131 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:240] - Beginning user authentication process.
19:46:32.131 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:283] - Filtering configured LoginHandlers: {urn:oasis:names:tc:SAML:2.0:ac:classes:PreviousSession=edu.internet2.middleware.shibboleth.idp.authn.provider.PreviousSessionLoginHandler at 27feae0f, urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport=edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler at 41556f4c}
19:46:32.131 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:332] - Filtering out previous session login handler because there is no existing IdP session
19:46:32.131 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:464] - Selecting appropriate login handler from filtered set {urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport=edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler at 41556f4c}
19:46:32.131 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:497] - Authenticating user with login handler of type edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler
19:46:32.131 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler:66] - Redirecting to https://shibboleth.vvc.edu:443/idp/Authn/UserPassword
19:46:32.193 - DEBUG [edu.internet2.middleware.shibboleth.idp.ui.ServiceTagSupport:305] - Found name in UIInfo, language=en
19:46:32.193 - DEBUG [edu.internet2.middleware.shibboleth.idp.ui.ServiceTagSupport:312] - returning name from UIInfo TestShib Test SP
19:46:32.209 - DEBUG [edu.internet2.middleware.shibboleth.idp.ui.ServiceLogoTag:156] - Found logo in UIInfo, width=253 height=88
19:46:32.209 - DEBUG [edu.internet2.middleware.shibboleth.idp.ui.ServiceLogoTag:159] - returning logo from UIInfo https://www.testshib.org/testshibtwo.jpg
19:46:32.209 - DEBUG [edu.internet2.middleware.shibboleth.idp.ui.ServiceTagSupport:305] - Found name in UIInfo, language=en
19:46:32.209 - DEBUG [edu.internet2.middleware.shibboleth.idp.ui.ServiceTagSupport:312] - returning name from UIInfo TestShib Test SP
19:46:32.224 - DEBUG [edu.internet2.middleware.shibboleth.idp.ui.ServiceDescriptionTag:62] - Found description in UIInfo, language=en
19:46:32.224 - DEBUG [edu.internet2.middleware.shibboleth.idp.ui.ServiceDescriptionTag:69] - returning description from UIInfo TestShib SP. Log into this to test your machine.
Once logged in check that all attributes that you expected have been
released.
19:46:32.224 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:150] - Redirecting to login page /login.jsp
19:46:55.021 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:170] - Attempting to authenticate user Shibboleth.Ldap
19:46:55.193 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:180] - useFirstPass = false
19:46:55.193 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:181] - tryFirstPass = false
19:46:55.193 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:182] - storePass = false
19:46:55.193 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:183] - clearPass = false
19:46:55.193 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:184] - setLdapPrincipal = true
19:46:55.193 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:185] - setLdapDnPrincipal = false
19:46:55.193 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:186] - setLdapCredential = true
19:46:55.193 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:187] - defaultRole = []
19:46:55.193 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:188] - principalGroupName = null
19:46:55.193 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:189] - roleGroupName = null
19:46:55.193 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:77] - userRoleAttribute = []
19:46:55.209 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:83] - Created authenticator: edu.vt.middleware.ldap.auth.AuthenticatorConfig at 492431071::env={java.naming.provider.url=ldap://10.150.3.1, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}
19:46:55.209 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:102] - Looking up DN using userFilter
19:46:55.209 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:193] - Search with the following parameters:
19:46:55.209 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:194] - dn = ou=VVC Fac-Staff,dc=vvc,dc=edu
19:46:55.209 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:195] - filter = sAMAccountName={0}
19:46:55.209 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:196] - filterArgs = [Shibboleth.Ldap]
19:46:55.209 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:197] - searchControls = javax.naming.directory.SearchControls at 465863
19:46:55.209 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:198] - handler = [edu.vt.middleware.ldap.handler.FqdnSearchResultHandler at a54cbb9]
19:46:55.209 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:74] - Bind with the following parameters:
19:46:55.209 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:75] - authtype = simple
19:46:55.209 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:76] - dn = cn=shibboleth ldap,ou=service accounts,dc=vvc,dc=edu
19:46:55.209 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:83] - credential = <suppressed>
19:46:55.584 - INFO [edu.vt.middleware.ldap.auth.SearchDnResolver:161] - Search for user: Shibboleth.Ldap failed using filter: sAMAccountName={0}
19:46:55.584 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:136] - Authentication failed
javax.naming.AuthenticationException: Cannot authenticate dn, invalid dn
at edu.vt.middleware.ldap.auth.AbstractAuthenticator.authenticateAndAuthorize(AbstractAuthenticator.java:160) ~[vt-ldap-3.3.6.jar:na]
at edu.vt.middleware.ldap.jaas.JaasAuthenticator.authenticate(JaasAuthenticator.java:74) ~[vt-ldap-3.3.6.jar:na]
at edu.vt.middleware.ldap.auth.Authenticator.authenticate(Authenticator.java:320) ~[vt-ldap-3.3.6.jar:na]
at edu.vt.middleware.ldap.auth.Authenticator.authenticate(Authenticator.java:277) ~[vt-ldap-3.3.6.jar:na]
at edu.vt.middleware.ldap.jaas.JaasAuthenticator.authenticate(JaasAuthenticator.java:60) ~[vt-ldap-3.3.6.jar:na]
at edu.vt.middleware.ldap.jaas.LdapLoginModule.login(LdapLoginModule.java:103) ~[vt-ldap-3.3.6.jar:na]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.6.0_45]
at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) ~[na:1.6.0_45]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[na:1.6.0_45]
at java.lang.reflect.Method.invoke(Unknown Source) ~[na:1.6.0_45]
at javax.security.auth.login.LoginContext.invoke(Unknown Source) [na:1.6.0_45]
at javax.security.auth.login.LoginContext.access$000(Unknown Source) [na:1.6.0_45]
at javax.security.auth.login.LoginContext$4.run(Unknown Source) [na:1.6.0_45]
at java.security.AccessController.doPrivileged(Native Method) [na:1.6.0_45]
at javax.security.auth.login.LoginContext.invokePriv(Unknown Source) [na:1.6.0_45]
at javax.security.auth.login.LoginContext.login(Unknown Source) [na:1.6.0_45]
at edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet.authenticateUser(UsernamePasswordLoginServlet.java:177) [shibboleth-identityprovider-2.4.0.jar:na]
at edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet.service(UsernamePasswordLoginServlet.java:123) [shibboleth-identityprovider-2.4.0.jar:na]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:723) [servlet-api.jar:na]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) [catalina.jar:6.0.37]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) [catalina.jar:6.0.37]
at edu.internet2.middleware.shibboleth.idp.util.NoCacheFilter.doFilter(NoCacheFilter.java:50) [shibboleth-identityprovider-2.4.0.jar:na]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) [catalina.jar:6.0.37]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) [catalina.jar:6.0.37]
at edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter.doFilter(IdPSessionFilter.java:87) [shibboleth-identityprovider-2.4.0.jar:na]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) [catalina.jar:6.0.37]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) [catalina.jar:6.0.37]
at edu.internet2.middleware.shibboleth.common.log.SLF4JMDCCleanupFilter.doFilter(SLF4JMDCCleanupFilter.java:52) [shibboleth-common-1.4.0.jar:na]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) [catalina.jar:6.0.37]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) [catalina.jar:6.0.37]
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:219) [catalina.jar:6.0.37]
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) [catalina.jar:6.0.37]
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127) [catalina.jar:6.0.37]
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103) [catalina.jar:6.0.37]
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) [catalina.jar:6.0.37]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:293) [catalina.jar:6.0.37]
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:861) [tomcat-coyote.jar:6.0.37]
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:606) [tomcat-coyote.jar:6.0.37]
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:489) [tomcat-coyote.jar:6.0.37]
at java.lang.Thread.run(Unknown Source) [na:1.6.0_45]
19:46:55.600 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:194] - User authentication for Shibboleth.Ldap failed
javax.security.auth.login.LoginException: Cannot authenticate dn, invalid dn
at edu.vt.middleware.ldap.jaas.LdapLoginModule.login(LdapLoginModule.java:138) ~[vt-ldap-3.3.6.jar:na]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.6.0_45]
at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) ~[na:1.6.0_45]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[na:1.6.0_45]
at java.lang.reflect.Method.invoke(Unknown Source) ~[na:1.6.0_45]
at javax.security.auth.login.LoginContext.invoke(Unknown Source) ~[na:1.6.0_45]
at javax.security.auth.login.LoginContext.access$000(Unknown Source) ~[na:1.6.0_45]
at javax.security.auth.login.LoginContext$4.run(Unknown Source) ~[na:1.6.0_45]
at java.security.AccessController.doPrivileged(Native Method) ~[na:1.6.0_45]
at javax.security.auth.login.LoginContext.invokePriv(Unknown Source) ~[na:1.6.0_45]
at javax.security.auth.login.LoginContext.login(Unknown Source) ~[na:1.6.0_45]
at edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet.authenticateUser(UsernamePasswordLoginServlet.java:177) [shibboleth-identityprovider-2.4.0.jar:na]
at edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet.service(UsernamePasswordLoginServlet.java:123) [shibboleth-identityprovider-2.4.0.jar:na]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:723) [servlet-api.jar:na]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) [catalina.jar:6.0.37]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) [catalina.jar:6.0.37]
at edu.internet2.middleware.shibboleth.idp.util.NoCacheFilter.doFilter(NoCacheFilter.java:50) [shibboleth-identityprovider-2.4.0.jar:na]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) [catalina.jar:6.0.37]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) [catalina.jar:6.0.37]
at edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter.doFilter(IdPSessionFilter.java:87) [shibboleth-identityprovider-2.4.0.jar:na]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) [catalina.jar:6.0.37]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) [catalina.jar:6.0.37]
at edu.internet2.middleware.shibboleth.common.log.SLF4JMDCCleanupFilter.doFilter(SLF4JMDCCleanupFilter.java:52) [shibboleth-common-1.4.0.jar:na]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) [catalina.jar:6.0.37]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) [catalina.jar:6.0.37]
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:219) [catalina.jar:6.0.37]
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) [catalina.jar:6.0.37]
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127) [catalina.jar:6.0.37]
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103) [catalina.jar:6.0.37]
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) [catalina.jar:6.0.37]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:293) [catalina.jar:6.0.37]
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:861) [tomcat-coyote.jar:6.0.37]
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:606) [tomcat-coyote.jar:6.0.37]
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:489) [tomcat-coyote.jar:6.0.37]
at java.lang.Thread.run(Unknown Source) [na:1.6.0_45]
--------------------------------------------------------------
Oleg Chaikovsky
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://shibboleth.net/pipermail/users/attachments/20130708/568d2b00/attachment-0001.html
More information about the users
mailing list