-
Notifications
You must be signed in to change notification settings - Fork 4.9k
Commit
This commit does not belong to any branch on this repository, and may belong to a fork outside of the repository.
Track overhead and close connections with excessive overhead
git-svn-id: https://svn.apache.org/repos/asf/tomcat/trunk@1852702 13f79535-47bb-0310-9956-ffa450edef68
- Loading branch information
Showing
2 changed files
with
47 additions
and
0 deletions.
There are no files selected for viewing
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
f9d8c25
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
We are having problems with this commit. The overhead count is disconnecting us from Tomcat after we perform a POST and, as a consequence, we upload a file and perform 5 other PUT from the Front.
We tried to set overheadCountFactor to 0. But that does not solve the problem.
Also, the code looks buggy because the implementation of reduceOverheadCount() decreases one unit but increaseOverheadCount() increases an amount that might not be 1.
This is a link to additional information on stackoverflow about the problem
https://stackoverflow.com/questions/61413934/http2-err-connection-closed-too-much-overhead
We tried to set overheadCountFactor to 0 but that does not solve the problem.
For example in implementation of function startRequestBodyFrame
Here, the overheadCount is set to a number and it is not taking into consideration the value of overheadCountFactor.
Also the method headersContinue
is performing arbitrary changes to overheadCount that might be the cause it to be > 0 and around line 345 of the code there is:
That is causing the disconnection
f9d8c25
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
As expected.
That analysis is incorrect.
I'll provide a longer response there.
As expected.
As intended.
Also as intended.
f9d8c25
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Thank you for you comments!
If the code behaviour is "as expected" (and I don't disagree with that) then it looks to me that something shall else shall be documented further to help people to properly configure tomcat to avoid false positives. Also, I miss an option to made the overheadCount feature optional in case other projects find it difficult to configure.
f9d8c25
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
We get similar behaviour (tomcat 9.0.38 & .43) in a spring boot based app with a react/node frontend. Getting alot of these:
java.lang.IllegalStateException: Connection [59], Stream [39], Unable to write to stream once it has been closed
Meanwhile the client gets zero byte response back.
Wondering how I should configure this?
Full example:
[TOMCAT] [2021-03-11 14:58:00,911] [hostnameremoved] [https-jsse-nio-443-exec-98] [DEBUG] [org.apache.coyote.http2.Stream] [180]: [Connection [59], Stream [57], Exclusive [true], Parent [55], Weight [220]]
[TOMCAT] [2021-03-11 14:58:00,911] [hostnameremoved] [https-jsse-nio-443-exec-98] [DEBUG] [org.apache.coyote.http2.Http2Parser] [451]: [Connection [59], Stream [57], Processing headers payload of size [35]]
[TOMCAT] [2021-03-11 14:58:00,911] [hostnameremoved] [https-jsse-nio-443-exec-98] [DEBUG] [org.apache.coyote.http2.Stream] [333]: [Connection [59], Stream [57], HTTP header [:method], Value [GET]]
[TOMCAT] [2021-03-11 14:58:00,911] [hostnameremoved] [https-jsse-nio-443-exec-98] [DEBUG] [org.apache.coyote.http2.Stream] [333]: [Connection [59], Stream [57], HTTP header [:authority], Value [itest-aaas-configurator.alfalaval.com]]
[TOMCAT] [2021-03-11 14:58:00,911] [hostnameremoved] [https-jsse-nio-443-exec-98] [DEBUG] [org.apache.coyote.http2.Stream] [333]: [Connection [59], Stream [57], HTTP header [:scheme], Value [https]]
[TOMCAT] [2021-03-11 14:58:00,912] [hostnameremoved] [https-jsse-nio-443-exec-98] [DEBUG] [org.apache.coyote.http2.Stream] [333]: [Connection [59], Stream [57], HTTP header [:path], Value [/main.js?5fbd851db70500328233]]
[TOMCAT] [2021-03-11 14:58:00,912] [hostnameremoved] [https-jsse-nio-443-exec-98] [DEBUG] [org.apache.coyote.http2.Stream] [333]: [Connection [59], Stream [57], HTTP header [user-agent], Value [Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/89.0.4389.82 Safari/537.36 Edg/89.0.774.48]]
[TOMCAT] [2021-03-11 14:58:00,912] [hostnameremoved] [https-jsse-nio-443-exec-98] [DEBUG] [org.apache.coyote.http2.Stream] [333]: [Connection [59], Stream [57], HTTP header [accept], Value [/]]
[TOMCAT] [2021-03-11 14:58:00,912] [hostnameremoved] [https-jsse-nio-443-exec-98] [DEBUG] [org.apache.coyote.http2.Stream] [333]: [Connection [59], Stream [57], HTTP header [sec-fetch-site], Value [same-origin]]
[TOMCAT] [2021-03-11 14:58:00,912] [hostnameremoved] [https-jsse-nio-443-exec-98] [DEBUG] [org.apache.coyote.http2.Stream] [333]: [Connection [59], Stream [57], HTTP header [sec-fetch-mode], Value [no-cors]]
[TOMCAT] [2021-03-11 14:58:00,912] [hostnameremoved] [https-jsse-nio-443-exec-98] [DEBUG] [org.apache.coyote.http2.Stream] [333]: [Connection [59], Stream [57], HTTP header [sec-fetch-dest], Value [script]]
[TOMCAT] [2021-03-11 14:58:00,912] [hostnameremoved] [https-jsse-nio-443-exec-98] [DEBUG] [org.apache.coyote.http2.Stream] [333]: [Connection [59], Stream [57], HTTP header [referer], Value [https://itest-aaas-configurator.alfalaval.com/start?sid=3f67f50c-2d5e-4dcf-80f5-400f2c44f37a]]
[TOMCAT] [2021-03-11 14:58:00,912] [hostnameremoved] [https-jsse-nio-443-exec-98] [DEBUG] [org.apache.coyote.http2.Stream] [333]: [Connection [59], Stream [57], HTTP header [accept-encoding], Value [gzip, deflate, br]]
[TOMCAT] [2021-03-11 14:58:00,912] [hostnameremoved] [https-jsse-nio-443-exec-98] [DEBUG] [org.apache.coyote.http2.Stream] [333]: [Connection [59], Stream [57], HTTP header [accept-language], Value [en-US,en;q=0.9]]
[TOMCAT] [2021-03-11 14:58:00,912] [hostnameremoved] [https-jsse-nio-443-exec-98] [DEBUG] [org.apache.coyote.http2.Http2Parser] [546]: [Connection [59], Stream [57], Swallowed [0] bytes]
[TOMCAT] [2021-03-11 14:58:00,913] [hostnameremoved] [https-jsse-nio-443-exec-98] [DEBUG] [org.apache.coyote.http2.StreamStateMachine] [112]: [Connection [59], Stream [57], State changed from [OPEN] to [HALF_CLOSED_REMOTE]]
[TOMCAT] [2021-03-11 14:58:00,913] [hostnameremoved] [https-jsse-nio-443-exec-98] [DEBUG] [org.apache.coyote.http2.Http2UpgradeHandler] [400]: [Exit, Connection [59], SocketState [UPGRADED]]
[TOMCAT] [2021-03-11 14:58:00,989] [hostnameremoved] [https-jsse-nio-443-exec-37] [DEBUG] [org.apache.coyote.http2.Http2UpgradeHandler] [662]: [Connection [59], Stream [39]]
[TOMCAT] [2021-03-11 14:58:00,989] [hostnameremoved] [https-jsse-nio-443-exec-68] [DEBUG] [org.apache.coyote.http2.Stream] [946]: [Connection [59], Stream [41], flushing output with buffer at position [845], writeInProgress [false] and closed [false]]
[TOMCAT] [2021-03-11 14:58:00,989] [hostnameremoved] [https-jsse-nio-443-exec-27] [DEBUG] [org.apache.coyote.http2.Stream] [946]: [Connection [59], Stream [43], flushing output with buffer at position [0], writeInProgress [false] and closed [false]]
[TOMCAT] [2021-03-11 14:58:00,990] [hostnameremoved] [https-jsse-nio-443-exec-3] [DEBUG] [org.apache.coyote.http2.Http2UpgradeHandler] [662]: [Connection [59], Stream [33]]
[TOMCAT] [2021-03-11 14:58:00,990] [hostnameremoved] [https-jsse-nio-443-exec-37] [DEBUG] [org.apache.coyote.http2.Stream] [946]: [Connection [59], Stream [39], flushing output with buffer at position [801], writeInProgress [false] and closed [false]]
[TOMCAT] [2021-03-11 14:58:00,990] [hostnameremoved] [https-jsse-nio-443-exec-68] [DEBUG] [org.apache.coyote.http2.AbstractStream] [143]: [Connection [59], Stream [41], reduce flow control window by [845] to [6290611]]
[TOMCAT] [2021-03-11 14:58:00,990] [hostnameremoved] [https-jsse-nio-443-exec-83] [DEBUG] [org.apache.coyote.http2.Http2UpgradeHandler] [662]: [Connection [59], Stream [35]]
[TOMCAT] [2021-03-11 14:58:00,990] [hostnameremoved] [https-jsse-nio-443-exec-37] [DEBUG] [org.apache.coyote.http2.AbstractStream] [143]: [Connection [59], Stream [39], reduce flow control window by [801] to [6290655]]
[TOMCAT] [2021-03-11 14:58:00,990] [hostnameremoved] [https-jsse-nio-443-exec-27] [DEBUG] [org.apache.coyote.http2.Stream] [946]: [Connection [59], Stream [43], flushing output with buffer at position [0], writeInProgress [false] and closed [true]]
[TOMCAT] [2021-03-11 14:58:00,990] [hostnameremoved] [https-jsse-nio-443-exec-27] [DEBUG] [org.apache.coyote.http2.Http2UpgradeHandler] [201]: [Connection [59], Stream [43], Data length [0]]
[TOMCAT] [2021-03-11 14:58:00,990] [hostnameremoved] [https-jsse-nio-443-exec-14] [DEBUG] [org.apache.coyote.http2.Http2UpgradeHandler] [662]: [Connection [59], Stream [31]]
[TOMCAT] [2021-03-11 14:58:00,990] [hostnameremoved] [https-jsse-nio-443-exec-27] [DEBUG] [org.apache.coyote.http2.StreamProcessor] [75]: [Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@594808ee:org.apache.tomcat.util.net.SecureNioChannel@75f53d2d:java.nio.channels.SocketChannel[connected local=/10.64.108.96:443 remote=/193.194.203.132:64023]], Status in: [OPEN_READ], State out: [CLOSED]]
[TOMCAT] [2021-03-11 14:58:00,990] [hostnameremoved] [https-jsse-nio-443-exec-27] [DEBUG] [org.apache.coyote.http11.Http11NioProtocol] [403]: [Removed processor [org.apache.coyote.http2.StreamProcessor@11237460] from waiting processors]
[TOMCAT] [2021-03-11 14:58:00,990] [hostnameremoved] [https-jsse-nio-443-exec-27] [DEBUG] [org.apache.coyote.http2.Stream] [752]: [Connection [59], Stream [43] has been recycled]
[TOMCAT] [2021-03-11 14:58:00,991] [hostnameremoved] [https-jsse-nio-443-exec-64] [DEBUG] [org.apache.coyote.http2.Http2UpgradeHandler] [662]: [Connection [59], Stream [29]]
[TOMCAT] [2021-03-11 14:58:00,991] [hostnameremoved] [https-jsse-nio-443-exec-18] [DEBUG] [org.apache.coyote.http2.Http2UpgradeHandler] [662]: [Connection [59], Stream [57]]
[TOMCAT] [2021-03-11 14:58:00,991] [hostnameremoved] [https-jsse-nio-443-exec-37] [DEBUG] [org.apache.coyote.http2.StreamProcessor] [398]: [Error during request processing]
java.lang.IllegalStateException: Connection [59], Stream [39], Unable to write to stream once it has been closed
at org.apache.coyote.http2.Stream$StreamOutputBuffer.doWrite(Stream.java:880) ~[tomcat-coyote.jar:9.0.38]
at org.apache.coyote.http11.filters.GzipOutputFilter$FakeOutputStream.write(GzipOutputFilter.java:158) ~[tomcat-coyote.jar:9.0.38]
at java.util.zip.GZIPOutputStream.finish(GZIPOutputStream.java:164) ~[?:1.8.0_275]
at org.apache.coyote.http11.filters.GzipOutputFilter.end(GzipOutputFilter.java:125) ~[tomcat-coyote.jar:9.0.38]
at org.apache.coyote.http2.Http2OutputBuffer.end(Http2OutputBuffer.java:71) ~[tomcat-coyote.jar:9.0.38]
at org.apache.coyote.http2.StreamProcessor.finishResponse(StreamProcessor.java:209) ~[tomcat-coyote.jar:9.0.38]
at org.apache.coyote.AbstractProcessor.action(AbstractProcessor.java:386) ~[tomcat-coyote.jar:9.0.38]
at org.apache.coyote.Response.action(Response.java:209) ~[tomcat-coyote.jar:9.0.38]
at org.apache.catalina.connector.OutputBuffer.close(OutputBuffer.java:261) ~[catalina.jar:9.0.38]
at org.apache.catalina.connector.Response.finishResponse(Response.java:443) ~[catalina.jar:9.0.38]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:374) ~[catalina.jar:9.0.38]
at org.apache.coyote.http2.StreamProcessor.service(StreamProcessor.java:395) [tomcat-coyote.jar:9.0.38]
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65) [tomcat-coyote.jar:9.0.38]
at org.apache.coyote.http2.StreamProcessor.process(StreamProcessor.java:73) [tomcat-coyote.jar:9.0.38]
at org.apache.coyote.http2.StreamRunnable.run(StreamRunnable.java:35) [tomcat-coyote.jar:9.0.38]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_275]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_275]
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-util.jar:9.0.38]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_275]
[TOMCAT] [2021-03-11 14:58:00,990] [hostnameremoved] [https-jsse-nio-443-exec-68] [DEBUG] [org.apache.coyote.http2.StreamProcessor] [398]: [Error during request processing]
java.lang.IllegalStateException: Connection [59], Stream [41], Unable to write to stream once it has been closed
at org.apache.coyote.http2.Stream$StreamOutputBuffer.doWrite(Stream.java:880) ~[tomcat-coyote.jar:9.0.38]
at org.apache.coyote.http11.filters.GzipOutputFilter$FakeOutputStream.write(GzipOutputFilter.java:158) ~[tomcat-coyote.jar:9.0.38]
at java.util.zip.GZIPOutputStream.finish(GZIPOutputStream.java:164) ~[?:1.8.0_275]
at org.apache.coyote.http11.filters.GzipOutputFilter.end(GzipOutputFilter.java:125) ~[tomcat-coyote.jar:9.0.38]
at org.apache.coyote.http2.Http2OutputBuffer.end(Http2OutputBuffer.java:71) ~[tomcat-coyote.jar:9.0.38]
at org.apache.coyote.http2.StreamProcessor.finishResponse(StreamProcessor.java:209) ~[tomcat-coyote.jar:9.0.38]
at org.apache.coyote.AbstractProcessor.action(AbstractProcessor.java:386) ~[tomcat-coyote.jar:9.0.38]
at org.apache.coyote.Response.action(Response.java:209) ~[tomcat-coyote.jar:9.0.38]
at org.apache.catalina.connector.OutputBuffer.close(OutputBuffer.java:261) ~[catalina.jar:9.0.38]
at org.apache.catalina.connector.Response.finishResponse(Response.java:443) ~[catalina.jar:9.0.38]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:374) ~[catalina.jar:9.0.38]
at org.apache.coyote.http2.StreamProcessor.service(StreamProcessor.java:395) [tomcat-coyote.jar:9.0.38]
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65) [tomcat-coyote.jar:9.0.38]
at org.apache.coyote.http2.StreamProcessor.process(StreamProcessor.java:73) [tomcat-coyote.jar:9.0.38]
at org.apache.coyote.http2.StreamRunnable.run(StreamRunnable.java:35) [tomcat-coyote.jar:9.0.38]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_275]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_275]
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-util.jar:9.0.38]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_275]
f9d8c25
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I've debugged some more and I can see this happening before errors. Don't know if it makes sense to you, to me it doesn't:
Line 118605: [TOMCAT] [2021-03-11 21:42:56,345] [sdaddss] [https-jsse-nio-443-exec-73] [DEBUG] [org.apache.coyote.http2.Http2Parser] [546]: [Connection [13], Stream [349], Swallowed [0] bytes]
Line 118608: [TOMCAT] [2021-03-11 21:42:56,345] [sdaddss] [https-jsse-nio-443-exec-73] [DEBUG] [org.apache.coyote.http2.Http2Parser] [622]: [Connection [13], Stream [349], Frame type [DATA], Flags [1], Payload size [75]]
Line 118609: [TOMCAT] [2021-03-11 21:42:56,345] [sdaddss] [https-jsse-nio-443-exec-73] [DEBUG] [org.apache.coyote.http2.Http2Parser] [168]: [Connection [13], Stream [349], Data length [75], Padding length [none]]
Line 118610: [TOMCAT] [2021-03-11 21:42:56,345] [sdaddss] [https-jsse-nio-443-exec-73] [DEBUG] [org.apache.coyote.http2.StreamStateMachine] [115]: [Connection [13], Stream [349], State changed from [OPEN] to [HALF_CLOSED_REMOTE]]
Line 118630: [TOMCAT] [2021-03-11 21:42:59,295] [sdaddss] [https-jsse-nio-443-exec-72] [DEBUG] [org.apache.coyote.http2.Http2Parser] [622]: [Connection [13], Stream [349], Frame type [RST], Flags [0], Payload size [4]]
Line 118631: [TOMCAT] [2021-03-11 21:42:59,295] [sdaddss] [https-jsse-nio-443-exec-72] [DEBUG] [org.apache.coyote.http2.Http2UpgradeHandler] [1624]: [Connection [13], Stream [349], Reset received due to [8]]
Line 118632: [TOMCAT] [2021-03-11 21:42:59,295] [sdaddss] [https-jsse-nio-443-exec-72] [DEBUG] [org.apache.coyote.http2.Stream] [176]: [Connection [13], Stream [349], Reset received due to [8]]
Line 118633: [TOMCAT] [2021-03-11 21:42:59,296] [sdaddss] [https-jsse-nio-443-exec-72] [DEBUG] [org.apache.coyote.http2.StreamStateMachine] [115]: [Connection [13], Stream [349], State changed from [HALF_CLOSED_REMOTE] to [CLOSED_RST_RX]]
Line 118634: [TOMCAT] [2021-03-11 21:42:59,296] [sdaddss] [https-jsse-nio-443-exec-72] [DEBUG] [org.apache.coyote.http2.WindowAllocationManager] [176]: [Connection [13], Stream [349], Waiting type [0], Notify type [3]]
Line 118667: [TOMCAT] [2021-03-11 21:43:01,249] [sdaddss] [https-jsse-nio-443-exec-29] [DEBUG] [org.apache.coyote.http2.Stream] [176]: [Connection [13], Stream [349], Reset received due to [8]]
Line 118668: [TOMCAT] [2021-03-11 21:43:01,249] [sdaddss] [https-jsse-nio-443-exec-29] [DEBUG] [org.apache.coyote.http2.StreamStateMachine] [115]: [Connection [13], Stream [349], State changed from [CLOSED_RST_RX] to [CLOSED_RST_RX]]
Line 118669: [TOMCAT] [2021-03-11 21:43:01,249] [sdaddss] [https-jsse-nio-443-exec-29] [DEBUG] [org.apache.coyote.http2.WindowAllocationManager] [176]: [Connection [13], Stream [349], Waiting type [0], Notify type [3]]
Line 119002: [TOMCAT] [2021-03-11 21:43:03,535] [sdaddss] [https-jsse-nio-443-exec-63] [DEBUG] [org.apache.coyote.http2.Http2UpgradeHandler] [670]: [Connection [13], Stream [349], Writing the headers, EndOfStream [false]]
Line 119003: [TOMCAT] [2021-03-11 21:43:03,542] [sdaddss] [https-jsse-nio-443-exec-63] [DEBUG] [org.apache.coyote.http2.Stream] [871]: [Connection [13], Stream [349], flushing output with buffer at position [8192], writeInProgress [true] and closed [false]]
Line 119004: [TOMCAT] [2021-03-11 21:43:03,542] [sdaddss] [https-jsse-nio-443-exec-63] [DEBUG] [org.apache.coyote.http2.AbstractStream] [151]: [Connection [13], Stream [349], reduce flow control window by [8192] to [6283264]]
Line 119032: [TOMCAT] [2021-03-11 21:43:03,543] [sdaddss] [https-jsse-nio-443-exec-63] [DEBUG] [org.apache.coyote.http2.StreamProcessor] [105]: [Connection [13], Stream [349], An error occurred during processing that was fatal to the connection]
Line 119049: [TOMCAT] [2021-03-11 21:43:03,544] [sdaddss] [https-jsse-nio-443-exec-63] [DEBUG] [org.apache.coyote.http2.Stream] [685]: [Connection [13], Stream [349] has been recycled]