处理较大body是遭遇reading blocked

night.zk89

rewrite阶段会使用lua读取http相关参数信息；

access阶段使用第三方模块，与远程服务器交互做一些检测工作，最后在post回当前请求，发生阻塞。

下面是nginx debug日志

2017/09/18 10:30:11 [debug] 36339#0: *406589 accept: 10.121.76.118:63334 fd:8

2017/09/18 10:30:11 [debug] 36339#0: *406589 event timer add: 8: 60000:1505701871936

2017/09/18 10:30:11 [debug] 36339#0: *406589 reusable connection: 1

2017/09/18 10:30:11 [debug] 36339#0: *406589 epoll add event: fd:8 op:1 ev:80002001

2017/09/18 10:30:11 [debug] 36339#0: *406589 http wait request handler

2017/09/18 10:30:11 [debug] 36339#0: *406589 malloc: 0000000001AF4010:1024

2017/09/18 10:30:11 [debug] 36339#0: *406589 recv: fd:8 1024 of 1024

2017/09/18 10:30:11 [debug] 36339#0: *406589 reusable connection: 0

2017/09/18 10:30:11 [debug] 36339#0: *406589 posix_memalign: 0000000001AE9F60:4096 @16

2017/09/18 10:30:11 [debug] 36339#0: *406589 http process request line

2017/09/18 10:30:11 [debug] 36339#0: *406589 http request line: "POST /waf HTTP/1.1"

2017/09/18 10:30:11 [debug] 36339#0: *406589 http uri: "/waf"

2017/09/18 10:30:11 [debug] 36339#0: *406589 http args: ""

2017/09/18 10:30:11 [debug] 36339#0: *406589 http exten: ""

2017/09/18 10:30:11 [debug] 36339#0: *406589 http process request header line

2017/09/18 10:30:11 [debug] 36339#0: *406589 http header: "User-Agent: curl/7.29.0"

2017/09/18 10:30:11 [debug] 36339#0: *406589 http header: "Host: 10.23.80.1"

2017/09/18 10:30:11 [debug] 36339#0: *406589 http header: "Accept: */*"

2017/09/18 10:30:11 [debug] 36339#0: *406589 http header: "Content-Length: 904"

2017/09/18 10:30:11 [debug] 36339#0: *406589 http header: "Content-Type: application/x-www-form-urlencoded"

2017/09/18 10:30:11 [debug] 36339#0: *406589 http header done

2017/09/18 10:30:11 [debug] 36339#0: *406589 event timer del: 8: 1505701871936

2017/09/18 10:30:11 [debug] 36339#0: *406589 rewrite phase: 0

2017/09/18 10:30:11 [debug] 36339#0: *406589 posix_memalign: 0000000001AA13F0:4096 @16

2017/09/18 10:30:11 [debug] 36339#0: *406589 http script value: "test_env"

2017/09/18 10:30:11 [debug] 36339#0: *406589 http script set $business_name

2017/09/18 10:30:11 [debug] 36339#0: *406589 test location: "/"

2017/09/18 10:30:11 [debug] 36339#0: *406589 test location: "ct"

2017/09/18 10:30:11 [debug] 36339#0: *406589 test location: "waf"

2017/09/18 10:30:11 [debug] 36339#0: *406589 using configuration "/waf"

2017/09/18 10:30:11 [debug] 36339#0: *406589 http cl:904 max:1048576

2017/09/18 10:30:11 [debug] 36339#0: *406589 rewrite phase: 2

2017/09/18 10:30:11 [debug] 36339#0: *406589 lua rewrite handler, uri:"/waf" c:1

2017/09/18 10:30:11 [debug] 36339#0: *406589 rewrite phase: 2

2017/09/18 10:30:11 [debug] 36339#0: *406589 rewrite phase: 3

2017/09/18 10:30:11 [debug] 36339#0: *406589 lua rewrite handler, uri:"/waf" c:1

2017/09/18 10:30:11 [debug] 36339#0: *406589 lua creating new thread

2017/09/18 10:30:11 [debug] 36339#0: *406589 lua reset ctx

2017/09/18 10:30:11 [debug] 36339#0: *406589 http cleanup add: 0000000001AEAF48

2017/09/18 10:30:11 [debug] 36339#0: *406589 lua run thread, top:0 c:1

2017/09/18 10:30:11 [debug] 36339#0: *406589 add cleanup: 0000000001AA16C8

2017/09/18 10:30:11 [debug] 36339#0: *406589 lua start to read buffered request body

2017/09/18 10:30:11 [debug] 36339#0: *406589 http client request body preread 876

