Smack timeout during disconnect

marcogramy · August 26, 2021, 1:14pm

I’m experiencing problem in my server environment, using the latest Smack version 4.4.x (“smack-java8” library) during shutdown phase, when calling XMPPTCPConnection.disconnect() method.
Disconnect method take 5 seconds (timeout?) to be completed. Enabling Smack debug logs (setting smack.debugEnabled=true) these are sent messages with timestamps:

12:01:57 SENT (0): 
<presence from='backend@xmpp.catapush.rocks/Server1' id='BL621-2' type='unavailable'/>
12:01:57 SENT (0): 
<a xmlns='urn:xmpp:sm:3' h='3'/>
12:01:57 SENT (0): 
</stream:stream>
12:01:57 RECV (1): 
<presence type="unavailable" xmlns="jabber:client" to="backend@xmpp.catapush.rocks/Server2" from="backend@xmpp.catapush.rocks/Server1"/>
12:02:02 XMPPConnection closed (XMPPTCPConnection[backend@xmpp.catapush.rocks/Server1] (0))
12:02:02 SENT (1): 
<presence from='backend@xmpp.catapush.rocks/Server2' id='DRJ6F-2' type='unavailable'/>
<a xmlns='urn:xmpp:sm:3' h='3'/>
</stream:stream>
12:02:07 XMPPConnection closed (XMPPTCPConnection[backend@xmpp.catapush.rocks/Server2] (1))

Last log “XMPPConnection closed” comes from my XMPPConnectionListener when connectionClosed event is fired, exactly after 5 seconds from last sent packet.

Here another example, using only one Resource:

15:03:18 SENT (0): 
<presence from='backend@xmpp.catapush.rocks/Server1' id='8TJEI-2' type='unavailable'/>
15:03:18 SENT (0): 
<a xmlns='urn:xmpp:sm:3' h='2'/>
15:03:18 SENT (0): 
</stream:stream>
15:03:23 XMPPConnection closed (XMPPTCPConnection[backend@xmpp.catapush.rocks/Server1] (0))

Using previous “smack-java7” library version 4.3.5 I don’t find this behaviour, without having 5 seconds timeout, as can be seen from these logs:

14:49:41 SENT (0): <presence from='backend@xmpp.catapush.rocks/Server1' id='8fhPX-21' type='unavailable'></presence>
14:49:41 SENT (0): <a xmlns='urn:xmpp:sm:3' h='3'/>
14:49:41 SENT (0): 
14:49:41 SENT (0): </stream:stream>
14:49:41 RECV (1): <presence type="unavailable" xmlns="jabber:client" to="backend@xmpp.catapush.rocks/Server2" from="backend@xmpp.catapush.rocks/Server1"/>
14:49:41 XMPPConnection closed (XMPPTCPConnection[backend@xmpp.catapush.rocks/Server1] (0))
14:49:41 SENT (1): <presence from='backend@xmpp.catapush.rocks/Server2' id='8fhPX-23' type='unavailable'></presence><a xmlns='urn:xmpp:sm:3' h='3'/>
14:49:41 SENT (1): </stream:stream>
14:49:41 XMPPConnection closed (XMPPTCPConnection[backend@xmpp.catapush.rocks/Server2] (1))

Can someone help us?
Does this behaviour also occur to someone else?

Thank you!

Flow · August 26, 2021, 1:20pm

A thread dump taken at the right time would help. That said, my first guess is that Smack waits for the closing stream tag from the server, which is not sent. But then you should see the following log message:

github.com

igniterealtime/Smack/blob/0d73c21945710134c500867ab413082ec3e4404f/smack-core/src/main/java/org/jivesoftware/smack/AbstractXMPPConnection.java#L1026

    
      
          
          
/**
           * Shuts the current connection down.
           */
          protected abstract void shutdown();
          
          
protected final boolean waitForClosingStreamTagFromServer() {
              try {
                  waitForConditionOrThrowConnectionException(() -> closingStreamReceived, "closing stream tag from the server");
              } catch (InterruptedException | SmackException | XMPPException e) {
                  LOGGER.log(Level.INFO, "Exception while waiting for closing stream element from the server " + this, e);
                  return false;
              }
              return true;
          }
          
          
