powered by Jive Software

Smack-omemo rework #177 - throws "No response received within reply timeout" even before stanzas are being sent


#1

Smack throws “No response received within reply timeout” even before the stanzas are being sent as shown in the aTalk log below. In fact both replied stanzas are well within the smack reply timeout set in aTalk.
Then for unknown reason smack aborts the connection with exception callConnectionClosedOnErrorListener.

The observed problem happen on Note-2 device upon first apk installation, and problems are repeatable.
Note-2 seems to be working OK on subsequent launch. Will continue monitoring.

Actually I have already included a patch for prekeys publish; look like similar patch also needs to be included for omemoManager init routine. Not sure how to take of sudden disconnection.

01-28 02:44:20.201 W/aTalk: [9] org.jivesoftware.smackx.omemo.OmemoService.publishBundle() Ignore OmemoManager publish 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=Z66br-97)), : fromFilter (OrFilter: (FromMatchesFilter (full): swordfish@atalk.org, FromMatchesFilter (full): null)).
01-28 02:44:23.111 I/aTalk: [10] service.httputil.HttpUtils.executeMethod().205 Auto checking for software update: GET http://atalk.sytes.net/releases/atalk-android/versionupdate.properties HTTP/1.1
01-28 02:44:30.291 E/aTalk: [9] org.atalk.crypto.omemo.AndroidOmemoService.initializationFailed().128 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=Z66br-99)), : fromFilter (OrFilter: (FromMatchesFilter (full): swordfish@atalk.org, FromMatchesFilter (full): null)).
                                at org.jivesoftware.smack.StanzaCollector.nextResultOrThrow(StanzaCollector.java:253)
                                at org.jivesoftware.smack.StanzaCollector.nextResultOrThrow(StanzaCollector.java:208)
                                at org.jivesoftware.smackx.pubsub.PubSubManager.getNode(PubSubManager.java:245)
                                at org.jivesoftware.smackx.pubsub.PubSubManager.getLeafNode(PubSubManager.java:331)
                                at org.jivesoftware.smackx.omemo.OmemoService.fetchDeviceList(OmemoService.java:611)
                                at org.jivesoftware.smackx.omemo.OmemoService.refreshAndRepublishDeviceList(OmemoService.java:660)
                                at org.jivesoftware.smackx.omemo.OmemoService.init(OmemoService.java:263)
                                at org.jivesoftware.smackx.omemo.OmemoManager.initialize(OmemoManager.java:245)
                                at org.jivesoftware.smackx.omemo.OmemoManager$2.run(OmemoManager.java:261)
                                at java.lang.Thread.run(Thread.java:841)
01-28 02:44:30.316 I/aTalk: [11] org.atalk.persistance.DatabaseBackend.storeCachedDeviceList().1327 Identities table updated for activeDevice: leopard@atalk.org:2102240613
01-28 02:44:30.381 I/aTalk: [11] org.atalk.persistance.DatabaseBackend.storeCachedDeviceList().1327 Identities table updated for activeDevice: hawk@atalk.org:1796289951
01-28 02:46:09.731 D/SMACK: SENT (0): <iq to='swordfish@atalk.org' id='Z66br-97' type='set'><pubsub xmlns='http://jabber.org/protocol/pubsub'><publish node='eu.siacs.conversations.axolotl.bundles:726991582'><item><bundle xmlns='eu.siacs.conversations.axolotl'><signedPreKeyPublic signedPreKeyId='1'>BcQiMq6EpoK/TVL26QXt7HCrNMIOAsjW32uYeC4CTHY7</signedPreKeyPublic><signedPreKeySignature>KDBClGfdRdtjfqyxqgxWFmjFO7Vx4CSiHIKOM6zNACNWSHCPowZwCZMCJ5cLrgFDqNF7DgIFVDk3E8tMgj9mDg==</signedPreKeySignature><identityKey>BYiSJJnKK+WrVjhVttVC7UClHJ+wTneNJhFc3UPJ6xNc</identityKey><prekeys><preKeyPublic preKeyId='1'>BQ/mr2pgnDUmLNbLgWEMyuiWALiBAr7hNZeDKp4v16wi</preKeyPublic><preKeyPublic preKeyId='2'>BfH7KXJ1Sibf5r9jvkcBviOFiWoxSlG9BtNH36xghnln</preKeyPublic><preKeyPublic preKeyId='39'>BRJO+wNXrIwrak2e1hBmn5BMxW4Otn9Vu0iwx+GmuRM7</preKeyPublic><preKeyPublic preKeyId='36'>BTvCSoIggEdPC8z8jsPVg/Jpexo/GoEeuyDNqKavUBsd</preKeyPublic><preKeyPublic preKeyId='37'>BUiivijE1p7H3SjRt9d8gz79C0zmIzeVxYNBkKjaa+tk</preKeyPublic><preKeyPublic preKeyId='42'>BSZpNZAYEAKB+AzdmQfx8rW4dp0ITgxFO9htucMISUM+</preKeyPublic><preKeyPublic preKeyId='43'>BT/R8EL63m895cLJYa
01-28 02:46:09.826 D/SMACK: SENT (0): </pubsub></iq><iq to='atalk.org' id='Z66br-98' type='get'><query xmlns='http://jabber.org/protocol/disco#items'></query></iq><iq to='swordfish@atalk.org' id='Z66br-99' type='get'><query xmlns='http://jabber.org/protocol/disco#info' node='eu.siacs.conversations.axolotl.devicelist'></query></iq>
01-28 02:46:14.106 D/SMACK: RECV (0): <iq xml:lang='en' to='swordfish@atalk.org/atalk2' from='swordfish@atalk.org' type='result' id='Z66br-97'><pubsub xmlns='http://jabber.org/protocol/pubsub'><publish node='eu.siacs.conversations.axolotl.bundles:726991582'><item id='5ED1339EA7395'/></publish></pubsub></iq>
01-28 02:46:14.121 D/SMACK: RECV (0): <iq xml:lang='en' to='swordfish@atalk.org/atalk2' from='atalk.org' type='result' id='Z66br-98'><query xmlns='http://jabber.org/protocol/disco#items'><item jid='conference.atalk.org'/><item jid='focus.atalk.org'/><item jid='irc.atalk.org'/><item jid='jitsi-videobridge.atalk.org'/><item jid='proxy.atalk.org'/><item jid='pubsub.atalk.org'/></query></iq>
01-28 02:46:14.141 D/SMACK: RECV (0): <iq xml:lang='en' to='swordfish@atalk.org/atalk2' from='swordfish@atalk.org' type='result' id='Z66br-99'><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>

01-28 03:04:34.991 W/aTalk: [12] org.jivesoftware.smack.AbstractXMPPConnection.callConnectionClosedOnErrorListener() Connection XMPPTCPConnection[swordfish@atalk.org/atalk2] (0) closed with error
                            javax.net.ssl.SSLException: Read error: ssl=0x59a3ddf8: I/O error during system call, Connection timed out
                                at org.apache.harmony.xnet.provider.jsse.NativeCrypto.SSL_read(Native Method)
                                at org.apache.harmony.xnet.provider.jsse.OpenSSLSocketImpl$SSLInputStream.read(OpenSSLSocketImpl.java:686)
                                at java.io.InputStreamReader.read(InputStreamReader.java:244)
                                at java.io.BufferedReader.read(BufferedReader.java:310)
                                at org.jivesoftware.smack.util.ObservableReader.read(ObservableReader.java:42)
                                at org.kxml2.io.KXmlParser.fillBuffer(KXmlParser.java:1496)
                                at org.kxml2.io.KXmlParser.peekType(KXmlParser.java:979)
                                at org.kxml2.io.KXmlParser.next(KXmlParser.java:346)
                                at org.kxml2.io.KXmlParser.next(KXmlParser.java:310)
                                at org.jivesoftware.smack.tcp.XMPPTCPConnection$PacketReader.parsePackets(XMPPTCPConnection.java:1244)
                                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:841)

