Bug: use `ngx.print` and `error_page` causes bad case.

[tzssangglass]

Minimal Reproduction Steps

# vim:set ft= ts=4 sw=4 et fdm=marker:

use Test::Nginx::Socket::Lua;

repeat_each(2);

plan tests => blocks() * repeat_each() * 2;

run_tests();

__DATA__

=== TEST 50: nginx crashes when encountering an illegal http if header(2)
crash with ngx.print()
--- main_config
--- config
error_page 412 /my_error_handler_412;

location /t {
    access_by_lua_block {
        ngx.print("OK")
        ngx.exit(200)
    }
}
location = /my_error_handler_412 {
    content_by_lua_block {
       -- here maybe some other lua code
        ngx.sleep(0.002)
        ngx.header["Content-Type"] = "text/plain"
    }
}
--- request
    GET /t
--- more_headers
If-Match: 1
--- error_code: 412
--- response_body eval
qr/\Ahello\z/

Root Cause Analysis

Direct cause

ngx.print will cause the header_filter to be entered, and the ngx_http_not_modified_header_filter determines that the request header's If-Match fails (in actual scenarios, it does not match the response header's etag), which leads to entering the error_handler set by error_page and entering the Lua code again.

call stack:

ngx_http_lua_run_thread(lua_State * L, ngx_http_request_t * r, ngx_http_lua_ctx_t * ctx, volatile int nrets) (ngx_lua-0.10.27/src/ngx_http_lua_util.c:1194)
ngx_http_lua_content_by_chunk(lua_State * L, ngx_http_request_t * r) (ngx_lua-0.10.27/src/ngx_http_lua_contentby.c:124)
ngx_http_lua_content_handler_inline(ngx_http_request_t * r) (ngx_lua-0.10.27/src/ngx_http_lua_contentby.c:312)
ngx_http_lua_content_handler(ngx_http_request_t * r) (ngx_lua-0.10.27/src/ngx_http_lua_contentby.c:222)
ngx_http_core_content_phase(ngx_http_request_t * r, ngx_http_phase_handler_t * ph) (nginx-1.27.1/src/http/ngx_http_core_module.c:1271)
ngx_http_core_run_phases(ngx_http_request_t * r) (nginx-1.27.1/src/http/ngx_http_core_module.c:885)
ngx_http_handler(ngx_http_request_t * r) (nginx-1.27.1/src/http/ngx_http_core_module.c:868)
ngx_http_internal_redirect(ngx_http_request_t * r, ngx_str_t * uri, ngx_str_t * args) (nginx-1.27.1/src/http/ngx_http_core_module.c:2557)
ngx_http_send_error_page(ngx_http_request_t * r, ngx_http_err_page_t * err_page) (nginx-1.27.1/src/http/ngx_http_special_response.c:620)
ngx_http_special_response_handler(ngx_http_request_t * r, ngx_int_t error) (nginx-1.27.1/src/http/ngx_http_special_response.c:463)
ngx_http_filter_finalize_request(ngx_http_request_t * r, ngx_module_t * m, ngx_int_t error) (nginx-1.27.1/src/http/ngx_http_special_response.c:548)
ngx_http_not_modified_header_filter(ngx_http_request_t * r) (nginx-1.27.1/src/http/modules/ngx_http_not_modified_filter_module.c:74)
ngx_http_send_header(ngx_http_request_t * r) (nginx-1.27.1/src/http/ngx_http_core_module.c:1859)
ngx_http_lua_send_header_if_needed(ngx_http_request_t * r, ngx_http_lua_ctx_t * ctx) (ngx_lua-0.10.27/src/ngx_http_lua_util.c:551)
ngx_http_lua_send_chain_link(ngx_http_request_t * r, ngx_http_lua_ctx_t * ctx, ngx_chain_t * in) (ngx_lua-0.10.27/src/ngx_http_lua_util.c:597)
ngx_http_lua_ngx_echo(lua_State * L, unsigned int newline) (ngx_lua-0.10.27/src/ngx_http_lua_output.c:240)
ngx_http_lua_ngx_print(lua_State * L) (ngx_lua-0.10.27/src/ngx_http_lua_output.c:26)
libluajit-5.1.so.2!lj_BC_FUNCC (Unknown Source:0)
ngx_http_lua_run_thread(lua_State * L, ngx_http_request_t * r, ngx_http_lua_ctx_t * ctx, volatile int nrets) (ngx_lua-0.10.27/src/ngx_http_lua_util.c:1194)
ngx_http_lua_subrequest_resume(ngx_http_request_t * r) (ngx_lua-0.10.27/src/ngx_http_lua_subrequest.c:1561)

