missing attributes in output from idpv3 /cas/serviceValidate

Thu Apr 7 00:03:52 EDT 2016

On Thu, Apr 07, 2016 at 12:36:30AM +0000, Cantor, Scott wrote:

> I don't see any obvious explanation for that in the code, doesn't seem
> possible. For one thing, it checks for a null AttributeContext and
> throws. So there absolutely cannot be any attributes in that context.
> 
> Are you sure that filtering evidence is from the serviceValidate step
> and not a /login step? My read is that it should be
> resolving/filtering twice, once for /login and then once for the
> /serviceValidate...

I'm not sure of anything other than it's not working ;). Ok, I tried this:

I wiped the log clean, then did the login step and made a copy of the log:

# cp logs/idp-process.log /tmp/idp-process-login.log

Then I did the serviceValidate step and made a copy of the log:

# cp logs/idp-process.log /tmp/idp-process-validate.log

# grep 'remained after filtering' /tmp/idp-process-login.log 
2016-04-06 20:23:57,280 - DEBUG [net.shibboleth.idp.attribute.filter.impl.AttributeFilterImpl:167] - Attribute filtering engine 'ShibbolethAttributeFilter': 4 values for attribute 'cppEduPersonAffiliation' remained after filtering

# grep PrepareTicketValidationResponseAction /tmp/idp-process-login.log 

# diff /tmp/idp-process-login.log /tmp/idp-process-validate.log | grep PrepareTicketValidationResponseAction

# diff /tmp/idp-process-login.log /tmp/idp-process-validate.log | grep 'remained after filtering'

The login step processed the attribute filter, the serviceValidate step
did not, and did not call PrepareTicketValidationResponseAction.

Now the same thing for samlValidate:

# grep 'remained after filtering' /tmp/idp-process-samllogin.log 

2016-04-06 20:36:12,780 - DEBUG [net.shibboleth.idp.attribute.filter.impl.AttributeFilterImpl:167] - Attribute filtering engine 'ShibbolethAttributeFilter': 4 values for attribute 'cppEduPersonAffiliation' remained after filtering

# grep PrepareTicketValidationResponseAction /tmp/idp-process-login.log

# diff /tmp/idp-process-samllogin.log /tmp/idp-process-samlvalidate.log | grep 'remained after filtering'
> 2016-04-06 20:36:33,148 - DEBUG [net.shibboleth.idp.attribute.filter.impl.AttributeFilterImpl:167] - Attribute filtering engine 'ShibbolethAttributeFilter': 4 values for attribute 'cppEduPersonAffiliation' remained after filtering

# diff /tmp/idp-process-samllogin.log /tmp/idp-process-samlvalidate.log | grep PrepareTicketValidationResponseAction
> 2016-04-06 20:36:33,156 - 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}]}

So, the samlValidate endpoint has attributes and the serviceValidate does
not. I'm pretty sure based on this methodology it's clear which logs are
from which step. It looks like the attribute filter policy isn't getting
triggered at all during the serviceValidate call? But it is for the
samlValidate call? What would cause that?

In the serviceValidate log, it ends like this:

> 2016-04-06 20:24:11,765 - DEBUG [net.shibboleth.idp.cas.flow.impl.ValidateIdpSessionAction:91] - Session 98bf511253f960848f1368b6994310c2371457b864bc43c1220c6a2c7b9b12db expired=false
> 2016-04-06 20:24:11,767 - DEBUG [net.shibboleth.idp.cas.flow.impl.UpdateIdPSessionWithSPSessionAction:94] - Created SP session CASSPSession: https://login.proxy-dev.library.cpp.edu/login via ST-1459999437311-ebm2wgG8gUOHzeIZQ1crhUWqP
> 2016-04-06 20:24:11,767 - DEBUG [net.shibboleth.idp.session.impl.StorageBackedIdPSession:656] - Saving SPSession for service https://login.proxy-dev.library.cpp.edu/login in session 98bf511253f960848f1368b6994310c2371457b864bc43c1220c6a2c7b9b12db
> 2016-04-06 20:24:11,768 - DEBUG [net.shibboleth.idp.session.SPSessionSerializerRegistry:86] - Registry located StorageSerializer of type 'net.shibboleth.idp.cas.session.impl.CASSPSessionSerializer' for SPSession type 'class net.shibboleth.idp.cas.session.impl.CASSPSession'
> 2016-04-06 20:24:11,768 - DEBUG [net.shibboleth.idp.session.impl.StorageBackedIdPSession:528] - Loading AuthenticationResult for flow authn/Password in session 98bf511253f960848f1368b6994310c2371457b864bc43c1220c6a2c7b9b12db

In the samlValidate log, after the similar line:

> 2016-04-06 20:36:32,724 - DEBUG [net.shibboleth.idp.cas.flow.impl.ValidateIdpSessionAction:91] - Session 4f81b49f63b7cbb8c95f5d3a964d290ca0fb51930e4ac3ce7d93f1947a9740d5 expired=false

The next lines are:

> 2016-04-06 20:36:32,732 - DEBUG [net.shibboleth.idp.profile.impl.ResolveAttributes:219] - Profile Action ResolveAttributes: No authentication context available.
> 2016-04-06 20:36:32,732 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:183] - Attribute Resolver 'ShibbolethAttributeResolver': Initiating attribute resolution

and there are a whole bunch of attribute related log lines that just aren't
in the serviceValidate log 8-/. Then after the last attribute log line it
continues similiarly to the other log:

> 2016-04-06 20:36:33,151 - DEBUG [net.shibboleth.idp.cas.flow.impl.UpdateIdPSessionWithSPSessionAction:94] - Created SP session CASSPSession: https://login.proxy-dev.library.cpp.edu/login via ST-1460000172816-SgwQ9qkJvuOoi8L0l6ZFPKu4s

Other than it also has:

> 2016-04-06 20:36:33,156 - 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}]}

and the SAML line:

> 2016-04-06 20:36:33,169 - DEBUG [net.shibboleth.idp.cas.flow.impl.BuildSamlValidationSuccessMessageAction:90] - Building SAML response for https://login.proxy-dev.library.cpp.edu/login in IdP session 4f81b49f63b7cbb8c95f5d3a964d290ca0fb51930e4ac3ce7d93f1947a9740d5

Scott, I hope you don't mind, but I'm going to shoot you these logs
in their entirety under separate cover.

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