Здравствуйте, специалисты по 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(:ejabberd_c2s:1502): ({socket_state,tls,{tlssock,#Port,#Port},}) Close session for admin@myhostname.com/3977817831382700501260091 =INFO REPORT==== 2013-10-25 16:22:57 === I(:ejabberd_c2s:1502): ({socket_state,tls,{tlssock,#Port,#Port},}) Close session for support@myhostname.com/11507889201382475822937194 =INFO REPORT==== 2013-10-25 16:22:58 === I(:ejabberd_c2s:1502): ({socket_state,gen_tcp,#Port,}) Close session for bot@myhostname.com/30615165031382475819899328

ejabberd.log: Некоторые клиенты пробуют вернуться: =INFO REPORT==== 2013-10-25 16:23:00 === I(:ejabberd_listener:281): (#Port) Accepted connection {{127,0,0,1},33716} -> {{127,0,0,1},5222} =INFO REPORT==== 2013-10-25 16:23:00 === I(:ejabberd_c2s:785): ({socket_state,gen_tcp,#Port,}) Accepted authentication for bot by [] =INFO REPORT==== 2013-10-25 16:23:01 === I(:ejabberd_c2s:938): ({socket_state,gen_tcp,#Port,}) Opened session for bot@myhostname.com/90172789113827037819693

ejabberd.log: Но сервер тут же выключается: =INFO REPORT==== 2013-10-25 16:23:02 === I(: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,}, {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(:ejabberd_config:260): The option 'modules' is disallowed, and will not be accepted =INFO REPORT==== 2013-10-25 16:23:31 === I(: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(:ejabberd_listener:281): (#Port) Accepted connection {{127,0,0,1},33730} -> {{127,0,0,1},5222} =INFO REPORT==== 2013-10-25 16:23:32 === I(:ejabberd_c2s:785): ({socket_state,gen_tcp,#Port,}) Accepted authentication for bot by [] =INFO REPORT==== 2013-10-25 16:23:32 === I(:ejabberd_c2s:938): ({socket_state,gen_tcp,#Port,}) 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=«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? Ну всякое бывает, раскройте мне глаза.

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