OpenLDAP Password Policy account state handling.

[O'Dowd, Josh]

Sure.  The following is DEBUG output from ldaptive packages.  I believe we are seeing a successful bind followed by a failed search operation.  The search operation appears to be restricted from the list of current allowed operations.  I believe this is due to the fact that the directory is enforcing a password-must-change policy that is active.  I am concluding that because search operations are not being restricted for accounts with normal account state.

2016-12-12 13:13:23,105 - DEBUG [org.ldaptive.BindOperation:168] - execute response=[org.ldaptive.Response at 81455065::result=null, resultCode=SUCCESS
, message=null, matchedDn=null, responseControls=[[org.ldaptive.control.PasswordPolicyControl at 159938469::criticality=false, timeBeforeExpiration=0,
graceAuthNsRemaining=0, error=CHANGE_AFTER_RESET]], referralURLs=null, messageId=-1] for request=[org.ldaptive.BindRequest at 1202371144::bindDn=uid=xxxxxx,ou=people,dc=umt,dc=edu, saslConfig=null, controls=[[org.ldaptive.control.PasswordPolicyControl at -350057371::criticality=false, timeBeforeExpiration=0, graceAuthNsRemaining=0, error=null]]] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection at 260634741::config=[org.ldap
tive.ConnectionConfig at 1845349421::ldapUrl=ldaps://example.umt.edu:636, connectTimeout=3000, responseTimeout=-1, sslConfig=[org.ldaptive.ssl.SslConf
ig at 1214272534::credentialConfig=net.shibboleth.idp.authn.impl.KeystoreResourceCredentialConfig at 4ca1c64e, trustManagers=null, enabledCipherSuites=nul
l, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=true, useStartTLS=false, connectionInitializer=null], providerConnectionFactory=
[org.ldaptive.provider.jndi.JndiConnectionFactory at 2131097089::metadata=[ldapUrl=ldaps://cidptest.umt.edu:636, count=1], environment={java.naming.lda
p.factory.socket=org.ldaptive.ssl.ThreadLocalTLSSocketFactory, com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.facto
ry.initial=com.sun.jndi.ldap.LdapCtxFactory, java.naming.security.protocol=ssl}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig at 12036
09377::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.ConnectionStrategies$Def
aultConnectionStrategy at 324998f5, controlProcessor=org.ldaptive.provider.ControlProcessor at 29e255d9, 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 at 3b08d257<mailto:Connection=org.ldaptive.provider.jndi.JndiConnection at 3b08d257>]

2016-12-12 13:13:23,105 - DEBUG [org.ldaptive.auth.PooledBindAuthenticationHandler:85] - authenticate response=[org.ldaptive.auth.AuthenticationHand
lerResponse at 1901772651::connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection at 260634741::config=[org.ldaptive.ConnectionConfig at 1845349
421::ldapUrl=ldaps://example.umt.edu:636, connectTimeout=3000, responseTimeout=-1, sslConfig=[org.ldaptive.ssl.SslConfig at 1214272534::credentialConf
ig=net.shibboleth.idp.authn.impl.KeystoreResourceCredentialConfig at 4ca1c64e, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, han
dshakeCompletedListeners=null], useSSL=true, useStartTLS=false, connectionInitializer=null], providerConnectionFactory=[org.ldaptive.provider.jndi.J
ndiConnectionFactory at 2131097089::metadata=[ldapUrl=ldaps://example.umt.edu:636, count=1], environment={java.naming.ldap.factory.socket=org.ldaptive
.ssl.ThreadLocalTLSSocketFactory, com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.
LdapCtxFactory, java.naming.security.protocol=ssl}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig at 1203609377::operationExceptionResu
ltCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.ConnectionStrategies$DefaultConnectionStrategy at 324998
f5, controlProcessor=org.ldaptive.provider.ControlProcessor at 29e255d9, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCode
s=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provi
der.jndi.JndiConnection at 3b08d257], result=true, resultCode=SUCCESS, message=null, controls=[[org.ldaptive.control.PasswordPolicyControl at 159938469::c
riticality=false, timeBeforeExpiration=0, graceAuthNsRemaining=0, error=CHANGE_AFTER_RESET]]] for criteria=[org.ldaptive.auth.AuthenticationCriteria
@1051329388::dn=uid=xxxxxx,ou=people,dc=umt,dc=edu, authenticationRequest=[org.ldaptive.auth.AuthenticationRequest at 850478646::user=[org.ldaptive.a
uth.User at 1890173199::identifier=xxxxxx, context=org.apache.velocity.VelocityContext at 3d31c60f], retAttrs=[umid]]]

