Server-side mid-air connection close on upload

Fri, 22 May 2020 10:26:30 -0700 

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.PoolingHttpClientConnectionManager - 
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.PoolingHttpClientConnectionManager - 
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.PoolingHttpClientConnectionManager - 
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.PoolingHttpClientConnectionManager - ep-00000000: 
connecting endpoint to https://<hostname>:11111 (3 MINUTES)
201 [main] DEBUG org.apache.hc.client5.http.impl.io.DefaultHttpClientConnectionOperator - 
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.DefaultHttpClientConnectionOperator - 
http-outgoing-0: connection established 192.168.1.12:54367<-><ip>:11111
433 [main] DEBUG 
org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager - 
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.DefaultManagedHttpClientConnection - 
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.PoolingHttpClientConnectionManager - 
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]~[0xffffffb3]P...
...
5861 [main] DEBUG org.apache.hc.client5.http.wire - http-outgoing-0 >> 
"[\r][0xffffffe0]t[0xffffffa1][0x1f][0xffffffb0][0xfffffffa][0xffffffa1]...
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.PoolingHttpClientConnectionManager - 
ep-00000000: releasing endpoint
5862 [main] DEBUG org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager 
- 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.PoolingHttpClientConnectionManager - 
Shutdown connection pool GRACEFUL
5862 [main] DEBUG 
org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager - 
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(SSLSocketImpl.java:1258)
    at 
org.apache.hc.client5.http.impl.io.LoggingOutputStream.write(LoggingOutputStream.java:72)
    at 
org.apache.hc.core5.http.impl.io.SessionOutputBufferImpl.flushBuffer(SessionOutputBufferImpl.java:117)
    at 
org.apache.hc.core5.http.impl.io.SessionOutputBufferImpl.write(SessionOutputBufferImpl.java:150)
    at 
org.apache.hc.core5.http.impl.io.ContentLengthOutputStream.write(ContentLengthOutputStream.java:113)
    at 
org.apache.hc.core5.http.io.entity.AbstractHttpEntity.writeTo(AbstractHttpEntity.java:85)
    at 
org.apache.hc.core5.http.io.entity.AbstractHttpEntity.writeTo(AbstractHttpEntity.java:93)
    at 
org.apache.hc.core5.http.impl.io.DefaultBHttpClientConnection.sendRequestEntity(DefaultBHttpClientConnection.java:153)
    at 
org.apache.hc.core5.http.impl.io.HttpRequestExecutor.execute(HttpRequestExecutor.java:148)
    at 
org.apache.hc.core5.http.impl.io.HttpRequestExecutor.execute(HttpRequestExecutor.java:225)
    at 
org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager$InternalConnectionEndpoint.execute(PoolingHttpClientConnectionManager.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(MainClientExec.java:107)
    at 
org.apache.hc.client5.http.impl.classic.ExecChainElement.execute(ExecChainElement.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(ConnectExec.java:181)
    at 
org.apache.hc.client5.http.impl.classic.ExecChainElement.execute(ExecChainElement.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(ProtocolExec.java:165)
    at 
org.apache.hc.client5.http.impl.classic.ExecChainElement.execute(ExecChainElement.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.execute(HttpRequestRetryExec.java:93)
    at 
org.apache.hc.client5.http.impl.classic.ExecChainElement.execute(ExecChainElement.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(RedirectExec.java:116)
    at 
org.apache.hc.client5.http.impl.classic.ExecChainElement.execute(ExecChainElement.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.execute(ContentCompressionExec.java:128)
    at 
org.apache.hc.client5.http.impl.classic.ExecChainElement.execute(ExecChainElement.java:51)
    at 
org.apache.hc.client5.http.impl.classic.InternalHttpClient.doExecute(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(SSLSocketOutputRecord.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(SSLSocketImpl.java:1246)
        at 
org.apache.hc.client5.http.impl.io.LoggingOutputStream.write(LoggingOutputStream.java:72)
        at 
org.apache.hc.core5.http.impl.io.SessionOutputBufferImpl.flushBuffer(SessionOutputBufferImpl.java:117)
        at 
org.apache.hc.core5.http.impl.io.SessionOutputBufferImpl.flush(SessionOutputBufferImpl.java:126)
        at 
org.apache.hc.core5.http.impl.io.ContentLengthOutputStream.close(ContentLengthOutputStream.java:93)
        at 
org.apache.hc.core5.http.impl.io.DefaultBHttpClientConnection.sendRequestEntity(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(SSLSocketOutputRecord.java:342)
    at 
java.base/sun.security.ssl.SSLSocketImpl$AppOutputStream.write(SSLSocketImpl.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.



[1] https://www.mail-archive.com/users@tomcat.apache.org/msg135207.html






















					Reply via email to