powered by Jive Software

Smack OmemoManager.purgeDevices() throws NoResponseException prior to sending the stanza

omemoManager.purgeDevices() throws a SmackException$NoResponseException even before the actual stanza is being sent. See log below.

Basing on the log event time stamp, it seems that the waiting filter IQ has been set incorrectly / or overwritten by the next stanza on the queue?

==================== aTalk log on purgeDevices() =======================

07-09 09:19:17.219 D/SMACK: SENT (0): <iq to=‘leopard@atalk.org’ id=‘qyRxG-173’ type=‘set’>

07-09 09:19:17.349 D/SMACK: RECV (0): <iq xml:lang=‘en’ to=‘leopard@atalk.org/atalk’ from=‘leopard@atalk.org’ type=‘result’** id=‘qyRxG-173’**>

07-09 09:19:17.379 D/SMACK: RECV (0):

07-09 09:19:17.399 D/SMACK: RECV (0):

07-09 09:19:22.879 W/System.err: org.jivesoftware.smack.SmackException$NoResponseException: 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=qyRxG-176**)), : fromFilter (OrFilter: (FromMatchesFilter (full): leopard@atalk.org, FromMatchesFilter (full): null)).

07-09 09:19:22.889 W/System.err: at org.jivesoftware.smack.StanzaCollector.nextResultOrThrow(StanzaCollector.java:2 53)

07-09 09:19:22.889 W/System.err: at org.jivesoftware.smack.StanzaCollector.nextResultOrThrow(StanzaCollector.java:2 08)

07-09 09:19:22.889 W/System.err: at org.jivesoftware.smackx.pubsub.LeafNode.send(LeafNode.java:350)

07-09 09:19:22.889 W/System.err: at org.jivesoftware.smackx.pubsub.LeafNode.send(LeafNode.java:325)

07-09 09:19:22.899 W/System.err: at org.jivesoftware.smackx.pubsub.PubSubManager.tryToPublishAndPossibleAutoCreate( PubSubManager.java:394)

07-09 09:19:22.899 W/System.err: at org.jivesoftware.smackx.omemo.OmemoService.publishBundle(OmemoService.java:300)

07-09 09:19:22.899 W/System.err: at org.jivesoftware.smackx.omemo.OmemoManager.purgeDevices(OmemoManager.java:374)

07-09 09:19:22.899 W/System.err: at org.atalk.crypto.omemo.OmemoDeviceDeleteDialog$2.onClick(OmemoDeviceDeleteDialo g.java:104)

07-09 09:19:22.899 W/System.err: at com.android.internal.app.AlertController$ButtonHandler.handleMessage(AlertContr oller.java:162)

07-09 09:19:22.899 W/System.err: at android.os.Handler.dispatchMessage(Handler.java:102)

07-09 09:19:22.909 W/System.err: at android.os.Looper.loop(Looper.java:145)

07-09 09:19:22.909 W/System.err: at android.app.ActivityThread.main(ActivityThread.java:5940)

07-09 09:19:22.909 W/System.err: at java.lang.reflect.Method.invoke(Native Method)

07-09 09:19:22.909 W/System.err: at java.lang.reflect.Method.invoke(Method.java:372)

07-09 09:19:22.909 W/System.err: at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:1389 )

07-09 09:19:22.909 W/System.err: at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1184)

