Re: поведение error page

[reaper]

давно не повторялось, сейчас вот опять
началось :)

на клиенте вижу ответ
HTTP/1.1 504 Gateway Time-out

хотя в error_page прописано 503

2012/04/14 12:51:50 [debug] 11906#0: *3332442 event timer del: 6:
2968108478
2012/04/14 12:51:50 [debug] 11906#0: *3332442 generic phase: 0
2012/04/14 12:51:50 [debug] 11906#0: *3332442 rewrite phase: 1
2012/04/14 12:51:50 [debug] 11906#0: *3332442 http script var
2012/04/14 12:51:50 [debug] 11906#0: *3332442 http script var:
"my.fs.test"
2012/04/14 12:51:50 [debug] 11906#0: *3332442 http script value:
"fs.test"
2012/04/14 12:51:50 [debug] 11906#0: *3332442 http script equal
2012/04/14 12:51:50 [debug] 11906#0: *3332442 http script equal: no
2012/04/14 12:51:50 [debug] 11906#0: *3332442 http script if
2012/04/14 12:51:50 [debug] 11906#0: *3332442 http script if: false
2012/04/14 12:51:50 [debug] 11906#0: *3332442 test location: "/"
2012/04/14 12:51:50 [debug] 11906#0: *3332442 using configuration "/"
2012/04/14 12:51:50 [debug] 11906#0: *3332442 http cl:-1 max:104857600
2012/04/14 12:51:50 [debug] 11906#0: *3332442 rewrite phase: 3
2012/04/14 12:51:50 [debug] 11906#0: *3332442 post rewrite phase: 4
2012/04/14 12:51:50 [debug] 11906#0: *3332442 generic phase: 5
2012/04/14 12:51:50 [debug] 11906#0: *3332442 generic phase: 6
2012/04/14 12:51:50 [debug] 11906#0: *3332442 generic phase: 7
2012/04/14 12:51:50 [debug] 11906#0: *3332442 access phase: 8
2012/04/14 12:51:50 [debug] 11906#0: *3332442 access phase: 9
2012/04/14 12:51:50 [debug] 11906#0: *3332442 access phase: 10
2012/04/14 12:51:50 [debug] 11906#0: *3332442 post access phase: 11
2012/04/14 12:51:50 [debug] 11906#0: *3332442 try files phase: 12
2012/04/14 12:51:50 [debug] 11906#0: *3332442 http init upstream, client
timer: 0
2012/04/14 12:51:50 [debug] 11906#0: *3332442 epoll add event: fd:6 op:3
ev:80000005
2012/04/14 12:51:50 [debug] 11906#0: *3332442 http script copy: "Host:
www.fs.test
"
2012/04/14 12:51:50 [debug] 11906#0: *3332442 http script copy:
"X-Real-IP: "
2012/04/14 12:51:50 [debug] 11906#0: *3332442 http script var:
"192.168.98.15"
2012/04/14 12:51:50 [debug] 11906#0: *3332442 http script copy: "
"
2012/04/14 12:51:50 [debug] 11906#0: *3332442 http script copy:
"X-Forwarded-For: "
2012/04/14 12:51:50 [debug] 11906#0: *3332442 http script var:
"192.168.98.15"
2012/04/14 12:51:50 [debug] 11906#0: *3332442 http script copy: "
"
2012/04/14 12:51:50 [debug] 11906#0: *3332442 http script copy:
"Connection: close
"
2012/04/14 12:51:50 [debug] 11906#0: *3332442 http proxy header:
"User-Agent: curl/7.25.0 (i486-pc-linux-gnu) libcurl/7.25.0
OpenSSL/1.0.1 zlib/1.2.6 libidn/1.24 libssh2/1.4.0 librtmp/2.3"
2012/04/14 12:51:50 [debug] 11906#0: *3332442 http proxy header:
"Accept: */*"
2012/04/14 12:51:50 [debug] 11906#0: *3332442 http proxy header:
"GET /f/free+free+free+free HTTP/1.0
Host: www.fs.test
X-Real-IP: 192.168.98.15
X-Forwarded-For: 192.168.98.15
Connection: close
User-Agent: curl/7.25.0 (i486-pc-linux-gnu) libcurl/7.25.0 OpenSSL/1.0.1
zlib/1.2.6 libidn/1.24 libssh2/1.4.0 librtmp/2.3
Accept: */*

"
2012/04/14 12:51:50 [debug] 11906#0: *3332442 http cleanup add:
09D81310
2012/04/14 12:51:50 [debug] 11906#0: *3332442 get ip hash peer, try: 1
2012/04/14 12:51:50 [debug] 11906#0: *3332442 get rr peer, try: 1
2012/04/14 12:51:50 [debug] 11906#0: *3332442 socket 20
2012/04/14 12:51:50 [debug] 11906#0: *3332442 epoll add connection:
fd:20 ev:80000005
2012/04/14 12:51:50 [debug] 11906#0: *3332442 connect to
192.168.98.175:80, fd:20 #3332443
2012/04/14 12:51:50 [debug] 11906#0: *3332442 http upstream connect: -2
2012/04/14 12:51:50 [debug] 11906#0: *3332442 event timer add: 20:
20000:2968068479
2012/04/14 12:51:50 [debug] 11906#0: *3332442 http finalize request: -4,
"/f/free+free+free+free?" a:1, c:2
2012/04/14 12:51:50 [debug] 11906#0: *3332442 http request count:2
blk:0
2012/04/14 12:51:50 [debug] 11906#0: *3332442 post event 09DF11A0
2012/04/14 12:51:50 [debug] 11906#0: *3332442 delete posted event
09DF11A0
2012/04/14 12:51:50 [debug] 11906#0: *3332442 http run request:
"/f/free+free+free+free?"
2012/04/14 12:51:50 [debug] 11906#0: *3332442 http upstream check
client, write event:1, "/f/free+free+free+free"
2012/04/14 12:51:50 [debug] 11906#0: *3332442 http upstream recv(): -1
(11: Resource temporarily unavailable)
2012/04/14 12:51:50 [debug] 11906#0: *3332442 post event 09DF0918
2012/04/14 12:51:50 [debug] 11906#0: *3332442 delete posted event
09DF0918
2012/04/14 12:51:50 [debug] 11906#0: *3332442 http upstream request:
"/f/free+free+free+free?"
2012/04/14 12:51:50 [debug] 11906#0: *3332442 http upstream send request
handler
2012/04/14 12:51:50 [debug] 11906#0: *3332442 http upstream send
request
2012/04/14 12:51:50 [debug] 11906#0: *3332442 chain writer buf fl:1
s:280
2012/04/14 12:51:50 [debug] 11906#0: *3332442 chain writer in: 09D81338
2012/04/14 12:51:50 [debug] 11906#0: *3332442 writev: 280
2012/04/14 12:51:50 [debug] 11906#0: *3332442 chain writer out:
00000000
2012/04/14 12:51:50 [debug] 11906#0: *3332442 event timer del: 20:
2968068479
2012/04/14 12:51:50 [debug] 11906#0: *3332442 event timer add: 20:
20000:2968068480
2012/04/14 12:52:10 [debug] 11906#0: *3332442 event timer del: 20:
2968068480
2012/04/14 12:52:10 [debug] 11906#0: *3332442 http upstream request:
"/f/free+free+free+free?"
2012/04/14 12:52:10 [debug] 11906#0: *3332442 http upstream process
header
2012/04/14 12:52:10 [debug] 11906#0: *3332442 http next upstream, 4
2012/04/14 12:52:10 [debug] 11906#0: *3332442 free rr peer 1 4
2012/04/14 12:52:10 [error] 11906#0: *3332442 upstream timed out (110:
Connection timed out) while reading response header from upstream,
client: 192.168.98.15, server: my.fs.test, request: "GET
/f/free+free+free+free HTTP/1.1", upstream:
"http://192.168.98.175:80/f/free+free+free+free", host: "my.fs.test"
2012/04/14 12:52:10 [debug] 11906#0: *3332442 finalize http upstream
request: 504
2012/04/14 12:52:10 [debug] 11906#0: *3332442 finalize http proxy
request
2012/04/14 12:52:10 [debug] 11906#0: *3332442 free rr peer 0 0
2012/04/14 12:52:10 [debug] 11906#0: *3332442 close http upstream
connection: 20
2012/04/14 12:52:10 [debug] 11906#0: *3332442 reusable connection: 0
2012/04/14 12:52:10 [debug] 11906#0: *3332442 http finalize request:
504, "/f/free+free+free+free?" a:1, c:1
2012/04/14 12:52:10 [debug] 11906#0: *3332442 http special response:
504, "/f/free+free+free+free?"
2012/04/14 12:52:10 [debug] 11906#0: *3332442 internal redirect: "/?"
2012/04/14 12:52:10 [debug] 11906#0: *3332442 rewrite phase: 1
2012/04/14 12:52:10 [debug] 11906#0: *3332442 http script var
2012/04/14 12:52:10 [debug] 11906#0: *3332442 http script var:
"my.fs.test"
2012/04/14 12:52:10 [debug] 11906#0: *3332442 http script value:
"fs.test"
2012/04/14 12:52:10 [debug] 11906#0: *3332442 http script equal
2012/04/14 12:52:10 [debug] 11906#0: *3332442 http script equal: no
2012/04/14 12:52:10 [debug] 11906#0: *3332442 http script if
2012/04/14 12:52:10 [debug] 11906#0: *3332442 http script if: false
2012/04/14 12:52:10 [debug] 11906#0: *3332442 test location: "/"
2012/04/14 12:52:10 [debug] 11906#0: *3332442 using configuration "/"
2012/04/14 12:52:10 [debug] 11906#0: *3332442 http cl:-1 max:104857600
2012/04/14 12:52:10 [debug] 11906#0: *3332442 rewrite phase: 3
2012/04/14 12:52:10 [debug] 11906#0: *3332442 post rewrite phase: 4
2012/04/14 12:52:10 [debug] 11906#0: *3332442 generic phase: 5
2012/04/14 12:52:10 [debug] 11906#0: *3332442 generic phase: 6
2012/04/14 12:52:10 [debug] 11906#0: *3332442 generic phase: 7
2012/04/14 12:52:10 [debug] 11906#0: *3332442 access phase: 8
2012/04/14 12:52:10 [debug] 11906#0: *3332442 access phase: 9
2012/04/14 12:52:10 [debug] 11906#0: *3332442 access phase: 10
2012/04/14 12:52:10 [debug] 11906#0: *3332442 post access phase: 11
2012/04/14 12:52:10 [debug] 11906#0: *3332442 try files phase: 12
2012/04/14 12:52:10 [debug] 11906#0: *3332442 http init upstream, client
timer: 0
2012/04/14 12:52:10 [debug] 11906#0: *3332442 http script copy: "Host:
www.fs.test
"
2012/04/14 12:52:10 [debug] 11906#0: *3332442 http script copy:
"X-Real-IP: "
2012/04/14 12:52:10 [debug] 11906#0: *3332442 http script var:
"192.168.98.15"
2012/04/14 12:52:10 [debug] 11906#0: *3332442 http script copy: "
"
2012/04/14 12:52:10 [debug] 11906#0: *3332442 http script copy:
"X-Forwarded-For: "
2012/04/14 12:52:10 [debug] 11906#0: *3332442 http script var:
"192.168.98.15"
2012/04/14 12:52:10 [debug] 11906#0: *3332442 http script copy: "
"
2012/04/14 12:52:10 [debug] 11906#0: *3332442 http script copy:
"Connection: close
"
2012/04/14 12:52:10 [debug] 11906#0: *3332442 http proxy header:
"User-Agent: curl/7.25.0 (i486-pc-linux-gnu) libcurl/7.25.0
OpenSSL/1.0.1 zlib/1.2.6 libidn/1.24 libssh2/1.4.0 librtmp/2.3"
2012/04/14 12:52:10 [debug] 11906#0: *3332442 http proxy header:
"Accept: */*"
2012/04/14 12:52:10 [debug] 11906#0: *3332442 http proxy header:
"GET /f/free+free+free+free HTTP/1.0
Host: www.fs.test
X-Real-IP: 192.168.98.15
X-Forwarded-For: 192.168.98.15
Connection: close
User-Agent: curl/7.25.0 (i486-pc-linux-gnu) libcurl/7.25.0 OpenSSL/1.0.1
zlib/1.2.6 libidn/1.24 libssh2/1.4.0 librtmp/2.3
Accept: */*

"
2012/04/14 12:52:10 [debug] 11906#0: *3332442 http cleanup add:
09D817D0
2012/04/14 12:52:10 [debug] 11906#0: *3332442 get ip hash peer, try: 1
2012/04/14 12:52:10 [debug] 11906#0: *3332442 get rr peer, try: 1
2012/04/14 12:52:10 [debug] 11906#0: *3332442 socket 3
2012/04/14 12:52:10 [debug] 11906#0: *3332442 epoll add connection: fd:3
ev:80000005
2012/04/14 12:52:10 [debug] 11906#0: *3332442 connect to
192.168.98.175:80, fd:3 #3333550
2012/04/14 12:52:10 [debug] 11906#0: *3332442 http upstream connect: -2
2012/04/14 12:52:10 [debug] 11906#0: *3332442 event timer add: 3:
20000:2968088483
2012/04/14 12:52:10 [debug] 11906#0: *3332442 http finalize request: -4,
"/?" a:1, c:3
2012/04/14 12:52:10 [debug] 11906#0: *3332442 http request count:3
blk:0
2012/04/14 12:52:10 [debug] 11906#0: *3332442 http finalize request: -4,
"/?" a:1, c:2
2012/04/14 12:52:10 [debug] 11906#0: *3332442 http request count:2
blk:0
2012/04/14 12:52:10 [debug] 11906#0: *3332442 post event 09DF0918
2012/04/14 12:52:10 [debug] 11906#0: *3332442 delete posted event
09DF0918
2012/04/14 12:52:10 [debug] 11906#0: *3332442 http upstream request:
"/?"
2012/04/14 12:52:10 [debug] 11906#0: *3332442 http upstream send request
handler
2012/04/14 12:52:10 [debug] 11906#0: *3332442 http upstream send
request
2012/04/14 12:52:10 [debug] 11906#0: *3332442 chain writer buf fl:1
s:280
2012/04/14 12:52:10 [debug] 11906#0: *3332442 chain writer in: 09D81878
2012/04/14 12:52:10 [debug] 11906#0: *3332442 writev: 280
2012/04/14 12:52:10 [debug] 11906#0: *3332442 chain writer out:
00000000
2012/04/14 12:52:10 [debug] 11906#0: *3332442 event timer del: 3:
2968088483
2012/04/14 12:52:10 [debug] 11906#0: *3332442 event timer add: 3:
20000:2968088498
2012/04/14 12:52:30 [debug] 11906#0: *3332442 event timer del: 3:
2968088498
2012/04/14 12:52:30 [debug] 11906#0: *3332442 http upstream request:
"/?"
2012/04/14 12:52:30 [debug] 11906#0: *3332442 http upstream process
header
2012/04/14 12:52:30 [debug] 11906#0: *3332442 http next upstream, 4
2012/04/14 12:52:30 [debug] 11906#0: *3332442 free rr peer 1 4
2012/04/14 12:52:30 [error] 11906#0: *3332442 upstream timed out (110:
Connection timed out) while reading response header from upstream,
client: 192.168.98.15, server: my.fs.test, request: "GET
/f/free+free+free+free HTTP/1.1", upstream:
"http://192.168.98.175:80/f/free+free+free+free", host: "my.fs.test"
2012/04/14 12:52:30 [debug] 11906#0: *3332442 finalize http upstream
request: 504
2012/04/14 12:52:30 [debug] 11906#0: *3332442 finalize http proxy
request
2012/04/14 12:52:30 [debug] 11906#0: *3332442 free rr peer 0 0
2012/04/14 12:52:30 [debug] 11906#0: *3332442 close http upstream
connection: 3
2012/04/14 12:52:30 [debug] 11906#0: *3332442 reusable connection: 0
2012/04/14 12:52:30 [debug] 11906#0: *3332442 http finalize request:
504, "/?" a:1, c:1
2012/04/14 12:52:30 [debug] 11906#0: *3332442 http special response:
504, "/?"
2012/04/14 12:52:30 [debug] 11906#0: *3332442 http set discard body
2012/04/14 12:52:30 [debug] 11906#0: *3332442 xslt filter header
2012/04/14 12:52:30 [debug] 11906#0: *3332442 posix_memalign:
09E24800:4096 @16
2012/04/14 12:52:30 [debug] 11906#0: *3332442 HTTP/1.1 504 Gateway
Time-out
Server: nginx/1.0.15
Date: Sat, 14 Apr 2012 12:52:30 GMT
Content-Type: text/html
Content-Length: 183
Connection: keep-alive

2012/04/14 12:52:30 [debug] 11906#0: *3332442 write new buf t:1 f:0
09E24810, pos 09E24810, size: 162 file: 0, size: 0
2012/04/14 12:52:30 [debug] 11906#0: *3332442 http write filter: l:0 f:0
s:162
2012/04/14 12:52:30 [debug] 11906#0: *3332442 http output filter "/?"
2012/04/14 12:52:30 [debug] 11906#0: *3332442 http copy filter: "/?"
2012/04/14 12:52:30 [debug] 11906#0: *3332442 image filter
2012/04/14 12:52:30 [debug] 11906#0: *3332442 xslt filter body
2012/04/14 12:52:30 [debug] 11906#0: *3332442 http postpone filter "/?"
09D81924
2012/04/14 12:52:30 [debug] 11906#0: *3332442 write old buf t:1 f:0
09E24810, pos 09E24810, size: 162 file: 0, size: 0
2012/04/14 12:52:30 [debug] 11906#0: *3332442 write new buf t:0 f:0
00000000, pos 080EA3E0, size: 130 file: 0, size: 0
2012/04/14 12:52:30 [debug] 11906#0: *3332442 write new buf t:0 f:0
00000000, pos 080E9060, size: 53 file: 0, size: 0
2012/04/14 12:52:30 [debug] 11906#0: *3332442 http write filter: l:1 f:0
s:345
2012/04/14 12:52:30 [debug] 11906#0: *3332442 http write filter limit 0
2012/04/14 12:52:30 [debug] 11906#0: *3332442 writev: 345
2012/04/14 12:52:30 [debug] 11906#0: *3332442 http write filter
00000000
2012/04/14 12:52:30 [debug] 11906#0: *3332442 http copy filter: 0 "/?"
2012/04/14 12:52:30 [debug] 11906#0: *3332442 http finalize request: 0,
"/?" a:1, c:1
2012/04/14 12:52:30 [debug] 11906#0: *3332442 set http keepalive
handler
2012/04/14 12:52:30 [debug] 11906#0: *3332442 http close request
2012/04/14 12:52:30 [debug] 11906#0: *3332442 http log handler
2012/04/14 12:52:30 [debug] 11906#0: *3332442 free: 09D80930, unused: 4
2012/04/14 12:52:30 [debug] 11906#0: *3332442 free: 09E24800, unused:
3816
2012/04/14 12:52:30 [debug] 11906#0: *3332442 event timer add: 6:
65000:2968153499
2012/04/14 12:52:30 [debug] 11906#0: *3332442 free: 09DB1B80
2012/04/14 12:52:30 [debug] 11906#0: *3332442 free: 09D88458
2012/04/14 12:52:30 [debug] 11906#0: *3332442 hc free: 00000000 0
2012/04/14 12:52:30 [debug] 11906#0: *3332442 hc busy: 00000000 0
2012/04/14 12:52:30 [debug] 11906#0: *3332442 tcp_nodelay
2012/04/14 12:52:30 [debug] 11906#0: *3332442 reusable connection: 1
2012/04/14 12:52:30 [debug] 11906#0: *3332442 post event 09DBD198
2012/04/14 12:52:30 [debug] 11906#0: *3332442 delete posted event
09DBD198
2012/04/14 12:52:30 [debug] 11906#0: *3332442 http keepalive handler
2012/04/14 12:52:30 [debug] 11906#0: *3332442 malloc: 09D88458:1024
2012/04/14 12:52:30 [debug] 11906#0: *3332442 recv: fd:6 -1 of 1024
2012/04/14 12:52:30 [debug] 11906#0: *3332442 recv() not ready (11:
Resource temporarily unavailable)
2012/04/14 12:52:30 [debug] 11906#0: *3332442 http keepalive handler
2012/04/14 12:52:30 [debug] 11906#0: *3332442 recv: fd:6 0 of 1024
2012/04/14 12:52:30 [info] 11906#0: *3332442 client 192.168.98.15 closed
keepalive connection
2012/04/14 12:52:30 [debug] 11906#0: *3332442 close http connection: 6
2012/04/14 12:52:30 [debug] 11906#0: *3332442 event timer del: 6:
2968153499
2012/04/14 12:52:30 [debug] 11906#0: *3332442 reusable connection: 0
2012/04/14 12:52:30 [debug] 11906#0: *3332442 free: 09D88458
2012/04/14 12:52:30 [debug] 11906#0: *3332442 free: 00000000
2012/04/14 12:52:30 [debug] 11906#0: *3332442 free: 09D760C0, unused: 28

Posted at Nginx Forum: http://forum.nginx.org/read.php?21,221921,225328#msg-225328