Nginx 0.8.45-0.8.49 segfault bug

url may cause nginx work process crash
the code in src/http/ngx_http_request.c:ngx_http_free_request
r->upstream may be a NULL pointer

#0 0x000000000042b368 in ngx_http_free_request (r=0x13b60c20, rc=0) at
src/http/ngx_http_request.c:2951
2951 switch (r->upstream->cache_status) {
(gdb) bt
#0 0x000000000042b368 in ngx_http_free_request (r=0x13b60c20, rc=0) at
src/http/ngx_http_request.c:2951
#1 0x000000000042b5d1 in ngx_http_close_request (r=, rc=0) at
src/http/ngx_http_request.c:2910
#2 0x000000000042de75 in ngx_http_finalize_connection (r=0x13b60c20) at
src/http/ngx_http_request.c:2145
#3 0x000000000042e4a1 in ngx_http_finalize_request (r=, rc=)
at src/http/ngx_http_request.c:2045
#4 0x000000000042e12c in ngx_http_finalize_request (r=0x13b60c20,
rc=400) at src/http/ngx_http_request.c:1929
#5 0x000000000042f97e in ngx_http_process_request_line (rev=0x13b740a8)
at src/http/ngx_http_request.c:900
#6 0x0000000000421583 in ngx_epoll_process_events (cycle=0x13b56b90,
timer=, flags=)
at src/event/modules/ngx_epoll_module.c:642
#7 0x0000000000419038 in ngx_process_events_and_timers
(cycle=0x13b56b90) at src/event/ngx_event.c:261
#8 0x000000000041ef50 in ngx_single_process_cycle (cycle=0x13b56b90) at
src/os/unix/ngx_process_cycle.c:306
#9 0x000000000040473b in main (argc=16, argv=0x13b560a0) at
src/core/nginx.c:393

Posted at Nginx Forum:

Hello!

On Wed, Sep 01, 2010 at 07:59:54AM -0400, zhijianpeng wrote:

url may cause nginx work process crash
the code in src/http/ngx_http_request.c:ngx_http_free_request
r->upstream may be a NULL pointer

#0 0x000000000042b368 in ngx_http_free_request (r=0x13b60c20, rc=0) at
src/http/ngx_http_request.c:2951
2951 switch (r->upstream->cache_status) {

There is no such code in nginx 0.8.49. Looks like you are
running with some third-party or local patches.

Maxim D.

Hello!

On Wed, Sep 01, 2010 at 09:10:45AM -0400, zhijianpeng wrote:

And in 0.8.49

Core was generated by `sbin/nginx -c conf/nginx.conf’.
Program terminated with signal 11, Segmentation fault.
[New process 20862]
#0 ngx_http_terminate_request (r=0x180dac00, rc=400) at
src/http/ngx_http_request.c:2073
2073 cln = cln->next;

This looks better, but indicate that somebody smashed cleanup
chain in request cleanup handler. This may be easily caused by
modules (not even talking about patches).

If you are able to reproduce the problem without third party /
local patches and modules - please provide more details, i.e.
debug log and config to reproduce the problem.

See here for details:

http://wiki.nginx.org/NginxDebugging

Maxim D.

And in 0.8.49

Core was generated by `sbin/nginx -c conf/nginx.conf’.
Program terminated with signal 11, Segmentation fault.
[New process 20862]
#0 ngx_http_terminate_request (r=0x180dac00, rc=400) at
src/http/ngx_http_request.c:2073
2073 cln = cln->next;
(gdb) n
The program is not being run.
(gdb) n
The program is not being run.
(gdb) n
The program is not being run.
(gdb) bt
#0 ngx_http_terminate_request (r=0x180dac00, rc=400) at
src/http/ngx_http_request.c:2073
#1 0x000000000042e033 in ngx_http_finalize_request (r=0x180dac00,
rc=400) at src/http/ngx_http_request.c:1903
#2 0x0000000000434bad in ngx_http_read_client_request_body_handler
(r=0x180dac00) at src/http/ngx_http_request_body.c:254
#3 0x000000000042b348 in ngx_http_request_handler (ev=0x180f2fb8) at
src/http/ngx_http_request.c:1791
#4 0x0000000000421533 in ngx_epoll_process_events (cycle=0x180d0b80,
timer=, flags=)
at src/event/modules/ngx_epoll_module.c:642
#5 0x0000000000418fe2 in ngx_process_events_and_timers
(cycle=0x180d0b80) at src/event/ngx_event.c:245
#6 0x000000000041ef00 in ngx_single_process_cycle (cycle=0x180d0b80) at
src/os/unix/ngx_process_cycle.c:306
#7 0x000000000040473b in main (argc=16, argv=0x180d00a0) at
src/core/nginx.c:393
(gdb) quit

