I have two openfire servers I maintain - and after the ugprade to 3.7 the two servers refuse to talk to each other. I’ve verified that both server can talk to each other via telnet on port 5269 - but when I try to send a message to a user on the opposite server, its lost in never never land. Any ideas whats going on?
Enable debug log and have a lock at debug.log. Then show us the relevant parts of the logs.
Flow
Here is what I got from one of the servers:
2011.03.31 08:54:37 LocalOutgoingServerSession: OS - Trying to connect to jabber.modevia.com:5269(DNS lookup: jabber.modevia.com:5269)
2011.03.31 08:54:37 LocalOutgoingServerSession: OS - Plain connection to jabber.modevia.com:5269 successful
2011.03.31 08:54:37 LocalOutgoingServerSession: OS - Indicating we want TLS to jabber.modevia.com
2011.03.31 08:54:37 LocalOutgoingServerSession: OS - Negotiating TLS with jabber.modevia.com
2011.03.31 08:54:37 LocalOutgoingServerSession: OS - TLS negotiation with jabber.modevia.com was successful
2011.03.31 08:54:38 LocalOutgoingServerSession: OS - Error, EXTERNAL SASL and SERVER DIALBACK were not offered by jabber.modevia.com
2011.03.31 08:54:38 LocalOutgoingServerSession: OS - Going to try connecting using server dialback with: jabber.modevia.com
2011.03.31 08:54:38 ServerDialback: OS - Trying to connect to jabber.modevia.com:5269(DNS lookup: jabber.modevia.com:5269)
2011.03.31 08:54:38 ServerDialback: OS - Connection to jabber.modevia.com:5269 successful
2011.03.31 08:54:38 ServerDialback: OS - Sent dialback key to host: jabber.modevia.com id: 6c85b753 from domain: jabber.uww.edu
2011.03.31 08:54:38 ServerDialback: OS - Unexpected answer in validation from: jabber.modevia.com id: 6c85b753 for domain: jabber.uww.edu answer:<stream:features xmlns:stream="http://etherx.jabber.org/streams"><starttls xmlns="urn:ietf:params:xml:ns:xmpp-tls"/><dialback xmlns="urn:xmpp:features:dialback"/><mechanisms xmlns="urn:ietf:params:xml:ns:xmpp-sasl"/></stream:features>
2011.03.31 08:54:38 LocalOutgoingServerSession: OS - Trying to connect to modevia.com:5269(DNS lookup: jabber.modevia.com:5269)
2011.03.31 08:54:38 ServerDialback: AS - Verifying key for host: jabber.modevia.com id: 6c85b753
2011.03.31 08:54:38 ServerDialback: AS - Key was: VALID for host: jabber.modevia.com id: 6c85b753
2011.03.31 08:54:38 ServerDialback: AS - Connection closed for host: jabber.modevia.com id: 6c85b753
2011.03.31 08:54:38 LocalOutgoingServerSession: OS - Plain connection to modevia.com:5269 successful
2011.03.31 08:54:38 LocalOutgoingServerSession: OS - Going to try connecting using server dialback with: modevia.com
2011.03.31 08:54:38 ServerDialback: OS - Trying to connect to modevia.com:5269(DNS lookup: jabber.modevia.com:5269)
2011.03.31 08:54:38 ServerDialback: OS - Connection to modevia.com:5269 successful
2011.03.31 08:54:38 ServerDialback: OS - Invalid namespace in packet: <stream:stream from="jabber.modevia.com" id="I6iMc" xmlns="jabber:server" xmlns:stream="http://etherx.jabber.org/streams" version="1.0">
<message to="myusername1@jabber.modevia.com" id="108" type="chat" from="myusername2@jabber.uww.edu/Office">
<message to="myusername1@jabber.modevia.com" type="chat" id="109" from="myusername2@jabber.uww.edu/Office">
<message to="myusername1@jabber.modevia.com" id="110" type="chat" from="myusername2@jabber.uww.edu/Office">
<message to="myusername1@jabber.modevia.com" type="chat" id="111" from="myusername2@jabber.uww.edu/Office">
<message to="myusername1@jabber.modevia.com" id="112" type="chat" from="myusername2@jabber.uww.edu/Office">
2011.03.31 08:54:38 LocalOutgoingServerSession: OS - Trying to connect to jabber.modevia.com:5269(DNS lookup: jabber.modevia.com:5269)
2011.03.31 08:54:38 LocalOutgoingServerSession: OS - Plain connection to jabber.modevia.com:5269 successful
2011.03.31 08:54:38 LocalOutgoingServerSession: OS - Indicating we want TLS to jabber.modevia.com
2011.03.31 08:54:38 LocalOutgoingServerSession: OS - Negotiating TLS with jabber.modevia.com
2011.03.31 08:54:39 LocalOutgoingServerSession: OS - TLS negotiation with jabber.modevia.com was successful
2011.03.31 08:54:39 LocalOutgoingServerSession: OS - Error, EXTERNAL SASL and SERVER DIALBACK were not offered by jabber.modevia.com
2011.03.31 08:54:39 LocalOutgoingServerSession: OS - Going to try connecting using server dialback with: jabber.modevia.com
2011.03.31 08:54:39 ServerDialback: OS - Trying to connect to jabber.modevia.com:5269(DNS lookup: jabber.modevia.com:5269)
2011.03.31 08:54:39 ServerDialback: OS - Connection to jabber.modevia.com:5269 successful
2011.03.31 08:54:39 ServerDialback: OS - Sent dialback key to host: jabber.modevia.com id: f1902d94 from domain: jabber.uww.edu
2011.03.31 08:54:39 ServerDialback: OS - Unexpected answer in validation from: jabber.modevia.com id: f1902d94 for domain: jabber.uww.edu answer:<stream:features xmlns:stream="http://etherx.jabber.org/streams"><starttls xmlns="urn:ietf:params:xml:ns:xmpp-tls"/><dialback xmlns="urn:xmpp:features:dialback"/><mechanisms xmlns="urn:ietf:params:xml:ns:xmpp-sasl"/></stream:features>
2011.03.31 08:54:39 LocalOutgoingServerSession: OS - Trying to connect to modevia.com:5269(DNS lookup: jabber.modevia.com:5269)
2011.03.31 08:54:39 LocalOutgoingServerSession: OS - Plain connection to modevia.com:5269 successful
2011.03.31 08:54:39 ServerDialback: AS - Verifying key for host: jabber.modevia.com id: f1902d94
2011.03.31 08:54:39 ServerDialback: AS - Key was: VALID for host: jabber.modevia.com id: f1902d94
2011.03.31 08:54:39 ServerDialback: AS - Connection closed for host: jabber.modevia.com id: f1902d94
2011.03.31 08:54:39 LocalOutgoingServerSession: OS - Going to try connecting using server dialback with: modevia.com
2011.03.31 08:54:39 ServerDialback: OS - Trying to connect to modevia.com:5269(DNS lookup: jabber.modevia.com:5269)
2011.03.31 08:54:39 ServerDialback: OS - Connection to modevia.com:5269 successful
2011.03.31 08:54:39 ServerDialback: OS - Invalid namespace in packet: <stream:stream from="jabber.modevia.com" id="TMv7M" xmlns="jabber:server" xmlns:stream="http://etherx.jabber.org/streams" version="1.0">
<message to="myusername1@jabber.modevia.com" type="chat" id="113" from="myusername2@jabber.uww.edu/Office">
<message to="myusername1@jabber.modevia.com" id="114" type="chat" from="myusername2@jabber.uww.edu/Office">
<message to="myusername1@jabber.modevia.com" type="chat" id="115" from="myusername2@jabber.uww.edu/Office">
I am not 100 % sure, but try disabling dialback. There is a issue with server dialback in 3.7.0.
xmpp.server.dialback.enabled = false
Flow
I’m assuming this requires me to bounce the service? - I’ll give it a shot later tonight and report back.
Still no luck - tried disable server dialback, but it still fails. New logs are below.
2011.04.01 06:05:44 LocalOutgoingServerSession: OS - Trying to connect to jabber.modevia.com:5269(DNS lookup: jabber.modevia.com:5269)
2011.04.01 06:05:44 LocalOutgoingServerSession: OS - Plain connection to jabber.modevia.com:5269 successful
2011.04.01 06:05:44 [/140.146.150.205:3612] Data Read: org.apache.mina.filter.support.SSLHandler@1790581 (HeapBuffer[pos=0 lim=22 cap=64: 17 03 01 00 11 E5 85 B2 E8 CF 68 02 B7 D1 98 D8 6E A0 54 2E 0F 7B])
2011.04.01 06:05:44 [/140.146.150.205:3612] unwrap()
2011.04.01 06:05:44 [/140.146.150.205:3612] inNetBuffer: java.nio.DirectByteBuffer[pos=0 lim=22 cap=16665]
2011.04.01 06:05:44 [/140.146.150.205:3612] appBuffer: java.nio.DirectByteBuffer[pos=0 lim=33330 cap=33330]
2011.04.01 06:05:44 [/140.146.150.205:3612] Unwrap res:Status = OK HandshakeStatus = NOT_HANDSHAKING
bytesConsumed = 22 bytesProduced = 1
2011.04.01 06:05:44 [/140.146.150.205:3612] inNetBuffer: java.nio.DirectByteBuffer[pos=22 lim=22 cap=16665]
2011.04.01 06:05:44 [/140.146.150.205:3612] appBuffer: java.nio.DirectByteBuffer[pos=1 lim=33330 cap=33330]
2011.04.01 06:05:44 [/140.146.150.205:3612] Unwrap res:Status = BUFFER_UNDERFLOW HandshakeStatus = NOT_HANDSHAKING
bytesConsumed = 0 bytesProduced = 0
2011.04.01 06:05:44 [/140.146.150.205:3612] appBuffer: java.nio.DirectByteBuffer[pos=0 lim=1 cap=33330]
2011.04.01 06:05:44 [/140.146.150.205:3612] app data read: HeapBuffer[pos=0 lim=1 cap=1: 20] (20)
2011.04.01 06:05:44 Launching thread for /140.146.150.205:3612
2011.04.01 06:05:44 Exiting since queue is empty for /140.146.150.205:3612
2011.04.01 06:05:44 [/140.146.150.205:3611] Data Read: org.apache.mina.filter.support.SSLHandler@589361 (HeapBuffer[pos=0 lim=22 cap=128: 17 03 01 00 11 30 F1 1B 35 37 AC C2 1D DA C3 4F 28 66 80 F9 5A C6])
2011.04.01 06:05:44 [/140.146.150.205:3611] unwrap()
2011.04.01 06:05:44 [/140.146.150.205:3611] inNetBuffer: java.nio.DirectByteBuffer[pos=0 lim=22 cap=16665]
2011.04.01 06:05:44 [/140.146.150.205:3611] appBuffer: java.nio.DirectByteBuffer[pos=0 lim=33330 cap=33330]
2011.04.01 06:05:44 [/140.146.150.205:3611] Unwrap res:Status = OK HandshakeStatus = NOT_HANDSHAKING
bytesConsumed = 22 bytesProduced = 1
2011.04.01 06:05:44 [/140.146.150.205:3611] inNetBuffer: java.nio.DirectByteBuffer[pos=22 lim=22 cap=16665]
2011.04.01 06:05:44 [/140.146.150.205:3611] appBuffer: java.nio.DirectByteBuffer[pos=1 lim=33330 cap=33330]
2011.04.01 06:05:44 [/140.146.150.205:3611] Unwrap res:Status = BUFFER_UNDERFLOW HandshakeStatus = NOT_HANDSHAKING
bytesConsumed = 0 bytesProduced = 0
2011.04.01 06:05:44 [/140.146.150.205:3611] appBuffer: java.nio.DirectByteBuffer[pos=0 lim=1 cap=33330]
2011.04.01 06:05:44 [/140.146.150.205:3611] app data read: HeapBuffer[pos=0 lim=1 cap=1: 20] (20)
2011.04.01 06:05:44 Launching thread for /140.146.150.205:3611
2011.04.01 06:05:44 Exiting since queue is empty for /140.146.150.205:3611
2011.04.01 06:05:44 LocalOutgoingServerSession: OS - Indicating we want TLS to jabber.modevia.com
2011.04.01 06:05:44 LocalOutgoingServerSession: OS - Negotiating TLS with jabber.modevia.com
2011.04.01 06:05:44 [/140.146.150.206:1452] Data Read: org.apache.mina.filter.support.SSLHandler@1481dc3 (HeapBuffer[pos=0 lim=22 cap=64: 17 03 01 00 11 FC 7B D2 C9 48 FF 76 51 AB 63 07 A7 2E 79 04 D6 1B])
2011.04.01 06:05:44 [/140.146.150.206:1452] unwrap()
2011.04.01 06:05:44 [/140.146.150.206:1452] inNetBuffer: java.nio.DirectByteBuffer[pos=0 lim=22 cap=16665]
2011.04.01 06:05:44 [/140.146.150.206:1452] appBuffer: java.nio.DirectByteBuffer[pos=0 lim=33330 cap=33330]
2011.04.01 06:05:44 [/140.146.150.206:1452] Unwrap res:Status = OK HandshakeStatus = NOT_HANDSHAKING
bytesConsumed = 22 bytesProduced = 1
2011.04.01 06:05:44 [/140.146.150.206:1452] inNetBuffer: java.nio.DirectByteBuffer[pos=22 lim=22 cap=16665]
2011.04.01 06:05:44 [/140.146.150.206:1452] appBuffer: java.nio.DirectByteBuffer[pos=1 lim=33330 cap=33330]
2011.04.01 06:05:44 [/140.146.150.206:1452] Unwrap res:Status = BUFFER_UNDERFLOW HandshakeStatus = NOT_HANDSHAKING
bytesConsumed = 0 bytesProduced = 0
2011.04.01 06:05:44 [/140.146.150.206:1452] appBuffer: java.nio.DirectByteBuffer[pos=0 lim=1 cap=33330]
2011.04.01 06:05:44 [/140.146.150.206:1452] app data read: HeapBuffer[pos=0 lim=1 cap=1: 20] (20)
2011.04.01 06:05:44 Launching thread for /140.146.150.206:1452
2011.04.01 06:05:44 Exiting since queue is empty for /140.146.150.206:1452
2011.04.01 06:05:44 LocalOutgoingServerSession: OS - TLS negotiation with jabber.modevia.com was successful
2011.04.01 06:05:44 [/140.146.150.172:2567] Data Read: org.apache.mina.filter.support.SSLHandler@18acf07 (HeapBuffer[pos=0 lim=22 cap=64: 17 03 01 00 11 44 9C D4 2E CE AD EA 6D FB 8D B9 36 A9 E3 0A 28 B8])
2011.04.01 06:05:44 [/140.146.150.172:2567] unwrap()
2011.04.01 06:05:44 [/140.146.150.172:2567] inNetBuffer: java.nio.DirectByteBuffer[pos=0 lim=22 cap=16665]
2011.04.01 06:05:44 [/140.146.150.172:2567] appBuffer: java.nio.DirectByteBuffer[pos=0 lim=33330 cap=33330]
2011.04.01 06:05:44 [/140.146.150.172:2567] Unwrap res:Status = OK HandshakeStatus = NOT_HANDSHAKING
bytesConsumed = 22 bytesProduced = 1
2011.04.01 06:05:44 [/140.146.150.172:2567] inNetBuffer: java.nio.DirectByteBuffer[pos=22 lim=22 cap=16665]
2011.04.01 06:05:44 [/140.146.150.172:2567] appBuffer: java.nio.DirectByteBuffer[pos=1 lim=33330 cap=33330]
2011.04.01 06:05:44 [/140.146.150.172:2567] Unwrap res:Status = BUFFER_UNDERFLOW HandshakeStatus = NOT_HANDSHAKING
bytesConsumed = 0 bytesProduced = 0
2011.04.01 06:05:44 [/140.146.150.172:2567] appBuffer: java.nio.DirectByteBuffer[pos=0 lim=1 cap=33330]
2011.04.01 06:05:44 [/140.146.150.172:2567] app data read: HeapBuffer[pos=0 lim=1 cap=1: 20] (20)
2011.04.01 06:05:44 Launching thread for /140.146.150.172:2567
2011.04.01 06:05:44 Exiting since queue is empty for /140.146.150.172:2567
2011.04.01 06:05:44 LocalOutgoingServerSession: OS - Error, EXTERNAL SASL and SERVER DIALBACK were not offered by jabber.modevia.com
2011.04.01 06:05:44 LocalOutgoingServerSession: OS - Trying to connect to modevia.com:5269(DNS lookup: jabber.modevia.com:5269)
2011.04.01 06:05:44 LocalOutgoingServerSession: OS - Plain connection to modevia.com:5269 successful
2011.04.01 06:05:44 [/140.146.217.222:49184] Filtered Write: org.apache.mina.filter.support.SSLHandler@13e6a71
2011.04.01 06:05:44 [/140.146.217.222:49184] encrypt: HeapBuffer[pos=0 lim=219 cap=4096: 3C 6D 65 73 73 61 67 65 20 69 64 3D 22 32 33 22 20 74 6F 3D 22 61 78 65 6C 73 65 6E 61 40 6A 61 62 62 65 72 2E 75 77 77 2E 65 64 75 2F 68 6F 6D 65 22 20 66 72 6F 6D 3D 22 61 78 65 6C 73 65 61 61 40 6A 61 62 62 65 72 2E 6D 6F 64 65 76 69 61 2E 63 6F 6D 22 20 74 79 70 65 3D 22 65 72 72 6F 72 22 3E 3C 65 72 72 6F 72 20 63 6F 64 65 3D 22 34 30 34 22 20 74 79 70 65 3D 22 63 61 6E 63 65 6C 22 3E 3C 72 65 6D 6F 74 65 2D 73 65 72 76 65 72 2D 6E 6F 74 2D 66 6F 75 6E 64 20 78 6D 6C 6E 73 3D 22 75 72 6E 3A 69 65 74 66 3A 70 61 72 61 6D 73 3A 78 6D 6C 3A 6E 73 3A 78 6D 70 70 2D 73 74 61 6E 7A 61 73 22 2F 3E 3C 2F 65 72 72 6F 72 3E 3C 2F 6D 65 73 73 61 67 65 3E]
2011.04.01 06:05:44 [/140.146.217.222:49184] Wrap res:Status = OK HandshakeStatus = NOT_HANDSHAKING
bytesConsumed = 219 bytesProduced = 245
2011.04.01 06:05:44 [/140.146.217.222:49184] encrypted buf: HeapBuffer[pos=0 lim=245 cap=245: 17 03 01 00 F0 F6 E0 97 EA 5D 95 C2 A7 4B 18 E5 28 4C 70 A3 10 97 11 19 0B 04 D3 32 40 98 63 9C C3 18 59 6C 17 83 DE FE BF 88 2A 0D 97 A2 18 3C 26 B2 0B 1F 8A 7C A7 8B 37 18 F1 86 6F A2 5D BC 34 B1 EB 05 62 D6 5A A3 A4 CA D5 02 5A 10 13 52 61 66 37 DB 53 3D B0 3B 19 95 2A 43 CC E5 FB C5 89 EF 77 FA 4B 42 F6 B7 37 39 84 80 0A 8B 01 C9 A3 91 CF F5 88 1C 91 66 89 4C 31 FB 59 8A 73 66 7A 9D 6D B6 2D FA 91 38 4F FF 67 4E 7B 12 ED 41 F8 B8 6B 5A DB 6B C3 99 5B D3 4A 9B B0 A6 9F A5 E1 6A 0D FD 6E 6F 91 0E C9 30 47 42 32 60 81 F7 FA F4 B9 25 AA E3 FC B8 0E 21 6D 1F 75 5E 5F 8B BE EF DA A1 DA B9 04 60 04 E4 A0 C8 F2 FA AC 63 07 E1 78 F8 09 EC BE DD 03 18 2E AC B3 38 DB EE 0A B7 DA 0B 97 C3 81 F4 CA 08 3D 89 8F 08 2B 77 9A 03 20 F6 A1]
2011.04.01 06:05:44 OutgoingSessionPromise: Error sending packet to remote server:
<message to="myusername1@jabber.modevia.com" id="23" type="chat" from="myusername2@jabber.uww.edu/home">
<x xmlns="jabber:x:event">
<id>{D89A39A4-61B9-4979-B555-307A66CA8C0A}</id>
<composing/>
</x>
</message>
java.lang.Exception: Failed to create connection to remote server
at org.jivesoftware.openfire.server.OutgoingSessionPromise$PacketsProcessor.sendPacket(OutgoingSessionPromise.java:274)
at org.jivesoftware.openfire.server.OutgoingSessionPromise$PacketsProcessor.run(OutgoingSessionPromise.java:238)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)
2011.04.01 06:05:44 Launching thread for /140.146.217.222:49184
2011.04.01 06:05:44 Exiting since queue is empty for /140.146.217.222:49184
Any other ideas? I’m SOL and nothings getting through between the two servers. I can downgrade I guess, but I’d really hate to do that …
In case anyone is tracking this, it will be fixed in 3.7.1
Hello!
Dont know if this is also relevant reg. Dialback but I get the following error:
at org.jivesoftware.openfire.session.LocalOutgoingServerSession.createOutgoingSession(LocalOutgoingServerSession.java:278) at org.jivesoftware.openfire.session.LocalOutgoingServerSession.authenticateDomain(LocalOutgoingServerSession.java:208) at org.jivesoftware.openfire.server.OutgoingSessionPromise$PacketsProcessor.sendPacket(OutgoingSessionPromise.java:261) at org.jivesoftware.openfire.server.OutgoingSessionPromise$PacketsProcessor.run(OutgoingSessionPromise.java:238) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source) at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) at java.lang.Thread.run(Unknown Source) 2011.06.06 13:35:51 Error trying to connect to remote server: ch(DNS lookup: ch:5269) java.net.UnknownHostException: ch at java.net.PlainSocketImpl.connect(Unknown Source) at java.net.SocksSocketImpl.connect(Unknown Source) at java.net.Socket.connect(Unknown Source)
As you see instead of swissjabber.ch it simply looks for ch which obviously does not work out at all! 
Is this also a Dialback issue? The connections is listed as incoming only.
Starry
AFAIK it’s normal that openfire traverses the DNS tree upwards. It’s nothing OF-443 related.
Flow