#2

Following are the observations I have while doing omemo messaging testing on Note-2. Note-2 has android API-4.3 and with JIT implementation. The deployed smack version is 4.2.3-SNAPSHOT. The same observation happen every time and is 100% repeatable.

  1. On adb installation of aTalk and first launch of aTalk application.
    Whenever there is an access to PublishManager services from OmemoService, smack always throws
    SmackException$NoResponseException but without any of the reported failed stanzas being sent (100% repeatable).

  2. On subsequent manual launching of aTalk, smack again throws SmackException$NoResponseException when accessing any of the PublishManager services from within OmemoService. Unlike the first case, this time all the mentioned failed stanzas are actually being sent with the corresponding replied stanzas received well within the defined smack reply timeout. (100% repeatable)

  3. Items #1 and #2 are repeatable, and omemo setup always failed because of the multiple SmackException$NoResponseException being thrown…

  4. After applying patches to the OmemoService to ignore SmackException$NoResponseException on all instances of PublishManager access i.e.
    a. fetchBundle
    b. publishBundle
    c, fetchDeviceList
    d. publishDeviceList

Only with these 4 patches in places, Omemo initial setup finally can proceed successfully. All the above 4 accesses actually throws NoResponseException but ignored.

  1. After the initial omemo setup in #4, any subsequent aTalk launches are proceed without seeing the NoResponseException being thrown again.

#3

Here is the patch file for OmemoService

01.OmemoService_4.2.3.patch (4.7 KB)

Update to #1 (After applying the patches): All the mentioned missing stanzas actually get sent but only 4 minutes later. Not sure it did sent before the patches, as I did not wait for that long to see the log output.

The network however gets disconnected half way through sending the publishBundle packet, it gets auto re-connected by ReconnectManager; Smack seems intelligent to resend all the missing stanzas after reconnect ion but reuse all the old id’s.

I have included the log below, but very long; in case it helps you to understand what I said.

============ aTalk first launch with applied pathces =================
01-29 17:21:01.221 W/aTalk: [9] org.jivesoftware.smackx.omemo.OmemoService.publishBundle() Ignore OmemoService publishBundle 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=IIRXC-87)), : fromFilter (OrFilter: (FromMatchesFilter (full): parrot@atalk.org, FromMatchesFilter (full): null)).
01-29 17:21:11.256 W/aTalk: [9] 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=IIRXC-89)), : fromFilter (OrFilter: (FromMatchesFilter (full): parrot@atalk.org, FromMatchesFilter (full): null)).
01-29 17:21:11.291 I/aTalk: [9] org.atalk.persistance.DatabaseBackend.storeCachedDeviceList().1352 Identities table updated for inactiveDevice: parrot@atalk.org:1584245149
01-29 17:21:11.326 I/aTalk: [9] org.atalk.persistance.DatabaseBackend.storeCachedDeviceList().1327 Identities table updated for activeDevice: parrot@atalk.org:1584245149
01-29 17:21:21.351 W/aTalk: [9] 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=IIRXC-90)), : fromFilter (OrFilter: (FromMatchesFilter (full): parrot@atalk.org, FromMatchesFilter (full): null)).
01-29 17:21:21.416 I/aTalk: [9] org.atalk.crypto.omemo.AndroidOmemoService.initializationFinished().121 Initialize OmemoManager successful for parrot@atalk.org/atalk
01-29 22:41:31.146 D/SMACK: RECV (0): <presence xml:lang='en' to='kingfisher@atalk.org/atalk' from='kingfisher@atalk.org/atalk' id='VWfbs-72'><x xmlns='vcard-temp:x:update'/><c xmlns='http://jabber.org/protocol/caps' hash='sha-1' node='http://android.atalk.org' ver='qlaf8fmwUojcVNOO07fSQc7Ko9Y='/><priority>30</priority><status/></presence>
01-29 22:41:31.306 D/SMACK: XMPPConnection authenticated (XMPPTCPConnection[kingfisher@atalk.org/atalk] (0))
01-29 22:41:52.561 W/aTalk: [6] org.jivesoftware.smackx.omemo.OmemoService.publishBundle() Ignore OmemoService publishBundle 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=VWfbs-74)), : fromFilter (OrFilter: (FromMatchesFilter (full): kingfisher@atalk.org, FromMatchesFilter (full): null)).
01-29 22:42:02.586 W/aTalk: [6] 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=VWfbs-75)), : fromFilter (OrFilter: (FromMatchesFilter (full): kingfisher@atalk.org, FromMatchesFilter (full): null)).
01-29 22:42:02.631 I/aTalk: [6] org.atalk.persistance.DatabaseBackend.storeCachedDeviceList().1352 Identities table updated for inactiveDevice: kingfisher@atalk.org:601605057
01-29 22:42:02.666 I/aTalk: [6] org.atalk.persistance.DatabaseBackend.storeCachedDeviceList().1327 Identities table updated for activeDevice: kingfisher@atalk.org:601605057
01-29 22:42:12.696 W/aTalk: [6] 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=VWfbs-76)), : fromFilter (OrFilter: (FromMatchesFilter (full): kingfisher@atalk.org, FromMatchesFilter (full): null)).
01-29 22:42:12.776 I/aTalk: [6] org.atalk.crypto.omemo.AndroidOmemoService.initializationFinished().121 Initialize OmemoManager successful for kingfisher@atalk.org/atalk
01-29 22:45:41.906 D/SMACK: SENT (0): <iq to='kingfisher@atalk.org' id='VWfbs-74' type='set'><pubsub xmlns='http://jabber.org/protocol/pubsub'><publish node='eu.siacs.conversations.axolotl.bundles:601605057'><item><bundle xmlns='eu.siacs.conversations.axolotl'><signedPreKeyPublic signedPreKeyId='1'>Bcm7hfFd0fCC3RNAArRbKzLDNp0nupi07coEQF7U78Fg</signedPreKeyPublic><signedPreKeySignature>9y8ilqF6NjoS+dOoVQ6scuDG4j/5e88o/qz9BK/4okK4nAyQ42nuVZtmw2p08kEKdIlEbOoOIPYD/gYAV9B2DQ==</signedPreKeySignature><identityKey>BZL8z3TLF/CRj+iwsluHJHcdaRoZcW1bwL6tREotrt03</identityKey><prekeys><preKeyPublic preKeyId='1'>BbEAGOBoA2zqJpVlRd/fJ0onLtYOdWjaulHd6phlNelw</preKeyPublic><preKeyPublic preKeyId='2'>BYKvJ4F2JdewzLBOedIAPS+7ybCc0JBjJ3+CXjRgEsd7</preKeyPublic><preKeyPublic 
...
preKeyId='42'>BRZ7TayZ2tmb8pbzkGwLNRGZHo7tWZQwKt+7FsH670xj</preKeyPublic><preKeyPublic preKeyId='43'>Bbhn7Z2H45trivDxP
01-29 22:45:42.146 D/SMACK: SENT (0): </pubsub></iq><iq to='kingfisher@atalk.org' id='VWfbs-75' type='get'><query xmlns='http://jabber.org/protocol/disco#info' node='eu.siacs.conversations.axolotl.devicelist'></query></iq><iq to='kingfisher@atalk.org' id='VWfbs-76' 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='601605057'/></list></item></publish></pubsub></iq><presence id='VWfbs-78'><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='qlaf8fmwUojcVNOO07fSQc7Ko9Y='/></presence>
01-29 22:45:42.176 W/aTalk: [9] org.jivesoftware.smack.AbstractXMPPConnection.callConnectionClosedOnErrorListener() Connection XMPPTCPConnection[kingfisher@atalk.org/atalk] (0) closed with error
                            javax.net.ssl.SSLException: Write error: ssl=0x5b70e678: I/O error during system call, Broken pipe
                                at org.apache.harmony.xnet.provider.jsse.NativeCrypto.SSL_write(Native Method)
                                at org.apache.harmony.xnet.provider.jsse.OpenSSLSocketImpl$SSLOutputStream.write(OpenSSLSocketImpl.java:728)
                                at java.io.OutputStreamWriter.flushBytes(OutputStreamWriter.java:167)
                                at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:158)
                                at org.jivesoftware.smack.util.ObservableWriter.flush(ObservableWriter.java:51)
                                at org.jivesoftware.smack.tcp.XMPPTCPConnection$PacketWriter.writePackets(XMPPTCPConnection.java:1453)
                                at org.jivesoftware.smack.tcp.XMPPTCPConnection$PacketWriter.access$3300(XMPPTCPConnection.java:1260)
                                at org.jivesoftware.smack.tcp.XMPPTCPConnection$PacketWriter$1.run(XMPPTCPConnection.java:1308)
                                at java.lang.Thread.run(Thread.java:841)
