SAML1.1 attribute release on Shib 3
Morris, Andi
amorris at cardiffmet.ac.uk
Wed Feb 15 11:17:08 EST 2017
Hi all,
I've read the Wiki, and searched the mailing list, but am still none the wiser to this issue. Please could somebody cast an eye to my setup and let me know where I'm going wrong?
I'm running Shib IdP 3.3.0 on CentOS 7 with Jetty 9.3 and Java 1.8.0_121
I'm successfully releasing attributes via SAML2 to the test UK Federation Service Provider, so I know my basic setup is working, however when I test for SAML1.1 connections with the same Service Provider I get a valid Shibboleth session, but no attributes released. We require SAML1.1 attributes to be released to the UK Federation as there are still some companies we use within that Federation that run SAML1.1.
Looking at my debug logs I can see that my user is authenticated, and the attributes are resolved, however I still can't see why they're not passed. It's specifically the eduPersonTargetedID, the eduPersonTargetedID.old and the eduPersonScopedAffiliation attributes that I want to be passed via SAML1.1. The other attributes are just being passed at the moment as part of my test/dev work on the IdP.
---------------------------------------------------------------------------------------------
My attribute filter shows:
<AttributeFilterPolicyGroup id="ShibbolethFilterPolicy"
xmlns="urn:mace:shibboleth:2.0:afp"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:schemaLocation="urn:mace:shibboleth:2.0:afp http://shibboleth.net/schema/idp/shibboleth-afp.xsd">
<AttributeFilterPolicy id="releaseToAnyone">
<PolicyRequirementRule xsi:type="ANY" />
<AttributeRule attributeID="eduPersonScopedAffiliation">
<PermitValueRule xsi:type="ANY" />
</AttributeRule>
<AttributeRule attributeID="eduPersonTargetedID">
<PermitValueRule xsi:type="ANY" />
</AttributeRule>
<AttributeRule attributeID="eduPersonTargetedID.old">
<PermitValueRule xsi:type="ANY" />
</AttributeRule>
</AttributeFilterPolicy>
-------------------------------------------------------------------------------------------------------------------------
My attribute resolver for the relevant attributes are:
<AttributeDefinition xsi:type="SAML2NameID" id="eduPersonTargetedID"
nameIdFormat="urn:oasis:names:tc:SAML:2.0:nameid-format:persistent" sourceAttributeID="computedID">
<Dependency ref="computedID" />
<AttributeEncoder xsi:type="SAML1XMLObject" name="urn:oid:1.3.6.1.4.1.5923.1.1.1.10" />
<AttributeEncoder xsi:type="SAML2XMLObject" name="urn:oid:1.3.6.1.4.1.5923.1.1.1.10" friendlyName="eduPersonTargetedID" />
</AttributeDefinition>
<AttributeDefinition xsi:type="Scoped" id="eduPersonTargetedID.old"
scope="%{idp.scope}" sourceAttributeID="computedID">
<Dependency ref="computedID" />
<AttributeEncoder xsi:type="SAML1ScopedString" name="urn:mace:dir:attribute-def:eduPersonTargetedID" />
</AttributeDefinition>
<AttributeDefinition id="eduPersonScopedAffiliation" xsi:type="Scoped" scope="%{idp.scope}" sourceAttributeID="affiliation">
<Dependency ref="staticAttributes" />
<AttributeEncoder xsi:type="SAML1ScopedString" name="urn:mace:dir:attribute-def:eduPersonScopedAffiliation" encodeType="false" />
<AttributeEncoder xsi:type="SAML2ScopedString" name="urn:oid:1.3.6.1.4.1.5923.1.1.1.9" friendlyName="eduPersonScopedAffiliation" encodeType="false" />
</AttributeDefinition>
<DataConnector xsi:type="ComputedId"
id="computedID"
generatedAttributeID="computedID"
sourceAttributeID="sAMAccountName"
salt="blahblahblah">
<Dependency ref="myLDAP" />
</DataConnector>
---------------------------------------------------------------------------------------
My debug log shows:
<snipped as message was too big for the list>
2017-02-15 15:26:12,633 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:411] - Attribute Resolver 'ShibbolethAttributeResolver': Resolving dependencies for 'eduPersonScopedAffiliation'
2017-02-15 15:26:12,633 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:367] - Attribute Resolver 'ShibbolethAttributeResolver': Resolving data connector staticAttributes
2017-02-15 15:26:12,634 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractDataConnector:139] - Data Connector 'staticAttributes': produced the following 1 attributes during resolution [affiliation]
2017-02-15 15:26:12,634 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractDataConnector:143] - Data Connector 'staticAttributes': Attribute 'affiliation': Values '[StringAttributeValue{value=member}]'
2017-02-15 15:26:12,634 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:385] - Attribute Resolver 'ShibbolethAttributeResolver': Data connector 'staticAttributes' resolved the following attributes: [affiliation]
2017-02-15 15:26:12,635 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:427] - Attribute Resolver 'ShibbolethAttributeResolver': Finished resolving dependencies for 'eduPersonScopedAffiliation'
2017-02-15 15:26:12,635 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractAttributeDefinition:247] - Attribute Definition 'eduPersonScopedAffiliation': produced an attribute with the following values [ScopedStringAttributeValue{value=member, scope=cardiffmet.ac.uk}]
2017-02-15 15:26:12,635 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:308] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute definition 'eduPersonScopedAffiliation' produced an attribute with 1 values
2017-02-15 15:26:12,636 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:411] - Attribute Resolver 'ShibbolethAttributeResolver': Resolving dependencies for 'eduPersonTargetedID'
2017-02-15 15:26:12,636 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:411] - Attribute Resolver 'ShibbolethAttributeResolver': Resolving dependencies for 'computedID'
2017-02-15 15:26:12,636 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:427] - Attribute Resolver 'ShibbolethAttributeResolver': Finished resolving dependencies for 'computedID'
2017-02-15 15:26:12,637 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:367] - Attribute Resolver 'ShibbolethAttributeResolver': Resolving data connector computedID
2017-02-15 15:26:12,637 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractDataConnector:139] - Data Connector 'computedID': produced the following 1 attributes during resolution [computedID]
2017-02-15 15:26:12,637 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractDataConnector:143] - Data Connector 'computedID': Attribute 'computedID': Values '[StringAttributeValue{value=MnfOovonkwgT2GZ17I5X9Kl5HiE=}]'
2017-02-15 15:26:12,638 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:385] - Attribute Resolver 'ShibbolethAttributeResolver': Data connector 'computedID' resolved the following attributes: [computedID]
2017-02-15 15:26:12,638 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:427] - Attribute Resolver 'ShibbolethAttributeResolver': Finished resolving dependencies for 'eduPersonTargetedID'
2017-02-15 15:26:12,638 - DEBUG [net.shibboleth.idp.saml.attribute.resolver.impl.SAML2NameIDAttributeDefinition:153] - Attribute Definition 'eduPersonTargetedID': building a SAML2 NameID with value of 'MnfOovonkwgT2GZ17I5X9Kl5HiE='
2017-02-15 15:26:12,639 - DEBUG [net.shibboleth.idp.saml.attribute.resolver.impl.SAML2NameIDAttributeDefinition:164] - Attribute Definition 'eduPersonTargetedID': Format set to 'urn:oasis:names:tc:SAML:2.0:nameid-format:persistent'
2017-02-15 15:26:12,639 - DEBUG [net.shibboleth.idp.saml.attribute.resolver.impl.SAML2NameIDAttributeDefinition:172] - Attribute Definition 'eduPersonTargetedID': NameQualifier set to 'https://idp3.dev.cardiffmet.ac.uk/idp/shibboleth'
2017-02-15 15:26:12,639 - DEBUG [net.shibboleth.idp.saml.attribute.resolver.impl.SAML2NameIDAttributeDefinition:182] - Attribute Definition 'eduPersonTargetedID': SPNameQualifier set to 'https://test.ukfederation.org.uk/entity'
2017-02-15 15:26:12,640 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractAttributeDefinition:247] - Attribute Definition 'eduPersonTargetedID': produced an attribute with the following values [XMLObjectAttributeValue{value=org.opensaml.saml.saml2.core.impl.NameIDImpl at 2a6763c5}]
2017-02-15 15:26:12,640 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:308] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute definition 'eduPersonTargetedID' produced an attribute with 1 values
2017-02-15 15:26:12,640 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:411] - Attribute Resolver 'ShibbolethAttributeResolver': Resolving dependencies for 'surname'
2017-02-15 15:26:12,641 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:427] - Attribute Resolver 'ShibbolethAttributeResolver': Finished resolving dependencies for 'surname'
2017-02-15 15:26:12,641 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractAttributeDefinition:247] - Attribute Definition 'surname': produced an attribute with the following values [StringAttributeValue{value=user}]
2017-02-15 15:26:12,641 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:308] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute definition 'surname' produced an attribute with 1 values
2017-02-15 15:26:12,642 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:411] - Attribute Resolver 'ShibbolethAttributeResolver': Resolving dependencies for 'displayName'
2017-02-15 15:26:12,642 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:427] - Attribute Resolver 'ShibbolethAttributeResolver': Finished resolving dependencies for 'displayName'
2017-02-15 15:26:12,642 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractAttributeDefinition:247] - Attribute Definition 'displayName': produced an attribute with the following values [StringAttributeValue{value=user, test}]
2017-02-15 15:26:12,643 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:308] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute definition 'displayName' produced an attribute with 1 values
2017-02-15 15:26:12,643 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:411] - Attribute Resolver 'ShibbolethAttributeResolver': Resolving dependencies for 'givenName'
2017-02-15 15:26:12,643 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:427] - Attribute Resolver 'ShibbolethAttributeResolver': Finished resolving dependencies for 'givenName'
2017-02-15 15:26:12,644 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractAttributeDefinition:247] - Attribute Definition 'givenName': produced an attribute with the following values [StringAttributeValue{value=test}]
2017-02-15 15:26:12,644 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:308] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute definition 'givenName' produced an attribute with 1 values
2017-02-15 15:26:12,644 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:411] - Attribute Resolver 'ShibbolethAttributeResolver': Resolving dependencies for 'eduPersonPrincipalName'
2017-02-15 15:26:12,645 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:427] - Attribute Resolver 'ShibbolethAttributeResolver': Finished resolving dependencies for 'eduPersonPrincipalName'
2017-02-15 15:26:12,645 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractAttributeDefinition:247] - Attribute Definition 'eduPersonPrincipalName': produced an attribute with the following values [ScopedStringAttributeValue{value=testuser, scope=cardiffmet.ac.uk}]
2017-02-15 15:26:12,646 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:308] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute definition 'eduPersonPrincipalName' produced an attribute with 1 values
2017-02-15 15:26:12,646 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:411] - Attribute Resolver 'ShibbolethAttributeResolver': Resolving dependencies for 'eduPersonTargetedID.old'
2017-02-15 15:26:12,646 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:427] - Attribute Resolver 'ShibbolethAttributeResolver': Finished resolving dependencies for 'eduPersonTargetedID.old'
2017-02-15 15:26:12,646 - DEBUG [net.shibboleth.idp.attribute.resolver.AbstractAttributeDefinition:247] - Attribute Definition 'eduPersonTargetedID.old': produced an attribute with the following values [ScopedStringAttributeValue{value=MnfOovonkwgT2GZ17I5X9Kl5HiE=, scope=cardiffmet.ac.uk}]
2017-02-15 15:26:12,647 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:308] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute definition 'eduPersonTargetedID.old' produced an attribute with 1 values
2017-02-15 15:26:12,647 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:231] - Attribute Resolver 'ShibbolethAttributeResolver': Finalizing resolved attributes
2017-02-15 15:26:12,648 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:473] - Attribute Resolver 'ShibbolethAttributeResolver': De-duping attribute definition uid result
2017-02-15 15:26:12,648 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:485] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute 'uid' has 1 values after post-processing
2017-02-15 15:26:12,648 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:473] - Attribute Resolver 'ShibbolethAttributeResolver': De-duping attribute definition mail result
2017-02-15 15:26:12,648 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:485] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute 'mail' has 1 values after post-processing
2017-02-15 15:26:12,649 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:473] - Attribute Resolver 'ShibbolethAttributeResolver': De-duping attribute definition eduPersonScopedAffiliation result
2017-02-15 15:26:12,649 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:485] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute 'eduPersonScopedAffiliation' has 1 values after post-processing
2017-02-15 15:26:12,649 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:473] - Attribute Resolver 'ShibbolethAttributeResolver': De-duping attribute definition eduPersonTargetedID result
2017-02-15 15:26:12,650 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:485] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute 'eduPersonTargetedID' has 1 values after post-processing
2017-02-15 15:26:12,650 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:473] - Attribute Resolver 'ShibbolethAttributeResolver': De-duping attribute definition surname result
2017-02-15 15:26:12,650 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:485] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute 'surname' has 1 values after post-processing
2017-02-15 15:26:12,651 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:473] - Attribute Resolver 'ShibbolethAttributeResolver': De-duping attribute definition displayName result
2017-02-15 15:26:12,651 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:485] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute 'displayName' has 1 values after post-processing
2017-02-15 15:26:12,651 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:473] - Attribute Resolver 'ShibbolethAttributeResolver': De-duping attribute definition givenName result
2017-02-15 15:26:12,652 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:485] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute 'givenName' has 1 values after post-processing
2017-02-15 15:26:12,652 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:473] - Attribute Resolver 'ShibbolethAttributeResolver': De-duping attribute definition eduPersonPrincipalName result
2017-02-15 15:26:12,652 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:485] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute 'eduPersonPrincipalName' has 1 values after post-processing
2017-02-15 15:26:12,653 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:473] - Attribute Resolver 'ShibbolethAttributeResolver': De-duping attribute definition eduPersonTargetedID.old result
2017-02-15 15:26:12,653 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:485] - Attribute Resolver 'ShibbolethAttributeResolver': Attribute 'eduPersonTargetedID.old' has 1 values after post-processing
2017-02-15 15:26:12,653 - DEBUG [net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:236] - Attribute Resolver 'ShibbolethAttributeResolver': Final resolved attribute collection: [uid, eduPersonScopedAffiliation, mail, eduPersonTargetedID, displayName, surname, givenName, eduPersonPrincipalName, eduPersonTargetedID.old]
2017-02-15 15:26:12,659 - DEBUG [net.shibboleth.idp.attribute.filter.impl.AttributeFilterImpl:125] - Attribute filtering engine 'ShibbolethAttributeFilter' Beginning process of filtering the following 9 attributes: [uid, eduPersonScopedAffiliation, mail, eduPersonTargetedID, displayName, surname, givenName, eduPersonPrincipalName, eduPersonTargetedID.old]
2017-02-15 15:26:12,659 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeFilterPolicy:128] - Attribute Filter Policy 'releaseToAnyone' Checking if attribute filter policy is active
2017-02-15 15:26:12,660 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeFilterPolicy:135] - Attribute Filter Policy 'releaseToAnyone' Policy is active for this request
2017-02-15 15:26:12,660 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeFilterPolicy:162] - Attribute Filter Policy 'releaseToAnyone' Applying attribute filter policy to current set of attributes: [uid, eduPersonScopedAffiliation, mail, eduPersonTargetedID, displayName, surname, givenName, eduPersonPrincipalName, eduPersonTargetedID.old]
2017-02-15 15:26:12,660 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:168] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_5ab7428aa93ae940280eea797d215c69' Filtering values for attribute 'eduPersonScopedAffiliation' which currently contains 1 values
2017-02-15 15:26:12,661 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:177] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_5ab7428aa93ae940280eea797d215c69' Filter has permitted the release of 1 values for attribute 'eduPersonScopedAffiliation'
2017-02-15 15:26:12,661 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:168] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_458e6c7d5f3133457c8bc39701ec43d9' Filtering values for attribute 'eduPersonTargetedID' which currently contains 1 values
2017-02-15 15:26:12,661 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:177] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_458e6c7d5f3133457c8bc39701ec43d9' Filter has permitted the release of 1 values for attribute 'eduPersonTargetedID'
2017-02-15 15:26:12,662 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:168] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_3bb1cacc64690900a1073ac27b34c03d' Filtering values for attribute 'eduPersonTargetedID.old' which currently contains 1 values
2017-02-15 15:26:12,662 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:177] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_3bb1cacc64690900a1073ac27b34c03d' Filter has permitted the release of 1 values for attribute 'eduPersonTargetedID.old'
2017-02-15 15:26:12,662 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeFilterPolicy:128] - Attribute Filter Policy 'testukfed' Checking if attribute filter policy is active
2017-02-15 15:26:12,663 - DEBUG [net.shibboleth.idp.attribute.filter.policyrule.filtercontext.impl.AttributeRequesterPolicyRule:54] - Attribute Filter '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/PolicyRequirementRule:_0abb1037a08cee8f9b5d275f2001c5d8': Found attribute requester: https://test.ukfederation.org.uk/entity
2017-02-15 15:26:12,663 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeFilterPolicy:135] - Attribute Filter Policy 'testukfed' Policy is active for this request
2017-02-15 15:26:12,663 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeFilterPolicy:162] - Attribute Filter Policy 'testukfed' Applying attribute filter policy to current set of attributes: [uid, eduPersonScopedAffiliation, mail, eduPersonTargetedID, displayName, surname, givenName, eduPersonPrincipalName, eduPersonTargetedID.old]
2017-02-15 15:26:12,663 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:168] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_20344d77d50a8dde58b34facd2067562' Filtering values for attribute 'eduPersonPrincipalName' which currently contains 1 values
2017-02-15 15:26:12,664 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:177] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_20344d77d50a8dde58b34facd2067562' Filter has permitted the release of 1 values for attribute 'eduPersonPrincipalName'
2017-02-15 15:26:12,664 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:168] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_5f5cf3bec6cc42c2de4fc9209f590346' Filtering values for attribute 'surname' which currently contains 1 values
2017-02-15 15:26:12,664 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:177] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_5f5cf3bec6cc42c2de4fc9209f590346' Filter has permitted the release of 1 values for attribute 'surname'
2017-02-15 15:26:12,665 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:168] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_3cfaa6b4476bd0b59ffd383288166a15' Filtering values for attribute 'mail' which currently contains 1 values
2017-02-15 15:26:12,665 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:177] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_3cfaa6b4476bd0b59ffd383288166a15' Filter has permitted the release of 1 values for attribute 'mail'
2017-02-15 15:26:12,665 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:168] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_168ada5c38c54795258752b67e1125c7' Filtering values for attribute 'givenName' which currently contains 1 values
2017-02-15 15:26:12,666 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:177] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_168ada5c38c54795258752b67e1125c7' Filter has permitted the release of 1 values for attribute 'givenName'
2017-02-15 15:26:12,666 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:168] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_082614391c79927faf2bfbcf454d11d7' Filtering values for attribute 'uid' which currently contains 1 values
2017-02-15 15:26:12,666 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeRule:177] - Attribute filtering engine '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeRule:_082614391c79927faf2bfbcf454d11d7' Filter has permitted the release of 1 values for attribute 'uid'
2017-02-15 15:26:12,667 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeFilterPolicy:128] - Attribute Filter Policy 'devlearn' Checking if attribute filter policy is active
2017-02-15 15:26:12,667 - DEBUG [net.shibboleth.idp.attribute.filter.policyrule.filtercontext.impl.AttributeRequesterPolicyRule:54] - Attribute Filter '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/PolicyRequirementRule:_964b6f6e8aee4466cd733dcd54aea262': Found attribute requester: https://test.ukfederation.org.uk/entity
2017-02-15 15:26:12,667 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeFilterPolicy:137] - Attribute Filter Policy 'devlearn' Policy is not active for this request
2017-02-15 15:26:12,668 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeFilterPolicy:128] - Attribute Filter Policy 'example2' Checking if attribute filter policy is active
2017-02-15 15:26:12,668 - DEBUG [net.shibboleth.idp.attribute.filter.policyrule.filtercontext.impl.AttributeRequesterPolicyRule:54] - Attribute Filter '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/Rule:_e1762729d0a7914eb4752b0cda31d266': Found attribute requester: https://test.ukfederation.org.uk/entity
2017-02-15 15:26:12,668 - DEBUG [net.shibboleth.idp.attribute.filter.policyrule.filtercontext.impl.AttributeRequesterPolicyRule:54] - Attribute Filter '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/Rule:_75e14dec5d7dfe7e62d322f64f55a0bd': Found attribute requester: https://test.ukfederation.org.uk/entity
2017-02-15 15:26:12,669 - DEBUG [net.shibboleth.idp.attribute.filter.AttributeFilterPolicy:137] - Attribute Filter Policy 'example2' Policy is not active for this request
2017-02-15 15:26:12,669 - DEBUG [net.shibboleth.idp.attribute.filter.impl.AttributeFilterImpl:189] - Attribute filtering engine 'ShibbolethAttributeFilter': 1 values for attribute 'uid' remained after filtering
2017-02-15 15:26:12,669 - DEBUG [net.shibboleth.idp.attribute.filter.impl.AttributeFilterImpl:189] - Attribute filtering engine 'ShibbolethAttributeFilter': 1 values for attribute 'eduPersonScopedAffiliation' remained after filtering
2017-02-15 15:26:12,670 - DEBUG [net.shibboleth.idp.attribute.filter.impl.AttributeFilterImpl:189] - Attribute filtering engine 'ShibbolethAttributeFilter': 1 values for attribute 'mail' remained after filtering
2017-02-15 15:26:12,670 - DEBUG [net.shibboleth.idp.attribute.filter.impl.AttributeFilterImpl:189] - Attribute filtering engine 'ShibbolethAttributeFilter': 1 values for attribute 'eduPersonTargetedID' remained after filtering
2017-02-15 15:26:12,670 - DEBUG [net.shibboleth.idp.attribute.filter.impl.AttributeFilterImpl:176] - Attribute filtering engine 'ShibbolethAttributeFilter': no policy permitted release of attribute displayName values
2017-02-15 15:26:12,671 - DEBUG [net.shibboleth.idp.attribute.filter.impl.AttributeFilterImpl:189] - Attribute filtering engine 'ShibbolethAttributeFilter': 1 values for attribute 'surname' remained after filtering
2017-02-15 15:26:12,671 - DEBUG [net.shibboleth.idp.attribute.filter.impl.AttributeFilterImpl:189] - Attribute filtering engine 'ShibbolethAttributeFilter': 1 values for attribute 'givenName' remained after filtering
2017-02-15 15:26:12,671 - DEBUG [net.shibboleth.idp.attribute.filter.impl.AttributeFilterImpl:189] - Attribute filtering engine 'ShibbolethAttributeFilter': 1 values for attribute 'eduPersonPrincipalName' remained after filtering
2017-02-15 15:26:12,672 - DEBUG [net.shibboleth.idp.attribute.filter.impl.AttributeFilterImpl:189] - Attribute filtering engine 'ShibbolethAttributeFilter': 1 values for attribute 'eduPersonTargetedID.old' remained after filtering
2017-02-15 15:26:12,688 - DEBUG [net.shibboleth.idp.saml.profile.impl.BaseAddAuthenticationStatementToAssertion:170] - Profile Action AddAuthenticationStatementToAssertion: Attempting to add an AuthenticationStatement to outgoing Assertion
2017-02-15 15:26:12,689 - DEBUG [net.shibboleth.idp.saml.saml1.profile.impl.AddAuthenticationStatementToAssertion:142] - Profile Action AddAuthenticationStatementToAssertion: Added AuthenticationStatement to Assertion _471caf9ce94e694fca247fd2d166d0a7
2017-02-15 15:26:12,698 - DEBUG [net.shibboleth.idp.saml.profile.logic.DefaultNameIdentifierFormatStrategy:124] - Configuration specifies the following formats: []
2017-02-15 15:26:12,699 - DEBUG [net.shibboleth.idp.saml.profile.logic.DefaultNameIdentifierFormatStrategy:134] - No formats specified in configuration or in metadata, returning default
2017-02-15 15:26:12,733 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:179] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler of type 'org.opensaml.messaging.handler.impl.BasicMessageHandlerChain' on OUTBOUND message context
2017-02-15 15:26:12,733 - DEBUG [net.shibboleth.idp.profile.impl.WebFlowMessageHandlerAdaptor:195] - Profile Action WebFlowMessageHandlerAdaptor: Invoking message handler on message context containing a message of type 'org.opensaml.saml.saml1.core.impl.ResponseImpl'
2017-02-15 15:26:12,748 - DEBUG [net.shibboleth.idp.saml.profile.impl.SpringAwareMessageEncoderFactory:100] - Looking up message encoder based on binding URI: urn:oasis:names:tc:SAML:1.0:profiles:browser-post
2017-02-15 15:26:12,758 - DEBUG [net.shibboleth.idp.profile.impl.RecordResponseComplete:89] - Profile Action RecordResponseComplete: Record response complete
2017-02-15 15:26:12,759 - INFO [Shibboleth-Audit.SSO:241] - 20170215T152612Z|urn:mace:shibboleth:1.0:profiles:AuthnRequest|_8f52e781-b2ff-4217-9966-b855cfc9f867|https://test.ukfederation.org.uk/entity|http://shibboleth.net/ns/profiles/saml1/sso/browser|https://idp3.dev.cardiffmet.ac.uk/idp/shibboleth|urn:oasis:names:tc:SAML:1.0:profiles:browser-post|_1ab667e6f53463679511e6c1d0014dd5|testuser|urn:ietf:rfc:1510||AAdzZWNyZXQxQKh5JwTkZ+sL3kKxSbyx7ATKbZh69iNHRHoKkkI5ciA0mMZocZXhMZJM95XAY75lxaeCarS216Lhw/UvSmL3AaUyRbKzmmdTspdYooqTrflqvQKQU8UIDf5nKLEvLLw3OkC8J5REJhLE2hAx|_471caf9ce94e694fca247fd2d166d0a7|
----------------------------------------------------------------------------
I suspect it's something to do with the name ID, and so I tried uncommenting the following lines one at a time the in conf/saml-nameid.properties but this made no noticeable difference.
idp.nameid.saml1.legacyGenerator = shibboleth.LegacySAML1NameIdentifierGenerator (this is uncommented in the logs above)
#idp.nameid.saml1.default = urn:mace:shibboleth:1.0:nameIdentifier (this is commented in the logs above, although I have tried with it uncommented)
Apologies if this is something obvious I've missed somewhere.
Cheers,
Andi
________________________________
[Cardiff Metropolitan University - Queens Anniversary Prizes 2015]<http://www.cardiffmet.ac.uk/news/Pages/Cardiff-Met-research-recognised-in-Queens-Anniversary-Prizes-for-Higher-and-Further-Education.aspx>
More information about the users
mailing list