[ https://issues.apache.org/jira/browse/JCLOUDS-1520?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Roded Bahat updated JCLOUDS-1520: --------------------------------- Attachment: screenshot-1.png > JClouds is not using the JDK's KeepAliveCache when > UntrustedSSLContextSupplier is used > -------------------------------------------------------------------------------------- > > Key: JCLOUDS-1520 > URL: https://issues.apache.org/jira/browse/JCLOUDS-1520 > Project: jclouds > Issue Type: Bug > Components: jclouds-core > Affects Versions: 2.1.0 > Reporter: Roded Bahat > Priority: Major > Attachments: screenshot-1.png > > > 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"): > {noformat} > /* see if one's already around */ > ret = (HttpsClient) kac.get(url, sf); > {noformat} > To reproduce, consider the following main: > {noformat} > 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); > } > {noformat} > If run using a JUL logging.properties with the following logger set to FINEST: > {noformat} > sun.net.www.protocol.http.level=FINEST > {noformat} > The following log is produced: > {noformat} > 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 > {noformat} > Note the "Creating new HttpsClient" for every request. > If however we disable the {{jclouds.trust-all-certs}} property, we get the > following log: > {noformat} > 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 > {noformat} > 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: > {noformat} > @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; > } > } > {noformat} -- This message was sent by Atlassian Jira (v8.3.4#803005)