2016-12-12 13:13:23,107 - DEBUG [org.ldaptive.auth.SearchEntryResolver:415] - resolve criteria=[org.ldaptive.auth.AuthenticationCriteria at 1051329388:
:dn=uid=xxxxxx,ou=people,dc=umt,dc=edu, authenticationRequest=[org.ldaptive.auth.AuthenticationRequest at 850478646::user=[org.ldaptive.auth.User at 1890173199::identifier=jo180287, context=org.apache.velocity.VelocityContext at 3d31c60f], retAttrs=[umid]]]

2016-12-12 13:13:23,107 - DEBUG [org.ldaptive.SearchOperation:138] - execute request=[org.ldaptive.SearchRequest at -742090779::baseDn=uid=xxxxxx,ou=people,dc=umt,dc=edu, searchFilter=[org.ldaptive.SearchFilter at 1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[umid], 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 at 260634741::config=[org.ldaptive.ConnectionConfig at 1845349421::ldapUrl=ldaps://example.umt.edu:636, connectTimeout=3000, responseTimeout=-1, sslConfig=[org.ldaptive.ssl.SslConfig at 1214272534::credentialConfig=net.shibboleth.idp.authn.impl.KeystoreResourceCredentialConfig at 4ca1c64e, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=true, useStartTLS=false, connectionInitializer=null], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory at 2131097089::metadata=[ldapUrl=ldaps://example.umt.edu:636, count=1], environment={java.naming.ldap.factory.socket=org.ldaptive.ssl.ThreadLocalTLSSocketFactory, com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory, java.naming.security.protocol=ssl}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig at 1203609377::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.ConnectionStrategies$DefaultConnectionStrategy at 324998f5, controlProcessor=org.ldaptive.provider.ControlProcessor at 29e255d9, 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 at 3b08d257<mailto:providerConnection=org.ldaptive.provider.jndi.JndiConnection at 3b08d257>]

2016-12-12 13:13:23,118 - DEBUG [org.ldaptive.auth.Authenticator:404] - entry resolution failed for resolver=[org.ldaptive.auth.SearchEntryResolver at 345806538::factory=null, baseDn=, userFilter=null, userFilterParameters=null, allowMultipleEntries=false, subtreeSearch=false, derefAliases=null, followReferrals=false, searchEntryHandlers=null]

2016-12-12 13:13:23,118 - DEBUG [org.ldaptive.auth.Authenticator:404] - entry resolution failed for resolver=[org.ldaptive.auth.SearchEntryResolver at 345806538::factory=null, baseDn=, userFilter=null, userFilterParameters=null, allowMultipleEntries=false, subtreeSearch=false, derefAliases=null, followReferrals=false, searchEntryHandlers=null]|
org.ldaptive.LdapException: javax.naming.NoPermissionException: [LDAP: error code 50 - Operations are restricted to bind/unbind/abandon/StartTLS/modify password]; remaining name 'uid=xxxxxx,ou=people,dc=umt,dc=edu'
        at org.ldaptive.provider.ProviderUtils.throwOperationException(ProviderUtils.java:77)
Caused by: javax.naming.NoPermissionException: [LDAP: error code 50 - Operations are restricted to bind/unbind/abandon/StartTLS/modify password]
        at com.sun.jndi.ldap.LdapCtx.mapErrorCode(LdapCtx.java:3144)

2016-12-12 13:13:23,118 - INFO [org.ldaptive.auth.Authenticator:282] - Authentication succeeded for dn: uid=xxxxxx,ou=people,dc=umt,dc=edu

2016-12-12 13:13:23,119 - DEBUG [org.ldaptive.auth.Authenticator:307] - authenticate response=[org.ldaptive.auth.AuthenticationHandlerResponse at 1901772651::connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection at 260634741::config=[org.ldaptive.ConnectionConfig at 1845349421::ldapUrl=ldaps://example.umt.edu:636, connectTimeout=3000, responseTimeout=-1, sslConfig=[org.ldaptive.ssl.SslConfig at 1214272534::credentialConfig=net.shibboleth.idp.authn.impl.KeystoreResourceCredentialConfig at 4ca1c64e, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=true, useStartTLS=false, connectionInitializer=null], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory at 2131097089::metadata=[ldapUrl=ldaps://example.umt.edu:636, count=1], environment={java.naming.ldap.factory.socket=org.ldaptive.ssl.ThreadLocalTLSSocketFactory, com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory, java.naming.security.protocol=ssl}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig at 1203609377::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.ConnectionStrategies$DefaultConnectionStrategy at 324998f5, controlProcessor=org.ldaptive.provider.ControlProcessor at 29e255d9, 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 at 3b08d257], result=true, resultCode=SUCCESS, message=null, controls=[[org.ldaptive.control.PasswordPolicyControl at 159938469::criticality=false, timeBeforeExpiration=0, graceAuthNsRemaining=0, error=CHANGE_AFTER_RESET]]] for dn=uid=jo180287,ou=people,dc=umt,dc=edu with request=[org.ldaptive.auth.AuthenticationRequest at 850478646::user=[org.ldaptive.auth.User at 1890173199::identifier=jo180287, context=org.apache.velocity.VelocityContext at 3d31c60f], retAttrs=[umid]]|10.10.18.162

2016-12-12 13:13:23,119 - TRACE [net.shibboleth.idp.authn.impl.ValidateUsernamePasswordAgainstLDAP:150] - Profile Action ValidateUsernamePasswordAgainstLDAP: Authentication response [org.ldaptive.auth.AuthenticationResponse at 1819759401::authenticationResultCode=AUTHENTICATION_HANDLER_SUCCESS, ldapEntry=[dn=uid=xxxxxx,ou=people,dc=umt,dc=edu[]], accountState=[org.ldaptive.auth.ext.PasswordPolicyAccountState at 481145515::accountWarnings=null, accountErrors=[CHANGE_AFTER_RESET]], result=true, resultCode=SUCCESS, message=null, controls=[[org.ldaptive.control.PasswordPolicyControl at 159938469::criticality=false, timeBeforeExpiration=0, graceAuthNsRemaining=0, error=CHANGE_AFTER_RESET]]]

2016-12-12 13:13:23,120 - INFO [net.shibboleth.idp.authn.impl.ValidateUsernamePasswordAgainstLDAP:152] - Profile Action ValidateUsernamePasswordAgainstLDAP: Login by 'xxxxxx' succeeded

Josh

From: users [mailto:users-bounces at shibboleth.net] On Behalf Of Daniel Fisher
Sent: Monday, December 12, 2016 12:52 PM
To: Shib Users <users at shibboleth.net>
Subject: Re: OpenLDAP Password Policy account state handling.

On Mon, Dec 12, 2016 at 12:41 PM, O'Dowd, Josh <Josh.O'Dowd at mso.umt.edu<mailto:Josh.O'Dowd at mso.umt.edu>> wrote:
So that is another problem in itself, I think…  that the return attributes are not fetched when there is an accountError within the account state.

Can you check your LDAP logs to confirm this? You should see the search for the umid attribute immediately after the bind. If you don't have access to the LDAP logs, you can also put the org.ldaptive package in DEBUG.

--Daniel Fisher

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://shibboleth.net/pipermail/users/attachments/20161212/2bcc4bd3/attachment-0001.html>