IDPv3.1.2 LDAP connector: using two distinct LDAP servers?

Fri Jul 1 18:01:22 EDT 2016

Here are some logs from scenario 1 with user ‘login1’ which only exists in our openLDAP instance.  The user has issues with the FormatDnResolver for Active Directory, as expected.
But, these FormatDnResolver issues seem to cause authentication to fail.  It seems to be doing a search against our openLDAP and a bind against our Active Directory.

2016-06-29 15:50:23,824 - DEBUG [org.springframework.webflow.execution.ActionExecutor:49] - Executing net.shibboleth.idp.authn.impl.ValidateUsernamePasswordAgainstLDAP at 1ef9e927<mailto:net.shibboleth.idp.authn.impl.ValidateUsernamePasswordAgainstLDAP at 1ef9e927>
2016-06-29 15:50:23,824 - DEBUG [net.shibboleth.idp.authn.impl.ValidateUsernamePasswordAgainstLDAP:131] - Profile Action ValidateUsernamePasswordAgainstLDAP: Attempting to authenticate user login1
2016-06-29 15:50:23,826 - DEBUG [org.ldaptive.auth.AggregateDnResolver:158] - submitted DN resolver [org.ldaptive.auth.PooledSearchDnResolver at 70985093::factory=[org.ldaptive.pool.PooledConnectionFactory at 750857363::pool=[org.ldaptive.pool.BlockingConnectionPool at 972662499::name=search-pool, poolConfig=[org.ldaptive.pool.PoolConfig at 263777208::minPoolSize=3, maxPoolSize=10, validateOnCheckIn=false, validateOnCheckOut=false, validatePeriodically=true, validatePeriod=300], activator=null, passivator=null, validator=[org.ldaptive.pool.SearchValidator at 1608024946::searchRequest=[org.ldaptive.SearchRequest at 1736332787::baseDn=, searchFilter=[org.ldaptive.SearchFilter at 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, followReferrals=false, intermediateResponseHandlers=null]] pruneStrategy=[org.ldaptive.pool.IdlePruneStrategy at 2091945142::prunePeriod=300, idleTime=600], connectOnCreate=true, connectionFactory=[org.ldaptive.DefaultConnectionFactory at 783558968::provider=org.ldaptive.provider.jndi.JndiProvider at 474d16e3, config=[org.ldaptive.ConnectionConfig at 1340261334::ldapUrl=ldap://open.ldap.domain.name:389, connectTimeout=3000, responseTimeout=-1, sslConfig=[org.ldaptive.ssl.SslConfig at 518795353::credentialConfig=net.shibboleth.idp.authn.impl.X509ResourceCredentialConfig at 3bd31309, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer at 1223147848::bindDn=cn=bindAccount,dc=domain1,dc=domain2, bindSaslConfig=null, bindControls=null]]], initialized=true, availableCount=3, activeCount=0]], baseDn=ou=oUnit,dc=domain1,dc=domain2, userFilter=(sn={user}), userFilterParameters=null, allowMultipleDns=false, subtreeSearch=true, derefAliases=null, followReferrals=false]
2016-06-29 15:50:23,826 - DEBUG [org.ldaptive.auth.PooledSearchDnResolver:244] - resolve user=login1
…
2016-06-29 15:50:23,827 - DEBUG [org.ldaptive.auth.AggregateDnResolver:158] - submitted DN resolver [org.ldaptive.auth.FormatDnResolver at 168467718::formatString=AD\%s, formatArgs=null, escapeUser=true]
…
2016-06-29 15:50:23,827 - DEBUG [org.ldaptive.auth.AggregateDnResolver:162] - waiting on DN resolver …
…
2016-06-29 15:50:23,834 - DEBUG [org.ldaptive.auth.FormatDnResolver:157] - Formatting DN for login1 with AD\%s
2016-06-29 15:50:23,835 - DEBUG [org.ldaptive.auth.AggregateDnResolver:165] - DN resolver …, availableCount=2, activeCount=1 … resolved dn adDirectory:AD\login1
…
2016-06-29 15:50:23,836 - DEBUG [org.ldaptive.SearchOperation:138] - execute request=[org.ldaptive.SearchRequest at -936973022::baseDn=ou=oUnit,dc=domain1,dc=domain2, searchFilter=[org.ldaptive.SearchFilter at -194221250::filter=(sn={user}), parameters={user=login1}], 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 at 1458652852::config=[org.ldaptive.ConnectionConfig at 1340261334::ldapUrl=ldap://open.ldap.domain.name:389, connectTimeout=3000, responseTimeout=-1, sslConfig=[org.ldaptive.ssl.SslConfig at 518795353::credentialConfig=net.shibboleth.idp.authn.impl.X509ResourceCredentialConfig at 3bd31309, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer at 1223147848::bindDn=cn=bindAccount,dc=domain1,dc=domain2, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory at 1306434347::metadata=[ldapUrl=ldap://open.ldap.domain.name:389, count=1], 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 at 2088272085::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.ConnectionStrategies$DefaultConnectionStrategy at 1738c37e, controlProcessor=org.ldaptive.provider.ControlProcessor at 508972a, 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 7a5eaace<mailto:providerConnection=org.ldaptive.provider.jndi.JndiConnection at 7a5eaace>]
…
2016-06-29 15:50:24,238 - DEBUG [org.ldaptive.SearchOperation:168] - execute response=[org.ldaptive.Response at 1413423838::result=[org.ldaptive.SearchResult at 154843235::entries=[[dn=cn=login1,ou=oUnit,dc=domain1,dc=domain2[], responseControls=null, messageId=-1]], references=[]], resultCode=SUCCESS, message=null, matchedDn=null, responseControls=null, referralURLs=null, messageId=-1] for request=[org.ldaptive.SearchRequest at -936973022::…
…
2016-06-29 15:50:24,240 - DEBUG [org.ldaptive.auth.AggregateDnResolver:165] - DN resolver [org.ldaptive.auth.FormatDnResolver at 168467718::formatString=AD\%s, formatArgs=null, escapeUser=true] resolved dn openLDAPDirectory:cn=login1,ou=oUnit,dc=domain1,dc=domain2
…
2016-06-29 15:50:24,242 - DEBUG [org.ldaptive.BindOperation:138] - execute request=[org.ldaptive.BindRequest at 928813590::bindDn=AD\login1, saslConfig=null, controls=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection at 1640130246::config=[org.ldaptive.ConnectionConfig at 378789712::ldapUrl=ldap://ad.domain.name:389, connectTimeout=3000, responseTimeout=-1, sslConfig=[org.ldaptive.ssl.SslConfig at 518795353::credentialConfig=net.shibboleth.idp.authn.impl.X509ResourceCredentialConfig at 3bd31309, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=false, useStartTLS=false, connectionInitializer=null], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory at 2135050842::metadata=[ldapUrl=ldap://ad.domain.name:389, count=1], 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 at 1001747042::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.ConnectionStrategies$DefaultConnectionStrategy at 1738c37e, controlProcessor=org.ldaptive.provider.ControlProcessor at 5dd8908d, 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 25b0833c]
2016-06-29 15:50:24,324 - DEBUG [org.ldaptive.auth.PooledBindAuthenticationHandler:85] - authenticate response=[org.ldaptive.auth.AuthenticationHandlerResponse at 963447754::…, result=false, resultCode=INVALID_CREDENTIALS, message=javax.naming.AuthenticationException: [LDAP: error code 49 - 80090308: LdapErr: DSID-0C0903D0, comment: AcceptSecurityContext error, data 52e, v2580^@], controls=null] for criteria=[org.ldaptive.auth.AuthenticationCriteria at 808830405::dn=AD\login1, authenticationRequest=[org.ldaptive.auth.AuthenticationRequest at 1838494916::user=login1, retAttrs=[*, +]]]
2016-06-29 15:50:24,324 - TRACE [org.ldaptive.auth.Authenticator:386] - resolved entry=[dn=AD\login1[]] with resolver=[org.ldaptive.auth.NoOpEntryResolver at 682793413]
…
2016-06-29 15:50:24,325 - INFO [org.ldaptive.auth.Authenticator:259] - Authentication failed for dn: adDirectory:AD\login1
2016-06-29 15:50:24,326 - DEBUG [org.ldaptive.auth.Authenticator:284] - authenticate response=[org.ldaptive.auth.AuthenticationHandlerResponse at 963447754::…, result=false, resultCode=INVALID_CREDENTIALS, message=javax.naming.AuthenticationException: [LDAP: error code 49 - 80090308: LdapErr: DSID-0C0903D0, comment: AcceptSecurityContext error, data 52e, v2580^@], controls=null] for dn=adDirectory:AD\login1 with request=[org.ldaptive.auth.AuthenticationRequest at 1838494916::user=login1, retAttrs=[*, +]]
2016-06-29 15:50:24,326 - TRACE [net.shibboleth.idp.authn.impl.ValidateUsernamePasswordAgainstLDAP:137] - Profile Action ValidateUsernamePasswordAgainstLDAP: Authentication response [org.ldaptive.auth.AuthenticationResponse at 1642715148::authenticationResultCode=AUTHENTICATION_HANDLER_FAILURE, ldapEntry=[dn=AD\login1[]], accountState=null, result=false, resultCode=INVALID_CREDENTIALS, message=javax.naming.AuthenticationException: [LDAP: error code 49 - 80090308: LdapErr: DSID-0C0903D0, comment: AcceptSecurityContext error, data 52e, v2580^@], controls=null]
2016-06-29 15:50:24,326 - INFO [net.shibboleth.idp.authn.impl.ValidateUsernamePasswordAgainstLDAP:152] - Profile Action ValidateUsernamePasswordAgainstLDAP: Login by 'login1' failed

From: users [mailto:users-bounces at shibboleth.net] On Behalf Of Daniel Fisher
Sent: Thursday, June 30, 2016 9:54 PM
To: Shib Users
Subject: Re: IDPv3.1.2 LDAP connector: using two distinct LDAP servers?

On Thu, Jun 30, 2016 at 7:42 PM, Raymond Gardner <r.gardner at ntta.com<mailto:r.gardner at ntta.com>> wrote:

Authentication for login1 fails:

o   Successful authentication against LDAP1

o   Failed authentication against LDAP2

Authentication for login2 succeeds:

o   Successful authentication against LDAP1 – I don’t understand this; this should not be successful as this user does not exist in this LDAP instance; I’m positive

o   Successful authentication against LDAP2

I'd have to see some logs to make sense of this. Only one bind should be occurring, so this is strange.
[Raymond Gardner] I tried sending more logs but your email server limits the size of emails to < 65K.  I’m not sure if there is something specific that I am missing.

Let me offer some snippets from my conf/authn/ldap-authn-config.xml file.  Any assistance will be greatly appreciated:

    <alias name="%{idp.authn.custom.LDAP.authenticator:aggregateAuthenticator}" alias="shibboleth.authn.custom.LDAP.authenticator" />

So are you setting the idp.authn.custom.LDAP.authenticator property or is the default being used?
[Raymond Gardner] Correct.  ‘idp.authn.custom.LDAP.authenticator’ is set in my conf/idp.properties file.  And, I set it to the same ‘aggregateAuthenticator’ value that is listed here as a default.

    <!—I set the ‘…-ref’ property to this new alias for the bean definition of ‘ValidateUsernamePasswordAgainstLDAP’  -->

Why did you make that change?
[Raymond Gardner] I made this change because I am supporting two different SPs with two different authentications.  SP1 uses the standard ‘adAuthenticator’ that Shibboleth provides.
I’m trying to also support SP2 which will need the ‘aggregateAuthenticator’.  So, I created a 2nd validate bean.  I have also created a 2nd password authentication flow.  So, any requests coming from SP2 uses the 2nd password authentication flow, which uses the 2nd validate bean, which uses the ‘aggregateAuthenticator’.  It all seems to flow correctly except for the LDAP binding and the authentication result.

--Daniel Fisher

****************************************************************
This email message is intended for the use of the person to whom it has been sent, and may contain information that is confidential or legally protected. If you are not the intended recipient or have received this message in error, you are not authorized to copy, distribute, or otherwise use this message or its attachments. Please notify the sender immediately by return e-mail and permanently delete this message and any attachments. NTT America makes no warranty that this email is error or virus free. Thank you.
****************************************************************

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