Smack sends some data twice after reconnection when Stream Management is enabled

Smack Smack Dev
1

Hi there,

I have a simple Android demo app where I enabled Stream Management

connection.setUseStreamManagement(true);

and also handle WiFi reconnection events via ConnectionListener

I noticed one strange thing when I switch OFF and then ON WiFi on my Android phone.
My app is reconnecting back to the server and in logs I see the following

12-02 15:05:41.411 31469-6611/com.igor.smackdemo D/SMACK: SENT (0): <stream:stream xmlns=‘jabber:client’ to=‘chat.quickblox.com’ xmlns:stream=‘http://etherx.jabber.org/streams’ version=‘1.0’ xml:lang=‘en’>

12-02 15:05:41.544 31469-6612/com.igor.smackdemo D/SMACK: RECV (0): <?xml version='1.0'?><stream:stream xmlns=‘jabber:client’ xmlns:stream=‘http://etherx.jabber.org/streams’ from=‘chat.quickblox.com’ id=‘ff35b34b-08dd-4a7c-9c18-adde7f014052’ version=‘1.0’ xml:lang=‘en’>

12-02 15:05:41.685 31469-6612/com.igor.smackdemo D/SMACK: RECV (0): stream:featuresPLAINANONYMOUSzlib</stream:features>

12-02 15:05:41.692 31469-6058/com.igor.smackdemo I/System.out: LOG > connected

12-02 15:05:41.692 31469-6058/com.igor.smackdemo D/SMACK: XMPPConnection connected (0)

12-02 15:05:41.692 31469-6611/com.igor.smackdemo D/SMACK: SENT (0): ADUxNzkyMTgtOTIAaWdvcnF1aWNrYmxveDcxMQ==

12-02 15:05:41.825 31469-6612/com.igor.smackdemo D/SMACK: RECV (0):

12-02 15:05:41.825 31469-6611/com.igor.smackdemo D/SMACK: SENT (0): <stream:stream xmlns=‘jabber:client’ to=‘chat.quickblox.com’ xmlns:stream=‘http://etherx.jabber.org/streams’ version=‘1.0’ id=‘ff35b34b-08dd-4a7c-9c18-adde7f014052’ xml:lang=‘en’>

12-02 15:05:41.966 31469-6612/com.igor.smackdemo D/SMACK: RECV (0): <?xml version='1.0'?><stream:stream xmlns=‘jabber:client’ xmlns:stream=‘http://etherx.jabber.org/streams’ from=‘chat.quickblox.com’ id=‘ff35b34b-08dd-4a7c-9c18-adde7f014052’ version=‘1.0’ xml:lang=‘en’>

12-02 15:05:42.138 31469-6612/com.igor.smackdemo D/SMACK: RECV (0): stream:featureszlib</stream:features>

12-02 15:05:42.138 31469-6611/com.igor.smackdemo D/SMACK: SENT (0): myresource

12-02 15:05:42.278 31469-6612/com.igor.smackdemo D/SMACK: RECV (0): 5179218-92@chat.quickblox.com/myresource

12-02 15:05:42.286 31469-6611/com.igor.smackdemo D/SMACK: SENT (0):

12-02 15:05:42.427 31469-6612/com.igor.smackdemo D/SMACK: RECV (0):

12-02 15:05:42.427 31469-6611/com.igor.smackdemo D/SMACK: SENT (0):

12-02 15:05:42.567 31469-6612/com.igor.smackdemo D/SMACK: RECV (0):

12-02 15:05:42.567 31469-6611/com.igor.smackdemo D/SMACK: SENT (0):

12-02 15:05:42.567 31469-6058/com.igor.smackdemo D/SMACK: User logged (0): 5179218-92@chat.quickblox.com:5222/myresource

12-02 15:05:42.567 31469-6058/com.igor.smackdemo I/System.out: LOG > authenticated

12-02 15:05:42.567 31469-6611/com.igor.smackdemo D/SMACK: SENT (0):

12-02 15:05:42.567 31469-6058/com.igor.smackdemo D/SMACK: XMPPConnection authenticated (0)

12-02 15:05:42.567 31469-6611/com.igor.smackdemo D/SMACK: SENT (0):

