Uploaded image for project: 'OpenSAML - Java'
  1. OpenSAML - Java
  2. OSJ-323

HttpClient configured TLS trust engine is not evaluated on TLS session resumption

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major
    • Resolution: Fixed
    • Affects Version/s: 4.0.0, 4.0.1
    • Fix Version/s: 4.1.0
    • Component/s: Security
    • Labels:
      None
    • Environment:
    • Operating System:
      Linux
    • Java Version:
      Red Hat OpenJDK 11
    • Servlet Container:
      Jetty 9.4

      Description

      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.

       

       

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              putmanb@shibboleth.net Brent Putman
              Reporter:
              henson@cpp.edu Paul B. Henson
              Watchers:
              2 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved:

                  Time Tracking

                  Estimated:
                  Original Estimate - Not Specified
                  Not Specified
                  Remaining:
                  Remaining Estimate - Not Specified
                  Not Specified
                  Logged:
                  Time Spent - 1 hour
                  1h