drizzle-nginx-module 超时60s问题，求解？

stonehuzhan · 2013-02-04T19:37:38+00:00

I am delighted to announce the new development version of ngx_openresty, 1.2.6.3: http://openresty.org/#Download Special thanks go to all our contribut...

drizzle-nginx-module 超时60s问题，求解？

stonehuzhan

nginx 1.2.3 ngx_drizzle v0.1.4

mysql 表记录很少只有几十条，drizzle子请求经常出现时间很长日志，出现概率大概10%，正常情况下，这个子请求访问时间小于 0.01s

加上time_out配置也不起作用， mysql加上慢查询分析，这个sql语句没有慢查询，很奇怪，不知道哪里出了问题，求解

配置如下

location = /test/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;

drizzle_connect_timeout 500ms; # default 60s 后面几行为后来添加，问题一样

drizzle_send_query_timeout 1s; # default 60s

drizzle_recv_cols_timeout 1s; # default 60s

drizzle_recv_rows_timeout 1s; # default 60s

}

upstream mysqlbackend {

drizzle_server 127.0.0.1:3306 dbname=db_user

password=111111 user=root protocol=mysql;

drizzle_keepalive max=1000 mode=single overflow=reject;

}

lua代码

................

local res = ngx.location.capture("/sync/db_querytoken",

{

args = {

backend = "mysqlbackend",

tbindex = "t_token",

token=token

}

})

if res.status ~= ngx.HTTP_OK then

return nil,-1

end

.................................

t_token 表结构

mysql> desc ts_upload_token;

+-----------+---------------+------+-----+---------+-------+

+-----------+---------------+------+-----+---------+-------+

+-----------+---------------+------+-----+---------+-------+

nginx日志，红色的是时间

113.210.130.166 2013-02-04T11:09:00+00:00 1359976140.675 59.846 0 1918 1 /test/db_querytoken "POST /test/upload?token=B99376F2DC344DF90D89K7Lf HTTP/1.1" 200 0 - "-" "-" "Dalvik/1.6.0 (Linux; U; Android 4.1.1; HTC T528t Build/JRO03H)" "-" "-"

正常日志为

222.66.115.138 2013-02-04T08:36:48+00:00 1359967008.133 0.003 0 108 1 /test/db_querytoken "POST /test/upload upload_token=5B0467B685AA41A0QS94R7P0 HTTP/1.1" 200 0 - "-" "-" "Dalvik/1.6.0 (Linux; U; Android 4.1.1; HTC T528t Build/JRO03H)" "-" "-"

stonehuzhan

再贴一些日志出来，

113.210.130.166 2013-02-04T06:51:09+00:00 1359960669.559 55.733 0 308 1 /test/db_querytoken "POST /test/upload upload_token=A56CA626424F4544SX7VY9Wf&start_pos=0 HTTP/1.1" 200 0 - "-" "-" "Dalvik/1.6.0 (Linux; U; Android 4.1.1; HTC T528t Build/JRO03H)" "-" "-"

113.210.130.166 2013-02-04T11:10:14+00:00 1359976214.047 59.680 0 1948 1 /test/db_querytoken "POST /test/upload?upload_token=0A7AA74CA7FB4BC2EL9NL9b0 HTTP/1.1" 200 0 - "-" "-" "Dalvik/1.6.0 (Linux; U; Android 4.1.1; HTC T528t Build/JRO03H)" "-" "-"222.66.115.138 2013-02-04T11:11:33+00:00 1359976293.717 55.217 0 1981 1 /sync/db_queryuploadtokeninfo "POST /sync/upload_file?upload_token=5308DAA3C00D47285K7M68dL&start_pos=0 HTTP/1.1" 200 0 - "-" "-" "Dalvik/1.6.0 (Linux; U; Android 4.1.1; HTC T528t Build/JRO03H)" "-" "-"

113.210.130.166 2013-02-04T11:15:42+00:00 1359976542.987 59.727 0 2058 1 /test/db_querytoken "POST /test/upload?upload_token=F2F129C655814B80KC7E67TC HTTP/1.1" 200 0 - "-" "-" "Dalvik/1.6.0 (Linux; U; Android 4.1.1; HTC 603e Build/JRO03H)" "-" "-"

