Dear all,
I had ejabberd 2.1.6 (CentOS5) running for 4 years without problems, now I upgraded to 15.02 (CentOS7) and it sometimes crashes.
In error.log I can find 2 different errors:
2015-03-12 10:56:21.874 [error] <0.972.0> gen_fsm <0.972.0> in state session_established terminated with reason: {badxml,{xmlel,<<"message">>,[{<<"from">>,<<"XXXXX@student.tugraz.at">>},{<<"to">>,<<"YYYYY@tugraz.at/39155994301426154180551869">>}],[{xmlel,<<"event">>,[{<<"xmlns">>,<<"http://jabber.org/protocol/pubsub#event">>}],[{xmlel,<<"items">>,[{<<"node">>,<<"http://jabber.org/protocol/nick">>}],[{xmlel,<<"item">>,[{<<"id">>,"52AB55372805B"}],[{xmlelement,"nick",[{"xmlns","http://jabber.org/protocol/nick"}],[{xmlcdata,<<"lava">>}]}]}]}]},{xmlel,<<"delay">>,[{<<"xmlns">>,<<"urn:xmpp:delay">>},...],...},...]},...} in xml:element_to_string/1 line 122and
2015-03-12 10:56:21.875 [error] <0.353.0> Supervisor ejabberd_c2s_sup had child undefined started with {ejabberd_c2s,start_link,undefined} at <0.972.0> exit with reason {badxml,{xmlel,<<"message">>,[{<<"from">>,<<"XXXXX@student.tugraz.at">>},{<<"to">>,<<"YYYYY@tugraz.at/39155994301426154180551869">>}],[{xmlel,
<<"event">>,[{<<"xmlns">>,<<"http://jabber.org/protocol/pubsub#event">>}],[{xmlel,<<"items">>,[{<<"node">>,<<"http://jabber.org/protocol/nick">>}],[{xmlel,<<"item">>,[{<<"id">>,"52AB55372805B"}],[{xmlelement,"nick",[{"xmlns","http://jabber.org/protocol/nick"}],[{xmlcdata,<<"lava">>}]}]}]}]},{xmlel,<<"delay">>,[{<<"xmlns">>,<<"urn:xmpp:delay">>},...],...},...]},...} in xml:element_to_string/1 line 122 in context child_terminatedany hints?
TIA
Reinfried
Which contributed modules are
Which contributed modules are you using ?
We suspect your problem comes from a contributed module that is not yet updated.
mod_admin_extra I can show
mod_admin_extra
I can show crash.log - but entries are very long ...
You could post your log file
You could post your log file to a pastebin and share the link here if it is big.
What I can say now: Messages
What I can say now: Messages (OSX) works without any problems, Psi+ and Pidgin don't work:
error.log:
2015-03-17 09:56:14.868 [error] <0.17108.0> gen_fsm <0.17108.0> in state session_established terminated with reason: {badxml,{xmlel,<<"message">>,[{<<"from">>,<<"my.default@student.tugraz.at">>},{<<"to">>,<<"my.default@student.tugraz.at/Psi+">>}],[{xmlel,<<"event">>,[{<<"xmlns">>,<<"http://jabber.org/protocol/pubsub#event">>}],[{xmlel,<<"items">>,[{<<"node">>,<<"http://jabber.org/protocol/tune">>}],[{xmlel,<<"item">>,[{<<"id">>,"current"}],[{xmlcdata,<<"\n">>},{xmlelement,"tune",[{"xmlns","http://jabber.org/protocol/tune"}],[]},{xmlcdata,<<"\n">>}]}]}]},{xmlel,<<"delay">>,[{<<"xmlns">>,<<"urn:xmpp:delay">>},...],...},...]},...} in xml:element_to_string/1 line 1222015-03-17 09:56:14.870 [error] <0.17108.0> CRASH REPORT Process <0.17108.0> with 0 neighbours exited with reason: {badxml,{xmlel,<<"message">>,[{<<"from">>,<<"my.default@student.tugraz.at">>},{<<"to">>,<<"my.default@student.tugraz.at/Psi+">>}],[{xmlel,<<"event">>,[{<<"xmlns">>,<<"http://jabber.org/protocol/pubsub#event">>}],[{xmlel,<<"items">>,[{<<"node">>,<<"http://jabber.org/protocol/tune">>}],[{xmlel,<<"item">>,[{<<"id">>,"current"}],[{xmlcdata,<<"\n">>},{xmlelement,"tune",[{"xmlns","http://jabber.org/protocol/tune"}],[]},{xmlcdata,<<"\n">>}]}]}]},{xmlel,<<"delay">>,[{<<"xmlns">>,<<"urn:xmpp:delay">>},...],...},...]},...} in xml:element_to_string/1 line 122 in p1_fsm:terminate/8 line 760
2015-03-17 09:56:14.871 [error] <0.359.0> Supervisor ejabberd_c2s_sup had child undefined started with {ejabberd_c2s,start_link,undefined} at <0.17108.0> exit with reason {badxml,{xmlel,<<"message">>,[{<<"from">>,<<"my.default@student.tugraz.at">>},{<<"to">>,<<"my.default@student.tugraz.at/Psi+">>}],[{xmlel,<<"event">>,[{<<"xmlns">>,<<"http://jabber.org/protocol/pubsub#event">>}],[{xmlel,<<"items">>,[{<<"node">>,<<"http://jabber.org/protocol/tune">>}],[{xmlel,<<"item">>,[{<<"id">>,"current"}],[{xmlcdata,<<"\n">>},{xmlelement,"tune",[{"xmlns","http://jabber.org/protocol/tune"}],[]},{xmlcdata,<<"\n">>}]}]}]},{xmlel,<<"delay">>,[{<<"xmlns">>,<<"urn:xmpp:delay">>},...],...},...]},...} in xml:element_to_string/1 line 122 in context child_terminated
crash.log:
2015-03-17 09:56:14 =ERROR REPORT====** State machine <0.17108.0> terminating
** Last message in was {send_filtered,{pep_message,<<"http://jabber.org/protocol/tune+notify">>},{jid,<<"my.default">>,<<"student.tugraz.at">>,<<>>,<<"my.default">>,<<"student.tugraz.at">>,<<>>},{jid,<<"my.default">>,<<"student.tugraz.at">>,<<"Psi+">>,<<"my.default">>,<<"student.tugraz.at">>,<<"Psi+">>},{xmlel,<<"message">>,[],[{xmlel,<<"event">>,[{<<"xmlns">>,<<"http://jabber.org/protocol/pubsub#event">>}],[{xmlel,<<"items">>,[{<<"node">>,<<"http://jabber.org/protocol/tune">>}],[{xmlel,<<"item">>,[{<<"id">>,"current"}],[{xmlcdata,<<"\n">>},{xmlelement,"tune",[{"xmlns","http://jabber.org/protocol/tune"}],[]},{xmlcdata,<<"\n">>}]}]}]},{xmlel,<<"delay">>,[{<<"xmlns">>,<<"urn:xmpp:delay">>},{<<"from">>,<<"my.default@student.tugraz.at/Psi+">>},{<<"stamp">>,<<"2015-02-24T13:42:33.927Z">>}],[]},{xmlel,<<"x">>,[{<<"xmlns">>,<<"jabber:x:delay">>},{<<"from">>,<<"my.default@student.tugraz.at/Psi+">>},{<<"stamp">>,<<"20150224T13:42:33">>}],[]}]}}
** When State == session_established
** Data == {state,{socket_state,p1_tls,{tlssock,#Port<0.40741>,#Port<0.41360>},<0.17107.0>},ejabberd_socket,#Ref<0.0.3.203468>,false,<<"4264472762">>,undefined,c2s,c2s_shaper,false,true,true,true,[verify_none,compression_none,{protocol_options,<<"no_tlsv1|no_sslv3">>},{certfile,<<"/etc/ssl/certs/jabber.pem">>}],true,{jid,<<"my.default">>,<<"student.tugraz.at">>,<<"Psi+">>,<<"my.default">>,<<"student.tugraz.at">>,<<"Psi+">>},<<"my.default">>,<<"student.tugraz.at">>,<<"Psi+">>,{{1426,582571,230327},<0.17108.0>},{pres_t,4},{pres_f,4},{pres_a,4},{xmlel,<<"presence">>,[{<<"xml:lang">>,<<"en">>}],[{xmlcdata,<<"\n">>},{xmlel,<<"priority">>,[],[{xmlcdata,<<"50">>}]},{xmlcdata,<<"\n">>},{xmlel,<<"c">>,[{<<"xmlns">>,<<"http://jabber.org/protocol/caps">>},{<<"node">>,<<"http://psi-dev.googlecode.com/caps">>},{<<"ver">>,<<"0.16">>},{<<"ext">>,<<"e-time ep-notify-2 html last-act mr">>}],[]},{xmlcdata,<<"\n">>},{xmlel,<<"x">>,[{<<"xmlns">>,<<"vcard-temp:x:update">>}],[{xmlcdata,<<"\n">>},{xmlel,<<"photo">>,[],[{xmlcdata,<<"6c315463b18b830836b94c619cf8cb1b37a146b5">>}]},{xmlcdata,<<"\n">>}]},{xmlcdata,<<"\n">>}]},{1426,582574,791034},{userlist,<<"blocked">>,[{listitem,none,none,allow,100,true,false,false,false,false}],false},c2s_tls,ejabberd_auth_ldap,{{129,27,236,151},47705},[{caps_resources,{1,{{<<"my.default">>,<<"student.tugraz.at">>,<<"Psi+">>},{caps,<<"http://psi-dev.googlecode.com/caps">>,<<"0.16">>,<<>>,[<<"e-time">>,<<"ep-notify-2">>,<<"html">>,<<"last-act">>,<<"mr">>]},nil,nil}}}],active,[],inactive,undefined,undefined,500,undefined,300,false,0,0,<<"en">>}
** Reason for termination =
** {{badxml,{xmlel,<<"message">>,[{<<"from">>,<<"my.default@student.tugraz.at">>},{<<"to">>,<<"my.default@student.tugraz.at/Psi+">>}],[{xmlel,<<"event">>,[{<<"xmlns">>,<<"http://jabber.org/protocol/pubsub#event">>}],[{xmlel,<<"items">>,[{<<"node">>,<<"http://jabber.org/protocol/tune">>}],[{xmlel,<<"item">>,[{<<"id">>,"current"}],[{xmlcdata,<<"\n">>},{xmlelement,"tune",[{"xmlns","http://jabber.org/protocol/tune"}],[]},{xmlcdata,<<"\n">>}]}]}]},{xmlel,<<"delay">>,[{<<"xmlns">>,<<"urn:xmpp:delay">>},{<<"from">>,<<"my.default@student.tugraz.at/Psi+">>},{<<"stamp">>,<<"2015-02-24T13:42:33.927Z">>}],[]},{xmlel,<<"x">>,[{<<"xmlns">>,<<"jabber:x:delay">>},{<<"from">>,<<"my.default@student.tugraz.at/Psi+">>},{<<"stamp">>,<<"20150224T13:42:33">>}],[]}]},{function_clause,[{xml,'-crypt/1-lbc$^0/2-0-',["current",<<>>],[{file,"src/xml.erl"},{line,152}]},{xml,attr_to_list,1,[{file,"src/xml.erl"},{line,149}]},{xml,'-attrs_to_list/1-lc$^0/1-0-',1,[{file,"src/xml.erl"},{line,146}]},{xml,element_to_string_nocatch,1,[{file,"src/xml.erl"},{line,136}]},{xml,'-element_to_string_nocatch/1-lc$^0/1-0-',1,[{file,"src/xml.erl"},{line,137}]},{xml,element_to_string_nocatch,1,[{file,"src/xml.erl"},{line,137}]},{xml,'-element_to_string_nocatch/1-lc$^0/1-0-',1,[{file,"src/xml.erl"},{line,137}]},{xml,element_to_string_nocatch,1,[{file,"src/xml.erl"},{line,137}]}]}},[{xml,element_to_string,1,[{file,"src/xml.erl"},{line,122}]},{xml,element_to_binary,1,[{file,"src/xml.erl"},{line,111}]},{ejabberd_c2s,send_element,2,[{file,"src/ejabberd_c2s.erl"},{line,1912}]},{ejabberd_c2s,send_stanza,2,[{file,"src/ejabberd_c2s.erl"},{line,1927}]},{ejabberd_c2s,handle_info,3,[{file,"src/ejabberd_c2s.erl"},{line,1774}]},{p1_fsm,handle_msg,10,[{file,"src/p1_fsm.erl"},{line,582}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,239}]}]}
2015-03-17 09:56:14 =CRASH REPORT====
crasher:
initial call: gen:init_it/6
pid: <0.17108.0>
registered_name: []
exception exit: {{{badxml,{xmlel,<<"message">>,[{<<"from">>,<<"my.default@student.tugraz.at">>},{<<"to">>,<<"my.default@student.tugraz.at/Psi+">>}],[{xmlel,<<"event">>,[{<<"xmlns">>,<<"http://jabber.org/protocol/pubsub#event">>}],[{xmlel,<<"items">>,[{<<"node">>,<<"http://jabber.org/protocol/tune">>}],[{xmlel,<<"item">>,[{<<"id">>,"current"}],[{xmlcdata,<<"\n">>},{xmlelement,"tune",[{"xmlns","http://jabber.org/protocol/tune"}],[]},{xmlcdata,<<"\n">>}]}]}]},{xmlel,<<"delay">>,[{<<"xmlns">>,<<"urn:xmpp:delay">>},{<<"from">>,<<"my.default@student.tugraz.at/Psi+">>},{<<"stamp">>,<<"2015-02-24T13:42:33.927Z">>}],[]},{xmlel,<<"x">>,[{<<"xmlns">>,<<"jabber:x:delay">>},{<<"from">>,<<"my.default@student.tugraz.at/Psi+">>},{<<"stamp">>,<<"20150224T13:42:33">>}],[]}]},{function_clause,[{xml,'-crypt/1-lbc$^0/2-0-',["current",<<>>],[{file,"src/xml.erl"},{line,152}]},{xml,attr_to_list,1,[{file,"src/xml.erl"},{line,149}]},{xml,'-attrs_to_list/1-lc$^0/1-0-',1,[{file,"src/xml.erl"},{line,146}]},{xml,element_to_string_nocatch,1,[{file,"src/xml.erl"},{line,136}]},{xml,'-element_to_string_nocatch/1-lc$^0/1-0-',1,[{file,"src/xml.erl"},{line,137}]},{xml,element_to_string_nocatch,1,[{file,"src/xml.erl"},{line,137}]},{xml,'-element_to_string_nocatch/1-lc$^0/1-0-',1,[{file,"src/xml.erl"},{line,137}]},{xml,element_to_string_nocatch,1,[{file,"src/xml.erl"},{line,137}]}]}},[{xml,element_to_string,1,[{file,"src/xml.erl"},{line,122}]},{xml,element_to_binary,1,[{file,"src/xml.erl"},{line,111}]},{ejabberd_c2s,send_element,2,[{file,"src/ejabberd_c2s.erl"},{line,1912}]},{ejabberd_c2s,send_stanza,2,[{file,"src/ejabberd_c2s.erl"},{line,1927}]},{ejabberd_c2s,handle_info,3,[{file,"src/ejabberd_c2s.erl"},{line,1774}]},{p1_fsm,handle_msg,10,[{file,"src/p1_fsm.erl"},{line,582}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,239}]}]},[{p1_fsm,terminate,8,[{file,"src/p1_fsm.erl"},{line,760}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,239}]}]}
ancestors: [ejabberd_c2s_sup,ejabberd_sup,<0.37.0>]
messages: []
links: [#Port<0.41360>,<0.359.0>]
dictionary: [{'$internal_queue_len',0}]
trap_exit: false
status: running
heap_size: 6772
stack_size: 27
reductions: 192293
neighbours:
2015-03-17 09:56:14 =SUPERVISOR REPORT====
Supervisor: {local,ejabberd_c2s_sup}
Context: child_terminated
Reason: {{badxml,{xmlel,<<"message">>,[{<<"from">>,<<"my.default@student.tugraz.at">>},{<<"to">>,<<"my.default@student.tugraz.at/Psi+">>}],[{xmlel,<<"event">>,[{<<"xmlns">>,<<"http://jabber.org/protocol/pubsub#event">>}],[{xmlel,<<"items">>,[{<<"node">>,<<"http://jabber.org/protocol/tune">>}],[{xmlel,<<"item">>,[{<<"id">>,"current"}],[{xmlcdata,<<"\n">>},{xmlelement,"tune",[{"xmlns","http://jabber.org/protocol/tune"}],[]},{xmlcdata,<<"\n">>}]}]}]},{xmlel,<<"delay">>,[{<<"xmlns">>,<<"urn:xmpp:delay">>},{<<"from">>,<<"my.default@student.tugraz.at/Psi+">>},{<<"stamp">>,<<"2015-02-24T13:42:33.927Z">>}],[]},{xmlel,<<"x">>,[{<<"xmlns">>,<<"jabber:x:delay">>},{<<"from">>,<<"my.default@student.tugraz.at/Psi+">>},{<<"stamp">>,<<"20150224T13:42:33">>}],[]}]},{function_clause,[{xml,'-crypt/1-lbc$^0/2-0-',["current",<<>>],[{file,"src/xml.erl"},{line,152}]},{xml,attr_to_list,1,[{file,"src/xml.erl"},{line,149}]},{xml,'-attrs_to_list/1-lc$^0/1-0-',1,[{file,"src/xml.erl"},{line,146}]},{xml,element_to_string_nocatch,1,[{file,"src/xml.erl"},{line,136}]},{xml,'-element_to_string_nocatch/1-lc$^0/1-0-',1,[{file,"src/xml.erl"},{line,137}]},{xml,element_to_string_nocatch,1,[{file,"src/xml.erl"},{line,137}]},{xml,'-element_to_string_nocatch/1-lc$^0/1-0-',1,[{file,"src/xml.erl"},{line,137}]},{xml,element_to_string_nocatch,1,[{file,"src/xml.erl"},{line,137}]}]}},[{xml,element_to_string,1,[{file,"src/xml.erl"},{line,122}]},{xml,element_to_binary,1,[{file,"src/xml.erl"},{line,111}]},{ejabberd_c2s,send_element,2,[{file,"src/ejabberd_c2s.erl"},{line,1912}]},{ejabberd_c2s,send_stanza,2,[{file,"src/ejabberd_c2s.erl"},{line,1927}]},{ejabberd_c2s,handle_info,3,[{file,"src/ejabberd_c2s.erl"},{line,1774}]},{p1_fsm,handle_msg,10,[{file,"src/p1_fsm.erl"},{line,582}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,239}]}]}
Offender: [{pid,<0.17108.0>},{name,undefined},{mfargs,{ejabberd_c2s,start_link,undefined}},{restart_type,temporary},{shutdown,1000},{child_type,worker}]
and look good.
Thanks for update. I think I
Thanks for update. I think I got an idea about what is going on.
How are your PEP / pubsub modules configured ?
For the record, we are now tracking the issue here:
I asked the users to update
I asked the users to update psi+ and pidgin and now it looks good for most of them.
Some of them report other problems (pidgin no says "not authorized"), but I'll check this.
About PEP/pubsub:
mod_pubsub:access_createnode: pubsub_createnode
## reduces resource comsumption, but XEP incompliant
ignore_pep_from_offline: true
## XEP compliant, but increases resource comsumption
## ignore_pep_from_offline: false
last_item_cache: false
plugins:
- "flat"
- "hometree"
- "pep" # pep requires mod_caps
Newest version of Pidgin and
Newest version of Pidgin and Adium can authenticate, but then the client gets Verbindung zum Server verloren: Die Verbindung wurde vom Kommunikationspartner zurückgesetzt which means Lost connection to server. Connection reset by peer
Yes, that's related to your
Yes, that's related to your crash. The issue is that you have old Pubsub data in your database from version 2.1 that ejabberd cannot understand.
That's the point of the ticket I have created on Github. Issue is now well identified. Thanks for reporting this.
Would it help to delete old
Would it help to delete old data and to start from scratch?
How could I do this?
Reinfried
Yes, that clean of pep items
Yes, that clean of pep items would help. What is your pubsub backend ? Do you have special configuration to put it in SQL database or is it the default one (Mnesia) ?
default, no SQL
default, no SQL
Do you need us to provide a
Do you need us to provide a command to clean the pubsub elements ?
That would help - thank you!
That would help - thank you!
To purge all PubSub data from
To purge all PubSub data from default backend (mnesia), you can try the following command in ejabberd debug console, then restart ejabberd. This removes everything from PubSub.
[mnesia:delete_table(T) || T<-[pubsub_last_item,pubsub_state,pubsub_item,pubsub_node,pubsub_subscription]].Thank you - at the moment
Thank you - at the moment crash.log is empty
ok, so it seems you are up
ok, so it seems you are up and running, so all looks good.
Is there anything in
Is there anything in ejabberd.log? I have ejabberd.log and error.log on my BSD machine. Usually the more helpful messages are in ejabberd.log
I stopped ejabberd, then
I stopped ejabberd, then removed the pubsub files from the file system:
$ grep 'SPOOL_DIR=/' `which ejabberdctl`/var/lib/ejabberd
$ rm /var/lib/ejabberd/pubsub*
$ /etc/init.d/ejabber start
This made it work.