Nginx holding subrequests when using thread pool

Sat Aug 13 03:07:33 UTC 2022

Hi,

I’m trying to modify the ModSecurity NGINX connector to use the thread
pool feature offered by NGINX. However when running the test suites
involving auth_request, as long as I did a ngx_thread_task_post in
either the rewrite phase or preaccess phase, the auth subrequest
always seems to somehow block until the main request canceled. What
happened in between?

Cheers,
W.

NGINX version: 1.21.4

Code of rewrite handler:

ngx_int_t ngx_http_modsecurity_rewrite_handler(ngx_http_request_t *r)
{
    ngx_http_modsecurity_rewrite_thread_ctx_t *ctx;
    ngx_http_modsecurity_ctx_t *m_ctx;
    ngx_thread_task_t *task;

    m_ctx = ngx_http_get_module_ctx(r, ngx_http_modsecurity_module);

    ngx_log_error(NGX_LOG_DEBUG, r->connection->log, 0, "recovering
ctx: %p", m_ctx);

    task = ngx_thread_task_alloc(r->pool,
sizeof(ngx_http_modsecurity_rewrite_thread_ctx_t));

    ctx = task->ctx;
    ctx->r = r;
    ctx->ctx = m_ctx;
    ctx->return_code = NGX_DECLINED;

    task->handler = ngx_http_modsecurity_rewrite_worker;
    task->event.handler = ngx_http_modsecurity_rewrite_finalizer;
    task->event.data = ctx;

    ngx_log_error(NGX_LOG_DEBUG, r->connection->log, 0, "[ModSecurity]
Using Thread Pool: %p", mcf->thread_pool);

    if (ngx_thread_task_post(mcf->thread_pool, task) != NGX_OK)
    {
        return NGX_ERROR;
    }

    return NGX_DONE;
}

The completion handler:

void ngx_http_modsecurity_rewrite_finalizer(ngx_event_t *ev)
{
    ngx_http_modsecurity_rewrite_thread_ctx_t *ctx = ev->data;
    ngx_http_core_main_conf_t *cmcf;

    ngx_log_error(NGX_LOG_DEBUG, ctx->r->connection->log, 0,
"[ModSecurity] Rewrite Job Finalized");

    cmcf = ngx_http_get_module_main_conf(ctx->r, ngx_http_core_module);

    switch (ctx->return_code)
    {
    case NGX_OK:
        ctx->r->phase_handler = cmcf->phase_engine.handlers->next;
        ngx_http_core_run_phases(ctx->r);
        break;
    case NGX_DECLINED:
        ctx->r->phase_handler++;
        ngx_http_core_run_phases(ctx->r);
        break;
    case NGX_AGAIN:
    case NGX_DONE:
        // ngx_http_core_run_phases(ctx->r);
        break;
    default:
        ngx_http_finalize_request(ctx->r, ctx->return_code);
    }
}

Note that even if I don’t do anything in
ngx_http_modsecurity_rewrite_worker, it still seems to block.

Relevant Config:

        location = /auth {
            return 200;
        }

        location = /useauth {
            modsecurity on;
            modsecurity_rules '
                SecRuleEngine On
                SecRequestBodyAccess On
            ';
            auth_request /auth;
            proxy_pass http://127.0.0.1:8081;
        }

Debug log (notice the gap, that’s when I Ctrl-C the curl):

2022/08/12 19:29:17 [debug] 17157#17160: Nothing to add on the body
inspection, reclaiming a NGX_DECLINED
2022/08/12 19:29:17 [debug] 17157#17160: complete task #2 in thread
pool "default"
2022/08/12 19:29:17 [debug] 17157#17157: epoll: fd:11 ev:0001 d:00005558A9EA4560
2022/08/12 19:29:17 [debug] 17157#17157: thread pool handler
2022/08/12 19:29:17 [debug] 17157#17157: run completion handler for task #2
2022/08/12 19:29:17 [debug] 17157#17157: *2 generic phase: 6
2022/08/12 19:29:17 [debug] 17157#17157: *2 generic phase: 7
2022/08/12 19:29:17 [debug] 17157#17157: *2 access phase: 8
2022/08/12 19:29:17 [debug] 17157#17157: *2 access phase: 9
2022/08/12 19:29:17 [debug] 17157#17157: *2 access phase: 10
2022/08/12 19:29:17 [debug] 17157#17157: *2 auth request handler
2022/08/12 19:29:17 [debug] 17157#17157: *2 http subrequest "/auth?"
2022/08/12 19:29:17 [debug] 17157#17157: timer delta: 0
2022/08/12 19:29:17 [debug] 17157#17157: worker cycle
2022/08/12 19:29:17 [debug] 17157#17157: epoll timer: -1
2022/08/12 19:29:23 [debug] 17157#17157: epoll: fd:3 ev:2001 d:00005558AB3ED909
2022/08/12 19:29:23 [debug] 17157#17157: *2 http run request: "/auth?"
2022/08/12 19:29:23 [debug] 17157#17157: *2 http request empty handler
2022/08/12 19:29:23 [debug] 17157#17157: *2 http posted request: "/auth?"
2022/08/12 19:29:23 [debug] 17157#17157: *2 rewrite phase: 0
2022/08/12 19:29:23 [debug] 17157#17157: *2 test location: "/bodylimitreject"
2022/08/12 19:29:23 [debug] 17157#17157: *2 test location: "/bodyaccess"
2022/08/12 19:29:23 [debug] 17157#17157: *2 test location: "/auth"
2022/08/12 19:29:23 [debug] 17157#17157: *2 using configuration "=/auth"
2022/08/12 19:29:23 [debug] 17157#17157: *2 http cl:-1 max:1048576
2022/08/12 19:29:23 [debug] 17157#17157: *2 rewrite phase: 2
2022/08/12 19:29:23 [debug] 17157#17157: *2 catching a new _rewrite_
phase handler

This is the log when I don’t bother with the thread pool:

2022/08/12 19:29:45 [debug] 18087#18087: *1 catching a new _rewrite_
phase handler
2022/08/12 19:29:45 [error] 18087#18087: *1 ModSecurity not enabled...
returning, client: 127.0.0.1, server: localhost, request: "GET
/useauth HTTP/1.1", host: "127.0.0.1:8080"
2022/08/12 19:29:45 [debug] 18087#18087: *1 rewrite phase: 3
2022/08/12 19:29:45 [debug] 18087#18087: *1 post rewrite phase: 4
2022/08/12 19:29:45 [debug] 18087#18087: *1 generic phase: 5
2022/08/12 19:29:45 [debug] 18087#18087: *1 catching a new _preaccess_
phase handler
2022/08/12 19:29:45 [error] 18087#18087: *1 ModSecurity not enabled...
returning, client: 127.0.0.1, server: localhost, request: "GET
/useauth HTTP/1.1", host: "127.0.0.1:8080"
2022/08/12 19:29:45 [debug] 18087#18087: *1 generic phase: 6
2022/08/12 19:29:45 [debug] 18087#18087: *1 generic phase: 7
2022/08/12 19:29:45 [debug] 18087#18087: *1 access phase: 8
2022/08/12 19:29:45 [debug] 18087#18087: *1 access phase: 9
2022/08/12 19:29:45 [debug] 18087#18087: *1 access phase: 10
2022/08/12 19:29:45 [debug] 18087#18087: *1 auth request handler
2022/08/12 19:29:45 [debug] 18087#18087: *1 http subrequest "/auth?"
2022/08/12 19:29:45 [debug] 18087#18087: *1 http posted request: "/auth?"
2022/08/12 19:29:45 [debug] 18087#18087: *1 rewrite phase: 0
2022/08/12 19:29:45 [debug] 18087#18087: *1 test location: "/bodylimitreject"
2022/08/12 19:29:45 [debug] 18087#18087: *1 test location: "/bodyaccess"
2022/08/12 19:29:45 [debug] 18087#18087: *1 test location: "/auth"
2022/08/12 19:29:45 [debug] 18087#18087: *1 using configuration "=/auth"
2022/08/12 19:29:45 [debug] 18087#18087: *1 http cl:-1 max:1048576
2022/08/12 19:29:45 [debug] 18087#18087: *1 rewrite phase: 2
2022/08/12 19:29:45 [debug] 18087#18087: *1 catching a new _rewrite_
phase handler
2022/08/12 19:29:45 [error] 18087#18087: *1 ModSecurity not enabled...
returning, client: 127.0.0.1, server: localhost, request: "GET
/useauth HTTP/1.1", subrequest: "/auth", host: "127.0.0.1:8080"
2022/08/12 19:29:45 [debug] 18087#18087: *1 rewrite phase: 3
2022/08/12 19:29:45 [debug] 18087#18087: *1 header filter, recovering
ctx: 0000000000000000