Ruby Passenger + Ngnix = зависание. В чем может быть причина?

Question

[Stan_1]

На сервере установлено и запущено на разных портах два экземпляра Passenger + Ngnix. Один для среды production, второй для среды test.

До недавнего времени все было хорошо. Но примерно с две недели назад, среда test стала повисать раз в 2-3 дня.

Выглядит это так:
При доступе к серверу он долго молчит и говорит 504 Gateway Timeout. При этом в логах ничего. Делаю re-start, и все работает корректно.

Поскольку production среда работает стабильно, полагаю, проблема в каких-то ошибках в коде, который постоянно разрабатывается и тестируется на test-среде. Но понять в чем причина не могу - в логах все чисто.

Какие существуют средства расширенного мониторинга Passenger? Может быть, есть какие-то детальные логи или еще что? Что можно посоветовать в такой ситуации?

Заранее спасибо!

Comments

[Михаил Алексеев]

Во всех логах пусто? access.log, error.log и production.log

[Stan_1]

В error.log есть такое (как раз перерыв 10 минут (с 01:39:27 по 01:48:57) - это зависание, после которого я делал restart)

[ 2014-06-10 01:30:04.1312 11350/7fcb800a6700 Pool2/Spawner.h:796 ]: [App 31287 stdout]
[ 2014-06-10 01:39:27.9124 11350/7fcb800a6700 Pool2/Spawner.h:796 ]: [App 32506 stdout]
[ 2014-06-10 01:39:30.9159 11350/7fcb800a6700 Pool2/Spawner.h:796 ]: [App 32681 stdout]
2014/06/10 01:48:57 [notice] 1643#0: signal process started
[ 2014-06-10 01:48:57.7487 1646/7f42564c0740 agents/Watchdog/Main.cpp:574 ]: Options: { 'analytics_log_user'
=> 'nobody', 'default_group' => 'www-data', 'default_python' => 'python', 'default_ruby' => '/usr/local/rvm/w
rappers/ruby-2.0.0-p247/ruby', 'default_user' => 'www-data', 'log_level' => '0', 'max_instances_per_app' => '
0', 'max_pool_size' => '6', 'passenger_root' => '/usr/local/rvm/gems/ruby-2.0.0-p247/gems/passenger-4.0.23',
'pool_idle_time' => '300', 'temp_dir' => '/tmp', 'union_station_gateway_address' => 'gateway.unionstationapp.
com', 'union_station_gateway_port' => '443', 'user_switching' => 'true', 'web_server_pid' => '17175', 'web_se
rver_type' => 'nginx', 'web_server_worker_gid' => '33', 'web_server_worker_uid' => '33' }
[ 2014-06-10 01:48:57.7645 1649/7f2eec544740 agents/HelperAgent/Main.cpp:619 ]: PassengerHelperAgent online,
listening at unix:/tmp/passenger.1.0.17175/generation-132/request
[ 2014-06-10 01:48:57.7751 1655/7f09e3379740 agents/LoggingAgent/Main.cpp:318 ]: PassengerLoggingAgent online
, listening at unix:/tmp/passenger.1.0.17175/generation-132/logging
[ 2014-06-10 01:48:57.7754 1646/7f42564c0740 agents/Watchdog/Main.cpp:761 ]: All Phusion Passenger agents sta
rted!

В production.log ничего криминального.

[Михаил Алексеев]

Ваше приложение использует какой-нибудь софт типа Elastic Search, Redis, MongoDB и тд?

[Stan_1]

REDIS с таймаутом 2 секунды, Postgres, MySQL

Answer 1

[Alexey Lesovsky]

попробую угадать, у вас там руби приложение под passenger'ом? включите логирование и смотрите ошибки в development.log (production.log для боевой среды). скорей всего запрос уходит в приложение и там застревает.

Comments

[Stan_1]

Я выше в комментарий бросал кусок лога. Увы. я явных проблем там не вижу. :(

[Alexey Lesovsky]

вы привели кусок лога который принадлежит нжинксу, я предлагаю вам копнуть на уровень ниже ближе к приложению.

[Stan_1]

Там нет ничего. Вот кусок до рестарта

I, [2014-06-10T01:39:30.650653 #32506] INFO -- : Started GET "/user/****/admin/helpdesk/statusbar?user_id=5661" for 198.100.*.* at 2014-06-10 01:39:30 -0400
I, [2014-06-10T01:39:30.684116 #32506] INFO -- : Processing by UserAdminHelpdeskController#statusbar as HTML
I, [2014-06-10T01:39:30.684208 #32506] INFO -- : Parameters: {"user_id"=>"5661", "token"=>"****"}
I, [2014-06-10T01:39:33.669684 #32681] INFO -- : Started GET "/user/*****/admin/helpdesk/statusbar?user_id=5661" for 198.100.*.* at 2014-06-10 01:39:33 -0400
I, [2014-06-10T01:39:33.705268 #32681] INFO -- : Processing by UserAdminHelpdeskController#statusbar as HTML
I, [2014-06-10T01:39:33.705358 #32681] INFO -- : Parameters: {"user_id"=>"5661", "token"=>"******"}

И все. Дальше я его завершаю и рестартую. И лог идет дальше, как ни в чем не бывало.

I, [2014-06-10T01:49:07.396657 #1720] INFO -- : Started GET "/user/***/agreements/stat?stat=pp%2C0%2C0%2C%2C%2Ctc%2C0%2C101" for 85.140.*.* at 2014-06-10 01:49:07 -0400
I, [2014-06-10T01:49:07.432364 #1720] INFO -- : Processing by UserController#agreements_stat as */*
I, [2014-06-10T01:49:07.432455 #1720] INFO -- : Parameters: {"stat"=>"pp,0,0,,,tc,0,101", "token"=>"****"}
I, [2014-06-10T01:49:07.591718 #1720] INFO -- : Filter chain halted as :is_user_access_granted rendered or redirected
I, [2014-06-10T01:49:07.591866 #1720] INFO -- : Completed 200 OK in 159ms (Views: 0.3ms | ActiveRecord: 58.6 ms)

[Alexey Lesovsky]

Вот, то что нужно, рельсовый лог если я не ошибаюсь. Теперь вам надо отловить ситуацию когда у вас происходит "зависание". Обратите внимание на время ответа, в нормальной ситуации оно у вас на уровне нескольких милисекунд. Во время же 504-х, время ответа наверняка переваливает за несколько тысяч ms. В результате nginx просто не дожидается когда ему ответит приложение и отдает клиенту 504.
Грепните этот лог на предмет больших значений времени ответа.

[Stan_1]

Я так обычно и ищу баги. :)

Но в данном случае, проблема в том, что вызов метода в контроллере фиксируется нормальный, а дальше - все. В лог больше ничего не пишется. Я пробовал несколько раз дожидаться ситуации 504, но в логе последняя строка остается

I, [2014-06-10T01:39:33.705358 #32681] INFO -- : Parameters:{"user_id"=>"5661", "token"=>"******"}

При этом Passenger больше не реагирует ни на что, кроме рестарта. В этом и проблема, что не могу локализовать, в чем проблема. :(

[Alexey Lesovsky]

и поди strace пробовали?

[Stan_1]

А вот это поди нет. :) Век живи, век учись. Обязательно попробую. Спасибо!

[Alexey Lesovsky]

если что вот, вдруг пригодится habrahabr.ru/post/215577