07-09 09:22:08.849 D/SMACK: SENT (0): <iq to=‘leopard@atalk.org’ id=‘qyRxG-176’ type=‘set’>BRrzarnIyYx8CiyOcvGZHGFDIuk8ahApVUTYJlGmNQ8y</signedPreKeyPu blic>RuMzAEBr21bXjsJ91GdlAnhyQSAFTKWms1tSq/IOnfcdh2LRlvPu UJJvznd6vfVzxgOsW+oNyXswJUKFYYFsjQ==BcBVdk+ +LLlB+H0cVIWl/HUg4PB3B/lYnTuZSW4pLt0DBUh1xIbw9n+iD5vVxsP3e8fHd8ZTEUCMAmbGP9gk5k1xBU7/+mypKARX1RvaEIfPdveJ7rsH7zXaUL9ny5hgamk4BeSRFhYzQSQcMEnJTAal8pWJO9pNiYIghqWJsqzo4fksBd+TMbbghylI/lbzjinwd1KsrRN8jCzPbexfTDrAWCU9Bbc9iEIIr0m126rRJDYJMjIq8wgCxvoTaYMNVZ5mOa4+BZpJ5frIzbXVHyMJfC49v7DXG/IYlB2LHBBdD3CV0DFvBQQkGBmsP5H6E+dBgWwHx9P5aV76TqBGlys9HomenbV+BVF1QZ+gdSlvC+skvUk/ZDBBox9u/Y+q/vmaXV0g9uIABb1bT7rMZmhmKKNA9GT+cxydiuGy0QGQrNUJAD/aBmsOBYSKbF4/kex+gUvuRO1u1Yzv40kOnLCsh/DEjru/YPYjBfESXGuQ6sprHYX9lsoIi11Cdsp3J6yGE7YE1d10abhEBdX/7rBf9K9Drp0jPz5XfdAf8QFomF+Arr3leAjYjiRzBTyRBy7Danhza3pw5g/MZY81nceZeQ9g7k/WLRJXJ9NjBRsSTAqflFIfWfyRCp1I/jyFicT8G+FdOA24k8lJPJocBXKEfwAhbTz/PId/y4Dq54Gc9RD/GLelz1j25iPPGKcMBe/v1QfCpKYiybw0oQHkhaK19yXeMkuAQcpr/x4xmic6BSmyrhDY5oGSSzHiPyGPjJaH3Zz29Bpz+5LBA2yF2NREBQwo22XvwZTqMrZXUX51K6HWl2nEuSbMUAS0co6WFA4pBU/G4DPnqOKcGVTv0RDuI4/zvSKQtXBNPJe/fzS3F8g4BSdC54cTW1VV1J6vjqFldhaMzrJ1ynq05PTiE8My/RINBZWjnlciOIWOdml+mtZd1iCVzG9FCEYRe1C18kxs7qZrBVhkISLTQzgfBLmVkqXvkL1fgeawAJr9U6Fcfs/2LGFlBR1ORiAUTWE3Vi3Srmq8Y+M/aSP74k8tk8+09wZthKk3BV+FF5W7vnDZ9Kq1y4ClroC76nySPndf5Zuxc7Zr0K4fBdrHJG5/0B9rwHxYHnejlui8N5MnWEA6c3eoIE/GKyVzBQFEpp5SsDzZXKF/ykfYft0/WwBrNJ5MiW23T95BbIJnBX9v86L5oXlGBIQBlV2dSB/GHHNBaoNMJ+/zEzC6KcU5BXhI/7oJAmyK7trY1Mny1oyAgv3Vpu0d73qJWptVBFQdBZT5F2llCsxCXn5Uj1q0XjM1VqXwZEFqVLuepwAv+eYRBY5eD+vv/JA2+O2JTn48iBTamAQ1xl2d/+sHLrS+PTYMBU5gEOB6ha57ZtrUOyBLwWYAls3PV82L803/He2MjgRPBfbzHpWg4FLfrVEO/Bk+x+JZfAuCvi5pSSfoskawvgVKBZ0OQQMMwkttS3XXM1MHr85mub+hOpH60lkYZwoerAQCBeN4PSzumn9K/94ZwFhZhSALpLyZTr8m9Mm/fehedWxMBVooJJ8nu30O6vDE42aOvJ+pUpLcgWycEEm8AKjYe253BV1SoVVLMwVUIBZ8dlaFizfDffY2OWuemyPiMDetcEsOBcKBPX5CNwZd45OOWoQ1qXh6dYI58RfUZSAtggArJjkWBatlhKhFMR7YYoYJXGKCjwSro16fiUua95YT6LnnvbdIBUtbjsjmtt8BEZE1tTlmqkd+yTNMCZdacHMZDVHUY3M7BQodeYv5ABJpZ7AT7zvpD5S9UeWrzTLGSbSr9Uv6hvAaBZ0dNyimKh/

07-09 09:22:08.849 D/SMACK: SENT (0):

07-09 09:22:13.179 D/SMACK: RECV (0):

07-09 09:26:13.099 D/SMACK: RECV (0):

07-09 09:26:13.209 D/SMACK: SENT (0):

Look like smack omemo also reported “No response received within reply timeout” even the reply is received well within the specified elapsed time (actually only 260mS against the 5 seconds timeout).

