2 questions on send_timeout (maybe bugs)

Thu May 19 06:39:43 MSD 2011

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.
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.
In this log, fd8 is downstream and fd9 is upstream. Only the downstream is what we will focus on (so ignore the fd9 please).
You can see that, in line 4, nginx write 496B to downstream, and the return value is non-NULL(line 5), which means the downstream is delayed.
In line 20, epoll_wait() returns with revents=25, which means the fd8(downstream) is *break*. But only a read-handler is called in line 21, and NO write-handler is called.
So, nginx doesnot detect the break of downstream, and waits for send_timeout, and *wakes* in line 32 and 35.

      0 ......
      1 2011/05/19 10:00:07 [debug] 26851#0: *1 write new buf t:0 f:0 0000000000000000, pos 00000000005AFB70, size: 4096 file: 0, size: 0
      2 2011/05/19 10:00:07 [debug] 26851#0: *1 http write filter: l:0 f:1 s:4096
      3 2011/05/19 10:00:07 [debug] 26851#0: *1 http write filter limit 0
      4 2011/05/19 10:00:07 [debug] 26851#0: *1 writev: 496
      5 2011/05/19 10:00:07 [debug] 26851#0: *1 http write filter 00000000005D91C0 
      6 2011/05/19 10:00:07 [debug] 26851#0: *1 copy filter: -2 "/data/music/885720/ä»~Jå¤©.mp3?xcode=efb9e826d9161812ab9483faf71dddbb"
      7 2011/05/19 10:00:07 [debug] 26851#0: *1 event timer add: 8: 20000:1305770427453
      8 2011/05/19 10:00:07 [debug] 26851#0: *1 event timer del: 9: 1305770467453
      9 2011/05/19 10:00:07 [debug] 26851#0: *1 epoll call wriet handler. fd: 9, revnets:5 
     10 2011/05/19 10:00:07 [debug] 26851#0: *1 http upstream request: "/data/music/885720/ä»~Jå¤©.mp3?xcode=efb9e826d9161812ab9483faf71dddbb"
     11 2011/05/19 10:00:07 [debug] 26851#0: *1 http upstream dummy handler
     12 2011/05/19 10:00:07 [debug] 26851#0: *1 epoll_wait: fd 9, revnets:5
     13 2011/05/19 10:00:07 [debug] 26851#0: *1 epoll call read handler. fd: 9, revnets:5
     14 2011/05/19 10:00:07 [debug] 26851#0: *1 http upstream request: "/data/music/885720/ä»~Jå¤©.mp3?xcode=efb9e826d9161812ab9483faf71dddbb"
     15 2011/05/19 10:00:07 [debug] 26851#0: *1 http upstream process non buffered upstream
     16 2011/05/19 10:00:07 [debug] 26851#0: *1 event timer: 8, old: 1305770427453, new: 1305770427453
     17 2011/05/19 10:00:07 [debug] 26851#0: *1 epoll call wriet handler. fd: 9, revnets:5
     18 2011/05/19 10:00:07 [debug] 26851#0: *1 http upstream request: "/data/music/885720/ä»~Jå¤©.mp3?xcode=efb9e826d9161812ab9483faf71dddbb"
     19 2011/05/19 10:00:07 [debug] 26851#0: *1 http upstream dummy handler
     20 2011/05/19 10:00:07 [debug] 26851#0: *1 epoll_wait: fd 8, revnets:25
     21 2011/05/19 10:00:07 [debug] 26851#0: *1 epoll call read handler. fd: 8, revnets:25
     22 2011/05/19 10:00:07 [debug] 26851#0: *1 http run request: "/data/music/885720/ä»~Jå¤©.mp3?xcode=efb9e826d9161812ab9483faf71dddbb"
     23 2011/05/19 10:00:07 [debug] 26851#0: *1 http reading blocked
     24 2011/05/19 10:00:07 [debug] 26851#0: *1 epoll_wait: fd 9, revnets:5
     25 2011/05/19 10:00:07 [debug] 26851#0: *1 epoll call read handler. fd: 9, revnets:5
     26 2011/05/19 10:00:07 [debug] 26851#0: *1 http upstream request: "/data/music/885720/ä»~Jå¤©.mp3?xcode=efb9e826d9161812ab9483faf71dddbb"
     27 2011/05/19 10:00:07 [debug] 26851#0: *1 http upstream process non buffered upstream
     28 2011/05/19 10:00:07 [debug] 26851#0: *1 event timer: 8, old: 1305770427453, new: 1305770427654
     29 2011/05/19 10:00:07 [debug] 26851#0: *1 epoll call wriet handler. fd: 9, revnets:5
     30 2011/05/19 10:00:07 [debug] 26851#0: *1 http upstream request: "/data/music/885720/ä»~Jå¤©.mp3?xcode=efb9e826d9161812ab9483faf71dddbb"
     31 2011/05/19 10:00:07 [debug] 26851#0: *1 http upstream dummy handler
     32 2011/05/19 10:00:27 [debug] 26851#0: *1 event timer del: 8: 1305770427453
     33 2011/05/19 10:00:27 [debug] 26851#0: *1 http run request: "/data/music/885720/ä»~Jå¤©.mp3?xcode=efb9e826d9161812ab9483faf71dddbb"
     34 2011/05/19 10:00:27 [debug] 26851#0: *1 http upstream process non buffered downstream
     35 2011/05/19 10:00:27 [info] 26851#0: *1 client timed out (110: Connection timed out) while sending to client, client: 61.135.169.175, server: z
        iyouziyuan.baidu.com, request: "GET /data/music/885720/%E4%BB%8A%E5%A4%A9.mp3?xcode=efb9e826d9161812ab9483faf71dddbb HTTP/1.0", upstream: "mem
        cached://172.18.254.50:11200"
     36 2011/05/19 10:00:27 [debug] 26851#0: *1 finalize http upstream request: 0
     37 2011/05/19 10:00:27 [debug] 26851#0: *1 finalize http memcached request 

>> 6. Then, we have to wait for send_timeout...
>> 
>> This situation dosenot occur everytime. If the downstream 
>> breaks, when nginx is sending data, the breaking will be 
>> detected.
>> But I can make this happen all the time, when:
>> 1. the client and server are far away from each other (e.g. not 
>> in a local net)
>> 2. using memc module
>>
>> Question2.
>> 
>> 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?

>
>Maxim Dounin
>
>_______________________________________________
>nginx mailing list
>nginx at nginx.org
>http://nginx.org/mailman/listinfo/nginx

Thanks again for you responding.
Best Regards,
Wu