2 questions on send_timeout (maybe bugs)

Maxim Dounin mdounin at mdounin.ru
Fri May 20 15:33:15 MSD 2011


Hello!

On Fri, May 20, 2011 at 11:58:20AM +0800, Wu Bingzheng wrote:

> Hi Maxim,
> 
> 1.
> I am so sorry that I made a big mistake on question 1.
> Nginx didn't detect the downstream breaking, because I use "proxy_ignore_client_abort on;".
> So Nginx works correctlly. I am so sorry about it.

I believe the problem may still appear with normal usage once 
upstream connection terminates, EPOLLHUP handling in epoll event 
module doesn't look correct for me.  This should be investigated 
further.

> 2.
> For question 2.
> You said that :
> >Note also that in debug log you provided nginx correctly times out 
> >after 20s from last send.
> 
> That's because I set the send_timeout as 10s. I am sorry that I did not make clear of that.
> 
> You can reproduce the doubled timeout easy:

Ok, I was able to reproduce this and see the problem.  Indeed, 
when upstream module detects client timeout it doesn't finalize 
request properly, and as a result http core thinks it should 
continue sending data in buffers and hence waits for another 
timeout.

Quick fix for this particular problem would be something like

diff --git a/src/http/ngx_http_upstream.c b/src/http/ngx_http_upstream.c
--- a/src/http/ngx_http_upstream.c
+++ b/src/http/ngx_http_upstream.c
@@ -2320,7 +2320,7 @@ ngx_http_upstream_process_non_buffered_d
     if (wev->timedout) {
         c->timedout = 1;
         ngx_connection_error(c, NGX_ETIMEDOUT, "client timed out");
-        ngx_http_upstream_finalize_request(r, u, 0);
+        ngx_http_upstream_finalize_request(r, u, NGX_HTTP_REQUEST_TIME_OUT);
         return;
     }

