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 <ma...@apache.org>
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 <ma...@apache.org>
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)
<thomas.hoffm...@speed4trade.com.INVALID>
Gesendet: Donnerstag, 28. Juli 2022 22:25
An: Tomcat Users List <users@tomcat.apache.org>
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)
<thomas.hoffm...@speed4trade.com.INVALID>
Gesendet: Mittwoch, 27. Juli 2022 20:52
An: Tomcat Users List <users@tomcat.apache.org>
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)
<thomas.hoffm...@speed4trade.com.INVALID>
Gesendet: Mittwoch, 27. Juli 2022 20:48
An: Tomcat Users List <users@tomcat.apache.org>
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)
<thomas.hoffm...@speed4trade.com.INVALID>
Gesendet: Dienstag, 5. Juli 2022 09:59
An: Tomcat Users List <users@tomcat.apache.org>
Betreff: AW: AW: Tomcat 10 with Http2 and compression sometimes
closes connection with Firefox
Hallo Mark,
-----Ursprüngliche Nachricht-----
Von: Mark Thomas <ma...@apache.org>
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:
<snip/>
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:
<quote>
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) </quote>
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
---------------------------------------------------------------------
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
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org
