Attach a log for this situation. Thanks.


At 2014-06-25 19:23:32,flygoast <flygoast@126.com> wrote:

# HG changeset patch
# User FengGu <flygoast@126.com>
# Date 1403694825 -28800
# Wed Jun 25 19:13:45 2014 +0800
# Node ID 12fd8ef2f6ea3167dd96cb000aafeb2665aeee14
# Parent 63d7d69d0fe48e030ff9fc520c7036dbd1ebc13f
Upstream: fix possible request hang when "proxy_buffering" is off.


In ngx_http_upstream_process_non_buffered_request(), when processing non
buffered request, if write event has been delayed, deleting write timer
event is likely to result in follow-up writing buffered in
ngx_http_write_filter() ever since.


diff -r 63d7d69d0fe4 -r 12fd8ef2f6ea src/http/ngx_http_upstream.c
--- a/src/http/ngx_http_upstream.c Fri Jun 20 12:55:41 2014 +0400
+++ b/src/http/ngx_http_upstream.c Wed Jun 25 19:13:45 2014 +0800
@@ -3058,6 +3058,7 @@
ngx_add_timer(downstream->write, clcf->send_timeout);


} else if (downstream->write->timer_set) {
+ downstream->write->delayed = 0;
ngx_del_timer(downstream->write);
}