在 2013年2月4日星期一UTC+8下午7时37分38秒，lua初学者写道：

nginx 1.2.3 ngx_drizzle v0.1.4

mysql 表记录很少只有几十条，drizzle子请求经常出现时间很长日志，出现概率大概10%，正常情况下，这个子请求访问时间小于 0.01s
加上time_out配置也不起作用， mysql加上慢查询分析，这个sql语句没有慢查询，很奇怪，不知道哪里出了问题，求解

配置如下

location = /test/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;
drizzle_connect_timeout 500ms; # default 60s 后面几行为后来添加，问题一样
drizzle_send_query_timeout 1s; # default 60s
drizzle_recv_cols_timeout 1s; # default 60s
drizzle_recv_rows_timeout 1s; # default 60s
}

upstream mysqlbackend {
drizzle_server 127.0.0.1:3306 dbname=db_user
password=111111 user=root protocol=mysql;
drizzle_keepalive max=1000 mode=single overflow=reject;
}

lua代码
................
local res = ngx.location.capture("/sync/db_querytoken",
{
args = {
backend = "mysqlbackend",
tbindex = "t_token",
token=token
}
})
if res.status ~= ngx.HTTP_OK then
return nil,-1
end
.................................

t_token 表结构

mysql> desc ts_upload_token;
+-----------+---------------+------+-----+---------+-------+
| Field | Type | Null | Key | Default | Extra |
+-----------+---------------+------+-----+---------+-------+
| token | binary(24) | NO | PRI | NULL | |
| user_id | bigint(20) | NO | | NULL | |
| time | bigint(20) | NO | MUL | NULL | |
+-----------+---------------+------+-----+---------+-------+

nginx日志，红色的是时间
113.210.130.166 2013-02-04T11:09:00+00:00 1359976140.675 59.846 0 1918 1 /test/db_querytoken "POST /test/upload?token=B99376F2DC344DF90D89K7Lf HTTP/1.1" 200 0 - "-" "-" "Dalvik/1.6.0 (Linux; U; Android 4.1.1; HTC T528t Build/JRO03H)" "-" "-"

正常日志为
113.210.130.166
2013-02-04T08:36:48+00:00 1359967008.133 0.003 0 108 1 /test/db_querytoken "POST /test/upload upload_token=5B0467B685AA41A0QS94R7P0 HTTP/1.1" 200 0 - "-" "-" "Dalvik/1.6.0 (Linux; U; Android 4.1.1; HTC T528t Build/JRO03H)" "-" "-"

stonehuzhan

刚才出现了一个更离奇的 600多秒

113.210.130.166 2013-02-04T17:53:47+08:00 1359971627.134 656.542 0 25655 1 /test/db_querytoken "POST /test/upload?token=38F0D2F520824F01Q68A07HC HTTP/1.1" 200 0 - "-" "-" "Dalvik/1.6.0 (Linux; U; Android 4.1.2; GT-N7100 Build/JZO54K)" "-" "-"

在 2013年2月4日星期一UTC+8下午7时41分25秒，lua初学者写道：

再贴一些日志出来，

113.210.130.166 2013-02-04T06:51:09+00:00 1359960669.559 55.733 0 308 1 /test/db_querytoken "POST /test/upload upload_token=A56CA626424F4544SX7VY9Wf&start_pos=0 HTTP/1.1" 200 0 - "-" "-" "Dalvik/1.6.0 (Linux; U; Android 4.1.1; HTC T528t Build/JRO03H)" "-" "-"

113.210.130.166 2013-02-04T11:10:14+00:00 1359976214.047 59.680 0 1948 1 /test/db_querytoken "POST /test/upload?upload_token=0A7AA74CA7FB4BC2EL9NL9b0 HTTP/1.1" 200 0 - "-" "-" "Dalvik/1.6.0 (Linux; U; Android 4.1.1; HTC T528t Build/JRO03H)" "-" "-"222.66.115.138 2013-02-04T11:11:33+00:00 1359976293.717 55.217 0 1981 1 /sync/db_queryuploadtokeninfo "POST /sync/upload_file?upload_token=5308DAA3C00D47285K7M68dL&start_pos=0 HTTP/1.1" 200 0 - "-" "-" "Dalvik/1.6.0 (Linux; U; Android 4.1.1; HTC T528t Build/JRO03H)" "-" "-"
113.210.130.166 2013-02-04T11:15:42+00:00 1359976542.987 59.727 0 2058 1 /test/db_querytoken "POST /test/upload?upload_token=F2F129C655814B80KC7E67TC HTTP/1.1" 200 0 - "-" "-" "Dalvik/1.6.0 (Linux; U; Android 4.1.1; HTC 603e Build/JRO03H)" "-" "-"

