sporadic user authenication issues

Esquivel, Vince Esquivelv at uhd.edu
Tue Feb 17 14:09:01 EST 2015 

Thanks for your reply

Unfortunately the security logs are no longer available on that Domain Controller.

Here is one that we are getting this morning, their account is valid in Active Directory and their password is not expired.

12:18:09.353 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:313] - Possible authentication handlers after filtering: {urn:oasis:names:tc:SAML:2.0:ac:classes:PreviousSession=edu.internet2.middleware.shibboleth.idp.authn.provider.PreviousSessionLoginHandler at 30e4a7, urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport=edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler at 1f39c59}
12:18:09.353 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:326] - Authenticating user with login handler of type edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler
12:18:09.354 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler:75] - Redirecting to https://idp.myu.edu:443/idp/Authn/UserPassword
12:18:09.361 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:142] - Redirecting to login page /login.jsp
12:18:18.747 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:163] - Attempting to authenticate user staff1
12:18:18.747 - DEBUG [edu.vt.middleware.ldap.LdapProperties:299] - edu.vt.middleware.ldap.auth.userField = uid
12:18:18.748 - DEBUG [edu.vt.middleware.ldap.LdapProperties:299] - edu.vt.middleware.ldap.auth.subtreeSearch = true
12:18:18.748 - DEBUG [edu.vt.middleware.ldap.Authenticator:143] - Looking up DN from userfield and base
12:18:18.749 - DEBUG [edu.vt.middleware.ldap.Ldap:549] - Search with the following parameters:
12:18:18.749 - DEBUG [edu.vt.middleware.ldap.Ldap:550] -   dn = OU=Accounts,DC=ldap,DC=local
12:18:18.749 - DEBUG [edu.vt.middleware.ldap.Ldap:551] -   filter = (uid=staff1)
12:18:18.749 - DEBUG [edu.vt.middleware.ldap.Ldap:552] -   filterArgs =
12:18:18.750 - DEBUG [edu.vt.middleware.ldap.Ldap:554] -     none
12:18:18.750 - DEBUG [edu.vt.middleware.ldap.Ldap:558] -   retAttrs =
12:18:18.750 - DEBUG [edu.vt.middleware.ldap.Ldap:562] -     []
12:18:18.751 - DEBUG [edu.vt.middleware.ldap.Ldap:1538] - Bind with the following parameters:
12:18:18.751 - DEBUG [edu.vt.middleware.ldap.Ldap:1539] -   dn = shibbuser at ldap.local
12:18:18.751 - DEBUG [edu.vt.middleware.ldap.Ldap:1543] -   credential = <suppressed>
12:18:22.119 - DEBUG [edu.vt.middleware.ldap.Ldap:1538] - Bind with the following parameters:
12:18:22.119 - DEBUG [edu.vt.middleware.ldap.Ldap:1539] -   dn = CN=staff1,OU=Employees,OU=Accounts,DC=ldap,DC=local
12:18:22.119 - DEBUG [edu.vt.middleware.ldap.Ldap:1543] -   credential = <suppressed>
12:18:22.138 - INFO [edu.vt.middleware.ldap.Authenticator:297] - Authentication succeeded for user: CN=staff1,OU=Employees,OU=Accounts,DC=ldap,DC=local
12:18:22.139 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:171] - Successfully authenticated user staff1
12:18:22.139 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:208] - Returning control to authentication engine
12:18:22.140 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:262] - Processing incoming request
12:18:22.140 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:523] - Completing user authentication process
12:18:22.141 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:576] - Validating authentication was performed successfully
12:18:22.141 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:668] - Updating session information for principal staff1
12:18:22.141 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:672] - Creating shibboleth session for principal staff1
12:18:22.142 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:759] - Adding IdP session cookie to HTTP response
12:18:22.142 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:682] - Recording authentication and service information in Shibboleth session for principal: staff1
12:18:22.143 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:551] - User staff1 authenticated with method urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport
12:18:22.143 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:227] - Returning control to profile handler at: /profile/SAML2/Redirect/SSO
12:18:22.144 - INFO [Shibboleth-Access:72] - 20150217T181822Z|172.17.x.x|idp.myu.edu:443|/profile/SAML2/Redirect/SSO|
12:18:22.144 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:85] - shibboleth.HandlerManager: Looking up profile handler for request path: /SAML2/Redirect/SSO
-
-
-
SAML request from relying party https://pa1268.peopleadmin.com/shibboleth
12:18:28.982 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:120] - shibboleth.AttributeResolver resolving attributes for principal staff1
12:18:28.983 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:258] - Specific attributes for principal staff1 were not requested, resolving all attributes.
12:18:28.983 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:294] - Resolving attribute uid for principal staff1
12:18:28.984 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:334] - Resolving data connector myLDAP for principal staff1
12:18:28.985 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:765] - Search filter: (uid=staff1)
12:18:28.986 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:781] - Retrieving attributes from LDAP
12:18:28.987 - DEBUG [edu.vt.middleware.ldap.Ldap:1538] - Bind with the following parameters:
12:18:28.987 - DEBUG [edu.vt.middleware.ldap.Ldap:1539] -   dn = shibbuser at ldap.local
12:18:28.988 - DEBUG [edu.vt.middleware.ldap.Ldap:1543] -   credential = <suppressed>
12:18:28.993 - DEBUG [edu.vt.middleware.ldap.Ldap:549] - Search with the following parameters:
12:18:28.994 - DEBUG [edu.vt.middleware.ldap.Ldap:550] -   dn = OU=Accounts,DC=ldap,DC=local
12:18:28.995 - DEBUG [edu.vt.middleware.ldap.Ldap:551] -   filter = (uid=staff1)
12:18:28.995 - DEBUG [edu.vt.middleware.ldap.Ldap:552] -   filterArgs =
12:18:28.996 - DEBUG [edu.vt.middleware.ldap.Ldap:554] -     none
12:18:28.996 - DEBUG [edu.vt.middleware.ldap.Ldap:558] -   retAttrs =
12:18:28.997 - DEBUG [edu.vt.middleware.ldap.Ldap:560] -     all attributes
12:18:33.006 - ERROR [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:838] - An error occured when attempting to search the LDAP: {java.naming.provider.url=ldap://172.17.x.x, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}
javax.naming.TimeLimitExceededException: [LDAP: error code 3 - Timelimit Exceeded]
        at com.sun.jndi.ldap.LdapCtx.mapErrorCode(LdapCtx.java:3070) [na:1.6.0_13]
        at com.sun.jndi.ldap.LdapCtx.processReturnCode(LdapCtx.java:2960) [na:1.6.0_13]
        at com.sun.jndi.ldap.LdapCtx.processReturnCode(LdapCtx.java:2767) [na:1.6.0_13]
        at com.sun.jndi.ldap.LdapNamingEnumeration.getNextBatch(LdapNamingEnumeration.java:129) [na:1.6.0_13]
        at com.sun.jndi.ldap.LdapNamingEnumeration.hasMoreImpl(LdapNamingEnumeration.java:198) [na:1.6.0_13]
        at com.sun.jndi.ldap.LdapNamingEnumeration.hasMore(LdapNamingEnumeration.java:171) [na:1.6.0_13]
        at edu.vt.middleware.ldap.LdapUtil.deepCopySearchResults(LdapUtil.java:108) [ldap-2.8.2.jar:na]
        at edu.vt.middleware.ldap.Ldap.search(Ldap.java:586) [ldap-2.8.2.jar:na]
        at edu.vt.middleware.ldap.Ldap.search(Ldap.java:449) [ldap-2.8.2.jar:na]
        at edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector.searchLdap(LdapDataConnector.java:836) [shibboleth-common-1.1.2.jar:na]
        at edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector.resolve(LdapDataConnector.java:782) [shibboleth-common-1.1.2.jar:na]
        at edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector.resolve(LdapDataConnector.java:60) [shibboleth-common-1.1.2.jar:na]
        at edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.ContextualDataConnector.resolve(ContextualDataConnector.java:76) [shibboleth-common-1.1.2.jar:na]

Thanks
Vince





From: users-bounces at shibboleth.net [mailto:users-bounces at shibboleth.net] On Behalf Of Daniel Fisher
Sent: Monday, February 16, 2015 7:59 PM
To: Shib Users
Subject: Re: sporadic user authenication issues

On Mon, Feb 16, 2015 at 6:53 PM, Esquivel, Vince <Esquivelv at uhd.edu<mailto:Esquivelv at uhd.edu>> wrote:
19:21:28.043 - INFO [edu.vt.middleware.ldap.Authenticator:301] - Authentication failed for user: CN=student1,OU=Students,OU=Accounts,DC=ldap,DC=local

Looks like a bad password. What does your LDAP logs say?

--Daniel Fisher

-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://shibboleth.net/pipermail/users/attachments/20150217/b8a5b652/attachment-0001.html

More information about the users mailing list