Uploaded image for project: 'jclouds'
  1. jclouds
  2. JCLOUDS-1520

JClouds is not using the JDK's KeepAliveCache when UntrustedSSLContextSupplier is used

    XMLWordPrintableJSON

    Details

    • Type: Bug
    • Status: Resolved
    • Priority: Major
    • Resolution: Fixed
    • Affects Version/s: 2.1.0
    • Fix Version/s: 2.3.0, 2.2.1
    • Component/s: jclouds-core
    • Labels:
      None

      Description

      It seems like the fact that UntrustedSSLContextSupplier returns a new SSLContext on every get() call causes a consistent cache miss on the JVM's sun.net.www.http.KeepAliveCache which causes JClouds to not reuse existing TLS connections even though it could.

      The cache miss happens at sun.net.www.protocol.https.HttpsClient line 329 (openjdk version "1.8.0_222"):

      /* see if one's already around */
      ret = (HttpsClient) kac.get(url, sf);
      

      To reproduce, consider the following main:

          public static void main(String[] args) {
              Properties overrides = new Properties();
              overrides.setProperty(org.jclouds.Constants.PROPERTY_TRUST_ALL_CERTS, "true");
              BlobStoreContext blobStoreContext = ContextBuilder.newBuilder("aws-s3")
                  .endpoint("https://s3.amazonaws.com")
                  .credentials("...", "...")
                  .overrides(overrides)
                  .buildView(BlobStoreContext.class);
              BlobStore blobStore = blobStoreContext.getBlobStore();
              blobStore.getBlob("roded-data", "blobname");
              blobStore.getBlob("roded-data", "blobname");
              blobStore.getBlob("roded-data", "blobname");
              blobStoreContext.close();
              System.exit(0);
          }
      

      If run using a JUL logging.properties with the following logger set to FINEST:

      sun.net.www.protocol.http.level=FINEST
      

      The following log is produced:

      2019-10-10 18:15:19.668 FINE    [org.jclouds.rest.internal.InvokeHttpMethod ] >> invoking GetBucketLocation
      2019-10-10 18:15:19.733 FINE    [org.jclouds.http.internal.JavaUrlHttpCommandExecutorService ] Sending request -1721710788: GET https://s3.amazonaws.com/roded-data?location HTTP/1.1
      2019-10-10 18:15:19.893 FINEST  [sun.net.www.protocol.http.HttpURLConnection ] Looking for HttpClient for URL https://s3.amazonaws.com/roded-data?location and proxy value of DIRECT
      2019-10-10 18:15:19.893 FINEST  [sun.net.www.protocol.http.HttpURLConnection ] Creating new HttpsClient with url:https://s3.amazonaws.com/roded-data?location and proxy:DIRECT with connect timeout:60000
      2019-10-10 18:15:20.837 FINE    [sun.net.www.protocol.http.HttpURLConnection ] sun.net.www.MessageHeader@537b32ef8 pairs: {GET /roded-data?location HTTP/1.1: null}{x-amz-content-sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855}{X-Amz-Date: 20191010T151519Z}{Authorization: AWS4-HMAC-SHA256 Credential=AKIAJO5RLGWKFW5ASG3A/20191010/us-east-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=896e11ddd9efac465b6ff2506d1688d454a50b3f73ac68d557ad036b1826e591}{User-Agent: jclouds/2019.224.2 java/1.8.0_222}{Host: s3.amazonaws.com}{Accept: text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2}{Connection: keep-alive}
      2019-10-10 18:15:21.169 FINE    [sun.net.www.protocol.http.HttpURLConnection ] sun.net.www.MessageHeader@6f815e7f7 pairs: {null: HTTP/1.1 200 OK}{x-amz-id-2: 1VVlx4h/fBOFe3n/7IxvpWN0RoVcE2rSpnnxMjvAQ93lJ6tHJAS+3IlXAx++/ZMEblp7kjJT4eQ=}{x-amz-request-id: AE0779131201B495}{Date: Thu, 10 Oct 2019 15:15:21 GMT}{Content-Type: application/xml}{Transfer-Encoding: chunked}{Server: AmazonS3}
      2019-10-10 18:15:21.185 FINE    [org.jclouds.http.internal.JavaUrlHttpCommandExecutorService ] Receiving response -1721710788: HTTP/1.1 200 OK
      2019-10-10 18:15:21.500 FINE    [org.jclouds.rest.internal.InvokeHttpMethod ] >> invoking GetObject
      2019-10-10 18:15:21.514 FINE    [org.jclouds.http.internal.JavaUrlHttpCommandExecutorService ] Sending request -1332190413: GET https://roded-data.s3-eu-central-1.amazonaws.com/blobname HTTP/1.1
      2019-10-10 18:15:21.517 FINEST  [sun.net.www.protocol.http.HttpURLConnection ] Looking for HttpClient for URL https://roded-data.s3-eu-central-1.amazonaws.com/blobname and proxy value of DIRECT
      2019-10-10 18:15:21.519 FINEST  [sun.net.www.protocol.http.HttpURLConnection ] Creating new HttpsClient with url:https://roded-data.s3-eu-central-1.amazonaws.com/blobname and proxy:DIRECT with connect timeout:60000
      2019-10-10 18:15:22.319 FINE    [sun.net.www.protocol.http.HttpURLConnection ] sun.net.www.MessageHeader@6a933be28 pairs: {GET /blobname HTTP/1.1: null}{x-amz-content-sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855}{X-Amz-Date: 20191010T151519Z}{Authorization: AWS4-HMAC-SHA256 Credential=AKIAJO5RLGWKFW5ASG3A/20191010/eu-central-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=52fadcda579bb56e62b9b0489d7a0a90080103213021b0ea26d63f9e9620f4cc}{User-Agent: jclouds/2019.224.2 java/1.8.0_222}{Host: roded-data.s3-eu-central-1.amazonaws.com}{Accept: text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2}{Connection: keep-alive}
      2019-10-10 18:15:22.414 FINE    [sun.net.www.protocol.http.HttpURLConnection ] sun.net.www.MessageHeader@5f78de227 pairs: {null: HTTP/1.1 404 Not Found}{x-amz-request-id: 145B1CB9D422BD58}{x-amz-id-2: mrOGaJartmhkS4hnf825y0fwc7M9p3EelfeY5s/wxvI+Yb6pzgggYPS7xm0Su+Fk2/Plb55+vgw=}{Content-Type: application/xml}{Transfer-Encoding: chunked}{Date: Thu, 10 Oct 2019 15:15:22 GMT}{Server: AmazonS3}
      2019-10-10 18:15:22.418 FINE    [org.jclouds.http.internal.JavaUrlHttpCommandExecutorService ] Receiving response -1332190413: HTTP/1.1 404 Not Found
      2019-10-10 18:15:22.444 FINE    [org.jclouds.rest.internal.InvokeHttpMethod ] >> invoking GetObject
      2019-10-10 18:15:22.453 FINE    [org.jclouds.http.internal.JavaUrlHttpCommandExecutorService ] Sending request -1332190413: GET https://roded-data.s3-eu-central-1.amazonaws.com/blobname HTTP/1.1
      2019-10-10 18:15:22.455 FINEST  [sun.net.www.protocol.http.HttpURLConnection ] Looking for HttpClient for URL https://roded-data.s3-eu-central-1.amazonaws.com/blobname and proxy value of DIRECT
      2019-10-10 18:15:22.456 FINEST  [sun.net.www.protocol.http.HttpURLConnection ] Creating new HttpsClient with url:https://roded-data.s3-eu-central-1.amazonaws.com/blobname and proxy:DIRECT with connect timeout:60000
      2019-10-10 18:15:22.710 FINE    [sun.net.www.protocol.http.HttpURLConnection ] sun.net.www.MessageHeader@375b5b7f8 pairs: {GET /blobname HTTP/1.1: null}{x-amz-content-sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855}{X-Amz-Date: 20191010T151519Z}{Authorization: AWS4-HMAC-SHA256 Credential=AKIAJO5RLGWKFW5ASG3A/20191010/eu-central-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=52fadcda579bb56e62b9b0489d7a0a90080103213021b0ea26d63f9e9620f4cc}{User-Agent: jclouds/2019.224.2 java/1.8.0_222}{Host: roded-data.s3-eu-central-1.amazonaws.com}{Accept: text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2}{Connection: keep-alive}
      2019-10-10 18:15:22.807 FINE    [sun.net.www.protocol.http.HttpURLConnection ] sun.net.www.MessageHeader@1813f3e97 pairs: {null: HTTP/1.1 404 Not Found}{x-amz-request-id: 1D56A991AE89399B}{x-amz-id-2: L3t4vJGnycAD6xDb0UCB6i5keZ+OdptP9xcAnPC36sLous0nlUht2zj1xrZXhc1EiBhQVJoVFKY=}{Content-Type: application/xml}{Transfer-Encoding: chunked}{Date: Thu, 10 Oct 2019 15:15:22 GMT}{Server: AmazonS3}
      2019-10-10 18:15:22.810 FINE    [org.jclouds.http.internal.JavaUrlHttpCommandExecutorService ] Receiving response -1332190413: HTTP/1.1 404 Not Found
      2019-10-10 18:15:22.831 FINE    [org.jclouds.rest.internal.InvokeHttpMethod ] >> invoking GetObject
      2019-10-10 18:15:22.842 FINE    [org.jclouds.http.internal.JavaUrlHttpCommandExecutorService ] Sending request -1332190413: GET https://roded-data.s3-eu-central-1.amazonaws.com/blobname HTTP/1.1
      2019-10-10 18:15:22.844 FINEST  [sun.net.www.protocol.http.HttpURLConnection ] Looking for HttpClient for URL https://roded-data.s3-eu-central-1.amazonaws.com/blobname and proxy value of DIRECT
      2019-10-10 18:15:22.845 FINEST  [sun.net.www.protocol.http.HttpURLConnection ] Creating new HttpsClient with url:https://roded-data.s3-eu-central-1.amazonaws.com/blobname and proxy:DIRECT with connect timeout:60000
      2019-10-10 18:15:23.118 FINE    [sun.net.www.protocol.http.HttpURLConnection ] sun.net.www.MessageHeader@25c5e9948 pairs: {GET /blobname HTTP/1.1: null}{x-amz-content-sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855}{X-Amz-Date: 20191010T151519Z}{Authorization: AWS4-HMAC-SHA256 Credential=AKIAJO5RLGWKFW5ASG3A/20191010/eu-central-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=52fadcda579bb56e62b9b0489d7a0a90080103213021b0ea26d63f9e9620f4cc}{User-Agent: jclouds/2019.224.2 java/1.8.0_222}{Host: roded-data.s3-eu-central-1.amazonaws.com}{Accept: text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2}{Connection: keep-alive}
      2019-10-10 18:15:23.214 FINE    [sun.net.www.protocol.http.HttpURLConnection ] sun.net.www.MessageHeader@378bd86d7 pairs: {null: HTTP/1.1 404 Not Found}{x-amz-request-id: 4B31AE0000A88E59}{x-amz-id-2: KbsHdUb8aHJlBuSqLky1ld5vutQonKeCHGeCLo7/4HLQ42wA3evSvHq3VPwJPDHt9Y69EIr/L/Y=}{Content-Type: application/xml}{Transfer-Encoding: chunked}{Date: Thu, 10 Oct 2019 15:15:22 GMT}{Server: AmazonS3}
      2019-10-10 18:15:23.217 FINE    [org.jclouds.http.internal.JavaUrlHttpCommandExecutorService ] Receiving response -1332190413: HTTP/1.1 404 Not Found
      

      Note the "Creating new HttpsClient" for every request.

      If however we disable the jclouds.trust-all-certs property, we get the following log:

      2019-10-10 18:19:42.752 FINE    [org.jclouds.http.internal.JavaUrlHttpCommandExecutorService ] Sending request 349720498: GET https://s3.amazonaws.com/roded-data?location HTTP/1.1
      2019-10-10 18:19:42.887 FINEST  [sun.net.www.protocol.http.HttpURLConnection ] Looking for HttpClient for URL https://s3.amazonaws.com/roded-data?location and proxy value of DIRECT
      2019-10-10 18:19:42.887 FINEST  [sun.net.www.protocol.http.HttpURLConnection ] Creating new HttpsClient with url:https://s3.amazonaws.com/roded-data?location and proxy:DIRECT with connect timeout:60000
      2019-10-10 18:19:44.506 FINE    [sun.net.www.protocol.http.HttpURLConnection ] sun.net.www.MessageHeader@757194dc8 pairs: {GET /roded-data?location HTTP/1.1: null}{x-amz-content-sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855}{X-Amz-Date: 20191010T151942Z}{Authorization: AWS4-HMAC-SHA256 Credential=AKIAJO5RLGWKFW5ASG3A/20191010/us-east-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=3a487b5e433bbb256329224f4bad65f7f29fc4ac14cfcec210e2edf8fac538a3}{User-Agent: jclouds/2019.224.2 java/1.8.0_222}{Host: s3.amazonaws.com}{Accept: text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2}{Connection: keep-alive}
      2019-10-10 18:19:44.695 FINE    [sun.net.www.protocol.http.HttpURLConnection ] sun.net.www.MessageHeader@7ff2b8d27 pairs: {null: HTTP/1.1 200 OK}{x-amz-id-2: kIwRu2VQM7kWQMr0Xw7fsxi5NVf7+1r93tbgY0dqcmDMXVdOc3Il4mZx+tlTRn288PgVQhs8FO0=}{x-amz-request-id: 3E70B5FDD3236B3B}{Date: Thu, 10 Oct 2019 15:19:45 GMT}{Content-Type: application/xml}{Transfer-Encoding: chunked}{Server: AmazonS3}
      2019-10-10 18:19:44.709 FINE    [org.jclouds.http.internal.JavaUrlHttpCommandExecutorService ] Receiving response 349720498: HTTP/1.1 200 OK
      2019-10-10 18:19:44.953 FINE    [org.jclouds.rest.internal.InvokeHttpMethod ] >> invoking GetObject
      2019-10-10 18:19:44.956 FINE    [org.jclouds.http.internal.JavaUrlHttpCommandExecutorService ] Sending request 1704375366: GET https://roded-data.s3-eu-central-1.amazonaws.com/blobname HTTP/1.1
      2019-10-10 18:19:44.957 FINEST  [sun.net.www.protocol.http.HttpURLConnection ] Looking for HttpClient for URL https://roded-data.s3-eu-central-1.amazonaws.com/blobname and proxy value of DIRECT
      2019-10-10 18:19:44.957 FINEST  [sun.net.www.protocol.http.HttpURLConnection ] Creating new HttpsClient with url:https://roded-data.s3-eu-central-1.amazonaws.com/blobname and proxy:DIRECT with connect timeout:60000
      2019-10-10 18:19:45.281 FINE    [sun.net.www.protocol.http.HttpURLConnection ] sun.net.www.MessageHeader@783ec9898 pairs: {GET /blobname HTTP/1.1: null}{x-amz-content-sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855}{X-Amz-Date: 20191010T151942Z}{Authorization: AWS4-HMAC-SHA256 Credential=AKIAJO5RLGWKFW5ASG3A/20191010/eu-central-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=baa2eab8c0a2aa579437fb8eeacfba21c49a6fb6eb38a64ad84266356d5dca91}{User-Agent: jclouds/2019.224.2 java/1.8.0_222}{Host: roded-data.s3-eu-central-1.amazonaws.com}{Accept: text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2}{Connection: keep-alive}
      2019-10-10 18:19:45.375 FINE    [sun.net.www.protocol.http.HttpURLConnection ] sun.net.www.MessageHeader@1ddd34787 pairs: {null: HTTP/1.1 404 Not Found}{x-amz-request-id: 704306CFDBF48166}{x-amz-id-2: 4kKdfwUUP7X11mUDEiziENQ24FHQew5sztVQUOrvFPWy8+Ziek6S29luoWxTiexL4gDaRp6b9nk=}{Content-Type: application/xml}{Transfer-Encoding: chunked}{Date: Thu, 10 Oct 2019 15:19:44 GMT}{Server: AmazonS3}
      2019-10-10 18:19:45.379 FINE    [org.jclouds.http.internal.JavaUrlHttpCommandExecutorService ] Receiving response 1704375366: HTTP/1.1 404 Not Found
      2019-10-10 18:19:45.400 FINE    [org.jclouds.rest.internal.InvokeHttpMethod ] >> invoking GetObject
      2019-10-10 18:19:45.407 FINE    [org.jclouds.http.internal.JavaUrlHttpCommandExecutorService ] Sending request 1704375366: GET https://roded-data.s3-eu-central-1.amazonaws.com/blobname HTTP/1.1
      2019-10-10 18:19:45.409 FINEST  [sun.net.www.protocol.http.HttpURLConnection ] Looking for HttpClient for URL https://roded-data.s3-eu-central-1.amazonaws.com/blobname and proxy value of DIRECT
      2019-10-10 18:19:45.411 FINEST  [sun.net.www.protocol.http.HttpURLConnection ] KeepAlive stream retrieved from the cache, sun.net.www.protocol.https.HttpsClient(https://roded-data.s3-eu-central-1.amazonaws.com/blobname)
      2019-10-10 18:19:45.413 FINE    [sun.net.www.protocol.http.HttpURLConnection ] sun.net.www.MessageHeader@7051777c8 pairs: {GET /blobname HTTP/1.1: null}{x-amz-content-sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855}{X-Amz-Date: 20191010T151942Z}{Authorization: AWS4-HMAC-SHA256 Credential=AKIAJO5RLGWKFW5ASG3A/20191010/eu-central-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=baa2eab8c0a2aa579437fb8eeacfba21c49a6fb6eb38a64ad84266356d5dca91}{User-Agent: jclouds/2019.224.2 java/1.8.0_222}{Host: roded-data.s3-eu-central-1.amazonaws.com}{Accept: text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2}{Connection: keep-alive}
      2019-10-10 18:19:45.501 FINE    [sun.net.www.protocol.http.HttpURLConnection ] sun.net.www.MessageHeader@3241713e7 pairs: {null: HTTP/1.1 404 Not Found}{x-amz-request-id: 95DCDF548AD1D3F5}{x-amz-id-2: nffnuE4bV5YV0zLQjEsmcH2zo9F+QIgkCAV3ynbrrkugvrPfoC86DIKZOG2kvbLiSeU0FAk63Kc=}{Content-Type: application/xml}{Transfer-Encoding: chunked}{Date: Thu, 10 Oct 2019 15:19:44 GMT}{Server: AmazonS3}
      2019-10-10 18:19:45.503 FINE    [org.jclouds.http.internal.JavaUrlHttpCommandExecutorService ] Receiving response 1704375366: HTTP/1.1 404 Not Found
      2019-10-10 18:19:45.519 FINE    [org.jclouds.rest.internal.InvokeHttpMethod ] >> invoking GetObject
      2019-10-10 18:19:45.528 FINE    [org.jclouds.http.internal.JavaUrlHttpCommandExecutorService ] Sending request 1704375366: GET https://roded-data.s3-eu-central-1.amazonaws.com/blobname HTTP/1.1
      2019-10-10 18:19:45.530 FINEST  [sun.net.www.protocol.http.HttpURLConnection ] Looking for HttpClient for URL https://roded-data.s3-eu-central-1.amazonaws.com/blobname and proxy value of DIRECT
      2019-10-10 18:19:45.531 FINEST  [sun.net.www.protocol.http.HttpURLConnection ] KeepAlive stream retrieved from the cache, sun.net.www.protocol.https.HttpsClient(https://roded-data.s3-eu-central-1.amazonaws.com/blobname)
      2019-10-10 18:19:45.537 FINE    [sun.net.www.protocol.http.HttpURLConnection ] sun.net.www.MessageHeader@2abc224d8 pairs: {GET /blobname HTTP/1.1: null}{x-amz-content-sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855}{X-Amz-Date: 20191010T151942Z}{Authorization: AWS4-HMAC-SHA256 Credential=AKIAJO5RLGWKFW5ASG3A/20191010/eu-central-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=baa2eab8c0a2aa579437fb8eeacfba21c49a6fb6eb38a64ad84266356d5dca91}{User-Agent: jclouds/2019.224.2 java/1.8.0_222}{Host: roded-data.s3-eu-central-1.amazonaws.com}{Accept: text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2}{Connection: keep-alive}
      2019-10-10 18:19:45.624 FINE    [sun.net.www.protocol.http.HttpURLConnection ] sun.net.www.MessageHeader@13cd7ea57 pairs: {null: HTTP/1.1 404 Not Found}{x-amz-request-id: 5F6BC6DF82764B6D}{x-amz-id-2: ib+NVkeJD0hSOu+8/1ZIo7OzeRa16SWDtQ+7k2K415w9KJFwbJISaal1u01wD1kKhPeE7UNbpRA=}{Content-Type: application/xml}{Transfer-Encoding: chunked}{Date: Thu, 10 Oct 2019 15:19:45 GMT}{Server: AmazonS3}
      2019-10-10 18:19:45.625 FINE    [org.jclouds.http.internal.JavaUrlHttpCommandExecutorService ] Receiving response 1704375366: HTTP/1.1 404 Not Found
      

      Note how the HttpsClient objects are retrieved from the cache.

      I purpose the following fix to UntrustedSSLContextSupplier which makes it return the same SSLContext for all get calls:

         @Singleton
         public static class UntrustedSSLContextSupplier implements Supplier<SSLContext> {
      
            private final SSLContext sslContext;
      
            @Inject
            UntrustedSSLContextSupplier(TrustAllCerts trustAllCerts) {
               try {
                  this.sslContext = SSLContext.getInstance("SSL");
                  this.sslContext.init(null, new TrustManager[] { trustAllCerts }, new SecureRandom());
               } catch (Exception e) {
                  throw Throwables.propagate(e);
               }
            }
      
            @Override
            public SSLContext get() {
               return sslContext;
            }
         }
      

        Attachments

        1. screenshot-1.png
          12 kB
          Roded Bahat

          Issue Links

            Activity

              People

              • Assignee:
                Unassigned
                Reporter:
                roded Roded Bahat
              • Votes:
                1 Vote for this issue
                Watchers:
                4 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved:

                  Time Tracking

                  Estimated:
                  Original Estimate - Not Specified
                  Not Specified
                  Remaining:
                  Remaining Estimate - 0h
                  0h
                  Logged:
                  Time Spent - 1.5h
                  1.5h