Shibboleth Developers

[Russell Beall <>]

(Meant to send this a while ago but it got stuck in an open mail window...  
This is the debug printing done with -Djavax.net.debug=all)

--------

Ok.  With that debugging parameter on, the IdP startup sequence pauses at 
this point, and prints to catalina.out:

main, called close()
main, called closeInternal(true)
main, SEND TLSv1 ALERT:  warning, description = close_notify
Padded plaintext before ENCRYPTION:  len = 32
0000: 01 00 56 C1 79 46 22 CB   A4 BF 7D 3D AB 5F D3 39  ..V.yF"....=._.9
0010: AD F5 34 3C 8F 7C 09 09   09 09 09 09 09 09 09 09  ..4<............
main, WRITE: TLSv1 Alert, length = 32
[Raw write]: length = 37
0000: 15 03 01 00 20 C8 F6 39   3D 34 A0 96 2B C0 11 29  .... ..9=4..+..)
0010: EB 3F 37 6B F7 66 89 DA   E5 03 32 D7 D5 70 67 E0  .?7k.f....2..pg.
0020: 2C EA 64 04 BA                                     ,.d..
main, waiting for close_notify or alert: state 5

---
Then after 60 secs or so, the rest is printed:
---

[Raw read]: length = 5
0000: 17 03 01 00 40                                     ....@
[Raw read]: length = 64
0000: 37 BF C9 14 42 5C B5 DC   CF A5 87 D5 72 CC 74 29  7...B\......r.t)
0010: B2 4A 9E 94 65 95 19 2C   CD 4F B3 5F 28 83 C0 7A  .J..e..,.O._(..z
0020: 27 75 02 61 3D A9 E2 40   A0 EB 1C F3 D9 67 6A 50  
'u.a=..@.....gjP
0030: FB 1E C7 7D E7 E6 46 5B   2C FC 51 95 81 35 63 3D  ......F[,.Q..5c=
Thread-2, READ: TLSv1 Application Data, length = 64
Padded plaintext after DECRYPTION:  len = 64
0000: 30 24 02 01 00 78 1F 0A   01 50 04 00 04 00 8A 16  0$...x...P......
0010: 31 2E 33 2E 36 2E 31 2E   34 2E 31 2E 31 34 36 36  1.3.6.1.4.1.1466
0020: 2E 32 30 30 33 36 6A 2A   6F B5 9E C0 A4 E4 D8 1B  .20036j*o.......
0030: 75 41 D1 26 74 B2 B7 85   90 08 05 05 05 05 05 05  uA.&t...........
main, received EOFException: ignored
main, called closeInternal(false)
main, close invoked again; state = 5
89.830: [GC 525312K->25629K(2013696K), 0.1485788 secs]
Finalizer, called close()
Finalizer, called closeInternal(true)

Hopefully this will be useful to Dan...

Russ.

On Jun 17, 2010, at 3:03 PM, Chad La Joie wrote:

> 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