Client certificate authentication failed for context issuer entity ID

Sean R. McNamara Sean.R.McNamara at dartmouth.edu
Wed Jan 9 17:50:26 EST 2013 

Hello all,

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 "Client certificate authentication failed for context issuer entity ID", but, it appears the real issue has to do with the line: "Failed to validate untrusted credential against trusted key" as other InCommon member SPs succeed at this point with the messages:


16:46:39.552 - DEBUG [org.opensaml.xml.security.trust.ExplicitKeyTrustEvaluator:90] - Successfully validated untrusted credential against trusted key

16:46:39.553 - DEBUG [org.opensaml.xml.security.trust.ChainingTrustEngine:59] - Token was trusted by chain member: org.opensaml.xml.security.trust.ExplicitKeyTrustEngine

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/

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..

Thank you very much for your help,

..Sean.


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

16:47:23.745 - DEBUG [org.opensaml.util.storage.ReplayCache:91] - Attempting to acquire lock for replay cache check

16:47:23.745 - DEBUG [org.opensaml.util.storage.ReplayCache:93] - Lock acquired

16:47:23.747 - DEBUG [org.opensaml.util.storage.ReplayCache:104] - Message ID _ef3a1721869276ca915103002f9ba164 was not a replay

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

16:47:23.750 - INFO [org.opensaml.common.binding.security.SAMLProtocolMessageXMLSignatureSecurityPolicyRule:99] - SAML protocol message was not signed, skipping XML signature processing

16:47:23.751 - DEBUG [org.opensaml.ws.security.provider.ClientCertAuthRule:135] - Attempting client certificate authentication using context issuer: https://Broken-SP/shibboleth

16:47:23.751 - DEBUG [org.opensaml.xml.security.trust.ExplicitKeyTrustEngine:68] - Attempting to validate untrusted credential

16:47:23.751 - DEBUG [org.opensaml.security.MetadataCredentialResolver:157] - Forcing on-demand metadata provider refresh if necessary

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]

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]

16:47:23.752 - DEBUG [org.opensaml.security.MetadataCredentialResolver:242] - Attempting to retrieve credentials from metadata for entity: https://Broken-SP/shibboleth

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'

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

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

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

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

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

16:47:23.754 - DEBUG [org.opensaml.xml.security.keyinfo.BasicProviderKeyInfoCredentialResolver:328] - Found 0 key names: org.opensaml.xml.util.LazySet at 3d9b23

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

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

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

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

16:47:23.756 - DEBUG [org.opensaml.xml.security.keyinfo.provider.InlineX509DataProvider:122] - Attempting to extract credential from an X509Data

16:47:23.763 - DEBUG [org.opensaml.xml.security.keyinfo.provider.InlineX509DataProvider:195] - Found 1 X509Certificates

16:47:23.763 - DEBUG [org.opensaml.xml.security.keyinfo.provider.InlineX509DataProvider:176] - Found 0 X509CRLs

16:47:23.763 - DEBUG [org.opensaml.xml.security.keyinfo.provider.InlineX509DataProvider:214] - Single certificate was present, treating as end-entity certificate

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

16:47:23.764 - DEBUG [org.opensaml.xml.security.keyinfo.BasicProviderKeyInfoCredentialResolver:161] - A total of 1 credentials were resolved

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

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]

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

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

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

16:47:23.766 - DEBUG [org.opensaml.xml.security.trust.ExplicitKeyTrustEvaluator:94] - Failed to validate untrusted credential against trusted key

16:47:23.766 - DEBUG [org.opensaml.xml.security.x509.PKIXX509CredentialTrustEngine:119] - Attempting PKIX validation of untrusted credential

16:47:23.766 - DEBUG [edu.internet2.middleware.shibboleth.common.security.MetadataPKIXValidationInformationResolver:188] - Forcing on-demand metadata provider refresh if necessary

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]

16:47:23.768 - DEBUG [edu.internet2.middleware.shibboleth.common.security.MetadataPKIXValidationInformationResolver:603] - Read lock over cache acquired

16:47:23.769 - DEBUG [edu.internet2.middleware.shibboleth.common.security.MetadataPKIXValidationInformationResolver:614] - Read lock over cache released

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]

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

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

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

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

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

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

16:47:23.771 - DEBUG [edu.internet2.middleware.shibboleth.common.security.MetadataPKIXValidationInformationResolver:671] - Write lock over cache acquired

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]

16:47:23.772 - DEBUG [edu.internet2.middleware.shibboleth.common.security.MetadataPKIXValidationInformationResolver:677] - Write lock over cache released

16:47:23.772 - DEBUG [edu.internet2.middleware.shibboleth.common.security.MetadataPKIXValidationInformationResolver:151] - Forcing on-demand metadata provider refresh if necessary

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]

16:47:23.772 - DEBUG [edu.internet2.middleware.shibboleth.common.security.MetadataPKIXValidationInformationResolver:533] - Read lock over cache acquired

16:47:23.773 - DEBUG [edu.internet2.middleware.shibboleth.common.security.MetadataPKIXValidationInformationResolver:544] - Read lock over cache released

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]

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

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

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

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

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

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

16:47:23.775 - DEBUG [edu.internet2.middleware.shibboleth.common.security.MetadataPKIXValidationInformationResolver:630] - Write lock over cache acquired

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]

16:47:23.775 - DEBUG [edu.internet2.middleware.shibboleth.common.security.MetadataPKIXValidationInformationResolver:636] - Write lock over cache released

16:47:23.776 - DEBUG [org.opensaml.xml.security.x509.PKIXX509CredentialTrustEngine:156] - Beginning PKIX validation using trusted validation information

16:47:23.776 - DEBUG [org.opensaml.xml.security.x509.BasicX509CredentialNameEvaluator:219] - Supplied trusted names are null or empty, skipping name evaluation

16:47:23.776 - DEBUG [org.opensaml.xml.security.x509.PKIXX509CredentialTrustEngine:174] - Trust of untrusted credential could not be established via PKIX validation

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

16:47:23.783 - ERROR [edu.internet2.middleware.shibboleth.idp.profile.saml1.AttributeQueryProfileHandler:171] - Message did not meet security requirements

org.opensaml.ws.security.SecurityPolicyException: Client certificate authentication failed for context issuer entity ID

…Stack trace removed…




-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://shibboleth.net/pipermail/users/attachments/20130109/1beb2f22/attachment-0001.html

More information about the users mailing list