Request is not finalized after ngx_http_finalize_request() is called

dustin2022 · January 6, 2026, 8:54am

My issue: The request is not finalized after ngx_http_finalize_request() is called.

How I encountered the problem:

I am developing a custom nginx module that hooks into the ACCESS phase. One of the module’s responsibilities is to read the request body from the client.

I use ngx_http_read_client_request_body(r, post_handler) as described in the official NGINX module development documentation.

After the request body is read successfully (no errors in the post handler), I call ngx_http_finalize_request() to finalize the request. However, based on debug logs, it appears that not only the request is freed, but the connection is also closed.

After inspecting the NGINX core code and reviewing error.log, I found that ngx_http_finalize_request() eventually calls ngx_http_finalize_connection(). From there, two outcomes are possible:

ngx_http_close_request() is called and the connection is closed if r->main->count != 1
The connection is kept alive

Case (2) is what I expect, but in practice case (1) occurs. According to the logs, r->main->count is 2 at the time of finalization.

Please check the below log. Please be awared that 2 seconds after POST-ing successfully to server, the client will send a GET to server.

2025/12/30 08:38:00 [debug] 844880#0: *1 access phase: 6
2025/12/30 08:38:00 [debug] 844880#0: *1 my_debug: ACCESS handler fired, uri=/my_test_loc, method=8
2025/12/30 08:38:00 [debug] 844880#0: *1 my_debug: received POST
2025/12/30 08:38:00 [debug] 844880#0: *1 http client request body preread 60
2025/12/30 08:38:00 [debug] 844880#0: *1 http request body content length filter
2025/12/30 08:38:00 [debug] 844880#0: *1 http body new buf t:1 f:0 00005576D91EA3DE, pos 00005576D91EA3DE, size: 60 file: 0, size: 0
2025/12/30 08:38:00 [debug] 844880#0: *1 HTTP/1.1 200 OK
Server: nginx
Date: Tue, 30 Dec 2025 08:38:00 GMT
Content-Type: text/plain
Content-Length: 2
Connection: keep-alive
Set-Cookie: js_auth=NGVhOGZlM2ZlZDJjNzk1ZDU2NjlmNTM1ZGZlMjYyMmE6MTc2NzA4Mzg4MGQ.63daa150eedec4f813367a94ce59f7a64d94a9f3720f67ee42e0f28e6ba6396d; Path=/; SameSite=Lax; HttpOnlyضU

2025/12/30 08:38:00 [debug] 844880#0: *1 write new buf t:1 f:0 00005576D91F0900, pos 00005576D91F0900, size: 322 file: 0, size: 0
2025/12/30 08:38:00 [debug] 844880#0: *1 http write filter: l:0 f:0 s:322
2025/12/30 08:38:00 [debug] 844880#0: *1 http output filter "/my_test_loc?"
2025/12/30 08:38:00 [debug] 844880#0: *1 http copy filter: "/my_test_loc?"
2025/12/30 08:38:00 [debug] 844880#0: *1 http postpone filter "/my_test_loc?" 00007FFE8E108E80
2025/12/30 08:38:00 [debug] 844880#0: *1 write old buf t:1 f:0 00005576D91F0900, pos 00005576D91F0900, size: 322 file: 0, size: 0
2025/12/30 08:38:00 [debug] 844880#0: *1 write new buf t:1 f:0 00005576D91F03F8, pos 00005576D91F03F8, size: 2 file: 0, size: 0
2025/12/30 08:38:00 [debug] 844880#0: *1 http write filter: l:1 f:0 s:324
2025/12/30 08:38:00 [debug] 844880#0: *1 http write filter limit 2097152
2025/12/30 08:38:00 [debug] 844880#0: *1 writev: 324 of 324
2025/12/30 08:38:00 [debug] 844880#0: *1 http write filter 0000000000000000
2025/12/30 08:38:00 [debug] 844880#0: *1 http copy filter: 0 "/my_test_loc?"
2025/12/30 08:38:00 [debug] 844880#0: *1 my_debug: end of POST handling
2025/12/30 08:38:00 [debug] 844880#0: *1 http finalize request: 0, "/my_test_loc?" a:1, c:2
2025/12/30 08:38:00 [debug] 844880#0: *1 my_debug: finalize req T3
2025/12/30 08:38:00 [debug] 844880#0: *1 my_debug: finalize conn, conn number = 2
2025/12/30 08:38:00 [debug] 844880#0: *1 my_debug: finalize conn, close conn T1
2025/12/30 08:38:00 [debug] 844880#0: *1 http request count:2 blk:0
2025/12/30 08:38:00 [debug] 844880#0: *1 my_debug: finish reading POST
2025/12/30 08:38:02 [debug] 844880#0: *1 http run request: "/my_test_loc?"
2025/12/30 08:38:02 [debug] 844880#0: *1 http reading blocked

