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.PoolingAsyncClientConnectionManager] 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.PoolingAsyncClientConnectionManager] 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.PoolingAsyncClientConnectionManager] 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.PoolingAsyncClientConnectionManager] 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.MultihomeIOSessionRequester] https://localhost:8080: resolving remote address 2019-08-22 12:02:44,001 DEBUG [main][org.apache.hc.client5.http.impl.nio.MultihomeIOSessionRequester] 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.MultihomeIOSessionRequester] 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.MultihomeIOSessionRequester] 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.DefaultManagedAsyncClientConnection] i/o-00000000: start TLS 2019-08-22 12:02:44,042 DEBUG [httpclient-dispatch-1][org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManager] ep-00000000: connected i/o-00000000 2019-08-22 12:02:44,042 DEBUG [httpclient-dispatch-1][org.apache.hc.client5.http.impl.async.InternalHttpAsyncClient] ep-00000000: endpoint connected 2019-08-22 12:02:44,043 DEBUG [httpclient-dispatch-1][org.apache.hc.client5.http.impl.async.AsyncConnectExec] ex-00000001: connected to target 2019-08-22 12:02:44,043 DEBUG [httpclient-dispatch-1][org.apache.hc.client5.http.impl.async.AsyncConnectExec] ex-00000001: route fully established 2019-08-22 12:02:44,043 DEBUG [httpclient-dispatch-1][org.apache.hc.client5.http.impl.async.HttpAsyncMainClientExec] 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.InternalHttpAsyncClient] ep-00000000: start execution ex-00000001 2019-08-22 12:02:44,044 DEBUG [httpclient-dispatch-1][org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManager] 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.DefaultManagedAsyncClientConnection] i/o-00000000: RequestExecutionCommand with NORMAL priority 2019-08-22 12:02:44,047 DEBUG [httpclient-dispatch-1][org.apache.hc.client5.http.ssl.DefaultClientTlsStrategy] Enabled protocols: [TLSv1, TLSv1.1, TLSv1.2] 2019-08-22 12:02:44,047 DEBUG [httpclient-dispatch-1][org.apache.hc.client5.http.ssl.DefaultClientTlsStrategy] 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.HttpAsyncMainClientExec] 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.InternalHttpAsyncClient] 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.PoolingAsyncClientConnectionManager] ep-00000000: close IMMEDIATE 2019-08-22 12:02:44,084 DEBUG [httpclient-dispatch-1][org.apache.hc.client5.http.impl.nio.DefaultManagedAsyncClientConnection] i/o-00000000: Shutdown connection IMMEDIATE 2019-08-22 12:02:44,084 DEBUG [httpclient-dispatch-1][org.apache.hc.client5.http.impl.async.InternalHttpAsyncClient] ep-00000000: endpoint closed 2019-08-22 12:02:44,084 DEBUG [httpclient-dispatch-1][org.apache.hc.client5.http.impl.async.InternalHttpAsyncClient] ep-00000000: discarding endpoint 2019-08-22 12:02:44,084 DEBUG [httpclient-dispatch-1][org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManager] ep-00000000: releasing endpoint 2019-08-22 12:02:44,084 DEBUG [httpclient-dispatch-1][org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManager] 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.PoolingHttpClientConnectionManager”. Just send the request > > synchronously and await the response … 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.PoolingAsyncClientConnectionManager” and trying to manage the > > response in 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.AsyncResponseConsumer”. > > 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