01-29 22:45:42.181 W/aTalk: [10] org.jivesoftware.smack.util.PacketParserUtils.parsePresence() Failed to parse extension element in Presence stanza: "java.net.SocketException: Socket is closed" from: 'kingfisher@atalk.org/atalk id: 'VWfbs-72'
01-29 22:45:42.291 D/SMACK: XMPPConnection closed due to an exception (XMPPTCPConnection[kingfisher@atalk.org/atalk] (0))
                            javax.net.ssl.SSLException: Write error: ssl=0x5b70e678: I/O error during system call, Broken pipe
                                at org.apache.harmony.xnet.provider.jsse.NativeCrypto.SSL_write(Native Method)
                                at org.apache.harmony.xnet.provider.jsse.OpenSSLSocketImpl$SSLOutputStream.write(OpenSSLSocketImpl.java:728)
                                at java.io.OutputStreamWriter.flushBytes(OutputStreamWriter.java:167)
                                at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:158)
                                at org.jivesoftware.smack.util.ObservableWriter.flush(ObservableWriter.java:51)
                                at org.jivesoftware.smack.tcp.XMPPTCPConnection$PacketWriter.writePackets(XMPPTCPConnection.java:1453)
                                at org.jivesoftware.smack.tcp.XMPPTCPConnection$PacketWriter.access$3300(XMPPTCPConnection.java:1260)
                                at org.jivesoftware.smack.tcp.XMPPTCPConnection$PacketWriter$1.run(XMPPTCPConnection.java:1308)
                                at java.lang.Thread.run(Thread.java:841)
