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)