sporadic user authenication issues

[Esquivel, Vince]

Good day,

We had some users experiencing some authentication issues last Wednesday evening between  7pm to 9pm on our IDP.  When this was happening some users were not able to login and would receive "Authentication Failed" on our IDP login page while trying to access some of our SP's.

Here is an example log of one of those users:

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
19:21:28.043 - DEBUG [edu.vt.middleware.ldap.Authenticator:198] - Authentication failed for user: CN=student1,OU=Students,OU=Accounts,DC=ldap,DC=local
19:21:28.047 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:192] - User authentication for [student1] failed
19:21:28.048 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:142] - Redirecting to login page /login.jsp
19:21:24.938 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:163] - Attempting to authenticate user student1
19:21:24.938 - DEBUG [edu.vt.middleware.ldap.LdapProperties:299] - edu.vt.middleware.ldap.auth.userField = uid
19:21:24.939 - DEBUG [edu.vt.middleware.ldap.LdapProperties:299] - edu.vt.middleware.ldap.auth.subtreeSearch = true
19:21:24.939 - DEBUG [edu.vt.middleware.ldap.Authenticator:143] - Looking up DN from userfield and base
19:21:24.939 - DEBUG [edu.vt.middleware.ldap.Ldap:549] - Search with the following parameters:
19:21:24.939 - DEBUG [edu.vt.middleware.ldap.Ldap:550] -   dn = OU=Accounts,DC=ldap,DC=local
19:21:24.940 - DEBUG [edu.vt.middleware.ldap.Ldap:551] -   filter = (uid=student1)
19:21:24.940 - DEBUG [edu.vt.middleware.ldap.Ldap:552] -   filterArgs =
19:21:24.940 - DEBUG [edu.vt.middleware.ldap.Ldap:554] -     none
19:21:24.941 - DEBUG [edu.vt.middleware.ldap.Ldap:558] -   retAttrs =
19:21:24.941 - DEBUG [edu.vt.middleware.ldap.Ldap:562] -     []
19:21:24.941 - DEBUG [edu.vt.middleware.ldap.Ldap:1538] - Bind with the following parameters:
19:21:24.942 - DEBUG [edu.vt.middleware.ldap.Ldap:1539] -   dn = shibbuser at ldap.local
19:21:24.942 - DEBUG [edu.vt.middleware.ldap.Ldap:1543] -   credential = <suppressed>
19:21:28.038 - DEBUG [edu.vt.middleware.ldap.Ldap:1538] - Bind with the following parameters:
19:21:28.038 - DEBUG [edu.vt.middleware.ldap.Ldap:1539] -   dn = CN=student1,OU=Students,OU=Accounts,DC=ldap,DC=local
19:21:28.038 - DEBUG [edu.vt.middleware.ldap.Ldap:1543] -   credential = <suppressed>
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
19:21:28.043 - DEBUG [edu.vt.middleware.ldap.Authenticator:198] - Authentication failed for user: CN=student1,OU=Students,OU=Accounts,DC=ldap,DC=local
19:21:28.047 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:192] - User authentication for [student1] failed
19:21:28.048 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:142] - Redirecting to login page /login.jsp
19:22:07.151 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:163] - Attempting to authenticate user student1
19:22:07.152 - DEBUG [edu.vt.middleware.ldap.LdapProperties:299] - edu.vt.middleware.ldap.auth.userField = uid
19:22:07.153 - DEBUG [edu.vt.middleware.ldap.LdapProperties:299] - edu.vt.middleware.ldap.auth.subtreeSearch = true
19:22:07.153 - DEBUG [edu.vt.middleware.ldap.Authenticator:143] - Looking up DN from userfield and base
19:22:07.153 - DEBUG [edu.vt.middleware.ldap.Ldap:549] - Search with the following parameters:
19:22:07.154 - DEBUG [edu.vt.middleware.ldap.Ldap:550] -   dn = OU=Accounts,DC=ldap,DC=local
19:22:07.154 - DEBUG [edu.vt.middleware.ldap.Ldap:551] -   filter = (uid=student1)
19:22:07.154 - DEBUG [edu.vt.middleware.ldap.Ldap:552] -   filterArgs =
19:22:07.154 - DEBUG [edu.vt.middleware.ldap.Ldap:554] -     none
19:22:07.154 - DEBUG [edu.vt.middleware.ldap.Ldap:558] -   retAttrs =
19:22:07.155 - DEBUG [edu.vt.middleware.ldap.Ldap:562] -     []
19:22:07.155 - DEBUG [edu.vt.middleware.ldap.Ldap:1538] - Bind with the following parameters:
19:22:07.155 - DEBUG [edu.vt.middleware.ldap.Ldap:1539] -   dn = shibbuser at ldap.local
19:22:07.155 - DEBUG [edu.vt.middleware.ldap.Ldap:1543] -   credential = <suppressed>
19:22:10.239 - DEBUG [edu.vt.middleware.ldap.Ldap:1538] - Bind with the following parameters:
19:22:10.239 - DEBUG [edu.vt.middleware.ldap.Ldap:1539] -   dn = CN=student1,OU=Students,OU=Accounts,DC=ldap,DC=local
19:22:10.240 - DEBUG [edu.vt.middleware.ldap.Ldap:1543] -   credential = <suppressed>
19:22:10.243 - INFO [edu.vt.middleware.ldap.Authenticator:301] - Authentication failed for user: CN=student1,OU=Students,OU=Accounts,DC=ldap,DC=local
19:22:10.244 - DEBUG [edu.vt.middleware.ldap.Authenticator:198] - Authentication failed for user: CN=student1,OU=Students,OU=Accounts,DC=ldap,DC=local
19:22:10.247 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:192] - User authentication for [student1] failed
19:22:10.248 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:142] - Redirecting to login page /login.jsp
19:22:40.209 - INFO [Shibboleth-Access:72] - 20150212T012240Z|172.2.x.x|idp.atmyu.edu:443|/profile/SAML2/Redirect/SSO|
19:22:40.210 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:85] - shibboleth.HandlerManager: Looking up profile handler

We are running an older version of shibboleth 2.1.2, we are looking to upgrade sometime later this year
Things are working fine since and users are authenticating successfully but just want to get a second set of eyes.

Thanks
Vince

-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://shibboleth.net/pipermail/users/attachments/20150216/aa1bf7e0/attachment.html