Shibboleth Developers

[Chad La Joie <>]

If it's TLS related you might also want to add the property 
-Djavax.net.debug=all to your startup properties.  That'll show whats 
going on in the TLS handshake too, at least as much as the IdP side knows.

On 6/17/10 5:47 PM, Russell Beall wrote:
> 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

--
Chad La Joie
http://itumi.biz
trusted identities, delivered