关于在log_by_lua中使用ngx.var.request问题

haoyun-kgq · 2013-08-25T15:47:46+00:00

Hello! 2013/8/22 逆雪寒: > 通过 ngx.var.fastcgi_script_name 是nil 。但 set $fsn $fastcgi_script_name &#x...

关于在log_by_lua中使用ngx.var.request问题

haoyun-kgq

大家好！

我遇到一个奇怪的问题，代码如下：

server {

log_by_lua_file conf/status.lua;

}

下面是status.lua文件内容：

local io = require("io")

local file = assert(io.open("/tmp/lua.log","a"))

file:write(ngx.var.request_method.." ")

file:write(ngx.var.request_uri.." ")

file:write(ngx.var.server_protocol.." ")

file:write("\n")

file:close()

如上代码，可以在lua.log中记录正常日志：

GET / HTTP/1.1

GET /favicon.ico HTTP/1.1

但是nginx的error.log里却记录了如下错误信息：

2013/08/25 04:31:26 [error] 2208#0: *2 failed to run log_by_lua*: /usr/local/openresty/nginx/conf/status.lua:39: attempt to concatenate field 'request_method' (a nil value)

stack traceback:

/usr/local/openresty/nginx/conf/status.lua:39: in function </usr/local/openresty/nginx/conf/status.lua:1> while logging request, client: 192.168.8.3, server: localhost

请大家帮我看下，这是怎么回事，明明日志里已经记录了变量的值，说明变量不是nil的，可是error.log里却提示'request_method' (a nil value)

3Q！

haoyun-kgq

我发现问题了，是浏览器请求造成的。我查看nginx的access.log，发现如下日志记录：

192.168.8.3 - - [25/Aug/2013:05:11:41 +0800] "GET / HTTP/1.1" 200 5 "-" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/28.0.1500.95 Safari/537.36"

192.168.8.3 - - [25/Aug/2013:05:11:41 +0800] "GET /favicon.ico HTTP/1.1" 304 0 "-" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/28.0.1500.95 Safari/537.36"

192.168.8.3 - - [25/Aug/2013:05:12:01 +0800] "-" 400 0 "-" "-"

一共3个请求，应该是最后一个造成的，最后这个是什么请求呢？

我用 tailf access.log 跟踪发现，前2个请求是同时发生的，最后那个请求要等好几秒才出现，这是什么原因的，为什么还有最后那个怪请求呢？

3Q！

在 2013-08-25 15:47:42，haoyun <haoy...@163.com> 写道：

大家好！
我遇到一个奇怪的问题，代码如下：
server {
log_by_lua_file conf/status.lua;
}
下面是status.lua文件内容：
local io = require("io")
local file = assert(io.open("/tmp/lua.log","a"))
file:write(ngx.var.request_method.." ")
file:write(ngx.var.request_uri.." ")
file:write(ngx.var.server_protocol.." ")
file:write("\n")
file:close()
如上代码，可以在lua.log中记录正常日志：
GET / HTTP/1.1
GET /favicon.ico HTTP/1.1
但是nginx的error.log里却记录了如下错误信息：
2013/08/25 04:31:26 [error] 2208#0: *2 failed to run log_by_lua*: /usr/local/openresty/nginx/conf/status.lua:39: attempt to concatenate field 'request_method' (a nil value)
stack traceback:
/usr/local/openresty/nginx/conf/status.lua:39: in function </usr/local/openresty/nginx/conf/status.lua:1> while logging request, client: 192.168.8.3, server: localhost
请大家帮我看下，这是怎么回事，明明日志里已经记录了变量的值，说明变量不是nil的，可是error.log里却提示'request_method' (a nil value)

3Q！

--

smallfish.xy

尽量自己写测试代码，或者基于cURL之类的工具。浏览器后面会有很多东西，

1. /favicon.ico 就是网站前面的小图标那个，默认都会请求，如果没有这个文件，都会记录在accesslog里，建议都是不记录log

2. 400空body的请求，应该是chrome预先载入和尝试访问遗留下来的，tengine有一个扩展指令，empty请求不记录log

smallfish http://chenxiaoyu.org

2013/8/25 haoyun <haoy...@163.com>

我发现问题了，是浏览器请求造成的。我查看nginx的access.log，发现如下日志记录：
192.168.8.3 - - [25/Aug/2013:05:11:41 +0800] "GET / HTTP/1.1" 200 5 "-" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/28.0.1500.95 Safari/537.36"

192.168.8.3 - - [25/Aug/2013:05:11:41 +0800] "GET /favicon.ico HTTP/1.1" 304 0 "-" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/28.0.1500.95 Safari/537.36"

