srcache-nginx-module对POST请求的缓存问题

wangyongke

Hi, 春哥及大家好

我们有些旧的接口使用POST方法，用于数据查询，因为有些请求参数太大了，所以使用了POST的body里面携带json作为输入的做法。

为了兼容这些接口，并为它们提供缓存机制，决定这些接口加个前端，用openresty里面的srcache。

我们的配置大概是这样的

rewrite_by_lua '

local ngx_var, ngx_req = ngx.var, ngx.req

local args = ngx_var.args

ngx_req.read_body()

local body = ngx_req.get_body_data()

if args or body then

#TODO

ngx_var.cache_key = ngx.md5(ngx_var.uri .. (args or "") .. (body or ""))

ngx_var.fetch_skip = 0

end

srcache_methods GET POST;

srcache_fetch_skip $fetch_skip;

srcache_store_skip $fetch_skip;

srcache_fetch GET /getcache key=$cache_key;

srcache_store GET /setcache key=$cache_key&ttl=60;

srcache_store_statuses 200;

proxy_pass http://be-custapi;

现在的问题是，如果post body太长的话（超过883个字节）整个客户端请求都没有响应，该请求被卡死了。但是如果post body比较小的话，一切流程都符合预期。

麻烦各位帮忙看下，谢谢。

现在的workaround是，对于这种请求，使用lua-resty-redis在lua代码里缓存。

version: ngx_openresty-1.9.3.1

wangyongke

Debug logs with/without problem attached.

