Am 2020-05-22 um 13:26 schrieb Mark Thomas:
On 21/05/2020 23:30, Osipov, Michael wrote:
<snip/>
Output will be sent privately.
Got it. Tx.
Looking at the direct case.
It looks like you have debug logging enabled for everything. You only
need it for the org.apache.coyote.http2 package.
grep "http2" catalina.2020-05-21.log | less
gives a nice clear view of what is happening which is roughly:
22:34:29 Client sends request headers and ~64k of body on stream 1
22:34:29 Server sends 401 response and resets stream 1
22:34:29 Client resends request with authorization header but NO body
22:34:31 Server tries to read request body
22:34:51 Server times out trying to read request body
22:34:51 Server sends 500 response due to timeout and resets stream 3
It looks like the response to stream 3 includes an authorization challenge.
I think something isn't quite right with the authentication process.
Which authenticator are you using?
I am using my SPNEGO authenticator which is publically available [1] and
based on the code which I have donated many years ago.
Would expect to see a second challenge form the server or should the
client be authenticated once the first auth header has been processed?
No, from a server's perspective the authentication has been completed
already, but the client failed to provide the body.
What is triggering the read of the body here?
>
Why isn't the client sending the body?
That's a good question. I need to ask fellow curl committers, this maybe
a bug in curl.
I am looking at this with another client now, HttpClient 5.0. Even w/o
authentication. the situation is even worse:
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 it seems that some clients cannot even see the response while the
mid-air close happens. This really looks bad. As far as I can see, I
need to set maxSwallowSize here again.
The proxy logs don't show nay http2 traffic at all.
That is obviously an error on my side. I will try to recreate them and
send again.
Michael
[1]
http://tomcatspnegoad.sourceforge.net/xref/net/sf/michaelo/tomcat/authenticator/SpnegoAuthenticator.html#SpnegoAuthenticator
