ResultCache values not reflecting LDAP values

David Bantz dabantz at alaska.edu
Tue Jul 8 20:53:07 EDT 2014 

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

-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://shibboleth.net/pipermail/users/attachments/20140708/b25a50e4/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/20140708/b25a50e4/attachment-0001.bin

More information about the users mailing list