On Thu, 2019-08-22 at 23:12 +0200, Joan grupoventus wrote:
> Hi Oleg,
>
> Well, not sure what's happening. In "our" git
> (https://github.com/joanbalaguero/HttpClient) I have uploaded 4
> files that
> connect by https to the problematic url.
>
> The "TestSync" is using a sync http5 client and works, ends with an
> exception "javax.net.ssl.SSLException: Unrecognized SSL message,
> plaintext
> connection?"
> The " TestAsync41ResponseConsumer.java" is using the async http 4.1.3
> client
> with an "HttpAsyncResponseConsumer" and works, ends with an exception
> "javax.net.ssl.SSLException: Unrecognized SSL message, plaintext
> connection?"
>
> The "TestAsync5FutureCallback" and "TestAsync5ResponseConsumer" are
> using an
> async http5 client (httpclient5-5-beta5 and httpcore5-5-beta9), the
> first
> one with a "FutureCallback<SimpleHttpResponse>" and the second with a
> "AsyncResponseConsumer<Void>". Both hang forever.
>
> So if this is not a bug in http5, what's wrong with these two last
> samples?
> The code there is minimal.
>
Joan,
I see nothing wrong with those samples and they all work for me
(HttpClient 5.0b5 + HttpCore 5.0b9-SNAPSHOT).
Oleg
---
2019-08-23 09:46:30,669 DEBUG
[main][org.apache.hc.client5.http.impl.async.InternalHttpAsyncClient]
ex-00000001: preparing request execution
2019-08-23 09:46:30,676 DEBUG
[main][org.apache.hc.client5.http.protocol.RequestAddCookies] CookieSpec
selected: standard
2019-08-23 09:46:30,680 DEBUG
[main][org.apache.hc.client5.http.protocol.RequestAuthCache] Auth cache not set
in the context
2019-08-23 09:46:30,680 DEBUG
[main][org.apache.hc.client5.http.impl.async.AsyncProtocolExec] ex-00000001:
target auth state: UNCHALLENGED
2019-08-23 09:46:30,681 DEBUG
[main][org.apache.hc.client5.http.impl.async.AsyncProtocolExec] ex-00000001:
proxy auth state: UNCHALLENGED
2019-08-23 09:46:30,683 DEBUG
[main][org.apache.hc.client5.http.impl.async.AsyncConnectExec] ex-00000001:
acquiring connection with route {s}->https://54.38.179.182:8083
2019-08-23 09:46:30,684 DEBUG
[main][org.apache.hc.client5.http.impl.async.InternalHttpAsyncClient]
ex-00000001: acquiring endpoint (3 MINUTES)
2019-08-23 09:46:30,685 DEBUG
[main][org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManager]
ex-00000001: endpoint lease request (3 MINUTES) [route:
{s}->https://54.38.179.182:8083][total kept alive: 0; route allocated: 0 of 5;
total allocated: 0 of 25]
2019-08-23 09:46:30,689 DEBUG
[main][org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManager]
ex-00000001: endpoint leased [route: {s}->https://54.38.179.182:8083][total
kept alive: 0; route allocated: 1 of 5; total allocated: 1 of 25]
2019-08-23 09:46:30,690 DEBUG
[main][org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManager]
ex-00000001: acquired ep-00000000
2019-08-23 09:46:30,690 DEBUG
[main][org.apache.hc.client5.http.impl.async.InternalHttpAsyncClient]
ex-00000001: acquired endpoint ep-00000000
2019-08-23 09:46:30,691 DEBUG
[main][org.apache.hc.client5.http.impl.async.InternalHttpAsyncClient]
ep-00000000: connecting endpoint (3 MINUTES)
2019-08-23 09:46:30,692 DEBUG
[main][org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManager]
ep-00000000: connecting endpoint to https://54.38.179.182:8083 (3 MINUTES)
2019-08-23 09:46:30,692 DEBUG
[main][org.apache.hc.client5.http.impl.nio.MultihomeIOSessionRequester]
https://54.38.179.182:8083: resolving remote address
2019-08-23 09:46:30,692 DEBUG
[main][org.apache.hc.client5.http.impl.nio.MultihomeIOSessionRequester]
https://54.38.179.182:8083: resolved to [/54.38.179.182]
2019-08-23 09:46:30,693 DEBUG
[main][org.apache.hc.client5.http.impl.nio.MultihomeIOSessionRequester]
https://54.38.179.182:8083: connecting null to /54.38.179.182:8083 (3 MINUTES)
2019-08-23 09:46:30,907 DEBUG
[httpclient-dispatch-1][org.apache.hc.client5.http.impl.nio.MultihomeIOSessionRequester]
https://54.38.179.182:8083: connected i/o-00000000
/192.168.43.142:48810->/54.38.179.182:8083
2019-08-23 09:46:30,912 DEBUG
[httpclient-dispatch-1][org.apache.hc.client5.http.impl.nio.DefaultManagedAsyncClientConnection]
i/o-00000000: start TLS
2019-08-23 09:46:30,963 DEBUG
[httpclient-dispatch-1][org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManager]
ep-00000000: connected i/o-00000000
2019-08-23 09:46:30,964 DEBUG
[httpclient-dispatch-1][org.apache.hc.client5.http.impl.async.InternalHttpAsyncClient]
ep-00000000: endpoint connected
2019-08-23 09:46:30,964 DEBUG
[httpclient-dispatch-1][org.apache.hc.client5.http.impl.async.AsyncConnectExec]
ex-00000001: connected to target
2019-08-23 09:46:30,964 DEBUG
[httpclient-dispatch-1][org.apache.hc.client5.http.impl.async.AsyncConnectExec]
ex-00000001: route fully established
2019-08-23 09:46:30,966 DEBUG
[httpclient-dispatch-1][org.apache.hc.client5.http.impl.async.HttpAsyncMainClientExec]
ex-00000001: executing POST /serhs HTTP/1.1
2019-08-23 09:46:30,969 DEBUG
[httpclient-dispatch-1][org.apache.hc.client5.http.impl.async.InternalHttpAsyncClient]
ep-00000000: start execution ex-00000001
2019-08-23 09:46:30,969 DEBUG
[httpclient-dispatch-1][org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManager]
ep-00000000: executing exchange ex-00000001 over i/o-00000000
2019-08-23 09:46:30,970 DEBUG
[httpclient-dispatch-1][org.apache.hc.client5.http.impl.nio.DefaultManagedAsyncClientConnection]
i/o-00000000: RequestExecutionCommand with NORMAL priority
2019-08-23 09:46:30,977 DEBUG
[httpclient-dispatch-1][org.apache.hc.client5.http.ssl.DefaultClientTlsStrategy]
Enabled protocols: [TLSv1.2]
2019-08-23 09:46:30,977 DEBUG
[httpclient-dispatch-1][org.apache.hc.client5.http.ssl.DefaultClientTlsStrategy]
Enabled cipher suites:[TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384,
TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384,
TLS_DHE_RSA_WITH_AES_256_GCM_SHA384, TLS_DHE_DSS_WITH_AES_256_GCM_SHA384,
TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256, TLS_DHE_RSA_WITH_AES_128_GCM_SHA256,
TLS_DHE_DSS_WITH_AES_128_GCM_SHA256]
2019-08-23 09:46:31,161 DEBUG
[httpclient-dispatch-1][org.apache.hc.client5.http.impl.async.HttpAsyncMainClientExec]
ex-00000001: execution failed: Unrecognized SSL message, plaintext connection?
2019-08-23 09:46:31,162 DEBUG
[httpclient-dispatch-1][org.apache.hc.client5.http.impl.async.InternalHttpAsyncClient]
ex-00000001: request failed: Unrecognized SSL message, plaintext connection?
2019-08-23 09:46:31,162 DEBUG
[httpclient-dispatch-1][org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManager]
ep-00000000: close IMMEDIATE
2019-08-23 09:46:31,162 DEBUG
[httpclient-dispatch-1][org.apache.hc.client5.http.impl.nio.DefaultManagedAsyncClientConnection]
i/o-00000000: Shutdown connection IMMEDIATE
2019-08-23 09:46:31,163 DEBUG
[httpclient-dispatch-1][org.apache.hc.client5.http.impl.async.InternalHttpAsyncClient]
ep-00000000: endpoint closed
2019-08-23 09:46:31,163 DEBUG
[httpclient-dispatch-1][org.apache.hc.client5.http.impl.async.InternalHttpAsyncClient]
ep-00000000: discarding endpoint
2019-08-23 09:46:31,163 DEBUG
[httpclient-dispatch-1][org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManager]
ep-00000000: releasing endpoint
2019-08-23 09:46:31,164 DEBUG
[httpclient-dispatch-1][org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManager]
ep-00000000: connection released [route:
{s}->https://54.38.179.182:8083][total kept alive: 0; route allocated: 0 of 5;
total allocated: 0 of 25]
failed !!!!javax.net.ssl.SSLException: Unrecognized SSL message, plaintext
connection?
at
sun.security.ssl.EngineInputRecord.bytesInCompletePacket(EngineInputRecord.java:156)
at sun.security.ssl.SSLEngineImpl.readNetRecord(SSLEngineImpl.java:868)
at sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:781)
at javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:624)
at
org.apache.hc.core5.reactor.ssl.SSLIOSession.doUnwrap(SSLIOSession.java:267)
at
org.apache.hc.core5.reactor.ssl.SSLIOSession.doHandshake(SSLIOSession.java:313)
at
org.apache.hc.core5.reactor.ssl.SSLIOSession.isAppInputReady(SSLIOSession.java:529)
at
org.apache.hc.core5.reactor.InternalDataChannel.onIOEvent(InternalDataChannel.java:122)
at
org.apache.hc.core5.reactor.InternalChannel.handleIOEvent(InternalChannel.java:51)
at
org.apache.hc.core5.reactor.SingleCoreIOReactor.processEvents(SingleCoreIOReactor.java:177)
at
org.apache.hc.core5.reactor.SingleCoreIOReactor.doExecute(SingleCoreIOReactor.java:127)
at
org.apache.hc.core5.reactor.AbstractSingleCoreIOReactor.execute(AbstractSingleCoreIOReactor.java:82)
at
org.apache.hc.core5.reactor.IOReactorWorker.run(IOReactorWorker.java:44)
at java.lang.Thread.run(Thread.java:748)
java.util.concurrent.ExecutionException: javax.net.ssl.SSLException:
Unrecognized SSL message, plaintext connection?
at
org.apache.hc.core5.concurrent.BasicFuture.getResult(BasicFuture.java:72)
at org.apache.hc.core5.concurrent.BasicFuture.get(BasicFuture.java:85)
at
testing.TestAsync5FutureCallback.main(TestAsync5FutureCallback.java:45)
Caused by: javax.net.ssl.SSLException: Unrecognized SSL message, plaintext
connection?
at
sun.security.ssl.EngineInputRecord.bytesInCompletePacket(EngineInputRecord.java:156)
at sun.security.ssl.SSLEngineImpl.readNetRecord(SSLEngineImpl.java:868)
at sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:781)
at javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:624)
at
org.apache.hc.core5.reactor.ssl.SSLIOSession.doUnwrap(SSLIOSession.java:267)
at
org.apache.hc.core5.reactor.ssl.SSLIOSession.doHandshake(SSLIOSession.java:313)
at
org.apache.hc.core5.reactor.ssl.SSLIOSession.isAppInputReady(SSLIOSession.java:529)
at
org.apache.hc.core5.reactor.InternalDataChannel.onIOEvent(InternalDataChannel.java:122)
at
org.apache.hc.core5.reactor.InternalChannel.handleIOEvent(InternalChannel.java:51)
at
org.apache.hc.core5.reactor.SingleCoreIOReactor.processEvents(SingleCoreIOReactor.java:177)
at
org.apache.hc.core5.reactor.SingleCoreIOReactor.doExecute(SingleCoreIOReactor.java:127)
at
org.apache.hc.core5.reactor.AbstractSingleCoreIOReactor.execute(AbstractSingleCoreIOReactor.java:82)
at
org.apache.hc.core5.reactor.IOReactorWorker.run(IOReactorWorker.java:44)
at java.lang.Thread.run(Thread.java:748)
2019-08-23 09:46:31,169 DEBUG
[main][org.apache.hc.client5.http.impl.async.InternalHttpAsyncClient] Shutdown
GRACEFUL
2019-08-23 09:46:31,180 DEBUG
[main][org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManager]
Shutdown connection pool GRACEFUL
2019-08-23 09:46:31,181 DEBUG
[main][org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManager]
Connection pool shut down
> Thanks,
> Joan.
>
>
> -----Original Message-----
> From: Oleg Kalnichevski <ol...@apache.org>
> Sent: Thursday, August 22, 2019 12:05 PM
> To: HttpClient User Discussion <httpclient-users@hc.apache.org>
> Subject: Re: Issue sending https to an http endpoint
>
> On Wed, 2019-08-21 at 22:24 +0200, Joan grupoventus wrote:
> > Hi Oleg,
> >
> > Tried with httpcore5-5.0-beta9.jar. The same result.
> >
>
> I am sorry, Joan, but I am unable to reproduce the problem with
> HttpClient
> 5.0-beta5 and the latest HttpCore 5.0-beta9-SNAPSHOT. It works as
> expected
> for me.
>
> Oleg
>
> ---
> 2019-08-22 12:02:43,978 DEBUG
> [main][org.apache.hc.client5.http.impl.async.InternalHttpAsyncClient]
> ex-00000001: preparing request execution
> 2019-08-22 12:02:43,986 DEBUG
> [main][org.apache.hc.client5.http.protocol.RequestAddCookies]
> CookieSpec
> selected: standard
> 2019-08-22 12:02:43,990 DEBUG
> [main][org.apache.hc.client5.http.protocol.RequestAuthCache] Auth
> cache not
> set in the context
> 2019-08-22 12:02:43,991 DEBUG
> [main][org.apache.hc.client5.http.impl.async.AsyncProtocolExec] ex-
> 00000001:
> target auth state: UNCHALLENGED
> 2019-08-22 12:02:43,991 DEBUG
> [main][org.apache.hc.client5.http.impl.async.AsyncProtocolExec] ex-
> 00000001:
> proxy auth state: UNCHALLENGED
> 2019-08-22 12:02:43,993 DEBUG
> [main][org.apache.hc.client5.http.impl.async.AsyncConnectExec] ex-
> 00000001:
> acquiring connection with route {s}->https://localhost:8080
> 2019-08-22 12:02:43,993 DEBUG
> [main][org.apache.hc.client5.http.impl.async.InternalHttpAsyncClient]
> ex-00000001: acquiring endpoint (3 MINUTES)
> 2019-08-22 12:02:43,995 DEBUG
> [main][org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnecti
> onManag
> er] ex-00000001: endpoint lease request (3 MINUTES) [route:
> {s}->https://localhost:8080][total kept alive: 0; route allocated: 0
> of 5;
> total allocated: 0 of 25]
> 2019-08-22 12:02:43,998 DEBUG
> [main][org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnecti
> onManag
> er] ex-00000001: endpoint leased [route: {s}->
> https://localhost:8080][total
> kept alive: 0; route allocated: 1 of 5; total allocated: 1 of 25]
> 2019-08-22 12:02:43,998 DEBUG
> [main][org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnecti
> onManag
> er] ex-00000001: acquired ep-00000000
> 2019-08-22 12:02:43,999 DEBUG
> [main][org.apache.hc.client5.http.impl.async.InternalHttpAsyncClient]
> ex-00000001: acquired endpoint ep-00000000
> 2019-08-22 12:02:43,999 DEBUG
> [main][org.apache.hc.client5.http.impl.async.InternalHttpAsyncClient]
> ep-00000000: connecting endpoint (3 MINUTES)
> 2019-08-22 12:02:44,000 DEBUG
> [main][org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnecti
> onManag
> er] ep-00000000: connecting endpoint to https://localhost:8080 (3
> MINUTES)
> 2019-08-22 12:02:44,000 DEBUG
> [main][org.apache.hc.client5.http.impl.nio.MultihomeIOSessionRequeste
> r]
> https://localhost:8080: resolving remote address
> 2019-08-22 12:02:44,001 DEBUG
> [main][org.apache.hc.client5.http.impl.nio.MultihomeIOSessionRequeste
> r]
> https://localhost:8080: resolved to [localhost/127.0.0.1]
> 2019-08-22 12:02:44,001 DEBUG
> [main][org.apache.hc.client5.http.impl.nio.MultihomeIOSessionRequeste
> r]
> https://localhost:8080: connecting null to localhost/127.0.0.1:8080
> (3
> MINUTES)
> 2019-08-22 12:02:44,023 DEBUG
> [httpclient-dispatch-
> 1][org.apache.hc.client5.http.impl.nio.MultihomeIOSessi
> onRequester] https://localhost:8080: connected i/o-00000000
> /127.0.0.1:50902->localhost/127.0.0.1:8080
> 2019-08-22 12:02:44,025 DEBUG
> [httpclient-dispatch-
> 1][org.apache.hc.client5.http.impl.nio.DefaultManagedAs
> yncClientConnection] i/o-00000000: start TLS
> 2019-08-22 12:02:44,042 DEBUG
> [httpclient-dispatch-
> 1][org.apache.hc.client5.http.impl.nio.PoolingAsyncClie
> ntConnectionManager] ep-00000000: connected i/o-00000000
> 2019-08-22 12:02:44,042 DEBUG
> [httpclient-dispatch-
> 1][org.apache.hc.client5.http.impl.async.InternalHttpAs
> yncClient] ep-00000000: endpoint connected
> 2019-08-22 12:02:44,043 DEBUG
> [httpclient-dispatch-
> 1][org.apache.hc.client5.http.impl.async.AsyncConnectEx
> ec] ex-00000001: connected to target
> 2019-08-22 12:02:44,043 DEBUG
> [httpclient-dispatch-
> 1][org.apache.hc.client5.http.impl.async.AsyncConnectEx
> ec] ex-00000001: route fully established
> 2019-08-22 12:02:44,043 DEBUG
> [httpclient-dispatch-
> 1][org.apache.hc.client5.http.impl.async.HttpAsyncMainC
> lientExec] ex-00000001: executing OPTIONS * HTTP/1.1
> 2019-08-22 12:02:44,044 DEBUG
> [httpclient-dispatch-
> 1][org.apache.hc.client5.http.impl.async.InternalHttpAs
> yncClient] ep-00000000: start execution ex-00000001
> 2019-08-22 12:02:44,044 DEBUG
> [httpclient-dispatch-
> 1][org.apache.hc.client5.http.impl.nio.PoolingAsyncClie
> ntConnectionManager] ep-00000000: executing exchange ex-00000001 over
> i/o-00000000
> 2019-08-22 12:02:44,045 DEBUG
> [httpclient-dispatch-
> 1][org.apache.hc.client5.http.impl.nio.DefaultManagedAs
> yncClientConnection] i/o-00000000: RequestExecutionCommand with
> NORMAL
> priority
> 2019-08-22 12:02:44,047 DEBUG
> [httpclient-dispatch-
> 1][org.apache.hc.client5.http.ssl.DefaultClientTlsStrat
> egy] Enabled protocols: [TLSv1, TLSv1.1, TLSv1.2]
> 2019-08-22 12:02:44,047 DEBUG
> [httpclient-dispatch-
> 1][org.apache.hc.client5.http.ssl.DefaultClientTlsStrat
> egy] Enabled cipher suites:[TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA384,
> TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384,
> TLS_RSA_WITH_AES_256_CBC_SHA256,
> TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA384,
> TLS_ECDH_RSA_WITH_AES_256_CBC_SHA384,
> TLS_DHE_RSA_WITH_AES_256_CBC_SHA256,
> TLS_DHE_DSS_WITH_AES_256_CBC_SHA256,
> TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA,
> TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA, TLS_RSA_WITH_AES_256_CBC_SHA,
> TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA,
> TLS_ECDH_RSA_WITH_AES_256_CBC_SHA,
> TLS_DHE_RSA_WITH_AES_256_CBC_SHA, TLS_DHE_DSS_WITH_AES_256_CBC_SHA,
> TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA256,
> TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256,
> TLS_RSA_WITH_AES_128_CBC_SHA256,
> TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA256,
> TLS_ECDH_RSA_WITH_AES_128_CBC_SHA256,
> TLS_DHE_RSA_WITH_AES_128_CBC_SHA256,
> TLS_DHE_DSS_WITH_AES_128_CBC_SHA256,
> TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA,
> TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA, TLS_RSA_WITH_AES_128_CBC_SHA,
> TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA,
> TLS_ECDH_RSA_WITH_AES_128_CBC_SHA,
> TLS_DHE_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_DSS_WITH_AES_128_CBC_SHA,
> TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384,
> TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256,
> TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384,
> TLS_RSA_WITH_AES_256_GCM_SHA384,
> TLS_ECDH_ECDSA_WITH_AES_256_GCM_SHA384,
> TLS_ECDH_RSA_WITH_AES_256_GCM_SHA384,
> TLS_DHE_RSA_WITH_AES_256_GCM_SHA384,
> TLS_DHE_DSS_WITH_AES_256_GCM_SHA384,
> TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256,
> TLS_RSA_WITH_AES_128_GCM_SHA256,
> TLS_ECDH_ECDSA_WITH_AES_128_GCM_SHA256,
> TLS_ECDH_RSA_WITH_AES_128_GCM_SHA256,
> TLS_DHE_RSA_WITH_AES_128_GCM_SHA256,
> TLS_DHE_DSS_WITH_AES_128_GCM_SHA256,
> TLS_EMPTY_RENEGOTIATION_INFO_SCSV]
> 2019-08-22 12:02:44,083 DEBUG
> [httpclient-dispatch-
> 1][org.apache.hc.client5.http.impl.async.HttpAsyncMainC
> lientExec] ex-00000001: execution failed: Unrecognized SSL message,
> plaintext connection?
> 2019-08-22 12:02:44,084 DEBUG
> [httpclient-dispatch-
> 1][org.apache.hc.client5.http.impl.async.InternalHttpAs
> yncClient] ex-00000001: request failed: Unrecognized SSL message,
> plaintext
> connection?
> 2019-08-22 12:02:44,084 DEBUG
> [httpclient-dispatch-
> 1][org.apache.hc.client5.http.impl.nio.PoolingAsyncClie
> ntConnectionManager] ep-00000000: close IMMEDIATE
> 2019-08-22 12:02:44,084 DEBUG
> [httpclient-dispatch-
> 1][org.apache.hc.client5.http.impl.nio.DefaultManagedAs
> yncClientConnection] i/o-00000000: Shutdown connection IMMEDIATE
> 2019-08-22 12:02:44,084 DEBUG
> [httpclient-dispatch-
> 1][org.apache.hc.client5.http.impl.async.InternalHttpAs
> yncClient] ep-00000000: endpoint closed
> 2019-08-22 12:02:44,084 DEBUG
> [httpclient-dispatch-
> 1][org.apache.hc.client5.http.impl.async.InternalHttpAs
> yncClient] ep-00000000: discarding endpoint
> 2019-08-22 12:02:44,084 DEBUG
> [httpclient-dispatch-
> 1][org.apache.hc.client5.http.impl.nio.PoolingAsyncClie
> ntConnectionManager] ep-00000000: releasing endpoint
> 2019-08-22 12:02:44,084 DEBUG
> [httpclient-dispatch-
> 1][org.apache.hc.client5.http.impl.nio.PoolingAsyncClie
> ntConnectionManager] ep-00000000: connection released [route:
> {s}->https://localhost:8080][total kept alive: 0; route allocated: 0
> of 5;
> total allocated: 0 of 25]
> NOK: HTTP/1.1 https://localhost:8080: OPTIONS * -> (Unrecognized SSL
> message, plaintext connection?)
>
> > Thanks,
> > Joan.
> >
> > -----Original Message-----
> > From: Oleg Kalnichevski <ol...@apache.org>
> > Sent: Monday, August 19, 2019 9:15 AM
> > To: HttpClient User Discussion <httpclient-users@hc.apache.org>
> > Subject: Re: Issue sending https to an http endpoint
> >
> > On Sun, 2019-08-18 at 21:05 +0200, Joan grupoventus wrote:
> > > Hello,
> > >
> > >
> > >
> > > A mistake made by one of our clients has brought us a possible
> > > issue
> > > to our attention. We have been able to reproduce it on our test
> > > environment.
> > >
> > >
> > >
> > > The client has an endpoint that only listens on http connections
> > > on
> > > ports 8080,8081,8082 and 8083. By mistake all traffic from our
> > > gateway to their backend has been sent by https instead of http,
> > > and
> > > this provoked the pool to have all connections allocated (pool
> > > exhausted).
> > >
> >
> > Hi Joan
> >
> > I think this issue has already been resolved in HttpCore master.
> > Could you please try to reproduce the issue the latest HttpCore
> > snapshot? You will need to build HttpCore from source to do so.
> >
> > https://github.com/apache/httpcomponents-core
> >
> > Oleg
> >
> > >
> > >
> > > We have tried to send https requests to an http endpoint using
> > > post
> > > methods through a “ <eclipse-javadoc:%E2%98%82=vpfw/web%5C/WEB-
> > > INF%5C/lib%5C/httpclient5-5.0-beta5.jar%3Corg> org. <eclipse-
> > > javadoc:%E2%98%82=vpfw/web%5C/WEB-INF%5C/lib%5C/httpclient5-5.0-
> > > beta5.jar%3Corg.apache> apache. <eclipse-
> > > javadoc:%E2%98%82=vpfw/web%5C/WEB-INF%5C/lib%5C/httpclient5-5.0-
> > > beta5.jar%3Corg.apache.hc> hc. <eclipse-
> > > javadoc:%E2%98%82=vpfw/web%5C/WEB-INF%5C/lib%5C/httpclient5-5.0-
> > > beta5.jar%3Corg.apache.hc.client5> client5. <eclipse-
> > > javadoc:%E2%98%82=vpfw/web%5C/WEB-INF%5C/lib%5C/httpclient5-5.0-
> > > beta5.jar%3Corg.apache.hc.client5.http> http. <eclipse-
> > > javadoc:%E2%98%82=vpfw/web%5C/WEB-INF%5C/lib%5C/httpclient5-5.0-
> > > beta5.jar%3Corg.apache.hc.client5.http.impl> impl. <eclipse-
> > > javadoc:%E2%98%82=vpfw/web%5C/WEB-INF%5C/lib%5C/httpclient5-5.0-
> > > beta5.jar%3Corg.apache.hc.client5.http.impl.io>
> > > io.PoolingHttpClientConnectionManag"r”. Just send the request
> > > synchronously and await the respo...se … and the error we
> > > immediately
> > > get is: javax.net.ssl.SSLException: Unrecognized SSL message,
> > > plaintext connection?
> > >
> > >
> > >
> >
> > ' That’s ok. Now we have tried the real situation, sending a
> > request
> > > asynchronously to the same endpoint using a “ <eclipse-
> > > javadoc:%E2%98%82=vpfw/web%5C/WEB-INF%5C/lib%5C/httpclient5-5.0-
> > > beta5.jar%3Corg> org. <eclipse-javadoc:%E2%98%82=vpfw/web%5C/WEB-
> > > INF%5C/lib%5C/httpclient5-5.0-beta5.jar%3Corg.apache> apache.
> > > <eclipse-javadoc:%E2%98%82=vpfw/web%5C/WEB-
> > > INF%5C/lib%5C/httpclient5-
> > > 5.0-beta5.jar%3Corg.apache.hc> hc. <eclipse-
> > > javadoc:%E2%98%82=vpfw/web%5C/WEB-INF%5C/lib%5C/httpclient5-5.0-
> > > beta5.jar%3Corg.apache.hc.client5> client5. <eclipse-
> > > javadoc:%E2%98%82=vpfw/web%5C/WEB-INF%5C/lib%5C/httpclient5-5.0-
> > > beta5.jar%3Corg.apache.hc.client5.http> http. <eclipse-
> > > javadoc:%E2%98%82=vpfw/web%5C/WEB-INF%5C/lib%5C/httpclient5-5.0-
> > > beta5.jar%3Corg.apache.hc.client5.http.impl> impl. <eclipse-
> > > javadoc:%E2%98%82=vpfw/web%5C/WEB-INF%5C/lib%5C/httpclient5-5.0-
> > > beta5.jar%3Corg.apache.hc.client5.http.impl.nio>
> > > nio.PoolingAsyncClientConnectionManag"r” and trying to manage
> > > the
> > > response i" a “ <eclipse-javadoc:%E2%98%82=vpfw/web%5C/WEB-
> > > INF%5C/lib%5C/httpcore5-5.0-beta8.jar%3Corg> org. <eclipse-
> > > javadoc:%E2%98%82=vpfw/web%5C/WEB-INF%5C/lib%5C/httpcore5-5.0-
> > > beta8.jar%3Corg.apache> apache. <eclipse-
> > > javadoc:%E2%98%82=vpfw/web%5C/WEB-INF%5C/lib%5C/httpcore5-5.0-
> > > beta8.jar%3Corg.apache.hc> hc. <eclipse-
> > > javadoc:%E2%98%82=vpfw/web%5C/WEB-INF%5C/lib%5C/httpcore5-5.0-
> > > beta8.jar%3Corg.apache.hc.core5> core5. <eclipse-
> > > javadoc:%E2%98%82=vpfw/web%5C/WEB-INF%5C/lib%5C/httpcore5-5.0-
> > > beta8.jar%3Corg.apache.hc.core5.http> http. <eclipse-
> > > javadoc:%E2%98%82=vpfw/web%5C/WEB-INF%5C/lib%5C/httpcore5-5.0-
> > > beta8.jar%3Corg.apache.hc.core5.http.nio>
> > > nio.AsyncResponseCo"sumer”.
> > > The result is the request never finishes (the thread is only
> > > released when the container asynchronous timeout is reached) and
> > > the
> > > connection is never returned to the pool.
> > >
> > >
> > >
> > > This is the trace for the first request sent at 20:30:51 that
> > > finished after 120s when the container asynchronous timeout was
> > > reached:
> > >
> > >
> > >
> > > App trace:
> > >
> > > 20:30:51.379,120419,response.noResponse,20:32:51.798
> > >
> > >
> > >
> > > Http5 trace:
> > >
> > > 20:30:51.381 ex-00000004: preparing request execution
> > >
> > > 20:30:51.381 ex-00000004: target auth state: UNCHALLENGED
> > >
> > > 20:30:51.381 ex-00000004: proxy auth state: UNCHALLENGED
> > >
> > > 20:30:51.381 ex-00000004: acquiring connection with route
> > > {s}->
> > > https://54.38.179.182:8080
> > >
> > > 20:30:51.381 ex-00000004: acquiring endpoint (1
> > > MILLISECONDS)
> > >
> > > 20:30:51.382 ex-00000004: endpoint lease request (1
> > > MILLISECONDS) [route: {s}->https://54.38.179.182:8080][total kept
> > > alive: 0; route allocated: 0 of 50; total allocated: 0 of 50]
> > >
> > > 20:30:51.382 ex-00000004: endpoint leased [route: {s}->
> > > https://54.38.179.182:8080][total kept alive: 0; route allocated:
> > > 1
> > > of 50; total allocated: 1 of 50]
> > >
> > > 20:30:51.382 ex-00000004: acquired ep-00000003
> > >
> > > 20:30:51.382 ex-00000004: acquired endpoint ep-00000003
> > >
> > > 20:30:51.382 ep-00000003: connecting endpoint (2,000
> > > MILLISECONDS)
> > >
> > > 20:30:51.382 ep-00000003: connecting endpoint to
> > > https://54.38.179.182:8080 (2,000 MILLISECONDS)
> > >
> > > 20:30:51.382 https://54.38.179.182:8080: resolving remote
> > > address
> > >
> > > 20:30:51.382 https://54.38.179.182:8080: resolved to
> > > [/54.38.179.182]
> > >
> > > 20:30:51.382 https://54.38.179.182:8080: connecting null to
> > > /54.38.179.182:8080 (2,000 MILLISECONDS)
> > >
> > > 20:30:51.383 https://54.38.179.182:8080: connected i/o-
> > > 00000003
> > > /54.36.51.138:45374->/54.38.179.182:8080
> > >
> > > 20:30:51.383 i/o-00000003: start TLS
> > >
> > > 20:30:51.383 ep-00000003: connected i/o-00000003
> > >
> > > 20:30:51.383 ep-00000003: endpoint connected
> > >
> > > 20:30:51.383 ex-00000004: connected to target
> > >
> > > 20:30:51.383 ex-00000004: route fully established
> > >
> > > 20:30:51.383 ex-00000004: executing POST /serhs HTTP/1.1
> > >
> > > 20:30:51.383 ep-00000003: start execution ex-00000004
> > >
> > > 20:30:51.383 ep-00000003: executing exchange ex-00000004
> > > over
> > > i/o-00000003
> > >
> > > 20:30:51.383 i/o-00000003: RequestExecutionCommand with
> > > NORMAL
> > > priority
> > >
> > > 20:30:51.383 Enabled protocols: [TLSv1.2]
> > >
> > > 20:30:51.383 Enabled cipher
> > > suites:[TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384,
> > > TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256,
> > > TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384,
> > > TLS_DHE_RSA_WITH_AES_256_GCM_SHA384,
> > > TLS_DHE_DSS_WITH_AES_256_GCM_SHA384,
> > > TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256,
> > > TLS_DHE_RSA_WITH_AES_128_GCM_SHA256,
> > > TLS_DHE_DSS_WITH_AES_128_GCM_SHA256]
> > >
> > >
> > >
> > >
> > >
> > > And this is the trace for the second request sent at 20:30:51. A
> > > second connection is allocated:
> > >
> > >
> > >
> > > App trace:
> > >
> > > 20:33:11.636,120173,response.noResponse,20:35:11.809
> > >
> > >
> > >
> > > Http5 trace:
> > >
> > > 20:33:11.638 ex-00000005: preparing request execution
> > >
> > > 20:33:11.638 ex-00000005: target auth state: UNCHALLENGED
> > >
> > > 20:33:11.638 ex-00000005: proxy auth state: UNCHALLENGED
> > >
> > > 20:33:11.638 ex-00000005: acquiring connection with route
> > > {s}->
> > > https://54.38.179.182:8081
> > >
> > > 20:33:11.638 ex-00000005: acquiring endpoint (1
> > > MILLISECONDS)
> > >
> > > 20:33:11.638 ex-00000005: endpoint lease request (1
> > > MILLISECONDS) [route: {s}->https://54.38.179.182:8081][total kept
> > > alive: 0; route allocated: 0 of 50; total allocated: 1 of 50]
> > >
> > > 20:33:11.638 ex-00000005: endpoint leased [route: {s}->
> > > https://54.38.179.182:8081][total kept alive: 0; route allocated:
> > > 1
> > > of 50; total allocated: 2 of 50]
> > >
> > > 20:33:11.638 ex-00000005: acquired ep-00000004
> > >
> > > 20:33:11.639 ex-00000005: acquired endpoint ep-00000004
> > >
> > > 20:33:11.639 ep-00000004: connecting endpoint (2,000
> > > MILLISECONDS)
> > >
> > > 20:33:11.639 ep-00000004: connecting endpoint to
> > > https://54.38.179.182:8081 (2,000 MILLISECONDS)
> > >
> > > 20:33:11.639 https://54.38.179.182:8081: resolving remote
> > > address
> > >
> > > 20:33:11.639 https://54.38.179.182:8081: resolved to
> > > [/54.38.179.182]
> > >
> > > 20:33:11.639 https://54.38.179.182:8081: connecting null to
> > > /54.38.179.182:8081 (2,000 MILLISECONDS)
> > >
> > > 20:33:11.640 https://54.38.179.182:8081: connected i/o-
> > > 00000004
> > > /54.36.51.138:36134->/54.38.179.182:8081
> > >
> > > 20:33:11.640 i/o-00000004: start TLS
> > >
> > > 20:33:11.640 ep-00000004: connected i/o-00000004
> > >
> > > 20:33:11.640 ep-00000004: endpoint connected
> > >
> > > 20:33:11.640 ex-00000005: connected to target
> > >
> > > 20:33:11.640 ex-00000005: route fully established
> > >
> > > 20:33:11.640 ex-00000005: executing POST /serhs HTTP/1.1
> > >
> > > 20:33:11.640 ep-00000004: start execution ex-00000005
> > >
> > > 20:33:11.640 ep-00000004: executing exchange ex-00000005
> > > over
> > > i/o-00000004
> > >
> > > 20:33:11.640 i/o-00000004: RequestExecutionCommand with
> > > NORMAL
> > > priority
> > >
> > > 20:33:11.640 Enabled protocols: [TLSv1.2]
> > >
> > > 20:33:11.640 Enabled cipher
> > > suites:[TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384,
> > > TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256,
> > > TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384,
> > > TLS_DHE_RSA_WITH_AES_256_GCM_SHA384,
> > > TLS_DHE_DSS_WITH_AES_256_GCM_SHA384,
> > > TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256,
> > > TLS_DHE_RSA_WITH_AES_128_GCM_SHA256,
> > > TLS_DHE_DSS_WITH_AES_128_GCM_SHA256]
> > >
> > >
> > >
> > > This is httpclient5-5.0-beta5 and httpcore5-5.0-beta8. The
> > > connection and response timeout for these requests are 2s and
> > > 10s.
> > >
> > >
> > >
> > > Let me know if you need further information.
> > >
> > >
> > >
> > > Thanks,
> > >
> > > Joan.
> > >
> >
> >
> > -----------------------------------------------------------------
> > ----
> > To unsubscribe, e-mail: httpclient-users-unsubscr...@hc.apache.org
> > For additional commands, e-mail:
> > httpclient-users-h...@hc.apache.org
> >
> >
> >
> >
> > -----------------------------------------------------------------
> > ----
> > To unsubscribe, e-mail: httpclient-users-unsubscr...@hc.apache.org
> > For additional commands, e-mail:
> > httpclient-users-h...@hc.apache.org
> >
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: httpclient-users-unsubscr...@hc.apache.org
> For additional commands, e-mail: httpclient-users-h...@hc.apache.org
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: httpclient-users-unsubscr...@hc.apache.org
> For additional commands, e-mail: httpclient-users-h...@hc.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscr...@hc.apache.org
For additional commands, e-mail: httpclient-users-h...@hc.apache.org
