[jadmin] s2s connection problem

Thu Jul 12 14:33:16 CDT 2007

Hello together

i'm just using and configuring a jabberd 1.4.3 out of the Debian Etch
Stable Release.

The Jabber Server seems to work fine except for the transport of
messages to other jabber server.

Sending a message from user at server1 to user at server1 (both with their own
       domain and different IP's on different machines result in a
bounce of the message back to the user who send it with the attached
message and the error "Server Connect Timeout".

I can with this similar when runnig the jabberd on the commandline with
the -D parameter.

Everything starts up normal and the server is ready, after that i send a
message from user at server1 to user at server1

jabberd -D puts out:
(note: i changed the real domain names against server1 and server2 for
privacy purposes)

Thu Jul 12 16:38:43 2007  deliver.c:266
deliver(to[andre at server2],from[testuser at server1/Psi],type[1],packet[<message
id='aae9a' to='andre at server2' from='testuser at server1/Psi'>
<subject>test</subject>
<body>test</body>
</message>])
Thu Jul 12 16:38:43 2007  deliver.c:474 DELIVER 1:server2 <message
id='aae9a' to='andre at server2' from='testuser at server1/Psi'>
<subject>test</subject>
<body>test</body>
</message>
Thu Jul 12 16:38:43 2007  deliver.c:678 delivering to instance 'dnsrv'
Thu Jul 12 16:38:43 2007  dnsrv.c:264 dnsrv: Creating lookup request
queue for server2
Thu Jul 12 16:38:43 2007  dnsrv.c:273 dnsrv: Transmitting lookup
request: <host>server2</host>
Thu Jul 12 16:38:43 2007  mtq 811F9F8 leaving to pth
Thu Jul 12 16:38:43 2007  dnsrv.c:159 DNSRV CHILD: Read from buffer:
<host>server2</host>
Thu Jul 12 16:38:43 2007  mio.c:816 mio while loop top
Thu Jul 12 16:38:43 2007  dnsrv.c:112 dnsrv: Recv'd lookup request for
server2
Thu Jul 12 16:38:43 2007  srv_resolv.c:161 srv: SRV resolution of
_xmpp-server._tcp.server2
Thu Jul 12 16:38:43 2007  srv_resolv.c:161 srv: SRV resolution of
_jabber-server._tcp.server2
Thu Jul 12 16:38:43 2007  srv_resolv.c:114 srv: Standard resolution of
server2
Thu Jul 12 16:38:43 2007  dnsrv.c:123 Resolved server2((null)):
62.75.171.236        resend to:s2s
Thu Jul 12 16:38:43 2007  dnsrv.c:338 incoming resolution: <host
ip='62.75.171.236' to='s2s'>server2</host>
Thu Jul 12 16:38:43 2007  deliver.c:474 DELIVER 4:s2s <route to='s2s'
ip='62.75.171.236'><message id='aae9a' to='andre at server2'
from='testuser at server1/Psi'>
<subject>test</subject>
<body>test</body>
</message></route>
Thu Jul 12 16:38:43 2007  deliver.c:678 delivering to instance 's2s'
Thu Jul 12 16:38:43 2007  dialback_out.c:217 dbout
packet[62.75.171.236]: <message id='aae9a' to='andre at server2'
from='testuser at server1/Psi'>
<subject>test</subject>
<body>test</body>
</message>
Thu Jul 12 16:38:43 2007  dialback_out.c:237 outgoing packet with key
server2/server1 and located existing 0
Thu Jul 12 16:38:43 2007  dialback_out.c:99 Attempting to connect to
server2/server1 at 62.75.171.236
Thu Jul 12 16:38:43 2007  mio.c:728 calling the connect handler for mio
object 81D97C8
Thu Jul 12 16:38:43 2007  dialback_out.c:354 dbout read: fd 15 flag 0
key server2/server1

Thu Jul 12 16:38:43 2007  dialback_out.c:359 NEW outgoing server socket
connected at 15
Thu Jul 12 16:38:43 2007  mio.c:1274 mio_write called on x: 0 buffer:
<?xml version='1.0'?><stream:stream
xmlns:stream='http://etherx.jabber.org/streams' id='46965913'
xmlns='jabber:server' to='server2' xmlns:db='jabber:server:dialback'>
Thu Jul 12 16:38:43 2007  mio.c:829 mio while loop, working
Thu Jul 12 16:38:43 2007  mio.c:895 socket 15 has been intialized with
starting karma 5
Thu Jul 12 16:38:43 2007  mio.c:418 write_dump writing data: <?xml
version='1.0'?><stream:stream
xmlns:stream='http://etherx.jabber.org/streams' id='46965913'
xmlns='jabber:server' to='server2' xmlns:db='jabber:server:dialback'>
Thu Jul 12 16:38:43 2007  mio.c:816 mio while loop top
Thu Jul 12 16:38:43 2007  mio.c:829 mio while loop, working
Thu Jul 12 16:38:43 2007  mio.c:816 mio while loop top
Thu Jul 12 16:39:07 2007  mio.c:829 mio while loop, working
Thu Jul 12 16:39:07 2007  mio.c:977 MIO read from socket 14:

Thu Jul 12 16:39:07 2007  mio.c:816 mio while loop top
Thu Jul 12 16:39:36 2007  jabberd.c:255 main load check of 1.00 with 14
total threads
Thu Jul 12 16:39:38 2007  MU-Conference [conference.c:1020
(con_beat_update)] HBTICK
Thu Jul 12 16:39:38 2007  users.c:88 checking users for host server1
Thu Jul 12 16:39:38 2007  usercount 1   total users
Thu Jul 12 16:39:40 2007  deliver.c:606 delivery failed (Server Connect
Timeout)
Thu Jul 12 16:39:40 2007  log.c:116 <log type='notice'
from='server2'>bouncing a packet to andre at server2 from
testuser at server1/Psi: Server Connect Timeout</log>
Thu Jul 12 16:39:40 2007  deliver.c:474 DELIVER 3:server2 <log
type='notice' from='server2'>bouncing a packet to andre at server2 from
testuser at server1/Psi: Server Connect Timeout</log>
Thu Jul 12 16:39:40 2007  deliver.c:678 delivering to instance 'elogger'
20070712T16:39:40: [notice] (server2): bouncing a packet to
andre at server2 from testuser at server1/Psi: Server Connect Timeout
Thu Jul 12 16:39:40 2007  deliver.c:474 DELIVER 1:server1 <message
id='aae9a' to='testuser at server1/Psi' from='andre at server2' type='error'>
<subject>test</subject>
<body>test</body>
<error code='502'>Server Connect Timeout</error></message>
Thu Jul 12 16:39:40 2007  deliver.c:678 delivering to instance 'sessions'
Thu Jul 12 16:39:40 2007  deliver.c:95 (80C1BC8)incoming packet <message
id='aae9a' to='testuser at server1/Psi' from='andre at server2' type='error'>
<subject>test</subject>
<body>test</body>
<error code='502'>Server Connect Timeout</error></message>
Thu Jul 12 16:39:40 2007  users.c:143 js_user(testuser at server1,811FED0)
Thu Jul 12 16:39:40 2007  deliver.c:55 delivering locally to
testuser at server1/Psi
Thu Jul 12 16:39:40 2007  modules.c:135 mapi_call 3
Thu Jul 12 16:39:40 2007  modules.c:158 MAPI 80C8080
Thu Jul 12 16:39:40 2007  modules.c:158 MAPI 80C86C0
Thu Jul 12 16:39:40 2007  deliver.c:474 DELIVER 2:server1 <xdb
type='get' to='testuser at server1' from='sessions' ns='jabber:iq:filter'
id='9'/>
Thu Jul 12 16:39:40 2007  deliver.c:678 delivering to instance 'xdb'
Thu Jul 12 16:39:40 2007  xdb_file.c:172 handling xdb request <xdb
type='get' to='testuser at server1' from='sessions' ns='jabber:iq:filter'
id='9'/>
Thu Jul 12 16:39:40 2007  xdb_file.c:109 loading
/var/lib/jabber/server1/testuser.xml
Thu Jul 12 16:39:40 2007  deliver.c:474 DELIVER 1:sessions <xdb
type='result' to='sessions' from='testuser at server1'
ns='jabber:iq:filter' id='9'/>
Thu Jul 12 16:39:40 2007  deliver.c:678 delivering to instance 'sessions'
Thu Jul 12 16:39:40 2007  xdb.c:52 xdb_results checking xdb packet <xdb
type='result' to='sessions' from='testuser at server1'
ns='jabber:iq:filter' id='9'/>
Thu Jul 12 16:39:40 2007  xdb.c:220 xdb_get() waiting for
testuser at server1 jabber:iq:filter
Thu Jul 12 16:39:40 2007  xdb.c:226 xdb_get() done waiting for
testuser at server1 jabber:iq:filter
Thu Jul 12 16:39:40 2007  mod_filter.c:338 Looking at rules: <query
xmlns='jabber:iq:filter'/>
Thu Jul 12 16:39:40 2007  modules.c:158 MAPI 80C8BC0
Thu Jul 12 16:39:40 2007  modules.c:175 mapi_call returning unhandled
Thu Jul 12 16:39:40 2007  mtq 811F9F8 entering from pth
Thu Jul 12 16:39:40 2007  mtq 811F9F8 queue call 81DB5E8
Thu Jul 12 16:39:40 2007  sessions.c:301 THREAD:SESSION:TO received data
from andre at server2!
Thu Jul 12 16:39:40 2007  modules.c:135 mapi_call 0
Thu Jul 12 16:39:40 2007  modules.c:158 MAPI 81D6FF0
Thu Jul 12 16:39:40 2007  modules.c:158 MAPI 81D7078
Thu Jul 12 16:39:40 2007  modules.c:175 mapi_call returning unhandled
Thu Jul 12 16:39:40 2007  deliver.c:474 DELIVER 4:c2s <route
from='testuser at server1/81D6D78' to='14 at c2s/80C1600'><message id='aae9a'
to='testuser at server1/Psi' from='andre at server2' type='error'>
<subject>test</subject>
<body>test</body>
<error code='502'>Server Connect Timeout</error></message></route>
Thu Jul 12 16:39:40 2007  deliver.c:678 delivering to instance 'c2s'
Thu Jul 12 16:39:40 2007  c2s [client.c:167] testuser at server1/81D6D78
has an active session, delivering packet
Thu Jul 12 16:39:40 2007  c2s [client.c:239] Writing packet to MIO:
<message id='aae9a' to='testuser at server1/Psi' from='andre at server2'
type='error'>
<subject>test</subject>
<body>test</body>
<error code='502'>Server Connect Timeout</error></message>
Thu Jul 12 16:39:40 2007  mio.c:1274 mio_write called on x: 811E1A8
buffer: (null)
Thu Jul 12 16:39:40 2007  mtq 811F9F8 leaving to pth
Thu Jul 12 16:39:40 2007  mio.c:829 mio while loop, working
Thu Jul 12 16:39:40 2007  mio.c:418 write_dump writing data: <message
id='aae9a' to='testuser at server1/Psi' from='andre at server2' type='error'>
<subject>test</subject>
<body>test</body>
<error code='502'>Server Connect Timeout</error></message>

While this happen I can watch the jabberd process on server 2 (startet
with -D parameter, too) getting an incoming stream from server1, but
after the establish of the stream nothing more happen - the jabberd is
runnig on normal except that it seem to ignore the incoming stream after
    it is established (i see no more messages).

After a while I get, as said, the Server Connection timeout message to
the user. At server2 a see nothing at the errorlog, too, server1 says
that the message was bounced because of the server timeout in the
errorlog like it was already send to the user, too.

If I swap the sending and send a message from server2 to server1, the
same happens but swap (server connection messages on server2, no
reaction on server1 then).

The established connection between server1 and server2 is shown at the
netstat command, so i thing the tcp-connection is established..

I have no idea what could be wrong ? Someone who can help me ?

Thanks a lot already

Andre