在 2013年2月4日星期一UTC+8下午7时37分38秒，lua初学者写道：
nginx 1.2.3 ngx_drizzle v0.1.4

mysql 表记录很少只有几十条，drizzle子请求经常出现时间很长日志，出现概率大概10%，正常情况下，这个子请求访问时间小于 0.01s
加上time_out配置也不起作用， mysql加上慢查询分析，这个sql语句没有慢查询，很奇怪，不知道哪里出了问题，求解

配置如下

location = /test/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;
drizzle_connect_timeout 500ms; # default 60s 后面几行为后来添加，问题一样
drizzle_send_query_timeout 1s; # default 60s
drizzle_recv_cols_timeout 1s; # default 60s
drizzle_recv_rows_timeout 1s; # default 60s
}

upstream mysqlbackend {
drizzle_server 127.0.0.1:3306 dbname=db_user
password=111111 user=root protocol=mysql;
drizzle_keepalive max=1000 mode=single overflow=reject;
}

lua代码
................
local res = ngx.location.capture("/sync/db_querytoken",
{
args = {
backend = "mysqlbackend",
tbindex = "t_token",
token=token
}
})
if res.status ~= ngx.HTTP_OK then
return nil,-1
end
.................................

t_token 表结构

mysql> desc ts_upload_token;
+-----------+---------------+------+-----+---------+-------+
| Field | Type | Null | Key | Default | Extra |
+-----------+---------------+------+-----+---------+-------+
| token | binary(24) | NO | PRI | NULL | |
| user_id | bigint(20) | NO | | NULL | |
| time | bigint(20) | NO | MUL | NULL | |
+-----------+---------------+------+-----+---------+-------+

nginx日志，红色的是时间
113.210.130.166 2013-02-04T11:09:00+00:00 1359976140.675 59.846 0 1918 1 /test/db_querytoken "POST /test/upload?token=B99376F2DC344DF90D89K7Lf HTTP/1.1" 200 0 - "-" "-" "Dalvik/1.6.0 (Linux; U; Android 4.1.1; HTC T528t Build/JRO03H)" "-" "-"

正常日志为
113.210.130.166
2013-02-04T08:36:48+00:00 1359967008.133 0.003 0 108 1 /test/db_querytoken "POST /test/upload upload_token=5B0467B685AA41A0QS94R7P0 HTTP/1.1" 200 0 - "-" "-" "Dalvik/1.6.0 (Linux; U; Android 4.1.1; HTC T528t Build/JRO03H)" "-" "-"

stonehuzhan

ngx_lua 版本为 v0.7.4

打开nginx debug ,（lua_check_client_abort 为on;）比较日志，发现异常情况下，没有马上进入drizzle的location调用，而是等待客户端关闭连接，

如果 lua_check_client_abort 为off 则出现几百秒的情况，明天我再吧日志继续贴上来，不知道这个是ngx_lua的bug

异常日志

......................................

2013/02/04 20:59:37 [debug] 21296#0: *171 post access phase: 10

2013/02/04 20:59:37 [debug] 21296#0: *171 lua content handler, uri " /test/upload"

2013/02/04 20:59:37 [debug] 21296#0: *171 lua reset ctx

2013/02/04 20:59:37 [debug] 21296#0: *171 lua creating new thread

2013/02/04 20:59:37 [debug] 21296#0: *171 http cleanup add: 0000000001F02E50

2013/02/04 20:59:37 [debug] 21296#0: *171 lua run thread, top:0

2013/02/04 20:59:37 [debug] 21296#0: *171 lua start to read buffered request body

2013/02/04 20:59:37 [debug] 21296#0: *171 lua req body post read

2013/02/04 20:59:37 [debug] 21296#0: *171 lua has read buffered request body in a single run