01-29 22:45:43.281 D/SMACK: XMPPConnection (XMPPTCPConnection[kingfisher@atalk.org/atalk] (0)) will reconnect in 1
01-29 22:45:44.281 D/SMACK: XMPPConnection (XMPPTCPConnection[kingfisher@atalk.org/atalk] (0)) will reconnect in 0
01-29 22:45:44.281 I/aTalk: [11] impl.protocol.jabber.ProtocolProviderServiceJabberImpl.reconnectingIn().1404 ReconnectionManager starting connection attempt...
01-29 22:45:44.281 D/SMACK: XMPPConnection (XMPPTCPConnection[kingfisher@atalk.org/atalk] (0)) will reconnect in 0
01-29 22:45:44.286 I/aTalk: [11] impl.protocol.jabber.ProtocolProviderServiceJabberImpl.reconnectingIn().1404 ReconnectionManager starting connection attempt...
01-29 22:45:44.721 D/SMACK: SENT (0): <stream:stream xmlns='jabber:client' to='atalk.org' xmlns:stream='http://etherx.jabber.org/streams' version='1.0' xml:lang='en'>
01-29 22:45:44.726 D/SMACK: RECV (0): <?xml version='1.0'?><stream:stream id='16128049930455402639' version='1.0' xml:lang='en' xmlns:stream='http://etherx.jabber.org/streams' from='atalk.org' xmlns='jabber:client'><stream:features><mechanisms xmlns='urn:ietf:params:xml:ns:xmpp-sasl'><mechanism>PLAIN</mechanism><mechanism>X-OAUTH2</mechanism><mechanism>SCRAM-SHA-1</mechanism></mechanisms><starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'/><register xmlns='http://jabber.org/features/iq-register'/></stream:features>
01-29 22:45:44.736 D/SMACK: SENT (0): <starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'></starttls>
01-29 22:45:44.741 D/SMACK: RECV (0): <proceed xmlns='urn:ietf:params:xml:ns:xmpp-tls'/>
01-29 22:45:44.816 D/SMACK: SENT (0): <stream:stream xmlns='jabber:client' to='atalk.org' xmlns:stream='http://etherx.jabber.org/streams' version='1.0' xml:lang='en'>
01-29 22:45:44.821 D/SMACK: RECV (0): <?xml version='1.0'?><stream:stream id='5811518194392253172' version='1.0' xml:lang='en' xmlns:stream='http://etherx.jabber.org/streams' from='atalk.org' xmlns='jabber:client'>
01-29 22:45:44.821 D/SMACK: RECV (0): <stream:features><mechanisms xmlns='urn:ietf:params:xml:ns:xmpp-sasl'><mechanism>PLAIN</mechanism><mechanism>X-OAUTH2</mechanism><mechanism>SCRAM-SHA-1</mechanism></mechanisms><register xmlns='http://jabber.org/features/iq-register'/></stream:features>
01-29 22:45:44.856 W/aTalk: [11] org.atalk.crypto.omemo.AndroidOmemoService.initOmemoManager().103 SetTrustCallBack Exception: TrustCallback can only be set once.
01-29 22:45:44.861 I/aTalk: [11] org.atalk.crypto.omemo.AndroidOmemoService.<init>().62 ### Registered omemo messageListener for: kingfisher@atalk.org
01-29 22:45:44.936 D/SMACK: XMPPConnection connected (XMPPTCPConnection[kingfisher@atalk.org/atalk] (0))
01-29 22:45:44.946 D/SMACK: SENT (0): <auth xmlns='urn:ietf:params:xml:ns:xmpp-sasl' mechanism='SCRAM-SHA-1'>biwsbj1raW5nZmlzaGVyLHI9ZHxoRmltZHZqfU5+TnVLIVAzbF9CbjtLemplKUhYXW0=</auth>
01-29 22:45:44.971 D/SMACK: RECV (0): <challenge xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>cj1kfGhGaW1kdmp9Tn5OdUshUDNsX0JuO0t6amUpSFhdbVM1YjFsMms4dlo4VmdwSGNGZlVyZEE9PSxzPVVsS2I3SitybldHVkxUVWpMQUFYYkE9PSxpPTQwOTY=</challenge>
01-29 22:45:45.296 D/dalvikvm: GC_FOR_ALLOC freed 1937K, 16% free 20679K/24380K, paused 92ms, total 92ms
01-29 22:45:46.196 D/SMACK: SENT (0): <response xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>Yz1iaXdzLHI9ZHxoRmltZHZqfU5+TnVLIVAzbF9CbjtLemplKUhYXW1TNWIxbDJrOHZaOFZncEhjRmZVcmRBPT0scD1TZXRwc0ZNOFM5N0x3Yi9MOWwySExzUzJ2Z0k9</response>
01-29 22:45:46.221 D/SMACK: RECV (0): <success xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>dj1HV3ltVm1hMEVwVytSamJIWkdJSlBSSzQvZVU9</success>
01-29 22:45:46.241 D/SMACK: SENT (0): <stream:stream xmlns='jabber:client' to='atalk.org' xmlns:stream='http://etherx.jabber.org/streams' version='1.0' id='5811518194392253172' xml:lang='en'><resume xmlns='urn:xmpp:sm:3' h='20' previd='g2gCbQAAAAVhdGFsa2gDYgAABe1iAAOdP2IAAnmw'/>
01-29 22:45:46.251 D/SMACK: RECV (0): <?xml version='1.0'?><stream:stream id='5579360492246494548' version='1.0' xml:lang='en' xmlns:stream='http://etherx.jabber.org/streams' from='atalk.org' xmlns='jabber:client'>
01-29 22:45:46.261 D/SMACK: RECV (0): <stream:features><bind xmlns='urn:ietf:params:xml:ns:xmpp-bind'/><session xmlns='urn:ietf:params:xml:ns:xmpp-session'><optional/></session><c ver='cJUVXXV+5khBwVJS8OXzJd4l35c=' node='http://www.process-one.net/en/ejabberd/' hash='sha-1' xmlns='http://jabber.org/protocol/caps'/><sm xmlns='urn:xmpp:sm:2'/><sm xmlns='urn:xmpp:sm:3'/><ver xmlns='urn:xmpp:features:rosterver'/><csi xmlns='urn:xmpp:csi:0'/></stream:features>
01-29 22:45:46.271 D/SMACK: RECV (0): <resumed previd='g2gCbQAAAAVhdGFsa2gDYgAABe1iAAOdP2IAAnmw' h='20' xmlns='urn:xmpp:sm:3'/>
01-29 22:45:46.281 D/SMACK: User logged (0): kingfisher@atalk.org:5222/atalk
01-29 22:45:46.291 D/SMACK: RECV (0): <iq to='kingfisher@atalk.org/atalk' from='atalk.org' type='get' id='5454706571586064403'><ping xmlns='urn:xmpp:ping'/></iq>
01-29 22:45:46.821 D/SMACK: XMPPConnection authenticated (XMPPTCPConnection[kingfisher@atalk.org/atalk] (0)) and resumed
01-29 22:45:56.376 E/aTalk: [14] org.jivesoftware.smack.roster.Roster.processException() Exception reloading roster
                            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=VWfbs-81)), : fromFilter (OrFilter: (FromMatchesFilter (full): null, FromMatchesFilter (ignoreResourcepart): kingfisher@atalk.org, FromMatchesFilter (full): atalk.org)).
                                at org.jivesoftware.smack.AbstractXMPPConnection$7.run(AbstractXMPPConnection.java:1563)
                                at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:390)
                                at java.util.concurrent.FutureTask.run(FutureTask.java:234)
                                at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:153)
                                at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:267)
                                at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1080)
                                at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:573)
                                at java.lang.Thread.run(Thread.java:841)
01-29 22:45:56.686 E/aTalk: [13] impl.protocol.jabber.OperationSetBasicInstantMessagingJabberImpl.enableDisableCarbon().763 Failed to set carbon state for: kingfisher@atalk.org/atalk to true
                            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=VWfbs-85)), : fromFilter (OrFilter: (FromMatchesFilter (full): null, FromMatchesFilter (ignoreResourcepart): kingfisher@atalk.org, FromMatchesFilter (full): atalk.org)).
                                at org.jivesoftware.smack.StanzaCollector.nextResultOrThrow(StanzaCollector.java:253)
                                at org.jivesoftware.smack.StanzaCollector.nextResultOrThrow(StanzaCollector.java:208)
                                at org.jivesoftware.smackx.carbons.CarbonManager.setCarbonsEnabled(CarbonManager.java:311)
                                at net.java.sip.communicator.impl.protocol.jabber.OperationSetBasicInstantMessagingJabberImpl.enableDisableCarbon(OperationSetBasicInstantMessagingJabberImpl.java:754)
                                at net.java.sip.communicator.impl.protocol.jabber.OperationSetBasicInstantMessagingJabberImpl.initAdditionalServices(OperationSetBasicInstantMessagingJabberImpl.java:736)
                                at net.java.sip.communicator.impl.protocol.jabber.OperationSetBasicInstantMessagingJabberImpl.access$700(OperationSetBasicInstantMessagingJabberImpl.java:102)
                                at net.java.sip.communicator.impl.protocol.jabber.OperationSetBasicInstantMessagingJabberImpl$RegistrationStateListener$1.run(OperationSetBasicInstantMessagingJabberImpl.java:704)
                                at java.lang.Thread.run(Thread.java:841)
