powered by Jive Software

Smack-4.2.3 throws SmackException - NoResponseException even when the stanza is received within the timeout period

android

#1

aTalk continuous to face problem with the latest release of Smack v4.2.3. Smack just arbitrarily throws NoResponseException even the reply has been received within the timeout period. The NoResponseException is causing more problem than helping the application. I am really lost what to do for aTalk. Any suggestion to handle the problem.

aTalk user is complaining the device screen turns black; I have checked and verified that most of the problem are due to incorrect report of NoResponseException by smack, and the long timeout of 50s that aTalk has implemented on some stanza iq to take care of the slow server response.

Hello,
I wanted to let you know that aTalk has become unstabile and crashes a lot with black screen.
Can not send any logs.
Regards,
v 1.1.3

03-23 11:22:50.359 I/aTalk: [6880] impl.protocol.jabber.InfoRetriever.retrieveDetails().138 Start loading VCard information for: cmeng_atalk@5222.de
03-23 11:22:50.365 D/SMACK: SENT (1): <iq to='cmeng_atalk@5222.de' id='VnajQ-67' type='get'><vCard xmlns='vcard-temp'/></iq>
03-23 11:22:50.878 D/SMACK: RECV (1): <iq id='VnajQ-67' type='error' to='cmeng_atalk@5222.de/atalk'><error type='cancel'><item-not-found xmlns='urn:ietf:params:xml:ns:xmpp-stanzas'/></error></iq>
03-23 11:23:40.368 W/aTalk: [6880] org.jivesoftware.smackx.avatar.vcardavatar.VCardAvatarManager.downloadVCard() Error while downloading VCard for: 'cmeng_atalk@5222.de'. Exception: No response received within reply timeout. Timeout was 50000ms (~50s). Waited for response using: IQReplyFilter: iqAndIdFilter (AndFilter: (OrFilter: (IQTypeFilter: type=error, IQTypeFilter: type=result), StanzaIdFilter: id=VnajQ-67)), : fromFilter (OrFilter: (FromMatchesFilter (full): cmeng_atalk@5222.de, FromMatchesFilter (full): null)).
03-23 11:23:40.371 W/aTalk: [6880] impl.protocol.jabber.InfoRetriever.retrieveDetails().148 Failed to download Vcard from server!


03-23 11:23:05.827 D/SMACK: SENT (1): <iq id='VnajQ-68' type='set'><query xmlns='jabber:iq:roster'><item jid='swordfish@atalk.org' name='swordfish@atalk.org' subscription='none'><group>friend</group></item></query></iq><r xmlns='urn:xmpp:sm:3'/>
03-23 11:23:06.240 D/SMACK: RECV (1): <iq id='VnajQ-68' type='result' to='cmeng_atalk@5222.de/atalk'/><iq id='lx11112' type='set'><query ver='1' xmlns='jabber:iq:roster'><item jid='swordfish@atalk.org' subscription='none' name='swordfish@atalk.org'><group>friend</group></item></query>
03-23 11:23:55.828 W/System.err: org.jivesoftware.smack.SmackException$NoResponseException: No response received within reply timeout. Timeout was 50000ms (~50s). Waited for response using: IQReplyFilter: iqAndIdFilter (AndFilter: (OrFilter: (IQTypeFilter: type=error, IQTypeFilter: type=result), StanzaIdFilter: id=VnajQ-68)), : fromFilter (OrFilter: (FromMatchesFilter (full): null, FromMatchesFilter (ignoreResourcepart): cmeng_atalk@5222.de, FromMatchesFilter (full): 5222.de)).

and more like carbon, omemo etc ....

#2

It is very likely that this issue is caused by synchronous stanzalisteners that are registered somewhere in aTalk, which try to handle the result of your query, blocking the stanzacollector that is meant to receive the answer. This issue is hard to debug though without going through the whole source code.

Please look in aTalks source code for synchronous stanza listeners that do heavy lifting (like firing another iq and waiting for the result) and try to make them asynchronous if possible.


#3

Thanks for your input. I was also wondering if the problem is actually due
to aTalk. I see currently aTalk setup its own stanzaListener on few items.
I will try to remove them and use only event trigger from smacks.


#4

