[JCLOUDS-1520] JClouds is not using the JDK's KeepAliveCache when UntrustedSSLContextSupplier is used - ASF JIRA

XML

Word

Printable

JSON

Details

Type: Bug
Status: Reopened
Priority: Major
Resolution: Unresolved
Affects Version/s: 2.1.0
Fix Version/s: None
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

- Sort By Name
- Sort By Date
- Ascending
- Descending

screenshot-1.png
13/Oct/19 08:06
12 kB
roded

Issue Links

links to

GitHub Pull Request #49

GitHub Pull Request #64

Activity

People

Assignee:: Unassigned

Reporter:: roded

Votes:: 0 Vote for this issue

Watchers:: 3 Start watching this issue

Dates

Created:: 10/Oct/19 15:21

Updated:: 03/Aug/22 22:41

Time Tracking

Estimated:

Not Specified

Remaining:

Logged:

5h 20m