You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@hc.apache.org by LAYFE <la...@mail.ru.INVALID> on 2021/08/18 19:05:18 UTC
AsyncHttpClient5: connection is unexpectedly closed with FORCE_HTTP_1 and TLS
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
layfe@mail.ru
https://github.com/layfe
Re: AsyncHttpClient5: connection is unexpectedly closed with FORCE_HTTP_1 and TLS
Posted by LAYFE <la...@mail.ru.INVALID>.
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
layfe@mail.ru
https://github.com/layfe
>August 18, 2021, 22:05 +03:00 от LAYFE <la...@mail.ru.invalid>:
>
>
>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
>layfe@mail.ru
>https://github.com/layfe
>
>