2013/02/04 20:59:37 [debug] 21296#0: *171 lua request header: "Accept-Encoding: default,gzip"

2013/02/04 20:59:37 [debug] 21296#0: *171 lua request header: "Content-Encoding: gzip"

2013/02/04 20:59:37 [debug] 21296#0: *171 lua request header: "Host: 192.168.0.17"

2013/02/04 20:59:37 [debug] 21296#0: *171 lua request header: "Connection: Keep-Alive"

2013/02/04 20:59:37 [debug] 21296#0: *171 lua request header: "Content-Type: application/x-www-form-urlencoded"

2013/02/04 20:59:37 [debug] 21296#0: *171 lua request header: "Content-Length: 290"

2013/02/04 20:59:37 [debug] 21296#0: *171 posix_memalign: 0000000001F47FE0:4096 @16

2013/02/04 20:59:37 [debug] 21296#0: *171 http subrequest " /test/db_querytoken?tbindex=ts_upload_token&backend=mysqlbackend&token=68E5D6B2149B46EET68WX7af"

2013/02/04 20:59:37 [debug] 21296#0: *171 lua resume returned 1

2013/02/04 20:59:37 [debug] 21296#0: *171 lua thread yielded

2013/02/04 20:59:37 [debug] 21296#0: *171 http finalize request: -4, " /test/upload?upload_token=68E5D6B2149B46EET68WX7af&start_pos=0" a:1, c:5

2013/02/04 20:59:37 [debug] 21296#0: *171 http request count:5 blk:0

2013/02/04 20:59:37 [debug] 21296#0: *171 http finalize request: -4, " /test/upload?upload_token=68E5D6B2149B46EET68WX7af&start_pos=0" a:1, c:4

2013/02/04 20:59:37 [debug] 21296#0: *171 http request count:4 blk:0

2013/02/04 20:59:37 [debug] 21296#0: *171 http finalize request: -4, " /test/upload?upload_token=68E5D6B2149B46EET68WX7af&start_pos=0" a:1, c:3

2013/02/04 20:59:37 [debug] 21296#0: *171 http request count:3 blk:0

2013/02/04 20:59:37 [debug] 21296#0: timer delta: 1

2013/02/04 20:59:37 [debug] 21296#0: posted events 0000000000000000

2013/02/04 20:59:37 [debug] 21296#0: worker cycle

2013/02/04 20:59:37 [debug] 21296#0: epoll timer: -1

2013/02/04 21:00:37 [debug] 21296#0: epoll: fd:3 ev:0001 d:00007F0B1D80F310

2013/02/04 21:00:37 [debug] 21296#0: *171 http run request: " /test/upload?upload_token=68E5D6B2149B46EET68WX7af&start_pos=0"

2013/02/04 21:00:37 [debug] 21296#0: *171 http lua check client, write event:0, " /test/upload"

2013/02/04 21:00:37 [debug] 21296#0: *171 http lua recv(): 0

2013/02/04 21:00:37 [info] 21296#0: *171 client prematurely closed connection, client: 192.168.1.120, server: *.intsig.net, request: "POST /test/upload?upload_token=68E5D6B2149B46EET68WX7af&start_pos=0 HTTP/1.1", host: "192.168.0.17"

2013/02/04 21:00:37 [debug] 21296#0: *171 lua request cleanup

......................................

正常日志

..........................................

2013/02/04 21:00:37 [debug] 21296#0: *175 access phase: 9

2013/02/04 21:00:37 [debug] 21296#0: *175 post access phase: 10

2013/02/04 21:00:37 [debug] 21296#0: *175 lua content handler, uri " /test/upload"

2013/02/04 21:00:37 [debug] 21296#0: *175 lua reset ctx

2013/02/04 21:00:37 [debug] 21296#0: *175 lua creating new thread

2013/02/04 21:00:37 [debug] 21296#0: *175 http cleanup add: 0000000001C5F3A0

2013/02/04 21:00:37 [debug] 21296#0: *175 lua run thread, top:0

2013/02/04 21:00:37 [debug] 21296#0: *175 lua start to read buffered request body

2013/02/04 21:00:37 [debug] 21296#0: *175 lua req body post read

2013/02/04 21:00:37 [debug] 21296#0: *175 lua has read buffered request body in a single run

