Re: Server-side mid-air connection close on upload

Michael Osipov Fri, 22 May 2020 16:10:30 -0700

Am 2020-05-22 um 22:18 schrieb Oleg Kalnichevski:

On Fri, 2020-05-22 at 19:25 +0200, Michael Osipov wrote:

Hi folks,


I believe that this is a wellknown limitation in blocking I/O, but
would
like to know how to solve/workaround this issue. The source
discussion
is here [1].

Bascially, I am posting a large file (~7 MB) to Tomcat 8.5.54 where
the
resource needs to be authenticated:

69 [main] DEBUG
org.apache.hc.client5.http.impl.classic.InternalHttpClient - ex-
00000001: preparing request execution
145 [main] DEBUG
org.apache.hc.client5.http.protocol.RequestAddCookies - Cookie spec
selected: strict
150 [main] DEBUG
org.apache.hc.client5.http.protocol.RequestAuthCache - Auth cache
not set in the context
150 [main] DEBUG
org.apache.hc.client5.http.impl.classic.ProtocolExec - ex-00000001:
target auth state: UNCHALLENGED
151 [main] DEBUG
org.apache.hc.client5.http.impl.classic.ProtocolExec - ex-00000001:
proxy auth state: UNCHALLENGED
151 [main] DEBUG
org.apache.hc.client5.http.impl.classic.ConnectExec - ex-00000001:
acquiring connection with route {s}->https://<hostname>:11111
151 [main] DEBUG
org.apache.hc.client5.http.impl.classic.InternalHttpClient - ex-
00000001: acquiring endpoint (3 MINUTES)
152 [main] DEBUG
org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManag
er - ex-00000001: endpoint lease request (3 MINUTES) [route: {s}->
https://<hostname>:11111][total available: 0; route allocated: 0 of
5; total allocated: 0 of 25]
175 [main] DEBUG
org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManag
er - ex-00000001: endpoint leased [route: {s}->
https://<hostname>:11111][total available: 0; route allocated: 1 of
5; total allocated: 1 of 25]
183 [main] DEBUG
org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManag
er - ex-00000001: acquired ep-00000000
183 [main] DEBUG
org.apache.hc.client5.http.impl.classic.InternalHttpClient - ex-
00000001: acquired endpoint ep-00000000
183 [main] DEBUG
org.apache.hc.client5.http.impl.classic.ConnectExec - ex-00000001:
opening connection {s}->https://<hostname>:11111
184 [main] DEBUG
org.apache.hc.client5.http.impl.classic.InternalHttpClient - ep-
00000000: connecting endpoint (3 MINUTES)
184 [main] DEBUG
org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManag
er - ep-00000000: connecting endpoint to https://<hostname>:11111
(3 MINUTES)
201 [main] DEBUG
org.apache.hc.client5.http.impl.io.DefaultHttpClientConnectionOpera
tor - http-outgoing-0: connecting to <hostname>/<ip>:11111
201 [main] DEBUG
org.apache.hc.client5.http.ssl.SSLConnectionSocketFactory -
Connecting socket to <hostname>/<ip>:11111 with timeout 3 MINUTES
237 [main] DEBUG
org.apache.hc.client5.http.ssl.SSLConnectionSocketFactory - Enabled
protocols: [TLSv1.3, TLSv1.2]
237 [main] DEBUG
org.apache.hc.client5.http.ssl.SSLConnectionSocketFactory - Enabled
cipher suites:[TLS_AES_256_GCM_SHA384, TLS_AES_128_GCM_SHA256,
TLS_CHACHA20_POLY1305_SHA256,
TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384,
TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256,
TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305_SHA256,
TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384,
TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305_SHA256,
TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256,
TLS_DHE_RSA_WITH_AES_256_GCM_SHA384,
TLS_DHE_RSA_WITH_CHACHA20_POLY1305_SHA256,
TLS_DHE_DSS_WITH_AES_256_GCM_SHA384,
TLS_DHE_RSA_WITH_AES_128_GCM_SHA256,
TLS_DHE_DSS_WITH_AES_128_GCM_SHA256,
TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA384,
TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384,
TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA256,
TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256,
TLS_DHE_RSA_WITH_AES_256_CBC_SHA256,
TLS_DHE_DSS_WITH_AES_256_CBC_SHA256,
TLS_DHE_RSA_WITH_AES_128_CBC_SHA256,
TLS_DHE_DSS_WITH_AES_128_CBC_SHA256,
TLS_ECDH_ECDSA_WITH_AES_256_GCM_SHA384,
TLS_ECDH_RSA_WITH_AES_256_GCM_SHA384,
TLS_ECDH_ECDSA_WITH_AES_128_GCM_SHA256,
TLS_ECDH_RSA_WITH_AES_128_GCM_SHA256,
TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA384,
TLS_ECDH_RSA_WITH_AES_256_CBC_SHA384,
TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA256,
TLS_ECDH_RSA_WITH_AES_128_CBC_SHA256,
TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA,
TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA,
TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA,
TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA,
TLS_DHE_RSA_WITH_AES_256_CBC_SHA, TLS_DHE_DSS_WITH_AES_256_CBC_SHA,
TLS_DHE_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_DSS_WITH_AES_128_CBC_SHA,
TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA,
TLS_ECDH_RSA_WITH_AES_256_CBC_SHA,
TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA,
TLS_ECDH_RSA_WITH_AES_128_CBC_SHA, TLS_RSA_WITH_AES_256_GCM_SHA384,
TLS_RSA_WITH_AES_128_GCM_SHA256, TLS_RSA_WITH_AES_256_CBC_SHA256,
TLS_RSA_WITH_AES_128_CBC_SHA256, TLS_RSA_WITH_AES_256_CBC_SHA,
TLS_RSA_WITH_AES_128_CBC_SHA, TLS_EMPTY_RENEGOTIATION_INFO_SCSV]
237 [main] DEBUG
org.apache.hc.client5.http.ssl.SSLConnectionSocketFactory -
Starting handshake
431 [main] DEBUG
org.apache.hc.client5.http.ssl.SSLConnectionSocketFactory - Secure
session established
431 [main] DEBUG
org.apache.hc.client5.http.ssl.SSLConnectionSocketFactory
-  negotiated protocol: TLSv1.3
431 [main] DEBUG
org.apache.hc.client5.http.ssl.SSLConnectionSocketFactory
-  negotiated cipher suite: TLS_AES_256_GCM_SHA384
431 [main] DEBUG
org.apache.hc.client5.http.ssl.SSLConnectionSocketFactory -  peer
principal: CN=<hostname>, OU=LDA DW, O=Siemens, C=DE
431 [main] DEBUG
org.apache.hc.client5.http.ssl.SSLConnectionSocketFactory -  peer
alternative names: [<hostname>]
431 [main] DEBUG
org.apache.hc.client5.http.ssl.SSLConnectionSocketFactory -  issuer
principal: CN=Siemens Issuing CA Intranet Server 2017, OU=Siemens
Trust Center, SERIALNUMBER=ZZZZZZB7, O=Siemens, L=Muenchen,
ST=Bayern, C=DE
433 [main] DEBUG
org.apache.hc.client5.http.impl.io.DefaultHttpClientConnectionOpera
tor - http-outgoing-0: connection established 192.168.1.12:54367<-

