"Странные" таймауты при получении ответа от бекенда

Thu, 24 Jul 2014 02:52:27 -0700 

Доброго времени суток!

С недавних пор стали появляться ошибки upstream timed out (60: Operation
timed out) while reading response header from upstream.
Что интересно, они появляются только для определенных клиентов, точнее, для
определенного клиента - какой-то китайской поисковой системы. Начали
разбираться с проблемой и наткнулись на еще одну странность.

Логи nginx для неудачного запроса:
2014/07/22 12:35:11 [debug] 63699#0: *200015 http header: "Host:
www.example.com"
2014/07/22 12:35:11 [debug] 63699#0: *200015 http header: "Accept:
text/html, application/xml;q=0.9, application/xhtml+xml, image/png,
image/jpeg, image/gif, image/x-xbitmap, */*;q=0.1"
2014/07/22 12:35:11 [debug] 63699#0: *200015 http header: "Accept-Language:
zh;q=0.9,en;q=0.8"
2014/07/22 12:35:11 [debug] 63699#0: *200015 http header: "Refer:
http://www.example.com/";
2014/07/22 12:35:11 [debug] 63699#0: *200015 http header: "Connection:
close"
2014/07/22 12:35:11 [debug] 63699#0: *200015 http header: "Content-Length:
927"
2014/07/22 12:35:11 [debug] 63699#0: *200015 http header: "Content-Type:
application/x-www-form-urlencoded"
2014/07/22 12:35:11 [debug] 63699#0: *200015 http header done
2014/07/22 12:35:11 [debug] 63699#0: *200015 generic phase: 0
2014/07/22 12:35:11 [debug] 63699#0: *200015 rewrite phase: 1
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script value:
"/usr/home/example/public_html/"
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script set $root_path
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script value: "ndcom"
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script set $mmc_host
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script value: "1"
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script set
$count_domain_volume
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script value: "0"
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script set $vhost_suspend
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script var
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script var: "0"
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script value: "1"
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script not equal
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script if
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script value: "0"
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script set $vhost_suspend
2014/07/22 12:35:11 [debug] 63699#0: *200015 test location: "/"
2014/07/22 12:35:11 [debug] 63699#0: *200015 test location: "robots.txt"
2014/07/22 12:35:11 [debug] 63699#0: *200015 test location: ~
"^.+\.(css|js|ico|gif|png|jpeg|jpg)$"
2014/07/22 12:35:11 [debug] 63699#0: *200015 test location: ~
"^.+\.(zip|tgz|gz|rar|bz2|doc|xls|exe|pdf|ppt|txt|tar|mid|midi|wav|mp3|bmp|rtf|dmg|xml)$"
2014/07/22 12:35:11 [debug] 63699#0: *200015 test location: ~ "\.php$"
2014/07/22 12:35:11 [debug] 63699#0: *200015 test location: ~
"/\.(ht[ap]|git)"
2014/07/22 12:35:11 [debug] 63699#0: *200015 using configuration "/"
2014/07/22 12:35:11 [debug] 63699#0: *200015 http cl:927 max:1048576
2014/07/22 12:35:11 [debug] 63699#0: *200015 rewrite phase: 3
2014/07/22 12:35:11 [debug] 63699#0: *200015 post rewrite phase: 4
2014/07/22 12:35:11 [debug] 63699#0: *200015 generic phase: 5
2014/07/22 12:35:11 [debug] 63699#0: *200015 generic phase: 6
2014/07/22 12:35:11 [debug] 63699#0: *200015 generic phase: 7
2014/07/22 12:35:11 [debug] 63699#0: *200015 access phase: 8
2014/07/22 12:35:11 [debug] 63699#0: *200015 access phase: 9
2014/07/22 12:35:11 [debug] 63699#0: *200015 post access phase: 10
2014/07/22 12:35:11 [debug] 63699#0: *200015 try files phase: 11
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script var:
"/usr/home/example/public_html/"
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script var:
"/download/driver/AZTECH+MDP_3858SP-WE.html"
2014/07/22 12:35:11 [debug] 63699#0: *200015 trying to use file:
"/download/driver/AZTECH+MDP_3858SP-WE.html"
"/usr/home/example/public_html//download/driver/AZTECH+MDP_3858SP-WE.html"
2014/07/22 12:35:11 [debug] 63699#0: *200015 add cleanup: 00000008038913E0
2014/07/22 12:35:11 [debug] 63699#0: *200015 malloc: 0000000803833B80:136
2014/07/22 12:35:11 [debug] 63699#0: *200015 malloc: 0000000803BC3240:71
2014/07/22 12:35:11 [debug] 63699#0: *200015 cached open file:
/usr/home/example/public_html//download/driver/AZTECH+MDP_3858SP-WE.html,
fd:-1, c:0, e:2, u:1
2014/07/22 12:35:11 [debug] 63699#0: *200015 trying to use file:
"@proxy_upstream" "/usr/home/example/public_html/@proxy_upstream"
2014/07/22 12:35:11 [debug] 63699#0: *200015 test location: "@default500"
2014/07/22 12:35:11 [debug] 63699#0: *200015 test location: "@error500"
2014/07/22 12:35:11 [debug] 63699#0: *200015 test location: "@fallback"
2014/07/22 12:35:11 [debug] 63699#0: *200015 test location: "@postDownload"
2014/07/22 12:35:11 [debug] 63699#0: *200015 test location:
"@proxy_upstream"
2014/07/22 12:35:11 [debug] 63699#0: *200015 using location: @proxy_upstream
"/download/driver/AZTECH+MDP_3858SP-WE.html?"
2014/07/22 12:35:11 [debug] 63699#0: *200015 rewrite phase: 3
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script value:
"/usr/local/www/htdocs/outofservice.html"
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script file op
0000000000000000 "/usr/local/www/htdocs/outofservice.html"
2014/07/22 12:35:11 [debug] 63699#0: *200015 add cleanup: 0000000803891510
2014/07/22 12:35:11 [debug] 63699#0: *200015 cached open file:
/usr/local/www/htdocs/outofservice.html, fd:-1, c:0, e:2, u:441
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script file op false
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script if
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script if: false
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script var
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script var: "0"
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script value: "1"
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script equal
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script equal: no
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script if
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script if: false
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script var
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script var: ""
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script value: ""
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script equal
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script if
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script complex value
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script var:
"www.example.com"
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script set $forced_host
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script value: "local"
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script set
$ndcom_upstream_name
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script var
2014/07/22 12:35:11 [debug] 63699#0: *200015 http map started
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script var:
"183.60.213.30"
2014/07/22 12:35:11 [debug] 63699#0: *200015 http map: "183.60.213.30"
"new-backends"
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script var:
"new-backends"
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script if
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script complex value
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script var:
"new-backends"
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script set $upstream_name
2014/07/22 12:35:11 [debug] 63699#0: *200015 post rewrite phase: 4
2014/07/22 12:35:11 [debug] 63699#0: *200015 generic phase: 5
2014/07/22 12:35:11 [debug] 63699#0: *200015 generic phase: 6
2014/07/22 12:35:11 [debug] 63699#0: *200015 generic phase: 7
2014/07/22 12:35:11 [debug] 63699#0: *200015 limit conn: 8AD0B9F2 1
2014/07/22 12:35:11 [debug] 63699#0: *200015 add cleanup: 0000000803891588
2014/07/22 12:35:11 [debug] 63699#0: *200015 access phase: 8
2014/07/22 12:35:11 [debug] 63699#0: *200015 access phase: 9
2014/07/22 12:35:11 [debug] 63699#0: *200015 post access phase: 10
2014/07/22 12:35:11 [debug] 63699#0: *200015 try files phase: 11
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script copy: "http://";
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script var:
"new-backends"
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script var:
"/download/driver/AZTECH+MDP_3858SP-WE.html"
2014/07/22 12:35:11 [debug] 63699#0: *200015 http client request body
preread 536
2014/07/22 12:35:11 [debug] 63699#0: *200015 http request body content
length filter
2014/07/22 12:35:11 [debug] 63699#0: *200015 http body new buf t:1 f:0
00000008038089E8, pos 00000008038089E8, size: 536 file: 0, size: 0
2014/07/22 12:35:11 [debug] 63699#0: *200015 http read client request body
2014/07/22 12:35:11 [debug] 63699#0: *200015 recv: eof:0, avail:0, err:0
2014/07/22 12:35:11 [debug] 63699#0: *200015 http client request body recv
-2
2014/07/22 12:35:11 [debug] 63699#0: *200015 http client request body rest
391
2014/07/22 12:35:11 [debug] 63699#0: *200015 event timer add: 38:
60000:1406032571647
2014/07/22 12:35:11 [debug] 63699#0: *200015 kevent set event: 38: ft:-1
fl:0025
2014/07/22 12:35:11 [debug] 63699#0: *200015 http finalize request: -4,
"/download/driver/AZTECH+MDP_3858SP-WE.html?" a:1, c:3
2014/07/22 12:35:11 [debug] 63699#0: *200015 http request count:3 blk:0
2014/07/22 12:35:11 [debug] 63699#0: *200015 http finalize request: -4,
"/download/driver/AZTECH+MDP_3858SP-WE.html?" a:1, c:2
2014/07/22 12:35:11 [debug] 63699#0: *200015 http request count:2 blk:0
2014/07/22 12:35:11 [debug] 63699#0: *200015 kevent: 38: ft:-1 fl:8020
ff:00000000 d:391 ud:0000000806C07381
2014/07/22 12:35:11 [debug] 63699#0: *200015 post event 0000000806C07380
2014/07/22 12:35:11 [debug] 63699#0: *200015 delete posted event
0000000806C07380
2014/07/22 12:35:11 [debug] 63699#0: *200015 http run request:
"/download/driver/AZTECH+MDP_3858SP-WE.html?"
2014/07/22 12:35:11 [debug] 63699#0: *200015 http read client request body
2014/07/22 12:35:11 [debug] 63699#0: *200015 recv: eof:1, avail:391, err:0
2014/07/22 12:35:11 [debug] 63699#0: *200015 recv: fd:38 391 of 391
2014/07/22 12:35:11 [debug] 63699#0: *200015 http client request body recv
391
2014/07/22 12:35:11 [debug] 63699#0: *200015 http body old buf t:1 f:0
00000008038089E8, pos 00000008038089E8, size: 536 file: 0, size: 0
2014/07/22 12:35:11 [debug] 63699#0: *200015 http body new buf t:1 f:0
0000000803891C90, pos 0000000803891C90, size: 391 file: 0, size: 0
2014/07/22 12:35:11 [debug] 63699#0: *200015 http client request body rest
0
2014/07/22 12:35:11 [debug] 63699#0: *200015 event timer del: 38:
1406032571647
2014/07/22 12:35:11 [debug] 63699#0: *200015 http init upstream, client
timer: 0
2014/07/22 12:35:11 [debug] 63699#0: *200015 kevent set event: 38: ft:-2
fl:0025
2014/07/22 12:35:11 [debug] 63699#0: *200015 posix_memalign:
0000000803893000:4096 @16
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script copy: "Host: "
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script var:
"www.example.com"
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script copy: "
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script copy: "X-Real-IP:
"
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script var:
"183.60.213.30"
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script copy: "
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script copy:
"X-Forwarded-For: "
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script var:
"183.60.213.30"
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script copy: "
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script copy:
"X-Forwarded-Port: "
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script var: "80"
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script copy: "
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script copy:
"Content-Length: "
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script var: "927"
2014/07/22 12:35:11 [debug] 63699#0: *200015 http script copy: "
2014/07/22 12:35:11 [debug] 63699#0: *200015 http proxy header: "User-Agent:
Mozilla/5.0 (compatible; EasouSpider;
+http://www.easou.com/search/spider.html)"
2014/07/22 12:35:11 [debug] 63699#0: *200015 http proxy header:
"Accept-Encoding: gzip, deflate"
2014/07/22 12:35:11 [debug] 63699#0: *200015 http proxy header: "Accept:
text/html, application/xml;q=0.9, application/xhtml+xml, image/png,
image/jpeg, image/gif, image/x-xbitmap, */*;q=0.1"
2014/07/22 12:35:11 [debug] 63699#0: *200015 http proxy header:
"Accept-Language: zh;q=0.9,en;q=0.8"
2014/07/22 12:35:11 [debug] 63699#0: *200015 http proxy header: "Refer:
http://www.example.com/";
2014/07/22 12:35:11 [debug] 63699#0: *200015 http proxy header:
"Content-Type: application/x-www-form-urlencoded"
2014/07/22 12:35:11 [debug] 63699#0: *200015 http proxy header:
2014/07/22 12:35:11 [debug] 63699#0: *200015 http cleanup add:
0000000803891FD0
2014/07/22 12:35:11 [debug] 63699#0: *200015 init keepalive peer
2014/07/22 12:35:11 [debug] 63699#0: *200015 get keepalive peer
2014/07/22 12:35:11 [debug] 63699#0: *200015 get rr peer, try: 2
2014/07/22 12:35:11 [debug] 63699#0: *200015 get rr peer, current: 0 -5
2014/07/22 12:35:11 [debug] 63699#0: *200015 socket 134
2014/07/22 12:35:11 [debug] 63699#0: *200015 connect to 127.0.0.1:80, fd:134
#200016
2014/07/22 12:35:11 [debug] 63699#0: *200015 kevent set event: 134: ft:-1
fl:0025
2014/07/22 12:35:11 [debug] 63699#0: *200015 kevent set event: 134: ft:-2
fl:0025
2014/07/22 12:35:11 [debug] 63699#0: *200015 http upstream connect: -2
2014/07/22 12:35:11 [debug] 63699#0: *200015 posix_memalign:
0000000803834800:128 @16
2014/07/22 12:35:11 [debug] 63699#0: *200015 event timer add: 134:
90000:1406032601647
2014/07/22 12:35:11 [debug] 63699#0: *200015 kevent: 38: ft:-2 fl:0020
ff:00000000 d:66608 ud:0000000806D1F381
2014/07/22 12:35:11 [debug] 63699#0: *200015 post event 0000000806D1F380
2014/07/22 12:35:11 [debug] 63699#0: *200015 kevent: 134: ft:-2 fl:0020
ff:00000000 d:43008 ud:0000000806D210D0
2014/07/22 12:35:11 [debug] 63699#0: *200015 post event 0000000806D210D0
2014/07/22 12:35:11 [debug] 63699#0: *200015 delete posted event
0000000806D210D0
2014/07/22 12:35:11 [debug] 63699#0: *200015 http upstream request:
"/download/driver/AZTECH+MDP_3858SP-WE.html?"
2014/07/22 12:35:11 [debug] 63699#0: *200015 http upstream send request
handler
2014/07/22 12:35:11 [debug] 63699#0: *200015 http upstream send request
2014/07/22 12:35:11 [debug] 63699#0: *200015 chain writer buf fl:0 s:554
2014/07/22 12:35:11 [debug] 63699#0: *200015 chain writer buf fl:0 s:536
2014/07/22 12:35:11 [debug] 63699#0: *200015 chain writer buf fl:1 s:391
2014/07/22 12:35:11 [debug] 63699#0: *200015 chain writer in:
0000000803893300
2014/07/22 12:35:11 [debug] 63699#0: *200015 writev: 1481 of 1481
2014/07/22 12:35:11 [debug] 63699#0: *200015 chain writer out:
0000000000000000
2014/07/22 12:35:11 [debug] 63699#0: *200015 event timer del: 134:
1406032601647
2014/07/22 12:35:11 [debug] 63699#0: *200015 event timer add: 134:
90000:1406032601648
2014/07/22 12:35:11 [debug] 63699#0: *200015 delete posted event
0000000806D1F380
2014/07/22 12:35:11 [debug] 63699#0: *200015 http run request:
"/download/driver/AZTECH+MDP_3858SP-WE.html?"
2014/07/22 12:35:11 [debug] 63699#0: *200015 http upstream check client,
write event:1, "/download/driver/AZTECH+MDP_3858SP-WE.html"
2014/07/22 12:35:11 [debug] 63699#0: *200015 kevent: 134: ft:-2 fl:0020
ff:00000000 d:43008 ud:0000000806D210D0
2014/07/22 12:35:11 [debug] 63699#0: *200015 post event 0000000806D210D0
2014/07/22 12:35:11 [debug] 63699#0: *200015 delete posted event
0000000806D210D0
2014/07/22 12:35:11 [debug] 63699#0: *200015 http upstream request:
"/download/driver/AZTECH+MDP_3858SP-WE.html?"
2014/07/22 12:35:11 [debug] 63699#0: *200015 http upstream dummy handler
2014/07/22 12:36:41 [debug] 63699#0: *200015 event timer del: 134:
1406032601648
2014/07/22 12:36:41 [debug] 63699#0: *200015 http upstream request:
"/download/driver/AZTECH+MDP_3858SP-WE.html?"
2014/07/22 12:36:41 [debug] 63699#0: *200015 http upstream process header
2014/07/22 12:36:41 [debug] 63699#0: *200015 http next upstream, 4
2014/07/22 12:36:41 [debug] 63699#0: *200015 free keepalive peer
2014/07/22 12:36:41 [debug] 63699#0: *200015 free rr peer 2 4
2014/07/22 12:36:41 [debug] 63699#0: *200015 free rr peer failed: 0 0
2014/07/22 12:36:41 [error] 63699#0: *200015 upstream timed out (60:
Operation timed out) while reading response header from upstream, client:
183.60.213.30, server: www.example.com, request: "GET
/download/driver/AZTECH+MDP_3858SP-WE.html HTTP/1.1", upstream:
"http://127.0.0.1:80/download/driver/AZTECH+MDP_3858SP-WE.html";, host:
"www.example.com"
2014/07/22 12:36:41 [debug] 63699#0: *200015 close http upstream connection:
134
2014/07/22 12:36:41 [debug] 63699#0: *200015 free: 0000000803834800, unused:
48
2014/07/22 12:36:41 [debug] 63699#0: *200015 reusable connection: 0
2014/07/22 12:36:41 [debug] 63699#0: *200015 get keepalive peer
2014/07/22 12:36:41 [debug] 63699#0: *200015 get rr peer, try: 1
2014/07/22 12:36:41 [debug] 63699#0: *200015 get rr peer, current: 1 0
2014/07/22 12:36:41 [debug] 63699#0: *200015 socket 3
2014/07/22 12:36:41 [debug] 63699#0: *200015 connect to 94.75.244.108:80,
fd:3 #204118
2014/07/22 12:36:41 [debug] 63699#0: *200015 kevent set event: 3: ft:-1
fl:0025
2014/07/22 12:36:41 [debug] 63699#0: *200015 kevent set event: 3: ft:-2
fl:0025
2014/07/22 12:36:41 [debug] 63699#0: *200015 http upstream connect: -2
2014/07/22 12:36:41 [debug] 63699#0: *200015 posix_memalign:
0000000803834780:128 @16
2014/07/22 12:36:41 [debug] 63699#0: *200015 event timer add: 3:
90000:1406032691649
2014/07/22 12:36:41 [debug] 63699#0: *200015 kevent: 3: ft:-2 fl:0020
ff:00000000 d:33304 ud:0000000806D210D1
2014/07/22 12:36:41 [debug] 63699#0: *200015 http upstream request:
"/download/driver/AZTECH+MDP_3858SP-WE.html?"
2014/07/22 12:36:41 [debug] 63699#0: *200015 http upstream send request
handler
2014/07/22 12:36:41 [debug] 63699#0: *200015 http upstream send request
2014/07/22 12:36:41 [debug] 63699#0: *200015 chain writer buf fl:0 s:554
2014/07/22 12:36:41 [debug] 63699#0: *200015 chain writer buf fl:0 s:536
2014/07/22 12:36:41 [debug] 63699#0: *200015 chain writer buf fl:1 s:391
2014/07/22 12:36:41 [debug] 63699#0: *200015 chain writer in:
0000000803893520
2014/07/22 12:36:41 [debug] 63699#0: *200015 writev: 1481 of 1481
2014/07/22 12:36:41 [debug] 63699#0: *200015 chain writer out:
0000000000000000
2014/07/22 12:36:41 [debug] 63699#0: *200015 event timer del: 3:
1406032691649
2014/07/22 12:36:41 [debug] 63699#0: *200015 event timer add: 3:
90000:1406032691650
2014/07/22 12:36:41 [debug] 63699#0: *200015 kevent: 3: ft:-2 fl:0020
ff:00000000 d:33304 ud:0000000806D210D1
2014/07/22 12:36:41 [debug] 63699#0: *200015 http upstream request:
"/download/driver/AZTECH+MDP_3858SP-WE.html?"
2014/07/22 12:36:41 [debug] 63699#0: *200015 http upstream dummy handler
2014/07/22 12:38:11 [debug] 63699#0: *200015 event timer del: 3:
1406032691650
2014/07/22 12:38:11 [debug] 63699#0: *200015 http upstream request:
"/download/driver/AZTECH+MDP_3858SP-WE.html?"
2014/07/22 12:38:11 [debug] 63699#0: *200015 http upstream process header
2014/07/22 12:38:11 [debug] 63699#0: *200015 http next upstream, 4
2014/07/22 12:38:11 [debug] 63699#0: *200015 free keepalive peer
2014/07/22 12:38:11 [debug] 63699#0: *200015 free rr peer 1 4
2014/07/22 12:38:11 [debug] 63699#0: *200015 free rr peer failed: 1 0
2014/07/22 12:38:11 [error] 63699#0: *200015 upstream timed out (60:
Operation timed out) while reading response header from upstream, client:
183.60.213.30, server: www.example.com, request: "GET
/download/driver/AZTECH+MDP_3858SP-WE.html HTTP/1.1", upstream:
"http://94.75.244.108:80/download/driver/AZTECH+MDP_3858SP-WE.html";, host:
"www.example.com"
2014/07/22 12:38:11 [debug] 63699#0: *200015 finalize http upstream request:
504
2014/07/22 12:38:11 [debug] 63699#0: *200015 finalize http proxy request
2014/07/22 12:38:11 [debug] 63699#0: *200015 close http upstream connection:
3
2014/07/22 12:38:11 [debug] 63699#0: *200015 free: 0000000803834780, unused:
48
2014/07/22 12:38:11 [debug] 63699#0: *200015 reusable connection: 0
2014/07/22 12:38:11 [debug] 63699#0: *200015 http finalize request: 504,
"/download/driver/AZTECH+MDP_3858SP-WE.html?" a:1, c:1
2014/07/22 12:38:11 [debug] 63699#0: *200015 http special response: 504,
"/download/driver/AZTECH+MDP_3858SP-WE.html?"
2014/07/22 12:38:11 [debug] 63699#0: *200015 test location: "@default500"
2014/07/22 12:38:11 [debug] 63699#0: *200015 test location: "@error500"
2014/07/22 12:38:11 [debug] 63699#0: *200015 using location: @error500
"/download/driver/AZTECH+MDP_3858SP-WE.html?"
2014/07/22 12:38:11 [debug] 63699#0: *200015 rewrite phase: 3
2014/07/22 12:38:11 [debug] 63699#0: *200015 post rewrite phase: 4
2014/07/22 12:38:11 [debug] 63699#0: *200015 generic phase: 5
2014/07/22 12:38:11 [debug] 63699#0: *200015 generic phase: 6
2014/07/22 12:38:11 [debug] 63699#0: *200015 generic phase: 7
2014/07/22 12:38:11 [debug] 63699#0: *200015 access phase: 8
2014/07/22 12:38:11 [debug] 63699#0: *200015 access phase: 9
2014/07/22 12:38:11 [debug] 63699#0: *200015 post access phase: 10
2014/07/22 12:38:11 [debug] 63699#0: *200015 try files phase: 11
2014/07/22 12:38:11 [debug] 63699#0: *200015 http script var:
"/usr/home/example/public_html/"
2014/07/22 12:38:11 [debug] 63699#0: *200015 trying to use file: "/500.htm"
"/usr/home/example/public_html//500.htm"
2014/07/22 12:38:11 [debug] 63699#0: *200015 add cleanup: 00000008038935A8
2014/07/22 12:38:11 [debug] 63699#0: *200015 malloc: 0000000807191680:136
2014/07/22 12:38:11 [debug] 63699#0: *200015 malloc: 0000000803BE50A0:37
2014/07/22 12:38:11 [debug] 63699#0: *200015 cached open file:
/usr/home/example/public_html//500.htm, fd:3, c:1, e:0, u:1
2014/07/22 12:38:11 [debug] 63699#0: *200015 try file uri: "/500.htm"
2014/07/22 12:38:11 [debug] 63699#0: *200015 content phase: 12
2014/07/22 12:38:11 [debug] 63699#0: *200015 content phase: 13
2014/07/22 12:38:11 [debug] 63699#0: *200015 content phase: 14
2014/07/22 12:38:11 [debug] 63699#0: *200015 content phase: 15
2014/07/22 12:38:11 [debug] 63699#0: *200015 http script var:
"/usr/home/example/public_html/"
2014/07/22 12:38:11 [debug] 63699#0: *200015 http filename:
"/usr/home/example/public_html//500.htm"
2014/07/22 12:38:11 [debug] 63699#0: *200015 add cleanup: 0000000803893608
2014/07/22 12:38:11 [debug] 63699#0: *200015 cached open file:
/usr/home/example/public_html//500.htm, fd:3, c:2, e:0, u:2
2014/07/22 12:38:11 [debug] 63699#0: *200015 http static fd: 3
2014/07/22 12:38:11 [debug] 63699#0: *200015 HTTP/1.1 503 Service
Temporarily Unavailable
2014/07/22 12:38:11 [debug] 63699#0: *200015 write new buf t:1 f:0
00000008038937C8, pos 00000008038937C8, size: 188 file: 0, size: 0
2014/07/22 12:38:11 [debug] 63699#0: *200015 http write filter: l:0 f:0
s:188
2014/07/22 12:38:11 [debug] 63699#0: *200015 http output filter "/500.htm?"
2014/07/22 12:38:11 [debug] 63699#0: *200015 http copy filter: "/500.htm?"
2014/07/22 12:38:11 [debug] 63699#0: *200015 image filter
2014/07/22 12:38:11 [debug] 63699#0: *200015 http postpone filter
"/500.htm?" 00007FFFFFFFD6E0
2014/07/22 12:38:11 [debug] 63699#0: *200015 write old buf t:1 f:0
00000008038937C8, pos 00000008038937C8, size: 188 file: 0, size: 0
2014/07/22 12:38:11 [debug] 63699#0: *200015 write new buf t:0 f:1
0000000000000000, pos 0000000000000000, size: 0 file: 0, size: 1202
2014/07/22 12:38:11 [debug] 63699#0: *200015 http write filter: l:1 f:0
s:1390
2014/07/22 12:38:11 [debug] 63699#0: *200015 http write filter limit 0
2014/07/22 12:38:11 [debug] 63699#0: *200015 tcp_nopush
2014/07/22 12:38:11 [debug] 63699#0: *200015 sendfile: 0, @0 1390:1202
2014/07/22 12:38:11 [debug] 63699#0: *200015 http write filter
0000000000000000
2014/07/22 12:38:11 [debug] 63699#0: *200015 http copy filter: 0
"/500.htm?"
2014/07/22 12:38:11 [debug] 63699#0: *200015 http finalize request: 0,
"/500.htm?" a:1, c:2
2014/07/22 12:38:11 [debug] 63699#0: *200015 http request count:2 blk:0
2014/07/22 12:38:11 [debug] 63699#0: *200015 http finalize request: -4,
"/500.htm?" a:1, c:1
2014/07/22 12:38:11 [debug] 63699#0: *200015 event timer add: 38:
5000:1406032696651
2014/07/22 12:38:11 [debug] 63699#0: *200015 http lingering close handler
2014/07/22 12:38:11 [debug] 63699#0: *200015 recv: eof:1, avail:0, err:0
2014/07/22 12:38:11 [debug] 63699#0: *200015 lingering read: 0
2014/07/22 12:38:11 [debug] 63699#0: *200015 http request count:1 blk:0
2014/07/22 12:38:11 [debug] 63699#0: *200015 http close request
2014/07/22 12:38:11 [debug] 63699#0: *200015 http log handler
2014/07/22 12:38:11 [debug] 63699#0: *200015 run cleanup: 0000000803893608
2014/07/22 12:38:11 [debug] 63699#0: *200015 close cached open file:
/usr/home/example/public_html//500.htm, fd:3, c:1, u:2, 0
2014/07/22 12:38:11 [debug] 63699#0: *200015 expire cached open file:
/usr/home/example/public_html//download/driver/ASUS+EAX800_Series/265242.html
2014/07/22 12:38:11 [debug] 63699#0: *200015 expire cached open file:
/usr/home/example/public_html//manual/newmans/1165563205KS0951(SM700433-00_11)pdf/get16192.html
2014/07/22 12:38:11 [debug] 63699#0: *200015 run cleanup: 00000008038935A8
2014/07/22 12:38:11 [debug] 63699#0: *200015 close cached open file:
/usr/home/example/public_html//500.htm, fd:3, c:0, u:2, 0
2014/07/22 12:38:11 [debug] 63699#0: *200015 expire cached open file:
/usr/home/example/public_html/manual/ks-rt510rb/get103327.html
2014/07/22 12:38:11 [debug] 63699#0: *200015 expire cached open file:
/usr/home/example/public_html//driver/GS-R115V-RH__1_0_/get52879.html
2014/07/22 12:38:11 [debug] 63699#0: *200015 run cleanup: 0000000803891588
2014/07/22 12:38:11 [debug] 63699#0: *200015 free: 0000000803890000, unused:
7
2014/07/22 12:38:11 [debug] 63699#0: *200015 free: 0000000803891000, unused:
8
2014/07/22 12:38:11 [debug] 63699#0: *200015 free: 0000000803893000, unused:
1364
2014/07/22 12:38:11 [debug] 63699#0: *200015 close http connection: 38
2014/07/22 12:38:11 [debug] 63699#0: *200015 event timer del: 38:
1406032696651
2014/07/22 12:38:11 [debug] 63699#0: *200015 reusable connection: 0
2014/07/22 12:38:11 [debug] 63699#0: *200015 free: 0000000803808800
2014/07/22 12:38:11 [debug] 63699#0: *200015 free: 0000000807182000, unused:
0
2014/07/22 12:38:11 [debug] 63699#0: *200015 free: 0000000807182100, unused:
108

