Smack 4.2.1-SNAPSHOT failed to capture Carbon.Enable() response on new registered Jid

aTalk has a method (as shown below) to enable the carbon using Carbon.Enable(); and verify success by checking for its iq response. However it always reports failure to receive response on timeout for a newly IB-Registered Jid account ‘test@atalk.org/atalk’, even thought the response did indeed sent by the server.

aTalk xmpp client has 3 jabber account registered. Carbon.Enable() is working correctly for the other two accounts

See capture log below.

Anybody has ideas what can be the problem that causes this strange behavior? Any help is appreciated?

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

private void enableDisableCarbon(final boolean enable)
{
IQ iq = enable ? new Carbon.Enable() : new Carbon.Disable();
isCarbonEnabled = false;

Stanza response = null;
try {
iq.setFrom(jabberProvider.getOurJID());
iq.setType(IQ.Type.set);
StanzaCollector packetCollector = jabberProvider.getConnection()
.createStanzaCollectorAndSend(new StanzaIdFilter(iq.getStanzaId()), iq);
response = packetCollector.nextResultOrThrow();
}
catch (Exception e) {
logger.error("Failed to enable carbon for: " + jabberProvider.getOurJID(), e);
return;
}

if ((response == null) || (response.getError() != null)) {
logger.error("Failed to enable carbon: " + response.getError());
}
else if ((response instanceof IQ) && (((IQ) response).getType() == IQ.Type.result)) {
isCarbonEnabled = true;
logger.info("Carbon enabled for: " + iq.getStanzaId());
}
else {
logger.error("Failed to enable carbon. The response is not correct: " + response);
}
}

=========== aTalk catpured log for Carbon.Enable() ================

06-06 13:54:08.975 D/SMACK: SENT (2):

06-06 13:54:09.345 D/SMACK: RECV (2):

06-06 13:54:09.345 I/αTalk: [17] impl.protocol.jabber.OperationSetBasicInstantMessagingJabberImpl.enableDisableC arbon().694 Carbon enabled for: d4F35-206

06-06 13:54:09.735 D/SMACK: SENT (1):

06-06 13:54:09.785 D/SMACK: RECV (1):

06-06 13:54:10.045 D/SMACK: SENT (0):

06-06 13:54:10.105 D/SMACK: RECV (0):

06-06 13:54:10.135 I/αTalk: [25] impl.protocol.jabber.OperationSetBasicInstantMessagingJabberImpl.enableDisableC arbon().694 Carbon enabled for: d4F35-238

06-06 13:54:14.735 E/αTalk: [22] impl.protocol.jabber.OperationSetBasicInstantMessagingJabberImpl.enableDisableC arbon().684 Failed to enable carbon for: test@atalk.org/atalk

org.jivesoftware.smack.SmackException$NoResponseException: No response received within reply timeout. Timeout was 5000ms (~5s). Waited for response using: StanzaIdFilter: id=d4F35-231.

at org.jivesoftware.smack.StanzaCollector.nextResultOrThrow(StanzaCollector.java:2 53)

at org.jivesoftware.smack.StanzaCollector.nextResultOrThrow(StanzaCollector.java:2 08)

at net.java.sip.communicator.impl.protocol.jabber.OperationSetBasicInstantMessagin gJabberImpl.enableDisableCarbon(OperationSetBasicInstantMessagingJabberImpl.java :681)

at net.java.sip.communicator.impl.protocol.jabber.OperationSetBasicInstantMessagin gJabberImpl.initAdditionalServices(OperationSetBasicInstantMessagingJabberImpl.j ava:657)

at net.java.sip.communicator.impl.protocol.jabber.OperationSetBasicInstantMessagin gJabberImpl.access$700(OperationSetBasicInstantMessagingJabberImpl.java:50)

at net.java.sip.communicator.impl.protocol.jabber.OperationSetBasicInstantMessagin gJabberImpl$RegistrationStateListener$1.run(OperationSetBasicInstantMessagingJab berImpl.java:624)

at java.lang.Thread.run(Thread.java:818)

I suggest to use CarbonManager.enableCarbons().

Many thanks for your suggestion. Change the method to the following with your input. The new method has been verified working with the OK account.

