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

192 views
Skip to first unread message

Tianyi Zhang

unread,
Feb 27, 2018, 12:20:48 AM2/27/18
to openresty


排查确认是 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] ？？


tokers

unread,
Feb 27, 2018, 1:05:48 AM2/27/18
to openresty
Hi!

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

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

Tianyi Zhang

unread,
Feb 27, 2018, 1:49:06 AM2/27/18
to openresty
版本是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写道：

tokers

unread,
Feb 27, 2018, 3:04:38 AM2/27/18
to openresty
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 代码逻辑是如何的，如果方便是不是可以提供一个最小化的例子方便复现并排查。


Tianyi Zhang

unread,
Feb 27, 2018, 3:45:52 AM2/27/18
to openresty
也就是说，ctx->posted_threads 是0x3e8的这个有问题的ctx是最初的，filter_finalize之后被改成了那个正常的ctx？但是这个posted_threads的值等于0x3e8很不合理，看代码没有地方会赋值成这样。

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

Tianyi Zhang

unread,
Feb 27, 2018, 4:08:35 AM2/27/18
to openresty
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
        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!

Zexuan Luo

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

--
--
邮件来自列表“openresty”,专用于技术讨论!
订阅: 请发空白邮件到 openresty+subscribe@googlegroups.com
发言: 请发邮件到 open...@googlegroups.com
退订: 请发邮件至 openresty+unsubscribe@googlegroups.com
归档: http://groups.google.com/group/openresty
官网: http://openresty.org/
仓库: https://github.com/agentzh/ngx_openresty
教程: http://openresty.org/download/agentzh-nginx-tutorials-zhcn.html

Reply all
Reply to author
Forward
0 new messages