Extremely slow IdP login

Martin Haase Martin.Haase at DAASI.de
Thu Aug 2 05:37:49 EDT 2012 

I forgot - a command line ldapsearch from the same machine using the
same parameters returns promptly, so we deduce it would not be an LDAP
issue.

Am 02.08.2012 11:24, schrieb 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
>
>
>
>
>
>
> --
> To unsubscribe from this list send an email to users-unsubscribe at shibboleth.net

-- 
-----------------------------------------------------------------------
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 --------------
An HTML attachment was scrubbed...
URL: http://shibboleth.net/pipermail/users/attachments/20120802/cdfca328/attachment.html 
-------------- 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/cdfca328/attachment.bin

More information about the users mailing list