Problems with LDAP Connection Pool in LDAP Data Connectors

Dan McLaughlin dmclaughlin at tech-consortium.com
Wed Oct 10 04:08:44 EDT 2012 

We've starting using LDAP Connection Pooling for our LDAP Data
Connectors this week and we've started running into " no failover data
connector available" exceptions.

Netstat only shows a single connection to the LDAP server.  Has anyone
else seen issues with the LDAP Connection Pooling?

Here is my data connector:

 <resolver:DataConnector xsi:type="dc:LDAPDirectory"
    id="NOVELLEDIR"
    ldapURL="ldaps://ldap01:636 ldaps://ldap02:636 ldaps://ldap03:636"
    baseDN="T=MYTREE">

    <dc:FilterTemplate>
      <![CDATA[
      (&(cn=$requestContext.principalName)(objectclass=person))
      ]]>
    </dc:FilterTemplate>

    <dc:ReturnAttributes>GUID cn sn givenName mail
telephoneNumber</dc:ReturnAttributes>

    <dc:LDAPProperty name="java.naming.ldap.derefAliases" value="never"/>
    <dc:LDAPProperty name="java.naming.ldap.attributes.binary" value="GUID"/>
    <dc:LDAPProperty name="com.sun.jndi.ldap.connect.timeout" value="500"/>

    <dc:ConnectionPool minPoolSize="5"
                       maxPoolSize="10"
                       blockWhenEmpty="true"
                       blockWaitTime="PT5S"
                       validatePeriodically="true"
                       validateTimerPeriod="PT30M"
                       validateDN="o=AUS"
                       validateFilter="(o=AUS)"
                       expirationTime="PT10M" />

  </resolver:DataConnector>

Here are TRACE logs showing the logs leading up the error…


