log_by_lua not run correctly in case of a 400 error

[Ludo D]

Hello,

I'm running the latest Openresty version (1.11.2.3) and am using it as a reverse-proxy. I'm currently implementing a custom logging routine using https://github.com/cloudflare/lua-resty-logger-socket, which works fine.

However, while doing all sorts of tests, I noticed that if Nginx throws a 400 error (generated on purpose with Curl) the log_by_lua routine is not executed in the "location" block which should serve the request.

Here is my simplified config snippet :

        server {
                location / {
                        log_by_lua_block {
                             ngx.log(ngx.ERR, "Testing log_by_lua")
                        }
                        proxy_pass 1.2.3.4:8080
                }
        }

When generating a 400 error with :

myheader=$(python -c "print 'A'*100000")
curl --header "X-MyHeader: $myheader" 'http://1.2.3.4'

The traditionnal access_log file is correctly written and I can see the request :

[...] "GET / HTTP/1.1" 400 242 "-" "curl/7.38.0" "-" [...]

But log_by_lua is not executed and I can't see my test message. It only works by duplicating the log_by_lua code in the "server" section of the config.

I read the Openresty docs and saw https://github.com/openresty/lua-nginx-module#missing-data-on-short-circuited-requests which states that "Nginx may terminate a request early [...] This means that phases that normally run are skipped, such as the rewrite or access phase. This also means that later phases that are run regardless, e.g. log_by_lua, will not have access to information that is normally set in those phases".

If I understand correctly, as the request is terminated early, any LUA code present in the "location /" block will not be executed because some phases are skipped ?

Thanks for your input !

[Robert Paprocki]

Hello!

On Fri, Jun 23, 2017 at 2:00 AM, Ludo D <dlu...@gmail.com> wrote:

Hello,

...

But log_by_lua is not executed and I can't see my test message. It only works by duplicating the log_by_lua code in the "server" section of the config.

I read the Openresty docs and saw https://github.com/openresty/lua-nginx-module#missing-data-on-short-circuited-requests which states that "Nginx may terminate a request early [...] This means that phases that normally run are skipped, such as the rewrite or access phase. This also means that later phases that are run regardless, e.g. log_by_lua, will not have access to information that is normally set in those phases".

If I understand correctly, as the request is terminated early, any LUA code present in the "location /" block will not be executed because some phases are skipped ?

Correct-ish. In the case of a 400 where the request could not possibly be handled because it was so invalid, Nginx may not select a location block to process. Therefore, any handlers in that location block would not execute. The workaround (as you astutely noted) is to define your log_by_lua handler in the parent server{} block. Be aware that, by nature of Nginx configuration inheritance, duplicate phase handlers in a server{} AND location{} block will not both run. If a *_by_lua handler is present in both server {} and location {}, only the location block handler will execute.

[Rob Kay]

A similar problem happens when an upstream returns >300 status and you have intercept errors and a matching error_page directive. The internal redirect skips the logging phase of the original location block

[Ludo D]

Thanks for the pointers Rpaprocki and Rob ! I'll define my LUA code in both server{} and location{} blocks to have a fallback routine in case of such specific requests.