Attribute release consent failing (sometimes)

[Manuel Haim]

Hi Tom,

I've tried to analyze the problem, but it persists. These are the facts:


1) The attribute release consent page fails only for some users, and
only for a single service provider (say, https://sp1.example.com).
Consents for all other service providers work for all users without
problems.

2) In attribute-resolver, I have a filter policy which reads like this:

<AttributeFilterPolicy id="SomeID">
  <PolicyRequirementRule xsi:type="OR">
    <Rule xsi:type="Requester"
          value="https://sp1.example.com/shibboleth" />
    <Rule xsi:type="Requester"
          value="https://sp2.example.com/shibboleth" />
    <Rule xsi:type="Requester"
          value="https://sp3.example.com/shibboleth" />
    <Rule xsi:type="Requester"
          value="https://sp4.example.com/shibboleth" />
    <Rule xsi:type="Requester"
          value="https://sp5.example.com/shibboleth" />
    <Rule xsi:type="Requester"
          value="https://sp6.example.com/shibboleth" />
  </PolicyRequirementRule>
  <AttributeRule attributeID="uid" permitAny="true"/>
  <AttributeRule attributeID="SomeCustomAttribute" permitAny="true"/>
</AttributeFilterPolicy>

3) sp1 and sp2 are our most used services (both are campus management
platforms). Both should be used by the same users from time to time
(i.e. our students). Their metadata files look very similar (only
difference is in the URLs, certificate and description).

4) We do not allow global consent or per-attribute consent.

5) I've tried both the distributed views/intercept/attribute-release.vm
template, as well as our customized one. Nothing helps.

6) Not all failing attribute release consent attempts seem to raise a
DEBUG message of net.shibboleth.idp.consent.flow.impl.ExtractConsent
within the log files. There appear some new entries in the
storagerecords table for context intercept/attribute-release with values
containing "appr":false which I cannot find a corresponding DEBUG
message for.

7) For the failing attempts which were DEBUG-logged within the
Shibboleth logs, I took a look at the User Agent in my loadbalancer's
log. There I can see failing logins coming only from these specific
browser versions (32 failures from 21-Sep-2017 thru 10-Oct-2017):
Safari 10.0
Safari 10.0.1
Chrome 53.0.2785.143
Chrome 54.0.2840.71
Firefox 49.0

8) For all failing attemts (with or without DEBUG log entry, about 111
in total), the same browsers were affected as in 6). (To look them up, I
took the "expires" timestamp from the affected entries in the
storagerecords table and subtracted one year.)

9) There are lots of other browser versions in the logs which did not
lead to errors yet.


Maybe I should just give up and disable the attribute release consent
interceptor for this single service provider.

Kind regards,
Manuel


Am 21.09.2017 um 17:24 schrieb Manuel Haim:
> Hi Tom,
> 
> On 13.09.2017 22:37 Tom Zeller wrote:
>> With n.s.i.consent.flow.impl.ExtractConsent at debug, there should be
>> lines in idp-process.log that look like : [...]
> 
> oh, it seems that I tried to configure the logger within the
> idp.properties file (as it was included within the logback.xml file).
> Now that I configured it correctly within logback.xml, I can see
> additional debug output in idp-process.log.
> 
> Here is the debug output for a failing consent:
> 
> 2017-09-21 16:01:11,586 - DEBUG
> [net.shibboleth.idp.consent.flow.impl.ExtractConsent:81] - Profile
> Action ExtractConsent: Extracted consent ids
> '[["uid","eduPersonScopedAffiliation","eduPersonEntitlement","UniMrLinkToPeople"]]'
> from request parameter '_shib_idp_consentIds'
> 
> 2017-09-21 16:01:11,587 - DEBUG
> [net.shibboleth.idp.consent.flow.impl.ExtractConsent:93] - Profile
> Action ExtractConsent: Consent context
> 'ConsentContext{previousConsents={}, chosenConsents={uid=Consent{id=uid,
> value=uxC/yjVxnyTNxxpWA5+THwS3bM9UtFLEg2mIJ28VRiw=, isApproved=false},
> eduPersonScopedAffiliation=Consent{id=eduPersonScopedAffiliation,
> value=E2mLrN74C6pSz08GRnpRDxdWw5Tl0zxSpFu7+ka0dWM=, isApproved=false},
> eduPersonEntitlement=Consent{id=eduPersonEntitlement,
> value=x7wtAxaDrz4H9nu67g7puu14HK79scDoXKXNppyUJk8=, isApproved=false},
> UniMrLinkToPeople=Consent{id=UniMrLinkToPeople,
> value=sgVy8m8WlL3yTx07qBUkfUQFq+b9FTda6SE6gTyLO9k=, isApproved=false}}}'
> 
> I am also starting to log the Referer and User-Agent headers on my load
> balancer now, so maybe I can find the culprit browsers.
> 
> Kind regards,
> Manuel
> 
>