I just wanted to update - I ran some tests against a separate instance using some automated login scripts with full debug enabled. I was not able to reproduce the exact issue I've seen before. However I did lock myself out of only a single account (as opposed to all users) after ~30k logins. The same behavior is observed: I am redirected back to the original login page with no error message. Typing an invalid password displays an error as normal.
I am currently using JDBC auditing and a hazelcast ticket registry, and have authentication against AD, with JDBC attributes.
Nothing seems out of the ordinary for logging here - After the bug is triggered and observed, further login attemps look like the following. On success, nothing is added to the audit log. On failure, the trial is logged to the jdbc audit log. Even though the LDAP is a success, it appears to hang after that with no query being executed to JDBC:
2016-11-16 12:21:11,331 DEBUG [org.ldaptive.auth.PooledSearchDnResolver] - resolve user=testuser
2016-11-16 12:21:11,332 DEBUG [org.ldaptive.auth.PooledSearchDnResolver] - searching for DN using userFilter
2016-11-16 12:21:11,332 DEBUG [org.ldaptive.SearchOperation] - execute request=[org.ldaptive.SearchRequest@-1425785245::baseDn=, searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=0, sizeLimit=1, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@309090556::config=[org.ldaptive.ConnectionConfig@1718262659::ldapUrl=ldap://company.domain , connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@1612610532::bindDn=CN=testuser,CN=Users,DC=COMPANY, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@1965307630::metadata=[ldapUrl=ldap://company.domain , count=1128], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1192906469::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@fa03edb, controlProcessor=org.ldaptive.provider.ControlProcessor@2cc635aa, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@111919cc]
2016-11-16 12:21:11,334 DEBUG [org.ldaptive.SearchOperation] - execute response=[org.ldaptive.Response@671935135::result=[org.ldaptive.SearchResult@-1951941189::entries=[[dn=[], responseControls=null, messageId=-1]], references=[]], resultCode=SUCCESS, message=null, matchedDn=null, responseControls=null, referralURLs=null, messageId=-1] for request=[org.ldaptive.SearchRequest@-1425785245::baseDn=, searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=0, sizeLimit=1, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@309090556::config=[org.ldaptive.ConnectionConfig@1718262659::ldapUrl=ldap://company.domain , connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@1612610532::bindDn=CN=testuser,CN=Users,DC=COMPANY, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@1965307630::metadata=[ldapUrl=ldap://company.domain , count=1128], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1192906469::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@fa03edb, controlProcessor=org.ldaptive.provider.ControlProcessor@2cc635aa, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@111919cc]
2016-11-16 12:21:11,336 DEBUG [org.ldaptive.SearchOperation] - execute request=[org.ldaptive.SearchRequest@-1201892857::baseDn=CN=Users,DC=COMPANY, searchFilter=[org.ldaptive.SearchFilter@-1616857661::filter=(&(objectCategory=Person)(sAMAccountName={user})), parameters={user=testuser}], returnAttributes=[1.1], searchScope=SUBTREE, timeLimit=0, sizeLimit=0, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@309090556::config=[org.ldaptive.ConnectionConfig@1718262659::ldapUrl=ldap://company.domain , connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@1612610532::bindDn=CN=testuser,CN=Users,DC=COMPANY, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@1965307630::metadata=[ldapUrl=ldap://company.domain , count=1128], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1192906469::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@fa03edb, controlProcessor=org.ldaptive.provider.ControlProcessor@2cc635aa, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@111919cc]
2016-11-16 12:21:11,343 DEBUG [org.ldaptive.SearchOperation] - execute response=[org.ldaptive.Response@609375658::result=[org.ldaptive.SearchResult@1551860074::entries=[[dn=CN=testuser,CN=Users,DC=COMPANY[], responseControls=null, messageId=-1]], references=[]], resultCode=SUCCESS, message=null, matchedDn=null, responseControls=null, referralURLs=null, messageId=-1] for request=[org.ldaptive.SearchRequest@-1201892857::baseDn=CN=Users,DC=COMPANY, searchFilter=[org.ldaptive.SearchFilter@-1616857661::filter=(&(objectCategory=Person)(sAMAccountName={user})), parameters={user=testuser}], returnAttributes=[1.1], searchScope=SUBTREE, timeLimit=0, sizeLimit=0, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@309090556::config=[org.ldaptive.ConnectionConfig@1718262659::ldapUrl=ldap://company.domain , connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@1612610532::bindDn=CN=testuser,CN=Users,DC=COMPANY, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@1965307630::metadata=[ldapUrl=ldap://company.domain , count=1128], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1192906469::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@fa03edb, controlProcessor=org.ldaptive.provider.ControlProcessor@2cc635aa, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@111919cc]
2016-11-16 12:21:11,343 DEBUG [org.ldaptive.auth.PooledSearchDnResolver] - resolved dn=CN=testuser,CN=Users,DC=COMPANY for user=testuser
2016-11-16 12:21:11,343 DEBUG [org.ldaptive.auth.Authenticator] - authenticate dn=CN=testuser,CN=Users,DC=COMPANY with request=[org.ldaptive.auth.AuthenticationRequest@1666496618::user=testuser, retAttrs=[1.1]]
2016-11-16 12:21:11,343 DEBUG [org.ldaptive.auth.PooledBindAuthenticationHandler] - authenticate criteria=[org.ldaptive.auth.AuthenticationCriteria@751038093::dn=CN=testuser,CN=Users,DC=COMPANY, authenticationRequest=[org.ldaptive.auth.AuthenticationRequest@1666496618::user=testuser, retAttrs=[1.1]]]
2016-11-16 12:21:11,343 DEBUG [org.ldaptive.SearchOperation] - execute request=[org.ldaptive.SearchRequest@-1425785245::baseDn=, searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=0, sizeLimit=1, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@1313467158::config=[org.ldaptive.ConnectionConfig@1956653060::ldapUrl=ldap://company.domain , connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@1466625650::bindDn=CN=testuser,CN=Users,DC=COMPANY, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@753503470::metadata=[ldapUrl=ldap://company.domain , count=21], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1707368966::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@fa03edb, controlProcessor=org.ldaptive.provider.ControlProcessor@772891dc, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@5eeec9e8]
2016-11-16 12:21:11,345 DEBUG [org.ldaptive.SearchOperation] - execute response=[org.ldaptive.Response@1585683254::result=[org.ldaptive.SearchResult@-1951941189::entries=[[dn=[], responseControls=null, messageId=-1]], references=[]], resultCode=SUCCESS, message=null, matchedDn=null, responseControls=null, referralURLs=null, messageId=-1] for request=[org.ldaptive.SearchRequest@-1425785245::baseDn=, searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=0, sizeLimit=1, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@1313467158::config=[org.ldaptive.ConnectionConfig@1956653060::ldapUrl=ldap://company.domain , connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@1466625650::bindDn=CN=testuser,CN=Users,DC=COMPANY, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@753503470::metadata=[ldapUrl=ldap://company.domain , count=21], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1707368966::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@fa03edb, controlProcessor=org.ldaptive.provider.ControlProcessor@772891dc, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@5eeec9e8]
2016-11-16 12:21:11,346 DEBUG [org.ldaptive.BindOperation] - execute request=[org.ldaptive.BindRequest@408092516::bindDn=CN=testuser,CN=Users,DC=COMPANY, saslConfig=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@1313467158::config=[org.ldaptive.ConnectionConfig@1956653060::ldapUrl=ldap://company.domain , connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@1466625650::bindDn=CN=testuser,CN=Users,DC=COMPANY, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@753503470::metadata=[ldapUrl=ldap://company.domain , count=21], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1707368966::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@fa03edb, controlProcessor=org.ldaptive.provider.ControlProcessor@772891dc, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@5eeec9e8]
2016-11-16 12:21:11,349 DEBUG [org.ldaptive.BindOperation] - execute response=[org.ldaptive.Response@735501669::result=null, resultCode=SUCCESS, message=null, matchedDn=null, responseControls=null, referralURLs=null, messageId=-1] for request=[org.ldaptive.BindRequest@408092516::bindDn=CN=testuser,CN=Users,DC=COMPANY, saslConfig=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@1313467158::config=[org.ldaptive.ConnectionConfig@1956653060::ldapUrl=ldap://company.domain , connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@1466625650::bindDn=CN=testuser,CN=Users,DC=COMPANY, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@753503470::metadata=[ldapUrl=ldap://company.domain , count=21], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1707368966::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@fa03edb, controlProcessor=org.ldaptive.provider.ControlProcessor@772891dc, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@5eeec9e8]
2016-11-16 12:21:11,350 DEBUG [org.ldaptive.auth.PooledBindAuthenticationHandler] - authenticate response=[org.ldaptive.auth.AuthenticationHandlerResponse@272829171::connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@1313467158::config=[org.ldaptive.ConnectionConfig@1956653060::ldapUrl=ldap://company.domain , connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@1466625650::bindDn=CN=testuser,CN=Users,DC=COMPANY, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@753503470::metadata=[ldapUrl=ldap://company.domain , count=21], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1707368966::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@fa03edb, controlProcessor=org.ldaptive.provider.ControlProcessor@772891dc, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@5eeec9e8], result=true, resultCode=SUCCESS, message=null, controls=null] for criteria=[org.ldaptive.auth.AuthenticationCriteria@751038093::dn=CN=testuser,CN=Users,DC=COMPANY, authenticationRequest=[org.ldaptive.auth.AuthenticationRequest@1666496618::user=testuser, retAttrs=[1.1]]]
2016-11-16 12:21:11,350 DEBUG [org.ldaptive.auth.SearchEntryResolver] - resolve criteria=[org.ldaptive.auth.AuthenticationCriteria@751038093::dn=CN=testuser,CN=Users,DC=COMPANY, authenticationRequest=[org.ldaptive.auth.AuthenticationRequest@1666496618::user=testuser, retAttrs=[1.1]]]
2016-11-16 12:21:11,351 DEBUG [org.ldaptive.SearchOperation] - execute request=[org.ldaptive.SearchRequest@-223087509::baseDn=CN=testuser,CN=Users,DC=COMPANY, searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=0, sizeLimit=0, derefAliases=null, typesOnly=false, binaryAttributes=[objectGUID, objectSid], sortBehavior=UNORDERED, searchEntryHandlers=[org.ldaptive.ad.handler.ObjectGuidHandler@3f939ef7, org.ldaptive.ad.handler.ObjectSidHandler@a7398008], searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@1313467158::config=[org.ldaptive.ConnectionConfig@1956653060::ldapUrl=ldap://company.domain , connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@1466625650::bindDn=CN=testuser,CN=Users,DC=COMPANY, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@753503470::metadata=[ldapUrl=ldap://company.domain , count=21], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1707368966::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@fa03edb, controlProcessor=org.ldaptive.provider.ControlProcessor@772891dc, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@5eeec9e8]
2016-11-16 12:21:11,352 DEBUG [org.ldaptive.SearchOperation] - execute response=[org.ldaptive.Response@1568478470::result=[org.ldaptive.SearchResult@1551860074::entries=[[dn=CN=testuser,CN=Users,DC=COMPANY[], responseControls=null, messageId=-1]], references=[]], resultCode=SUCCESS, message=null, matchedDn=null, responseControls=null, referralURLs=null, messageId=-1] for request=[org.ldaptive.SearchRequest@-223087509::baseDn=CN=testuser,CN=Users,DC=COMPANY, searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=0, sizeLimit=0, derefAliases=null, typesOnly=false, binaryAttributes=[objectGUID, objectSid], sortBehavior=UNORDERED, searchEntryHandlers=[org.ldaptive.ad.handler.ObjectGuidHandler@3f939ef7, org.ldaptive.ad.handler.ObjectSidHandler@a7398008], searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@1313467158::config=[org.ldaptive.ConnectionConfig@1956653060::ldapUrl=ldap://company.domain , connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@1466625650::bindDn=CN=testuser,CN=Users,DC=COMPANY, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@753503470::metadata=[ldapUrl=ldap://company.domain , count=21], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1707368966::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@fa03edb, controlProcessor=org.ldaptive.provider.ControlProcessor@772891dc, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@5eeec9e8]
2016-11-16 12:21:11,353 DEBUG [org.ldaptive.auth.SearchEntryResolver] - resolved result=[org.ldaptive.SearchResult@1551860074::entries=[[dn=CN=testuser,CN=Users,DC=COMPANY[], responseControls=null, messageId=-1]], references=[]] for criteria=[org.ldaptive.auth.AuthenticationCriteria@751038093::dn=CN=testuser,CN=Users,DC=COMPANY, authenticationRequest=[org.ldaptive.auth.AuthenticationRequest@1666496618::user=testuser, retAttrs=[1.1]]]2016-11-16 12:21:11,353 INFO [org.ldaptive.auth.Authenticator] - Authentication succeeded for dn: CN=testuser,CN=Users,DC=COMPANY
2016-11-16 12:21:11,354 DEBUG [org.ldaptive.auth.Authenticator] - authenticate response=[org.ldaptive.auth.AuthenticationHandlerResponse@272829171::connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@1313467158::config=[org.ldaptive.ConnectionConfig@1956653060::ldapUrl=ldap://company.domain , connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@1466625650::bindDn=CN=testuser,CN=Users,DC=COMPANY, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@753503470::metadata=[ldapUrl=ldap://company.domain , count=21], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1707368966::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@fa03edb, controlProcessor=org.ldaptive.provider.ControlProcessor@772891dc, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@5eeec9e8], result=true, resultCode=SUCCESS, message=null, controls=null] for dn=CN=testuser,CN=Users,DC=COMPANY with request=[org.ldaptive.auth.AuthenticationRequest@1666496618::user=testuser, retAttrs=[1.1]]
2016-11-16 12:21:11,354 DEBUG [org.springframework.jdbc.core.JdbcTemplate] - Executing prepared SQL query
2016-11-16 12:21:11,354 DEBUG [org.springframework.jdbc.core.JdbcTemplate] - Executing prepared SQL statement [SELECT ID,username,FirstName,LastName,Email,ID_USERTYPE FROM aur_User WHERE UserName = ?]
2016-11-16 12:21:11,354 DEBUG [org.springframework.jdbc.datasource.DataSourceUtils] - Fetching JDBC Connection from DataSource
2016-11-16 12:21:11,355 DEBUG [org.springframework.jdbc.datasource.DataSourceUtils] - Returning JDBC Connection to DataSource
Which I do NOT see when the bug occurs.
I'm currently using connection poolings through c3po. However, it's strange to me that this specific test instance only affects a single user.
I'll continue to report what I find, but this seems very strange. Any ideas?