192.168.8.3 - - [25/Aug/2013:05:12:01 +0800] "-" 400 0 "-" "-"
一共3个请求，应该是最后一个造成的，最后这个是什么请求呢？
我用 tailf access.log 跟踪发现，前2个请求是同时发生的，最后那个请求要等好几秒才出现，这是什么原因的，为什么还有最后那个怪请求呢？

3Q！

在 2013-08-25 15:47:42，haoyun <haoy...@163.com> 写道：

大家好！
我遇到一个奇怪的问题，代码如下：
server {
log_by_lua_file conf/status.lua;
}
下面是status.lua文件内容：
local io = require("io")

local file = assert(io.open("/tmp/lua.log","a"))
file:write(ngx.var.request_method.." ")
file:write(ngx.var.request_uri.." ")
file:write(ngx.var.server_protocol.." ")

file:write("\n")
file:close()
如上代码，可以在lua.log中记录正常日志：
GET / HTTP/1.1
GET /favicon.ico HTTP/1.1
但是nginx的error.log里却记录了如下错误信息：

2013/08/25 04:31:26 [error] 2208#0: *2 failed to run log_by_lua*: /usr/local/openresty/nginx/conf/status.lua:39: attempt to concatenate field 'request_method' (a nil value)
stack traceback:

/usr/local/openresty/nginx/conf/status.lua:39: in function </usr/local/openresty/nginx/conf/status.lua:1> while logging request, client: 192.168.8.3, server: localhost

请大家帮我看下，这是怎么回事，明明日志里已经记录了变量的值，说明变量不是nil的，可是error.log里却提示'request_method' (a nil value)

3Q！

--

--

haoyun-kgq

嗯，多谢兄弟。我找到一篇博客，也说明了这个问题，就是chrome浏览器的问题，和并发连接数有关。

http://chaoskeh.com/blog/nginx-400-bad-request-error-reason.html

在 2013-08-25 16:38:54，smallfish <small...@gmail.com> 写道：

尽量自己写测试代码，或者基于cURL之类的工具。浏览器后面会有很多东西，

1. /favicon.ico 就是网站前面的小图标那个，默认都会请求，如果没有这个文件，都会记录在accesslog里，建议都是不记录log
2. 400空body的请求，应该是chrome预先载入和尝试访问遗留下来的，tengine有一个扩展指令，empty请求不记录log

--
smallfish http://chenxiaoyu.org

2013/8/25 haoyun <haoy...@163.com>

我发现问题了，是浏览器请求造成的。我查看nginx的access.log，发现如下日志记录：
192.168.8.3 - - [25/Aug/2013:05:11:41 +0800] "GET / HTTP/1.1" 200 5 "-" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/28.0.1500.95 Safari/537.36"

192.168.8.3 - - [25/Aug/2013:05:11:41 +0800] "GET /favicon.ico HTTP/1.1" 304 0 "-" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/28.0.1500.95 Safari/537.36"

192.168.8.3 - - [25/Aug/2013:05:12:01 +0800] "-" 400 0 "-" "-"
一共3个请求，应该是最后一个造成的，最后这个是什么请求呢？
我用 tailf access.log 跟踪发现，前2个请求是同时发生的，最后那个请求要等好几秒才出现，这是什么原因的，为什么还有最后那个怪请求呢？

3Q！

在 2013-08-25 15:47:42，haoyun <haoy...@163.com> 写道：

大家好！
我遇到一个奇怪的问题，代码如下：
server {
log_by_lua_file conf/status.lua;
}
下面是status.lua文件内容：
local io = require("io")

local file = assert(io.open("/tmp/lua.log","a"))
file:write(ngx.var.request_method.." ")
file:write(ngx.var.request_uri.." ")
file:write(ngx.var.server_protocol.." ")

file:write("\n")
file:close()
如上代码，可以在lua.log中记录正常日志：
GET / HTTP/1.1
GET /favicon.ico HTTP/1.1
但是nginx的error.log里却记录了如下错误信息：

2013/08/25 04:31:26 [error] 2208#0: *2 failed to run log_by_lua*: /usr/local/openresty/nginx/conf/status.lua:39: attempt to concatenate field 'request_method' (a nil value)
stack traceback:

/usr/local/openresty/nginx/conf/status.lua:39: in function </usr/local/openresty/nginx/conf/status.lua:1> while logging request, client: 192.168.8.3, server: localhost

请大家帮我看下，这是怎么回事，明明日志里已经记录了变量的值，说明变量不是nil的，可是error.log里却提示'request_method' (a nil value)

3Q！

--

--

--