2014/06/25 18:36:07 [debug] 29435#0: *31 accept: 127.0.0.1:54178 fd:15
2014/06/25 18:36:07 [debug] 29435#0: *31 event timer add: 15: 60000:1403692627362
2014/06/25 18:36:07 [debug] 29435#0: *31 reusable connection: 1
2014/06/25 18:36:07 [debug] 29435#0: *31 epoll add event: fd:15 op:1 ev:80002001
2014/06/25 18:36:07 [debug] 29435#0: *31 http wait request handler
2014/06/25 18:36:07 [debug] 29435#0: *31 malloc: 00000000006FDF90:1024
2014/06/25 18:36:07 [debug] 29435#0: *31 recv: fd:15 175 of 1024
2014/06/25 18:36:07 [debug] 29435#0: *31 reusable connection: 0
2014/06/25 18:36:07 [debug] 29435#0: *31 posix_memalign: 00000000006FE3A0:4096 @16
2014/06/25 18:36:07 [debug] 29435#0: *31 http process request line
2014/06/25 18:36:07 [debug] 29435#0: *31 http request line: "GET /uri/a HTTP/1.1"
2014/06/25 18:36:07 [debug] 29435#0: *31 http uri: "/uri/a"
2014/06/25 18:36:07 [debug] 29435#0: *31 http args: ""
2014/06/25 18:36:07 [debug] 29435#0: *31 http exten: ""
2014/06/25 18:36:07 [debug] 29435#0: *31 http process request header line
2014/06/25 18:36:07 [debug] 29435#0: *31 http header: "User-Agent: curl/7.19.7 (x86_64-unknown-linux-gnu) libcurl/7.19.7 NSS/3.12.7.0 zlib/1.2.3 libidn/1.18 libssh2/1.2.2"
2014/06/25 18:36:07 [debug] 29435#0: *31 http header: "Host: 127.0.0.1:8080"
2014/06/25 18:36:07 [debug] 29435#0: *31 http header: "Accept: */*"
2014/06/25 18:36:07 [debug] 29435#0: *31 http header done
2014/06/25 18:36:07 [debug] 29435#0: *31 event timer del: 15: 1403692627362
2014/06/25 18:36:07 [debug] 29435#0: *31 rewrite phase: 0
2014/06/25 18:36:07 [debug] 29435#0: *31 test location: "/"
2014/06/25 18:36:07 [debug] 29435#0: *31 test location: "login"
2014/06/25 18:36:07 [debug] 29435#0: *31 test location: "test2"
2014/06/25 18:36:07 [debug] 29435#0: *31 using configuration "/"
2014/06/25 18:36:07 [debug] 29435#0: *31 http cl:-1 max:20971520
2014/06/25 18:36:07 [debug] 29435#0: *31 rewrite phase: 2
2014/06/25 18:36:07 [debug] 29435#0: *31 post rewrite phase: 3
2014/06/25 18:36:07 [debug] 29435#0: *31 generic phase: 4
2014/06/25 18:36:07 [debug] 29435#0: *31 generic phase: 5
2014/06/25 18:36:07 [debug] 29435#0: *31 access phase: 6
2014/06/25 18:36:07 [debug] 29435#0: *31 access phase: 7
2014/06/25 18:36:07 [debug] 29435#0: *31 post access phase: 8
2014/06/25 18:36:07 [debug] 29435#0: *31 posix_memalign: 00000000007223F0:4096 @16
2014/06/25 18:36:07 [debug] 29435#0: *31 http init upstream, client timer: 0
2014/06/25 18:36:07 [debug] 29435#0: *31 epoll add event: fd:15 op:3 ev:80002005
2014/06/25 18:36:07 [debug] 29435#0: *31 http script var: "/uri/a"
2014/06/25 18:36:07 [debug] 29435#0: *31 http cache key: "/uri/a"
2014/06/25 18:36:07 [debug] 29435#0: *31 add cleanup: 0000000000722B10
2014/06/25 18:36:07 [debug] 29435#0: *31 http file cache exists: -5 e:0
2014/06/25 18:36:07 [debug] 29435#0: *31 cache file: "/usr/local/nginx/cache/c0/4b/6e38e8dcfe0f57344b453eb30f974bc0"
2014/06/25 18:36:07 [debug] 29435#0: *31 add cleanup: 0000000000722B68
2014/06/25 18:36:07 [debug] 29435#0: *31 http file cache lock u:1 wt:0
2014/06/25 18:36:07 [debug] 29435#0: *31 http upstream cache: -5
2014/06/25 18:36:07 [debug] 29435#0: *31 http script copy: "User-Agent: 360 nginx src cache
2014/06/25 18:36:07 [debug] 29435#0: *31 http script copy: "X-Forwarded-For: "
2014/06/25 18:36:07 [debug] 29435#0: *31 http script var: "127.0.0.1"
2014/06/25 18:36:07 [debug] 29435#0: *31 http script copy: "
2014/06/25 18:36:07 [debug] 29435#0: *31 http script copy: "Host: "
2014/06/25 18:36:07 [debug] 29435#0: *31 http script var: "127.0.0.1"
2014/06/25 18:36:07 [debug] 29435#0: *31 http script copy: "
2014/06/25 18:36:07 [debug] 29435#0: *31 http script copy: "Connection: close
2014/06/25 18:36:07 [debug] 29435#0: *31 http script copy: ""
2014/06/25 18:36:07 [debug] 29435#0: *31 http script copy: ""
2014/06/25 18:36:07 [debug] 29435#0: *31 http script copy: ""
2014/06/25 18:36:07 [debug] 29435#0: *31 http script copy: ""
2014/06/25 18:36:07 [debug] 29435#0: *31 http proxy header: "Accept: */*"
2014/06/25 18:36:07 [debug] 29435#0: *31 http proxy header:
2014/06/25 18:36:07 [debug] 29435#0: *31 http cleanup add: 0000000000722D08
2014/06/25 18:36:07 [debug] 29435#0: *31 get rr peer, try: 1
2014/06/25 18:36:07 [debug] 29435#0: *31 socket 16
2014/06/25 18:36:07 [debug] 29435#0: *31 epoll add connection: fd:16 ev:80002005
2014/06/25 18:36:07 [debug] 29435#0: *31 connect to 127.0.0.1:8081, fd:16 #32
2014/06/25 18:36:07 [debug] 29435#0: *31 http upstream connect: -2
2014/06/25 18:36:07 [debug] 29435#0: *31 posix_memalign: 0000000000708A90:128 @16
2014/06/25 18:36:07 [debug] 29435#0: *31 event timer add: 16: 60000:1403692627362
2014/06/25 18:36:07 [debug] 29435#0: *31 http finalize request: -4, "/uri/a?" a:1, c:2
2014/06/25 18:36:07 [debug] 29435#0: *31 http request count:2 blk:0
2014/06/25 18:36:07 [debug] 29435#0: *31 http run request: "/uri/a?"
2014/06/25 18:36:07 [debug] 29435#0: *31 http upstream check client, write event:1, "/uri/a"
2014/06/25 18:36:07 [debug] 29435#0: *31 http upstream recv(): -1 (11: Resource temporarily unavailable)
2014/06/25 18:36:07 [debug] 29435#0: *31 http upstream request: "/uri/a?"
2014/06/25 18:36:07 [debug] 29435#0: *31 http upstream send request handler
2014/06/25 18:36:07 [debug] 29435#0: *31 http upstream send request
2014/06/25 18:36:07 [debug] 29435#0: *31 chain writer buf fl:1 s:133
2014/06/25 18:36:07 [debug] 29435#0: *31 chain writer in: 0000000000722D40
2014/06/25 18:36:07 [debug] 29435#0: *31 writev: 133
2014/06/25 18:36:07 [debug] 29435#0: *31 chain writer out: 0000000000000000
2014/06/25 18:36:07 [debug] 29435#0: *31 event timer del: 16: 1403692627362
2014/06/25 18:36:07 [debug] 29435#0: *31 event timer add: 16: 60000:1403692627363
2014/06/25 18:36:07 [debug] 29435#0: *31 http upstream request: "/uri/a?"
2014/06/25 18:36:07 [debug] 29435#0: *31 http upstream process header
2014/06/25 18:36:07 [debug] 29435#0: *31 malloc: 0000000000723400:4096
2014/06/25 18:36:07 [debug] 29435#0: *31 recv: fd:16 225 of 4043
2014/06/25 18:36:07 [debug] 29435#0: *31 http proxy status 200 "200 OK"
2014/06/25 18:36:07 [debug] 29435#0: *31 http proxy header: "Server: Tengine/1.5.1"
2014/06/25 18:36:07 [debug] 29435#0: *31 http proxy header: "Date: Wed, 25 Jun 2014 10:36:07 GMT"
2014/06/25 18:36:07 [debug] 29435#0: *31 http proxy header: "Content-Type: application/octet-stream"
2014/06/25 18:36:07 [debug] 29435#0: *31 http proxy header: "Content-Length: 2"
2014/06/25 18:36:07 [debug] 29435#0: *31 http proxy header: "Last-Modified: Fri, 14 Mar 2014 10:31:36 GMT"
2014/06/25 18:36:07 [debug] 29435#0: *31 http proxy header: "Connection: close"
2014/06/25 18:36:07 [debug] 29435#0: *31 http proxy header: "Accept-Ranges: bytes"
2014/06/25 18:36:07 [debug] 29435#0: *31 http proxy header done
2014/06/25 18:36:07 [debug] 29435#0: *31 http script var: "MISS"
2014/06/25 18:36:07 [debug] 29435#0: *31 HTTP/1.1 200 OK
2014/06/25 18:36:07 [debug] 29435#0: *31 write new buf t:1 f:0 0000000000723048, pos 0000000000723048, size: 238 file: 0, size: 0
2014/06/25 18:36:07 [debug] 29435#0: *31 http write filter: l:0 f:0 s:238
2014/06/25 18:36:07 [debug] 29435#0: *31 http proxy filter init s:200 h:0 c:0 l:2
2014/06/25 18:36:07 [debug] 29435#0: *31 tcp_nodelay
2014/06/25 18:36:07 [debug] 29435#0: *31 http output filter "/uri/a?"
2014/06/25 18:36:07 [debug] 29435#0: *31 http copy filter: "/uri/a?"
2014/06/25 18:36:07 [debug] 29435#0: *31 http postpone filter "/uri/a?" 00007FFFFFFFE200
2014/06/25 18:36:07 [debug] 29435#0: *31 write old buf t:1 f:0 0000000000723048, pos 0000000000723048, size: 238 file: 0, size: 0
2014/06/25 18:36:07 [debug] 29435#0: *31 write new buf t:0 f:0 0000000000000000, pos 0000000000000000, size: 0 file: 0, size: 0
2014/06/25 18:36:07 [debug] 29435#0: *31 http write filter: l:0 f:1 s:238
2014/06/25 18:36:07 [debug] 29435#0: *31 http write filter limit 8192
2014/06/25 18:36:07 [debug] 29435#0: *31 writev: 238
2014/06/25 18:36:07 [debug] 29435#0: *31 http write filter 0000000000000000
2014/06/25 18:36:07 [debug] 29435#0: *31 event timer add: 15: 1:1403692567364
2014/06/25 18:36:07 [debug] 29435#0: *31 http copy filter: 0 "/uri/a?"
2014/06/25 18:36:07 [debug] 29435#0: *31 http upstream process non buffered upstream
2014/06/25 18:36:07 [debug] 29435#0: *31 recv: fd:16 2 of 4096
2014/06/25 18:36:07 [debug] 29435#0: *31 http output filter "/uri/a?"
2014/06/25 18:36:07 [debug] 29435#0: *31 http copy filter: "/uri/a?"
2014/06/25 18:36:07 [debug] 29435#0: *31 http postpone filter "/uri/a?" 0000000000723218
2014/06/25 18:36:07 [debug] 29435#0: *31 write new buf t:0 f:0 0000000000000000, pos 0000000000723400, size: 2 file: 0, size: 0
2014/06/25 18:36:07 [debug] 29435#0: *31 http write filter: l:0 f:1 s:2
2014/06/25 18:36:07 [debug] 29435#0: *31 http copy filter: -2 "/uri/a?"
2014/06/25 18:36:07 [debug] 29435#0: *31 recv: fd:16 0 of 4094
2014/06/25 18:36:07 [debug] 29435#0: *31 http output filter "/uri/a?"
2014/06/25 18:36:07 [debug] 29435#0: *31 http copy filter: "/uri/a?"
2014/06/25 18:36:07 [debug] 29435#0: *31 http postpone filter "/uri/a?" 0000000000000000
2014/06/25 18:36:07 [debug] 29435#0: *31 write old buf t:0 f:0 0000000000000000, pos 0000000000723400, size: 2 file: 0, size: 0
2014/06/25 18:36:07 [debug] 29435#0: *31 http write filter: l:0 f:1 s:2
2014/06/25 18:36:07 [debug] 29435#0: *31 http copy filter: -2 "/uri/a?"
2014/06/25 18:36:07 [debug] 29435#0: *31 event timer del: 15: 1403692567364
2014/06/25 18:36:07 [debug] 29435#0: *31 event timer: 16, old: 1403692627363, new: 1403692627363
2014/06/25 18:36:07 [debug] 29435#0: *31 http upstream request: "/uri/a?"
2014/06/25 18:36:07 [debug] 29435#0: *31 http upstream dummy handler
2014/06/25 18:36:37 [debug] 29435#0: *31 http upstream request: "/uri/a?"
2014/06/25 18:36:37 [debug] 29435#0: *31 http upstream process non buffered upstream
2014/06/25 18:36:37 [debug] 29435#0: *31 http output filter "/uri/a?"
2014/06/25 18:36:37 [debug] 29435#0: *31 http copy filter: "/uri/a?"
2014/06/25 18:36:37 [debug] 29435#0: *31 http postpone filter "/uri/a?" 0000000000000000
2014/06/25 18:36:37 [debug] 29435#0: *31 write old buf t:0 f:0 0000000000000000, pos 0000000000723400, size: 2 file: 0, size: 0
2014/06/25 18:36:37 [debug] 29435#0: *31 http write filter: l:0 f:1 s:2
2014/06/25 18:36:37 [debug] 29435#0: *31 http copy filter: -2 "/uri/a?"
2014/06/25 18:36:37 [debug] 29435#0: *31 recv: fd:16 0 of 4094
2014/06/25 18:36:37 [debug] 29435#0: *31 http output filter "/uri/a?"
2014/06/25 18:36:37 [debug] 29435#0: *31 http copy filter: "/uri/a?"
2014/06/25 18:36:37 [debug] 29435#0: *31 http postpone filter "/uri/a?" 0000000000000000
2014/06/25 18:36:37 [debug] 29435#0: *31 write old buf t:0 f:0 0000000000000000, pos 0000000000723400, size: 2 file: 0, size: 0
2014/06/25 18:36:37 [debug] 29435#0: *31 http write filter: l:0 f:1 s:2
2014/06/25 18:36:37 [debug] 29435#0: *31 http copy filter: -2 "/uri/a?"
2014/06/25 18:36:37 [debug] 29435#0: *31 event timer del: 16: 1403692627363
2014/06/25 18:36:37 [debug] 29435#0: *31 event timer add: 16: 60000:1403692657639
2014/06/25 18:36:37 [debug] 29435#0: *31 http upstream request: "/uri/a?"
2014/06/25 18:36:37 [debug] 29435#0: *31 http upstream dummy handler
_______________________________________________
nginx-devel mailing list
nginx-devel@nginx.org
http://mailman.nginx.org/mailman/listinfo/nginx-devel