2 questions on send_timeout (maybe bugs)

[Maxim Dounin]

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