I have spent the last one week or so, gone through 3 rounds of source cleanup for aTalk to improve and optimize the smack stanza Listeners loading. Followings are some of the steps taken.
Note: Before the above changes, all aTalk code already uses only asyncStanzaListener.

  1. Removed all partial implemented aTalk features so as not to load smack unnecessary.
  2. Change aTalk stanza listeners to use the smack predefined stanza listeners, so aTalk code is only get called when the specific events have occurred.
  3. Whenever possible change the stanza listeners to have more specific stanza filter defined, so aTalk do not spent unnecessary time to filter for the required stanza.
  4. Removed the listeners once they are not further required.

After the above changes, it seems like there is some improvements in NoResponseException, however no completely eliminate them. I feel Smack stanza response checking is too sensitive to external resource sharing/loading; and aTalk apk happens to have many features implemented. I hope Smack team can help to investigate how to improve smack handling of stanza response so it is less sensitive to external loading.
As for aTalk, I really do not know what else can I try.

aTalk has already implemented Omemo, but seems like https://omemo.top/ indicates otherwise, and I can understand for as long the problem remains unresolved; It really have serious impact how users rate aTalk performance. Please help.

Following is the log captured with the latest source on Note-3:

04-02 22:25:40.611 19131-19346/org.atalk.android D/SMACK: SENT (0): <iq to='aaa123@atalk.org' id='07Czk-86' type='get'><query xmlns='http://jabber.org/protocol/disco#info' node='eu.siacs.conversations.axolotl.devicelist'></query></iq><r xmlns='urn:xmpp:sm:3'/>
04-02 22:25:41.521 19131-19347/org.atalk.android D/SMACK: RECV (0): <iq xml:lang='en' to='aaa123@atalk.org/atalk' from='aaa123@atalk.org' type='result' id='07Czk-86'><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/protocol/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>
04-02 22:25:50.611 19131-19391/org.atalk.android W/aTalk: [8] org.jivesoftware.smackx.omemo.OmemoService.fetchDeviceList() Ignore OmemoService fetchDeviceList response timeout: 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=07Czk-86)), : fromFilter (OrFilter: (FromMatchesFilter (full): aaa123@atalk.org, FromMatchesFilter (full): null)).

04-02 22:25:50.631 19131-19346/org.atalk.android D/SMACK: SENT (0): <iq to='aaa123@atalk.org' id='07Czk-88' type='set'><pubsub xmlns='http://jabber.org/protocol/pubsub'><publish node='eu.siacs.conversations.axolotl.devicelist'><item><list xmlns='eu.siacs.conversations.axolotl'><device id='329546192'/></list></item></publish></pubsub></iq>
04-02 22:25:50.831 19131-19347/org.atalk.android D/SMACK: RECV (0): <iq xml:lang='en' to='aaa123@atalk.org/atalk' from='aaa123@atalk.org' type='result' id='07Czk-88'><pubsub xmlns='http://jabber.org/protocol/pubsub'><publish node='eu.siacs.conversations.axolotl.devicelist'><item id='5F2A5CEE99790'/></publish></pubsub></iq>
04-02 22:26:00.641 19131-19391/org.atalk.android W/aTalk: [8] org.jivesoftware.smackx.omemo.OmemoService.publishDeviceList() Ignore OmemoService publishDeviceList response timeout: 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=07Czk-88)), : fromFilter (OrFilter: (FromMatchesFilter (full): aaa123@atalk.org, FromMatchesFilter (full): null)).

04-02 22:26:41.541 19131-19347/org.atalk.android W/aTalk: [10] org.jivesoftware.smack.AbstractXMPPConnection.callConnectionClosedOnErrorListener() Connection XMPPTCPConnection[aaa123@atalk.org/atalk] (0) closed with error
    org.jivesoftware.smack.SmackException: Parser got END_DOCUMENT event. This could happen e.g. if the server closed the connection without sending a closing stream element
        at org.jivesoftware.smack.tcp.XMPPTCPConnection$PacketReader.parsePackets(XMPPTCPConnection.java:1239)
        at org.jivesoftware.smack.tcp.XMPPTCPConnection$PacketReader.access$300(XMPPTCPConnection.java:994)
        at org.jivesoftware.smack.tcp.XMPPTCPConnection$PacketReader$1.run(XMPPTCPConnection.java:1010)
        at java.lang.Thread.run(Thread.java:818)
