Hello. We use AsyncHttpClient from Apache HttpClient5 (version 5.1). We faced an error when connection is unexpectedly closed using TLS and forced HTTP/1.1. We use client to send HTTP messages to our customers. Every customer has its own environment which we can't control. We have to use TLS. Also, it's required to force HTTP/1.1 (HttpVersionPolicy.FORCE_HTTP_1) because some of our customers have troubles with protocol upgrade. We noticed that for some customers response a processing ends up with unexpectedly closed connection. We've tried httpclient4 (classic) and AsyncHttpClient (Netty based). Both of them work correctly. In the log below the customer responds with 200 OK and an empty body. We can see response headers but connection is prematurely closed. [2021-08-16T20:22:50.950+03:00] … [headers] c-0000000000 << HTTP/1.1 200 OK [2021-08-16T20:22:50.950+03:00] … [headers] c-0000000000 << Server: nginx [2021-08-16T20:22:50.950+03:00] … [headers] c-0000000000 << Date: Mon, 16 Aug 2021 17:22:50 GMT [2021-08-16T20:22:50.951+03:00] … [headers] c-0000000000 << Content-Type: text/html; charset=UTF-8 [2021-08-16T20:22:50.951+03:00] … [headers] c-0000000000 << Connection: close [2021-08-16T20:22:50.951+03:00] … [headers] c-0000000000 << Set-Cookie: <masked cookie>; expires=Sat, 21-Aug-2021 17:22:50 GMT; Max-Age=432000; path=/ [2021-08-16T20:22:50.951+03:00] … [headers] c-0000000000 << Expires: Thu, 19 Nov 1981 08:52:00 GMT [2021-08-16T20:22:50.951+03:00] … [headers] c-0000000000 << Cache-Control: no-store, no-cache, must-revalidate [2021-08-16T20:22:50.951+03:00] … [headers] c-0000000000 << Pragma: no-cache [2021-08-16T20:22:50.954+03:00] … [HttpAsyncMainClientExec] ex-0000000001 consume response HTTP/1.1 200 OK, entity len -9223372036854775807 [2021-08-16T20:22:50.967+03:00] … [HttpAsyncMainClientExec] ex-0000000001 execution failed: Connection is closed [2021-08-16T20:22:50.968+03:00] … [InternalAbstractHttpAsyncClient] ex-0000000001 request failed: Connection is closed [2021-08-16T20:22:50.968+03:00] … [PoolingAsyncClientConnectionManager] ep-0000000000 close IMMEDIATE [2021-08-16T20:22:50.968+03:00] … [DefaultManagedAsyncClientConnection] c-0000000000 Shutdown connection IMMEDIATE
After switching to negotiating version policy (default) everything works correctly. There was a protocol upgrade in the logs below. [2021-08-18T15:19:42.032+03:00] … [headers] c-0000000000 << :status: 200 [2021-08-18T15:19:42.032+03:00] … [headers] c-0000000000 << server: nginx [2021-08-18T15:19:42.032+03:00] … [headers] c-0000000000 << date: Wed, 18 Aug 2021 12:19:42 GMT [2021-08-18T15:19:42.032+03:00] … [headers] c-0000000000 << content-type: text/html; charset=UTF-8 [2021-08-18T15:19:42.032+03:00] … [headers] c-0000000000 << set-cookie: <masked cookie>; expires=Mon, 23-Aug-2021 12:19:42 GMT; Max-Age=432000; path=/ [2021-08-18T15:19:42.033+03:00] … [headers] c-0000000000 << expires: Thu, 19 Nov 1981 08:52:00 GMT [2021-08-18T15:19:42.033+03:00] … [headers] c-0000000000 << cache-control: no-store, no-cache, must-revalidate [2021-08-18T15:19:42.033+03:00] … [headers] c-0000000000 << pragma: no-cache [2021-08-18T15:19:42.040+03:00] … [HttpAsyncMainClientExec] ex-0000000001 consume response HTTP/2.0 200 OK, entity len -1 [2021-08-18T15:19:42.046+03:00] … [HttpAsyncMainClientExec] ex-0000000001 end of response data [2021-08-18T15:19:42.107+03:00] … [InternalAbstractHttpAsyncClient] ex-0000000001 message exchange successfully completed There is also a stacktrace that describes the way the connection is closed: onTLSSessionEnd:182, InternalDataChannel (org.apache.hc.core5.reactor) execute:225, InternalDataChannel$2 (org.apache.hc.core5.reactor) execute:221, InternalDataChannel$2 (org.apache.hc.core5.reactor) updateEventMask:422, SSLIOSession (org.apache.hc.core5.reactor.ssl) access$500:72, SSLIOSession (org.apache.hc.core5.reactor.ssl) outputReady:184, SSLIOSession$1 (org.apache.hc.core5.reactor.ssl) onIOEvent:141, InternalDataChannel (org.apache.hc.core5.reactor) handleIOEvent:51, InternalChannel (org.apache.hc.core5.reactor) processEvents:178, SingleCoreIOReactor (org.apache.hc.core5.reactor) doExecute:127, SingleCoreIOReactor (org.apache.hc.core5.reactor) execute:85, AbstractSingleCoreIOReactor (org.apache.hc.core5.reactor) run:44, IOReactorWorker (org.apache.hc.core5.reactor) run:829, Thread (java.lang) The interesting thing is the field "endOfStream" in method SSLIOSession.updateEventMask() has a value "true". But I can't figure out why. That happens with the almost default configuration of the HTTP client (only versionPolicy and tlsStrategy are configured). For some customers this behaviour is permament but I haven't been able to reproduce it using local echo server. I don't have any idea why some connections are prematurely closed. It probably might be a bug. Has anyone ever seen such behavior? Maybe you have an idea how to debug it, or fix? Kind regards, Vita Komarova [email protected] https://github.com/layfe
