Shibboleth Developers

[Daniel Fisher <>]

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
> >

Attachment: smime.p7s
Description: S/MIME Cryptographic Signature