Hello Mark,
> -----Ursprüngliche Nachricht-----
> Von: Mark Thomas <ma...@apache.org>
> 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 <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(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
> >> a:388) at
> >> org.apache.coyote.http2.StreamProcessor.service(StreamProcessor.java:
> >> 426) at
> >> org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLig
> >> ht.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(ThreadPoo
> >> lExecutor.java:1191) at
> >>
> org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPo
> >> olExecutor.java:659) at
> >>
> org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskTh
> >> read.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/b738fa6ee0e6789b104e652d95
> c98
> >> 2827e9753dd
> >>
> >> 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.ja
> >>>> va:171
> >>>> )
> >>>> at
> >>>> org.apache.coyote.http11.filters.GzipOutputFilter.end(GzipOutputFil
> >>>> ter.java
> >>>> :125)
> >>>> at
> >>>>
> org.apache.coyote.http2.Http2OutputBuffer.end(Http2OutputBuffer.jav
> >>>> a: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.jav
> >>>> a:420
> >>>> )
> >>>> at
> >>>> org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorL
> >>>> ight.ja
> >>>> va:65)
> >>>> at
> >>>>
> org.apache.coyote.http2.StreamProcessor.process(StreamProcessor.jav
> >>>> a:73
> >>>> )
> >>>> at
> >>>>
> org.apache.coyote.http2.StreamRunnable.run(StreamRunnable.java:35)
> >>>> at
> >>>> java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadP
> >>>> oolE
> >>>> xecutor.java:1136)
> >>>> at
> >>>> java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Thread
> >>>> Pool
> >>>> Executor.java:635)
> >>>> at
> >>>>
> org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(Task
> >>>> Thr
> >>>> 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
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org
