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
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:
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/apache/tomcat/commit/b738fa6ee0e6789b104e652d95c982827e9753dd
Mark
On 01/08/2022 21:46, Thomas Hoffmann (Speed4Trade GmbH) wrote:
Hello,
I would create a ticket and sum up all the collected information about this
issue, if there are no further suggestions.
Closing a single stream in http2 causes an internal exception in
StreamProcessor which bubbles up in different ways, depending whether
http-compression is active or not.
In the first case it leads to closing the complete TCP connection.
Thanks! Thomas
-Ursprüngliche Nachricht-
Von: Thomas Hoffmann (Speed4Trade GmbH)
Gesendet: Donnerstag, 28. Juli 2022 22:25
An: Tomcat Users List
Betreff: AW: AW: Tomcat 10 with Http2 and compression sometimes closes
connection with Firefox
Hello Mark,
I got a stack trace which also shows the involvement of the gzip filter. I set
the loglevel for the http2-StreamProcessor to get the details.
The stack trace was written when the problem with FF occurred.
FF cl
AW: AW: AW: Tomcat 10 with Http2 and compression sometimes closes connection with Firefox
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:
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
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/apache/tomcat/commit/b738fa6ee0e6789b104e652d95c982827e9753dd
Mark
On 01/08/2022 21:46, Thomas Hoffmann (Speed4Trade GmbH) wrote:
> Hello,
>
> I would create a ticket and sum up all the collected information about this
> issue, if there are no further suggestions.
>
> Closing a single stream in http2 causes an internal exception in
> StreamProcessor which bubbles up in different ways, depending whether
> http-compression is active or not.
> In the first case it leads to closing the complete TCP connection.
>
> Thanks! Thomas
>
>
>> -Ursprüngliche Nachricht-
>> Von: Thomas Hoffmann (Speed4Trade GmbH)
>>
>> Gesendet: Donnerstag, 28. Juli 2022 22:25
>> An: Tomcat Users List
>> Betreff: AW: AW: Tomcat 10 with Http2 and compression sometimes closes
>> connection with Firefox
>>
>> Hello Mark,
>>
>> I got a stack trace which also shows the involvement of the gzip filter. I
>> set
>> the loglevel for the http2-StreamProcessor to get the details.
>> The stack trace was written when the problem with FF occurred.
>> FF closed one single stream in http2 connection and tomcat seemed to have
>> closed the whole TCP connection:
>>
>> 28-Jul-2022 22:16:40.939 FEIN [https-openssl-nio-443-exec-13]
>> org.apache.coyote.http2.StreamProcessor.process Connection [0], Stream
>> [23], An error occurred during processing that was fatal to the connection
>>
AW: AW: Tomcat 10 with Http2 and compression sometimes closes connection with Firefox
Hello, I would create a ticket and sum up all the collected information about this issue, if there are no further suggestions. Closing a single stream in http2 causes an internal exception in StreamProcessor which bubbles up in different ways, depending whether http-compression is active or not. In the first case it leads to closing the complete TCP connection. Thanks! Thomas > -Ursprüngliche Nachricht- > Von: Thomas Hoffmann (Speed4Trade GmbH) > > Gesendet: Donnerstag, 28. Juli 2022 22:25 > An: Tomcat Users List > Betreff: AW: AW: Tomcat 10 with Http2 and compression sometimes closes > connection with Firefox > > Hello Mark, > > I got a stack trace which also shows the involvement of the gzip filter. I set > the loglevel for the http2-StreamProcessor to get the details. > The stack trace was written when the problem with FF occurred. > FF closed one single stream in http2 connection and tomcat seemed to have > closed the whole TCP connection: > > 28-Jul-2022 22:16:40.939 FEIN [https-openssl-nio-443-exec-13] > org.apache.coyote.http2.StreamProcessor.process Connection [0], Stream > [23], An error occurred during processing that was fatal to the connection > java.lang.IllegalStateException: Connection [0], Stream [23], > Unable > to write to stream once it has been closed >at > org.apache.coyote.http2.Stream$StreamOutputBuffer.doWrite(Stream.java: > 880) >at > org.apache.coyote.http11.filters.GzipOutputFilter$FakeOutputStream.write( > GzipOutputFilter.java:158) >at > java.base/java.util.zip.GZIPOutputStream.finish(GZIPOutputStream.java:171 > ) >at > org.apache.coyote.http11.filters.GzipOutputFilter.end(GzipOutputFilter.java > :125) >at > org.apache.coyote.http2.Http2OutputBuffer.end(Http2OutputBuffer.java:71 > ) >at > org.apache.coyote.http2.StreamProcessor.finishResponse(StreamProcessor. > java:209) >at > org.apache.coyote.AbstractProcessor.action(AbstractProcessor.java:386) >at > org.apache.coyote.http2.StreamProcessor.service(StreamProcessor.java:420 > ) >at > org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.ja > va:65) >at > org.apache.coyote.http2.StreamProcessor.process(StreamProcessor.java:73 > ) >at > org.apache.coyote.http2.StreamRunnable.run(StreamRunnable.java:35) >at > java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolE > xecutor.java:1136) >at > java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPool > Executor.java:635) >at > org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThr > ead.java:61) >at > java.base/java.lang.Thread.run(Thread.java:833) > > I hope the stack shows the problem and helps to identify the problem. > Seems like the error handling has changed a bit with Tomcat 10.0.0 M8 with > http2 and is causing the issue. > > Thanks in advance! > Thomas > > > -Ursprüngliche Nachricht- > > Von: Thomas Hoffmann (Speed4Trade GmbH) > > > > Gesendet: Mittwoch, 27. Juli 2022 20:52 > > An: Tomcat Users List > > Betreff: AW: AW: Tomcat 10 with Http2 and compression sometimes closes > > connection with Firefox > > > > Oh... I also discovered an additional message in the wireshark dump. > > Tomcat replied with a goaway packet with the text: > > Connection [22], Stream [19], An error occurred during processing > > that was fatal to the connection > > > > > -Ursprüngliche Nachricht- > > > Von: Thomas Hoffmann (Speed4Trade GmbH) > > > > > > Gesendet: Mittwoch, 27. Juli 2022 20:48 > > > An: Tomcat Users List > > > Betreff: AW: AW: Tomcat 10 with Http2 and compression sometimes > > > closes connection with Firefox > > > > > > Hello Mark, > > > > > > I did some further investigations. I hope I don’t bother you with this > topic. > > > > > > I was trying to narrow down the tomcat version where the problem > > > started to appear. > > > The problem with the interrupted connection started with 10.0.0-M8 > > > With Tomcat 10.0.0-M7 everything works fine. > > > > > > Comparing the sources, there are some (maybe relevant) changes in > > >
AW: AW: Tomcat 10 with Http2 and compression sometimes closes connection with Firefox
Hello Mark, I got a stack trace which also shows the involvement of the gzip filter. I set the loglevel for the http2-StreamProcessor to get the details. The stack trace was written when the problem with FF occurred. FF closed one single stream in http2 connection and tomcat seemed to have closed the whole TCP connection: 28-Jul-2022 22:16:40.939 FEIN [https-openssl-nio-443-exec-13] org.apache.coyote.http2.StreamProcessor.process Connection [0], Stream [23], An error occurred during processing that was fatal to the connection java.lang.IllegalStateException: Connection [0], Stream [23], Unable to write to stream once it has been closed at org.apache.coyote.http2.Stream$StreamOutputBuffer.doWrite(Stream.java:880) at org.apache.coyote.http11.filters.GzipOutputFilter$FakeOutputStream.write(GzipOutputFilter.java:158) at java.base/java.util.zip.GZIPOutputStream.finish(GZIPOutputStream.java:171) at org.apache.coyote.http11.filters.GzipOutputFilter.end(GzipOutputFilter.java:125) at org.apache.coyote.http2.Http2OutputBuffer.end(Http2OutputBuffer.java:71) at org.apache.coyote.http2.StreamProcessor.finishResponse(StreamProcessor.java:209) at org.apache.coyote.AbstractProcessor.action(AbstractProcessor.java:386) at org.apache.coyote.http2.StreamProcessor.service(StreamProcessor.java:420) at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65) at org.apache.coyote.http2.StreamProcessor.process(StreamProcessor.java:73) at org.apache.coyote.http2.StreamRunnable.run(StreamRunnable.java:35) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) at java.base/java.lang.Thread.run(Thread.java:833) I hope the stack shows the problem and helps to identify the problem. Seems like the error handling has changed a bit with Tomcat 10.0.0 M8 with http2 and is causing the issue. Thanks in advance! Thomas > -Ursprüngliche Nachricht- > Von: Thomas Hoffmann (Speed4Trade GmbH) > > Gesendet: Mittwoch, 27. Juli 2022 20:52 > An: Tomcat Users List > Betreff: AW: AW: Tomcat 10 with Http2 and compression sometimes closes > connection with Firefox > > Oh... I also discovered an additional message in the wireshark dump. > Tomcat replied with a goaway packet with the text: > Connection [22], Stream [19], An error occurred during processing that was > fatal to the connection > > > -Ursprüngliche Nachricht- > > Von: Thomas Hoffmann (Speed4Trade GmbH) > > > > Gesendet: Mittwoch, 27. Juli 2022 20:48 > > An: Tomcat Users List > > Betreff: AW: AW: Tomcat 10 with Http2 and compression sometimes closes > > connection with Firefox > > > > Hello Mark, > > > > I did some further investigations. I hope I don’t bother you with this > > topic. > > > > I was trying to narrow down the tomcat version where the problem > > started to appear. > > The problem with the interrupted connection started with 10.0.0-M8 > > With Tomcat 10.0.0-M7 everything works fine. > > > > Comparing the sources, there are some (maybe relevant) changes in the > > org.apache.coyote.http2 package from M7 --> M8: > > - Http2AsynUpgradeHandler > > - Http2UpgradeHandler > > - Stream > > - StreamProcessor > > > > The observed problem was, that the browser (firefox) was sending a > > RST_Stream packet to close a single stream within the http2 protocol > > and tomcat was closing the whole connection instead of closing just > > that stream (wireshark dump would be available). > > > > In Stream.java a new method "doStreamCancel" was introduced (or an old > > method was renamed) with release M8. > > This looks related to the observed problem mentioned above. > > > > Does this information help to take a look again at this problem? > > If I should try something or can assist with testing, just let me know. > > > > Thanks! > > Thomas > > > > > > > > > > > -Ursprüngliche Nachricht- > > > Von: Thomas Hoffmann (Speed4Trade GmbH) > > > > > > Gesendet: Dienstag, 5. Juli 2022 09:59 > >
AW: AW: Tomcat 10 with Http2 and compression sometimes closes connection with Firefox
Oh... I also discovered an additional message in the wireshark dump. Tomcat replied with a goaway packet with the text: Connection [22], Stream [19], An error occurred during processing that was fatal to the connection > -Ursprüngliche Nachricht- > Von: Thomas Hoffmann (Speed4Trade GmbH) > > Gesendet: Mittwoch, 27. Juli 2022 20:48 > An: Tomcat Users List > Betreff: AW: AW: Tomcat 10 with Http2 and compression sometimes closes > connection with Firefox > > Hello Mark, > > I did some further investigations. I hope I don’t bother you with this topic. > > I was trying to narrow down the tomcat version where the problem started > to appear. > The problem with the interrupted connection started with 10.0.0-M8 With > Tomcat 10.0.0-M7 everything works fine. > > Comparing the sources, there are some (maybe relevant) changes in the > org.apache.coyote.http2 package from M7 --> M8: > - Http2AsynUpgradeHandler > - Http2UpgradeHandler > - Stream > - StreamProcessor > > The observed problem was, that the browser (firefox) was sending a > RST_Stream packet to close a single stream within the http2 protocol and > tomcat was closing the whole connection instead of closing just that stream > (wireshark dump would be available). > > In Stream.java a new method "doStreamCancel" was introduced (or an old > method was renamed) with release M8. > This looks related to the observed problem mentioned above. > > Does this information help to take a look again at this problem? > If I should try something or can assist with testing, just let me know. > > Thanks! > Thomas > > > > > > -Ursprüngliche Nachricht- > > Von: Thomas Hoffmann (Speed4Trade GmbH) > > > > Gesendet: Dienstag, 5. Juli 2022 09:59 > > An: Tomcat Users List > > Betreff: AW: AW: Tomcat 10 with Http2 and compression sometimes closes > > connection with Firefox > > > > Hallo Mark, > > > > > -----Ursprüngliche Nachricht- > > > Von: Mark Thomas > > > Gesendet: Montag, 4. Juli 2022 19:37 > > > An: users@tomcat.apache.org > > > Betreff: Re: AW: Tomcat 10 with Http2 and compression sometimes > > > closes connection with Firefox > > > > > > On 30/06/2022 07:40, Mark Thomas wrote: > > > > > > > > > > > > > I think I'm going to need the sample app to investigate this. > > > > > > I have received the sample application and can recreate the issue. > > > > > > Going back to your original summary: > > > > > > > > > 1) Main page was requested by Firefox from Tomcat (GET ...) > > > 2) Tomcat sends the first compressed chunks of data to the browser > > > 3) Firefox reads the first packages and notices, that additional > > > resources are needed (CSS, JS ...) > > > 4) While Tomcat is still sending the main page in chunks, the > > > browser is already requesting additional resources on other channels > > > 5) Firefox is sending a RST_STREAM and closes that last requested > > > stream(s) (dunno why it does request first and then closes the > > > channel) > > > 6) Tomcat is sending a GoAway message to the browser > > > 7) Tomcat stops also sending the main page (on a different channel) > > > > > > > > > I tested with 10.0.x. > > > > > > I don't see the above sequence. > > > > > > I ran the test 4 times, closing the browser between each test > > > > > > When things go wrong it appears that FireFox is re-using the main > > > page > > > (ticket.jsp) from a cache. > > > > > > I see the additional resources being requested and then cancelled. > > > > > > I do not see any GOAWAY messages from Tomcat. > > > > > > I do see a single GOAWAY message from the browser to Tomcat when I > > > close the browser window (as expected). > > > > > > I don't see anything going wrong on the Tomcat side. > > > > > > At the moment, this looks to me like an issue with Firefox rather > > > than with Tomcat. > > > > > > If you can narrow the test case to something that shows Tomcat doing > > > something wrong, then I'd be happy to look at this again. > > > > > > Mark > > > > > > > > > - > > > > Thank you very much for taking a look at it! > > > > I could also see that the browser cache is used sometimes. Sometimes > > the j
AW: AW: Tomcat 10 with Http2 and compression sometimes closes connection with Firefox
Hello Mark, I did some further investigations. I hope I don’t bother you with this topic. I was trying to narrow down the tomcat version where the problem started to appear. The problem with the interrupted connection started with 10.0.0-M8 With Tomcat 10.0.0-M7 everything works fine. Comparing the sources, there are some (maybe relevant) changes in the org.apache.coyote.http2 package from M7 --> M8: - Http2AsynUpgradeHandler - Http2UpgradeHandler - Stream - StreamProcessor The observed problem was, that the browser (firefox) was sending a RST_Stream packet to close a single stream within the http2 protocol and tomcat was closing the whole connection instead of closing just that stream (wireshark dump would be available). In Stream.java a new method "doStreamCancel" was introduced (or an old method was renamed) with release M8. This looks related to the observed problem mentioned above. Does this information help to take a look again at this problem? If I should try something or can assist with testing, just let me know. Thanks! Thomas > -Ursprüngliche Nachricht- > Von: Thomas Hoffmann (Speed4Trade GmbH) > > Gesendet: Dienstag, 5. Juli 2022 09:59 > An: Tomcat Users List > Betreff: AW: AW: Tomcat 10 with Http2 and compression sometimes closes > connection with Firefox > > Hallo Mark, > > > -Ursprüngliche Nachricht- > > Von: Mark Thomas > > Gesendet: Montag, 4. Juli 2022 19:37 > > An: users@tomcat.apache.org > > Betreff: Re: AW: Tomcat 10 with Http2 and compression sometimes closes > > connection with Firefox > > > > On 30/06/2022 07:40, Mark Thomas wrote: > > > > > > > > > I think I'm going to need the sample app to investigate this. > > > > I have received the sample application and can recreate the issue. > > > > Going back to your original summary: > > > > > > 1) Main page was requested by Firefox from Tomcat (GET ...) > > 2) Tomcat sends the first compressed chunks of data to the browser > > 3) Firefox reads the first packages and notices, that additional > > resources are needed (CSS, JS ...) > > 4) While Tomcat is still sending the main page in chunks, the browser > > is already requesting additional resources on other channels > > 5) Firefox is sending a RST_STREAM and closes that last requested > > stream(s) (dunno why it does request first and then closes the > > channel) > > 6) Tomcat is sending a GoAway message to the browser > > 7) Tomcat stops also sending the main page (on a different channel) > > > > > > I tested with 10.0.x. > > > > I don't see the above sequence. > > > > I ran the test 4 times, closing the browser between each test > > > > When things go wrong it appears that FireFox is re-using the main page > > (ticket.jsp) from a cache. > > > > I see the additional resources being requested and then cancelled. > > > > I do not see any GOAWAY messages from Tomcat. > > > > I do see a single GOAWAY message from the browser to Tomcat when I > > close the browser window (as expected). > > > > I don't see anything going wrong on the Tomcat side. > > > > At the moment, this looks to me like an issue with Firefox rather than > > with Tomcat. > > > > If you can narrow the test case to something that shows Tomcat doing > > something wrong, then I'd be happy to look at this again. > > > > Mark > > > > - > > Thank you very much for taking a look at it! > > I could also see that the browser cache is used sometimes. Sometimes the > jsp is requested from the server, sometimes not. > > I did several tests again and the behaviour is not very consistent, thus it's > hard to get a handle on the problem. > I was also thinking about the possibility of a Firefox bug but this wouldn’t > explain that: > 1) It only happens with Tomcat 10.x and doesn’t show up with Tomcat 9.x > 2) Users don’t report any problems with other internet websites (using > Firefox) > > The GoAway seems to be sent from time to time by Tomcat, but not always. > I recorded one session which matches my last description: > https://privfile.com/download.php?fid=62c3ec1170199-MTM2OTM= > I set up another PC for testing, thus the IP addresses (source/target) differ > and can be interpreted more easily. > Maybe the last Capture was not readable without the keyfile, thus I > exported it differently and it should be readable now. > > a) Is the behaviour according to the linked network trace an expected > behaviour? (sending a GoAway after a rst_stream message) > b) Have you been able to reproduce the error with Tomcat 9.x? > > If you have any hints or suggestions, how I could narrow it down, please drop > a line. > I don’t have any big or great ideas at the moment. > > Thank you very much! > Thomas > > > > - > To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org > For additional commands, e-mail: users-h...@tomcat.apache.org
AW: AW: Tomcat 10 with Http2 and compression sometimes closes connection with Firefox
Hallo Mark, > -Ursprüngliche Nachricht- > Von: Mark Thomas > Gesendet: Montag, 4. Juli 2022 19:37 > An: users@tomcat.apache.org > Betreff: Re: AW: Tomcat 10 with Http2 and compression sometimes closes > connection with Firefox > > On 30/06/2022 07:40, Mark Thomas wrote: > > > > > I think I'm going to need the sample app to investigate this. > > I have received the sample application and can recreate the issue. > > Going back to your original summary: > > > 1) Main page was requested by Firefox from Tomcat (GET ...) > 2) Tomcat sends the first compressed chunks of data to the browser > 3) Firefox reads the first packages and notices, that additional resources are > needed (CSS, JS ...) > 4) While Tomcat is still sending the main page in chunks, the browser is > already requesting additional resources on other channels > 5) Firefox is sending a RST_STREAM and closes that last requested > stream(s) (dunno why it does request first and then closes the channel) > 6) Tomcat is sending a GoAway message to the browser > 7) Tomcat stops also sending the main page (on a different channel) > > > I tested with 10.0.x. > > I don't see the above sequence. > > I ran the test 4 times, closing the browser between each test > > When things go wrong it appears that FireFox is re-using the main page > (ticket.jsp) from a cache. > > I see the additional resources being requested and then cancelled. > > I do not see any GOAWAY messages from Tomcat. > > I do see a single GOAWAY message from the browser to Tomcat when I close > the browser window (as expected). > > I don't see anything going wrong on the Tomcat side. > > At the moment, this looks to me like an issue with Firefox rather than with > Tomcat. > > If you can narrow the test case to something that shows Tomcat doing > something wrong, then I'd be happy to look at this again. > > Mark > > - Thank you very much for taking a look at it! I could also see that the browser cache is used sometimes. Sometimes the jsp is requested from the server, sometimes not. I did several tests again and the behaviour is not very consistent, thus it's hard to get a handle on the problem. I was also thinking about the possibility of a Firefox bug but this wouldn’t explain that: 1) It only happens with Tomcat 10.x and doesn’t show up with Tomcat 9.x 2) Users don’t report any problems with other internet websites (using Firefox) The GoAway seems to be sent from time to time by Tomcat, but not always. I recorded one session which matches my last description: https://privfile.com/download.php?fid=62c3ec1170199-MTM2OTM= I set up another PC for testing, thus the IP addresses (source/target) differ and can be interpreted more easily. Maybe the last Capture was not readable without the keyfile, thus I exported it differently and it should be readable now. a) Is the behaviour according to the linked network trace an expected behaviour? (sending a GoAway after a rst_stream message) b) Have you been able to reproduce the error with Tomcat 9.x? If you have any hints or suggestions, how I could narrow it down, please drop a line. I don’t have any big or great ideas at the moment. Thank you very much! Thomas - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: AW: Tomcat 10 with Http2 and compression sometimes closes connection with Firefox
On 30/06/2022 07:40, Mark Thomas wrote: I think I'm going to need the sample app to investigate this. I have received the sample application and can recreate the issue. Going back to your original summary: 1) Main page was requested by Firefox from Tomcat (GET ...) 2) Tomcat sends the first compressed chunks of data to the browser 3) Firefox reads the first packages and notices, that additional resources are needed (CSS, JS ...) 4) While Tomcat is still sending the main page in chunks, the browser is already requesting additional resources on other channels 5) Firefox is sending a RST_STREAM and closes that last requested stream(s) (dunno why it does request first and then closes the channel) 6) Tomcat is sending a GoAway message to the browser 7) Tomcat stops also sending the main page (on a different channel) I tested with 10.0.x. I don't see the above sequence. I ran the test 4 times, closing the browser between each test When things go wrong it appears that FireFox is re-using the main page (ticket.jsp) from a cache. I see the additional resources being requested and then cancelled. I do not see any GOAWAY messages from Tomcat. I do see a single GOAWAY message from the browser to Tomcat when I close the browser window (as expected). I don't see anything going wrong on the Tomcat side. At the moment, this looks to me like an issue with Firefox rather than with Tomcat. If you can narrow the test case to something that shows Tomcat doing something wrong, then I'd be happy to look at this again. Mark - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: AW: Tomcat 10 with Http2 and compression sometimes closes connection with Firefox
On 27/06/2022 21:49, Thomas Hoffmann (Speed4Trade GmbH) wrote: Von: Mark Thomas On 26/06/2022 15:59, Thomas Hoffmann (Speed4Trade GmbH) wrote: Problem: When opening a webpage at a new Tab, Firefox sometimes doesn't load the full page from Tomcat 10 Observation / Circumstances: - Doesn't happen with Tomcat 9 (tested up to 9.0.64) - Problem showed up after upgrading from Tomcat 9.0.56 to 10.0.16 - Tomcat 10.0.16 also showed a stacktrace in the logfile 07-Mar-2022 07:24:01.780 SCHWERWIEGEND [https-openssl-nio-443- exec-21] org.apache.catalina.core.ApplicationDispatcher.invoke Servlet.service() for servlet [jsp] threw exception java.lang.IllegalStateException: Connection [66], Stream [113], Unable to write to stream once it has been closed at org.apache.coyote.http2.Stream$StreamOutputBuffer.doWrite(Stream.java: 843) - The stack is probably related but not the cause of the issue - The stacktrace was not logged any more with Tomcat 10.0.18 (but problem stayed) - The problem only occurs with HTTP2 - It also only occurs when http compression is activated (compression="force" or "on") - a provided debug-log of HTTP2 (loglevel FINE) didn't narrow down the issue This week I found time for digging down into the rabbit hole and also was able to create an almost static application. I did several network traces and it followed the following scheme: 1) Main page was requested by Firefox from Tomcat (GET ...) 2) Tomcat sends the first compressed chunks of data to the browser 3) Firefox reads the first packages and notices, that additional resources are needed (CSS, JS ...) 4) While Tomcat is still sending the main page in chunks, the browser is already requesting additional resources on other channels 5) Firefox is sending a RST_STREAM and closes that last requested stream(s) (dunno why it does request first and then closes the channel) 6) Tomcat is sending a GoAway message to the browser 7) Tomcat stops also sending the main page (on a different channel) Shouldn't tomcat just close the requested stream and continue serving the other stream(s)? Looks like Tomcat got upset and also closed the other stream :) Pcap-file is available at https://privfile.com/download.php?fid=62b8721f9f29a-MTM1NTk= for around 2 weeks. I could also provide an almost static app which relatively often shows this issue (after several trials). As it contains some internal CI and stuff, I could sent it to a personal address. I tested with Win10 and Win11, FF 101, Tomcat 10.0.16 I am currently working on some HTTP/2 test failures that might be relevant. Can you re-test with this additional attribute set on the Connector element: useAsyncIO="false" Hello Mark, despite this setting, the problem can still be reproduced. My connector looked like: Maybe the wireshark trace above can provide some hints or ideas. If I can test something else or if I should send you the sample app, just drop a line. I think I'm going to need the sample app to investigate this. ma...@apache.org Thanks, Mark - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
AW: Tomcat 10 with Http2 and compression sometimes closes connection with Firefox
> -Ursprüngliche Nachricht- > Von: Mark Thomas > Gesendet: Montag, 27. Juni 2022 22:00 > An: users@tomcat.apache.org > Betreff: Re: Tomcat 10 with Http2 and compression sometimes closes > connection with Firefox > > On 26/06/2022 15:59, Thomas Hoffmann (Speed4Trade GmbH) wrote: > > Hello Mark, > > few months ago we already discussed an issue with http2 and > compression. The old title was "Many IllegalStateException when using http2 > protocol". > > I start from scratch so nobody needs to lookup old stuff and first I want to > summarize the old discussion and then add the new gathered information. > > > > Problem: > > When opening a webpage at a new Tab, Firefox sometimes doesn't load > > the full page from Tomcat 10 > > > > Observation / Circumstances: > > - Doesn't happen with Tomcat 9 (tested up to 9.0.64) > > - Problem showed up after upgrading from Tomcat 9.0.56 to 10.0.16 > > - Tomcat 10.0.16 also showed a stacktrace in the logfile > > 07-Mar-2022 07:24:01.780 SCHWERWIEGEND [https-openssl-nio-443- > exec-21] org.apache.catalina.core.ApplicationDispatcher.invoke > Servlet.service() for servlet [jsp] threw exception > > java.lang.IllegalStateException: Connection [66], Stream [113], > Unable to write to stream once it has been closed > > at > org.apache.coyote.http2.Stream$StreamOutputBuffer.doWrite(Stream.java: > 843) > > at > org.apache.coyote.http11.filters.GzipOutputFilter$FakeOutputStream.write( > GzipOutputFilter.java:159) > > at > java.base/java.util.zip.DeflaterOutputStream.deflate(DeflaterOutputStream. > java:252) > > at > java.base/java.util.zip.DeflaterOutputStream.write(DeflaterOutputStream.ja > va:210) > > at > java.base/java.util.zip.GZIPOutputStream.write(GZIPOutputStream.java:148 > ) > > at > org.apache.coyote.http11.filters.GzipOutputFilter.doWrite(GzipOutputFilter. > java:69) > > at > org.apache.coyote.http2.Http2OutputBuffer.doWrite(Http2OutputBuffer.jav > a:59) > > at org.apache.coyote.Response.doWrite(Response.java:625) > > at > org.apache.catalina.connector.OutputBuffer.realWriteBytes(OutputBuffer.ja > va:340) > > at > org.apache.catalina.connector.OutputBuffer.flushByteBuffer(OutputBuffer.j > ava:783) > > at > org.apache.catalina.connector.OutputBuffer.realWriteChars(OutputBuffer.ja > va:453) > > at > org.apache.catalina.connector.OutputBuffer.flushCharBuffer(OutputBuffer.j > ava:788) > > at > org.apache.catalina.connector.OutputBuffer.append(OutputBuffer.java:727) > > at > org.apache.catalina.connector.OutputBuffer.write(OutputBuffer.java:505) > > at > org.apache.catalina.connector.CoyoteWriter.write(CoyoteWriter.java:148) > > at > org.apache.catalina.filters.ExpiresFilter$XPrintWriter.write(ExpiresFilter.java: > 850) > > at > org.apache.jasper.runtime.JspWriterImpl.write(JspWriterImpl.java:275) > > at java.base/java.io.PrintWriter.write(PrintWriter.java:506) > > at > org.apache.jasper.runtime.JspWriterImpl.write(JspWriterImpl.java:275) > > at java.base/java.io.PrintWriter.write(PrintWriter.java:506) > > at > org.apache.jasper.runtime.JspWriterImpl.flushBuffer(JspWriterImpl.java:112 > ) > > at > org.apache.jasper.runtime.JspWriterImpl.flush(JspWriterImpl.java:160) > > at > org.apache.jsp.WEB_002dINF.jsp.businessrelations.ticket_005frelations_inc_ > jsp._jspService(ticket_005frelations_inc_jsp.java:702) > > ... > > - The stack is probably related but not the cause of the issue > > - The stacktrace was not logged any more with Tomcat 10.0.18 (but > > problem stayed) > > - The problem only occurs with HTTP2 > > - It also only occurs when http compression is activated > > (compression="force" or "on") > > - a provided debug-log of HTTP2 (loglevel FINE) didn't narrow down the > > issue > > > > > > This week I found time for digging down into the rabbit hole and also was > able to create an almost static application. > > > > I did several network traces and it followed the following scheme: > > 1) Main page was requested by Firefox from Tomcat (GET ...) > > 2) Tomcat sends the first compressed chunks of data to the browser > > 3) Firefox reads the first packages and notices, that additional > > resources are needed (CSS, JS ...) > > 4) While Tomcat is still sending the main page in chunks, the browser > > is already requesting additional resources on other channels > > 5) Firefox is sending a RST_STREAM and closes that last requested > > stream(s) (dunno why it does request first and then closes the > > channel) > > 6) Tomcat is sending a GoAway message to the browser > > 7) Tomcat stops also sending the main page (on a different channel) > > > > Shouldn't tomcat just close the requested stream and continue serving the > other stream(s)? > > Looks like Tomcat got upset and also clo
