Proxying request - HTTP/1.1 502 Bad Gateway

Tue Aug 9 06:12:19 UTC 2011

Hello,
we have problem with proxying some RPC (POST) requests to a backend
server. 
When a request is sent without proxy to the backend directly everrything
is OK. So problem is probably caused by nginx proxy.
When the request is sent from the same server as proxy is installed,
response is allways OK as well.
The problem occurs just when a method with many parameters is called
(large POST request). And the strangest thing is that the same request
is sometimes OK and sometimes produces 502 Bad Gateway.

A part of http section from nginx.conf:
    client_header_buffer_size 32k;
    large_client_header_buffers 4 64k;
    client_body_buffer_size 32k;
    proxy_buffer_size 32k;
    proxy_buffers 8 16k;
    proxy_busy_buffers_size 64k; 
    sendfile        on; 
    #tcp_nopush     on; 
    tcp_nodelay on;
    keepalive_timeout  5;
    keepalive_requests 50;
    server_tokens off

    proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;

and the location just:
        location ~ "^/public/RPC2$" {
            proxy_pass      http://localhost:3352;
        }

Part of debug log, when the request is not processed correctly:
2011/08/08 16:05:25 [debug] 23971#0: *218 post event 00002B69C5051350
2011/08/08 16:05:25 [debug] 23971#0: *218 post event 00002B69C51F2350
2011/08/08 16:05:25 [debug] 23971#0: *218 delete posted event
00002B69C51F2350
2011/08/08 16:05:25 [debug] 23971#0: *218 http upstream request:
"/public/RPC2?"
2011/08/08 16:05:25 [debug] 23971#0: *218 http upstream dummy handler
2011/08/08 16:05:25 [debug] 23971#0: *218 delete posted event
00002B69C5051350
2011/08/08 16:05:25 [debug] 23971#0: *218 http upstream request:
"/public/RPC2?"
2011/08/08 16:05:25 [debug] 23971#0: *218 http upstream process header
2011/08/08 16:05:25 [debug] 23971#0: *218 malloc:
000000001BC070A0:32768
2011/08/08 16:05:25 [debug] 23971#0: *218 recv: fd:48 0 of 32768
2011/08/08 16:05:25 [error] 23971#0: *218 upstream prematurely closed
connection while reading response header from upstream, client:
10.0.132.6, server: xxxxxxxxxxxx, request: "POST /public/RPC2 HTTP/1.1",
upstream: "http://127.0.0.1:3352/public/RPC2", host: "yyyyyyyyyyyyyy"
2011/08/08 16:05:25 [debug] 23971#0: *218 http next upstream, 2
2011/08/08 16:05:25 [debug] 23971#0: *218 free rr peer 1 4
2011/08/08 16:05:25 [debug] 23971#0: *218 finalize http upstream
request: 502
2011/08/08 16:05:25 [debug] 23971#0: *218 finalize http proxy request
2011/08/08 16:05:25 [debug] 23971#0: *218 free rr peer 0 0
2011/08/08 16:05:25 [debug] 23971#0: *218 close http upstream
connection: 48
2011/08/08 16:05:25 [debug] 23971#0: *218 event timer del: 48:
1312812380324
2011/08/08 16:05:25 [debug] 23971#0: *218 reusable connection: 0
2011/08/08 16:05:25 [debug] 23971#0: *218 http finalize request: 502,
"/public/RPC2?" a:1, c:2
2011/08/08 16:05:25 [debug] 23971#0: *218 http special response: 502,
"/public/RPC2?"
2011/08/08 16:05:25 [debug] 23971#0: *218 http set discard body
2011/08/08 16:05:25 [debug] 23971#0: *218 HTTP/1.1 502 Bad Gateway
Server: nginx
Date: Mon, 08 Aug 2011 14:05:25 GMT
Content-Type: text/html
Content-Length: 166
Connection: keep-alive

2011/08/08 16:05:25 [debug] 23971#0: *218 write new buf t:1 f:0
000000001BBAB4F0, pos 000000001BBAB4F0, size: 150 file: 0, size: 0
2011/08/08 16:05:25 [debug] 23971#0: *218 http write filter: l:0 f:0
s:150
2011/08/08 16:05:25 [debug] 23971#0: *218 http output filter
"/public/RPC2?"
2011/08/08 16:05:25 [debug] 23971#0: *218 http copy filter:
"/public/RPC2?"
2011/08/08 16:05:25 [debug] 23971#0: *218 write old buf t:1 f:0
000000001BBAB4F0, pos 000000001BBAB4F0, size: 150 file: 0, size: 0
2011/08/08 16:05:25 [debug] 23971#0: *218 write new buf t:0 f:0
0000000000000000, pos 000000000068C360, size: 120 file: 0, size: 0
2011/08/08 16:05:25 [debug] 23971#0: *218 write new buf t:0 f:0
0000000000000000, pos 000000000068B200, size: 46 file: 0, size: 0
2011/08/08 16:05:25 [debug] 23971#0: *218 http write filter: l:1 f:0
s:316
2011/08/08 16:05:25 [debug] 23971#0: *218 http write filter limit 0
2011/08/08 16:05:25 [debug] 23971#0: *218 writev: 316
2011/08/08 16:05:25 [debug] 23971#0: *218 http write filter
0000000000000000
2011/08/08 16:05:25 [debug] 23971#0: *218 http copy filter: 0
"/public/RPC2?"
2011/08/08 16:05:25 [debug] 23971#0: *218 http finalize request: 0,
"/public/RPC2?" a:1, c:2
2011/08/08 16:05:25 [debug] 23971#0: *218 http request count:2 blk:0
2011/08/08 16:05:25 [debug] 23971#0: *218 post event 00002B69C5051218
2011/08/08 16:05:25 [debug] 23971#0: *218 post event 00002B69C51F2218
2011/08/08 16:05:25 [debug] 23971#0: *218 delete posted event
00002B69C51F2218
2011/08/08 16:05:25 [debug] 23971#0: *218 http run request:
"/public/RPC2?"
2011/08/08 16:05:25 [debug] 23971#0: *218 http request empty handler
2011/08/08 16:05:25 [debug] 23971#0: *218 delete posted event
00002B69C5051218
2011/08/08 16:05:25 [debug] 23971#0: *218 http run request:
"/public/RPC2?"
2011/08/08 16:05:25 [debug] 23971#0: *218 http upstream check client,
write event:0, "/public/RPC2"
2011/08/08 16:05:25 [debug] 23971#0: *218 http upstream recv(): 1

Posted at Nginx Forum: http://forum.nginx.org/read.php?2,213552,213552#msg-213552