REFEDS R&S SP reports intermittent failures

Sat Apr 23 00:48:38 EDT 2016

I'm trying to troubleshoot reported intermittent failures by an REFEDS
R&S SP (CILogon) by users using our IdP (2.4.4). The SP reports the
failures are the result of not receiving any attributes for the user.

I'm stumped at this point. If anyone has any ideas of anything else
to look for or try, I would very much appreciate the suggestions.

They have provided us with some of their logs.

===== SP logs
I'm assuming this is an excerpt that represents a failure due to the lack
of cached attributes:

2016-04-14 18:53:46 INFO Shibboleth-TRANSACTION [110]: New session (ID: _b765dc8a7efd5d1175f00e516bb1aadc) with (applicationId: default) for principal from (IdP: https://idp.hawaii.edu/idp/shibboleth) at (ClientAddress: 10.10.151.79) with (NameIdentifier: _cc955f74f9f861d8ac71e79d435d5c82) using (Protocol: urn:oasis:names:tc:SAML:2.0:protocol) from (AssertionID: _fe6a805a3176fcdc6c247ea8b2151306)
2016-04-14 18:53:46 INFO Shibboleth-TRANSACTION [110]: Cached the following attributes with session (ID: _b765dc8a7efd5d1175f00e516bb1aadc) for (applicationId: default) {
2016-04-14 18:53:46 INFO Shibboleth-TRANSACTION [110]: }

And that this is a success:

2016-04-15 10:50:36 INFO Shibboleth-TRANSACTION [127]: New session (ID: _51fe7b33d6aba3e4fd628c7ce0f4e073) with (applicationId: default) for principal from (IdP: https://idp.hawaii.edu/idp/shibboleth) at (ClientAddress: 10.10.37.85) with (NameIdentifier: _53b7fea682b761382175445789dde9e7) using (Protocol: urn:oasis:names:tc:SAML:2.0:protocol) from (AssertionID: _f16f59e9abdaeec2d43b2d60b9aad93f)
2016-04-15 10:50:36 INFO Shibboleth-TRANSACTION [127]: Cached the following attributes with session (ID: _51fe7b33d6aba3e4fd628c7ce0f4e073) for (applicationId: default) {
2016-04-15 10:50:36 INFO Shibboleth-TRANSACTION [127]:  sn (1 values)
2016-04-15 10:50:36 INFO Shibboleth-TRANSACTION [127]:  eppn (1 values)
2016-04-15 10:50:36 INFO Shibboleth-TRANSACTION [127]:  mail (1 values)
2016-04-15 10:50:36 INFO Shibboleth-TRANSACTION [127]:  givenName (1 values)
2016-04-15 10:50:36 INFO Shibboleth-TRANSACTION [127]: }
=====

On our IdP side I seem to be able to correlate the SP sessions in our logs
using the NameIdentifier token from the SP.

===== IdP logs
failure:

2016-04-14 13:53:45.970 - INFO [Shibboleth-Audit:1028] - 20160414T235345Z|urn:oasis:names:tc:SAML:2.0:bindings:HTTP-Redirect|_474802ddb0cfa6f17916ba05bc934eac|https://cilogon.org/shibboleth|urn:mace:shibboleth:2.0:profiles:saml2:sso|https://idp.hawaii.edu/idp/shibboleth|urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST|_04653d4b3b8fcb473f1f152ffb195dd8|FAILED_USER|urn:oasis:names:tc:SAML:2.0:ac:classes:unspecified||_cc955f74f9f861d8ac71e79d435d5c82||

success:

2016-04-15 05:50:36.482 - INFO [Shibboleth-Audit:1028] - 20160415T155036Z|urn:oasis:names:tc:SAML:2.0:bindings:HTTP-Redirect|_e904d92459abc4062c8bbff65f974158|https://cilogon.org/shibboleth|urn:mace:shibboleth:2.0:profiles:saml2:sso|https://idp.hawaii.edu/idp/shibboleth|urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST|_7bf0cf790d13445237d85df6a26f475e|SUCCESS_USER|urn:oasis:names:tc:SAML:2.0:ac:classes:unspecified|surname,eduPersonPrincipalName,email,transientId,givenName,|_53b7fea682b761382175445789dde9e7||
=====

I note the attributes being returned for the success.

Since I am logging at the INFO level, I don't think I have more details
available. I don't think changing the log level to DEBUG is feasible due
to the increased logging volume, and afaict, it would be difficult to
disentangle the DEBUG logs on a busy server.

I have also tried testing this with aacli on a spare IdP host with the
same config where I can log at DEBUG level.

===== aacli test, log excerpts
*** www.cilogon.org:

$ aacli.sh --configDir=conf --principal=baron --requester=https://www.cilogon.org/shibboleth
No attribute statement.

2016-04-15 17:18:17.553 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:157] - No custom or group-based relying party configuration found for https://www.cilogon.org/shibboleth. Using default relying party configuration.
...
2016-04-15 17:18:17.650 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:130] - Evaluating if filter policy REFED_RandS is active for principal baron
2016-04-15 17:18:17.650 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.match.saml.AbstractEntityAttributeMatchFunctor:110] - No metadata available for the entity ***
2016-04-15 17:18:17.650 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:134] - Filter policy REFED_RandS is not active for principal baron
...
2016-04-15 17:18:17.655 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:114] - Filtered attributes for principal baron.  The following attributes remain: [transientId]