18:07:13.318 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:144]
- Begin initialize
18:07:13.318 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:180]
- useFirstPass = false
18:07:13.318 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:181]
- tryFirstPass = false
18:07:13.318 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:182]
- storePass = false
18:07:13.319 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:183]
- clearPass = false
18:07:13.319 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:184]
- setLdapPrincipal = true
18:07:13.319 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:185]
- setLdapDnPrincipal = false
18:07:13.319 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:186]
- setLdapCredential = true
18:07:13.319 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:187]
- defaultRole = []
18:07:13.319 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:188]
- principalGroupName = null
18:07:13.320 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:189]
- roleGroupName = null
18:07:13.320 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:77]
- userRoleAttribute = []
18:07:13.320 - TRACE
[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1385] - setting
searchScope: ONELEVEL
18:07:13.321 - TRACE
[edu.vt.middleware.ldap.auth.AuthenticatorConfig:427] - setting
subtreeSearch: true
18:07:13.321 - TRACE
[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1385] - setting
searchScope: SUBTREE
18:07:13.321 - TRACE
[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1370] - setting
baseDn: T=MYTREE
18:07:13.322 - TRACE
[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1834] - setting ssl:
true
18:07:13.322 - TRACE
[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1168] - setting
ldapUrl: ldap://ldap01:636 ldap://ldap02:636 ldap://ldap03:636
18:07:13.323 - TRACE
[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:93] - setting
connectionStrategy: ACTIVE_PASSIVE
18:07:13.323 - TRACE
[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1119] - setting
connectionHandler:
edu.vt.middleware.ldap.handler.DefaultConnectionHandler at fa67f2
18:07:13.323 - TRACE
[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1651] - setting
derefAliases: never
18:07:13.324 - TRACE
[edu.vt.middleware.ldap.auth.AuthenticatorConfig:290] - setting
userFilter: (&(cn={0})(objectclass=person))
18:07:13.324 - TRACE
[edu.vt.middleware.ldap.auth.AuthenticatorConfig:1260] - setting
timeout: 1000
18:07:13.324 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:83]
- Created authenticator:
edu.vt.middleware.ldap.auth.AuthenticatorConfig at 30042229::env={java.naming.provider.url=ldap://ldap01:636
ldap://ldap02:636 ldap://ldap03:636,
java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory,
com.sun.jndi.ldap.connect.timeout=1000,
java.naming.ldap.derefAliases=never,
java.naming.security.protocol=ssl}
18:07:13.325 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:412]
- Begin getCredentials
18:07:13.325 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:413]
-   useFistPass = false
18:07:13.325 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:414]
-   tryFistPass = false
18:07:13.325 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:415]
-   useCallback = false
18:07:13.325 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:416]
-   callbackhandler class =
javax.security.auth.login.LoginContext$SecureCallbackHandler
18:07:13.325 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:419]
-   name callback class = javax.security.auth.callback.NameCallback
18:07:13.326 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:421]
-   password callback class =
javax.security.auth.callback.PasswordCallback
18:07:13.326 - DEBUG
[edu.vt.middleware.ldap.auth.SearchDnResolver:102] - Looking up DN
using userFilter
18:07:13.326 - DEBUG
[edu.vt.middleware.ldap.auth.SearchDnResolver:193] - Search with the
following parameters:
18:07:13.326 - DEBUG
[edu.vt.middleware.ldap.auth.SearchDnResolver:194] -   dn = T=MYTREE
18:07:13.326 - DEBUG
[edu.vt.middleware.ldap.auth.SearchDnResolver:195] -   filter =
(&(cn={0})(objectclass=person))
18:07:13.326 - DEBUG
[edu.vt.middleware.ldap.auth.SearchDnResolver:196] -   filterArgs =
[myuser]
18:07:13.326 - DEBUG
[edu.vt.middleware.ldap.auth.SearchDnResolver:197] -   searchControls
= javax.naming.directory.SearchControls at 18fe272
18:07:13.327 - DEBUG
[edu.vt.middleware.ldap.auth.SearchDnResolver:198] -   handler =
[edu.vt.middleware.ldap.handler.FqdnSearchResultHandler at 15bebcb]
18:07:13.327 - TRACE
[edu.vt.middleware.ldap.auth.SearchDnResolver:200] -   config =
{java.naming.provider.url=ldap://ldap01:636 ldap://ldap02:636
ldap://ldap03:636,
java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory,
com.sun.jndi.ldap.connect.timeout=1000,
java.naming.ldap.derefAliases=never,
java.naming.security.protocol=ssl}
18:07:13.327 - TRACE
[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:93] - setting
connectionStrategy: ACTIVE_PASSIVE
18:07:13.327 - TRACE
[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:110] -
setting connectionRetryExceptions: [class
javax.naming.NamingException]
18:07:13.327 - TRACE
[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:152] - {0}
Attempting connection to ldap://ldap01:636 for strategy ACTIVE_PASSIVE
18:07:13.328 - DEBUG
[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:74] - Bind
with the following parameters:
18:07:13.328 - DEBUG
[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:75] -
authtype = simple
18:07:13.328 - DEBUG
[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:76] -   dn =
null
18:07:13.328 - DEBUG
[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:83] -
credential = <suppressed>
18:07:13.328 - TRACE
[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:87] -   env =
{java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory,
java.naming.provider.url=ldap://ldap01:636,
com.sun.jndi.ldap.connect.timeout=1000,
java.naming.ldap.derefAliases=never,
java.naming.security.protocol=ssl}
18:07:13.338 - DEBUG
[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:128] - Set
hostname verifier for ldaps
18:07:13.342 - DEBUG
[edu.vt.middleware.ldap.ssl.AggregateTrustManager:75] - invoking
checkServerTrusted for sun.security.ssl.X509TrustManagerImpl at 1d57cec
18:07:13.342 - DEBUG
[edu.vt.middleware.ldap.ssl.AggregateTrustManager:75] - invoking
checkServerTrusted for
edu.vt.middleware.ldap.ssl.HostnameVerifyingTrustManager at a31c7f
18:07:13.343 - DEBUG
[edu.vt.middleware.ldap.ssl.DefaultHostnameVerifier:122] - Verify with
the following parameters:
18:07:13.343 - DEBUG
[edu.vt.middleware.ldap.ssl.DefaultHostnameVerifier:123] -   hostname
= ldap01
18:07:13.343 - DEBUG
[edu.vt.middleware.ldap.ssl.DefaultHostnameVerifier:124] -   cert =
CN=ldap01, O=MYORG
18:07:13.343 - DEBUG
[edu.vt.middleware.ldap.ssl.DefaultHostnameVerifier:197] - verifyDNS
using subjectAltNames = []
18:07:13.343 - DEBUG
[edu.vt.middleware.ldap.ssl.DefaultHostnameVerifier:214] - verifyDNS
using CN = [ldap01]
18:07:13.344 - DEBUG
[edu.vt.middleware.ldap.ssl.DefaultHostnameVerifier:219] - verifyDNS
found hostname match: ldap01
18:07:13.344 - DEBUG
[edu.vt.middleware.ldap.ssl.AggregateTrustManager:90] - invoking
getAcceptedIssuers invoked for
sun.security.ssl.X509TrustManagerImpl at 1d57cec
18:07:13.344 - DEBUG
[edu.vt.middleware.ldap.ssl.AggregateTrustManager:90] - invoking
getAcceptedIssuers invoked for
edu.vt.middleware.ldap.ssl.HostnameVerifyingTrustManager at a31c7f
18:07:13.393 - TRACE
[edu.vt.middleware.ldap.handler.FqdnSearchResultHandler:83] -
processing non-relative dn:
ldap://ldap01:636/cn=MYUSER,ou=MY,ou=ORG,o=Div
18:07:13.394 - TRACE
[edu.vt.middleware.ldap.handler.FqdnSearchResultHandler:95] -
processed dn: cn=MYUSER,ou=MY,ou=ORG,o=Div
18:07:13.394 - TRACE
[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:93] - setting
connectionStrategy: ACTIVE_PASSIVE
18:07:13.394 - TRACE
[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:110] -
setting connectionRetryExceptions: [class
javax.naming.NamingException]
18:07:13.395 - TRACE
[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:152] - {1}
Attempting connection to ldap://ldap01:636 for strategy ACTIVE_PASSIVE
18:07:13.395 - DEBUG
[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:74] - Bind
with the following parameters:
18:07:13.395 - DEBUG
[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:75] -
authtype = simple
18:07:13.395 - DEBUG
[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:76] -   dn =
cn=MYUSER,ou=MY,ou=ORG,o=Div
18:07:13.395 - DEBUG
[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:83] -
credential = <suppressed>
18:07:13.395 - TRACE
[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:87] -   env =
{java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory,
java.naming.provider.url=ldap://ldap01:636,
com.sun.jndi.ldap.connect.timeout=1000,
java.naming.ldap.derefAliases=never,
java.naming.security.protocol=ssl}
18:07:13.405 - DEBUG
[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:128] - Set
hostname verifier for ldaps
18:07:13.411 - DEBUG
[edu.vt.middleware.ldap.ssl.AggregateTrustManager:75] - invoking
checkServerTrusted for sun.security.ssl.X509TrustManagerImpl at 1f4c3df
18:07:13.411 - DEBUG
[edu.vt.middleware.ldap.ssl.AggregateTrustManager:75] - invoking
checkServerTrusted for
edu.vt.middleware.ldap.ssl.HostnameVerifyingTrustManager at 95eac8
18:07:13.412 - DEBUG
[edu.vt.middleware.ldap.ssl.DefaultHostnameVerifier:122] - Verify with
the following parameters:
18:07:13.412 - DEBUG
[edu.vt.middleware.ldap.ssl.DefaultHostnameVerifier:123] -   hostname
= ldap01
18:07:13.412 - DEBUG
[edu.vt.middleware.ldap.ssl.DefaultHostnameVerifier:124] -   cert =
CN=ldap01, O=MYORG
18:07:13.412 - DEBUG
[edu.vt.middleware.ldap.ssl.DefaultHostnameVerifier:197] - verifyDNS
using subjectAltNames = []
18:07:13.412 - DEBUG
[edu.vt.middleware.ldap.ssl.DefaultHostnameVerifier:214] - verifyDNS
using CN = [ldap01]
18:07:13.413 - DEBUG
[edu.vt.middleware.ldap.ssl.DefaultHostnameVerifier:219] - verifyDNS
found hostname match: ldap01
18:07:13.413 - DEBUG
[edu.vt.middleware.ldap.ssl.AggregateTrustManager:90] - invoking
getAcceptedIssuers invoked for
sun.security.ssl.X509TrustManagerImpl at 1f4c3df
18:07:13.413 - DEBUG
[edu.vt.middleware.ldap.ssl.AggregateTrustManager:90] - invoking
getAcceptedIssuers invoked for
edu.vt.middleware.ldap.ssl.HostnameVerifyingTrustManager at 95eac8
18:07:13.458 - INFO
[edu.vt.middleware.ldap.jaas.JaasAuthenticator:176] - Authentication
succeeded for dn: cn=MYUSER,ou=MY,ou=ORG,o=Div
18:07:13.459 - DEBUG
[edu.vt.middleware.ldap.auth.SearchDnResolver:102] - Looking up DN
using userFilter
18:07:13.459 - DEBUG
[edu.vt.middleware.ldap.auth.SearchDnResolver:193] - Search with the
following parameters:
18:07:13.459 - DEBUG
[edu.vt.middleware.ldap.auth.SearchDnResolver:194] -   dn = T=MYTREE
18:07:13.459 - DEBUG
[edu.vt.middleware.ldap.auth.SearchDnResolver:195] -   filter =
(&(cn={0})(objectclass=person))
18:07:13.459 - DEBUG
[edu.vt.middleware.ldap.auth.SearchDnResolver:196] -   filterArgs =
[myuser]
18:07:13.460 - DEBUG
[edu.vt.middleware.ldap.auth.SearchDnResolver:197] -   searchControls
= javax.naming.directory.SearchControls at 9d48c4
18:07:13.460 - DEBUG
[edu.vt.middleware.ldap.auth.SearchDnResolver:198] -   handler =
[edu.vt.middleware.ldap.handler.FqdnSearchResultHandler at 15bebcb]
18:07:13.460 - TRACE
[edu.vt.middleware.ldap.auth.SearchDnResolver:200] -   config =
{java.naming.provider.url=ldap://ldap01:636 ldap://ldap02:636
ldap://ldap03:636,
java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory,
com.sun.jndi.ldap.connect.timeout=1000,
java.naming.ldap.derefAliases=never,
java.naming.security.protocol=ssl}
18:07:13.467 - TRACE
[edu.vt.middleware.ldap.handler.FqdnSearchResultHandler:83] -
processing non-relative dn:
ldap://ldap01:636/cn=MYUSER,ou=MY,ou=ORG,o=Div
18:07:13.468 - TRACE
[edu.vt.middleware.ldap.handler.FqdnSearchResultHandler:95] -
processed dn: cn=MYUSER,ou=MY,ou=ORG,o=Div
18:07:13.470 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:208]
- Begin commit
18:07:13.470 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:223]
- Committed the following principals: [myuser[]]
18:07:13.470 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:229]
- Committed the following roles: []
18:07:13.594 - INFO [Shibboleth-Access:74] -
20121009T230713Z|144.45.7.142|www.mysite.com:443|/profile/SAML2/Redirect/SSO|
18:07:13.598 - TRACE
[edu.vt.middleware.ldap.pool.BlockingLdapPool:103] - waiting on pool
lock for check out 0
18:07:13.598 - TRACE
[edu.vt.middleware.ldap.pool.BlockingLdapPool:114] - retrieve
available ldap object
18:07:13.598 - TRACE
[edu.vt.middleware.ldap.pool.BlockingLdapPool:209] - waiting on pool
lock for retrieve available 0
18:07:13.598 - TRACE
[edu.vt.middleware.ldap.pool.BlockingLdapPool:219] - retrieved
available ldap object:
edu.vt.middleware.ldap.Ldap at 12299583::config=edu.vt.middleware.ldap.LdapConfig at 19983350::env={java.naming.provider.url=ldaps://ldap01:636
ldaps://ldap02:636 ldaps://ldap03:636,
java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory,
com.sun.jndi.ldap.connect.timeout=500,
java.naming.ldap.derefAliases=never,
java.naming.ldap.attributes.binary=GUID}
18:07:13.599 - TRACE
[edu.vt.middleware.ldap.pool.DefaultLdapFactory:127] - no activator
configured
18:07:13.599 - DEBUG [edu.vt.middleware.ldap.Ldap:193] - Search with
the following parameters:
18:07:13.599 - DEBUG [edu.vt.middleware.ldap.Ldap:194] -   dn = T=MYTREE
18:07:13.599 - DEBUG [edu.vt.middleware.ldap.Ldap:195] -   filter =
(&(cn=myuser)(objectclass=person))
18:07:13.599 - DEBUG [edu.vt.middleware.ldap.Ldap:196] -   filterArgs = []
18:07:13.599 - DEBUG [edu.vt.middleware.ldap.Ldap:197] -
searchControls = javax.naming.directory.SearchControls at 22a718
18:07:13.600 - DEBUG [edu.vt.middleware.ldap.Ldap:198] -   handler =
[edu.vt.middleware.ldap.handler.FqdnSearchResultHandler at 2cffbe,
edu.vt.middleware.ldap.handler.EntryDnSearchResultHandler at 4a3a04,
edu.vt.middleware.ldap.handler.BinarySearchResultHandler at 126ec25]
18:07:13.600 - TRACE [edu.vt.middleware.ldap.Ldap:200] -   config =
{java.naming.provider.url=ldaps://ldap01:636 ldaps://ldap02:636
ldaps://ldap03:636,
java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory,
com.sun.jndi.ldap.connect.timeout=500,
java.naming.ldap.derefAliases=never,
java.naming.ldap.attributes.binary=GUID}
18:07:13.601 - TRACE
[edu.vt.middleware.ldap.pool.DefaultLdapFactory:146] - no passivator
configured
18:07:13.601 - TRACE
[edu.vt.middleware.ldap.pool.BlockingLdapPool:297] - waiting on pool
lock for check in 0
18:07:13.602 - TRACE
[edu.vt.middleware.ldap.pool.BlockingLdapPool:306] - returned active
ldap object: edu.vt.middleware.ldap.Ldap at 12299583::config=edu.vt.middleware.ldap.LdapConfig at 19983350::env={java.naming.provider.url=ldaps://ldap01:636
ldaps://ldap02:636 ldaps://ldap03:636,
java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory,
com.sun.jndi.ldap.connect.timeout=500,
java.naming.ldap.derefAliases=never,
java.naming.ldap.attributes.binary=GUID}
18:07:13.602 - ERROR
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:379]
- Received the following error from data connector NOVELLEDIR, no
failover data connector available
edu.internet2.middleware.shibboleth.common.attribute.resolver.AttributeResolutionException:
An error occurred when attempting to search the LDAP
        at edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector.searchLdap(LdapDataConnector.java:372)
