Roded Bahat created JCLOUDS-1520:
------------------------------------
Summary: 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
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 reusing
existing TLS connections even though it could.
The cache miss happens at {{sun.net.www.protocol.https.HttpsClient}} line 329:
{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}}s are retreived from the cache.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