Solutions I’ve tried:

I noticed that r->main->count is incremented when ngx_http_read_client_request_body() is called. Based on my understanding of NGINX internals, this count should be decremented (by finalizing request) once request body reading is completed. However, in my module, that decrement never seems to happen.

My understanding is that module code should not manually modify r->main->count and should instead let NGINX manage it internally. However, while reviewing some open-source NGINX modules, I noticed that certain modules do manually decrement r->main->count, apparently without issues.

link

As an experiment, I manually decremented r->main->count after the request body was read successfully and just before calling ngx_http_finalize_request(). With this change, the module behaves as expected: the request is finalized and the connection is kept alive.

2025/12/30 08:54:19 [debug] 851593#0: *1 access phase: 6
2025/12/30 08:54:19 [debug] 851593#0: *1 my_debug: ACCESS handler fired, uri=/my_test_loc, method=8
2025/12/30 08:54:19 [debug] 851593#0: *1 my_debug: received POST
2025/12/30 08:54:19 [debug] 851593#0: *1 http client request body preread 59
2025/12/30 08:54:19 [debug] 851593#0: *1 http request body content length filter
2025/12/30 08:54:19 [debug] 851593#0: *1 http body new buf t:1 f:0 0000558252DA53DE, pos 0000558252DA53DE, size: 59 file: 0, size: 0
2025/12/30 08:54:19 [debug] 851593#0: *1 HTTP/1.1 200 OK
Server: nginx
Date: Tue, 30 Dec 2025 08:54:19 GMT
Content-Type: text/plain
Content-Length: 2
Connection: keep-alive
Set-Cookie: js_auth=ZWY3N2NiNjcxOTE5NDEyOTRlYjhlYmM0NTdjNTRkNzE6MTc2NzA4NDg1OWQ.d7104bce4ff1fd735c421c20a1823b1edd3ae0bed01c346b51515740b1f89a8b; Path=/; SameSite=Lax; HttpOnly��R�U

2025/12/30 08:54:19 [debug] 851593#0: *1 write new buf t:1 f:0 0000558252DAB900, pos 0000558252DAB900, size: 323 file: 0, size: 0
2025/12/30 08:54:19 [debug] 851593#0: *1 http write filter: l:0 f:0 s:323
2025/12/30 08:54:19 [debug] 851593#0: *1 http output filter "/my_test_loc?"
2025/12/30 08:54:19 [debug] 851593#0: *1 http copy filter: "/my_test_loc?"
2025/12/30 08:54:19 [debug] 851593#0: *1 http postpone filter "/my_test_loc?" 00007FFD67818EC0
2025/12/30 08:54:19 [debug] 851593#0: *1 write old buf t:1 f:0 0000558252DAB900, pos 0000558252DAB900, size: 323 file: 0, size: 0
2025/12/30 08:54:19 [debug] 851593#0: *1 write new buf t:1 f:0 0000558252DAB3F8, pos 0000558252DAB3F8, size: 2 file: 0, size: 0
2025/12/30 08:54:19 [debug] 851593#0: *1 http write filter: l:1 f:0 s:325
2025/12/30 08:54:19 [debug] 851593#0: *1 http write filter limit 2097152
2025/12/30 08:54:19 [debug] 851593#0: *1 writev: 325 of 325
2025/12/30 08:54:19 [debug] 851593#0: *1 http write filter 0000000000000000
2025/12/30 08:54:19 [debug] 851593#0: *1 http copy filter: 0 "/my_test_loc?"
2025/12/30 08:54:19 [debug] 851593#0: *1 my_debug: end of POST handling
2025/12/30 08:54:19 [debug] 851593#0: *1 http finalize request: 0, "/my_test_loc?" a:1, c:1
2025/12/30 08:54:19 [debug] 851593#0: *1 my_debug: finalize req T3
2025/12/30 08:54:19 [debug] 851593#0: *1 my_debug: finalize conn, conn number = 1
2025/12/30 08:54:19 [debug] 851593#0: *1 my_debug: finalize conn, keepalive check: ngx_terminate=0 ngx_exiting=0 r->keepalive=1 keepalive_timeout=75000
2025/12/30 08:54:19 [debug] 851593#0: *1 set http keepalive handler
2025/12/30 08:54:19 [debug] 851593#0: *1 my_debug: free request T3
2025/12/30 08:54:19 [debug] 851593#0: *1 http close request
2025/12/30 08:54:19 [debug] 851593#0: *1 http log handler
2025/12/30 08:54:19 [debug] 851593#0: *1 free: 0000558252DAA470, unused: 8
2025/12/30 08:54:19 [debug] 851593#0: *1 free: 0000558252DAB480, unused: 2433
2025/12/30 08:54:19 [debug] 851593#0: *1 free: 0000558252DA5250
2025/12/30 08:54:19 [debug] 851593#0: *1 hc free: 0000000000000000
2025/12/30 08:54:19 [debug] 851593#0: *1 hc busy: 0000000000000000 0
2025/12/30 08:54:19 [debug] 851593#0: *1 reusable connection: 1
2025/12/30 08:54:19 [debug] 851593#0: *1 event timer add: 3: 75000:5285830793
2025/12/30 08:54:19 [debug] 851593#0: *1 my_debug: finish reading POST
2025/12/30 08:54:21 [debug] 851593#0: *1 http keepalive handler
2025/12/30 08:54:21 [debug] 851593#0: *1 malloc: 0000558252DA5250:1024
2025/12/30 08:54:21 [debug] 851593#0: *1 recv: eof:0, avail:-1
2025/12/30 08:54:21 [debug] 851593#0: *1 recv: fd:3 626 of 1024
2025/12/30 08:54:21 [debug] 851593#0: *1 reusable connection: 0
2025/12/30 08:54:21 [debug] 851593#0: *1 posix_memalign: 0000558252DAA470:4096 @16
2025/12/30 08:54:21 [debug] 851593#0: *1 event timer del: 3: 5285830793
2025/12/30 08:54:21 [debug] 851593#0: *1 http process request line
2025/12/30 08:54:21 [debug] 851593#0: *1 http request line: "GET / HTTP/1.1"
2025/12/30 08:54:21 [debug] 851593#0: *1 http uri: "/"
2025/12/30 08:54:21 [debug] 851593#0: *1 http args: ""
2025/12/30 08:54:21 [debug] 851593#0: *1 http exten: ""
2025/12/30 08:54:21 [debug] 851593#0: *1 posix_memalign: 0000558252DAB480:4096 @16

