[jdev] Jabber-1.4.3 login problem

Mon Mar 14 14:01:29 CST 2005

I am seeing rather long delays when I try to into my Jabber server.
Sometimes there is no delay and sometimes it takes a minute or so to log in.
I am running jabberd 1.4.3 with jadc2s and using xdb_auth_cpile to
authenticate with LDAP. I have received some great help on this issue from
Jitender Arora who suggested that I setup jadc2s but I am still seeing the
problem.  He also was good enough to share his scripts with me that will
monitor the jabber processes and restart them if necessary.  The scripts may
well be the answer but this problem happens so frequently that I really
think I should find the cause of the problem.  I can't go live with this
server unless I get this fixed.

I ran jabbed in debug mode and here is what I got when a user called
grant at jabber2.uark was taking a long time to authenticate.  I was using
Exodus and the login timed out several times.

I see this pattern repeated several times:

Sun Mar 13 18:16:47 2005  mio.c:1274 mio_write called on x: 9D00FC0 buffer:
(null) Sun Mar 13 18:16:47 2005  deliver.c:474 DELIVER 2:jabber2.uark.edu
<xdb type='get' to='grant at jabber2.uark.edu' from='sessions'
ns='jabber:iq:auth' id='337'/> Sun Mar 13 18:16:47 2005  deliver.c:678
delivering to instance 'xdb_auth_cpile'

Does this indicate that 'xdb_auth_cpile' is not responding or that perhaps
jabberd has died and is not responding to xdb_auth_cpile?

How would I determine what process in not responding?

What does ## js_user not current ## tell me?

----------------------- begin jabberd debug --------------------------------

