Re: AW: AW: AW: AW: AW: AW: Tomcat 10 with Http2 and compression sometimes closes connection with Firefox
On 21/09/2022 06:48, Thomas Hoffmann (Speed4Trade GmbH) wrote: Hallo Mark, thank you for the explanation. Could you guide me in this case? Shall I set all logging options in tomcat to trace (logging.properties)? Thomas, The level of logging in your most recent off-list trace was perfect. The issue was that the logging did not show the problem you described. The issue you described is that the client resets a single stream and Tomcat then incorrectly closes the entire connection. That in turns triggers stack traces in the logs as the application attempts to write to the other streams in the connection as those streams are now closed. I could not find any evidence of that in the logging you provided. Every stack trace associated with a write to a closed stream was preceded by the client sending a reset frame for that stream. You need to: - recreate the case of Tomcat closing an entire connection in response to the client resetting a single stream - capture HTTP/2 debug logs when this occurs - provide those logs Mark Thanks! Thomas -Ursprüngliche Nachricht- Von: Mark Thomas Gesendet: Dienstag, 20. September 2022 22:28 An: users@tomcat.apache.org Betreff: Re: AW: AW: AW: AW: AW: Tomcat 10 with Http2 and compression sometimes closes connection with Firefox On 20/09/2022 20:22, Thomas Hoffmann (Speed4Trade GmbH) wrote: Hello Mark, -Ursprüngliche Nachricht- Von: Mark Thomas Gesendet: Dienstag, 20. September 2022 20:13 An: users@tomcat.apache.org Betreff: Re: AW: AW: AW: AW: Tomcat 10 with Http2 and compression sometimes closes connection with Firefox On 20/09/2022 17:58, Thomas Hoffmann (Speed4Trade GmbH) wrote: Hello Mark, I will send you the log and access-log to your email address. I am not sure whether it contradicts the observation. For example: - Browser opens a TCP-connection and requests the HTML page. - Tomcat sends single packages with HTML via http2-stream no 1. - Browser requests CSS via http2-stream no 2. - Tomcat serves HTML via stream 1 and css via stream 2. - Browser closes stream 2 which triggers tomcat to close the whole TCP connection including stream 1. - Thus the html stream is also cancelled, leading to a partly visible html page. Thomas, I can find no evidence of the sequence above in the logs you provided. In all the cases I could find, the client first reset the stream sending 0x08 (cancel) as the reason. If you can provide a connection and stream id that exhibits the behaviour you are describing, I'll be happy to look at it. Mark I can record a network trace with wireshark if this helps. The last time I saw that the browser aborts one stream as you described. It shouldn’t close the whole TCP connection, just the stream. I try to get a wireshark dump on weekend. Thomas, A wireshark trace is unlikely to help. I need the Tomcat debug logs to see what is happening internally. You need to provide the debug log trace for an instance where Tomcat closes the entire connection after the client resets a single stream. In all the examples in the previous log, every time there was a stack trace for a stream, it was preceeded by the client resetting that stream - and hence was normal behaviour. Mark - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
AW: AW: AW: AW: AW: AW: Tomcat 10 with Http2 and compression sometimes closes connection with Firefox
Hallo Mark, thank you for the explanation. Could you guide me in this case? Shall I set all logging options in tomcat to trace (logging.properties)? Thanks! Thomas > -Ursprüngliche Nachricht- > Von: Mark Thomas > Gesendet: Dienstag, 20. September 2022 22:28 > An: users@tomcat.apache.org > Betreff: Re: AW: AW: AW: AW: AW: Tomcat 10 with Http2 and compression > sometimes closes connection with Firefox > > On 20/09/2022 20:22, Thomas Hoffmann (Speed4Trade GmbH) wrote: > > Hello Mark, > > > >> -Ursprüngliche Nachricht- > >> Von: Mark Thomas > >> Gesendet: Dienstag, 20. September 2022 20:13 > >> An: users@tomcat.apache.org > >> Betreff: Re: AW: AW: AW: AW: Tomcat 10 with Http2 and compression > >> sometimes closes connection with Firefox > >> > >> On 20/09/2022 17:58, Thomas Hoffmann (Speed4Trade GmbH) wrote: > >>> Hello Mark, > >>> > >>> > >>> I will send you the log and access-log to your email address. > >>> > >>> I am not sure whether it contradicts the observation. > >>> > >>> > >>> For example: > >>> > >>> - Browser opens a TCP-connection and requests the HTML page. > >>> > >>> - Tomcat sends single packages with HTML via http2-stream no 1. > >>> > >>> - Browser requests CSS via http2-stream no 2. > >>> > >>> - Tomcat serves HTML via stream 1 and css via stream 2. > >>> > >>> - Browser closes stream 2 which triggers tomcat to close the whole > >>> TCP > >> connection including stream 1. > >>> > >>> - Thus the html stream is also cancelled, leading to a partly > >>> visible html > >> page. > >> > >> Thomas, > >> > >> I can find no evidence of the sequence above in the logs you provided. > >> In all the cases I could find, the client first reset the stream > >> sending > >> 0x08 (cancel) as the reason. > >> > >> If you can provide a connection and stream id that exhibits the > >> behaviour you are describing, I'll be happy to look at it. > >> > >> Mark > > > > I can record a network trace with wireshark if this helps. > > The last time I saw that the browser aborts one stream as you described. > > It shouldn’t close the whole TCP connection, just the stream. > > I try to get a wireshark dump on weekend. > > Thomas, > > A wireshark trace is unlikely to help. I need the Tomcat debug logs to see > what is happening internally. > > You need to provide the debug log trace for an instance where Tomcat > closes the entire connection after the client resets a single stream. > > In all the examples in the previous log, every time there was a stack trace > for > a stream, it was preceeded by the client resetting that stream > - and hence was normal behaviour. > > Mark > > > - > To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org > For additional commands, e-mail: users-h...@tomcat.apache.org
Re: AW: AW: AW: AW: AW: Tomcat 10 with Http2 and compression sometimes closes connection with Firefox
On 20/09/2022 20:22, Thomas Hoffmann (Speed4Trade GmbH) wrote: Hello Mark, -Ursprüngliche Nachricht- Von: Mark Thomas Gesendet: Dienstag, 20. September 2022 20:13 An: users@tomcat.apache.org Betreff: Re: AW: AW: AW: AW: Tomcat 10 with Http2 and compression sometimes closes connection with Firefox On 20/09/2022 17:58, Thomas Hoffmann (Speed4Trade GmbH) wrote: Hello Mark, I will send you the log and access-log to your email address. I am not sure whether it contradicts the observation. For example: - Browser opens a TCP-connection and requests the HTML page. - Tomcat sends single packages with HTML via http2-stream no 1. - Browser requests CSS via http2-stream no 2. - Tomcat serves HTML via stream 1 and css via stream 2. - Browser closes stream 2 which triggers tomcat to close the whole TCP connection including stream 1. - Thus the html stream is also cancelled, leading to a partly visible html page. Thomas, I can find no evidence of the sequence above in the logs you provided. In all the cases I could find, the client first reset the stream sending 0x08 (cancel) as the reason. If you can provide a connection and stream id that exhibits the behaviour you are describing, I'll be happy to look at it. Mark I can record a network trace with wireshark if this helps. The last time I saw that the browser aborts one stream as you described. It shouldn’t close the whole TCP connection, just the stream. I try to get a wireshark dump on weekend. Thomas, A wireshark trace is unlikely to help. I need the Tomcat debug logs to see what is happening internally. You need to provide the debug log trace for an instance where Tomcat closes the entire connection after the client resets a single stream. In all the examples in the previous log, every time there was a stack trace for a stream, it was preceeded by the client resetting that stream - and hence was normal behaviour. Mark - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
AW: AW: AW: AW: AW: Tomcat 10 with Http2 and compression sometimes closes connection with Firefox
Hello Mark, > -Ursprüngliche Nachricht- > Von: Mark Thomas > Gesendet: Dienstag, 20. September 2022 20:13 > An: users@tomcat.apache.org > Betreff: Re: AW: AW: AW: AW: Tomcat 10 with Http2 and compression > sometimes closes connection with Firefox > > On 20/09/2022 17:58, Thomas Hoffmann (Speed4Trade GmbH) wrote: > > Hello Mark, > > > > > > I will send you the log and access-log to your email address. > > > > I am not sure whether it contradicts the observation. > > > > > > For example: > > > > - Browser opens a TCP-connection and requests the HTML page. > > > > - Tomcat sends single packages with HTML via http2-stream no 1. > > > > - Browser requests CSS via http2-stream no 2. > > > > - Tomcat serves HTML via stream 1 and css via stream 2. > > > > - Browser closes stream 2 which triggers tomcat to close the whole TCP > connection including stream 1. > > > > - Thus the html stream is also cancelled, leading to a partly visible html > page. > > Thomas, > > I can find no evidence of the sequence above in the logs you provided. > In all the cases I could find, the client first reset the stream sending > 0x08 (cancel) as the reason. > > If you can provide a connection and stream id that exhibits the behaviour you > are describing, I'll be happy to look at it. > > Mark I can record a network trace with wireshark if this helps. The last time I saw that the browser aborts one stream as you described. It shouldn’t close the whole TCP connection, just the stream. I try to get a wireshark dump on weekend. > > > > I hope the logs will provide more information. > > > > > > Thanks! Thomas > > > > > > > > Von: Mark Thomas > > Gesendet: Dienstag, 20. September 2022 09:04 > > An: users@tomcat.apache.org > > Betreff: Re: AW: AW: AW: Tomcat 10 with Http2 and compression > > sometimes closes connection with Firefox > > > > On 19/09/2022 19:19, Thomas Hoffmann (Speed4Trade GmbH) wrote: > >> Hello Mark, > >> > >> thanks for the update. > >> > >> The commit looked promising. I tried with Tomcat 10.1 M17 but > unfortunately it didn't help. > >> > >> The partly loaded website is still occuring. > >> > >> > >> Setting http2 logging to fine, I can see the following stack: > > > > That looks like the client reset the stream but that doesn't match > > what you are observing which sounds like Tomcat is truncating the > response. > > > >> 19-Sep-2022 20:07:16.651 FEIN [https-openssl-nio-443-exec-9] > >> org.apache.coyote.AbstractProcessor.setErrorState Error state > >> [CLOSE_NOW] reported while processing request > >> org.apache.coyote.CloseNowException: Connection [1], Stream [23], > >> This stream is not writable > > > > That this is happening with connection 1 is good. It means it should > > be easy to reproduce. Please can you: > > - enable debug logging for HTTP/2 > > - restart Tomcat > > - trigger this problem > > - provide the full debug logs > > > > I want to trace what is happening on the HTTP/2 connection leading up > > to the truncation occurring. > > > > Thanks, > > > > Mark > > > > > >> at org.apache.coyote.http2.Stream.doStreamCancel(Stream.java:258) > >> at > >> > org.apache.coyote.http2.Http2UpgradeHandler.reserveWindowSize(Http2U > p > >> gradeHandler.java:919) at > >> > org.apache.coyote.http2.Stream$StreamOutputBuffer.flush(Stream.java:9 > >> 45) at > >> > org.apache.coyote.http2.Stream$StreamOutputBuffer.flush(Stream.java:8 > >> 91) at > >> > org.apache.coyote.http2.Stream$StreamOutputBuffer.end(Stream.java:990 > >> ) at > >> org.apache.coyote.http11.filters.GzipOutputFilter.end(GzipOutputFilte > >> r.java:128) at > >> org.apache.coyote.http2.Http2OutputBuffer.end(Http2OutputBuffer.java: > >> 71) at > >> > org.apache.coyote.http2.StreamProcessor.finishResponse(StreamProcesso > >> r.java:230) at > >> org.apache.coyote.AbstractProcessor.action(AbstractProcessor.java:391 > >> ) at org.apache.coyote.Response.action(Response.java:210) > >> at > >> org.apache.catalina.connector.OutputBuffer.close(OutputBuffer.java:25 > >> 8) at > >> org.apache.catalina.connector.Response.finishResponse(Response.java:4 > >> 18) at > >> org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.jav > &g
Re: AW: AW: AW: AW: Tomcat 10 with Http2 and compression sometimes closes connection with Firefox
On 20/09/2022 17:58, Thomas Hoffmann (Speed4Trade GmbH) wrote:
Hello Mark,
I will send you the log and access-log to your email address.
I am not sure whether it contradicts the observation.
For example:
- Browser opens a TCP-connection and requests the HTML page.
- Tomcat sends single packages with HTML via http2-stream no 1.
- Browser requests CSS via http2-stream no 2.
- Tomcat serves HTML via stream 1 and css via stream 2.
- Browser closes stream 2 which triggers tomcat to close the whole TCP
connection including stream 1.
- Thus the html stream is also cancelled, leading to a partly visible html page.
Thomas,
I can find no evidence of the sequence above in the logs you provided.
In all the cases I could find, the client first reset the stream sending
0x08 (cancel) as the reason.
If you can provide a connection and stream id that exhibits the
behaviour you are describing, I'll be happy to look at it.
Mark
I hope the logs will provide more information.
Thanks! Thomas
Von: Mark Thomas
Gesendet: Dienstag, 20. September 2022 09:04
An: users@tomcat.apache.org
Betreff: Re: AW: AW: AW: Tomcat 10 with Http2 and compression sometimes closes
connection with Firefox
On 19/09/2022 19:19, Thomas Hoffmann (Speed4Trade GmbH) wrote:
Hello Mark,
thanks for the update.
The commit looked promising. I tried with Tomcat 10.1 M17 but unfortunately it
didn't help.
The partly loaded website is still occuring.
Setting http2 logging to fine, I can see the following stack:
That looks like the client reset the stream but that doesn't match what
you are observing which sounds like Tomcat is truncating the response.
19-Sep-2022 20:07:16.651 FEIN [https-openssl-nio-443-exec-9]
org.apache.coyote.AbstractProcessor.setErrorState Error state [CLOSE_NOW]
reported while processing request
org.apache.coyote.CloseNowException: Connection [1], Stream [23], This stream
is not writable
That this is happening with connection 1 is good. It means it should be
easy to reproduce. Please can you:
- enable debug logging for HTTP/2
- restart Tomcat
- trigger this problem
- provide the full debug logs
I want to trace what is happening on the HTTP/2 connection leading up to
the truncation occurring.
Thanks,
Mark
at org.apache.coyote.http2.Stream.doStreamCancel(Stream.java:258)
at
org.apache.coyote.http2.Http2UpgradeHandler.reserveWindowSize(Http2UpgradeHandler.java:919)
at org.apache.coyote.http2.Stream$StreamOutputBuffer.flush(Stream.java:945)
at org.apache.coyote.http2.Stream$StreamOutputBuffer.flush(Stream.java:891)
at org.apache.coyote.http2.Stream$StreamOutputBuffer.end(Stream.java:990)
at
org.apache.coyote.http11.filters.GzipOutputFilter.end(GzipOutputFilter.java:128)
at org.apache.coyote.http2.Http2OutputBuffer.end(Http2OutputBuffer.java:71)
at
org.apache.coyote.http2.StreamProcessor.finishResponse(StreamProcessor.java:230)
at org.apache.coyote.AbstractProcessor.action(AbstractProcessor.java:391)
at org.apache.coyote.Response.action(Response.java:210)
at org.apache.catalina.connector.OutputBuffer.close(OutputBuffer.java:258)
at org.apache.catalina.connector.Response.finishResponse(Response.java:418)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:388)
at org.apache.coyote.http2.StreamProcessor.service(StreamProcessor.java:426)
at
org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
at org.apache.coyote.http2.StreamProcessor.process(StreamProcessor.java:87)
at org.apache.coyote.http2.StreamRunnable.run(StreamRunnable.java:35)
at
org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
at
org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
at
org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.base/java.lang.Thread.run(Thread.java:833)
Caused by: org.apache.coyote.http2.StreamException: Connection [1], Stream
[23], This stream is not writable
at org.apache.coyote.http2.Stream.doStreamCancel(Stream.java:250)
... 20 more
Looks like the Exception bubbles up from the last line of tthis method:
void doStreamCancel(String msg, Http2Error error) throws
CloseNowException {
StreamException se = new StreamException(msg, error, getIdAsInt());
// Prevent the application making further writes
streamOutputBuffer.closed = true;
// Prevent Tomcat's error handling trying to write
coyoteResponse.setError();
coyoteResponse.setErrorReported();
// Trigger a reset once control returns to Tomcat
streamOutputBuffer.reset = se;
throw new CloseNowException(msg, se);
}
The CloseNowException() bubbles up without being caught maybe (?)
Stream.write(...) is not contained here.
Greetings, Thoas
Von: Mark Thomas
Gesendet: Montag, 19. September 2022 19:22
An: users@tomcat.apache.or
AW: AW: AW: AW: Tomcat 10 with Http2 and compression sometimes closes connection with Firefox
Hello Mark,
I will send you the log and access-log to your email address.
I am not sure whether it contradicts the observation.
For example:
- Browser opens a TCP-connection and requests the HTML page.
- Tomcat sends single packages with HTML via http2-stream no 1.
- Browser requests CSS via http2-stream no 2.
- Tomcat serves HTML via stream 1 and css via stream 2.
- Browser closes stream 2 which triggers tomcat to close the whole TCP
connection including stream 1.
- Thus the html stream is also cancelled, leading to a partly visible html page.
I hope the logs will provide more information.
Thanks! Thomas
Von: Mark Thomas
Gesendet: Dienstag, 20. September 2022 09:04
An: users@tomcat.apache.org
Betreff: Re: AW: AW: AW: Tomcat 10 with Http2 and compression sometimes closes
connection with Firefox
On 19/09/2022 19:19, Thomas Hoffmann (Speed4Trade GmbH) wrote:
> Hello Mark,
>
> thanks for the update.
>
> The commit looked promising. I tried with Tomcat 10.1 M17 but unfortunately
> it didn't help.
>
> The partly loaded website is still occuring.
>
>
> Setting http2 logging to fine, I can see the following stack:
That looks like the client reset the stream but that doesn't match what
you are observing which sounds like Tomcat is truncating the response.
> 19-Sep-2022 20:07:16.651 FEIN [https-openssl-nio-443-exec-9]
> org.apache.coyote.AbstractProcessor.setErrorState Error state [CLOSE_NOW]
> reported while processing request
> org.apache.coyote.CloseNowException: Connection [1], Stream [23], This stream
> is not writable
That this is happening with connection 1 is good. It means it should be
easy to reproduce. Please can you:
- enable debug logging for HTTP/2
- restart Tomcat
- trigger this problem
- provide the full debug logs
I want to trace what is happening on the HTTP/2 connection leading up to
the truncation occurring.
Thanks,
Mark
> at org.apache.coyote.http2.Stream.doStreamCancel(Stream.java:258)
> at
> org.apache.coyote.http2.Http2UpgradeHandler.reserveWindowSize(Http2UpgradeHandler.java:919)
> at org.apache.coyote.http2.Stream$StreamOutputBuffer.flush(Stream.java:945)
> at org.apache.coyote.http2.Stream$StreamOutputBuffer.flush(Stream.java:891)
> at org.apache.coyote.http2.Stream$StreamOutputBuffer.end(Stream.java:990)
> at
> org.apache.coyote.http11.filters.GzipOutputFilter.end(GzipOutputFilter.java:128)
> at org.apache.coyote.http2.Http2OutputBuffer.end(Http2OutputBuffer.java:71)
> at
> org.apache.coyote.http2.StreamProcessor.finishResponse(StreamProcessor.java:230)
> at org.apache.coyote.AbstractProcessor.action(AbstractProcessor.java:391)
> at org.apache.coyote.Response.action(Response.java:210)
> at org.apache.catalina.connector.OutputBuffer.close(OutputBuffer.java:258)
> at org.apache.catalina.connector.Response.finishResponse(Response.java:418)
> at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:388)
> at org.apache.coyote.http2.StreamProcessor.service(StreamProcessor.java:426)
> at
> org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
> at org.apache.coyote.http2.StreamProcessor.process(StreamProcessor.java:87)
> at org.apache.coyote.http2.StreamRunnable.run(StreamRunnable.java:35)
> at
> org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
> at
> org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
> at
> org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
> at java.base/java.lang.Thread.run(Thread.java:833)
> Caused by: org.apache.coyote.http2.StreamException: Connection [1], Stream
> [23], This stream is not writable
> at org.apache.coyote.http2.Stream.doStreamCancel(Stream.java:250)
> ... 20 more
>
>
>
> Looks like the Exception bubbles up from the last line of tthis method:
>
> void doStreamCancel(String msg, Http2Error error) throws
> CloseNowException {
> StreamException se = new StreamException(msg, error, getIdAsInt());
> // Prevent the application making further writes
> streamOutputBuffer.closed = true;
> // Prevent Tomcat's error handling trying to write
> coyoteResponse.setError();
> coyoteResponse.setErrorReported();
> // Trigger a reset once control returns to Tomcat
> streamOutputBuffer.reset = se;
> throw new CloseNowException(msg, se);
> }
>
> The CloseNowException() bubbles up without being caught maybe (?)
> Stream.write(...) is not contained here.
>
> Greetings, Thoas
>
>
> Von: Mark Thomas
> Gesendet: Montag, 19. September 2022 19:22
> An: users@tomcat.apache.org
> Betreff: Re: AW: AW: Tomcat 10 with Http2 and compression sometimes closes
> connection with Firefox
>
> Thomas,
>
> Please update to the latest 10.1.x release and re-test. There is what
> looks like a fix for this issue in 10.1.0-M12:
>
> https://github.com/a
