Smack: Roster#presenceChanged() failed to deliver all received <presence/> stanza status to the presenceChanged() listener

Following is the log captured on aTalk upon user login. From the log, there are a total of 5 stanzas sent from server and received by smack, however only 3 out of 5 status update are relayed via PresenceEventListener to the app. Just to ensure that aTalk is not loading on Smack leading to the problem, presenceChanged() method contains only one single print statement in the testing i.e.

        @Override
        public void presenceChanged(final Presence presence)
        {
            logger.info("Smack presence update for: = " + presence.getFrom() + " - " + presence.getType());
            // firePresenceStatusChanged(presence);
        }

I also tried the followings, instead of using presenceChanged() event, I included aTalk own addAsyncStanzaListener(), addSyncStanzaListener with or without StanzaTypeFilter.PRESENCE,
the result remains unchanged i.e. the 2 missing stanzas are not received by the StanzaListener at all.

I included a debug log message right at the XMPPConnection#parsePackets(), after case Presence.ELEMENT: , and found that all the missing stanzas are also not received by this method i.e. class PacketReader().

                        switch (name) {
                        case Message.ELEMENT:
                        case IQ.IQ_ELEMENT:
                        case Presence.ELEMENT:
                            LOGGER.log(Level.WARNING,"### Stanza received: " + name);

I disabled the Smack debugger, from the log messages, again I see there is no change to the result.
I also found out that total time taken for parseAndProcessStanza(parser) is from 7~32ms in my test cases;
possibly that this has led to the observed problem?

  1. Can it be possible that the stanza streaming from server is too fast for Smack to handle?
    The stanzas is only separated by only 1~4 ms of each other.

  2. Is the PacketReader class designed only to read the stream input at fixed interval e.g. 10mS, hence it misses all the packets arrive during the silent wait period?

  3. What is different between Smack Debugger and the PacketReader, SmackDebuuger is able to see all the incoming stanzas but not the PacketReader? Any explanation.

  4. Is there anything else I can try to find the cause of the problem?

======= aTalk log on <presence/> stanza  ==========
06-01 18:34:32.545 608-1321/org.atalk.android D/SMACK: RECV (0): <presence xmlns="jabber:client" id="lKCk0-2123" from="test6@example.org/atalk">
       <status />
       <priority>35</priority>
       <show>chat</show>
       <x xmlns="vcard-temp:x:update" />
       <c xmlns="http://jabber.org/protocol/caps" node="http://android.atalk.org" hash="sha-1" ver="SPANeHrMhKxipyDRRXFZu1T21So=" />
    </presence>
06-01 18:34:32.548 608-1321/org.atalk.android D/SMACK: RECV (0): <presence xmlns="jabber:client" id="oDR64-283" from="test1@example.org/atalk">
       <status />
       <priority>30</priority>
       <c xmlns="http://jabber.org/protocol/caps" node="http://android.atalk.org" hash="sha-1" ver="SPANeHrMhKxipyDRRXFZu1T21So=" />
       <x xmlns="vcard-temp:x:update" />
    </presence>
06-01 18:34:32.549 608-1321/org.atalk.android D/SMACK: RECV (0): <presence xmlns="jabber:client" from="test2@example.org/test2">
       <show>away</show>
       <status>Ich bin gerade nicht hier</status>
       <query xmlns="jabber:iq:last" seconds="302" />
       <c xmlns="http://jabber.org/protocol/caps" node="http://pidgin.im/" hash="sha-1" ext="voice-v1 camera-v1 video-v1" ver="lV6i//bt2U8Rm0REcX8h4F3Nk3M=" />
       <x xmlns="vcard-temp:x:update">
          <photo>e3e1301f50e9c0ec70ab7a74e2fe584d05ba0d5d</photo>
       </x>
    </presence>
06-01 18:34:32.553 608-1321/org.atalk.android D/SMACK: RECV (0): <presence xmlns="jabber:client" id="C78YU-13" from="test7@example.org/jitsi-1t0srj5">
       <status />
       <priority>30</priority>
       <x xmlns="vcard-temp:x:update">
          <photo />
       </x>
       <c xmlns="http://jabber.org/protocol/caps" hash="sha-1" ext="" node="http://jitsi.org" ver="yrwYh3KH39OWQUWRdU4fOGclT5I=" />
    </presence>

06-01 18:34:32.787 608-1321/org.atalk.android D/SMACK: RECV (0): <presence xmlns="jabber:client" from="example.org" />

06-01 18:34:32.588 608-1708/org.atalk.android I/aTalk: [45844] impl.protocol.jabber.OperationSetPersistentPresenceJabberImpl.presenceChanged().1173 Smack presence available for: = test6@example.org/atalk
06-01 18:34:32.620 608-1709/org.atalk.android I/aTalk: [45845] impl.protocol.jabber.OperationSetPersistentPresenceJabberImpl.presenceChanged().1173 Smack presence available for: = test7@example.org/jitsi-1t0srj5
06-01 18:34:32.828 608-1711/org.atalk.android I/aTalk: [45846] impl.protocol.jabber.OperationSetPersistentPresenceJabberImpl.presenceChanged().1173 Smack presence available for: = null

[20180604]
For me to get an estimate of the time taken for each of the <presence/> phrase, I included two log statements one before and another after the parseAndProcessStanza(parser);

                        switch (name) {
                            case Presence.ELEMENT:
                                LOGGER.log(Level.WARNING, "Received Stanza: " + name);
                                try {
                                    parseAndProcessStanza(parser);
                                } finally {
                                    clientHandledStanzasCount = SMUtils.incrementHeight(clientHandledStanzasCount);
                                }
                                LOGGER.log(Level.WARNING, "End of parse Stanza: " + name);
                                break;

I observed one strange behavior is that parseAndProcessStanza() does not always return from the current <presence/> stanza processing, look like it is locked in the endless loop waiting for the end tag; it only exit after it receives another new <presence/> stanza.

In my new test, with only two test accounts active i.e. test1(Note8) and test2(Note3), neither of them can see each other presence status, not matter what I do. Then I decided to add another third test account running on Ubuntu gajim (test3). After the third account has logged into the server, all the sudden the other two test accounts (test1 & test2) are now able to see each other presence statuses, including the third test3 account. The third active account seems to have helped to resync/flush out the the all packets for processing, but itself is also being consumed.

  1. Can it be possible that the <presence/> is out of sync or end tag is not flushed out, leading to the parsePresence(XmlPullParser parser) waiting in endless loop, until the end tag is pushed out, refilled? and resync by the next incoming <presence/> stanza. It seems this is the root cause based on test results and observation.

Below the is the log captured on Note 8:
When only two accounts are active (test1 and test2), the below log shows that although test2 <presence/> is received, but is does not return from parseAndProcessStanza(parser) processing;

06-04 17:47:33.411 20221-20320/org.atalk.android D/SMACK: RECV (0): <presence xmlns="jabber:client" id="m4uyY-179" from="test2@example.org/atalk">
       <status />
       <priority>30</priority>
       <x xmlns="vcard-temp:x:update" />
       <c xmlns="http://jabber.org/protocol/caps" node="http://android.atalk.org" hash="sha-1" ver="SPANeHrMhKxipyDRRXFZu1T21So=" />
    </presence>
06-04 17:47:33.414 20221-20320/org.atalk.android W/aTalk: [49736] org.jivesoftware.smack.tcp.XMPPTCPConnection.parsePackets() Received Stanza: presence
### missing: "End of parse Stanza: presence"

Upon test3 account login: then test1, test2 and test3 all can see each other presence. From the log, It is seen that the previous <presence/> stanza “End of parse Stanza: presence” is triggered by the new incomiong <presence/> stanza, but itself is also being consumed. Just by chance, the server actually sent test3 <presence/> stanza twice, the first one although is being consumed by the previous <presence/> stanza, the second test3 <presence/> allows it to be processed and shown in the contact list.

06-04 17:48:46.644 20221-20320/org.atalk.android D/SMACK: RECV (0): <presence xmlns="jabber:client" id="eeb210cd-cc3a-49ef-9f00-d230b350186c" from="test3@example.org/gajim.8UMM7OSE">
       <priority>50</priority>
       <x xmlns="vcard-temp:x:update">
          <photo />
       </x>
       <c xmlns="http://jabber.org/protocol/caps" node="http://gajim.org" hash="sha-1" ver="p44lDLrkpzGW+3RnMPI52AXyZCc=" />
    </presence>
06-04 17:48:46.663 20221-20320/org.atalk.android W/aTalk: [49736] org.jivesoftware.smack.tcp.XMPPTCPConnection.parsePackets() End of parse Stanza: presence
06-04 17:48:46.664 20221-20320/org.atalk.android D/SMACK: RECV (0): <presence xmlns="jabber:client" id="a64da9ba-d498-4c16-aebd-619a849bb5c6" from="test3@example.org/gajim.8UMM7OSE">
       <priority>50</priority>
       <x xmlns="vcard-temp:x:update">
          <photo />
       </x>
       <c xmlns="http://jabber.org/protocol/caps" node="http://gajim.org" hash="sha-1" ver="p44lDLrkpzGW+3RnMPI52AXyZCc=" />
    </presence>
06-04 17:48:46.672 20221-20320/org.atalk.android W/aTalk: [49736] org.jivesoftware.smack.tcp.XMPPTCPConnection.parsePackets() Received Stanza: presence
06-04 17:48:46.689 20221-20320/org.atalk.android W/aTalk: [49736] org.jivesoftware.smack.tcp.XMPPTCPConnection.parsePackets() End of parse Stanza: presence

My first though would be that it is a bug within the presence parser. What would really help is a thread dump including the stacktrace of Smack’s packet reader thread. Then we would immediately see where there parser “hangs”.

If you are on Android, then you can acquire a thread dump using https://stackoverflow.com/a/13592951/194894

Thank for your guidance to learn another skill in android debugging. I found the problem using your proposed thread dump.

The problem is actually due to aTalk own VCardTempXUpdateProvider class implementation; the current implementation does not take care of a non-standard <presence/> stanza when the photo element is missing as compared to a standard.

<x xmlns='vcard-temp:x:update'><photo>186f39da130310dbc59002608c56d1bd26abd72d</photo></x>

This finding is most likely to fix many of my earlier reported problems.
Sorry for the inconvenience cause to the smack team, because of a fault created in atalk.

1 Like

No worries, I’m glad you fund the culprit. :slight_smile: