HttpClient configured TLS trust engine is not evaluated on TLS session resumption
Description
Environment
CentOS Linux release 8.1.1911 (Core)
openjdk 11.0.6 2020-01-14 LTS
OpenJDK Runtime Environment 18.9 (build 11.0.6+10-LTS)
OpenJDK 64-Bit Server VM 18.9 (build 11.0.6+10-LTS, mixed mode, sharing)
jetty-bin-9.4.31.v20200723-1.noarch
Activity
Brent Putman November 13, 2020 at 8:02 PM
Yes, I think so. I was mainly just holding open to get some solid confirmation over time, which I think we have now. I'll go ahead and close.
Paul B. Henson November 13, 2020 at 7:33 PM
I've been running this backported to 4.0.1 on my dev/test instances for the last couple months and haven't seen any problems.
Scott Cantor November 13, 2020 at 3:39 PM
@Brent Putman This should be resolved, right?
Paul B. Henson September 4, 2020 at 3:05 AM
Ah, d'oh, my bad. I actually had that repo checked out from when I was working on debugging this. I cherry-picked your 3 commits onto a branch I made from the 4.0.1 tag and compiled it and then the 4.0.1 idp code. Looks good, no more failures on repeated CAS proxy connections :).
Is there going to be another 4.0.x bug fix release, or will this be released with 4.1?
Thanks again for sorting it out.
Brent Putman September 3, 2020 at 7:19 PM
This fix is to the java-opensaml project, which is a dependency of the IdP. So in order to test you'd have to build that from source and install to your local Maven repo ("mvn clean install") and then build the IdP project.
I checked that in very late, so I'm not sure if it made it into the overnight 4.1.0-SNAPSHOT build. It definitely should be tomorrow though. So in that case if you build the IdP it should just get pulled in automatically.
CAS proxy callback validation seems to work only once every 10 minutes. The first attempt works fine:
2020-08-16 20:13:07,435 -
2620:df:8000:ff10:0:1:247:16/node0np5dpf62x7qd1xpq7vzwncvwi1 - INFO
[net.shibboleth.idp.cas.flow.impl.ValidateTicketAction:153] - Profile Action
ValidateTicketAction: Successfully validated
ST-AADXGZLDOJSXIMPCXDWYYTI3TYSIZNNR5NVOYQ7L4MN2B7SP4SNLTIKY3ZMDVJJWIDZ66OISNE7X3
O5VPSPPATZRC3BVXDMRDOCSY7RS5WTX6CFEKHGO7TS3EHANWCENLNQG76UJUZNELW6WSJNTJ2NA3SGJK
P3CUKHOBS5EQYTVWCSNKJBMEYSKEHH5ESVS4Z3AXYYK42CJKLHKY3SJTBPPCWMI5EUHJTAGX3HHXUM4S
SBD62LMBKTHMNY4WCBZLV4MYETY7ROYTF5254UYMESLUF4CHPPMPZKSLTKQZLVJTTY3VNGWX3TMJL4TC
ZQL3DMBATAN3EJ2XAW5LN62LYMBLQM7Y6KXRK44RZQCTUYEPRJKGSKJS6M4FAKA---- for
https://www.idm.unx.cpp.edu/webui-dev
2020-08-16 20:13:07,441 -
2620:df:8000:ff10:0:1:247:16/node0np5dpf62x7qd1xpq7vzwncvwi1 - DEBUG
[net.shibboleth.idp.cas.flow.impl.ValidateProxyCallbackAction:159] - Profile
Action ValidateProxyCallbackAction: Attempting proxy authentication to
https://www.idm.unx.cpp.edu/cas_pgt-dev?pgtId=PGT-1597633987438-RimfopY1FUF9y1MS
Uwjd5E4EM4rJq0KImM94M22Dekq0HbsSvT&pgtIou=PGTIOU-1597633987441-AWOqUCZFoKlTj5C7Q
gD2OwVKBF8wFmpUaBEe3MjdHLOrdQl8Sk
2020-08-16 20:13:07,442 -
2620:df:8000:ff10:0:1:247:16/node0np5dpf62x7qd1xpq7vzwncvwi1 - DEBUG
[net.shibboleth.idp.cas.proxy.impl.HttpClientProxyValidator:162] - Attempting to
validate CAS proxy callback URI
https://www.idm.unx.cpp.edu/cas_pgt-dev?pgtId=PGT-1597633987438-RimfopY1FUF9y1MS
Uwjd5E4EM4rJq0KImM94M22Dekq0HbsSvT&pgtIou=PGTIOU-1597633987441-AWOqUCZFoKlTj5C7Q
gD2OwVKBF8wFmpUaBEe3MjdHLOrdQl8Sk
2020-08-16 20:13:07,456 - 2620:df:8000:ff10:0:1:247:16/node0np5dpf62x7qd1xpq7vzwncvwi1 - 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-16 20:13:07,456 -
2620:df:8000:ff10:0:1:247:16/node0np5dpf62x7qd1xpq7vzwncvwi1 - DEBUG
[org.opensaml.saml.security.impl.MetadataCredentialResolver:434] - Retrieving
role descriptor metadata for entity 'https://www.idm.unx.cpp.edu/' in role
'{urn:oasis:names:tc:SAML:2.0:metadata}SPSSODescriptor' for protocol
'https://www.apereo.org/cas/protocol'
olver.impl.AbstractBatchMetadataResolver:178] - Metadata Resolver
FilesystemMetadataResolver cpp-cas: Resolved 1 c
andidates via EntityIdCriterion: EntityIdCriterion
[id=https://www.idm.unx.cpp.edu/]
2020-08-16 20:13:07,460 -
2620:df:8000:ff10:0:1:247:16/node0np5dpf62x7qd1xpq7vzwncvwi1 - DEBUG
[org.opensaml.saml.metada
ta.resolver.impl.AbstractMetadataResolver:610] - Metadata Resolver
FilesystemMetadataResolver cpp-cas: Attempting to fil
ter candidate EntityDescriptors via resolved Predicates
2020-08-16 20:13:07,460 -
2620:df:8000:ff10:0:1:247:16/node0np5dpf62x7qd1xpq7vzwncvwi1 - DEBUG
[org.opensaml.saml.metada
ta.resolver.impl.AbstractMetadataResolver:632] - Metadata Resolver
FilesystemMetadataResolver cpp-cas: After predicate filtering 1
EntityDescriptors remain
2020-08-16 20:13:07,500 -
2620:df:8000:ff10:0:1:247:16/node0np5dpf62x7qd1xpq7vzwncvwi1 - DEBUG [net.shibboleth.idp.cas.ticket.impl.AbstractTicketService:179] - Storing mapping
of PGT-1597633987438-RimfopY1FUF9y1MSUwjd5E4EM4rJq0KImM94M22Dekq0HbsSvT to
04e5585eeb8b0fb39cc59214aa90122cc066ddf9effde81253465458eafb5fbd in context
https://www.apereo.org/cas/protocol/serviceValidate
2020-08-16 20:13:07,501 -
2620:df:8000:ff10:0:1:247:16/node0np5dpf62x7qd1xpq7vzwncvwi1 - DEBUG
[net.shibboleth.idp.cas.ticket.impl.AbstractTicketService:183] - Storing
PGT-1597633987438-RimfopY1FUF9y1MSUwjd5E4EM4rJq0KImM94M22Dekq0HbsSvT in context
04e5585eeb8b0fb39cc59214aa90122cc066ddf9effde81253465458eafb5fbd
A subsequent attempt fails:
2020-08-16 20:14:56,646 -
2620:df:8000:ff10:0:1:247:16/node01pf4gxx0vbayfq9f6avlhfaxu2 - INFO
[net.shibboleth.idp.cas.fl
ow.impl.ValidateTicketAction:153] - Profile Action ValidateTicketAction:
Successfully validated ST-AADXGZLDOJSXIMIXKFELT
Y3E7JWSD2TLC5AVKPSRU3QNMI2GPRPQ6TI25AYYZK56C7GHVNWE3XT4GFJN56KZ5CSB2J47LUEWFZBRA
Y6FJOARPNPUNTUIWV2WP5APZ4E67ZHWUCRKQI5HQ
BCMGTMO7R5ERXHQBCY47W6S33E2HPVZU6GMZIS4YSSFTIV57OGAP7CF3HJFKW5CDZAHYODA26I74NGDQ
BWY2OGNU2NYCGQWOGMBKQR6TF6KO2WCZB53EAVXZ
BBH6CXBFPIIBE54WNXRINMCFTDB2YCZEAIVSKOTK5XFFN3H5QXRHY7RVC6AIG5EGYYBRLACDQD46E3OR
AOUBGD4HGOL4UPUNARYCI2XFQ7PUAXFCVFVZBZQ-
— for https://www.idm.unx.cpp.edu/webui-dev
2020-08-16 20:14:56,647 -
2620:df:8000:ff10:0:1:247:16/node01pf4gxx0vbayfq9f6avlhfaxu2 - DEBUG
[net.shibboleth.idp.cas.f
low.impl.ValidateProxyCallbackAction:159] - Profile Action
ValidateProxyCallbackAction: Attempting proxy authentication
to
https://www.idm.unx.cpp.edu/cas_pgt-dev?pgtId=PGT-1597634096647-2G7mZZANKA9j6GHz
cyIyr1lJp92DwuhUB3PiTJPonGFDtMLb9w&pg
tIou=PGTIOU-1597634096647-WG3okNIyBA7UN42qCQMArT8TKlHSn8JsXghTscSeVN6kBAWGdf
2020-08-16 20:14:56,648 -
2620:df:8000:ff10:0:1:247:16/node01pf4gxx0vbayfq9f6avlhfaxu2 - DEBUG
[net.shibboleth.idp.cas.proxy.impl.HttpClientProxyValidator:162] - Attempting to
validate CAS proxy callback URI
https://www.idm.unx.cpp.edu/cas_pgt-dev?pgtId=PGT-1597634096647-2G7mZZANKA9j6GHz
cyIyr1lJp92DwuhUB3PiTJPonGFDtMLb9w&pgtIou=PGTIOU-1597634096647-WG3okNIyBA7UN42qC
QMArT8TKlHSn8JsXghTscSeVN6kBAWGdf
2020-08-16 20:14:56,680 -
2620:df:8000:ff10:0:1:247:16/node01pf4gxx0vbayfq9f6avlhfaxu2 - WARN [org.opensaml.security.httpclient.HttpClientSecuritySupport:109] - Configured
TLS trust engine was not used to verify server TLS credential, the appropriate
socket factory was likely not configured
2020-08-16 20:14:56,683 -
2620:df:8000:ff10:0:1:247:16/node01pf4gxx0vbayfq9f6avlhfaxu2 - 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
javax.security.auth.login.CredentialException: Untrusted certificate presented
by CAS proxy callback endpoint
If 10 minutes go by without making a a request, the callback succeeds again, once, then fails again until no calls are made for 10 minutes.
This failure is distinct from an actual cert mismatch, which looks like:
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)
Also, with an actual cert mismatch no request is logged on the CAS proxy client access log. When the call fails with "Configured TLS trust engine was not used", there is an entry on the CAS proxy client access log. It appears that the actual callback request is made successfully, but that it thinks it wasn't validated.
This is very strange. I restarted with a fresh stock config and updated just the bare minimum to be able to successfully auth and have CAS metadata and it still happens.