2015/11/23 01:28:20 [debug] 20022#0: accept on 0.0.0.0:8000, ready: 1
2015/11/23 01:28:20 [debug] 20022#0: posix_memalign: 0000000000A82850:256 @16
2015/11/23 01:28:20 [debug] 20022#0: *4 accept: 127.0.0.1:44349 fd:13
2015/11/23 01:28:20 [debug] 20022#0: posix_memalign: 0000000000A82960:256 @16
2015/11/23 01:28:20 [debug] 20022#0: *4 event timer add: 13: 60000:1448242160593
2015/11/23 01:28:20 [debug] 20022#0: *4 reusable connection: 1
2015/11/23 01:28:20 [debug] 20022#0: *4 epoll add event: fd:13 op:1 ev:80002001
2015/11/23 01:28:20 [debug] 20022#0: accept() not ready (11: Resource temporarily unavailable)
2015/11/23 01:28:20 [debug] 20022#0: *4 http wait request handler
2015/11/23 01:28:20 [debug] 20022#0: *4 malloc: 0000000000ADD7B0:1024
2015/11/23 01:28:20 [debug] 20022#0: *4 recv: fd:13 1024 of 1024
2015/11/23 01:28:20 [debug] 20022#0: *4 reusable connection: 0
2015/11/23 01:28:20 [debug] 20022#0: *4 posix_memalign: 0000000000ADDBC0:4096 @16
2015/11/23 01:28:20 [debug] 20022#0: *4 http process request line
2015/11/23 01:28:20 [debug] 20022#0: *4 http request line: "POST /ripple_cust_api/ HTTP/1.1"
2015/11/23 01:28:20 [debug] 20022#0: *4 http uri: "/ripple_cust_api/"
2015/11/23 01:28:20 [debug] 20022#0: *4 http args: ""
2015/11/23 01:28:20 [debug] 20022#0: *4 http exten: ""
2015/11/23 01:28:20 [debug] 20022#0: *4 http process request header line
2015/11/23 01:28:20 [debug] 20022#0: *4 http header: "User-Agent: curl/7.35.0"
2015/11/23 01:28:20 [debug] 20022#0: *4 http header: "Host: localhost:8000"
2015/11/23 01:28:20 [debug] 20022#0: *4 http header: "Accept: */*"
2015/11/23 01:28:20 [debug] 20022#0: *4 http header: "Content-type: text/plain"
2015/11/23 01:28:20 [debug] 20022#0: *4 http header: "Content-Length: 883"
2015/11/23 01:28:20 [debug] 20022#0: *4 http header done
2015/11/23 01:28:20 [debug] 20022#0: *4 event timer del: 13: 1448242160593
2015/11/23 01:28:20 [debug] 20022#0: *4 rewrite phase: 0
2015/11/23 01:28:20 [debug] 20022#0: *4 rewrite phase: 1
2015/11/23 01:28:20 [debug] 20022#0: *4 test location: "/api/shop"
2015/11/23 01:28:20 [debug] 20022#0: *4 test location: "/getcache-aux"
2015/11/23 01:28:20 [debug] 20022#0: *4 test location: "/setcache"
2015/11/23 01:28:20 [debug] 20022#0: *4 test location: "/ripple_cust_api/"
2015/11/23 01:28:20 [debug] 20022#0: *4 using configuration "/ripple_cust_api/"
2015/11/23 01:28:20 [debug] 20022#0: *4 http cl:883 max:10485760
2015/11/23 01:28:20 [debug] 20022#0: *4 rewrite phase: 3
2015/11/23 01:28:20 [debug] 20022#0: *4 rewrite phase: 4
2015/11/23 01:28:20 [debug] 20022#0: *4 posix_memalign: 0000000000ADEBD0:4096 @16
2015/11/23 01:28:20 [debug] 20022#0: *4 http script value: ""
2015/11/23 01:28:20 [debug] 20022#0: *4 http script set $cache_key
2015/11/23 01:28:20 [debug] 20022#0: *4 http script value: "1"
2015/11/23 01:28:20 [debug] 20022#0: *4 http script set $fetch_skip
2015/11/23 01:28:20 [debug] 20022#0: *4 rewrite phase: 5
2015/11/23 01:28:20 [debug] 20022#0: *4 lua rewrite handler, uri:"/ripple_cust_api/" c:1
2015/11/23 01:28:20 [debug] 20022#0: *4 add cleanup: 0000000000ADEBA0
2015/11/23 01:28:20 [debug] 20022#0: *4 lua creating new vm state
2015/11/23 01:28:20 [debug] 20022#0: *4 lua initializing lua registry
2015/11/23 01:28:20 [debug] 20022#0: *4 lua initializing lua globals
2015/11/23 01:28:20 [debug] 20022#0: *4 lua initialize the global Lua VM 0000000041EC2378
2015/11/23 01:28:20 [debug] 20022#0: *4 malloc: 0000000000A89600:16
2015/11/23 01:28:20 [debug] 20022#0: *4 lua creating new thread
2015/11/23 01:28:20 [debug] 20022#0: *4 lua reset ctx
2015/11/23 01:28:20 [debug] 20022#0: *4 http cleanup add: 0000000000ADEE68
2015/11/23 01:28:20 [debug] 20022#0: *4 lua run thread, top:0 c:1
2015/11/23 01:28:20 [debug] 20022#0: *4 lua start to read buffered request body
2015/11/23 01:28:20 [debug] 20022#0: *4 http client request body preread 882
2015/11/23 01:28:20 [debug] 20022#0: *4 http request body content length filter
2015/11/23 01:28:20 [debug] 20022#0: *4 http body new buf t:1 f:0 0000000000ADD83E, pos 0000000000ADD83E, size: 882 file: 0, size: 0
2015/11/23 01:28:20 [debug] 20022#0: *4 http read client request body
2015/11/23 01:28:20 [debug] 20022#0: *4 recv: fd:13 1 of 1
2015/11/23 01:28:20 [debug] 20022#0: *4 http client request body recv 1
2015/11/23 01:28:20 [debug] 20022#0: *4 http body old buf t:1 f:0 0000000000ADD83E, pos 0000000000ADD83E, size: 882 file: 0, size: 0
2015/11/23 01:28:20 [debug] 20022#0: *4 http body new buf t:1 f:0 0000000000ADEF90, pos 0000000000ADEF90, size: 1 file: 0, size: 0
2015/11/23 01:28:20 [debug] 20022#0: *4 http client request body rest 0
2015/11/23 01:28:20 [debug] 20022#0: *4 lua req body post read, c:2
2015/11/23 01:28:20 [debug] 20022#0: *4 lua has read buffered request body in a single run
2015/11/23 01:28:20 [debug] 20022#0: *4 lua resume returned 0
2015/11/23 01:28:20 [debug] 20022#0: *4 lua light thread ended normally
2015/11/23 01:28:20 [debug] 20022#0: *4 lua deleting light thread
2015/11/23 01:28:20 [debug] 20022#0: *4 post rewrite phase: 6
2015/11/23 01:28:20 [debug] 20022#0: *4 generic phase: 7
2015/11/23 01:28:20 [debug] 20022#0: *4 generic phase: 8
2015/11/23 01:28:20 [debug] 20022#0: *4 access phase: 9
2015/11/23 01:28:20 [debug] 20022#0: *4 access phase: 10
2015/11/23 01:28:20 [debug] 20022#0: *4 access phase: 11
2015/11/23 01:28:20 [debug] 20022#0: *4 http script var: "0"
2015/11/23 01:28:20 [debug] 20022#0: *4 http script copy: "key="
2015/11/23 01:28:20 [debug] 20022#0: *4 http script var: "d0a496ad050c0b31c9449aa1df1dd466"
2015/11/23 01:28:20 [debug] 20022#0: *4 posix_memalign: 0000000000ADFBE0:4096 @16
2015/11/23 01:28:20 [debug] 20022#0: *4 http subrequest "/getcache?key=d0a496ad050c0b31c9449aa1df1dd466"
2015/11/23 01:28:20 [debug] 20022#0: *4 http posted request: "/getcache?key=d0a496ad050c0b31c9449aa1df1dd466"
2015/11/23 01:28:20 [debug] 20022#0: *4 rewrite phase: 0
2015/11/23 01:28:20 [debug] 20022#0: *4 rewrite phase: 1
2015/11/23 01:28:20 [debug] 20022#0: *4 test location: "/api/shop"
2015/11/23 01:28:20 [debug] 20022#0: *4 test location: "/getcache-aux"
2015/11/23 01:28:20 [debug] 20022#0: *4 test location: "/api/uid-mac"
2015/11/23 01:28:20 [debug] 20022#0: *4 test location: "/getcache"
2015/11/23 01:28:20 [debug] 20022#0: *4 using configuration "=/getcache"
2015/11/23 01:28:20 [debug] 20022#0: *4 http cl:883 max:1048576
2015/11/23 01:28:20 [debug] 20022#0: *4 rewrite phase: 3
2015/11/23 01:28:20 [debug] 20022#0: *4 rewrite phase: 4
2015/11/23 01:28:20 [debug] 20022#0: *4 rewrite phase: 5
2015/11/23 01:28:20 [debug] 20022#0: *4 lua rewrite handler, uri:"/getcache" c:2
2015/11/23 01:28:20 [debug] 20022#0: *4 post rewrite phase: 6
2015/11/23 01:28:20 [debug] 20022#0: *4 generic phase: 7
2015/11/23 01:28:20 [debug] 20022#0: *4 generic phase: 8
2015/11/23 01:28:20 [debug] 20022#0: *4 lua content handler, uri:"/getcache" c:2
2015/11/23 01:28:20 [debug] 20022#0: *4 add cleanup: 0000000000ADFBA8
2015/11/23 01:28:20 [debug] 20022#0: *4 lua creating new vm state
2015/11/23 01:28:20 [debug] 20022#0: *4 lua initializing lua registry
2015/11/23 01:28:20 [debug] 20022#0: *4 lua initializing lua globals
2015/11/23 01:28:20 [debug] 20022#0: *4 lua initialize the global Lua VM 00000000413CF378
2015/11/23 01:28:20 [debug] 20022#0: *4 malloc: 0000000000A89620:16
2015/11/23 01:28:20 [debug] 20022#0: *4 lua reset ctx
2015/11/23 01:28:20 [debug] 20022#0: *4 lua creating new thread
2015/11/23 01:28:20 [debug] 20022#0: *4 http cleanup add: 0000000000AE0310
2015/11/23 01:28:20 [debug] 20022#0: *4 lua run thread, top:0 c:2
2015/11/23 01:28:20 [debug] 20022#0: *4 lua location capture, uri:"/getcache" c:2
2015/11/23 01:28:20 [debug] 20022#0: *4 posix_memalign: 0000000000AE0BF0:4096 @16
2015/11/23 01:28:20 [debug] 20022#0: *4 http subrequest "/getcache-aux?key=d0a496ad050c0b31c9449aa1df1dd466"
2015/11/23 01:28:20 [debug] 20022#0: *4 lua resume returned 1
2015/11/23 01:28:20 [debug] 20022#0: *4 lua thread yielded
2015/11/23 01:28:20 [debug] 20022#0: *4 http finalize request: -4, "/getcache?key=d0a496ad050c0b31c9449aa1df1dd466" a:1, c:4
2015/11/23 01:28:20 [debug] 20022#0: *4 http request count:4 blk:0
2015/11/23 01:28:20 [debug] 20022#0: *4 http posted request: "/getcache-aux?key=d0a496ad050c0b31c9449aa1df1dd466"
2015/11/23 01:28:20 [debug] 20022#0: *4 rewrite phase: 0
2015/11/23 01:28:20 [debug] 20022#0: *4 rewrite phase: 1
2015/11/23 01:28:20 [debug] 20022#0: *4 test location: "/api/shop"
2015/11/23 01:28:20 [debug] 20022#0: *4 test location: "/getcache-aux"
2015/11/23 01:28:20 [debug] 20022#0: *4 using configuration "=/getcache-aux"
2015/11/23 01:28:20 [debug] 20022#0: *4 http cl:0 max:1048576
2015/11/23 01:28:20 [debug] 20022#0: *4 rewrite phase: 3
2015/11/23 01:28:20 [debug] 20022#0: *4 rewrite phase: 4
2015/11/23 01:28:20 [debug] 20022#0: *4 rewrite phase: 5
2015/11/23 01:28:20 [debug] 20022#0: *4 lua rewrite handler, uri:"/getcache-aux" c:3
2015/11/23 01:28:20 [debug] 20022#0: *4 post rewrite phase: 6
2015/11/23 01:28:20 [debug] 20022#0: *4 generic phase: 7
2015/11/23 01:28:20 [debug] 20022#0: *4 generic phase: 8
2015/11/23 01:28:20 [debug] 20022#0: *4 http init upstream, client timer: 0
2015/11/23 01:28:20 [debug] 20022#0: *4 epoll add event: fd:13 op:3 ev:80002005
2015/11/23 01:28:20 [debug] 20022#0: *4 http script var: "d0a496ad050c0b31c9449aa1df1dd466"
2015/11/23 01:28:20 [debug] 20022#0: *4 http redis2 request: ""
2015/11/23 01:28:20 [debug] 20022#0: *4 http cleanup add: 0000000000AE1AF0
2015/11/23 01:28:20 [debug] 20022#0: *4 init keepalive peer
2015/11/23 01:28:20 [debug] 20022#0: *4 get keepalive peer
2015/11/23 01:28:20 [debug] 20022#0: *4 get rr peer, try: 1
2015/11/23 01:28:20 [debug] 20022#0: *4 get keepalive peer: using connection 00007F05BFDEC520
2015/11/23 01:28:20 [debug] 20022#0: *4 http upstream connect: -4
2015/11/23 01:28:20 [debug] 20022#0: *4 http upstream send request
2015/11/23 01:28:20 [debug] 20022#0: *4 http upstream send request body
2015/11/23 01:28:20 [debug] 20022#0: *4 chain writer buf fl:0 s:75
2015/11/23 01:28:20 [debug] 20022#0: *4 chain writer in: 0000000000AE1B60
2015/11/23 01:28:20 [debug] 20022#0: *4 writev: 75 of 75
2015/11/23 01:28:20 [debug] 20022#0: *4 chain writer out: 0000000000000000
2015/11/23 01:28:20 [debug] 20022#0: *4 event timer add: 11: 60000:1448242160593
2015/11/23 01:28:20 [debug] 20022#0: *4 http finalize request: -4, "/getcache-aux?key=d0a496ad050c0b31c9449aa1df1dd466" a:0, c:4
2015/11/23 01:28:20 [debug] 20022#0: *4 http request count:4 blk:0
2015/11/23 01:28:20 [debug] 20022#0: *4 http run request: "/getcache?key=d0a496ad050c0b31c9449aa1df1dd466"
2015/11/23 01:28:20 [debug] 20022#0: *4 http request empty handler
2015/11/23 01:28:20 [debug] 20022#0: *4 http upstream request: "/getcache-aux?key=d0a496ad050c0b31c9449aa1df1dd466"
2015/11/23 01:28:20 [debug] 20022#0: *4 http upstream process header
2015/11/23 01:28:20 [debug] 20022#0: *4 malloc: 0000000000AE1C00:4096
2015/11/23 01:28:20 [debug] 20022#0: *4 posix_memalign: 0000000000AE2C10:4096 @16
2015/11/23 01:28:20 [debug] 20022#0: *4 recv: fd:11 10 of 4096
2015/11/23 01:28:20 [debug] 20022#0: *4 lua capture header filter, uri "/getcache-aux"
2015/11/23 01:28:20 [debug] 20022#0: *4 lua capturing response body
2015/11/23 01:28:20 [debug] 20022#0: *4 tcp_nodelay
2015/11/23 01:28:20 [debug] 20022#0: *4 http upstream process non buffered downstream
2015/11/23 01:28:20 [debug] 20022#0: *4 http output filter "/getcache-aux?key=d0a496ad050c0b31c9449aa1df1dd466"
2015/11/23 01:28:20 [debug] 20022#0: *4 http copy filter: "/getcache-aux?key=d0a496ad050c0b31c9449aa1df1dd466"
2015/11/23 01:28:20 [debug] 20022#0: *4 lua capture body filter, uri "/getcache-aux"
2015/11/23 01:28:20 [debug] 20022#0: *4 lua capture body filter capturing response body, uri "/getcache-aux"
2015/11/23 01:28:20 [debug] 20022#0: *4 lua allocate new chainlink and new buf of size 10, cl:0000000000AE1BD0
2015/11/23 01:28:20 [debug] 20022#0: *4 http copy filter: 0 "/getcache-aux?key=d0a496ad050c0b31c9449aa1df1dd466"
2015/11/23 01:28:20 [debug] 20022#0: *4 finalize http upstream request: 0
2015/11/23 01:28:20 [debug] 20022#0: *4 finalize http redis2 request
2015/11/23 01:28:20 [debug] 20022#0: *4 free keepalive peer
2015/11/23 01:28:20 [debug] 20022#0: *4 free keepalive peer: saving connection 00007F05BFDEC520
2015/11/23 01:28:20 [debug] 20022#0: *4 event timer del: 11: 1448242160593
2015/11/23 01:28:20 [debug] 20022#0: *4 free rr peer 1 0
2015/11/23 01:28:20 [debug] 20022#0: *4 http output filter "/getcache-aux?key=d0a496ad050c0b31c9449aa1df1dd466"
2015/11/23 01:28:20 [debug] 20022#0: *4 http copy filter: "/getcache-aux?key=d0a496ad050c0b31c9449aa1df1dd466"
2015/11/23 01:28:20 [debug] 20022#0: *4 lua capture body filter, uri "/getcache-aux"
2015/11/23 01:28:20 [debug] 20022#0: *4 lua capture body filter capturing response body, uri "/getcache-aux"
2015/11/23 01:28:20 [debug] 20022#0: *4 http copy filter: 0 "/getcache-aux?key=d0a496ad050c0b31c9449aa1df1dd466"
2015/11/23 01:28:20 [debug] 20022#0: *4 http finalize request: 0, "/getcache-aux?key=d0a496ad050c0b31c9449aa1df1dd466" a:0, c:3
2015/11/23 01:28:20 [debug] 20022#0: *4 lua run post subrequest handler, rc:0 c:3
2015/11/23 01:28:20 [debug] 20022#0: *4 lua restoring write event handler
2015/11/23 01:28:20 [debug] 20022#0: *4 http wake parent request: "/getcache?key=d0a496ad050c0b31c9449aa1df1dd466"
2015/11/23 01:28:20 [debug] 20022#0: *4 http posted request: "/getcache?key=d0a496ad050c0b31c9449aa1df1dd466"
2015/11/23 01:28:20 [debug] 20022#0: *4 lua run subrequests done, resuming lua thread
2015/11/23 01:28:20 [debug] 20022#0: *4 lua handle subrequest responses
2015/11/23 01:28:20 [debug] 20022#0: *4 lua run thread, top:0 c:2
2015/11/23 01:28:20 [debug] 20022#0: *4 lua exit with code 404
2015/11/23 01:28:20 [debug] 20022#0: *4 lua resume returned 1
2015/11/23 01:28:20 [debug] 20022#0: *4 lua thread yielded
2015/11/23 01:28:20 [debug] 20022#0: *4 lua thread aborting request with status 404
2015/11/23 01:28:20 [debug] 20022#0: *4 lua request cleanup: forcible=0
2015/11/23 01:28:20 [debug] 20022#0: *4 lua run thread returned 404
2015/11/23 01:28:20 [debug] 20022#0: *4 http finalize request: 404, "/getcache?key=d0a496ad050c0b31c9449aa1df1dd466" a:1, c:2
2015/11/23 01:28:20 [debug] 20022#0: *4 http wake parent request: "/ripple_cust_api/?"
2015/11/23 01:28:20 [debug] 20022#0: *4 http posted request: "/getcache?key=d0a496ad050c0b31c9449aa1df1dd466"
2015/11/23 01:28:20 [debug] 20022#0: *4 lua run write event handler: timedout:0, ready:1, writing_raw_req_socket:0
2015/11/23 01:28:20 [debug] 20022#0: *4 useless lua write event handler
2015/11/23 01:28:20 [debug] 20022#0: *4 http posted request: "/ripple_cust_api/?"
2015/11/23 01:28:20 [debug] 20022#0: *4 http request empty handler

