Неожиданная перезагрузка EJabberd — как такое возможно?

Здравствуйте, специалисты по Linux, Erlang и/или EJabberd.

Я столкнулся с очень странной (и даже невероятной) ситуацией при использовании EJabberd. Необъяснимость произошедшего очень заинтересовала, но собственное расследование ни к чему не привело. Надеюсь на помощь сообщества.

Исходные данные: VDS под Xen, на которой уже полгода крутится Ubuntu 12.04, и стандартные пакеты: изолированный (без S2S) EJabberd и RabbitMQ. За всё это время оба приложения перезагружались только планово при обновлениях или перезагрузках всего сервера, в остальном работали стабильно. К ejabberd локально подключен jabber-bot.

Недавно, пересматривая логи, обнаружил что бот терял связь с сервером на 40 секунд. Удивился, не сеть localhost же отваливался — посмотрел больше. И тут началось интересное.

Исходя из логов и таблицы процессов оказалось что процесс с Erlang VM (beam) был перезагружен. Время создание beam-процесса и его внутренний uptime (ejabberdctl stats uptimeseconds) конечно же соответствовали времени отключения бота.

Вопросы: почему упал(?) хвалёный пуленепробиваемый elrang. И, что более интересно, — кто его перезапустил?

Подвох в том, что в стандартном пакете 12.04 он запускается не через upstart (который умеет следить и respawn'ить), а через старый init.d (SysV), который является простым набором скриптов и запущенные процессы не контролирует, "умерла так умерла".

Ejabberd действительно никто не мониторит. "Убитый девяткой" (kill -9) не поднимается.

Перезагрузился только ejabberd. Ни RabbitMQ, ни epmd, ни другие демоны не "пострадали".

Это произошло во время выполнения cron.daily (стандартный набор). Послужило ли это причиной падения и/или поднятия? Возможно, но я не знаю какая связь. И в предыдущие полгода ничего такого не происходило.

Собрал все логи в одну ленту времени, расположил хронологически.

syslog.log: Cron начинает работу:

Oct 25 16:18:01 myhostname CRON[18678]: (root) CMD (test -x /usr/sbin/anacron || ( cd / && run-parts --report /etc/cron.daily ))

ejabberd.log: EJD без видимой причины начинает отключать всех клиентов:

=INFO REPORT==== 2013-10-25 16:22:57 ===
I(<0.16451.0>:ejabberd_c2s:1502) : ({socket_state,tls,{tlssock,#Port<0.8176>,#Port<0.8178>},<0.16450.0>}) Close session for admin@myhostname.com/3977817831382700501260091

=INFO REPORT==== 2013-10-25 16:22:57 ===
I(<0.14970.0>:ejabberd_c2s:1502) : ({socket_state,tls,{tlssock,#Port<0.7808>,#Port<0.7810>},<0.14969.0>}) Close session for support@myhostname.com/11507889201382475822937194

=INFO REPORT==== 2013-10-25 16:22:58 ===
I(<0.14965.0>:ejabberd_c2s:1502) : ({socket_state,gen_tcp,#Port<0.7805>,<0.14964.0>}) Close session for bot@myhostname.com/30615165031382475819899328

ejabberd.log: Некоторые клиенты пробуют вернуться:

=INFO REPORT==== 2013-10-25 16:23:00 ===
I(<0.900.0>:ejabberd_listener:281) : (#Port<0.8261>) Accepted connection {{127,0,0,1},33716} -> {{127,0,0,1},5222}

=INFO REPORT==== 2013-10-25 16:23:00 ===
I(<0.16531.0>:ejabberd_c2s:785) : ({socket_state,gen_tcp,#Port<0.8261>,<0.16530.0>}) Accepted authentication for bot by []

=INFO REPORT==== 2013-10-25 16:23:01 ===
I(<0.16531.0>:ejabberd_c2s:938) : ({socket_state,gen_tcp,#Port<0.8261>,<0.16530.0>}) Opened session for bot@myhostname.com/90172789113827037819693

ejabberd.log: Но сервер тут же выключается:

=INFO REPORT==== 2013-10-25 16:23:02 ===
I(<0.41.0>:ejabberd_app:89) : ejabberd 2.1.10 is stopped in the node ejabberd@myhostname

erlang.log, ejabberd.log: Сервер читает конфигурацию, поднимается:

=PROGRESS REPORT==== 25-Oct-2013::16:23:29 ===
          supervisor: {local,ejabberd_sup}
             started: [{pid,<0.247.0>},
                       {name,ejabberd_hooks},
                       {mfargs,{ejabberd_hooks,start_link,[]}},
                       {restart_type,permanent},
                       {shutdown,brutal_kill},
                       {child_type,worker}]
=WARNING REPORT==== 2013-10-25 16:23:29 ===
W(<0.41.0>:ejabberd_config:260) : The option 'modules' is disallowed, and will not be accepted

=INFO REPORT==== 2013-10-25 16:23:31 ===
I(<0.41.0>:ejabberd_app:72) : ejabberd 2.1.10 is started in the node ejabberd@myhostname

ejabberd.log: Возвращаются клиенты:

=INFO REPORT==== 2013-10-25 16:23:32 ===
I(<0.892.0>:ejabberd_listener:281) : (#Port<0.3285>) Accepted connection {{127,0,0,1},33730} -> {{127,0,0,1},5222}

=INFO REPORT==== 2013-10-25 16:23:32 ===
I(<0.895.0>:ejabberd_c2s:785) : ({socket_state,gen_tcp,#Port<0.3285>,<0.894.0>}) Accepted authentication for bot by []

=INFO REPORT==== 2013-10-25 16:23:32 ===
I(<0.895.0>:ejabberd_c2s:938) : ({socket_state,gen_tcp,#Port<0.3285>,<0.894.0>}) Opened session for bot@myhostname.com/21300376551382703812415798

syslog.log: При этом cron всё ещё работает.

Oct 25 16:23:38 myhostname rsyslogd: [origin software="rsyslogd" swVersion="5.8.6" x-pid="454" x-info="http://www.rsyslog.com"] rsyslogd was HUPed

Гипотезы, аргументы и вопросы:

1. Это просто был очень редкий гейзенбаг. Но кто же тогда перезапустил демона?

2. Cron перезапустил процесс для каких-то своих целей. Но раньше такого никогда не случалось. Да и слишком топорно для сетевого сервера.

3. Ejabberd решил перезапуститься по какой-то причине. Критическая ошибка, плановая перезагрузка (поискал в документации и коде про это — не нашёл). Похоже, потому что перезагрузка была мягкая, вначале отключались клиенты, в потом завершился процесс. Но почему тогда перезагрузилась сама VM? Обычно EJD рестартует внутри VM (ejabberdctl restart).

4. Erlang VM решил перезапуститься по какой-то причине. Если это критическая ошибка, то вряд ли EJD успел бы плавно отключить всех клиентов. Если плановая перезагрузка —… мы же про Erlang говорим, а не про Win95.

5. Это так Xen шалит. Не работал с ним, не в курсе его возможностей и особенностей. Но странно, если он отстреливает и перезапускает процессы.

6. Я проглядел монитор-респаунер EJD. Почему он тогда не поднимается после kill -9? Ну всякое бывает, раскройте мне глаза.

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

  • Вопрос задан
  • 3755 просмотров
Пригласить эксперта
Ответы на вопрос 1

Очень похоже, что сработал супервизор Erlang/OTP. См.: http://www.erlang.org/doc/design_principles/sup_princ.html (что очевидно, как мне кажется).
Вопрос в том, почему он сработал. Могу предположить, что память закончилась или попортилась.
Crash-дампы не сохранились? (они обычно в пишутся в директорию, куда ведутся логи).
Вообще, конечно, мало информации: erlang.log надо смотреть полностью + ejabberd.log за несколько минут до того, как началось отключение клиентов.

Ответ написан
Ваш ответ на вопрос

Войдите, чтобы написать ответ

Войти через центр авторизации
Похожие вопросы