Posted at Nginx Forum:

Maxim D. Wrote:


nginx mailing list
[email protected]
nginx Info Page

It is the code of 0.8.47,and i have no third-party or local patches

Posted at Nginx Forum:

Hello!

On Wed, Sep 01, 2010 at 10:11:31AM -0400, zhijianpeng wrote:

r->upstream may be a NULL pointer

It is the code of 0.8.47,and i have no third-party or local patches

There is no such code in 0.8.47 either. Line 2951 in
ngx_http_request.c as of 0.8.47 looks like:

if (rc > 0 && (r->headers_out.status == 0 || r->connection->sent == 

0)) {

and there is no “switch (r->upstream->cache_status)” statement in
the whole nginx source code (and never been, in all versions).

Maxim D.

Sorry,I forgot about that my friend patch 0.8.47 for me.

Let’s forget about it, and 0.8.49 is clean
here is my conf:

#user  nobody;
worker_processes  1;

#daemon off;
#master_process off;

#error_log  logs/error.log;
#error_log  logs/error.log  notice;
error_log  logs/error.log  debug;

#pid        logs/nginx.pid;


events {
    worker_connections  1024;
}


http {
        [b]client_header_buffer_size       8k;[/b]


    server {
        listen       80;
        server_name  localhost;
        root    /opt/www;
        [b]proxy_ignore_client_abort       on;[/b]

        location / {
                        proxy_pass http://81.19.68.137;

                }

        }

}

and my test shell:

# telnet localhost 80
Trying 127.0.0.1...
Connected to localhost.localdomain (127.0.0.1).
Escape character is '^]'.
[b]POST /aa/bb HTTP/1.1
Host: www.nginx.net
Content-Length: 5

aa=11[/b]
[color=#FF0000][b]Connection closed by foreign host.[/b][/color]

and the debug log

2010/09/02 00:14:51 [debug] 15807#0: epoll: fd:6 ev:0001
d:00002B77E3EDC010
2010/09/02 00:14:51 [debug] 15807#0: accept on 0.0.0.0:80, ready: 0
2010/09/02 00:14:51 [debug] 15807#0: posix_memalign:
000000001025AF10:256 @16
2010/09/02 00:14:51 [debug] 15807#0: *3 accept: 127.0.0.1 fd:3
2010/09/02 00:14:51 [debug] 15807#0: *3 event timer add: 3:
60000:1283357751685
2010/09/02 00:14:51 [debug] 15807#0: *3 epoll add event: fd:3 op:1
ev:80000001
2010/09/02 00:14:51 [debug] 15807#0: timer delta: 18645
2010/09/02 00:14:51 [debug] 15807#0: posted events 0000000000000000
2010/09/02 00:14:51 [debug] 15807#0: worker cycle
2010/09/02 00:14:51 [debug] 15807#0: epoll timer: 60000
2010/09/02 00:14:52 [debug] 15807#0: epoll: fd:3 ev:0001
d:00002B77E3EDC160
2010/09/02 00:14:52 [debug] 15807#0: *3 malloc: 000000001025D300:1248
2010/09/02 00:14:52 [debug] 15807#0: *3 posix_memalign:
0000000010252360:256 @16
2010/09/02 00:14:52 [debug] 15807#0: *3 malloc: 0000000010256AF0:8192
2010/09/02 00:14:52 [debug] 15807#0: *3 posix_memalign:
000000001025D7F0:4096 @16
2010/09/02 00:14:52 [debug] 15807#0: *3 http process request line
2010/09/02 00:14:52 [debug] 15807#0: *3 recv: fd:3 22 of 8192
2010/09/02 00:14:52 [debug] 15807#0: *3 http request line: "POST /aa/bb
HTTP/1.1"
2010/09/02 00:14:52 [debug] 15807#0: *3 http uri: "/aa/bb"
2010/09/02 00:14:52 [debug] 15807#0: *3 http args: ""
2010/09/02 00:14:52 [debug] 15807#0: *3 http exten: ""
2010/09/02 00:14:52 [debug] 15807#0: *3 http process request header
line
2010/09/02 00:14:52 [debug] 15807#0: *3 recv: fd:3 -1 of 8170
2010/09/02 00:14:52 [debug] 15807#0: *3 recv() not ready (11: Resource
temporarily unavailable)
2010/09/02 00:14:52 [debug] 15807#0: timer delta: 651
2010/09/02 00:14:52 [debug] 15807#0: posted events 0000000000000000
2010/09/02 00:14:52 [debug] 15807#0: worker cycle
2010/09/02 00:14:52 [debug] 15807#0: epoll timer: 59349
2010/09/02 00:14:52 [debug] 15807#0: epoll: fd:3 ev:0001
d:00002B77E3EDC160
2010/09/02 00:14:52 [debug] 15807#0: *3 http process request header
line
2010/09/02 00:14:52 [debug] 15807#0: *3 recv: fd:3 21 of 8170
2010/09/02 00:14:52 [debug] 15807#0: *3 http header: "Host:
www.nginx.net"
2010/09/02 00:14:52 [debug] 15807#0: *3 recv: fd:3 -1 of 8149
2010/09/02 00:14:52 [debug] 15807#0: *3 recv() not ready (11: Resource
temporarily unavailable)
2010/09/02 00:14:52 [debug] 15807#0: timer delta: 6
2010/09/02 00:14:52 [debug] 15807#0: posted events 0000000000000000
2010/09/02 00:14:52 [debug] 15807#0: worker cycle
2010/09/02 00:14:52 [debug] 15807#0: epoll timer: 59343
2010/09/02 00:14:52 [debug] 15807#0: epoll: fd:3 ev:0001
d:00002B77E3EDC160
2010/09/02 00:14:52 [debug] 15807#0: *3 http process request header
line
2010/09/02 00:14:52 [debug] 15807#0: *3 recv: fd:3 19 of 8149
2010/09/02 00:14:52 [debug] 15807#0: *3 http header: "Content-Length:
5"
2010/09/02 00:14:52 [debug] 15807#0: *3 recv: fd:3 -1 of 8130
2010/09/02 00:14:52 [debug] 15807#0: *3 recv() not ready (11: Resource
temporarily unavailable)
2010/09/02 00:14:52 [debug] 15807#0: timer delta: 4
2010/09/02 00:14:52 [debug] 15807#0: posted events 0000000000000000
2010/09/02 00:14:52 [debug] 15807#0: worker cycle
2010/09/02 00:14:52 [debug] 15807#0: epoll timer: 59339
2010/09/02 00:14:52 [debug] 15807#0: epoll: fd:3 ev:0001
d:00002B77E3EDC160
2010/09/02 00:14:52 [debug] 15807#0: *3 http process request header
line
2010/09/02 00:14:52 [debug] 15807#0: *3 recv: fd:3 2 of 8130
2010/09/02 00:14:52 [debug] 15807#0: *3 http header done
2010/09/02 00:14:52 [debug] 15807#0: *3 event timer del: 3:
1283357751685
2010/09/02 00:14:52 [debug] 15807#0: *3 rewrite phase: 0
2010/09/02 00:14:52 [debug] 15807#0: *3 test location: "/"
2010/09/02 00:14:52 [debug] 15807#0: *3 using configuration "/"
2010/09/02 00:14:52 [debug] 15807#0: *3 http cl:5 max:1048576
2010/09/02 00:14:52 [debug] 15807#0: *3 rewrite phase: 2
2010/09/02 00:14:52 [debug] 15807#0: *3 post rewrite phase: 3
2010/09/02 00:14:52 [debug] 15807#0: *3 generic phase: 4
2010/09/02 00:14:52 [debug] 15807#0: *3 generic phase: 5
2010/09/02 00:14:52 [debug] 15807#0: *3 access phase: 6
2010/09/02 00:14:52 [debug] 15807#0: *3 access phase: 7
2010/09/02 00:14:52 [debug] 15807#0: *3 post access phase: 8
2010/09/02 00:14:52 [debug] 15807#0: *3 http read client request body
2010/09/02 00:14:52 [debug] 15807#0: *3 recv: fd:3 -1 of 5
2010/09/02 00:14:52 [debug] 15807#0: *3 recv() not ready (11: Resource
temporarily unavailable)
2010/09/02 00:14:52 [debug] 15807#0: *3 http client request body recv
-2
2010/09/02 00:14:52 [debug] 15807#0: *3 http client request body rest 5
2010/09/02 00:14:52 [debug] 15807#0: *3 event timer add: 3:
60000:1283357752356
2010/09/02 00:14:52 [debug] 15807#0: *3 http finalize request: -4,
"/aa/bb?" a:1, c:2
2010/09/02 00:14:52 [debug] 15807#0: *3 http request count:2 blk:0
2010/09/02 00:14:52 [debug] 15807#0: timer delta: 10
2010/09/02 00:14:52 [debug] 15807#0: posted events 0000000000000000
2010/09/02 00:14:52 [debug] 15807#0: worker cycle
2010/09/02 00:14:52 [debug] 15807#0: epoll timer: 60000
2010/09/02 00:14:53 [debug] 15807#0: epoll: fd:3 ev:0001
d:00002B77E3EDC160
2010/09/02 00:14:53 [debug] 15807#0: *3 http run request: "/aa/bb?"
2010/09/02 00:14:53 [debug] 15807#0: *3 http read client request body
2010/09/02 00:14:53 [debug] 15807#0: *3 recv: fd:3 5 of 5
2010/09/02 00:14:53 [debug] 15807#0: *3 http client request body recv 5
2010/09/02 00:14:53 [debug] 15807#0: *3 http client request body rest 0
2010/09/02 00:14:53 [debug] 15807#0: *3 event timer del: 3:
1283357752356
2010/09/02 00:14:53 [debug] 15807#0: *3 http init upstream, client
timer: 0
2010/09/02 00:14:53 [debug] 15807#0: *3 epoll add event: fd:3 op:3
ev:80000005
2010/09/02 00:14:53 [debug] 15807#0: *3 http script copy: "Host: "
2010/09/02 00:14:53 [debug] 15807#0: *3 http script var: "81.19.68.137"
2010/09/02 00:14:53 [debug] 15807#0: *3 http script copy: "
"
2010/09/02 00:14:53 [debug] 15807#0: *3 http script copy: "Connection:
close
"
2010/09/02 00:14:53 [debug] 15807#0: *3 http proxy header:
"Content-Length: 5"
2010/09/02 00:14:53 [debug] 15807#0: *3 http proxy header:
"POST /aa/bb HTTP/1.0
Host: 81.19.68.137
Connection: close
Content-Length: 5