Обратил внимание на следующие строки:
2014/07/22 12:35:11 [debug] 63699#0: *200015 http upstream request:
"/download/driver/AZTECH+MDP_3858SP-WE.html?"
2014/07/22 12:35:11 [debug] 63699#0: *200015 http upstream dummy handler
2014/07/22 12:36:41 [debug] 63699#0: *200015 event timer del: 134:
1406032601648
2014/07/22 12:36:41 [debug] 63699#0: *200015 http upstream request:
"/download/driver/AZTECH+MDP_3858SP-WE.html?"
2014/07/22 12:36:41 [debug] 63699#0: *200015 http upstream process header
2014/07/22 12:36:41 [debug] 63699#0: *200015 http next upstream, 4
2014/07/22 12:36:41 [debug] 63699#0: *200015 free keepalive peer
2014/07/22 12:36:41 [debug] 63699#0: *200015 free rr peer 2 4
2014/07/22 12:36:41 [debug] 63699#0: *200015 free rr peer failed: 0 0
2014/07/22 12:36:41 [error] 63699#0: *200015 upstream timed out (60:
Operation timed out) while reading response header from upstream, client:
183.60.213.30, server: www.example.com, request: "GET
/download/driver/AZTECH+MDP_3858SP-WE.html HTTP/1.1", upstream:
"http://127.0.0.1:80/download/driver/AZTECH+MDP_3858SP-WE.html";, host:
"www.example.com"
2014/07/22 12:36:41 [debug] 63699#0: *200015 close http upstream connection:
134