2017/09/18 10:30:11 [debug] 36339#0: *406589 http request body content length filter

2017/09/18 10:30:11 [debug] 36339#0: *406589 http body new buf t:1 f:0 0000000001AF40A4, pos 0000000001AF40A4, size: 876 file: 0, size: 0

2017/09/18 10:30:11 [debug] 36339#0: *406589 http read client request body

2017/09/18 10:30:11 [debug] 36339#0: *406589 recv: fd:8 28 of 28

2017/09/18 10:30:11 [debug] 36339#0: *406589 http client request body recv 28

2017/09/18 10:30:11 [debug] 36339#0: *406589 http body old buf t:1 f:0 0000000001AF40A4, pos 0000000001AF40A4, size: 876 file: 0, size: 0

2017/09/18 10:30:11 [debug] 36339#0: *406589 http body new buf t:1 f:0 0000000001AA1830, pos 0000000001AA1830, size: 28 file: 0, size: 0

2017/09/18 10:30:11 [debug] 36339#0: *406589 http client request body rest 0

2017/09/18 10:30:11 [debug] 36339#0: *406589 lua req body post read, c:2

2017/09/18 10:30:11 [debug] 36339#0: *406589 lua has read buffered request body in a single run

2017/09/18 10:30:11 [debug] 36339#0: *406589 lua resume returned 0

2017/09/18 10:30:11 [debug] 36339#0: *406589 lua light thread ended normally

2017/09/18 10:30:11 [debug] 36339#0: *406589 lua deleting light thread

2017/09/18 10:30:11 [debug] 36339#0: *406589 post rewrite phase: 4

2017/09/18 10:30:11 [debug] 36339#0: *406589 generic phase: 5

2017/09/18 10:30:11 [debug] 36339#0: *406589 generic phase: 6

2017/09/18 10:30:11 [debug] 36339#0: *406589 access phase: 7

2017/09/18 10:30:11 [debug] 36339#0: *406589 posix_memalign: 0000000001A8A5B0:4096 @16

2017/09/18 10:30:11 [debug] 36339#0: *406589 http subrequest "@skynet?"

2017/09/18 10:30:11 [debug] 36339#0: *406589 test location: "@skynet"

2017/09/18 10:30:11 [debug] 36339#0: *406589 using location: @skynet "@skynet?"

2017/09/18 10:30:11 [debug] 36339#0: *406589 rewrite phase: 2

2017/09/18 10:30:11 [debug] 36339#0: *406589 rewrite phase: 3

2017/09/18 10:30:11 [debug] 36339#0: *406589 lua rewrite handler, uri:"@skynet" c:4

2017/09/18 10:30:11 [debug] 36339#0: *406589 post rewrite phase: 4

2017/09/18 10:30:11 [debug] 36339#0: *406589 generic phase: 5

2017/09/18 10:30:11 [debug] 36339#0: *406589 generic phase: 6

2017/09/18 10:30:11 [debug] 36339#0: *406589 http init upstream, client timer: 0

2017/09/18 10:30:11 [debug] 36339#0: *406589 epoll add event: fd:8 op:3 ev:80002005

2017/09/18 10:30:11 [debug] 36339#0: *406589 http cleanup add: 0000000001A8B568

2017/09/18 10:30:11 [debug] 36339#0: *406589 init keepalive peer

2017/09/18 10:30:11 [debug] 36339#0: *406589 posix_memalign: 0000000001AF0740:4096 @16

2017/09/18 10:30:11 [debug] 36339#0: *406589 get keepalive peer

2017/09/18 10:30:11 [debug] 36339#0: *406589 get rr peer, try: 1

2017/09/18 10:30:11 [debug] 36339#0: *406589 stream socket 19

2017/09/18 10:30:11 [debug] 36339#0: *406589 epoll add connection: fd:19 ev:80002005

2017/09/18 10:30:11 [debug] 36339#0: *406589 connect to 10.153.120.133:8000, fd:19 #406590

2017/09/18 10:30:11 [debug] 36339#0: *406589 http upstream connect: -2

2017/09/18 10:30:11 [debug] 36339#0: *406589 posix_memalign: 0000000001AE5800:128 @16

2017/09/18 10:30:11 [debug] 36339#0: *406589 event timer add: 19: 1000:1505701812938

2017/09/18 10:30:11 [debug] 36339#0: *406589 http finalize request: -4, "@skynet?" a:1, c:5

2017/09/18 10:30:11 [debug] 36339#0: *406589 http request count:5 blk:0