"
2010/09/02 00:14:53 [debug] 15807#0: *3 posix_memalign:
0000000010258B00:4096 @16
2010/09/02 00:14:53 [debug] 15807#0: *3 http cleanup add:
0000000010258B80
2010/09/02 00:14:53 [debug] 15807#0: *3 get rr peer, try: 1
2010/09/02 00:14:53 [debug] 15807#0: *3 socket 9
2010/09/02 00:14:53 [debug] 15807#0: *3 epoll add connection: fd:9
ev:80000005
2010/09/02 00:14:53 [debug] 15807#0: *3 connect to 81.19.68.137:80, fd:9
#4
2010/09/02 00:14:53 [debug] 15807#0: *3 http upstream connect: -2
2010/09/02 00:14:53 [debug] 15807#0: *3 event timer add: 9:
60000:1283357753347
2010/09/02 00:14:53 [debug] 15807#0: timer delta: 991
2010/09/02 00:14:53 [debug] 15807#0: posted events 0000000000000000
2010/09/02 00:14:53 [debug] 15807#0: worker cycle
2010/09/02 00:14:53 [debug] 15807#0: epoll timer: 60000
2010/09/02 00:14:53 [debug] 15807#0: epoll: fd:3 ev:0005
d:00002B77E3EDC160
2010/09/02 00:14:53 [debug] 15807#0: *3 http run request: "/aa/bb?"
2010/09/02 00:14:53 [debug] 15807#0: *3 http read client request body
2010/09/02 00:14:53 [debug] 15807#0: *3 add cleanup: 0000000010258CE0
2010/09/02 00:14:53 [debug] 15807#0: *3 hashed path:
/opt/itc/vmsnginx/client_body_temp/0000000002
2010/09/02 00:14:53 [debug] 15807#0: *3 temp fd:10
2010/09/02 00:14:53 [warn] 15807#0: *3 a client request body is buffered
to a temporary file /opt/itc/vmsnginx/client_body_temp/0000000002 while
connecting to upstream, client: 127.0.0.1, server: localhost, request:
"POST /aa/bb HTTP/1.1", upstream: "http://81.19.68.137:80/aa/bb", host:
"www.nginx.net"
2010/09/02 00:14:53 [debug] 15807#0: *3 write: 10, 000000001025E6B0, 5,
0
2010/09/02 00:14:53 [debug] 15807#0: *3 recv: fd:3 0 of 0
2010/09/02 00:14:53 [debug] 15807#0: *3 http client request body recv 0
2010/09/02 00:14:53 [info] 15807#0: *3 client closed prematurely
connection while connecting to upstream, client: 127.0.0.1, server:
localhost, request: "POST /aa/bb HTTP/1.1", upstream:
"http://81.19.68.137:80/aa/bb", host: "www.nginx.net"
2010/09/02 00:14:53 [debug] 15807#0: *3 http finalize request: 400,
"/aa/bb?" a:1, c:1
2010/09/02 00:14:53 [debug] 15807#0: *3 http terminate request count:1
2010/09/02 00:14:53 [debug] 15807#0: *3 cleanup http upstream request:
"/aa/bb"
2010/09/02 00:14:53 [debug] 15807#0: *3 finalize http upstream request:
-4
2010/09/02 00:14:53 [debug] 15807#0: *3 finalize http proxy request
2010/09/02 00:14:53 [debug] 15807#0: *3 free rr peer 1 0
2010/09/02 00:14:53 [debug] 15807#0: *3 close http upstream connection:
9
2010/09/02 00:14:53 [debug] 15807#0: *3 event timer del: 9:
1283357753347
2010/09/02 00:14:53 [debug] 15807#0: *3 http finalize request: -4,
"/aa/bb?" a:1, c:1
2010/09/02 00:14:53 [debug] 15807#0: *3 set http keepalive handler
2010/09/02 00:14:53 [debug] 15807#0: *3 http close request
2010/09/02 00:14:53 [debug] 15807#0: *3 http log handler
2010/09/02 00:14:53 [debug] 15807#0: *3 run cleanup: 0000000010258CE0
2010/09/02 00:14:53 [debug] 15807#0: *3 file cleanup: fd:10
2010/09/02 00:14:53 [debug] 15807#0: *3 free: 000000001025D7F0, unused:
16
2010/09/02 00:14:53 [debug] 15807#0: *3 free: 0000000010258B00, unused:
3469
2010/09/02 00:14:53 [debug] 15807#0: *3 event timer add: 3:
75000:1283357768347
2010/09/02 00:14:53 [debug] 15807#0: *3 free: 000000001025D300
2010/09/02 00:14:53 [debug] 15807#0: *3 free: 0000000010256AF0
2010/09/02 00:14:53 [debug] 15807#0: *3 hc free: 0000000000000000 0
2010/09/02 00:14:53 [debug] 15807#0: *3 hc busy: 0000000000000000 0
2010/09/02 00:14:53 [debug] 15807#0: *3 tcp_nodelay
[b][color=#FF0000]2010/09/02 00:14:53 [notice] 15803#0: signal 17
(SIGCHLD) received
2010/09/02 00:14:53 [alert] 15803#0: worker process 15807 exited on
signal 11[/color][/b]
2010/09/02 00:14:53 [debug] 15803#0: wake up, sigio 0
2010/09/02 00:14:53 [debug] 15803#0: reap children
2010/09/02 00:14:53 [debug] 15803#0: child: 0 15807 e:0 t:1 d:0 r:1 j:0
2010/09/02 00:14:53 [debug] 15803#0: channel 3:7
2010/09/02 00:14:53 [debug] 15811#0: malloc: 000000001025BAF0:6144
2010/09/02 00:14:53 [debug] 15811#0: malloc: 00002B77E3EDC010:172032
2010/09/02 00:14:53 [debug] 15811#0: malloc: 000000001026A8D0:106496
2010/09/02 00:14:53 [debug] 15811#0: malloc: 00000000102848E0:106496
2010/09/02 00:14:53 [debug] 15811#0: epoll add event: fd:6 op:1
ev:00000001
2010/09/02 00:14:53 [debug] 15811#0: epoll add event: fd:7 op:1
ev:00000001
2010/09/02 00:14:53 [debug] 15811#0: setproctitle: "nginx: worker
process"
2010/09/02 00:14:53 [debug] 15811#0: worker cycle
2010/09/02 00:14:53 [debug] 15811#0: epoll timer: -1
2010/09/02 00:14:53 [notice] 15803#0: start worker process 15811
2010/09/02 00:14:53 [debug] 15803#0: sigsuspend

Posted at Nginx Forum:

In my case

[root@aqjh ~]# cat /etc/redhat-release
Red Hat Enterprise Linux AS release 4 (Nahant Update 5)
[root@aqjh ~]# /opt/work/nginx/sbin/nginx -V
nginx version: nginx/0.8.49
built by gcc 3.4.6 20060404 (Red Hat 3.4.6-8)
configure arguments: --prefix=/opt/work/nginx
[root@aqjh ~]#

nginx always crashes when configure

request_pool_size               1024k;

under request

[root@aqjh ~]# telnet 0 80
Trying 0.0.0.0...
Connected to 0 (0.0.0.0).
Escape character is '^]'.
POST /aa/bb HTTP/1.1
Host: www.nginx.net
Content-Length: 5

aa=11
Connection closed by foreign host.
[root@aqjh ~]#

with arbitrary Host header

Posted at Nginx Forum:

Hello!

On Wed, Sep 01, 2010 at 12:19:55PM -0400, zhijianpeng wrote:

Sorry,I forgot about that my friend patch 0.8.47 for me.

Let’s forget about it, and 0.8.49 is clean

[…]

    [b]proxy_ignore_client_abort       on;[/b]

[…]

d:00002B77E3EDC160
www.nginx.net
2010/09/02 00:14:53 [debug] 15807#0: *3 write: 10, 000000001025E6B0, 5,
0
2010/09/02 00:14:53 [debug] 15807#0: *3 recv: fd:3 0 of 0
2010/09/02 00:14:53 [debug] 15807#0: *3 http client request body recv 0
2010/09/02 00:14:53 [info] 15807#0: *3 client closed prematurely
connection while connecting to upstream, client: 127.0.0.1, server:
localhost, request: “POST /aa/bb HTTP/1.1”, upstream:
http://81.19.68.137:80/aa/bb”, host: “www.nginx.net
2010/09/02 00:14:53 [debug] 15807#0: *3 http finalize request: 400,
“/aa/bb?” a:1, c:1

[…]

This seems to be (somewhat known) issue with
“proxy_ignore_client_abort on;” and requests with body. It
doesn’t modify request handlers correctly (don’t clear request
body read handler if one was set) and this may cause unexpected
behaviour.

I’ll take a look at this more closely later. Thanks for your
debugging.

Maxim D.

Hello!

On Mon, Sep 06, 2010 at 02:55:41PM +0400, Igor S. wrote:

On Wed, Sep 01, 2010 at 10:18:26PM +0400, Maxim D. wrote:

Hello!

On Wed, Sep 01, 2010 at 12:19:55PM -0400, zhijianpeng wrote:

Sorry,I forgot about that my friend patch 0.8.47 for me.

Let’s forget about it, and 0.8.49 is clean

[…]

    [b]proxy_ignore_client_abort       on;[/b]

[…]

2010/09/02 00:14:53 [debug] 15807#0: *3 connect to 81.19.68.137:80, fd:9
#4
2010/09/02 00:14:53 [debug] 15807#0: *3 http upstream connect: -2
2010/09/02 00:14:53 [debug] 15807#0: *3 event timer add: 9:
60000:1283357753347
2010/09/02 00:14:53 [debug] 15807#0: timer delta: 991
2010/09/02 00:14:53 [debug] 15807#0: posted events 0000000000000000
2010/09/02 00:14:53 [debug] 15807#0: worker cycle
2010/09/02 00:14:53 [debug] 15807#0: epoll timer: 60000
2010/09/02 00:14:53 [debug] 15807#0: epoll: fd:3 ev:0005
d:00002B77E3EDC160
2010/09/02 00:14:53 [debug] 15807#0: *3 http run request: “/aa/bb?”
2010/09/02 00:14:53 [debug] 15807#0: *3 http read client request body
2010/09/02 00:14:53 [debug] 15807#0: *3 add cleanup: 0000000010258CE0
2010/09/02 00:14:53 [debug] 15807#0: *3 hashed path:
/opt/itc/vmsnginx/client_body_temp/0000000002
2010/09/02 00:14:53 [debug] 15807#0: *3 temp fd:10
2010/09/02 00:14:53 [warn] 15807#0: *3 a client request body is buffered
to a temporary file /opt/itc/vmsnginx/client_body_temp/0000000002 while
connecting to upstream, client: 127.0.0.1, server: localhost, request:
“POST /aa/bb HTTP/1.1”, upstream: “http://81.19.68.137:80/aa/bb”, host:
www.nginx.net
2010/09/02 00:14:53 [debug] 15807#0: *3 write: 10, 000000001025E6B0, 5,
0
2010/09/02 00:14:53 [debug] 15807#0: *3 recv: fd:3 0 of 0
2010/09/02 00:14:53 [debug] 15807#0: *3 http client request body recv 0
2010/09/02 00:14:53 [info] 15807#0: *3 client closed prematurely
connection while connecting to upstream, client: 127.0.0.1, server:
localhost, request: “POST /aa/bb HTTP/1.1”, upstream:
http://81.19.68.137:80/aa/bb”, host: “www.nginx.net
2010/09/02 00:14:53 [debug] 15807#0: *3 http finalize request: 400,
“/aa/bb?” a:1, c:1

[…]

This seems to be (somewhat known) issue with
“proxy_ignore_client_abort on;” and requests with body. It
doesn’t modify request handlers correctly (don’t clear request
body read handler if one was set) and this may cause unexpected
behaviour.

I’ll take a look at this more closely later. Thanks for your
debugging.

I my test nginx run

2010/09/06 14:48:22 [debug] 25462#0: *1 http run request: “/aa/bb?”
2010/09/06 14:48:22 [debug] 25462#0: *1 http request empty handler

instead of

2010/09/02 00:14:53 [debug] 15807#0: *3 http run request: “/aa/bb?”
2010/09/02 00:14:53 [debug] 15807#0: *3 http read client request body

I believe here is some patch or something else.

The problem with proxy_ignore_client_abort (i.e. unexpected “read
client request body” with resulting finalize 400) is easily
reproduceable here (and was reported previously).

It is racy though: it needs read body handler to be set and fired
again due to other activity on client’s connection before request
to upstream was completed (note that in original report client
claims content length 5 but sends 5 bytes and newline). Hint: try
reproducing with unreachable upstream server.

I wasn’t able to reproduce SIGSEGV though, but this may be even
more racy or manifest itself only with particular event method.

Maxim D.

On Wed, Sep 01, 2010 at 10:18:26PM +0400, Maxim D. wrote:

Hello!

On Wed, Sep 01, 2010 at 12:19:55PM -0400, zhijianpeng wrote:

Sorry,I forgot about that my friend patch 0.8.47 for me.

Let’s forget about it, and 0.8.49 is clean

[…]

    [b]proxy_ignore_client_abort       on;[/b]

[…]

2010/09/02 00:14:53 [debug] 15807#0: *3 connect to 81.19.68.137:80, fd:9
#4
2010/09/02 00:14:53 [debug] 15807#0: *3 http upstream connect: -2
2010/09/02 00:14:53 [debug] 15807#0: *3 event timer add: 9:
60000:1283357753347
2010/09/02 00:14:53 [debug] 15807#0: timer delta: 991
2010/09/02 00:14:53 [debug] 15807#0: posted events 0000000000000000
2010/09/02 00:14:53 [debug] 15807#0: worker cycle
2010/09/02 00:14:53 [debug] 15807#0: epoll timer: 60000
2010/09/02 00:14:53 [debug] 15807#0: epoll: fd:3 ev:0005
d:00002B77E3EDC160
2010/09/02 00:14:53 [debug] 15807#0: *3 http run request: “/aa/bb?”
2010/09/02 00:14:53 [debug] 15807#0: *3 http read client request body
2010/09/02 00:14:53 [debug] 15807#0: *3 add cleanup: 0000000010258CE0
2010/09/02 00:14:53 [debug] 15807#0: *3 hashed path:
/opt/itc/vmsnginx/client_body_temp/0000000002
2010/09/02 00:14:53 [debug] 15807#0: *3 temp fd:10
2010/09/02 00:14:53 [warn] 15807#0: *3 a client request body is buffered
to a temporary file /opt/itc/vmsnginx/client_body_temp/0000000002 while
connecting to upstream, client: 127.0.0.1, server: localhost, request:
“POST /aa/bb HTTP/1.1”, upstream: “http://81.19.68.137:80/aa/bb”, host:
www.nginx.net
2010/09/02 00:14:53 [debug] 15807#0: *3 write: 10, 000000001025E6B0, 5,
0
2010/09/02 00:14:53 [debug] 15807#0: *3 recv: fd:3 0 of 0
2010/09/02 00:14:53 [debug] 15807#0: *3 http client request body recv 0
2010/09/02 00:14:53 [info] 15807#0: *3 client closed prematurely
connection while connecting to upstream, client: 127.0.0.1, server:
localhost, request: “POST /aa/bb HTTP/1.1”, upstream:
http://81.19.68.137:80/aa/bb”, host: “www.nginx.net
2010/09/02 00:14:53 [debug] 15807#0: *3 http finalize request: 400,
“/aa/bb?” a:1, c:1

[…]

This seems to be (somewhat known) issue with
“proxy_ignore_client_abort on;” and requests with body. It
doesn’t modify request handlers correctly (don’t clear request
body read handler if one was set) and this may cause unexpected
behaviour.

I’ll take a look at this more closely later. Thanks for your
debugging.

I my test nginx run

2010/09/06 14:48:22 [debug] 25462#0: *1 http run request: “/aa/bb?”
2010/09/06 14:48:22 [debug] 25462#0: *1 http request empty handler

instead of

2010/09/02 00:14:53 [debug] 15807#0: *3 http run request: “/aa/bb?”
2010/09/02 00:14:53 [debug] 15807#0: *3 http read client request body

I believe here is some patch or something else.


Igor S.
http://sysoev.ru/en/