2 questions on send_timeout (maybe bugs)

[Wu Bingzheng]

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.


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:

[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