http variables in log_by_lua

edmund.lhot · 2012-12-25T07:18:36+00:00

Hello, all I am happy to announce the new stable version of ngx_openresty, 1.2.4.14: http://openresty.org/#Download Special thanks go to all our contr...

http variables in log_by_lua

edmund.lhot

Hi!

I'm trying to use log_by_lua to store some request information, but the most of http variables (bytes_sent, upstream_cache_status, etc.) are not present in this phase.

Is there a way to find out which variables are available in this phase?

Regards,

Edmund

agentzh

Hello!

On Mon, Dec 24, 2012 at 3:18 PM, Edmund Lhot wrote:
> I'm trying to use log_by_lua to store some request information, but the most
> of http variables (bytes_sent, upstream_cache_status, etc.) are not present
> in this phase.
>
> Is there a way to find out which variables are available in this phase?
>

There should be no such limitations in the log phase.

The variables you named are working fine here in log_by_lua. I've
tried the following minimal example on my side to access $bytes_sent
and $upstream_cache_status in the log_by_lua handler:

    proxy_cache_path /tmp/cache levels=1 keys_zone=static:10m;

    server {
        listen 8080;

        location = /t {
            proxy_cache static;
            proxy_pass http://127.0.0.1:$server_port/remote;

            log_by_lua '
                print("bytes sent: ", ngx.var.bytes_sent)
                print("upstream cache status: ", ngx.var.upstream_cache_status)
            ';
        }

        # to mock a remote HTTP service:
        location = /remote {
            echo hello world;
        }
    }

Accessing /t gives

    $ curl localhost:8080/t
    hello world

And then check out the outputs of the log_by_lua handler in the
nginx's error log file:

    $ grep -E 'notice.*lua' logs/error.log
    2012/12/24 18:18:58 [notice] 9492#0: *1 [lua] [string
"log_by_lua"]:2: bytes sent: 166 while logging request, ...
    2012/12/24 18:18:58 [notice] 9492#0: *1 [lua] [string
"log_by_lua"]:3: upstream cache status: MISS while logging request,
...

We can see that both the $bytes_sent and $upstream_cache_status have
meaningful values within log_by_lua.

Best regards,
-agentzh

billfzhu

The

$bytes_sent become a common variable since nginx version 1.2.5, see details:

    http://nginx.org/en/docs/http/ngx_http_log_module.html#log_format

So you can use

$bytes_sent by setting ngx.var.bytes_sent in lua

 since nginx version 1.2.5.

    http://wiki.nginx.org/HttpLuaModule#ngx.var.VARIABLE

On Tuesday, December 25, 2012 7:18:36 AM UTC+8, Edmund Lhot wrote:

Hi!

I'm trying to use log_by_lua to store some request information, but the most of http variables (bytes_sent, upstream_cache_status, etc.) are not present in this phase.

Is there a way to find out which variables are available in this phase?

Regards,

Edmund

agentzh

Hello!

On Mon, Dec 24, 2012 at 6:30 PM, Bill Zhu wrote:
> The $bytes_sent become a common variable since nginx version 1.2.5, see
> details:
>
>     http://nginx.org/en/docs/http/ngx_http_log_module.html#log_format
>
> So you can use $bytes_sent by setting ngx.var.bytes_sent in lua since nginx
> version 1.2.5.
>
>     http://wiki.nginx.org/HttpLuaModule#ngx.var.VARIABLE
>

Yes, indeed you're right. I was testing against Nginx 1.2.6.

If using Nginx 1.2.4, then $bytes_sent will become nil. But
$upstream_cache_status should still work with earlier Nginx versions
because it has always been a true Nginx variable :)

Edmund: if you're using the ngx_openresty bundle, then you can try the
1.2.6.1rc1 pre-release tarball, which includes the Nginx 1.2.6 core:

    http://agentzh.org/misc/nginx/ngx_openresty-1.2.6.1rc1.tar.gz

Best regards,
-agentzh

