Постоянные обрывы коннектов

Maxim Dounin mdounin at mdounin.ru
Thu Jul 16 06:15:13 MSD 2009 

Hello!

On Thu, Jul 16, 2009 at 12:32:58AM +0200, Anton Kuznetsov wrote:

> 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;

Ушёл, дождался окончания задержки, начал отправлять данные 
клиенту, забил tcp'шный буфер на отправку, ушёл дожидаться пока 
клиенту из буфера что-нибудь уйдёт.  Клиенту так ничего и не 
отправилось, соединение было закрыто по таймауту.

Для полноты картины неплохо бы ещё поймать tcpdump подобной сессии 
(достаточно просто заголовков, без содержимого пакетов), и 
рассматривать вместе с debug log'ом.

> Фича? Конфликт двух настроек? Но вылазит только на "Download Master"? Истина
> где-то рядом.... :)

У вас случайно никаких файрволов сопровождающихся блокировками не 
настроено?  Очень похоже что где-то по дороге стали просто дропать 
пакеты.  Я сомневаюсь что вышеописанное поведение свойственно 
самому Download Master'у, но вот его неумеренная настойчивость 
вполне может вызывать реакцию всяких скриптов следящих за 
логами...

Maxim Dounin

> 
> Антон.
> 
> 
> 2009/7/15 Михаил Монашёв <postmaster at softsearch.ru>
> 
> > Здравствуйте, Антон.
> >
> > Залогируй  в  существующем  логе  ещё  два  параметра:  юзерагента   и
> > заголовок  Range.  Найди  строчки,  вызывающие  подозрение.  И  в этих
> > подозрительных  строчках  возьми  ip  и  по нему отфильтруй всю сессию
> > качания  от  начала  и  до конца. И если лог выйдет небольшой, то кинь
> > сюда. Если большой, то дай на неё ссылку.
> >
> >
> > P.S.
> > Возможный  вывод  -  переполняется  зона.  Посчитай на пике количество
> > уникальных  ip,  умнож  на  два  для верности и рассчитай размер зоны.
> > Игорь тут как-то писал сколько на один ip тратится памяти в зоне.
> >
> >
> > --
> >
> > С уважением,
> > Михаил Монашёв, SoftSearch.ru
> > mailto:postmaster at softsearch.ru
> > ICQ# 166233339
> > http://michael.mindmix.ru/
> > Без бэкапа по жизни.
> >
> >
> >
> 
> 
> -- 
> Best regards,
> Anton Kuznetsov.

More information about the nginx-ru mailing list