Shibboleth Developers

[Russell Beall <>]

On the LDAP side, by grepping for the particular connection, here is what I 
see on startup:

[17/Jun/2010:15:37:35 -0700] conn=2252464 op=-1 msgId=-1 - fd=177 slot=177 
LDAP connection from 128.125.253.234:35717 to 68.181.195.113
[17/Jun/2010:15:37:35 -0700] conn=2252464 op=0 msgId=1 - EXT 
oid="1.3.6.1.4.1.1466.20037"
[17/Jun/2010:15:37:35 -0700] conn=2252464 op=0 msgId=1 - RESULT err=0 tag=120 
nentries=0 etime=0, Start TLS request accepted.Server willing to negotiate 
SSL.
[17/Jun/2010:15:37:39 -0700] conn=2252464 op=-1 msgId=-1 - SSL 256-bit AES-256
[17/Jun/2010:15:37:39 -0700] conn=2252464 op=1 msgId=2 - BIND 
dn="uscrdn=usc.edu.xxxxxxxxxxxxx,ou=accounts,dc=usc,dc=edu" method=128 
version=3
[17/Jun/2010:15:37:42 -0700] conn=2252464 op=1 msgId=2 - RESULT err=0 tag=97 
nentries=0 etime=4 dn="uscrdn=usc.edu.scfs2kk2,ou=accounts,dc=usc,dc=edu"
[17/Jun/2010:15:38:43 -0700] conn=2252464 op=2 msgId=0 - RESULT err=80 
tag=120 nentries=0 etime=61
[17/Jun/2010:15:38:43 -0700] conn=2252464 op=-1 msgId=-1 - closing from 
128.125.253.234:35717 - B1 - Client request contains an ASN.1 BER tag that is 
corrupt or connection aborted -
[17/Jun/2010:15:38:43 -0700] conn=2252464 op=-1 msgId=-1 - closed.



