missing attributes in output from idpv3 /cas/serviceValidate

Mon Apr 4 13:58:59 EDT 2016

I'm testing our library dev ezproxy system with my test idpv3 server and
I seem to be having an issue with CAS attributes. I have it defined in
cas-protocol.xml as follows:

   <bean class="net.shibboleth.idp.cas.service.ServiceDefinition"
         c:regex="https?://(login\.)?proxy(-dev)?\.library\.cpp\.edu/login.*"
         p:group="cas-cppEduPersonAffiliation"
         p:singleLogoutParticipant="true"
         p:authorizedToProxy="false" />

with a corresponding entry in my attribute-filter.xml config:

    <AttributeFilterPolicy id="cas-cppEduPersonAffiliation">
        <PolicyRequirementRule xsi:type="InEntityGroup" groupID="cas-cppEduPersonAffiliation" />

        <AttributeRule permitAny="true" attributeID="cppEduPersonAffiliation" />
    </AttributeFilterPolicy>

However, when authenticating to ezproxy, according to the debug log, no
attributes show up:

ServiceValidateURL https://idp-dev.cpp.edu/idp/profile/cas/serviceValidate
CASServiceValidate HTTP/1.1 200 OK
CASServiceValidate Server: Apache-Coyote/1.1
CASServiceValidate Cache-Control: no-store
CASServiceValidate Expires: Wed, 31 Dec 1969 16:00:00 PST
CASServiceValidate Set-Cookie: JSESSIONID=AE8CA71D7875AB38A8008DCD0AD34A18; Path=/idp/; Secure; HttpOnly
CASServiceValidate Content-Type: text/html;charset=utf-8
CASServiceValidate Content-Length: 228
CASServiceValidate Date: Mon, 04 Apr 2016 17:33:48 GMT
CASServiceValidate Connection: close
CASServiceValidate 
CASServiceValidate <?xml version="1.0" encoding="UTF-8"?>
CASServiceValidate <cas:serviceResponse xmlns:cas="http://www.yale.edu/tp/cas">
CASServiceValidate   <cas:authenticationSuccess>
CASServiceValidate     <cas:user>henson</cas:user>
CASServiceValidate               </cas:authenticationSuccess>
CASServiceValidate </cas:serviceResponse>

Per the idp logs, it looks like the release policy is firing:

2016-04-04 10:33:48,461 - DEBUG [net.shibboleth.idp.attribute.filter.policyrule.filtercontext.impl.AttributeRequesterPol
icyRule:54] - Attribute Filter '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/PolicyRequirementRule:_9ae8a206f8831f
4ae294b2c259b4407b': Found attribute requester: https://login.proxy-dev.library.cpp.edu/login?qurl=ezp.2aHR0cHM6Ly9sb2dp
bi5wcm94eS1kZXYubGlicmFyeS5jcHAuZWR1L215Z3JvdXBz
2016-04-04 10:33:48,463 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeFilterPolicy:159] - Attribute Filter Polic
y 'cas-cppEduPersonAffiliation'  Applying attribute filter policy to current set of attributes: [uid, eduPersonPrincipal
Name, eduPersonAffiliation, eduPersonPrimaryAffiliation, calstateEduPersonPrimaryAffiliation, organizationName, eduPerso
nScopedAffiliation, surname, givenName, memberOf, calstateEduPersonAffiliation, title, calstateEduPersonID, eduPersonOrg
DN, initials, calstateEduPersonEmplID, eduPersonEntitlement, organizationalUnit, cppEduPersonAffiliation, mail, calstate
EduPersonPrincipalName, campusLabsCardId, eduPersonTargetedID, calstateEduPersonOrg, cn, calstateEduPersonAssuranceLevel
, telephoneNumber, displayName]
2016-04-04 10:33:48,463 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:168] - Attribute filtering engine '/A
ttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_e318e2ddf241a7f0f4c21678ed5733b8'  Filtering values for 
attribute 'cppEduPersonAffiliation' which currently contains 4 values
2016-04-04 10:33:48,463 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:177] - Attribute filtering engine '/A
ttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_e318e2ddf241a7f0f4c21678ed5733b8'  Filter has permitted 
the release of 4 values for attribute 'cppEduPersonAffiliation'

The one weird thing is that that after finding the matching relying party:

2016-04-04 10:33:48,516 - DEBUG [net.shibboleth.idp.cas.service.PatternServiceRegistry:85] - Evaluating whether https://login.proxy-dev.library.cpp.edu/login?qurl=ezp.2aHR0cHM6Ly9sb2dpbi5wcm94eS1kZXYubGlicmFyeS5jcHAuZWR1L215Z3JvdXBz matches https?://(login\.)?proxy(-dev)?\.library\.cpp\.edu/login.*
2016-04-04 10:33:48,517 - DEBUG [net.shibboleth.idp.cas.service.PatternServiceRegistry:87] - Found match
2016-04-04 10:33:48,517 - DEBUG [net.shibboleth.idp.cas.flow.impl.BuildRelyingPartyContextAction:81] - Setting up RP context for verified relying party https://login.proxy-dev.library.cpp.edu/login?qurl=ezp.2aHR0cHM6Ly9sb2dpbi5wcm94eS1kZXYubGlicmFyeS5jcHAuZWR1L215Z3JvdXBz

It then says there's no match and it's using the default?