2013/02/04 21:00:37 [debug] 21296#0: *175 lua request header: "Accept-Encoding: default,gzip"

2013/02/04 21:00:37 [debug] 21296#0: *175 lua request header: "Content-Encoding: gzip"

2013/02/04 21:00:37 [debug] 21296#0: *175 lua request header: "User-Agent: Dalvik/1.6.0 (Linux; U; Android 4.1.1; HTC T528t Build/JRO03H)"

2013/02/04 21:00:37 [debug] 21296#0: *175 lua request header: "Host: 192.168.0.17"

2013/02/04 21:00:37 [debug] 21296#0: *175 lua request header: "Connection: Keep-Alive"

2013/02/04 21:00:37 [debug] 21296#0: *175 lua request header: "Content-Type: application/x-www-form-urlencoded"

2013/02/04 21:00:37 [debug] 21296#0: *175 lua request header: "Content-Length: 290"

2013/02/04 21:00:37 [debug] 21296#0: *175 posix_memalign: 0000000002E2D970:4096 @16

2013/02/04 21:00:37 [debug] 21296#0: *175 http subrequest " /test/db_querytoken?tbindex=ts_upload_token&backend=mysqlbackend&token=452D3A0B78454F42CX7Vg9JL"

2013/02/04 21:00:37 [debug] 21296#0: *175 lua resume returned 1

2013/02/04 21:00:37 [debug] 21296#0: *175 lua thread yielded

2013/02/04 21:00:37 [debug] 21296#0: *175 http finalize request: -4, " /test/upload?upload_token=452D3A0B78454F42CX7Vg9JL&start_pos=0" a:1, c:3

2013/02/04 21:00:37 [debug] 21296#0: *175 http request count:3 blk:0

2013/02/04 21:00:37 [debug] 21296#0: *175 http posted request: " /test/db_querytoken?tbindex=ts_upload_token&backend=mysqlbackend&token=452D3A0B78454F42CX7Vg9JL"

2013/02/04 21:00:37 [debug] 21296#0: *175 rewrite phase: 0

2013/02/04 21:00:37 [debug] 21296#0: *175 test location: "/"

2013/02/04 21:00:37 [debug] 21296#0: *175 test location: "queue/db_addmsg"

2013/02/04 21:00:37 [debug] 21296#0: *175 using configuration "= /test/db_querytoken"

..........................................

在 2013年2月4日星期一UTC+8下午8时27分47秒，lua初学者写道：

刚才出现了一个更离奇的 600多秒

113.210.130.166 2013-02-04T17:53:47+08:00 1359971627.134 656.542 0 25655 1 /test/db_querytoken "POST /test/upload?token=38F0D2F520824F01Q68A07HC HTTP/1.1" 200 0 - "-" "-" "Dalvik/1.6.0 (Linux; U; Android 4.1.2; GT-N7100 Build/JZO54K)" "-" "-"

在 2013年2月4日星期一UTC+8下午7时41分25秒，lua初学者写道：
再贴一些日志出来，

113.210.130.166 2013-02-04T06:51:09+00:00 1359960669.559 55.733 0 308 1 /test/db_querytoken "POST /test/upload upload_token=A56CA626424F4544SX7VY9Wf&start_pos=0 HTTP/1.1" 200 0 - "-" "-" "Dalvik/1.6.0 (Linux; U; Android 4.1.1; HTC T528t Build/JRO03H)" "-" "-"

113.210.130.166 2013-02-04T11:10:14+00:00 1359976214.047 59.680 0 1948 1 /test/db_querytoken "POST /test/upload?upload_token=0A7AA74CA7FB4BC2EL9NL9b0 HTTP/1.1" 200 0 - "-" "-" "Dalvik/1.6.0 (Linux; U; Android 4.1.1; HTC T528t Build/JRO03H)" "-" "-"222.66.115.138 2013-02-04T11:11:33+00:00 1359976293.717 55.217 0 1981 1 /sync/db_queryuploadtokeninfo "POST /sync/upload_file?upload_token=5308DAA3C00D47285K7M68dL&start_pos=0 HTTP/1.1" 200 0 - "-" "-" "Dalvik/1.6.0 (Linux; U; Android 4.1.1; HTC T528t Build/JRO03H)" "-" "-"
113.210.130.166 2013-02-04T11:15:42+00:00 1359976542.987 59.727 0 2058 1 /test/db_querytoken "POST /test/upload?upload_token=F2F129C655814B80KC7E67TC HTTP/1.1" 200 0 - "-" "-" "Dalvik/1.6.0 (Linux; U; Android 4.1.1; HTC 603e Build/JRO03H)" "-" "-"