01-29 22:45:57.351 W/aTalk: [15] org.jivesoftware.smackx.omemo.OmemoService.publishBundle() Ignore OmemoService publishBundle 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=VWfbs-86)), : fromFilter (OrFilter: (FromMatchesFilter (full): kingfisher@atalk.org, FromMatchesFilter (full): null)).
01-29 22:46:07.381 W/aTalk: [15] 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=VWfbs-87)), : fromFilter (OrFilter: (FromMatchesFilter (full): kingfisher@atalk.org, FromMatchesFilter (full): null)).
01-29 22:46:07.421 I/aTalk: [15] org.atalk.persistance.DatabaseBackend.storeCachedDeviceList().1352 Identities table updated for inactiveDevice: kingfisher@atalk.org:601605057
01-29 22:46:07.456 I/aTalk: [15] org.atalk.persistance.DatabaseBackend.storeCachedDeviceList().1327 Identities table updated for activeDevice: kingfisher@atalk.org:601605057
01-29 22:46:17.486 W/aTalk: [15] 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=VWfbs-88)), : fromFilter (OrFilter: (FromMatchesFilter (full): kingfisher@atalk.org, FromMatchesFilter (full): null)).
01-29 22:46:17.556 I/aTalk: [15] org.atalk.crypto.omemo.AndroidOmemoService.initializationFinished().121 Initialize OmemoManager successful for kingfisher@atalk.org/atalk
01-29 22:47:38.336 D/SMACK: SENT (0): <iq to='kingfisher@atalk.org' id='VWfbs-74' type='set'><pubsub xmlns='http://jabber.org/protocol/pubsub'><publish node='eu.siacs.conversations.axolotl.bundles:601605057'><item><bundle xmlns='eu.siacs.conversations.axolotl'><signedPreKeyPublic signedPreKeyId='1'>Bcm7hfFd0fCC3RNAArRbKzLDNp0nupi07coEQF7U78Fg</signedPreKeyPublic><signedPreKeySignature>9y8ilqF6NjoS+dOoVQ6scuDG4j/5e88o/qz9BK/4okK4nAyQ42nuVZtmw2p08kEKdIlEbOoOIPYD/gYAV9B2DQ==</signedPreKeySignature><identityKey>BZL8z3TLF/CRj+iwsluHJHcdaRoZcW1bwL6tREotrt03</identityKey><prekeys><preKeyPublic preKeyId='1'>BbEAGOBoA2zqJpVlRd/fJ0onLtYOdWjaulHd6phlNelw</preKeyPublic><preKeyPublic preKeyId='2'>BYKvJ4F2JdewzLBOedIAPS+7ybCc0JBjJ3+CXjRgEsd7</preKeyPublic><preKeyPublic preKeyId='3'>BZ1n1+zoWx422Wh/ku05QPoqO4QPuk+3a/kc3wTMGhNA</preKeyPublic><preKeyPublic preKeyId='4'>Baf8UmtoguXQfm6bpxdXoLRY4FB8BOwCf+Kd1FSv7l5V</preKeyPublic><preKeyPublic
....
preKeyId='42'>BRZ7TayZ2tmb8pbzkGwLNRGZHo7tWZQwKt+7FsH670xj</preKeyPublic><preKeyPublic preKeyId='43'>Bbhn7Z2H45trivDxP
01-29 22:49:27.916 D/SMACK: SENT (0): </pubsub></iq><r xmlns='urn:xmpp:sm:3'/><iq to='kingfisher@atalk.org' id='VWfbs-75' type='get'><query xmlns='http://jabber.org/protocol/disco#info' node='eu.siacs.conversations.axolotl.devicelist'></query></iq><iq to='kingfisher@atalk.org' id='VWfbs-76' 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='601605057'/></list></item></publish></pubsub></iq><presence id='VWfbs-78'><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='qlaf8fmwUojcVNOO07fSQc7Ko9Y='/></presence><r xmlns='urn:xmpp:sm:3'/><a xmlns='urn:xmpp:sm:3' h='21'/><iq to='atalk.org' id='5454706571586064403' type='result'></iq><iq id='VWfbs-81' type='get'><query xmlns='jabber:iq:roster' ver='5e02d2fb58d78f38abb41ff50450a7a27a4c6712'></query></iq><r xmlns='urn:xmpp:sm:3'/><presence id='VWfbs-84'><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='qlaf8fmwUojcVNOO07fSQc7Ko9Y='/></presence><iq id='VWfbs-85' type='set'><enable xmlns='urn:xmpp:carbons:2'/></iq><iq to='kingfisher@atalk.org' id='VWfbs-86' type='set'><pubsub xmlns='http://jabber.org/protocol/pubsub'><publish node='eu.siacs.conversations.axolotl.bundles:601605057'><item><bundle xmlns='eu.siacs.conversations.axolotl'><signedPreKeyPublic signedPreKeyId='1'>Bcm7hfFd0fCC3RNAArRbKzLDNp0nupi07coEQF7U78Fg</signedPreKeyPublic><signedPreKeySignature>9y8ilqF6NjoS+dOoVQ6scuDG4j/5e88o/qz9BK/4okK4nAyQ42nuVZtmw2p08kEKdIlEbOoOIPYD/gYAV9B2DQ==</signedPreKeySignature><identityKey>BZL8z3TLF/CRj+iwsluHJHcdaRoZcW1bwL6tREotrt03</identityKey><prekeys><preKeyPublic preKeyId='1'>BbEAGOBoA2zqJpVlRd/fJ0onLtYOdWjaulHd6phlNelw</preKeyPublic><preKeyPublic preKeyId='2'>BYKvJ4F2JdewzLBOedIAPS+7ybCc0JBjJ3+CXjRgEsd7</preKeyPublic><preKeyPublic preKeyId='3'>BZ1n1+zoWx422Wh/ku05QPoqO4QPuk+3a/kc3wTMGhNA</preKeyPublic><preKeyPublic
...
+A986llLUyamveSdsYu9qTx1U</preKeyPublic><preKeyPublic preKeyId='24'>BbRA5abE8v3MP3Xp0HAqbD5Bb89PNBMxqGfYgA5t8jQJ</preKeyPublic><preKeyPublic preKeyId='27'>BcewzgGsjrLNxZaYZhu0HNgcQMgAb
01-29 22:49:27.996 D/SMACK: SENT (0): </pubsub></iq><iq to='kingfisher@atalk.org' id='VWfbs-87' type='get'><query xmlns='http://jabber.org/protocol/disco#info' node='eu.siacs.conversations.axolotl.devicelist'></query></iq><iq to='kingfisher@atalk.org' id='VWfbs-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='601605057'/></list></item></publish></pubsub></iq><r xmlns='urn:xmpp:sm:3'/><presence id='VWfbs-90'><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='qlaf8fmwUojcVNOO07fSQc7Ko9Y='/></presence>
01-29 22:49:28.751 D/SMACK: RECV (0): <iq xml:lang='en' to='kingfisher@atalk.org/atalk' from='kingfisher@atalk.org' type='result' id='VWfbs-74'><pubsub xmlns='http://jabber.org/protocol/pubsub'><publish node='eu.siacs.conversations.axolotl.bundles:601605057'><item id='5ED39F1FAF9C6'/></publish></pubsub></iq>
01-29 22:49:28.776 D/SMACK: RECV (0): <iq xml:lang='en' to='kingfisher@atalk.org/atalk' from='kingfisher@atalk.org' type='result' id='VWfbs-75'><query node='eu.siacs.conversations.axolotl.devicelist' xmlns='http://jabber.org/protocol/disco#info'><identity type='registered' category='account'/></query></iq>
01-29 22:49:28.786 D/SMACK: RECV (0): <iq xml:lang='en' to='kingfisher@atalk.org/atalk' from='kingfisher@atalk.org' type='result' id='VWfbs-76'><pubsub xmlns='http://jabber.org/protocol/pubsub'><publish node='eu.siacs.conversations.axolotl.devicelist'><item id='5ED39F2057B8F'/></publish></pubsub></iq>
01-29 22:49:28.801 D/SMACK: RECV (0): <presence xml:lang='en' to='kingfisher@atalk.org/atalk' from='kingfisher@atalk.org/atalk' id='VWfbs-78'><x xmlns='vcard-temp:x:update'/><c xmlns='http://jabber.org/protocol/caps' hash='sha-1' node='http://android.atalk.org' ver='qlaf8fmwUojcVNOO07fSQc7Ko9Y='/><priority>30</priority><status/></presence>
01-29 22:49:28.806 D/SMACK: RECV (0): <iq xml:lang='en' to='kingfisher@atalk.org/atalk' from='kingfisher@atalk.org' type='result' id='VWfbs-81'/>
01-29 22:49:28.806 D/SMACK: RECV (0): <presence xml:lang='en' to='kingfisher@atalk.org/atalk' from='kingfisher@atalk.org/atalk' id='VWfbs-84'><x xmlns='vcard-temp:x:update'/><c xmlns='http://jabber.org/protocol/caps' hash='sha-1' node='http://android.atalk.org' ver='qlaf8fmwUojcVNOO07fSQc7Ko9Y='/><priority>30</priority><status/></presence>
01-29 22:49:28.811 D/SMACK: RECV (0): <iq xml:lang='en' to='kingfisher@atalk.org/atalk' from='kingfisher@atalk.org' type='result' id='VWfbs-85'/>
01-29 22:49:32.326 D/SMACK: RECV (0): <iq xml:lang='en' to='kingfisher@atalk.org/atalk' from='kingfisher@atalk.org' type='result' id='VWfbs-86'><pubsub xmlns='http://jabber.org/protocol/pubsub'><publish node='eu.siacs.conversations.axolotl.bundles:601605057'><item id='5ED39F23D5470'/></publish></pubsub></iq>
01-29 22:49:32.331 D/SMACK: RECV (0): <iq xml:lang='en' to='kingfisher@atalk.org/atalk' from='kingfisher@atalk.org' type='result' id='VWfbs-87'><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>
01-29 22:49:32.346 D/SMACK: RECV (0): <iq xml:lang='en' to='kingfisher@atalk.org/atalk' from='kingfisher@atalk.org' type='result' id='VWfbs-88'><pubsub xmlns='http://jabber.org/protocol/pubsub'><publish node='eu.siacs.conversations.axolotl.devicelist'><item id='5ED39F23E637B'/></publish></pubsub></iq>

