nginx debug 日志如下,红色的地方,相差17秒,客户端17秒后端口连接,lua才开始继续执行,不知道什么原因。
2013/02/05 12:50:00 [debug] 27380#0: epoll: fd:6 ev:0001 d:00007F5C92639010
2013/02/05 12:50:00 [debug] 27380#0: accept on 0.0.0.0:80, ready: 0
2013/02/05 12:50:00 [debug] 27380#0: posix_memalign: 0000000000D27A40:256 @16
2013/02/05 12:50:00 [debug] 27380#0: *3 accept: 192.168.1.100 fd:3
2013/02/05 12:50:00 [debug] 27380#0: *3 event timer add: 3: 100000:1360039900499
2013/02/05 12:50:00 [debug] 27380#0: *3 epoll add event: fd:3 op:1 ev:80000001
2013/02/05 12:50:00 [debug] 27380#0: timer delta: 4539360
2013/02/05 12:50:00 [debug] 27380#0: posted events 0000000000000000
2013/02/05 12:50:00 [debug] 27380#0: worker cycle
2013/02/05 12:50:00 [debug] 27380#0: epoll timer: 100000
2013/02/05 12:50:03 [debug] 27380#0: epoll: fd:3 ev:0001 d:00007F5C92639191
2013/02/05 12:50:03 [debug] 27380#0: *3 malloc: 0000000000D2F560:1256
2013/02/05 12:50:03 [debug] 27380#0: *3 posix_memalign: 0000000000D27BA0:256 @16
2013/02/05 12:50:03 [debug] 27380#0: *3 malloc: 0000000000D2FA50:1024
2013/02/05 12:50:03 [debug] 27380#0: *3 posix_memalign: 0000000000D32B80:4096 @16
2013/02/05 12:50:03 [debug] 27380#0: *3 http process request line
2013/02/05 12:50:03 [debug] 27380#0: *3 recv: fd:3 669 of 1024
2013/02/05 12:50:03 [debug] 27380#0: *3 http request line: "POST /sync/upload_file?upload_token=2F7D3A6B6467433Ef7Abg9JL&start_pos=0 HTTP/1.1"
2013/02/05 12:50:03 [debug] 27380#0: *3 http uri: "/sync/upload_file"
2013/02/05 12:50:03 [debug] 27380#0: *3 http args: "upload_token=2F7D3A6B6467433Ef7Abg9JL&start_pos=0"
2013/02/05 12:50:03 [debug] 27380#0: *3 http exten: ""
2013/02/05 12:50:03 [debug] 27380#0: *3 http process request header line
2013/02/05 12:50:03 [debug] 27380#0: *3 http header: "Accept-Encoding: default,gzip"
2013/02/05 12:50:03 [debug] 27380#0: *3 http header: "Content-Encoding: gzip"
2013/02/05 12:50:03 [debug] 27380#0: *3 http header: "User-Agent: Dalvik/1.6.0 (Linux; U; Android 4.1.1; HTC T528t Build/JRO03H)"
2013/02/05 12:50:03 [debug] 27380#0: *3 http header: "Host: 192.168.0.17"
2013/02/05 12:50:03 [debug] 27380#0: *3 http header: "Connection: Keep-Alive"
2013/02/05 12:50:03 [debug] 27380#0: *3 http header: "Content-Type: application/x-www-form-urlencoded"
2013/02/05 12:50:03 [debug] 27380#0: *3 http header: "Transfer-Encoding: chunked"
2013/02/05 12:50:03 [debug] 27380#0: *3 http header done
2013/02/05 12:50:03 [info] 27380#0: *3 client sent "Transfer-Encoding: chunked" header while reading client request headers, client: 192.168.1.100, server: , request: "POST /sync/upload_file?upload_token=2F7D3A6B6467433Ef7Abg9JL&start_pos=0 HTTP/1.1", host: "192.168.0.17"
2013/02/05 12:50:03 [debug] 27380#0: *3 http finalize request: 411, "/sync/upload_file?upload_token=2F7D3A6B6467433Ef7Abg9JL&start_pos=0" a:1, c:1
2013/02/05 12:50:03 [debug] 27380#0: *3 event timer del: 3: 1360039900499
2013/02/05 12:50:03 [debug] 27380#0: *3 http special response: 411, "/sync/upload_file?upload_token=2F7D3A6B6467433Ef7Abg9JL&start_pos=0"
2013/02/05 12:50:03 [debug] 27380#0: *3 test location: "@my_411_error"
2013/02/05 12:50:03 [debug] 27380#0: *3 using location: @my_411_error "/sync/upload_file?upload_token=2F7D3A6B6467433Ef7Abg9JL&start_pos=0"
2013/02/05 12:50:03 [debug] 27380#0: *3 rewrite phase: 2
2013/02/05 12:50:03 [debug] 27380#0: *3 post rewrite phase: 3
2013/02/05 12:50:03 [debug] 27380#0: *3 generic phase: 4
2013/02/05 12:50:03 [debug] 27380#0: *3 generic phase: 5
2013/02/05 12:50:03 [debug] 27380#0: *3 access phase: 6
2013/02/05 12:50:03 [debug] 27380#0: *3 access phase: 7
2013/02/05 12:50:03 [debug] 27380#0: *3 access phase: 8
2013/02/05 12:50:03 [debug] 27380#0: *3 post access phase: 9
2013/02/05 12:50:03 [debug] 27380#0: *3 internal redirect: "/sync/upload_file?upload_token=2F7D3A6B6467433Ef7Abg9JL&start_pos=0"
2013/02/05 12:50:03 [debug] 27380#0: *3 rewrite phase: 0
2013/02/05 12:50:03 [debug] 27380#0: *3 test location: "/"
2013/02/05 12:50:03 [debug] 27380#0: *3 test location: "sync/upload_file"
2013/02/05 12:50:03 [debug] 27380#0: *3 using configuration "=/sync/upload_file"
2013/02/05 12:50:03 [debug] 27380#0: *3 http cl:1 max:10485760
2013/02/05 12:50:03 [debug] 27380#0: *3 rewrite phase: 2
2013/02/05 12:50:03 [debug] 27380#0: *3 post rewrite phase: 3
2013/02/05 12:50:03 [debug] 27380#0: *3 generic phase: 4
2013/02/05 12:50:03 [debug] 27380#0: *3 generic phase: 5
2013/02/05 12:50:03 [debug] 27380#0: *3 access phase: 6
2013/02/05 12:50:03 [debug] 27380#0: *3 chunkin: http chunked client request body preread 332
2013/02/05 12:50:03 [debug] 27380#0: *3 chunkin: chunk size: 10
2013/02/05 12:50:03 [debug] 27380#0: *3 chunkin: data bytes read: 10 (char: "")
2013/02/05 12:50:03 [debug] 27380#0: *3 chunkin: chunk size: 1
2013/02/05 12:50:03 [debug] 27380#0: *3 chunkin: chunk size: 19
2013/02/05 12:50:03 [debug] 27380#0: *3 chunkin: chunk size: 305
2013/02/05 12:50:03 [debug] 27380#0: *3 chunkin: data bytes read: 305 (char: "")
2013/02/05 12:50:03 [debug] 27380#0: *3 chunkin: chunk size: 0
2013/02/05 12:50:03 [debug] 27380#0: *3 access phase: 7
2013/02/05 12:50:03 [debug] 27380#0: *3 access phase: 8
2013/02/05 12:50:03 [debug] 27380#0: *3 post access phase: 9
2013/02/05 12:50:03 [debug] 27380#0: *3 lua content handler, uri "/sync/upload_file"
2013/02/05 12:50:03 [debug] 27380#0: *3 lua reset ctx
2013/02/05 12:50:03 [debug] 27380#0: *3 lua creating new thread
2013/02/05 12:50:03 [debug] 27380#0: *3 http cleanup add: 0000000000D33A60
2013/02/05 12:50:03 [debug] 27380#0: *3 lua run thread, top:0
2013/02/05 12:50:03 [debug] 27380#0: *3 lua start to read buffered request body
2013/02/05 12:50:03 [debug] 27380#0: *3 lua req body post read
2013/02/05 12:50:03 [debug] 27380#0: *3 lua has read buffered request body in a single run
2013/02/05 12:50:03 [debug] 27380#0: *3 posix_memalign: 0000000000D94590:4096 @16
2013/02/05 12:50:03 [debug] 27380#0: *3 http subrequest "/sync/db_querytoken?tbindex=ts_upload_token&backend=syncmysqlbackend&token=2F7D3A6B6467433Ef7Abg9JL"
2013/02/05 12:50:03 [debug] 27380#0: *3 posix_memalign: 0000000000D955A0:4096 @16
2013/02/05 12:50:03 [debug] 27380#0: *3 lua resume returned 1
2013/02/05 12:50:03 [debug] 27380#0: *3 lua thread yielded
2013/02/05 12:50:03 [debug] 27380#0: *3 http finalize request: -4, "/sync/upload_file?upload_token=2F7D3A6B6467433Ef7Abg9JL&start_pos=0" a:1, c:5
2013/02/05 12:50:03 [debug] 27380#0: *3 http request count:5 blk:0
2013/02/05 12:50:03 [debug] 27380#0: *3 http finalize request: -4, "/sync/upload_file?upload_token=2F7D3A6B6467433Ef7Abg9JL&start_pos=0" a:1, c:4
2013/02/05 12:50:03 [debug] 27380#0: *3 http request count:4 blk:0
2013/02/05 12:50:03 [debug] 27380#0: *3 http finalize request: -4, "/sync/upload_file?upload_token=2F7D3A6B6467433Ef7Abg9JL&start_pos=0" a:1, c:3
2013/02/05 12:50:03 [debug] 27380#0: *3 http request count:3 blk:0
2013/02/05 12:50:03 [debug] 27380#0: timer delta: 2639
2013/02/05 12:50:03 [debug] 27380#0: posted events 0000000000000000
2013/02/05 12:50:03 [debug] 27380#0: worker cycle
2013/02/05 12:50:03 [debug] 27380#0: epoll timer: -1
2013/02/05 12:50:20 [debug] 27380#0: epoll: fd:3 ev:0001 d:00007F5C92639191
2013/02/05 12:50:20 [debug] 27380#0: *3 http run request: "/sync/upload_file?upload_token=2F7D3A6B6467433Ef7Abg9JL&start_pos=0"
2013/02/05 12:50:20 [debug] 27380#0: *3 http reading blocked
2013/02/05 12:50:20 [debug] 27380#0: *3 http posted request: "/sync/db_querytoken?tbindex=ts_upload_token&backend=syncmysqlbackend&token=2F7D3A6B6467433Ef7Abg9JL"
2013/02/05 12:50:20 [debug] 27380#0: *3 rewrite phase: 0
2013/02/05 12:50:20 [debug] 27380#0: *3 test location: "/"
2013/02/05 12:50:20 [debug] 27380#0: *3 test location: "sync/upload_file"
2013/02/05 12:50:20 [debug] 27380#0: *3 test location: "sync/db_querytoken"
2013/02/05 12:50:20 [debug] 27380#0: *3 using configuration "=/sync/db_querytoken"
2013/02/05 12:50:20 [debug] 27380#0: *3 http cl:0 max:1048576
2013/02/05 12:50:20 [debug] 27380#0: *3 rewrite phase: 2
2013/02/05 12:50:20 [debug] 27380#0: *3 http script complex value
2013/02/05 12:50:20 [debug] 27380#0: *3 http script var: "syncmysqlbackend"
2013/02/05 12:50:20 [debug] 27380#0: *3 http script value (post filter): "syncmysqlbackend"
2013/02/05 12:50:20 [debug] 27380#0: *3 http script set $backend
2013/02/05 12:50:20 [debug] 27380#0: *3 http script complex value
2013/02/05 12:50:20 [debug] 27380#0: *3 http script var: "2F7D3A6B6467433Ef7Abg9JL"
2013/02/05 12:50:20 [debug] 27380#0: *3 http script value (post filter): "2F7D3A6B6467433Ef7Abg9JL"
2013/02/05 12:50:20 [debug] 27380#0: *3 http script set $token
2013/02/05 12:50:20 [debug] 27380#0: *3 http script complex value
2013/02/05 12:50:20 [debug] 27380#0: *3 http script var: "2F7D3A6B6467433Ef7Abg9JL"
2013/02/05 12:50:20 [debug] 27380#0: *3 http script value (post filter): "'2F7D3A6B6467433Ef7Abg9JL'"
2013/02/05 12:50:20 [debug] 27380#0: *3 http script set $token
2013/02/05 12:50:20 [debug] 27380#0: *3 post rewrite phase: 3
2013/02/05 12:50:20 [debug] 27380#0: *3 generic phase: 4
2013/02/05 12:50:20 [debug] 27380#0: *3 generic phase: 5
2013/02/05 12:50:20 [debug] 27380#0: *3 http script var: "syncmysqlbackend"
2013/02/05 12:50:20 [debug] 27380#0: *3 http init upstream, client timer: 0
2013/02/05 12:50:20 [debug] 27380#0: *3 epoll add event: fd:3 op:3 ev:80000005
2013/02/05 12:50:20 [debug] 27380#0: *3 http cleanup add: 0000000000D95BE0
2013/02/05 12:50:20 [debug] 27380#0: *3 drizzle init peer
2013/02/05 12:50:20 [debug] 27380#0: *3 malloc: 0000000000DA0000:9256
2013/02/05 12:50:20 [debug] 27380#0: *3 http script copy: "SELECT user_id FROM "
2013/02/05 12:50:20 [debug] 27380#0: *3 http script var: "ts_upload_token"
2013/02/05 12:50:20 [debug] 27380#0: *3 http script copy: " WHERE token="
2013/02/05 12:50:20 [debug] 27380#0: *3 http script var: "'2F7D3A6B6467433Ef7Abg9JL'"
2013/02/05 12:50:20 [debug] 27380#0: *3 drizzle get peer
2013/02/05 12:50:20 [debug] 27380#0: *3 active drizzle connections 1
2013/02/05 12:50:20 [debug] 27380#0: *3 http upstream connect: -4
2013/02/05 12:50:20 [debug] 27380#0: *3 drizzle process events, state: 0
2013/02/05 12:50:20 [debug] 27380#0: *3 drizzle connect: user intsig, password intsig
2013/02/05 12:50:20 [debug] 27380#0: *3 drizzle sending query "SELECT user_id FROM ts_upload_token WHERE token='2F7D3A6B6467433Ef7Abg9JL'"
2013/02/05 12:50:20 [debug] 27380#0: *3 drizzle libdrizzle returned IO_WAIT while sending query
2013/02/05 12:50:20 [debug] 27380#0: *3 event timer add: 9: 60000:1360039880639
2013/02/05 12:50:20 [debug] 27380#0: *3 http finalize request: -4, "/sync/db_querytoken?tbindex=ts_upload_token&backend=syncmysqlbackend&token=2F7D3A6B6467433Ef7Abg9JL" a:0, c:3
2013/02/05 12:50:20 [debug] 27380#0: *3 http request count:3 blk:0
2013/02/05 12:50:20 [debug] 27380#0: timer delta: 17501
2013/02/05 12:50:20 [debug] 27380#0: posted events 0000000000000000
2013/02/05 12:50:20 [debug] 27380#0: worker cycle
2013/02/05 12:50:20 [debug] 27380#0: epoll timer: 60000
2013/02/05 12:50:20 [debug] 27380#0: epoll: fd:3 ev:0005 d:00007F5C92639191
2013/02/05 12:50:20 [debug] 27380#0: *3 http run request: "/sync/upload_file?upload_token=2F7D3A6B6467433Ef7Abg9JL&start_pos=0"
2013/02/05 12:50:20 [debug] 27380#0: *3 http reading blocked
2013/02/05 12:50:20 [debug] 27380#0: *3 http run request: "/sync/upload_file?upload_token=2F7D3A6B6467433Ef7Abg9JL&start_pos=0"
2013/02/05 12:50:20 [debug] 27380#0: *3 http request empty handler
2013/02/05 12:50:20 [debug] 27380#0: timer delta: 1
2013/02/05 12:50:20 [debug] 27380#0: posted events 0000000000000000
2013/02/05 12:50:20 [debug] 27380#0: worker cycle
2013/02/05 12:50:20 [debug] 27380#0: epoll timer: 59999
2013/02/05 12:50:20 [debug] 27380#0: epoll: fd:9 ev:0005 d:00007F5C92639250
2013/02/05 12:50:20 [debug] 27380#0: *3 http upstream request: "/sync/db_querytoken?tbindex=ts_upload_token&backend=syncmysqlbackend&token=2F7D3A6B6467433Ef7Abg9JL"
2013/02/05 12:50:20 [debug] 27380#0: *3 drizzle process events, state: 1
2013/02/05 12:50:20 [debug] 27380#0: *3 drizzle sending query "SELECT user_id FROM ts_upload_token WHERE token='2F7D3A6B6467433Ef7Abg9JL'"
2013/02/05 12:50:20 [debug] 27380#0: *3 event timer del: 9: 1360039880639
2013/02/05 12:50:20 [debug] 27380#0: *3 malloc: 0000000000D965B0:4096
2013/02/05 12:50:20 [debug] 27380#0: *3 drizzle receive resultset columns
2013/02/05 12:50:20 [debug] 27380#0: *3 drizzle receive resultset rows
2013/02/05 12:50:20 [debug] 27380#0: *3 drizzle receive resultset row 0
2013/02/05 12:50:20 [debug] 27380#0: *3 drizzle upstream done
2013/02/05 12:50:20 [debug] 27380#0: *3 rds json header filter, "/sync/db_querytoken"
2013/02/05 12:50:20 [debug] 27380#0: *3 rds json header filter postponed header sending
2013/02/05 12:50:20 [debug] 27380#0: *3 http output filter "/sync/db_querytoken?tbindex=ts_upload_token&backend=syncmysqlbackend&token=2F7D3A6B6467433Ef7Abg9JL"
2013/02/05 12:50:20 [debug] 27380#0: *3 http copy filter: "/sync/db_querytoken?tbindex=ts_upload_token&backend=syncmysqlbackend&token=2F7D3A6B6467433Ef7Abg9JL"
2013/02/05 12:50:20 [debug] 27380#0: *3 rds json body filter, "/sync/db_querytoken"
2013/02/05 12:50:20 [debug] 27380#0: *3 rds json body filter postponed header sending
2013/02/05 12:50:20 [debug] 27380#0: *3 lua capture header filter, uri "/sync/db_querytoken"
2013/02/05 12:50:20 [debug] 27380#0: *3 lua capturing response body
2013/02/05 12:50:20 [debug] 27380#0: *3 malloc: 0000000000DA2430:4096
2013/02/05 12:50:20 [debug] 27380#0: *3 lua capture body filter, uri "/sync/db_querytoken"
2013/02/05 12:50:20 [debug] 27380#0: *3 lua capture body filter capturing response body, uri "/sync/db_querytoken"
2013/02/05 12:50:20 [debug] 27380#0: *3 lua allocate new chainlink and new buf of size 2, cl:0000000000D95ED0
2013/02/05 12:50:20 [debug] 27380#0: *3 http copy filter: 0 "/sync/db_querytoken?tbindex=ts_upload_token&backend=syncmysqlbackend&token=2F7D3A6B6467433Ef7Abg9JL"
2013/02/05 12:50:20 [debug] 27380#0: *3 finalize http upstream request: 0
2013/02/05 12:50:20 [debug] 27380#0: *3 drizzle free peer
2013/02/05 12:50:20 [debug] 27380#0: *3 drizzle: free keepalive peer
2013/02/05 12:50:20 [debug] 27380#0: *3 drizzle: free keepalive peer: saving connection 00007F5C92639250
2013/02/05 12:50:20 [debug] 27380#0: *3 http output filter "/sync/db_querytoken?tbindex=ts_upload_token&backend=syncmysqlbackend&token=2F7D3A6B6467433Ef7Abg9JL"
2013/02/05 12:50:20 [debug] 27380#0: *3 http copy filter: "/sync/db_querytoken?tbindex=ts_upload_token&backend=syncmysqlbackend&token=2F7D3A6B6467433Ef7Abg9JL"
2013/02/05 12:50:20 [debug] 27380#0: *3 rds json body filter, "/sync/db_querytoken"
2013/02/05 12:50:20 [debug] 27380#0: *3 rds json body filter postponed header sending
2013/02/05 12:50:20 [debug] 27380#0: *3 rds json body filter discarding unexpected trailing buffers
2013/02/05 12:50:20 [debug] 27380#0: *3 http copy filter: 0 "/sync/db_querytoken?tbindex=ts_upload_token&backend=syncmysqlbackend&token=2F7D3A6B6467433Ef7Abg9JL"
2013/02/05 12:50:20 [debug] 27380#0: *3 http finalize request: 0, "/sync/db_querytoken?tbindex=ts_upload_token&backend=syncmysqlbackend&token=2F7D3A6B6467433Ef7Abg9JL" a:0, c:2
2013/02/05 12:50:20 [debug] 27380#0: *3 lua run post subrequest handler: rc:0
2013/02/05 12:50:20 [debug] 27380#0: *3 lua restoring write event handler
2013/02/05 12:50:20 [debug] 27380#0: *3 http log handler
2013/02/05 12:50:20 [debug] 27380#0: *3 http wake parent request: "/sync/upload_file?upload_token=2F7D3A6B6467433Ef7Abg9JL&start_pos=0"
2013/02/05 12:50:20 [debug] 27380#0: *3 http posted request: "/sync/upload_file?upload_token=2F7D3A6B6467433Ef7Abg9JL&start_pos=0"
2013/02/05 12:50:20 [debug] 27380#0: *3 lua run subrequests done, resuming lua thread
2013/02/05 12:50:20 [debug] 27380#0: *3 lua handle subrequest responses
2013/02/05 12:50:20 [debug] 27380#0: *3 lua run thread, top:0
2013/02/05 12:50:20 [debug] 27380#0: *3 lua reuse free buf chain, but reallocate memory because 24 >= 2, cl:0000000000D95ED0, p:0000000000D95588
2013/02/05 12:50:20 [debug] 27380#0: *3 lua print response
2013/02/05 12:50:20 [debug] 27380#0: *3 rds json header filter, "/sync/upload_file"
2013/02/05 12:50:20 [debug] 27380#0: *3 rds json: skipped because not enabled in the current location
2013/02/05 12:50:20 [debug] 27380#0: *3 lua capture header filter, uri "/sync/upload_file"
2013/02/05 12:50:20 [debug] 27380#0: *3 HTTP/1.1 200 OK
Server: nginx/1.2.3
Date: Tue, 05 Feb 2013 04:50:20 GMT
Content-Type: text/plain
Transfer-Encoding: chunked
Connection: close
2013/02/05 12:50:20 [debug] 27380#0: *3 write new buf t:1 f:0 0000000000D96198, pos 0000000000D96198, size: 150 file: 0, size: 0
2013/02/05 12:50:20 [debug] 27380#0: *3 http write filter: l:0 f:0 s:150
2013/02/05 12:50:20 [debug] 27380#0: *3 http output filter "/sync/upload_file?upload_token=2F7D3A6B6467433Ef7Abg9JL&start_pos=0"
2013/02/05 12:50:20 [debug] 27380#0: *3 http copy filter: "/sync/upload_file?upload_token=2F7D3A6B6467433Ef7Abg9JL&start_pos=0"
2013/02/05 12:50:20 [debug] 27380#0: *3 rds json body filter, "/sync/upload_file"
2013/02/05 12:50:20 [debug] 27380#0: *3 lua capture body filter, uri "/sync/upload_file"
2013/02/05 12:50:20 [debug] 27380#0: *3 image filter
2013/02/05 12:50:20 [debug] 27380#0: *3 http postpone filter "/sync/upload_file?upload_token=2F7D3A6B6467433Ef7Abg9JL&start_pos=0" 0000000000D95ED0
2013/02/05 12:50:20 [debug] 27380#0: *3 http chunk: 24
2013/02/05 12:50:20 [debug] 27380#0: *3 write old buf t:1 f:0 0000000000D96198, pos 0000000000D96198, size: 150 file: 0, size: 0
2013/02/05 12:50:20 [debug] 27380#0: *3 write new buf t:1 f:0 0000000000D96318, pos 0000000000D96318, size: 4 file: 0, size: 0
2013/02/05 12:50:20 [debug] 27380#0: *3 write new buf t:1 f:0 0000000000D96120, pos 0000000000D96120, size: 24 file: 0, size: 0
2013/02/05 12:50:20 [debug] 27380#0: *3 write new buf t:0 f:0 0000000000000000, pos 00000000004DAFBD, size: 2 file: 0, size: 0
2013/02/05 12:50:20 [debug] 27380#0: *3 http write filter: l:0 f:0 s:180
2013/02/05 12:50:20 [debug] 27380#0: *3 http copy filter: 0 "/sync/upload_file?upload_token=2F7D3A6B6467433Ef7Abg9JL&start_pos=0"
2013/02/05 12:50:20 [debug] 27380#0: *3 lua exit with code 200
2013/02/05 12:50:20 [debug] 27380#0: *3 lua resume returned 1
2013/02/05 12:50:20 [debug] 27380#0: *3 lua thread yielded
2013/02/05 12:50:20 [debug] 27380#0: *3 lua thread aborting request with status 200
2013/02/05 12:50:20 [debug] 27380#0: *3 lua request cleanup
2013/02/05 12:50:20 [debug] 27380#0: *3 lua sending last buf of the response body
2013/02/05 12:50:20 [debug] 27380#0: *3 http output filter "/sync/upload_file?upload_token=2F7D3A6B6467433Ef7Abg9JL&start_pos=0"
2013/02/05 12:50:20 [debug] 27380#0: *3 http copy filter: "/sync/upload_file?upload_token=2F7D3A6B6467433Ef7Abg9JL&start_pos=0"
2013/02/05 12:50:20 [debug] 27380#0: *3 rds json body filter, "/sync/upload_file"
2013/02/05 12:50:20 [debug] 27380#0: *3 lua capture body filter, uri "/sync/upload_file"
2013/02/05 12:50:20 [debug] 27380#0: *3 image filter
2013/02/05 12:50:20 [debug] 27380#0: *3 http postpone filter "/sync/upload_file?upload_token=2F7D3A6B6467433Ef7Abg9JL&start_pos=0" 00007FFF960FE310
2013/02/05 12:50:20 [debug] 27380#0: *3 http chunk: 0
2013/02/05 12:50:20 [debug] 27380#0: *3 write old buf t:1 f:0 0000000000D96198, pos 0000000000D96198, size: 150 file: 0, size: 0
2013/02/05 12:50:20 [debug] 27380#0: *3 write old buf t:1 f:0 0000000000D96318, pos 0000000000D96318, size: 4 file: 0, size: 0
2013/02/05 12:50:20 [debug] 27380#0: *3 write old buf t:1 f:0 0000000000D96120, pos 0000000000D96120, size: 24 file: 0, size: 0
2013/02/05 12:50:20 [debug] 27380#0: *3 write old buf t:0 f:0 0000000000000000, pos 00000000004DAFBD, size: 2 file: 0, size: 0
2013/02/05 12:50:20 [debug] 27380#0: *3 write new buf t:0 f:0 0000000000000000, pos 00000000004DAFBA, size: 5 file: 0, size: 0
2013/02/05 12:50:20 [debug] 27380#0: *3 http write filter: l:1 f:0 s:185
2013/02/05 12:50:20 [debug] 27380#0: *3 http write filter limit 0
2013/02/05 12:50:20 [debug] 27380#0: *3 writev: 185
2013/02/05 12:50:20 [debug] 27380#0: *3 http write filter 0000000000000000
2013/02/05 12:50:20 [debug] 27380#0: *3 http copy filter: 0 "/sync/upload_file?upload_token=2F7D3A6B6467433Ef7Abg9JL&start_pos=0"
2013/02/05 12:50:20 [debug] 27380#0: *3 lua run thread returned 200
2013/02/05 12:50:20 [debug] 27380#0: *3 http finalize request: 200, "/sync/upload_file?upload_token=2F7D3A6B6467433Ef7Abg9JL&start_pos=0" a:1, c:1
2013/02/05 12:50:20 [debug] 27380#0: *3 event timer add: 3: 5000:1360039825641
2013/02/05 12:50:20 [debug] 27380#0: *3 http lingering close handler
2013/02/05 12:50:20 [debug] 27380#0: *3 recv: fd:3 0 of 4096
2013/02/05 12:50:20 [debug] 27380#0: *3 lingering read: 0
2013/02/05 12:50:20 [debug] 27380#0: *3 http request count:1 blk:0
2013/02/05 12:50:20 [debug] 27380#0: *3 http close request
2013/02/05 12:50:20 [debug] 27380#0: *3 http log handler
2013/02/05 12:50:20 [debug] 27380#0: *3 posix_memalign: 0000000000DA3440:4096 @16
2013/02/05 12:50:20 [debug] 27380#0: *3 free: 0000000000DA2430
2013/02/05 12:50:20 [debug] 27380#0: *3 free: 0000000000D965B0
2013/02/05 12:50:20 [debug] 27380#0: *3 free: 0000000000DA0000
2013/02/05 12:50:20 [debug] 27380#0: *3 free: 0000000000D32B80, unused: 1
2013/02/05 12:50:20 [debug] 27380#0: *3 free: 0000000000D94590, unused: 6
2013/02/05 12:50:20 [debug] 27380#0: *3 free: 0000000000D955A0, unused: 288
2013/02/05 12:50:20 [debug] 27380#0: *3 free: 0000000000DA3440, unused: 3692
2013/02/05 12:50:20 [debug] 27380#0: *3 close http connection: 3
2013/02/05 12:50:20 [debug] 27380#0: *3 event timer del: 3: 1360039825641
2013/02/05 12:50:20 [debug] 27380#0: *3 reusable connection: 0
2013/02/05 12:50:20 [debug] 27380#0: *3 free: 0000000000D2FA50
2013/02/05 12:50:20 [debug] 27380#0: *3 free: 0000000000D2F560
2013/02/05 12:50:20 [debug] 27380#0: *3 free: 0000000000D27A40, unused: 0
2013/02/05 12:50:20 [debug] 27380#0: *3 free: 0000000000D27BA0, unused: 112
2013/02/05 12:50:20 [debug] 27380#0: drizzle: keepalive dummy handler
2013/02/05 12:50:20 [debug] 27380#0: timer delta: 1
2013/02/05 12:50:20 [debug] 27380#0: posted events 0000000000000000
2013/02/05 12:50:20 [debug] 27380#0: worker cycle
2013/02/05 12:50:20 [debug] 27380#0: epoll timer: -1
在 2013年2月5日星期二UTC+8下午12时25分06秒,lua初学者写道:
这个是upstream配置,不过有没有这个不影响复现
upstream syncmysqlbackend {
password=test user=test protocol=mysql;
drizzle_keepalive max=30 mode=single overflow=reject;
}
在 2013年2月5日星期二UTC+8上午11时53分45秒,lua初学者写道:
nginx 1.2.3 chunkin-nginx-module-0.23rc3 lua换成0.7.14rc2还是一样
完整实例可以稳定复现这个问题,现在感觉可能是 chunkin 的问题
每当客户端一断开,lua才开始执行。
如果吧 local tokeninfo,ret = utest.query_tokeninfo(token) 这个去掉,则没问题,立马返回200
客户端post的数据,我已经转换成16禁止
504f5354202f73796e632f75706c6f61645f66696c653f75706c6f61645f746f6b656e3d324637443341364236343637343333456637416267394a4c2673746172745f706f733d3020485454502f312e310d0a4163636570742d456e636f64696e673a2064656661756c742c677a69700d0a436f6e74656e742d456e636f64696e673a20677a69700d0a557365722d4167656e743a2044616c76696b2f312e362e3020284c696e75783b20553b20416e64726f696420342e312e313b20485443205435323874204275696c642f4a524f303348290d0a486f73743a203139322e3136382e302e31370d0a436f6e6e656374696f6e3a204b6565702d416c6976650d0a436f6e74656e742d547970653a206170706c69636174696f6e2f782d7777772d666f726d2d75726c656e636f6465640d0a5472616e736665722d456e636f64696e673a206368756e6b65640d0a0d0a610d0a1f8b08000000000000000d0a3133310d0a85904b6ec2301086f7917287c86b881ce7e520b108608410203509842e0db683ab8620933e68d5756fc0beea057a2ace51a7a245eda6ab198dffef1b79165ced65b5b51c1b9a4608ad8497d53d378d4c96bcebb8018428c4c8358d19d5837e363888dcf557b1bf2a708ae711c583a522f60dabd6a6a10dce3f868207942dc7090927634246e1d43be0f06abebc18901533f60b8f3c1f9e713189b2c522d84cdd598e92592a263de464aa77c653f9c4bb087aa6f10ce85dbda914e88078cb54251968019d69974c80cec5db02bb07063abad6b2bee53a7e3a7e9c8eafa7b7770dac15a735677f005af0bd0e16c36494664e1ca96b51932c89fa454ec810696ec744fbdb177b7a50d3a22d59439d5f4baabeb6367da5e44fbfd73fd0293ff26df8883d6443f0d29ce513cf53ce0ca80100000d0a300d0a0d0a
下面是抓包记录
10:51:35.600114 IP 192.168.1.100.10213 > 192.168.0.17.http: Flags [S], seq 3410286470, win 8192, options [mss 1460,nop,wscale 2,nop,nop,sackOK], length 0
0x0000: 4500 0034 5850 4000 8006 1fae c0a8 0164 E..4XP@........d
0x0010: c0a8 0011 27e5 0050 cb44 d786 0000 0000 ....'..P.D......
0x0020: 8002 2000 0150 0000 0204 05b4 0103 0302 .....P..........
0x0030: 0101 0402 ....
10:51:35.600202 IP 192.168.0.17.http > 192.168.1.100.10213: Flags [S.], seq 3251514090, ack 3410286471, win 14600, options [mss 1460,nop,nop,sackOK,nop,wscale 7], length 0
0x0000: 4500 0034 0000 4000 4006 b7fe c0a8 0011 E..4..@.@.......
0x0010: c0a8 0164 0050 27e5 c1ce 2aea cb44 d787 ...d.P'...*..D..
0x0020: 8012 3908 fb78 0000 0204 05b4 0101 0402 ..9..x..........
0x0030: 0103 0307 ....
10:51:35.601060 IP 192.168.1.100.10213 > 192.168.0.17.http: Flags [.], ack 1, win 16425, length 0
0x0000: 4500 0028 5851 4000 8006 1fb9 c0a8 0164 E..(XQ@........d
0x0010: c0a8 0011 27e5 0050 cb44 d787 c1ce 2aeb ....'..P.D....*.
0x0020: 5010 4029 352a 0000 0000 0000 0000 P.@)5*........
10:51:37.992639 IP 192.168.1.100.10213 > 192.168.0.17.http: Flags [P.], seq 1:670, ack 1, win 16425, length 669
0x0000: 4500 02c5 5855 4000 8006 1d18 c0a8 0164 E...XU@........d
0x0010: c0a8 0011 27e5 0050 cb44 d787 c1ce 2aeb ....'..P.D....*.
0x0020: 5018 4029 72a7 0000 504f 5354 202f 7379 P.@)r...POST./sy
0x0030: 6e63 2f75 706c 6f61 645f 6669 6c65 3f75 nc/upload_file?u
0x0040: 706c 6f61 645f 746f 6b65 6e3d 3246 3744 pload_token=2F7D
0x0050: 3341 3642 3634 3637 3433 3345 6637 4162 3A6B6467433Ef7Ab
0x0060: 6739 4a4c 2673 7461 7274 5f70 6f73 3d30 g9JL&start_pos=0
0x0070: 2048 5454 502f 312e 310d 0a41 6363 6570 .HTTP/1.1..Accep
0x0080: 742d 456e 636f 6469 6e67 3a20 6465 6661 t-Encoding:.defa
0x0090: 756c 742c 677a 6970 0d0a 436f 6e74 656e ult,gzip..Conten
0x00a0: 742d 456e 636f 6469 6e67 3a20 677a 6970 t-Encoding:.gzip
0x00b0: 0d0a 5573 6572 2d41 6765 6e74 3a20 4461 ..User-Agent:.Da
0x00c0: 6c76 696b 2f31 2e36 2e30 2028 4c69 6e75 lvik/
1.6.0.(Linu
0x00d0: 783b 2055 3b20 416e 6472 6f69 6420 342e x;.U;.Android.4.
0x00e0: 312e 313b 2048 5443 2054 3532 3874 2042 1.1;.HTC.T528t.B
0x00f0: 7569 6c64 2f4a 524f 3033 4829 0d0a 486f uild/JRO03H)..Ho
0x0100: 7374 3a20 3139 322e 3136 382e 302e 3137 st:.192.168.0.17
0x0110: 0d0a 436f 6e6e 6563 7469 6f6e 3a20 4b65 ..Connection:.Ke
0x0120: 6570 2d41 6c69 7665 0d0a 436f 6e74 656e ep-Alive..Conten
0x0130: 742d 5479 7065 3a20 6170 706c 6963 6174 t-Type:.applicat
0x0140: 696f 6e2f 782d 7777 772d 666f 726d 2d75 ion/x-www-form-u
0x0150: 726c 656e 636f 6465 640d 0a54 7261 6e73 rlencoded..Trans
0x0160: 6665 722d 456e 636f 6469 6e67 3a20 6368 fer-Encoding:.ch
0x0170: 756e 6b65 640d 0a0d 0a61 0d0a 1f8b 0800 unked....a......
0x0180: 0000 0000 0000 0d0a 3133 310d 0a85 904b ........131....K
0x0190: 6ec2 3010 86f7 9172 87c8 6b88 1ce7 e520 n.0....r..k.....
0x01a0: b108 6084 1020 3509 842e 0db6 83ab 8620 ..`...5.........
0x01b0: 933e 68d5 756f c0be ea05 7a2a ce51 a7a2 .>h.uo....z*.Q..
0x01c0: 45ed a6ab 198d ffef 1b79 165c ed65 b5b5 E........y.\.e..
0x01d0: 1c1b 9a46 08ad 8497 d53d 378d 4c96 bceb ...F.....=7.L...
0x01e0: b801 8428 c4c8 358d 19d5 837e 3638 88dc ...(..5....~68..
0x01f0: f557 b1bf 2a70 8ae7 11c5 83a5 22f6 0dab .W..*p......"...
0x0200: d6a6 a10d ce3f 8682 0794 2dc7 0909 2763 .....?....-...'c
0x0210: 4246 e1d4 3be0 f06a bebc 1890 1533 f60b BF..;..j.....3..
0x0220: 8f3c 1f9e 7131 89b2 c522 d84c dd59 8e92 .<..q1...".L.Y..
0x0230: 592a 263d e464 aa77 c653 f9c4 bb08 7aa6 Y*&=.d.w.S....z.
0x0240: f10c e85d bda9 14e8 8078 cb54 2519 6801 ...].....x.T%.h.
0x0250: 9d69 974c 80ce c5db 02bb 0706 3aba d6b2 .i.L........:...
0x0260: bee5 3a7e 3a7e 9c8e afa7 b777 0dac 15a7 ..:~:~.....w....
0x0270: 3567 7f00 5af0 bd0e 16c3 6494 664e 1ca9 5g..Z.....d.fN..
0x0280: 6b51 932c 89fa 454e c810 696e c744 fbdb kQ.,..EN..in.D..
0x0290: 177b 7a50 d3a2 2d59 439d 5f4b aabe b636 .{zP..-YC._K...6
0x02a0: 7da5 e44f bfd7 3fd0 293f f26d f888 3d64 }..O..?.)?.m..=d
0x02b0: 43f0 d29c e513 cf53 ce0c a801 0000 0d0a C......S........
0x02c0: 300d 0a0d 0a 0....
10:51:37.992702 IP 192.168.0.17.http > 192.168.1.100.10213: Flags [.], ack 670, win 125, length 0
0x0000: 4500 0028 cd08 4000 4006 eb01 c0a8 0011 E..(..@.@.......
0x0010: c0a8 0164 0050 27e5 c1ce 2aeb cb44 da24 ...d.P'...*..D.$
0x0020: 5010 007d 7239 0000 P..}r9..
nginx.conf
------------------------------------------------
worker_processes 1;
worker_rlimit_core 102400000;
working_directory /tmp;
error_log logs/error.log debug;
#error_log logs/error.log error;
events {
worker_connections 102400;
}
http {
include mime.types;
default_type application/octet-stream;
log_format main '$remote_addr $time_iso8601 $msec $request_time $request_length '
'$connection $connection_requests $uri "$request" '
'$status $body_bytes_sent $sent_http_X_IS_Error_Code "$sent_http_X_IS_Error_Msg" "$http_referer" '
'"$http_user_agent" "$http_x_forwarded_for" "$http_x_is_ip"';
access_log logs/access.log main;
log_subrequest on;
include *backend.conf;
keepalive_timeout 100;
keepalive_requests 10240;
client_header_timeout 100;
client_body_timeout 100;
lua_package_path '/usr/local/nginx/conf/?.lua;/usr/local/nginx/lua/lib/lua/5.1/?.lua;;';
lua_package_cpath '/usr/local/nginx/lua/lib/lua/5.1/?.so;;';
chunkin on;
error_page 411 = @my_411_error;
server {
listen 80;
lua_check_client_abort on;
location @my_411_error {
chunkin_resume;
}
location / {
access_log off;
log_subrequest off;
return 444;
}
location = /sync/upload_file
{
lua_check_client_abort off;
client_body_in_file_only on;
client_body_buffer_size 10M;
client_max_body_size 10M;
content_by_lua_file 'conf/sync_upload_file.lua';
}
location = /sync/db_querytoken
{
internal;
set_unescape_uri $backend $arg_backend;
set_unescape_uri $token $arg_token;
set_quote_sql_str $token $token;
drizzle_query "SELECT user_id FROM $arg_tbindex WHERE token=$token";
drizzle_pass $backend;
rds_json on;
}
}
}
------------------------------------------------
utest.lua
------------------------------------------------
local utest = {}
utest.query_tokeninfo = function(token)
local res = ngx.location.capture("/sync/db_querytoken",
{
args = {
backend = "syncmysqlbackend",
tbindex = "ts_upload_token",
token=token
}
})
if res.status ~= ngx.HTTP_OK then
return nil,-1
end
return 0,0
end
return utest
------------------------------------------------
sync_upload_file.lua
------------------------------------------------
ngx.req.read_body()
local args = ngx.req.get_uri_args()
local token = args.upload_token
local data = "">
utest = require "utest"
ngx.header.content_type = 'text/plain'
if nil == data then
local fname = ngx.req.get_body_file()
if nil == fname then
ngx.exit(406)
end
local fp,err = io.open(fname,"rb")
if nil == fp then
ngx.exit(500)
end
data = "" "*a"
fp:close()
end
local tokeninfo,ret = utest.query_tokeninfo(token)
ngx.print(token)
ngx.exit(200)
------------------------------------------------
在 2013年2月5日星期二UTC+8上午9时27分31秒,
lua初学者写道:
换成最新版还是不行,我一会弄一个完整实例上来。
在 2013年2月5日星期二UTC+8上午9时16分50秒,lua初学者写道:日志配置为:
log_format main '$remote_addr $time_iso8601 $msec $request_time $request_length '
'$connection $connection_requests $uri "$request" '
'$status $body_bytes_sent $sent_http_X_IS_Error_Code "$sent_http_X_IS_Error_Msg" "$http_referer" '
'"$http_user_agent" "$http_x_forwarded_for" "$http_x_is_ip"';
不好意思,日志中的url是我替换了的,本不想吧业务系统的信息发出,我吧/sync/db_querytoken ? 替换成 /test/db_querytoken这个了,在chrome上粘贴,? 不小心也一起覆盖了变成空格。
我今天换成新版lua试下。
在 2013年2月5日星期二UTC+8上午8时55分06秒,agentzh写道:Hello!
2013/2/4 lua初学者 <stone...@gmail.com>:
>
> ngx_lua 版本为 v0.7.4
>
> 打开nginx debug ,(lua_check_client_abort
> 为on;)比较日志,发现异常情况下,没有马上进入drizzle的location调用,而是等待客户端关闭连接,
> 如果 lua_check_client_abort 为off 则出现几百秒的情况,明天我再吧日志继续贴上来,不知道这个是ngx_lua的bug
>
多谢你的报告!
我有几个问题:
1. 为什么你提供的 nginx 配置片段中 ngx_drizzle 的 location 是
/test/db_querytoken,但你提供的 Lua 代码片段中调用 ngx.location.capture() 访问的却是
/sync/db_querytoken ?
2. 为什么你提供的两份 nginx 调试日志(即“正常日志”和“异常日志”)中所有的 URI 开头都有一个空格?
3. 我在你的“异常日志”片段中看到一个我无法解释的消息序列:
[debug] 21296#0: *171 http finalize request: -4, "..." a:1, c:5
[debug] 21296#0: *171 http request count:5 blk:0
[debug] 21296#0: *171 http finalize request: -4, "..." a:1, c:4
[debug] 21296#0: *171 http request count:4 blk:0
[debug] 21296#0: *171 http finalize request: -4, "..." a:1, c:3
[debug] 21296#0: *171 http request count:3 blk:0
简单的 ngx.location.capture 调用是不会产生这样的动作序列的。你能提供完整的示例么?包括主请求 /test/upload
对应的 location 配置和你运行的所有 Lua 代码(最好能先最小化一下)。
同时也有几个建议和请求:
1. 请提供你实际使用的 nginx 的配置细节,可以通过命令 /path/to/your/nginx/sbin/nginx -V 命令来输出。
2. 你能否将 ngx_lua 模块升级到最新的 0.7.14 版?0.7.4 之后有不少 bug 修复,其中一些和子请求有关。
3. 请提供一个最小化的能复现问题的完整示例,以及复现问题所需要的具体操作步骤,如果我能在我本地复现此问题,则问题将容易追踪得多 :)
4. 请提供你使用的操作系统的详细信息,一般通过 uname -a 命令可以得到。
Thanks!
-agentzh