~[shibboleth-common-1.3.5.jar:na]
        at edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector.resolve(LdapDataConnector.java:315)
~[shibboleth-common-1.3.5.jar:na]
        at edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector.resolve(LdapDataConnector.java:50)
~[shibboleth-common-1.3.5.jar:na]
        at edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.ContextualDataConnector.resolve(ContextualDataConnector.java:77)
~[shibboleth-common-1.3.5.jar:na]
        at edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.ContextualDataConnector.resolve(ContextualDataConnector.java:31)
~[shibboleth-common-1.3.5.jar:na]
        at edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver.resolveDataConnector(ShibbolethAttributeResolver.java:374)
[shibboleth-common-1.3.5.jar:na]
        at edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver.resolveDependencies(ShibbolethAttributeResolver.java:410)
[shibboleth-common-1.3.5.jar:na]
        at edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver.resolveAttribute(ShibbolethAttributeResolver.java:332)
[shibboleth-common-1.3.5.jar:na]
        at edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver.resolveAttributes(ShibbolethAttributeResolver.java:284)
[shibboleth-common-1.3.5.jar:na]
        at edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver.resolveAttributes(ShibbolethAttributeResolver.java:131)
[shibboleth-common-1.3.5.jar:na]
        at edu.internet2.middleware.shibboleth.common.attribute.provider.ShibbolethSAML2AttributeAuthority.getAttributes(ShibbolethSAML2AttributeAuthority.java:174)