#4

@Flow once suggested, that the log is not 100% accurate, so the order of stanza might get messed up in the logs. It is unlikely though, that the stanzas get delayed for 4 minutes in the logs.

I appreciate your bugfix, but I’d rather like to pin point the actual issue within smack, which causes the original issue :slight_smile:


#5

I tested again with new account kingfisher@atalk.org. With the patches, Note-2 has successfully setup the required table for properly omemo messaging. Without the patches, I just unable to get omemo working on Note-2.

I agree with you that we should get to the root cause and find a solution instead of patch. I will only keep the patch until a solution is found without holding back next release for aTalk. It seems that the problem is also tied to old android with JIT implementation as I have mentioned for aTalk installation in below link, and smack / PublishManager seems to be very sensitive to this.

http://atalk.sytes.net/faq.html
Why aTalk is not working properly on my old android devices?

I understand that the log timestamp is not 100% accurate, but the resolution is certainly good enough for purpose of testing. At one time I did a cross reference between aTalk log and the log on ejabberd server. I found that both the timestamp matches with only difference of the realtime clock between the two.

Following log is the cross reference of the above mentioned event between aTalk and ejabberd server.
Note: ejabberd real-time clock leads Note-2 real-time clock by 25 seconds (actual readings on both devices); this 25sec is also reflected in the actual time Stamp between the two, and matches to within 1s. The network delay are negligible in my case as both devices are sitting on the same network.

From ejabberd log, the publishBundle actually received by ejabberd only on second attempt after re-connection. The first attempt on publishBundle get interrupted by sudden disconnection. Therefore the previous mentioned of ~4 mins (01-29 22:45:41.906 - 01-29 22:41:52.561) really did happen for the first attempt.

01-29 22:41:52.561 W/aTalk: [6] org.jivesoftware.smackx.omemo.OmemoService.publishBundle() Ignore OmemoService publishBundle 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=VWfbs-74)), : fromFilter (OrFilter: (FromMatchesFilter (full): kingfisher@atalk.org, FromMatchesFilter (full): null)).
01-29 22:45:41.906 D/SMACK: SENT (0): <iq to='kingfisher@atalk.org' id='VWfbs-74' type='set'><pubsub xmlns='http://jabber.org/protocol/pubsub'><publish node='eu.siacs.conversations.axolotl.bundles:601605057'><item><bundle xmlns='eu.siacs.conversations.axolotl'.....

Cross reference between atalk and ejabberd log

==+======== aTalk Log ==============
01-29 22:41:31.146 D/SMACK: RECV (0): <presence xml:lang='en' to='kingfisher@atalk.org/atalk' from='kingfisher@atalk.org/atalk' id='VWfbs-72'><x xmlns='vcard-temp:x:update'/><c xmlns='http://jabber.org/protocol/caps' hash='sha-1' node='http://android.atalk.org' ver='qlaf8fmwUojcVNOO07fSQc7Ko9Y='/><priority>30</priority><status/></presence>

01-29 22:47:38.336 D/SMACK: SENT (0): <iq to='kingfisher@atalk.org' id='VWfbs-74' type='set'><pubsub xmlns='http://jabber.org/protocol/pubsub'><publish node='eu.siacs.conversations.axolotl.bundles:601605057'><item><bundle xmlns='eu.siacs.conversations.axolotl'><signedPreKeyPublic signedPreKeyId='1'>Bcm7hfFd0fCC3RNAArRbKzLDNp0nupi07coEQF7U78Fg<

==+======== ejabberd Log ==============
2018-01-29 22:41:06.892 [debug] <0.21087.0>@ejabberd_sm:do_route:693 sending to process <0.21087.0>:
#presence{id = <<"VWfbs-72">>,type = available,lang = <<"en">>,
          from = {jid,<<"kingfisher">>,<<"atalk.org">>,<<"atalk">>,
                      <<"kingfisher">>,<<"atalk.org">>,<<"atalk">>},
          to = {jid,<<"kingfisher">>,<<"atalk.org">>,<<"atalk">>,
                    <<"kingfisher">>,<<"atalk.org">>,<<"atalk">>},
          show = undefined,
          status = [#text{lang = <<>>,data = <<>>}],
          priority = 30,
          sub_els = [{vcard_xupdate,{<<>>,<<>>},undefined},
                     {xmlel,<<"c">>,
                            [{<<"xmlns">>,
                              <<"http://jabber.org/protocol/caps">>},
                             {<<"hash">>,<<"sha-1">>},
                             {<<"node">>,<<"http://android.atalk.org">>},
                             {<<"ver">>,<<"qlaf8fmwUojcVNOO07fSQc7Ko9Y=">>}],
                            []}],
          meta = #{ip => {0,0,0,0,0,65535,29506,21708}}

2018-01-29 22:47:14.057 [debug] <0.21103.0>@ejabberd_receiver:process_data:284 Received XML on stream = <<"<iq to='kingfisher@atalk.org' id='VWfbs-74' type='set'><pubsub xmlns='http://jabber.org/protocol/pubsub'><publish node='eu.siacs.conversations.axolotl.bundles:601605057'><item><bundle

#6

Thats strange. I wonder how Signal deals with older devices and JIT.


#7

Conversations uses Signal, but it has a less complicated state table to handle stanza sending and receiving.

Actually I should not just said that NoResponseException only happen on slow android device with JIT. Is also happen on new android but less frequent. Just got a NoResponseException on my Note-8 while testing.
Just wonder if there is actually a synchronize problem or race condition happen in smack while waiting for response. Last time when I reviewed smack code on this area, I believe smack is using loop to check for reply.

Like the Note-8 log below, the received of 3 stanza happen so fast and one after another within <3ms; look like smack miss the last one which happen within fraction of ms apart for the last two - too fast for smack handler?
Look like smack does not like too slow or too fast android devices?
Really appreciate the smack team can seriously look into the cause of the problem.

Sometimes smack NoResponseException really makes my testing very difficult, have to keep checking the log to see the cause and ascertain it it leads to the observed problem. Failure to join chat room, means I have to restart the whole environment setup again before can proceed to do further testing.

====== Note 8 Log ===========
01-31 09:54:31.838 D/SMACK: SENT (0): <iq to='atalk.org' id='9YKjY-167' type='get'><query xmlns='http://jabber.org/protocol/disco#items'></query></iq><iq to='chatroom-ajwr@conference.atalk.org' id='9YKjY-168' type='get'><query xmlns='http://jabber.org/protocol/disco#info'></query></iq><r xmlns='urn:xmpp:sm:3'/><iq id='9YKjY-172' type='get'><query xmlns='jabber:iq:roster' ver='0ec6508444796c502c41aea673ee00198b56b441'></query></iq>
01-31 09:54:32.107 D/SMACK: RECV (0): <iq xml:lang='en' to='swordfish@atalk.org/atalk' from='atalk.org' type='result' id='9YKjY-167'><query xmlns='http://jabber.org/protocol/disco#items'><item jid='conference.atalk.org'/><item jid='focus.atalk.org'/><item jid='irc.atalk.org'/><item jid='jitsi-videobridge.atalk.org'/><item jid='proxy.atalk.org'/><item jid='pubsub.atalk.org'/></query></iq>
01-31 09:54:32.109 D/SMACK: RECV (0): <iq xml:lang='en' to='swordfish@atalk.org/atalk' from='chatroom-ajwr@conference.atalk.org' type='result' id='9YKjY-168'><query xmlns='http://jabber.org/protocol/disco#info'><identity name='chatroom-ajwr' type='text' category='conference'/><feature var='vcard-temp'/><feature var='http://jabber.org/protocol/muc'/><feature var='muc_hidden'/><feature var='muc_persistent'/><feature var='muc_membersonly'/><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>
01-31 09:54:32.109 D/SMACK: RECV (0): <iq xml:lang='en' to='swordfish@atalk.org/atalk' from='swordfish@atalk.org' type='result' id='9YKjY-172'/>
01-31 09:54:41.839 E/aTalk: [27605] org.jivesoftware.smack.roster.Roster.processException() Exception reloading roster
                            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=9YKjY-172)), : fromFilter (OrFilter: (FromMatchesFilter (full): null, FromMatchesFilter (ignoreResourcepart): swordfish@atalk.org, FromMatchesFilter (full): atalk.org)).
                                at org.jivesoftware.smack.AbstractXMPPConnection$7.run(AbstractXMPPConnection.java:1563)
                                at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:428)
                                at java.util.concurrent.FutureTask.run(FutureTask.java:237)
                                at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:272)
                                at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1133)
                                at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:607)
                                at java.lang.Thread.run(Thread.java:762)

