Am 2020-05-20 um 15:07 schrieb Mark Thomas:
On 20/05/2020 11:05, Osipov, Michael wrote:
<snip/>
My questions are:
* Why is parseRequestLine printing the request body?
Because it is the contents of the input buffer that is being logged, not
just the headers.
* Can someone confirm the erratic behavior of HTTPd's module?
I'm not sure it is erratic. httpd is writing a request and Tomcat closes
the connection before httpd has finished. Most HTTP user agents don't
try reading the response until they have finished writing the request.
That is what appears to be happening here.
It seems that it is not ideal, far from it. When I look at the case with
curl and Tomcat directly, curl handles the "premature" close perfectly
as you can see with:
NEGOTIATE send, close instead of sending 7598613 bytes
maxSwallowSize was created to address this.
* Is there anything we need to improve on the Tomcat side?
I don't see anything Tomcat can do differently here.
Tomcat has to close the connection if it isn't going to read/swallow the
rest of the request body. There is no other choice.
I didn't even doubt that there is something wrong with Tomcat. I thougt
there might be some more gracefully way. E.g., detect that client is
still sending. Just a wild guess.
You could set maxSwallowSize to -1 and rely on httpd to enforce upload
limits. Looking at the httpd docs that might be easier said than done
when mod_proxy is used.
It is beginning to look like you need to pick a maxSwallowSize that is
high enough for your users but low enough to prevent DoS.
Obviously :-(
I guess mod_proxy could try to read the response sooner but it doesn't
know it needs to that until the connection is dropped by which time it
is too late. And how to ensure mod_proxy has read the response before
dropping the connection? I can of ways around this but they are all more
complex and that may impact.
There must be a way, does't it? If can do too?
Is there an option to proxy via HTTP/2? That should be able to handle
these sorts of situations more gracefully.
This seems to be broken for some reason in another way:
I have enabled the UpgradeProtocol on both connectors, localhost and
remote IP. Remote IP is:
$ curl -X POST --anyauth -u : --upload-file inputs.zip -H "Content-Type: application/zip"
https://<hostname>:11111/content-dev/api/documents --verbose -H "Expect:"
* Uses proxy env variable NO_PROXY == 'localhost .siemens.net .siemens.com
.siemens.de'
* Trying <ip>:11111...
* Connected to <hostname> (<ip>) port 11111 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* successfully set certificate verify locations:
* CAfile: none
CApath: /etc/ssl/certs/
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
* TLSv1.3 (IN), TLS handshake, Server hello (2):
* TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
* TLSv1.3 (IN), TLS handshake, Certificate (11):
* TLSv1.3 (IN), TLS handshake, CERT verify (15):
* TLSv1.3 (IN), TLS handshake, Finished (20):
* TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
* TLSv1.3 (OUT), TLS handshake, Finished (20):
* SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384
* ALPN, server accepted to use h2
* Server certificate:
* subject: C=DE; O=Siemens; OU=LDA DW; CN=<hostname>
* start date: Mar 12 09:50:16 2020 GMT
* expire date: Mar 19 13:10:13 2021 GMT
* subjectAltName: host "<hostname>" matched cert's "<hostname>"
* issuer: C=DE; ST=Bayern; L=Muenchen; O=Siemens; serialNumber=ZZZZZZB7;
OU=Siemens Trust Center; CN=Siemens Issuing CA Intranet Server 2017
* SSL certificate verify ok.
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
* Using Stream ID: 1 (easy handle 0x800d91800)
POST /content-dev/api/documents HTTP/2
Host: <hostname>:11111
user-agent: curl/7.70.0
accept: */*
content-type: application/zip
content-length: 7664149
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* old SSL session ID is stale, removing
* Connection state changed (MAX_CONCURRENT_STREAMS == 100)!
< HTTP/2 401
< www-authenticate: Negotiate
< content-type: text/html;charset=utf-8
< content-language: en
< content-length: 437
< date: Wed, 20 May 2020 16:31:37 GMT
* NEGOTIATE send, close instead of sending 7598614 bytes
* HTTP error before end of send, stop sending
<
* Ignoring the response-body
* Connection #0 to host <hostname> left intact
* Issue another request to this URL:
'https://<hostname>:11111/content-dev/api/documents'
* Uses proxy env variable NO_PROXY == 'localhost .siemens.net .siemens.com
.siemens.de'
* Found bundle for host <hostname>: 0x800cba3c0 [can multiplex]
* Re-using existing connection! (#0) with host <hostname>
* Connected to <hostname> (<ip>) port 11111 (#0)
* Server auth using Negotiate with user ''
* Using Stream ID: 3 (easy handle 0x800d91800)
POST /content-dev/api/documents HTTP/2
Host: <hostname>:11111
authorization: Negotiate YIIRjQYGK...
user-agent: curl/7.70.0
accept: */*
content-type: application/zip
content-length: 7664149
< HTTP/2 500
< www-authenticate: Negotiate oYG3MIG0o...
< vary: Origin
< access-control-allow-credentials: true
< access-control-expose-headers:
Correlation-Id,Content-Disposition,Content-Length,Location
< content-type: text/html;charset=utf-8
< content-language: en
< content-length: 455
< date: Wed, 20 May 2020 16:31:58 GMT
* HTTP error before end of send, stop sending
<
* HTTP/2 stream 0 was not closed cleanly: Unknown error code (err 11)
* stopped the pause stream!
* Connection #0 to host <hostname> left intact
curl: (92) HTTP/2 stream 0 was not closed cleanly: Unknown error code (err 11)
On the server-side:
2020-05-20T18:29:43.934 [https-openssl-apr-11111-exec-5] INFO
c.s.d.l.w.c.DocumentsController: Saving request body from user
'osipo...@ad001.siemens.net' to
'/usr/local/ldadocgen/content-dev/tomcat-1/temp/lda-docgen.5171589506941585923.zip'
2020-05-20T18:30:03.962 [https-openssl-apr-11111-exec-5] ERROR
c.s.d.l.w.c.DocumentsController: Saving request body failed
org.apache.catalina.connector.ClientAbortException:
org.apache.coyote.CloseNowException: Timeout waiting to read data from client
at
org.apache.catalina.connector.InputBuffer.realReadBytes(InputBuffer.java:348)
at
org.apache.catalina.connector.InputBuffer.checkByteBufferEof(InputBuffer.java:663)
at org.apache.catalina.connector.InputBuffer.read(InputBuffer.java:370)
at
org.apache.catalina.connector.CoyoteInputStream.read(CoyoteInputStream.java:152)
at java.nio.file.Files.copy(Files.java:2908)
at java.nio.file.Files.copy(Files.java:3027)
With '--http1.1' curl works as expected.
Let's try via mod_proxy_http2:
curl says
<!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML 2.0//EN">
<html><head>
<title>503 Service Unavailable</title>
</head><body>
<h1>Service Unavailable</h1>
<p>The server is temporarily unable to service your
request due to maintenance downtime or capacity
problems. Please try again later.</p>
<hr>
<address>Apache/2.4.43 (FreeBSD) OpenSSL/1.1.1d-freebsd mod_auth_gssapi/1.6.1 Server
at sitex-ldadw.ad001.siemens.net Port 443</address>
</body></html>
* we are done reading and this is set to close, stop send
* Closing connection 2
while catalina.out says
2020-05-20T18:51:03 FEIN [http-apr-127.0.1.2-8083-exec-10]
org.apache.coyote.http2.Http2Parser.validateFrame Connection [4], Stream [1],
Frame type [DATA], Flags [0], Payload size [1]
2020-05-20T18:51:03 FEIN [http-apr-127.0.1.2-8083-exec-10]
org.apache.coyote.http2.Http2Parser.readDataFrame Connection [4], Stream [1],
Data length, [1], Padding length [none]
2020-05-20T18:51:03 FEIN [http-apr-127.0.1.2-8083-exec-10]
org.apache.tomcat.util.net.SocketWrapperBase.populateReadBuffer Socket:
[org.apache.tomcat.util.net.AprEndpoint$AprSocketWrapper@b1aa062:45046403232],
Read from buffer: [1]
2020-05-20T18:51:03 FEIN [http-apr-127.0.1.2-8083-exec-10]
org.apache.coyote.http2.Stream$StreamInputBuffer.onDataAvailable Data added to
inBuffer when read thread is waiting. Signalling that thread to continue
2020-05-20T18:51:03 FEIN [http-apr-127.0.1.2-8083-exec-10]
org.apache.coyote.http2.Http2UpgradeHandler.upgradeDispatch Connection error
org.apache.coyote.http2.ConnectionException: Connection [4], Too much
overhead so the connection will be closed
at
org.apache.coyote.http2.Http2UpgradeHandler.upgradeDispatch(Http2UpgradeHandler.java:342)
at
org.apache.coyote.http11.upgrade.UpgradeProcessorInternal.dispatch(UpgradeProcessorInternal.java:54)
at
org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:59)
at
org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:818)
at
org.apache.tomcat.util.net.AprEndpoint$SocketProcessor.doRun(AprEndpoint.java:2071)
at
org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at
org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:748)
2020-05-20T18:51:03 FEIN [http-apr-127.0.1.2-8083-exec-10]
org.apache.coyote.http2.Stream.receiveReset stream.reset.debug
2020-05-20T18:51:03 FEIN [http-apr-127.0.1.2-8083-exec-10]
org.apache.coyote.http2.StreamStateMachine.stateChange Connection [4], Stream
[1], State changed from [OPEN] to [CLOSED_RST_RX]
2020-05-20T18:51:03 FEIN [http-apr-127.0.1.2-8083-exec-10]
org.apache.coyote.http2.WindowAllocationManager.notify Connection [4], Stream
[1], Waiting type [0], Notify type [3]
2020-05-20T18:51:03 FEIN [http-apr-127.0.1.2-8083-exec-10]
org.apache.coyote.http2.Http2UpgradeHandler.upgradeDispatch Exit, Connection
[4], SocketState [CLOSED]
2020-05-20T18:51:03 FEIN [http-apr-127.0.1.2-8083-exec-10]
org.apache.coyote.AbstractProcessorLight.process Socket:
[org.apache.tomcat.util.net.AprEndpoint$AprSocketWrapper@b1aa062:45046403232],
Status in: [OPEN_READ], State out: [CLOSED]
What now?
Michael
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org