06-07 08:40:34.410 D/SMACK: SENT (1):

06-07 08:40:34.570 I/αTalk: [17] impl.protocol.jabber.OperationSetBasicInstantMessagingJabberImpl.enableDisableC arbon().676 Carbon enable state for: leopard@atalk.org/atalk = true

/**

  • Enable carbon feature if supported by server.

*/
private void enableDisableCarbon()
{
EntityFullJid userJid = jabberProvider.getOurJID();
CarbonManager carbonManager = CarbonManager.getInstanceFor(jabberProvider.getConnection());
try {
boolean enableCarbon = carbonManager.isSupportedByServer()
&& !jabberProvider.getAccountID().getAccountPropertyBoolean(
ProtocolProviderFactory.IS_CARBON_DISABLED, false);

if (enableCarbon) {
carbonManager.setCarbonsEnabled(true);
isCarbonEnabled = true;
}
else {
isCarbonEnabled = false;
}
logger.info("Carbon enable state for: " + userJid + " = " + isCarbonEnabled);
}
catch (NoResponseException | InterruptedException | NotConnectedException
| XMPPException.XMPPErrorException e) {
logger.error("Failed to set carbon for: " + userJid + " to " + isCarbonEnabled, e);
}
}

I disabled two other working accounts, leaving only the newly IB-registered account; Still experience the same problem for the test account (see log). Checking on the stored properties in sql database for the newly IB-registered account, it has all the property correct settings as the working accounts; the account also login successfully with the server. Strange, received the correct response, still reported by CarbonManager as timeout. Need further investigation.

============= aTalk log with new enableDisableCarbon() method =================

06-07 08:12:02.520 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’>

06-07 08:12:02.520 D/SMACK: RECV (0): <?xml version='1.0'?><stream:stream id=‘16986692509373570944’ version=‘1.0’ xml:lang=‘en’ xmlns:stream=‘http://etherx.jabber.org/streams’ from=‘atalk.org’ xmlns=‘jabber:client’>

06-07 08:12:02.530 D/SMACK: RECV (0): stream:featuresSCRAM-SHA-1PLAINX-OAUTH2</stream:features>

06-07 08:12:02.530 D/SMACK: SENT (0):

06-07 08:12:02.540 D/SMACK: RECV (0):

06-07 08:12:02.610 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’>

06-07 08:12:02.610 D/SMACK: RECV (0): <?xml version='1.0'?><stream:stream id=‘292884885646378449’ version=‘1.0’ xml:lang=‘en’ xmlns:stream=‘http://etherx.jabber.org/streams’ from=‘atalk.org’ xmlns=‘jabber:client’>

06-07 08:12:02.610 D/SMACK: RECV (0): stream:featuresSCRAM-SHA-1PLAINX-OAUTH2</stream:features>

06-07 08:12:02.790 D/SMACK: SENT (0): biwsbj10ZXN0LHI9Y21pIn5vZmVHLWV0Ilh4U1lVTigoUyojdX5fQDV 9dVo=

06-07 08:12:02.800 D/SMACK: RECV (0): cj1jbWkifm9mZUctZXQiWHhTWVVOKChTKiN1fl 9ANX11WklqOU80bTVpK2phZHNlT2JrbjNvOWc9PSxzPUFlVHVURmQxMlV6anN4SjZkNy80RlE9PSxpPT QwOTY=

06-07 08:12:03.570 D/SMACK: SENT (0): Yz1iaXdzLHI9Y21pIn5vZmVHLWV0Ilh4U1lVTi goUyojdX5fQDV9dVpJajlPNG01aStqYWRzZU9ia24zbzlnPT0scD1wZjlxbUJNUi9uYzIxeUc4RmhJQm 9QbVRoMDg9

06-07 08:12:03.590 D/SMACK: RECV (0): dj1RelVUQmxsTzBRcUI4SmN6NE1nWmowdmpNdG M9

06-07 08:12:03.590 D/SMACK: SENT (0): <stream:stream xmlns=‘jabber:client’ to=‘atalk.org’ xmlns:stream=‘http://etherx.jabber.org/streams’ version=‘1.0’ id=‘292884885646378449’ xml:lang=‘en’>

