Fixed upstream->read timer when downstream->write not ready
xiaolong hong
imhongxiaolong at gmail.com
Fri Jan 19 12:43:06 UTC 2018
# HG changeset patch
# User Xiaolong Hong <imhongxiaolong at gmail.com>
# Date 1516354115 -28800
# Fri Jan 19 17:28:35 2018 +0800
# Node ID f017b8c1a99433cc3321475968556aee50609145
# Parent 93abb5a855d6534f0356882f45be49f8c6a95a8b
Fixed upstream->read timer when downstream->write not ready.
diff -r 93abb5a855d6 -r f017b8c1a994 src/http/ngx_http_upstream.c
--- a/src/http/ngx_http_upstream.c Thu Jan 11 21:43:49 2018 +0300
+++ b/src/http/ngx_http_upstream.c Fri Jan 19 17:28:35 2018 +0800
@@ -3625,7 +3625,9 @@ ngx_http_upstream_process_non_buffered_r
return;
}
- if (upstream->read->active && !upstream->read->ready) {
+ if (upstream->read->active && !upstream->read->ready
+ && !(u->length == 0 || (upstream->read->eof && u->length == -1)))
+ {
ngx_add_timer(upstream->read, u->conf->read_timeout);
} else if (upstream->read->timer_set) {
--------
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.
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.
This problem could be fixed to check upstream eof when trying to add
upstream->read timer.
--------
We got debug logs as follows:
2018/01/19 17:16:44 [debug] 19674#0: *5 http write filter: l:0 f:1 s:510767
2018/01/19 17:16:44 [debug] 19674#0: *5 http write filter limit 0
2018/01/19 17:16:44 [debug] 19674#0: *5 http write filter 000000010080E068
2018/01/19 17:16:44 [debug] 19674#0: *5 http copy filter: -2 "/t?"
2018/01/19 17:16:44 [debug] 19674#0: *5 event timer del: 7: 1516353481686
2018/01/19 17:16:44 [debug] 19674#0: *5 event timer add: 7:
77000:1516353481990 (add downstream->write timer)
2018/01/19 17:16:44 [debug] 19674#0: *5 event timer: 8, old: 1516353426958,
new: 1516353426990
2018/01/19 17:16:44 [debug] 19674#0: timer delta: 16
2018/01/19 17:16:44 [debug] 19674#0: worker cycle
2018/01/19 17:16:44 [debug] 19674#0: kevent timer: 21968, changes: 0 (add
upstream->read timer)
2018/01/19 17:16:45 [debug] 19674#0: kevent events: 1
2018/01/19 17:16:45 [debug] 19674#0: kevent: 8: ft:-1 fl:0025 ff:00000000
d:3068 ud:000000010180C6D0
2018/01/19 17:16:45 [debug] 19674#0: *5 http upstream request: "/t?"
2018/01/19 17:16:45 [debug] 19674#0: *5 http upstream process non buffered
upstream
2018/01/19 17:16:45 [debug] 19674#0: *5 recv: eof:0, avail:3068, err:0
2018/01/19 17:16:45 [debug] 19674#0: *5 recv: fd:8 3080 of 4734892
2018/01/19 17:16:45 [debug] 19674#0: *5 posix_memalign:
000000010100AE00:4096 @16
2018/01/19 17:16:45 [debug] 19674#0: *5 http output filter "/t?"
2018/01/19 17:16:45 [debug] 19674#0: *5 http copy filter: "/t?"
2018/01/19 17:16:45 [debug] 19674#0: *5 http postpone filter "/t?"
000000010100AE20
2018/01/19 17:16:45 [debug] 19674#0: *5 http chunk: 3080
2018/01/19 17:17:06 [debug] 19674#0: kevent events: 0
2018/01/19 17:17:06 [debug] 19674#0: timer delta: 21739
2018/01/19 17:17:06 [debug] 19674#0: *5 event timer del: 8: 1516353426958
2018/01/19 17:17:06 [debug] 19674#0: *5 http upstream request: "/t?"
2018/01/19 17:17:06 [debug] 19674#0: *5 http upstream process non buffered
upstream
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: "http://127.0.0.1:9
090/t", host: "t.taobao.com"
2018/01/19 17:17:06 [debug] 19674#0: *5 finalize http upstream request: 504
2018/01/19 17:17:06 [debug] 19674#0: *5 finalize http proxy request
2018/01/19 17:17:06 [debug] 19674#0: *5 free rr peer 1 0
2018/01/19 17:17:06 [debug] 19674#0: *5 close http upstream connection: 8
2018/01/19 17:17:06 [debug] 19674#0: *5 free: 0000000100300220, unused: 48
2018/01/19 17:17:06 [debug] 19674#0: *5 reusable connection: 0
2018/01/19 17:17:06 [debug] 19674#0: *5 http output filter "/t?"
2018/01/19 17:17:06 [debug] 19674#0: *5 http copy filter: "/t?"
2018/01/19 17:17:06 [debug] 19674#0: *5 http postpone filter "/t?"
00007FFEEFBFF1B0
2018/01/19 17:17:06 [debug] 19674#0: *5 http chunk: 0
2018/01/19 17:18:23 [debug] 19674#0: kevent events: 0
2018/01/19 17:18:23 [debug] 19674#0: timer delta: 77012
2018/01/19 17:18:23 [debug] 19674#0: *5 event timer del: 7: 1516353503980
2018/01/19 17:18:23 [debug] 19674#0: *5 http run request: "/t?"
2018/01/19 17:18:23 [debug] 19674#0: *5 http writer handler: "/t?"
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: "http://127.0.0.1:909
0/t", host: "t.taobao.com"
2018/01/19 17:18:23 [debug] 19674#0: *5 http finalize request: 408, "/t?"
a:1, c:1
2018/01/19 17:18:23 [debug] 19674#0: *5 http terminate request count:1
2018/01/19 17:18:23 [debug] 19674#0: *5 http terminate cleanup count:1 blk:0
2018/01/19 17:18:23 [debug] 19674#0: *5 http posted request: "/t?"
2018/01/19 17:18:23 [debug] 19674#0: *5 http terminate handler count:1
2018/01/19 17:18:23 [debug] 19674#0: *5 http request count:1 blk:0
2018/01/19 17:18:23 [debug] 19674#0: *5 http close request
2018/01/19 17:18:23 [debug] 19674#0: *5 http log handler
--------
We could reproduce this problem by:
1、Configuration as follows:
```
http {
include mime.types;
default_type application/octet-stream;
#log_format main '$remote_addr - $remote_user [$time_local]
"$request" '
# '$status $body_bytes_sent "$http_referer" '
# '"$http_user_agent" "$http_x_forwarded_for"';
#access_log logs/access.log main;
sendfile on;
#tcp_nopush on;
#keepalive_timeout 0;
keepalive_timeout 65;
proxy_connect_timeout 60s;
proxy_send_timeout 33s;
proxy_read_timeout 22s;
proxy_max_temp_file_size 0;
proxy_busy_buffers_size 5120k;
proxy_buffer_size 5120k;
proxy_buffers 8 5120k;
proxy_buffering off;
client_header_timeout 55s;
client_body_timeout 66s;
send_timeout 77s;
```
2. Create a HTTP Server as upstream to produce 1Mb response.
3. Create a downstream but only connect()->send()->sleep() beforce recv().
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.nginx.org/pipermail/nginx-devel/attachments/20180119/5a280d5c/attachment.html>
More information about the nginx-devel
mailing list