Hi,
Gentoo-Linux
ejabberd-1.1.3
erlang 11.2.5
since few week I my ejabberd-server cannot connect to other servers. Here an outgoing example. User window:
meAtEjabber: hallohallohallo meOtherJabber: Ihre Nachricht kann nicht zugestellt werden: "hallohallohallo", Grund: ""
Translated: the message could not be sent - reason: " ".
The ejabber-log shows following:
=INFO REPORT==== 22-Nov-2007::18:28:54 === I(<0.410.0>:ejabberd_s2s_out:662): terminated: normal =INFO REPORT==== 22-Nov-2007::18:28:54 === I(<0.411.0>:ejabberd_s2s_out:662): terminated: normal =INFO REPORT==== 22-Nov-2007::18:28:54 === I(<0.412.0>:ejabberd_s2s_out:662): terminated: normal =INFO REPORT==== 22-Nov-2007::18:28:54 === I(<0.413.0>:ejabberd_s2s_out:662): terminated: normal =INFO REPORT==== 22-Nov-2007::18:29:08 === I(<0.416.0>:ejabberd_s2s_out:662): terminated: normal
I already started the ejabber manually with the -kernel... flag from http://www.ejabberd.im/fix-dns-srv . But still no contact to other jabber-servers. Can anyone help me with this problem?
Thanks, H.
honana wrote: I already
I already started the ejabber manually with the -kernel... flag from http://www.ejabberd.im/fix-dns-srv . But still no contact to other jabber-servers. Can anyone help me with this problem?
Looking at your ejabberd logs, it seems ejabberd tries to establish S2S connections. If they are not correctly established, I can think of several reasons:
If you restart ejabberd, you could take a look at ejabberd.log and sasl.log, maybe they indicate an 'ERROR' during the start process.
crashes and data-rescue?
I tried to reinstall ejabberd to be sure to have clean binaries. But since then I even cannont start the ejabberd-server anymore :-(. Every start crashes and gives me a huge (15KB) sasl.log.
After I started /etc/init.d/ejabberd start following processes are running:
7212 ? S 0:00 /usr/lib/erlang/erts-5.5.5/bin/epmd -daemon 7214 ? Sl 0:07 /usr/lib/erlang/erts-5.5.5/bin/beam -- -root /usr/lib/erlang -progname erl -- -home /var/run/jabber -pa /usr/lib/erlang/lib/ejabberd-1.1.3/ebin -sname ejabberd -s ejabberd -ejabberd config "/etc/jabber/ejabberd.cfg" log_path "/var/log/jabber/ejabberd.log" -kernel inetrc "/etc/jabber/inetrc" -sasl sasl_error_logger {file,"/var/log/jabber/sasl.log"} -mnesia dir "/var/spool/jabber" -noshell -noshell -noinput 7228 ? Ss 0:00 /usr/lib/erlang/lib/ssl-3.1.1.1/priv/bin/ssl_esockBut the ejabberd-server is NOT working :-( The Sasl.log-file look like this:
jabber jabber # cat sasl.log =PROGRESS REPORT==== 24-Nov-2007::10:44:31 === supervisor: {local,sasl_safe_sup} started: [{pid,<0.45.0>}, {name,alarm_handler}, {mfa,{alarm_handler,start_link,[]}}, {restart_type,permanent}, {shutdown,2000}, {child_type,worker}] =PROGRESS REPORT==== 24-Nov-2007::10:44:31 === supervisor: {local,sasl_safe_sup} started: [{pid,<0.46.0>}, {name,overload}, {mfa,{overload,start_link,[]}}, {restart_type,permanent}, {shutdown,2000}, {child_type,worker}] =PROGRESS REPORT==== 24-Nov-2007::10:44:31 === supervisor: {local,sasl_sup} started: [{pid,<0.44.0>}, {name,sasl_safe_sup}, {mfa, {supervisor, start_link, [{local,sasl_safe_sup},sasl,safe]}}, {restart_type,permanent}, {shutdown,infinity}, {child_type,supervisor}] =PROGRESS REPORT==== 24-Nov-2007::10:44:31 === supervisor: {local,sasl_sup} started: [{pid,<0.47.0>}, {name,release_handler}, {mfa,{release_handler,start_link,[]}}, {restart_type,permanent}, {shutdown,2000}, {child_type,worker}] =PROGRESS REPORT==== 24-Nov-2007::10:44:31 === application: sasl started_at: ejabberd@jabber =PROGRESS REPORT==== 24-Nov-2007::10:44:31 === supervisor: {local,kernel_safe_sup} started: [{pid,<0.51.0>}, {name,dets_sup}, {mfa,{dets_sup,start_link,[]}}, {restart_type,permanent}, {shutdown,1000}, {child_type,supervisor}] =PROGRESS REPORT==== 24-Nov-2007::10:44:31 === supervisor: {local,kernel_safe_sup} started: [{pid,<0.52.0>}, {name,dets}, {mfa,{dets_server,start_link,[]}}, {restart_type,permanent}, {shutdown,2000}, {child_type,worker}] =PROGRESS REPORT==== 24-Nov-2007::10:44:31 === supervisor: {local,mnesia_sup} started: [{pid,<0.60.0>}, {name,mnesia_event}, {mfa,{mnesia_sup,start_event,[]}}, {restart_type,permanent}, {shutdown,30000}, {child_type,worker}] =PROGRESS REPORT==== 24-Nov-2007::10:44:31 === supervisor: {local,mnesia_kernel_sup} started: [{pid,<0.62.0>}, {name,mnesia_monitor}, {mfa,{mnesia_monitor,start,[]}}, {restart_type,permanent}, {shutdown,3000}, {child_type,worker}] =PROGRESS REPORT==== 24-Nov-2007::10:44:31 === supervisor: {local,mnesia_kernel_sup} started: [{pid,<0.63.0>}, {name,mnesia_subscr}, {mfa,{mnesia_subscr,start,[]}}, {restart_type,permanent}, {shutdown,3000}, {child_type,worker}] =PROGRESS REPORT==== 24-Nov-2007::10:44:31 === supervisor: {local,mnesia_kernel_sup} started: [{pid,<0.64.0>}, {name,mnesia_locker}, {mfa,{mnesia_locker,start,[]}}, {restart_type,permanent}, {shutdown,3000}, {child_type,worker}] =PROGRESS REPORT==== 24-Nov-2007::10:44:31 === supervisor: {local,mnesia_kernel_sup} started: [{pid,<0.65.0>}, {name,mnesia_recover}, {mfa,{mnesia_recover,start,[]}}, {restart_type,permanent}, {shutdown,180000}, {child_type,worker}] =PROGRESS REPORT==== 24-Nov-2007::10:44:32 === supervisor: {local,kernel_safe_sup} started: [{pid,<0.70.0>}, {name,disk_log_sup}, {mfa,{disk_log_sup,start_link,[]}}, {restart_type,permanent}, {shutdown,1000}, {child_type,supervisor}] =PROGRESS REPORT==== 24-Nov-2007::10:44:32 === supervisor: {local,kernel_safe_sup} started: [{pid,<0.71.0>}, {name,disk_log_server}, {mfa,{disk_log_server,start_link,[]}}, {restart_type,permanent}, {shutdown,2000}, {child_type,worker}] =PROGRESS REPORT==== 24-Nov-2007::10:44:32 === supervisor: {local,kernel_safe_sup} started: [{pid,<0.82.0>}, {name,timer_server}, {mfa,{timer,start_link,[]}}, {restart_type,permanent}, {shutdown,1000}, {child_type,worker}] =PROGRESS REPORT==== 24-Nov-2007::10:44:32 === supervisor: {local,mnesia_kernel_sup} started: [{pid,<0.66.0>}, {name,mnesia_tm}, {mfa,{mnesia_tm,start,[]}}, {restart_type,permanent}, {shutdown,30000}, {child_type,worker}] =PROGRESS REPORT==== 24-Nov-2007::10:44:32 === supervisor: {local,mnesia_kernel_sup} started: [{pid,<0.83.0>}, {name,mnesia_checkpoint_sup}, {mfa,{mnesia_checkpoint_sup,start,[]}}, {restart_type,permanent}, {shutdown,infinity}, {child_type,supervisor}] =PROGRESS REPORT==== 24-Nov-2007::10:44:32 === supervisor: {local,mnesia_kernel_sup} started: [{pid,<0.84.0>}, {name,mnesia_snmp_sup}, {mfa,{mnesia_snmp_sup,start,[]}}, {restart_type,permanent}, {shutdown,infinity}, {child_type,supervisor}] =PROGRESS REPORT==== 24-Nov-2007::10:44:32 === supervisor: {local,mnesia_kernel_sup} started: [{pid,<0.85.0>}, {name,mnesia_controller}, {mfa,{mnesia_controller,start,[]}}, {restart_type,permanent}, {shutdown,3000}, {child_type,worker}] =PROGRESS REPORT==== 24-Nov-2007::10:44:32 === supervisor: {local,mnesia_kernel_sup} started: [{pid,<0.86.0>}, {name,mnesia_late_loader}, {mfa,{mnesia_late_loader,start,[]}}, {restart_type,permanent}, {shutdown,3000}, {child_type,worker}] =PROGRESS REPORT==== 24-Nov-2007::10:44:32 === supervisor: {local,mnesia_sup} started: [{pid,<0.61.0>}, {name,mnesia_kernel_sup}, {mfa,{mnesia_kernel_sup,start,[]}}, {restart_type,permanent}, {shutdown,infinity}, {child_type,supervisor}] =PROGRESS REPORT==== 24-Nov-2007::10:44:32 === application: mnesia started_at: ejabberd@jabber =CRASH REPORT==== 24-Nov-2007::10:44:42 === crasher: pid: <0.60.0> registered_name: mnesia_event error_info: killed initial_call: {gen,init_it, [gen_event, <0.59.0>, <0.59.0>, {local,mnesia_event}, [], [], []]} ancestors: [mnesia_sup,<0.58.0>] messages: [] links: [] dictionary: [] trap_exit: true status: running heap_size: 377 stack_size: 21 reductions: 496 neighbours: =CRASH REPORT==== 24-Nov-2007::10:44:42 === crasher: pid: <0.57.0> registered_name: [] error_info: killed initial_call: {application_master, init, [<0.5.0>, <0.56.0>, {appl_data, mnesia, [mnesia_dumper_load_regulator, mnesia_event, mnesia_fallback, mnesia_controller, mnesia_kernel_sup, mnesia_late_loader, mnesia_locker, mnesia_monitor, mnesia_recover, mnesia_substr, mnesia_sup, mnesia_tm], undefined, {mnesia_sup,[]}, [mnesia, mnesia_backup, mnesia_bup, mnesia_checkpoint, mnesia_checkpoint_sup, mnesia_controller, mnesia_dumper, mnesia_event, mnesia_frag, mnesia_frag_hash, mnesia_frag_old_hash, mnesia_index, mnesia_kernel_sup, mnesia_late_loader, mnesia_lib, mnesia_loader, mnesia_locker, mnesia_log, mnesia_monitor, mnesia_recover, mnesia_registry, mnesia_schema, mnesia_snmp_hook, mnesia_snmp_sup, mnesia_subscr, mnesia_sup, mnesia_sp, mnesia_text, mnesia_tm], [], infinity, infinity}, normal]} ancestors: [<0.56.0>] messages: [] links: [<0.5.0>] dictionary: [] trap_exit: true status: running heap_size: 987 stack_size: 21 reductions: 2223 neighbours: =PROGRESS REPORT==== 24-Nov-2007::10:44:42 === supervisor: {local,crypto_sup} started: [{pid,<0.135.0>}, {name,crypto_server}, {mfa,{crypto_server,start_link,[]}}, {restart_type,permanent}, {shutdown,2000}, {child_type,worker}] =PROGRESS REPORT==== 24-Nov-2007::10:44:42 === application: crypto started_at: ejabberd@jabber =PROGRESS REPORT==== 24-Nov-2007::10:44:42 === supervisor: {local,ssl_sup} started: [{pid,<0.141.0>}, {name,ssl_server}, {mfa,{ssl_server,start_link,[]}}, {restart_type,permanent}, {shutdown,2000}, {child_type,worker}] =PROGRESS REPORT==== 24-Nov-2007::10:44:42 === supervisor: {local,ssl_sup} started: [{pid,<0.142.0>}, {name,ssl_broker_sup}, {mfa,{ssl_broker_sup,start_link,[]}}, {restart_type,permanent}, {shutdown,2000}, {child_type,supervisor}] =PROGRESS REPORT==== 24-Nov-2007::10:44:42 === application: ssl started_at: ejabberd@jabber =CRASH REPORT==== 24-Nov-2007::10:44:44 === crasher: pid: <0.36.0> registered_name: [] error_info: {bad_return, {{ejabberd_app,start,[normal,[]]}, {'EXIT', {{badmatch, {aborted,{node_not_running,ejabberd@jabber}}}, [{ejabberd_config,set_opts,1}, {ejabberd_app,start,2}, {application_master,start_it_old,4}]}}}} initial_call: {application_master, init, [<0.5.0>, <0.35.0>, {appl_data, ejabberd, [ejabberd, ejabberd_sup, ejabberd_auth, ejabberd_router, ejabberd_sm, ejabberd_s2s, ejabberd_local, ejabberd_listeners, ejabberd_iq_sup, ejabberd_service_sup, ejabberd_s2s_out_sup, ejabberd_s2s_in_sup, ejabberd_c2s_sup, ejabberd_mod_roster, ejabberd_mod_echo, ejabberd_mod_pubsub, ejabberd_mod_irc, ejabberd_mod_muc, ejabberd_offline, random_generator], undefined, {ejabberd_app,[]}, [acl, configure, cyrsasl, cyrsasl_digest, cyrsasl_plain, ejabberd, ejabberd_app, ejabberd_auth, ejabberd_c2s, ejabberd_config, ejabberd_listener, ejabberd_logger_h, ejabberd_local, ejabberd_router, ejabberd_s2s, ejabberd_s2s_in, ejabberd_s2s_out, ejabberd_service, ejabberd_sm, ejabberd_sup, ejabberd_tmp_sup, gen_iq_handler, gen_mod, jd2ejd, jlib, mod_configure, mod_disco, mod_echo, mod_last, mod_offline, mod_private, mod_register, mod_roster, mod_stats, mod_time, mod_vcard, mod_version, randoms, sha, shaper, translate, xml, xml_stream], [], infinity, infinity}, normal]} ancestors: [<0.35.0>] messages: [{'EXIT',<0.37.0>,normal}] links: [<0.35.0>,<0.5.0>] dictionary: [] trap_exit: true status: running heap_size: 987 stack_size: 21 reductions: 2041 neighbours:Unluckily I dont understand the meaning of these messages - only that it crashed. But what was the reason? How can I fix it? - and how can I rescue all the roasters incl. the authentifications? Is it enough to copy the /var/spool/jabber-directory?
I am using: OpenSSH_4.7p1, OpenSSL 0.9.8g 19 Oct 2007
Ciao, H.
Strange error message
I tried to reinstall ejabberd to be sure to have clean binaries. But since then I even cannont start the ejabberd-server anymore :-(. Every start crashes and gives me a huge (15KB) sasl.log.
But the ejabberd-server is NOT working :-( The Sasl.log-file look like this:
... =PROGRESS REPORT==== 24-Nov-2007::10:44:32 === application: mnesia started_at: ejabberd@jabber =CRASH REPORT==== 24-Nov-2007::10:44:42 === crasher: pid: <0.60.0> registered_name: mnesia_event error_info: killed initial_call: {gen,init_it, [gen_event, <0.59.0>, <0.59.0>, {local,mnesia_event}, [], [], []]} ancestors: [mnesia_sup,<0.58.0>] messages: [] links: [] dictionary: [] trap_exit: true status: running heap_size: 377 stack_size: 21 reductions: 496 neighbours: ...Unluckily I dont understand the meaning of these messages - only that it crashed. But what was the reason? How can I fix it? - and how can I rescue all the roasters incl. the authentifications?
I don't know either what can be the reason, since I don't find any clue in the logs. It seems Mnesia is started, and is instantly killed for no apparent reason. Mnesia is a database system included in Erlang/OTP.
Usual problems with Mnesia are: wrong file permissions, wrong path to spool dir, corrupted files, spool dir created in a different machine... but the error messages in those cases provide some clue to the reason of the problem. So I think your case is not one of those.
How did you install ejabberd: using binary installer from Process-one site; using a package in your operating system; compiling from source code...?
Now you resinstalled ejabberd: did you reinstall the same version? 1.1.3, or 1.1.4 or whatever you had?
Did you also reinstall Erlang/OTP?
Is it enough to copy the /var/spool/jabber-directory?
Yes. There is a thing you can try to investigate where is the problem:
Let's hope we can find the reason for that problem, and fix it soon :)
corrupted data-files
Thanks for your hints badlop. Gentoo is always installing directly from source-code and I am still using 1.1.3 as the 1.1.4-gentoo-package is mask as instable. With your hints I could figure out two errors:
The corrupted file(s) in erlang I could remove with a reinstall of erlang :-). But how can I identify and fix the corrupted file(s) in /var/spool/jabber?
Here is my saved /var/spool/jabber-directory:
-rw-r--r-- 1 101 crontab 154 Nov 24 12:46 DECISION_TAB.LOG
-rw-r--r-- 1 101 crontab 93 Nov 24 12:46 LATEST.LOG
-rw-r--r-- 1 root root 278 Nov 23 09:41 acl.DCD
-rw-r--r-- 1 root root 1632 Nov 23 09:41 config.DCD
-rw-r--r-- 1 101 crontab 5752 Oct 3 21:36 disco_publish.DAT
-rw-r--r-- 1 101 crontab 385 Nov 22 16:23 last_activity.DCD
-rw-r--r-- 1 root root 202 Nov 23 00:23 last_activity.DCL
-rw-r--r-- 1 root root 4388 Nov 23 09:41 local_config.DCD
-rw-r--r-- 1 101 crontab 8 Oct 3 21:36 motd.DCD
-rw-r--r-- 1 101 crontab 8 Oct 3 21:36 motd_users.DCD
-rw-r--r-- 1 101 crontab 8 Oct 3 21:36 muc_registered.DCD
-rw-r--r-- 1 101 crontab 8 Oct 3 21:36 muc_room.DCD
-rw-r--r-- 1 root root 15056 Nov 23 02:34 offline_msg.DAT
-rw-r--r-- 1 101 crontab 437 Oct 13 12:49 passwd.DCD
-rw-r--r-- 1 101 crontab 8 Oct 3 21:36 privacy.DCD
-rw-r--r-- 1 101 crontab 7239 Oct 12 20:20 private_storage.DAT
-rw-r--r-- 1 101 crontab 10328 Oct 4 18:03 pubsub_node.DAT
-rw-r--r-- 1 101 crontab 7800 Nov 24 12:46 pubsub_node_3.DAT
-rw-r--r-- 1 101 crontab 5214 Oct 30 17:22 roster.DCD
-rw-r--r-- 1 101 crontab 719 Nov 18 12:33 roster.DCL
-rw-r--r-- 1 101 crontab 16935 Oct 3 21:57 schema.DAT
-rw-r--r-- 1 101 crontab 8991 Nov 22 16:30 vcard.DAT
-rw-r--r-- 1 101 crontab 312 Nov 22 16:31 vcard_search.DCD
(ignore the wrong user and group as the files are saved on a different machine)
And here are the new and empty created files of /var/spool/jabber:
-rw-r--r-- 1 jabber jabber 154 Nov 25 00:12 DECISION_TAB.LOG
-rw-r--r-- 1 jabber jabber 93 Nov 25 00:12 LATEST.LOG
-rw-r--r-- 1 jabber jabber 212 Nov 25 00:09 acl.DCD
-rw-r--r-- 1 jabber jabber 286 Nov 25 00:12 acl.DCL
-rw-r--r-- 1 jabber jabber 1366 Nov 25 00:09 config.DCD
-rw-r--r-- 1 jabber jabber 2243 Nov 25 00:12 config.DCL
-rw-r--r-- 1 jabber jabber 5752 Nov 24 23:40 disco_publish.DAT
-rw-r--r-- 1 jabber jabber 8 Nov 24 23:38 last_activity.DCD
-rw-r--r-- 1 jabber jabber 3205 Nov 25 00:09 local_config.DCD
-rw-r--r-- 1 jabber jabber 4245 Nov 25 00:12 local_config.DCL
-rw-r--r-- 1 jabber jabber 8 Nov 24 23:38 motd.DCD
-rw-r--r-- 1 jabber jabber 8 Nov 24 23:38 motd_users.DCD
-rw-r--r-- 1 jabber jabber 8 Nov 24 23:38 muc_registered.DCD
-rw-r--r-- 1 jabber jabber 8 Nov 24 23:38 muc_room.DCD
-rw-r--r-- 1 jabber jabber 5752 Nov 24 23:40 offline_msg.DAT
-rw-r--r-- 1 jabber jabber 8 Nov 24 23:38 passwd.DCD
-rw-r--r-- 1 jabber jabber 8 Nov 24 23:38 privacy.DCD
-rw-r--r-- 1 jabber jabber 5752 Nov 24 23:40 private_storage.DAT
-rw-r--r-- 1 jabber jabber 9606 Nov 25 00:09 pubsub_node.DAT
-rw-r--r-- 1 jabber jabber 8 Nov 24 23:38 roster.DCD
-rw-r--r-- 1 jabber jabber 16935 Nov 25 00:09 schema.DAT
-rw-r--r-- 1 jabber jabber 5752 Nov 24 23:40 vcard.DAT
-rw-r--r-- 1 jabber jabber 8 Nov 24 23:38 vcard_search.DCD
The MOST and VERY IMPORTANT is the roaster with its authentifications - if they will get lost I will be in trouble. Can I reinstall all the users and then just copy the saved roaster back without later upcoming problems?
Does ejabberd work correctly with empty DB?
But how can I identify and fix the corrupted file(s) in /var/spool/jabber?
When I kill ejabberd abruptly and later try to start it, ejabberd reports:
and it starts correctly.
Did ejabberd start and work correctly with that newly empty database? I mean: could you create a user, stop ejabberd, start ejabberd and worked correctly? If so, then you know the problem is in your old spool dir.
The MOST and VERY IMPORTANT is the roaster with its authentifications - if they will get lost I will be in trouble. Can I reinstall all the users and then just copy the saved roaster back without later upcoming problems?
Yes, quite probably. The files that are worth recovering from your old database are: passwd.* roster.* vcard.*. If ejabberd works correctly with the new database, you can test your luck: copy those files from the old database dir to the new one, overwriting the new (empty one) files; and then start ejabberd.
strange ejabberd behavior and log file level
My "clean" ejabberd is not working correctly. After adding accounts on myjabberserver the internal communication is working. But no external communication :-( - the only feedback on the client: Reason: ""
The s2s-parts of my ejabberd.cfg:
{listen ... {5269, ejabberd_s2s_in, [{shaper, s2s_shaper}, {max_stanza_size, 131072} ]}, ... % Use STARTTLS+Dialback for S2S connections {s2s_use_starttls, true}. {s2s_certfile, "/etc/jabber/ssl.pem"}. %{domain_certfile, "example.org", "./example_org.pem"}. %{domain_certfile, "example.com", "./example_com.pem"}. % If SRV lookup fails, then port 5269 is used to communicate with remote server {outgoing_s2s_port, 5269}. ...- and the log-files shows:
=INFO REPORT==== 2007-11-25 15:41:54 === I(<0.512.0>:ejabberd_s2s_out:106): started: {"myjabberserver.com", "jabber.ccc.de", {new,"1874468111"}} =INFO REPORT==== 2007-11-25 15:43:43 === I(<0.501.0>:ejabberd_s2s_in:519): terminated: normal =INFO REPORT==== 2007-11-25 15:45:06 === I(<0.512.0>:ejabberd_s2s_out:662): terminated: normalHow can I make sure that ejabberd tells more details in client-feedback and log-files? And what can be still corrupted after erlang and ejabberd reinstallation? Do I have to setup a whole new machine? How can I get more logging details?
Two different problems
The log messages indicate that your ejabberd tries to connect to the other server. After 2 minutes something happens. Quite probably it's a timeout. I bet it's a firewall bloking the port 5269, or a DNS misconfiguration.
How can I make sure that ejabberd tells more details in client-feedback and log-files? How can I get more logging details?
The next ejabberd version which will be released soon probably provides more information.
And what can be still corrupted after erlang and ejabberd reinstallation? Do I have to setup a whole new machine?
Regarding the problematic database with important information: to find what file is problematic, you could try this: