Bug 63223 - org.apache.coyote.http2.Http2UpgradeHandler.pruneClosedStreams
Summary: org.apache.coyote.http2.Http2UpgradeHandler.pruneClosedStreams
Status: RESOLVED FIXED
Alias: None
Product: Tomcat 9
Classification: Unclassified
Component: Catalina (show other bugs)
Version: 9.0.14
Hardware: PC Linux
: P2 blocker (vote)
Target Milestone: -----
Assignee: Tomcat Developers Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2019-03-03 09:30 UTC by TehKantz
Modified: 2019-03-07 11:55 UTC (History)
0 users



Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description TehKantz 2019-03-03 09:30:59 UTC
We have a blocking potential bug occurring on our web server, 
Once in a while the server get into blocking state not accepting new connections. 

The logs are showing the following errors every few milliseconds: 

19-Feb-2019 06:09:10.455 WARNING [https-openssl-apr-8443-exec-435] org.apache.coyote.http2.Http2UpgradeHandler.pruneClosedStreams Connection [3442] Failed to fully prune the connection because streams were active / used in the priority tree. There are [7] too many streams
19-Feb-2019 06:09:10.455 WARNING [https-openssl-apr-8443-exec-435] org.apache.coyote.http2.Http2UpgradeHandler.pruneClosedStreams Connection [3442] Failed to fully prune the connection because streams were active / used in the priority tree. There are [7] too many streams
19-Feb-2019 06:09:10.456 WARNING [https-openssl-apr-8443-exec-435] org.apache.coyote.http2.Http2UpgradeHandler.pruneClosedStreams Connection [3442] Failed to fully prune the connection because streams were active / used in the priority tree. There are [7] too many streams
19-Feb-2019 06:09:10.457 WARNING [https-openssl-apr-8443-exec-435] org.apache.coyote.http2.Http2UpgradeHandler.pruneClosedStreams Connection [3442] Failed to fully prune the connection because streams were active / used in the priority tree. There are [7] too many streams
19-Feb-2019 06:09:10.457 WARNING [https-openssl-apr-8443-exec-435] org.apache.coyote.http2.Http2UpgradeHandler.pruneClosedStreams Connection [3442] Failed to fully prune the connection because streams were active / used in the priority tree. There are [7] too many streams


It may stuck in this state for a random of time in minutes, once it was stuck like that for over an hour. when I restarted the server the errors disappeared.
Comment 1 Mark Thomas 2019-03-04 11:32:14 UTC
That behaviour looks to be correct. The client for Connection 3442 has exceeded the maximum number of open streams per connection so subsequent requests to open a new stream are rejected.

Please follow the up on the users@ mailing list where you can provide more details about the use case and potential configuration changes can be discussed.

If further investigation does identify a Tomcat bug then this issue can be re-opened.
Comment 2 TehKantz 2019-03-04 12:20:31 UTC
This is is the configuration used for the ssl connection as part of the tomcat server.xml template:

    <Connector port="8443" protocol="org.apache.coyote.http11.Http11AprProtocol"
               maxThreads="150" SSLEnabled="true" >
        <UpgradeProtocol className="org.apache.coyote.http2.Http2Protocol" />
        <SSLHostConfig>
            <Certificate certificateKeyFile="conf/privkey.pem"
                         certificateFile="conf/cert.pem"
                         certificateChainFile="conf/chain.pem"
                         type="RSA" />
        </SSLHostConfig>
    </Connector>


I am not sure that the behavior is correct. 
when it happens, the server gets into a blocking state rejecting requests from all users across all WebApps, and the only way to stop it is killing the process.  
It Doesn't seems to be a desired behaviour, on top of that the logs created from this are insane it blocks the IO of the server make it even harder to shutdown the process
Comment 3 Mark Thomas 2019-03-05 20:26:28 UTC
We can look at reducing the logging frequency but the remainder of this issue belongs on the users@ list for now.
Comment 4 Mark Thomas 2019-03-07 11:55:57 UTC
Looking at the code, those messages should never appear if everything is being tracked correctly. I've found a couple of places where pushed streams weren't being properly tracked and I've fixed them. I've also improved the error message so, if it should be logged, it is clearer what is happening.

I'm still a little concerned at the rate the messages were being logged. The most they can appear - even if the tracking has gone wrong - is once every 10 new streams created for a connection. The rate you were seeing the messages suggests a very high rate of stream creation. The access log should be able to confirm this.

Should you still see this in 9.0.17 the improved log messages will help. The other thing that would be useful is a thread dump. ideally three thread dumps taken one after another.

Fixed in:
- trunk for 9.0.17 onwards
- 8.5.x for 8.5.39 onwards