Ex: RE:: CAS proxy validation failure - Configured TLS trust engine was not used

Tue Aug 18 04:59:35 UTC 2020

On Mon, Aug 17, 2020 at 08:59:33PM -0700, Paul B. Henson wrote:

> What happens in between the calls to SecurityEnhancedTLSSocketFactory.setup
> and SecurityEnhancedTLSSocketFactory.teardown? It seems whatever runs
> in that window sometimes loads the cert and sometimes doesn't.

I got a bit more logging detail. In the success case,
org.opensaml.security.x509.tls.impl.ThreadLocalX509TrustManager is called
and validates the credential: 

2020-08-17 21:18:14,546 - 2620:df:8000:ff10:0:1:247:16 - TRACE [org.opensaml.security.httpclient.impl.SecurityEnhancedTLSSocketFactory:144] - In connectSocket
2020-08-17 21:18:14,546 - 2620:df:8000:ff10:0:1:247:16 - TRACE [org.opensaml.security.httpclient.impl.SecurityEnhancedTLSSocketFactory:178] - Attempting to setup thread-local data for TLS evaluation
2020-08-17 21:18:14,546 - 2620:df:8000:ff10:0:1:247:16 - TRACE [org.opensaml.security.httpclient.impl.SecurityEnhancedTLSSocketFactory:233] - Saw CriteriaSet: [TrustedNamesCriterion [names=[www.idm.unx.cpp.edu]], EntityRoleCriterion [role={urn:oasis:names:tc:SAML:2.0:metadata}SPSSODescriptor], UsageCriterion [credUsage=SIGNING], EntityIdCriterion [id=https://www.idm.unx.cpp.edu/], ProtocolCriterion [protocol=https://www.apereo.org/cas/protocol]]
2020-08-17 21:18:14,547 - 2620:df:8000:ff10:0:1:247:16 - TRACE [org.opensaml.security.httpclient.impl.SecurityEnhancedTLSSocketFactory:207] - X509Credential not supplied by caller, skipping ThreadLocalX509CredentialContext population
2020-08-17 21:18:14,596 - 2620:df:8000:ff10:0:1:247:16 - DEBUG [org.opensaml.security.x509.tls.impl.ThreadLocalX509TrustManager:114] - Attempting to evaluate server TLS credential against supplied TrustEngine and CriteriaSet
2020-08-17 21:18:14,597 - 2620:df:8000:ff10:0:1:247:16 - TRACE [org.opensaml.security.x509.tls.impl.ThreadLocalX509TrustManager:118] - Saw trust engine of type: org.opensaml.security.trust.impl.ChainingTrustEngine
2020-08-17 21:18:14,597 - 2620:df:8000:ff10:0:1:247:16 - DEBUG [org.opensaml.security.trust.impl.ExplicitX509CertificateTrustEngine:83] - Attempting to validate untrusted credential
2020-08-17 21:18:14,598 - 2620:df:8000:ff10:0:1:247:16 - DEBUG [org.opensaml.saml.security.impl.MetadataCredentialResolver:285] - Resolving credentials from metadata using entityID: https://www.idm.unx.cpp.edu/, role: {urn:oasis:names:tc:SAML:2.0:metadata}SPSSODescriptor, protocol: https://www.apereo.org/cas/protocol, usage: SIGNING
2020-08-17 21:18:14,646 - 2620:df:8000:ff10:0:1:247:16 - DEBUG [org.opensaml.security.trust.impl.ExplicitX509CertificateTrustEvaluator:91] - Successfully validated untrusted credential against trusted certificate
2020-08-17 21:18:14,646 - 2620:df:8000:ff10:0:1:247:16 - DEBUG [org.opensaml.security.trust.impl.ChainingTrustEngine:76] - Token was trusted by chain member: org.opensaml.security.trust.impl.ExplicitX509CertificateTrustEngine
2020-08-17 21:18:14,646 - 2620:df:8000:ff10:0:1:247:16 - DEBUG [org.opensaml.security.x509.tls.impl.ThreadLocalX509TrustManager:122] - Credential evaluated as trusted
2020-08-17 21:18:14,654 - 2620:df:8000:ff10:0:1:247:16 - DEBUG [net.shibboleth.utilities.java.support.httpclient.TLSSocketFactory:338] - Connected to: www.idm.unx.cpp.edu/134.71.247.16:443

In the failure case, no sign of it:

2020-08-17 21:21:31,694 - 2620:df:8000:ff10:0:1:247:16 - TRACE [org.opensaml.security.httpclient.impl.SecurityEnhancedTLSSocketFactory:144] - In connectSocket
2020-08-17 21:21:31,694 - 2620:df:8000:ff10:0:1:247:16 - TRACE [org.opensaml.security.httpclient.impl.SecurityEnhancedTLSSocketFactory:178] - Attempting to setup thread-local
 data for TLS evaluation
2020-08-17 21:21:31,694 - 2620:df:8000:ff10:0:1:247:16 - TRACE [org.opensaml.security.httpclient.impl.SecurityEnhancedTLSSocketFactory:233] - Saw CriteriaSet: [TrustedNamesCr
iterion [names=[www.idm.unx.cpp.edu]], EntityRoleCriterion [role={urn:oasis:names:tc:SAML:2.0:metadata}SPSSODescriptor], UsageCriterion [credUsage=SIGNING], EntityIdCriterion
 [id=https://www.idm.unx.cpp.edu/], ProtocolCriterion [protocol=https://www.apereo.org/cas/protocol]]
2020-08-17 21:21:31,694 - 2620:df:8000:ff10:0:1:247:16 - TRACE [org.opensaml.security.httpclient.impl.SecurityEnhancedTLSSocketFactory:207] - X509Credential not supplied by
 c
aller, skipping ThreadLocalX509CredentialContext population
2020-08-17 21:21:31,706 - 2620:df:8000:ff10:0:1:247:16 - DEBUG [net.shibboleth.utilities.java.support.httpclient.TLSSocketFactory:338] - Connected to: www.idm.unx.cpp.edu/134
.71.247.16:443

In the failure case, there's clearly a trust engine involved in the
connection, otherwise 'Saw CriteriaSet' wouldn't be logged. Why isn't it
getting called like in the success case?

I dunno, after killing most of the day trying to track this down I think
I might be stalled. Any thoughts on where to dig further?

Thanks...

-- 
Paul B. Henson  |  (909) 979-6361  |  http://www.cpp.edu/~henson/
Operating Systems and Network Analyst  |  henson at cpp.edu
California State Polytechnic University  |  Pomona CA 91768