ResultCache values not reflecting LDAP values

David Bantz dabantz at alaska.edu
Wed Jul 9 13:51:29 EDT 2014 

In the absence of better informed response, is the following a possible explanation?

Is is conceivable that the attribute FILTER removes ePA from the cached LDAP results because it has not been encoded?  That seems odd, but would explain why the next trip through the resolver using the cache, the resolver finds 0 values.

(Why isn’t ePA encoded? My attribute resolver relies on ePA from our LDAP directory, and manipulates the values of ePA in the definition of a locally-defined attribute that has Member or Attribute added as appropriate to whatever values are in the LDAP directory.  It’s that locally-defined attribute with augmented values that is with SAML name urn:oid:1.3.6.1.4.1.5923.1.1.1.1  - that is, as ePA.)

David Bantz
 
On Tue, 8 Jul 2014, at 16:53 , David Bantz <dabantz at Alaska.edu> wrote:

> A user with values of an attribute (ePA) in LDAP has the correct values retrieved and subsequently released the first time through, but on subsequent request, using cached values, logs indicate 0 values for the attribute when using the cache.
> 
> Has anyone a theory or a workaround (other than turning off the ResultsCache)?
> 
> David Bantz
> 
> Pertinent lines from the process log with key snippets underlined:
> 
> 16:32:23.009 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:354] - Resolving data connector myLDAP for principal tabbey
> 16:32:23.010 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:308] - Search filter: (|(uid=tabbey)(uasystemid=tabbey)(bannerid=tabbey))
> 16:32:23.010 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:344] - LDAP data connector myLDAP - Checking cache for search results
> 16:32:23.010 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:351] - LDAP data connector myLDAP - No results cached for search filter '(|(uid=tabbey)(uasystemid=tabbey)(bannerid=tabbey))'
> 16:32:23.010 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:363] - LDAP data connector myLDAP - Retrieving attributes from LDAP
> 16:32:23.087 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:414] - LDAP data connector myLDAP - Found the following attribute: uid[1XJWUFPD01]
> 16:32:23.087 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:414] - LDAP data connector myLDAP - Found the following attribute: eduPersonAffiliation[Staff, Employee]
> 
> 16:32:23.100 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:314] - Resolving attribute eduPersonAffiliation for principal tabbey
> 16:32:23.107 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:336] - Resolved attribute eduPersonAffiliation containing 2 values
> 
> 16:32:23.587 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:336] - Resolved attribute eduPersonAffiliation containing 2 values
> 16:32:23.593 - DEBUG [edu.internet2.middleware.shibboleth.resolver.Script.scriptTest:-1] -  ePA script; starting uakePA values: [Staff, Employee]
> 16:32:23.593 - DEBUG [edu.internet2.middleware.shibboleth.resolver.Script.scriptTest:-1] -  ePA script: include Member; uakePA  values: [Staff, Employee]
> 16:32:23.593 - DEBUG [edu.internet2.middleware.shibboleth.resolver.Script.scriptTest:-1] -  ePA script non-S/E/S/F; uakePA values: [Staff, Employee]
> 16:32:23.594 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:336] - Resolved attribute uakeduPersonAffiliation containing 3 values
> 
> 16:32:23.605 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:468] - Attribute eduPersonAffiliation has 2 values after post-processing
> 
> 16:32:23.612 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:468] - Attribute uakeduPersonAffiliation has 3 values after post-processing
> 
> 16:32:23.625 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:163] - Processing permit value rule for attribute assignmentCount for principal tabbey
> 16:32:23.625 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:163] - Processing permit value rule for attribute creditHoursCurrent for principal tabbey
> 16:32:23.625 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:163] - Processing permit value rule for attribute bannerID for principal tabbey
> 16:32:23.625 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:163] - Processing permit value rule for attribute uakeduPersonAffiliation for principal tabbey
> 16:32:23.625 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:163] - Processing permit value rule for attribute displayname for principal tabbey
> 16:32:23.625 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:163] - Processing permit value rule for attribute email for principal tabbey
> 
> 16:32:23.655 - DEBUG [PROTOCOL_MESSAGE:74] - 
> <?xml version="1.0" encoding="UTF-8"?><saml2p:Response xmlns:saml2p="urn:oasis:names:tc:SAML:2.0:protocol" Destination="https://demo.origamirisk.com/Origami/SSO/SamlLogin?providerAccount=UofAK" ID="_8c0967b2083811931f91d1f120a35077" InResponseTo="_63CBB1656DB783793AAD850D9ACB726C" IssueInstant="2014-07-09T00:32:23.635Z" Version="2.0">
> …
>          <saml2:Attribute FriendlyName="eduPersonAffiliation" Name="urn:oid:1.3.6.1.4.1.5923.1.1.1.1" NameFormat="urn:oasis:names:tc:SAML:2.0:attrname-format:uri">
>             <saml2:AttributeValue xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:type="xs:string">Member</saml2:AttributeValue>
>             <saml2:AttributeValue xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:type="xs:string">Staff</saml2:AttributeValue>
>             <saml2:AttributeValue xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:type="xs:string">Employee</saml2:AttributeValue>
>          </saml2:Attribute>
> …
> Now using a different browser just a few seconds later:
> 
> 16:33:02.797 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:478] - Basing previous session authentication on active authentication method urn:oasis:names:tc:SAML:2.0:ac:classes:Password16:33:02.797 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:467] - Authenticating user with previous session LoginHandler
> 16:33:02.797 - DEBUG [edu.internet2.middleware.assurance.mcb.authn.provider.MCBLoginHandler:91] - MCBConfiguration bean = [edu.internet2.middleware.assurance.mcb.authn.provider.MCBConfiguration at 15e3d24a]
> 16:33:02.798 - DEBUG [edu.internet2.middleware.assurance.mcb.authn.provider.MCBLoginHandler:105] - Relying party = [https://demo.origamirisk.com]
> 16:33:02.798 - DEBUG [edu.internet2.middleware.assurance.mcb.authn.provider.MCBLoginHandler:121] - Using existing IdP session for tabbey
> 
> 16:33:02.810 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:119] - shibboleth.AttributeResolver resolving attributes for principal tabbey
> 16:33:02.810 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:275] - Specific attributes for principal tabbey were not requested, resolving all attributes.
> 16:33:02.810 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:314] - Resolving attribute uid for principal tabbey
> 16:33:02.810 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:354] - Resolving data connector myLDAP for principal tabbey
> 16:33:02.812 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:308] - Search filter: (|(uid=tabbey)(uasystemid=tabbey)(bannerid=tabbey))
> 16:33:02.812 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:344] - LDAP data connector myLDAP - Checking cache for search results
> 16:33:02.813 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:347] - LDAP data connector myLDAP - Returning attributes from cache
> 16:33:02.813 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:336] - Resolved attribute uid containing 1 values
> 16:33:02.813 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:314] - Resolving attribute eduPersonAffiliation for principal tabbey
> 16:33:02.815 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:336] - Resolved attribute eduPersonAffiliation containing 0 values
> 
> --
> To unsubscribe from this list send an email to users-unsubscribe at shibboleth.net

-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://shibboleth.net/pipermail/users/attachments/20140709/fc6df369/attachment-0001.html 
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 163 bytes
Desc: Message signed with OpenPGP using GPGMail
Url : http://shibboleth.net/pipermail/users/attachments/20140709/fc6df369/attachment-0001.bin

More information about the users mailing list