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
