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

Tue Aug 18 03:59:33 UTC 2020

On Tue, Aug 18, 2020 at 01:23:20AM +0000, Paul B. Henson wrote:

>  So I'm guessing it fails when for some reason the certificate is not
>  loaded into the TLS settings for that particular connection?

More logging; from a successful validate:

2020-08-17 20:17:09,493 - 2620:df:8000:ff10:0:1:247:16 - DEBUG [org.apache.http.impl.conn.PoolingHttpClientConnectionManager:267] - Connection request: [route: {s}->https://www.idm.unx.cpp.edu:443][total available: 0; route allocated: 0 of 100; total allocated: 0 of 100]
2020-08-17 20:17:09,506 - 2620:df:8000:ff10:0:1:247:16 - DEBUG [org.apache.http.impl.conn.PoolingHttpClientConnectionManager:312] - Connection leased: [id: 0][route: {s}->https://www.idm.unx.cpp.edu:443][total available: 0; route allocated: 1 of 100; total allocated: 1 of 100]
2020-08-17 20:17:09,507 - 2620:df:8000:ff10:0:1:247:16 - DEBUG [org.apache.http.impl.execchain.MainClientExec:234] - Opening connection {s}->https://www.idm.unx.cpp.edu:443
2020-08-17 20:17:09,511 - 2620:df:8000:ff10:0:1:247:16 - TRACE [org.opensaml.security.httpclient.impl.SecurityEnhancedTLSSocketFactory:134] - In createSocket
2020-08-17 20:17:09,512 - 2620:df:8000:ff10:0:1:247:16 - DEBUG [org.apache.http.impl.conn.DefaultHttpClientConnectionOperator:139] - Connecting to www.idm.unx.cpp.edu/134.71.247.16:443
2020-08-17 20:17:09,513 - 2620:df:8000:ff10:0:1:247:16 - TRACE [org.opensaml.security.httpclient.impl.SecurityEnhancedTLSSocketFactory:144] - In connectSocket
2020-08-17 20:17:09,513 - 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 20:17:09,513 - 2620:df:8000:ff10:0:1:247:16 - TRACE [org.opensaml.security.httpclient.impl.SecurityEnhancedTLSSocketFactory:233] - Saw CriteriaSet: [UsageCriterion [credUsage=SIGNING], TrustedNamesCriterion [names=[www.idm.unx.cpp.edu]], EntityRoleCriterion [role={urn:oasis:names:tc:SAML:2.0:metadata}SPSSODescriptor], EntityIdCriterion [id=https://www.idm.unx.cpp.edu/], ProtocolCriterion [protocol=https://www.apereo.org/cas/protocol]]
2020-08-17 20:17:09,514 - 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 20:17:09,537 - 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 20:17:09,590 - 2620:df:8000:ff10:0:1:247:16 - TRACE [org.opensaml.security.httpclient.impl.ThreadLocalServerTLSHandler:53] - Saw ThreadLocalX509TrustEngineContext.getTrusted: true
2020-08-17 20:17:09,590 - 2620:df:8000:ff10:0:1:247:16 - TRACE [org.opensaml.security.httpclient.impl.ThreadLocalServerTLSHandler:58] - Clearing ThreadLocalX509TrustEngineContext

and a failure:

2020-08-17 20:20:31,180 - 2620:df:8000:ff10:0:1:247:16 - DEBUG [org.apache.http.impl.conn.PoolingHttpClientConnectionMan
ager:267] - Connection request: [route: {s}->https://www.idm.unx.cpp.edu:443][total available: 0; route allocated: 1 of
100; total allocated: 1 of 100]
2020-08-17 20:20:31,180 - 2620:df:8000:ff10:0:1:247:16 - DEBUG [org.apache.http.impl.conn.PoolingHttpClientConnectionMan
ager:312] - Connection leased: [id: 1][route: {s}->https://www.idm.unx.cpp.edu:443][total available: 0; route allocated:
 2 of 100; total allocated: 2 of 100]
2020-08-17 20:20:31,181 - 2620:df:8000:ff10:0:1:247:16 - DEBUG [org.apache.http.impl.execchain.MainClientExec:234] - Ope
ning connection {s}->https://www.idm.unx.cpp.edu:443
2020-08-17 20:20:31,186 - 2620:df:8000:ff10:0:1:247:16 - TRACE [org.opensaml.security.httpclient.impl.SecurityEnhancedTL
SSocketFactory:134] - In createSocket
2020-08-17 20:20:31,187 - 2620:df:8000:ff10:0:1:247:16 - DEBUG [org.apache.http.impl.conn.DefaultHttpClientConnectionOpe
rator:139] - Connecting to www.idm.unx.cpp.edu/134.71.247.16:443
2020-08-17 20:20:31,187 - 2620:df:8000:ff10:0:1:247:16 - TRACE [org.opensaml.security.httpclient.impl.SecurityEnhancedTL
SSocketFactory:144] - In connectSocket
2020-08-17 20:20:31,187 - 2620:df:8000:ff10:0:1:247:16 - TRACE [org.opensaml.security.httpclient.impl.SecurityEnhancedTL
SSocketFactory:178] - Attempting to setup thread-local data for TLS evaluation
2020-08-17 20:20:31,187 - 2620:df:8000:ff10:0:1:247:16 - TRACE [org.opensaml.security.httpclient.impl.SecurityEnhancedTL
SSocketFactory:233] - Saw CriteriaSet: [UsageCriterion [credUsage=SIGNING], TrustedNamesCriterion [names=[www.idm.unx.cp
p.edu]], EntityRoleCriterion [role={urn:oasis:names:tc:SAML:2.0:metadata}SPSSODescriptor], EntityIdCriterion [id=https:/
/www.idm.unx.cpp.edu/], ProtocolCriterion [protocol=https://www.apereo.org/cas/protocol]]
2020-08-17 20:20:31,187 - 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 20:20:31,200 - 2620:df:8000:ff10:0:1:247:16 - TRACE [org.opensaml.security.httpclient.impl.SecurityEnhancedTLSSocketFactory:261] - Scheduling deferred clearing of thread-local server TLS TrustEngine and CriteriaSet
2020-08-17 20:20:31,201 - 2620:df:8000:ff10:0:1:247:16 - DEBUG [org.apache.http.impl.conn.DefaultHttpClientConnectionOperator:146] - Connection established 134.71.246.199:55520<->134.71.247.16:443

2020-08-17 20:20:31,215 - 2620:df:8000:ff10:0:1:247:16 - TRACE [org.opensaml.security.httpclient.impl.ThreadLocalServerTLSHandler:53] - Saw ThreadLocalX509TrustEngineContext.getTrusted: null
2020-08-17 20:20:31,215 - 2620:df:8000:ff10:0:1:247:16 - TRACE [org.opensaml.security.httpclient.impl.ThreadLocalServerTLSHandler:58] - Clearing ThreadLocalX509TrustEngineContext

In both success and failure, there are messages from
SecurityEnhancedTLSSocketFactory? So it seems the right socket factory
was configured?

In both cases, the same CriteriaSet is seen? The only difference seems to
be that the MetadataCredentialResolver is called when it works and not
called when it fails.

The last log line before the MetadataCredentialResolver logs are seen in
the one that works is:

2020-08-17 20:17:09,514 - 2620:df:8000:ff10:0:1:247:16 - TRACE [org.opensaml.security.httpclient.impl.SecurityEnhancedTL
SSocketFactory:207] - X509Credential not supplied by caller, skipping ThreadLocalX509CredentialContext population

Then the log line right after the MetadataCredentialResolver runs is:

2020-08-17 20:17:09,564 - 2620:df:8000:ff10:0:1:247:16 - TRACE [org.opensaml.security.httpclient.impl.SecurityEnhancedTLSSocketFactory:261] - Scheduling deferred clearing of thread-local server TLS TrustEngine and CriteriaSet

The first log comes from SecurityEnhancedTLSSocketFactory.setupClientTLS,
called by SecurityEnhancedTLSSocketFactory.setup. That's the last thing 
logged before setup returns.

Then the second line comes from SecurityEnhancedTLSSocketFactory.teardown.

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.

Then in the success case, the ThreadLocalServerTLSHandler logs:

2020-08-17 20:17:09,590 - 2620:df:8000:ff10:0:1:247:16 - TRACE [org.opensaml.security.httpclient.impl.ThreadLocalServerTLSHandler:53] - Saw ThreadLocalX509TrustEngineContext.getTrusted: true

whereas in the failure:

2020-08-17 20:20:31,215 - 2620:df:8000:ff10:0:1:247:16 - TRACE [org.opensaml.security.httpclient.impl.ThreadLocalServerTLSHandler:53] - Saw ThreadLocalX509TrustEngineContext.getTrusted: null

That what checkTLSCredentialEvaluated looks at and barfs on in the case of
failure.

It looks like that is set by
CheckAndRecordServerTLSEntityAuthenticationtHandler? That file has debug
logging in it, but I don't see the output in my logs?

I have
	    <logger name="org.opensaml.saml" level="TRACE"/>
            <logger name="org.opensaml.common" level="TRACE"/>
and even
    <logger name="org.opensaml.saml.common.binding.security.impl" level="TRACE"/>

configured, is there something else I need to get those logs?

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