<div dir="ltr"><div># HG changeset patch</div><div># User Xiaolong Hong <<a href="mailto:imhongxiaolong@gmail.com">imhongxiaolong@gmail.com</a>></div><div># Date 1516354115 -28800</div><div>#      Fri Jan 19 17:28:35 2018 +0800</div><div># Node ID f017b8c1a99433cc3321475968556aee50609145</div><div># Parent  93abb5a855d6534f0356882f45be49f8c6a95a8b</div><div>Fixed upstream->read timer when downstream->write not ready.</div><div><br></div><div>diff -r 93abb5a855d6 -r f017b8c1a994 src/http/ngx_http_upstream.c</div><div>--- a/src/http/ngx_http_upstream.c      Thu Jan 11 21:43:49 2018 +0300</div><div>+++ b/src/http/ngx_http_upstream.c      Fri Jan 19 17:28:35 2018 +0800</div><div>@@ -3625,7 +3625,9 @@ ngx_http_upstream_process_non_buffered_r</div><div>         return;</div><div>     }</div><div><br></div><div>-    if (upstream->read->active && !upstream->read->ready) {</div><div>+    if (upstream->read->active && !upstream->read->ready</div><div>+        && !(u->length == 0 || (upstream->read->eof && u->length == -1)))</div><div>+    {</div><div>         ngx_add_timer(upstream->read, u->conf->read_timeout);</div><div><br></div><div>     } else if (upstream->read->timer_set) {</div><div><br></div><div>--------</div><div><br></div><div>When downstream hung and nginx received the last buffer from upstream, both downstream->write timer and upstream->read timer would be added in the meantime because downstream->write->ready and upstream->read->ready would opportunely be 0.</div><div><br></div><div>Actually if clcf->send_timeout less then u->conf->read_timeout, upstream->read timer would be waked before downstream->write timer, it caused mistakes to report the "upstream timed out" error deviating from the fact that upstream worked normally but downstream hung.</div><div><br></div><div>This problem could be fixed to check upstream eof when trying to add upstream->read timer.</div><div><br></div><div>--------</div><div><br></div><div>We got debug logs as follows:</div><div><br></div><div>2018/01/19 17:16:44 [debug] 19674#0: *5 http write filter: l:0 f:1 s:510767</div><div>2018/01/19 17:16:44 [debug] 19674#0: *5 http write filter limit 0</div><div>2018/01/19 17:16:44 [debug] 19674#0: *5 http write filter 000000010080E068</div><div>2018/01/19 17:16:44 [debug] 19674#0: *5 http copy filter: -2 "/t?"</div><div>2018/01/19 17:16:44 [debug] 19674#0: *5 event timer del: 7: 1516353481686</div><div>2018/01/19 17:16:44 [debug] 19674#0: *5 event timer add: 7: 77000:1516353481990   (add downstream->write timer)</div><div>2018/01/19 17:16:44 [debug] 19674#0: *5 event timer: 8, old: 1516353426958, new: 1516353426990</div><div>2018/01/19 17:16:44 [debug] 19674#0: timer delta: 16</div><div>2018/01/19 17:16:44 [debug] 19674#0: worker cycle</div><div>2018/01/19 17:16:44 [debug] 19674#0: kevent timer: 21968, changes: 0 (add upstream->read timer)</div><div>2018/01/19 17:16:45 [debug] 19674#0: kevent events: 1</div><div>2018/01/19 17:16:45 [debug] 19674#0: kevent: 8: ft:-1 fl:0025 ff:00000000 d:3068 ud:000000010180C6D0</div><div>2018/01/19 17:16:45 [debug] 19674#0: *5 http upstream request: "/t?"</div><div>2018/01/19 17:16:45 [debug] 19674#0: *5 http upstream process non buffered upstream</div><div>2018/01/19 17:16:45 [debug] 19674#0: *5 recv: eof:0, avail:3068, err:0</div><div>2018/01/19 17:16:45 [debug] 19674#0: *5 recv: fd:8 3080 of 4734892</div><div>2018/01/19 17:16:45 [debug] 19674#0: *5 posix_memalign: 000000010100AE00:4096 @16</div><div>2018/01/19 17:16:45 [debug] 19674#0: *5 http output filter "/t?"</div><div>2018/01/19 17:16:45 [debug] 19674#0: *5 http copy filter: "/t?"</div><div>2018/01/19 17:16:45 [debug] 19674#0: *5 http postpone filter "/t?" 000000010100AE20</div><div>2018/01/19 17:16:45 [debug] 19674#0: *5 http chunk: 3080</div><div><br></div><div><br></div><div>2018/01/19 17:17:06 [debug] 19674#0: kevent events: 0</div><div>2018/01/19 17:17:06 [debug] 19674#0: timer delta: 21739</div><div>2018/01/19 17:17:06 [debug] 19674#0: *5 event timer del: 8: 1516353426958</div><div>2018/01/19 17:17:06 [debug] 19674#0: *5 http upstream request: "/t?"</div><div>2018/01/19 17:17:06 [debug] 19674#0: *5 http upstream process non buffered upstream</div><div>2018/01/19 17:17:06 [error] 19674#0: *5 upstream timed out (60: Operation timed out) while reading upstream, client: 127.0.0.1, server: localhost, request: "GET /t HTTP/1.1", upstream: "<a href="http://127.0.0.1:9">http://127.0.0.1:9</a></div><div>090/t", host: "<a href="http://t.taobao.com">t.taobao.com</a>"</div><div>2018/01/19 17:17:06 [debug] 19674#0: *5 finalize http upstream request: 504</div><div>2018/01/19 17:17:06 [debug] 19674#0: *5 finalize http proxy request</div><div>2018/01/19 17:17:06 [debug] 19674#0: *5 free rr peer 1 0</div><div>2018/01/19 17:17:06 [debug] 19674#0: *5 close http upstream connection: 8</div><div>2018/01/19 17:17:06 [debug] 19674#0: *5 free: 0000000100300220, unused: 48</div><div>2018/01/19 17:17:06 [debug] 19674#0: *5 reusable connection: 0</div><div>2018/01/19 17:17:06 [debug] 19674#0: *5 http output filter "/t?"</div><div>2018/01/19 17:17:06 [debug] 19674#0: *5 http copy filter: "/t?"</div><div>2018/01/19 17:17:06 [debug] 19674#0: *5 http postpone filter "/t?" 00007FFEEFBFF1B0</div><div>2018/01/19 17:17:06 [debug] 19674#0: *5 http chunk: 0</div><div><br></div><div><br></div><div>2018/01/19 17:18:23 [debug] 19674#0: kevent events: 0</div><div>2018/01/19 17:18:23 [debug] 19674#0: timer delta: 77012</div><div>2018/01/19 17:18:23 [debug] 19674#0: *5 event timer del: 7: 1516353503980</div><div>2018/01/19 17:18:23 [debug] 19674#0: *5 http run request: "/t?"</div><div>2018/01/19 17:18:23 [debug] 19674#0: *5 http writer handler: "/t?"</div><div>2018/01/19 17:18:23 [info] 19674#0: *5 client timed out (60: Operation timed out) while sending to client, client: 127.0.0.1, server: localhost, request: "GET /t HTTP/1.1", upstream: "<a href="http://127.0.0.1:909">http://127.0.0.1:909</a></div><div>0/t", host: "<a href="http://t.taobao.com">t.taobao.com</a>"</div><div>2018/01/19 17:18:23 [debug] 19674#0: *5 http finalize request: 408, "/t?" a:1, c:1</div><div>2018/01/19 17:18:23 [debug] 19674#0: *5 http terminate request count:1</div><div>2018/01/19 17:18:23 [debug] 19674#0: *5 http terminate cleanup count:1 blk:0</div><div>2018/01/19 17:18:23 [debug] 19674#0: *5 http posted request: "/t?"</div><div>2018/01/19 17:18:23 [debug] 19674#0: *5 http terminate handler count:1</div><div>2018/01/19 17:18:23 [debug] 19674#0: *5 http request count:1 blk:0</div><div>2018/01/19 17:18:23 [debug] 19674#0: *5 http close request</div><div>2018/01/19 17:18:23 [debug] 19674#0: *5 http log handler</div><div><br></div><div>--------</div><div><br></div><div>We could reproduce this problem by:</div><div><br></div><div>1、Configuration as follows:</div><div>```</div><div>http {</div><div>    include       mime.types;</div><div>    default_type  application/octet-stream;</div><div><br></div><div>    #log_format  main  '$remote_addr - $remote_user [$time_local] "$request" '</div><div>    #                  '$status $body_bytes_sent "$http_referer" '</div><div>    #                  '"$http_user_agent" "$http_x_forwarded_for"';</div><div><br></div><div>    #access_log  logs/access.log  main;</div><div><br></div><div>    sendfile        on;</div><div>    #tcp_nopush     on;</div><div><br></div><div>    #keepalive_timeout  0;</div><div>    keepalive_timeout  65;</div><div><br></div><div>    proxy_connect_timeout 60s;</div><div>    proxy_send_timeout 33s;</div><div>    proxy_read_timeout 22s;</div><div><br></div><div>    proxy_max_temp_file_size 0;</div><div>    proxy_busy_buffers_size 5120k;</div><div>    proxy_buffer_size 5120k;</div><div>    proxy_buffers 8 5120k;</div><div>    proxy_buffering off;</div><div><br></div><div>    client_header_timeout 55s;</div><div>    client_body_timeout 66s;</div><div><br></div><div>    send_timeout 77s;</div><div>```</div><div><br></div><div>2. Create a HTTP Server as upstream to produce 1Mb response.</div><div>3. Create a downstream but only connect()->send()->sleep() beforce recv().</div><div><br></div></div>