06-07 08:12:03.600 D/SMACK: RECV (0): <?xml version='1.0'?><stream:stream id=‘12600408223121564971’ version=‘1.0’ xml:lang=‘en’ xmlns:stream=‘http://etherx.jabber.org/streams’ from=‘atalk.org’ xmlns=‘jabber:client’>

06-07 08:12:03.600 D/SMACK: RECV (0): stream:features</stream:features>

06-07 08:12:03.600 D/SMACK: SENT (0): atalk

06-07 08:12:03.690 D/SMACK: RECV (0): test@atalk.org/atalk

06-07 08:12:03.710 D/SMACK: SENT (0):

06-07 08:12:03.760 D/SMACK: RECV (0):

06-07 08:12:06.170 D/SMACK: SENT (0):

06-07 08:12:06.410 D/SMACK: RECV (2):

06-07 08:12:11.170 E/αTalk: [9] impl.protocol.jabber.OperationSetBasicInstantMessagingJabberImpl.enableDisableC arbon().680 Failed to set carbon for: test@atalk.org/atalk to false

                        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=c3YjH-75)), : fromFilter (OrFilter: (FromMatchesFilter (full): null, FromMatchesFilter (ignoreResourcepart): test@atalk.org, FromMatchesFilter (full): atalk.org)).

at org.jivesoftware.smack.StanzaCollector.nextResultOrThrow(StanzaCollector.java:2 53)

at org.jivesoftware.smack.StanzaCollector.nextResultOrThrow(StanzaCollector.java:2 08)

at org.jivesoftware.smackx.carbons.CarbonManager.setCarbonsEnabled(CarbonManager.j ava:309)

at net.java.sip.communicator.impl.protocol.jabber.OperationSetBasicInstantMessagin gJabberImpl.enableDisableCarbon(OperationSetBasicInstantMessagingJabberImpl.java :670)

at net.java.sip.communicator.impl.protocol.jabber.OperationSetBasicInstantMessagin gJabberImpl.initAdditionalServices(OperationSetBasicInstantMessagingJabberImpl.j ava:653)

at net.java.sip.communicator.impl.protocol.jabber.OperationSetBasicInstantMessagin gJabberImpl.access$700(OperationSetBasicInstantMessagingJabberImpl.java:50)

at net.java.sip.communicator.impl.protocol.jabber.OperationSetBasicInstantMessagin gJabberImpl$RegistrationStateListener$1.run(OperationSetBasicInstantMessagingJab berImpl.java:624)

at java.lang.Thread.run(Thread.java:818)

Thinking it may be due to the test account has been used repeatedly for testing and that has caused data non-sync between the client and server.

I decided to completely remove the test account from both the server and client; and created a new2@atalk.org for testing. I even restart the ejabberd server; but the problem remains. I even check the log on the ejabberd server, everything seems OK. However Smack on the client still reported failure due to response timeout.

Anybody has idea how to proceed from here to find the cause?

Note: Please ignore there is some system time dependency between the server and client as shown in the log messages timestamp. Client is about 1 min ahead of server.

========= ejabberd xmpp server log =====================

2017-06-07 10:56:16.029 [debug] <0.920.0>@ejabberd_receiver:process_data:287 ##### Received XML on stream = <<"">>

2017-06-07 10:56:16.046 [info] <0.689.0>@mod_carboncopy:iq_handler:114 ##### carbons enabled for user new2@atalk.org/atalk

2017-06-07 10:56:16.046 [debug] <0.689.0>@mod_carboncopy:enable:248 ##### enabling for <<“new2”>>

2017-06-07 10:56:16.046 [debug] <0.689.0>@mod_carboncopy:iq_handler:122 ##### carbons IQ result: ok

2017-06-07 10:56:16.046 [debug] <0.921.0>@ejabberd_socket:send:216 ##### (tls|<0.920.0>) Send XML on stream = <<"">>

========= atalk client log ==================

06-07 10:57:12.446 D/SMACK: SENT (0):

06-07 10:57:12.656 D/SMACK: RECV (0):

