Geekly Articles each Day
📜 ⬆️ ⬇️

The story of one problem with disabling Ejabberd users after update 2.1.13-> 15.07

Due to the fact that Google has helped little in solving the problem that has arisen - let it remain here, maybe someone from fellow admins can save some amount of time and nerves.
We have ejabberd 2.1.13 from freebsd (10) ports, one and a half hundred registered users within the organization, and some need for its updating.
We reassemble (portmaster) erlang (from R16 to R18), restart ejabberd - a dozen users who are online in the evening have successfully reconnected.
We collect ejabberd, backup, portmaster ejabberd, restart. We convert a config to yaml.
The server goes up, a dozen clients are connected, sendxmpp is working, zabbix is ​​working too, we are quietly leaving home.

In the morning it turns out that one of the employees does not have a client (Miranda IM).
That is, the connection is made, the list of contacts is loaded, and right there - going offline.
We try shamanism - to update the client, change to Miranda NG, change the client computer ...
Then it turns out that the problem is not just one user.
For another user, the connection is successful from ... the tenth attempt. In logs - only
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}]


The main problem of an administrator using ejabberd out of the box is the lack of knowledge and experience with erlang / mnesia db.
From logs immediately suggest something intelligible - does not work. Google also did not save.
ejabberdctl backup / resore, ejabberdctl dump / load did not help.
')
Eventually:
1. Dump all mnesia database tables into separate text files.
ejabberdctl dump_table WHERE. Dump TABLE NAME
 #!/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
see that the entry of this attribute is only in pubsub_node.dump
3. cat pubsub_node.dump | grep jabber.domain.tld | wc -l
80
that is, 80 people have a similar attribute, and apparently they do not work.
We start reading that for the pubsub module, we understand that its data is not critical.

4. We crash the section with our user from the dump, try to load it: ejabberdctl load pubsub_node.dump
Data is only added, section deletion did not occur.
Well, then we climb with dirty hands - delete the pubsub_node.DCD table file, restart ejabberd, create the file, and reload the file.
The problem user has connected, the problem has been localized.
Look further at
part of the contents of the dump 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">>,<<>>}], []}.

Content does not suggest anything special about its value - neither the roster nor the archive - anything important.
Then we will delete the entire table again, and in the morning all the other users have successfully connected.

Next, from the substrings
{<<"stamp">>,<<"2012-01-18T06:41:03Z">>}

[{xmlelement,"mood",[{"xmlns","http://jabber.org/protocol/mood"}],[{xmlelement,"invincible"...
and recalling the history, we make an assumption about the involvement of the Miranda hotcoffee assembly that was previously used on the part of the workstations with a certain set of plug-ins.

Eh, here if someone else would have suggested that ejabberd did not like this dump ...

Source: https://habr.com/ru/post/271871/

More articles:


All Articles