Re[2]: циклический ресет при закачке файлов

Tue Mar 31 16:48:18 MSD 2009

On Tue, 31 Mar 2009, Vladimir Fursin wrote:

> Tuesday, March 31, 2009, 10:13:53 AM, you wrote:
>
>> On Tue, 31 Mar 2009, Vladimir Fursin wrote:
>
>>> Здравствуйте!
>>>
>>> Для раздачи мультимедийного контента используется следующая
>>> конфигурация - nginx в режиме прокси + апач, выполняющий
>>> в PHP задачу авторизации. Если авторизация успешна, управление
>>> возвращается в nginx, который через internal location отдает файл
>>> клиенту.
>>>        Просматривая логи nginx обнаружил многократно повторяющиеся
>>> записи скачивания с одного и того же URL, одним и тем же клиентским
>>> IP, одной и той же длины. Пример :
>>>
>>> 2009-03-29T04:49:00+0300 XX.XX.XX.XX - - [29/Mar/2009:04:48:59
>>> +0300] "GET /fetch/mp3/hch...Wbg==/kreschenie.mp3 HTTP/1.1" 200 33396
>>> "Mozilla/4.0(compatible; MSIE 5.00; Windows 98)"
>>>
>>> Такого вида записи в логах повторяются с интервалом 1-2 сек и
>>> могут составлять до 30% всех записей лога! С одного и того же
>>> клиентского адреса такие повторяющиеся запросы могут идти сутками.
>>> Причем это не один клиент, таких много - с разных сетей при доступе
>>> на сервера в разных городах, т.е. явление массовое.
>>>
>>> Пытался смотреть на то, что происходит, tcpdump'ом - видно, что
>>> после клиентского GET-запроса сервер отвечает HTTP-заголовком,
>>> начинает передавать содержимое файла и после второго посланного
>>> пакета клиент присылает FIN и RST, после чего все повторяется заново.
>
>> Владимир,
>
>> а чего же вы tcpdump не прислали - он бы сильно помог раобраться что там у
>> вас происходит.
>
>> Ещё понадобится error.log от nginx c debug'ом проблемного соединения.
>
> tcpdump:
> 12:53:40.706993 IP XX.XX.XX.XX.bmc-ea > mass.example.com.http: S 1702467945:1702467945(0) win 65535 <mss 1452,nop,nop,sackOK>
> E..0J. at .}...].Br.....c.Pey.i....p...S...........
> 12:53:40.707023 IP mass.example.com.http > XX.XX.XX.XX.bmc-ea: S 1304190803:1304190803(0) ack 1702467946 win 5840 <mss 1460,nop,nop,sackOK>
> E..0.. at .@.......].Br.P.cM._Sey.jp...............
> 12:53:40.724599 IP XX.XX.XX.XX.bmc-ea > mass.example.com.http: . ack 1 win 65535
> E..(J   @.}...].Br.....c.Pey.jM._TP....2........
> 12:53:40.821980 IP XX.XX.XX.XX.bmc-ea > mass.example.com.http: P 1:545(544) ack 1 win 65535
> E..HJ. at .}...].Br.....c.Pey.jM._TP.......GET /fetch/mp3/435sePBm3kIMjjqen4jQSBLgCvZ
> 12:53:40.822002 IP mass.example.com.http > XX.XX.XX.XX.bmc-ea: . ack 545 win 6528
> E..(.. at .@.......].Br.P.cM._Tey..P.......
> 12:53:40.825764 IP mass.example.com.http > XX.XX.XX.XX.bmc-ea: P 1:233(232) ack 545 win 6528
> E..... at .@.......].Br.P.cM._Tey..P..."...HTTP/1.1 200 OK
> Server: nginx/0.6.35
> Dat
> 12:53:40.825784 IP mass.example.com.http > XX.XX.XX.XX.bmc-ea: . 233:1685(1452) ack 545 win 6528
> E..... at .@..C....].Br.P.cM.`<ey..P...'...RIFF..).AVI LIST~"..hdrlavih8.............
> 12:53:40.845192 IP XX.XX.XX.XX.bmc-ea > mass.example.com.http: . ack 1685 win 65535
> E..(J. at .}...].Br.....c.Pey..M.e.P....~........
> 12:53:40.845208 IP mass.example.com.http > XX.XX.XX.XX.bmc-ea: . 1685:6041(4356) ack 545 win 6528
> E..,.. at .@.......].Br.P.cM.e.ey..P...3.............................................
> 12:53:40.846384 IP XX.XX.XX.XX.bmc-ea > mass.example.com.http: F 545:545(0) ack 1685 win 65535
> E..(J^M at .}...].Br.....c.Pey..M.e.P....}........
> 12:53:40.864201 IP XX.XX.XX.XX.bmc-ea > mass.example.com.http: R 546:546(0) ack 3137 win 0
> E..(J. at .}...].Br.....c.Pey..M.k.P.............

Я вижу, что RST посылает клиент "XX.XX.XX.XX.bmc-ea".

> 12:53:40.864220 IP XX.XX.XX.XX.bmc-ea > mass.example.com.http: R 1702468490:1702468490(0) win 0
> E..(J...}...].Br.....c.Pey..ey..P...}+........
> 12:53:40.866103 IP XX.XX.XX.XX.bmc-ea > mass.example.com.http: R 1702468490:1702468490(0) win 0
> E..(J...}...].Br.....c.Pey..ey..P...}+........
>
>
> debug_log:
> 2009/03/31 12:53:40 [info] 27545#0: *8559903 client closed prematurely connection while sending response to client, client: XX.XX.XX.XX, server: download
> .example.com, request: "GET /fetch/mp3/435sePBm3kIMjjqen4jQSBLgCvZGpgBojLtzIQQl5EKMIAXS4jUL6x9X4CUrWJFUlmkxwRXctR4WvfwPQpAa98s5Wgta0UIUlnterb++TUjtTHFVxFcRVL
> N7
> bYG5wV-8+4SuGOc6x56COMgJ-s-gqOO1TuwjaOo4RX7gLPM9ai2XZO4A-88bXvZZFpMcwYAQ/battlestar_galactica_season_3_%5Bru%5D_part009.avi HTTP/1.1", upstream: "http://127.0
> .0.1:8888/nginx.php?path=XX.XX.XX.XX-435sePBm3kIMjjqen4jQSBLgCvZGpgBojLtzIQQl5EKMIAXS4jUL6x9X4CUrWJFUlmkxwRXctR4WvfwPQpAa98s5Wgta0UIUlnterb%2b%2bTUjtTHFVxFc
> RVLN7bYG5wV-8%2b4SuGOc6x56COMgJ-s-gqOO1TuwjaOo4RX7gLPM9ai2XZO4A-88bXvZZFpMcwYAQ/battlestar_galactica_season_3_[ru]_part009.avi", host: "download.example.c
> om
> ", referrer: "http://video.example.com/browse/series/ru/10364.html"

Это не дебаг - это у вас обычный error.log

Вам надо
- собрать nginx с опцией --with-debug
- добавить в конфиг волшебное слово
   debug_connection XX.XX.XX.XX.bmc-ea;
   (возможно, понадобится ручками разрешить имя и вписать адрес)

Тогда в логе вы увидите примерно такое:

kaa at dl2$ grep --text debug /logs/error.log |head
2009/03/31 13:45:07 [debug] 12244#0: *121 accept: 194.85.1.2 fd:20
2009/03/31 13:45:07 [debug] 12244#0: *121 event timer add: 20: 60000:1542186691
2009/03/31 13:45:07 [debug] 12244#0: *121 kevent set event: 20: ft:-1 fl:0025
2009/03/31 13:45:07 [debug] 12244#0: *121 kevent: 20: ft:-1 fl:0020 ff:00000000 d:671 ud:081520B5
2009/03/31 13:45:07 [debug] 12244#0: *121 post event 081520B4
2009/03/31 13:45:07 [debug] 12244#0: *121 delete posted event 081520B4
2009/03/31 13:45:07 [debug] 12244#0: *121 malloc: 080CD800:640
2009/03/31 13:45:07 [debug] 12244#0: *121 malloc: 080CDC00:1024
2009/03/31 13:45:07 [debug] 12244#0: *121 malloc: 080C9000:4096
2009/03/31 13:45:07 [debug] 12244#0: *121 http process request line
kaa at dl2$

-- 
Best regards,
Andrew Kopeyko <kaa at zvuki.ru>