在 2013年2月4日星期一UTC+8下午7时37分38秒，lua初学者写道：
nginx 1.2.3 ngx_drizzle v0.1.4

mysql 表记录很少只有几十条，drizzle子请求经常出现时间很长日志，出现概率大概10%，正常情况下，这个子请求访问时间小于 0.01s
加上time_out配置也不起作用， mysql加上慢查询分析，这个sql语句没有慢查询，很奇怪，不知道哪里出了问题，求解

配置如下

location = /test/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;
drizzle_connect_timeout 500ms; # default 60s 后面几行为后来添加，问题一样
drizzle_send_query_timeout 1s; # default 60s
drizzle_recv_cols_timeout 1s; # default 60s
drizzle_recv_rows_timeout 1s; # default 60s
}

upstream mysqlbackend {
drizzle_server 127.0.0.1:3306 dbname=db_user
password=111111 user=root protocol=mysql;
drizzle_keepalive max=1000 mode=single overflow=reject;
}

lua代码
................
local res = ngx.location.capture("/sync/db_querytoken",
{
args = {
backend = "mysqlbackend",
tbindex = "t_token",
token=token
}
})
if res.status ~= ngx.HTTP_OK then
return nil,-1
end
.................................

t_token 表结构

mysql> desc ts_upload_token;
+-----------+---------------+------+-----+---------+-------+
| Field | Type | Null | Key | Default | Extra |
+-----------+---------------+------+-----+---------+-------+
| token | binary(24) | NO | PRI | NULL | |
| user_id | bigint(20) | NO | | NULL | |
| time | bigint(20) | NO | MUL | NULL | |
+-----------+---------------+------+-----+---------+-------+

nginx日志，红色的是时间
113.210.130.166 2013-02-04T11:09:00+00:00 1359976140.675 59.846 0 1918 1 /test/db_querytoken "POST /test/upload?token=B99376F2DC344DF90D89K7Lf HTTP/1.1" 200 0 - "-" "-" "Dalvik/1.6.0 (Linux; U; Android 4.1.1; HTC T528t Build/JRO03H)" "-" "-"

正常日志为
113.210.130.166
2013-02-04T08:36:48+00:00 1359967008.133 0.003 0 108 1 /test/db_querytoken "POST /test/upload upload_token=5B0467B685AA41A0QS94R7P0 HTTP/1.1" 200 0 - "-" "-" "Dalvik/1.6.0 (Linux; U; Android 4.1.1; HTC T528t Build/JRO03H)" "-" "-"

agentzh

Hello!

2013/2/4 lua初学者:
>
> nginx日志 ，红色的是时间
> 113.210.130.166 2013-02-04T11:09:00+00:00 1359976140.675 59.846 0 1918 1
> /test/db_querytoken "POST /test/upload?token=B99376F2DC344DF90D89K7Lf
> HTTP/1.1" 200 0 - "-" "-" "Dalvik/1.6.0 (Linux; U; Android 4.1.1; HTC T528t
> Build/JRO03H)" "-" "-"
>
>
> 正常日志为
> 222.66.115.138 2013-02-04T08:36:48+00:00 1359967008.133 0.003 0 108 1
> /test/db_querytoken "POST /test/upload upload_token=5B0467B685AA41A0QS94R7P0
> HTTP/1.1" 200 0 - "-" "-" "Dalvik/1.6.0 (Linux; U; Android 4.1.1; HTC T528t
> Build/JRO03H)" "-" "-"
>

你能提供你的 log_format 指令的配置模版么？我不确定你这里记录的时间究竟对应哪一个变量。

看起来你记录的是主请求的 $request_time 变量。这个时间值会包括读写下游连接的时间。当慢速客户端（比如使用较慢的 wifi
网络的客户端）访问你的服务器时，那些时间都会算在你的 $request_time 里面而无论你的服务器本身的处理有多快。