2015/11/23 01:31:43 [debug] 20022#0: accept on 0.0.0.0:8000, ready: 1
2015/11/23 01:31:43 [debug] 20022#0: posix_memalign: 0000000000A82A70:256 @16
2015/11/23 01:31:43 [debug] 20022#0: *5 accept: 127.0.0.1:44774 fd:14
2015/11/23 01:31:43 [debug] 20022#0: posix_memalign: 0000000000A82B80:256 @16
2015/11/23 01:31:43 [debug] 20022#0: *5 event timer add: 14: 60000:1448242363312
2015/11/23 01:31:43 [debug] 20022#0: *5 reusable connection: 1
2015/11/23 01:31:43 [debug] 20022#0: *5 epoll add event: fd:14 op:1 ev:80002001
2015/11/23 01:31:43 [debug] 20022#0: accept() not ready (11: Resource temporarily unavailable)
2015/11/23 01:31:43 [debug] 20022#0: *5 http wait request handler
2015/11/23 01:31:43 [debug] 20022#0: *5 malloc: 0000000000AE3C20:1024
2015/11/23 01:31:43 [debug] 20022#0: *5 recv: fd:14 1024 of 1024
2015/11/23 01:31:43 [debug] 20022#0: *5 reusable connection: 0
2015/11/23 01:31:43 [debug] 20022#0: *5 posix_memalign: 0000000000AE4030:4096 @16
2015/11/23 01:31:43 [debug] 20022#0: *5 http process request line
2015/11/23 01:31:43 [debug] 20022#0: *5 http request line: "POST /ripple_cust_api/ HTTP/1.1"
2015/11/23 01:31:43 [debug] 20022#0: *5 http uri: "/ripple_cust_api/"
2015/11/23 01:31:43 [debug] 20022#0: *5 http args: ""
2015/11/23 01:31:43 [debug] 20022#0: *5 http exten: ""
2015/11/23 01:31:43 [debug] 20022#0: *5 http process request header line
2015/11/23 01:31:43 [debug] 20022#0: *5 http header: "User-Agent: curl/7.35.0"
2015/11/23 01:31:43 [debug] 20022#0: *5 http header: "Host: localhost:8000"
2015/11/23 01:31:43 [debug] 20022#0: *5 http header: "Accept: */*"
2015/11/23 01:31:43 [debug] 20022#0: *5 http header: "Content-type: text/plain"
2015/11/23 01:31:43 [debug] 20022#0: *5 http header: "Content-Length: 882"
2015/11/23 01:31:43 [debug] 20022#0: *5 http header done
2015/11/23 01:31:43 [debug] 20022#0: *5 event timer del: 14: 1448242363312
2015/11/23 01:31:43 [debug] 20022#0: *5 rewrite phase: 0
2015/11/23 01:31:43 [debug] 20022#0: *5 rewrite phase: 1
2015/11/23 01:31:43 [debug] 20022#0: *5 test location: "/api/shop"
2015/11/23 01:31:43 [debug] 20022#0: *5 test location: "/getcache-aux"
2015/11/23 01:31:43 [debug] 20022#0: *5 test location: "/setcache"
2015/11/23 01:31:43 [debug] 20022#0: *5 test location: "/ripple_cust_api/"
2015/11/23 01:31:43 [debug] 20022#0: *5 using configuration "/ripple_cust_api/"
2015/11/23 01:31:43 [debug] 20022#0: *5 http cl:882 max:10485760
2015/11/23 01:31:43 [debug] 20022#0: *5 rewrite phase: 3
2015/11/23 01:31:43 [debug] 20022#0: *5 rewrite phase: 4
2015/11/23 01:31:43 [debug] 20022#0: *5 posix_memalign: 0000000000AE5040:4096 @16
2015/11/23 01:31:43 [debug] 20022#0: *5 http script value: ""
2015/11/23 01:31:43 [debug] 20022#0: *5 http script set $cache_key
2015/11/23 01:31:43 [debug] 20022#0: *5 http script value: "1"
2015/11/23 01:31:43 [debug] 20022#0: *5 http script set $fetch_skip
2015/11/23 01:31:43 [debug] 20022#0: *5 rewrite phase: 5
2015/11/23 01:31:43 [debug] 20022#0: *5 lua rewrite handler, uri:"/ripple_cust_api/" c:1
2015/11/23 01:31:43 [debug] 20022#0: *5 add cleanup: 0000000000AE5010
2015/11/23 01:31:43 [debug] 20022#0: *5 lua creating new vm state
2015/11/23 01:31:43 [debug] 20022#0: *5 lua initializing lua registry
2015/11/23 01:31:43 [debug] 20022#0: *5 lua initializing lua globals
2015/11/23 01:31:43 [debug] 20022#0: *5 lua initialize the global Lua VM 00000000406B9378
2015/11/23 01:31:43 [debug] 20022#0: *5 malloc: 0000000000A89640:16
2015/11/23 01:31:43 [debug] 20022#0: *5 lua creating new thread
2015/11/23 01:31:43 [debug] 20022#0: *5 lua reset ctx
2015/11/23 01:31:43 [debug] 20022#0: *5 http cleanup add: 0000000000AE52D8
2015/11/23 01:31:43 [debug] 20022#0: *5 lua run thread, top:0 c:1
2015/11/23 01:31:43 [debug] 20022#0: *5 lua start to read buffered request body
2015/11/23 01:31:43 [debug] 20022#0: *5 http client request body preread 882
2015/11/23 01:31:43 [debug] 20022#0: *5 http request body content length filter
2015/11/23 01:31:43 [debug] 20022#0: *5 http body new buf t:1 f:0 0000000000AE3CAE, pos 0000000000AE3CAE, size: 882 file: 0, size: 0
2015/11/23 01:31:43 [debug] 20022#0: *5 lua req body post read, c:2
2015/11/23 01:31:43 [debug] 20022#0: *5 lua has read buffered request body in a single run
2015/11/23 01:31:43 [debug] 20022#0: *5 lua resume returned 0
2015/11/23 01:31:43 [debug] 20022#0: *5 lua light thread ended normally
2015/11/23 01:31:43 [debug] 20022#0: *5 lua deleting light thread
2015/11/23 01:31:43 [debug] 20022#0: *5 post rewrite phase: 6
2015/11/23 01:31:43 [debug] 20022#0: *5 generic phase: 7
2015/11/23 01:31:43 [debug] 20022#0: *5 generic phase: 8
2015/11/23 01:31:43 [debug] 20022#0: *5 access phase: 9
2015/11/23 01:31:43 [debug] 20022#0: *5 access phase: 10
2015/11/23 01:31:43 [debug] 20022#0: *5 access phase: 11
2015/11/23 01:31:43 [debug] 20022#0: *5 http script var: "0"
2015/11/23 01:31:43 [debug] 20022#0: *5 http script copy: "key="
2015/11/23 01:31:43 [debug] 20022#0: *5 http script var: "e97f9635e589757dc74fa9b7b9f3f1c8"
2015/11/23 01:31:43 [debug] 20022#0: *5 posix_memalign: 0000000000AE6050:4096 @16
2015/11/23 01:31:43 [debug] 20022#0: *5 http subrequest "/getcache?key=e97f9635e589757dc74fa9b7b9f3f1c8"
2015/11/23 01:31:43 [debug] 20022#0: *5 http posted request: "/getcache?key=e97f9635e589757dc74fa9b7b9f3f1c8"
2015/11/23 01:31:43 [debug] 20022#0: *5 rewrite phase: 0
2015/11/23 01:31:43 [debug] 20022#0: *5 rewrite phase: 1
2015/11/23 01:31:43 [debug] 20022#0: *5 test location: "/api/shop"
2015/11/23 01:31:43 [debug] 20022#0: *5 test location: "/getcache-aux"
2015/11/23 01:31:43 [debug] 20022#0: *5 test location: "/api/uid-mac"
2015/11/23 01:31:43 [debug] 20022#0: *5 test location: "/getcache"
2015/11/23 01:31:43 [debug] 20022#0: *5 using configuration "=/getcache"
2015/11/23 01:31:43 [debug] 20022#0: *5 http cl:882 max:1048576
2015/11/23 01:31:43 [debug] 20022#0: *5 rewrite phase: 3
2015/11/23 01:31:43 [debug] 20022#0: *5 rewrite phase: 4
2015/11/23 01:31:43 [debug] 20022#0: *5 rewrite phase: 5
2015/11/23 01:31:43 [debug] 20022#0: *5 lua rewrite handler, uri:"/getcache" c:2
2015/11/23 01:31:43 [debug] 20022#0: *5 post rewrite phase: 6
2015/11/23 01:31:43 [debug] 20022#0: *5 generic phase: 7
2015/11/23 01:31:43 [debug] 20022#0: *5 generic phase: 8
2015/11/23 01:31:43 [debug] 20022#0: *5 lua content handler, uri:"/getcache" c:2
2015/11/23 01:31:43 [debug] 20022#0: *5 add cleanup: 0000000000AE5F30
2015/11/23 01:31:43 [debug] 20022#0: *5 lua creating new vm state
2015/11/23 01:31:43 [debug] 20022#0: *5 lua initializing lua registry
2015/11/23 01:31:43 [debug] 20022#0: *5 lua initializing lua globals
2015/11/23 01:31:43 [debug] 20022#0: *5 lua initialize the global Lua VM 0000000040039378
2015/11/23 01:31:43 [debug] 20022#0: *5 malloc: 0000000000A82C90:16
2015/11/23 01:31:43 [debug] 20022#0: *5 lua reset ctx
2015/11/23 01:31:43 [debug] 20022#0: *5 lua creating new thread
2015/11/23 01:31:43 [debug] 20022#0: *5 http cleanup add: 0000000000AE5F48
2015/11/23 01:31:43 [debug] 20022#0: *5 lua run thread, top:0 c:2
2015/11/23 01:31:43 [debug] 20022#0: *5 lua location capture, uri:"/getcache" c:2
2015/11/23 01:31:43 [debug] 20022#0: *5 posix_memalign: 0000000000AE7060:4096 @16
2015/11/23 01:31:43 [debug] 20022#0: *5 http subrequest "/getcache-aux?key=e97f9635e589757dc74fa9b7b9f3f1c8"
2015/11/23 01:31:43 [debug] 20022#0: *5 lua resume returned 1
2015/11/23 01:31:43 [debug] 20022#0: *5 lua thread yielded
2015/11/23 01:31:43 [debug] 20022#0: *5 http finalize request: -4, "/getcache?key=e97f9635e589757dc74fa9b7b9f3f1c8" a:1, c:4
2015/11/23 01:31:43 [debug] 20022#0: *5 http request count:4 blk:0
2015/11/23 01:31:43 [debug] 20022#0: *5 http posted request: "/getcache-aux?key=e97f9635e589757dc74fa9b7b9f3f1c8"
2015/11/23 01:31:43 [debug] 20022#0: *5 rewrite phase: 0
2015/11/23 01:31:43 [debug] 20022#0: *5 rewrite phase: 1
2015/11/23 01:31:43 [debug] 20022#0: *5 test location: "/api/shop"
2015/11/23 01:31:43 [debug] 20022#0: *5 test location: "/getcache-aux"
2015/11/23 01:31:43 [debug] 20022#0: *5 using configuration "=/getcache-aux"
2015/11/23 01:31:43 [debug] 20022#0: *5 http cl:0 max:1048576
2015/11/23 01:31:43 [debug] 20022#0: *5 rewrite phase: 3
2015/11/23 01:31:43 [debug] 20022#0: *5 rewrite phase: 4
2015/11/23 01:31:43 [debug] 20022#0: *5 rewrite phase: 5
2015/11/23 01:31:43 [debug] 20022#0: *5 lua rewrite handler, uri:"/getcache-aux" c:3
2015/11/23 01:31:43 [debug] 20022#0: *5 post rewrite phase: 6
2015/11/23 01:31:43 [debug] 20022#0: *5 generic phase: 7
2015/11/23 01:31:43 [debug] 20022#0: *5 generic phase: 8
2015/11/23 01:31:43 [debug] 20022#0: *5 http init upstream, client timer: 0
2015/11/23 01:31:43 [debug] 20022#0: *5 epoll add event: fd:14 op:3 ev:80002005
2015/11/23 01:31:43 [debug] 20022#0: *5 http script var: "e97f9635e589757dc74fa9b7b9f3f1c8"
2015/11/23 01:31:43 [debug] 20022#0: *5 http redis2 request: ""
2015/11/23 01:31:43 [debug] 20022#0: *5 http cleanup add: 0000000000AE6F70
2015/11/23 01:31:43 [debug] 20022#0: *5 init keepalive peer
2015/11/23 01:31:43 [debug] 20022#0: *5 get keepalive peer
2015/11/23 01:31:43 [debug] 20022#0: *5 get rr peer, try: 1
2015/11/23 01:31:43 [debug] 20022#0: *5 get keepalive peer: using connection 00007F05BFDEC520
2015/11/23 01:31:43 [debug] 20022#0: *5 http upstream connect: -4
2015/11/23 01:31:43 [debug] 20022#0: *5 http upstream send request
2015/11/23 01:31:43 [debug] 20022#0: *5 http upstream send request body
2015/11/23 01:31:43 [debug] 20022#0: *5 chain writer buf fl:0 s:75
2015/11/23 01:31:43 [debug] 20022#0: *5 chain writer in: 0000000000AE6FE0
2015/11/23 01:31:43 [debug] 20022#0: *5 writev: 75 of 75
2015/11/23 01:31:43 [debug] 20022#0: *5 chain writer out: 0000000000000000
2015/11/23 01:31:43 [debug] 20022#0: *5 event timer add: 11: 60000:1448242363312
2015/11/23 01:31:43 [debug] 20022#0: *5 http finalize request: -4, "/getcache-aux?key=e97f9635e589757dc74fa9b7b9f3f1c8" a:0, c:4
2015/11/23 01:31:43 [debug] 20022#0: *5 http request count:4 blk:0
2015/11/23 01:31:43 [debug] 20022#0: *5 http run request: "/getcache?key=e97f9635e589757dc74fa9b7b9f3f1c8"
2015/11/23 01:31:43 [debug] 20022#0: *5 http request empty handler
2015/11/23 01:31:43 [debug] 20022#0: *5 http upstream request: "/getcache-aux?key=e97f9635e589757dc74fa9b7b9f3f1c8"
2015/11/23 01:31:43 [debug] 20022#0: *5 http upstream process header
2015/11/23 01:31:43 [debug] 20022#0: *5 malloc: 0000000000AE8070:4096
2015/11/23 01:31:43 [debug] 20022#0: *5 recv: fd:11 10 of 4096
2015/11/23 01:31:43 [debug] 20022#0: *5 lua capture header filter, uri "/getcache-aux"
2015/11/23 01:31:43 [debug] 20022#0: *5 lua capturing response body
2015/11/23 01:31:43 [debug] 20022#0: *5 tcp_nodelay
2015/11/23 01:31:43 [debug] 20022#0: *5 http upstream process non buffered downstream
2015/11/23 01:31:43 [debug] 20022#0: *5 http output filter "/getcache-aux?key=e97f9635e589757dc74fa9b7b9f3f1c8"
2015/11/23 01:31:43 [debug] 20022#0: *5 http copy filter: "/getcache-aux?key=e97f9635e589757dc74fa9b7b9f3f1c8"
2015/11/23 01:31:43 [debug] 20022#0: *5 lua capture body filter, uri "/getcache-aux"
2015/11/23 01:31:43 [debug] 20022#0: *5 lua capture body filter capturing response body, uri "/getcache-aux"
2015/11/23 01:31:43 [debug] 20022#0: *5 lua allocate new chainlink and new buf of size 10, cl:0000000000AE7DE8
2015/11/23 01:31:43 [debug] 20022#0: *5 http copy filter: 0 "/getcache-aux?key=e97f9635e589757dc74fa9b7b9f3f1c8"
2015/11/23 01:31:43 [debug] 20022#0: *5 finalize http upstream request: 0
2015/11/23 01:31:43 [debug] 20022#0: *5 finalize http redis2 request
2015/11/23 01:31:43 [debug] 20022#0: *5 free keepalive peer
2015/11/23 01:31:43 [debug] 20022#0: *5 free keepalive peer: saving connection 00007F05BFDEC520
2015/11/23 01:31:43 [debug] 20022#0: *5 event timer del: 11: 1448242363312
2015/11/23 01:31:43 [debug] 20022#0: *5 free rr peer 1 0
2015/11/23 01:31:43 [debug] 20022#0: *5 http output filter "/getcache-aux?key=e97f9635e589757dc74fa9b7b9f3f1c8"
2015/11/23 01:31:43 [debug] 20022#0: *5 http copy filter: "/getcache-aux?key=e97f9635e589757dc74fa9b7b9f3f1c8"
2015/11/23 01:31:43 [debug] 20022#0: *5 lua capture body filter, uri "/getcache-aux"
2015/11/23 01:31:43 [debug] 20022#0: *5 lua capture body filter capturing response body, uri "/getcache-aux"
2015/11/23 01:31:43 [debug] 20022#0: *5 http copy filter: 0 "/getcache-aux?key=e97f9635e589757dc74fa9b7b9f3f1c8"
2015/11/23 01:31:43 [debug] 20022#0: *5 http finalize request: 0, "/getcache-aux?key=e97f9635e589757dc74fa9b7b9f3f1c8" a:0, c:3
2015/11/23 01:31:43 [debug] 20022#0: *5 lua run post subrequest handler, rc:0 c:3
2015/11/23 01:31:43 [debug] 20022#0: *5 lua restoring write event handler
2015/11/23 01:31:43 [debug] 20022#0: *5 http wake parent request: "/getcache?key=e97f9635e589757dc74fa9b7b9f3f1c8"
2015/11/23 01:31:43 [debug] 20022#0: *5 http posted request: "/getcache?key=e97f9635e589757dc74fa9b7b9f3f1c8"
2015/11/23 01:31:43 [debug] 20022#0: *5 lua run subrequests done, resuming lua thread
2015/11/23 01:31:43 [debug] 20022#0: *5 lua handle subrequest responses
2015/11/23 01:31:43 [debug] 20022#0: *5 lua run thread, top:0 c:2
2015/11/23 01:31:43 [debug] 20022#0: *5 lua exit with code 404
2015/11/23 01:31:43 [debug] 20022#0: *5 lua resume returned 1
2015/11/23 01:31:43 [debug] 20022#0: *5 lua thread yielded
2015/11/23 01:31:43 [debug] 20022#0: *5 lua thread aborting request with status 404
2015/11/23 01:31:43 [debug] 20022#0: *5 lua request cleanup: forcible=0
2015/11/23 01:31:43 [debug] 20022#0: *5 lua run thread returned 404
2015/11/23 01:31:43 [debug] 20022#0: *5 http finalize request: 404, "/getcache?key=e97f9635e589757dc74fa9b7b9f3f1c8" a:1, c:2
2015/11/23 01:31:43 [debug] 20022#0: *5 http wake parent request: "/ripple_cust_api/?"
2015/11/23 01:31:43 [debug] 20022#0: *5 http posted request: "/getcache?key=e97f9635e589757dc74fa9b7b9f3f1c8"
2015/11/23 01:31:43 [debug] 20022#0: *5 lua run write event handler: timedout:0, ready:1, writing_raw_req_socket:0
2015/11/23 01:31:43 [debug] 20022#0: *5 useless lua write event handler
2015/11/23 01:31:43 [debug] 20022#0: *5 http posted request: "/ripple_cust_api/?"
2015/11/23 01:31:43 [debug] 20022#0: *5 access phase: 11
2015/11/23 01:31:43 [debug] 20022#0: *5 http script var: "0"
2015/11/23 01:31:43 [debug] 20022#0: *5 post access phase: 12
2015/11/23 01:31:43 [debug] 20022#0: *5 posix_memalign: 0000000000AE9080:4096 @16
2015/11/23 01:31:43 [debug] 20022#0: *5 http init upstream, client timer: 0
2015/11/23 01:31:43 [debug] 20022#0: *5 http script copy: "Host: "
2015/11/23 01:31:43 [debug] 20022#0: *5 http script var: "be-custapi"
2015/11/23 01:31:43 [debug] 20022#0: *5 http script copy: "
"
2015/11/23 01:31:43 [debug] 20022#0: *5 http script copy: "Connection: close
"
2015/11/23 01:31:43 [debug] 20022#0: *5 http script copy: "Content-Length: "
2015/11/23 01:31:43 [debug] 20022#0: *5 http script var: "882"
2015/11/23 01:31:43 [debug] 20022#0: *5 http script copy: "
"
2015/11/23 01:31:43 [debug] 20022#0: *5 http script copy: ""
2015/11/23 01:31:43 [debug] 20022#0: *5 http script copy: ""
2015/11/23 01:31:43 [debug] 20022#0: *5 http proxy header: "User-Agent: curl/7.35.0"
2015/11/23 01:31:43 [debug] 20022#0: *5 http proxy header: "Accept: */*"
2015/11/23 01:31:43 [debug] 20022#0: *5 http proxy header: "Content-type: text/plain"
2015/11/23 01:31:43 [debug] 20022#0: *5 http proxy header:
"POST /ripple_cust_api/ HTTP/1.0
Host: be-custapi
Connection: close
Content-Length: 882
User-Agent: curl/7.35.0
Accept: */*
Content-type: text/plain

"
2015/11/23 01:31:43 [debug] 20022#0: *5 http cleanup add: 0000000000AE96F8
2015/11/23 01:31:43 [debug] 20022#0: *5 init keepalive peer
2015/11/23 01:31:43 [debug] 20022#0: *5 get keepalive peer
2015/11/23 01:31:43 [debug] 20022#0: *5 get rr peer, try: 1
2015/11/23 01:31:43 [debug] 20022#0: *5 socket 15
2015/11/23 01:31:43 [debug] 20022#0: *5 epoll add connection: fd:15 ev:80002005
2015/11/23 01:31:43 [debug] 20022#0: *5 connect to 127.0.0.1:3333, fd:15 #6
2015/11/23 01:31:43 [debug] 20022#0: *5 http upstream connect: -2
2015/11/23 01:31:43 [debug] 20022#0: *5 posix_memalign: 0000000000A893A0:128 @16
2015/11/23 01:31:43 [debug] 20022#0: *5 event timer add: 15: 60000:1448242363317
2015/11/23 01:31:43 [debug] 20022#0: *5 http finalize request: -4, "/ripple_cust_api/?" a:1, c:2
2015/11/23 01:31:43 [debug] 20022#0: *5 http request count:2 blk:0
2015/11/23 01:31:43 [debug] 20022#0: *5 http posted request: "/ripple_cust_api/?"
2015/11/23 01:31:43 [debug] 20022#0: *5 http upstream check client, write event:1, "/ripple_cust_api/"
2015/11/23 01:31:43 [debug] 20022#0: *5 http upstream recv(): -1 (11: Resource temporarily unavailable)
2015/11/23 01:31:43 [debug] 20022#0: *5 http upstream request: "/ripple_cust_api/?"
2015/11/23 01:31:43 [debug] 20022#0: *5 http upstream process header
2015/11/23 01:31:43 [error] 20022#0: *5 connect() failed (111: Connection refused) while connecting to upstream, client: 127.0.0.1, server: , request: "POST /ripple_cust_api/ HTTP/1.1", upstream: "http://127.0.0.1:3333/ripple_cust_api/";, host: "localhost:8000"
2015/11/23 01:31:43 [debug] 20022#0: *5 http next upstream, 2
2015/11/23 01:31:43 [debug] 20022#0: *5 free keepalive peer
2015/11/23 01:31:43 [debug] 20022#0: *5 free rr peer 1 4
2015/11/23 01:31:43 [debug] 20022#0: *5 finalize http upstream request: 502
2015/11/23 01:31:43 [debug] 20022#0: *5 finalize http proxy request
2015/11/23 01:31:43 [debug] 20022#0: *5 close http upstream connection: 15
2015/11/23 01:31:43 [debug] 20022#0: *5 free: 0000000000A893A0, unused: 48
2015/11/23 01:31:43 [debug] 20022#0: *5 event timer del: 15: 1448242363317
2015/11/23 01:31:43 [debug] 20022#0: *5 reusable connection: 0
2015/11/23 01:31:43 [debug] 20022#0: *5 http finalize request: 502, "/ripple_cust_api/?" a:1, c:1
2015/11/23 01:31:43 [debug] 20022#0: *5 http special response: 502, "/ripple_cust_api/?"
2015/11/23 01:31:43 [debug] 20022#0: *5 lua capture header filter, uri "/ripple_cust_api/"
2015/11/23 01:31:43 [debug] 20022#0: *5 http script var: "0"
2015/11/23 01:31:43 [debug] 20022#0: *5 srcache_store bypassed because of unmatched status code 502 with srcache_store_statuses
2015/11/23 01:31:43 [debug] 20022#0: *5 HTTP/1.1 502 Bad Gateway
Server: openresty/1.9.3.1
Date: Mon, 23 Nov 2015 01:31:43 GMT
Content-Type: text/html
Content-Length: 178
Connection: keep-alive

2015/11/23 01:31:43 [debug] 20022#0: *5 write new buf t:1 f:0 0000000000AE97B8, pos 0000000000AE97B8, size: 162 file: 0, size: 0
2015/11/23 01:31:43 [debug] 20022#0: *5 http write filter: l:0 f:0 s:162
2015/11/23 01:31:43 [debug] 20022#0: *5 http output filter "/ripple_cust_api/?"
2015/11/23 01:31:43 [debug] 20022#0: *5 http copy filter: "/ripple_cust_api/?"
2015/11/23 01:31:43 [debug] 20022#0: *5 lua capture body filter, uri "/ripple_cust_api/"
2015/11/23 01:31:43 [debug] 20022#0: *5 http postpone filter "/ripple_cust_api/?" 0000000000AE9988
2015/11/23 01:31:43 [debug] 20022#0: *5 write old buf t:1 f:0 0000000000AE97B8, pos 0000000000AE97B8, size: 162 file: 0, size: 0
2015/11/23 01:31:43 [debug] 20022#0: *5 write new buf t:0 f:0 0000000000000000, pos 0000000000730620, size: 120 file: 0, size: 0
2015/11/23 01:31:43 [debug] 20022#0: *5 write new buf t:0 f:0 0000000000000000, pos 0000000000731900, size: 58 file: 0, size: 0
2015/11/23 01:31:43 [debug] 20022#0: *5 http write filter: l:1 f:0 s:340
2015/11/23 01:31:43 [debug] 20022#0: *5 http write filter limit 0
2015/11/23 01:31:43 [debug] 20022#0: *5 writev: 340 of 340
2015/11/23 01:31:43 [debug] 20022#0: *5 http write filter 0000000000000000
2015/11/23 01:31:43 [debug] 20022#0: *5 http copy filter: 0 "/ripple_cust_api/?"
2015/11/23 01:31:43 [debug] 20022#0: *5 http finalize request: 0, "/ripple_cust_api/?" a:1, c:1
2015/11/23 01:31:43 [debug] 20022#0: *5 set http keepalive handler
2015/11/23 01:31:43 [debug] 20022#0: *5 http close request
2015/11/23 01:31:43 [debug] 20022#0: *5 lua request cleanup: forcible=0
2015/11/23 01:31:43 [debug] 20022#0: *5 http log handler
2015/11/23 01:31:43 [debug] 20022#0: *5 run cleanup: 0000000000AE5F30
2015/11/23 01:31:43 [debug] 20022#0: *5 run cleanup: 0000000000AE5010
2015/11/23 01:31:43 [debug] 20022#0: *5 free: 0000000000AE8070
2015/11/23 01:31:43 [debug] 20022#0: *5 free: 0000000000AE4030, unused: 0
2015/11/23 01:31:43 [debug] 20022#0: *5 free: 0000000000AE5040, unused: 0
2015/11/23 01:31:43 [debug] 20022#0: *5 free: 0000000000AE6050, unused: 0
2015/11/23 01:31:43 [debug] 20022#0: *5 free: 0000000000AE7060, unused: 8
2015/11/23 01:31:43 [debug] 20022#0: *5 free: 0000000000AE9080, unused: 1583
2015/11/23 01:31:43 [debug] 20022#0: *5 free: 0000000000AE3C20
2015/11/23 01:31:43 [debug] 20022#0: *5 hc free: 0000000000000000 0
2015/11/23 01:31:43 [debug] 20022#0: *5 hc busy: 0000000000000000 0
2015/11/23 01:31:43 [debug] 20022#0: *5 reusable connection: 1
2015/11/23 01:31:43 [debug] 20022#0: *5 event timer add: 14: 65000:1448242368318
2015/11/23 01:31:43 [debug] 20022#0: *5 post event 00007F05BF7EC370
2015/11/23 01:31:43 [debug] 20022#0: *5 delete posted event 00007F05BF7EC370
2015/11/23 01:31:43 [debug] 20022#0: *5 http keepalive handler
2015/11/23 01:31:43 [debug] 20022#0: *5 malloc: 0000000000AE3C20:1024
2015/11/23 01:31:43 [debug] 20022#0: *5 recv: fd:14 -1 of 1024
2015/11/23 01:31:43 [debug] 20022#0: *5 recv() not ready (11: Resource temporarily unavailable)
2015/11/23 01:31:43 [debug] 20022#0: *5 free: 0000000000AE3C20
2015/11/23 01:31:43 [debug] 20022#0: *5 http keepalive handler
2015/11/23 01:31:43 [debug] 20022#0: *5 malloc: 0000000000AE3C20:1024
2015/11/23 01:31:43 [debug] 20022#0: *5 recv: fd:14 0 of 1024
2015/11/23 01:31:43 [info] 20022#0: *5 client 127.0.0.1 closed keepalive connection
2015/11/23 01:31:43 [debug] 20022#0: *5 close http connection: 14
2015/11/23 01:31:43 [debug] 20022#0: *5 event timer del: 14: 1448242368318
2015/11/23 01:31:43 [debug] 20022#0: *5 reusable connection: 0
2015/11/23 01:31:43 [debug] 20022#0: *5 free: 0000000000AE3C20
2015/11/23 01:31:43 [debug] 20022#0: *5 free: 0000000000A82A70, unused: 24
2015/11/23 01:31:43 [debug] 20022#0: *5 free: 0000000000A82B80, unused: 72

agentzh

Hello!

2015-11-23 9:33 GMT+08:00 Yongke Wang:
> Debug logs with/without problem attached.
>

你的 log_with_problem.txt 中显示你在 Lua 代码中使用了
ngx.location.capture*，而你第一封邮件里面提供的 Lua 代码里并没有地方使用这个 API
函数。请确保你提供的最小化的例子和你的调试日志是严格一致的。另外，你的调试日志中出现的 location /getcache-aux
在你提供的配置里面也没有出现，请确保你提供的配置片段是足够完整的。否则作为读者，其实是很迷惑的。

Regards,
-agentzh

agentzh

Hello!

2015-11-23 17:34 GMT+08:00 Yichun Zhang (agentzh):
>
> 你的 log_with_problem.txt 中显示你在 Lua 代码中使用了
> ngx.location.capture*，而你第一封邮件里面提供的 Lua 代码里并没有地方使用这个 API
> 函数。请确保你提供的最小化的例子和你的调试日志是严格一致的。另外，你的调试日志中出现的 location /getcache-aux
> 在你提供的配置里面也没有出现，请确保你提供的配置片段是足够完整的。否则作为读者，其实是很迷惑的。
>

你提供的代码示例中使用的是 srcache，而你的调试日志中并没有任何 srcache 运行的痕迹，相反，都是用的 ngx_lua 的
ngx.location.capture. 你有问题的那个配置，应当是在 ngx.location.capture 指向的子请求的
location 里面禁掉了 proxy 模块的 buffering（比如配置了 proxy_buffering off 或者
proxy_max_temp_file_size 0），此时 ngx.location.capture 会挂起，这受限于 ngx_proxy
模块的内部实现。建议开启子请求 location 中的 proxy buffering.

Regards,
-agentzh

wangyongke

Sorry，春哥

这个配置在另外一个文件中，忘记贴出来了，内容是这样的

location = /getcache {

internal;

content_by_lua '

local res = ngx.location.capture(

"/getcache-aux?" .. ngx.var.args)

local body = res.body

local len = #body

-- pattern match follow http://redis.io/topics/protocol

local _, new = string.match(body, "+OK\\r\\n$(%d+)\\r\\n(.+)\\r\\n")

if not new then

ngx.exit(ngx.HTTP_NOT_FOUND)

end

ngx.say(new)

}

location = /getcache-aux {

internal;

redis2_query auth 123;

redis2_query get $arg_key;

redis2_pass redis-cache;

}

location = /setcache {

internal;

echo_read_request_body;

redis2_query auth 123;

redis2_query setex $arg_key $arg_ttl $echo_request_body;

redis2_pass redis-cache;

}

在 2015年11月23日星期一 UTC+8下午5:34:41，agentzh写道：

Hello!

2015-11-23 9:33 GMT+08:00 Yongke Wang:
> Debug logs with/without problem attached.
>

你的 log_with_problem.txt 中显示你在 Lua 代码中使用了
ngx.location.capture*，而你第一封邮件里面提供的 Lua 代码里并没有地方使用这个 API
函数。请确保你提供的最小化的例子和你的调试日志是严格一致的。另外，你的调试日志中出现的 location /getcache-aux
在你提供的配置里面也没有出现，请确保你提供的配置片段是足够完整的。否则作为读者，其实是很迷惑的。

Regards,
-agentzh

agentzh

Hello!

2015-11-23 17:53 GMT+08:00 Yongke Wang:
>     srcache_fetch GET /getcache key=$cache_key;
>
[...]
>
> location = /getcache {
>     internal;
>     content_by_lua '
>        local res = ngx.location.capture(

问题原因：你在同一个子请求链条中混用了 srcache_fetch 和 ngx.location.capture，这是不支持的，请参见：

https://github.com/openresty/lua-nginx-module#locations-configured-by-subrequest-directives-of-other-modules

解决办法：你这里直接换用 lua-resty-redis 就好了，并不需要使用 ngx.location.capture +
ngx_redis. 毕竟 lua-resty-redis 也更为高效。

Regards,
-agentzh

agentzh

Hello!

On Mon, Nov 23, 2015 at 5:59 PM, Yichun Zhang (agentzh) wrote:
> 2015-11-23 17:53 GMT+08:00 Yongke Wang:
>>     srcache_fetch GET /getcache key=$cache_key;
>>
> [...]
>>
>> location = /getcache {
>>     internal;
>>     content_by_lua '
>>        local res = ngx.location.capture(
>
> 问题原因：你在同一个子请求链条中混用了 srcache_fetch 和 ngx.location.capture，这是不支持的，请参见：
>
> https://github.com/openresty/lua-nginx-module#locations-configured-by-subrequest-directives-of-other-modules
>
> 解决办法：你这里直接换用 lua-resty-redis 就好了，并不需要使用 ngx.location.capture +
> ngx_redis. 毕竟 lua-resty-redis 也更为高效。

事实上，更简单的做法是在 /getcache 里面直接使用 ngx_redis 模块，正如官方文档中所演示的：

    https://github.com/openresty/srcache-nginx-module#caching-with-redis

这里根本不必用 Lua.

Regards,
-agentzh

wangyongke

春哥，可是我们没有任何显式的关闭proxy buffering的配置。我记得proxy buffering默认都是开启的。

在 2015年11月23日星期一 UTC+8下午5:40:00，agentzh写道：

Hello!

2015-11-23 17:34 GMT+08:00 Yichun Zhang (agentzh):
>
> 你的 log_with_problem.txt 中显示你在 Lua 代码中使用了
> ngx.location.capture*，而你第一封邮件里面提供的 Lua 代码里并没有地方使用这个 API
> 函数。请确保你提供的最小化的例子和你的调试日志是严格一致的。另外，你的调试日志中出现的 location /getcache-aux
> 在你提供的配置里面也没有出现，请确保你提供的配置片段是足够完整的。否则作为读者，其实是很迷惑的。
>

你提供的代码示例中使用的是 srcache，而你的调试日志中并没有任何 srcache 运行的痕迹，相反，都是用的 ngx_lua 的
ngx.location.capture. 你有问题的那个配置，应当是在 ngx.location.capture 指向的子请求的
location 里面禁掉了 proxy 模块的 buffering（比如配置了 proxy_buffering off 或者
proxy_max_temp_file_size 0），此时 ngx.location.capture 会挂起，这受限于 ngx_proxy
模块的内部实现。建议开启子请求 location 中的 proxy buffering.

Regards,
-agentzh

agentzh

Hello!

2015-11-23 18:03 GMT+08:00 Yongke Wang <wang...@gmail.com>:
> 春哥， 可是我们没有任何显式的关闭proxy buffering的配置。我记得proxy buffering默认都是开启的。
>

可以忽略我先前对 proxy buffering 的描述（是的，由于你的配置不全，我被搞晕了）。请以我前面最后两封邮件的内容为准。

Regards,
-agentzh

wangyongke

非常感谢春哥的答复，我们现在就是直接用lua-resty-redis的。

在 2015年11月23日星期一 UTC+8下午5:59:18，agentzh写道：

Hello!

2015-11-23 17:53 GMT+08:00 Yongke Wang:
> srcache_fetch GET /getcache key=$cache_key;
>
[...]
>
> location = /getcache {
> internal;
> content_by_lua '
> local res = ngx.location.capture(

问题原因：你在同一个子请求链条中混用了 srcache_fetch 和 ngx.location.capture，这是不支持的，请参见：

https://github.com/openresty/lua-nginx-module#locations-configured-by-subrequest-directives-of-other-modules

解决办法：你这里直接换用 lua-resty-redis 就好了，并不需要使用 ngx.location.capture +
ngx_redis. 毕竟 lua-resty-redis 也更为高效。

Regards,
-agentzh

wangyongke

谢谢春哥，但是官方的redis不支持auth，但是比较坑的aliyun的kvs，不能去掉auth，必须设置一个password...

在 2015年11月23日星期一 UTC+8下午6:01:17，agentzh写道：

Hello!

On Mon, Nov 23, 2015 at 5:59 PM, Yichun Zhang (agentzh) wrote:
> 2015-11-23 17:53 GMT+08:00 Yongke Wang:
>> srcache_fetch GET /getcache key=$cache_key;
>>
> [...]
>>
>> location = /getcache {
>> internal;
>> content_by_lua '
>> local res = ngx.location.capture(
>
> 问题原因：你在同一个子请求链条中混用了 srcache_fetch 和 ngx.location.capture，这是不支持的，请参见：
>
> https://github.com/openresty/lua-nginx-module#locations-configured-by-subrequest-directives-of-other-modules
>
> 解决办法：你这里直接换用 lua-resty-redis 就好了，并不需要使用 ngx.location.capture +
> ngx_redis. 毕竟 lua-resty-redis 也更为高效。

事实上，更简单的做法是在 /getcache 里面直接使用 ngx_redis 模块，正如官方文档中所演示的：

https://github.com/openresty/srcache-nginx-module#caching-with-redis

这里根本不必用 Lua.

Regards,
-agentzh

agentzh

Hello!

2015-11-23 18:08 GMT+08:00 Yongke Wang:
> 谢谢春哥， 但是官方的redis不支持auth， 但是比较坑的aliyun的kvs， 不能去掉auth， 必须设置一个password...
>

哦，我明白了。值得一提的是，那个 ngx_redis 模块也不是官方的模块，而是 FreeBSD 社区的 Sergey A. Osokin 编写的第三方模块。

Regards,
-agentzh