Shibboleth Developers

[Russell Beall <>]

Ok, it is sent off.

Russ.

On Jun 18, 2010, at 9:28 AM, Daniel Fisher wrote:

> Can you send a complete trace?
> Send it to me directly if you don't want it on the list.
> There's definitely something suspicious going on, I'm hoping some of the 
> handshake details will point to the problem.
> 
> --Daniel Fisher
> 
> On 6/17/10 6:55 PM, Russell Beall wrote:
>> (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
>>>     
> 
>