Daniel,
Here's the full trace of the authentication request for my "castester" user.
Thanks,
Mike
On Fri, Jul 24, 2015 at 4:59 PM, Daniel Fisher <[email protected]> wrote:
> On Fri, Jul 24, 2015 at 7:03 PM, Mike Seiler <[email protected]>
> wrote:
>
>> When I log in with my own user account, I also get the accountState=null
>> in the logs, and I am not part of the same group as "castester."
>>
>
> Can you put the org.ldaptive package in debug and post those logs?
>
> --Daniel Fisher
>
>
> --
> You are currently subscribed to [email protected] as:
> [email protected]
> To unsubscribe, change settings or access archives, see
> http://www.ja-sig.org/wiki/display/JSG/cas-user
>
>
--
*Michael Seiler*
--------------------------------------------------
Systems Integration Engineer
Fuller Theological Seminary
Phone: (970) 306-6105
[email protected]
*Fuller Summer Hours:* Please note that all Fuller offices will be closed
on Fridays from 7/3-8/28
*Mike's Vacation Notice:* From 7/3-8/28 I will also be taking Mondays off,
and will be out of the office for vacation 7/31 - 8/31
*Please NOTE:*
I respond to email at 8 AM, 1PM, and at 4:30PM. If you need more immediate
help, please contact TSS (626.584.5675) and they can route the issue to the
appropriate person. If this is a business process life or death emergency,
you may call me at the above number.
--
You are currently subscribed to [email protected] as:
[email protected]
To unsubscribe, change settings or access archives, see
http://www.ja-sig.org/wiki/display/JSG/cas-user
2015-07-28 08:44:09,481 DEBUG
[org.jasig.cas.authentication.LdapAuthenticationHandler] - <Attempting LDAP
authentication for castester+password>
2015-07-28 08:44:09,481 DEBUG [org.ldaptive.auth.PooledSearchDnResolver] -
<resolve user=castester>
2015-07-28 08:44:09,481 DEBUG [org.ldaptive.auth.PooledSearchDnResolver] -
<searching for DN using userFilter>
2015-07-28 08:44:09,481 TRACE [org.ldaptive.pool.BlockingConnectionPool] -
<waiting on pool lock for check out 0>
2015-07-28 08:44:09,482 TRACE [org.ldaptive.pool.BlockingConnectionPool] -
<retrieve available connection from pool of size 3>
2015-07-28 08:44:09,482 TRACE [org.ldaptive.pool.BlockingConnectionPool] -
<waiting on pool lock for retrieve available 0>
2015-07-28 08:44:09,482 TRACE [org.ldaptive.pool.BlockingConnectionPool] -
<retrieved available connection:
org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy@28d996bb>
2015-07-28 08:44:09,482 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <no
activator configured>
2015-07-28 08:44:09,484 DEBUG [org.ldaptive.SearchOperation] - <execute
request=[org.ldaptive.SearchRequest@-410124487::baseDn=ou=fuller,DC=id,DC=fuller,DC=edu,
searchFilter=[org.ldaptive.SearchFilter@1877340396::filter=(sAMAccountName={user}),
parameters={user=castester}], returnAttributes=[1.1], searchScope=SUBTREE,
timeLimit=0, sizeLimit=0, derefAliases=null, typesOnly=false,
binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null,
searchReferenceHandlers=null, controls=null, followReferrals=false,
intermediateResponseHandlers=null] with
connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@685291700::config=[org.ldaptive.ConnectionConfig@327780318::ldapUrl=ldaps://id.fuller.edu,
connectTimeout=3000, responseTimeout=-1,
sslConfig=[org.ldaptive.ssl.SslConfig@598195920::credentialConfig=[org.ldaptive.ssl.X509CredentialConfig@1427787790::trustCertificates=file:/etc/cas/id_app.pem,
authenticationCertificate=null, authenticationKey=null], trustManagers=null,
enabledCipherSuites=null, enabledProtocols=null,
handshakeCompletedListeners=null], useSSL=false, useStartTLS=false,
connectionInitializer=[org.ldaptive.BindConnectionInitializer@1856427390::[email protected],
bindSaslConfig=null, bindControls=null]],
providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@742803039::metadata=[ldapUrl=ldaps://id.fuller.edu,
count=1],
environment={java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory,
com.sun.jndi.ldap.connect.timeout=3000,
java.naming.ldap.factory.socket=org.ldaptive.ssl.ThreadLocalTLSSocketFactory,
java.naming.ldap.version=3},
providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@778154098::operationExceptionResultCodes=[PROTOCOL_ERROR,
SERVER_DOWN], properties={},
connectionStrategy=org.ldaptive.provider.ConnectionStrategies$DefaultConnectionStrategy@71315edf,
controlProcessor=org.ldaptive.provider.ControlProcessor@7bb841e8,
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@39b61dae]>
2015-07-28 08:44:09,486 TRACE [org.ldaptive.provider.jndi.JndiConnection] -
<reading search result: CN=CAS Tester 55508: null:null:No attributes>
2015-07-28 08:44:09,486 TRACE [org.ldaptive.provider.jndi.JndiConnection] -
<formatting relative dn 'CN=CAS Tester 55508' with baseDn
'ou=fuller,DC=id,DC=fuller,DC=edu'>
2015-07-28 08:44:09,486 TRACE [org.ldaptive.provider.jndi.JndiConnection] -
<formatted dn 'CN=CAS Tester 55508' as 'CN=CAS Tester
55508,ou=fuller,DC=id,DC=fuller,DC=edu'>
2015-07-28 08:44:09,486 TRACE [org.ldaptive.SearchOperation] - <Received search
item=[org.ldaptive.provider.SearchItem@1371537871::searchEntry=[dn=CN=CAS
Tester 55508,ou=fuller,DC=id,DC=fuller,DC=edu[], responseControls=null,
messageId=-1]]>
2015-07-28 08:44:09,487 DEBUG [org.ldaptive.SearchOperation] - <execute
response=[org.ldaptive.Response@347530999::result=[org.ldaptive.SearchResult@-868764508::entries=[[dn=CN=CAS
Tester 55508,ou=fuller,DC=id,DC=fuller,DC=edu[], responseControls=null,
messageId=-1]], references=[]], resultCode=SUCCESS, message=null,
matchedDn=null, responseControls=null, referralURLs=null, messageId=-1] for
request=[org.ldaptive.SearchRequest@-410124487::baseDn=ou=fuller,DC=id,DC=fuller,DC=edu,
searchFilter=[org.ldaptive.SearchFilter@1877340396::filter=(sAMAccountName={user}),
parameters={user=castester}], returnAttributes=[1.1], searchScope=SUBTREE,
timeLimit=0, sizeLimit=0, derefAliases=null, typesOnly=false,
binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null,
searchReferenceHandlers=null, controls=null, followReferrals=false,
intermediateResponseHandlers=null] with
connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@685291700::config=[org.ldaptive.ConnectionConfig@327780318::ldapUrl=ldaps://id.fuller.edu,
connectTimeout=3000, responseTimeout=-1,
sslConfig=[org.ldaptive.ssl.SslConfig@598195920::credentialConfig=[org.ldaptive.ssl.X509CredentialConfig@1427787790::trustCertificates=file:/etc/cas/id_app.pem,
authenticationCertificate=null, authenticationKey=null], trustManagers=null,
enabledCipherSuites=null, enabledProtocols=null,
handshakeCompletedListeners=null], useSSL=false, useStartTLS=false,
connectionInitializer=[org.ldaptive.BindConnectionInitializer@1856427390::[email protected],
bindSaslConfig=null, bindControls=null]],
providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@742803039::metadata=[ldapUrl=ldaps://id.fuller.edu,
count=1],
environment={java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory,
com.sun.jndi.ldap.connect.timeout=3000,
java.naming.ldap.factory.socket=org.ldaptive.ssl.ThreadLocalTLSSocketFactory,
java.naming.ldap.version=3},
providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@778154098::operationExceptionResultCodes=[PROTOCOL_ERROR,
SERVER_DOWN], properties={},
connectionStrategy=org.ldaptive.provider.ConnectionStrategies$DefaultConnectionStrategy@71315edf,
controlProcessor=org.ldaptive.provider.ControlProcessor@7bb841e8,
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@39b61dae]>
2015-07-28 08:44:09,487 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <no
passivator configured>
2015-07-28 08:44:09,487 TRACE [org.ldaptive.pool.BlockingConnectionPool] -
<waiting on pool lock for check in 0>
2015-07-28 08:44:09,487 TRACE [org.ldaptive.pool.BlockingConnectionPool] -
<returned active connection:
org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy@28d996bb>
2015-07-28 08:44:09,487 DEBUG [org.ldaptive.auth.PooledSearchDnResolver] -
<resolved dn=CN=CAS Tester 55508,ou=fuller,DC=id,DC=fuller,DC=edu for
user=castester>
2015-07-28 08:44:09,487 DEBUG [org.ldaptive.auth.Authenticator] - <authenticate
dn=CN=CAS Tester 55508,ou=fuller,DC=id,DC=fuller,DC=edu with
request=[org.ldaptive.auth.AuthenticationRequest@1157146056::user=castester,
retAttrs=[]]>
2015-07-28 08:44:09,487 DEBUG
[org.ldaptive.auth.PooledBindAuthenticationHandler] - <authenticate
criteria=[org.ldaptive.auth.AuthenticationCriteria@541855960::dn=CN=CAS Tester
55508,ou=fuller,DC=id,DC=fuller,DC=edu,
authenticationRequest=[org.ldaptive.auth.AuthenticationRequest@1157146056::user=castester,
retAttrs=[]]]>
2015-07-28 08:44:09,487 TRACE [org.ldaptive.pool.BlockingConnectionPool] -
<waiting on pool lock for check out 0>
2015-07-28 08:44:09,487 TRACE [org.ldaptive.pool.BlockingConnectionPool] -
<retrieve available connection from pool of size 3>
2015-07-28 08:44:09,488 TRACE [org.ldaptive.pool.BlockingConnectionPool] -
<waiting on pool lock for retrieve available 0>
2015-07-28 08:44:09,488 TRACE [org.ldaptive.pool.BlockingConnectionPool] -
<retrieved available connection:
org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy@7f1b4271>
2015-07-28 08:44:09,488 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <no
activator configured>
2015-07-28 08:44:09,488 DEBUG [org.ldaptive.BindOperation] - <execute
request=[org.ldaptive.BindRequest@1642456440::bindDn=CN=CAS Tester
55508,ou=fuller,DC=id,DC=fuller,DC=edu, saslConfig=null,
controls=[[org.ldaptive.control.PasswordPolicyControl@-350057371::criticality=false,
timeBeforeExpiration=0, graceAuthNsRemaining=0, error=null]]] with
connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@2132436074::config=[org.ldaptive.ConnectionConfig@941869506::ldapUrl=ldaps://id.fuller.edu,
connectTimeout=3000, responseTimeout=-1,
sslConfig=[org.ldaptive.ssl.SslConfig@598195920::credentialConfig=[org.ldaptive.ssl.X509CredentialConfig@1427787790::trustCertificates=file:/etc/cas/id_app.pem,
authenticationCertificate=null, authenticationKey=null], trustManagers=null,
enabledCipherSuites=null, enabledProtocols=null,
handshakeCompletedListeners=null], useSSL=false, useStartTLS=false,
connectionInitializer=null],
providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@1943150890::metadata=[ldapUrl=ldaps://id.fuller.edu,
count=1],
environment={java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory,
com.sun.jndi.ldap.connect.timeout=3000,
java.naming.ldap.factory.socket=org.ldaptive.ssl.ThreadLocalTLSSocketFactory,
java.naming.ldap.version=3},
providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1753188301::operationExceptionResultCodes=[PROTOCOL_ERROR,
SERVER_DOWN], properties={},
connectionStrategy=org.ldaptive.provider.ConnectionStrategies$DefaultConnectionStrategy@71315edf,
controlProcessor=org.ldaptive.provider.ControlProcessor@592fa3df,
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@cacd954]>
2015-07-28 08:44:09,488 TRACE [org.ldaptive.provider.ControlProcessor] -
<processing request controls:
[[org.ldaptive.control.PasswordPolicyControl@-350057371::criticality=false,
timeBeforeExpiration=0, graceAuthNsRemaining=0, error=null]]>
2015-07-28 08:44:09,488 TRACE [org.ldaptive.provider.ControlProcessor] -
<produced provider request controls: [javax.naming.ldap.BasicControl@44cd09b3]>
2015-07-28 08:44:09,677 DEBUG [org.ldaptive.BindOperation] - <execute
response=[org.ldaptive.Response@233273140::result=null, resultCode=SUCCESS,
message=null, matchedDn=null, responseControls=null, referralURLs=null,
messageId=-1] for request=[org.ldaptive.BindRequest@1642456440::bindDn=CN=CAS
Tester 55508,ou=fuller,DC=id,DC=fuller,DC=edu, saslConfig=null,
controls=[[org.ldaptive.control.PasswordPolicyControl@-350057371::criticality=false,
timeBeforeExpiration=0, graceAuthNsRemaining=0, error=null]]] with
connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@2132436074::config=[org.ldaptive.ConnectionConfig@941869506::ldapUrl=ldaps://id.fuller.edu,
connectTimeout=3000, responseTimeout=-1,
sslConfig=[org.ldaptive.ssl.SslConfig@598195920::credentialConfig=[org.ldaptive.ssl.X509CredentialConfig@1427787790::trustCertificates=file:/etc/cas/id_app.pem,
authenticationCertificate=null, authenticationKey=null], trustManagers=null,
enabledCipherSuites=null, enabledProtocols=null,
handshakeCompletedListeners=null], useSSL=false, useStartTLS=false,
connectionInitializer=null],
providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@1943150890::metadata=[ldapUrl=ldaps://id.fuller.edu,
count=1],
environment={java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory,
com.sun.jndi.ldap.connect.timeout=3000,
java.naming.ldap.factory.socket=org.ldaptive.ssl.ThreadLocalTLSSocketFactory,
java.naming.ldap.version=3},
providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1753188301::operationExceptionResultCodes=[PROTOCOL_ERROR,
SERVER_DOWN], properties={},
connectionStrategy=org.ldaptive.provider.ConnectionStrategies$DefaultConnectionStrategy@71315edf,
controlProcessor=org.ldaptive.provider.ControlProcessor@592fa3df,
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@cacd954]>
2015-07-28 08:44:09,679 DEBUG
[org.ldaptive.auth.PooledBindAuthenticationHandler] - <authenticate
response=[org.ldaptive.auth.AuthenticationHandlerResponse@1464008205::connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@2132436074::config=[org.ldaptive.ConnectionConfig@941869506::ldapUrl=ldaps://id.fuller.edu,
connectTimeout=3000, responseTimeout=-1,
sslConfig=[org.ldaptive.ssl.SslConfig@598195920::credentialConfig=[org.ldaptive.ssl.X509CredentialConfig@1427787790::trustCertificates=file:/etc/cas/id_app.pem,
authenticationCertificate=null, authenticationKey=null], trustManagers=null,
enabledCipherSuites=null, enabledProtocols=null,
handshakeCompletedListeners=null], useSSL=false, useStartTLS=false,
connectionInitializer=null],
providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@1943150890::metadata=[ldapUrl=ldaps://id.fuller.edu,
count=1],
environment={java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory,
com.sun.jndi.ldap.connect.timeout=3000,
java.naming.ldap.factory.socket=org.ldaptive.ssl.ThreadLocalTLSSocketFactory,
java.naming.ldap.version=3},
providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1753188301::operationExceptionResultCodes=[PROTOCOL_ERROR,
SERVER_DOWN], properties={},
connectionStrategy=org.ldaptive.provider.ConnectionStrategies$DefaultConnectionStrategy@71315edf,
controlProcessor=org.ldaptive.provider.ControlProcessor@592fa3df,
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@cacd954],
result=true, resultCode=SUCCESS, message=null, controls=null] for
criteria=[org.ldaptive.auth.AuthenticationCriteria@541855960::dn=CN=CAS Tester
55508,ou=fuller,DC=id,DC=fuller,DC=edu,
authenticationRequest=[org.ldaptive.auth.AuthenticationRequest@1157146056::user=castester,
retAttrs=[]]]>
2015-07-28 08:44:09,681 DEBUG [org.ldaptive.auth.SearchEntryResolver] -
<resolve
criteria=[org.ldaptive.auth.AuthenticationCriteria@541855960::dn=CN=CAS Tester
55508,ou=fuller,DC=id,DC=fuller,DC=edu,
authenticationRequest=[org.ldaptive.auth.AuthenticationRequest@1157146056::user=castester,
retAttrs=[]]]>
2015-07-28 08:44:09,681 DEBUG [org.ldaptive.SearchOperation] - <execute
request=[org.ldaptive.SearchRequest@-357527465::baseDn=CN=CAS Tester
55508,ou=fuller,DC=id,DC=fuller,DC=edu,
searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*),
parameters={}], returnAttributes=[], searchScope=OBJECT, timeLimit=0,
sizeLimit=0, derefAliases=null, typesOnly=false, binaryAttributes=null,
sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null,
controls=null, followReferrals=false, intermediateResponseHandlers=null] with
connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@2132436074::config=[org.ldaptive.ConnectionConfig@941869506::ldapUrl=ldaps://id.fuller.edu,
connectTimeout=3000, responseTimeout=-1,
sslConfig=[org.ldaptive.ssl.SslConfig@598195920::credentialConfig=[org.ldaptive.ssl.X509CredentialConfig@1427787790::trustCertificates=file:/etc/cas/id_app.pem,
authenticationCertificate=null, authenticationKey=null], trustManagers=null,
enabledCipherSuites=null, enabledProtocols=null,
handshakeCompletedListeners=null], useSSL=false, useStartTLS=false,
connectionInitializer=null],
providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@1943150890::metadata=[ldapUrl=ldaps://id.fuller.edu,
count=1],
environment={java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory,
com.sun.jndi.ldap.connect.timeout=3000,
java.naming.ldap.factory.socket=org.ldaptive.ssl.ThreadLocalTLSSocketFactory,
java.naming.ldap.version=3},
providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1753188301::operationExceptionResultCodes=[PROTOCOL_ERROR,
SERVER_DOWN], properties={},
connectionStrategy=org.ldaptive.provider.ConnectionStrategies$DefaultConnectionStrategy@71315edf,
controlProcessor=org.ldaptive.provider.ControlProcessor@592fa3df,
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@cacd954]>
2015-07-28 08:44:09,684 TRACE [org.ldaptive.provider.jndi.JndiConnection] -
<reading search result: : null:null:{displayname=displayName: CAS Tester 55508,
givenname=givenName: CAS, samaccounttype=sAMAccountType: 805306368,
primarygroupid=primaryGroupID: 513, objectclass=objectClass: top, person,
organizationalPerson, user, badpasswordtime=badPasswordTime: 0,
objectcategory=objectCategory:
CN=Person,CN=Schema,CN=Configuration,DC=id,DC=fuller,DC=edu, mail=mail:
[email protected], cn=cn: CAS Tester 55508,
useraccountcontrol=userAccountControl: 512,
userprincipalname=userPrincipalName: [email protected],
dscorepropagationdata=dSCorePropagationData: 16010101000000.0Z,
codepage=codePage: 0, distinguishedname=distinguishedName: CN=CAS Tester
55508,OU=fuller,DC=id,DC=fuller,DC=edu, whenchanged=whenChanged:
20150724224530.0Z, whencreated=whenCreated: 20150723002824.0Z,
pwdlastset=pwdLastSet: 130821507786639794, description=description: CAS,
accountexpires=accountExpires: 130961088000000000,
lastlogontimestamp=lastLogonTimestamp: 130822510138487578,
objectguid=objectGUID: Rءџ��O�8jRIP�, sn=sn: Tester, usnchanged=uSNChanged:
1239446, usncreated=uSNCreated: 1223840, objectsid=objectSid:
\00\00\00\00\00\00\00\00��2�Zy<�� Uz\00\00, countrycode=countryCode: 0,
samaccountname=sAMAccountName: castester, instancetype=instanceType: 0,
memberof=memberOf: CN=castest,OU=groups,OU=fuller,DC=id,DC=fuller,DC=edu,
CN=LibraryMembers,OU=groups,OU=fuller,DC=id,DC=fuller,DC=edu,
badpwdcount=badPwdCount: 0, name=name: CAS Tester 55508}>
2015-07-28 08:44:09,684 TRACE [org.ldaptive.provider.jndi.JndiConnection] -
<formatting relative dn '' with baseDn 'CN=CAS Tester
55508,ou=fuller,DC=id,DC=fuller,DC=edu'>
2015-07-28 08:44:09,684 TRACE [org.ldaptive.provider.jndi.JndiConnection] -
<formatted dn '' as 'CN=CAS Tester 55508,ou=fuller,DC=id,DC=fuller,DC=edu'>
2015-07-28 08:44:09,687 TRACE [org.ldaptive.SearchOperation] - <Received search
item=[org.ldaptive.provider.SearchItem@469236168::searchEntry=[dn=CN=CAS Tester
55508,ou=fuller,DC=id,DC=fuller,DC=edu[[lastLogonTimestamp[130822510138487578]],
[countryCode[0]], [givenName[CAS]], [whenChanged[20150724224530.0Z]],
[memberOf[CN=castest,OU=groups,OU=fuller,DC=id,DC=fuller,DC=edu,
CN=LibraryMembers,OU=groups,OU=fuller,DC=id,DC=fuller,DC=edu]],
[instanceType[0]], [codePage[0]], [dSCorePropagationData[16010101000000.0Z]],
[uSNCreated[1223840]], [uSNChanged[1239446]], [badPwdCount[0]],
[whenCreated[20150723002824.0Z]], [description[CAS]], [name[CAS Tester 55508]],
[objectCategory[CN=Person,CN=Schema,CN=Configuration,DC=id,DC=fuller,DC=edu]],
[objectClass[organizationalPerson, person, user, top]],
[mail[[email protected]]], [sn[Tester]], [userAccountControl[512]],
[sAMAccountType[805306368]], [pwdLastSet[130821507786639794]],
[badPasswordTime[0]], [distinguishedName[CN=CAS Tester
55508,OU=fuller,DC=id,DC=fuller,DC=edu]], [cn[CAS Tester 55508]],
[primaryGroupID[513]], [sAMAccountName[castester]],
[objectSid[\00\00\00\00\00\00\00\00��2�Zy<�� Uz\00\00]],
[accountExpires[130961088000000000]],
[userPrincipalName[[email protected]]], [objectGUID[Rءџ��O�8jRIP�]],
[displayName[CAS Tester 55508]]], responseControls=null, messageId=-1]]>
2015-07-28 08:44:09,688 DEBUG [org.ldaptive.SearchOperation] - <execute
response=[org.ldaptive.Response@892323792::result=[org.ldaptive.SearchResult@997201060::entries=[[dn=CN=CAS
Tester
55508,ou=fuller,DC=id,DC=fuller,DC=edu[[lastLogonTimestamp[130822510138487578]],
[countryCode[0]], [givenName[CAS]], [whenChanged[20150724224530.0Z]],
[memberOf[CN=castest,OU=groups,OU=fuller,DC=id,DC=fuller,DC=edu,
CN=LibraryMembers,OU=groups,OU=fuller,DC=id,DC=fuller,DC=edu]],
[instanceType[0]], [codePage[0]], [dSCorePropagationData[16010101000000.0Z]],
[uSNCreated[1223840]], [uSNChanged[1239446]], [badPwdCount[0]],
[whenCreated[20150723002824.0Z]], [description[CAS]], [name[CAS Tester 55508]],
[objectCategory[CN=Person,CN=Schema,CN=Configuration,DC=id,DC=fuller,DC=edu]],
[objectClass[organizationalPerson, person, user, top]],
[mail[[email protected]]], [sn[Tester]], [userAccountControl[512]],
[sAMAccountType[805306368]], [pwdLastSet[130821507786639794]],
[badPasswordTime[0]], [distinguishedName[CN=CAS Tester
55508,OU=fuller,DC=id,DC=fuller,DC=edu]], [cn[CAS Tester 55508]],
[primaryGroupID[513]], [sAMAccountName[castester]],
[objectSid[\00\00\00\00\00\00\00\00��2�Zy<�� Uz\00\00]],
[accountExpires[130961088000000000]],
[userPrincipalName[[email protected]]], [objectGUID[Rءџ��O�8jRIP�]],
[displayName[CAS Tester 55508]]], responseControls=null, messageId=-1]],
references=[]], resultCode=SUCCESS, message=null, matchedDn=null,
responseControls=null, referralURLs=null, messageId=-1] for
request=[org.ldaptive.SearchRequest@-357527465::baseDn=CN=CAS Tester
55508,ou=fuller,DC=id,DC=fuller,DC=edu,
searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*),
parameters={}], returnAttributes=[], searchScope=OBJECT, timeLimit=0,
sizeLimit=0, derefAliases=null, typesOnly=false, binaryAttributes=null,
sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null,
controls=null, followReferrals=false, intermediateResponseHandlers=null] with
connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@2132436074::config=[org.ldaptive.ConnectionConfig@941869506::ldapUrl=ldaps://id.fuller.edu,
connectTimeout=3000, responseTimeout=-1,
sslConfig=[org.ldaptive.ssl.SslConfig@598195920::credentialConfig=[org.ldaptive.ssl.X509CredentialConfig@1427787790::trustCertificates=file:/etc/cas/id_app.pem,
authenticationCertificate=null, authenticationKey=null], trustManagers=null,
enabledCipherSuites=null, enabledProtocols=null,
handshakeCompletedListeners=null], useSSL=false, useStartTLS=false,
connectionInitializer=null],
providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@1943150890::metadata=[ldapUrl=ldaps://id.fuller.edu,
count=1],
environment={java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory,
com.sun.jndi.ldap.connect.timeout=3000,
java.naming.ldap.factory.socket=org.ldaptive.ssl.ThreadLocalTLSSocketFactory,
java.naming.ldap.version=3},
providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1753188301::operationExceptionResultCodes=[PROTOCOL_ERROR,
SERVER_DOWN], properties={},
connectionStrategy=org.ldaptive.provider.ConnectionStrategies$DefaultConnectionStrategy@71315edf,
controlProcessor=org.ldaptive.provider.ControlProcessor@592fa3df,
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@cacd954]>
2015-07-28 08:44:09,689 DEBUG [org.ldaptive.auth.SearchEntryResolver] -
<resolved result=[org.ldaptive.SearchResult@997201060::entries=[[dn=CN=CAS
Tester
55508,ou=fuller,DC=id,DC=fuller,DC=edu[[lastLogonTimestamp[130822510138487578]],
[countryCode[0]], [givenName[CAS]], [whenChanged[20150724224530.0Z]],
[memberOf[CN=castest,OU=groups,OU=fuller,DC=id,DC=fuller,DC=edu,
CN=LibraryMembers,OU=groups,OU=fuller,DC=id,DC=fuller,DC=edu]],
[instanceType[0]], [codePage[0]], [dSCorePropagationData[16010101000000.0Z]],
[uSNCreated[1223840]], [uSNChanged[1239446]], [badPwdCount[0]],
[whenCreated[20150723002824.0Z]], [description[CAS]], [name[CAS Tester 55508]],
[objectCategory[CN=Person,CN=Schema,CN=Configuration,DC=id,DC=fuller,DC=edu]],
[objectClass[organizationalPerson, person, user, top]],
[mail[[email protected]]], [sn[Tester]], [userAccountControl[512]],
[sAMAccountType[805306368]], [pwdLastSet[130821507786639794]],
[badPasswordTime[0]], [distinguishedName[CN=CAS Tester
55508,OU=fuller,DC=id,DC=fuller,DC=edu]], [cn[CAS Tester 55508]],
[primaryGroupID[513]], [sAMAccountName[castester]],
[objectSid[\00\00\00\00\00\00\00\00��2�Zy<�� Uz\00\00]],
[accountExpires[130961088000000000]],
[userPrincipalName[[email protected]]], [objectGUID[Rءџ��O�8jRIP�]],
[displayName[CAS Tester 55508]]], responseControls=null, messageId=-1]],
references=[]] for
criteria=[org.ldaptive.auth.AuthenticationCriteria@541855960::dn=CN=CAS Tester
55508,ou=fuller,DC=id,DC=fuller,DC=edu,
authenticationRequest=[org.ldaptive.auth.AuthenticationRequest@1157146056::user=castester,
retAttrs=[]]]>
2015-07-28 08:44:09,690 TRACE [org.ldaptive.auth.Authenticator] - <resolved
entry=[dn=CN=CAS Tester
55508,ou=fuller,DC=id,DC=fuller,DC=edu[[lastLogonTimestamp[130822510138487578]],
[countryCode[0]], [givenName[CAS]], [whenChanged[20150724224530.0Z]],
[memberOf[CN=castest,OU=groups,OU=fuller,DC=id,DC=fuller,DC=edu,
CN=LibraryMembers,OU=groups,OU=fuller,DC=id,DC=fuller,DC=edu]],
[instanceType[0]], [codePage[0]], [dSCorePropagationData[16010101000000.0Z]],
[uSNCreated[1223840]], [uSNChanged[1239446]], [badPwdCount[0]],
[whenCreated[20150723002824.0Z]], [description[CAS]], [name[CAS Tester 55508]],
[objectCategory[CN=Person,CN=Schema,CN=Configuration,DC=id,DC=fuller,DC=edu]],
[objectClass[organizationalPerson, person, user, top]],
[mail[[email protected]]], [sn[Tester]], [userAccountControl[512]],
[sAMAccountType[805306368]], [pwdLastSet[130821507786639794]],
[badPasswordTime[0]], [distinguishedName[CN=CAS Tester
55508,OU=fuller,DC=id,DC=fuller,DC=edu]], [cn[CAS Tester 55508]],
[primaryGroupID[513]], [sAMAccountName[castester]],
[objectSid[\00\00\00\00\00\00\00\00��2�Zy<�� Uz\00\00]],
[accountExpires[130961088000000000]],
[userPrincipalName[[email protected]]], [objectGUID[Rءџ��O�8jRIP�]],
[displayName[CAS Tester 55508]]], responseControls=null, messageId=-1] with
resolver=[org.ldaptive.auth.SearchEntryResolver@1407665143::factory=null,
baseDn=, userFilter=null, userFilterParameters=null,
allowMultipleEntries=false, subtreeSearch=false, derefAliases=null,
followReferrals=false, searchEntryHandlers=null]>
2015-07-28 08:44:09,690 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <no
passivator configured>
2015-07-28 08:44:09,690 TRACE [org.ldaptive.pool.BlockingConnectionPool] -
<waiting on pool lock for check in 0>
2015-07-28 08:44:09,690 TRACE [org.ldaptive.pool.BlockingConnectionPool] -
<returned active connection:
org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy@7f1b4271>
2015-07-28 08:44:09,690 INFO [org.ldaptive.auth.Authenticator] -
<Authentication succeeded for dn: CN=CAS Tester
55508,ou=fuller,DC=id,DC=fuller,DC=edu>
2015-07-28 08:44:09,691 DEBUG [org.ldaptive.auth.Authenticator] - <authenticate
response=[org.ldaptive.auth.AuthenticationHandlerResponse@1464008205::connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@2132436074::config=[org.ldaptive.ConnectionConfig@941869506::ldapUrl=ldaps://id.fuller.edu,
connectTimeout=3000, responseTimeout=-1,
sslConfig=[org.ldaptive.ssl.SslConfig@598195920::credentialConfig=[org.ldaptive.ssl.X509CredentialConfig@1427787790::trustCertificates=file:/etc/cas/id_app.pem,
authenticationCertificate=null, authenticationKey=null], trustManagers=null,
enabledCipherSuites=null, enabledProtocols=null,
handshakeCompletedListeners=null], useSSL=false, useStartTLS=false,
connectionInitializer=null],
providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@1943150890::metadata=[ldapUrl=ldaps://id.fuller.edu,
count=1],
environment={java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory,
com.sun.jndi.ldap.connect.timeout=3000,
java.naming.ldap.factory.socket=org.ldaptive.ssl.ThreadLocalTLSSocketFactory,
java.naming.ldap.version=3},
providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1753188301::operationExceptionResultCodes=[PROTOCOL_ERROR,
SERVER_DOWN], properties={},
connectionStrategy=org.ldaptive.provider.ConnectionStrategies$DefaultConnectionStrategy@71315edf,
controlProcessor=org.ldaptive.provider.ControlProcessor@592fa3df,
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@cacd954],
result=true, resultCode=SUCCESS, message=null, controls=null] for dn=CN=CAS
Tester 55508,ou=fuller,DC=id,DC=fuller,DC=edu with
request=[org.ldaptive.auth.AuthenticationRequest@1157146056::user=castester,
retAttrs=[]]>
2015-07-28 08:44:09,692 DEBUG
[org.jasig.cas.authentication.LdapAuthenticationHandler] - <LDAP response:
[org.ldaptive.auth.AuthenticationResponse@1606525448::authenticationResultCode=AUTHENTICATION_HANDLER_SUCCESS,
ldapEntry=[dn=CN=CAS Tester
55508,ou=fuller,DC=id,DC=fuller,DC=edu[[lastLogonTimestamp[130822510138487578]],
[countryCode[0]], [givenName[CAS]], [whenChanged[20150724224530.0Z]],
[memberOf[CN=castest,OU=groups,OU=fuller,DC=id,DC=fuller,DC=edu,
CN=LibraryMembers,OU=groups,OU=fuller,DC=id,DC=fuller,DC=edu]],
[instanceType[0]], [codePage[0]], [dSCorePropagationData[16010101000000.0Z]],
[uSNCreated[1223840]], [uSNChanged[1239446]], [badPwdCount[0]],
[whenCreated[20150723002824.0Z]], [description[CAS]], [name[CAS Tester 55508]],
[objectCategory[CN=Person,CN=Schema,CN=Configuration,DC=id,DC=fuller,DC=edu]],
[objectClass[organizationalPerson, person, user, top]],
[mail[[email protected]]], [sn[Tester]], [userAccountControl[512]],
[sAMAccountType[805306368]], [pwdLastSet[130821507786639794]],
[badPasswordTime[0]], [distinguishedName[CN=CAS Tester
55508,OU=fuller,DC=id,DC=fuller,DC=edu]], [cn[CAS Tester 55508]],
[primaryGroupID[513]], [sAMAccountName[castester]],
[objectSid[\00\00\00\00\00\00\00\00��2�Zy<�� Uz\00\00]],
[accountExpires[130961088000000000]],
[userPrincipalName[[email protected]]], [objectGUID[Rءџ��O�8jRIP�]],
[displayName[CAS Tester 55508]]], responseControls=null, messageId=-1],
accountState=null, result=true, resultCode=SUCCESS, message=null,
controls=null]>
2015-07-28 08:44:09,692 DEBUG
[org.jasig.cas.authentication.LdapAuthenticationHandler] - <Applying password
policy to
[org.ldaptive.auth.AuthenticationResponse@1606525448::authenticationResultCode=AUTHENTICATION_HANDLER_SUCCESS,
ldapEntry=[dn=CN=CAS Tester
55508,ou=fuller,DC=id,DC=fuller,DC=edu[[lastLogonTimestamp[130822510138487578]],
[countryCode[0]], [givenName[CAS]], [whenChanged[20150724224530.0Z]],
[memberOf[CN=castest,OU=groups,OU=fuller,DC=id,DC=fuller,DC=edu,
CN=LibraryMembers,OU=groups,OU=fuller,DC=id,DC=fuller,DC=edu]],
[instanceType[0]], [codePage[0]], [dSCorePropagationData[16010101000000.0Z]],
[uSNCreated[1223840]], [uSNChanged[1239446]], [badPwdCount[0]],
[whenCreated[20150723002824.0Z]], [description[CAS]], [name[CAS Tester 55508]],
[objectCategory[CN=Person,CN=Schema,CN=Configuration,DC=id,DC=fuller,DC=edu]],
[objectClass[organizationalPerson, person, user, top]],
[mail[[email protected]]], [sn[Tester]], [userAccountControl[512]],
[sAMAccountType[805306368]], [pwdLastSet[130821507786639794]],
[badPasswordTime[0]], [distinguishedName[CN=CAS Tester
55508,OU=fuller,DC=id,DC=fuller,DC=edu]], [cn[CAS Tester 55508]],
[primaryGroupID[513]], [sAMAccountName[castester]],
[objectSid[\00\00\00\00\00\00\00\00��2�Zy<�� Uz\00\00]],
[accountExpires[130961088000000000]],
[userPrincipalName[[email protected]]], [objectGUID[Rءџ��O�8jRIP�]],
[displayName[CAS Tester 55508]]], responseControls=null, messageId=-1],
accountState=null, result=true, resultCode=SUCCESS, message=null,
controls=null]>
2015-07-28 08:44:09,692 DEBUG
[org.jasig.cas.authentication.support.DefaultAccountStateHandler] - <Account
state not defined>
2015-07-28 08:44:09,692 DEBUG
[org.jasig.cas.authentication.support.DefaultAccountStateHandler] - <Handling
null>
2015-07-28 08:44:09,693 DEBUG
[org.jasig.cas.authentication.support.DefaultAccountStateHandler] - <No LDAP
error mapping defined for null>
2015-07-28 08:44:09,693 DEBUG
[org.jasig.cas.authentication.support.DefaultAccountStateHandler] - <Account
state warning not defined>
2015-07-28 08:44:09,693 DEBUG
[org.jasig.cas.authentication.LdapAuthenticationHandler] - <Found principal
attribute: [memberOf[CN=castest,OU=groups,OU=fuller,DC=id,DC=fuller,DC=edu,
CN=LibraryMembers,OU=groups,OU=fuller,DC=id,DC=fuller,DC=edu]]>
2015-07-28 08:44:09,693 DEBUG
[org.jasig.cas.authentication.LdapAuthenticationHandler] - <Found principal
attribute: [mail[[email protected]]]>
2015-07-28 08:44:09,693 DEBUG
[org.jasig.cas.authentication.LdapAuthenticationHandler] - <Found principal
attribute: [displayName[CAS Tester 55508]]>
2015-07-28 08:44:09,693 DEBUG
[org.jasig.cas.authentication.LdapAuthenticationHandler] - <Found principal
attribute: [pwdLastSet[130821507786639794]]>
2015-07-28 08:44:09,694 INFO
[org.jasig.cas.authentication.PolicyBasedAuthenticationManager] -
<LdapAuthenticationHandler successfully authenticated castester+password>
2015-07-28 08:44:09,694 DEBUG
[org.jasig.cas.authentication.principal.PersonDirectoryPrincipalResolver] -
<Attempting to resolve a principal...>
2015-07-28 08:44:09,694 DEBUG
[org.jasig.cas.authentication.principal.PersonDirectoryPrincipalResolver] -
<Creating SimplePrincipal for [castester]>
2015-07-28 08:44:09,694 DEBUG
[org.jasig.cas.authentication.PolicyBasedAuthenticationManager] -
<org.jasig.cas.authentication.principal.PersonDirectoryPrincipalResolver@4fbf062b
resolved castester from castester+password>
2015-07-28 08:44:09,695 INFO
[org.jasig.cas.authentication.PolicyBasedAuthenticationManager] -
<Authenticated castester with credentials [castester+password].>
2015-07-28 08:44:09,695 DEBUG
[org.jasig.cas.authentication.PolicyBasedAuthenticationManager] - <Attribute
map for castester: {uid=uid, eduPersonAffiliation=eduPersonAffiliation,
groupMembership=groupMembership}>
2015-07-28 08:44:09,698 INFO
[com.github.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - <Audit
trail record BEGIN
=============================================================
WHO: audit:unknown
WHAT: supplied credentials: [castester+password]
ACTION: AUTHENTICATION_SUCCESS
APPLICATION: CAS
WHEN: Tue Jul 28 08:44:09 PDT 2015
CLIENT IP ADDRESS: 184.99.147.218
SERVER IP ADDRESS: 192.168.72.160
=============================================================
>
2015-07-28 08:44:09,700 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Added ticket
[TGT-1-zpvq322cEEduNa0pwwxayuTXha4pBYSg6Tk3HBLWpyRvYoihGu-logintest.fuller.edu]
to registry.>
2015-07-28 08:44:09,700 INFO
[com.github.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - <Audit
trail record BEGIN
=============================================================
WHO: audit:unknown
WHAT:
TGT-1-zpvq322cEEduNa0pwwxayuTXha4pBYSg6Tk3HBLWpyRvYoihGu-logintest.fuller.edu
ACTION: TICKET_GRANTING_TICKET_CREATED
APPLICATION: CAS
WHEN: Tue Jul 28 08:44:09 PDT 2015
CLIENT IP ADDRESS: 184.99.147.218
SERVER IP ADDRESS: 192.168.72.160
=============================================================
>
2015-07-28 08:44:09,700 DEBUG
[org.jasig.cas.web.support.CookieRetrievingCookieGenerator] - <Removed cookie
with name [CASPRIVACY]>
2015-07-28 08:44:09,700 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Attempting to retrieve
ticket
[TGT-1-zpvq322cEEduNa0pwwxayuTXha4pBYSg6Tk3HBLWpyRvYoihGu-logintest.fuller.edu]>
2015-07-28 08:44:09,700 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Ticket
[TGT-1-zpvq322cEEduNa0pwwxayuTXha4pBYSg6Tk3HBLWpyRvYoihGu-logintest.fuller.edu]
found in registry.>
2015-07-28 08:44:09,701 DEBUG
[org.jasig.cas.web.support.CookieRetrievingCookieGenerator] - <Added cookie
with name [CASTGC] and value
[TGT-1-zpvq322cEEduNa0pwwxayuTXha4pBYSg6Tk3HBLWpyRvYoihGu-logintest.fuller.edu]>
2015-07-28 08:44:09,914 DEBUG [org.jasig.cas.web.support.CasArgumentExtractor]
- <Extractor did not generate service.>