2017/09/18 10:30:11 [debug] 36339#0: *406589 http finalize request: -4, "@skynet?" a:1, c:4

2017/09/18 10:30:11 [debug] 36339#0: *406589 http request count:4 blk:0

2017/09/18 10:30:11 [debug] 36339#0: *406589 http posted request: "@skynet?"

2017/09/18 10:30:11 [debug] 36339#0: *406589 http upstream check client, write event:1, "@skynet"

2017/09/18 10:30:11 [debug] 36339#0: *406589 http upstream recv(): -1 (11: Resource temporarily unavailable)

2017/09/18 10:30:11 [debug] 36339#0: *406589 http run request: "@skynet?"

2017/09/18 10:30:11 [debug] 36339#0: *406589 http upstream check client, write event:1, "@skynet"

2017/09/18 10:30:11 [debug] 36339#0: *406589 http upstream recv(): -1 (11: Resource temporarily unavailable)

2017/09/18 10:30:11 [debug] 36339#0: *406589 http upstream request: "@skynet?"

2017/09/18 10:30:11 [debug] 36339#0: *406589 http upstream send request handler

2017/09/18 10:30:11 [debug] 36339#0: *406589 http upstream send request

2017/09/18 10:30:11 [debug] 36339#0: *406589 http upstream send request body

2017/09/18 10:30:11 [debug] 36339#0: *406589 chain writer buf fl:0 s:5

2017/09/18 10:30:11 [debug] 36339#0: *406589 chain writer buf fl:0 s:148

2017/09/18 10:30:11 [debug] 36339#0: *406589 chain writer buf fl:0 s:5

2017/09/18 10:30:11 [debug] 36339#0: *406589 chain writer buf fl:0 s:876

2017/09/18 10:30:11 [debug] 36339#0: *406589 chain writer buf fl:0 s:28

2017/09/18 10:30:11 [debug] 36339#0: *406589 chain writer buf fl:0 s:5

2017/09/18 10:30:11 [debug] 36339#0: *406589 chain writer buf fl:0 s:109

2017/09/18 10:30:11 [debug] 36339#0: *406589 chain writer in: 0000000001AF0808

2017/09/18 10:30:11 [debug] 36339#0: *406589 writev: 1176 of 1176

2017/09/18 10:30:11 [debug] 36339#0: *406589 chain writer out: 0000000000000000

2017/09/18 10:30:11 [debug] 36339#0: *406589 event timer del: 19: 1505701812938

2017/09/18 10:30:11 [debug] 36339#0: *406589 event timer add: 19: 1000:1505701812990

2017/09/18 10:30:12 [debug] 36339#0: *406589 http upstream request: "@skynet?"

2017/09/18 10:30:12 [debug] 36339#0: *406589 http upstream process header

2017/09/18 10:30:12 [debug] 36339#0: *406589 malloc: 0000000001AAE1B0:4096

2017/09/18 10:30:12 [debug] 36339#0: *406589 recv: fd:19 6 of 4096

2017/09/18 10:30:12 [debug] 36339#0: *406589 finalize http upstream request: 0

2017/09/18 10:30:12 [debug] 36339#0: *406589 free keepalive peer

2017/09/18 10:30:12 [debug] 36339#0: *406589 free keepalive peer: saving connection 00007F09F288F6A0

2017/09/18 10:30:12 [debug] 36339#0: *406589 event timer del: 19: 1505701812990

2017/09/18 10:30:12 [debug] 36339#0: *406589 free rr peer 1 0

2017/09/18 10:30:12 [debug] 36339#0: *406589 http finalize request: 0, "@skynet?" a:1, c:3

2017/09/18 10:30:12 [debug] 36339#0: *406589 http finalize request: -4, "@skynet?" a:1, c:3

2017/09/18 10:30:12 [debug] 36339#0: *406589 http request count:3 blk:0

2017/09/18 10:30:12 [debug] 36339#0: *406589 http wake parent request: "/waf?"

2017/09/18 10:30:12 [debug] 36339#0: *406589 http posted request: "/waf?"

2017/09/18 10:30:12 [debug] 36339#0: *406589 http request empty handler

2017/09/18 10:31:59 [debug] 36339#0: *406589 http run request: "/waf?"

2017/09/18 10:31:59 [debug] 36339#0: *406589 http reading blocked

2017/09/18 10:31:59 [debug] 36339#0: *406589 http run request: "/waf?"

2017/09/18 10:31:59 [debug] 36339#0: *406589 http request empty handler

同样的请求，减少body的长度，则不会出现阻塞情况；

