http2 request log in accurate $request_time ?

classic Classic list List threaded Threaded
6 messages Options
Reply | Threaded
Open this post in threaded view
|

http2 request log in accurate $request_time ?

Olaf van der Spek
nginx version: nginx-1.9.5


hi,nginx compute $request_time   in log phase, which is in    

ngx_http_free_request (r) ->  ngx_http_log_request(r) -> log_handler(r)


but in http2 world, I see  every request closed through
ngx_http_v2_close_stream(stream, rc)

in ngx_http_v2_close_stream    have code below:


```
void
ngx_http_v2_close_stream(ngx_http_v2_stream_t *stream, ngx_int_t rc)
{
    ngx_event_t               *ev;
    ngx_connection_t          *fc;
    ngx_http_v2_node_t        *node;
    ngx_http_v2_connection_t  *h2c;

    h2c = stream->connection;
    node = stream->node;

    ngx_log_debug3(NGX_LOG_DEBUG_HTTP, h2c->connection->log, 0,
                   "http2 close stream %ui, queued %ui, processing %ui",
                   node->id, stream->queued, h2c->processing);
   
    fc = stream->request->connection;
   
    if (stream->queued) {
        fc->write->handler = ngx_http_v2_close_stream_handler;              
   
        return;
    }

    if (!stream->out_closed) {
        if (ngx_http_v2_send_rst_stream(h2c, node->id,
                                        NGX_HTTP_V2_INTERNAL_ERROR)
            != NGX_OK)
        {
            h2c->connection->error = 1;
        }
    }
   
    node->stream = NULL;
           
    ngx_queue_insert_tail(&h2c->closed, &node->reuse);
    h2c->closed_nodes++;
       
    ngx_http_free_request(stream->request, rc);
    xxx
}
```
if  stream->queued  is true,   then ngx_http_free_request will not be called
immediately, which will result $request_time larger then real request time?



any body can affirm this ?

Posted at Nginx Forum: https://forum.nginx.org/read.php?2,286797,286797#msg-286797

_______________________________________________
nginx mailing list
[hidden email]
http://mailman.nginx.org/mailman/listinfo/nginx
Reply | Threaded
Open this post in threaded view
|

Re: http2 request log in accurate $request_time ?

Olaf van der Spek
In  our production env, I found that $request_time is very large under
http2 protocol.      


by the way, some requests, not every one.

Posted at Nginx Forum: https://forum.nginx.org/read.php?2,286797,286798#msg-286798

_______________________________________________
nginx mailing list
[hidden email]
http://mailman.nginx.org/mailman/listinfo/nginx
Reply | Threaded
Open this post in threaded view
|

Re: http2 request log in accurate $request_time ?

J.R.
In reply to this post by Olaf van der Spek
> nginx version: nginx-1.9.5

Have you tried updating to a newer version of nginx? The 1.9 branch is
probably 5 years old...

It looks like the code you mention has changed somewhat, though I
don't know if it has any effect on $request_time.

https://github.com/nginx/nginx/blob/60f648f035fa05667b9ccbbea1b3a60d83534d9a/src/http/v2/ngx_http_v2.c
_______________________________________________
nginx mailing list
[hidden email]
http://mailman.nginx.org/mailman/listinfo/nginx
Reply | Threaded
Open this post in threaded view
|

Re: http2 request log in accurate $request_time ?

Maxim Dounin
In reply to this post by Olaf van der Spek
Hello!

On Wed, Jan 22, 2020 at 10:38:42AM -0500, xt3627216 wrote:

[...]

> if  stream->queued  is true,   then ngx_http_free_request will not be called
> immediately, which will result $request_time larger then real request time?

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.

--
Maxim Dounin
http://mdounin.ru/
_______________________________________________
nginx mailing list
[hidden email]
http://mailman.nginx.org/mailman/listinfo/nginx
Reply | Threaded
Open this post in threaded view
|

Re: http2 request log in accurate $request_time ?

Olaf van der Spek
Maxim Dounin Wrote:
-------------------------------------------------------

> Hello!
>
> On Wed, Jan 22, 2020 at 10:38:42AM -0500, xt3627216 wrote:
>
> [...]
>
> > if  stream->queued  is true,   then ngx_http_free_request will not
> be called
> > immediately, which will result $request_time larger then real
> request time?
>
> 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.
>
> --
> Maxim Dounin
> http://mdounin.ru/
> _______________________________________________
> nginx mailing list
> [hidden email]
> http://mailman.nginx.org/mailman/listinfo/nginx


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.

thanks many.

Posted at Nginx Forum: https://forum.nginx.org/read.php?2,286797,286806#msg-286806

_______________________________________________
nginx mailing list
[hidden email]
http://mailman.nginx.org/mailman/listinfo/nginx
Reply | Threaded
Open this post in threaded view
|

Re: 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/
_______________________________________________
nginx mailing list
[hidden email]
http://mailman.nginx.org/mailman/listinfo/nginx