S2S - SASL authentication failed between two OF instances

Jabber-Server.de · January 28, 2016, 2:18pm

Hi there,

running into some strange issue between two OF instances - mostly configured the same way but one machine throws the following message during initial s2s connection setup:

Unable to authenticated the connection: SASL authentication failed (and dialback is not available)

Both using self signed certificates and the s2s config looks like this on both machines:

STARTTLS policy required
Mutual Authentication disabled
Certificate chain checking allow self signed + verify cert
Encryption Protocols TLS1,2,3 + SSL2 Hello

Machine #1 can write message to machine #2 (receivices it) but machine #1 did not receive a written message from machine #2.

What kind of missconfiguration can cause this issue? Note that s2s on machine #1 is working properly in both directions with other servers like jabber.ccc.de

akrherz · January 28, 2016, 3:44pm

Please enable debug log on both systems and see what interesting things get logged. Also, you are using Openfire 4.0.1 right?

Jabber-Server.de · January 28, 2016, 4:56pm

Yep, both running 4.0.1

machine #2 who receivices messages but can’t send shows the following in debug.log

2016.01.28 17:43:35 org.jivesoftware.openfire.server.ServerDialback[Acting as Receiving Server: Verify key with AS: machine#1 for OS: machine #2 (id ai8bh3jcx3)] - Successfully negotiated TLS with AS…

2016.01.28 17:43:35 org.jivesoftware.openfire.server.ServerDialback[Acting as Receiving Server: Verify key with AS: machine#1 for OS: machine #2 (id ai8bh3jcx3)] - Send the Authoritative Server a stream header and wait for answer.

2016.01.28 17:43:35 org.jivesoftware.openfire.server.ServerDialback[Acting as Receiving Server: Verify key with AS: machine#1 for OS: machine #2 (id ai8bh3jcx3)] - Got a response.

2016.01.28 17:43:35 org.jivesoftware.openfire.server.ServerDialback[Acting as Receiving Server: Verify key with AS:machine#1 for OS: machine #2 (id ai8bh3jcx3)] - The remote server is XMPP 1.0 compliant (or at least reports to be).

2016.01.28 17:43:35 org.jivesoftware.openfire.server.ServerDialback[Acting as Receiving Server: Verify key with AS: machine#1 for OS: machine #2 (id ai8bh3jcx3)] - Request for verification of the key and wait for response

2016.01.28 17:43:35 org.jivesoftware.openfire.server.ServerDialback[Acting as Receiving Server: Verify key with AS: machine#1 for OS: machine #2 (id ai8bh3jcx3)] - Key was VERIFIED by the Authoritative Server.

2016.01.28 17:43:35 org.jivesoftware.openfire.server.ServerDialback[Acting as Receiving Server: Verify key with AS: machine#1 for OS: machine #2 (id ai8bh3jcx3)] - Successfully verified key!

2016.01.28 17:43:35 org.jivesoftware.openfire.server.ServerDialback[Acting as Receiving Server: Validate domain:machine #2 (id ai8bh3jcx3) for OS: machine#1] - Dialback key isvalid. Sending verification result to remote domain.

2016.01.28 17:43:35 org.jivesoftware.openfire.server.ServerDialback[Acting as Receiving Server: Validate domain:machine #2(id ai8bh3jcx3) for OS: machine#1] - Successfully validated domain!

Furhter more machine #2 shows:

2016.01.28 17:49:49 org.jivesoftware.openfire.net.SocketUtil - Found 1 host(s) for XMPP domain ‘machine #1’.

2016.01.28 17:49:49 org.jivesoftware.openfire.net.SocketUtil - Trying to create socket connection to XMPP domain ‘machine #1’ using remote host: machine #1:5269 (blocks up to 120000 ms) …

2016.01.28 17:49:49 org.jivesoftware.openfire.net.SocketUtil - Successfully created socket connection to XMPP domain ‘machine #1’ using remote host: machine #1:5269!

2016.01.28 17:49:49 org.jivesoftware.openfire.session.LocalOutgoingServerSession[Create outgoing session for: machine #2 to machine #1] - Send the stream header and wait for response…

2016.01.28 17:49:49 org.jivesoftware.openfire.session.LocalOutgoingServerSession[Create outgoing session for: machine #2 to machine #1] - Got a response (stream ID: 6wuxepktd8, version: 1.0). Check if the remote server is XMPP 1.0 compliant…

2016.01.28 17:49:49 org.jivesoftware.openfire.session.LocalOutgoingServerSession[Create outgoing session for: machine #2 to machine #1] - The remote server is XMPP 1.0 compliant (or at least reports to be).

2016.01.28 17:49:49 org.jivesoftware.openfire.session.LocalOutgoingServerSession[Create outgoing session for: machine #2 to machine #1] - Processing stream features of the remote domain…

2016.01.28 17:49:49 org.jivesoftware.openfire.session.LocalOutgoingServerSession[Create outgoing session for: machine #2 to machine #1] - Check if both us as well as the remote server have enabled STARTTLS and/or dialback …

2016.01.28 17:49:49 org.jivesoftware.openfire.session.LocalOutgoingServerSession[Create outgoing session for: machine #2 to machine #1] - Both us and the remote server support the STARTTLS feature. Secure and authenticate the connection with TLS & SASL…

2016.01.28 17:49:49 org.jivesoftware.openfire.session.LocalOutgoingServerSession[Secure/Authenticate connection for: machine #2 to: machine #1] - Securing and authenticating connection …

2016.01.28 17:49:49 org.jivesoftware.openfire.session.LocalOutgoingServerSession[Secure/Authenticate connection for: machine #2 to:machine #1] - Indicating we want TLS and wait for response.

2016.01.28 17:49:49 org.jivesoftware.openfire.session.LocalOutgoingServerSession[Secure/Authenticate connection for: machine #2 to: machine #1] - Received ‘proceed’ from remote server. Negotiating TLS…

2016.01.28 17:49:49 org.jivesoftware.openfire.keystore.OpenfireX509TrustManager - Constructed trust manager. Number of trusted issuers: 163, accepts self-signed: true, checks validity: true

2016.01.28 17:49:50 org.jivesoftware.openfire.keystore.OpenfireX509TrustManager - Attempting to verify a chain of 1 certificates.

2016.01.28 17:49:50 org.jivesoftware.openfire.keystore.OpenfireX509TrustManager - Attempting to accept the self-signed certificate of this chain of length one, as instructed by configuration.

2016.01.28 17:49:50 org.jivesoftware.openfire.keystore.OpenfireX509TrustManager - Chain of one appears to be self-signed. Adding it to the set of trusted issuers.

2016.01.28 17:49:50 org.jivesoftware.openfire.keystore.OpenfireX509TrustManager - Validating chain with 1 certificates, using 158 trust anchors.

2016.01.28 17:49:50 org.jivesoftware.openfire.session.LocalOutgoingServerSession[Secure/Authenticate connection for: machine #2 to:machine #1] - TLS negotiation was successful. Connection secured. Proceeding with authentication…

2016.01.28 17:49:50 org.jivesoftware.openfire.session.LocalOutgoingServerSession[Create outgoing session for: machine #2 to machine #1] - Unable to secure and authenticate the connection with TLS & SASL.

2016.01.28 17:49:50 org.jivesoftware.openfire.session.LocalOutgoingServerSession[Create outgoing session for: machine #2 to machine centos7.1] - Something went wrong so close the connection and try server dialback over a plain connection

2016.01.28 17:49:50 org.apache.mina.filter.ssl.SslFilter - Session Server3: Writing Message : WriteRequest: HeapBuffer[pos=0 lim=263 cap=4096: 3C 6D 65 73 73 61 67 65 20 69 64 3D 22 77 43 46…]

2016.01.28 17:49:50 org.jivesoftware.openfire.server.OutgoingSessionPromise - OutgoingSessionPromise: Error sending packet to remote server: 50QQ45 java.lang.Exception: Failed to create connection to remote server at org.jivesoftware.openfire.server.OutgoingSessionPromise$PacketsProcessor.sendPa cket(OutgoingSessionPromise.java:279) at org.jivesoftware.openfire.server.OutgoingSessionPromise$PacketsProcessor.run(Ou tgoingSessionPromise.java:243)

And** machine #1** who can send and receivie messages shows this:

2016.01.28 17:44:04 org.jivesoftware.openfire.net.SocketConnection - Peer certificates have not been verified - there are no certificates to return for: null

javax.net.ssl.SSLPeerUnverifiedException: peer not authenticated at sun.security.ssl.SSLSessionImpl.getPeerCertificates(Unknown Source) at org.jivesoftware.openfire.net.SocketConnection.getPeerCertificates(SocketConnec tion.java:452) at org.jivesoftware.openfire.net.SASLAuthentication.getSASLMechanismsElement(SASLA uthentication.java:200) at org.jivesoftware.openfire.net.SASLAuthentication.getSASLMechanisms(SASLAuthenti cation.java:183) at org.jivesoftware.openfire.net.SocketReadingMode.tlsNegotiated(SocketReadingMode .java:117) at org.jivesoftware.openfire.net.BlockingReadingMode.tlsNegotiated(BlockingReading Mode.java:183) at org.jivesoftware.openfire.net.BlockingReadingMode.readStream(BlockingReadingMod e.java:139) at org.jivesoftware.openfire.net.BlockingReadingMode.run(BlockingReadingMode.java: 76) at org.jivesoftware.openfire.net.SocketReader.run(SocketReader.java:145) at java.lang.Thread.run(Unknown Source)

2016.01.28 17:44:04 org.jivesoftware.openfire.server.ServerDialback[Acting as Authoritative Server: Verify key sent by RS: machine #2 (id ai8bh3jcx3)] - Verifying key…

2016.01.28 17:44:04 org.jivesoftware.openfire.server.ServerDialback[Acting as Authoritative Server: Verify key sent by RS: machine #2 (id ai8bh3jcx3)] - Verification successful! Key was: VALID

I think machine #2 is the bad boy?

Jabber-Server.de · January 29, 2016, 1:28pm

Follow-up: I digged a little deeper and found the following debug.log of machine #2 (the one who can receive but not send):

2016.01.29 14:19:45 org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_RECEIVED event for session 6 2016.01.29 14:19:45 org.apache.mina.filter.codec.ProtocolCodecFilter - Processing a MESSAGE_RECEIVED for session 6 2016.01.29 14:19:45 class org.jivesoftware.openfire.streammanagement.StreamManager[148.251.217.203] - Received acknowledgement from client: h=15 2016.01.29 14:19:45 class org.jivesoftware.openfire.streammanagement.StreamManager[148.251.217.203] - Before processing client Ack (h=15): 5 unacknowledged stanzas. 2016.01.29 14:19:45 class org.jivesoftware.openfire.streammanagement.StreamManager[148.251.217.203] - After processing client Ack (h=15): 0 unacknowledged stanzas.
2016.01.29 14:19:45 org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_RECEIVED has been fired for session 6
2016.01.29 14:19:45 org.jivesoftware.openfire.session.LocalOutgoingServerSession[Create outgoing session for: machine #2 to machine #1] - Check if both us as well as the remote server have enabled STARTTLS and/or dialback ... 2016.01.29 14:19:45 org.jivesoftware.openfire.session.LocalOutgoingServerSession[Create outgoing session for: machine #2 to machine #1] - Both us and the remote server support the STARTTLS feature. Secure and authenticate the connection with TLS & SASL...
2016.01.29 14:19:45 org.jivesoftware.openfire.session.LocalOutgoingServerSession[Secure/Authenticate connection for: machine #2 to: machine #1] - Securing and authenticating connection ... 2016.01.29 14:19:45 org.jivesoftware.openfire.session.LocalOutgoingServerSession[Secure/Authenticate connection for: machine #2 to: machine #1] - Indicating we want TLS and wait for response. 2016.01.29 14:19:45 org.jivesoftware.openfire.session.LocalOutgoingServerSession[Secure/Authenticate connection for: machine #2 to: machine #1] - Received 'proceed' from remote server. Negotiating TLS... 2016.01.29 14:19:45 org.jivesoftware.openfire.keystore.OpenfireX509TrustManager - Constructed trust manager. Number of trusted issuers: 163, accepts self-signed: true, checks validity: true 2016.01.29 14:19:46 org.jivesoftware.openfire.keystore.OpenfireX509TrustManager - Attempting to verify a chain of 1 certificates. 2016.01.29 14:19:46 org.jivesoftware.openfire.keystore.OpenfireX509TrustManager - Attempting to accept the self-signed certificate of this chain of length one, as instructed by configuration. 2016.01.29 14:19:46 org.jivesoftware.openfire.keystore.OpenfireX509TrustManager - Chain of one appears to be self-signed. Adding it to the set of trusted issuers. 2016.01.29 14:19:46 org.jivesoftware.openfire.keystore.OpenfireX509TrustManager - Validating chain with 1 certificates, using 158 trust anchors. 2016.01.29 14:19:46 org.jivesoftware.openfire.session.LocalOutgoingServerSession[Secure/Authenticate connection for: machine #2 to: machine #1] - TLS negotiation was successful. Connection secured. Proceeding with authentication... 2016.01.29 14:19:46 org.jivesoftware.openfire.session.LocalOutgoingServerSession[Create outgoing session for: machine #2 to machine #1] - Unable to secure and authenticate the connection with TLS & SASL. 2016.01.29 14:19:46 org.jivesoftware.openfire.session.LocalOutgoingServerSession[Create outgoing session for: machine #2 to machine #1] - Something went wrong so close the connection and try server dialback over a plain connection 2016.01.29 14:19:46 org.apache.mina.filter.ssl.SslFilter - Session Server[6](SSL): Writing Message : WriteRequest: HeapBuffer[pos=0 lim=223 cap=4096: 3C 70 72 65 73 65 6E 63 65 20 74 6F 3D 22 72 65...] 2016.01.29 14:19:46 class org.jivesoftware.openfire.streammanagement.StreamManager[148.251.217.203] - Added stanza of type 'presence' to collection of unacknowledged stanzas (x=16). Collection size is now 1. 2016.01.29 14:19:46 org.jivesoftware.openfire.server.OutgoingSessionPromise - OutgoingSessionPromise: Error sending packet to remote server: <presence from="machine #2" to="machine #1"> <c xmlns="http://jabber.org/protocol/caps" node="http://conversations.im" hash="sha-1" ver="zakHMFRmGODGLpvwNK9/i4+qv84="/>

Everything looked good until “Unable to secure and authenticate the connection with TLS & SASL.” Then “Something went wrong so close the connection and try server dialback over a plain connection” and nothing happened…

Jabber-Server.de · February 3, 2016, 2:12pm

I tried this and that but still get the same issue after all

2016.02.03 15:04:56 org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_RECEIVED event for session 297 2016.02.03 15:04:56 org.apache.mina.filter.codec.ProtocolCodecFilter - Processing a MESSAGE_RECEIVED for session 297 2016.02.03 15:04:56 class org.jivesoftware.openfire.streammanagement.StreamManager[148.251.217.205] - Received acknowledgement from client: h=45 2016.02.03 15:04:56 class org.jivesoftware.openfire.streammanagement.StreamManager[148.251.217.205] - Before processing client Ack (h=45): 5 unacknowledged stanzas. 2016.02.03 15:04:56 class org.jivesoftware.openfire.streammanagement.StreamManager[148.251.217.205] - After processing client Ack (h=45): 0 unacknowledged stanzas. 2016.02.03 15:04:56 org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_RECEIVED has been fired for session 297 2016.02.03 15:04:56 org.jivesoftware.openfire.session.LocalOutgoingServerSession[Secure/Authenticate connection for: machine #2 to: machine #1] - TLS negotiation was successful. Connection secured. Proceeding with authentication... 2016.02.03 15:04:56 org.jivesoftware.openfire.session.LocalOutgoingServerSession[Create outgoing session for: machine #2 to: machine #1] - Unable to secure and authenticate the connection with TLS & SASL. 2016.02.03 15:04:56 org.jivesoftware.openfire.session.LocalOutgoingServerSession[Create outgoing session for: machine #2 to: machine #1] - Something went wrong so close the connection and try server dialback over a plain connection 2016.02.03 15:04:56 org.apache.mina.filter.ssl.SslFilter - Session Server[299](SSL): Writing Message : WriteRequest: HeapBuffer[pos=0 lim=247 cap=4096: 3C 6D 65 73 73 61 67 65 20 69 64 3D 22 70 75 72...] 2016.02.03 15:04:56 org.jivesoftware.openfire.server.OutgoingSessionPromise - OutgoingSessionPromise: Error sending packet to remote server: <message type="chat" id="purplef3ba6653" to="jid@machine#1/Spark" from="jid@machine#2/pidgin"> <active xmlns="http://jabber.org/protocol/chatstates"/> <body>hgmhgkm</body> </message> java.lang.Exception: Failed to create connection to remote server at org.jivesoftware.openfire.server.OutgoingSessionPromise$PacketsProcessor.sendPacket(OutgoingSessionPromise.java:279) at org.jivesoftware.openfire.server.OutgoingSessionPromise$PacketsProcessor.run(OutgoingSessionPromise.java:243) at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) at java.lang.Thread.run(Unknown Source) 2016.02.03 15:04:56 org.apache.mina.filter.ssl.SslFilter - Session Server[299](SSL): Writing Message : WriteRequest: HeapBuffer[pos=0 lim=247 cap=4096: 3C 6D 65 73 73 61 67 65 20 69 64 3D 22 70 75 72...] 2016.02.03 15:04:56 org.jivesoftware.openfire.server.OutgoingSessionPromise - OutgoingSessionPromise: Error sending packet to remote server (fast discard): <message type="chat" id="purplef3ba6654" to="jid@machine#1/Spark" from="jid@machine#2/pidgin"> <active xmlns="http://jabber.org/protocol/chatstates"/> </message>

Machine #1 only got an outgoing connection to machine #2 with dialback authentication an cipher TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256

Machine #2 only got an incoming connection from machine #1 with dialback authentication an cipher TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256

Fx1 · February 4, 2016, 11:41pm

Not sure, but seems it familiar with An exception occurred while creating outgoing session to remote server

Jabber-Server.de · February 7, 2016, 2:43pm

Thanks for the hint but it does not look similiar to me, because it reads “could not determine namespace bound to element prefix stream”.

During the initial s2s connection i run into this error: “Unable to secure and authenticate the connection with TLS & SASL.” Then “Something went wrong so close the connection and try server dialback over a plain connection”.