Extremely slow IdP login

[Martin Haase]

Hi list,

we encountered an instance where UsernamePassword login and attribute
retrieval with the IdP is extremely slow. The whole login procedure
takes longer than one minute, which is not acceptable.

Environment:
IdP 2.3.6
Tomcat 6.0.35-1+squeeze2
openjdk-6-jre 6b18-1.8.13-0+squeeze1
Debian 6.0.5
Login and attributes from a Novell eDirectory, LDAPS (version unknown,
maintainer currently unavailable)

Relevant details from the log, level ALL, note the times:

[First, some 24 sec for Authentication...]

11:01:42.119 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:170]
- Attempting to authenticate user test
[...]
11:01:42.131 - DEBUG
[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:128] - Set
hostname verifier for ldaps
11:01:42.139 - DEBUG
[edu.vt.middleware.ldap.ssl.AggregateTrustManager:75] - invoking
checkServerTrusted for sun.security.ssl.X509TrustManagerImpl at 50ef8db9
11:01:42.143 - DEBUG
[edu.vt.middleware.ldap.ssl.AggregateTrustManager:75] - invoking
checkServerTrusted for
edu.vt.middleware.ldap.ssl.HostnameVerifyingTrustManager at 23fd55f6
11:01:42.144 - DEBUG
[edu.vt.middleware.ldap.ssl.DefaultHostnameVerifier:122] - Verify with
the following parameters:
11:01:42.144 - DEBUG
[edu.vt.middleware.ldap.ssl.DefaultHostnameVerifier:123] -   hostname =
ldap.example.de
11:01:42.144 - DEBUG
[edu.vt.middleware.ldap.ssl.DefaultHostnameVerifier:124] -   cert =
CN=ldap.example.de, O=Example, C=DE
11:01:42.144 - DEBUG
[edu.vt.middleware.ldap.ssl.DefaultHostnameVerifier:197] - verifyDNS
using subjectAltNames = []
11:01:42.145 - DEBUG
[edu.vt.middleware.ldap.ssl.DefaultHostnameVerifier:214] - verifyDNS
using CN = [ldap.example.de]
11:01:42.145 - DEBUG
[edu.vt.middleware.ldap.ssl.DefaultHostnameVerifier:219] - verifyDNS
found hostname match: ldap.example.de
11:01:50.368 - TRACE
[edu.vt.middleware.ldap.handler.FqdnSearchResultHandler:69] - processing
relative dn: cn=test,ou=xyz
11:01:50.368 - TRACE
[edu.vt.middleware.ldap.handler.FqdnSearchResultHandler:95] - processed
dn: cn=test,ou=xyz,o=example
11:02:06.930 - TRACE
[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:93] - setting
connectionStrategy: DEFAULT
11:02:06.930 - TRACE
[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:110] - setting
connectionRetryExceptions: [class javax.naming.NamingException]
11:02:06.931 - TRACE
[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:152] - {1}
Attempting connection to ldaps://ldap.example.de:636 for strategy DEFAULT
11:02:06.931 - DEBUG
[edu.vt.middleware.ldap.handler.DefaultConnectionHandler:74] - Bind with
the following parameters:

[and then, after some acceptable 4 seconds, TWICE an inacceptable 24
seconds delay...]

11:02:10.506 - DEBUG
[edu.vt.middleware.ldap.ssl.DefaultHostnameVerifier:219] - verifyDNS
found hostname match: ldap.example.de
11:02:10.825 - DEBUG [edu.vt.middleware.ldap.Ldap:193] - Search with the
following parameters:
11:02:10.825 - DEBUG [edu.vt.middleware.ldap.Ldap:194] -   dn = o=example
11:02:10.826 - DEBUG [edu.vt.middleware.ldap.Ldap:195] -   filter =
(cn=test)
11:02:10.826 - DEBUG [edu.vt.middleware.ldap.Ldap:196] -   filterArgs = []
11:02:10.826 - DEBUG [edu.vt.middleware.ldap.Ldap:197] -  searchControls
= javax.naming.directory.SearchControls at b8d7705
11:02:10.826 - DEBUG [edu.vt.middleware.ldap.Ldap:198] -   handler =
[edu.vt.middleware.ldap.handler.FqdnSearchResultHandler at 4af788d6,
edu.vt.middleware.ldap.handler.EntryDnSearchResultHandler at 4138c00d,
edu.vt.middleware.ldap.handler.BinarySearchResultHandler at 74c8b6ee]
11:02:10.826 - TRACE [edu.vt.middleware.ldap.Ldap:200] -   config =
{java.naming.provider.url=ldaps://ldap.example.de:636,
java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}
11:02:18.411 - TRACE
[edu.vt.middleware.ldap.handler.FqdnSearchResultHandler:69] - processing
relative dn: cn=test,ou=xyz
11:02:18.411 - TRACE
[edu.vt.middleware.ldap.handler.FqdnSearchResultHandler:95] - processed
dn: cn=test,ou=xyz,o=example
11:02:34.571 - TRACE
[edu.vt.middleware.ldap.pool.DefaultLdapFactory:123] - destroyed ldap
object:
edu.vt.middleware.ldap.Ldap at 2012647778::config=edu.vt.middleware.ldap.LdapConfig at 809997314::env={java.naming.provider.url=ldaps://ldap.example.de:636,
java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}
11:02:34.572 - DEBUG
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:414]
- LDAP data connector IdMLDAP - Found the following attribute: uid[test]

Currently we have no idea how to debug this further. Do you guys have
some idea what this could be caused by?

Cheers,
Martin




-- 
-----------------------------------------------------------------------
Dr. Martin Haase
DAASI International GmbH                   phone:     +49 7071 407109-6
Europaplatz 3                              Fax  :     +49 7071 407109-9
D-72072 Tübingen                           email: Martin.Haase at DAASI.de
Germany                                    Web  :   http://www.daasi.de

Directory Applications for Advanced Security and Information Management
-----------------------------------------------------------------------



-------------- next part --------------
A non-text attachment was scrubbed...
Name: smime.p7s
Type: application/pkcs7-signature
Size: 2345 bytes
Desc: S/MIME Kryptografische Unterschrift
Url : http://shibboleth.net/pipermail/users/attachments/20120802/81ab33fc/attachment.bin