<ip>:11111

433 [main] DEBUG
org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManag
er - ep-00000000: connected http-outgoing-0
433 [main] DEBUG
org.apache.hc.client5.http.impl.classic.InternalHttpClient - ep-
00000000: endpoint connected
434 [main] DEBUG
org.apache.hc.client5.http.impl.classic.MainClientExec - ex-
00000001: executing POST /content-dev/api/documents HTTP/1.1
434 [main] DEBUG
org.apache.hc.client5.http.impl.io.DefaultManagedHttpClientConnecti
on - http-outgoing-0: set socket timeout to 100 MILLISECONDS
434 [main] DEBUG
org.apache.hc.client5.http.impl.classic.InternalHttpClient - ep-
00000000: start execution ex-00000001
434 [main] DEBUG
org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManag
er - ep-00000000: executing exchange ex-00000001 over http-
outgoing-0
435 [main] DEBUG org.apache.hc.client5.http.headers - http-
outgoing-0 >> POST /content-dev/api/documents HTTP/1.1
435 [main] DEBUG org.apache.hc.client5.http.headers - http-
outgoing-0 >> Accept-Encoding: gzip, x-gzip, deflate
435 [main] DEBUG org.apache.hc.client5.http.headers - http-
outgoing-0 >> Content-Length: 7664149
435 [main] DEBUG org.apache.hc.client5.http.headers - http-
outgoing-0 >> Content-Type: application/zip
435 [main] DEBUG org.apache.hc.client5.http.headers - http-
outgoing-0 >> Host: <hostname>:11111
435 [main] DEBUG org.apache.hc.client5.http.headers - http-
outgoing-0 >> Connection: keep-alive
435 [main] DEBUG org.apache.hc.client5.http.headers - http-
outgoing-0 >> User-Agent: Apache-HttpClient/5.0 (Java/13.0.2)
578 [main] DEBUG org.apache.hc.client5.http.wire - http-outgoing-0

