http2 request log in accurate $request_time ?

[Maxim Dounin]

Hello!

On Thu, Jan 23, 2020 at 01:37:42AM -0500, xt3627216 wrote:

[...]

> > If stream->queued is true, this means that there are unsent frames 
> > in the stream, and the request is not yet complete.  As such, 
> > queue "larger" $request_time is correct, as it is expected to 
> > account sending the response to client as well.
> 
> thanks Maxim, I see your point.
> 
> Anyway, I found some http2 requests have large $request_time in my logs(
> which is unreasonable large),  will you be sure that the $request_time in
> http2 protocol 
> compute correctly. ?  the value of $request_time denote the actual time of 
> RT.  
> 
> Will the multiplexing mechanism  affect  “mis-computing" the value of RT. 

The $request_time variable is defined to show time of the request, 
since the first byte received till the actual logging.  That is, 
it is certainly correct.

The question is why you are seeing "unreasonable large" values in 
logs.  This may be due to client behaviour, as HTTP/2 allows 
clients to easily delay individual streams using the flow control 
mechanism, or due to a bug in nginx which might fail to properly 
send the stream for some reason.

Either way, given that nginx 1.9.5 is the first nginx version 
where expirimental support for HTTP/2 was introduced, it is a 
really bad idea to use nginx 1.9.5 with HTTP/2 enabled.  There 
were a lot of bug fixes since then, including security ones.  If 
you want to use HTTP/2, consider upgrading to a modern nginx 
version, such as nginx 1.17.8 or 1.16.1.

-- 
Maxim Dounin
http://mdounin.ru/