connection to upstream (PHP FastCGI) timed out

[umask <umask@xxxxxxxxx>]

Доброе утро,



имеется такая схема:



[internet]---[nginx]---[PHP FastCGI]---[MySQL]

~~~~~~~~~~~~~~~~~~~~~\~~~~~~~~~~~~~~~~~~~~~~~~

~~~~~~~~~~~~~~~~~~~~~~\_[imap4|pop3]~~~~~~~~~~~~



В данной схеме nginx представляет собой http-сервер c отдачей php на обработку 
fast-cgi серверу php. Помимо http-сервера nginx выполняет роль 
imap4/pop3-прокси-сервера на imap4/pop3-бэкэнды.

Как и полагается используется внешний http-сервер авторизации, по которому 
nginx выясняет легитимность юзера и юзерский бэкенд. http-сервер авторизации - 
этот тот же самые nginx, код авторизатора написан на php, исполняется он на 
[PHP FastCGI] сервере, этот код обращается к [MySQL].



Во всей это связке все работает хорошо, кроме [PHP FastCGI].

Странность проявила себя в первую же ночь, как только на эту схему дали 
небольшую нагрузку (порядка 10 активных подключений в секунду (т.е. не 
keep-alived, а именна юзеров, которые авторизуются, качают почту по имапу\попу).

В 2 часа 16 минут ночи [PHP FastCGI] сервер перестал обрабатывать запросы.

nginx отдавал gateway timeout.



Вот некоторые выдержки из логов.



логи сервера авторизации:

127.0.0.1 - - [29/Aug/2007:02:13:49 +0400] GET /auth.php HTTP/1.0 "200" 1 "-" 
"-" "-"

127.0.0.1 - - [29/Aug/2007:02:14:41 +0400] GET /auth.php HTTP/1.0 "200" 1 "-" 
"-" "-"

127.0.0.1 - - [29/Aug/2007:02:16:42 +0400] GET /auth.php HTTP/1.0 "200" 1 "-" 
"-" "-"

127.0.0.1 - - [29/Aug/2007:02:16:47 +0400] GET /auth.php HTTP/1.0 "200" 1 "-" 
"-" "-"

127.0.0.1 - - [29/Aug/2007:02:17:52 +0400] GET /auth.php HTTP/1.0 "499" 0 "-" 
"-" "-"

127.0.0.1 - - [29/Aug/2007:02:18:26 +0400] GET /auth.php HTTP/1.0 "499" 0 "-" 
"-" "-"

127.0.0.1 - - [29/Aug/2007:02:18:26 +0400] GET /auth.php HTTP/1.0 "499" 0 "-" 
"-" "-"

127.0.0.1 - - [29/Aug/2007:02:22:48 +0400] GET /auth.php HTTP/1.0 "499" 0 "-" 
"-" "-"

127.0.0.1 - - [29/Aug/2007:02:23:26 +0400] GET /auth.php HTTP/1.0 "499" 0 "-" 
"-" "-"

127.0.0.1 - - [29/Aug/2007:02:23:26 +0400] GET /auth.php HTTP/1.0 "499" 0 "-" 
"-" "-"

127.0.0.1 - - [29/Aug/2007:02:26:16 +0400] GET /auth.php HTTP/1.0 "499" 0 "-" 
"-" "-"

127.0.0.1 - - [29/Aug/2007:02:26:49 +0400] GET /auth.php HTTP/1.0 "499" 0 "-" 
"-" "-"

127.0.0.1 - - [29/Aug/2007:02:28:26 +0400] GET /auth.php HTTP/1.0 "499" 0 "-" 
"-" "-"



access.log http-сервера:

XX.XX.XX.XX - - [29/Aug/2007:02:16:25 +0400] GET /*REMOVED* HTTP/1.1 "200" 2993 
"*REMOVED*" "Opera/9.10 (Windows NT 5.1; U; ru)" "-"

XX.XX.XX.XX - - [29/Aug/2007:02:16:27 +0400] GET /*REMOVED* HTTP/1.1 "200" 3010 
"*REMOVED*" "Opera/9.10 (Windows NT 5.1; U; ru)" "-"

XX.XX.XX.XX - - [29/Aug/2007:02:16:30 +0400] GET /*REMOVED* HTTP/1.1 "200" 4779 
"*REMOVED*" "Opera/9.10 (Windows NT 5.1; U; ru)" "-"

XX.XX.XX.XX - - [29/Aug/2007:02:16:47 +0400] GET /*REMOVED* HTTP/1.1 "499" 0 
"*REMOVED*" "Opera/9.10 (Windows NT 5.1; U; ru)" "-"

XX.XX.XX.XX - - [29/Aug/2007:02:16:54 +0400] GET /*REMOVED* HTTP/1.1 "499" 0 
"*REMOVED*" "Opera/9.10 (Windows NT 5.1; U; ru)" "-"

XX.XX.XX.XX - - [29/Aug/2007:02:16:59 +0400] GET /*REMOVED* HTTP/1.1 "499" 0 
"*REMOVED*" "Opera/9.10 (Windows NT 5.1; U; ru)" "-"

XX.XX.XX.XX - - [29/Aug/2007:02:17:01 +0400] GET /*REMOVED* HTTP/1.1 "499" 0 
"*REMOVED*" "Opera/9.10 (Windows NT 5.1; U; ru)" "-"





error.log http-сервера:

2007/08/29 02:18:14 [error] 1186#0: *5304 upstream timed out (110: Connection 
timed out) while reading response header from upstream, client: XX.XX.XX.XX, 
server: XXX, URL: "/*REMOVED*", upstream: "fastcgi://127.0.0.1:9000", host: 
"rupochta.ru", refer

rer: "*REMOVED*"

...

2007/08/29 02:20:04 [info] 6213#0: *6892 client closed prematurely connection, 
so upstream connection is closed too while sending request to upstream, client: 
XX.XX.XX.XX, server: XX, URL: "/", upstream: "fastcgi://127.0.0.1:9000", host: 
"XXX"

...

2007/08/29 02:21:55 [info] 6213#0: *6902 client closed prematurely connection, 
so upstream connection is closed too while sending request to upstream, client: 
XX.XX.XX.XX, server: XXX, URL: "/", upstream: "fastcgi://127.0.0.1:9000", host: 
"XXX"



в error.log'е с 2 часов 17 минут только такие сообщения.

в access.log'е с 2 часов 17 минут все обращения имеют http код 499.



[root@mail]# cat /etc/redhat-release 

CentOS release 5 (Final)

[root@mail]# uname -a

Linux massmail-1 2.6.18-8.1.8.el5 #1 SMP Tue Jul 10 06:50:22 EDT 2007 i686 i686 
i386 GNU/Linux

[root@mail]# rpm -qa | grep php

...

php-5.1.6-12.el5







PHP FastCGI пускается так (под непривелигированном пользователем):

# Tcp-port to bind php-cgi on

FCGIPORT1="9000"



# IP to bind php-cgi on

FCGIADDR1="127.0.0.1"



# Number of PHP children to spawn

PHP_FCGI_CHILDREN1=20



# Number of request before php-process will be restarted

PHP_FCGI_MAX_REQUESTS1=1024



# Path to the php-cgi binary and parameters

COMMAND="/usr/bin/php-cgi -q -b $FCGIADDR1:$FCGIPORT1 -c $CONFIG1 &"



Во время проблемы php-cgi в списке процессор присутствовали, процессор не 
потребляли.



У кого-нибудь есть идеи из-за чего себя так странно повёл FastCGI-сервер?



--

Ilyas