建议在你配置了 ngx_drizzle 模块的 location 里面配置 log_format 指令并使用
$upstream_response_time 这个变量[1]，同时配置 log_subrequest 指令 [2]。你在访问日志里面记录的
ngx_drizzle 子请求（即对应 location = /test/db_querytoken）中的
$upstream_response_time 的值才是比较准确的上游访问的时间。

Best regards,
-agentzh

[1] $upstream_response_time
变量：http://wiki.nginx.org/HttpUpstreamModule#.24upstream_response_time
[2] log_subrequest 指令： http://wiki.nginx.org/HttpCoreModule#log_subrequest

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

stonehuzhan

日志配置为：

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

stonehuzhan

换成最新版还是不行，我一会弄一个完整实例上来。
在 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

stonehuzhan

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

stonehuzhan

这个是upstream配置，不过有没有这个不影响复现

upstream syncmysqlbackend {

drizzle_server 127.0.0.1:3306 dbname=db_test

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

stonehuzhan

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 {
drizzle_server 127.0.0.1:3306 dbname=db_test
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

agentzh

Hello!

2013/2/4 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禁止
>

这确实是 ngx_chunkin 模块的问题，它并不能和 nginx 子请求一起工作。我已经在我本地修复了这个问题，过一会儿等测试全部跑完之后，我就提交一下。

多谢！

Best regards,
-agentzh

agentzh

Hello!

2013/2/4 agentzh <age...@gmail.com>:
> 2013/2/4 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禁止
>>
>
> 这确实是 ngx_chunkin 模块的问题，它并不能和 nginx 子请求一起工作。我已经在我本地修复了这个问题，过一会儿等测试全部跑完之后，我就提交一下。
>

我刚刚提交了一个补丁修正了此问题：

    https://github.com/agentzh/chunkin-nginx-module/commit/178f049

请尝试最新的 ngx_chunkin v0.23rc4:

    https://github.com/agentzh/chunkin-nginx-module/tags/

值得一提的是，从 Nginx 1.3.9 开始，Nginx 核心已经对 chunked 编码的请求体提供了原生支持。所以对于 1.3.9
及其以后的版本，不再需要使用 ngx_chunkin 模块了。

顺便提一下，ngx_lua 最新的版本是 v0.7.14 而不是 v0.7.14rc2. GitHub tags 页面上的自动排序并不是按照发布时间的顺序 ;)

Thanks!
-agentzh

stonehuzhan

多谢，刚才下载了，已经可以了，不知道为什么 chunked 模块没有合并的nginx的稳定版本，我们线上环境不太敢用开发版本

在 2013年2月5日星期二UTC+8下午1时28分23秒，agentzh写道：

Hello!

2013/2/4 agentzh <age...@gmail.com>:
> 2013/2/4 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禁止
>>
>
> 这确实是 ngx_chunkin 模块的问题，它并不能和 nginx 子请求一起工作。我已经在我本地修复了这个问题，过一会儿等测试全部跑完之后，我就提交一下。
>

我刚刚提交了一个补丁修正了此问题：

https://github.com/agentzh/chunkin-nginx-module/commit/178f049

请尝试最新的 ngx_chunkin v0.23rc4:

https://github.com/agentzh/chunkin-nginx-module/tags/

值得一提的是，从 Nginx 1.3.9 开始，Nginx 核心已经对 chunked 编码的请求体提供了原生支持。所以对于 1.3.9
及其以后的版本，不再需要使用 ngx_chunkin 模块了。

顺便提一下，ngx_lua 最新的版本是 v0.7.14 而不是 v0.7.14rc2. GitHub tags 页面上的自动排序并不是按照发布时间的顺序 ;)

Thanks!
-agentzh

agentzh

Hello!

2013/2/4 lua初学者:
> 多谢，刚才下载了，已经可以了，

好极。多谢反馈 :)

> 不知道为什么 chunked 模块没有合并的nginx的稳定版本，我们线上环境不太敢用开发版本
>

因为这个功能是前不久刚添加进 Nginx 1.3.x 开发版分支的。你可以等 Nginx 1.4.x 稳定版分支；在此之前就先凑和着使
ngx_chunkin 吧，呵呵。

Best regards,
-agentzh