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

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 with ‘ask’ attribute in 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 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): atalk member

05-21 16:59:33.851 D/SMACK: RECV (1): atalk memberPossessing ‘ask’ attribute is not allowed by RFC6121

Excellent bug report. Created [SMACK-766] Smack possibly includes ‘ask’ attribute in roster items when sending requests - IgniteRealtime JIRA.

Will be fixed in Smack 4.2.1.

Should be fixed with Don’t send ‘ask’ roster item attribute · Flowdalic/Smack@847890b · GitHub

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): friends

06-09 11:01:09.936 D/SMACK: RECV (0):

06-09 11:01:09.936 D/SMACK: RECV (0):

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)

There appears to be an issue with IQ requests to the user’s account. I’ve created [SMACK-768] Smack throws NoResponse timeout when waiting for IQ although there was a response - IgniteRealtime JIRA

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 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):

06-10 02:35:58.136 D/SMACK: RECV (0):

============= 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):

06-10 03:16:51.896 D/SMACK: RECV (0):

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):

06-10 03:19:37.316 D/SMACK: RECV (0):

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):

06-10 03:23:18.366 D/SMACK: RECV (0):

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):

06-10 03:25:31.896 D/SMACK: RECV (0):

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):

06-10 03:27:06.876 D/SMACK: RECV (0):

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):

06-10 03:29:19.386 D/SMACK: RECV (0):

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

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.

Should be fixed in Smack 4.2.1-SNAPSHOTS and in the upcoming Smack 4.2.1 release.

I have just tested the latest Smack 4.2.1-SNAPSHOT, I do not encounter anymore problem on response timeout.

Thanks for the new release