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 < [email protected]> 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 > >
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
_______________________________________________ nginx-devel mailing list [email protected] http://mailman.nginx.org/mailman/listinfo/nginx-devel
