<html>
<head>
<meta http-equiv="Content-Type" content="text/html; charset=Windows-1252">
</head>
<body style="word-wrap: break-word; -webkit-nbsp-mode: space; -webkit-line-break: after-white-space; ">
<div style="color: rgb(0, 0, 0); font-family: Calibri, sans-serif; font-size: 14px; ">
Hello all,</div>
<div style="color: rgb(0, 0, 0); font-family: Calibri, sans-serif; font-size: 14px; ">
<br>
</div>
<div><font face="Calibri,sans-serif">We're running the Shibboleth IdP 2.1.2 and are members of incommon. We've recently been trying to interoperate with a new SP and are running into issues with their attribute request. The end result is an exception "</font><span style="color: rgb(0, 0, 0); font-family: Helvetica; font-size: 12px; ">Client
certificate authentication failed for context issuer entity ID", but, it appears the real issue has to do with the line: "</span><font face="Helvetica"><span style="font-size: 12px;">Failed to validate untrusted credential against trusted key" as other InCommon
member SPs succeed at this point with the messages:</span></font></div>
<div><font face="Helvetica"><span style="font-size: 12px;"><br>
</span></font></div>
<div>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:46:39.552 - DEBUG [org.opensaml.xml.security.trust.ExplicitKeyTrustEvaluator:90] - Successfully validated untrusted credential against trusted key</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:46:39.553 - DEBUG [org.opensaml.xml.security.trust.ChainingTrustEngine:59] - Token was trusted by chain member: org.opensaml.xml.security.trust.ExplicitKeyTrustEngine</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:46:39.553 - INFO [org.opensaml.ws.security.provider.ClientCertAuthRule:137] - Authentication via client certificate succeeded for context issuer entity ID: https://Working-SP/</p>
</div>
<div><br>
</div>
<div>This is a little deep for me and I'm not totally sure where to look next to figure out what's going wrong. I've seen some past archive messages that seem close to what I'm running into, but, don't quite fit 100% (nor do the proposed solutions fix the
problem). I'd really appreciate some help and guidance on finding a solution to this problem! Below is the debug log I described above. I tried to keep it as concise as possible, and so, if more detail would be helpful, please let me know. I masked
the names of the Sps involved.. </div>
<div><br>
</div>
<div>Thank you very much for your help,</div>
<div><br>
</div>
<div>..Sean.</div>
<div><br>
</div>
<div>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.745 - DEBUG [org.opensaml.ws.message.decoder.BaseMessageDecoder:82] - Evaluating security policy of type 'edu.internet2.middleware.shibboleth.common.security.ShibbolethSecurityPolicy'
for decoded message</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.745 - DEBUG [org.opensaml.util.storage.ReplayCache:91] - Attempting to acquire lock for replay cache check</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.745 - DEBUG [org.opensaml.util.storage.ReplayCache:93] - Lock acquired</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.747 - DEBUG [org.opensaml.util.storage.ReplayCache:104] - Message ID _ef3a1721869276ca915103002f9ba164 was not a replay</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.748 - DEBUG [org.opensaml.util.storage.ReplayCache:131] - Writing message ID https://Broken-SP/shibboleth_ef3a1721869276ca915103002f9ba164 to replay cache with expiration time 2013-01-09T16:52:23.748-05:00</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.750 - INFO [org.opensaml.common.binding.security.SAMLProtocolMessageXMLSignatureSecurityPolicyRule:99] - SAML protocol message was not signed, skipping XML signature processing</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.751 - DEBUG [org.opensaml.ws.security.provider.ClientCertAuthRule:135] - Attempting client certificate authentication using context issuer: https://Broken-SP/shibboleth</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.751 - DEBUG [org.opensaml.xml.security.trust.ExplicitKeyTrustEngine:68] - Attempting to validate untrusted credential</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.751 - DEBUG [org.opensaml.security.MetadataCredentialResolver:157] - Forcing on-demand metadata provider refresh if necessary</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.752 - DEBUG [org.opensaml.security.MetadataCredentialResolver:205] - Attempting to retrieve credentials from cache using index: [https://Broken-SP/shibboleth,{urn:oasis:names:tc:SAML:2.0:metadata}SPSSODescriptor,urn:oasis:names:tc:SAML:1.1:protocol,SIGNING]</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.752 - DEBUG [org.opensaml.security.MetadataCredentialResolver:222] - Unable to retrieve credentials from cache using index: [https://Broken-SP/shibboleth,{urn:oasis:names:tc:SAML:2.0:metadata}SPSSODescriptor,urn:oasis:names:tc:SAML:1.1:protocol,SIGNING]</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.752 - DEBUG [org.opensaml.security.MetadataCredentialResolver:242] - Attempting to retrieve credentials from metadata for entity: https://Broken-SP/shibboleth</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.753 - DEBUG [org.opensaml.security.MetadataCredentialResolver:314] - Retrieving metadata for entity 'https://Broken-SP/shibboleth' in role '{urn:oasis:names:tc:SAML:2.0:metadata}SPSSODescriptor'
for protocol 'urn:oasis:names:tc:SAML:1.1:protocol'</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.753 - DEBUG [org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:194] - Checking child metadata provider for entity descriptor with entity ID: https://Broken-SP/shibboleth</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.753 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:206] - Searching for entity descriptor with an entity ID of https://Broken-SP/shibboleth</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.753 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:77] - Metadata document does not contain an EntityDescriptor with the ID https://Broken-SP/shibboleth</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.754 - DEBUG [org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:194] - Checking child metadata provider for entity descriptor with entity ID: https://Broken-SP/shibboleth</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.754 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:206] - Searching for entity descriptor with an entity ID of https://Broken-SP/shibboleth</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.754 - DEBUG [org.opensaml.xml.security.keyinfo.BasicProviderKeyInfoCredentialResolver:328] - Found 0 key names: org.opensaml.xml.util.LazySet@3d9b23</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.754 - DEBUG [org.opensaml.xml.security.keyinfo.BasicProviderKeyInfoCredentialResolver:253] - Processing KeyInfo child with qname: {http://www.w3.org/2000/09/xmldsig#}X509Data</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.755 - DEBUG [org.opensaml.xml.security.keyinfo.BasicProviderKeyInfoCredentialResolver:291] - Provider org.opensaml.xml.security.keyinfo.provider.RSAKeyValueProvider doesn't handle objects
of type {http://www.w3.org/2000/09/xmldsig#}X509Data, skipping</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.755 - DEBUG [org.opensaml.xml.security.keyinfo.BasicProviderKeyInfoCredentialResolver:291] - Provider org.opensaml.xml.security.keyinfo.provider.DSAKeyValueProvider doesn't handle objects
of type {http://www.w3.org/2000/09/xmldsig#}X509Data, skipping</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.755 - DEBUG [org.opensaml.xml.security.keyinfo.BasicProviderKeyInfoCredentialResolver:296] - Processing KeyInfo child {http://www.w3.org/2000/09/xmldsig#}X509Data with provider org.opensaml.xml.security.keyinfo.provider.InlineX509DataProvider</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.756 - DEBUG [org.opensaml.xml.security.keyinfo.provider.InlineX509DataProvider:122] - Attempting to extract credential from an X509Data</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.763 - DEBUG [org.opensaml.xml.security.keyinfo.provider.InlineX509DataProvider:195] - Found 1 X509Certificates</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.763 - DEBUG [org.opensaml.xml.security.keyinfo.provider.InlineX509DataProvider:176] - Found 0 X509CRLs</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.763 - DEBUG [org.opensaml.xml.security.keyinfo.provider.InlineX509DataProvider:214] - Single certificate was present, treating as end-entity certificate</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.764 - DEBUG [org.opensaml.xml.security.keyinfo.BasicProviderKeyInfoCredentialResolver:301] - Credentials successfully extracted from child {http://www.w3.org/2000/09/xmldsig#}X509Data
by provider org.opensaml.xml.security.keyinfo.provider.InlineX509DataProvider</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.764 - DEBUG [org.opensaml.xml.security.keyinfo.BasicProviderKeyInfoCredentialResolver:161] - A total of 1 credentials were resolved</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.764 - DEBUG [org.opensaml.xml.security.credential.criteria.EvaluableCredentialCriteriaRegistry:106] - Registry could not locate evaluable criteria for criteria class org.opensaml.xml.security.keyinfo.KeyInfoCriteria</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.765 - DEBUG [org.opensaml.security.MetadataCredentialResolver:347] - Added new credential collection to cache with key: [https://Broken-SP/shibboleth,{urn:oasis:names:tc:SAML:2.0:metadata}SPSSODescriptor,urn:oasis:names:tc:SAML:1.1:protocol,SIGNING]</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.765 - DEBUG [org.opensaml.xml.security.credential.criteria.EvaluableCredentialCriteriaRegistry:75] - Registry located evaluable criteria class org.opensaml.xml.security.credential.criteria.EvaluableUsageCredentialCriteria
for criteria class org.opensaml.xml.security.criteria.UsageCriteria</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.765 - DEBUG [org.opensaml.xml.security.credential.criteria.EvaluableCredentialCriteriaRegistry:106] - Registry could not locate evaluable criteria for criteria class org.opensaml.security.MetadataCriteria</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.765 - DEBUG [org.opensaml.xml.security.credential.criteria.EvaluableCredentialCriteriaRegistry:75] - Registry located evaluable criteria class org.opensaml.xml.security.credential.criteria.EvaluableEntityIDCredentialCriteria
for criteria class org.opensaml.xml.security.criteria.EntityIDCriteria</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.766 - DEBUG [org.opensaml.xml.security.trust.ExplicitKeyTrustEvaluator:94] - Failed to validate untrusted credential against trusted key</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.766 - DEBUG [org.opensaml.xml.security.x509.PKIXX509CredentialTrustEngine:119] - Attempting PKIX validation of untrusted credential</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.766 - DEBUG [edu.internet2.middleware.shibboleth.common.security.MetadataPKIXValidationInformationResolver:188] - Forcing on-demand metadata provider refresh if necessary</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.768 - DEBUG [edu.internet2.middleware.shibboleth.common.security.MetadataPKIXValidationInformationResolver:600] - Attempting to retrieve trusted names from cache using index: [https://Broken-SP/shibboleth,{urn:oasis:names:tc:SAML:2.0:metadata}SPSSODescriptor,urn:oasis:names:tc:SAML:1.1:protocol,SIGNING]</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.768 - DEBUG [edu.internet2.middleware.shibboleth.common.security.MetadataPKIXValidationInformationResolver:603] - Read lock over cache acquired</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.769 - DEBUG [edu.internet2.middleware.shibboleth.common.security.MetadataPKIXValidationInformationResolver:614] - Read lock over cache released</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.769 - DEBUG [edu.internet2.middleware.shibboleth.common.security.MetadataPKIXValidationInformationResolver:617] - Unable to retrieve trusted names from cache using index: [https://Broken-SP/shibboleth,{urn:oasis:names:tc:SAML:2.0:metadata}SPSSODescriptor,urn:oasis:names:tc:SAML:1.1:protocol,SIGNING]</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.769 - DEBUG [edu.internet2.middleware.shibboleth.common.security.MetadataPKIXValidationInformationResolver:437] - Attempting to retrieve trusted names for PKIX validation from metadata
for entity: https://Broken-SP/shibboleth</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.770 - DEBUG [org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:194] - Checking child metadata provider for entity descriptor with entity ID: https://Broken-SP/shibboleth</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.770 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:206] - Searching for entity descriptor with an entity ID of https://Broken-SP/shibboleth</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.770 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:77] - Metadata document does not contain an EntityDescriptor with the ID https://Broken-SP/shibboleth</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.770 - DEBUG [org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:194] - Checking child metadata provider for entity descriptor with entity ID: https://Broken-SP/shibboleth</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.771 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:206] - Searching for entity descriptor with an entity ID of https://Broken-SP/shibboleth</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.771 - DEBUG [edu.internet2.middleware.shibboleth.common.security.MetadataPKIXValidationInformationResolver:671] - Write lock over cache acquired</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.771 - DEBUG [edu.internet2.middleware.shibboleth.common.security.MetadataPKIXValidationInformationResolver:674] - Added new PKIX info to entity cache with key: [https://Broken-SP/shibboleth,{urn:oasis:names:tc:SAML:2.0:metadata}SPSSODescriptor,urn:oasis:names:tc:SAML:1.1:protocol,SIGNING]</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.772 - DEBUG [edu.internet2.middleware.shibboleth.common.security.MetadataPKIXValidationInformationResolver:677] - Write lock over cache released</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.772 - DEBUG [edu.internet2.middleware.shibboleth.common.security.MetadataPKIXValidationInformationResolver:151] - Forcing on-demand metadata provider refresh if necessary</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.772 - DEBUG [edu.internet2.middleware.shibboleth.common.security.MetadataPKIXValidationInformationResolver:530] - Attempting to retrieve PKIX validation info from cache using index:
[https://Broken-SP/shibboleth,{urn:oasis:names:tc:SAML:2.0:metadata}SPSSODescriptor,urn:oasis:names:tc:SAML:1.1:protocol,SIGNING]</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.772 - DEBUG [edu.internet2.middleware.shibboleth.common.security.MetadataPKIXValidationInformationResolver:533] - Read lock over cache acquired</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.773 - DEBUG [edu.internet2.middleware.shibboleth.common.security.MetadataPKIXValidationInformationResolver:544] - Read lock over cache released</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.773 - DEBUG [edu.internet2.middleware.shibboleth.common.security.MetadataPKIXValidationInformationResolver:547] - Unable to retrieve PKIX validation info from cache using index: [https://Broken-SP/shibboleth,{urn:oasis:names:tc:SAML:2.0:metadata}SPSSODescriptor,urn:oasis:names:tc:SAML:1.1:protocol,SIGNING]</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.773 - DEBUG [edu.internet2.middleware.shibboleth.common.security.MetadataPKIXValidationInformationResolver:258] - Attempting to retrieve PKIX validation info from metadata for entity:
https://Broken-SP/shibboleth</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.773 - DEBUG [org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:194] - Checking child metadata provider for entity descriptor with entity ID: https://Broken-SP/shibboleth</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.774 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:206] - Searching for entity descriptor with an entity ID of https://Broken-SP/shibboleth</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.774 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:77] - Metadata document does not contain an EntityDescriptor with the ID https://Broken-SP/shibboleth</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.774 - DEBUG [org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:194] - Checking child metadata provider for entity descriptor with entity ID: https://Broken-SP/shibboleth</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.775 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:206] - Searching for entity descriptor with an entity ID of https://Broken-SP/shibboleth</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.775 - DEBUG [edu.internet2.middleware.shibboleth.common.security.MetadataPKIXValidationInformationResolver:630] - Write lock over cache acquired</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.775 - DEBUG [edu.internet2.middleware.shibboleth.common.security.MetadataPKIXValidationInformationResolver:633] - Added new PKIX info to entity cache with key: [https://Broken-SP/shibboleth,{urn:oasis:names:tc:SAML:2.0:metadata}SPSSODescriptor,urn:oasis:names:tc:SAML:1.1:protocol,SIGNING]</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.775 - DEBUG [edu.internet2.middleware.shibboleth.common.security.MetadataPKIXValidationInformationResolver:636] - Write lock over cache released</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.776 - DEBUG [org.opensaml.xml.security.x509.PKIXX509CredentialTrustEngine:156] - Beginning PKIX validation using trusted validation information</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.776 - DEBUG [org.opensaml.xml.security.x509.BasicX509CredentialNameEvaluator:219] - Supplied trusted names are null or empty, skipping name evaluation</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.776 - DEBUG [org.opensaml.xml.security.x509.PKIXX509CredentialTrustEngine:174] - Trust of untrusted credential could not be established via PKIX validation</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.776 - ERROR [org.opensaml.ws.security.provider.ClientCertAuthRule:141] - Authentication via client certificate failed for context issuer entity ID https://Broken-SP/shibboleth</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">16:47:23.783 - ERROR [edu.internet2.middleware.shibboleth.idp.profile.saml1.AttributeQueryProfileHandler:171] - Message did not meet security requirements</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">org.opensaml.ws.security.SecurityPolicyException: Client certificate authentication failed for context issuer entity ID</p>
<p style="margin: 0px; font-size: 12px; font-family: Helvetica; ">…Stack trace removed…</p>
</div>
<div><br>
</div>
<div><br>
</div>
<div><br>
</div>
<div><br>
</div>
</body>
</html>