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

[Paul B. Henson]

> From: users Cantor, Scott
> Sent: Monday, August 17, 2020 11:08 AM
> 
> Yes, so my only conclusion is that the error means what it says. The second
> client can't be running a trusted certificate at the proxy validation endpoint and
> that's just the fallout from it not being able to verify it.

Hmm, I think we are talking about different clients. I meant the idp was using the same httpclient both times, working the first time and failing the second. It sounds like you are talking about the CAS proxy client; in this test scenario, there is only one server acting as the proxy client, with only one certificate. I am reasonably confident that the proper certificate is being presented on every request, both the failed one and the successful one.

I tried updating the CAS metadata to intentionally cause a certificate mismatch. In that scenario, the errors that show up in the logs are:

2020-08-17 11:39:06,675 - 2620:df:8000:ff10:0:1:247:16 - ERROR [org.opensaml.security.x509.impl.BasicX509CredentialNameEvaluator:297] - Credential failed name check: [subjectName='CN=idm.unx.cpp.edu,OU=CSU Pomona,O=California State Polytechnic University\, Pomona,STREET=3801 West Temple Avenue,L=Pomona,ST=CA,2.5.4.17=#13053931373638,C=US']
2020-08-17 11:39:06,684 - 2620:df:8000:ff10:0:1:247:16 - WARN [net.shibboleth.idp.cas.flow.impl.ValidateProxyCallbackAction:170] - Profile Action ValidateProxyCallbackAction: Proxy authentication failed for https://www.idm.unx.cpp.edu/cas_pgt-dev
java.security.cert.CertificateException: Trust engine could not establish trust of presented TLS credential
        at org.opensaml.security.x509.tls.impl.ThreadLocalX509TrustManager.performTrustEval(ThreadLocalX509TrustManager.java:93)

These errors occur every try, and the access log on the CAS proxy client does not show a request. There do not appear to be any messages about missing socket factories in this scenario.

On the other hand, with the proper certificates in place on both sides, the first request succeeds, with an entry in the access log:

134.71.246.199 - - [17/Aug/2020:11:43:21 -0700] "GET /cas_pgt-dev?pgtId=PGT-1597689801209-ZZ1bCcKh0LX551MNDaOPyVmnv0X75D
ea2VpVAYuWmDHU3J5zvy&pgtIou=PGTIOU-1597689801210-ErqjPdiaqqdnQBUAmHPLQ1cwgssS1NUy9KTjaokND19FBCWnk4 HTTP/1.1" 200 561 "-
" "ShibbolethIdp/4.0.1 OpenSAML/4.0.1"

Subsequent requests continue to fail with this error message:

2020-08-17 11:44:19,396 - 2620:df:8000:ff10:0:1:247:16 - WARN [org.opensaml.security.httpclient.HttpClientSecuritySuppor
t:109] - Configured TLS trust engine was not used to verify server TLS credential, the appropriate socket factory was li
kely not configured

Interestingly, even though the request fails on the idp side, there is still an entry logged on the CAS proxy for the request:

134.71.246.199 - - [17/Aug/2020:11:44:19 -0700] "GET /cas_pgt-dev?pgtId=PGT-1597689859374-qDP1X4sBI1iGevCwdPRq52VYFxINsqlWvFJkh2HuCAVWfpHTnz&pgtIou=PGTIOU-1597689859374-UDJ8msuAAegAxHsu1Cu8ypaIb4TNQ0YD3cNmBCIFSA1XBvjZ4K HTTP/1.1" 200 561 "-" "ShibbolethIdp/4.0.1 OpenSAML/4.0.1"

When the certificates are mismatched, the connection fails at the TLS negotiation level, there is never an actual GET made to the proxy. With this error though, it appears that the TLS negotiation succeeds, the request is actually made to the proxy client, but then something happens afterwards causing a failure.

> Otherwise it's a complex bug with no real quick answer.

Yeah, my vote is going towards complex bug :(. After some further testing, it looks like if I wait 10 minutes after the last request, success or failure, it works again. Once, then starts failing again. Until another 10 minutes passes with no requests, then it works again once. If the request is made before 10 minutes passes, requests continue to fail until 10 minutes after that request, so it seems to be holding onto something broken for 10 minutes.

Any thoughts off the top of your head what involving httpclients gets cached for 10 minutes? I reverted to the stock config and made just the bare minimum number of changes required in order to successfully authenticate, so I don't think this is coming from anything I changed.