12-02 15:05:42.575 31469-6611/com.igor.smackdemo D/SMACK: SENT (0):

12-02 15:05:42.575 31469-6058/com.igor.smackdemo I/System.out: LOG > reconnectionSuccessful

12-02 15:05:42.575 31469-6058/com.igor.smackdemo D/SMACK: XMPPConnection reconnected (0)

12-02 15:05:42.575 31469-6611/com.igor.smackdemo D/SMACK: SENT (0): myresource

12-02 15:05:42.575 31469-6611/com.igor.smackdemo D/SMACK: SENT (0):

12-02 15:05:42.575 31469-6611/com.igor.smackdemo D/SMACK: SENT (0):

12-02 15:05:42.583 31469-6611/com.igor.smackdemo D/SMACK: SENT (0):

12-02 15:05:42.583 31469-6611/com.igor.smackdemo D/SMACK: SENT (0):

12-02 15:05:42.716 31469-6612/com.igor.smackdemo D/SMACK: RECV (0):

12-02 15:05:42.724 31469-6612/com.igor.smackdemo D/SMACK: RECV (0): 5179218-92@chat.quickblox.com/myresource<presence xmlns=“jabber:client” from="5179218-

12-02 15:05:42.724 31469-6611/com.igor.smackdemo D/SMACK: SENT (0):

12-02 15:05:42.731 31469-6611/com.igor.smackdemo D/SMACK: SENT (0):

12-02 15:05:42.731 31469-6611/com.igor.smackdemo D/SMACK: SENT (0):

12-02 15:05:42.739 31469-6611/com.igor.smackdemo D/SMACK: SENT (0):

12-02 15:05:42.739 31469-6611/com.igor.smackdemo D/SMACK: SENT (0):

12-02 15:05:42.755 31469-6611/com.igor.smackdemo D/SMACK: SENT (0):

12-02 15:05:42.864 31469-6612/com.igor.smackdemo D/SMACK: RECV (0): 92@chat.quickblox.com/myresource" to="5179218-92@chat.quickblox.com" id=“UCh61-30”>

12-02 15:05:42.864 31469-6611/com.igor.smackdemo D/SMACK: SENT (0):

So you can see that Smack sends some auth data twice

Here is my simple Android app to test this scenario

https://github.com/soulfly/smack-codesample/tree/master/android/SmackDemo/app/sr c/main/java/com/igor/smackdemo

2

Which Smack version?

3

The latest stable 4.1.5

4

-25, and -27 are duplicated. Those are and I’ve a pretty good idea what’s going wrong there. Tracked as SMACK-706.

I’ve uploaded Smack 4.1.6-SNAPSHOT to Maven Central’s snapshot repository, which includes Drop SM state before binding the resource · Flowdalic/Smack@0a1c7a3 · GitHub , could you try and report back if it fixes the issue for you?

5

Thanks, now no duplicates with the bind and session iqs.

But it still requests the roster more than 1 time. And after each connect/disconnect it started request it 1 time more each new reconnect.
For example, I did connect/disconnect 3 times on my Android phone, here is what I see in my logs then:

12-07 16:02:39.284 15464-16464/com.sdk.snippets I/Snippet: reconnectingIn: 5

12-07 16:02:44.291 15464-16464/com.sdk.snippets I/Snippet: reconnectingIn: 0

12-07 16:02:44.502 15464-16645/com.sdk.snippets D/SMACK: SENT (0): <stream:stream xmlns=‘jabber:client’ to=‘chat.quickblox.com’ xmlns:stream=‘http://etherx.jabber.org/streams’ version=‘1.0’ xml:lang=‘en’>

12-07 16:02:44.643 15464-16646/com.sdk.snippets D/SMACK: RECV (0): <?xml version='1.0'?><stream:stream xmlns=‘jabber:client’ xmlns:stream=‘http://etherx.jabber.org/streams’ from=‘chat.quickblox.com’ id=‘47ee1171-c9d3-4616-bc46-6185aefa4b9b’ version=‘1.0’ xml:lang=‘en’>

12-07 16:02:44.784 15464-16646/com.sdk.snippets D/SMACK: RECV (0): stream:featuresPLAINANONYMOUSzlib</stream:features>

12-07 16:02:44.784 15464-16464/com.sdk.snippets I/Snippet: connected

