请教在access_by_lua中进行打印日志操作，一次请求打印了两次日志？

xiaooolooong · 2015-12-30T18:00:08+00:00

Hello! 2015-12-29 21:38 GMT-08:00 Ruoshan Huang: > > 哈哈哈, 那我等发布了之后&#x63D0...

请教在access_by_lua中进行打印日志操作，一次请求打印了两次日志？

xiaooolooong

在nginx.conf的http块加入配置

access_by_lua_file test.lua;

test.lua：

ngx.log(ngx.ALERT, ngx.worker.id())

ngx.say(ngx.worker.id())

此时执行一次curl，却可以在error.log看到一条日志：

2015/12/30 17:58:01 [alert] 10811#0: *937 [lua] test.lua:1: 0, client: 127.0.0.1, server: localhost, request: "GET / HTTP/1.1", host: "localhost"

但是将ngx.say()删去：

test.lua:

ngx.log(ngx.ALERT, ngx.worker.id())

使用curl请求一次：http://localhost

在error.log里却发现有两条日志生成：

2015/12/30 17:54:49 [alert] 10811#0: *897 [lua] test.lua:1: 0, client: 127.0.0.1, server: localhost, request: "GET / HTTP/1.1", host: "localhost"

请教为何test.lua执行了两次？

xiaooolooong

sbin/nginx -V

nginx version: openresty/1.9.7.1

built by gcc 4.4.7 20120313 (Red Hat 4.4.7-16) (GCC)

built with OpenSSL 1.0.1e-fips 11 Feb 2013

TLS SNI support enabled

configure arguments: --prefix=/usr/local/nginx --with-cc-opt=-O2 --add-module=../ngx_devel_kit-0.2.19 --add-module=../echo-nginx-module-0.58 --add-module=../xss-nginx-module-0.05 --add-module=../ngx_coolkit-0.2rc3 --add-module=../set-misc-nginx-module-0.29 --add-module=../form-input-nginx-module-0.11 --add-module=../encrypted-session-nginx-module-0.04 --add-module=../srcache-nginx-module-0.30 --add-module=../ngx_lua-0.9.20 --add-module=../ngx_lua_upstream-0.04 --add-module=../headers-more-nginx-module-0.29 --add-module=../array-var-nginx-module-0.04 --add-module=../memc-nginx-module-0.16 --add-module=../redis2-nginx-module-0.12 --add-module=../redis-nginx-module-0.3.7 --add-module=../rds-json-nginx-module-0.14 --add-module=../rds-csv-nginx-module-0.07 --with-ld-opt=-Wl,-rpath,/usr/local/luajit/lib --with-http_ssl_module

yuansheng

给一个相对完整的可复现问题的配置+代码，你现在给的配置、代码有点少，担心其他配置干扰。

On Wed, Dec 30, 2015 at 6:03 PM, xiaooloong <xiaoo...@gmail.com> wrote:

sbin/nginx -V
nginx version: openresty/1.9.7.1
built by gcc 4.4.7 20120313 (Red Hat 4.4.7-16) (GCC)
built with OpenSSL 1.0.1e-fips 11 Feb 2013
TLS SNI support enabled
configure arguments: --prefix=/usr/local/nginx --with-cc-opt=-O2 --add-module=../ngx_devel_kit-0.2.19 --add-module=../echo-nginx-module-0.58 --add-module=../xss-nginx-module-0.05 --add-module=../ngx_coolkit-0.2rc3 --add-module=../set-misc-nginx-module-0.29 --add-module=../form-input-nginx-module-0.11 --add-module=../encrypted-session-nginx-module-0.04 --add-module=../srcache-nginx-module-0.30 --add-module=../ngx_lua-0.9.20 --add-module=../ngx_lua_upstream-0.04 --add-module=../headers-more-nginx-module-0.29 --add-module=../array-var-nginx-module-0.04 --add-module=../memc-nginx-module-0.16 --add-module=../redis2-nginx-module-0.12 --add-module=../redis-nginx-module-0.3.7 --add-module=../rds-json-nginx-module-0.14 --add-module=../rds-csv-nginx-module-0.07 --with-ld-opt=-Wl,-rpath,/usr/local/luajit/lib --with-http_ssl_module

--

YuanSheng Wang

---------------------------------------

My Github: https://github.com/membphis

OpenResty lover ^_^

ms2008vip

我猜测是由于 index 引起的内部跳转，具体可见春哥的教程：

https://openresty.org/download/agentzh-nginx-tutorials-zhcn.html#02-NginxDirectiveExecOrder06

在 2015年12月30日星期三 UTC+8下午6:00:09，xiaooloong写道：

在nginx.conf的http块加入配置
access_by_lua_file test.lua;

test.lua：
ngx.log(ngx.ALERT, ngx.worker.id())
ngx.say(ngx.worker.id())

此时执行一次curl，却可以在error.log看到一条日志：
2015/12/30 17:58:01 [alert] 10811#0: *937 [lua] test.lua:1: 0, client: 127.0.0.1, server: localhost, request: "GET / HTTP/1.1", host: "localhost"

但是将ngx.say()删去：
test.lua:
ngx.log(ngx.ALERT, ngx.worker.id())

使用curl请求一次：http://localhost

在error.log里却发现有两条日志生成：
2015/12/30 17:54:49 [alert] 10811#0: *897 [lua] test.lua:1: 0, client: 127.0.0.1, server: localhost, request: "GET / HTTP/1.1", host: "localhost"
2015/12/30 17:54:49 [alert] 10811#0: *897 [lua] test.lua:1: 0, client: 127.0.0.1, server: localhost, request: "GET / HTTP/1.1", host: "localhost"

请教为何test.lua执行了两次？

xiaooolooong

感谢回复，新编译的openresty，默认配置，列出的就是所有的改动项了。

原因已经找到，请求/时的内部跳转，我会在后面的回复中说明

在 2015年12月30日星期三 UTC+8下午8:40:48，YuanSheng写道：

给一个相对完整的可复现问题的配置+代码，你现在给的配置、代码有点少，担心其他配置干扰。

xiaooolooong

感谢！

确实是因为内部跳转的原因。我做了两个实验：

一是直接访问http://localhost/index.html，可以观察到只有一条日志。

二是将test.lua修改为：

ngx.log(ngx.ALERT, ngx.req.is_internal())

此时请求http://localhost ，可以在error.og中观察到两次日志，其中第二次是内部请求：

2015/12/31 10:02:39 [alert] 10811#0: *12522 [lua] test.lua:1: false, client: 127.0.0.1, server: localhost, request: "GET / HTTP/1.1", host: "localhost"

2015/12/31 10:02:39 [alert] 10811#0: *12522 [lua] test.lua:1: true, client: 127.0.0.1, server: localhost, request: "GET / HTTP/1.1", host: "localhost"

在 2015年12月30日星期三 UTC+8下午11:49:30，ms2008写道：

我猜测是由于 index 引起的内部跳转，具体可见春哥的教程：
https://openresty.org/download/agentzh-nginx-tutorials-zhcn.html#02-NginxDirectiveExecOrder06