下面是正常情况下nginx debug日志：

2017/09/18 10:50:22 [debug] 36339#0: *408088 accept: 10.121.76.118:64790 fd:25

2017/09/18 10:50:22 [debug] 36339#0: *408088 event timer add: 25: 60000:1505703082116

2017/09/18 10:50:22 [debug] 36339#0: *408088 reusable connection: 1

2017/09/18 10:50:22 [debug] 36339#0: *408088 epoll add event: fd:25 op:1 ev:80002001

2017/09/18 10:50:22 [debug] 36339#0: *408088 http wait request handler

2017/09/18 10:50:22 [debug] 36339#0: *408088 malloc: 0000000001AEF240:1024

2017/09/18 10:50:22 [debug] 36339#0: *408088 recv: fd:25 889 of 1024

2017/09/18 10:50:22 [debug] 36339#0: *408088 reusable connection: 0

2017/09/18 10:50:22 [debug] 36339#0: *408088 posix_memalign: 0000000001A6DB20:4096 @16

2017/09/18 10:50:22 [debug] 36339#0: *408088 http process request line

2017/09/18 10:50:22 [debug] 36339#0: *408088 http request line: "POST /waf HTTP/1.1"

2017/09/18 10:50:22 [debug] 36339#0: *408088 http uri: "/waf"

2017/09/18 10:50:22 [debug] 36339#0: *408088 http args: ""

2017/09/18 10:50:22 [debug] 36339#0: *408088 http exten: ""

2017/09/18 10:50:22 [debug] 36339#0: *408088 http process request header line

2017/09/18 10:50:22 [debug] 36339#0: *408088 http header: "User-Agent: curl/7.29.0"

2017/09/18 10:50:22 [debug] 36339#0: *408088 http header: "Host: 10.23.80.1"

2017/09/18 10:50:22 [debug] 36339#0: *408088 http header: "Accept: */*"

2017/09/18 10:50:22 [debug] 36339#0: *408088 http header: "Content-Length: 741"

2017/09/18 10:50:22 [debug] 36339#0: *408088 http header: "Content-Type: application/x-www-form-urlencoded"

2017/09/18 10:50:22 [debug] 36339#0: *408088 http header done

2017/09/18 10:50:22 [debug] 36339#0: *408088 event timer del: 25: 1505703082116

2017/09/18 10:50:22 [debug] 36339#0: *408088 rewrite phase: 0

2017/09/18 10:50:22 [debug] 36339#0: *408088 posix_memalign: 0000000001AF95F0:4096 @16

2017/09/18 10:50:22 [debug] 36339#0: *408088 http script value: "test_env"

2017/09/18 10:50:22 [debug] 36339#0: *408088 http script set $business_name

2017/09/18 10:50:22 [debug] 36339#0: *408088 test location: "/"

2017/09/18 10:50:22 [debug] 36339#0: *408088 test location: "ct"

2017/09/18 10:50:22 [debug] 36339#0: *408088 test location: "waf"

2017/09/18 10:50:22 [debug] 36339#0: *408088 using configuration "/waf"

2017/09/18 10:50:22 [debug] 36339#0: *408088 http cl:741 max:1048576

2017/09/18 10:50:22 [debug] 36339#0: *408088 rewrite phase: 2

2017/09/18 10:50:22 [debug] 36339#0: *408088 rewrite phase: 3

2017/09/18 10:50:22 [debug] 36339#0: *408088 lua rewrite handler, uri:"/waf" c:1

2017/09/18 10:50:22 [debug] 36339#0: *408088 lua creating new thread

2017/09/18 10:50:22 [debug] 36339#0: *408088 lua reset ctx

2017/09/18 10:50:22 [debug] 36339#0: *408088 http cleanup add: 0000000001A6EB08

2017/09/18 10:50:22 [debug] 36339#0: *408088 lua run thread, top:0 c:1

2017/09/18 10:50:22 [debug] 36339#0: *408088 add cleanup: 0000000001AF98C8

2017/09/18 10:50:22 [debug] 36339#0: *408088 lua start to read buffered request body

2017/09/18 10:50:22 [debug] 36339#0: *408088 http client request body preread 741

2017/09/18 10:50:22 [debug] 36339#0: *408088 http request body content length filter

2017/09/18 10:50:22 [debug] 36339#0: *408088 http body new buf t:1 f:0 0000000001AEF2D4, pos 0000000001AEF2D4, size: 741 file: 0, size: 0

2017/09/18 10:50:22 [debug] 36339#0: *408088 lua req body post read, c:2

