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

Question

[NoN]

Здравствуйте, специалисты по 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 [e-mail]/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 [e-mail]/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 [e-mail]/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 [e-mail]/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 [e-mail]/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? Ну всякое бывает, раскройте мне глаза.

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

Comments

[jj_killer]

А какая у него реакция на kill -SIGHUP?

[jj_killer]

Да и что более важно на kill -SIGKILL.

[NoN]

Про SIGKILL (-9) уже писал — он молча умирает. SIGHUP проверил сейчас — также умирает и не перезапускается.

[NoN]

Logrotate вместо SIGHUP для EJD использует ejabberdctl reopen-log.

[jj_killer]

Ну тогда самый простой вариант тот, что его кто-то перезапустил вручную. Посмотрите вывод last.

[NoN]

Все простые варианты были рассмотрены в первую очередь. Никаких логинов в те сутки вообще. И доступа к этому серверу нет ни у кого больше.

Я думаю это какая-то неизвестная мне особенность erlang или ejd. Хорошо бы нашёлся специалист в этих делах, да рассказал.

Answer 1

[Иван Осипов]

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

Comments

[NoN]

В ejabberd.log в течение часа до первой приведённой записи ничего не писалось. erlang.log — месяц тишины, а потом всё начинается с <code>supervisor: {local,ejabberd_sup} started: [{pid,<0.247.0>}</code> и десятки других started. Других логов, кордампов и прочего нет. Память во время cronjob наверняка кушается изрядно, это вообще пиковая нагрузка за сутки. Но в swap вполне много места. Да и в syslog было бы что-то сказано, а там тишина. И главный вопрос — supervisor и остальные компоненты работают же внутри одного beam-процесса. Неужели он в случае паники форкается?