My code (not full) looks like as below

/* read body post_handler */
static void ngx_http_my_module_read_body(ngx_http_request_t *r)
{
    ...
    /* src code to verify the request */
    ...

    static const char ok[] = "OK";
    rc = send_string(r, "text/plain", ok, sizeof(ok)-1, NGX_HTTP_OK);

    if (rc == NGX_AGAIN) {
        return;
    }
    ngx_log_error(NGX_LOG_DEBUG, r->connection->log, 0, "my_debug: end of POST handling");
    if (r->main->count > 1) {
        r->main->count--;
    }
    ngx_http_finalize_request(r, rc);
    return;
}

static ngx_int_t send_string(ngx_http_request_t *r, const char *ctype, const char *body, size_t len, ngx_int_t status) {
    r->headers_out.status = status;
    r->headers_out.content_length_n = (off_t) len;
    r->headers_out.content_type.len = strlen(ctype);
    r->headers_out.content_type.data = (u_char *) ctype;

    ngx_int_t rc = ngx_http_send_header(r);
    if (rc != NGX_OK) {
        return rc;
    }

    ngx_buf_t *b = ngx_create_temp_buf(r->pool, len);
    if (b == NULL) {
        return NGX_ERROR;
    }

    ngx_memcpy(b->pos, body, len);
    b->last = b->pos + len;
    b->memory = 1;
    b->last_buf = 1;
    b->last_in_chain = 1;

    ngx_chain_t out;
    out.buf = b;
    out.next = NULL;

    return ngx_http_output_filter(r, &out);
}

So my question is:

Is it safe for a module to manually decrement r->main->count?
If it is safe, what conditions or invariants should be checked to ensure correctness?
If it is not safe, what is the correct way to resolve the issue where r->main->count remains greater than 1 after reading the request body?

Any guidance on the correct lifecycle handling here would be appreciated.

Topic		Replies	Views
How to get the subrequest response in custom module NGINX codebase , subrequest , custom-module	3	121	July 3, 2025
NGINX uploads entire 2GB request body even though auth_request returns 401 NGINX auth , docker , reverse-proxy	14	147	December 18, 2025
[HTTP Upgraded Connection] : Memory not getting released after connection termination NGINX reverse-proxy , stream , websocket , memory	2	105	July 10, 2025
NGINX does not drop connections on bad requests with empty host headers NGINX request , web-server , headers , return	19	551	August 1, 2025
Content-Length getting updated to 0 in multipart HTTP requests NGINX reverse-proxy , headers	2	93	November 6, 2025

Request is not finalized after ngx_http_finalize_request() is called

Related topics