04-03 12:28:36.601 17794-20535/org.atalk.android D/SMACK: SENT (0): <a xmlns='urn:xmpp:sm:3' h='5'/><iq to='aaa123@atalk.org' id='Iz26w-115' type='get'><pubsub xmlns='http://jabber.org/protocol/pubsub'><items node='eu.siacs.conversations.axolotl.devicelist'/></pubsub></iq><r xmlns='urn:xmpp:sm:3'/>
    RECV (0): <iq xml:lang='en' to='aaa123@atalk.org/atalk' from='aaa123@atalk.org' type='result' id='Iz26w-115'><pubsub xmlns='http://jabber.org/protocol/pubsub'><set xmlns='http://jabber.org/protocol/rsm'><index>0</index><count>10</count><first index='0'>creation@001522:724015:838095</first><last>creation@001522:713874:133728</last></set><items node='eu.siacs.conversations.axolotl.devicelist'><item id='5F2B0C2FCC34C'><list xmlns='eu.siacs.conversations.axolotl'><device id='329546192'/></list></item><item id='5F2B0BDF3C654'><list xmlns='eu.siacs.conversations.axolotl'><device id='329546192'/></list></item><item id='5F2B0992A1D25'><list xmlns='eu.siacs.conversations.axolotl'><device id='329546192'/></list></item><item id='5F2B075B457FF'><list xmlns='eu.siacs.conversations.axolotl'><device id='329546192'/></list></item><item id='5F2AEBBB4D332'><list xmlns='eu.siacs.conversations.axolotl'><device id='329546192'/></list></item><item id='5F2AEBB2E0D2C'><list xmlns='eu.siacs.conversations.axolotl'><device id='329546192'/></list></item><item id='5F2AEBAEBE4FA'><list xmlns='eu.siacs.conversations.axolotl'><device id='329546192'/></list></item><item id='5F2AEBAA8E5DC'><list xmlns='eu.siacs.conversations.axolotl'><device id='329546192'/></list></item><item id='5F2AE49AA3F2E'><list xmlns='eu.siacs.conversations.axolotl'><device id='329546192'/></list></item><item id='5F2AE492203DE'><list xmlns='eu.siacs.conversations.axolotl'><device id='329546192'/></list></item></items></pubsub></iq>
04-03 12:28:46.611 17794-20538/org.atalk.android E/aTalk: [15] org.atalk.crypto.omemo.AndroidOmemoService.initializationFailed().127 OmemoManager init failed
    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=Iz26w-115)), : fromFilter (OrFilter: (FromMatchesFilter (full): aaa123@atalk.org, FromMatchesFilter (full): null)).
        at org.jivesoftware.smack.StanzaCollector.nextResultOrThrow(StanzaCollector.java:260)

#5

That’s usually an indication that the service closed the (TCP) connection.


#6

Following log is captured with the sequence of events as follow:
a. After aaa123 has authenticated, it sends its own </presence/> stanza.
b. The server then relays this </presence> to all the aaa123 active resources.
c. OmemoManager init failed due to NoResponseException even the stanza has been received.
d. Then aaa123 is logout, however ejabberd does not response to the closing stream. Smack throws exception to that effect as expected.
e. But smack issues another warning: Failed to parse extension element in Presence stanza: “java.net.SocketException: socket is closed” from: 'aaa123@atalk.org/atalk id: ‘TGWmD-82’

  1. Why it says the socket is closed from … ‘TGWmD-82’ and not at logout (d)?
  2. I just wonder can the problem of (c) is actually due to (b) unable to parse extension elements in presence. Is smack not designed to handle the two extensions below?

<x xmlns='vcard-temp:x:update'/> <c xmlns='http://jabber.org/protocol/caps' hash='sha-1' node='http://android.atalk.org' ver='+2gTKKtAURCQpAYqIsV3IgTmQRU='/>