Can it be same problem on response timeout as reported early as in

Smack 4.2.0 sends ‘ask’ attribute in Roster.removeEntry not allowed by RFC6121

================= aTalk log on start up ====================

07-15 17:08:33.469 D/SMACK: SENT (0): <iq to=‘test@atalk.org’ id=‘v3H89-190’ type=‘get’>

07-15 17:08:33.729 D/SMACK: RECV (0): <iq xml:lang=‘en’ to=‘test@atalk.org/atalk’ from=‘test@atalk.org’ type=‘result’ id=‘v3H89-190’>

07-15 17:08:38.479 E/αTalk: [4] org.jivesoftware.smackx.omemo.OmemoManager.authenticated() 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=v3H89-190)), : fromFilter (OrFilter: (FromMatchesFilter (full): test@atalk.org, FromMatchesFilter (full): null)).

Could you try the latest snapshot from Maven Central and report if the problem still exists?

I have yet to test the Smack OmemoManager.purgeDevices() result using 4.2.1-beta2-SNAPSHOT. However I found that on my Samsung S3, similarly response timeout also happen during as shown in the captured log below. Samsung Note 3 does not seem to have this problem. It appears that the problem happen very frequent on slow android devices. I observed many times on S3, the reply timeout even without the stanza being sent at all???

Note: I have increased the smack default reply timeout for aTalk to 10 seconds globally. Samsung Note 3 with lightly loaded xmpp server takes ~4.3 seconds (S3 takes ~7 Sec).; expect this to be even longer if server is heavily loaded. The default smack 5 Sec reply timeout may need to increase when publish omemo bundle.

============== atalk - No response received within reply timeout before sending stanza =============

07-21 17:14:26.022 D/SMACK: XMPPConnection authenticated (XMPPTCPConnection[swan@atalk.org/atalk] (0))

07-21 17:14:26.037 D/SMACK: RECV (0):

07-21 17:14:26.342 D/SMACK: SENT (0):

07-21 17:14:26.367 D/SMACK: RECV (0):

07-21 17:14:26.517 D/SMACK: SENT (0):

07-21 17:14:26.532 D/SMACK: RECV (0): 01creation@001500:348071:994282creation@001500:348071:994 282

07-21 17:14:37.172 E/αTalk: [11] 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=dVeA3-112**)), : fromFilter (OrFilter: (FromMatchesFilter (full): swan@atalk.org, FromMatchesFilter (full): null)).

07-21 17:16:19.442 D/SMACK: SENT (0): <iq to=‘swan@atalk.org’ id=‘dVeA3-112’ type=‘set’>BSnb5U5LfsRclhInPggIBSkDzzXKGN4KR53pHaS1BxkC</signedPreKeyPu blic>d588c51cjsjBYnvHFERfdcH+ehm2LvCdUH266mM9C1dB1H8cDjR8 Siz75Y5huPTAyDG1Ja/xpUlWCLyHD5plDQ==BUwtBjE W56yMH+2NuWD861F8QxoGJIR3zGCIzjAFDesEBRMihW/mUsxJ9wVK0CnY7ex6CJlFLpWT7Pe7AEi/ElYnBWksRfURixEDVmovfOU3ZGvF8RDXZpgs74kEfCG9wIofBTJATJFkLWhEQ+hWHmRX7c4UmVxIhFSpgixZkFlQ2Twl … BTuSdRoiMruvc00drp4wKTJiJwzDhAOznV4YIAIEvOgfBTtdxBtETfVvAaU1uMx7uyAkm83GGT3Fr5/oH55SSL9ZBY+e0mGHPd1GuURjh/1y3f09ZsYUY4WZHbzxQmyVw6M8Bfny1WcC8UeuQHZ1HgPTWVFWN9lGETSL9XjeXUx8fDo2Baj6PslEyRa86NbZYC5Ui

07-21 17:16:19.447 D/SMACK: SENT (0):

07-21 17:16:26.487 D/SMACK: RECV (0): <iq xml:lang=‘en’ to=‘swan@atalk.org/atalk’ from=‘swan@atalk.org’ type=‘result’** id=‘dVeA3-112’**>

