[Fixed] Some users cannot connect anymore since 16.09 update - Pubsub errors

Hello,

I finally did the move to upgrade to the latest version. Unfortunately, I cannot manage to make it work to all my users. It works fine for most of the users, but I have one that is always immediately disconnected.

After investigating the log, it is due to the error: 

2016-11-24 00:23:40.450 [error] <0.609.0> gen_fsm <0.609.0>
 in state session_established terminated with reason: bad argument in call to
 fxml:element_to_binary({xmlel,<<"message">>,
  [{<<"from">>,<<"account@server">>},{<<"to">>,<<"account@serv...">>},...],\
...})
 in ejabberd_c2s:send_element/2 line 1934
2016-11-24 00:23:40.453 [error] <0.609.0> CRASH REPORT Process <0.609.0>
 with 0 neighbours exited with reason: bad argument in call to
 fxml:element_to_binary({xmlel,<<"message">>,
  [{<<"from">>,<<"account@server">>},{<<"to">>,<<"account@serv...">>},...],..\
.})
 in ejabberd_c2s:send_element/2 line 1934

A more detailed aspect of the problem seems explained in the crash.log file:

2016-11-24 00:23:40 =ERROR REPORT====
** State machine <0.609.0> terminating
** Last message in was {send_filtered,{pep_message,<<"http://jabber.org/protocol/geoloc+notify">>},{jid,<<"user">>,<<"domain.org">>,<<>>,<<"user">>,<<"domain.org">>,<<>>},{jid,<<"user">>,<<"domain.org">>,<<"user">>,<<"user">>,<<"domain.org">>,<<"user">>},{xmlel,<<"messag\
e">>,[{<<"type">>,<<"headline">>}],[{xmlel,<<"event">>,[{<<"xmlns">>,<<"http://jabber.org/protocol/pubsub#event">>}],[{xmlel,<<"items">>,[{<<"node">>,<<"http://jabber.org/protocol/geoloc">>}],[{xmlel,<<"item">>,[{<<"id">>,"549BDBCB4583D"}],[{xmlelement,"geoloc",[{"xmlns"\
,"http://jabber.org/protocol/geoloc"}],[]}]}]}]},{xmlel,<<"delay">>,[{<<"xmlns">>,<<"urn:xmpp:delay">>},{<<"from">>,<<"user@domain.org/Portable">>},{<<"stamp">>,<<"2012-11-24T17:12:43Z">>}],[{xmlcdata,<<>>}]}]}}
** When State == session_established
**      Data  == {state,{socket_state,fast_tls,{tlssock,#Port<0.32317>,#Port<0.32318>},<0.608.0>},ejabberd_socket,#Ref<0.0.1.13766>,false,<<"10356939927130984092">>,undefined,c2s,c2s_shaper,false,true,false,true,[verify_none,compression_none,{certfile,<<"/etc/ssl/ejabber\
d/domain.org.pem">>}],true,{jid,<<"user">>,<<"domain.org">>,<<"user">>,<<"user">>,<<"domain.org">>,<<"user">>},<<"user">>,<<"domain.org">>,<<"user">>,{{1479,943420,2},<0.609.0>},{pres_t,32},{pres_f,32},{pres_a,2},{xmlel,<<"presence">>,[{<<"xml:lang">>,<<"fr">>}],[{xmlcda\
ta,<<"\n">>},{xmlel,<<"priority">>,[],[{xmlcdata,<<"5">>}]},{xmlcdata,<<"\n">>},{xmlel,<<"c">>,[{<<"xmlns">>,<<"http://jabber.org/protocol/caps">>},{<<"node">>,<<"http://psi-im.org/caps">>},{<<"ver">>,<<"caps-b75d8d2b25">>},{<<"ext">>,<<"cs ep-notify-2 html">>}],[]},{xml\
cdata,<<"\n">>}]},{1479,943420,370064},{userlist,none,[],false},c2s_tls,ejabberd_auth_ldap,{{192,168,0,4},60780},[{caps_resources,{1,{{<<"user">>,<<"domain.org">>,<<"user">>},{caps,<<"http://psi-im.org/caps">>,<<"caps-b75d8d2b25">>,<<>>,[<<"cs">>,<<"ep-notify-2">>,<<"htm\
l">>]},nil,nil}}}],active,inactive,undefined,undefined,1000,undefined,300,300,60000,undefined,false,0,0,0,true,<<"fr">>}
** Reason for termination =
** {badarg,[{fxml,element_to_binary,[{xmlel,<<"message">>,[{<<"from">>,<<"user@domain.org">>},{<<"to">>,<<"user@domain.org/user">>},{<<"type">>,<<"headline">>}],[{xmlel,<<"event">>,[{<<"xmlns">>,<<"http://jabber.org/protocol/pubsub#event">>}],[{xmlel,<<"items">>,[{<<"nod\
e">>,<<"http://jabber.org/protocol/geoloc">>}],[{xmlel,<<"item">>,[{<<"id">>,"549BDBCB4583D"}],[{xmlelement,"geoloc",[{"xmlns","http://jabber.org/protocol/geoloc"}],[]}]}]}]},{xmlel,<<"delay">>,[{<<"xmlns">>,<<"urn:xmpp:delay">>},{<<"from">>,<<"user@domain.org/Portable">\
>},{<<"stamp">>,<<"2012-11-24T17:12:43Z">>}],[{xmlcdata,<<>>}]}]}],[]},{ejabberd_c2s,send_element,2,[{file,"src/ejabberd_c2s.erl"},{line,1934}]},{ejabberd_c2s,send_stanza,2,[{file,"src/ejabberd_c2s.erl"},{line,1944}]},{ejabberd_c2s,handle_info,3,[{file,"src/ejabberd_c2s.\
erl"},{line,1776}]},{p1_fsm,handle_msg,10,[{file,"src/p1_fsm.erl"},{line,582}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,247}]}]}
2016-11-24 00:23:40 =CRASH REPORT====
  crasher:
    initial call: ejabberd_c2s:init/1
    pid: <0.609.0>
    registered_name: []
    exception exit: {{badarg,[{fxml,element_to_binary,[{xmlel,<<"message">>,[{<<"from">>,<<"user@domain.org">>},{<<"to">>,<<"user@domain.org/user">>},{<<"type">>,<<"headline">>}],[{xmlel,<<"event">>,[{<<"xmlns">>,<<"http://jabber.org/protocol/pubsub#event">>}],[{xmlel,<<\
"items">>,[{<<"node">>,<<"http://jabber.org/protocol/geoloc">>}],[{xmlel,<<"item">>,[{<<"id">>,"549BDBCB4583D"}],[{xmlelement,"geoloc",[{"xmlns","http://jabber.org/protocol/geoloc"}],[]}]}]}]},{xmlel,<<"delay">>,[{<<"xmlns">>,<<"urn:xmpp:delay">>},{<<"from">>,<<"user@dom\
ain.org/Portable">>},{<<"stamp">>,<<"2012-11-24T17:12:43Z">>}],[{xmlcdata,<<>>}]}]}],[]},{ejabberd_c2s,send_element,2,[{file,"src/ejabberd_c2s.erl"},{line,1934}]},{ejabberd_c2s,send_stanza,2,[{file,"src/ejabberd_c2s.erl"},{line,1944}]},{ejabberd_c2s,handle_info,3,[{file,\
"src/ejabberd_c2s.erl"},{line,1776}]},{p1_fsm,handle_msg,10,[{file,"src/p1_fsm.erl"},{line,582}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,247}]}]},[{p1_fsm,terminate,8,[{file,"src/p1_fsm.erl"},{line,760}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl\
"},{line,247}]}]}
    ancestors: [<0.601.0>,ejabberd_listeners,ejabberd_sup,<0.63.0>]
    messages: [{send_filtered,{pep_message,<<"http://jabber.org/protocol/nick+notify">>},{jid,<<"anotherUser">>,<<"domain.org">>,<<>>,<<"anotherUser">>,<<"domain.org">>,<<>>},{jid,<<"user">>,<<"domain.org">>,<<"user">>,<<"user">>,<<"domain.org">>,<<"user">>},{xmlel,<<"me\
ssage">>,[{<<"type">>,<<"headline">>}],[{xmlel,<<"event">>,[{<<"xmlns">>,<<"http://jabber.org/protocol/pubsub#event">>}],[{xmlel,<<"items">>,[{<<"node">>,<<"http://jabber.org/protocol/nick">>}],[{xmlel,<<"item">>,[{<<"id">>,"54E4526472AC5"}],[{xmlelement,"nick",[{"xmlns"\
,"http://jabber.org/protocol/nick"}],[{xmlcdata,<<"anotherUser@domain.org">>}]}]}]}]},{xmlel,<<"delay">>,[{<<"xmlns">>,<<"urn:xmpp:delay">>},{<<"from">>,<<"anotherUser@domain.org/numitor">>},{<<"stamp">>,<<"2013-01-15T20:53:56Z">>}],[{xmlcdata,<<>>}]}]}}]
    links: [#Port<0.32318>]
    dictionary: [{'$internal_queue_len',0}]
    trap_exit: false
    status: running
    heap_size: 6772
    stack_size: 27
    reductions: 68283
  neighbours:

It seems like it is a bug to me, but I am not sure I really understand what happens. Thank you for the one who will allow me to solve this.

As you can see most of the

As you can see most of the elements in the XMPP packets are in binary format: <<"something">>, and using the new xmlel. But somewhere in the log I can see plain strings: "something" and the old xmlelement. This probably indicates that migration of data in the database from old format to new format was not complete, maybe due to a bug in ejabberd.

The good news is that apparently the half-migrated data is in the pubsub table. If you are using SQL, try to delete the entries in pubsub tables related to that user. If you are using mnesia, probably you don't know how to do this... is it acceptable for you to delete all the pubsub table contents?

Indeed, I have confirmed it

Indeed, I have confirmed it is related to pubsub data : I managed to allow that user connect by disabling pubsub for the whole server.

However, this is not really a solution, but just a workaround. It is totally acceptable to empty all the pubsub data.

The database system used is Mnesia. Could you please explain me how I can delete the pusub table contents with Mnesia ?

Login to ejabberd WebAdmin ->

Login to ejabberd WebAdmin -> Nodes -> your node -> Database -> on each pubsub table, switch to "delete content" -> then click "Send"

Thank you very much for your

Thank you very much for your precious advice. It allowed me to fixed these users login problems.
Kind regards.

Syndicate content