Some analysis

1. Lua Code call ngx.print causes C Stack, when entering ngx_http_filter_finalize_request, it will clean the r->ctx

ngx_int_t
ngx_http_filter_finalize_request(ngx_http_request_t *r, ngx_module_t *m,
    ngx_int_t error)
{
...
    /* clear the modules contexts */
    ngx_memzero(r->ctx, sizeof(void *) * ngx_http_max_module);
...
}

2. then after entering ngx_http_lua_rewrite_handler(you can watch r->ctx in GDB to see where it changes), it will create the new r->ctx

ngx_int_t
ngx_http_lua_rewrite_handler(ngx_http_request_t *r)
{
    ...
    if (ctx == NULL) {
        ctx = ngx_http_lua_create_ctx(r);
        if (ctx == NULL) {
            return NGX_ERROR;
        }
    }
...
}

3. then after entering ngx_http_lua_content_by_chunk, it would set ctx->entered_content_phase to 1

ngx_int_t
ngx_http_lua_content_by_chunk(lua_State *L, ngx_http_request_t *r)
{
   ...
    ctx->entered_content_phase = 1;

4. then return to the ngx_http_lua_send_header_if_needed, it would set the new ctx

ngx_int_t
ngx_http_lua_send_header_if_needed(ngx_http_request_t *r,
    ngx_http_lua_ctx_t *ctx)
{
   ...
        if (!ctx->buffering) {
            dd("sending headers");
            rc = ngx_http_send_header(r);
            if (r->filter_finalize) {
                ngx_http_set_ctx(r, ctx, ngx_http_lua_module);
            }

            ctx->header_sent = 1;
            return rc;
        }

5. when resuming the ngx.sleep, since the ctx->entered_content_phaseis 1, it would enter ngx_http_core_run_phases

void
ngx_http_lua_sleep_handler(ngx_event_t *ev)
{
   ...

    if (ctx->entered_content_phase) {
        (void) ngx_http_lua_sleep_resume(r);

    } else {
        ctx->resume_handler = ngx_http_lua_sleep_resume;
        ngx_http_core_run_phases(r);
    }

    ngx_http_run_posted_requests(c);
}

here caused the Lua code to run from the wrong position after ngx.sleep, starting execution from the content_by_lua_block entry location of /my_error_handler_412, rather than the actual place after sleep (this is because the code cache hit found the wrong entry).

[tzssangglass]

cc @zhuizhuhaomeng PTAL

[zhuizhuhaomeng]

Did you test on the latest lua-nginx-module? @tzssangglass

[tzssangglass]

Yes, I test on the master branch of lua-nginx-module.

[catbro666]

In OpenResty, a r can only correspond to one ctx at any one point in time. But in this particular internal-redirect case, a r corresponds to two ctxs at the same time. ngx_http_filter_finalize_request cleared all the module contexts and set r->filter_finalize = 1, so in the first phase of the error_handler location, it would create a new module ctx. Then in ngx_http_lua_send_header_if_needed, because r->filter_finalize was set it set the old ctx back again.

The error_handler ctx was in the entered_content_phase state, but the original ctx was not. So when the timer expired, it should have taken the if branch and resumed directly, but instead in fact it took the else branch and loaded the code chunk and ran again.

void
ngx_http_lua_sleep_handler(ngx_event_t *ev)
{
   ...

    if (ctx->entered_content_phase) {
        (void) ngx_http_lua_sleep_resume(r);

    } else {
        ctx->resume_handler = ngx_http_lua_sleep_resume;
        ngx_http_core_run_phases(r);
    }

    ngx_http_run_posted_requests(c);
}

[tzssangglass]

try to show what happens between ngx.print -> my_error_handler_412 -> sleep -> resume sleep, and supplement what @catbro666 said.

[zhuizhuhaomeng]

This is another issue. It seems we can't have our cake and eat it too.
892b7ee#diff-f3b5eff9e699ddda300088e61df1dc7165a40293ea307f6f7163075ef720a14a

[zhuizhuhaomeng]

@oowl
The last fix was not perfect.

[tzssangglass]

closed by: #2401