I am logging the time to serve a request using %D (or %{us}T) in a log format. Since upgrading from 2.4.55 to 2.4.56, I see a lot of requests logged as taking over 10 seconds (and up to 35 seconds) to process. All my traffic is reverse proxied to other applications over HTTP, ie I am using HTTPD for SSL termination and request routing. For example, one server recorded 100 requests all day requiring >10s yesterday, but has already recorded >4500 in 5 hours since installing 2.4.56. I don't see any difference when looking at the timing in the browser network pane. The affected traffic seems to be a mix of HTTP/1.1 and 2.0. I have keepalives on with a KeepAliveTimeout of 35. I wonder if it is counting time until the connection is closed now?
I've experimented a bit with h2c, a straightforward HTTP/2 command-line client. This tool allows you to open a persistent connection (connect), send requests, and then close it (disconnect). I ran some tests using both the new Apache 2.4.57 and the older 2.4.54. Interestingly, there seems to have been a shift in the login behavior. Here's how I tested: I opened an HTTP/2 connection (connect), sent GET requests to a script that echoes and induces sleep between requests, and finally closed the connection (disconnect). With the older Apache version, every request within a connection was logged immediately, and the service time (%D) in access_log was approximately 1.5ms. However, with the new Apache, each request was logged either upon disconnect or when the next request was submitted within the same connection. Here, the service time (%D) in access_log included both the service time and idle time between the previous and the current request, or to disconnect. Notably, the timestamp of the request submission (%t) was logged correctly. Moreover, in a connect/get/disconnect scenario, the older Apache version logged %D at around 1.5ms, while the new Apache version logged a notably higher time of about 6.5ms.
Thanks for the report. Will look into the issue. From what I cant tell, the new mod_http2 does not seem to cleanup finished requests as timely as before. And the cleanup causes the access log to be written and the time counted. It seems cleanup sometimes happens after the *next* activity on the connection, which then gives overlong run times and late access logging.
Opened <https://github.com/icing/mod_h2/issues/253> for this.
Please see <https://github.com/icing/mod_h2/pull/254> for a fix. I reproduced the wrong behaviour in a test case. Hope this works in your environments too. Could you verify? Thanks.
Fixed in r1909769 and proposed to backport to 2.4.x
With changes from https://github.com/icing/mod_h2/pull/254 logging is working as expected for me.
Fine for me also.
Thanks for reporting back!