Random connection handler picks same ldap server every time
Joep Driesen
Joep.Driesen at kuleuven.be
Tue Oct 8 05:10:53 EDT 2013
Off course. Here is an ldap trace log of startup + 1 successful login attempt:
11:00:09.674 - WARN [edu.internet2.middleware.shibboleth.common.config.attribute.resolver.dataConnector.LdapDataConnectorBeanDefinitionParser:390] - [main:] - Data connection myLDAP: use of 'cacheResults' attribute is deprecated. Use <ResultCache> instead.
11:00:10.386 - TRACE [edu.vt.middleware.ldap.LdapConfig:1168] - [main:] - setting ldapUrl: ldaps://logonserver-1.example.com
11:00:10.387 - TRACE [edu.vt.middleware.ldap.LdapConfig:1370] - [main:] - setting baseDn: ou=people,dc=example,dc=com
11:00:10.387 - TRACE [edu.vt.middleware.ldap.LdapConfig:1401] - [main:] - setting authtype: simple
11:00:10.387 - TRACE [edu.vt.middleware.ldap.LdapConfig:1276] - [main:] - setting bindDn: cn=idp,ou=admins,dc=example,dc=com
11:00:10.389 - TRACE [edu.vt.middleware.ldap.LdapConfig:1309] - [main:] - setting bindCredential: <suppressed>
11:00:10.389 - TRACE [edu.vt.middleware.ldap.LdapConfig:1385] - [main:] - setting searchScope: SUBTREE
11:00:10.390 - TRACE [edu.vt.middleware.ldap.LdapConfig:1119] - [main:] - setting connectionHandler: edu.vt.middleware.ldap.handler.DefaultConnectionHandler at 22cb4138
11:00:10.390 - TRACE [edu.vt.middleware.ldap.LdapConfig:1433] - [main:] - setting timeLimit: 3000
11:00:10.390 - TRACE [edu.vt.middleware.ldap.LdapConfig:1448] - [main:] - setting countLimit: 1
11:00:10.491 - TRACE [edu.vt.middleware.ldap.LdapConfig:1683] - [main:] - setting searchResultsHandlers: [edu.vt.middleware.ldap.handler.FqdnSearchResultHandler at 31672113, edu.vt.middleware.ldap.handler.EntryDnSearchResultHandler at 69ac7fbb, edu.vt.middleware.ldap.handler.BinarySearchResultHandler at 3bf60430]
11:00:10.493 - TRACE [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:93] - [main:] - setting connectionStrategy: ACTIVE_PASSIVE
11:00:10.498 - TRACE [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:93] - [main:] - setting connectionStrategy: ACTIVE_PASSIVE
11:00:10.499 - TRACE [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:110] - [main:] - setting connectionRetryExceptions: [class javax.naming.NamingException]
11:00:10.500 - TRACE [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:152] - [main:] - {0} Attempting connection to ldaps://logonserver-1.example.com for strategy ACTIVE_PASSIVE
11:00:10.500 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:74] - [main:] - Bind with the following parameters:
11:00:10.500 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:75] - [main:] - authtype = simple
11:00:10.501 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:76] - [main:] - dn = cn=idp,ou=admins,dc=example,dc=com
11:00:10.501 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:83] - [main:] - credential = <suppressed>
11:00:10.501 - TRACE [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:87] - [main:] - env = {java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory, java.naming.provider.url=ldaps://logonserver-1.example.com}
11:00:10.668 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:128] - [main:] - Set hostname verifier for ldaps
11:00:10.765 - DEBUG [edu.vt.middleware.ldap.ssl.AggregateTrustManager:75] - [Thread-4:] - invoking checkServerTrusted for sun.security.ssl.X509TrustManagerImpl at 79424b7b
11:00:11.084 - DEBUG [edu.vt.middleware.ldap.ssl.AggregateTrustManager:75] - [Thread-4:] - invoking checkServerTrusted for edu.vt.middleware.ldap.ssl.HostnameVerifyingTrustManager at c33aa9b
11:00:11.085 - DEBUG [edu.vt.middleware.ldap.ssl.DefaultHostnameVerifier:122] - [Thread-4:] - Verify with the following parameters:
11:00:11.085 - DEBUG [edu.vt.middleware.ldap.ssl.DefaultHostnameVerifier:123] - [Thread-4:] - hostname = logonserver-1.example.com
11:00:11.085 - DEBUG [edu.vt.middleware.ldap.ssl.DefaultHostnameVerifier:124] - [Thread-4:] - cert = ---
11:00:11.096 - DEBUG [edu.vt.middleware.ldap.ssl.DefaultHostnameVerifier:197] - [Thread-4:] - verifyDNS using subjectAltNames = [---]
11:00:11.096 - DEBUG [edu.vt.middleware.ldap.ssl.DefaultHostnameVerifier:205] - [Thread-4:] - verifyDNS found hostname match: logonserver-1.example.com
11:00:11.164 - TRACE [edu.vt.middleware.ldap.pool.DefaultLdapFactory:123] - [main:] - destroyed ldap object: edu.vt.middleware.ldap.Ldap at 1820523433::config=edu.vt.middleware.ldap.LdapConfig at 1671237131::env={java.naming.provider.url=ldaps://logonserver-1.example.com, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}
11:00:11.181 - WARN [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.ComputedIDDataConnector:65] - [main:] - This data connector is deprecated. The StoredID data connector should be used in its place.
11:00:13.060 - TRACE [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:93] - [main:] - setting connectionStrategy: ACTIVE_PASSIVE
11:00:13.061 - TRACE [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:110] - [main:] - setting connectionRetryExceptions: [class javax.naming.NamingException]
11:00:13.062 - TRACE [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:152] - [main:] - {1} Attempting connection to ldaps://logonserver-1.example.com for strategy ACTIVE_PASSIVE
11:00:13.062 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:74] - [main:] - Bind with the following parameters:
11:00:13.062 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:75] - [main:] - authtype = simple
11:00:13.066 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:76] - [main:] - dn = cn=idp,ou=admins,dc=example,dc=com
11:00:13.067 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:83] - [main:] - credential = <suppressed>
11:00:13.067 - TRACE [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:87] - [main:] - env = {java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory, java.naming.provider.url=ldaps://logonserver-1.example.com}
11:00:13.118 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:128] - [main:] - Set hostname verifier for ldaps
11:00:13.133 - DEBUG [edu.vt.middleware.ldap.ssl.AggregateTrustManager:75] - [main:] - invoking checkServerTrusted for sun.security.ssl.X509TrustManagerImpl at 512fb063
11:00:13.141 - DEBUG [edu.vt.middleware.ldap.ssl.AggregateTrustManager:75] - [main:] - invoking checkServerTrusted for edu.vt.middleware.ldap.ssl.HostnameVerifyingTrustManager at 7fdb04ed
11:00:13.142 - DEBUG [edu.vt.middleware.ldap.ssl.DefaultHostnameVerifier:122] - [main:] - Verify with the following parameters:
11:00:13.148 - DEBUG [edu.vt.middleware.ldap.ssl.DefaultHostnameVerifier:123] - [main:] - hostname = logonserver-1.example.com
11:00:13.149 - DEBUG [edu.vt.middleware.ldap.ssl.DefaultHostnameVerifier:124] - [main:] - cert = ---
11:00:13.154 - DEBUG [edu.vt.middleware.ldap.ssl.DefaultHostnameVerifier:197] - [main:] - verifyDNS using subjectAltNames = [---]
11:00:13.159 - DEBUG [edu.vt.middleware.ldap.ssl.DefaultHostnameVerifier:205] - [main:] - verifyDNS found hostname match: logonserver-1.example.com
11:00:13.220 - TRACE [edu.vt.middleware.ldap.pool.DefaultLdapFactory:123] - [main:] - destroyed ldap object: edu.vt.middleware.ldap.Ldap at 1309334871::config=edu.vt.middleware.ldap.LdapConfig at 1671237131::env={java.naming.provider.url=ldaps://logonserver-1.example.com, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}
11:00:13.752 - WARN [edu.internet2.middleware.shibboleth.common.config.attribute.filtering.AttributeFilterPolicyBeanDefinitionParser:62] - [main:] - AttributeFilterPolicy elements should include an 'id' attribute. This is not currently required but will be in future versions.
11:00:29.538 - INFO [Shibboleth-Access:74] - [TP-Processor3:] - 20131008T090029Z|10.32.129.216|idp.t.example.com:443|/profile/SAML2/Redirect/SSO|
11:00:36.440 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:144] - [TP-Processor1:] - Begin initialize
11:00:36.551 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:180] - [TP-Processor1:] - useFirstPass = false
11:00:36.551 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:181] - [TP-Processor1:] - tryFirstPass = false
11:00:36.552 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:182] - [TP-Processor1:] - storePass = false
11:00:36.552 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:183] - [TP-Processor1:] - clearPass = false
11:00:36.552 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:184] - [TP-Processor1:] - setLdapPrincipal = false
11:00:36.553 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:185] - [TP-Processor1:] - setLdapDnPrincipal = false
11:00:36.553 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:186] - [TP-Processor1:] - setLdapCredential = true
11:00:36.553 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:187] - [TP-Processor1:] - defaultRole = []
11:00:36.554 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:188] - [TP-Processor1:] - principalGroupName = null
11:00:36.554 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:189] - [TP-Processor1:] - roleGroupName = null
11:00:36.555 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:77] - [TP-Processor1:] - userRoleAttribute = []
11:00:36.585 - TRACE [edu.vt.middleware.ldap.auth.AuthenticatorConfig:1385] - [TP-Processor1:] - setting searchScope: ONELEVEL
11:00:36.609 - TRACE [edu.vt.middleware.ldap.auth.AuthenticatorConfig:427] - [TP-Processor1:] - setting subtreeSearch: true
11:00:36.612 - TRACE [edu.vt.middleware.ldap.auth.AuthenticatorConfig:1385] - [TP-Processor1:] - setting searchScope: SUBTREE
11:00:36.613 - TRACE [edu.vt.middleware.ldap.auth.AuthenticatorConfig:1370] - [TP-Processor1:] - setting baseDn: dc=example,dc=com
11:00:36.614 - TRACE [edu.vt.middleware.ldap.auth.AuthenticatorConfig:1834] - [TP-Processor1:] - setting ssl: true
11:00:36.616 - TRACE [edu.vt.middleware.ldap.auth.AuthenticatorConfig:1168] - [TP-Processor1:] - setting ldapUrl: ldaps://logonserver-1.example.com:636 ldaps://logonserver-2.example.com:636
11:00:36.679 - TRACE [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:93] - [TP-Processor1:] - setting connectionStrategy: RANDOM
11:00:36.682 - TRACE [edu.vt.middleware.ldap.auth.AuthenticatorConfig:1119] - [TP-Processor1:] - setting connectionHandler: edu.vt.middleware.ldap.handler.DefaultConnectionHandler at 27f899e9
11:00:36.687 - TRACE [edu.vt.middleware.ldap.auth.AuthenticatorConfig:1276] - [TP-Processor1:] - setting bindDn: cn=idp,ou=admins,dc=example,dc=com
11:00:36.688 - TRACE [edu.vt.middleware.ldap.auth.AuthenticatorConfig:290] - [TP-Processor1:] - setting userFilter: uid={0}
11:00:36.689 - TRACE [edu.vt.middleware.ldap.auth.AuthenticatorConfig:1309] - [TP-Processor1:] - setting bindCredential: <suppressed>
11:00:36.693 - TRACE [edu.vt.middleware.ldap.auth.AuthenticatorConfig:1119] - [TP-Processor1:] - setting connectionHandler: edu.vt.middleware.ldap.handler.DefaultConnectionHandler at 3240a47f
11:00:36.701 - TRACE [edu.vt.middleware.ldap.auth.AuthenticatorConfig:1260] - [TP-Processor1:] - setting timeout: 1000
11:00:39.914 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:83] - [TP-Processor1:] - Created authenticator: edu.vt.middleware.ldap.auth.AuthenticatorConfig at 226438572::env={java.naming.provider.url=ldaps://logonserver-1.example.com:636 ldaps://logonserver-2.example.com:636, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory, com.sun.jndi.ldap.connect.timeout=1000, java.naming.security.protocol=ssl}
11:00:39.925 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:412] - [TP-Processor1:] - Begin getCredentials
11:00:39.926 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:413] - [TP-Processor1:] - useFistPass = false
11:00:39.926 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:414] - [TP-Processor1:] - tryFistPass = false
11:00:39.927 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:415] - [TP-Processor1:] - useCallback = false
11:00:39.928 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:416] - [TP-Processor1:] - callbackhandler class = javax.security.auth.login.LoginContext$SecureCallbackHandler
11:00:39.929 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:419] - [TP-Processor1:] - name callback class = javax.security.auth.callback.NameCallback
11:00:39.929 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:421] - [TP-Processor1:] - password callback class = javax.security.auth.callback.PasswordCallback
11:00:39.960 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:102] - [TP-Processor1:] - Looking up DN using userFilter
11:00:39.966 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:193] - [TP-Processor1:] - Search with the following parameters:
11:00:39.966 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:194] - [TP-Processor1:] - dn = dc=example,dc=com
11:00:39.967 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:195] - [TP-Processor1:] - filter = uid={0}
11:00:39.968 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:196] - [TP-Processor1:] - filterArgs = [testuser]
11:00:39.972 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:197] - [TP-Processor1:] - searchControls = javax.naming.directory.SearchControls at 3957f3a4
11:00:39.973 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:198] - [TP-Processor1:] - handler = [edu.vt.middleware.ldap.handler.FqdnSearchResultHandler at 3d3cb165]
11:00:39.974 - TRACE [edu.vt.middleware.ldap.auth.SearchDnResolver:200] - [TP-Processor1:] - config = {java.naming.provider.url=ldaps://logonserver-1.example.com:636 ldaps://logonserver-2.example.com:636, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory, com.sun.jndi.ldap.connect.timeout=1000, java.naming.security.protocol=ssl}
11:00:39.975 - TRACE [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:93] - [TP-Processor1:] - setting connectionStrategy: DEFAULT
11:00:39.977 - TRACE [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:110] - [TP-Processor1:] - setting connectionRetryExceptions: [class javax.naming.NamingException]
11:00:39.980 - TRACE [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:152] - [TP-Processor1:] - {0} Attempting connection to ldaps://logonserver-1.example.com:636 ldaps://logonserver-2.example.com:636 for strategy DEFAULT
11:00:39.982 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:74] - [TP-Processor1:] - Bind with the following parameters:
11:00:39.984 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:75] - [TP-Processor1:] - authtype = simple
11:00:39.985 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:76] - [TP-Processor1:] - dn = cn=idp,ou=admins,dc=example,dc=com
11:00:39.986 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:83] - [TP-Processor1:] - credential = <suppressed>
11:00:39.987 - TRACE [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:87] - [TP-Processor1:] - env = {java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory, java.naming.provider.url=ldaps://logonserver-1.example.com:636 ldaps://logonserver-2.example.com:636, com.sun.jndi.ldap.connect.timeout=1000, java.naming.security.protocol=ssl}
11:00:40.014 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:128] - [TP-Processor1:] - Set hostname verifier for ldaps
11:00:40.038 - DEBUG [edu.vt.middleware.ldap.ssl.AggregateTrustManager:75] - [TP-Processor1:] - invoking checkServerTrusted for sun.security.ssl.X509TrustManagerImpl at d1a9f20
11:00:40.042 - DEBUG [edu.vt.middleware.ldap.ssl.AggregateTrustManager:75] - [TP-Processor1:] - invoking checkServerTrusted for edu.vt.middleware.ldap.ssl.HostnameVerifyingTrustManager at 5af92541
11:00:40.044 - DEBUG [edu.vt.middleware.ldap.ssl.DefaultHostnameVerifier:122] - [TP-Processor1:] - Verify with the following parameters:
11:00:40.045 - DEBUG [edu.vt.middleware.ldap.ssl.DefaultHostnameVerifier:123] - [TP-Processor1:] - hostname = logonserver-1.example.com
11:00:40.047 - DEBUG [edu.vt.middleware.ldap.ssl.DefaultHostnameVerifier:124] - [TP-Processor1:] - cert = ---
11:00:40.048 - DEBUG [edu.vt.middleware.ldap.ssl.DefaultHostnameVerifier:197] - [TP-Processor1:] - verifyDNS using subjectAltNames = [---]
11:00:40.049 - DEBUG [edu.vt.middleware.ldap.ssl.DefaultHostnameVerifier:205] - [TP-Processor1:] - verifyDNS found hostname match: logonserver-1.example.com
11:00:40.140 - TRACE [edu.vt.middleware.ldap.handler.FqdnSearchResultHandler:69] - [TP-Processor1:] - processing relative dn: uid=testuser,ou=people
11:00:40.141 - TRACE [edu.vt.middleware.ldap.handler.FqdnSearchResultHandler:95] - [TP-Processor1:] - processed dn: uid=testuser,ou=people,dc=example,dc=com
11:00:40.142 - TRACE [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:93] - [TP-Processor1:] - setting connectionStrategy: DEFAULT
11:00:40.143 - TRACE [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:110] - [TP-Processor1:] - setting connectionRetryExceptions: [class javax.naming.NamingException]
11:00:40.145 - TRACE [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:152] - [TP-Processor1:] - {1} Attempting connection to ldaps://logonserver-1.example.com:636 ldaps://logonserver-2.example.com:636 for strategy DEFAULT
11:00:40.146 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:74] - [TP-Processor1:] - Bind with the following parameters:
11:00:40.148 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:75] - [TP-Processor1:] - authtype = simple
11:00:40.149 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:76] - [TP-Processor1:] - dn = uid=testuser,ou=people,dc=example,dc=com
11:00:40.151 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:83] - [TP-Processor1:] - credential = <suppressed>
11:00:40.154 - TRACE [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:87] - [TP-Processor1:] - env = {java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory, java.naming.provider.url=ldaps://logonserver-1.example.com:636 ldaps://logonserver-2.example.com:636, com.sun.jndi.ldap.connect.timeout=1000, java.naming.security.protocol=ssl}
11:00:40.169 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:128] - [TP-Processor1:] - Set hostname verifier for ldaps
11:00:40.174 - DEBUG [edu.vt.middleware.ldap.ssl.AggregateTrustManager:75] - [TP-Processor1:] - invoking checkServerTrusted for sun.security.ssl.X509TrustManagerImpl at 1f2a45c7
11:00:40.176 - DEBUG [edu.vt.middleware.ldap.ssl.AggregateTrustManager:75] - [TP-Processor1:] - invoking checkServerTrusted for edu.vt.middleware.ldap.ssl.HostnameVerifyingTrustManager at 4896b555
11:00:40.176 - DEBUG [edu.vt.middleware.ldap.ssl.DefaultHostnameVerifier:122] - [TP-Processor1:] - Verify with the following parameters:
11:00:40.176 - DEBUG [edu.vt.middleware.ldap.ssl.DefaultHostnameVerifier:123] - [TP-Processor1:] - hostname = logonserver-1.example.com
11:00:40.177 - DEBUG [edu.vt.middleware.ldap.ssl.DefaultHostnameVerifier:124] - [TP-Processor1:] - cert = CN=---
11:00:40.177 - DEBUG [edu.vt.middleware.ldap.ssl.DefaultHostnameVerifier:197] - [TP-Processor1:] - verifyDNS using subjectAltNames = [---]
11:00:40.177 - DEBUG [edu.vt.middleware.ldap.ssl.DefaultHostnameVerifier:205] - [TP-Processor1:] - verifyDNS found hostname match: logonserver-1.example.com
11:00:40.221 - INFO [edu.vt.middleware.ldap.jaas.JaasAuthenticator:176] - [TP-Processor1:] - Authentication succeeded for dn: uid=testuser,ou=people,dc=example,dc=com
11:00:40.223 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:102] - [TP-Processor1:] - Looking up DN using userFilter
11:00:40.224 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:193] - [TP-Processor1:] - Search with the following parameters:
11:00:40.224 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:194] - [TP-Processor1:] - dn = dc=example,dc=com
11:00:40.224 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:195] - [TP-Processor1:] - filter = uid={0}
11:00:40.224 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:196] - [TP-Processor1:] - filterArgs = [testuser]
11:00:40.225 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:197] - [TP-Processor1:] - searchControls = javax.naming.directory.SearchControls at 46380c76
11:00:40.225 - DEBUG [edu.vt.middleware.ldap.auth.SearchDnResolver:198] - [TP-Processor1:] - handler = [edu.vt.middleware.ldap.handler.FqdnSearchResultHandler at 3d3cb165]
11:00:40.225 - TRACE [edu.vt.middleware.ldap.auth.SearchDnResolver:200] - [TP-Processor1:] - config = {java.naming.provider.url=ldaps://logonserver-1.example.com:636 ldaps://logonserver-2.example.com:636, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory, com.sun.jndi.ldap.connect.timeout=1000, java.naming.security.protocol=ssl}
11:00:40.228 - TRACE [edu.vt.middleware.ldap.handler.FqdnSearchResultHandler:69] - [TP-Processor1:] - processing relative dn: uid=testuser,ou=people
11:00:40.229 - TRACE [edu.vt.middleware.ldap.handler.FqdnSearchResultHandler:95] - [TP-Processor1:] - processed dn: uid=testuser,ou=people,dc=example,dc=com
11:00:40.234 - TRACE [edu.vt.middleware.ldap.jaas.LdapLoginModule:208] - [TP-Processor1:] - Begin commit
11:00:40.235 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:223] - [TP-Processor1:] - Committed the following principals: []
11:00:40.235 - DEBUG [edu.vt.middleware.ldap.jaas.LdapLoginModule:229] - [TP-Processor1:] - Committed the following roles: []
11:00:40.377 - INFO [Shibboleth-Access:74] - [TP-Processor6:] - 20131008T090040Z|10.32.129.216|idp.t.example.com:443|/profile/SAML2/Redirect/SSO|
11:00:40.485 - TRACE [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:93] - [TP-Processor6:] - setting connectionStrategy: ACTIVE_PASSIVE
11:00:40.486 - TRACE [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:110] - [TP-Processor6:] - setting connectionRetryExceptions: [class javax.naming.NamingException]
11:00:40.487 - TRACE [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:152] - [TP-Processor6:] - {2} Attempting connection to ldaps://logonserver-1.example.com for strategy ACTIVE_PASSIVE
11:00:40.487 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:74] - [TP-Processor6:] - Bind with the following parameters:
11:00:40.488 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:75] - [TP-Processor6:] - authtype = simple
11:00:40.489 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:76] - [TP-Processor6:] - dn = cn=idp,ou=admins,dc=example,dc=com
11:00:40.489 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:83] - [TP-Processor6:] - credential = <suppressed>
11:00:40.490 - TRACE [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:87] - [TP-Processor6:] - env = {java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory, java.naming.provider.url=ldaps://logonserver-1.example.com}
11:00:40.514 - DEBUG [edu.vt.middleware.ldap.handler.DefaultConnectionHandler:128] - [TP-Processor6:] - Set hostname verifier for ldaps
11:00:40.525 - DEBUG [edu.vt.middleware.ldap.ssl.AggregateTrustManager:75] - [TP-Processor6:] - invoking checkServerTrusted for sun.security.ssl.X509TrustManagerImpl at 621f6c18
11:00:40.529 - DEBUG [edu.vt.middleware.ldap.ssl.AggregateTrustManager:75] - [TP-Processor6:] - invoking checkServerTrusted for edu.vt.middleware.ldap.ssl.HostnameVerifyingTrustManager at 219baf0b
11:00:40.530 - DEBUG [edu.vt.middleware.ldap.ssl.DefaultHostnameVerifier:122] - [TP-Processor6:] - Verify with the following parameters:
11:00:40.531 - DEBUG [edu.vt.middleware.ldap.ssl.DefaultHostnameVerifier:123] - [TP-Processor6:] - hostname = logonserver-1.example.com
11:00:40.532 - DEBUG [edu.vt.middleware.ldap.ssl.DefaultHostnameVerifier:124] - [TP-Processor6:] - cert = ---
11:00:40.533 - DEBUG [edu.vt.middleware.ldap.ssl.DefaultHostnameVerifier:197] - [TP-Processor6:] - verifyDNS using subjectAltNames = [---]
11:00:40.541 - DEBUG [edu.vt.middleware.ldap.ssl.DefaultHostnameVerifier:205] - [TP-Processor6:] - verifyDNS found hostname match: logonserver-1.example.com
11:00:40.600 - DEBUG [edu.vt.middleware.ldap.Ldap:193] - [TP-Processor6:] - Search with the following parameters:
11:00:40.602 - DEBUG [edu.vt.middleware.ldap.Ldap:194] - [TP-Processor6:] - dn = ou=people,dc=example,dc=com
11:00:40.603 - DEBUG [edu.vt.middleware.ldap.Ldap:195] - [TP-Processor6:] - filter = (uid=testuser)
11:00:40.604 - DEBUG [edu.vt.middleware.ldap.Ldap:196] - [TP-Processor6:] - filterArgs = []
11:00:40.605 - DEBUG [edu.vt.middleware.ldap.Ldap:197] - [TP-Processor6:] - searchControls = javax.naming.directory.SearchControls at 51274873
11:00:40.606 - DEBUG [edu.vt.middleware.ldap.Ldap:198] - [TP-Processor6:] - handler = [edu.vt.middleware.ldap.handler.FqdnSearchResultHandler at 31672113, edu.vt.middleware.ldap.handler.EntryDnSearchResultHandler at 69ac7fbb, edu.vt.middleware.ldap.handler.BinarySearchResultHandler at 3bf60430]
11:00:40.607 - TRACE [edu.vt.middleware.ldap.Ldap:200] - [TP-Processor6:] - config = {java.naming.provider.url=ldaps://logonserver-1.example.com, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}
11:00:40.657 - TRACE [edu.vt.middleware.ldap.handler.FqdnSearchResultHandler:69] - [TP-Processor6:] - processing relative dn: uid=testuser
11:00:40.658 - TRACE [edu.vt.middleware.ldap.handler.FqdnSearchResultHandler:95] - [TP-Processor6:] - processed dn: uid=testuser,ou=people,dc=example,dc=com
11:00:40.676 - TRACE [edu.vt.middleware.ldap.pool.DefaultLdapFactory:123] - [TP-Processor6:] - destroyed ldap object: edu.vt.middleware.ldap.Ldap at 1582868867::config=edu.vt.middleware.ldap.LdapConfig at 1671237131::env={java.naming.provider.url=ldaps://logonserver-1.example.com, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}
It seems he is setting the connection strategy to RANDOM, but then overriding it to DEFAULT after... Seems a bit weird.
Regards,
Joep
-----Original Message-----
From: users-bounces at shibboleth.net [mailto:users-bounces at shibboleth.net] On Behalf Of Daniel Fisher
Sent: maandag 7 oktober 2013 5:36
To: Shib Users
Subject: Re: Random connection handler picks same ldap server every time
On Mon, Oct 7, 2013 at 2:41 AM, Joep Driesen <Joep.Driesen at kuleuven.be> wrote:
> Hi all,
>
> I am trying to setup an Active-Active configuration using a jaas login.conf file. Currently my setup is as follows:
>
> ShibUserPassAuth {
>
> edu.vt.middleware.ldap.jaas.LdapLoginModule required
> ldapUrl="ldaps://ldap1.example.com:636 ldaps://ldap2.example.com:636"
> ssl="true"
> connectionHandler="edu.vt.middleware.ldap.handler.DefaultConnectionHandler{{connectionStrategy=RANDOM}}"
> timeout="1000"
> baseDn="---"
> bindDn="---"
> bindCredential="---"
> tls="false"
> userFilter="uid={0}"
> setLdapPrincipal="false"
> subtreeSearch="true"
> ;
>
> };
>
> It seems shibboleth always picks the first LDAP server for authentication, whereas I would like it to switch between both servers. I'm not sure how to troubleshoot this, so any advice would be welcome.
>
> I have made sure that both LDAP servers work correctly when used on their own, so that should not be the problem...
Can you provide some TRACE logging for the edu.vt.middleware.ldap package?
--Daniel Fisher
--
To unsubscribe from this list send an email to users-unsubscribe at shibboleth.net
More information about the users
mailing list