Pull to refresh

История одной проблемы с отключением пользователей Ejabberd после обновления 2.1.13->15.07

Reading time 14 min
Views 4.4K
В связи с тем, что гугль мало помог в решении возникшей проблемы — пусть это останется тут, может кому из коллег-админов поможет сэкономить некоторое количество времени и нервов.
Имеем ejabberd 2.1.13 из портов freebsd (10), полторы сотни зарегистрированных пользователей внутри организации, и некоторую потребность в его обновлении.
Пересобираем (portmaster) erlang (с R16 до R18), перезапускаем ejabberd — имеющиеся в онлайне в вечернее время полтора десятка пользователей успешно переподключились.
Собираем ejabberd, бекап, portmaster ejabberd, рестарт. Конвертируем конфиг в yaml.
Сервер поднимается, полтора десятка клиентов подключились, sendxmpp работает, zabbix тоже заработал, спокойно уходим домой.

С утра выясняется, что у одного из сотрудников не работает клиент (Miranda IM).
То есть происходит подключение, грузится список контактов и тут же — уход в офлайн.
Пробуем шаманства — обновить клиента, поменять на Miranda NG, поменять клиентский комп…
Потом выясняется, что проблема не только у одного пользователя.
У другого пользователя — подключение удается с… дцатой попытки. В логах — только
ejabberd.log
2015-11-25 07:59:06.454 [info] <0.3549.0>@ejabberd_c2s:wait_for_sasl_response:909 ({socket_state,p1_tls,{tlssock,#Port<0.21518>,#Port<0.21520>},<0.3548.0>}) Accepted authentication for USERNAME_vv by ejabberd_auth_internal from 192.168.1.
2015-11-25 07:59:06.673 [info] <0.3549.0>@ejabberd_c2s:wait_for_session:1120 ({socket_state,p1_tls,{tlssock,#Port<0.21518>,#Port<0.21520>},<0.3548.0>}) Opened session for USERNAME_vv@jabber.domain.tld/Miranda
2015-11-25 07:59:08.456 [info] <0.3549.0>@ejabberd_s2s:new_connection:460 New s2s connection started <0.3559.0>
2015-11-25 07:59:08.457 [info] <0.3559.0>@ejabberd_s2s_out:log_s2s_out:1303 Trying to open s2s connection: jabber.domain.tld -> gmail.com with TLS=true
2015-11-25 07:59:08.516 [info] <0.3549.0>@ejabberd_c2s:terminate:1842 ({socket_state,p1_tls,{tlssock,#Port<0.21518>,#Port<0.21520>},<0.3548.0>}) Close session for USERNAME_vv@jabber.domain.tld/Mirand

crash.log
2015-11-25 14:58:41 =ERROR REPORT====
** State machine <0.14519.0> terminating
** Last message in was {send_filtered,{pep_message,<<"http://jabber.org/protocol/mood+notify">>},{jid,<<"USERNAME_vv">>,<<"jabber.domain.tld">>,<<>>,<<"USERNAME_vv">>,<<"jabber.domain.tld">>,<<>>},{jid,<<"USERNAME_vv">>,<<"jabber.domain.tld">>,<<"Miranda">>,<<"USERNAME_vv">>,<<"jabber.domain.tld">>,<<"Miranda">>},{xmlel,<<"message">>,[{<<"type">>,<<"headline">>}],[{xmlel,<<"event">>,[{<<"xmlns">>,<<"http://jabber.org/protocol/pubsub#event">>}],[{xmlel,<<"items">>,[{<<"type">>,<<"headline">>},{<<"node">>,<<"http://jabber.org/protocol/mood">>}],[{xmlel,<<"item">>,[{<<"id">>,"current"}],[{xmlelement,"mood",[{"xmlns","http://jabber.org/protocol/mood"}],[{xmlelement,"invincible",[],[]}]}]}]}]},{xmlel,<<"delay">>,[{<<"xmlns">>,
<<"urn:xmpp:delay">>},{<<"from">>,<<"USERNAME_vv@jabber.domain.tld/Miranda">>},{<<"stamp">>,<<"2012-01-18T06:41:03Z">>}],[{xmlcdata,<<>>}]}]}}
** When State == session_established
** Data == {state,{socket_state,p1_tls,{tlssock,#Port<0.31340>,#Port<0.31342>},<0.14518.0>},ejabberd_socket,#Ref<0.0.1.82499>,false,<<"330053456">>,undefined,c2s,c2s_shaper,false,true,false,true,[verify_none,compression_none,{certfile,<<"/usr/local/etc/ejabberd/ejabberd.pem">>}],true,{jid,<<"USERNAME_vv">>,<<"jabber.domain.tld">>,<<"Miranda">>,<<"USERNAME_vv">>,<<"jabber.domain.tld">>,<<"Miranda">>},<<"USERNAME_vv">>,<<"jabber.domain.tld">>,<<"Miranda">>,{{1448,452720,235717},<0.14519.0>},{pres_t,197},{pres_f,198},{pres_a,82},{xmlel,<<"presence">>,[{<<"xml:lang">>,<<"en">>}],[{xmlel,<<"priority">>,[],[{xmlcdata,<<"0">>}]},{xmlel,<<"c">>,[{<<"xmlns">>,<<"http://jabber.org/protocol/caps">>},{<<"node">>,<<"http://miranda-im.org/caps">>},{<<"ver">>,<<"0.10.39.0">>},{<<"ext">>,<<"mood activity mir_notes">>}],[]},{xmlel,<<"x">>,[{<<"xmlns">>,<<"vcard-temp:x:update">>}],[{xmlel,<<"photo">>,[],[{xmlcdata,<<"75e20de1b840c2e8509aaf1886c806b602e877b4">>}]}]},{xmlel,<<"status">>,[],[{xmlcdata,<<"Yep, I'm here.">>}]}]},{1448,452721,597774},{userlist,none,[],false},c2s_tls,undefined,{{192,168,1,13},51796},[{caps_resources,{18,{{<<"user1">>,<<"jabber.domain.tld">>,<<"Miranda">>},{caps,<<"http://miranda-im.org/caps">>,<<"0.8.9.1">>,<<>>,[<<"mood">>,<<"activity">>,<<"mir_notes">>]},{{<<"user2">>,<<"jabber.domain.tld">>,<<"Miranda">>},{caps,<<"http://miranda-im.org/caps">>,<<"0.8.4.0">>,<<>>,[<<"mood">>,<<"activity">>,<<"mir_notes">>]},{{<<"user3">>,<<"jabber.domain.tld">>,<<"Miranda">>},{caps,<<"http://miranda-ng.org/caps">>,<<"0.95.4.13028">>,<<>>,[<<"x64">>,<<"mood">>,<<"activity">>,<<"mir_notes">>]},{{<<"user4">>,<<"jabber.domain.tld">>,<<"Miranda">>},{caps,<<"http://miranda-im.org/caps">>,<<"0.10.24.0">>,<<>>,[<<"mood">>,<<"activity">>,<<"mir_notes">>]},{{<<"user5">>,<<"jabber.domain.tld">>,<<"Miranda">>},{caps,<<"http://miranda-im.org/caps">>,<<"0.9.41.0">>,<<>>,[<<"mood">>,<<"tune">>,<<"activity">>,<<"mir_notes">>]},{{<<"user7">>,<<"jabber.domain.tld">>,<<"Work">>},{caps,<<"http://miranda-ng.org/caps">>,<<"0.95.4.13028">>,<<>>,[<<"x64">>,<<"cmds">>,<<"mood">>,<<"tune">>,<<"activity">>,<<"mir_notes">>]},{{<<"user8">>,<<"jabber.domain.tld">>,<<"Miranda">>},{caps,<<"http://miranda-im.org/caps">>,<<"0.10.24.0">>,<<>>,[<<"mood">>,<<"activity">>,<<"mir_notes">>]},{{<<"user9">>,<<"jabber.domain.tld">>,<<208,160,208,176,208,177,208,190,209,130,208,176>>},{caps,<<"http://qip.ru/caps">>,<<"9380">>,<<>>,[<<"voice-v1">>]},nil,nil},nil},{{<<"user10">>,<<"jabber.domain.tld">>,<<"QIP">>},{caps,<<"http://qip.ru/caps">>,<<"7221">>,<<>>,[<<"voice-v1">>]},nil,nil}},{{<<"user11">>,<<"jabber.domain.tld">>,<<"Miranda">>},{caps,<<"http://miranda-im.org/caps">>,<<"0.8.4.0">>,<<>>,[<<"mood">>,<<"activity">>,<<"mir_notes">>]},nil,nil}},{{<<"user12">>,<<"jabber.domain.tld">>,<<"OIT-2">>},{caps,<<"http://miranda-im.org/caps">>,<<"0.10.10.0">>,<<>>,[<<"mood">>,<<"activity">>,<<"mir_notes">>]},{{<<"user13">>,<<"jabber.domain.tld">>,<<"Miranda">>},{caps,<<"http://miranda-im.org/caps">>,<<"0.8.4.0">>,<<>>,[<<"mood">>,<<"activity">>,<<"mir_notes">>]},nil,nil},nil}},nil},{{<<"user14">>,<<"jabber.domain.tld">>,<<"Miranda">>},{caps,<<"http://miranda-im.org/caps">>,<<"0.8.4.0">>,<<>>,[<<"mood">>,<<"activity">>,<<"mir_notes">>]},nil,nil}},{{<<"user15">>,<<"jabber.domain.tld">>,<<"QIP">>},{caps,<<"http://qip.ru/caps">>,<<"9380">>,<<>>,[<<"voice-v1">>]},{{<<"user16">>,<<"jabber.domain.tld">>,<<"QIP">>},{caps,<<"http://qip.ru/caps">>,<<"7221">>,<<>>,[<<"voice-v1">>]},{{<<"user17">>,<<"jabber.domain.tld">>,<<"Miranda">>},{caps,<<"http://miranda-ng.org/caps">>,<<"0.95.2.9966">>,<<>>,[<<"x64">>,<<"mood">>,<<"activity">>,<<"mir_notes">>]},nil,nil},nil},{{<<"user18">>,<<"jabber.domain.tld">>,<<"QIP">>},{caps,<<"http://qip.ru/caps">>,<<"8921">>,<<>>,[<<"voice-v1">>]},{{<<"USERNAME_vv">>,<<"jabber.domain.tld">>,<<"Miranda">>},{caps,<<"http://miranda-im.org/caps">>,<<"0.10.39.0">>,<<>>,[<<"mood">>,<<"activity">>,<<"mir_notes">>]},nil,nil},nil}}}}}],active,[],inactive,undefined,undefined,1000,undefined,300,false,0,0,<<"en">>}
** Reason for termination =
** {badarg,[{xml,element_to_binary,[{xmlel,<<"message">>,[{<<"from">>,<<"USERNAME_vv@jabber.domain.tld">>},{<<"to">>,<<"USERNAME_vv@jabber.domain.tld/Miranda">>},{<<"type">>,<<"headline">>}],[{xmlel,<<"event">>,[{<<"xmlns">>,<<"http://jabber.org/protocol/pubsub#event">>}],[{xmlel,<<"items">>,[{<<"type">>,<<"headline">>},{<<"node">>,<<"http://jabber.org/protocol/mood">>}],[{xmlel,<<"item">>,[{<<"id">>,"current"}],[{xmlelement,"mood",[{"xmlns","http://jabber.org/protocol/mood"}],[{xmlelement,"invincible",[],[]}]}]}]}]},{xmlel,<<"delay">>,[{<<"xmlns">>,<<"urn:xmpp:delay">>},{<<"from">>,<<"USERNAME_vv@jabber.domain.tld/Miranda">>},{<<"stamp">>,<<"2012-01-18T06:41:03Z">>}],[{xmlcdata,<<>>}]}]}],[]},{ejabberd_c2s,send_element,2,[{file,"src/ejabberd_c2s.erl"},{line,1910}]},{ejabberd_c2s,send_stanza,2,[{file,"src/ejabberd_c2s.erl"},{line,1920}]},{ejabberd_c2s,handle_info,3,[{file,"src/ejabberd_c2s.erl"},{line,1772}]},{p1_fsm,handle_msg,10,[{file,"src/p1_fsm.erl"},{line,582}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,240}]}]}
2015-11-25 14:58:41 =CRASH REPORT====
crasher:
initial call: gen:init_it/6
pid: <0.14519.0>
registered_name: []
exception exit: {{badarg,[{xml,element_to_binary,[{xmlel,<<"message">>,[{<<"from">>,<<"USERNAME_vv@jabber.domain.tld">>},{<<"to">>,<<"USERNAME_vv@jabber.domain.tld/Miranda">>},{<<"type">>,<<"headline">>}],[{xmlel,<<"event">>,[{<<"xmlns">>,<<"http://jabber.org/protocol/pubsub#event">>}],[{xmlel,<<"items">>,[{<<"type">>,<<"headline">>},{<<"node">>,<<"http://jabber.org/protocol/mood">>}],[{xmlel,<<"item">>,[{<<"id">>,"current"}],[{xmlelement,"mood",[{"xmlns","http://jabber.org/protocol/mood"}],[{xmlelement,"invincible",[],[]}]}]}]}]},{xmlel,<<"delay">>,[{<<"xmlns">>,<<"urn:xmpp:delay">>},{<<"from">>,<<"USERNAME_vv@jabber.domain.tld/Miranda">>},{<<"stamp">>,<<"2012-01-18T06:41:03Z">>}],[{xmlcdata,<<>>}]}]}],[]},{ejabberd_c2s,send_element,2,[{file,"src/ejabberd_c2s.erl"},{line,1910}]},{ejabberd_c2s,send_stanza,2,[{file,"src/ejabberd_c2s.erl"},{line,1920}]},{ejabberd_c2s,handle_info,3,[{file,"src/ejabberd_c2s.erl"},{line,1772}]},{p1_fsm,handle_msg,10,[{file,"src/p1_fsm.erl"},{line,582}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,240}]}]},[{p1_fsm,terminate,8,[{file,"src/p1_fsm.erl"},{line,760}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,240}]}]}
ancestors: [ejabberd_c2s_sup,ejabberd_sup,<0.1543.0>]
messages: []
links: [#Port<0.31342>,<0.1849.0>]
dictionary: [{'$internal_queue_len',0}]
trap_exit: false
status: running
heap_size: 10958
stack_size: 27
reductions: 502300
neighbours:
2015-11-25 14:58:41 =SUPERVISOR REPORT====
Supervisor: {local,ejabberd_c2s_sup}
Context: child_terminated
Reason: {badarg,[{xml,element_to_binary,[{xmlel,<<"message">>,[{<<"from">>,<<"USERNAME_vv@jabber.domain.tld">>},{<<"to">>,<<"USERNAME_vv@jabber.domain.tld/Miranda">>},{<<"type">>,<<"headline">>}],[{xmlel,<<"event">>,[{<<"xmlns">>,<<"http://jabber.org/protocol/pubsub#event">>}],[{xmlel,<<"items">>,[{<<"type">>,<<"headline">>},{<<"node">>,<<"http://jabber.org/protocol/mood">>}],[{xmlel,<<"item">>,[{<<"id">>,"current"}],[{xmlelement,"mood",[{"xmlns","http://jabber.org/protocol/mood"}],[{xmlelement,"invincible",[],[]}]}]}]}]},{xmlel,<<"delay">>,[{<<"xmlns">>,<<"urn:xmpp:delay">>},{<<"from">>,<<"USERNAME_vv@jabber.domain.tld/Miranda">>},{<<"stamp">>,<<"2012-01-18T06:41:03Z">>}],[{xmlcdata,<<>>}]}]}],[]},{ejabberd_c2s,send_element,2,[{file,"src/ejabberd_c2s.erl"},{line,1910}]},{ejabberd_c2s,send_stanza,2,[{file,"src/ejabberd_c2s.erl"},{line,1920}]},{ejabberd_c2s,handle_info,3,[{file,"src/ejabberd_c2s.erl"},{line,1772}]},{p1_fsm,handle_msg,10,[{file,"src/p1_fsm.erl"},{line,582}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,240}]}]}
Offender: [{pid,<0.14519.0>},{id,undefined},{mfargs,{ejabberd_c2s,start_link,undefined}},{restart_type,temporary},{shutdown,1000},{child_type,worker}]


Основная проблема администратора, использующего ejabberd из коробки, — отсутствие знаний и общедоступного опыта с erlang / mnesia db.
Из логов сходу предположить что-либо внятное — не получается. Гугль тоже не спас.
ejabberdctl backup/resore, ejabberdctl dump/load не помогли.

В итоге:
1. Сдампил все таблицы базы mnesia в отдельные текстовые файлы.
ejabberdctl dump_table КУДА.дампить ИМЯ_ТАБЛИЦЫ
#!/bin/sh
for DBNAME in `ls /var/spool/ejabberd/*.DAT | sed 's/\.DAT//' | sed 's/\/var\/spool\/ejabberd\///' `
do
echo $DBNAME .DAT
ejabberdctl dump_table $DBNAME.dump $DBNAME
done
for DBNAME in `ls /var/spool/ejabberd/*.DCD | sed 's/\.DCD//' | sed 's/\/var\/spool\/ejabberd\///' `
do
echo dumping $DBNAME .DCD
ejabberdctl dump_table $DBNAME.dump $DBNAME
done

2. fgrep headline *.dump
видим, что вхождение этого атрибута только в pubsub_node.dump
3. cat pubsub_node.dump |grep jabber.domain.tld |wc -l
80
то есть, 80 человек имеют подобный атрибут, и по всей видимости, они и не работают.
Начинаем читать, что за модуль pubsub, понимаем, что его данные — не критически важные.

4. Грохнем секцию с нашим пользователем из дампа, пробуем его загрузить: ejabberdctl load pubsub_node.dump
Данные только добавляются, удаление секции не произошло.
Чтож, тогда лезем грязными руками — удалим файл таблицы pubsub_node.DCD, перезапустим ejabberd, файл создается, и сделаем загрузку заново.
Проблемный пользователь подключился, проблему локализовали.
Дальше смотрим на
часть содержимого дампа pubsub_node.dump
{pubsub_node,{{<<"dm">>,<<"jabber.domain.tld">>,<<>>},
              <<"http://jabber.org/protocol/mood">>},
             8,[],<<"pep">>,
             [{<<"dm">>,<<"jabber.domain.org">>,<<>>}],
             [{node_type,pep},
              {deliver_payloads,true},
              {notify_config,false},
              {notify_delete,false},
              {notify_retract,false},
              {persist_items,false},
              {max_items,10},
              {subscribe,true},
              {access_model,presence},
              {roster_groups_allowed,[]},
              {publish_model,publishers},
              {max_payload_size,60000},
              {send_last_published_item,on_sub_and_presence},
              {deliver_notifications,true},
              {presence_based_delivery,true}]}.
{pubsub_node,{<<"pubsub.jabber.domain.tld">>,<<"pubsub">>},
             4,[],<<>>,
             [{<<>>,<<"pubsub.jabber.domain.tld">>,<<>>}],
             []}. 

Содержимое не наводит на мысли о его особой ценности — ни ростера, ни архива — ничего важного.
Тогда снова удалим всю таблицу, а с утра все остальные пользователи успешно подключились.

Далее, из подстрок
{<<"stamp">>,<<"2012-01-18T06:41:03Z">>}
и
[{xmlelement,"mood",[{"xmlns","http://jabber.org/protocol/mood"}],[{xmlelement,"invincible"...

и вспоминания истории делаем предположение о причастности ранее используемой на части рабочих станций сборки «Miranda hotcoffee» с некоторым набором плагинов.

Эх, вот если бы еще кто подсказал, что в этом дампе не понравилось ejabberd…
Tags:
Hubs:
-1
Comments 0
Comments Leave a comment

Articles