edmund.lhot

Hello!

Something is strange here, cause I added another variables in log_by_lua, that I'm using in nginx access_log, but it didn't work too.

daemon off;

worker_processes 2;

error_log /tmp/nginx_error.log debug;

events {

}

http {

log_format combinedio '$remote_addr - $remote_user [$time_local] "$request" $status $body_bytes_sent "$http_referer" "$http_user_agent" "$http_header_cookie" $request_length $bytes_sent $request_time $upstream_cache_status';

proxy_cache_path /tmp/cache levels=1 keys_zone=static:10m;

server {

listen 8080;

location = /t {

proxy_cache static;

proxy_pass http://127.0.0.1:$server_port/remote;

root .;

access_log /tmp/nginx.log combinedio;

log_by_lua '

print("debug_vars bytes sent: ", ngx.var.bytes_sent)

print("debug_vars remote address: ", ngx.var.remote_addr)

print("debug_vars http status code: ", ngx.var.status)

print("debug_vars request length: ", ngx.var.request_length)

print("debug_vars request time: ", ngx.var.request_time)

print("debug_vars upstream cache status: ", ngx.var.upstream_cache_status)

}

# to mock a remote HTTP service:

location = /remote {

echo hello world;

}

The log generated was the following:

2012/12/25 12:07:36 [notice] 13371#0: *1 [lua] [string "log_by_lua"]:2: debug_vars bytes sent: nil while logging request, client: 127.0.0.1, server: , request: "GET /t HTTP/1.1", upstream: "http://127.0.0.1:8080/remote", host: "localhost:8080"

2012/12/25 12:07:36 [notice] 13371#0: *1 [lua] [string "log_by_lua"]:3: debug_vars remote address: 127.0.0.1 while logging request, client: 127.0.0.1, server: , request: "GET /t HTTP/1.1", upstream: "http://127.0.0.1:8080/remote", host: "localhost:8080"

2012/12/25 12:07:36 [notice] 13371#0: *1 [lua] [string "log_by_lua"]:4: debug_vars http status code: 200 while logging request, client: 127.0.0.1, server: , request: "GET /t HTTP/1.1", upstream: "http://127.0.0.1:8080/remote", host: "localhost:8080"

2012/12/25 12:07:36 [notice] 13371#0: *1 [lua] [string "log_by_lua"]:5: debug_vars request length: nil while logging request, client: 127.0.0.1, server: , request: "GET /t HTTP/1.1", upstream: "http://127.0.0.1:8080/remote", host: "localhost:8080"

2012/12/25 12:07:36 [notice] 13371#0: *1 [lua] [string "log_by_lua"]:6: debug_vars request time: nil while logging request, client: 127.0.0.1, server: , request: "GET /t HTTP/1.1", upstream: "http://127.0.0.1:8080/remote", host: "localhost:8080"

2012/12/25 12:07:36 [notice] 13371#0: *1 [lua] [string "log_by_lua"]:7: debug_vars upstream cache status: MISS while logging request, client: 127.0.0.1, server: , request: "GET /t HTTP/1.1", upstream: "http://127.0.0.1:8080/remote", host: "localhost:8080"

But my access_log is ok:

127.0.0.1 - - [25/Dec/2012:12:07:36 -0500] "GET /t HTTP/1.1" 200 22 "-" "curl/7.19.7 (x86_64-redhat-linux-gnu) libcurl/7.19.7 NSS/3.13.1.0 zlib/1.2.3 libidn/1.18 libssh2/1.2.2" "-" 170 188 0.002 MISS

Currently I'm using the openresty bundle 1.2.4.13:

nginx version: ngx_openresty/1.2.4.13

built by gcc 4.4.6 20120305 (Red Hat 4.4.6-4) (GCC)

TLS SNI support enabled

configure arguments: --prefix=/opt/openresty/nginx --with-debug --with-cc-opt='-O0 -I/usr/lib64/perl5/CORE -O2 -Wno-deprecated-declarations' --add-module=../ngx_devel_kit-0.2.17 --add-module=../echo-nginx-module-0.41 --add-module=../xss-nginx-module-0.03rc9 --add-module=../ngx_coolkit-0.2rc1 --add-module=../set-misc-nginx-module-0.22rc8 --add-module=../form-input-nginx-module-0.07rc5 --add-module=../encrypted-session-nginx-module-0.02 --add-module=../srcache-nginx-module-0.16 --add-module=../ngx_lua-0.7.8 --add-module=../headers-more-nginx-module-0.19 --add-module=../array-var-nginx-module-0.03rc1 --add-module=../memc-nginx-module-0.13rc3 --add-module=../redis2-nginx-module-0.09 --add-module=../redis-nginx-module-0.3.6 --add-module=../auth-request-nginx-module-0.2 --add-module=../rds-json-nginx-module-0.12rc10 --add-module=../rds-csv-nginx-module-0.05rc2 --with-ld-opt=-Wl,-rpath,/opt/openresty/luajit/lib --user=nginx --group=nginx --with-pcre-jit --with-http_stub_status_module --with-http_gzip_static_module --with-http_geoip_module --with-http_image_filter_module --with-http_realip_module --with-http_perl_module --with-http_ssl_module

Any idea about my problem?

Are you using openresty 1.2.6 in production?

Tks!

Edmund

On Tue, Dec 25, 2012 at 12:36 AM, agentzh <age...@gmail.com> wrote:

Hello!

On Mon, Dec 24, 2012 at 6:30 PM, Bill Zhu wrote:
> The $bytes_sent become a common variable since nginx version 1.2.5, see
> details:
>
> http://nginx.org/en/docs/http/ngx_http_log_module.html#log_format

>
> So you can use $bytes_sent by setting ngx.var.bytes_sent in lua since nginx
> version 1.2.5.
>
> http://wiki.nginx.org/HttpLuaModule#ngx.var.VARIABLE
>

Yes, indeed you're right. I was testing against Nginx 1.2.6.

If using Nginx 1.2.4, then $bytes_sent will become nil. But
$upstream_cache_status should still work with earlier Nginx versions
because it has always been a true Nginx variable :)

Edmund: if you're using the ngx_openresty bundle, then you can try the
1.2.6.1rc1 pre-release tarball, which includes the Nginx 1.2.6 core:

http://agentzh.org/misc/nginx/ngx_openresty-1.2.6.1rc1.tar.gz

Best regards,
-agentzh

guilherme.e

I updated to 1.2.6.1rc1 and it worked like a charm!

2012/12/25 12:43:24 [notice] 14804#0: *1 [lua] [string "log_by_lua"]:2: debug_vars bytes sent: 190 while logging request, client: 127.0.0.1, server: , request: "GET /t HTTP/1.1", upstream: "http://127.0.0.1:8080/remote", host: "localhost:8080"
2012/12/25 12:43:24 [notice] 14804#0: *1 [lua] [string "log_by_lua"]:3: debug_vars remote address: 127.0.0.1 while logging request, client: 127.0.0.1, server: , request: "GET /t HTTP/1.1", upstream: "http://127.0.0.1:8080/remote", host: "localhost:8080"
2012/12/25 12:43:24 [notice] 14804#0: *1 [lua] [string "log_by_lua"]:4: debug_vars http status code: 200 while logging request, client: 127.0.0.1, server: , request: "GET /t HTTP/1.1", upstream: "http://127.0.0.1:8080/remote", host: "localhost:8080"
2012/12/25 12:43:24 [notice] 14804#0: *1 [lua] [string "log_by_lua"]:5: debug_vars request length: nil while logging request, client: 127.0.0.1, server: , request: "GET /t HTTP/1.1", upstream: "http://127.0.0.1:8080/remote", host: "localhost:8080"
2012/12/25 12:43:24 [notice] 14804#0: *1 [lua] [string "log_by_lua"]:6: debug_vars request time: 0.002 while logging request, client: 127.0.0.1, server: , request: "GET /t HTTP/1.1", upstream: "http://127.0.0.1:8080/remote", host: "localhost:8080"
2012/12/25 12:43:24 [debug] 14804#0: *1 posix_memalign: 0000000001A8E0B0:4096 @16
2012/12/25 12:43:24 [notice] 14804#0: *1 [lua] [string "log_by_lua"]:7: debug_vars upstream cache status: MISS while logging request, client: 127.0.0.1, server: , request: "GET /t HTTP/1.1", upstream: "http://127.0.0.1:8080/remote", host: "localhost:8080"

Do you have an ETA about the 1.2.6.1 stable release?

Tks!

On Tue, Dec 25, 2012 at 3:26 PM, Edmund Lhot <edmun...@gmail.com> wrote:

Hello!

Something is strange here, cause I added another variables in log_by_lua, that I'm using in nginx access_log, but it didn't work too.

daemon off;

worker_processes 2;

error_log /tmp/nginx_error.log debug;

events {
}

http {

log_format combinedio '$remote_addr - $remote_user [$time_local] "$request" $status $body_bytes_sent "$http_referer" "$http_user_agent" "$http_header_cookie" $request_length $bytes_sent $request_time $upstream_cache_status';

proxy_cache_path /tmp/cache levels=1 keys_zone=static:10m;

server {
listen 8080;

location = /t {

proxy_cache static;
proxy_pass http://127.0.0.1:$server_port/remote;

root .;
access_log /tmp/nginx.log combinedio;

log_by_lua '
print("debug_vars bytes sent: ", ngx.var.bytes_sent)
print("debug_vars remote address: ", ngx.var.remote_addr)

print("debug_vars http status code: ", ngx.var.status)
print("debug_vars request length: ", ngx.var.request_length)
print("debug_vars request time: ", ngx.var.request_time)

print("debug_vars upstream cache status: ", ngx.var.upstream_cache_status)
';
}

# to mock a remote HTTP service:

location = /remote {
echo hello world;
}
}
}

The log generated was the following:

2012/12/25 12:07:36 [notice] 13371#0: *1 [lua] [string "log_by_lua"]:2: debug_vars bytes sent: nil while logging request, client: 127.0.0.1, server: , request: "GET /t HTTP/1.1", upstream: "http://127.0.0.1:8080/remote", host: "localhost:8080"

2012/12/25 12:07:36 [notice] 13371#0: *1 [lua] [string "log_by_lua"]:3: debug_vars remote address: 127.0.0.1 while logging request, client: 127.0.0.1, server: , request: "GET /t HTTP/1.1", upstream: "http://127.0.0.1:8080/remote", host: "localhost:8080"

2012/12/25 12:07:36 [notice] 13371#0: *1 [lua] [string "log_by_lua"]:4: debug_vars http status code: 200 while logging request, client: 127.0.0.1, server: , request: "GET /t HTTP/1.1", upstream: "http://127.0.0.1:8080/remote", host: "localhost:8080"

2012/12/25 12:07:36 [notice] 13371#0: *1 [lua] [string "log_by_lua"]:5: debug_vars request length: nil while logging request, client: 127.0.0.1, server: , request: "GET /t HTTP/1.1", upstream: "http://127.0.0.1:8080/remote", host: "localhost:8080"

2012/12/25 12:07:36 [notice] 13371#0: *1 [lua] [string "log_by_lua"]:6: debug_vars request time: nil while logging request, client: 127.0.0.1, server: , request: "GET /t HTTP/1.1", upstream: "http://127.0.0.1:8080/remote", host: "localhost:8080"

2012/12/25 12:07:36 [notice] 13371#0: *1 [lua] [string "log_by_lua"]:7: debug_vars upstream cache status: MISS while logging request, client: 127.0.0.1, server: , request: "GET /t HTTP/1.1", upstream: "http://127.0.0.1:8080/remote", host: "localhost:8080"

But my access_log is ok:

127.0.0.1 - - [25/Dec/2012:12:07:36 -0500] "GET /t HTTP/1.1" 200 22 "-" "curl/7.19.7 (x86_64-redhat-linux-gnu) libcurl/7.19.7 NSS/3.13.1.0 zlib/1.2.3 libidn/1.18 libssh2/1.2.2" "-" 170 188 0.002 MISS

Currently I'm using the openresty bundle 1.2.4.13:

nginx version: ngx_openresty/1.2.4.13

built by gcc 4.4.6 20120305 (Red Hat 4.4.6-4) (GCC)
TLS SNI support enabled
configure arguments: --prefix=/opt/openresty/nginx --with-debug --with-cc-opt='-O0 -I/usr/lib64/perl5/CORE -O2 -Wno-deprecated-declarations' --add-module=../ngx_devel_kit-0.2.17 --add-module=../echo-nginx-module-0.41 --add-module=../xss-nginx-module-0.03rc9 --add-module=../ngx_coolkit-0.2rc1 --add-module=../set-misc-nginx-module-0.22rc8 --add-module=../form-input-nginx-module-0.07rc5 --add-module=../encrypted-session-nginx-module-0.02 --add-module=../srcache-nginx-module-0.16 --add-module=../ngx_lua-0.7.8 --add-module=../headers-more-nginx-module-0.19 --add-module=../array-var-nginx-module-0.03rc1 --add-module=../memc-nginx-module-0.13rc3 --add-module=../redis2-nginx-module-0.09 --add-module=../redis-nginx-module-0.3.6 --add-module=../auth-request-nginx-module-0.2 --add-module=../rds-json-nginx-module-0.12rc10 --add-module=../rds-csv-nginx-module-0.05rc2 --with-ld-opt=-Wl,-rpath,/opt/openresty/luajit/lib --user=nginx --group=nginx --with-pcre-jit --with-http_stub_status_module --with-http_gzip_static_module --with-http_geoip_module --with-http_image_filter_module --with-http_realip_module --with-http_perl_module --with-http_ssl_module

Any idea about my problem?

Are you using openresty 1.2.6 in production?

Tks!

Edmund

On Tue, Dec 25, 2012 at 12:36 AM, agentzh <age...@gmail.com> wrote:
Hello!

On Mon, Dec 24, 2012 at 6:30 PM, Bill Zhu wrote:
> The $bytes_sent become a common variable since nginx version 1.2.5, see
> details:
>
> http://nginx.org/en/docs/http/ngx_http_log_module.html#log_format

>
> So you can use $bytes_sent by setting ngx.var.bytes_sent in lua since nginx
> version 1.2.5.
>
> http://wiki.nginx.org/HttpLuaModule#ngx.var.VARIABLE
>

Yes, indeed you're right. I was testing against Nginx 1.2.6.

If using Nginx 1.2.4, then $bytes_sent will become nil. But
$upstream_cache_status should still work with earlier Nginx versions
because it has always been a true Nginx variable :)

Edmund: if you're using the ngx_openresty bundle, then you can try the
1.2.6.1rc1 pre-release tarball, which includes the Nginx 1.2.6 core:

http://agentzh.org/misc/nginx/ngx_openresty-1.2.6.1rc1.tar.gz

Best regards,
-agentzh

.

agentzh

Hello!

On Tue, Dec 25, 2012 at 9:50 AM, Guilherme wrote:
> I updated to 1.2.6.1rc1 and it worked like a charm!
>

Good to know :)

>
> Do you have an ETA about the 1.2.6.1 stable release?
>

1.2.6.1rc1 has already passed all the tests in all testing modes on my
Amazon EC2 test cluster:

    http://qa.openresty.org/

So feel free to use it in production. The final release 1.2.6.1 will
be out in the next few days or so :)

Best regards,
-agentzh

edmund.lhot

Great! I recompiled openresty and now everything is ok! ;)