2017/09/18 10:50:22 [debug] 36339#0: *408088 lua has read buffered request body in a single run

2017/09/18 10:50:22 [debug] 36339#0: *408088 lua resume returned 0

2017/09/18 10:50:22 [debug] 36339#0: *408088 lua light thread ended normally

2017/09/18 10:50:22 [debug] 36339#0: *408088 lua deleting light thread

2017/09/18 10:50:22 [debug] 36339#0: *408088 post rewrite phase: 4

2017/09/18 10:50:22 [debug] 36339#0: *408088 generic phase: 5

2017/09/18 10:50:22 [debug] 36339#0: *408088 generic phase: 6

2017/09/18 10:50:22 [debug] 36339#0: *408088 access phase: 7

2017/09/18 10:50:22 [debug] 36339#0: *408088 posix_memalign: 0000000001A7A120:4096 @16

2017/09/18 10:50:22 [debug] 36339#0: *408088 http subrequest "@skynet?"

2017/09/18 10:50:22 [debug] 36339#0: *408088 test location: "@skynet"

2017/09/18 10:50:22 [debug] 36339#0: *408088 using location: @skynet "@skynet?"

2017/09/18 10:50:22 [debug] 36339#0: *408088 rewrite phase: 2

2017/09/18 10:50:22 [debug] 36339#0: *408088 rewrite phase: 3

2017/09/18 10:50:22 [debug] 36339#0: *408088 lua rewrite handler, uri:"@skynet" c:4

2017/09/18 10:50:22 [debug] 36339#0: *408088 post rewrite phase: 4

2017/09/18 10:50:22 [debug] 36339#0: *408088 generic phase: 5

2017/09/18 10:50:22 [debug] 36339#0: *408088 generic phase: 6

2017/09/18 10:50:22 [debug] 36339#0: *408088 http init upstream, client timer: 0

2017/09/18 10:50:22 [debug] 36339#0: *408088 epoll add event: fd:25 op:3 ev:80002005

2017/09/18 10:50:22 [debug] 36339#0: *408088 http cleanup add: 0000000001A7AB88

2017/09/18 10:50:22 [debug] 36339#0: *408088 init keepalive peer

2017/09/18 10:50:22 [debug] 36339#0: *408088 get keepalive peer

2017/09/18 10:50:22 [debug] 36339#0: *408088 get rr peer, try: 1

2017/09/18 10:50:22 [debug] 36339#0: *408088 streahttp upstream recv()m socket 27

2017/09/18 10:50:22 [debug] 36339#0: *408088 epoll add connection: fd:27 ev:80002005

2017/09/18 10:50:22 [debug] 36339#0: *408088 connect to 10.153.120.133:8000, fd:27 #408089

2017/09/18 10:50:22 [debug] 36339#0: *408088 http upstream connect: -2

2017/09/18 10:50:22 [debug] 36339#0: *408088 posix_memalign: 0000000001AA33A0:128 @16

2017/09/18 10:50:22 [debug] 36339#0: *408088 event timer add: 27: 1000:1505703023117

2017/09/18 10:50:22 [debug] 36339#0: *408088 http finalize request: -4, "@skynet?" a:1, c:5

2017/09/18 10:50:22 [debug] 36339#0: *408088 http request count:5 blk:0

2017/09/18 10:50:22 [debug] 36339#0: *408088 http finalize request: -4, "@skynet?" a:1, c:4

2017/09/18 10:50:22 [debug] 36339#0: *408088 http request count:4 blk:0

2017/09/18 10:50:22 [debug] 36339#0: *408088 http posted request: "@skynet?"

2017/09/18 10:50:22 [debug] 36339#0: *408088 http upstream check client, write event:1, "@skynet"

2017/09/18 10:50:22 [debug] 36339#0: *408088 http upstream recv(): -1 (11: Resource temporarily unavailable)

2017/09/18 10:50:22 [debug] 36339#0: *408088 http run request: "@skynet?"

2017/09/18 10:50:22 [debug] 36339#0: *408088 http upstream check client, write event:1, "@skynet"

2017/09/18 10:50:22 [debug] 36339#0: *408088 http upstream recv(): -1 (11: Resource temporarily unavailable)

2017/09/18 10:50:22 [debug] 36339#0: *408088 http upstream request: "@skynet?"

2017/09/18 10:50:22 [debug] 36339#0: *408088 http upstream send request handler

2017/09/18 10:50:22 [debug] 36339#0: *408088 http upstream send request

2017/09/18 10:50:22 [debug] 36339#0: *408088 http upstream send request body