"POST /content-dev/api/documents HTTP/1.1[\r][\n]"

578 [main] DEBUG org.apache.hc.client5.http.wire - http-outgoing-0

"Accept-Encoding: gzip, x-gzip, deflate[\r][\n]"

578 [main] DEBUG org.apache.hc.client5.http.wire - http-outgoing-0

"Content-Length: 7664149[\r][\n]"

578 [main] DEBUG org.apache.hc.client5.http.wire - http-outgoing-0

"Content-Type: application/zip[\r][\n]"

578 [main] DEBUG org.apache.hc.client5.http.wire - http-outgoing-0

"Host: <hostname>:11111[\r][\n]"

579 [main] DEBUG org.apache.hc.client5.http.wire - http-outgoing-0

"Connection: keep-alive[\r][\n]"

579 [main] DEBUG org.apache.hc.client5.http.wire - http-outgoing-0

"User-Agent: Apache-HttpClient/5.0 (Java/13.0.2)[\r][\n]"

579 [main] DEBUG org.apache.hc.client5.http.wire - http-outgoing-0

"[\r][\n]"

580 [main] DEBUG org.apache.hc.client5.http.wire - http-outgoing-0

"PK[0x3][0x4][0x14][0x0][0x0][0x0][0x0][0x0][0xffffffd3]~[0xffffffb
3]P...
...
5861 [main] DEBUG org.apache.hc.client5.http.wire - http-outgoing-0

"[\r][0xffffffe0]t[0xffffffa1][0x1f][0xffffffb0][0xfffffffa][0xffff
ffa1]...
5861 [main] DEBUG org.apache.hc.client5.http.wire - http-outgoing-0

"[write] I/O error: Connection or outbound has closed"

5862 [main] DEBUG
org.apache.hc.client5.http.impl.classic.InternalHttpClient - ep-
00000000: endpoint closed
5862 [main] DEBUG
org.apache.hc.client5.http.impl.classic.InternalHttpClient - ep-
00000000: discarding endpoint
5862 [main] DEBUG
org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManag
er - ep-00000000: releasing endpoint
5862 [main] DEBUG
org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManag
er - ep-00000000: connection released [route: {s}->
https://<hostname>:11111][total available: 0; route allocated: 0 of
5; total allocated: 0 of 25]
5862 [main] DEBUG
org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManag
er - Shutdown connection pool GRACEFUL
5862 [main] DEBUG
org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManag
er - Connection pool shut down
Exception in thread "main" javax.net.ssl.SSLException: Eine
bestehende Verbindung wurde softwaregesteuert
durch den Hostcomputer abgebrochen
     at
java.base/sun.security.ssl.Alert.createSSLException(Alert.java:127)
     at
java.base/sun.security.ssl.TransportContext.fatal(TransportContext.
java:324)
     at
java.base/sun.security.ssl.TransportContext.fatal(TransportContext.
java:267)
     at
java.base/sun.security.ssl.TransportContext.fatal(TransportContext.
java:262)
     at
java.base/sun.security.ssl.SSLSocketImpl$AppOutputStream.write(SSLS
ocketImpl.java:1258)
     at
org.apache.hc.client5.http.impl.io.LoggingOutputStream.write(Loggin
gOutputStream.java:72)
     at
org.apache.hc.core5.http.impl.io.SessionOutputBufferImpl.flushBuffe
r(SessionOutputBufferImpl.java:117)
     at
org.apache.hc.core5.http.impl.io.SessionOutputBufferImpl.write(Sess
ionOutputBufferImpl.java:150)
     at
