iChat server (jabberd) won't work after power failure

[corbywan]

SLS 10.6.1 on Mac Mini.

I've had this happen twice, but in different ways. We've had some storms come through and knock the power out recently. Everything seems to come back online fine, except for iChat server (jabberd of course). The first time, I was getting errors about c2s and sm not being able to connect to, well, itself. I was never able to actually fix those, I have to reinstall the whole system.

This time I'm getting similar errors where the system isn't talking to itself properly. Here is the log from clicking "Start iChat" to trying to connect from client.

Nov 8 05:28:20 myserver jabberd/router[1156]: reopening log ...
Nov 8 05:28:20 myserver jabberd/resolver[1154]: reopening log ...
Nov 8 05:28:20 myserver jabberd/sm[1155]: HUP handled. reloading modules...
Nov 8 05:28:20 myserver jabberd/sm[1155]: reopening log ...
Nov 8 05:28:20 myserver jabberd/c2s[1157]: reopening log ...
Nov 8 05:28:20 myserver jabberd/s2s[1159]: reopening log ...
Nov 8 05:28:20 myserver jabberd/router[1156]: log started
Nov 8 05:28:20 myserver jabberd/router[1156]: reloading filter ...
Nov 8 05:28:20 myserver jabberd/router[1156]: couldn't open filter file /etc/jabberd/router-filter.xml: No such file or directory
Nov 8 05:28:20 myserver jabberd/c2s[1157]: log started
Nov 8 05:28:20 myserver jabberd/c2s[1157]: shutting down
Nov 8 05:28:20 myserver jabberd/router[1156]: shutting down
Nov 8 05:28:20 myserver jabberd/router[1156]: [127.0.0.1, port=49413] disconnect
Nov 8 05:28:20 myserver jabberd/router[1156]: [proxy65.myserver.com] offline
Nov 8 05:28:20 myserver jabberd/resolver[1154]: log started
Nov 8 05:28:20 myserver jabberd/resolver[1154]: shutting down
Nov 8 05:28:20 myserver jabberd/sm[1155]: log started
Nov 8 05:28:20 myserver jabberd/sm[1155]: shutting down
Nov 8 05:28:20 myserver jabberd/s2s[1159]: log started
Nov 8 05:28:20 myserver jabberd/s2s[1159]: shutting down
Nov 8 05:28:20 myserver jabberd/s2s[1159]: connection to router closed
Nov 8 05:28:21 myserver jabberd/router[1156]: [127.0.0.1, port=49415] disconnect
Nov 8 05:28:21 myserver jabberd/router[1156]: [conference.myserver.com] offline
Nov 8 05:28:22 myserver jabberd/router[1156]: [127.0.0.1, port=49417] disconnect
Nov 8 05:28:22 myserver jabberd/router[1156]: [pubsub.myserver.com] offline
Nov 8 05:28:22 myserver jabberd/router[1156]: [127.0.0.1, port=49420] disconnect
Nov 8 05:28:22 myserver jabberd/router[1156]: [resolver] offline
Nov 8 05:28:22 myserver jabberd/router[1156]: [127.0.0.1, port=49421] disconnect
Nov 8 05:28:22 myserver jabberd/router[1156]: [s2s] default route offline
Nov 8 05:28:22 myserver jabberd/router[1156]: [s2s] offline
Nov 8 05:28:22 myserver jabberd/router[1156]: [127.0.0.1, port=49408] disconnect
Nov 8 05:28:22 myserver jabberd/router[1156]: [myserver.local] offline
Nov 8 05:28:22 myserver jabberd/router[1156]: [127.0.0.1, port=49407] disconnect
Nov 8 05:28:22 myserver jabberd/router[1156]: [c2s] offline
Nov 8 05:28:25 myserver servermgrd[67]: servermgr_jabber[N]: waiting for jabberd to finish shutdown...
Nov 8 05:28:25 myserver servermgrd[67]: servermgr_jabber[N]: jabberd service shutdown completed.
Nov 8 05:28:25 myserver servermgrd[67]: servermgr_jabber: STARTING UP iChat Server.
Nov 8 05:28:25 myserver servermgrd[67]: servermgr_jabber[N]: waiting for jabberd to finish startup...
Nov 8 05:28:25 myserver jabberd/c2s[9720]: starting up
Nov 8 05:28:25 myserver jabberd/resolver[9717]: starting up
Nov 8 05:28:25 myserver jabberd/s2s[9722]: starting up (interval=60, queue=60, keepalive=0, idle=86400)
Nov 8 05:28:25 myserver jabberd/c2s[9720]: modules search path: /var/jabberd/modules/jabberd2
Nov 8 05:28:25 myserver jabberd/router[9719]: starting up
Nov 8 05:28:25 myserver jabberd/c2s[9720]: initialized auth module 'sqlite'
Nov 8 05:28:25 myserver jabberd/s2s[9722]: failed to load local SSL pemfile, SSL will not be available to peers
Nov 8 05:28:25 myserver jabberd/resolver[9717]: attempting connection to router at 127.0.0.1, port=5347
Nov 8 05:28:25 myserver jabberd/resolver[9717]: [4] [router] write error: Broken pipe (32)
Nov 8 05:28:25 myserver jabberd/resolver[9717]: connection to router closed
Nov 8 05:28:25 myserver jabberd/resolver[9717]: attempting reconnect (3 left)
Nov 8 05:28:25 myserver jabberd/sm[9718]: starting up
Nov 8 05:28:25 myserver jabberd/sm[9718]: id: myserver.local
Nov 8 05:28:25 myserver jabberd/router[9719]: loaded user table (1 users)
Nov 8 05:28:25 myserver jabberd/router[9719]: couldn't open filter file /etc/jabberd/router-filter.xml: No such file or directory
Nov 8 05:28:25 myserver jabberd/sm[9718]: initialised storage driver 'sqlite'
Nov 8 05:28:25 myserver jabberd/sm[9718]: modules search path: /var/jabberd/modules/jabberd2
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'iq-last' added to chain 'sess-end' (order 0 index 0 seq 0)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'validate' added to chain 'in-sess' (order 0 index 1 seq 0)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'privacy' added to chain 'in-sess' (order 1 index 2 seq 0)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'roster' added to chain 'in-sess' (order 2 index 3 seq 0)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'vacation' added to chain 'in-sess' (order 3 index 4 seq 0)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'iq-vcard' added to chain 'in-sess' (order 4 index 5 seq 0)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'iq-ping' added to chain 'in-sess' (order 5 index 6 seq 0)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'iq-private' added to chain 'in-sess' (order 6 index 7 seq 0)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'disco' added to chain 'in-sess' (order 7 index 8 seq 0)
Nov 8 05:28:25 myserver jabberd/router[9719]: [127.0.0.1, port=5347] listening for incoming connections
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'amp' added to chain 'in-sess' (order 8 index 9 seq 0)
Nov 8 05:28:25 myserver jabberd/s2s[9722]: attempting connection to router at 127.0.0.1, port=5347
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'offline' added to chain 'in-sess' (order 9 index 10 seq 0)
Nov 8 05:28:25 myserver jabberd/router[9719]: [127.0.0.1, port=63455] connect
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'announce' added to chain 'in-sess' (order 10 index 11 seq 0)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'presence' added to chain 'in-sess' (order 11 index 12 seq 0)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'deliver' added to chain 'in-sess' (order 12 index 13 seq 0)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'session' added to chain 'in-router' (order 0 index 14 seq 0)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'validate' added to chain 'in-router' (order 1 index 1 seq 1)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'presence' added to chain 'in-router' (order 2 index 12 seq 1)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'privacy' added to chain 'in-router' (order 3 index 2 seq 1)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'privacy' added to chain 'out-router' (order 0 index 2 seq 2)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'iq-last' added to chain 'pkt-sm' (order 0 index 0 seq 1)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'iq-ping' added to chain 'pkt-sm' (order 1 index 6 seq 1)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'iq-time' added to chain 'pkt-sm' (order 2 index 15 seq 0)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'iq-version' added to chain 'pkt-sm' (order 3 index 16 seq 0)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'amp' added to chain 'pkt-sm' (order 4 index 9 seq 1)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'disco' added to chain 'pkt-sm' (order 5 index 8 seq 1)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'announce' added to chain 'pkt-sm' (order 6 index 11 seq 1)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'help' added to chain 'pkt-sm' (order 7 index 17 seq 0)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'echo' added to chain 'pkt-sm' (order 8 index 18 seq 0)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'roster' added to chain 'pkt-user' (order 0 index 3 seq 1)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'presence' added to chain 'pkt-user' (order 1 index 12 seq 2)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'iq-vcard' added to chain 'pkt-user' (order 2 index 5 seq 1)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'amp' added to chain 'pkt-user' (order 3 index 9 seq 2)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'deliver' added to chain 'pkt-user' (order 4 index 13 seq 1)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'vacation' added to chain 'pkt-user' (order 5 index 4 seq 1)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'offline' added to chain 'pkt-user' (order 6 index 10 seq 1)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'disco-publish' added to chain 'pkt-user' (order 7 index 19 seq 0)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'iq-last' added to chain 'pkt-user' (order 8 index 0 seq 2)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'session' added to chain 'pkt-router' (order 0 index 14 seq 1)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'disco' added to chain 'pkt-router' (order 1 index 8 seq 2)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'active' added to chain 'user-load' (order 0 index 20 seq 0)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'roster' added to chain 'user-load' (order 1 index 3 seq 2)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'roster-publish' added to chain 'user-load' (order 2 index 21 seq 0)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'privacy' added to chain 'user-load' (order 3 index 2 seq 3)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'disco-publish' added to chain 'user-load' (order 4 index 19 seq 1)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'vacation' added to chain 'user-load' (order 5 index 4 seq 2)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'active' added to chain 'user-create' (order 0 index 20 seq 1)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'template-roster' added to chain 'user-create' (order 1 index 22 seq 0)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'active' added to chain 'user-delete' (order 0 index 20 seq 2)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'announce' added to chain 'user-delete' (order 1 index 11 seq 2)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'disco-publish' added to chain 'user-delete' (order 2 index 19 seq 2)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'offline' added to chain 'user-delete' (order 3 index 10 seq 2)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'privacy' added to chain 'user-delete' (order 4 index 2 seq 4)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'roster' added to chain 'user-delete' (order 5 index 3 seq 3)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'vacation' added to chain 'user-delete' (order 6 index 4 seq 3)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'iq-last' added to chain 'user-delete' (order 7 index 0 seq 3)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'iq-private' added to chain 'user-delete' (order 8 index 7 seq 1)
Nov 8 05:28:25 myserver jabberd/sm[9718]: module 'iq-vcard' added to chain 'user-delete' (order 9 index 5 seq 2)
Nov 8 05:28:25 myserver jabberd/sm[9718]: version: jabberd sm 2.1.24.1-326
Nov 8 05:28:25 myserver jabberd/c2s[9720]: [myserver.com] configured; realm=myserver.com, registration disabled
Nov 8 05:28:25 myserver jabberd/c2s[9720]: attempting connection to router at 127.0.0.1, port=5347
Nov 8 05:28:25 myserver jabberd/router[9719]: [127.0.0.1, port=63456] connect
Nov 8 05:28:25 myserver jabberd/sm[9718]: attempting connection to router at 127.0.0.1, port=5347
Nov 8 05:28:25 myserver jabberd/router[9719]: [127.0.0.1, port=63457] connect
Nov 8 05:28:25 myserver jabberd/router[9719]: [127.0.0.1, port=63457] authenticated as jabberd
Nov 8 05:28:25 myserver jabberd/router[9719]: [127.0.0.1, port=63455] authenticated as jabberd
Nov 8 05:28:25 myserver jabberd/router[9719]: [127.0.0.1, port=63456] authenticated as jabberd
Nov 8 05:28:25 myserver jabberd/sm[9718]: connection to router established
Nov 8 05:28:25 myserver jabberd/router[9719]: [myserver.local] online (bound to 127.0.0.1, port 63457)
Nov 8 05:28:25 myserver jabberd/sm[9718]: ready for sessions
Nov 8 05:28:25 myserver jabberd/s2s[9722]: connection to router established
Nov 8 05:28:25 myserver jabberd/router[9719]: [s2s] set as default route
Nov 8 05:28:25 myserver jabberd/router[9719]: [s2s] online (bound to 127.0.0.1, port 63455)
Nov 8 05:28:25 myserver jabberd/s2s[9722]: [::, port=5269] listening for connections
Nov 8 05:28:25 myserver jabberd/s2s[9722]: ready for connections
Nov 8 05:28:25 myserver jabberd/c2s[9720]: connection to router established
Nov 8 05:28:25 myserver jabberd/router[9719]: [c2s] online (bound to 127.0.0.1, port 63456)
Nov 8 05:28:25 myserver jabberd/c2s[9720]: [::, port=5222] listening for connections
Nov 8 05:28:25 myserver jabberd/c2s[9720]: ready for connections
Nov 8 05:28:25 myserver servermgrd[67]: servermgr_jabber[N]: jabberd service startup completed.
Nov 8 05:28:25 myserver servermgrd[67]: portmaplist: synch needed /private/etc/nat/autoportmap.plist
Nov 8 05:28:25 myserver org.jabber.proxy65[9726]: /System/Library/Frameworks/Python.framework/Versions/2.6/Extras/lib/python/twisted/persisted/sob.py:12: DeprecationWarning: the md5 module is deprecated; use hashlib instead
Nov 8 05:28:25 myserver org.jabber.proxy65[9726]: import os, md5, sys
Nov 8 05:28:25 myserver org.jabber.proxy65[9726]: /System/Library/Frameworks/Python.framework/Versions/2.6/Extras/lib/python/twisted/python/filepath.py:12: DeprecationWarning: the sha module is deprecated; use the hashlib module instead
Nov 8 05:28:25 myserver org.jabber.proxy65[9726]: import sha
Nov 8 05:28:26 myserver jabberd/router[9719]: [127.0.0.1, port=63461] connect
Nov 8 05:28:26 myserver jabberd/router[9719]: [127.0.0.1, port=63461] authenticated as proxy65.myserver.com
Nov 8 05:28:26 myserver jabberd/router[9719]: [proxy65.myserver.com] online (bound to 127.0.0.1, port 63461)
Nov 8 05:28:26 myserver jabberd/router[9719]: [127.0.0.1, port=63462] connect
Nov 8 05:28:26 myserver jabberd/router[9719]: [127.0.0.1, port=63462] authenticated as conference.myserver.com
Nov 8 05:28:26 myserver jabberd/router[9719]: [conference.myserver.com] online (bound to 127.0.0.1, port 63462)
Nov 8 05:28:27 myserver jabberd/resolver[9717]: attempting connection to router at 127.0.0.1, port=5347
Nov 8 05:28:27 myserver jabberd/router[9719]: [127.0.0.1, port=63467] connect
Nov 8 05:28:27 myserver jabberd/router[9719]: [127.0.0.1, port=63467] authenticated as jabberd
Nov 8 05:28:27 myserver jabberd/resolver[9717]: connection to router established
Nov 8 05:28:27 myserver jabberd/router[9719]: [resolver] online (bound to 127.0.0.1, port 63467)
Nov 8 05:28:27 myserver jabberd/resolver[9717]: ready to resolve