I just tested Smack OmemoManager.purgeDevices() on both my Note3 and S3. Both the devices executed successfully without the reply timeout exception. (with 10 seconds smack reply timeout)

From smack log, I see that the device publishes the devicelist with only its own omemoDevice Id; and the publish_item deviceList on the server also reflected this latest changes. However its buddy who subscribed to the event notification also received the pubsub#event on the newly updated deviceList, but no action is taken to update its identities table.

What should be the correct reaction from buddy upon receiving this newly updated deviceList pubsub#event?

When will the removed device ID in the identities table get clean up?

Look like the reply timeout prior to stanza being sent can also happen on Note3. See attached log

The following log is captured when I performed re-login after logout the account on Note 3; then starting up a chat session with swan@atalk.org. The chatSession will chek for contactSupportsOmemo().

============ aTalk (Note3) log on reply timeout before stanza being sent ==============

07-22 12:02:06.627 E/αTalk: [105] 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=xuuZ7-443)), : fromFilter (OrFilter: (FromMatchesFilter (full): leopard@atalk.org, FromMatchesFilter (full): null)).

07-22 12:02:12.907 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=xuuZ7-444)), : fromFilter (OrFilter: (FromMatchesFilter (full): swan@atalk.org)).

07-22 12:02:12.917 W/System.err: at org.jivesoftware.smack.StanzaCollector.nextResultOrThrow(StanzaCollector.java:2 53)

07-22 12:02:12.917 W/System.err: at org.jivesoftware.smack.StanzaCollector.nextResultOrThrow(StanzaCollector.java:2 08)

07-22 12:02:12.917 W/System.err: at org.jivesoftware.smackx.pubsub.PubSubManager.getNode(PubSubManager.java:243)

07-22 12:02:12.917 W/System.err: at org.jivesoftware.smackx.pubsub.PubSubManager.getLeafNode(PubSubManager.java:322 )

07-22 12:02:12.917 W/System.err: at org.jivesoftware.smackx.omemo.OmemoService.fetchDeviceListNode(OmemoService.jav a:436)

07-22 12:02:12.917 W/System.err: at org.jivesoftware.smackx.omemo.OmemoService.fetchDeviceList(OmemoService.java:45 3)

07-22 12:02:12.927 W/System.err: at org.jivesoftware.smackx.omemo.OmemoService.refreshDeviceList(OmemoService.java: 505)

07-22 12:02:12.927 W/System.err: at org.jivesoftware.smackx.omemo.OmemoManager.contactSupportsOmemo(OmemoManager.java:489)

07-22 12:02:12.927 W/System.err: at org.atalk.crypto.CryptoFragment.isOmemoSupport(CryptoFragment.java:800)

07-22 12:02:12.927 W/System.err: at org.atalk.crypto.CryptoFragment.setCurrentChatSession(CryptoFragment.java:494)

07-22 12:02:12.927 W/System.err: at org.atalk.crypto.CryptoFragment.doInit(CryptoFragment.java:150)

07-22 12:02:12.927 W/System.err: at org.atalk.crypto.CryptoFragment.onCreateOptionsMenu(CryptoFragment.java:191)

07-22 12:02:12.937 W/System.err: at android.support.v4.app.Fragment.performCreateOptionsMenu(Fragment.java:2291)

07-22 12:02:12.937 W/System.err: at android.support.v4.app.FragmentManagerImpl.dispatchCreateOptionsMenu(FragmentMa nager.java:3011)

07-22 12:02:12.937 W/System.err: at android.support.v4.app.FragmentController.dispatchCreateOptionsMenu(FragmentCon troller.java:328)

07-22 12:02:12.937 W/System.err: at android.support.v4.app.FragmentActivity.onCreatePanelMenu(FragmentActivity.java :363)

07-22 12:02:12.937 W/System.err: at com.android.internal.policy.impl.PhoneWindow.preparePanel(PhoneWindow.java:599)

07-22 12:02:12.937 W/System.err: at com.android.internal.policy.impl.PhoneWindow.doInvalidatePanelMenu(PhoneWindow. java:973)

07-22 12:02:12.937 W/System.err: at com.android.internal.policy.impl.PhoneWindow$1.run(PhoneWindow.java:305)

07-22 12:02:12.947 W/System.err: at android.os.Handler.handleCallback(Handler.java:739)