12-07 16:02:44.784 15464-16464/com.sdk.snippets D/SMACK: XMPPConnection connected (0)

12-07 16:02:44.791 15464-16645/com.sdk.snippets D/SMACK: SENT (0): ADUxNzkyMTgtOTIAaWdvcnF1aWNrYmxveDcxMQ==

12-07 16:02:44.932 15464-16646/com.sdk.snippets D/SMACK: RECV (0):

12-07 16:02:44.932 15464-16645/com.sdk.snippets D/SMACK: SENT (0): <stream:stream xmlns=‘jabber:client’ to=‘chat.quickblox.com’ xmlns:stream=‘http://etherx.jabber.org/streams’ version=‘1.0’ id=‘47ee1171-c9d3-4616-bc46-6185aefa4b9b’ xml:lang=‘en’>

12-07 16:02:45.073 15464-16646/com.sdk.snippets D/SMACK: RECV (0): <?xml version='1.0'?><stream:stream xmlns=‘jabber:client’ xmlns:stream=‘http://etherx.jabber.org/streams’ from=‘chat.quickblox.com’ id=‘47ee1171-c9d3-4616-bc46-6185aefa4b9b’ version=‘1.0’ xml:lang=‘en’>

12-07 16:02:45.252 15464-16646/com.sdk.snippets D/SMACK: RECV (0): stream:featureszlib</stream:features>

12-07 16:02:45.252 15464-16645/com.sdk.snippets D/SMACK: SENT (0): Smack

12-07 16:02:45.393 15464-16646/com.sdk.snippets D/SMACK: RECV (0): 5179218-92@chat.quickblox.com/Smack

12-07 16:02:45.393 15464-16645/com.sdk.snippets D/SMACK: SENT (0):

12-07 16:02:45.526 15464-16646/com.sdk.snippets D/SMACK: RECV (0):

12-07 16:02:45.534 15464-16645/com.sdk.snippets D/SMACK: SENT (0):

12-07 16:02:45.682 15464-16646/com.sdk.snippets D/SMACK: RECV (0):

12-07 16:02:45.682 15464-16645/com.sdk.snippets D/SMACK: SENT (0):

12-07 16:02:45.682 15464-16464/com.sdk.snippets D/SMACK: User logged (0): 5179218-92@chat.quickblox.com:5222/Smack

12-07 16:02:45.682 15464-16645/com.sdk.snippets D/SMACK: SENT (0):

12-07 16:02:45.682 15464-16464/com.sdk.snippets I/Snippet: authenticated

12-07 16:02:45.682 15464-16645/com.sdk.snippets D/SMACK: SENT (0):

12-07 16:02:45.682 15464-16645/com.sdk.snippets D/SMACK: SENT (0):

12-07 16:02:45.682 15464-16645/com.sdk.snippets D/SMACK: SENT (0):

12-07 16:02:45.690 15464-16645/com.sdk.snippets D/SMACK: SENT (0):

12-07 16:02:45.690 15464-16464/com.sdk.snippets D/SMACK: XMPPConnection authenticated (0)

12-07 16:02:45.690 15464-16464/com.sdk.snippets I/Snippet: reconnectionSuccessful

12-07 16:02:45.698 15464-16464/com.sdk.snippets D/SMACK: XMPPConnection reconnected (0)

12-07 16:02:45.698 15464-16645/com.sdk.snippets D/SMACK: SENT (0):

12-07 16:02:45.698 15464-16645/com.sdk.snippets D/SMACK: SENT (0):

12-07 16:02:46.534 15464-16646/com.sdk.snippets D/SMACK: RECV (0):

12-07 16:02:46.541 15464-16645/com.sdk.snippets D/SMACK: SENT (0):

12-07 16:02:46.549 15464-16645/com.sdk.snippets D/SMACK: SENT (0):

12-07 16:02:46.557 15464-16645/com.sdk.snippets D/SMACK: SENT (0):

12-07 16:02:46.557 15464-16645/com.sdk.snippets D/SMACK: SENT (0):

12-07 16:02:46.565 15464-16645/com.sdk.snippets D/SMACK: SENT (0):

12-07 16:02:46.565 15464-16645/com.sdk.snippets D/SMACK: SENT (0):

