connection to upstream (PHP FastCGI) timed out

Wed Aug 29 09:32:21 MSD 2007

Доброе утро,

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

[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 at mail]# cat /etc/redhat-release 

CentOS release 5 (Final)

[root at 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 at 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