lua ngx.log prints repeatedly

[wbcmax]

Problem description

When I start a docker-openresty to debug my lua script, the log prints duplicates

Version

openresty docker image version: docker.io/openresty/openresty:1.21.4.1-alpine

$ openresty -V

nginx version: openresty/1.21.4.1
built by gcc 11.2.1 20220219 (Alpine 11.2.1_git20220219)
built with OpenSSL 1.1.1p  21 Jun 2022
TLS SNI support enabled
configure arguments: --prefix=/usr/local/openresty/nginx --with-cc-opt='-O2 -DNGX_LUA_ABORT_AT_PANIC -I/usr/local/openresty/pcre/include -I/usr/local/openresty/openssl/include' --add-module=../ngx_devel_kit-0.3.1 --add-module=../echo-nginx-module-0.62 --add-module=../xss-nginx-module-0.06 --add-module=../ngx_coolkit-0.2 --add-module=../set-misc-nginx-module-0.33 --add-module=../form-input-nginx-module-0.12 --add-module=../encrypted-session-nginx-module-0.09 --add-module=../srcache-nginx-module-0.32 --add-module=../ngx_lua-0.10.21 --add-module=../ngx_lua_upstream-0.07 --add-module=../headers-more-nginx-module-0.33 --add-module=../array-var-nginx-module-0.05 --add-module=../memc-nginx-module-0.19 --add-module=../redis2-nginx-module-0.15 --add-module=../redis-nginx-module-0.3.9 --add-module=../rds-json-nginx-module-0.15 --add-module=../rds-csv-nginx-module-0.09 --add-module=../ngx_stream_lua-0.0.11 --with-ld-opt='-Wl,-rpath,/usr/local/openresty/luajit/lib -L/usr/local/openresty/pcre/lib -L/usr/local/openresty/openssl/lib -Wl,-rpath,/usr/local/openresty/pcre/lib:/usr/local/openresty/openssl/lib' --with-pcre --with-compat --with-file-aio --with-http_addition_module --with-http_auth_request_module --with-http_dav_module --with-http_flv_module --with-http_geoip_module=dynamic --with-http_gunzip_module --with-http_gzip_static_module --with-http_image_filter_module=dynamic --with-http_mp4_module --with-http_random_index_module --with-http_realip_module --with-http_secure_link_module --with-http_slice_module --with-http_ssl_module --with-http_stub_status_module --with-http_sub_module --with-http_v2_module --with-http_xslt_module=dynamic --with-ipv6 --with-mail --with-mail_ssl_module --with-md5-asm --with-sha1-asm --with-stream --with-stream_ssl_module --with-threads --with-pcre-jit --with-stream --with-stream_ssl_preread_module

A minimal and standalone test case that others can easily run on their side and reproduce the issue you are seeing.

docker run -itd --name openresty -p 80:80 openresty/openresty:1.21.4.1-alpine

docker exec -it openresty sh

cd /etc/nginx/conf.d/

This is my test default.conf

# nginx.vh.default.conf  --  docker-openresty
#
# This file is installed to:
#   `/etc/nginx/conf.d/default.conf`
#
# It tracks the `server` section of the upstream OpenResty's `nginx.conf`.
#
# This config (and any other configs in `etc/nginx/conf.d/`) is loaded by
# default by the `include` directive in `/usr/local/openresty/nginx/conf/nginx.conf`.
#
# See https://github.com/openresty/docker-openresty/blob/master/README.md#nginx-config-files
#

server {
    listen       80;
    server_name  localhost;

    #charset koi8-r;
    #access_log  /var/log/nginx/host.access.log  main;

    location / {
        root   /usr/local/openresty/nginx/html;
        index  index.html index.htm;
        rewrite_by_lua_file /opt/wbc/lua-redis.lua;         <----------------- my lua script
    }

    #error_page  404              /404.html;

    # redirect server error pages to the static page /50x.html
    #
    error_page   500 502 503 504  /50x.html;
    location = /50x.html {
        root   /usr/local/openresty/nginx/html;
    }

    # proxy the PHP scripts to Apache listening on 127.0.0.1:80
    #
    #location ~ \.php$ {
    #    proxy_pass   http://127.0.0.1;
    #}

    # pass the PHP scripts to FastCGI server listening on 127.0.0.1:9000
    #
    #location ~ \.php$ {
    #    root           /usr/local/openresty/nginx/html;
    #    fastcgi_pass   127.0.0.1:9000;
    #    fastcgi_index  index.php;
    #    fastcgi_param  SCRIPT_FILENAME  /scripts$fastcgi_script_name;
    #    include        fastcgi_params;
    #}

    # deny access to .htaccess files, if Apache's document root
    # concurs with nginx's one
    #
    #location ~ /\.ht {
    #    deny  all;
    #}
}

This is my lua script

ngx.log(ngx.ERR, "111")

Request error log

You can see that "111" is recorded twice in the log

2022/07/19 11:21:07 [error] 7#7: *1 [lua] lua-redis.lua:1: 111, client: 192.168.251.85, server: localhost, request: "GET / HTTP/1.1", host: "192.168.251.100:80"
2022/07/19 11:21:07 [error] 7#7: *1 [lua] lua-redis.lua:1: 111, client: 192.168.251.85, server: localhost, request: "GET / HTTP/1.1", host: "192.168.251.100:80"
192.168.251.85 - - [19/Jul/2022:11:21:07 +0000] "GET / HTTP/1.1" 200 1097 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/103.0.0.0 Safari/537.36"

The result I expected

The log in the lua script is only recorded once.

Thanks!

[neomantra]

Can you check if it does the same in non-containerized OpenResty? In other words, does this have anything to do with it being in a container?

[neomantra]

You might be facing this? https://groups.google.com/g/openresty-en/c/me3b1kKDxuk

[wbcmax]

Can you check if it does the same in non-containerized OpenResty? In other words, does this have anything to do with it being in a container?

I deployed an openresty on a virtual machine and reproduced the problem, it doesn't just appear on docker-openresty

[wbcmax]

Problem solved!

https://stackoverflow.com/questions/63443482/openresty-why-does-access-by-lua-file-call-twice-when-accessing-the-root-directo

Thank you for your help @neomantra !