You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@tomcat.apache.org by "Osipov, Michael" <mi...@siemens.com> on 2020/05/20 10:05:20 UTC
maxSwallowSize and misbehaving clients (e.g., mod_proxy_http)
Hi folks,
I am experiencing an issue which I believe is an already reported bug in
HTTPd, but I am not 100% sure. I first observed this with py-requests
which does not support the Expect header, but was also able to reproduce
with curl too.
My setup is running several Tomcat instances behind HTTPd via
mod_proxy_http:
> VersionLoggerListener.log Server version name: Apache Tomcat/8.5.53
> VersionLoggerListener.log Server built: Mar 11 2020 10:01:39 UTC
> VersionLoggerListener.log Server version number: 8.5.53.0
> VersionLoggerListener.log OS Name: FreeBSD
> VersionLoggerListener.log OS Version: 12.1-STABLE
> VersionLoggerListener.log Architecture: amd64
> VersionLoggerListener.log Java Home: /usr/local/openjdk8/jre
> VersionLoggerListener.log JVM Version: 1.8.0_242-b07
> VersionLoggerListener.log JVM Vendor: Oracle Corporation
and
> Apache HTTPd 2.4.43
(Log output will be replaced with ellipsis for brevity)
Find catalina.out and httpd.log at
http://home.apache.org/~michaelo/issues/502-broken-pipe/
Now consider the following requests, 443 via HTTP forward proxy, 11111
directly to Tomcat:
> $ curl -X POST --anyauth -u : --upload-file inputs.zip -H "Content-Type: application/zip" https://<hostname>/content-dev/api/documents --verbose -H "Expect:"
> * Uses proxy env variable NO_PROXY == 'localhost .siemens.net .siemens.com .siemens.de'
> * Trying <ip>:443...
> * Connected to <hostname> (<ip>) port 443 (#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 http/1.1
> * 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.
>> POST /content-dev/api/documents HTTP/1.1
>> Host: <hostname>
>> 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
> * We are completely uploaded and fine
> * Mark bundle as not supporting multiuse
> < HTTP/1.1 502 Bad Gateway
> < Date: Wed, 20 May 2020 08:27:45 GMT
> < Server: Apache/2.4.43 (FreeBSD) OpenSSL/1.1.1d-freebsd mod_auth_gssapi/1.6.1
> < X-Frame-Options: SAMEORIGIN
> < Correlation-Id: XsTqAS8xDsem5B3tl8pp0wAAAJI
> < Content-Length: 374
> < Content-Type: text/html; charset=iso-8859-1
> <
> <!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML 2.0//EN">
> <html><head>
> <title>502 Bad Gateway</title>
> </head><body>
> <h1>Bad Gateway</h1>
> <p>The proxy server received an invalid
> response from an upstream server.<br />
> </p>
> <hr>
> <address>Apache/2.4.43 (FreeBSD) OpenSSL/1.1.1d-freebsd mod_auth_gssapi/1.6.1 Server at <hostname> Port 443</address>
> </body></html>
> * Connection #0 to host <hostname> left intact
and
> $ 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 did not agree to a protocol
> * 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.
>> POST /content-dev/api/documents HTTP/1.1
>> 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
> * Mark bundle as not supporting multiuse
> < HTTP/1.1 401
> < WWW-Authenticate: Negotiate
> < Content-Type: text/html;charset=utf-8
> < Content-Language: en
> < Content-Length: 437
> < Date: Wed, 20 May 2020 08:28:16 GMT
> * NEGOTIATE send, close instead of sending 7598613 bytes
> <
> * Excess found: excess = 437 url = /content-dev/api/documents (zero-length body)
> * Closing connection 0
> * 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'
> * Hostname <hostname> was found in DNS cache
> * Trying <ip>:11111...
> * Connected to <hostname> (<ip>) port 11111 (#1)
> * ALPN, offering h2
> * ALPN, offering http/1.1
> * successfully set certificate verify locations:
> * CAfile: none
> CApath: /etc/ssl/certs/
> * SSL re-using session ID
> * 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 did not agree to a protocol
> * 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.
> * Server auth using Negotiate with user ''
>> POST /content-dev/api/documents HTTP/1.1
>> Host: <hostname>:11111
>> Authorization: Negotiate YIIRjQYG^...
>> User-Agent: curl/7.70.0
>> Accept: */*
>> Content-Type: application/zip
>> Content-Length: 7664149
>>
> * TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
> * old SSL session ID is stale, removing
> * TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
> * old SSL session ID is stale, removing
> * We are completely uploaded and fine
> * Mark bundle as not supporting multiuse
> < HTTP/1.1 201
> < WWW-Authenticate: Negotiate oYG3MIG0o...
> < vary: Origin
> < Access-Control-Allow-Credentials: true
> < Access-Control-Expose-Headers: Correlation-Id,Content-Disposition,Content-Length,Location
> < Location: https://<hostname>:11111/content-dev/api/documents/68552d0c-8f0b-4631-a14a-614d7bd7469d
> < Content-Length: 0
> < Date: Wed, 20 May 2020 08:28:17 GMT
> <
> * Connection #1 to host <hostname> left intact
As you can see the request is failing via mod_proxy_http with a 502.
After a few hours of investigation and reading log files it came to me
that mod_proxy_http does not read the response from Tomcat while it
sends the request body because Tomcat has already decided to abort the
request with 401.
See log files: What suprises me that
Http11InputBuffer.parseRequestLine() not only prints the request
headers, but also the entire body (misbehavior of mod_proxy_http?!). As
soon as I increase maxSwallowSize the symptom is gone until the new
threshold.
Similar issues:
* https://bz.apache.org/bugzilla/show_bug.cgi?id=64016
* https://bz.apache.org/bugzilla/show_bug.cgi?id=61090
* https://bz.apache.org/bugzilla/show_bug.cgi?id=60717
* https://github.com/eclipse/jetty.project/issues/651
My questions are:
* Why is parseRequestLine printing the request body?
* Can someone confirm the erratic behavior of HTTPd's module?
* Is there anyting we need to improve on the Tomcat side?
The more I use HTTPd with mod_proxy_http the more I notice that the has
been focus on websites and not real API usages.
Regards,
Michael
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: maxSwallowSize and misbehaving clients (e.g., mod_proxy_http)
Posted by "Osipov, Michael" <mi...@siemens.com>.
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?
>
> Would expect to see a second challenge form the server or should the
> client be authenticated once the first auth header has been processed?
>
> What is triggering the read of the body here?
>
> Why isn't the client sending the body?
I have made some progress on the topic with curl and HttpClient.
RFC 7230, 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.
curl perfectly manages the situation of 6.5 by using non-blocking I/O
[1]. As for HttpClient, it does not handle this because of [2], [3],
blocking I/O limitation. It then suffers from section 6.6:
> If a server performs an immediate close of a TCP connection, there is
> a significant risk that the client will not be able to read the last
> HTTP response. If the server receives additional data from the
> client on a fully closed connection, such as another request that was
> sent by the client before receiving the server's response, the
> server's TCP stack will send a reset packet to the client;
> unfortunately, the reset packet might erase the client's
> unacknowledged input buffers before they can be read and interpreted
> by the client's HTTP parser.
So I at least believe that according to 6.5 Tomcat has to include
"Connection: close" on the response.
As for the HTTP/2 issues, I will create separate threads when I have
gathered the appropriate data.
Michael
[1] https://curl.haxx.se/mail/archive-2020-05/0054.html
[2] https://stackoverflow.com/a/9176445/696632
[3]
http://mail-archives.apache.org/mod_mbox/hc-httpclient-users/202005.mbox/%3Cc43e2056-a95c-2070-3b9c-dd081a5f5235%40apache.org%3E
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: maxSwallowSize and misbehaving clients (e.g., mod_proxy_http)
Posted by "Osipov, Michael" <mi...@siemens.com>.
Am 2020-05-27 um 12:35 schrieb Mark Thomas:
> This then opens up an interesting question of whether to bother reading
> *any* of the request body if Tomcat knows it is going to close the
> connection before reading all of it. Based on what you have observed,
> would earlier closure of the connection (after a response with a
> "Connection: close" header) create additional difficulties? Would those
> clients that currently read the response while Tomcat is swallowing the
> first 2MB of upload still read the response if Tomcat didn't swallow any
> of the request? I think you can test this with maxSwallowSize="0"
As requested, reconfigured to 0 plain HTTP and HTTPS. For clients which
can handle early responses at anytime, e.g. curl, it does not matter.
They will stop sending as soon as possible. So does curl here.
For clients which do not handle this, they will fail earlier, but not as
soon as possible because they will send until the socket is broken and a
SocketException is raised. They don't see the early response at all. If
and only if the entire body is swallowed the final response is seen.
Personally, I prefer to fail fast.
I see no silver bullet here. It seriously depends on the usecase. If the
usecase contains a slow link between client and server, I prefer 0. For
a fast link, it depends on the average size of the request payload.
Can provide output for both, if required.
Michael
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: maxSwallowSize and misbehaving clients (e.g., mod_proxy_http)
Posted by Oleg Kalnichevski <ol...@apache.org>.
On Wed, 2020-05-27 at 14:47 +0200, Osipov, Michael wrote:
> Am 2020-05-27 um 12:35 schrieb Mark Thomas:
> > On 27/05/2020 10:59, Osipov, Michael wrote:
> > >
> > >
> > > Am 2020-05-27 um 10:51 schrieb Mark Thomas:
> > > > On 22/05/2020 22:59, Osipov, Michael wrote:
> > > >
> > > > <snip/>
> > > >
> > > > > I found one issue with HttpClient and Tomcat via HTTP/1.1. I
> > > > > have
> > > > > decrypted the TLS traffic [1]. I can see that HttpClient
> > > > > sends the
> > > > > headers also with a 4 KiB large chunk of the ZIP file. In
> > > > > return a
> > > > > Tomcats send the 401 response with:
> > > > > > Keep-Alive: timeout=300
> > > > > > Connection: keep-alive
> > > > >
> > > > > The client keeps sending in 8 KiB large blocks. After 2 134
> > > > > 016 written
> > > > > bytes there is a TLS alert: Close Notify. A few packets
> > > > > later: RST.
> > > > >
> > > > > I would expect to see here: "Connection: close".
> > > >
> > > > Why?
> > > >
> > > > Does the client provide a content-length header and no
> > > > expectation? If
> > > > so, Tomcat could determine that the maxSwallowSize is going to
> > > > be
> > > > exceeded and close the connection early.
> > >
> > > Yes, it does. CL present and not expectation. A transcript is
> > > here [1].
> > > We have already a working patch for the early response, also Oleg
> > > is
> > > already working on the early close not happening which is a bug
> > > in
> > > HttpClient.
> > >
> > > As for the connection header: I do not understand why you assume
> > > the
> > > header is no necessary. Your reasoning is that if the server
> > > closes the
> > > physical connection before the client has spooled the entire body
> > > and it
> > > is imperative for the client to close the connection too regard
> > > of the
> > > presense of the header?
> >
> > I didn't assume the header is not necessary. I asked for further
> > explanation from you of why you thought it was necessary. I also
> > asked
> > some questions relevant to a potential justification for adding the
> > header.
>
> Sorry if I caused confusion or missed something.
>
> This is my understanding from section 6.5 the last paragraph. The
> justification will follow below.
>
> > Tomcat has enough information to know that:
> > - it needs to return a 401
> > - the request body won't be read (by the application)
> > - the request body is larger than maxSwallowSize so once that many
> > bytes
> > have been swallowed, Tomcat is going to close the connection
> >
> > At this point I think we are heading outside of behaviour defined
> > by the
> > HTTP/1.1 specification. I haven't found language covering aborted
> > uploads.
> >
> > RFC 7230, 6.6 states a "Connection: close" header SHOULD be sent if
> > Tomcat knows it is going to close the connection. I think that
> > applies
> > in this case so I'd be in favour of adding that behaviour.
>
> That's the first paragraph, I agree. See also this example from the
> now
> working HttpClient:
>
> > 5921 [main] DEBUG
> > org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManag
> > er - ep-00000001: connected http-outgoing-1
> > 5921 [main] DEBUG
> > org.apache.hc.client5.http.impl.classic.InternalHttpClient - ep-
> > 00000001: endpoint connected
> > 5921 [main] DEBUG
> > org.apache.hc.client5.http.impl.classic.MainClientExec - ex-
> > 00000002: executing POST /content-dev/api/documents HTTP/1.1
> > 5921 [main] DEBUG
> > org.apache.hc.client5.http.impl.classic.InternalHttpClient - ep-
> > 00000001: start execution ex-00000002
> > 5921 [main] DEBUG
> > org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManag
> > er - ep-00000001: executing exchange ex-00000002 over http-
> > outgoing-1
> > 5921 [main] DEBUG org.apache.hc.client5.http.headers - http-
> > outgoing-1 >> POST /content-dev/api/documents HTTP/1.1
> > 5921 [main] DEBUG org.apache.hc.client5.http.headers - http-
> > outgoing-1 >> Accept-Encoding: gzip, x-gzip, deflate
> > 5921 [main] DEBUG org.apache.hc.client5.http.headers - http-
> > outgoing-1 >> Content-Length: 7664149
> > 5921 [main] DEBUG org.apache.hc.client5.http.headers - http-
> > outgoing-1 >> Content-Type: application/zip
> > 5921 [main] DEBUG org.apache.hc.client5.http.headers - http-
> > outgoing-1 >> Host: <hostname>:11111
> > 5921 [main] DEBUG org.apache.hc.client5.http.headers - http-
> > outgoing-1 >> Connection: keep-alive
> > 5921 [main] DEBUG org.apache.hc.client5.http.headers - http-
> > outgoing-1 >> User-Agent: Apache-HttpClient/5.0.1-SNAPSHOT
> > (Java/13.0.2)
> > 5949 [main] DEBUG org.apache.hc.client5.http.headers - http-
> > outgoing-1 << HTTP/1.1 401
> > 5949 [main] DEBUG org.apache.hc.client5.http.headers - http-
> > outgoing-1 << WWW-Authenticate: Negotiate
> > 5949 [main] DEBUG org.apache.hc.client5.http.headers - http-
> > outgoing-1 << Content-Type: text/html;charset=utf-8
> > 5949 [main] DEBUG org.apache.hc.client5.http.headers - http-
> > outgoing-1 << Content-Language: en
> > 5949 [main] DEBUG org.apache.hc.client5.http.headers - http-
> > outgoing-1 << Content-Length: 437
> > 5949 [main] DEBUG org.apache.hc.client5.http.headers - http-
> > outgoing-1 << Date: Wed, 27 May 2020 12:15:29 GMT
> > 5949 [main] DEBUG org.apache.hc.client5.http.headers - http-
> > outgoing-1 << Keep-Alive: timeout=300
> > 5949 [main] DEBUG org.apache.hc.client5.http.headers - http-
> > outgoing-1 << Connection: keep-alive
> > 5952 [main] DEBUG
> > org.apache.hc.client5.http.impl.classic.MainClientExec - ex-
> > 00000002: connection can be kept alive for 300 SECONDS
> > 5954 [main] DEBUG
> > org.apache.hc.client5.http.impl.auth.HttpAuthenticator -
> > Authentication required
> > 5954 [main] DEBUG
> > org.apache.hc.client5.http.impl.auth.HttpAuthenticator -
> > <hostname>:11111 requested authentication
> > 5954 [main] DEBUG
> > org.apache.hc.client5.http.impl.DefaultAuthenticationStrategy -
> > Authentication schemes in the order of preference: [Negotiate,
> > Kerberos, NTLM, Digest, Basic]
> > 5956 [main] DEBUG
> > org.apache.hc.client5.http.impl.DefaultAuthenticationStrategy -
> > Challenge for Kerberos authentication scheme not available
> > 5956 [main] DEBUG
> > org.apache.hc.client5.http.impl.DefaultAuthenticationStrategy -
> > Challenge for NTLM authentication scheme not available
> > 5956 [main] DEBUG
> > org.apache.hc.client5.http.impl.DefaultAuthenticationStrategy -
> > Challenge for Digest authentication scheme not available
> > 5956 [main] DEBUG
> > org.apache.hc.client5.http.impl.DefaultAuthenticationStrategy -
> > Challenge for Basic authentication scheme not available
> > 5956 [main] DEBUG
> > org.apache.hc.client5.http.impl.auth.HttpAuthenticator - Selecting
> > authentication options
> > 5956 [main] WARN
> > org.apache.hc.client5.http.impl.auth.HttpAuthenticator - Missing
> > auth challenge
> > <!doctype html><html lang="en"><head><title>HTTP Status 401 –
> > Unauthorized</title><style type="text/css">body {font-
> > family:Tahoma,Arial,sans-serif;} h1, h2, h3, b
> > {color:white;background-color:#525D76;} h1 {font-size:22px;} h2
> > {font-size:16px;} h3 {font-size:14px;} p {font-size:12px;} a
> > {color:black;} .line {height:1px;background-
> > color:#525D76;border:none;}</style></head><body><h1>HTTP Status 401
> > – Unauthorized</h1></body></html>5956 [main] DEBUG
> > org.apache.hc.client5.http.impl.classic.InternalHttpClient - ep-
> > 00000001: releasing valid endpoint
> > 5956 [main] DEBUG
> > org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManag
> > er - ep-00000001: releasing endpoint
> > 5956 [main] DEBUG
> > org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManag
> > er - ep-00000001: connection is not kept alive
> > 5956 [main] DEBUG
> > org.apache.hc.client5.http.impl.io.DefaultManagedHttpClientConnecti
> > on - http-outgoing-1: close connection GRACEFUL
> > 5980 [main] DEBUG
> > org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManag
> > er - ep-00000001: connection released [route: {s}->
> > https://<hostname>:11111][total available: 0; route allocated: 0 of
> > 5; total allocated: 0 of 25]
>
> C: Connection: keep-alive
> S: knows that the connection will be closed, but still sends keep
> alive
> information.
> While HttpClient ignores this piece of information because the
> connection must closed anyway accoring to section 6.5, but other
> clients
> might not be so "smart". curl also handles this correcly with
> "Connection: keep-alive".
>
> > This then opens up an interesting question of whether to bother
> > reading
> > *any* of the request body if Tomcat knows it is going to close the
> > connection before reading all of it. Based on what you have
> > observed,
> > would earlier closure of the connection (after a response with a
> > "Connection: close" header) create additional difficulties? Would
> > those
> > clients that currently read the response while Tomcat is swallowing
> > the
> > first 2MB of upload still read the response if Tomcat didn't
> > swallow any
> > of the request? I think you can test this with maxSwallowSize="0"
>
> I will test this, but this heavily depends on the client, especially
> how
> I/O is handled. Blocking or non-blocking. The ClassicHttpClient is
> blocking and what we do now is to wait (with a small timeout) for
> the
> early response after having sent off the headers. We cannot detect
> this
> in flight (after the first byte of the body has been sent) [1] while
> non-blocking clients (e.g., curl, AsyncHttpClient) can detect in-
> flight.
> I don't think that there is a silverbullet or whether maxSwallowSize
> should be by default 0.
>
> @Oleg, what you is your opinion here because you supplied the
> patches?
>
Hi Michael
Based on my reading of the specification the server does not need to
send `Connection: close` response header _as long as_ it is fully
prepared to consume and discard the rest of the request message body
declared in `Content-Length` request header. It is however might be
cheaper and safer to discard the connection anyway, in which
case `Connection: close` response header should be included in the
early response message.
Cheers
Oleg
> Michael
>
> [1]
>
https://github.com/ok2c/httpcomponents-core/compare/344b79f858f11064ca859faad09751b3610ba631...39f6d69a87586c147dc080431d45d6d48acb2c80
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: maxSwallowSize and misbehaving clients (e.g., mod_proxy_http)
Posted by "Osipov, Michael" <mi...@siemens.com>.
Am 2020-05-27 um 12:35 schrieb Mark Thomas:
> On 27/05/2020 10:59, Osipov, Michael wrote:
>>
>>
>> Am 2020-05-27 um 10:51 schrieb Mark Thomas:
>>> On 22/05/2020 22:59, Osipov, Michael wrote:
>>>
>>> <snip/>
>>>
>>>> I found one issue with HttpClient and Tomcat via HTTP/1.1. I have
>>>> decrypted the TLS traffic [1]. I can see that HttpClient sends the
>>>> headers also with a 4 KiB large chunk of the ZIP file. In return a
>>>> Tomcats send the 401 response with:
>>>>> Keep-Alive: timeout=300
>>>>> Connection: keep-alive
>>>>
>>>> The client keeps sending in 8 KiB large blocks. After 2 134 016 written
>>>> bytes there is a TLS alert: Close Notify. A few packets later: RST.
>>>>
>>>> I would expect to see here: "Connection: close".
>>>
>>> Why?
>>>
>>> Does the client provide a content-length header and no expectation? If
>>> so, Tomcat could determine that the maxSwallowSize is going to be
>>> exceeded and close the connection early.
>>
>> Yes, it does. CL present and not expectation. A transcript is here [1].
>> We have already a working patch for the early response, also Oleg is
>> already working on the early close not happening which is a bug in
>> HttpClient.
>>
>> As for the connection header: I do not understand why you assume the
>> header is no necessary. Your reasoning is that if the server closes the
>> physical connection before the client has spooled the entire body and it
>> is imperative for the client to close the connection too regard of the
>> presense of the header?
>
> I didn't assume the header is not necessary. I asked for further
> explanation from you of why you thought it was necessary. I also asked
> some questions relevant to a potential justification for adding the header.
Sorry if I caused confusion or missed something.
This is my understanding from section 6.5 the last paragraph. The
justification will follow below.
> Tomcat has enough information to know that:
> - it needs to return a 401
> - the request body won't be read (by the application)
> - the request body is larger than maxSwallowSize so once that many bytes
> have been swallowed, Tomcat is going to close the connection
>
> At this point I think we are heading outside of behaviour defined by the
> HTTP/1.1 specification. I haven't found language covering aborted uploads.
>
> RFC 7230, 6.6 states a "Connection: close" header SHOULD be sent if
> Tomcat knows it is going to close the connection. I think that applies
> in this case so I'd be in favour of adding that behaviour.
That's the first paragraph, I agree. See also this example from the now
working HttpClient:
> 5921 [main] DEBUG org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager - ep-00000001: connected http-outgoing-1
> 5921 [main] DEBUG org.apache.hc.client5.http.impl.classic.InternalHttpClient - ep-00000001: endpoint connected
> 5921 [main] DEBUG org.apache.hc.client5.http.impl.classic.MainClientExec - ex-00000002: executing POST /content-dev/api/documents HTTP/1.1
> 5921 [main] DEBUG org.apache.hc.client5.http.impl.classic.InternalHttpClient - ep-00000001: start execution ex-00000002
> 5921 [main] DEBUG org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager - ep-00000001: executing exchange ex-00000002 over http-outgoing-1
> 5921 [main] DEBUG org.apache.hc.client5.http.headers - http-outgoing-1 >> POST /content-dev/api/documents HTTP/1.1
> 5921 [main] DEBUG org.apache.hc.client5.http.headers - http-outgoing-1 >> Accept-Encoding: gzip, x-gzip, deflate
> 5921 [main] DEBUG org.apache.hc.client5.http.headers - http-outgoing-1 >> Content-Length: 7664149
> 5921 [main] DEBUG org.apache.hc.client5.http.headers - http-outgoing-1 >> Content-Type: application/zip
> 5921 [main] DEBUG org.apache.hc.client5.http.headers - http-outgoing-1 >> Host: <hostname>:11111
> 5921 [main] DEBUG org.apache.hc.client5.http.headers - http-outgoing-1 >> Connection: keep-alive
> 5921 [main] DEBUG org.apache.hc.client5.http.headers - http-outgoing-1 >> User-Agent: Apache-HttpClient/5.0.1-SNAPSHOT (Java/13.0.2)
> 5949 [main] DEBUG org.apache.hc.client5.http.headers - http-outgoing-1 << HTTP/1.1 401
> 5949 [main] DEBUG org.apache.hc.client5.http.headers - http-outgoing-1 << WWW-Authenticate: Negotiate
> 5949 [main] DEBUG org.apache.hc.client5.http.headers - http-outgoing-1 << Content-Type: text/html;charset=utf-8
> 5949 [main] DEBUG org.apache.hc.client5.http.headers - http-outgoing-1 << Content-Language: en
> 5949 [main] DEBUG org.apache.hc.client5.http.headers - http-outgoing-1 << Content-Length: 437
> 5949 [main] DEBUG org.apache.hc.client5.http.headers - http-outgoing-1 << Date: Wed, 27 May 2020 12:15:29 GMT
> 5949 [main] DEBUG org.apache.hc.client5.http.headers - http-outgoing-1 << Keep-Alive: timeout=300
> 5949 [main] DEBUG org.apache.hc.client5.http.headers - http-outgoing-1 << Connection: keep-alive
> 5952 [main] DEBUG org.apache.hc.client5.http.impl.classic.MainClientExec - ex-00000002: connection can be kept alive for 300 SECONDS
> 5954 [main] DEBUG org.apache.hc.client5.http.impl.auth.HttpAuthenticator - Authentication required
> 5954 [main] DEBUG org.apache.hc.client5.http.impl.auth.HttpAuthenticator - <hostname>:11111 requested authentication
> 5954 [main] DEBUG org.apache.hc.client5.http.impl.DefaultAuthenticationStrategy - Authentication schemes in the order of preference: [Negotiate, Kerberos, NTLM, Digest, Basic]
> 5956 [main] DEBUG org.apache.hc.client5.http.impl.DefaultAuthenticationStrategy - Challenge for Kerberos authentication scheme not available
> 5956 [main] DEBUG org.apache.hc.client5.http.impl.DefaultAuthenticationStrategy - Challenge for NTLM authentication scheme not available
> 5956 [main] DEBUG org.apache.hc.client5.http.impl.DefaultAuthenticationStrategy - Challenge for Digest authentication scheme not available
> 5956 [main] DEBUG org.apache.hc.client5.http.impl.DefaultAuthenticationStrategy - Challenge for Basic authentication scheme not available
> 5956 [main] DEBUG org.apache.hc.client5.http.impl.auth.HttpAuthenticator - Selecting authentication options
> 5956 [main] WARN org.apache.hc.client5.http.impl.auth.HttpAuthenticator - Missing auth challenge
> <!doctype html><html lang="en"><head><title>HTTP Status 401 – Unauthorized</title><style type="text/css">body {font-family:Tahoma,Arial,sans-serif;} h1, h2, h3, b {color:white;background-color:#525D76;} h1 {font-size:22px;} h2 {font-size:16px;} h3 {font-size:14px;} p {font-size:12px;} a {color:black;} .line {height:1px;background-color:#525D76;border:none;}</style></head><body><h1>HTTP Status 401 – Unauthorized</h1></body></html>5956 [main] DEBUG org.apache.hc.client5.http.impl.classic.InternalHttpClient - ep-00000001: releasing valid endpoint
> 5956 [main] DEBUG org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager - ep-00000001: releasing endpoint
> 5956 [main] DEBUG org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager - ep-00000001: connection is not kept alive
> 5956 [main] DEBUG org.apache.hc.client5.http.impl.io.DefaultManagedHttpClientConnection - http-outgoing-1: close connection GRACEFUL
> 5980 [main] DEBUG org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager - ep-00000001: connection released [route: {s}->https://<hostname>:11111][total available: 0; route allocated: 0 of 5; total allocated: 0 of 25]
C: Connection: keep-alive
S: knows that the connection will be closed, but still sends keep alive
information.
While HttpClient ignores this piece of information because the
connection must closed anyway accoring to section 6.5, but other clients
might not be so "smart". curl also handles this correcly with
"Connection: keep-alive".
> This then opens up an interesting question of whether to bother reading
> *any* of the request body if Tomcat knows it is going to close the
> connection before reading all of it. Based on what you have observed,
> would earlier closure of the connection (after a response with a
> "Connection: close" header) create additional difficulties? Would those
> clients that currently read the response while Tomcat is swallowing the
> first 2MB of upload still read the response if Tomcat didn't swallow any
> of the request? I think you can test this with maxSwallowSize="0"
I will test this, but this heavily depends on the client, especially how
I/O is handled. Blocking or non-blocking. The ClassicHttpClient is
blocking and what we do now is to wait (with a small timeout) for the
early response after having sent off the headers. We cannot detect this
in flight (after the first byte of the body has been sent) [1] while
non-blocking clients (e.g., curl, AsyncHttpClient) can detect in-flight.
I don't think that there is a silverbullet or whether maxSwallowSize
should be by default 0.
@Oleg, what you is your opinion here because you supplied the patches?
Michael
[1]
https://github.com/ok2c/httpcomponents-core/compare/344b79f858f11064ca859faad09751b3610ba631...39f6d69a87586c147dc080431d45d6d48acb2c80
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: maxSwallowSize and misbehaving clients (e.g., mod_proxy_http)
Posted by Mark Thomas <ma...@apache.org>.
On 27/05/2020 10:59, Osipov, Michael wrote:
>
>
> Am 2020-05-27 um 10:51 schrieb Mark Thomas:
>> On 22/05/2020 22:59, Osipov, Michael wrote:
>>
>> <snip/>
>>
>>> I found one issue with HttpClient and Tomcat via HTTP/1.1. I have
>>> decrypted the TLS traffic [1]. I can see that HttpClient sends the
>>> headers also with a 4 KiB large chunk of the ZIP file. In return a
>>> Tomcats send the 401 response with:
>>>> Keep-Alive: timeout=300
>>>> Connection: keep-alive
>>>
>>> The client keeps sending in 8 KiB large blocks. After 2 134 016 written
>>> bytes there is a TLS alert: Close Notify. A few packets later: RST.
>>>
>>> I would expect to see here: "Connection: close".
>>
>> Why?
>>
>> Does the client provide a content-length header and no expectation? If
>> so, Tomcat could determine that the maxSwallowSize is going to be
>> exceeded and close the connection early.
>
> Yes, it does. CL present and not expectation. A transcript is here [1].
> We have already a working patch for the early response, also Oleg is
> already working on the early close not happening which is a bug in
> HttpClient.
>
> As for the connection header: I do not understand why you assume the
> header is no necessary. Your reasoning is that if the server closes the
> physical connection before the client has spooled the entire body and it
> is imperative for the client to close the connection too regard of the
> presense of the header?
I didn't assume the header is not necessary. I asked for further
explanation from you of why you thought it was necessary. I also asked
some questions relevant to a potential justification for adding the header.
Tomcat has enough information to know that:
- it needs to return a 401
- the request body won't be read (by the application)
- the request body is larger than maxSwallowSize so once that many bytes
have been swallowed, Tomcat is going to close the connection
At this point I think we are heading outside of behaviour defined by the
HTTP/1.1 specification. I haven't found language covering aborted uploads.
RFC 7230, 6.6 states a "Connection: close" header SHOULD be sent if
Tomcat knows it is going to close the connection. I think that applies
in this case so I'd be in favour of adding that behaviour.
This then opens up an interesting question of whether to bother reading
*any* of the request body if Tomcat knows it is going to close the
connection before reading all of it. Based on what you have observed,
would earlier closure of the connection (after a response with a
"Connection: close" header) create additional difficulties? Would those
clients that currently read the response while Tomcat is swallowing the
first 2MB of upload still read the response if Tomcat didn't swallow any
of the request? I think you can test this with maxSwallowSize="0"
Mark
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: maxSwallowSize and misbehaving clients (e.g., mod_proxy_http)
Posted by "Osipov, Michael" <mi...@siemens.com>.
Am 2020-05-27 um 10:51 schrieb Mark Thomas:
> On 22/05/2020 22:59, Osipov, Michael wrote:
>
> <snip/>
>
>> I found one issue with HttpClient and Tomcat via HTTP/1.1. I have
>> decrypted the TLS traffic [1]. I can see that HttpClient sends the
>> headers also with a 4 KiB large chunk of the ZIP file. In return a
>> Tomcats send the 401 response with:
>>> Keep-Alive: timeout=300
>>> Connection: keep-alive
>>
>> The client keeps sending in 8 KiB large blocks. After 2 134 016 written
>> bytes there is a TLS alert: Close Notify. A few packets later: RST.
>>
>> I would expect to see here: "Connection: close".
>
> Why?
>
> Does the client provide a content-length header and no expectation? If
> so, Tomcat could determine that the maxSwallowSize is going to be
> exceeded and close the connection early.
Yes, it does. CL present and not expectation. A transcript is here [1].
We have already a working patch for the early response, also Oleg is
already working on the early close not happening which is a bug in
HttpClient.
As for the connection header: I do not understand why you assume the
header is no necessary. Your reasoning is that if the server closes the
physical connection before the client has spooled the entire body and it
is imperative for the client to close the connection too regard of the
presense of the header?
Michael
[1]
https://www.mail-archive.com/httpclient-users@hc.apache.org/msg09927.html
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: maxSwallowSize and misbehaving clients (e.g., mod_proxy_http)
Posted by Mark Thomas <ma...@apache.org>.
On 22/05/2020 22:59, Osipov, Michael wrote:
<snip/>
> I found one issue with HttpClient and Tomcat via HTTP/1.1. I have
> decrypted the TLS traffic [1]. I can see that HttpClient sends the
> headers also with a 4 KiB large chunk of the ZIP file. In return a
> Tomcats send the 401 response with:
>> Keep-Alive: timeout=300
>> Connection: keep-alive
>
> The client keeps sending in 8 KiB large blocks. After 2 134 016 written
> bytes there is a TLS alert: Close Notify. A few packets later: RST.
>
> I would expect to see here: "Connection: close".
Why?
Does the client provide a content-length header and no expectation? If
so, Tomcat could determine that the maxSwallowSize is going to be
exceeded and close the connection early.
Mark
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: maxSwallowSize and misbehaving clients (e.g., mod_proxy_http)
Posted by "Osipov, Michael" <mi...@siemens.com>.
Am 2020-05-22 um 18:51 schrieb [ext] Osipov, Michael:
>
> 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:
> ...
I found one issue with HttpClient and Tomcat via HTTP/1.1. I have
decrypted the TLS traffic [1]. I can see that HttpClient sends the
headers also with a 4 KiB large chunk of the ZIP file. In return a
Tomcats send the 401 response with:
> Keep-Alive: timeout=300
> Connection: keep-alive
The client keeps sending in 8 KiB large blocks. After 2 134 016 written
bytes there is a TLS alert: Close Notify. A few packets later: RST.
I would expect to see here: "Connection: close".
If necessary, I can provide the pcap and the keylog file.
[1] https://github.com/neykov/extract-tls-secrets
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: maxSwallowSize and misbehaving clients (e.g., mod_proxy_http)
Posted by "Osipov, Michael" <mi...@siemens.com>.
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
Re: maxSwallowSize and misbehaving clients (e.g., mod_proxy_http)
Posted by Mark Thomas <ma...@apache.org>.
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?
Would expect to see a second challenge form the server or should the
client be authenticated once the first auth header has been processed?
What is triggering the read of the body here?
Why isn't the client sending the body?
The proxy logs don't show nay http2 traffic at all.
Mark
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: maxSwallowSize and misbehaving clients (e.g., mod_proxy_http)
Posted by "Osipov, Michael" <mi...@siemens.com>.
Am 2020-05-21 um 23:36 schrieb Mark Thomas:
> On 21/05/2020 21:45, Osipov, Michael wrote:
>>
>>
>> Am 2020-05-21 um 11:02 schrieb Mark Thomas:
>>> On 20/05/2020 17:57, Osipov, Michael wrote:
>>>
>>>>> 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:
>>>
>>> <snip/>
>>>
>>>> What now?
>>>
>>> Turn on debug logging for o.a.coyote.http2 for both.
>>>
>>> For httpd, disable/relax the overhead protection although it would we
>>> worth looking at what httpd is doing to trigger that.
>>
>> I did now the tests with h2/h2c direct and via proxy. Will send output
>> privately.
>>
>> What explicit overhead protection in HTTPd are you referring?
>> mod_proxy_http2 does not provide any options. Please note that clients
>> talk to HTTPd via HTTP/1.1 only.
>>
>> Plese tell the exact tunable and I will retry.
>
> Sorry, I meant for the httpd as a proxy test, relax/disable Tomcat's
> HTTP/2 overhead protection.
Done. Set overheadCountFactor="0".
> $ time curl -X POST --anyauth -u : --upload-file inputs.zip -H "Content-Type: application/zip" https://<hostname>/content-dev/api/documents --verbose -H "Expect:" --trace trace.proxy
> Warning: --trace overrides an earlier trace/verbose option
> <!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 Server at <hostname> Port 443</address>
> </body></html>
>
> real 0m53,683s
> user 0m9,948s
> sys 0m0,821s
The execution time has exploded for real. Direct was with HTTP/1.1 6
seconds, via proxy 12 s, now a minute.
The worst I can see is that requests are physically replayed twice:
> 2020-05-22T00:11:29 WARNUNG [http-apr-127.0.1.2-8083-exec-9] net.sf.michaelo.tomcat.authenticator.SpnegoAuthenticator.doAuthenticate The Negotiate (SPNEGO) authentication token is invalid: YIIRjAY...
> GSSException: Failure unspecified at GSS-API level (Mechanism level: Request is a replay (34))
> 2020-05-22T00:11:55 WARNUNG [http-apr-127.0.1.2-8083-exec-5] net.sf.michaelo.tomcat.authenticator.SpnegoAuthenticator.doAuthenticate The Negotiate (SPNEGO) authentication token is invalid: YIIRjQYGKwYBBQU...
> GSSException: Failure unspecified at GSS-API level (Mechanism level: Request is a replay (34))
Output will be sent privately.
Thanks,
Michael
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: maxSwallowSize and misbehaving clients (e.g., mod_proxy_http)
Posted by Mark Thomas <ma...@apache.org>.
On 21/05/2020 21:45, Osipov, Michael wrote:
>
>
> Am 2020-05-21 um 11:02 schrieb Mark Thomas:
>> On 20/05/2020 17:57, Osipov, Michael wrote:
>>
>>>> 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:
>>
>> <snip/>
>>
>>> What now?
>>
>> Turn on debug logging for o.a.coyote.http2 for both.
>>
>> For httpd, disable/relax the overhead protection although it would we
>> worth looking at what httpd is doing to trigger that.
>
> I did now the tests with h2/h2c direct and via proxy. Will send output
> privately.
>
> What explicit overhead protection in HTTPd are you referring?
> mod_proxy_http2 does not provide any options. Please note that clients
> talk to HTTPd via HTTP/1.1 only.
>
> Plese tell the exact tunable and I will retry.
Sorry, I meant for the httpd as a proxy test, relax/disable Tomcat's
HTTP/2 overhead protection.
Mark
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: maxSwallowSize and misbehaving clients (e.g., mod_proxy_http)
Posted by "Osipov, Michael" <mi...@siemens.com>.
Am 2020-05-21 um 11:02 schrieb Mark Thomas:
> On 20/05/2020 17:57, Osipov, Michael wrote:
>
>>> 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:
>
> <snip/>
>
>> What now?
>
> Turn on debug logging for o.a.coyote.http2 for both.
>
> For httpd, disable/relax the overhead protection although it would we
> worth looking at what httpd is doing to trigger that.
I did now the tests with h2/h2c direct and via proxy. Will send output
privately.
What explicit overhead protection in HTTPd are you referring?
mod_proxy_http2 does not provide any options. Please note that clients
talk to HTTPd via HTTP/1.1 only.
Plese tell the exact tunable and I will retry.
Regards,
Michael
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: maxSwallowSize and misbehaving clients (e.g., mod_proxy_http)
Posted by Mark Thomas <ma...@apache.org>.
On 20/05/2020 17:57, Osipov, Michael wrote:
>> 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:
<snip/>
> What now?
Turn on debug logging for o.a.coyote.http2 for both.
For httpd, disable/relax the overhead protection although it would we
worth looking at what httpd is doing to trigger that.
Mark
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: maxSwallowSize and misbehaving clients (e.g., mod_proxy_http)
Posted by "Osipov, Michael" <mi...@siemens.com>.
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 'osipovmi@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-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: maxSwallowSize and misbehaving clients (e.g., mod_proxy_http)
Posted by Mark Thomas <ma...@apache.org>.
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.
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.
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.
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.
Is there an option to proxy via HTTP/2? That should be able to handle
these sorts of situations more gracefully.
Mark
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org