org.apache.hc.core5.http.impl.io.ContentLengthOutputStream.write(Co
ntentLengthOutputStream.java:113)
     at
org.apache.hc.core5.http.io.entity.AbstractHttpEntity.writeTo(Abstr
actHttpEntity.java:85)
     at
org.apache.hc.core5.http.io.entity.AbstractHttpEntity.writeTo(Abstr
actHttpEntity.java:93)
     at
org.apache.hc.core5.http.impl.io.DefaultBHttpClientConnection.sendR
equestEntity(DefaultBHttpClientConnection.java:153)
     at
org.apache.hc.core5.http.impl.io.HttpRequestExecutor.execute(HttpRe
questExecutor.java:148)
     at
org.apache.hc.core5.http.impl.io.HttpRequestExecutor.execute(HttpRe
questExecutor.java:225)
     at
org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManag
er$InternalConnectionEndpoint.execute(PoolingHttpClientConnectionMa
nager.java:596)
     at
org.apache.hc.client5.http.impl.classic.InternalExecRuntime.execute
(InternalExecRuntime.java:220)
     at
org.apache.hc.client5.http.impl.classic.MainClientExec.execute(Main
ClientExec.java:107)
     at
org.apache.hc.client5.http.impl.classic.ExecChainElement.execute(Ex
ecChainElement.java:51)
     at
org.apache.hc.client5.http.impl.classic.ExecChainElement$1.proceed(
ExecChainElement.java:57)
     at
org.apache.hc.client5.http.impl.classic.ConnectExec.execute(Connect
Exec.java:181)
     at
org.apache.hc.client5.http.impl.classic.ExecChainElement.execute(Ex
ecChainElement.java:51)
     at
org.apache.hc.client5.http.impl.classic.ExecChainElement$1.proceed(
ExecChainElement.java:57)
     at
org.apache.hc.client5.http.impl.classic.ProtocolExec.execute(Protoc
olExec.java:165)
     at
org.apache.hc.client5.http.impl.classic.ExecChainElement.execute(Ex
ecChainElement.java:51)
     at
org.apache.hc.client5.http.impl.classic.ExecChainElement$1.proceed(
ExecChainElement.java:57)
     at
org.apache.hc.client5.http.impl.classic.HttpRequestRetryExec.execut
e(HttpRequestRetryExec.java:93)
     at
org.apache.hc.client5.http.impl.classic.ExecChainElement.execute(Ex
ecChainElement.java:51)
     at
org.apache.hc.client5.http.impl.classic.ExecChainElement$1.proceed(
ExecChainElement.java:57)
     at
org.apache.hc.client5.http.impl.classic.RedirectExec.execute(Redire
ctExec.java:116)
     at
org.apache.hc.client5.http.impl.classic.ExecChainElement.execute(Ex
ecChainElement.java:51)
     at
org.apache.hc.client5.http.impl.classic.ExecChainElement$1.proceed(
ExecChainElement.java:57)
     at
org.apache.hc.client5.http.impl.classic.ContentCompressionExec.exec
ute(ContentCompressionExec.java:128)
     at
org.apache.hc.client5.http.impl.classic.ExecChainElement.execute(Ex
ecChainElement.java:51)
     at
org.apache.hc.client5.http.impl.classic.InternalHttpClient.doExecut
e(InternalHttpClient.java:178)
     at
org.apache.hc.client5.http.impl.classic.CloseableHttpClient.execute
(CloseableHttpClient.java:75)
     at
org.apache.hc.client5.http.impl.classic.CloseableHttpClient.execute
(CloseableHttpClient.java:89)
     at sspijava.SspiAuth.main(SspiAuth.java:59)
     Suppressed: java.net.SocketException: Eine bestehende
Verbindung wurde softwaregesteuert
durch den Hostcomputer abgebrochen
         at
java.base/sun.nio.ch.NioSocketImpl.implWrite(NioSocketImpl.java:421
)
         at
java.base/sun.nio.ch.NioSocketImpl.write(NioSocketImpl.java:441)
         at
java.base/sun.nio.ch.NioSocketImpl$2.write(NioSocketImpl.java:825)
         at
java.base/java.net.Socket$SocketOutputStream.write(Socket.java:1007
)
         at