[shibboleth-common-1.3.5.jar:na]
        at edu.internet2.middleware.shibboleth.common.attribute.provider.ShibbolethSAML2AttributeAuthority.getAttributes(ShibbolethSAML2AttributeAuthority.java:58)
[shibboleth-common-1.3.5.jar:na]
        at edu.internet2.middleware.shibboleth.idp.profile.saml2.AbstractSAML2ProfileHandler.resolveAttributes(AbstractSAML2ProfileHandler.java:476)
[shibboleth-identityprovider-2.3.6.jar:na]
        at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.completeAuthenticationRequest(SSOProfileHandler.java:298)
[shibboleth-identityprovider-2.3.6.jar:na]
        at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.processRequest(SSOProfileHandler.java:177)
[shibboleth-identityprovider-2.3.6.jar:na]
        at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.processRequest(SSOProfileHandler.java:88)
[shibboleth-identityprovider-2.3.6.jar:na]
        at edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet.service(ProfileRequestDispatcherServlet.java:84)
[shibboleth-common-1.3.5.jar:na]
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:722)
[servlet-api.jar:na]
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:305)
[catalina.jar:7.0.27]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
[catalina.jar:7.0.27]
        at edu.internet2.middleware.shibboleth.idp.util.NoCacheFilter.doFilter(NoCacheFilter.java:50)
