Terminating requests

Thu Mar 5 16:26:34 UTC 2015

I have investigated this further and found that ngx_finalize_connection()
is being called recursively and on the third recursive call, called by
ngx_upstream_finalize_request(), sometimes the call to
set_lingering_close() calls ngx_http_close_request() which runs the log
handler then closes the connection. This frees up r->pool and during the
unwinding of the stack ngx_http_log_request()/ngx_http_log_handler() are
called a second time which end up calling ngx_pnalloc() with a null r->pool
pointer here:
http://lxr.nginx.org/source/src/http/modules/ngx_http_log_module.c#0349

This is reproducible with the module linked below when setup with an
upstream and nikto pointed at nginx.

I have found a fix by setting r->keepalive to 0 before finalising the
request, if you revert this commit nginx will stop coring and the issue
seems to be taken care of.

https://github.com/tommywatson/nginx-hello-world-module/commit/1d94b065be875d26e11ff14257c411076aa79eaa

Any help on a better solution would be great.

Cheers.

On Fri, Feb 13, 2015 at 8:44 PM, tommy watson <
tommywatson+nginx-devel at gmail.com> wrote:

> Hello,
>   I'm trying to continue or cancel an ngx_http_request_t after a slight
> delay but am failing miserably, I keep getting crashes and am not sure what
> I'm doing wrong.
> The code is here https://github.com/tommywatson/nginx-hello-world-module
> (borrowed from https://www.ruby-forum.com/topic/5564332) basically it
> pauses and fires and event to continue or finalize the request. Firing
> nikto at it brings the dump below.
>  Any help/insight appreciated.
>
> Cheers.
>
> Program terminated with signal SIGSEGV, Segmentation fault.
> #0  0x0000000000406af2 in ngx_pnalloc (pool=0x0, size=181) at
> src/core/ngx_palloc.c:155
> 155    if (size <= pool->max) {
> (gdb) where
> #0  0x0000000000406af2 in ngx_pnalloc (pool=0x0, size=181) at
> src/core/ngx_palloc.c:155
> #1  0x0000000000452692 in ngx_http_log_handler (r=0x6676b50) at
> src/http/modules/ngx_http_log_module.c:349
> #2  0x000000000044c385 in ngx_http_log_request (r=0x6676b50) at
> src/http/ngx_http_request.c:3510
> #3  0x000000000044c1f2 in ngx_http_free_request (r=0x6676b50, rc=0) at
> src/http/ngx_http_request.c:3457
> #4  0x000000000044b297 in ngx_http_set_keepalive (r=0x6676b50) at
> src/http/ngx_http_request.c:2895
> #5  0x000000000044a994 in ngx_http_finalize_connection (r=0x6676b50) at
> src/http/ngx_http_request.c:2532
> #6  0x000000000044a10b in ngx_http_finalize_request (r=0x6676b50, rc=-4)
> at src/http/ngx_http_request.c:2262
> #7  0x000000000043cb18 in ngx_http_core_content_phase (r=0x6676b50,
> ph=0x60b7798) at src/http/ngx_http_core_module.c:1407
> #8  0x000000000043b911 in ngx_http_core_run_phases (r=0x6676b50) at
> src/http/ngx_http_core_module.c:888
> #9  0x00000000004af101 in hack_event (e=0x6677bc8) at
> ../nginx-hello-world-module/ngx_http_hello_world_module.c:85
> #10 0x000000000042afac in ngx_event_expire_timers () at
> src/event/ngx_event_timer.c:94
> #11 0x00000000004290a7 in ngx_process_events_and_timers (cycle=0x608f310)
> at src/event/ngx_event.c:262
> #12 0x000000000043493f in ngx_worker_process_cycle (cycle=0x608f310,
> data=0x0) at src/os/unix/ngx_process_cycle.c:824
> #13 0x000000000043176d in ngx_spawn_process (cycle=0x608f310,
> proc=0x43476b <ngx_worker_process_cycle>, data=0x0, name=0x4b3180 "worker
> process", respawn=-3) at src/os/unix/ngx_process.c:198
> #14 0x0000000000433a71 in ngx_start_worker_processes (cycle=0x608f310,
> n=1, type=-3) at src/os/unix/ngx_process_cycle.c:368
> #15 0x00000000004331cd in ngx_master_process_cycle (cycle=0x608f310) at
> src/os/unix/ngx_process_cycle.c:140
> #16 0x00000000004037c6 in main (argc=1, argv=0xffefffbe8) at
> src/core/nginx.c:407
> (gdb) quit
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.nginx.org/pipermail/nginx-devel/attachments/20150305/bdaac664/attachment.html>
-------------- next part --------------
2015/02/17 16:27:53 [error] 3537#0: *381 finalize_request:2256:273:396 **1** ++++++++++++ [2256] r:0000000001CA1640 p:0000000001CA15F0 c:00007F95F5976280 while connecting to upstrea
2015/02/17 16:27:53 [error] 3537#0: *381 finalize_request:2257:273:396 **1** || RC -4 || r:0000000001CA1640 p:0000000001CA15F0 c:00007F95F5976280 while connecting to upstream, clien
2015/02/17 16:27:53 [error] 3537#0: *381 ngx_http_finalize_connection:2524:273:396 **1** ++++++++++++ [2524] r:0000000001CA1640 p:0000000001CA15F0 c:00007F95F5976280 while connectin
2015/02/17 16:27:53 [error] 3537#0: *381 ngx_http_finalize_connection:2548:273:396 **1** || Close rq|| r:0000000001CA1640 p:0000000001CA15F0 c:00007F95F5976280 while connecting to u
2015/02/17 16:27:53 [error] 3537#0: *381 ngx_http_close_request:3427:273:396 **1** ++++++++++++ [3427] r:0000000001CA1640 p:0000000001CA15F0 c:00007F95F5976280 while connecting to u
2015/02/17 16:27:53 [error] 3537#0: *381 ngx_http_close_request:3427:273:396 **1** ------------ [3441] r:0000000001CA1640 p:0000000001CA15F0 c:00007F95F5976280 while connecting to u
2015/02/17 16:27:53 [error] 3537#0: *381 ngx_http_finalize_connection:2524:273:396 **1** ------------ [2550] r:0000000001CA1640 p:0000000001CA15F0 c:00007F95F5976280 while connectin
2015/02/17 16:27:53 [error] 3537#0: *381 finalize_request:2256:273:396 **1** ------------ [2267] r:0000000001CA1640 p:0000000001CA15F0 c:00007F95F5976280 while connecting to upstrea
2015/02/17 16:27:53 [error] 3537#0: *381 finalize_request:2256:273:396 **1** ++++++++++++ [2256] r:0000000001CA1640 p:0000000001CA15F0 c:00007F95F5976280 while sending request to up
2015/02/17 16:27:53 [error] 3537#0: *381 finalize_request:2257:273:396 **1** || RC 404 || r:0000000001CA1640 p:0000000001CA15F0 c:00007F95F5976280 while sending request to upstream,
2015/02/17 16:27:53 [error] 3537#0: *381 finalize_request:2256:273:396 **2** ++++++++++++ [2256] r:0000000001CA1640 p:0000000001CA15F0 c:00007F95F5976280 while sending request to up
2015/02/17 16:27:53 [error] 3537#0: *381 finalize_request:2257:273:396 **2** || RC 0 || r:0000000001CA1640 p:0000000001CA15F0 c:00007F95F5976280 while sending request to upstream, c
2015/02/17 16:27:53 [error] 3537#0: *381 ngx_http_finalize_connection:2524:273:396 **1** ++++++++++++ [2524] r:0000000001CA1640 p:0000000001CA15F0 c:00007F95F5976280 while sending r
2015/02/17 16:27:53 [error] 3537#0: *381 ngx_http_set_keepalive:2868:273:396 **1** ++++++++++++ [2868] r:0000000001CA1640 p:0000000001CA15F0 c:00007F95F5976280 while sending request
2015/02/17 16:27:53 [error] 3537#0: *381 ngx_http_free_request:3468:273:396 **1** ++++++++++++ [3468] r:0000000001CA1640 p:0000000001CA15F0 c:00007F95F5976280 while closing request,
2015/02/17 16:27:53 [alert] 3537#0: *381 +++ handler 000000000043F237 0000000001CA1640 +++ while closing request, client: 127.0.0.1, server: localhost, request: "GET /web800fo/ HTTP
2015/02/17 16:27:53 [error] 3537#0: *381 ngx_http_upstream_cleanup:3730:273:396 **1** ++++++++++++ [3730] r:0000000001CA1640 p:0000000001CA15F0 c:00007F95F5976280 while closing requ
2015/02/17 16:27:53 [error] 3537#0: *381 ngx_http_upstream_finalize_request:3745:273:396 **59** ++++++++++++ [3745] r:0000000001CA1640 p:0000000001CA15F0 c:00007F95F5976280 while cl
2015/02/17 16:27:53 [error] 3537#0: *381 ngx_http_upstream_finalize_request:3768:273:396 **59** || +++ U->FINALIZE|| r:0000000001CA1640 p:0000000001CA15F0 c:00007F95F5976280 while c
2015/02/17 16:27:53 [error] 3537#0: *381 ngx_http_upstream_finalize_request:3770:273:396 **59** || --- U->FINALIZE|| r:0000000001CA1640 p:0000000001CA15F0 c:00007F95F5976280 while c
2015/02/17 16:27:53 [error] 3537#0: *381 ngx_http_upstream_finalize_request:3867:273:396 **59** || +++ HEADER SENT +++|| r:0000000001CA1640 p:0000000001CA15F0 c:00007F95F5976280 whi
2015/02/17 16:27:53 [error] 3537#0: *381 finalize_request:2256:273:396 **3** ++++++++++++ [2256] r:0000000001CA1640 p:0000000001CA15F0 c:00007F95F5976280 while sending to client, cl
2015/02/17 16:27:53 [error] 3537#0: *381 finalize_request:2257:273:396 **3** || RC -4 || r:0000000001CA1640 p:0000000001CA15F0 c:00007F95F5976280 while sending to client, client: 12
2015/02/17 16:27:53 [error] 3537#0: *381 ngx_http_finalize_connection:2524:273:396 **2** ++++++++++++ [2524] r:0000000001CA1640 p:0000000001CA15F0 c:00007F95F5976280 while sending t
2015/02/17 16:27:53 [error] 3537#0: *381 ngx_http_set_lingering_close:3235:273:396 **1** ++++++++++++ [3235] r:0000000001CA1640 p:0000000001CA15F0 c:00007F95F5976280 while sending t
2015/02/17 16:27:53 [error] 3537#0: *381 ngx_http_close_request:3427:273:396 **1** ++++++++++++ [3427] r:0000000001CA1640 p:0000000001CA15F0 c:00007F95F5976280 while sending to clie
2015/02/17 16:27:53 [error] 3537#0: *381 ngx_http_free_request:3468:273:396 **2** ++++++++++++ [3468] r:0000000001CA1640 p:0000000001CA15F0 c:00007F95F5976280 while sending to clien
2015/02/17 16:27:53 [error] 3537#0: *381 ngx_http_free_request:3509:273:396 **2** || +++ LOG REQUEST|| r:0000000001CA1640 p:0000000001CA15F0 c:00007F95F5976280 while logging request
2015/02/17 16:27:53 [error] 3537#0: *381 ngx_http_log_request:3558:273:396 **1** ++++++++++++ [3558] r:0000000001CA1640 p:0000000001CA15F0 c:00007F95F5976280 while logging request,
2015/02/17 16:27:53 [error] 3537#0: *381 ngx_http_log_request:3558:273:396 **1** ------------ [3567] r:0000000001CA1640 p:0000000001CA15F0 c:00007F95F5976280 while logging request,
2015/02/17 16:27:53 [error] 3537#0: *381 ngx_http_free_request:3511:273:396 **2** || --- LOG REQUEST|| r:0000000001CA1640 p:0000000001CA15F0 c:00007F95F5976280 while logging request
2015/02/17 16:27:53 [error] 3537#0: *381 ngx_http_free_request:3468:273:396 **2** ------------ [3548] r:0000000001CA1640 p:0000000000000000 c:00007F95F5976280 while closing request,
2015/02/17 16:27:53 [error] 3537#0: *381 ***** CLOSE CONN while closing request, client: 127.0.0.1, server: 0.0.0.0:8089
2015/02/17 16:27:53 [error] 3537#0: *381 ngx_http_close_request:3427:273:396 **1** ------------ [3455] r:0000000001CA1640 p:0000000000000000 c:00007F95F5976280 while closing request
2015/02/17 16:27:53 [error] 3537#0: *381 ngx_http_set_lingering_close:3235:273:396 **1** ------------ [3274] r:0000000001CA1640 p:0000000000000000 c:00007F95F5976280 while closing r
2015/02/17 16:27:53 [error] 3537#0: *381 ngx_http_finalize_connection:2524:273:396 **2** ------------ [2571] r:0000000001CA1640 p:0000000000000000 c:00007F95F5976280 while closing r
2015/02/17 16:27:53 [error] 3537#0: *381 finalize_request:2256:273:396 **3** ------------ [2267] r:0000000001CA1640 p:0000000000000000 c:00007F95F5976280 while closing request, clie
2015/02/17 16:27:53 [error] 3537#0: *381 ngx_http_upstream_finalize_request:3869:273:396 **59** || --- HEADER SENT ---|| r:0000000001CA1640 p:0000000000000000 c:00007F95F5976280 whi
2015/02/17 16:27:53 [error] 3537#0: *381 ngx_http_upstream_cleanup:3730:273:396 **1** ------------ [3735] r:0000000001CA1640 p:0000000000000000 c:00007F95F5976280 while closing requ
2015/02/17 16:27:53 [alert] 3537#0: *381 --- handler 0000000000000000 0000000001CA1640 --- while closing request, client: 127.0.0.1, server: 0.0.0.0:8089
2015/02/17 16:27:53 [error] 3537#0: *381 ngx_http_free_request:3509:273:396 **1** || +++ LOG REQUEST|| r:0000000001CA1640 p:0000000000000000 c:00007F95F5976280 while logging request
2015/02/17 16:27:53 [error] 3537#0: *381 ngx_http_log_request:3558:273:396 **1** ++++++++++++ [3558] r:0000000001CA1640 p:0000000000000000 c:00007F95F5976280 while logging request