===== joining chat room failed =

01-31 10:33:03.680 D/SMACK: SENT (0): <iq to='conference.atalk.org' id='Kfakx-119' type='get'><query xmlns='http://jabber.org/protocol/disco#info'></query></iq>
01-31 10:33:03.689 D/ViewRootImpl@6a80adf[aTalk]: MSG_WINDOW_FOCUS_CHANGED 0
01-31 10:33:03.696 D/SMACK: RECV (0): <iq xml:lang='en' to='swordfish@atalk.org/atalk' from='conference.atalk.org' type='result' id='Kfakx-119'><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>
01-31 10:33:13.689 E/aTalk: [27878] impl.protocol.jabber.ChatRoomJabberImpl.joinAs().651 Failed to join room chatroom-ajwr@conference.atalk.org with nickname: swordfish
                            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=Kfakx-119)), : fromFilter (OrFilter: (FromMatchesFilter (full): conference.atalk.org)).
                                at org.jivesoftware.smack.StanzaCollector.nextResultOrThrow(StanzaCollector.java:253)
                                at org.jivesoftware.smack.StanzaCollector.nextResultOrThrow(StanzaCollector.java:208)
                                at org.jivesoftware.smackx.disco.ServiceDiscoveryManager.discoverInfo(ServiceDiscoveryManager.java:542)
                                at org.jivesoftware.smackx.disco.ServiceDiscoveryManager.discoverInfo(ServiceDiscoveryManager.java:508)
                                at org.jivesoftware.smackx.disco.ServiceDiscoveryManager.supportsFeatures(ServiceDiscoveryManager.java:738)
                                at org.jivesoftware.smackx.disco.ServiceDiscoveryManager.supportsFeatures(ServiceDiscoveryManager.java:734)
                                at org.jivesoftware.smackx.disco.ServiceDiscoveryManager.supportsFeature(ServiceDiscoveryManager.java:730)
                                at org.jivesoftware.smackx.muc.MultiUserChatManager.providesMucService(MultiUserChatManager.java:359)
                                at org.jivesoftware.smackx.muc.MultiUserChat.enter(MultiUserChat.java:311)
                                at org.jivesoftware.smackx.muc.MultiUserChat.join(MultiUserChat.java:711)
                                at org.jivesoftware.smackx.muc.MultiUserChat.join(MultiUserChat.java:603)
                                at net.java.sip.communicator.impl.protocol.jabber.ChatRoomJabberImpl.joinAs(ChatRoomJabberImpl.java:611)
                                at net.java.sip.communicator.impl.protocol.jabber.ChatRoomJabberImpl.joinAs(ChatRoomJabberImpl.java:667)
                                at net.java.sip.communicator.impl.muc.MUCServiceImpl$JoinChatRoomTask.run(MUCServiceImpl.java:607)


#8

I have released aTalk currently at version 1.1.1 with the latest Omemo library. However aTalk is continuously haunted by the unexplained NoResponseException throws from smack; It happens on my Note-3 and confirmed also on Note-8. Both devices are already with AOT compilation OS. Both the devices also get disconnected on callConnectionClosedOnErrorListener() for no apparent reason. This uncontrolled smack behavior has really caused problem for a proper working aTalk. The aTalk have already received two rating of “1” with simple notes of “not working” or “no even connect” from users. Just wonder if this has to do with NoResponseException.

On network reconnected after callConnectionClosedOnErrorListener(), similar NoResponseException for carbon, pubsub stanzas etc again happen. The re-connection can happen more than 1 time on Note-8. On Note-3 it is even worst and callConnectionClosedOnErrorListener() repeated multiple times.

Following is a captured log (extracted with only the relevant stanzas) on Note-8 after a new account is registered on the server. I have already included patch to ignore the NoResponseException in OmemoService, but looks like the problem is random and can happen on other stanzas. Without the patch, there would not be any Omemo messaging support on aTalk. It is 100% failure on NoResponseException even on my Note-8 for all the omemo stanzas access i.e. omemo.OmemoService.publishBundle(), omemo.OmemoService.fetchDeviceList() and OmemoService.publishDeviceList().

From the log, it is seen that all stanzas send and receive are well within the timeout period specified. Yet Samck throws NoResponseException.

The received format is correct, but smack complains “Failed to parse extension element in Presence stanza:” and next tihng it does is to throw callConnectionClosedOnErrorListener and terminate the network connection.

Appreciate the smack team would seriously look into the problem and offer a solution.

02-11 17:24:35.200 D/SMACK: SENT (1): <presence id='X3c7l-158'><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='qlaf8fmwUojcVNOO07fSQc7Ko9Y='/></presence>