12-07 16:02:46.674 15464-16646/com.sdk.snippets D/SMACK: RECV (0):

12-07 16:02:46.682 15464-16645/com.sdk.snippets D/SMACK: SENT (0):

12-07 16:02:46.690 15464-16645/com.sdk.snippets D/SMACK: SENT (0):

And also the initial presence is sent each time.

Do you have any thoughts on this?
6

Short answer: After a quick look at the source I found no reason why the roster should be loaded multiple times. As this is usually tricked by Roster.reload(), you don’t call that method yourself in your application code? I also don’t remember seeing this when implementing $stuff (which of course, doesn’t mean that the bug slipped in).

7

Yes, I don’t use roster.reload() method

I did some debug and found that Smack calls this method only once, but in logs I see it many times

12-07 16:02:45.393 15464-16645/com.sdk.snippets D/SMACK: SENT (0):

12-07 16:02:45.526 15464-16646/com.sdk.snippets D/SMACK: RECV (0):

12-07 16:02:45.534 15464-16645/com.sdk.snippets D/SMACK: SENT (0):

12-07 16:02:45.682 15464-16646/com.sdk.snippets D/SMACK: RECV (0):

12-07 16:02:45.682 15464-16645/com.sdk.snippets D/SMACK: SENT (0):

12-07 16:02:45.682 15464-16464/com.sdk.snippets D/SMACK: User logged (0): 5179218-92@chat.quickblox.com:5222/Smack

12-07 16:02:45.682 15464-16645/com.sdk.snippets D/SMACK: SENT (0):

12-07 16:02:45.682 15464-16464/com.sdk.snippets I/Snippet: authenticated

12-07 16:02:45.682 15464-16645/com.sdk.snippets D/SMACK: SENT (0):

12-07 16:02:45.682 15464-16645/com.sdk.snippets D/SMACK: SENT (0):

12-07 16:02:45.682 15464-16645/com.sdk.snippets D/SMACK: SENT (0):

12-07 16:02:45.690 15464-16645/com.sdk.snippets D/SMACK: SENT (0):

12-07 16:02:45.690 15464-16464/com.sdk.snippets D/SMACK: XMPPConnection authenticated (0)

12-07 16:02:45.690 15464-16464/com.sdk.snippets I/Snippet: reconnectionSuccessful

12-07 16:02:45.698 15464-16464/com.sdk.snippets D/SMACK: XMPPConnection reconnected (0)

– Here I see my break point inside Roster.reload

12-07 16:02:45.698 15464-16645/com.sdk.snippets D/SMACK: SENT (0):

So I still don’t understand why I see this request many time in logs and what part of code is producing them

8

Is this with your SmackDemo app?

On approach to diagnose the cause would be to set a break point in Roster.reload() and view the call stack when it’s called. The four iq:roster get IQs should be caused by four calls to Roster.reload().

9

Yes, this is my SmackDemo app.

And I guess I found a root cause. did some deep debug

Every reconnect the Smack is trying to send all unacknowledged stanzas.

Since I don’t set any predicates via connection.addRequestAckPredicate() - the Predicate.forMessagesOrAfter5Stanzas() will be used.

So I don’t send 5 stanzas after start app and as the result - all ‘get roster’ requests stay in unacknowledged queue.

And Smack is trying to resend them every next connect.

So I added:

public class SMAskPredicate extends FlexibleStanzaTypeFilter {

@Override
protected boolean acceptSpecific(Stanza stanza) {

return true;

}

}

…

connection.addRequestAckPredicate(new SMAskPredicate());

and now it works correct - no duplicates

A bit tricky thing and hard to debug if you don’t know how XEP-0198 works

thanks
I updated my repo

10

We can actually just use

connection.addRequestAckPredicate(ForEveryStanza.INSTANCE);

11

And Smack is trying to resend them every next connect.

I doubt that we see resends because of unacked stanzas, for various reasons, but mostly because the stanza IDs of the four requests differ. The fact that you report setting the ForEveryStanza predicate fixes the issues doesn’t match to the different stanza IDs.

Edit: Of course, if RosterPacket’s wouldn’t had a stanza ID set on construction time…, but I’ve just looked and RosterPacket’s are constructed with a stanza ID.