2017/09/18 10:50:22 [debug] 36339#0: *408088 chain writer buf fl:0 s:5

2017/09/18 10:50:22 [debug] 36339#0: *408088 chain writer buf fl:0 s:148

2017/09/18 10:50:22 [debug] 36339#0: *408088 chain writer buf fl:0 s:5

2017/09/18 10:50:22 [debug] 36339#0: *408088 chain writer buf fl:0 s:741

2017/09/18 10:50:22 [debug] 36339#0: *408088 chain writer buf fl:0 s:5

2017/09/18 10:50:22 [debug] 36339#0: *408088 chain writer buf fl:0 s:109

2017/09/18 10:50:22 [debug] 36339#0: *408088 chain writer in: 0000000001A7AC68

2017/09/18 10:50:22 [debug] 36339#0: *408088 writev: 1013 of 1013

2017/09/18 10:50:22 [debug] 36339#0: *408088 chain writer out: 0000000000000000

2017/09/18 10:50:22 [debug] 36339#0: *408088 event timer del: 27: 1505703023117

2017/09/18 10:50:22 [debug] 36339#0: *408088 event timer add: 27: 1000:1505703023167

2017/09/18 10:50:22 [debug] 36339#0: *408088 http upstream request: "@skynet?"

2017/09/18 10:50:22 [debug] 36339#0: *408088 http upstream process header

2017/09/18 10:50:22 [debug] 36339#0: *408088 malloc: 0000000001AE8040:4096

2017/09/18 10:50:22 [debug] 36339#0: *408088 recv: fd:27 6 of 4096

2017/09/18 10:50:22 [debug] 36339#0: *408088 finalize http upstream request: 0

2017/09/18 10:50:22 [debug] 36339#0: *408088 free keepalive peer

2017/09/18 10:50:22 [debug] 36339#0: *408088 free keepalive peer: saving connection 00007F09F288FA60

2017/09/18 10:50:22 [debug] 36339#0: *408088 event timer del: 27: 1505703023167

2017/09/18 10:50:22 [debug] 36339#0: *408088 free rr peer 1 0

2017/09/18 10:50:22 [debug] 36339#0: *408088 http finalize request: 0, "@skynet?" a:1, c:3

2017/09/18 10:50:22 [debug] 36339#0: *408088 http finalize request: -4, "@skynet?" a:1, c:3

2017/09/18 10:50:22 [debug] 36339#0: *408088 http request count:3 blk:0

2017/09/18 10:50:22 [debug] 36339#0: *408088 http wake parent request: "/waf?"

2017/09/18 10:50:22 [debug] 36339#0: *408088 http posted request: "/waf?"

2017/09/18 10:50:22 [debug] 36339#0: *408088 access phase: 7

2017/09/18 10:50:22 [debug] 36339#0: *408088 access phase: 8

2017/09/18 10:50:22 [debug] 36339#0: *408088 access phase: 9

2017/09/18 10:50:22 [debug] 36339#0: *408088 post access phase: 10

2017/09/18 10:50:22 [debug] 36339#0: *408088 lua content handler, uri:"/waf" c:1

2017/09/18 10:50:22 [debug] 36339#0: *408088 lua reset ctx

2017/09/18 10:50:22 [debug] 36339#0: *408088 lua creating new thread

2017/09/18 10:50:22 [debug] 36339#0: *408088 lua run thread, top:0 c:1

2017/09/18 10:50:22 [debug] 36339#0: *408088 lua allocate new chainlink and new buf of size 21, cl:0000000001A7AC58

2017/09/18 10:50:22 [debug] 36339#0: *408088 lua say response

2017/09/18 10:50:22 [debug] 36339#0: *408088 lua capture header filter, uri "/waf"

2017/09/18 10:50:22 [debug] 36339#0: *408088 HTTP/1.1 200 OK

2017/09/18 10:50:22 [debug] 36339#0: *408088 write new buf t:1 f:0 0000000001A7AF48, pos 0000000001A7AF48, size: 170 file: 0, size: 0

2017/09/18 10:50:22 [debug] 36339#0: *408088 http write filter: l:0 f:0 s:170

2017/09/18 10:50:22 [debug] 36339#0: *408088 http output filter "/waf?"

2017/09/18 10:50:22 [debug] 36339#0: *408088 http copy filter: "/waf?"

2017/09/18 10:50:22 [debug] 36339#0: *408088 lua capture body filter, uri "/waf"

2017/09/18 10:50:22 [debug] 36339#0: *408088 http postpone filter "/waf?" 0000000001A7AC58