06-07 10:57:17.486 E/αTalk: [10] impl.protocol.jabber.OperationSetBasicInstantMessagingJabberImpl.enableDisableC arbon().680 Failed to set carbon for: new2@atalk.org/atalk to false

                        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=JaMF3-68)), : fromFilter (OrFilter: (FromMatchesFilter (full): null, FromMatchesFilter (ignoreResourcepart): new2@atalk.org, FromMatchesFilter (full): atalk.org)).

at org.jivesoftware.smack.StanzaCollector.nextResultOrThrow(StanzaCollector.java:2 53)

at org.jivesoftware.smack.StanzaCollector.nextResultOrThrow(StanzaCollector.java:2 08)

at org.jivesoftware.smackx.carbons.CarbonManager.setCarbonsEnabled(CarbonManager.j ava:309)

at net.java.sip.communicator.impl.protocol.jabber.OperationSetBasicInstantMessagin gJabberImpl.enableDisableCarbon(OperationSetBasicInstantMessagingJabberImpl.java :670)

at net.java.sip.communicator.impl.protocol.jabber.OperationSetBasicInstantMessagin gJabberImpl.initAdditionalServices(OperationSetBasicInstantMessagingJabberImpl.j ava:653)

at net.java.sip.communicator.impl.protocol.jabber.OperationSetBasicInstantMessagin gJabberImpl.access$700(OperationSetBasicInstantMessagingJabberImpl.java:50)

at net.java.sip.communicator.impl.protocol.jabber.OperationSetBasicInstantMessagin gJabberImpl$RegistrationStateListener$1.run(OperationSetBasicInstantMessagingJab berImpl.java:624)

at java.lang.Thread.run(Thread.java:818)

Try adding in an earlier account created on server to the client, everything is OK. However when an account is newly created on server and added into the shared roster as other earlier created accounts. The newly created account when added to the client has the same problem. Actually this happen on any new account added.

With further testing, I realize that it is not just the carbon feature that has problem, in fact all the responses received by smack lower layer (seems normal from the log messages) are not propagated to the Smack upper layer manager? and/or the application e.g. avatar, presence etc send from online contacts/server are not reflected on the client contact list avatar image and presence status. Very strange!!!

A bit lost what else can I try to pinpoint the cause. Any help is appreciated.

The root cause for the problem seeing in avatar retrieval and presence status update are actually due to an uncaught exception on a null object reference in VCardAvatarManager.downloadVCard().

After the above fixes. still seeing carbon enable timeout even a response is always received, and without any uncaught exception observed from the capture log. However occasionally carbon enable does work OK.

I performed a line-by-line and process flow comparison on two captured instances i.e. good and failed cases on carbon enabled. However I just cannot find any clue that leads to the failure. Since carbon is not a vital feature for aTalk application operation at this time, I will just leave the state as it and come back again later after implemented OMEMO for aTalk.

Below are the two log captured for the good and fail cases.

=========== aTalk log - good case ==================

06-08 14:48:37.489 D/SMACK: RECV (0):

06-08 14:48:37.519 D/SMACK: SENT (0):

06-08 14:48:37.649 D/SMACK: RECV (0): http://jabber.org/network/serverinfo

06-08 14:48:37.659 D/SMACK: SENT (0):

06-08 14:48:37.809 D/SMACK: RECV (0): <feature

06-08 14:48:37.829 D/SMACK: RECV (0): var=‘http://jabber.org/protocol/rsm’/>http://jabber.org/network/serverinfo

06-08 14:48:37.879 D/SMACK: SENT (0):

06-08 14:48:37.899 I/aTalk: [5] impl.protocol.jabber.ProtocolProviderServiceJabberImpl.authenticated().1402 Smack: User Authenticated-isResumed: false

06-08 14:48:37.899 D/aTalk: [5] service.protocol.AbstractProtocolProviderService.fireRegistrationStateChanged() .156 The provider changed state from: RegistrationState = Registered to: RegistrationState = Registered. Reason: Smack: User Authenticated-isResumed: false

06-08 14:48:37.899 D/aTalk: [5] service.protocol.AbstractProtocolProviderService.fireRegistrationStateChanged() .169 Dispatching RegistrationStateChangeEvent[ oldState=Registered; newState=RegistrationState = Registered; reasonCode=0; reason=Smack: User Authenticated-isResumed: false] to 16 listeners.