07-22 12:02:12.947 W/System.err: at android.os.Handler.dispatchMessage(Handler.java:95)

07-22 12:02:12.947 W/System.err: at android.os.Looper.loop(Looper.java:145)

07-22 12:02:12.947 W/System.err: at android.app.ActivityThread.main(ActivityThread.java:5940)

07-22 12:02:12.947 W/System.err: at java.lang.reflect.Method.invoke(Native Method)

07-22 12:02:12.947 W/System.err: at java.lang.reflect.Method.invoke(Method.java:372)

07-22 12:02:12.947 W/System.err: at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:1389 )

07-22 12:02:12.947 W/System.err: at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1184)

07-22 12:04:40.037 D/SMACK: SENT (3): BcdRaXODwwV2iX21saahdi5EXYx2zHnKL9ToLHwQPExS</signedPreKeyPu blic>9InTdCLINuWZFTQpidfrcoCthzXG0UEBWG6KC+0pLXUlclSKZo6C OLUCgZT26lfv7Xw5PUW+WkJwC7F2avykAA==BbZGG4d UIqGR4GkiE2QDSwoa2JnFyiTowje+tIlOkAZ5BbW/KsLDl9IoAu9mmojckoRpRXBIRc+APhilqE+Ua193<preK eyPublic

preKeyId=‘46’>BeXzeIe5mr3a0Dbz+wsSYpnHPt0zB9CdlzM6g2TpVuUHBX2+cFhupE

07-22 12:04:40.067 D/SMACK: SENT (3):

07-22 12:04:44.357 D/SMACK: RECV (3):

07-22 12:04:44.357 D/SMACK: RECV (3): <iq xml:lang=‘en’ to=‘leopard@atalk.org/atalk’ from=‘leopard@atalk.org’ type=‘result’ id='xuuZ7-443’>

07-22 12:04:44.397 D/SMACK: RECV (3):

07-22 12:04:44.397 D/SMACK: RECV (3): <feature var='http://jabber.org/protocol/pubsub#auto-

07-22 12:04:44.407 D/SMACK: SENT (3):

07-22 12:04:44.437 D/SMACK: RECV (3): create’/>

Without more testings: found that the above problem has 100% failures every time I performed account re-login after logout on Note 3; leading also to 100% failure on OmemoManager.contactSupportsOmemo(). It is also strange that the Omemo bundle stanza only sent more than 2 minutes after reply timeout.

Note: The re-login “resume” state is always false under the above case since a proper logout is being executed.

However if I exit/terminate aTalk and relaunch aTalk, then the above problem does not occurred. After this step, the 100% failure on re-login no further occur, everything is back to normal operation.

It seems the 100% failure starts once there is a reply timeout occur - some failure state no clear???

====== log with aTalk exit and relaunch ================

07-23 14:38:16.758 D/SMACK: XMPPConnection authenticated (XMPPTCPConnection[leopard@atalk.org/atalk] (0))

07-23 14:38:17.048 D/SMACK: RECV (0):

07-23 14:38:17.068 D/SMACK: SENT (0):

07-23 14:38:17.268 D/SMACK: RECV (0): 01creation@001500:680925:992891creation@001500:680925:992 891

07-23 14:38:17.878 D/SMACK: SENT (0): BcdRaXODwwV2iX21saahdi5EXYx2zHnKL9ToLHwQPExS</signedPreKeyPu blic>9InTdCLINuWZFTQpidfrcoCthzXG0UEBWG6KC+0pLXUlclSKZo6C OLUCgZT26lfv7Xw5PUW+WkJwC7F2avykAA==BbZGG4d UIqGR4GkiE2QDSwoa2JnFyiTowje+tIlOkAZ5BbW/KsLDl9IoAu9mmojckoRpRXBIRc+APhilqE+Ua193<preK eyPublic

preKeyId=‘60’>BcgL6TvrTajpgosdaG1qBF/ECRLANG8oivF4oFaqKuhKBU3EwWiMLqLZ9KmANhmmT3esbgXlpjWgWHwSZAy99eRXBeXzeIe5mr3a0Dbz+wsSYpnHPt0zB9CdlzM6g2TpVuUHBX2+cFhupE

07-23 14:38:17.878 D/SMACK: SENT (0):

07-23 14:38:22.238 D/SMACK: RECV (0):