Login failes when trying to do a ldap lookup from idp3

Wed Nov 4 16:31:36 EST 2015

I've set up an IDP3 server and I am trying to authenticate against a
LDAP server. The ldap.properties looks like this: (aside from the
wrap-around)

# LDAP authentication configuration, see authn/ldap-authn-config.xml

## Authenticator strategy, either anonSearchAuthenticator,
bindSearchAuthenticator, directAuthenticator, adAuthenticator
#idp.authn.LDAP.authenticator  = anonSearchAuthenticator

## Connection properties ##

idp.authn.LDAP.ldapURL         = ldap://xxxxxx.villanova.edu:389
idp.authn.LDAP.useStartTLS                     = false
idp.authn.LDAP.useSSL                          = false
#idp.authn.LDAP.connectTimeout                  = 3000

## SSL configuration, either jvmTrust, certificateTrust, or
keyStoreTrust ##
#idp.authn.LDAP.sslConfig                       = certificateTrust
## If using certificateTrust above, set to the trusted certificate's
path
idp.authn.LDAP.trustCertificates =
{idp.home}/credentials/ldap-server.crt
## If using keyStoreTrust above, set to the truststore path
idp.authn.LDAP.trustStore                       =
{idp.home}/credentials/ldap-server.truststore

## Return attributes ##
idp.authn.LDAP.returnAttributes  = cn,businessCategory,mail

## DN resolution properties ##

# Search DN resolution, used by anonSearchAuthenticator,
bindSearchAuthenticator
# for AD: CN=Users,DC=example,DC=org
idp.authn.LDAP.baseDN                           = o=villanova.edu
#idp.authn.LDAP.subtreeSearch                   = false
idp.authn.LDAP.userFilter                       = (uid={user})
# bind search configuration
# for AD: idp.authn.LDAP.bindDN=adminuser at domain.com
idp.authn.LDAP.bindDN                           =
uid=xxxxxx,ou=xxxxxx,o=villanova.edu
idp.authn.LDAP.bindDNCredential                 = xxxxxx

# Format DN resolution, used by directAuthenticator, adAuthenticator
# for AD use idp.authn.LDAP.dnFormat=%s at domain.com
idp.authn.LDAP.dnFormat = uid=%s,ou=People,o=villanova.edu

# LDAP attribute configuration, see attribute-resolver.xml
idp.attribute.resolver.LDAP.ldapURL = %{idp.authn.LDAP.ldapURL}
idp.attribute.resolver.LDAP.baseDN  = %{idp.authn.LDAP.baseDN}
idp.attribute.resolver.LDAP.bindDN  = %{idp.authn.LDAP.bindDN}
idp.attribute.resolver.LDAP.bindDNCredential =
%{idp.authn.LDAP.bindDNCredential}
idp.attribute.resolver.LDAP.useStartTLS =
%{idp.authn.LDAP.useStartTLS:true}
idp.attribute.resolver.LDAP.trustCertificates =
%{idp.authn.LDAP.trustCertificates}

# LDAP pool configuration, used for both authn and DN resolution
#idp.pool.LDAP.minSize                          = 3
#idp.pool.LDAP.maxSize                          = 10
#idp.pool.LDAP.validateOnCheckout               = false
#idp.pool.LDAP.validatePeriodically             = true
#idp.pool.LDAP.validatePeriod                   = 300
#idp.pool.LDAP.prunePeriod                      = 300

        However,

The LDAP fails, but I don't see why. I've done ldap lookup against the
same ldap server from this server and it's successful. I know ldap is
working and this server is working. I don't see why it's not working
here. Here is the log snippet.

2015-11-04 14:54:48,394 - DEBUG
[net.shibboleth.idp.authn.AbstractExtractionAction:137] - Profile Action
ExtractUsernamePasswordFromFormRequest: Trimming whitespace of input
string 'xxxxxxxx'
2015-11-04 14:54:48,396 - DEBUG
[net.shibboleth.idp.authn.impl.ExtractUsernamePasswordFromFormRequest:140] - Profile Action ExtractUsernamePasswordFromFormRequest: Recording do-not-cache instruction in authentication context
2015-11-04 14:54:48,397 - DEBUG