06-08 14:48:37.909 I/aTalk: [5] impl.protocol.jabber.InfoRetriever.retrieveDetails().143 Start loading VCard information for: newx@atalk.org

06-08 14:48:37.909 D/SMACK: SENT (0):

06-08 14:48:37.949 D/SMACK: RECV (0):

06-08 14:48:37.979 D/SMACK: RECV (0):

06-08 14:48:37.989 D/aTalk: [9] org.jivesoftware.smack.roster.Roster.processStanza() RosterResultListener received {}

06-08 14:48:37.999 I/aTalk: [5] org.jivesoftware.smackx.avatar.vcardavatar.packet.VCardTempXUpdate.setAvatarHas h() Account avatar hash updated with (old => new):

null

06-08 14:48:38.019 I/aTalk: [5] org.jivesoftware.smackx.avatar.vcardavatar.VCardAvatarManager.downloadVCard() Downloaded vcard info for: newx@atalk.org; Hash =

06-08 14:48:38.019 I/aTalk: [5] impl.protocol.jabber.InfoRetriever.retrieveDetails().325 Added retrievedDetails for: newx@atalk.org size: 0

06-08 14:48:38.029 D/aTalk: [5] impl.protocol.jabber.OperationSetMultiUserChatJabberImpl.registrationStateChang ed().692 adding an Invitation listener to the smack muc

06-08 14:48:38.039 D/aTalk: [5] impl.protocol.jabber.OperationSetTelephonyConferencingJabberImpl.registrationSt ateChanged().112 Subscribes to Coin packets

06-08 14:48:38.049 I/aTalk: [14] impl.protocol.jabber.OperationSetPersistentPresenceJabberImpl.publishPresenceSt atus().601 Smack: sending presence:available/

06-08 14:48:38.059 D/SMACK: SENT (0): 30

06-08 14:48:38.059 D/aTalk: [14] service.protocol.AbstractOperationSetPersistentPresence.fireProviderStatusChang eEvent().229 Dispatching Provider Status Change. Listeners=2 evt=ProviderPresenceStatusChangeEvent-[OldStatus=PresenceStatus:Offline, NewStatus=PresenceStatus:Available]

06-08 14:48:38.059 D/SMACK: SENT (0): 30

06-08 14:48:38.059 I/aTalk: [14] impl.msghistory.MessageSourceService.log() Handle new provider added and status changed to online: newx@atalk.org

06-08 14:48:38.069 V/aTalk: [15] org.atalk.impl.fileaccess.FileAccessServiceImpl.log() [entry] getPrivatePersistentFile

06-08 14:48:38.069 V/aTalk: [15] org.atalk.impl.fileaccess.FileAccessServiceImpl.log() [entry] accessibleFile

06-08 14:48:38.069 V/aTalk: [15] org.atalk.impl.fileaccess.FileAccessServiceImpl.log() [exit] accessibleFile

06-08 14:48:38.079 V/aTalk: [15] org.atalk.impl.fileaccess.FileAccessServiceImpl.log() [exit] getPrivatePersistentFile

06-08 14:48:38.079 I/aTalk: [16] impl.msghistory.MessageHistoryServiceImpl.findRecentMessagesPerContact().621 Find recent message for: Jabber:newx@atalk.org -> null

06-08 14:48:38.089 I/aTalk: [13] impl.protocol.jabber.OperationSetBasicInstantMessagingJabberImpl.enableDisableC arbon().669 Required new state for enableCarbon: true

06-08 14:48:38.089 D/aTalk: [5] org.atalk.impl.configuration.ConfigurationServiceImpl.log() Created an empty file in $HOME: /data/data/org.atalk.android/files/sip-communicator.xml

06-08 14:48:38.089 D/SMACK: SENT (0):