[shibboleth-identityprovider-2.3.6.jar:na]
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)
[catalina.jar:7.0.27]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
[catalina.jar:7.0.27]
        at edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter.doFilter(IdPSessionFilter.java:81)
[shibboleth-identityprovider-2.3.6.jar:na]
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)
[catalina.jar:7.0.27]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
[catalina.jar:7.0.27]
        at edu.internet2.middleware.shibboleth.common.log.SLF4JMDCCleanupFilter.doFilter(SLF4JMDCCleanupFilter.java:52)
[shibboleth-common-1.3.5.jar:na]
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)
[catalina.jar:7.0.27]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
[catalina.jar:7.0.27]
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:208)
[catalina.jar:7.0.27]
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:169)
[catalina.jar:7.0.27]
        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:472)
[catalina.jar:7.0.27]
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:168)
[catalina.jar:7.0.27]
        at com.googlecode.psiprobe.Tomcat70AgentValve.invoke(Tomcat70AgentValve.java:38)
[tomcat70adaptor-2.3.2.jar:2.3.2]
        at org.apache.catalina.ha.session.JvmRouteBinderValve.invoke(JvmRouteBinderValve.java:219)
[catalina-ha.jar:7.0.27]
        at org.apache.catalina.ha.tcp.ReplicationValve.invoke(ReplicationValve.java:333)
