局部变量诡异更改导致的coredump

ratherthanqq

排查确认是 ngx_http_lua_subrequest_resume 中的ctx发生了变更，导致了出core，如下代码，标红了ctx出现的地方，除了通过ngx_http_get_module_ctx给ctx赋值，没有别的地方修改ctx的值了。

但诡异的是，ctx的值还是发生了变化。。

static ngx_int_t
ngx_http_lua_subrequest_resume(ngx_http_request_t *r)
{
    lua_State                   *vm;
    ngx_int_t                    rc;
    ngx_connection_t            *c;
    ngx_http_lua_ctx_t          *ctx;
    ngx_http_lua_co_ctx_t       *coctx;

    ctx = ngx_http_get_module_ctx(r, ngx_http_lua_module);
    if (ctx == NULL) {
        return NGX_ERROR;
    }

    ctx->resume_handler = ngx_http_lua_wev_handler;

    ngx_log_debug0(NGX_LOG_DEBUG_HTTP, r->connection->log, 0,
                   "lua run subrequests done, resuming lua thread");

    coctx = ctx->cur_co_ctx;

    dd("nsubreqs: %d", (int) coctx->nsubreqs);

    ngx_http_lua_handle_subreq_responses(r, ctx);

    dd("free sr_statues/headers/bodies memory ASAP");

#if 1
    ngx_pfree(r->pool, coctx->sr_statuses);

    coctx->sr_statuses = NULL;
    coctx->sr_headers = NULL;
    coctx->sr_bodies = NULL;
    coctx->sr_flags = NULL;
#endif

    c = r->connection;
    vm = ngx_http_lua_get_lua_vm(r, ctx);

    rc = ngx_http_lua_run_thread(vm, r, ctx, coctx->nsubreqs);

    ngx_log_debug1(NGX_LOG_DEBUG_HTTP, r->connection->log, 0,
                   "lua run thread returned %d", rc);

    if (rc == NGX_AGAIN) {
        return ngx_http_lua_run_posted_threads(c, vm, r, ctx);
    }

    if (rc == NGX_DONE) {
        ngx_http_lua_finalize_request(r, NGX_DONE);
       // core在此处
        return ngx_http_lua_run_posted_threads(c, vm, r, ctx);
    }

    /* rc == NGX_ERROR || rc >= NGX_OK */

    if (ctx->entered_content_phase) {
        ngx_http_lua_finalize_request(r, rc);
        return NGX_DONE;
    }

    return rc;
}

ngx_http_get_module_ctx(r, ngx_http_lua_module) 对应的取值就是 r->ctx[ngx_http_lua_module.ctx_index]

看到上面打出的值是0x7fe69e8dcb20，再看内容也是正确的，resume_handler就是ngx_http_lua_wev_handler。

但这里打出ctx这个局部变量的值，却是0x7fe69df1b2f0，看整段代码，除了第一次给ctx赋值，没有其他地方会修改ctx的值。

十分困扰，难道ngx_http_get_module_ctx(r, ngx_http_lua_module) 并不对应 r->ctx[ngx_http_lua_module.ctx_index] ？？

zchao1995

Hi!

你用的是什么版本的 lua-nginx-module？

另外 coredump 发生在 ngx_http_lua_run_posted_threads 这个函数的哪一行？

ratherthanqq

版本是0.10.6, coredump在下面标粗这行，原因是 pt = ctx->posted_threads，这里的ctx->posted_threads已经不对了，如图：

这个posted_threads 是0x3e8

