19 Replies Latest reply on Aug 24, 2017 10:14 PM by cmeng

    Smack 4.2.1-beta2-SNAPSHOT: No response received within reply timeout even when reply is received well within the specified PacketReplyTimeout.

    cmeng

      I am re-open the issue as it happens quite frequent (10~20%) while performing system testing on aTalk installed on Note 3. The "No response received within reply timeout" can happen under following conditions:

      1. Reply received well within the specified timeout (case #1)

      2. Even before the request stanza is sent (no log attached)

      3. Even before the request is sent (case #2)

       

      I am not sure if the problem happen because there are too many smack debug messages being sent to console.

       

      ======= Case #1 ===========

      08-03 11:50:45.881 D/SMACK: SENT (0): <iq to='leopard@atalk.org' id='cx166-109' type='get'><query xmlns='http://jabber.org/protocol/disco#info' node='eu.siacs.conversations.axolotl.devicelist'></query></iq>

      08-03 11:50:46.331 D/SMACK: RECV (0): <iq xml:lang='en' to='leopard@atalk.org/atalk' from='leopard@atalk.org' type='result' id='cx166-109'><query node='eu.siacs.conversations.axolotl.devicelist' xmlns='http://jabber.org/protocol/disco#info'><identity type='pep' category='pubsub'/><identity type='leaf' category='pubsub'/><identity type='registered' category='account'/><feature var='http://jabber.org/protocol/pubsub'/><feature var='http://jabber.org/protocol/rsm'/><feature var='http://jabber.org/protocol/pubsub#create-nodes'/><feature var='http://jabber.org/protocol/pubsub#auto-create'/><feature var='http://jabber.org/protocol/pubsub#auto-subscribe'/><feature var='http://jabber.org/protocol/pubsub#delete-nodes'/><feature var='http://jabber.org/protocol/pubsub#delete-items'/><feature var='http://jabber.org/protocol/pubsub#filtered-notifications'/><feature var='http://jabber.org/protocol/pubsub#modify-affiliations'/><feature var='http://jabber.org/protocol/pubsub#outcast-affiliation'/><feature var='http://jabber.org/protocol/pubsub#persistent-items'/><feature var='http://jabber.org/protoco

      08-03 11:50:46.331 D/SMACK: RECV (0): l/pubsub#publish'/><feature var='http://jabber.org/protocol/pubsub#purge-nodes'/><feature var='http://jabber.org/protocol/pubsub#retract-items'/><feature var='http://jabber.org/protocol/pubsub#retrieve-affiliations'/><feature var='http://jabber.org/protocol/pubsub#retrieve-items'/><feature var='http://jabber.org/protocol/pubsub#retrieve-subscriptions'/><feature var='http://jabber.org/protocol/pubsub#subscribe'/></query></iq>

      08-03 11:50:55.891 E/αTalk: [10] org.jivesoftware.smackx.omemo.OmemoManager.run() connectionListener.authenticated() failed to initialize OmemoManager: No response received within reply timeout. Timeout was 10000ms (~10s). Waited for response using: IQReplyFilter: iqAndIdFilter (AndFilter: (OrFilter: (IQTypeFilter: type=error, IQTypeFilter: type=result), StanzaIdFilter: id=cx166-109)), : fromFilter (OrFilter: (FromMatchesFilter (full): leopard@atalk.org, FromMatchesFilter (full): null)).

       

      ======= Case #2 ===========

      08-03 12:11:50.011 D/SMACK: SENT (0): </pubsub></iq><iq to='leopard@atalk.org' id='cx166-170' type='set'><pubsub xmlns='http://jabber.org/protocol/pubsub'><publish node='eu.siacs.conversations.axolotl.bundles:1011347036'><item><bundle xmlns='eu.siacs.conversations.axolotl'><signedPreKeyPublic signedPreKeyId='1'>BcdRaXODwwV2iX21saahdi5EXYx2zHnKL9ToLHwQPExS</signedPreKeyPu blic><signedPreKeySignature>9InTdCLINuWZFTQpidfrcoCthzXG0UEBWG6KC+0pLXUlclSKZo6C OLUCgZT26lfv7Xw5PUW+WkJwC7F2avykAA==</signedPreKeySignature><identityKey>BbZGG4d UIqGR4GkiE2QDSwoa2JnFyiTowje+tIlOkAZ5</identityKey><prekeys><preKeyPublic preKeyId='103'>BbW/KsLDl9IoAu9mmojckoRpRXBIRc+APhilqE+Ua193</preKeyPublic><preK eyPublic

      ....

      preKeyId='46'>BeXzeIe5mr3a0Dbz+wsSYpnHPt0zB9CdlzM6g2TpVuUH</preKeyPublic><preKey Public preKeyId='

      08-03 12:11:53.361 E/αTalk: [17] org.jivesoftware.smackx.omemo.OmemoManager.run() connectionListener.authenticated() failed to initialize OmemoManager: No response received within reply timeout. Timeout was 5000ms (~5s). Waited for response using: IQReplyFilter: iqAndIdFilter (AndFilter: (OrFilter: (IQTypeFilter: type=error, IQTypeFilter: type=result), StanzaIdFilter: id=cx166-170)), : fromFilter (OrFilter: (FromMatchesFilter (full): leopard@atalk.org, FromMatchesFilter (full): null)).

      08-03 12:12:02.861 D/SMACK: RECV (0): <iq xml:lang='en' to='leopard@atalk.org/atalk' from='leopard@atalk.org' type='result' id='cx166-170'><pubsub xmlns='http://jabber.org/protocol/pubsub'><publish node='eu.siacs.conversations.axolotl.bundles:1011347036'><item id='5DDB31097DC8F'/></publish></pubsub></iq>

        • Re: Smack 4.2.1-beta2-SNAPSHOT: No response received within reply timeout even when reply is received well within the specified PacketReplyTimeout.
          Paul Schaub

          Issue #2 is probably irrelevant, since the debugger not always preserves the correct order of stanzas when printing them to console.

           


          Regarding OMEMO there's already a fix that needs to be tested and merged.

          • Re: Smack 4.2.1-beta2-SNAPSHOT: No response received within reply timeout even when reply is received well within the specified PacketReplyTimeout.
            cmeng

            Hi Paul,

            Currently the turn around time taken for pubsub on Omemo bundle from send to reply takes ~4.4 seconds (Note 3) during aTalk system testing; it will be even logger for slow device and heavily loaded server (~6.7 seconds for S3). In aTalk implemented , I use SmackConfiguration.setDefaultReplyTimeout(10000), globally setting all stanza reply timeout to 10 seconds to ensure Omemo works under all environment. However setting to 10 Sec globally, at times causes aTalk to hang in black screen for that duration before returning to user (actually in most cases, the reply timeout is found to be caused by smack unable to detect the reply received even it is within the elapsed timeout.).

             

            I would appreciate if you would seriously consider setting the stanza reply timeout to longer (say 10 seconds) than the default smack timeout of 5 seconds temporary during omemo bundle sending. I would like to remove the aTalk approach to set globally reply timeout to 10 seconds.

             

            ================== aTalk log for Omemo Bundle Pubsub Timing ================

            08-09 09:06:08.859 D/SMACK: SENT (0): <iq to='leopard@atalk.org' id='tDoVV-136' type='set'><pubsub xmlns='http://jabber.org/protocol/pubsub'><publish node='eu.siacs.conversations.axolotl.bundles:1011347036'><item><bundle xmlns='eu.siacs.conversations.axolotl'>

            ..........

            <preKeyPublic preKeyId='14'>BX2+cFhupE</pubsub></iq>

            08-09 09:06:13.259 D/SMACK: RECV (0): <iq xml:lang='en' to='leopard@atalk.org/atalk' from='leopard@atalk.org' type='result' id='tDoVV-136'><pubsub xmlns='http://jabber.org/protocol/pubsub'><publish node='eu.siacs.conversations.axolotl.bundles:1011347036'><item id='5DE3AC3A3869A'/></publish></pubsub></iq>

             

            ============== aTalk log - screen black out for 10 seconds even reply received (10~50ms) within timeout (~10S)================

            08-09 10:34:10.539 D/SMACK: SENT (0): <presence to='chatroom-9z2e@conference.atalk.org/leopard' id='s311k-261'><x xmlns='http://jabber.org/protocol/muc'></x><x xmlns='vcard-temp:x:update'></x><c xmlns='http://jabber.org/protocol/caps' hash='sha-1' node='http://android.atalk.org' ver='ly4V5FEXrvryOHsfSaS6M5WX9WA='/></presence>

            08-09 10:34:10.589 D/SMACK: RECV (0): <presence xml:lang='en' to='leopard@atalk.org/atalk' from='chatroom-9z2e@conference.atalk.org/leopard' id='s311k-261'><x xmlns='vcard-temp:x:update'/><c xmlns='http://jabber.org/protocol/caps' hash='sha-1' node='http://android.atalk.org' ver='ly4V5FEXrvryOHsfSaS6M5WX9WA='/><x xmlns='http://jabber.org/protocol/muc#user'><item jid='leopard@atalk.org/atalk' role='moderator' affiliation='owner'/><status code='100'/><status code='201'/><status code='110'/></x></presence>

             

            08-09 10:34:10.869 D/SMACK: SENT (0): <iq to='chatroom-9z2e@conference.atalk.org' id='s311k-265' type='get'><query xmlns='http://jabber.org/protocol/disco#info'></query></iq>

            08-09 10:34:10.879 D/SMACK: RECV (0): <iq xml:lang='en' to='leopard@atalk.org/atalk' from='chatroom-9z2e@conference.atalk.org' type='result' id='s311k-265'><query xmlns='http://jabber.org/protocol/disco#info'><identity name='chatroom-9z2e' type='text' category='conference'/><feature var='vcard-temp'/><feature var='http://jabber.org/protocol/muc'/><feature var='muc_hidden'/><feature var='muc_temporary'/><feature var='muc_open'/><feature var='muc_nonanonymous'/><feature var='muc_moderated'/><feature var='muc_unsecured'/><feature var='urn:xmpp:mam:tmp'/><feature var='urn:xmpp:mam:0'/><feature var='urn:xmpp:mam:1'/><x type='result' xmlns='jabber:x:data'><field var='FORM_TYPE' type='hidden'><value>http://jabber.org/protocol/muc#roominfo</value></field><field var='muc#roominfo_description' type='text-single' label='Room description'/><field var='muc#roominfo_occupants' type='text-single' label='Number of occupants'><value>1</value></field></x></query></iq>

             

            08-09 10:34:20.539 E/αTalk: [16] impl.protocol.jabber.ChatRoomJabberImpl.joinAs().620 Failed to join room chatroom-9z2e@conference.atalk.org with nickname: leopard

                                        org.jivesoftware.smack.SmackException$NoResponseException: No response received within reply timeout. Timeout was 10000ms (~10s). Waited for response using: AndFilter: (StanzaTypeFilter: Presence, OrFilter: (AndFilter: (FromMatchesFilter (ignoreResourcepart): chatroom-9z2e@conference.atalk.org, MUCUserStatusCodeFilter: status=110), AndFilter: (FromMatchesFilter (full): chatroom-9z2e@conference.atalk.org/leopard, StanzaIdFilter: id=s311k-261, PresenceTypeFilter: type=error))).

                                            at org.jivesoftware.smack.StanzaCollector.nextResultOrThrow(StanzaCollector.java:2 53)

             

            08-09 10:34:20.879 W/System.err: org.jivesoftware.smack.SmackException$NoResponseException: No response received within reply timeout. Timeout was 10000ms (~10s). Waited for response using: IQReplyFilter: iqAndIdFilter (AndFilter: (OrFilter: (IQTypeFilter: type=error, IQTypeFilter: type=result), StanzaIdFilter: id=s311k-265)), : fromFilter (OrFilter: (FromMatchesFilter (full): chatroom-9z2e@conference.atalk.org)).

            08-09 10:34:20.879 W/System.err:     at org.jivesoftware.smack.StanzaCollector.nextResultOrThrow(StanzaCollector.java:2 53)

              • Re: Smack 4.2.1-beta2-SNAPSHOT: No response received within reply timeout even when reply is received well within the specified PacketReplyTimeout.
                Paul Schaub

                Hi cmeng!

                The timeout is caused by a carbon listener being registered synchronously, causing the packet reader thread to block. There is already a fix in the current 4.2 branch (2e61e0a4d333688187aa257a65bafe6783f80519). I don't know when this will be available in the maven repository, but you could build 4.2 yourself in order to test, if this fixes your problem

                  • Re: Smack 4.2.1-beta2-SNAPSHOT: No response received within reply timeout even when reply is received well within the specified PacketReplyTimeout.
                    cmeng

                    Thanks for the information and update. Currently I am facing other problems even from android studio

                    https://issuetracker.google.com/issues/64425255

                    Still trying to see if I am able to do something to avoid the problem.

                     

                    To build smack from source, I found out previously that I cannot just build the only module that is being affected, but need to build all the smack modules. This is because all smack modules have inter-dependency specified; and AS/gradle complain duplication if I just swap out one smack module. I try not to doing this, unless it is really unavoidable.

                    Hopefully smack will release a snapshot internally before I release next version 0.8.7 for atalk.

                      • Re: Smack 4.2.1-beta2-SNAPSHOT: No response received within reply timeout even when reply is received well within the specified PacketReplyTimeout.
                        cmeng

                        Look like the smack reply timeout is more serious in aTalk application operation. Beside black out the device screen, the user is also failed in joining the chat room either locally newly created chat room or invited from buddy; the reply timeout is 100% failure in atalk conference setup. Hopefully smack will release a SNAPSHOT fix soon.

                         

                        I try to build the smack 4.2 libraries as a plugin in aTalk, but there are so many built options in the gradle.build file. The AS gradle sync process just gives missing source error one after the other.

                          • Re: Smack 4.2.1-beta2-SNAPSHOT: No response received within reply timeout even when reply is received well within the specified PacketReplyTimeout.
                            cmeng

                            I proceed to build smack libraries from source pulled from branch 4.2 (f7ae216138ce6588377a165f484a20ed5bfe7c53)

                            GitHub - igniterealtime/Smack at 4.2

                            last change log: Merge remote-tracking branch 'ignite/4.2' into 4.2.

                             

                            to be included in aTalk testing. However the reported problem in this thread i.e.response reply timeout even when reply has been resolved remains unresolved.

                            1 of 1 people found this helpful
                              • Re: Smack 4.2.1-beta2-SNAPSHOT: No response received within reply timeout even when reply is received well within the specified PacketReplyTimeout.
                                Paul Schaub

                                Hm, good to know, thank you .

                                In three weeks or so I'm available to OMEMO again, until then I really appreciate how you keep searching for the issue .

                                  • Re: Smack 4.2.1-beta2-SNAPSHOT: No response received within reply timeout even when reply is received well within the specified PacketReplyTimeout.
                                    cmeng

                                    Hi Paul,

                                    I compare my current source checkout from the branch 4.2 and smack-4.2.1-beta2_SNAPSHOT source, I do not see much differences between the two. Am I testing source compiled from the wrong branch 4.2 (f7ae216138ce6588377a165f484a20ed5bfe7c53)

                                     

                                    As for your mentioned branch "There is already a fix in the current 4.2 branch (2e61e0a4d333688187aa257a65bafe6783f80519)", is this available to the public? What is the correct link?

                                      • Re: Smack 4.2.1-beta2-SNAPSHOT: No response received within reply timeout even when reply is received well within the specified PacketReplyTimeout.
                                        cmeng

                                        With reference to the muc <presence/> reply timeout at 100% failures. I traced into the MultiUserChat#enter(MucEnterConfiguration). Everything seems Ok including the responseFilter setup. Appreciate if someone can clarify the following:

                                         

                                        responseFilter checks for "status=110", however the <presence/> reply is with multiple "status codes".

                                        1. Does "status" and "status codes" are irrelevant during comparison? It is just the way the log message is being displayed.

                                        2. Does the collector iterate over all the received "status code" or just the first encountered?

                                         

                                        Also I found that within the MultiUserChat constructor line #191

                                        "final EntityFullJid from = presence.getFrom().asEntityFullJidIfPossible()"

                                        here the presence.getFrom() may return null hence throw exception if executed null.asEntityFullJidIfPossible()

                                         

                                         

                                        // Create a listener for all presence updates.
                                        presenceListener = new StanzaListener() {
                                           @Override
                                           public void processStanza(Stanza packet) {
                                           Presence presence = (Presence) packet;
                                           final EntityFullJid from = presence.getFrom().asEntityFullJidIfPossible();
                                           if (from == null) {
                                           LOGGER.warning("Presence not from a full JID: " + presence.getFrom());
                                           return;
                                           }

                                         

                                         

                                        // ==================================//

                                        <presence xml:lang='en' to='leopard@atalk.org/atalk' from='chatroom-9z2e@conference.atalk.org/leopard' id='s311k-261'><x xmlns='vcard-temp:x:update'/><c xmlns='http://jabber.org/protocol/caps' hash='sha-1' node='http://android.atalk.org' ver='ly4V5FEXrvryOHsfSaS6M5WX9WA='/><x xmlns='http://jabber.org/protocol/muc#user'><item jid='leopard@atalk.org/atalk' role='moderator' affiliation='owner'/><status code='100'/><status code='201'/><status code='110'/></x></presence>

                                         

                                        org.jivesoftware.smack.SmackException$NoResponseException: No response received within reply timeout. Timeout was 10000ms (~10s). Waited for response using: AndFilter: (StanzaTypeFilter: Presence, OrFilter: (AndFilter: (FromMatchesFilter (ignoreResourcepart): chatroom-9z2e@conference.atalk.org, MUCUserStatusCodeFilter: status=110), AndFilter: (FromMatchesFilter (full): chatroom-9z2e@conference.atalk.org/leopard, StanzaIdFilter: id=s311k-261, PresenceTypeFilter: type=error))).

                                                                        at org.jivesoftware.smack.StanzaCollector.nextResultOrThrow(StanzaCollector.java:2 53)

                                          • Re: Smack 4.2.1-beta2-SNAPSHOT: No response received within reply timeout even when reply is received well within the specified PacketReplyTimeout.
                                            cmeng

                                            The following is the error log that I have captured. However I am not sure how genuine is the debug log; as I have been experiencing AS sometimes just throws exception randomly

                                            (I have reported to AS in the link below. https://issuetracker.google.com/issues/64425255 )

                                             

                                            ====== Log capture with reply time out on joining chatroom =============

                                            08-14 23:00:48.753 A/art: art/runtime/thread.cc:1116] Throwing new exception 'Attempt to invoke virtual method 'org.jxmpp.jid.Jid org.jivesoftware.smack.packet.Presence.getFrom()' on a null object reference' with unexpected pending exception: org.jivesoftware.smack.SmackException$NoResponseException: No response received within reply timeout. Timeout was 10000ms (~10s). Waited for response using: AndFilter: (StanzaTypeFilter: Presence, OrFilter: (AndFilter: (FromMatchesFilter (ignoreResourcepart): chatroom1234@conference.icrypto.com, MUCUserStatusCodeFilter: status=110), AndFilter: (FromMatchesFilter (full): chatroom1234@conference.icrypto.com/leopard, StanzaIdFilter: id=STdAm-230, PresenceTypeFilter: type=error))).

                                            08-14 23:00:48.753 A/art: art/runtime/thread.cc:1116]   at org.jivesoftware.smack.packet.Stanza org.jivesoftware.smack.StanzaCollector.nextResultOrThrow(long) (StanzaCollector.java:253)

                                            08-14 23:00:48.753 A/art: art/runtime/thread.cc:1116]   at org.jivesoftware.smack.packet.Presence org.jivesoftware.smackx.muc.MultiUserChat.enter(org.jivesoftware.smackx.muc.Muc EnterConfiguration) (MultiUserChat.java:355)

                                            08-14 23:00:48.753 A/art: art/runtime/thread.cc:1116]   at void org.jivesoftware.smackx.muc.MultiUserChat.join(org.jivesoftware.smackx.muc.MucE nterConfiguration) (MultiUserChat.java:712)

                                            08-14 23:00:48.753 A/art: art/runtime/thread.cc:1116]   at void org.jivesoftware.smackx.muc.MultiUserChat.join(org.jxmpp.jid.parts.Resourcepart ) (MultiUserChat.java:604)

                                            08-14 23:00:48.753 A/art: art/runtime/thread.cc:1116]   at void net.java.sip.communicator.impl.protocol.jabber.ChatRoomJabberImpl.joinAs(java.l ang.String, byte[]) (ChatRoomJabberImpl.java:571)

                                          • Re: Smack 4.2.1-beta2-SNAPSHOT: No response received within reply timeout even when reply is received well within the specified PacketReplyTimeout.
                                            Paul Schaub

                                            Sorry, I haven't noticed that you linked the latest snapshot in the title. The fix is already in that build (unfortunately it seems to not work), so the problem is probably caused by something else.

                                              • Re: Smack 4.2.1-beta2-SNAPSHOT: No response received within reply timeout even when reply is received well within the specified PacketReplyTimeout.
                                                cmeng

                                                I have inserted some debug codes in both smack AbstractXMPPConnection.java and AbstractFromToMatchesFilter.java to better understand the sequence flow.

                                                With reference to smack MultiUserChat.java#enter(MucEnterConfiguration) and the below captured log for aTalk debug messages while joining chat room.

                                                 

                                                Following are my observations and understandings. Hopefully these help the smack team to find out the root cause of the reply timeout problem during muc setup.

                                                1. The initial send and receive of the disco#info are working properly without problem. The Stanza collector is able to report correctly the received reply.

                                                2.  Executing the "presence = connection.createStanzaCollectorAndSend(responseFilter, joinPresence).nextResultOrThrow(conf.getTimeout());"

                                                I have checked and verified that createStanzaCollector() registered correctly and added the responseFilter to the collectors.

                                                3. The #presenceInterceptor correctly receives and processes the <Presence> SENT.

                                                4. However the AbstractXMPPConnecor#invokeStanzaCollectorsAndNotifyRecvListeners(final Stanza) never get triggered even server has responded to the SENT <presence/>.

                                                The #presenceListener is also not being called to process the stanza (not sure if this is also expected or overridden by the collector filter setup).

                                                5. Exception "Attempt to invoke virtual method 'org.jxmpp.jid.Jid org.jivesoftware.smack.packet.Presence.getFrom()" from log

                                                If the above exception is in fact reflects the actual situation, look like StanzaCollector has triggered the exception somehow, hence failed to process further the RECV <presence/>.

                                                leading to reply timeout.

                                                 

                                                I am still unable to find the location where and how the received stanza is checked against the responseFilter before invokeStanzaCollectorsAndNotifyRecvListeners. Any help?

                                                 

                                                ============ aTalk log when joining chatRoom =============

                                                08-16 12:07:29.240 D/SMACK: SENT (0): <iq to='conference.icrypto.com' id='Vg0iy-216' type='get'><query xmlns='http://jabber.org/protocol/disco#info'></query></iq>

                                                08-16 12:07:29.250 D/SMACK: RECV (0): <iq xml:lang='en' to='leopard@icrypto.com/atalk' from='conference.icrypto.com' type='result' id='Vg0iy-216'><query xmlns='http://jabber.org/protocol/disco#info'><identity name='Chatrooms' type='text' category='conference'/><feature var='http://jabber.org/protocol/disco#info'/><feature var='http://jabber.org/protocol/disco#items'/><feature var='jabber:iq:register'/><feature var='http://jabber.org/protocol/muc'/><feature var='vcard-temp'/><feature var='urn:xmpp:mucsub:0'/><feature var='http://jabber.org/protocol/muc#unique'/><feature var='http://jabber.org/protocol/rsm'/><feature var='urn:xmpp:mam:tmp'/><feature var='urn:xmpp:mam:0'/><feature var='urn:xmpp:mam:1'/><x type='result' xmlns='jabber:x:data'><field var='FORM_TYPE' type='hidden'><value>http://jabber.org/network/serverinfo</value></field></x></query></iq>

                                                08-16 12:07:29.260 W/αTalk: [6] org.jivesoftware.smack.AbstractXMPPConnection.invokeStanzaCollectorsAndNotifyRe cvListeners() Collector: IQReplyFilter: iqAndIdFilter (AndFilter: (OrFilter: (IQTypeFilter: type=error, IQTypeFilter: type=result), StanzaIdFilter: id=Vg0iy-216)), : fromFilter (OrFilter: (FromMatchesFilter (full): conference.icrypto.com))

                                                08-16 12:07:29.260 W/αTalk: [6] org.jivesoftware.smack.filter.AbstractFromToMatchesFilter.accept() Accept Stanza: IQ Stanza (query http://jabber.org/protocol/disco#info) [to=leopard@icrypto.com/atalk,from=conference.icrypto.com,id=Vg0iy-216,type=result,]

                                                 

                                                 

                                                08-16 12:07:29.270 W/αTalk: [17] org.jivesoftware.smack.filter.AbstractFromToMatchesFilter.accept() Accept Stanza: Presence Stanza [to=chatroom1234@conference.icrypto.com/leopard,id=Vg0iy-215,type=available,]  ### cmeng - for presenceInterceptor

                                                08-16 12:07:29.270 D/SMACK: SENT (0): <presence to='chatroom1234@conference.icrypto.com/leopard' id='Vg0iy-215'><x xmlns='http://jabber.org/protocol/muc'></x><x xmlns='vcard-temp:x:update'></x><c xmlns='http://jabber.org/protocol/caps' hash='sha-1' node='http://android.atalk.org' ver='ly4V5FEXrvryOHsfSaS6M5WX9WA='/></presence>

                                                08-16 12:07:29.310 D/SMACK: RECV (0): <presence xml:lang='en' to='leopard@icrypto.com/atalk' from='chatroom1234@conference.icrypto.com/leopard' id='Vg0iy-215'><x xmlns='vcard-temp:x:update'/><c xmlns='http://jabber.org/protocol/caps' hash='sha-1' node='http://android.atalk.org' ver='ly4V5FEXrvryOHsfSaS6M5WX9WA='/><x xmlns='http://jabber.org/protocol/muc#user'><item jid='leopard@icrypto.com/atalk' role='moderator' affiliation='owner'/><status code='100'/><status code='201'/><status code='110'/></x></presence>

                                                08-16 12:07:29.310 D/SMACK: RECV (0): <message to='leopard@icrypto.com/atalk' from='chatroom1234@conference.icrypto.com' type='groupchat'><subject/></message>

                                                 

                                                08-16 12:07:39.430 A/art: art/runtime/thread.cc:1116] Throwing new exception 'Attempt to invoke virtual method 'org.jxmpp.jid.Jid org.jivesoftware.smack.packet.Presence.getFrom()' on a null object reference' with unexpected pending exception: org.jivesoftware.smack.SmackException$NoResponseException: No response received within reply timeout. Timeout was 10000ms (~10s). Waited for response using: AndFilter: (StanzaTypeFilter: Presence, OrFilter: (AndFilter: (FromMatchesFilter (ignoreResourcepart): chatroom1234@conference.icrypto.com, MUCUserStatusCodeFilter: status=110), AndFilter: (FromMatchesFilter (full): chatroom1234@conference.icrypto.com/leopard, StanzaIdFilter: id=Vg0iy-215, PresenceTypeFilter: type=error))).

                                                08-16 12:07:39.430 A/art: art/runtime/thread.cc:1116]  at org.jivesoftware.smack.packet.Stanza org.jivesoftware.smack.StanzaCollector.nextResultOrThrow(long) (StanzaCollector.java:253)

                                                  • Re: Smack 4.2.1-beta2-SNAPSHOT: No response received within reply timeout even when reply is received well within the specified PacketReplyTimeout.
                                                    cmeng

                                                    I decided to trace back previous aTalk releases to see when the reply timeout problem occurred

                                                    1. aTalk 0.8.1 to 0.8.4 - (smack 4.2.1-SNAPSHOT) muc setup work correctly without problem

                                                    2. aTalk 0.8.5 - (smack 4.2.1-beta2-SNAPSHOT) muc setup work correctly without problem

                                                    3. aTalk 0.8.6 - (smack 4.2.1-beta2-SNAPSHOT) muc reply timeout started

                                                    Checking on the change log, I really cannot see anything changes that can cause this problem. However I also realize that this is also the time at which I have updated the AS SDK which also shown up in debug log when aTalk starts (v0.8.6). Since the new SDK, I begin to see weird behavior during aTalk debug as reported in 

                                                    https://issuetracker.google.com/issues/64425255

                                                     

                                                    I now wonder the problem that I see are actually due to new AS SDK built.

                                                     

                                                    ===== aTalk start up with new SDK compiled code =========

                                                    08-17 07:14:45.490 I/MultiDex: VM with version 1.6.0 does not have multidex support

                                                    08-17 07:14:45.490 I/MultiDex: install

                                                    08-17 07:14:45.490 I/MultiDex: MultiDexExtractor.load(/data/app/org.atalk.android-2.apk, false)

                                                    08-17 07:14:45.500 I/MultiDex: Detected that extraction must be performed.

                                                     

                                                    ========================

                                                    Version: 0.8.6 - change log

                                                    Author: cmeng

                                                    Upload Date: 08/05/2017

                                                    - Fix implementation error in denying OTR session setup request from buddy while OMEMO session is in progress

                                                    - Implement XEP-0084 User Avatar publishing with reflection patch for Smack PepManager.publish to support old server

                                                    - Harmonize operations between XEP-0084 User Avatar and XEP-0153 VCardAvatar for co-existence

                                                    - When XEP-0084 is enabled, omit avatar hash in presence stanza VCardTempXUpdate x-extension

                                                    - Sync main menu avatar display with user selected picture

                                                    - Delay the auto software update version check on application start up

                                                    - Remove all unused smiley java files from built

                                                    - Remove large screen landscape contactList and chatFragment side-by-side support

                                                    • Re: Smack 4.2.1-beta2-SNAPSHOT: No response received within reply timeout even when reply is received well within the specified PacketReplyTimeout.
                                                      Flow

                                                      What you really want to do is taking a thread dump while the situation is happening: How to make Java Thread Dump in Android? - Stack Overflow

                                                       

                                                      That would most likely show the culprit.

                                                        • Re: Smack 4.2.1-beta2-SNAPSHOT: No response received within reply timeout even when reply is received well within the specified PacketReplyTimeout.
                                                          cmeng

                                                          Finally, I have found the root cause.

                                                          aTalk has implemented XEP-0084: User Avatar; if the option is enabled, then the  vcard-temp:x:update" (XEP-0153) will be sent as

                                                          <x xmlns='vcard-temp:x:update'></x>.in all the <presence/> stanza including the muc join room <presence/> stanza i.e. without <photo/> element.

                                                          However reply from server will be in short-form, and looks like smack does not like to see a single <x xmlns='vcard-temp:x:update'/> element without the <photo/> attribute. This results to a reply timeout exception thrown by smack.

                                                           

                                                          // ============ aTalk with XEP-0084 option enabled ==============

                                                          08-17 06:43:45.790 D/SMACK: SENT (0): <presence to='chatroom@conference.atalk.org/swan' id='M92qo-119'><x xmlns='http://jabber.org/protocol/muc'></x><x xmlns='vcard-temp:x:update'></x><c xmlns='http://jabber.org/protocol/caps' hash='sha-1' node='http://android.atalk.org' ver='ly4V5FEXrvryOHsfSaS6M5WX9WA='/></presence>

                                                          08-17 06:43:45.880 D/SMACK: RECV (0): <presence xml:lang='en' to='swan@atalk.org/atalk' from='chatroom@conference.atalk.org/swan' id='M92qo-119'><x xmlns='vcard-temp:x:update'/><c xmlns='http://jabber.org/protocol/caps' hash='sha-1' node='http://android.atalk.org' ver='ly4V5FEXrvryOHsfSaS6M5WX9WA='/><x xmlns='http://jabber.org/protocol/muc#user'><item jid='swan@atalk.org/atalk' role='moderator' affiliation='owner'/><status code='100'/><status code='110'/></x></presence>

                                                          ================== //

                                                           

                                                          If I enabled the full vcard-temp:x:update" (XEP-0153) together with <photo/> elements in <presence/> stanza when joining room, then smack works correctly as captured in the log below.

                                                          On seeing muc <presence/> with <photo/> hash, aTalk tries to retrieve the avatar from MUC. However smack throws an exception again as shown in the log below.

                                                          Setting vCards / Avatars for MUC rooms | ejabberd Docs

                                                           

                                                          aTalk has implemented catch, bus seems it is not captured???

                                                          try {
                                                             mVCard = vCardMgr.loadVCard((EntityBareJid) userId);
                                                          }
                                                          catch (SmackException.NoResponseException | XMPPException.XMPPErrorException
                                                             | SmackException.NotConnectedException | InterruptedException e) {
                                                             LOGGER.log(Level.WARNING, "Error while downloading VCard for: '" + userId
                                                             + "'. Exception: " + e.getMessage());
                                                          }

                                                           

                                                          ============= aTalk muc setup ================

                                                          08-17 17:35:51.418 D/SMACK: SENT (0): <presence to='chatroom1234@conference.icrypto.com/leopard' id='T0Fhc-212'><x xmlns='http://jabber.org/protocol/muc'></x><c xmlns='http://jabber.org/protocol/caps' hash='sha-1' node='http://android.atalk.org' ver='ly4V5FEXrvryOHsfSaS6M5WX9WA='/><x xmlns='vcard-temp:x:update'><photo>186f39da130310dbc59002608c56d1bd26abd72d</ph oto></x></presence>

                                                          08-17 17:35:51.468 D/SMACK: RECV (0): <presence xml:lang='en' to='leopard@icrypto.com/atalk' from='chatroom1234@conference.icrypto.com/leopard' id='T0Fhc-212'><c xmlns='http://jabber.org/protocol/caps' hash='sha-1' node='http://android.atalk.org' ver='ly4V5FEXrvryOHsfSaS6M5WX9WA='/><x xmlns='vcard-temp:x:update'><photo>186f39da130310dbc59002608c56d1bd26abd72d</ph oto></x><x xmlns='http://jabber.org/protocol/muc#user'><item jid='leopard@icrypto.com/atalk' role='moderator' affiliation='owner'/><status code='100'/><status code='201'/><status code='110'/></x></presence>

                                                          08-17 17:35:51.468 D/SMACK: RECV (0): <message to='leopard@icrypto.com/atalk' from='chatroom1234@conference.icrypto.com' type='groupchat'><subject/></message>

                                                          08-17 17:35:51.478 D/SMACK: SENT (0): <iq to='chatroom1234@conference.icrypto.com' id='T0Fhc-216' type='get'><vCard xmlns='vcard-temp'/></iq>

                                                          08-17 17:35:51.478 D/SMACK: SENT (0): <iq to='chatroom1234@conference.icrypto.com' id='T0Fhc-218' type='set'><query xmlns='http://jabber.org/protocol/muc#owner'><x xmlns='jabber:x:data' type='submit'></x></query></iq>

                                                          08-17 17:35:51.488 D/SMACK: SENT (0): <message to='chatroom1234@conference.icrypto.com' id='T0Fhc-219' type='groupchat'><subject>Group Chat</subject></message>

                                                          08-17 17:35:51.908 D/SMACK: RECV (0): <iq xml:lang='en' to='leopard@icrypto.com/atalk' from='chatroom1234@conference.icrypto.com' type='error' id='T0Fhc-216'><vCard xmlns='vcard-temp'/><error code='404' type='cancel'><item-not-found xmlns='urn:ietf:params:xml:ns:xmpp-stanzas'/></error></iq>

                                                          08-17 17:35:51.938 D/SMACK: RECV (0): <iq xml:lang='en' to='leopard@icrypto.com/atalk' from='chatroom1234@conference.icrypto.com' type='result' id='T0Fhc-218'/>

                                                          08-17 17:35:51.958 D/SMACK: RECV (0): <message xml:lang='en' to='leopard@icrypto.com/atalk' from='chatroom1234@conference.icrypto.com/leopard' type='groupchat' id='T0Fhc-219'><archived by='chatroom1234@conference.icrypto.com' id='1502962468715132' xmlns='urn:xmpp:mam:tmp'/><stanza-id by='chatroom1234@conference.icrypto.com' id='1502962468715132' xmlns='urn:xmpp:sid:0'/><subject>Group Chat</subject></message>

                                                          08-17 17:35:52.008 E/αTalk: [15] util.UtilActivator.uncaughtException().95 An uncaught exception occurred in thread=Thread[Smack-Cached Executor 1 (0),5,main] and message was: XMPP error reply received from chatroom1234@conference.icrypto.com: XMPPError: item-not-found - cancel

                                                                                      org.jivesoftware.smack.XMPPException$XMPPErrorException: XMPP error reply received from chatroom1234@conference.icrypto.com: XMPPError: item-not-found - cancel

                                                                                          at org.jivesoftware.smack.StanzaCollector.nextResultOrThrow(StanzaCollector.java:2 56)

                                                                                          at org.jivesoftware.smack.StanzaCollector.nextResultOrThrow(StanzaCollector.java:2 08)

                                                                                          at org.jivesoftware.smackx.vcardtemp.VCardManager.loadVCard(VCardManager.java:133)

                                                                                          at org.jivesoftware.smackx.avatar.vcardavatar.VCardAvatarManager.downloadVCard(VCa rdAvatarManager.java:186)

                                                                                          at org.jivesoftware.smackx.avatar.vcardavatar.VCardAvatarManager.parseContactPhoto Presence(VCardAvatarManager.java:294)

                                                                                          at org.jivesoftware.smackx.avatar.vcardavatar.VCardAvatarManager.access$300(VCardA vatarManager.java:45)

                                                                                          at org.jivesoftware.smackx.avatar.vcardavatar.VCardAvatarManager$3.processStanza(V CardAvatarManager.java:163)

                                                                                          at org.jivesoftware.smack.AbstractXMPPConnection$4.run(AbstractXMPPConnection.java :1202)

                                                                                          at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1120)

                                                                                          at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:588)

                                                                                          at java.lang.Thread.run(Thread.java:820)

                                                          08-17 17:35:52.028 E/αTalk: [16] util.UtilActivator.uncaughtException().95 An uncaught exception occurred in thread=Thread[Smack-Single Threaded Executor 0 (0),5,main] and message was: Attempt to invoke interface method 'boolean java.util.Iterator.hasNext()' on a null object reference

                                                                                      java.lang.NullPointerException: Attempt to invoke interface method 'boolean java.util.Iterator.hasNext()' on a null object reference

                                                                                          at org.jivesoftware.smackx.muc.MultiUserChat$3.processStanza(MultiUserChat.java:25 2)

                                                                                          at org.jivesoftware.smack.AbstractXMPPConnection$5.run(AbstractXMPPConnection.java :1228)

                                                                                          at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1120)

                                                                                          at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:588)

                                                                                          at java.lang.Thread.run(Thread.java:820)