AW: HTTP/2 streams reset by Tomcat are treted as 503 errors by Apache HTTP Server
Hello Lorenzo, > -Ursprüngliche Nachricht- > Von: Lorenzo Dalla Vecchia > 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 htt
Re[2]: HTTP/2 streams reset by Tomcat are treted as 503 errors by Apache HTTP Server
Hello Lorenzo, -Ursprüngliche Nachricht- Von: Lorenzo Dalla Vecchia 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
Re: HTTP/2 streams reset by Tomcat are treted as 503 errors by Apache HTTP Server
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-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re[2]: HTTP/2 streams reset by Tomcat are treted as 503 errors by Apache HTTP Server
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-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: HTTP/2 streams reset by Tomcat are treted as 503 errors by Apache HTTP Server
On 15/12/2022 22:42, Lorenzo Dalla Vecchia wrote:
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-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org
Re[2]: HTTP/2 streams reset by Tomcat are treted as 503 errors by Apache HTTP Server
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-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
