по неясным причинам fcgi рвет соединение с nginx
psixozzz at gmail.com
psixozzz at gmail.com
Mon Sep 21 15:55:32 MSD 2009
Приветствую, all.
Возникла следующая ситуация, бьюсь который день уже.
На FreeBSD 7.2 стоит nginx 0.7.62 + spawn-fcgi 1.6.2 + php 5.2.6
Все работает как часы кроме одного единственного момента. При отправке
post-запроса с использованием jquery ajax клиент не получает ответа от
сервера или получает с ооочень большой задержкой. Вот что говорит
nginx, собранный с --debug и error_log = /var/log/nginx-error.log http_debug;
2009/09/21 17:31:37 [debug] 58091#0: *121 http keepalive handler
2009/09/21 17:31:37 [debug] 58091#0: *121 http process request line
2009/09/21 17:31:37 [debug] 58091#0: *121 http request line: "POST /order/?c=240 HTTP/1.1"
2009/09/21 17:31:37 [debug] 58091#0: *121 http uri: "/order/"
2009/09/21 17:31:37 [debug] 58091#0: *121 http args: "c=240"
2009/09/21 17:31:37 [debug] 58091#0: *121 http exten: ""
2009/09/21 17:31:37 [debug] 58091#0: *121 http process request header line
2009/09/21 17:31:37 [debug] 58091#0: *121 http header: "Host: perfectflowers.ru"
2009/09/21 17:31:37 [debug] 58091#0: *121 http header: "User-Agent: Mozilla/5.0 (Windows; U; Windows NT 6.1; ru; rv:1.9.1.3) Gecko/20090824 Firefox/3.5.3"
2009/09/21 17:31:37 [debug] 58091#0: *121 http header: "Accept: */*"
2009/09/21 17:31:37 [debug] 58091#0: *121 http header: "Accept-Language: ru,en-us;q=0.7,en;q=0.3"
2009/09/21 17:31:37 [debug] 58091#0: *121 http header: "Accept-Encoding: gzip,deflate"
2009/09/21 17:31:37 [debug] 58091#0: *121 http header: "Accept-Charset: windows-1251,utf-8;q=0.7,*;q=0.7"
2009/09/21 17:31:37 [debug] 58091#0: *121 http header: "Keep-Alive: 300"
2009/09/21 17:31:37 [debug] 58091#0: *121 http header: "Connection: keep-alive"
2009/09/21 17:31:37 [debug] 58091#0: *121 http header: "Content-Type: application/x-www-form-urlencoded; charset=UTF-8"
2009/09/21 17:31:37 [debug] 58091#0: *121 http header: "X-Requested-With: XMLHttpRequest"
2009/09/21 17:31:37 [debug] 58091#0: *121 http header: "Referer: http://perfectflowers.ru/order/?c=240"
2009/09/21 17:31:37 [debug] 58091#0: *121 http header: "Content-Length: 878"
2009/09/21 17:31:37 [debug] 58091#0: *121 http header: "Cookie: es=1b94254cba970c54560eb6265c51b882; __utma=89191066.535248667.1252935177.1253527786.1253532639.19; __utmz=89191066.1252935177.1.1.utmcsr=(direct)|utmccn=(direct)|utmcmd=(none); es=1b94254cba970c54560eb6265c51b882; __utmc=89191066; __utmb=89191066.1.10.1253532639"
2009/09/21 17:31:37 [debug] 58091#0: *121 http header: "Pragma: no-cache"
2009/09/21 17:31:37 [debug] 58091#0: *121 http header: "Cache-Control: no-cache"
2009/09/21 17:31:37 [debug] 58091#0: *121 http header done
2009/09/21 17:31:37 [debug] 58091#0: *121 generic phase: 0
2009/09/21 17:31:37 [debug] 58091#0: *121 http script complex value
2009/09/21 17:31:37 [debug] 58091#0: *121 http script var: "/home/edws/web/www/order/"
2009/09/21 17:31:37 [debug] 58091#0: *121 http script copy: ""
2009/09/21 17:31:37 [debug] 58091#0: *121 http script file op 0000000000000005 "/home/edws/web/www/order/"
2009/09/21 17:31:37 [debug] 58091#0: *121 http script if
2009/09/21 17:31:37 [debug] 58091#0: *121 http script regex: "^(.*)$"
2009/09/21 17:31:37 [notice] 58091#0: *121 "^(.*)$" matches "/order/", client: 90.157.122.218, server: perfectflowers.ru, request: "POST /order/?c=240 HTTP/1.1", host: "perfectflowers.ru", referrer: "http://perfectflowers.ru/order/?c=240"
2009/09/21 17:31:37 [debug] 58091#0: *121 http script copy: "/index.php"
2009/09/21 17:31:37 [debug] 58091#0: *121 http script regex end
2009/09/21 17:31:37 [notice] 58091#0: *121 rewritten data: "/index.php", args: "c=240", client: 90.157.122.218, server: perfectflowers.ru, request: "POST /order/?c=240 HTTP/1.1", host: "perfectflowers.ru", referrer: "http://perfectflowers.ru/order/?c=240"
2009/09/21 17:31:37 [debug] 58091#0: *121 test location: "/\.ht"
2009/09/21 17:31:37 [debug] 58091#0: *121 test location: ~ "/eventer/"
2009/09/21 17:31:37 [debug] 58091#0: *121 test location: ~ "\.php$"
2009/09/21 17:31:37 [debug] 58091#0: *121 using configuration "\.php$"
2009/09/21 17:31:37 [debug] 58091#0: *121 http cl:878 max:2097152
2009/09/21 17:31:37 [debug] 58091#0: *121 generic phase: 2
2009/09/21 17:31:37 [debug] 58091#0: *121 post rewrite phase: 3
2009/09/21 17:31:37 [debug] 58091#0: *121 generic phase: 4
2009/09/21 17:31:37 [debug] 58091#0: *121 generic phase: 5
2009/09/21 17:31:37 [debug] 58091#0: *121 access phase: 6
2009/09/21 17:31:37 [debug] 58091#0: *121 access phase: 7
2009/09/21 17:31:37 [debug] 58091#0: *121 post access phase: 8
2009/09/21 17:31:37 [debug] 58091#0: *121 http read client request body
2009/09/21 17:31:37 [debug] 58091#0: *121 http client request body recv -2
2009/09/21 17:31:37 [debug] 58091#0: *121 http client request body rest 878
2009/09/21 17:31:38 [debug] 58091#0: *121 http run request: "/index.php?c=240"
2009/09/21 17:31:38 [debug] 58091#0: *121 http read client request body
2009/09/21 17:31:38 [debug] 58091#0: *121 http client request body recv 878
2009/09/21 17:31:38 [debug] 58091#0: *121 http client request body rest 0
2009/09/21 17:31:38 [debug] 58091#0: *121 http init upstream, client timer: 0
2009/09/21 17:31:38 [debug] 58091#0: *121 http script copy: "SCRIPT_FILENAME"
2009/09/21 17:31:38 [debug] 58091#0: *121 http script copy: "/home/edws/web/www"
2009/09/21 17:31:38 [debug] 58091#0: *121 http script var: "/index.php"
2009/09/21 17:31:38 [debug] 58091#0: *121 fastcgi param: "SCRIPT_FILENAME: /home/edws/web/www/index.php"
2009/09/21 17:31:38 [debug] 58091#0: *121 http script copy: "QUERY_STRING"
2009/09/21 17:31:38 [debug] 58091#0: *121 http script var: "c=240"
2009/09/21 17:31:38 [debug] 58091#0: *121 fastcgi param: "QUERY_STRING: c=240"
2009/09/21 17:31:38 [debug] 58091#0: *121 http script copy: "REQUEST_METHOD"
2009/09/21 17:31:38 [debug] 58091#0: *121 http script var: "POST"
2009/09/21 17:31:38 [debug] 58091#0: *121 fastcgi param: "REQUEST_METHOD: POST"
2009/09/21 17:31:38 [debug] 58091#0: *121 http script copy: "CONTENT_TYPE"
2009/09/21 17:31:38 [debug] 58091#0: *121 http script var: "application/x-www-form-urlencoded; charset=UTF-8"
2009/09/21 17:31:38 [debug] 58091#0: *121 fastcgi param: "CONTENT_TYPE: application/x-www-form-urlencoded; charset=UTF-8"
2009/09/21 17:31:38 [debug] 58091#0: *121 http script copy: "CONTENT_LENGTH"
2009/09/21 17:31:38 [debug] 58091#0: *121 http script var: "878"
2009/09/21 17:31:38 [debug] 58091#0: *121 fastcgi param: "CONTENT_LENGTH: 878"
2009/09/21 17:31:38 [debug] 58091#0: *121 http script copy: "SCRIPT_NAME"
2009/09/21 17:31:38 [debug] 58091#0: *121 http script var: "/index.php"
2009/09/21 17:31:38 [debug] 58091#0: *121 fastcgi param: "SCRIPT_NAME: /index.php"
2009/09/21 17:31:38 [debug] 58091#0: *121 http script copy: "REQUEST_URI"
2009/09/21 17:31:38 [debug] 58091#0: *121 http script var: "/order/?c=240"
2009/09/21 17:31:38 [debug] 58091#0: *121 fastcgi param: "REQUEST_URI: /order/?c=240"
2009/09/21 17:31:38 [debug] 58091#0: *121 http script copy: "DOCUMENT_URI"
2009/09/21 17:31:38 [debug] 58091#0: *121 http script var: "/index.php"
2009/09/21 17:31:38 [debug] 58091#0: *121 fastcgi param: "DOCUMENT_URI: /index.php"
2009/09/21 17:31:38 [debug] 58091#0: *121 http script copy: "DOCUMENT_ROOT"
2009/09/21 17:31:38 [debug] 58091#0: *121 http script var: "/home/edws/web/www"
2009/09/21 17:31:38 [debug] 58091#0: *121 fastcgi param: "DOCUMENT_ROOT: /home/edws/web/www"
2009/09/21 17:31:38 [debug] 58091#0: *121 http script copy: "SERVER_PROTOCOL"
2009/09/21 17:31:38 [debug] 58091#0: *121 http script var: "HTTP/1.1"
2009/09/21 17:31:38 [debug] 58091#0: *121 fastcgi param: "SERVER_PROTOCOL: HTTP/1.1"
2009/09/21 17:31:38 [debug] 58091#0: *121 http script copy: "GATEWAY_INTERFACECGI/1.1"
2009/09/21 17:31:38 [debug] 58091#0: *121 fastcgi param: "GATEWAY_INTERFACE: CGI/1.1"
2009/09/21 17:31:38 [debug] 58091#0: *121 http script copy: "SERVER_SOFTWARE"
2009/09/21 17:31:38 [debug] 58091#0: *121 http script copy: "nginx/"
2009/09/21 17:31:38 [debug] 58091#0: *121 http script var: "0.7.62"
2009/09/21 17:31:38 [debug] 58091#0: *121 fastcgi param: "SERVER_SOFTWARE: nginx/0.7.62"
2009/09/21 17:31:38 [debug] 58091#0: *121 http script copy: "REMOTE_ADDR"
2009/09/21 17:31:38 [debug] 58091#0: *121 http script var: "90.157.122.218"
2009/09/21 17:31:38 [debug] 58091#0: *121 fastcgi param: "REMOTE_ADDR: 90.157.122.218"
2009/09/21 17:31:38 [debug] 58091#0: *121 http script copy: "REMOTE_PORT"
2009/09/21 17:31:38 [debug] 58091#0: *121 http script var: "56339"
2009/09/21 17:31:38 [debug] 58091#0: *121 fastcgi param: "REMOTE_PORT: 56339"
2009/09/21 17:31:38 [debug] 58091#0: *121 http script copy: "SERVER_ADDR"
2009/09/21 17:31:38 [debug] 58091#0: *121 http script var: "88.198.65.104"
2009/09/21 17:31:38 [debug] 58091#0: *121 fastcgi param: "SERVER_ADDR: 88.198.65.104"
2009/09/21 17:31:38 [debug] 58091#0: *121 http script copy: "SERVER_PORT"
2009/09/21 17:31:38 [debug] 58091#0: *121 http script var: "80"
2009/09/21 17:31:38 [debug] 58091#0: *121 fastcgi param: "SERVER_PORT: 80"
2009/09/21 17:31:38 [debug] 58091#0: *121 http script copy: "SERVER_NAME"
2009/09/21 17:31:38 [debug] 58091#0: *121 http script var: "perfectflowers.ru"
2009/09/21 17:31:38 [debug] 58091#0: *121 fastcgi param: "SERVER_NAME: perfectflowers.ru"
2009/09/21 17:31:38 [debug] 58091#0: *121 http script copy: "REDIRECT_STATUS200"
2009/09/21 17:31:38 [debug] 58091#0: *121 fastcgi param: "REDIRECT_STATUS: 200"
2009/09/21 17:31:38 [debug] 58091#0: *121 http cleanup add: 0000000801554C98
2009/09/21 17:31:38 [debug] 58091#0: *121 get rr peer, try: 1
2009/09/21 17:31:38 [debug] 58091#0: *121 http upstream connect: -2
2009/09/21 17:31:38 [debug] 58091#0: *121 http upstream request: "/index.php?c=240"
2009/09/21 17:31:38 [debug] 58091#0: *121 http upstream send request handler
2009/09/21 17:31:38 [debug] 58091#0: *121 http upstream send request
2009/09/21 17:31:38 [debug] 58091#0: *121 http upstream request: "/index.php?c=240"
2009/09/21 17:31:38 [debug] 58091#0: *121 http upstream dummy handler
2009/09/21 17:31:56 [debug] 58091#0: *123 http keepalive handler
2009/09/21 17:31:56 [info] 58091#0: *123 kevent() reported that client 90.157.122.218 closed keepalive connection
2009/09/21 17:31:56 [debug] 58091#0: *123 close http connection: 10
2009/09/21 17:31:56 [debug] 58091#0: *124 http keepalive handler
2009/09/21 17:31:56 [info] 58091#0: *124 kevent() reported that client 90.157.122.218 closed keepalive connection
2009/09/21 17:31:56 [debug] 58091#0: *124 close http connection: 13
после этого, через некоторое время видим в логах это:
kevent() reported that client closed prematurely connection, so upstream connection is closed too while sending request to upstream, client: 90.157.122.218, server: perfectflowers.ru, request: "POST /order/?c=240 HTTP/1.1", upstream: "fastcgi://127.0.0.1:1026", host: "perfectflowers.ru", referrer: "http://perfectflowers.ru/order/?c=240"
Из лога видно что запрос проходит nginx, отправляется fast-cgi и
передается php. Путем установки вызова отладочной функции выяснилось,
что и php отрабатывается нормально. Но вот fast-cgi после этого рвет
соединение. Почему - не ясно. Точно такой же скрипт прекрасно работает
на другой машине (читай та же порграмма на другой конфигурации
сервера), т.е. в самом php ошибок нет. Логи ошибок mysql и php молчат.
Да, кстати, Соединение может и рвется судя по логам, а вот судя по
netstat -ln они копятся, пока не заполнят spawn_fcgi_children. В этом
случае помогает только рестарт fcgi.
С точки зрения клиента все это выглядит так: запрос уходит и все,
сервер больше не отвечает.
Искал в гугле и архиве рассылки, видел, что я не одинок, но как решить
проблему так и не нашел. Помогите, пожалуйста, выяснить, в чем же причина
моего хождения по мукам.
--
С уважением,
Вадим Лужбин mailto:psixozzz at gmail.com
More information about the nginx-ru
mailing list