======= atalk log on Note-3 with account aaa123 =========
04-03 17:58:25.239 28045-28259/org.atalk.android D/SMACK: SENT (0): <presence id='TGWmD-82'><status></status><priority>30</priority><x xmlns='vcard-temp:x:update'></x><c xmlns='http://jabber.org/protocol/caps' hash='sha-1' node='http://android.atalk.org' ver='+2gTKKtAURCQpAYqIsV3IgTmQRU='/></presence>
04-03 17:58:26.149 28045-28264/org.atalk.android D/SMACK: RECV (0): <presence xml:lang='en' to='aaa123@atalk.org/atalk' from='aaa123@atalk.org/atalk' id='TGWmD-82'><x xmlns='vcard-temp:x:update'/><c xmlns='http://jabber.org/protocol/caps' hash='sha-1' node='http://android.atalk.org' ver='+2gTKKtAURCQpAYqIsV3IgTmQRU='/><priority>30</priority><status/></presence>
04-03 17:58:26.149 28045-28259/org.atalk.android D/SMACK: SENT (0): <iq to='aaa123@atalk.org' id='TGWmD-84' type='get'><pubsub xmlns='http://jabber.org/protocol/pubsub'><items node='eu.siacs.conversations.axolotl.devicelist'/></pubsub></iq>
04-03 17:58:26.519 28045-28264/org.atalk.android D/SMACK: RECV (0): <r xmlns='urn:xmpp:sm:3'/>
04-03 17:58:26.529 28045-28264/org.atalk.android D/SMACK: RECV (0): <iq xml:lang='en' to='aaa123@atalk.org/atalk' from='aaa123@atalk.org' type='result' id='TGWmD-84'><pubsub xmlns='http://jabber.org/protocol/pubsub'><set xmlns='http://jabber.org/protocol/rsm'><index>0</index><count>10</count><first index='0'>creation@001522:748713:999128</first><last>creation@001522:723346:664563</last></set><items node='eu.siacs.conversations.axolotl.devicelist'><item id='5F2B6CA9F37B7'><list xmlns='eu.siacs.conversations.axolotl'><device id='329546192'/></list></item><item id='5F2B6C9AE368F'><list xmlns='eu.siacs.conversations.axolotl'><device id='329546192'/></list></item><item id='5F2B6585E120F'><list xmlns='eu.siacs.conversations.axolotl'><device id='329546192'/></list></item><item id='5F2B43CF1363C'><list xmlns='eu.siacs.conversations.axolotl'><device id='329546192'/></list></item><item id='5F2B3CC0DE7F'><list xmlns='eu.siacs.conversations.axolotl'><device id='329546192'/></list></item><item id='5F2B35E42E1E6'><list xmlns='eu.siacs.conversations.axolotl'><device id='329546192'/></list></item><item id='5F2B35924711D'><list xmlns='eu.siacs.conversations.axolotl'><device id='329546192'/></list></item><item id='5F2B0C2FCC34C'><list xmlns='eu.siacs.conversations.axolotl'><device id='329546192'/></list></item><item id='5F2B0BDF3C654'><list xmlns='eu.siacs.conversations.axolotl'><device id='329546192'/></list></item><item id='5F2B0992A1D25'><list xmlns='eu.siacs.conversations.axolotl'><device id='329546192'/></list></item></items></pubsub></iq>
04-03 17:58:36.159 28045-28281/org.atalk.android E/aTalk: [8] org.atalk.crypto.omemo.AndroidOmemoService.initializationFailed().127 OmemoManager init failed
    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=TGWmD-84)), : fromFilter (OrFilter: (FromMatchesFilter (full): aaa123@atalk.org, FromMatchesFilter (full): null)).
        at org.jivesoftware.smack.StanzaCollector.nextResultOrThrow(StanzaCollector.java:260)
04-03 18:03:40.549 28045-28259/org.atalk.android D/SMACK: SENT (0): <presence id='TGWmD-86' type='unavailable'></presence><r xmlns='urn:xmpp:sm:3'/><a xmlns='urn:xmpp:sm:3' h='22'/>
04-03 18:03:40.559 28045-28259/org.atalk.android D/SMACK: SENT (0): </stream:stream>
04-03 18:03:50.559 28045-28527/org.atalk.android I/aTalk: [10] org.jivesoftware.smack.tcp.XMPPTCPConnection.shutdown() Exception while waiting for closing stream element from the server XMPPTCPConnection[aaa123@atalk.org/atalk] (0)
    org.jivesoftware.smack.SmackException$NoResponseException: No response received within reply timeout. Timeout was 10000ms (~10s). While waiting for stream closing element received
        at org.jivesoftware.smack.SynchronizationPoint.checkForResponse(SynchronizationPoint.java:272)
04-03 18:03:50.569 28045-28264/org.atalk.android W/aTalk: [11] org.jivesoftware.smack.util.PacketParserUtils.parsePresence() Failed to parse extension element in Presence stanza: "java.net.SocketException: socket is closed" from: 'aaa123@atalk.org/atalk id: 'TGWmD-82'

#7

The problems described here seem to be related to the reported problem which has been fixed. All <presence/> stanza problems are now OK.