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 <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
