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

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