java.base/sun.security.ssl.SSLSocketOutputRecord.encodeAlert(SSLSoc
ketOutputRecord.java:82)
         at
java.base/sun.security.ssl.TransportContext.fatal(TransportContext.
java:355)
         ... 35 more
     Suppressed: java.net.SocketException: Connection or outbound
has closed
         at
java.base/sun.security.ssl.SSLSocketImpl$AppOutputStream.write(SSLS
ocketImpl.java:1246)
         at
org.apache.hc.client5.http.impl.io.LoggingOutputStream.write(Loggin
gOutputStream.java:72)
         at
org.apache.hc.core5.http.impl.io.SessionOutputBufferImpl.flushBuffe
r(SessionOutputBufferImpl.java:117)
         at
org.apache.hc.core5.http.impl.io.SessionOutputBufferImpl.flush(Sess
ionOutputBufferImpl.java:126)
         at
org.apache.hc.core5.http.impl.io.ContentLengthOutputStream.close(Co
ntentLengthOutputStream.java:93)
         at
org.apache.hc.core5.http.impl.io.DefaultBHttpClientConnection.sendR
equestEntity(DefaultBHttpClientConnection.java:154)
         ... 25 more
Caused by: java.net.SocketException: Eine bestehende Verbindung
wurde softwaregesteuert
durch den Hostcomputer abgebrochen
     at
java.base/sun.nio.ch.NioSocketImpl.implWrite(NioSocketImpl.java:421
)
     at
java.base/sun.nio.ch.NioSocketImpl.write(NioSocketImpl.java:441)
     at
java.base/sun.nio.ch.NioSocketImpl$2.write(NioSocketImpl.java:825)
     at
java.base/java.net.Socket$SocketOutputStream.write(Socket.java:1007
)
     at
java.base/sun.security.ssl.SSLSocketOutputRecord.deliver(SSLSocketO
utputRecord.java:342)
     at
java.base/sun.security.ssl.SSLSocketImpl$AppOutputStream.write(SSLS
ocketImpl.java:1253)
     ... 32 more


So what happens here, HttpClient uploads the file while Tomcat
pretty
quick notices that the requests needs to be authenticated, responds
401
and closes the connection.
Is my understanding correct? What do I have to do to solve this?
curl seems to handle this properly, aborts the request and retries
with
proper credentials.

The key difference I see in Tomcats logs is that headers are seen
first
first, authnz checks, then curl sends the body while HttpClient
sends
headers and the first block of the payload. I can provide the trace
output from Tomcat.

Regards,

Michael

PS: Yes, I know I can use Expect, but I am trying to reproduce this
for
a failure with mod_proxy_http and py-requests.


Hi Micheal

I think your analysis is quite accurate. HttpClient indeed tries to
pack the request body into the same IP frame as the header for
performance reasons. It also does not stop and check for any out of
sequence response from the server due to high cost of such operation.
The only way to properly solve the problem is to enable `expect-
continue` handshake or use an async version of HttpClient.

Thanks for the confirmation. I can see this now in Wireshark too. I wasalso able to answer it with your answer here [1] as well as here [2].RFC 7230, section 6.5 says:


>    A client sending a message body SHOULD monitor the network connection
>    for an error response while it is transmitting the request.  If the
>    client sees a response that indicates the server does not wish to
>    receive the message body and is closing the connection, the client
>    SHOULD immediately cease transmitting the body and close its side of
>    the connection.

This is exactly what we don't have.

Theoretically we could enhance the classic client-side protocol handler
to check if the length of the request entity is known and is greater,
say, than 1MB, send the request head first, stop and wait for an early
response, but this could potentially kill performance of entity
enclosing requests processed in proper request-response sequence. This
approach has been considered on several occasions but always decided
against.

So basically, if I understand your idea correctly, we could have eitherat client or request level a #setEarlyResponseThreshold(long, Timeout)(in bytes, how long to wait for an early response) which checks for"Content-Length" and sends headers first, tries to read, no response,continues sending else process early response -- all in the same thread?!


Michael

[1] https://stackoverflow.com/a/9176445/696632
[2] https://stackoverflow.com/a/14483857/696632

---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscr...@hc.apache.org
For additional commands, e-mail: httpclient-users-h...@hc.apache.org

Re: Server-side mid-air connection close on upload

Reply via email to