[net.shibboleth.idp.authn.impl.ValidateUsernamePasswordAgainstLDAP:172]
- Profile Action ValidateUsernamePasswordAgainstLDAP: Attempting to
authenticate user xxxxxxxx
2015-11-04 14:54:48,397 - DEBUG
[org.ldaptive.auth.PooledSearchDnResolver:244] - resolve user=xxxxxxxx
2015-11-04 14:54:48,397 - DEBUG
[org.ldaptive.auth.PooledSearchDnResolver:310] - searching for DN using
userFilter
2015-11-04 14:54:48,397 - DEBUG [org.ldaptive.SearchOperation:138] -
execute
request=[org.ldaptive.SearchRequest at 1486053290::baseDn=o=villanova.edu,
searchFilter=[org.ldaptive.SearchFilter at -1501703986::filter=(uid={user}), parameters={user=xxxxxxxx}], returnAttributes=[1.1], searchScope=ONELEVEL, 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 72543088::config=[org.ldaptive.ConnectionConfig at 240400228::ldapUrl=ldap://xxxxxx.villanova.edu:389, connectTimeout=3000, responseTimeout=-1, sslConfig=[org.ldaptive.ssl.SslConfig at 1754690767::credentialConfig=net.shibboleth.idp.authn.impl.X509ResourceCredentialConfig at 71f0cce6, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=false, useStartTLS=false, connectionInitializer=null], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory at 1659547843::metadata=[ldapUrl=ldap://xxxxxx.villanova.edu: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 1294619885::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.ConnectionStrategies$DefaultConnectionStrategy at 1641718b, controlProcessor=org.ldaptive.provider.ControlProcessor at 61a10859, 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 567ad006]
2015-11-04 14:54:48,408 - DEBUG [org.ldaptive.SearchOperation:168] -
execute
response=[org.ldaptive.Response at 1231579928::result=[org.ldaptive.SearchResult at 4303153::entries=[], references=[]], resultCode=SUCCESS, message=null, matchedDn=null, responseControls=null, referralURLs=null, messageId=-1] for request=[org.ldaptive.SearchRequest at 1486053290::baseDn=o=villanova.edu, searchFilter=[org.ldaptive.SearchFilter at -1501703986::filter=(uid={user}), parameters={user=xxxxxxxx}], returnAttributes=[1.1], searchScope=ONELEVEL, 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 72543088::config=[org.ldaptive.ConnectionConfig at 240400228::ldapUrl=ldap://xxxxxx.villanova.edu:389, connectTimeout=3000, responseTimeout=-1, sslConfig=[org.ldaptive.ssl.SslConfig at 1754690767::credentialConfig=net.shibboleth.idp.authn.impl.X509ResourceCredentialConfig at 71f0cce6, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=false, useStartTLS=false, connectionInitializer=null], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory at 1659547843::metadata=[ldapUrl=ldap://xxxxxx.villanova.edu: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 1294619885::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.ConnectionStrategies$DefaultConnectionStrategy at 1641718b, controlProcessor=org.ldaptive.provider.ControlProcessor at 61a10859, 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 567ad006]
2015-11-04 14:54:48,409 - INFO
[org.ldaptive.auth.PooledSearchDnResolver:268] - search for
user=xxxxxxxx failed using
filter=[org.ldaptive.SearchFilter at -1501703986::filter=(uid={user}),
parameters={user=xxxxxxxx}]
2015-11-04 14:54:48,409 - DEBUG
[org.ldaptive.auth.PooledSearchDnResolver:279] - resolved dn=null for
user=xxxxxxxx
2015-11-04 14:54:48,410 - DEBUG [org.ldaptive.auth.Authenticator:236] -
authenticate dn=null with
request=[org.ldaptive.auth.AuthenticationRequest at 1412994711::user=xxxxxxxx, retAttrs=[cn, businessCategory, mail]] 
2015-11-04 14:54:48,410 - INFO
[net.shibboleth.idp.authn.impl.ValidateUsernamePasswordAgainstLDAP:192]
- Profile Action ValidateUsernamePasswordAgainstLDAP: Login by
'xxxxxxxx' failed
2015-11-04 14:54:48,429 - DEBUG
[net.shibboleth.idp.ui.context.RelyingPartyUIContext:310] - Returning
name from UIInfo 'TestShib Test SP'
2015-11-04 14:54:48,430 - DEBUG
[net.shibboleth.idp.ui.context.RelyingPartyUIContext:770] - Returning
logo from UIInfo, (253 x 88) : https://www.testshib.org/testshibtwo.jpg
2015-11-04 14:54:48,432 - DEBUG
[net.shibboleth.idp.ui.context.RelyingPartyUIContext:264] - Acceptable
Scheme 'https', returning value
'https://www.testshib.org/testshibtwo.jpg'

-- 
Christopher A. Washburn
Villanova University
800 Lancaster Ave
Villanova, PA 19085
(610) 519-4711