8 Replies Latest reply on Jun 17, 2017 2:24 AM by cmeng

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

    cmeng

      While testing aTalk, trying to remove a roster entry using the method below:

      roster.removeEntry(entry);

       

      Note: the entry is still pending subscription authorization from the contact.

       

      Smack 4.2.0 sends an <query xmlns='jabber:iq:roster'> with 'ask' attribute in <item/> which is not allow as per RFC6121 document

       

      ================ RFC6121 section 2.1.2.2 extraction =================

      2.1.2.2.  Ask Attribute

         The 'ask' attribute of the <item/> element with a value of

         "subscribe" is used to signal various subscription sub-states that

         include a "Pending Out" aspect as described under Section 3.1.2.

       

         A server SHOULD include the 'ask' attribute to inform the client of

         "Pending Out" sub-states.  A client MUST NOT include the 'ask'

         attribute in the roster sets it sends to the server, but instead MUST

         use presence stanzas of type "subscribe" and "unsubscribe" to manage

         such sub-states as described under Section 3.1.2.

       

      ========= SMACK Error Log ======================

      05-21 16:59:33.441 D/SMACK: SENT (1): <iq id='w2HYF-301' type='set'><query xmlns='jabber:iq:roster'><item jid='abc123@atalk.org' name='abc123.atalk' subscription='remove' ask='subscribe'><group>atalk member</group></item></query></iq>

      05-21 16:59:33.851 D/SMACK: RECV (1): <iq xml:lang='en' to='abc123@jabbim.com/atalk' from='abc123@jabbim.com' type='error' id='w2HYF-301'><query xmlns='jabber:iq:roster'><item ask='subscribe' subscription='remove' name='abc123.atalk' jid='abc123@atalk.org'><group>atalk member</group></item></query><error code='400' type='modify'><bad-request xmlns='urn:ietf:params:xml:ns:xmpp-stanzas'/><text xml:lang='en' xmlns='urn:ietf:params:xml:ns:xmpp-stanzas'>Possessing &apos;ask&apos; attribute is not allowed by RFC6121</text></error></iq>

          • Re: Smack 4.2.0 sends 'ask' attribute in Roster.removeEntry not allowed by RFC6121
            cmeng

            I have just tested the latest SNAPSHOT released on Jun 5, 2017.  Although the problem on the 'ask' attribute has been corrected, the capture log still shows response timeout?

             

            I have checked the log on the server, there is no related error reported, and the contact that has been removed is also properly deleted from its database. However this problem does not happen when performed on an earlier registered account. Strange? Look like I really need to get to the root cause of the response timeout on other scenarios.

             

            Any ideas?

             

            ================== aTalk - Contact (waiting for authorization) removal log ======================

            06-09 11:01:09.816 D/SMACK: SENT (0): <iq id='4MH5l-82' type='set'><query xmlns='jabber:iq:roster'><item jid='abc123@atalk.org' name='abc123@atalk.org' subscription='remove'><group>friends</group></item></query></iq>

            06-09 11:01:09.936 D/SMACK: RECV (0): <iq to='newx@atalk.org/atalk' from='newx@atalk.org' type='set' id='push13559684941514785749'><query ver='f64161520b7c9c038747ee5e36769fcbd52aca29' xmlns='jabber:iq:roster'><item subscription='remove' jid='abc123@atalk.org'/></query></iq>

            06-09 11:01:09.936 D/SMACK: RECV (0): <iq xml:lang='en' to='newx@atalk.org/atalk' from='newx@atalk.org' type='result' id='4MH5l-82'/>

            06-09 11:01:14.816 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=4MH5l-82)), : fromFilter (OrFilter: (FromMatchesFilter (full): null, FromMatchesFilter (ignoreResourcepart): newx@atalk.org, FromMatchesFilter (full): atalk.org)).

            06-09 11:01:14.836 W/System.err:     at org.jivesoftware.smack.StanzaCollector.nextResultOrThrow(StanzaCollector.java:2 53)

            06-09 11:01:14.836 W/System.err:     at org.jivesoftware.smack.StanzaCollector.nextResultOrThrow(StanzaCollector.java:2 08)

            06-09 11:01:14.836 W/System.err:     at org.jivesoftware.smack.roster.Roster.removeEntry(Roster.java:752)

            06-09 11:01:14.836 W/System.err:     at net.java.sip.communicator.impl.protocol.jabber.ServerStoredContactListJabberImp l.removeContact(ServerStoredContactListJabberImpl.java:751)

            06-09 11:01:14.836 W/System.err:     at net.java.sip.communicator.impl.protocol.jabber.OperationSetPersistentPresenceJa bberImpl.unsubscribe(OperationSetPersistentPresenceJabberImpl.java:799)

            06-09 11:01:14.836 W/System.err:     at net.java.sip.communicator.impl.contactlist.MetaContactListServiceImpl.removeCon tact(MetaContactListServiceImpl.java:1068)

            06-09 11:01:14.836 W/System.err:     at net.java.sip.communicator.impl.contactlist.MetaContactListServiceImpl.removeMet aContact(MetaContactListServiceImpl.java:1106)

            06-09 11:01:14.836 W/System.err:     at org.atalk.android.gui.contactlist.MetaContactListManager$2.run(MetaContactListM anager.java:81)

            06-09 11:01:14.836 W/System.err:     at java.lang.Thread.run(Thread.java:818)

                • Re: Smack 4.2.0 sends 'ask' attribute in Roster.removeEntry not allowed by RFC6121
                  cmeng

                  I did further testing on the response timeout issue. Upon execution break on

                  setCarbonsEnabled##connection().createStanzaCollectorAndSend(setIQ).nextResultOr Throw();

                  I place two more break points br#1 and br#2 in the following method; and caught it reaches br#1. Below is the captured debug variables when this happens. I checked through the packetFilter, and seems it is being correctly set, however the result == null although the correct IQ result has already been received. It looks like the problem is within the nextResult(timeout);

                   

                  Another observation is that the reply is received 10mS after sending the IQ-set. Will there be a race condition; where under this case the StanzaCollector is slow in the preparation to receive the IQ-result.

                   

                  I did more testings, capturing instances for passed and failed cases (see log below). Based on the measured data, it seems ~110mS is the pivot point for pass or fail.

                   

                  -----------------------------

                  public <P extends Stanza> P nextResultOrThrow(long timeout) throws NoResponseException,
                     XMPPErrorException, InterruptedException, NotConnectedException {
                     P result = nextResult(timeout);
                     cancel();
                     if (result == null) {
                     if (!connection.isConnected()) {
                     throw new NotConnectedException(connection, packetFilter);
                     }
                  br#1   throw NoResponseException.newWith(connection, this);
                     }
                     XMPPErrorException.ifHasErrorThenThrow(result);
                  br#2   return result;
                  }

                   

                  ============ aTalk debug log to enable carbon ===================

                  06-10 02:35:58.126 D/SMACK: SENT (0): <iq id='26c6I-69' type='set'><enable xmlns='urn:xmpp:carbons:2'/></iq>

                  06-10 02:35:58.136 D/SMACK: RECV (0): <iq xml:lang='en' to='newx@atalk.org/atalk' from='newx@atalk.org' type='result' id='26c6I-69'/>

                   

                  ============= aTalk debug variable =================

                  result = null

                  packetFilter = {IQReplyFilter@22283} "IQReplyFilter: iqAndIdFilter (AndFilter: (OrFilter: (IQTypeFilter: type=error, IQTypeFilter: type=result), StanzaIdFilter: id=26c6I-69)), : fromFilter (OrFilter: (FromMatchesFilter (full): null, FromMatchesFilter (ignoreResourcepart): newx@atalk.org, FromMatchesFilter (full): atalk.org))"

                  fromFilter = {OrFilter@22287} "OrFilter: (FromMatchesFilter (full): null, FromMatchesFilter (ignoreResourcepart): newx@atalk.org, FromMatchesFilter (full): atalk.org)"

                  iqAndIdFilter = {AndFilter@22288} "AndFilter: (OrFilter: (IQTypeFilter: type=error, IQTypeFilter: type=result), StanzaIdFilter: id=26c6I-69)"

                  local = {LocalDomainAndResourcepartJid@22289} "newx@atalk.org/atalk"

                  packetId = "26c6I-69"

                  server = {DomainpartJid@22291} "atalk.org"

                  to = null

                  shadow$_klass_ = {Class@22151} "class org.jivesoftware.smack.filter.IQReplyFilter"

                  shadow$_monitor_ = -1123969654

                   

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

                  ============ aTalk debug for carbon enabled passed/failed cases based on reply time ===============

                  06-10 03:16:51.786 D/SMACK: SENT (0): <iq id='52KFZ-74' type='set'><enable xmlns='urn:xmpp:carbons:2'/></iq>

                  06-10 03:16:51.896 D/SMACK: RECV (0): <iq xml:lang='en' to='newx@atalk.org/atalk' from='newx@atalk.org' type='result' id='52KFZ-74'/>

                  06-10 03:16:51.906 I/αTalk: [11] impl.protocol.jabber.OperationSetBasicInstantMessagingJabberImpl.enableDisableC arbon().678 Successfully setting carbon new state for: newx@atalk.org/atalk to true

                   

                  06-10 03:19:37.226 D/SMACK: SENT (0): <iq id='15ajs-69' type='set'><enable xmlns='urn:xmpp:carbons:2'/></iq>

                  06-10 03:19:37.316 D/SMACK: RECV (0): <iq xml:lang='en' to='newx@atalk.org/atalk' from='newx@atalk.org' type='result' id='15ajs-69'/>

                  06-10 03:19:42.226 E/αTalk: [14] impl.protocol.jabber.OperationSetBasicInstantMessagingJabberImpl.enableDisableC arbon().683 Failed to set carbon state for: newx@atalk.org/atalk to true

                   

                  06-10 03:23:18.216 D/SMACK: SENT (0): <iq id='DzdIF-75' type='set'><enable xmlns='urn:xmpp:carbons:2'/></iq>

                  06-10 03:23:18.366 D/SMACK: RECV (0): <iq xml:lang='en' to='newx@atalk.org/atalk' from='newx@atalk.org' type='result' id='DzdIF-75'/>

                  06-10 03:23:18.366 I/αTalk: [12] impl.protocol.jabber.OperationSetBasicInstantMessagingJabberImpl.enableDisableC arbon().678 Successfully setting carbon new state for: newx@atalk.org/atalk to true

                   

                  06-10 03:25:31.686 D/SMACK: SENT (0): <iq id='3qAtg-68' type='set'><enable xmlns='urn:xmpp:carbons:2'/></iq>

                  06-10 03:25:31.896 D/SMACK: RECV (0): <iq xml:lang='en' to='newx@atalk.org/atalk' from='newx@atalk.org' type='result' id='3qAtg-68'/>

                  06-10 03:25:31.906 I/αTalk: [11] impl.protocol.jabber.OperationSetBasicInstantMessagingJabberImpl.enableDisableC arbon().678 Successfully setting carbon new state for: newx@atalk.org/atalk to true

                   

                  06-10 03:27:06.766 D/SMACK: SENT (0): <iq id='ArHmR-75' type='set'><enable xmlns='urn:xmpp:carbons:2'/></iq><r xmlns='urn:xmpp:sm:3'/>

                  06-10 03:27:06.876 D/SMACK: RECV (0): <iq xml:lang='en' to='newx@atalk.org/atalk' from='newx@atalk.org' type='result' id='ArHmR-75'/>

                  06-10 03:27:11.776 E/αTalk: [12] impl.protocol.jabber.OperationSetBasicInstantMessagingJabberImpl.enableDisableC arbon().683 Failed to set carbon state for: newx@atalk.org/atalk to true

                   

                  06-10 03:29:19.296 D/SMACK: SENT (0): <iq id='6R3bW-75' type='set'><enable xmlns='urn:xmpp:carbons:2'/></iq><r xmlns='urn:xmpp:sm:3'/>

                  06-10 03:29:19.386 D/SMACK: RECV (0): <iq xml:lang='en' to='newx@atalk.org/atalk' from='newx@atalk.org' type='result' id='6R3bW-75'/>

                  06-10 03:29:24.296 E/αTalk: [13] impl.protocol.jabber.OperationSetBasicInstantMessagingJabberImpl.enableDisableC arbon().683 Failed to set carbon state for: newx@atalk.org/atalk to true

                • Re: Smack 4.2.0 sends 'ask' attribute in Roster.removeEntry not allowed by RFC6121
                  Flow

                  Could you create a test account on atalk.org for me and send the me credentials via private message? I'd like to try re-creating the issue.