在试图复现这个问题的时候,我意外的发现了另外一个问题(也可能与之前那个有关,但我暂时还无法在最小环境中复现),似乎和 ngx.eof() ngx.location.capture_multi() 与 proxy_pass 合作有关,具体的说,就是当使用 ngx.eof() 之后,如果用 capture_multi请求 proxy_pass,之后的lua代码似乎将不再执行,而不启用 ngx.eof() 时是正常的。以下示例
[root@lg101 logs]# cat /usr/local/openresty/nginx/conf/nginx.conf
user nobody;
worker_processes 8;
worker_rlimit_nofile 65535;
error_log /data/logs/error.log;
pid /data/logs/nginx.pid;
events {
use epoll;
worker_connections 4096;
}
http {
log_format cx '$remote_addr - $remote_user [$time_local] '
'"$request" $status $body_bytes_sent '
'$request_time';
server {
listen 80 default backlog=8192;
access_log /data/logs/80.access.log cx;
error_log /data/logs/80.error.log notice;
location /proxy
{
internal;
proxy_connect_timeout 20000ms;
proxy_read_timeout 20000ms;
proxy_pass $args;
}
location / {
content_by_lua '
ngx.say(1)
ngx.eof()
local resps = { ngx.location.capture_multi{
{ "/proxy", { args = "
http://127.0.0.1:81/?a=1" } },
{ "/proxy", { args = "
http://127.0.0.1:81/?b=1" } },
} }
local logfn = "/data/logs/m.log"
local msg = ""
for i, resp in ipairs(resps) do
msg = msg .. resp.status .. " " .. resp.body .. "\\n"
end
local fh = io.open(logfn, "a+")
fh:write(msg .. "==========\\n")
fh:close()
';
}
}
server {
listen 81;
access_log /data/logs/81.access.log cx;
error_log /data/logs/81.error.log notice;
location / {
content_by_lua '
ngx.sleep(3)
ngx.print(81);
';
}
}
}
假如注释掉 ngx.eof() 一行,运行结果及log如下
[root@lg101 logs]# cat 80.access.log
127.0.0.1 - - [12/Sep/2012:11:32:02 +0800] "GET / HTTP/1.1" 200 12 3.004
[root@lg101 logs]# cat 81.access.log
127.0.0.1 - - [12/Sep/2012:11:32:02 +0800] "GET /?a=1 HTTP/1.0" 200 2 3.003
127.0.0.1 - - [12/Sep/2012:11:32:02 +0800] "GET /?b=1 HTTP/1.0" 200 2 3.003
[root@lg101 logs]# cat m.log
200 81
200 81
==========
[root@lg101 logs]#
这个看起来是正常的,但当打开 ngx.eof() 一行之后重新执行,结果及log就是样了
[root@lg101 logs]# curl "
http://localhost"
1
[root@lg101 logs]# cat 80.access.log
127.0.0.1 - - [12/Sep/2012:11:32:02 +0800] "GET / HTTP/1.1" 200 12 3.004
127.0.0.1 - - [12/Sep/2012:11:32:36 +0800] "GET / HTTP/1.1" 200 12 0.001
[root@lg101 logs]# cat 81.access.log
127.0.0.1 - - [12/Sep/2012:11:32:02 +0800] "GET /?a=1 HTTP/1.0" 200 2 3.003
127.0.0.1 - - [12/Sep/2012:11:32:02 +0800] "GET /?b=1 HTTP/1.0" 200 2 3.003
127.0.0.1 - - [12/Sep/2012:11:32:39 +0800] "GET /?a=1 HTTP/1.0" 200 2 3.003
127.0.0.1 - - [12/Sep/2012:11:32:39 +0800] "GET /?b=1 HTTP/1.0" 200 2 3.003
[root@lg101 logs]# cat m.log
200 81
200 81
==========
[root@lg101 logs]#
请求完成时间从 3.004 变成了 0.001,这个如愿了,但最后的 m.log 里,却没有了更新的内容,虽然看 81.access.log 里,请求已经送到并正常返回,但原始请求里写 m.log的部分确没有被执行。
更多的,我把写 m.log 那段换成了重新请求一次 capture_multi,同样在 81.access.log 里也没有看到有更多的请求过来。
Lance
2012/9/12 agentzh
<age...@gmail.com>
Hello!
2012/9/11 Lance <lance...@gmail.com>:
> 在用 ngx.eof() 中断用户连接后,后面的操作(proxy_pass)继续执行完成后,errorlog里会有类似
> 这样一条日志
> 2012/09/12 00:12:05 [alert] 5162#0: *114756769 http finalize non-active
> request:
> 应该就是说明这种情况的。
>
请问你能提供一个能复现此问题的最小化的完整示例么?
> 请问除了改源码,有什么好办法能干掉这条日志?虽然它无害,但太烦了,而且errorlog全被它
> 堆满,其他的error就被淹没了
>
我想修复一下真正的这个问题,而不是干掉这一条 alert 日志 :)
Best regards,
-agentzh