Hello. I've found out a way to reproduce such behavior. All of these conditions must be met: 1) Server must be accessed via nginx version 1.16.1 (I think versions 1.18.0 and older are appropriate, but I tested only 1.16.1); 2) A request contains a body; 3) A response contains neither "Content-Length" nor "Transfer-Encoding" header; 4) TLS is used. 5) HTTP/1.1 is used. But, I still don't know why the connection unexpectedly closes.
Kind regards, Vita Komarova [email protected] https://github.com/layfe >August 18, 2021, 22:05 +03:00 от LAYFE <[email protected]>: > > >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 > >