2017/09/18 10:50:22 [debug] 36339#0: *408088 http chunk: 21

2017/09/18 10:50:22 [debug] 36339#0: *408088 write old buf t:1 f:0 0000000001A7AF48, pos 0000000001A7AF48, size: 170 file: 0, size: 0

2017/09/18 10:50:22 [debug] 36339#0: *408088 write new buf t:1 f:0 0000000001A7B0B0, pos 0000000001A7B0B0, size: 4 file: 0, size: 0

2017/09/18 10:50:22 [debug] 36339#0: *408088 write new buf t:1 f:0 0000000001A7AEC8, pos 0000000001A7AEC8, size: 21 file: 0, size: 0

2017/09/18 10:50:22 [debug] 36339#0: *408088 write new buf t:0 f:0 0000000000000000, pos 00000000004E6526, size: 2 file: 0, size: 0

2017/09/18 10:50:22 [debug] 36339#0: *408088 http write filter: l:0 f:0 s:197

2017/09/18 10:50:22 [debug] 36339#0: *408088 http copy filter: 0 "/waf?"

2017/09/18 10:50:22 [debug] 36339#0: *408088 lua resume returned 0

2017/09/18 10:50:22 [debug] 36339#0: *408088 lua light thread ended normally

2017/09/18 10:50:22 [debug] 36339#0: *408088 lua deleting light thread

2017/09/18 10:50:22 [debug] 36339#0: *408088 lua sending last buf of the response body

2017/09/18 10:50:22 [debug] 36339#0: *408088 posix_memalign: 0000000001A56620:4096 @16

2017/09/18 10:50:22 [debug] 36339#0: *408088 http output filter "/waf?"

2017/09/18 10:50:22 [debug] 36339#0: *408088 http copy filter: "/waf?"

2017/09/18 10:50:22 [debug] 36339#0: *408088 lua capture body filter, uri "/waf"

2017/09/18 10:50:22 [debug] 36339#0: *408088 http postpone filter "/waf?" 00007FFE76DB9B50

2017/09/18 10:50:22 [debug] 36339#0: *408088 http chunk: 0

2017/09/18 10:50:22 [debug] 36339#0: *408088 write old buf t:1 f:0 0000000001A7AF48, pos 0000000001A7AF48, size: 170 file: 0, size: 0

2017/09/18 10:50:22 [debug] 36339#0: *408088 write old buf t:1 f:0 0000000001A7B0B0, pos 0000000001A7B0B0, size: 4 file: 0, size: 0

2017/09/18 10:50:22 [debug] 36339#0: *408088 write old buf t:1 f:0 0000000001A7AEC8, pos 0000000001A7AEC8, size: 21 file: 0, size: 0

2017/09/18 10:50:22 [debug] 36339#0: *408088 write old buf t:0 f:0 0000000000000000, pos 00000000004E6526, size: 2 file: 0, size: 0

2017/09/18 10:50:22 [debug] 36339#0: *408088 write new buf t:0 f:0 0000000000000000, pos 00000000004E6523, size: 5 file: 0, size: 0

2017/09/18 10:50:22 [debug] 36339#0: *408088 http write filter: l:1 f:0 s:202

2017/09/18 10:50:22 [debug] 36339#0: *408088 http write filter limit 0

2017/09/18 10:50:22 [debug] 36339#0: *408088 writev: 202 of 202

2017/09/18 10:50:22 [debug] 36339#0: *408088 http write filter 0000000000000000

2017/09/18 10:50:22 [debug] 36339#0: *408088 http copy filter: 0 "/waf?"

2017/09/18 10:50:22 [debug] 36339#0: *408088 http finalize request: 0, "/waf?" a:1, c:1

2017/09/18 10:50:22 [debug] 36339#0: *408088 set http keepalive handler

2017/09/18 10:50:22 [debug] 36339#0: *408088 http close request

2017/09/18 10:50:22 [debug] 36339#0: *408088 lua request cleanup: forcible=0

2017/09/18 10:50:22 [debug] 36339#0: *408088 lua log handler, uri:"/waf" c:1

2017/09/18 10:50:22 [error] 36339#0: *408088 [lua] waf_log.lua:1: waf-log while logging request, client: 10.121.76.118, server: localhost, request: "POST /waf HTTP/1.1", host: "10.23.80.1"

2017/09/18 10:50:22 [debug] 36339#0: *408088 http log handler

2017/09/18 10:50:22 [debug] 36339#0: *408088 run cleanup: 0000000001AF98C8

