Re: Re[8]: Постоянные обрывы кон нектов

[Anton Kuznetsov <maybe@xxxxxxxxxxxx>]

Uniq IP: 386     Established connection:  938
limit_req_zone $binary_remote_addr  zone=avi:10m   rate=2r/m;
По-моему - как до Луны... :)

log:
217.118.90.158 - - [16/Jul/2009:02:02:18 +0400] 40.311 bytes=575302136- GET /filmiki/mary.poppins.cd2.avi HTTP/1.0 ZZ 206 30216 "Download Master"

Debug:
2009/07/16 02:01:37 [debug] 55481#0: *594615 accept: 217.118.90.158 fd:130
2009/07/16 02:01:37 [debug] 55481#0: *594615 event timer add: 130: 30000:2154811833
2009/07/16 02:01:37 [debug] 55481#0: *594615 kevent set event: 130: ft:-1 fl:0025

2009/07/16 02:01:38 [debug] 55481#0: *594615 post event 2844FD20
2009/07/16 02:01:38 [debug] 55481#0: *594615 delete posted event 2844FD20
2009/07/16 02:01:38 [debug] 55481#0: *594615 malloc: 29030400:660
2009/07/16 02:01:38 [debug] 55481#0: *594615 malloc: 29030800:1024

2009/07/16 02:01:38 [debug] 55481#0: *594615 malloc: 29039000:4096
2009/07/16 02:01:38 [debug] 55481#0: *594615 http process request line
2009/07/16 02:01:38 [debug] 55481#0: *594615 recv: eof:0, avail:424, err:0

2009/07/16 02:01:38 [debug] 55481#0: *594615 recv: fd:130 424 of 1024
2009/07/16 02:01:38 [debug] 55481#0: *594615 http request line: "GET /filmiki/mary.poppins.cd2.avi HTTP/1.0"
2009/07/16 02:01:38 [debug] 55481#0: *594615 http uri: "/filmiki/mary.poppins.cd2.avi"

2009/07/16 02:01:38 [debug] 55481#0: *594615 http args: ""
2009/07/16 02:01:38 [debug] 55481#0: *594615 http exten: "avi"
2009/07/16 02:01:38 [debug] 55481#0: *594615 http process request header line

2009/07/16 02:01:38 [debug] 55481#0: *594615 http header: "User-Agent: Download Master"
2009/07/16 02:01:38 [debug] 55481#0: *594615 http header: "Cookie: __utma=17544366.2091389341.1247520403.1247520403.1247520403.1; __utmz=17544366.1247520403.1.1.utmccn=(referral)|utmcsr=multiki.arjlover.net|utmcct=/|utmcmd=referral"

2009/07/16 02:01:38 [debug] 55481#0: *594615 http header: "Accept: */*"
2009/07/16 02:01:38 [debug] 55481#0: *594615 http header: "Referer: http://filmiki.arjlover.net/info/mary.poppins.cd2.avi.html"

2009/07/16 02:01:38 [debug] 55481#0: *594615 http header: "Range: bytes=575302136-"
2009/07/16 02:01:38 [debug] 55481#0: *594615 http header: "Pragma: no-cache"
2009/07/16 02:01:38 [debug] 55481#0: *594615 http header: "Cache-Control: no-cache"

2009/07/16 02:01:38 [debug] 55481#0: *594615 http header: "Host: inka.arjlover.net"
2009/07/16 02:01:38 [debug] 55481#0: *594615 http header done
2009/07/16 02:01:38 [debug] 55481#0: *594615 event timer del: 130: 2154811833

2009/07/16 02:01:38 [debug] 55481#0: *594615 generic phase: 0
2009/07/16 02:01:38 [debug] 55481#0: *594615 add cleanup: 29039598
2009/07/16 02:01:38 [debug] 55481#0: *594615 generic phase: 1
2009/07/16 02:01:38 [debug] 55481#0: *594615 test location: "/"