@Override
          public void addConnectionListener(ConnectionListener connectionListener) {
              if (connectionListener == null) {
                  return;
              }

marcogramy · August 27, 2021, 10:14am

Hi! Thank you for you reply!

I’m trying to log network traffic between smack and my XMPP server, but unfortunately I cannot have clear traffic despite settings

config.setSecurityMode(ConnectionConfiguration.SecurityMode.disabled);
config.setCompressionEnabled(false);

while establishing a connection.

With old Smack version (4.3.x) these 2 configs allow to have clear traffic but with this new version of smack start TLS anyway.
Am I forgetting something?

guus · September 2, 2021, 7:49pm

For what it’s worth, with a very basic client that performs a login and logout, I’m seeing an immediate disconnect. I was using Smack 4.4.2, connecting to Openfire 4.6.4.

<r xmlns='urn:xmpp:sm:3' />
<a xmlns='urn:xmpp:sm:3' h='15' />
21:45:16 RECV (0): 
<iq type="get" id="696-46" to="john@example.org/164vjih9bw" from="example.org">
  <query xmlns="http://jabber.org/protocol/disco#info"/>
</iq>
<presence id="K12R6-13" from="john@example.org/164vjih9bw" to="john@example.org/164vjih9bw">
  <priority>
    0
  </priority>
  <c xmlns="http://jabber.org/protocol/caps" hash="sha-1" node="https://igniterealtime.org/projects/smack" ver="lWpWNgqtfynY+MxupmhOr2LZqOg=">
  </c>
</presence>
<presence id="K12R6-14" type="unavailable" from="john@example.org/164vjih9bw" to="john@example.org/164vjih9bw"/>
</stream:stream>
21:45:16 XMPPConnection closed (XMPPTCPConnection[john@example.org/164vjih9bw] (0))

Process finished with exit code 0

Client code:

import org.jivesoftware.smack.*;
import org.jivesoftware.smack.tcp.*;

public class TestClient {
    public static void main(String[] args) throws Exception {
        XMPPTCPConnectionConfiguration config = XMPPTCPConnectionConfiguration.builder()
                .setUsernameAndPassword("john", "secret")
                .setXmppDomain("example.org")
                .setHost("localhost")
                .setPort(5222)
                .setSecurityMode(ConnectionConfiguration.SecurityMode.disabled)
                .build();

        AbstractXMPPConnection conn = new XMPPTCPConnection(config);
        conn.connect();
        conn.login();
        conn.disconnect();
    }
}

marcogramy · September 28, 2021, 4:27pm

Hi, thank you for your replies. Below the results of my test.

We have 6 connections with the same user, using 6 different Resources.
As you can see in the logs below, each connection incurs a 5 seconds timeout, the Xmpp server does not include the closing stream tag and we do not see the error log “Exception while waiting for closing stream element from the server”.

2021-09-28T15:55:36,707GMT INFO v6.2.1-SNAPSHOT [Thread-33](XMPPConnectionListener.java:25) com.xmpp.smack.XMPPConnectionListener: [ClientId: client-1] Connection closed
2021-09-28T15:55:41,708GMT INFO v6.2.1-SNAPSHOT [Thread-33](XMPPConnectionListener.java:25) com.xmpp.smack.XMPPConnectionListener: [ClientId: client-2] Connection closed
2021-09-28T15:55:46,710GMT INFO v6.2.1-SNAPSHOT [Thread-33](XMPPConnectionListener.java:25) com.xmpp.smack.XMPPConnectionListener: [ClientId: client-3] Connection closed
2021-09-28T15:55:51,712GMT INFO v6.2.1-SNAPSHOT [Thread-33](XMPPConnectionListener.java:25) com.xmpp.smack.XMPPConnectionListener: [ClientId: client-4] Connection closed
2021-09-28T15:55:56,714GMT INFO v6.2.1-SNAPSHOT [Thread-33](XMPPConnectionListener.java:25) com.xmpp.smack.XMPPConnectionListener: [ClientId: client-5] Connection closed
2021-09-28T15:56:01,715GMT INFO v6.2.1-SNAPSHOT [Thread-33](XMPPConnectionListener.java:25) com.xmpp.smack.XMPPConnectionListener: [ClientId: client-6] Connection closed

Here is the Xmpp traffic during the shutdown phase (with my comments):

# First connection sends shutdown and closes the stream
T 172.31.87.65:40214 -> 52.212.55.84:5222 [AP] #289
<presence from='user@xmpp.example.com/client-1' id='QCD1M-2' type='unavailable'/><a xmlns='urn:xmpp:sm:3' h='31'/></stream:stream>
#####
# Xmpp server sends disconnection event to other resources of the same user.
# Smack connections have these source ports:
40214
40216
40218
40220
40222
40224

All active clients receive the logout event (see below) with the 5 seconds timeout, as reported by XMPPConnectionListener.

T 52.212.55.84:5222 -> 172.31.87.65:40222 [AP] #294
<presence xmlns="jabber:client" from="user@xmpp.example.com/client-1" to="user@xmpp.example.com/client-5" type="unavailable"/>
##
T 52.212.55.84:5222 -> 172.31.87.65:40224 [AP] #296
<presence type="unavailable" xmlns="jabber:client" from="user@xmpp.example.com/client-1" id="QCD1M-1"><priority>0</priority><c hash="sha-1" ver="NfJ3flI83zSdUDzCEICtbypursw=" xmlns="http://jabber.org/protocol/caps" node="https://igniterealtime.org/projects/smack"/></presence>
#
T 52.212.55.84:5222 -> 172.31.87.65:40218 [AP] #297
<presence type="unavailable" xmlns="jabber:client" from="user@xmpp.example.com/client-1" id="QCD1M-1"><priority>0</priority><c hash="sha-1" ver="NfJ3flI83zSdUDzCEICtbypursw=" xmlns="http://jabber.org/protocol/caps" node="https://igniterealtime.org/projects/smack"/></presence>
###
T 52.212.55.84:5222 -> 172.31.87.65:40220 [AP] #300
<presence type="unavailable" xmlns="jabber:client" from="user@xmpp.example.com/client-1" id="QCD1M-1"><priority>0</priority><c hash="sha-1" ver="NfJ3flI83zSdUDzCEICtbypursw=" xmlns="http://jabber.org/protocol/caps" node="https://igniterealtime.org/projects/smack"/></presence>
##
T 52.212.55.84:5222 -> 172.31.87.65:40216 [AP] #302
<presence type="unavailable" xmlns="jabber:client" from="user@xmpp.example.com/client-1" id="QCD1M-1"><priority>0</priority><c hash="sha-1" ver="NfJ3flI83zSdUDzCEICtbypursw=" xmlns="http://jabber.org/protocol/caps" node="https://igniterealtime.org/projects/smack"/></presence>
#
#

T 172.31.87.65:40216 -> 52.212.55.84:5222 [AP] #304
<presence from='user@xmpp.example.com/client-2' id='17PJH-2' type='unavailable'/><a xmlns='urn:xmpp:sm:3' h='31'/></stream:stream>
#####
T 52.212.55.84:5222 -> 172.31.87.65:40218 [AP] #309
<presence type="unavailable" from="user@xmpp.example.com/client-2" xmlns="jabber:client" to="user@xmpp.example.com/client-3"/>
##
T 52.212.55.84:5222 -> 172.31.87.65:40220 [AP] #311
<presence type="unavailable" from="user@xmpp.example.com/client-2" xmlns="jabber:client" to="user@xmpp.example.com/client-4"/>
##
T 52.212.55.84:5222 -> 172.31.87.65:40224 [AP] #313
<presence type="unavailable" from="user@xmpp.example.com/client-2" xmlns="jabber:client" to="user@xmpp.example.com/client-6"/>
##
T 52.212.55.84:5222 -> 172.31.87.65:40222 [AP] #315
<presence xmlns="jabber:client" from="user@xmpp.example.com/client-2" type="unavailable" id="17PJH-1"><priority>0</priority><c hash="sha-1" ver="NfJ3flI83zSdUDzCEICtbypursw=" xmlns="http://jabber.org/protocol/caps" node="https://igniterealtime.org/projects/smack"/></presence>
#
#

T 172.31.87.65:40218 -> 52.212.55.84:5222 [AP] #317
<presence from='user@xmpp.example.com/client-3' id='LTZYC-2' type='unavailable'/><a xmlns='urn:xmpp:sm:3' h='32'/></stream:stream>
####
T 52.212.55.84:5222 -> 172.31.87.65:40220 [AP] #321
<presence type="unavailable" from="user@xmpp.example.com/client-3" xmlns="jabber:client" to="user@xmpp.example.com/client-4"/>
##
T 52.212.55.84:5222 -> 172.31.87.65:40224 [AP] #323
<presence type="unavailable" from="user@xmpp.example.com/client-3" xmlns="jabber:client" to="user@xmpp.example.com/client-6"/>
###
T 52.212.55.84:5222 -> 172.31.87.65:40222 [AP] #326
<presence xmlns="jabber:client" from="user@xmpp.example.com/client-3" type="unavailable" id="LTZYC-1"><priority>0</priority><c hash="sha-1" ver="NfJ3flI83zSdUDzCEICtbypursw=" xmlns="http://jabber.org/protocol/caps" node="https://igniterealtime.org/projects/smack"/></presence>
##


T 172.31.87.65:40220 -> 52.212.55.84:5222 [AP] #328
<presence from='user@xmpp.example.com/client-4' id='UWUH8-2' type='unavailable'/>
##
T 172.31.87.65:40220 -> 52.212.55.84:5222 [AP] #330
<a xmlns='urn:xmpp:sm:3' h='33'/></stream:stream>
#
T 52.212.55.84:5222 -> 172.31.87.65:40224 [AP] #331
<presence type="unavailable" from="user@xmpp.example.com/client-4" xmlns="jabber:client" to="user@xmpp.example.com/client-6"/>
#####
T 52.212.55.84:5222 -> 172.31.87.65:40222 [AP] #336
<presence xmlns="jabber:client" from="user@xmpp.example.com/client-4" type="unavailable" id="UWUH8-2"/>
###


T 172.31.87.65:40222 -> 52.212.55.84:5222 [AP] #339
<presence from='user@xmpp.example.com/client-5' id='CP7RJ-2' type='unavailable'/><a xmlns='urn:xmpp:sm:3' h='34'/></stream:stream>
#####
T 52.212.55.84:5222 -> 172.31.87.65:40224 [AP] #344
<presence type="unavailable" xmlns="jabber:client" from="user@xmpp.example.com/client-5" id="CP7RJ-1"><priority>0</priority><c hash="sha-1" ver="NfJ3flI83zSdUDzCEICtbypursw=" xmlns="http://jabber.org/protocol/caps" node="https://igniterealtime.org/projects/smack"/></presence>
#
#
T 172.31.87.65:40224 -> 52.212.55.84:5222 [AP] #346
<presence from='user@xmpp.example.com/client-6' id='DSZAW-2' type='unavailable'/><a xmlns='urn:xmpp:sm:3' h='35'/></stream:stream>
####

With previous Smack version (4.3.x) there was no problem even if the server didn’t send the closing tag.
Why does this behavior occur, with the Smack version 4.4.x?

We took also the thread dumps, if necessary we can share them.
Thank for again for your help!

Flow · September 28, 2021, 5:06pm

You do not see the exception?

Smack, being a well-behaved XMPP client library, awaits the closing stream tag for a few seconds to ensure that all pending stream elements have been drained from the server to the client. Hope that answers your question.

marcogramy · September 30, 2021, 8:21am

Hi Flow,
yes, we do not see the exception log.

system · December 1, 2021, 8:21am

This topic was automatically closed 62 days after the last reply. New replies are no longer allowed.