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