2009/07/16 02:01:38 [debug] 55481#0: *594615 test location: "50x.html"
2009/07/16 02:01:38 [debug] 55481#0: *594615 test location: "statn"
2009/07/16 02:01:38 [debug] 55481#0: *594615 test location: "no.html"

2009/07/16 02:01:38 [debug] 55481#0: *594615 test location: ~ "/php2/"
2009/07/16 02:01:38 [debug] 55481#0: *594615 test location: ~ "/mrtg/.*"
2009/07/16 02:01:38 [debug] 55481#0: *594615 test location: ~ "\.(html|php|pl)$"

2009/07/16 02:01:38 [debug] 55481#0: *594615 test location: ~ "/(stat|session)/"
2009/07/16 02:01:38 [debug] 55481#0: *594615 test location: ~ "^/(film|filmiki|multiki)/.*\.(avi|mpg|gif|jpg)$"
2009/07/16 02:01:38 [debug] 55481#0: *594615 using configuration "^/(film|filmiki|multiki)/.*\.(avi|mpg|gif|jpg)$"

2009/07/16 02:01:38 [debug] 55481#0: *594615 http cl:-1 max:1048576
2009/07/16 02:01:38 [debug] 55481#0: *594615 generic phase: 3
2009/07/16 02:01:38 [debug] 55481#0: *594615 http script var
2009/07/16 02:01:38 [debug] 55481#0: *594615 http script var: ""

2009/07/16 02:01:38 [debug] 55481#0: *594615 http script if
2009/07/16 02:01:38 [debug] 55481#0: *594615 http script if: false
2009/07/16 02:01:38 [debug] 55481#0: *594615 http script var
2009/07/16 02:01:38 [debug] 55481#0: *594615 http script var: "/filmiki/mary.poppins.cd2.avi"

2009/07/16 02:01:38 [debug] 55481#0: *594615 http script regex: "\.(gif|jpg)$"
2009/07/16 02:01:38 [notice] 55481#0: *594615 "\.(gif|jpg)$" does not match "/filmiki/mary.poppins.cd2.avi", client: 217.118.90.158, server: inka.arjlover.net, request: "GET /filmiki/mary.poppins.cd2.avi HTTP/1.0", host: "inka.arjlover.net", referrer: "http://filmiki.arjlover.net/info/mary.poppins.cd2.avi.html"

2009/07/16 02:01:38 [debug] 55481#0: *594615 http script if
2009/07/16 02:01:38 [debug] 55481#0: *594615 http script if: false
2009/07/16 02:01:38 [debug] 55481#0: *594615 post rewrite phase: 4
2009/07/16 02:01:38 [debug] 55481#0: *594615 generic phase: 5

2009/07/16 02:01:38 [debug] 55481#0: *594615 add cleanup: 290396A8
2009/07/16 02:01:38 [debug] 55481#0: *594615 generic phase: 6
2009/07/16 02:01:38 [debug] 55481#0: *594615 limit_req: -2 0.308
2009/07/16 02:01:38 [warn] 55481#0: *594615 delaying request, excess: 0.308, by zone "avi", client: 217.118.90.158, server: inka.arjlover.net, request: "GET /filmiki/mary.poppins.cd2.avi HTTP/1.0", host: "inka.arjlover.net", referrer: "http://filmiki.arjlover.net/info/mary.poppins.cd2.avi.html"

2009/07/16 02:01:38 [debug] 55481#0: *594615 event timer add: 130: 308:2154782904
2009/07/16 02:01:38 [debug] 55481#0: *594615 event timer del: 130: 2154782904
2009/07/16 02:01:38 [debug] 55481#0: *594615 http run request: "/filmiki/mary.poppins.cd2.avi?"

2009/07/16 02:01:38 [debug] 55481#0: *594615 add cleanup: 290396A8
2009/07/16 02:01:38 [debug] 55481#0: *594615 generic phase: 6
2009/07/16 02:01:38 [debug] 55481#0: *594615 limit_req: -2 0.308
2009/07/16 02:01:38 [warn] 55481#0: *594615 delaying request, excess: 0.308, by zone "avi", client: 217.118.90.158, server: inka.arjlover.net, request: "GET /filmiki/mary.poppins.cd2.avi HTTP/1.0", host: "inka.arjlover.net", referrer: "http://filmiki.arjlover.net/info/mary.poppins.cd2.avi.html"

