Shibboleth Developers

[Russell Beall <>]

Ok.  It seems to be related to a TLS bind because if I turn TLS off, I don't 
get any delays.

Here is a snippet from startup with TLS on.  You can see here the one second 
interval between the bind and the start of the next line:

14:28:24.617 - DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:490]
 - Loading 3 principal connectors
14:28:24.640 - DEBUG [edu.vt.middleware.ldap.handler.TlsConnectionHandler:80] 
- Bind with the following parameters:
14:28:24.641 - DEBUG [edu.vt.middleware.ldap.handler.TlsConnectionHandler:81] 
-   dn = uscrdn=usc.edu.xxxxxxxxxxxx,ou=accounts,dc=usc,dc=edu
14:28:24.642 - DEBUG [edu.vt.middleware.ldap.handler.TlsConnectionHandler:88] 
-   credential = <suppressed>
14:29:28.478 - INFO 
[edu.internet2.middleware.shibboleth.common.config.BaseService:179] - 
shibboleth.AttributeResolver service configuration loaded


And here is a section of the login attempt, also with one second between the 
search attempt and the resulting data processing:
14:28:34.809 - DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:294]
 - Search filter: (uid=beall)
14:28:34.810 - DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:349]
 - LDAP data connector gds - Retrieving attributes from LDAP
14:28:34.810 - DEBUG [edu.vt.middleware.ldap.handler.TlsConnectionHandler:80] 
- Bind with the following parameters:
14:28:34.811 - DEBUG [edu.vt.middleware.ldap.handler.TlsConnectionHandler:81] 
-   dn = uscrdn=usc.edu.xxxxxxxxxxxx,ou=accounts,dc=usc,dc=edu
14:28:34.812 - DEBUG [edu.vt.middleware.ldap.handler.TlsConnectionHandler:88] 
-   credential = <suppressed>
14:28:34.917 - DEBUG [edu.vt.middleware.ldap.Ldap:191] - Search with the 
following parameters:
14:28:34.918 - DEBUG [edu.vt.middleware.ldap.Ldap:192] -   dn = dc=usc,dc=edu
14:28:34.919 - DEBUG [edu.vt.middleware.ldap.Ldap:193] -   filter = 
(uid=beall)
14:28:34.920 - DEBUG [edu.vt.middleware.ldap.Ldap:194] -   filterArgs = []
14:28:34.920 - DEBUG [edu.vt.middleware.ldap.Ldap:195] -   searchControls = 
javax.naming.directory.SearchControls@5c3f1224
14:28:34.921 - DEBUG [edu.vt.middleware.ldap.Ldap:196] -   handler = 
[edu.vt.middleware.ldap.handler.FqdnSearchResultHandler@30c028cc,
 
edu.vt.middleware.ldap.handler.BinarySearchResultHandler@17b68215,
 
edu.vt.middleware.ldap.handler.EntryDnSearchResultHandler@4f163cdc]
14:29:35.157 - DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:400]
 - LDAP data connector gds - Found the following attribute: uid[beall]
14:29:35.190 - DEBUG 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:400]
 - LDAP data connector gds - Found the following attribute: 
eduPersonPrincipalName[]

Russ.

On Jun 17, 2010, at 2:07 PM, Chad La Joie wrote:

> Can you turn on debug logging for the LDAP library and send me a log for 
> one login?  I'll review it with Dan and see if anything stands out.
> 
> On 6/17/10 2:49 PM, Russell Beall wrote:
>> I installed this in my staging environment, and the first thing I had to 
>> do was instrument some more LDAP related classes to the TC config.
>> 
>> That was pretty easy since TC prompted me regarding which classes needed 
>> to be added.
>> 
>> Initial results show quite an increase in the load time, not because it 
>> was busy, but because it was hanging on something.  Then when I try to log 
>> into anything, it hangs again.  Debug tracing seems to indicate that it is 
>> waiting on the LDAP code, for instance, the login attempt seems to hang 
>> after the line "Attempting to authenticate user 'beall'".  And on startup, 
>> it seems to hang just after printing the line "Loading 3 principal 
>> connectors".  There is a precision to the delay time also, since it is 
>> precisely 60 seconds each time for most of the delays, and precisely 120 
>> seconds for several of the authentication attempts.
>> 
>> This happens both with and without TC in the mix.
>> 
>> Perhaps some of my deprecated time specifiers changed the timing 
>> somewhere?  I noticed that time specifiers which formerly read 60000ms, 
>> now print to the log as 60000000ms.  I presume that the field specifiers 
>> changed from milliseconds to seconds?
>> 
>> Haven't dug much beyond this point yet.
>> 
>> Russ.
>> 
>> On Jun 16, 2010, at 6:20 AM, Chad La Joie wrote:
>> 
>>> I have just released a new version[1] of IdP v2.2 (the 20100616 version).
>>> 
>>> The main changes in this release focus on metadata fetching and reloading 
>>> and include:
>>> - ability to turn off the fail-fast initialization behavior
>>> - reloading of metadata is now done in a background process
>>> - HTTP (and FileBackedHTTP) providers now support:
>>>  - gzip and deflate compression
>>>  - conditional fetching based on Last-Modified and/or ETag data
>>>  - ability to ignore the server's SSL certificate
>>>  - HTTP proxy support
>>>  - HTTP basic authentication support
>>>  - byte-for-byte equality of backup file created by the FileBackedHTTP 
>>> provider
>>> 
>>> The documentation on the site has been updated, though will be reworked 
>>> before the release, especially the part describing the reloading process.
>>> 
>>> I am asking people to *please* test this release, especially the metadata 
>>> related items.  I've done a fair amount of testing on them, but quite a 
>>> lot of the metadata provider code changed so I'd prefer other people give 
>>> it a go as well.  And if you do test it, please report back positive test 
>>> results, I don't want to assume that no news is good news in this case.
>>> 
>>> Thanks.
>>> 
>>> [1] 
>>> http://shibboleth.internet2.edu/downloads/maven2/edu/internet2/middleware/shibboleth-identityprovider/2.2.0-SNAPSHOT
>>> --
>>> Chad La Joie
>>> http://itumi.biz
>>> trusted identities, delivered
>> 
>> 
> 
> -- 
> Chad La Joie
> http://itumi.biz
> trusted identities, delivered