# 2 questions on send\_timeout (maybe bugs) **URL:** \ **Category:** NGINX\ **Created:** [May 18, 2011, 11:15am UTC](https://www.ruby-forum.com/t/2-questions-on-send-timeout-maybe-bugs/207102 "2011-05-18T11:15:36Z")\ **Posts on this page:** 6\ **Page:** 1
**Author:** ![dubstep](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/d/cdc98d/32.png) [@dubstep](https://www.ruby-forum.com/u/dubstep)\ **Post date:** [May 18, 2011, 11:15am UTC](https://www.ruby-forum.com/t/2-questions-on-send-timeout-maybe-bugs/207102/1 "2011-05-18T11:15:36Z")
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 !!! 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. Thanks Wu ---
**Author:** ![SSWuSSBingzhengSS\_S](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/s/35a633/32.png) [@SSWuSSBingzhengSS\_S](https://www.ruby-forum.com/u/SSWuSSBingzhengSS_S)\ **Post date:** [May 18, 2011, 3:35pm UTC](https://www.ruby-forum.com/t/2-questions-on-send-timeout-maybe-bugs/207102/2 "2011-05-18T15:35:58Z")
Hello! On Wed, May 18, 2011 at 05:15:00PM +0800, Wu Bingzheng wrote: > 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). > Question2. > 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. Maxim D. ---
**Author:** ![SSWuSSBingzhengSS\_S](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/s/35a633/32.png) [@SSWuSSBingzhengSS\_S](https://www.ruby-forum.com/u/SSWuSSBingzhengSS_S)\ **Post date:** [May 19, 2011, 4:40am UTC](https://www.ruby-forum.com/t/2-questions-on-send-timeout-maybe-bugs/207102/3 "2011-05-19T04:40:29Z")
Hi Maxim, Thanks for your answer. But I am still confused. At 2011-05-18 21:35:07，“Maxim D.” [removed\_email\_address@domain.invalid](mailto:removed_email_address@domain.invalid) wrote: > > Question1. > > 5. epoll detect the breaking, so epoll\_wait() continues in > > 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](http://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 > > Question2. > > 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 D. > > * * * > > nginx mailing list > [removed\_email\_address@domain.invalid](mailto:removed_email_address@domain.invalid) > [mailman.nginx.org archive](http://nginx.org/mailman/listinfo/nginx) Thanks again for you responding. Best Regards, Wu ---
**Author:** ![SSWuSSBingzhengSS\_S](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/s/35a633/32.png) [@SSWuSSBingzhengSS\_S](https://www.ruby-forum.com/u/SSWuSSBingzhengSS_S)\ **Post date:** [May 19, 2011, 1:38pm UTC](https://www.ruby-forum.com/t/2-questions-on-send-timeout-maybe-bugs/207102/4 "2011-05-19T13:38:52Z")
Hello! On Thu, May 19, 2011 at 10:39:43AM +0800, Wu Bingzheng wrote: > > > downstream breaking was not detected by nginx !!! > > > 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] [poll](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. […] > > 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 D. ---
**Author:** ![SSWuSSBingzhengSS\_S](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/s/35a633/32.png) [@SSWuSSBingzhengSS\_S](https://www.ruby-forum.com/u/SSWuSSBingzhengSS_S)\ **Post date:** [May 20, 2011, 5:58am UTC](https://www.ruby-forum.com/t/2-questions-on-send-timeout-maybe-bugs/207102/5 "2011-05-20T05:58:47Z")
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. 1. 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 ---
**Author:** ![SSWuSSBingzhengSS\_S](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/s/35a633/32.png) [@SSWuSSBingzhengSS\_S](https://www.ruby-forum.com/u/SSWuSSBingzhengSS_S)\ **Post date:** [May 20, 2011, 1:33pm UTC](https://www.ruby-forum.com/t/2-questions-on-send-timeout-maybe-bugs/207102/6 "2011-05-20T13:33:51Z")
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. > 1. > > 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 D.