2009/07/16 02:01:38 [debug] 55481#0: *594615 event timer add: 130: 308:2154782904
2009/07/16 02:01:38 [debug] 55481#0: *594615 event timer del: 130: 2154782904
2009/07/16 02:01:38 [debug] 55481#0: *594615 http run request: "/filmiki/mary.poppins.cd2.avi?"

2009/07/16 02:01:38 [debug] 55481#0: *594615 limit_req delay
2009/07/16 02:01:38 [debug] 55481#0: *594615 generic phase: 6
2009/07/16 02:01:38 [debug] 55481#0: *594615 generic phase: 7
2009/07/16 02:01:38 [debug] 55481#0: *594615 add cleanup: 290396C4

2009/07/16 02:01:38 [debug] 55481#0: *594615 limit zone: 7D873670 2
2009/07/16 02:01:38 [debug] 55481#0: *594615 access phase: 8
2009/07/16 02:01:38 [debug] 55481#0: *594615 access phase: 9
2009/07/16 02:01:38 [debug] 55481#0: *594615 post access phase: 10

2009/07/16 02:01:38 [debug] 55481#0: *594615 content phase: 11
2009/07/16 02:01:38 [debug] 55481#0: *594615 content phase: 12
2009/07/16 02:01:38 [debug] 55481#0: *594615 content phase: 13
2009/07/16 02:01:38 [debug] 55481#0: *594615 content phase: 14

2009/07/16 02:01:38 [debug] 55481#0: *594615 content phase: 15
2009/07/16 02:01:38 [debug] 55481#0: *594615 http filename: "/data/filmiki/mary.poppins.cd2.avi"
2009/07/16 02:01:38 [debug] 55481#0: *594615 add cleanup: 290396FC

2009/07/16 02:01:38 [debug] 55481#0: *594615 http static fd: 163
2009/07/16 02:01:38 [debug] 55481#0: *594615 http set discard body
2009/07/16 02:01:38 [debug] 55481#0: *594615 HTTP/1.1 206 Partial Content
2009/07/16 02:01:38 [debug] 55481#0: *594615 write new buf t:1 f:0 29039898, pos 29039898, size: 292 file: 0, size: 0

2009/07/16 02:01:38 [debug] 55481#0: *594615 http write filter: l:0 f:0 s:292
2009/07/16 02:01:38 [debug] 55481#0: *594615 http output filter "/filmiki/mary.poppins.cd2.avi?"
2009/07/16 02:01:38 [debug] 55481#0: *594615 http range body buf: 0-734515200

2009/07/16 02:01:38 [debug] 55481#0: *594615 copy filter: "/filmiki/mary.poppins.cd2.avi?"
2009/07/16 02:01:38 [debug] 55481#0: *594615 http postpone filter "/filmiki/mary.poppins.cd2.avi?" 7FBFE8F0

2009/07/16 02:01:38 [debug] 55481#0: *594615 write old buf t:1 f:0 29039898, pos 29039898, size: 292 file: 0, size: 0
2009/07/16 02:01:38 [debug] 55481#0: *594615 write new buf t:0 f:1 00000000, pos 00000000, size: 0 file: 575302136, size: 159213064

2009/07/16 02:01:38 [debug] 55481#0: *594615 http write filter: l:1 f:0 s:159213356
2009/07/16 02:01:38 [debug] 55481#0: *594615 http write filter limit 65536
2009/07/16 02:01:38 [debug] 55481#0: *594615 tcp_nopush

2009/07/16 02:01:38 [debug] 55481#0: *594615 sendfile() sent only 30508 bytes (35: Resource temporarily unavailable)
2009/07/16 02:01:38 [debug] 55481#0: *594615 sendfile: -1, @575302136 30508:67080
2009/07/16 02:01:38 [debug] 55481#0: *594615 http write filter 29039A0C