[catalina-ha.jar:7.0.27]
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:98)
[catalina.jar:7.0.27]
        at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:927)
[catalina.jar:7.0.27]
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:118)
[catalina.jar:7.0.27]
        at org.apache.catalina.valves.RemoteIpValve.invoke(RemoteIpValve.java:680)
[catalina.jar:7.0.27]
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:407)
[catalina.jar:7.0.27]
        at org.apache.coyote.ajp.AjpAprProcessor.process(AjpAprProcessor.java:197)
[tomcat-coyote.jar:7.0.27]
        at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:565)
[tomcat-coyote.jar:7.0.27]
        at org.apache.tomcat.util.net.AprEndpoint$SocketProcessor.run(AprEndpoint.java:1812)
[tomcat-coyote.jar:7.0.27]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
[na:1.7.0_04]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
[na:1.7.0_04]
        at java.lang.Thread.run(Thread.java:722) [na:1.7.0_04]
18:07:13.603 - WARN
[edu.internet2.middleware.shibboleth.idp.profile.saml2.AbstractSAML2ProfileHandler:480]
- Error resolving attributes for principal 'myuser'.  No name
identifier or attribute statement will be included in response
18:07:13.637 - INFO [Shibboleth-Audit:989] -
20121009T230713Z|urn:oasis:names:tc:SAML:2.0:bindings:HTTP-Redirect|_2c1b9fc9b662dfa15878ac4e44facc5d|https://www.mysite.com/shibboleth|urn:mace:shibboleth:2.0:profiles:saml2:sso|https://www.mysite.com/idp/shibboleth|urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST|_3aa92cef4407cb7e2fdfd0a36372fb00|myuser|urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport||||


--

Thanks,

Dan McLaughlin

More information about the users mailing list