06-08 14:48:38.109 D/aTalk: [5] org.atalk.impl.configuration.ConfigurationServiceImpl.log() acc1496900806953.lastAccountStatus( oldValue=Available, newValue=Available.

06-08 14:48:38.119 D/aTalk: [14] service.protocol.AbstractOperationSetPersistentPresence.fireProviderStatusChang eEvent().236 status dispatching done.

06-08 14:48:38.139 D/aTalk: [5] util.account.LoginManager.registrationStateChanged().116 Protocol provider: ProtocolProviderServiceJabberImpl(newx@atalk.org (Jabber)) changes state to: Registered Reason: Smack: User Authenticated-isResumed: false

06-08 14:48:38.149 D/aTalk: [5] service.protocol.AbstractProtocolProviderService.fireRegistrationStateChanged() .190 Done.

06-08 14:48:38.149 D/SMACK: XMPPConnection authenticated (XMPPTCPConnection[newx@atalk.org/atalk] (0))

06-08 14:48:38.239 D/SMACK: RECV (0): 910ec77e99e8fbf80778932ef26902f5ebe650df</ph oto>30

06-08 14:48:38.269 D/SMACK: RECV (0): 30

06-08 14:48:38.269 D/SMACK: RECV (0):

06-08 14:48:38.279 D/SMACK: RECV (0):

06-08 14:48:38.279 D/SMACK: RECV (0): 30

06-08 14:48:38.279 D/SMACK: RECV (0):

06-08 14:48:38.299 D/aTalk: [17] impl.protocol.jabber.OperationSetPersistentPresenceJabberImpl.firePresenceStatu sChanged().1415 Received a status update for buddy = abc123@atalk.org/jitsi-1qtrd5k

06-08 14:48:38.309 D/aTalk: [17] impl.protocol.jabber.OperationSetPersistentPresenceJabberImpl.updateContactStat us().1267 Will Dispatch the contact status event.

06-08 14:48:38.309 D/aTalk: [18] impl.contactlist.MetaContactListServiceImpl.fireProtoContactEvent().2479 Will dispatch the following mcl property change event: net.java.sip.communicator.service.contactlist.event.ProtoContactEvent[source=Ja bberContact[ id=abc123@atalk.org, isPersistent=true, isResolved=true]]

06-08 14:48:38.319 I/aTalk: [13] impl.protocol.jabber.OperationSetBasicInstantMessagingJabberImpl.enableDisableC arbon().678 Successfully setting carbon new state for: newx@atalk.org/atalk to true

06-08 14:48:38.329 D/aTalk: [17] service.protocol.AbstractOperationSetPersistentPresence.fireContactPresenceStat usChangeEvent().161 Dispatching Contact Status Change. Listeners=4 evt=ContactPresenceStatusChangeEvent-[ ContactID=abc123@atalk.org, ParentGroupatalk member, OldStatus=PresenceStatus:Offline, NewStatus=PresenceStatus:Available]

06-08 14:48:38.329 D/aTalk: [1] org.atalk.android.gui.contactlist.model.MetaContactListAdapter.log() Contact presence status changed: abc123@atalk.org

06-08 14:48:38.339 D/aTalk: [18] org.atalk.android.gui.contactlist.model.MetaContactListAdapter.log() PROTO CONTACT MODIFIED: abc123@atalk.org

=========== aTalk log - good case ==================

06-08 14:53:08.309 D/SMACK: RECV (0):

06-08 14:53:08.319 D/SMACK: SENT (0):

06-08 14:53:08.489 D/SMACK: RECV (0): http://jabber.org/network/serverinfo

06-08 14:53:08.499 D/SMACK: SENT (0):

06-08 14:53:08.629 D/SMACK: RECV (0): <feature v

06-08 14:53:08.639 D/SMACK: RECV (0): ar=‘http://jabber.org/protocol/rsm’/>http://jabber.org/network/serverinfo

06-08 14:53:08.679 D/SMACK: SENT (0):

06-08 14:53:08.689 I/aTalk: [4] impl.protocol.jabber.ProtocolProviderServiceJabberImpl.authenticated().1402 Smack: User Authenticated-isResumed: false

06-08 14:53:08.689 D/aTalk: [4] service.protocol.AbstractProtocolProviderService.fireRegistrationStateChanged() .156 The provider changed state from: RegistrationState = Registered to: RegistrationState = Registered. Reason: Smack: User Authenticated-isResumed: false

06-08 14:53:08.689 D/aTalk: [4] service.protocol.AbstractProtocolProviderService.fireRegistrationStateChanged() .169 Dispatching RegistrationStateChangeEvent[ oldState=Registered; newState=RegistrationState = Registered; reasonCode=0; reason=Smack: User Authenticated-isResumed: false] to 16 listeners.

06-08 14:53:08.699 I/aTalk: [4] impl.protocol.jabber.InfoRetriever.retrieveDetails().143 Start loading VCard information for: newx@atalk.org

06-08 14:53:08.699 D/SMACK: SENT (0):

06-08 14:53:08.779 D/SMACK: RECV (0):

06-08 14:53:08.779 D/SMACK: RECV (0):

06-08 14:53:08.789 D/aTalk: [12] org.jivesoftware.smack.roster.Roster.processStanza() RosterResultListener received {}

06-08 14:53:08.789 I/aTalk: [4] org.jivesoftware.smackx.avatar.vcardavatar.packet.VCardTempXUpdate.setAvatarHas h() Account avatar hash updated with (old => new):

null

06-08 14:53:08.799 I/aTalk: [4] org.jivesoftware.smackx.avatar.vcardavatar.VCardAvatarManager.downloadVCard() Downloaded vcard info for: newx@atalk.org; Hash =

06-08 14:53:08.799 I/aTalk: [4] impl.protocol.jabber.InfoRetriever.retrieveDetails().325 Added retrievedDetails for: newx@atalk.org size: 0

06-08 14:53:08.819 D/aTalk: [4] impl.protocol.jabber.OperationSetMultiUserChatJabberImpl.registrationStateChang ed().692 adding an Invitation listener to the smack muc

06-08 14:53:08.829 D/aTalk: [4] impl.protocol.jabber.OperationSetTelephonyConferencingJabberImpl.registrationSt ateChanged().112 Subscribes to Coin packets

06-08 14:53:08.859 I/aTalk: [15] impl.protocol.jabber.OperationSetPersistentPresenceJabberImpl.publishPresenceSt atus().601 Smack: sending presence:available/

06-08 14:53:08.969 D/aTalk: [15] service.protocol.AbstractOperationSetPersistentPresence.fireProviderStatusChang eEvent().236 status dispatching done.

06-08 14:53:08.869 D/SMACK: SENT (0): 30

06-08 14:53:08.879 I/aTalk: [15] impl.msghistory.MessageSourceService.log() Handle new provider added and status changed to online: newx@atalk.org

06-08 14:53:08.849 V/aTalk: [14] org.atalk.impl.fileaccess.FileAccessServiceImpl.log() [entry] getPrivatePersistentFile

06-08 14:53:08.859 V/aTalk: [14] org.atalk.impl.fileaccess.FileAccessServiceImpl.log() [exit] accessibleFile

06-08 14:53:08.849 V/aTalk: [14] org.atalk.impl.fileaccess.FileAccessServiceImpl.log() [entry] accessibleFile

06-08 14:53:08.869 V/aTalk: [14] org.atalk.impl.fileaccess.FileAccessServiceImpl.log() [exit] getPrivatePersistentFile

06-08 14:53:08.899 I/aTalk: [16] impl.msghistory.MessageHistoryServiceImpl.findRecentMessagesPerContact().621 Find recent message for: Jabber:newx@atalk.org -> null

06-08 14:53:08.879 I/aTalk: [13] impl.protocol.jabber.OperationSetBasicInstantMessagingJabberImpl.enableDisableC arbon().669 Required new state for enableCarbon: true

06-08 14:53:08.889 D/aTalk: [4] org.atalk.impl.configuration.ConfigurationServiceImpl.log() Created an empty file in $HOME: /data/data/org.atalk.android/files/sip-communicator.xml

06-08 14:53:08.889 D/SMACK: SENT (0):

06-08 14:48:38.109 D/aTalk: [5] org.atalk.impl.configuration.ConfigurationServiceImpl.log() acc1496900806953.lastAccountStatus( oldValue=Available, newValue=Available.

06-08 14:48:38.119 D/aTalk: [14] service.protocol.AbstractOperationSetPersistentPresence.fireProviderStatusChang eEvent().236 status dispatching done.

06-08 14:53:08.939 D/aTalk: [4] util.account.LoginManager.registrationStateChanged().116 Protocol provider: ProtocolProviderServiceJabberImpl(newx@atalk.org (Jabber)) changes state to: Registered Reason: Smack: User Authenticated-isResumed: false

06-08 14:53:08.989 D/aTalk: [4] service.protocol.AbstractProtocolProviderService.fireRegistrationStateChanged() .190 Done.

06-08 14:53:08.989 D/SMACK: XMPPConnection authenticated (XMPPTCPConnection[newx@atalk.org/atalk] (0))

06-08 14:53:09.059 D/SMACK: RECV (0): 910ec77e99e8fbf80778932ef26902f5ebe650df</ph oto>30

06-08 14:53:09.079 D/SMACK: RECV (0): 30

06-08 14:53:09.079 D/SMACK: RECV (0):

06-08 14:53:09.089 D/aTalk: [17] impl.protocol.jabber.OperationSetPersistentPresenceJabberImpl.firePresenceStatu sChanged().1415 Received a status update for buddy = abc123@atalk.org/jitsi-1qtrd5k

06-08 14:53:09.089 D/aTalk: [17] impl.protocol.jabber.OperationSetPersistentPresenceJabberImpl.updateContactStat us().1267 Will Dispatch the contact status event.

06-08 14:53:09.089 D/aTalk: [12] impl.contactlist.MetaContactListServiceImpl.fireProtoContactEvent().2479 Will dispatch the following mcl property change event: net.java.sip.communicator.service.contactlist.event.ProtoContactEvent[source=Ja bberContact[ id=abc123@atalk.org, isPersistent=true, isResolved=true]]

06-08 14:53:09.089 D/aTalk: [17] service.protocol.AbstractOperationSetPersistentPresence.fireContactPresenceStat usChangeEvent().161 Dispatching Contact Status Change. Listeners=4 evt=ContactPresenceStatusChangeEvent-[ ContactID=abc123@atalk.org, ParentGroupatalk member, OldStatus=PresenceStatus:Offline, NewStatus=PresenceStatus:Available]

06-08 14:53:09.099 D/aTalk: [1] org.atalk.android.gui.contactlist.model.MetaContactListAdapter.log() Contact presence status changed: abc123@atalk.org

06-08 14:53:09.099 D/aTalk: [12] org.atalk.android.gui.contactlist.model.MetaContactListAdapter.log() PROTO CONTACT MODIFIED: abc123@atalk.org

06-08 14:53:13.899 E/aTalk: [13] impl.protocol.jabber.OperationSetBasicInstantMessagingJabberImpl.enableDisableC arbon().683 Failed to set carbon state for: newx@atalk.org/atalk to true

                        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=QAucJ-101)), : fromFilter (OrFilter: (FromMatchesFilter (full): null, FromMatchesFilter (ignoreResourcepart): newx@atalk.org, FromMatchesFilter (full): atalk.org)).

at org.jivesoftware.smack.StanzaCollector.nextResultOrThrow(StanzaCollector.java:2 53)

at org.jivesoftware.smack.StanzaCollector.nextResultOrThrow(StanzaCollector.java:2 08)

at org.jivesoftware.smackx.carbons.CarbonManager.setCarbonsEnabled(CarbonManager.j ava:309)

at net.java.sip.communicator.impl.protocol.jabber.OperationSetBasicInstantMessagin gJabberImpl.enableDisableCarbon(OperationSetBasicInstantMessagingJabberImpl.java :672)

at net.java.sip.communicator.impl.protocol.jabber.OperationSetBasicInstantMessagin gJabberImpl.initAdditionalServices(OperationSetBasicInstantMessagingJabberImpl.j ava:654)

at net.java.sip.communicator.impl.protocol.jabber.OperationSetBasicInstantMessagin gJabberImpl.access$700(OperationSetBasicInstantMessagingJabberImpl.java:50)

at net.java.sip.communicator.impl.protocol.jabber.OperationSetBasicInstantMessagin gJabberImpl$RegistrationStateListener$1.run(OperationSetBasicInstantMessagingJab berImpl.java:625)

at java.lang.Thread.run(Thread.java:818)