Hello!
On Tue, Aug 21, 2012 at 1:20 AM, 朱德江 wrote:
> 在使用resty-redis模块时出现：failed to set keepalive: unread data in buffer 的报错
>
> 最小复现的例子如下：
>
> local redis = require "resty.redis"
> local red = redis:new()
> red:set_timeout(1000) -- 1 sec
> local ok, err = red:connect("127.0.0.1", 6379)
> if not ok then ngx.say("failed to connect: ", err) return end
> red:init_pipeline()
> local results, err = red:commit_pipeline()
> local res, err = red:get("dog")
> red:init_pipeline()
> local results, err = red:commit_pipeline()
> local ok, err = red:set_keepalive(0, 100)
> if not ok then ngx.say("failed to set keepalive: ", err) return end
>
> 用的是：ngx_openresty/1.0.15.10，不知道是不是bug，还是说这么用是非法的，多谢春哥 :）
>
多谢你提供的用例！这确实暴露了 ngx_lua 模块的 TCP cosocket API 中的一个 bug. tcpsock:send()
方法中并没有总是对 ngx_chain_writer_ctx_t 中的 out 和 last
字段进行重新初始化，导致上一次调用遗留的垃圾数据可能被发送出去。
通过下面的 systemtap 脚本运行上面的示例，可以证明这一点：
global active
probe process("nginx").mark("http-lua-socket-tcp-send-start") {
active = 1
printf("sock:send(\"%s\") len:%d\n",
text_str(user_string_n($arg3, $arg4)), $arg4)
}
probe process("nginx").mark("http-lua-socket-tcp-receive-done") {
printf("sock:receive(\"%s\")\n", text_str(user_string_n($arg3, $arg4)))
}
probe process("nginx").function("ngx_http_lua_socket_tcp_setkeepalive") {
delete active
}
probe process("nginx").mark("http-lua-socket-tcp-setkeepalive-buf-unread") {
printf("setkeepalive unread: [%s]\n",
text_str(user_string_n($arg3, $arg4)))
}
probe syscall.recvfrom.return {
if (active && pid() == target()) {
printf("recvfrom: got \"%s\"\n",
text_str(user_string_n($ubuf,$size)))
}
}
probe syscall.writev {
if (active && pid() == target()) {
printf("writev(%s)\n", ngx_iovec_dump($vec, $vlen))
}
}
stap-nginx 工具的输出是
sock:send("") len:0
sock:send("*2\r\n$3\r\nget\r\n$3\r\ndog\r\n") len:22
writev("*2\r\n$3\r\nget\r\n$3\r\ndog\r\n"(0xffef70)
"*2\r\n$3\r\nget\r\n$3\r\ndog\r\n"(0xffef70))
recvfrom: got "$-1\r\n$-1\r\n"
sock:receive("$-1")
sock:send("") len:0
setkeepalive unread: [$-1\r\n]
可以看到，第一行 sock:send("") 是 Lua 代码中的第一次 red:commit_pipeline()
调用触发的，然后第二行输出则对应 Lua 代码中的 red:get("dog") 调用所产生的 redis 请求，我们看到长度为 22
个字节。但紧接着，底层的 writev 系统调用却写了两遍！于是这导致随后的 recvfrom 系统调用从 redis
远方服务器一下子接收到两条连在一起的 redis 响应，即 "$-1\r\n$-1\r\n"，而 red:get("dog") 这句 Lua
调用读取了第一条 redis 响应，于是当前 cosocket 的接收缓冲区中还有一条 redis 响应，即 "$-1\r\n"，于是在调用
setkeepalive() 方法时便报错了。
我们可以进一步追踪为什么 writev 会重复两遍 redis 请求数据。在我的 Linux 系统上，cosocket 写数据的调用序列是：
sock:send() --> ngx_output_chain --> ngx_chain_writer -->
ngx_linux_sendfile_chain --> writev
中间的三个 C 函数都位于 nginx 核心中。
于是可以添加下面的 systemtap 脚本片段，对中间的三个 C 调用进行追踪：
probe process("nginx").function("ngx_output_chain") {
printf("ngx_output_chain: %s\n", ngx_chain_dump($in))
}
probe process("nginx").function("ngx_chain_writer") {
printf("ngx_chain_writer: %s\n", ngx_chain_dump($in))
}
probe process("nginx").function("ngx_linux_sendfile_chain") {
printf("ngx_linux_sendfile_chain: %s\n", ngx_chain_dump($in))
}
运行后新产生的输出是：
ngx_output_chain: [*2\r\n$3\r\nget\r\n$3\r\ndog\r\n]
ngx_chain_writer: [*2\r\n$3\r\nget\r\n$3\r\ndog\r\n]
ngx_linux_sendfile_chain: [*2\r\n$3\r\nget\r\n$3\r\ndog\r\n]
[*2\r\n$3\r\nget\r\n$3\r\ndog\r\n]
显然，直到进入 ngx_chain_writer 时，数据还是正确的，但在调用 ngx_linux_sendfile_chain
时，数据已经多了一倍，所以问题一定出在 ngx_chain_writer 函数体中，而 ngx_chain_writer 函数在操纵它的
ngx_chain_writer_ctx_t 数据时，确实遇到了麻烦。
我已经向 ngx_lua 的 master 分支提交了一个补丁，修正了 ngx_chain_writer_ctx_t 数据的初始化问题：
https://github.com/chaoslawful/lua-nginx-module/commit/5201828
在应用了此补丁之后，运行前面的第一个 systemtap 脚本，但得到了期望的输出：
sock:send("") len:0
sock:send("*2\r\n$3\r\nget\r\n$3\r\ndog\r\n") len:22
writev("*2\r\n$3\r\nget\r\n$3\r\ndog\r\n"(0xf30f80))
recvfrom: got "$-1\r\n"
sock:receive("$-1")
sock:send("") len:0
同时 sock:setkeepalive() 调用也不再报错了。
多谢你提供的最小化用例！这对于快速定位此 bug 非常关键 :)
我同时抄送给了 openresty 邮件组：https://groups.google.com/group/openresty
也欢迎你加入那里和我们交流 :)
Thanks!
-agentzh