В 12:35:11 отправили запрос бекенду, а через полторы минуты вывалились по
таймауту. Все бы ничего, если бы не логи самого бекенда:
183.60.213.30 - - [22/Jul/2014:12:36:41 +0000] "GET
/download/driver/AZTECH+MDP_3858SP-WE.html HTTP/1.1" 200 4953 0/45331 "-"
"Mozilla/5.0 (compatible; EasouSpider;
+http://www.easou.com/search/spider.html)"

Бекенд получил и обработал этот запрос как раз в тот момент, когда nginx
разрывает соединение. Обработка запроса заняла 45331 us. То есть, как
такового таймаута быть не должно, бекенд моментально обработал этот запрос.
Так вот, непонятно, куда все таки попал этот http-запрос и почему он попал к
бекенду при срабатывании таймаута nginx'а.

Кто-нибудь сталкивался с подобным? Есть ли мысли о причинах подобного
поведения?

Версии софта:
ОС: FreeBSD 9.0-RELEASE-p3 #0: Tue Jun 12 02:52:29 UTC 2012    
[email protected]:/usr/obj/usr/src/sys/GENERIC  amd64

Nginx:
nginx version: nginx/1.4.4
TLS SNI support enabled
configure arguments: --prefix=/usr/local/etc/nginx --with-cc-opt='-I
/usr/local/include' --with-ld-opt='-L /usr/local/lib'
--conf-path=/usr/local/etc/nginx/nginx.conf
--sbin-path=/usr/local/sbin/nginx --pid-path=/var/run/nginx.pid
--error-log-path=/var/log/nginx-error.log --user=www --group=www
--with-debug --with-file-aio
--http-client-body-temp-path=/var/tmp/nginx/client_body_temp
--http-fastcgi-temp-path=/var/tmp/nginx/fastcgi_temp
--http-proxy-temp-path=/var/tmp/nginx/proxy_temp
--http-scgi-temp-path=/var/tmp/nginx/scgi_temp
--http-uwsgi-temp-path=/var/tmp/nginx/uwsgi_temp
--http-log-path=/var/log/nginx-access.log --with-http_addition_module
--with-http_geoip_module --with-http_gzip_static_module
--with-http_image_filter_module --with-http_perl_module
--with-http_realip_module --with-http_secure_link_module
--with-http_stub_status_module --with-pcre --with-http_ssl_module

Apache:
Server version: Apache/2.2.22 (FreeBSD)
Server built:   Oct 27 2012 07:23:23

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

_______________________________________________
nginx-ru mailing list
[email protected]
http://mailman.nginx.org/mailman/listinfo/nginx-ru

Ответить