ngx_http_lua_run_posted_threads(ngx_connection_t *c, lua_State *L,
    ngx_http_request_t *r, ngx_http_lua_ctx_t *ctx)
{
    ngx_int_t                        rc;
    ngx_http_lua_posted_thread_t    *pt;

    for ( ;; ) {
        if (c->destroyed) {
            return NGX_DONE;
        }

        pt = ctx->posted_threads;
        if (pt == NULL) {
            return NGX_DONE;
        }

        ctx->posted_threads = pt->next;

        ngx_http_lua_probe_run_posted_thread(r, pt->co_ctx->co,
                                             (int) pt->co_ctx->co_status);

        if (pt->co_ctx->co_status != NGX_HTTP_LUA_CO_RUNNING) {
            continue;
        }

        ctx->cur_co_ctx = pt->co_ctx;

        rc = ngx_http_lua_run_thread(L, r, ctx, 0);

        if (rc == NGX_AGAIN) {
            continue;
        }

        if (rc == NGX_DONE) {
            ngx_http_lua_finalize_request(r, NGX_DONE);
            continue;
        }

        /* rc == NGX_ERROR || rc >= NGX_OK */

        if (ctx->entered_content_phase) {
            ngx_http_lua_finalize_request(r, rc);
        }

        return rc;
    }

在 2018年2月27日星期二 UTC+8下午2:05:48，tokers写道：

Hi!

你用的是什么版本的 lua-nginx-module？

另外 coredump 发生在 ngx_http_lua_run_posted_threads 这个函数的哪一行？

zchao1995

Hello!

我目前能够想到的，ctx 被改变的情况只有一种：

ngx_http_lua_subrequest_resume 里有调用 ngx_http_lua_run_thread 来运行 Lua 协程，

如果你的 Lua 代码里有使用 ngx.print 这样的 output api，且请求头里携带 If-Match 或者 If-Unmodified-Since 时，

在对应 ETag 不符合或者对应 Last-Modified 不符合的情况下，nginx 会触发 filter_finalize，

这部分的逻辑题主可以参考 nginx 的 not_modified_header_filter。

filter_finalize 会导致 nginx clear 所有模块的 ctx，接下来如果有配置对应的 error_page 导致了内部跳转，

走到新的 location 执行了 ngx_lua 逻辑，则对应请求的

r->ctx[ngx_http_lua_module.ctx_index]

就会设置成新的值了。

注意上面整套逻辑的调用栈都是连续的，等到调用栈回到 ngx_http_lua_subrequest_resume 时，自动变量 ctx 指向的和 r->ctx 里的就是不同的了。

这个问题我之前已经报告给 OpenResty 官方，并提交了 PR，见 https://github.com/openresty/lua-nginx-module/pull/1132

不知道题主你的配置和 Lua 代码逻辑是如何的，如果方便是不是可以提供一个最小化的例子方便复现并排查。

ratherthanqq

也就是说，ctx->posted_threads 是0x3e8的这个有问题的ctx是最初的，filter_finalize之后被改成了那个正常的ctx？但是这个posted_threads的值等于0x3e8很不合理，看代码没有地方会赋值成这样。

在 2018年2月27日星期二 UTC+8下午4:04:38，tokers写道：

Hello!

我目前能够想到的，ctx 被改变的情况只有一种：

ngx_http_lua_subrequest_resume 里有调用 ngx_http_lua_run_thread 来运行 Lua 协程，
如果你的 Lua 代码里有使用 ngx.print 这样的 output api，且请求头里携带 If-Match 或者 If-Unmodified-Since 时，
在对应 ETag 不符合或者对应 Last-Modified 不符合的情况下，nginx 会触发 filter_finalize，
这部分的逻辑题主可以参考 nginx 的 not_modified_header_filter。

filter_finalize 会导致 nginx clear 所有模块的 ctx，接下来如果有配置对应的 error_page 导致了内部跳转，
走到新的 location 执行了 ngx_lua 逻辑，则对应请求的

r->ctx[ngx_http_lua_module.ctx_index]

就会设置成新的值了。

注意上面整套逻辑的调用栈都是连续的，等到调用栈回到 ngx_http_lua_subrequest_resume 时，自动变量 ctx 指向的和 r->ctx 里的就是不同的了。

这个问题我之前已经报告给 OpenResty 官方，并提交了 PR，见 https://github.com/openresty/lua-nginx-module/pull/1132

不知道题主你的配置和 Lua 代码逻辑是如何的，如果方便是不是可以提供一个最小化的例子方便复现并排查。

ratherthanqq

lua代码里没有调用output api，location中也没有跳转到其他location的配置

location / {

proxy_http_version 1.1;

proxy_set_header Connection "";

proxy_set_header Host $host;

proxy_set_header X-Real-IP $remote_addr;

proxy_set_header X-Real-Port $remote_port;

proxy_set_header X-Timestamp $msec;

proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;

proxy_set_header X-Forwarded-Proto $scheme;

access_by_lua_file qos.lua;

proxy_set_header Accept-Encoding "";

if ($http_iflow_gz2 ~ "true") { gz2 on;add_header private-encoding gz2; }

set $dy_xxx_gray_1 dy_xxx_gray_1;

set_by_lua $res '

local args = ngx.req.get_uri_args()

local x = ""

local metaParams = {"ds", "ut"}

for k,v in pairs(metaParams) do

if args[v] ~= nil then

if type(args[v]) == "table" then

local len = table.getn(args[v])

x = args[v][len]

else

x = args[v]

end

break

end

if x == "" then return 1000 end

local hash = mmh2(x)

return hash % 1000 ';

if ($res ~ ^([0-9]|10)$) {proxy_pass http://$dy_xxx_gray_1;}

set $dy_xxx dy_xxx;

proxy_pass http://$dy_xxx_iniflowserver;

}

在 2018年2月27日星期二 UTC+8下午4:04:38，tokers写道：

Hello!

我目前能够想到的，ctx 被改变的情况只有一种：

ngx_http_lua_subrequest_resume 里有调用 ngx_http_lua_run_thread 来运行 Lua 协程，
如果你的 Lua 代码里有使用 ngx.print 这样的 output api，且请求头里携带 If-Match 或者 If-Unmodified-Since 时，
在对应 ETag 不符合或者对应 Last-Modified 不符合的情况下，nginx 会触发 filter_finalize，
这部分的逻辑题主可以参考 nginx 的 not_modified_header_filter。

filter_finalize 会导致 nginx clear 所有模块的 ctx，接下来如果有配置对应的 error_page 导致了内部跳转，
走到新的 location 执行了 ngx_lua 逻辑，则对应请求的

r->ctx[ngx_http_lua_module.ctx_index]

就会设置成新的值了。

注意上面整套逻辑的调用栈都是连续的，等到调用栈回到 ngx_http_lua_subrequest_resume 时，自动变量 ctx 指向的和 r->ctx 里的就是不同的了。

这个问题我之前已经报告给 OpenResty 官方，并提交了 PR，见 https://github.com/openresty/lua-nginx-module/pull/1132

不知道题主你的配置和 Lua 代码逻辑是如何的，如果方便是不是可以提供一个最小化的例子方便复现并排查。

spacewanderlzx

看 ctx 输出，貌似 ctx 指向的内存被 free 掉了，所以里面才有一些垃圾数据？
也许某个地方提前释放了 r->pool 指向的内存。不过奇怪的是 r->ctx 却是正常的（后面又重新分配了？）
建议带 Valgrind 跑一下，看看有什么相关的报告。或者用 gdb 跟一下。
如果有最小化可重现例子（不依赖其他第三方模块，和对 Nginx 的私有修改），建议报告到 lua-nginx-module 的 issue 上。

在 2018年2月27日下午1:20，Tianyi Zhang <rathe...@gmail.com>写道：

排查确认是 ngx_http_lua_subrequest_resume 中的ctx发生了变更，导致了出core，如下代码，标红了ctx出现的地方，除了通过ngx_http_get_module_ctx给ctx赋值，没有别的地方修改ctx的值了。

但诡异的是，ctx的值还是发生了变化。。

static ngx_int_t ngx_http_lua_subrequest_resume(ngx_http_request_t *r) { lua_State *vm; ngx_int_t rc; ngx_connection_t *c; ngx_http_lua_ctx_t *ctx; ngx_http_lua_co_ctx_t *coctx; ctx = ngx_http_get_module_ctx(r, ngx_http_lua_module); if (ctx == NULL) { return NGX_ERROR; } ctx->resume_handler = ngx_http_lua_wev_handler; ngx_log_debug0(NGX_LOG_DEBUG_HTTP, r->connection->log, 0, "lua run subrequests done, resuming lua thread"); coctx = ctx->cur_co_ctx; dd("nsubreqs: %d", (int) coctx->nsubreqs); ngx_http_lua_handle_subreq_responses(r, ctx); dd("free sr_statues/headers/bodies memory ASAP"); #if 1 ngx_pfree(r->pool, coctx->sr_statuses); coctx->sr_statuses = NULL; coctx->sr_headers = NULL; coctx->sr_bodies = NULL; coctx->sr_flags = NULL; #endif c = r->connection; vm = ngx_http_lua_get_lua_vm(r, ctx); rc = ngx_http_lua_run_thread(vm, r, ctx, coctx->nsubreqs); ngx_log_debug1(NGX_LOG_DEBUG_HTTP, r->connection->log, 0, "lua run thread returned %d", rc); if (rc == NGX_AGAIN) { return ngx_http_lua_run_posted_threads(c, vm, r, ctx); } if (rc == NGX_DONE) { ngx_http_lua_finalize_request(r, NGX_DONE); // core在此处 return ngx_http_lua_run_posted_threads(c, vm, r, ctx); } /* rc == NGX_ERROR || rc >= NGX_OK */ if (ctx->entered_content_phase) { ngx_http_lua_finalize_request(r, rc); return NGX_DONE; } return rc; }

ngx_http_get_module_ctx(r, ngx_http_lua_module) 对应的取值就是 r->ctx[ngx_http_lua_module.ctx_index]

看到上面打出的值是0x7fe69e8dcb20，再看内容也是正确的，resume_handler就是ngx_http_lua_wev_handler。

但这里打出ctx这个局部变量的值，却是0x7fe69df1b2f0，看整段代码，除了第一次给ctx赋值，没有其他地方会修改ctx的值。

十分困扰，难道ngx_http_get_module_ctx(r, ngx_http_lua_module) 并不对应 r->ctx[ngx_http_lua_module.ctx_index] ？？

--