You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@tomcat.apache.org by Lorenzo Dalla Vecchia <lo...@webratio.com> on 2022/12/15 22:42:19 UTC
HTTP/2 streams reset by Tomcat are treted as 503 errors by Apache HTTP Server
Hello.
We are having a random issue in a setup with Tomcat deployed behind
Apache httpd. Some HTTP/2 requests proxied to Tomcat by httpd end with a
503 (service unavailable) response to the web browser client.
Tomcat version is 9.0.58 running with Java 1.8.0 in a Docker container.
Docker version is 18.09.2 and the host machine runs Ubuntu 18.04.
I only have access to httpd logs, because enabling Tomcat logs
(org.apache.coyote.http2.level = FINE) cause the problem to go away.
The following is an excerpt of a failing HTTP/2 stream, requested by
httpd to Tomcat.
[Thu Dec 15 21:21:25.202719 2022] [proxy_http2:debug] [pid 44:tid
139828875544320] h2_proxy_session.c(931): [remote 192.168.65.2:18095]
AH03363: h2_proxy_session(219-1289): submit localhost/app/143.js -> 1
[Thu Dec 15 21:21:25.202784 2022] [proxy_http2:debug] [pid 44:tid
139828875544320] h2_proxy_session.c(345): [remote 192.168.65.2:18095]
AH03343: h2_proxy_session(219-1289): sent FRAME[HEADERS[length=549,
hend=1, stream=1, eos=0]]
[Thu Dec 15 21:21:25.277438 2022] [proxy_http2:debug] [pid 44:tid
139828875544320] h2_proxy_session.c(267): [remote 192.168.65.2:18095]
AH03341: h2_proxy_session(219-1289): recv FRAME[HEADERS[length=120,
hend=1, stream=1, eos=0]]
[Thu Dec 15 21:21:25.277441 2022] [proxy_http2:debug] [pid 44:tid
139828875544320] h2_proxy_session.c(267): [remote 192.168.65.2:18095]
AH03341: h2_proxy_session(219-1289): recv FRAME[DATA[length=0, flags=1,
stream=1, padlen=0]]
[Thu Dec 15 21:21:25.277445 2022] [proxy_http2:debug] [pid 44:tid
139828875544320] h2_proxy_session.c(267): [remote 192.168.65.2:18095]
AH03341: h2_proxy_session(219-1289): recv FRAME[RST_STREAM[length=4,
flags=0, stream=1]]
[Thu Dec 15 21:21:25.277448 2022] [proxy_http2:debug] [pid 44:tid
139828875544320] h2_proxy_session.c(560): [remote 192.168.65.2:18095]
AH03360: h2_proxy_session(219-1289): stream=1, closed, err=8
[Thu Dec 15 21:21:25.277449 2022] [proxy_http2:debug] [pid 44:tid
139828875544320] h2_proxy_session.c(1352): [remote 192.168.65.2:18095]
AH03364: h2_proxy_sesssion(219-1289): stream(1) closed (touched=0,
error=8)
This is a similar excerpt from a successful HTTP/2 stream between the
same servers.
[Wed Dec 14 15:31:19.516817 2022] [proxy_http2:debug] [pid 42:tid
140518005270272] h2_proxy_session.c(931): [remote 192.168.65.2:18095]
AH03363: h2_proxy_session(212-197): submit localhost/app/1543.js -> 3
[Wed Dec 14 15:31:19.516849 2022] [proxy_http2:debug] [pid 42:tid
140518005270272] h2_proxy_session.c(345): [remote 192.168.65.2:18095]
AH03343: h2_proxy_session(212-197): sent FRAME[HEADERS[length=59,
hend=1, stream=3, eos=0]]
[Wed Dec 14 15:31:19.569569 2022] [proxy_http2:debug] [pid 42:tid
140518005270272] h2_proxy_session.c(267): [remote 192.168.65.2:18095]
AH03341: h2_proxy_session(212-197): recv FRAME[HEADERS[length=33,
hend=1, stream=3, eos=0]]
[Wed Dec 14 15:31:19.569575 2022] [proxy_http2:debug] [pid 42:tid
140518005270272] h2_proxy_session.c(267): [remote 192.168.65.2:18095]
AH03341: h2_proxy_session(212-197): recv FRAME[DATA[length=0, flags=1,
stream=3, padlen=0]]
[Wed Dec 14 15:31:19.569576 2022] [proxy_http2:debug] [pid 42:tid
140518005270272] h2_proxy_session.c(560): [remote 192.168.65.2:18095]
AH03360: h2_proxy_session(212-197): stream=3, closed, err=0
[Wed Dec 14 15:31:19.569577 2022] [proxy_http2:debug] [pid 42:tid
140518005270272] h2_proxy_session.c(1352): [remote 192.168.65.2:18095]
AH03364: h2_proxy_sesssion(212-197): stream(3) closed (touched=0,
error=0)
[Wed Dec 14 15:31:19.569753 2022] [proxy_http2:debug] [pid 42:tid
140518005270272] h2_proxy_session.c(267): [remote 192.168.65.2:18095]
AH03341: h2_proxy_session(212-197): recv FRAME[RST_STREAM[length=4,
flags=0, stream=3]]
In both cases, the request is a GET with "If-Modified-Since" header that
should result in a 304 response (not modified).
So, it is correct that there is no request nor response body.
The sequence of exchanged frames is
- httpd sends HEADERS frame,
- Tomcat sends HEADERS frame,
- Tomcat sends DATA frame with length 0 (correct) and with END_STREAM
flag (1),
- Tomcat sends RST_STREAM frame.
I think the problem is somehow related to the RST_STREAM frame.
In the failing case, it is read by httpd before it declares the stream
closed, and the frame contained the CANCEL error code (error=8, err=8).
In the successful case, it is read by httpd after the stream is declared
closed, so the log does not show its error code. Either the code is
NO_ERROR (0) or it is still CANCEL (8) but it is too late for httpd to
change the outcome of the stream, which it declared error=0.
The cases when the stream ends with a non-zero code on httpd side are
precisely the ones that result in a 503 error for the client.
The problem looks very time-sensitive. I can only reproduce it with
Tomcat HTTP/2 logs disabled, without a Java debugger attached to Tomcat,
and with real network lag.
I created an automatic test case that uses a browser to download 20
files concurrently and repeats every couple of seconds.
- With httpd and Tomcat on two different cloud machines, without Tomcat
logs, the problem happens after maximum 30 seconds.
- With httpd and Tomcat on my machine or Tomcat logs/debug enabled, I
gave up reproducing the problem after 10 hours.
It also appears that the problem is sensitive to the response being a
304 with no body.
If I disable caching, the problem becomes a lot harder to reproduce but
still possible (I'd say about 20 times less probable).
My guess is that the RST_STREAM frame sent by Tomcat always contains the
CANCEL code, and there is a race condition with httpd closing the
stream. When the RST_STREAM arrives before closing, httpd interprets the
CANCEL code as an error condition and reports that to the client with
503 error code.
I looked at the sources for the HTTP/2 connector and found this code
around line 100 of org.apache.coyote.http2.StreamProcessor.
StreamException se = new StreamException(
sm.getString("streamProcessor.cancel", stream.getConnectionId(),
stream.getIdAsString()), Http2Error.CANCEL,
stream.getIdAsInt());
stream.close(se);
This seems to be the only place where the connector is sending a CANCEL
besides the forced closing of the connection in
org.apache.coyote.http2.Http2UpgradeHandler.close().
I don't know HTTP/2 deeply enough to say that sending CANCEL here is
wrong, also because I'm not sure I understand the situation that the
connector is addressing. However, could it be that the correct code here
shold be Http2Error.NO_ERROR?
I recompiled the class with that change, and my test case ran for 12
hours without fail.
There is also this bug report for the Go http2 package:
https://github.com/golang/go/issues/19948
It looks pretty similar to the problem we see here (except that, in that
case, the client is directly a browser).
The folks there conclude that the CANCEL error code is mostly intended
for clients and that servers should end "useless" streams with NO_ERROR.
They also quote a section of the RFC
(https://www.rfc-editor.org/rfc/rfc7540#section-8.1), but I am not sure
if it applies to the Tomcat case.
What do you think? Could this be a rare Tomcat bug, an httpd bug, or
something else?
Please let me know if you need more information.
Thanks in advance for your help.
Regards.
--
Lorenzo
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re[2]: HTTP/2 streams reset by Tomcat are treted as 503 errors by Apache HTTP Server
Posted by Lorenzo Dalla Vecchia <lo...@webratio.com>.
>The specification language isn't is tight as I'd like it to be but I think you're right - the intention of the spec authors was that NO_ERROR gets used here. I'll get that updated for the next round of releases.
Cool! Thanks a lot, Mark!
--
Lorenzo
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: HTTP/2 streams reset by Tomcat are treted as 503 errors by Apache HTTP Server
Posted by Mark Thomas <ma...@apache.org>.
On 15/12/2022 22:42, Lorenzo Dalla Vecchia wrote:
<snip/>
> I looked at the sources for the HTTP/2 connector and found this code
> around line 100 of org.apache.coyote.http2.StreamProcessor.
>
> StreamException se = new StreamException(
> sm.getString("streamProcessor.cancel", stream.getConnectionId(),
> stream.getIdAsString()), Http2Error.CANCEL,
> stream.getIdAsInt());
> stream.close(se);
>
> This seems to be the only place where the connector is sending a CANCEL
> besides the forced closing of the connection in
> org.apache.coyote.http2.Http2UpgradeHandler.close().
>
> I don't know HTTP/2 deeply enough to say that sending CANCEL here is
> wrong, also because I'm not sure I understand the situation that the
> connector is addressing. However, could it be that the correct code here
> shold be Http2Error.NO_ERROR?
> I recompiled the class with that change, and my test case ran for 12
> hours without fail.
>
> There is also this bug report for the Go http2 package:
> https://github.com/golang/go/issues/19948
> It looks pretty similar to the problem we see here (except that, in that
> case, the client is directly a browser).
> The folks there conclude that the CANCEL error code is mostly intended
> for clients and that servers should end "useless" streams with NO_ERROR.
> They also quote a section of the RFC
> (https://www.rfc-editor.org/rfc/rfc7540#section-8.1), but I am not sure
> if it applies to the Tomcat case.
>
> What do you think? Could this be a rare Tomcat bug, an httpd bug, or
> something else?
> Please let me know if you need more information.
The specification language isn't is tight as I'd like it to be but I
think you're right - the intention of the spec authors was that NO_ERROR
gets used here. I'll get that updated for the next round of releases.
Mark
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re[2]: HTTP/2 streams reset by Tomcat are treted as 503 errors by Apache HTTP Server
Posted by Lorenzo Dalla Vecchia <lo...@webratio.com>.
>Hello Lorenzo,
>
>> -----Ursprüngliche Nachricht-----
>> Von: Lorenzo Dalla Vecchia <lo...@webratio.com>
>> Gesendet: Donnerstag, 15. Dezember 2022 23:42
>> An: users@tomcat.apache.org
>> Betreff: HTTP/2 streams reset by Tomcat are treted as 503 errors by Apache
>> HTTP Server
>>
>> Hello.
>>
>> We are having a random issue in a setup with Tomcat deployed behind Apache
>> httpd. Some HTTP/2 requests proxied to Tomcat by httpd end with a
>> 503 (service unavailable) response to the web browser client.
>>
>> Tomcat version is 9.0.58 running with Java 1.8.0 in a Docker container.
>> Docker version is 18.09.2 and the host machine runs Ubuntu 18.04.
>>
>> I only have access to httpd logs, because enabling Tomcat logs
>> (org.apache.coyote.http2.level = FINE) cause the problem to go away.
>>
>> The following is an excerpt of a failing HTTP/2 stream, requested by httpd to
>> Tomcat.
>>
>> [Thu Dec 15 21:21:25.202719 2022] [proxy_http2:debug] [pid 44:tid
>> 139828875544320] h2_proxy_session.c(931): [remote 192.168.65.2:18095]
>> AH03363: h2_proxy_session(219-1289): submit localhost/app/143.js -> 1
>> [Thu Dec 15 21:21:25.202784 2022] [proxy_http2:debug] [pid 44:tid
>> 139828875544320] h2_proxy_session.c(345): [remote 192.168.65.2:18095]
>> AH03343: h2_proxy_session(219-1289): sent FRAME[HEADERS[length=549,
>> hend=1, stream=1, eos=0]]
>> [Thu Dec 15 21:21:25.277438 2022] [proxy_http2:debug] [pid 44:tid
>> 139828875544320] h2_proxy_session.c(267): [remote 192.168.65.2:18095]
>> AH03341: h2_proxy_session(219-1289): recv FRAME[HEADERS[length=120,
>> hend=1, stream=1, eos=0]]
>> [Thu Dec 15 21:21:25.277441 2022] [proxy_http2:debug] [pid 44:tid
>> 139828875544320] h2_proxy_session.c(267): [remote 192.168.65.2:18095]
>> AH03341: h2_proxy_session(219-1289): recv FRAME[DATA[length=0, flags=1,
>> stream=1, padlen=0]]
>> [Thu Dec 15 21:21:25.277445 2022] [proxy_http2:debug] [pid 44:tid
>> 139828875544320] h2_proxy_session.c(267): [remote 192.168.65.2:18095]
>> AH03341: h2_proxy_session(219-1289): recv FRAME[RST_STREAM[length=4,
>> flags=0, stream=1]]
>> [Thu Dec 15 21:21:25.277448 2022] [proxy_http2:debug] [pid 44:tid
>> 139828875544320] h2_proxy_session.c(560): [remote 192.168.65.2:18095]
>> AH03360: h2_proxy_session(219-1289): stream=1, closed, err=8
>> [Thu Dec 15 21:21:25.277449 2022] [proxy_http2:debug] [pid 44:tid
>> 139828875544320] h2_proxy_session.c(1352): [remote 192.168.65.2:18095]
>> AH03364: h2_proxy_sesssion(219-1289): stream(1) closed (touched=0,
>> error=8)
>>
>> This is a similar excerpt from a successful HTTP/2 stream between the same
>> servers.
>>
>> [Wed Dec 14 15:31:19.516817 2022] [proxy_http2:debug] [pid 42:tid
>> 140518005270272] h2_proxy_session.c(931): [remote 192.168.65.2:18095]
>> AH03363: h2_proxy_session(212-197): submit localhost/app/1543.js -> 3
>> [Wed Dec 14 15:31:19.516849 2022] [proxy_http2:debug] [pid 42:tid
>> 140518005270272] h2_proxy_session.c(345): [remote 192.168.65.2:18095]
>> AH03343: h2_proxy_session(212-197): sent FRAME[HEADERS[length=59,
>> hend=1, stream=3, eos=0]]
>> [Wed Dec 14 15:31:19.569569 2022] [proxy_http2:debug] [pid 42:tid
>> 140518005270272] h2_proxy_session.c(267): [remote 192.168.65.2:18095]
>> AH03341: h2_proxy_session(212-197): recv FRAME[HEADERS[length=33,
>> hend=1, stream=3, eos=0]]
>> [Wed Dec 14 15:31:19.569575 2022] [proxy_http2:debug] [pid 42:tid
>> 140518005270272] h2_proxy_session.c(267): [remote 192.168.65.2:18095]
>> AH03341: h2_proxy_session(212-197): recv FRAME[DATA[length=0, flags=1,
>> stream=3, padlen=0]]
>> [Wed Dec 14 15:31:19.569576 2022] [proxy_http2:debug] [pid 42:tid
>> 140518005270272] h2_proxy_session.c(560): [remote 192.168.65.2:18095]
>> AH03360: h2_proxy_session(212-197): stream=3, closed, err=0
>> [Wed Dec 14 15:31:19.569577 2022] [proxy_http2:debug] [pid 42:tid
>> 140518005270272] h2_proxy_session.c(1352): [remote 192.168.65.2:18095]
>> AH03364: h2_proxy_sesssion(212-197): stream(3) closed (touched=0,
>> error=0)
>> [Wed Dec 14 15:31:19.569753 2022] [proxy_http2:debug] [pid 42:tid
>> 140518005270272] h2_proxy_session.c(267): [remote 192.168.65.2:18095]
>> AH03341: h2_proxy_session(212-197): recv FRAME[RST_STREAM[length=4,
>> flags=0, stream=3]]
>>
>> In both cases, the request is a GET with "If-Modified-Since" header that should
>> result in a 304 response (not modified).
>> So, it is correct that there is no request nor response body.
>> The sequence of exchanged frames is
>>
>> - httpd sends HEADERS frame,
>> - Tomcat sends HEADERS frame,
>> - Tomcat sends DATA frame with length 0 (correct) and with END_STREAM flag
>> (1),
>> - Tomcat sends RST_STREAM frame.
>>
>> I think the problem is somehow related to the RST_STREAM frame.
>> In the failing case, it is read by httpd before it declares the stream closed, and
>> the frame contained the CANCEL error code (error=8, err=8).
>> In the successful case, it is read by httpd after the stream is declared closed, so
>> the log does not show its error code. Either the code is NO_ERROR (0) or it is
>> still CANCEL (8) but it is too late for httpd to change the outcome of the stream,
>> which it declared error=0.
>>
>> The cases when the stream ends with a non-zero code on httpd side are
>> precisely the ones that result in a 503 error for the client.
>>
>> The problem looks very time-sensitive. I can only reproduce it with Tomcat
>> HTTP/2 logs disabled, without a Java debugger attached to Tomcat, and with
>> real network lag.
>> I created an automatic test case that uses a browser to download 20 files
>> concurrently and repeats every couple of seconds.
>>
>> - With httpd and Tomcat on two different cloud machines, without Tomcat logs,
>> the problem happens after maximum 30 seconds.
>> - With httpd and Tomcat on my machine or Tomcat logs/debug enabled, I gave
>> up reproducing the problem after 10 hours.
>>
>> It also appears that the problem is sensitive to the response being a
>> 304 with no body.
>> If I disable caching, the problem becomes a lot harder to reproduce but still
>> possible (I'd say about 20 times less probable).
>>
>> My guess is that the RST_STREAM frame sent by Tomcat always contains the
>> CANCEL code, and there is a race condition with httpd closing the stream.
>> When the RST_STREAM arrives before closing, httpd interprets the CANCEL
>> code as an error condition and reports that to the client with
>> 503 error code.
>>
>> I looked at the sources for the HTTP/2 connector and found this code around
>> line 100 of org.apache.coyote.http2.StreamProcessor.
>>
>> StreamException se = new StreamException(
>> sm.getString("streamProcessor.cancel", stream.getConnectionId(),
>> stream.getIdAsString()), Http2Error.CANCEL, stream.getIdAsInt());
>> stream.close(se);
>>
>> This seems to be the only place where the connector is sending a CANCEL
>> besides the forced closing of the connection in
>> org.apache.coyote.http2.Http2UpgradeHandler.close().
>>
>> I don't know HTTP/2 deeply enough to say that sending CANCEL here is wrong,
>> also because I'm not sure I understand the situation that the connector is
>> addressing. However, could it be that the correct code here shold be
>> Http2Error.NO_ERROR?
>> I recompiled the class with that change, and my test case ran for 12 hours
>> without fail.
>>
>> There is also this bug report for the Go http2 package:
>>https://github.com/golang/go/issues/19948
>> It looks pretty similar to the problem we see here (except that, in that case, the
>> client is directly a browser).
>> The folks there conclude that the CANCEL error code is mostly intended for
>> clients and that servers should end "useless" streams with NO_ERROR.
>> They also quote a section of the RFC
>> (https://www.rfc-editor.org/rfc/rfc7540#section-8.1), but I am not sure if it
>> applies to the Tomcat case.
>>
>> What do you think? Could this be a rare Tomcat bug, an httpd bug, or
>> something else?
>> Please let me know if you need more information.
>>
>> Thanks in advance for your help.
>> Regards.
>>
>> --
>> Lorenzo
>>
>>
>Can you check, whether http compression is enabled on your tomcat?
>Connector-Snippet from server.xml would also be fine.
>
>I have similar sporadic issues when compression is enabled.
>Maybe we experience the same issue.
>
>Greetings, Thomas
Hi Thomas.
Here is my connector configuration.
<Connector URIEncoding="UTF-8" executor="sharedThreadPool"
port="18080" protocol="HTTP/1.1" connectionTimeout="20000"
asyncTimeout="${ASYNC_TIMEOUT}" secure="true" scheme="https"
redirectPort="8443" proxyPort="443" server="-"
maxHttpHeaderSize="65536">
<UpgradeProtocol
className="org.apache.coyote.http2.Http2Protocol"/>
</Connector>
Looks like compression is disabled.
--
Lorenzo
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
AW: HTTP/2 streams reset by Tomcat are treted as 503 errors by Apache HTTP Server
Posted by "Thomas Hoffmann (Speed4Trade GmbH)" <Th...@speed4trade.com.INVALID>.
Hello Lorenzo,
> -----Ursprüngliche Nachricht-----
> Von: Lorenzo Dalla Vecchia <lo...@webratio.com>
> Gesendet: Donnerstag, 15. Dezember 2022 23:42
> An: users@tomcat.apache.org
> Betreff: HTTP/2 streams reset by Tomcat are treted as 503 errors by Apache
> HTTP Server
>
> Hello.
>
> We are having a random issue in a setup with Tomcat deployed behind Apache
> httpd. Some HTTP/2 requests proxied to Tomcat by httpd end with a
> 503 (service unavailable) response to the web browser client.
>
> Tomcat version is 9.0.58 running with Java 1.8.0 in a Docker container.
> Docker version is 18.09.2 and the host machine runs Ubuntu 18.04.
>
> I only have access to httpd logs, because enabling Tomcat logs
> (org.apache.coyote.http2.level = FINE) cause the problem to go away.
>
> The following is an excerpt of a failing HTTP/2 stream, requested by httpd to
> Tomcat.
>
> [Thu Dec 15 21:21:25.202719 2022] [proxy_http2:debug] [pid 44:tid
> 139828875544320] h2_proxy_session.c(931): [remote 192.168.65.2:18095]
> AH03363: h2_proxy_session(219-1289): submit localhost/app/143.js -> 1
> [Thu Dec 15 21:21:25.202784 2022] [proxy_http2:debug] [pid 44:tid
> 139828875544320] h2_proxy_session.c(345): [remote 192.168.65.2:18095]
> AH03343: h2_proxy_session(219-1289): sent FRAME[HEADERS[length=549,
> hend=1, stream=1, eos=0]]
> [Thu Dec 15 21:21:25.277438 2022] [proxy_http2:debug] [pid 44:tid
> 139828875544320] h2_proxy_session.c(267): [remote 192.168.65.2:18095]
> AH03341: h2_proxy_session(219-1289): recv FRAME[HEADERS[length=120,
> hend=1, stream=1, eos=0]]
> [Thu Dec 15 21:21:25.277441 2022] [proxy_http2:debug] [pid 44:tid
> 139828875544320] h2_proxy_session.c(267): [remote 192.168.65.2:18095]
> AH03341: h2_proxy_session(219-1289): recv FRAME[DATA[length=0, flags=1,
> stream=1, padlen=0]]
> [Thu Dec 15 21:21:25.277445 2022] [proxy_http2:debug] [pid 44:tid
> 139828875544320] h2_proxy_session.c(267): [remote 192.168.65.2:18095]
> AH03341: h2_proxy_session(219-1289): recv FRAME[RST_STREAM[length=4,
> flags=0, stream=1]]
> [Thu Dec 15 21:21:25.277448 2022] [proxy_http2:debug] [pid 44:tid
> 139828875544320] h2_proxy_session.c(560): [remote 192.168.65.2:18095]
> AH03360: h2_proxy_session(219-1289): stream=1, closed, err=8
> [Thu Dec 15 21:21:25.277449 2022] [proxy_http2:debug] [pid 44:tid
> 139828875544320] h2_proxy_session.c(1352): [remote 192.168.65.2:18095]
> AH03364: h2_proxy_sesssion(219-1289): stream(1) closed (touched=0,
> error=8)
>
> This is a similar excerpt from a successful HTTP/2 stream between the same
> servers.
>
> [Wed Dec 14 15:31:19.516817 2022] [proxy_http2:debug] [pid 42:tid
> 140518005270272] h2_proxy_session.c(931): [remote 192.168.65.2:18095]
> AH03363: h2_proxy_session(212-197): submit localhost/app/1543.js -> 3
> [Wed Dec 14 15:31:19.516849 2022] [proxy_http2:debug] [pid 42:tid
> 140518005270272] h2_proxy_session.c(345): [remote 192.168.65.2:18095]
> AH03343: h2_proxy_session(212-197): sent FRAME[HEADERS[length=59,
> hend=1, stream=3, eos=0]]
> [Wed Dec 14 15:31:19.569569 2022] [proxy_http2:debug] [pid 42:tid
> 140518005270272] h2_proxy_session.c(267): [remote 192.168.65.2:18095]
> AH03341: h2_proxy_session(212-197): recv FRAME[HEADERS[length=33,
> hend=1, stream=3, eos=0]]
> [Wed Dec 14 15:31:19.569575 2022] [proxy_http2:debug] [pid 42:tid
> 140518005270272] h2_proxy_session.c(267): [remote 192.168.65.2:18095]
> AH03341: h2_proxy_session(212-197): recv FRAME[DATA[length=0, flags=1,
> stream=3, padlen=0]]
> [Wed Dec 14 15:31:19.569576 2022] [proxy_http2:debug] [pid 42:tid
> 140518005270272] h2_proxy_session.c(560): [remote 192.168.65.2:18095]
> AH03360: h2_proxy_session(212-197): stream=3, closed, err=0
> [Wed Dec 14 15:31:19.569577 2022] [proxy_http2:debug] [pid 42:tid
> 140518005270272] h2_proxy_session.c(1352): [remote 192.168.65.2:18095]
> AH03364: h2_proxy_sesssion(212-197): stream(3) closed (touched=0,
> error=0)
> [Wed Dec 14 15:31:19.569753 2022] [proxy_http2:debug] [pid 42:tid
> 140518005270272] h2_proxy_session.c(267): [remote 192.168.65.2:18095]
> AH03341: h2_proxy_session(212-197): recv FRAME[RST_STREAM[length=4,
> flags=0, stream=3]]
>
> In both cases, the request is a GET with "If-Modified-Since" header that should
> result in a 304 response (not modified).
> So, it is correct that there is no request nor response body.
> The sequence of exchanged frames is
>
> - httpd sends HEADERS frame,
> - Tomcat sends HEADERS frame,
> - Tomcat sends DATA frame with length 0 (correct) and with END_STREAM flag
> (1),
> - Tomcat sends RST_STREAM frame.
>
> I think the problem is somehow related to the RST_STREAM frame.
> In the failing case, it is read by httpd before it declares the stream closed, and
> the frame contained the CANCEL error code (error=8, err=8).
> In the successful case, it is read by httpd after the stream is declared closed, so
> the log does not show its error code. Either the code is NO_ERROR (0) or it is
> still CANCEL (8) but it is too late for httpd to change the outcome of the stream,
> which it declared error=0.
>
> The cases when the stream ends with a non-zero code on httpd side are
> precisely the ones that result in a 503 error for the client.
>
> The problem looks very time-sensitive. I can only reproduce it with Tomcat
> HTTP/2 logs disabled, without a Java debugger attached to Tomcat, and with
> real network lag.
> I created an automatic test case that uses a browser to download 20 files
> concurrently and repeats every couple of seconds.
>
> - With httpd and Tomcat on two different cloud machines, without Tomcat logs,
> the problem happens after maximum 30 seconds.
> - With httpd and Tomcat on my machine or Tomcat logs/debug enabled, I gave
> up reproducing the problem after 10 hours.
>
> It also appears that the problem is sensitive to the response being a
> 304 with no body.
> If I disable caching, the problem becomes a lot harder to reproduce but still
> possible (I'd say about 20 times less probable).
>
> My guess is that the RST_STREAM frame sent by Tomcat always contains the
> CANCEL code, and there is a race condition with httpd closing the stream.
> When the RST_STREAM arrives before closing, httpd interprets the CANCEL
> code as an error condition and reports that to the client with
> 503 error code.
>
> I looked at the sources for the HTTP/2 connector and found this code around
> line 100 of org.apache.coyote.http2.StreamProcessor.
>
> StreamException se = new StreamException(
> sm.getString("streamProcessor.cancel", stream.getConnectionId(),
> stream.getIdAsString()), Http2Error.CANCEL, stream.getIdAsInt());
> stream.close(se);
>
> This seems to be the only place where the connector is sending a CANCEL
> besides the forced closing of the connection in
> org.apache.coyote.http2.Http2UpgradeHandler.close().
>
> I don't know HTTP/2 deeply enough to say that sending CANCEL here is wrong,
> also because I'm not sure I understand the situation that the connector is
> addressing. However, could it be that the correct code here shold be
> Http2Error.NO_ERROR?
> I recompiled the class with that change, and my test case ran for 12 hours
> without fail.
>
> There is also this bug report for the Go http2 package:
> https://github.com/golang/go/issues/19948
> It looks pretty similar to the problem we see here (except that, in that case, the
> client is directly a browser).
> The folks there conclude that the CANCEL error code is mostly intended for
> clients and that servers should end "useless" streams with NO_ERROR.
> They also quote a section of the RFC
> (https://www.rfc-editor.org/rfc/rfc7540#section-8.1), but I am not sure if it
> applies to the Tomcat case.
>
> What do you think? Could this be a rare Tomcat bug, an httpd bug, or
> something else?
> Please let me know if you need more information.
>
> Thanks in advance for your help.
> Regards.
>
> --
> Lorenzo
>
>
Can you check, whether http compression is enabled on your tomcat?
Connector-Snippet from server.xml would also be fine.
I have similar sporadic issues when compression is enabled.
Maybe we experience the same issue.
Greetings, Thomas
Re[2]: HTTP/2 streams reset by Tomcat are treted as 503 errors by Apache HTTP Server
Posted by Lorenzo Dalla Vecchia <lo...@webratio.com>.
>On 15/12/2022 22:42, Lorenzo Dalla Vecchia wrote:
>>Hello.
>>
>>We are having a random issue in a setup with Tomcat deployed behind Apache httpd. Some HTTP/2 requests proxied to Tomcat by httpd end with a 503 (service unavailable) response to the web browser client.
>>
>>Tomcat version is 9.0.58 running with Java 1.8.0 in a Docker container.
>
>Please update to 9.0.70 and re-test. There are HTTP/2 fixes (particularly in 9.0.68 and 9.0.70) that may help.
>
>Mark
Hello Mark,
I tried with Tomcat 9.0.70 and the problem is the same: RST_STREAM with
error CANCEL (8) followed by Apache httpd responding with a 503 error.
--
Lorenzo
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: HTTP/2 streams reset by Tomcat are treted as 503 errors by Apache HTTP Server
Posted by Mark Thomas <ma...@apache.org>.
On 15/12/2022 22:42, Lorenzo Dalla Vecchia wrote:
> Hello.
>
> We are having a random issue in a setup with Tomcat deployed behind
> Apache httpd. Some HTTP/2 requests proxied to Tomcat by httpd end with a
> 503 (service unavailable) response to the web browser client.
>
> Tomcat version is 9.0.58 running with Java 1.8.0 in a Docker container.
Please update to 9.0.70 and re-test. There are HTTP/2 fixes
(particularly in 9.0.68 and 9.0.70) that may help.
Mark
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org