mod_http2 not honouring KeepAliveTimeout since 1.10.16

[tunetheweb]

mod_http2 is closing HTTP/2 sessions after 1 second of timeout and this appears to have started since 1.10.16

To repeat:

• Install mod_http 1.10.16 or later
• Set a KeepAliveTime value (the default of 5 seconds in extra/httpd-default.conf is fine)
• Open Chrome and go to chrome://net-internals/#events&q=type:HTTP2_SESSION%20is:active
• Visit your site in another tab and click on that session.
• Note that approximately 1000 milliseconds (1 second) after the last frame is received, Chrome receives a timeout go away frame - no matter what your KeepAliveTime value is set to:

t=150102 [st= 675]    HTTP2_SESSION_UPDATE_RECV_WINDOW
                      --> delta = 311
                      --> window_size = 15728640
t=151055 [st=1628]    HTTP2_SESSION_RECV_GOAWAY
                      --> active_streams = 0
                      --> debug_data = "timeout"
                      --> error_code = "0 (NO_ERROR)"
                      --> last_accepted_stream_id = 9
                      --> unclaimed_streams = 0
t=151055 [st=1628]    HTTP2_SESSION_CLOSE
                      --> description = "Finished going away"
                      --> net_error = 0 (?)
t=151055 [st=1628]    HTTP2_SESSION_POOL_REMOVE_SESSION
t=151055 [st=1628] -HTTP2_SESSION

• Install mod_http2 1.10.15 and repeat the test.
• Note it now takes approximately 5 seconds (or whatever KeepAliveTimeout you have set) to receive the GOAWAY timeout frame:

t=434838 [st= 837]    HTTP2_SESSION_UPDATE_RECV_WINDOW
                      --> delta = 311
                      --> window_size = 15728640
t=440849 [st=6848]    HTTP2_SESSION_RECV_GOAWAY
                      --> active_streams = 0
                      --> debug_data = "timeout"
                      --> error_code = "0 (NO_ERROR)"
                      --> last_accepted_stream_id = 9
                      --> unclaimed_streams = 0
t=440849 [st=6848]    HTTP2_SESSION_CLOSE
                      --> description = "Finished going away"
                      --> net_error = 0 (?)
t=440850 [st=6849]    HTTP2_SESSION_POOL_REMOVE_SESSION
t=440850 [st=6849] -HTTP2_SESSION

[rotate4all]

It's not just in Chrome, saw the same behavior in Firefox, Opera and Edge as well.
So it's definitely a bug due to which I had to disable HTTP/2 until a fix is issued.

[tunetheweb]

Agreed. It's a mod_http2 bug, it's just easier to verify in Chrome (or Opera) thanks to the net-internals page. It's not ideal I admit, but at least it's not on most page loads (as they typically don't leave over a second between requesting a resource) - it's just on browsing around the site. But still, needs to be fixed. You can always roll back to 1.10.15 until it is fixed.

[icing]

That was a change httpd did in an attempt to clean up mpm_event connection handling and it did backfire for HTTP/2. Sorry about that. Talking to the persons involved about how we can fix this.

[icing]

@bazzadp, I assume you can compile yourself. Could you check if this patch (applies to 2.4.x also) brings back the correct behaviour for you too?

[tunetheweb]

Works for me. Tested on 2.4.33 on Centos 7.4

[icing]

Thanks for verifying! Released as v1.10.20.