2009/07/16 02:01:38 [debug] 55481#0: *594615 copy filter: -2 "/filmiki/mary.poppins.cd2.avi?"
2009/07/16 02:01:38 [debug] 55481#0: *594615 http finalize request: -2, "/filmiki/mary.poppins.cd2.avi?" 1

2009/07/16 02:01:38 [debug] 55481#0: *594615 event timer add: 130: 40000:2154822906
2009/07/16 02:01:38 [debug] 55481#0: *594615 kevent set event: 130: ft:-2 fl:0025
2009/07/16 02:02:18 [debug] 55481#0: *594615 event timer del: 130: 2154822906

2009/07/16 02:02:18 [debug] 55481#0: *594615 http run request: "/filmiki/mary.poppins.cd2.avi?"
2009/07/16 02:02:18 [debug] 55481#0: *594615 http writer handler: "/filmiki/mary.poppins.cd2.avi?"

2009/07/16 02:02:18 [info] 55481#0: *594615 client timed out (60: Operation timed out) while sending response to client, client: 217.118.90.158, server: inka.arjlover.net, request: "GET /filmiki/mary.poppins.cd2.avi HTTP/1.0", host: "inka.arjlover.net", referrer: "http://filmiki.arjlover.net/info/mary.poppins.cd2.avi.html"

2009/07/16 02:02:18 [debug] 55481#0: *594615 http finalize request: 408, "/filmiki/mary.poppins.cd2.avi?" 1
2009/07/16 02:02:18 [debug] 55481#0: *594615 http close request
2009/07/16 02:02:18 [debug] 55481#0: *594615 http log handler

2009/07/16 02:02:18 [debug] 55481#0: *594615 http geo started: 217.118.90.158
2009/07/16 02:02:18 [debug] 55481#0: *594615 http geo: ZZ
2009/07/16 02:02:18 [debug] 55481#0: *594615 run cleanup: 290396FC
2009/07/16 02:02:18 [debug] 55481#0: *594615 file cleanup: fd:163

2009/07/16 02:02:18 [debug] 55481#0: *594615 run cleanup: 290396C4
2009/07/16 02:02:18 [debug] 55481#0: *594615 free: 29039000, unused: 1211
2009/07/16 02:02:18 [debug] 55481#0: *594615 close http connection: 130

2009/07/16 02:02:18 [debug] 55481#0: *594615 free: 29030800
2009/07/16 02:02:18 [debug] 55481#0: *594615 free: 29030400
2009/07/16 02:02:18 [debug] 55481#0: *594615 free: 2846FF00, unused: 56


Как я понимаю - коннект ушел на удержание, но оборвался через время равное  send_timeout 40s; 
Фича? Конфликт двух настроек? Но вылазит только на "Download Master"? Истина где-то рядом.... :)

Антон.

2009/7/15 Михаил Монашёв <postmaster@xxxxxxxxxxxxx>

Здравствуйте, Антон.

Залогируй  в  существующем  логе  ещё  два  параметра:  юзерагента   и
заголовок  Range.  Найди  строчки,  вызывающие  подозрение.  И  в этих
подозрительных  строчках  возьми  ip  и  по нему отфильтруй всю сессию
качания  от  начала  и  до конца. И если лог выйдет небольшой, то кинь
сюда. Если большой, то дай на неё ссылку.


P.S.
Возможный  вывод  -  переполняется  зона.  Посчитай на пике количество
уникальных  ip,  умнож  на  два  для верности и рассчитай размер зоны.
Игорь тут как-то писал сколько на один ip тратится памяти в зоне.

--

С уважением,
Михаил Монашёв, SoftSearch.ru
mailto:postmaster@xxxxxxxxxxxxx
ICQ# 166233339
http://michael.mindmix.ru/
Без бэкапа по жизни.

-- 
Best regards,
Anton Kuznetsov.