Sun Mar 13 18:16:36 2005  users.c:143
js_user(grant at jabber2.uark.edu,9C37598)
Sun Mar 13 18:16:36 2005  users.c:150 ## js_user not current ## Sun Mar 13
18:16:36 2005  deliver.c:474 DELIVER 2:jabber2.uark.edu <xdb type='get'
to='grant at jabber2.uark.edu' from='sessions' ns='jabber:iq:auth' id='339'/>
Sun Mar 13 18:16:36 2005  deliver.c:678 delivering to instance
'xdb_auth_cpile'
Sun Mar 13 18:16:36 2005  mio.c:1274 mio_write called on x: 9D06FC0 buffer:
(null) Sun Mar 13 18:16:36 2005  xdb.c:220 xdb_get() waiting for
grant at jabber2.uark.edu jabber:iq:auth Sun Mar 13 18:16:47 2005
deliver.c:474 DELIVER 2:jabber2.uark.edu <xdb type='get'
to='grant at jabber2.uark.edu' from='sessions' ns='jabber:iq:auth' id='339'/>
Sun Mar 13 18:16:47 2005  deliver.c:678 delivering to instance
'xdb_auth_cpile'
Sun Mar 13 18:16:47 2005  mio.c:1274 mio_write called on x: 9D17740 buffer:
(null) Sun Mar 13 18:16:47 2005  deliver.c:474 DELIVER 2:jabber2.uark.edu
<xdb type='get' to='grant at jabber2.uark.edu' from='sessions'
ns='jabber:iq:auth' id='338'/> Sun Mar 13 18:16:47 2005  deliver.c:678
delivering to instance 'xdb_auth_cpile'
Sun Mar 13 18:16:47 2005  mio.c:1274 mio_write called on x: 9D00FC0 buffer:
(null) Sun Mar 13 18:16:47 2005  deliver.c:474 DELIVER 2:jabber2.uark.edu
<xdb type='get' to='grant at jabber2.uark.edu' from='sessions'
ns='jabber:iq:auth' id='337'/> Sun Mar 13 18:16:47 2005  deliver.c:678
delivering to instance 'xdb_auth_cpile'
Sun Mar 13 18:16:47 2005  mio.c:1274 mio_write called on x: 9D060B8 buffer:
(null) Sun Mar 13 18:16:58 2005  deliver.c:474 DELIVER 2:jabber2.uark.edu
<xdb type='get' to='grant at jabber2.uark.edu' from='sessions'
ns='jabber:iq:auth' id='339'/> Sun Mar 13 18:16:58 2005  deliver.c:678
delivering to instance 'xdb_auth_cpile'
Sun Mar 13 18:16:58 2005  mio.c:1274 mio_write called on x: 9CF1B60 buffer:
(null) Sun Mar 13 18:16:58 2005  deliver.c:474 DELIVER 2:jabber2.uark.edu
<xdb type='get' to='grant at jabber2.uark.edu' from='sessions'
ns='jabber:iq:auth' id='338'/> Sun Mar 13 18:16:58 2005  deliver.c:678
delivering to instance 'xdb_auth_cpile'
Sun Mar 13 18:16:58 2005  mio.c:1274 mio_write called on x: 9D2F448 buffer:
(null) Sun Mar 13 18:16:58 2005  deliver.c:474 DELIVER 2:jabber2.uark.edu
<xdb type='get' to='grant at jabber2.uark.edu' from='sessions'
ns='jabber:iq:auth' id='337'/> Sun Mar 13 18:16:58 2005  deliver.c:678
delivering to instance 'xdb_auth_cpile'
Sun Mar 13 18:16:58 2005  mio.c:1274 mio_write called on x: 9CEF668 buffer:
(null) Sun Mar 13 18:16:59 2005  xdb_file.c:96 purge check Sun Mar 13
18:16:59 2005  xdb_file.c:83 purging ./spool/jabber2.uark.edu/grant.xml
Sun Mar 13 18:17:02 2005  jabberd.c:255 main load check of 1.00 with 14
total threads Sun Mar 13 18:17:09 2005  xdb.c:226 xdb_get() done waiting for
grant at jabber2.uark.edu jabber:iq:auth Sun Mar 13 18:17:09 2005
deliver.c:474 DELIVER 2:jabber2.uark.edu <xdb type='get'
to='grant at jabber2.uark.edu' from='sessions' ns='jabber:iq:auth:crypt'
id='340'/> Sun Mar 13 18:17:09 2005  deliver.c:678 delivering to instance
'xdb'
Sun Mar 13 18:17:09 2005  xdb_file.c:172 handling xdb request <xdb
type='get' to='grant at jabber2.uark.edu' from='sessions'
ns='jabber:iq:auth:crypt' id='340'/> Sun Mar 13 18:17:09 2005
xdb_file.c:109 loading ./spool/jabber2.uark.edu/grant.xml
Sun Mar 13 18:17:09 2005  xdb_file.c:129 caching
./spool/jabber2.uark.edu/grant.xml
Sun Mar 13 18:17:09 2005  deliver.c:474 DELIVER 1:sessions <xdb
type='result' to='sessions' from='grant at jabber2.uark.edu'
ns='jabber:iq:auth:crypt' id='340'/> Sun Mar 13 18:17:09 2005  deliver.c:678
delivering to instance 'sessions'
Sun Mar 13 18:17:09 2005  xdb.c:52 xdb_results checking xdb packet <xdb
type='result' to='sessions' from='grant at jabber2.uark.edu'
ns='jabber:iq:auth:crypt' id='340'/> Sun Mar 13 18:17:09 2005  xdb.c:220
xdb_get() waiting for grant at jabber2.uark.edu jabber:iq:auth:crypt Sun Mar 13
18:17:09 2005  xdb.c:226 xdb_get() done waiting for grant at jabber2.uark.edu
jabber:iq:auth:crypt Sun Mar 13 18:17:09 2005  deliver.c:474 DELIVER
4:jadc2s <route from='grant at jabber2.uark.edu' to='7 at jadc2s' type='auth'><iq
id='MX_54' type='error'><query
xmlns='jabber:iq:auth'><username>grant</username></query><error
code='401'>Unauthorized</error></iq></route>
Sun Mar 13 18:17:09 2005  deliver.c:678 delivering to instance 'jadc2s'
Sun Mar 13 18:17:09 2005  mio.c:1274 mio_write called on x: 9D1B9B8 buffer:
(null) Sun Mar 13 18:17:09 2005  mtq 9C370C0 leaving to pth Sun Mar 13
18:17:09 2005  xdb.c:226 xdb_get() done waiting for grant at jabber2.uark.edu
jabber:iq:auth Sun Mar 13 18:17:09 2005  deliver.c:474 DELIVER
2:jabber2.uark.edu <xdb type='get' to='grant at jabber2.uark.edu'
from='sessions' ns='jabber:iq:auth:crypt' id='341'/> Sun Mar 13 18:17:09
2005  deliver.c:678 delivering to instance 'xdb'
Sun Mar 13 18:17:09 2005  xdb_file.c:172 handling xdb request <xdb
type='get' to='grant at jabber2.uark.edu' from='sessions'
ns='jabber:iq:auth:crypt' id='341'/> Sun Mar 13 18:17:09 2005
xdb_file.c:109 loading ./spool/jabber2.uark.edu/grant.xml
Sun Mar 13 18:17:09 2005  deliver.c:474 DELIVER 1:sessions <xdb
type='result' to='sessions' from='grant at jabber2.uark.edu'
ns='jabber:iq:auth:crypt' id='341'/> Sun Mar 13 18:17:09 2005  deliver.c:678
delivering to instance 'sessions'
Sun Mar 13 18:17:09 2005  xdb.c:52 xdb_results checking xdb packet <xdb
type='result' to='sessions' from='grant at jabber2.uark.edu'
ns='jabber:iq:auth:crypt' id='341'/> Sun Mar 13 18:17:09 2005  xdb.c:220
xdb_get() waiting for grant at jabber2.uark.edu jabber:iq:auth:crypt Sun Mar 13
18:17:09 2005  xdb.c:226 xdb_get() done waiting for grant at jabber2.uark.edu
jabber:iq:auth:crypt Sun Mar 13 18:17:09 2005  deliver.c:474 DELIVER
4:jadc2s <route from='grant at jabber2.uark.edu' to='7 at jadc2s' type='auth'><iq
id='MX_55' type='error'><query
xmlns='jabber:iq:auth'><username>grant</username></query><error
code='401'>Unauthorized</error></iq></route>
Sun Mar 13 18:17:09 2005  deliver.c:678 delivering to instance 'jadc2s'
Sun Mar 13 18:17:09 2005  mio.c:1274 mio_write called on x: 9D2E550 buffer:
(null) Sun Mar 13 18:17:09 2005  mtq 9C58F10 leaving to pth Sun Mar 13
18:17:09 2005  xdb.c:226 xdb_get() done waiting for grant at jabber2.uark.edu
jabber:iq:auth Sun Mar 13 18:17:09 2005  deliver.c:474 DELIVER
2:jabber2.uark.edu <xdb type='get' to='grant at jabber2.uark.edu'
from='sessions' ns='jabber:iq:auth:crypt' id='342'/> Sun Mar 13 18:17:09
2005  deliver.c:678 delivering to instance 'xdb'
Sun Mar 13 18:17:09 2005  xdb_file.c:172 handling xdb request <xdb
type='get' to='grant at jabber2.uark.edu' from='sessions'
ns='jabber:iq:auth:crypt' id='342'/> Sun Mar 13 18:17:09 2005
xdb_file.c:109 loading ./spool/jabber2.uark.edu/grant.xml
Sun Mar 13 18:17:09 2005  deliver.c:474 DELIVER 1:sessions <xdb
type='result' to='sessions' from='grant at jabber2.uark.edu'
ns='jabber:iq:auth:crypt' id='342'/> Sun Mar 13 18:17:09 2005  deliver.c:678
delivering to instance 'sessions'
Sun Mar 13 18:17:09 2005  xdb.c:52 xdb_results checking xdb packet <xdb
type='result' to='sessions' from='grant at jabber2.uark.edu'
ns='jabber:iq:auth:crypt' id='342'/> Sun Mar 13 18:17:09 2005  xdb.c:220
xdb_get() waiting for grant at jabber2.uark.edu jabber:iq:auth:crypt Sun Mar 13
18:17:09 2005  xdb.c:226 xdb_get() done waiting for grant at jabber2.uark.edu
jabber:iq:auth:crypt Sun Mar 13 18:17:09 2005  deliver.c:55 delivering
locally to grant at jabber2.uark.edu/UarkJabber v3.5 Sun Mar 13 18:17:09 2005
modules.c:135 mapi_call 3 Sun Mar 13 18:17:09 2005  modules.c:158 MAPI
9BD8528 Sun Mar 13 18:17:09 2005  mod_presence deliver phase Sun Mar 13
18:17:09 2005  modules.c:175 mapi_call returning unhandled Sun Mar 13
18:17:09 2005  util.c:75 dropping 404 packet <presence type='unavailable'
to='grant at jabber2.uark.edu/UarkJabber v3.5'
from='txxxxxtest at yahoo.jabber2.uark.edu'/>
Sun Mar 13 18:17:09 2005  base_accept.c:120 process XML: m:9C314A8 state:3,
arg:9C22EC0, x:9D560E8 Sun Mar 13 18:17:09 2005  deliver.c:474 DELIVER
1:jabber2.uark.edu <presence type='unavailable'
to='grant at jabber2.uark.edu/UarkJabber v3.5'
from='dstxxxx2001 at yahoo.jabber2.uark.edu'/>
Sun Mar 13 18:17:09 2005  deliver.c:678 delivering to instance 'sessions'
Sun Mar 13 18:17:09 2005  deliver.c:95 (9BCEED0)incoming packet <presence
type='unavailable' to='grant at jabber2.uark.edu/UarkJabber v3.5'
from='dstxxxx2001 at yahoo.jabber2.uark.edu'/>
Sun Mar 13 18:17:09 2005  users.c:143
js_user(grant at jabber2.uark.edu,9C37598)
Sun Mar 13 18:17:09 2005  users.c:150 ## js_user not current ## Sun Mar 13
18:17:09 2005  deliver.c:474 DELIVER 2:jabber2.uark.edu <xdb type='get'
to='grant at jabber2.uark.edu' from='sessions' ns='jabber:iq:auth' id='343'/>
Sun Mar 13 18:17:09 2005  deliver.c:678 delivering to instance
'xdb_auth_cpile'
Sun Mar 13 18:17:09 2005  mio.c:1274 mio_write called on x: 9D0D760 buffer:
(null) Sun Mar 13 18:17:09 2005  xdb.c:220 xdb_get() waiting for
grant at jabber2.uark.edu jabber:iq:auth

Les Seigneur
les at uark.edu
479.575.2905