lua-ngx-module version: 0.9.10
nginx version: nginx-1.4.2
Hi，春哥
最近我们的系统在上线之后发现了一个问题，就是在lua代码中调用socket:connect(host, port) 函数，会hang住很久（有时hang甚至1个小时）
打开debug日志，信息如下：
2015/05/29 00:25:39 [debug] 28619#0: *1915458 accept: 10.98.30.53 fd:5576
2015/05/29 00:25:39 [debug] 28619#0: *1915458 event timer add: 5576: 60000:1432830399381
2015/05/29 00:25:39 [debug] 28619#0: *1915458 reusable connection: 1
2015/05/29 00:25:39 [debug] 28619#0: *1915458 epoll add event: fd:5576 op:1 ev:80000001
2015/05/29 00:25:39 [debug] 28619#0: *1915458 post event 00007F050EB225A8
2015/05/29 00:25:39 [debug] 28619#0: *1915458 delete posted event 00007F050EB225A8
2015/05/29 00:25:39 [debug] 28619#0: *1915458 http wait request handler
2015/05/29 00:25:39 [debug] 28619#0: *1915458 posix_memalign: 00000000068FE850:256 @16
2015/05/29 00:25:39 [debug] 28619#0: *1915458 malloc: 00000000068FE960:8192
2015/05/29 00:25:39 [debug] 28619#0: *1915458 recv: fd:5576 337 of 8192
2015/05/29 00:25:39 [debug] 28619#0: *1915458 reusable connection: 0
2015/05/29 00:25:39 [debug] 28619#0: *1915458 posix_memalign: 0000000006900970:4096 @16
2015/05/29 00:25:39 [debug] 28619#0: *1915458 http process request line
2015/05/29 00:25:39 [debug] 28619#0: *1915458 http request line: "**** HTTP/1.1"
2015/05/29 00:25:39 [debug] 28619#0: *1915458 http uri: "****"
2015/05/29 00:25:39 [debug] 28619#0: *1915458 http args: "****"
2015/05/29 00:25:39 [debug] 28619#0: *1915458 http exten: ""
2015/05/29 00:25:39 [debug] 28619#0: *1915458 http process request header line
2015/05/29 00:25:39 [debug] 28619#0: *1915458 http header: "****"
2015/05/29 00:25:39 [debug] 28619#0: *1915458 http header: "HTTP-X-ISIS-CALLID: 0.16"
2015/05/29 00:25:39 [debug] 28619#0: *1915458 http header: "HTTP-X-ISIS-LOGID: 3432949156436116974"
2015/05/29 00:25:39 [debug] 28619#0: *1915458 http header done
2015/05/29 00:25:39 [debug] 28619#0: *1915458 event timer del: 5576: 1432830399381
2015/05/29 00:25:39 [debug] 28619#0: *1915458 generic phase: 0
2015/05/29 00:25:39 [debug] 28619#0: *1915458 rewrite phase: 1
2015/05/29 00:25:39 [debug] 28619#0: *1915458 posix_memalign: 0000000006901980:4096 @16
2015/05/29 00:25:39 [debug] 28619#0: *1915458 http script value: "0"
2015/05/29 00:25:39 [debug] 28619#0: *1915458 http script set $req_log_id
2015/05/29 00:25:39 [debug] 28619#0: *1915458 test location: "/"
2015/05/29 00:25:39 [debug] 28619#0: *1915458 using configuration "/"
2015/05/29 00:25:39 [debug] 28619#0: *1915458 http cl:-1 max:2147483648
2015/05/29 00:25:39 [debug] 28619#0: *1915458 rewrite phase: 3
2015/05/29 00:25:39 [debug] 28619#0: *1915458 post rewrite phase: 4
2015/05/29 00:25:39 [debug] 28619#0: *1915458 generic phase: 5
2015/05/29 00:25:39 [debug] 28619#0: *1915458 generic phase: 6
2015/05/29 00:25:39 [debug] 28619#0: *1915458 generic phase: 7
2015/05/29 00:25:39 [debug] 28619#0: *1915458 access phase: 8
2015/05/29 00:25:39 [debug] 28619#0: *1915458 access phase: 9
2015/05/29 00:25:39 [debug] 28619#0: *1915458 post access phase: 10
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua content handler, uri:"/****" c:1
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua reset ctx
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua creating new thread
2015/05/29 00:25:39 [debug] 28619#0: *1915458 http cleanup add: 0000000006901950
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua run thread, top:0 c:1
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua create ngx.ctx table for the current request
2015/05/29 00:25:39 [debug] 28619#0: *1915458 add cleanup: 0000000006901C00
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua request header: "Host: ****"
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua request header: "HTTP-X-ISIS-CALLID: 0.16"
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua request header: "HTTP-X-ISIS-LOGID: 3432949156436116974"
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua request header: "Host: ****"
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua request header: "HTTP-X-ISIS-CALLID: 0.16"
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua request header: "HTTP-X-ISIS-LOGID: 3432949156436116974"
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua request header: "Host: ****"
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua request header: "HTTP-X-ISIS-CALLID: 0.16"
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua request header: "HTTP-X-ISIS-LOGID: 3432949156436116974"
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 00:25:39 [info] 28619#0: *1915458 ngx_http_lua_socket_tcp_connect start!, client: 10.98.30.53, server: ****, request: "GET / ****", host: " ****"
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua tcp socket pool get keepalive peer
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua tcp socket keepalive connection pool not found
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua tcp socket connect timeout: 3000
2015/05/29 00:25:39 [info] 28619#0: *1915458 ngx_http_lua_socket_tcp_connect end at 760!, client: 10.98.30.53, server: ****, request: " ****", host: "****"
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua resume returned 1
2015/05/29 00:25:39 [debug] 28619#0: *1915458 lua thread yielded
2015/05/29 00:25:39 [debug] 28619#0: *1915458 http finalize request: -4, " ****" a:1, c:2
2015/05/29 00:25:39 [debug] 28619#0: *1915458 http request count:2 blk:0
发现这个地方hang 5 s
2015/05/29 00:25:44 [debug] 28619#0: *1915458 http run request: " ****"
2015/05/29 00:25:44 [debug] 28619#0: *1915458 http reading blocked
发现这个地方开始hang，ngx_http_lua_socket_resolve_handler一直hang着没有触发回调。
2015/05/29 01:14:17 [debug] 28619#0: *1915458 lua tcp socket resolve handler
2015/05/29 01:14:17 [debug] 28619#0: *1915458 name was resolved to ****
2015/05/29 01:14:17 [debug] 28619#0: *1915458 lua tcp operation done, resuming lua thread
2015/05/29 01:14:17 [debug] 28619#0: *1915458 lua tcp socket calling prepare retvals handler 000000000056472B, u:0000000043C9C8B8
2015/05/29 01:14:17 [info] 28619#0: *1915458 ngx_http_lua_socket_resolve_retval_handler start!, client: 10.98.30.53, server: ****, request: "GET ****", host: " ****"
2015/05/29 01:14:17 [debug] 28619#0: *1915458 lua tcp socket resolve retval handler
2015/05/29 01:14:17 [info] 28619#0: *1915458 ngx_event_connect_peer start!, client: 10.98.30.53, server: * ****, request: " ****", host: " ****"
2015/05/29 01:14:17 [debug] 28619#0: *1915458 socket 5577
2015/05/29 01:14:17 [debug] 28619#0: *1915458 epoll add connection: fd:5577 ev:80000005
2015/05/29 01:14:17 [debug] 28619#0: *1915458 connect to ****, fd:5577 #2068387
2015/05/29 01:14:17 [info] 28619#0: *1915458 ngx_event_connect_peer end at 186!, client: 10.98.30.53, server: * ****, request: " ****", host: " ****"
2015/05/29 01:14:17 [debug] 28619#0: *1915458 http cleanup add: 0000000006901DD8
2015/05/29 01:14:17 [debug] 28619#0: *1915458 lua tcp socket connect: -2
2015/05/29 01:14:17 [debug] 28619#0: *1915458 event timer add: 5577: 3000:1432833260080
2015/05/29 01:14:17 [info] 28619#0: *1915458 ngx_http_lua_socket_resolve_retval_handler end at 1191!, client: 10.98.30.53, server: *****, request: "****", host: "****"
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket handler for "****", wev 1
2015/05/29 01:14:24 [debug] 28619#0: *1915458 event timer del: 5577: 1432833260080
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket connected
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket waking up the current request (conn)
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp operation done, resuming lua thread
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket calling prepare retvals handler 00000000005650ED, u:0000000043C9C8B8
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua run thread, top:0 c:1
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [info] 28619#0: *1915458 lua upstream: 0000000043C9C8B8, client: 10.98.30.53, server: *****, request: "****", host: "****"
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket send timeout: 3000
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua allocate new chainlink and new buf of size 357, cl:0000000006901DF0
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket send data
2015/05/29 01:14:24 [debug] 28619#0: *1915458 send: fd:5577 357 of 357
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket sent all the data
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket calling receive() method
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket read timeout: 5000
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua allocate new chainlink and new buf of size 4096, cl:0000000006901FB8
2015/05/29 01:14:24 [debug] 28619#0: *1915458 malloc: 00000000089967F0:4096
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket read data: wait:0
2015/05/29 01:14:24 [debug] 28619#0: *1915458 event timer add: 5577: 5000:1432833269248
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua resume returned 1
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua thread yielded
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua run thread returned -2
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket handler for "****", wev 0
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket read handler
2015/05/29 01:14:24 [debug] 28619#0: *1915458 event timer del: 5577: 1432833269248
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket read data: wait:1
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket try to recv data 4096: "****"
2015/05/29 01:14:24 [debug] 28619#0: *1915458 recv: fd:5577 368 of 4096
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket recv returned 368: "****"
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket read line
"015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket read the final line part: "HTTP/1.1 403 Forbidden
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket receive done: wait:1, eof:0, uri:"****"
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket waking up the current request (read)
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp operation done, resuming lua thread
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket calling prepare retvals handler 00000000005666E4, u:0000000043C9C8B8
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket receive return value handler
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua run thread, top:0 c:1
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket calling receive() method
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket read timeout: 5000
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket read data: wait:0
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket read line
"015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket read the final line part: "Date: Thu, 28 May 2015 17:14:24 GMT
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket receive done: wait:0, eof:0, uri:"****"
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket receive done in a single run
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket receive return value handler
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket calling receive() method
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket read timeout: 5000
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket read data: wait:0
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket read line
"015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket read the final line part: "Content-Type: text/json
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket receive done: wait:0, eof:0, uri:"****"
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket receive done in a single run
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket receive return value handler
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket calling receive() method
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket read timeout: 5000
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket read data: wait:0
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket read line
"015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket read the final line part: "Connection: keep-alive
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket receive done: wait:0, eof:0, uri:"****"
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket receive done in a single run
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket receive return value handler
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket calling receive() method
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket read timeout: 5000
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket read data: wait:0
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket read line
"015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket read the final line part: "****"
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket receive done in a single run
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket receive return value handler
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket calling receive() method
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket read timeout: 5000
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket read data: wait:0
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket read line
"015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket read the final line part: "****"
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket receive done in a single run
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket receive return value handler
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket calling receive() method
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket read timeout: 5000
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket read data: wait:0
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket read line
"015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket read the final line part: "Content-Length: 62
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket receive done: wait:0, eof:0, uri:"****"
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket receive done in a single run
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket receive return value handler
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket calling receive() method
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket read timeout: 5000
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket read data: wait:0
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket read line
"015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket read the final line part: "Server: **** 1.0
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket receive done: wait:0, eof:0, uri:"****"
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket receive done in a single run
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket receive return value handler
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket calling receive() method
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket read timeout: 5000
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket read data: wait:0
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket read line
"015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket read the final line part: "
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket receive done: wait:0, eof:0, uri:"****"
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket receive done in a single run
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket receive return value handler
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket calling receive() method
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket read timeout: 5000
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket read data: wait:0
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket read chunk 62
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket receive done: wait:0, eof:0, uri:"****"
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket receive done in a single run
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket receive return value handler
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket set keepalive: saving connection 00007F050EC9F010
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket clear current socket connection
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua tcp socket keepalive timeout: 60000 ms
2015/05/29 01:14:24 [debug] 28619#0: *1915458 event timer add: 5577: 60000:1432833324756
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua finalize socket
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua send headers
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua capture header filter, uri "/****"
2015/05/29 01:14:24 [debug] 28619#0: *1915458 HTTP/1.1 403 Forbidden
2015/05/29 01:14:24 [debug] 28619#0: *1915458 write new buf t:1 f:0 00000000069021E8, pos 00000000069021E8, size: 330 file: 0, size: 0
2015/05/29 01:14:24 [debug] 28619#0: *1915458 http write filter: l:0 f:0 s:330
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua reuse free buf memory 357 >= 62, cl:0000000006901DF0, p:0000000006901E50
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua print response
2015/05/29 01:14:24 [debug] 28619#0: *1915458 http output filter "****"
2015/05/29 01:14:24 [debug] 28619#0: *1915458 http copy filter: "****"
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua capture body filter, uri "****" 0000000006901DF0
2015/05/29 01:14:24 [debug] 28619#0: *1915458 write old buf t:1 f:0 00000000069021E8, pos 00000000069021E8, size: 330 file: 0, size: 0
2015/05/29 01:14:24 [debug] 28619#0: *1915458 write new buf t:1 f:0 0000000006901E50, pos 0000000006901E50, size: 62 file: 0, size: 0
2015/05/29 01:14:24 [debug] 28619#0: *1915458 http write filter: l:0 f:0 s:392
2015/05/29 01:14:24 [debug] 28619#0: *1915458 http copy filter: 0 "****"
2015/05/29 01:14:24 [debug] 28619#0: *1915458 http output filter "****"
2015/05/29 01:14:24 [debug] 28619#0: *1915458 http copy filter: "****"
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua capture body filter, uri "/****"
2015/05/29 01:14:24 [debug] 28619#0: *1915458 http postpone filter "/****" 0000000006902410
2015/05/29 01:14:24 [debug] 28619#0: *1915458 write old buf t:1 f:0 00000000069021E8, pos 00000000069021E8, size: 330 file: 0, size: 0
2015/05/29 01:14:24 [debug] 28619#0: *1915458 write old buf t:1 f:0 0000000006901E50, pos 0000000006901E50, size: 62 file: 0, size: 0
2015/05/29 01:14:24 [debug] 28619#0: *1915458 write new buf t:0 f:0 0000000000000000, pos 0000000000000000, size: 0 file: 0, size: 0
2015/05/29 01:14:24 [debug] 28619#0: *1915458 http write filter: l:0 f:1 s:392
2015/05/29 01:14:24 [debug] 28619#0: *1915458 http write filter limit 0
2015/05/29 01:14:24 [debug] 28619#0: *1915458 writev: 392
2015/05/29 01:14:24 [debug] 28619#0: *1915458 http write filter 0000000000000000
2015/05/29 01:14:24 [debug] 28619#0: *1915458 http copy filter: 0 "****"
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua flush asynchronously
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua fetching existing ngx.ctx table for the current request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua exit with code 200
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua resume returned 1
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua thread yielded
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua thread aborting request with status 200
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua request cleanup: forcible=0
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua sending last buf of the response body
2015/05/29 01:14:24 [debug] 28619#0: *1915458 http output filter "****"
2015/05/29 01:14:24 [debug] 28619#0: *1915458 http copy filter: "****"
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua capture body filter, uri "****" 00007FFFB3C04CE0
2015/05/29 01:14:24 [debug] 28619#0: *1915458 write new buf t:0 f:0 0000000000000000, pos 0000000000000000, size: 0 file: 0, size: 0
2015/05/29 01:14:24 [debug] 28619#0: *1915458 http write filter: l:1 f:0 s:0
2015/05/29 01:14:24 [debug] 28619#0: *1915458 http copy filter: 0 "****"
2015/05/29 01:14:24 [debug] 28619#0: *1915458 lua run thread returned 0
2015/05/29 01:14:24 [debug] 28619#0: *1915458 http finalize request: 0, "****" a:1, c:1
2015/05/29 01:14:24 [debug] 28619#0: *1915458 set http keepalive handler
2015/05/29 01:14:24 [debug] 28619#0: *1915458 http close request
2015/05/29 01:14:24 [debug] 28619#0: *1915458 http log handler
2015/05/29 01:14:24 [debug] 28619#0: *1915458 run cleanup: 0000000006901C00
2015/05/29 01:14:24 [debug] 28619#0: *1915458 free: 00000000089967F0
2015/05/29 01:14:24 [debug] 28619#0: *1915458 free: 0000000006900970, unused: 1
2015/05/29 01:14:24 [debug] 28619#0: *1915458 free: 0000000006901980, unused: 475
2015/05/29 01:14:24 [debug] 28619#0: *1915458 free: 00000000068FE960
2015/05/29 01:14:24 [debug] 28619#0: *1915458 hc free: 0000000000000000 0
2015/05/29 01:14:24 [debug] 28619#0: *1915458 hc busy: 0000000000000000 0
2015/05/29 01:14:24 [debug] 28619#0: *1915458 tcp_nodelay
2015/05/29 01:14:24 [debug] 28619#0: *1915458 reusable connection: 1
2015/05/29 01:14:24 [debug] 28619#0: *1915458 event timer add: 5576: 5000:1432833269756
2015/05/29 01:14:24 [debug] 28619#0: *1915458 post event 00007F050EB225A8
2015/05/29 01:14:24 [debug] 28619#0: *1915458 delete posted event 00007F050EB225A8
2015/05/29 01:14:24 [debug] 28619#0: *1915458 http keepalive handler
2015/05/29 01:14:24 [debug] 28619#0: *1915458 malloc: 0000000000DE9B80:8192
2015/05/29 01:14:24 [debug] 28619#0: *1915458 recv: fd:5576 0 of 8192
2015/05/29 01:14:24 [info] 28619#0: *1915458 client 10.98.30.53 closed keepalive connection
2015/05/29 01:14:24 [debug] 28619#0: *1915458 close http connection: 5576
2015/05/29 01:14:24 [debug] 28619#0: *1915458 event timer del: 5576: 1432833269756
2015/05/29 01:14:24 [debug] 28619#0: *1915458 reusable connection: 0
2015/05/29 01:14:24 [debug] 28619#0: *1915458 free: 0000000000DE9B80
2015/05/29 01:14:24 [debug] 28619#0: *1915458 free: 00000000068FE740, unused: 0
2015/05/29 01:14:24 [debug] 28619#0: *1915458 free: 00000000068FE850, unused: 112
这个connect hang问题，并不是时刻发生，有时会爆发。觉得是不是跟 resolve host name有关？我看了nginx 1.6.2 的Changes，Bugfix： request might hang if resolver was used and a DNS server return a malformed response.
但是nginx源码不是很懂，所以没有找到证据。。。