2017/09/18 10:50:22 [debug] 36339#0: *408088 free: 0000000001AE8040

2017/09/18 10:50:22 [debug] 36339#0: *408088 free: 0000000001A6DB20, unused: 0

2017/09/18 10:50:22 [debug] 36339#0: *408088 free: 0000000001AF95F0, unused: 0

2017/09/18 10:50:22 [debug] 36339#0: *408088 free: 0000000001A7A120, unused: 0

2017/09/18 10:50:22 [debug] 36339#0: *408088 free: 0000000001A56620, unused: 3640

2017/09/18 10:50:22 [debug] 36339#0: *408088 free: 0000000001AEF240

2017/09/18 10:50:22 [debug] 36339#0: *408088 hc free: 0000000000000000 0

2017/09/18 10:50:22 [debug] 36339#0: *408088 hc busy: 0000000000000000 0

2017/09/18 10:50:22 [debug] 36339#0: *408088 tcp_nodelay

2017/09/18 10:50:22 [debug] 36339#0: *408088 reusable connection: 1

2017/09/18 10:50:22 [debug] 36339#0: *408088 event timer add: 25: 65000:1505703087217

2017/09/18 10:50:22 [debug] 36339#0: *408088 post event 00007F09F1F2E310

2017/09/18 10:50:22 [debug] 36339#0: *408088 delete posted event 00007F09F1F2E310

2017/09/18 10:50:22 [debug] 36339#0: *408088 http keepalive handler

2017/09/18 10:50:22 [debug] 36339#0: *408088 malloc: 0000000001A8BF50:1024

2017/09/18 10:50:22 [debug] 36339#0: *408088 recv: fd:25 -1 of 1024

2017/09/18 10:50:22 [debug] 36339#0: *408088 recv() not ready (11: Resource temporarily unavailable)

2017/09/18 10:50:22 [debug] 36339#0: *408088 free: 0000000001A8BF50

2017/09/18 10:50:22 [debug] 36339#0: *408088 http keepalive handler

2017/09/18 10:50:22 [debug] 36339#0: *408088 malloc: 0000000001A8BF50:1024

2017/09/18 10:50:22 [debug] 36339#0: *408088 recv: fd:25 0 of 1024

2017/09/18 10:50:22 [info] 36339#0: *408088 client 10.121.76.118 closed keepalive connection

2017/09/18 10:50:22 [debug] 36339#0: *408088 close http connection: 25

2017/09/18 10:50:22 [debug] 36339#0: *408088 event timer del: 25: 1505703087217

2017/09/18 10:50:22 [debug] 36339#0: *408088 reusable connection: 0

2017/09/18 10:50:22 [debug] 36339#0: *408088 free: 0000000001A8BF50

2017/09/18 10:50:22 [debug] 36339#0: *408088 free: 0000000001A8D080, unused: 112

agentzh

Hello!

看起来像是你用的第三方模块的 bug。我们显然没有资源来帮你调试第三方模块的问题了。如果你认为是 ngx_lua
模块的问题，请提供一个最小化的独立的测试用例，以便我们可以方便地在本地运行和复现问题。否则你只能自己想办法了。

值得一提的是，这么大的日志请放到 gist.github.com 这样的网站上，然后在邮件里面附上链接就好了，以节约大家的邮件带宽。谢谢合作。

Regards,
Yichun

night.zk89

多谢大神回复：）确实是第三方模块的问题，他们给出的回复是：

• lua模块在读完request body之后把事件处理函数给清掉了，导致他们的模块在执行结束之后无法继续后续的处理逻辑而阻塞，后面他们手动设置了一下时间处理函数，就OK了。

在 2017年9月19日星期二 UTC+8上午4:09:43，agentzh写道：

Hello!

看起来像是你用的第三方模块的 bug。我们显然没有资源来帮你调试第三方模块的问题了。如果你认为是 ngx_lua
模块的问题，请提供一个最小化的独立的测试用例，以便我们可以方便地在本地运行和复现问题。否则你只能自己想办法了。

值得一提的是，这么大的日志请放到 gist.github.com 这样的网站上，然后在邮件里面附上链接就好了，以节约大家的邮件带宽。谢谢合作。

Regards,
Yichun

agentzh

Hello!

2017-09-18 20:33 GMT-07:00 周凯:
> •   lua模块在读完request
> body之后把事件处理函数给清掉了，

读完必须清掉事件啊，要不对于 pipeline requests 和使用水平触发事件的情况，不清掉就热循环了。这是基于事件编程的常识了。

Regards,
Yichun