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
On success (eg, with a different login) after this is logged the following:
2016-11-16 15:55:19,163 DEBUG
[org.springframework.jdbc.datasource.DataSourceTransactionManager] -
Creating new transaction with name [null]:
PROPAGATION_REQUIRED,ISOLATION_READ_COMMITTED
2016-11-16 15:55:19,163 DEBUG
[org.springframework.jdbc.datasource.DataSourceTransactionManager] -
Acquired Connection [com.mchange.v2.c3p0.i
mpl.NewProxyConnection@495ef936 [wrapping:
com.mysql.jdbc.JDBC4Connection@73765a8a]] for JDBC transaction
2016-11-16 15:55:19,163 DEBUG
[org.springframework.jdbc.datasource.DataSourceUtils] - Changing isolation
level of JDBC Connection [com.mchang
e.v2.c3p0.impl.NewProxyConnection@495ef936 [wrapping:
com.mysql.jdbc.JDBC4Connection@73765a8a]] to 2
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?
On Tuesday, July 19, 2016 at 3:09:59 PM UTC-7, Jeffrey Wong wrote:
>
> After about a month of working perfectly on 4.2.2 deployed to tomcat7,
> running under java8, randomly the in-memory ticketing system would not
> create any more tickets. Restarting the tomcat instance fixed it, but I'm
> wondering why CAS would randomly break on me after working so well! Using a
> LDAP (AD) backed user base with a mysql backed attribute DB. We have pretty
> minimal traffic, so I'm not sure why I am seeing issues after such a small
> amount of time.
>
> Despite having an <AsyncRoot level="error">, no errors have been thrown at
> the time of issue.
>
> Unfortunately, I've only had the org.springframework.jdbc logger set to
> debug, and all others at info, so I have very minimal logging around the
> issue.
>
> I'm noticing both the ldap auth AND the jdbc handlers returning without
> issues (no errors). ...But no tickets?
>
> Here's a sample of the logs:
>
> 2016-07-19 16:28:16,399 INFO
> [org.jasig.cas.authentication.PolicyBasedAuthenticationManager] -
> <LdapAuthenticationHandler successfully authenticated user1>
> 2016-07-19 16:28:16,400 DEBUG [org.springframework.jdbc.core.JdbcTemplate] -
> <Executing prepared SQL query>
> 2016-07-19 16:28:16,400 DEBUG [org.springframework.jdbc.core.JdbcTemplate] -
> <Executing prepared SQL statement[SELECT
> ID,username,FirstName,LastName,Email FROM User WHERE UserName = ?]>
> 2016-07-19 16:28:16,400 DEBUG
> [org.springframework.jdbc.datasource.DataSourceUtils] - <Fetching JDBC
> Connection from DataSource>
> 2016-07-19 16:28:16,401 DEBUG
> [org.springframework.jdbc.datasource.DataSourceUtils] - <Returning JDBC
> Connection to DataSource>
> 2016-07-19 16:28:19,015 INFO
> [org.jasig.cas.authentication.PolicyBasedAuthenticationManager] -
> <LdapAuthenticationHandler successfully authenticated user2>
> 2016-07-19 16:28:19,015 DEBUG [org.springframework.jdbc.core.JdbcTemplate] -
> <Executing prepared SQL query>
> 2016-07-19 16:28:19,015 DEBUG [org.springframework.jdbc.core.JdbcTemplate] -
> <Executing prepared SQL statement[SELECT
> ID,username,FirstName,LastName,Email FROM User WHERE UserName = ?]>
> 2016-07-19 16:28:19,015 DEBUG
> [org.springframework.jdbc.datasource.DataSourceUtils] - <Fetching JDBC
> Connection from DataSource>
> 2016-07-19 16:28:19,017 DEBUG
> [org.springframework.jdbc.datasource.DataSourceUtils] - <Returning JDBC
> Connection to DataSource>
>
> Immediately before this, I've seen tickets that are created (an audit log
> is posted that a ticket granting ticket has been created and validated, and
> all is good). There are no exceptions thrown between when the tickets were
> able to be created and when there was this bottleneck.
>
> On the front end, after the logs say 'success' without a ticket created,
> they are redirected to the main cas login page. Reproducing this is also
> difficult as it will stop intermittently, without warning.
>
> What are the best ways to debug or resolve these sorts of issues? What
> could be causing this issue?
>
> Thanks in advance,
> Jeff
>
--
- CAS gitter chatroom: https://gitter.im/apereo/cas
- CAS mailing list guidelines: https://apereo.github.io/cas/Mailing-Lists.html
- CAS documentation website: https://apereo.github.io/cas
- CAS project website: https://github.com/apereo/cas
---
You received this message because you are subscribed to the Google Groups "CAS
Community" group.
To unsubscribe from this group and stop receiving emails from it, send an email
to [email protected].
To view this discussion on the web visit
https://groups.google.com/a/apereo.org/d/msgid/cas-user/bec03c51-d46e-4f19-86d4-c82294110dfd%40apereo.org.