Nov 8 05:28:33 myserver jabberd/router[9719]: [127.0.0.1, port=63475] connect
Nov 8 05:28:33 myserver jabberd/router[9719]: [127.0.0.1, port=63475] authenticated as pubsub.myserver.com
Nov 8 05:28:33 myserver jabberd/router[9719]: [pubsub.myserver.com] online (bound to 127.0.0.1, port 63475)

This is what it does when I try to connect from a client. The client just keeps getting a username/password prompts over and over. (12.34.56.78 is of course a made up IP) It will do this repeatedly with a different port number, going higher and higher. In some cases it will add "is being rate limited" This will just loop and loop until I shut iChat and Push Notifications down.

Nov 8 05:32:02 myserver jabberd/c2s[9720]: [7] [::ffff:12.34.56.78, port=50830] connect
Nov 8 05:32:02 myserver jabberd/c2s[9720]: [7] [::ffff:12.34.56.78, port=50830] disconnect jid=unbound, packets: 0

Is all of that supposed to bind to 127.0.0.1? Another posting on here said to try and reinstall just the serveressentials.pkg from the disc. I tried that on a previous install and it didn't seem to do anything. Is there any kind of repair or restore script that can be run in situations like power failures where the thing doesn't shut down gracefully? jabberd seems pretty delicate.

Thanks in advance

 

[pherplexed]

Not sure if this is helpful since you're also having issue with the iChat service on the server. But on the client side, I was able to fix my iChat server issues by deleting the Jabber accounts from the iChat clients, delete the iChat jabber preference files, then re-add the jabber account and rebooting the client machines.

Seemed to do the trick for me.

 

[corbywan]

Thanks for the input, but sadly no joy.

 

[corbywan]

I don't have the link right now, but someone out there said, when faced with a similar problem and situation, that he did a rebuild of the sqlite database that jabberd uses, but he didn't say how he did it. Does anyone know how that is done? What the default username and password might be to login and do that and what the commands are? Thanks.