Similar situations occur during login, and multiple connections are made and 
closed with an error condition.  I xxxxxx'ed out the service account DN and 
my DN, so in the below text, xxxxxxxx is the shib service account, and 
yyyyyyy denotes my DN (probably didn't need to hide that one...).

[17/Jun/2010:15:42:54 -0700] conn=2252496 op=-1 msgId=-1 - fd=172 slot=172 
LDAP connection from 128.125.253.234:35734 to 68.181.195.113
[17/Jun/2010:15:42:54 -0700] conn=2252496 op=0 msgId=1 - EXT 
oid="1.3.6.1.4.1.1466.20037"
[17/Jun/2010:15:42:54 -0700] conn=2252496 op=0 msgId=1 - RESULT err=0 tag=120 
nentries=0 etime=0, Start TLS request accepted.Server willing to negotiate 
SSL.
[17/Jun/2010:15:42:54 -0700] conn=2252496 op=-1 msgId=-1 - SSL 256-bit AES-256
[17/Jun/2010:15:42:54 -0700] conn=2252496 op=1 msgId=2 - BIND 
dn="uscrdn=usc.edu.xxxxxxxxxxxxx,ou=accounts,dc=usc,dc=edu" method=128 
version=3
[17/Jun/2010:15:42:54 -0700] conn=2252496 op=1 msgId=2 - RESULT err=0 tag=97 
nentries=0 etime=0 dn="uscrdn=usc.edu.scfs2kk2,ou=accounts,dc=usc,dc=edu"
[17/Jun/2010:15:42:54 -0700] conn=2252496 op=2 msgId=3 - SRCH 
base="dc=usc,dc=edu" scope=2 filter="(uid=beall)" attrs="1.1"
[17/Jun/2010:15:42:54 -0700] conn=2252496 op=2 msgId=3 - RESULT err=0 tag=101 
nentries=1 etime=0
[17/Jun/2010:15:42:54 -0700] conn=2252497 op=-1 msgId=-1 - fd=176 slot=176 
LDAP connection from 128.125.253.234:35735 to 68.181.195.113
[17/Jun/2010:15:42:54 -0700] conn=2252497 op=0 msgId=1 - EXT 
oid="1.3.6.1.4.1.1466.20037"
[17/Jun/2010:15:42:54 -0700] conn=2252497 op=0 msgId=1 - RESULT err=0 tag=120 
nentries=0 etime=0, Start TLS request accepted.Server willing to negotiate 
SSL.
[17/Jun/2010:15:42:54 -0700] conn=2252497 op=-1 msgId=-1 - SSL 256-bit AES-256
[17/Jun/2010:15:42:54 -0700] conn=2252497 op=1 msgId=2 - BIND 
dn="uscrdn=usc.edu.yyyyyyyyyyyyyy,ou=accounts,dc=usc,dc=edu" method=128 
version=3
[17/Jun/2010:15:42:55 -0700] conn=2252497 op=1 msgId=2 - RESULT err=0 tag=97 
nentries=0 etime=1 dn="uscrdn=usc.edu.scrf7xn7,ou=accounts,dc=usc,dc=edu"
[17/Jun/2010:15:43:55 -0700] conn=2252497 op=2 msgId=0 - RESULT err=80 
tag=120 nentries=0 etime=60
[17/Jun/2010:15:43:55 -0700] conn=2252497 op=-1 msgId=-1 - closing from 
128.125.253.234:35735 - B1 - Client request contains an ASN.1 BER tag that is 
corrupt or connection aborted -
[17/Jun/2010:15:43:55 -0700] conn=2252497 op=-1 msgId=-1 - closed.
[17/Jun/2010:15:43:55 -0700] conn=2252496 op=3 msgId=4 - SRCH 
base="dc=usc,dc=edu" scope=2 filter="(uid=beall)" attrs="1.1"
[17/Jun/2010:15:43:55 -0700] conn=2252496 op=3 msgId=4 - RESULT err=0 tag=101 
nentries=1 etime=0
[17/Jun/2010:15:44:55 -0700] conn=2252496 op=4 msgId=0 - RESULT err=80 
tag=120 nentries=0 etime=60
[17/Jun/2010:15:44:55 -0700] conn=2252496 op=-1 msgId=-1 - closing from 
128.125.253.234:35734 - B1 - Client request contains an ASN.1 BER tag that is 
corrupt or connection aborted -
[17/Jun/2010:15:44:55 -0700] conn=2252496 op=-1 msgId=-1 - closed.
[17/Jun/2010:15:44:55 -0700] conn=2252509 op=-1 msgId=-1 - fd=172 slot=172 
LDAP connection from 128.125.253.234:35741 to 68.181.195.113
[17/Jun/2010:15:44:55 -0700] conn=2252509 op=0 msgId=1 - EXT 
oid="1.3.6.1.4.1.1466.20037"
[17/Jun/2010:15:44:55 -0700] conn=2252509 op=0 msgId=1 - RESULT err=0 tag=120 
nentries=0 etime=0, Start TLS request accepted.Server willing to negotiate 
SSL.
[17/Jun/2010:15:44:55 -0700] conn=2252509 op=-1 msgId=-1 - SSL 256-bit AES-256
[17/Jun/2010:15:44:55 -0700] conn=2252509 op=1 msgId=2 - BIND 
dn="uscrdn=usc.edu.xxxxxxxxxxxx,ou=accounts,dc=usc,dc=edu" method=128 
version=3
[17/Jun/2010:15:44:55 -0700] conn=2252509 op=1 msgId=2 - RESULT err=0 tag=97 
nentries=0 etime=0 dn="uscrdn=usc.edu.scfs2kk2,ou=accounts,dc=usc,dc=edu"
[17/Jun/2010:15:44:55 -0700] conn=2252509 op=2 msgId=3 - SRCH 
base="dc=usc,dc=edu" scope=2 filter="(uid=beall)" attrs=ALL
[17/Jun/2010:15:44:55 -0700] conn=2252509 op=2 msgId=3 - RESULT err=0 tag=101 
nentries=1 etime=0
[17/Jun/2010:15:45:56 -0700] conn=2252509 op=3 msgId=0 - RESULT err=80 
tag=120 nentries=0 etime=60
[17/Jun/2010:15:45:56 -0700] conn=2252509 op=-1 msgId=-1 - closing from 
128.125.253.234:35741 - B1 - Client request contains an ASN.1 BER tag that is 
corrupt or connection aborted -
[17/Jun/2010:15:45:56 -0700] conn=2252509 op=-1 msgId=-1 - closed.


Russ.

On Jun 17, 2010, at 3:19 PM, Daniel Fisher wrote:

> What does your DataConnector configuration look like for both TLS and 
> non-TLS?
> Do the LDAP logs shed any light on the problem?
> 
> --Daniel Fisher
> 
> 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
>>>     
> 
>