I don't know if it's relevant, but I note that it reports "No metadata
available for the entity". This differs from when I try the same test with
another arbitrary REFEDS R&S SP.

*** ligo.org:
$ aacli.sh --configDir=conf --principal=baron --requester=https://wiki.ligo.org/shibboleth-sp
<?xml version="1.0" encoding="UTF-8"?>
<saml2:AttributeStatement xmlns:saml2="urn:oasis:names:tc:SAML:2.0:assertion">
...
</saml2:AttributeStatement>

2016-04-21 15:58:26.116 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:157] - No custom or group-based relying party configuration found for https://wiki.ligo.org/shibboleth-sp. Using default relying party configuration.
...
2016-04-21 15:58:26.231 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:130] - Evaluating if filter policy REFED_RandS is active for principal baron
2016-04-21 15:58:26.232 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.match.saml.AbstractEntityAttributeMatchFunctor:198] - Descriptor for https://wiki.ligo.org/shibboleth-sp contains an entity attribute with the name http://macedir.org/entity-category and the format null
2016-04-21 15:58:26.232 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.match.saml.AbstractEntityAttributeMatchFunctor:126] - Checking if entity attribute http://macedir.org/entity-category contains the required value.
2016-04-21 15:58:26.232 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.match.saml.AbstractEntityAttributeMatchFunctor:144] - Entity attribute http://macedir.org/entity-category value http://id.incommon.org/category/research-and-scholarship does not meet matching requirements
2016-04-21 15:58:26.232 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.match.saml.AbstractEntityAttributeMatchFunctor:141] - Entity attribute http://macedir.org/entity-category value http://refeds.org/category/research-and-scholarship meets matching requirements
...
2016-04-21 15:58:26.242 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:114] - Filtered attributes for principal baron.  The following attributes remain: [surname, eduPersonPrincipalName, email, transientId, givenName, UhEduPerson_displayName]
=====

The LIGO example seems to work as expected, and I believe both CILogon and
LIGO should be using the same REFEDS R&S membership test.

However, another confusing aspect is that if I try CILogon's test site at
<https://cilogon.org/secure/testidp/>, it succeeds and the displays the
received attributes. This, using the same IdP host where I can get a "No
attribute statement" using the aacli utility.

Aloha,
-baron
-- 
Baron Fujimoto <baron at hawaii.edu> :: UH Information Technology Services
minutas cantorum, minutas balorum, minutas carboratum desendus pantorum