02-11 17:24:35.202 D/SMACK: SENT (1): <iq id='X3c7l-159' type='set'><enable xmlns='urn:xmpp:carbons:2'/></iq><r xmlns='urn:xmpp:sm:3'/>
02-11 17:24:35.593 D/SMACK: RECV (1): <presence xml:lang='en' to='aaa@atalk.org/atalk' from='aaa@atalk.org/atalk' id='X3c7l-158'><x xmlns='vcard-temp:x:update'/><c xmlns='http://jabber.org/protocol/caps' hash='sha-1' node='http://android.atalk.org' ver='qlaf8fmwUojcVNOO07fSQc7Ko9Y='/><priority>30</priority><status/></presence>

02-11 17:24:35.593 D/SMACK: RECV (1): <iq xml:lang='en' to='aaa@atalk.org/atalk' from='aaa@atalk.org' type='result' id='X3c7l-159'/>

02-11 17:24:36.880 D/SMACK: SENT (1): <iq to='aaa@atalk.org' id='X3c7l-176' type='set'><pubsub xmlns='http://jabber.org/protocol/pubsub'><publish node='eu.siacs.conversations.axolotl.bundles:1772012830'><item><bundle xmlns='eu.siacs.conversations.axolotl'><signedPreKeyPublic 
.....
preKeyId='14'>BSB+u4k30/1RsFNpl96Eo8O98GVg+R6jE8DSyHBwTK5u</preKeyPublic><preKeyPublic preKeyId='46'>BXFf1r/Jo2tIG8ycjuuv87jdMrtHYHDHyJWfNWwo6Ow1</preKeyPublic><preKeyPublic preKeyId='20'>BVQ8qZ5j</pubsub></iq>
02-11 17:24:41.185 D/SMACK: RECV (1): <iq xml:lang='en' to='aaa@atalk.org/atalk' from='aaa@atalk.org' type='result' id='X3c7l-176'><pubsub xmlns='http://jabber.org/protocol/pubsub'><publish node='eu.siacs.conversations.axolotl.bundles:1772012830'><item id='5EE5345A3FD07'/></publish></pubsub></iq>

02-11 17:24:45.205 E/aTalk: [10891] impl.protocol.jabber.OperationSetBasicInstantMessagingJabberImpl.enableDisableCarbon().731 Failed to set carbon state for: aaa@atalk.org/atalk to true
                            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=X3c7l-159)), : fromFilter (OrFilter: (FromMatchesFilter (full): null, FromMatchesFilter (ignoreResourcepart): aaa@atalk.org, FromMatchesFilter (full): atalk.org)).
                                at org.jivesoftware.smack.StanzaCollector.nextResultOrThrow(StanzaCollector.java:253)
                                at org.jivesoftware.smack.StanzaCollector.nextResultOrThrow(StanzaCollector.java:208)
                                at org.jivesoftware.smackx.carbons.CarbonManager.setCarbonsEnabled(CarbonManager.java:311)
                                at net.java.sip.communicator.impl.protocol.jabber.OperationSetBasicInstantMessagingJabberImpl.enableDisableCarbon(OperationSetBasicInstantMessagingJabberImpl.java:721)
                                at net.java.sip.communicator.impl.protocol.jabber.OperationSetBasicInstantMessagingJabberImpl.initAdditionalServices(OperationSetBasicInstantMessagingJabberImpl.java:704)
                                at net.java.sip.communicator.impl.protocol.jabber.OperationSetBasicInstantMessagingJabberImpl.access$700(OperationSetBasicInstantMessagingJabberImpl.java:102)
                                at net.java.sip.communicator.impl.protocol.jabber.OperationSetBasicInstantMessagingJabberImpl$RegistrationStateListener$1.run(OperationSetBasicInstantMessagingJabberImpl.java:673)
                                at java.lang.Thread.run(Thread.java:762)

02-11 17:25:26.582 W/aTalk: [10890] org.jivesoftware.smackx.omemo.OmemoService.publishBundle() Ignore OmemoService publishBundle response timeout: 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=X3c7l-176)), : fromFilter (OrFilter: (FromMatchesFilter (full): aaa@atalk.org, FromMatchesFilter (full): null)).
02-11 17:25:26.585 D/SMACK: SENT (1): <iq to='aaa@atalk.org' id='X3c7l-194' type='get'><query xmlns='http://jabber.org/protocol/disco#info' node='eu.siacs.conversations.axolotl.devicelist'></query></iq>
02-11 17:25:26.604 D/SMACK: RECV (1): <iq xml:lang='en' to='aaa@atalk.org/atalk' from='aaa@atalk.org' type='result' id='X3c7l-194'><query node='eu.siacs.conversations.axolotl.devicelist' xmlns='http://jabber.org/protocol/disco#info'><identity type='registered' category='account'/></query></iq>
02-11 17:26:16.584 W/aTalk: [10890] org.jivesoftware.smackx.omemo.OmemoService.fetchDeviceList() Ignore OmemoService fetchDeviceList response timeout: 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=X3c7l-194)), : fromFilter (OrFilter: (FromMatchesFilter (full): aaa@atalk.org, FromMatchesFilter (full): null)).

02-11 17:26:16.591 D/SMACK: SENT (1): <iq to='aaa@atalk.org' id='X3c7l-195' 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='1772012830'/></list></item></publish></pubsub></iq>
02-11 17:26:16.592 W/aTalk: [10862] org.jivesoftware.smack.util.PacketParserUtils.parsePresence() Failed to parse extension element in Presence stanza: "java.net.SocketException: socket is closed" from: 'aaa@atalk.org/atalk id: 'X3c7l-158'
02-11 17:26:16.597 W/aTalk: [10861] org.jivesoftware.smack.AbstractXMPPConnection.callConnectionClosedOnErrorListener() Connection XMPPTCPConnection[aaa@atalk.org/atalk] (1) closed with error
                            javax.net.ssl.SSLException: Write error: ssl=0xd10aca00: I/O error during system call, Broken pipe
                                at com.android.org.conscrypt.NativeCrypto.SSL_write(Native Method)
                                at com.android.org.conscrypt.OpenSSLSocketImpl$SSLOutputStream.write(OpenSSLSocketImpl.java:855)
                                at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
                                at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:291)
                                at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:295)
                                at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:141)
                                at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:229)
                                at org.jivesoftware.smack.util.ObservableWriter.flush(ObservableWriter.java:51)
                                at org.jivesoftware.smack.tcp.XMPPTCPConnection$PacketWriter.writePackets(XMPPTCPConnection.java:1453)
                                at org.jivesoftware.smack.tcp.XMPPTCPConnection$PacketWriter.access$3300(XMPPTCPConnection.java:1260)
                                at org.jivesoftware.smack.tcp.XMPPTCPConnection$PacketWriter$1.run(XMPPTCPConnection.java:1308)
                                at java.lang.Thread.run(Thread.java:762)
02-11 17:26:17.622 D/SMACK: XMPPConnection (XMPPTCPConnection[aaa@atalk.org/atalk] (1)) will reconnect in 9
02-11 17:26:18.623 D/SMACK: XMPPConnection (XMPPTCPConnection[aaa@atalk.org/atalk] (1)) will reconnect in 8
02-11 17:26:19.625 D/SMACK: XMPPConnection (XMPPTCPConnection[aaa@atalk.org/atalk] (1)) will reconnect in 7
...

#9

That is possibly a deadlock which resolves itself after awaiting a response times out throwing a NoResponseException. A common cause is performing a request/await-response operation in a sync listener.


#10

I will close this issue. Mostly like it also due to aTalk own problem. Does not seem to encounter this after the below fix.