2016-04-04 10:33:48,517 - DEBUG [net.shibboleth.idp.relyingparty.impl.DefaultRelyingPartyConfigurationResolver:293] - Resolving relying party configuration
2016-04-04 10:33:48,517 - DEBUG [net.shibboleth.idp.relyingparty.impl.DefaultRelyingPartyConfigurationResolver:314] - No relying party configurations are applicable, returning the default configuration shibboleth.DefaultRelyingParty
2016-04-04 10:33:48,518 - DEBUG [net.shibboleth.idp.profile.impl.SelectRelyingPartyConfiguration:136] - Profile Action SelectRelyingPartyConfiguration: Found relying party configuration shibboleth.DefaultRelyingParty for request

I have another test entry using the same release policy:

      <bean class="net.shibboleth.idp.cas.service.ServiceDefinition"
            c:regex="https://dunkin\.unx\.cpp\.edu/.*"
            p:group="cas-cppEduPersonAffiliation"
            p:singleLogoutParticipant="true"
            p:authorizedToProxy="false" />

This one works fine; however, it's using mod_auth_cas and the samlValidate
endpoint. The logs look a bit different for it, although it has the same
entry about the default relying party after finding the right one, so
maybe that's expected:

2016-04-04 10:50:51,915 - DEBUG [net.shibboleth.idp.cas.service.PatternServiceRegistry:85] - Evaluating whether https://dunkin.unx.cpp.edu/secured/ matches https://dunkin\.unx\.cpp\.edu/.*
2016-04-04 10:50:51,915 - DEBUG [net.shibboleth.idp.cas.service.PatternServiceRegistry:87] - Found match
2016-04-04 10:50:51,915 - DEBUG [net.shibboleth.idp.cas.flow.impl.BuildRelyingPartyContextAction:81] - Setting up RP context for verified relying party https://dunkin.unx.cpp.edu/secured/
2016-04-04 10:50:51,916 - DEBUG [net.shibboleth.idp.relyingparty.impl.DefaultRelyingPartyConfigurationResolver:293] - Resolving relying party configuration
2016-04-04 10:50:51,916 - DEBUG [net.shibboleth.idp.relyingparty.impl.DefaultRelyingPartyConfigurationResolver:314] - No relying party configurations are applicable, returning the default configuration shibboleth.DefaultRelyingParty
2016-04-04 10:50:51,916 - DEBUG [net.shibboleth.idp.profile.impl.SelectRelyingPartyConfiguration:136] - Profile Action SelectRelyingPartyConfiguration: Found relying party configuration shibboleth.DefaultRelyingParty for request
2016-04-04 10:50:53,851 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeFilterPolicy:125] - Attribute Filter Polic
y 'cas-cppEduPersonAffiliation'  Checking if attribute filter policy is active
2016-04-04 10:50:53,852 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeFilterPolicy:132] - Attribute Filter Polic
y 'cas-cppEduPersonAffiliation'  Policy is active for this request
2016-04-04 10:50:53,852 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeFilterPolicy:159] - Attribute Filter Polic
y 'cas-cppEduPersonAffiliation'  Applying attribute filter policy to current set of attributes: [uid, eduPersonPrincipal
Name, eduPersonAffiliation, eduPersonPrimaryAffiliation, calstateEduPersonPrimaryAffiliation, organizationName, eduPerso
nScopedAffiliation, surname, givenName, memberOf, calstateEduPersonAffiliation, title, calstateEduPersonID, eduPersonOrg
DN, initials, calstateEduPersonEmplID, eduPersonEntitlement, organizationalUnit, cppEduPersonAffiliation, mail, calstate
EduPersonPrincipalName, campusLabsCardId, eduPersonTargetedID, calstateEduPersonOrg, cn, calstateEduPersonAssuranceLevel
, telephoneNumber, displayName]
2016-04-04 10:50:53,852 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:168] - Attribute filtering engine '/A
ttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_e318e2ddf241a7f0f4c21678ed5733b8'  Filtering values for 
attribute 'cppEduPersonAffiliation' which currently contains 4 values
2016-04-04 10:50:53,852 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:177] - Attribute filtering engine '/A
ttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_e318e2ddf241a7f0f4c21678ed5733b8'  Filter has permitted 
the release of 4 values for attribute 'cppEduPersonAffiliation'

2016-04-04 10:50:53,856 - DEBUG [net.shibboleth.idp.attribute.filter.impl.AttributeFilterImpl:167] - Attribute filtering
 engine 'ShibbolethAttributeFilter': 4 values for attribute 'cppEduPersonAffiliation' remained after filtering

2016-04-04 10:50:53,860 - DEBUG [net.shibboleth.idp.cas.flow.impl.PrepareTicketValidationResponseAction:111] - Processing IdPAttribute{id=cppEduPersonAffiliation, displayNames={}, displayDescriptions={}, encoders=[net.shibboleth.idp.saml.attribute.encoding.impl.SAML2StringAttributeEncoder at 7302b65a], values=[StringAttributeValue{value=member}, StringAttributeValue{value=staff}, StringAttributeValue{value=eoc_essential}, StringAttributeValue{value=employee}]}

Any thoughts on why the attributes aren't showing up?

Thanks...

-- 
Paul B. Henson  |  (909) 979-6361  |  http://www.cpp.edu/~henson/
Operating Systems and Network Analyst  |  henson at cpp.edu
California State Polytechnic University  |  Pomona CA 91768