powered by Jive Software

Smack timeout during disconnect

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!

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:

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?

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();
    }
}

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!

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.

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

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