zero size reply (200 0 в логах)

[Igor Sysoev]

On Tue, Aug 25, 2009 at 10:49:29PM +0400, Maxim Dounin wrote:

> Hello!
> 
> On Tue, Aug 25, 2009 at 08:59:20PM +0400, Alexander Azarov wrote:
> 
> > Добрый день!
> >
> > Наблюдаю записи в логах со статусом 200 и размером ответа 0. При  
> > рассмотрении debug лога обнаружилось две странности. Первая:
> >
> > 2009/08/25 20:13:16 [info] 17099#0: *1338651 client closed prematurely  
> > connection, so upstream conne
> > ction is closed too while sending request to upstream, client:  
> > 66.249.65.86, server: ***,
> >  request: "GET /forum-52 HTTP/1.1", subrequest: "/news.html", u
> > pstream: "fastcgi://127.0.0.1:9004", host: "***"
> > 2009/08/25 20:13:16 [debug] 17099#0: *1338651 finalize http upstream  
> > request: 499
> >
> > /news.html это SSI вставка. Клиент закрыл соединение, это ОК. Должен был 
> > бы получиться статус 499 и он таковой для подзапроса, однако у запроса в 
> > логе 200. Это баг или фича? Можно ли как-то в логе получить 499?
> 
> Заголовки ответа на основной запрос уходят раньше, чем начинает 
> работать SSI.  Именно код ответа из этих заголовков (т.е. отданный 
> клиенту) логгируется.
> 
> Точно так же для обычного ответа клиент может закрыть соединение 
> раньше, чем получит весь ответ.  В этом случае будет код 200 - но 
> по размеру отданного будет видно, что клиент забрал не всё.
> 
> 499 в логе будет только если клиент закрыл соединение до того, как 
> ему отправили заголовки.

На самом деле, сейчас, если клиент закрыл соедиение в подзапросе, но
nginx уже сформировал заголовок (а на стадии подазпроса он уже есть
всегда), но ещё не передал его в ядро, то будет всё равно 200.

В ближайших версиях, возможно, уже в 0.8.11, в этом случае будет
логироваться 499.

> > Вторая странность. Указанный запрос был от Гугла:
> >
> > 66.249.65.86 - - [25/Aug/2009:20:13:16 +0400] "GET /forum-52 HTTP/1.1"  
> > 200 0 "-" "Mediapartners-Google" 0.027
> >
> > Получен он был в 20:13:16 и в ту же секунду "client closed connection". С 
> > чего бы? Я далек от мысли, что удачно увидел падение гуглобота и, к тому 
> > же, видел такие же "client closed connection в ту же секунду" в других 
> > debug логах. У меня паранойя или?...
> 
> Очень похоже что "Mediapartners-Google" - это такой специальный 
> гугловый бот, расчитанный на нагнетание психологической 
> напряжённости и стимуляцию психических заболеваний среди админов.
> 
> В частности, у себя в логах я вижу:
> 
> 66.249.65.40 - - [17/Aug/2009:17:50:54 +0400] "GET /index2.php?fold=&fil=655 HTTP/1.1" 499 0 "-" "Mediapartners-Google" "pravda.zerok.ru" "-" "-"
> 
> 2009/08/17 17:50:54 [info] 918#0: *1202995 kevent() reported that 
> client closed prematurely connection, so upstream connection is 
> closed too while sending request to upstream, client: 
> 66.249.65.40, server: other, request: "GET 
> /index2.php?fold=&fil=655 HTTP/1.1", upstream: 
> "http://127.0.0.1:80/index2.php?fold=&fil=655", host: 
> "pravda.zerok.ru"
> 
> В общем, имеет смысл забить.
> 
> Maxim Dounin

-- 
Игорь Сысоев
http://sysoev.ru