@@ -3013,6 +3013,7 @@ ngx_http_upstream_finalize_request(ngx_h
 #endif

     if (u->header_sent
+        && rc != NGX_HTTP_REQUEST_TIME_OUT
         && (rc == NGX_ERROR || rc >= NGX_HTTP_SPECIAL_RESPONSE))
     {
         rc = 0;


Though upstream module certainly requires larger cleanup of error 
handling.  This is not the first time I've been bitten by upstream 
not finalizing requests properly.

Maxim Dounin

> 
> [server] using nginx-1.0.0, without any addon module. in nginx.conf:
> 
>     server {
>         listen       5821;
>         proxy_buffering off; #must in non-buffering mode
>         send_timeout 10;
> 
>         location / {
>             proxy_pass http://sourceserver;
>         }
>     }
> 
> 
> 
> [client] you can run this simple python script:
> 
>   #!/usr/bin/python
>   import socket
>   import time
>   s = socket.socket(socket.AF_INET,socket.SOCK_STREAM)
>   s.connect((127.0.0.1, 5821))
>   s.send("GET /data/something HTTP/1.0\r\n\r\n")
>   buf = s.recv(100)
>   print buf
>   time.sleep(100)
> 
> 
> 
> Then, in access.log, you will find that the request is finished in 20s.
> 
> 
> Best Regads,
> Wu
> 
> 
> 
> 
> 
> 
> 
> 
> At 2011-05-19 19:38:42,"Maxim Dounin" <mdounin at mdounin.ru> wrote:
> 
> >Hello!
> >
> >On Thu, May 19, 2011 at 10:39:43AM +0800, Wu Bingzheng wrote:
> >
> >> Hi Maxim,
> >> 
> >> Thanks for your answer. But I am still confused.
> >> 
> >> 
> >> At 2011-05-18 21:35:07,"Maxim Dounin" <mdounin at mdounin.ru> wrote:
> >> 
> >> >Hello!
> >> >
> >> >On Wed, May 18, 2011 at 05:15:00PM +0800, Wu Bingzheng wrote:
> >> >
> >> >> hi all,
> >> >> 
> >> >> 
> >> >> I meet 2 question when using nginx 1.0.0.
> >> >> 
> >> >> 
> >> >> Question1.
> >> >> 
> >> >> what happens if the downstream connection breaks, before all 
> >> >> data sent to the client?
> >> >> 
> >> >> 1. get client's request
> >> >> 2. set handler: r->read_event_handle=ngx_http_block_reading
> >> >> 3. send data to client, and blocked ( 
> >> >> write_filter.c:c->send_chain() returns non-NULL or non-error), 
> >> >> and go back to epoll_wait
> >> >> 4. HERE, the downstream breaks
> >> >> 5. epoll detect the breaking, so epoll_wait() continues in 
> >> >> ngx_epoll_process_events(), where the revents==EPOLL_IN | 
> >> >> EPOLL_ERR | EPOLL_HUP. So we call rev->handler(), which calls 
> >> >> r->read_event_handle, which dose nothing. AS A RESULT, the 
> >> >> downstream breaking was not detected by nginx !!!
> >> >
> >> >Here write event handler will be called.  While standard 
> >> >ngx_http_writer() is in use - it will call output filter chain and 
> >> >detect error.  Else it's up to active handler to correctly handle 
> >> >this, e.g. standard upstream modules (proxy/fastcgi/...) may 
> >> >either terminate request immediately or wait for full upstream 
> >> >response depending on various settings (proxy_ignore_client_abort, 
> >> >proxy_cache/proxy_store enabled).
> >> >
> >> 
> >> You said the write handler will be called. But if a connection 
> >> is break, revents returned by epoll_wait() is 'EPOLL_IN |  
> >> EPOLL_ERR | EPOLL_HUP', and no EPOLL_OUT in revents. So I think 
> >> the write-handler will NOT be called.
> >
> >Ah, ok, it looks like I was wrong here.  Write handler will be 
> >only called if there are no EPOLLIN flag in revents, and this is 
> >probably wrong assuming EPOLLHUP follows the same semantics as 
> >POLLHUP[1], i.e.
> >
> >POLLHUP
> >...  This event and POLLOUT are mutually-exclusive; a stream can 
> >never be writable if a hangup has occurred. ...
> >
> >Could you please provide detailed instructions to reproduce the 
> >problem, preferably with standard modules involved?
> >
> >[1] http://pubs.opengroup.org/onlinepubs/9699919799/functions/poll.html
> >
> >> The FACT is, in my server, there are many many access logs whose 
> >> time-taken are 40.001s. (send_timeout is 20s, and this is a 
> >> music online server, so many people re-choose a song before the 
> >> current song finishs, which means the downstream breaks before 
> >> nginx sends all data).
> >> 
> >> I add 2 debug log in ngx_epoll_process_events(), and copy part 
> >> of the debug log here.
> >
> >Just a side note: mostly same information may be seen at global 
> >level debug log.
> >
> >[...]
> >
> >> >> I set 'send_timeout' as 20s, but nginx timeouts in 40s actually.
> >> >> 
> >> >> 1. in 
> >> >> src/http/ngx_http_upstream.c[line2448]:ngx_http_upstream_process_non_buffered_request(), 
> >> >> a timer is added;
> >> >> 2. after that timer timeout, in 
> >> >> src/http/ngx_http_request.c[line2179]:ngx_http_set_write_handler(), 
> >> >> another timer is added again.
> >> >> 
> >> >> so the send_timeout is doubled.
> >> >
> >> >Timeout is re-set on each send operation, and expected to be 
> >> >triggered when nothing happens during send_timeout.
> >> 
> >> So, you think that, I set 'send_timeout' as 20s, but nginx 
> >> actually timeout in 40s is right and expected?
> >
> >It should timeout in 20s after last send.  Whether request time 
> >of 40s is wrong or not depends on many factors, but the code you 
> >pointed out looks fine.
> >
> >Note also that in debug log you provided nginx correctly times out 
> >after 20s from last send.
> >
> >Maxim Dounin
> 
> 
> _______________________________________________
> nginx mailing list
> nginx at nginx.org
> http://nginx.org/mailman/listinfo/nginx



More information about the nginx mailing list