onChannelJoined called with unsynchronized channel

ajitdubey-mob-ibtech commented 7 years ago

I am using "com.twilio:chat-android:1.0.8" version. Create channel by using below process: Scenario A: Step1-(Android App)User A make request to application server for creating a channel(Name is Hello) and server create channel(Name is Hello) by using below code:

Twilio.init(externalCredential.getProperty(TwilioConstants.TWILIO_ACCOUNT_SID_KEY), externalCredential.getProperty(TwilioConstants.TWILIO_AUTH_TOKEN_KEY)); ChannelCreator channelCreator = Channel.creator(externalCredential.getProperty(TwilioConstants.TWILIO_SERVICE_SID_KEY)); channelCreator.setFriendlyName(friendlyName); channelCreator.setUniqueName(uniqueName); channelCreator.setType(ChannelType.PRIVATE); Channel channel = channelCreator.create(); return channel.getSid();

Step2-application server added user A into channel by using below code:

Twilio.init(externalCredential.getProperty(TwilioConstants.TWILIO_ACCOUNT_SID_KEY), externalCredential.getProperty(TwilioConstants.TWILIO_AUTH_TOKEN_KEY));
MemberCreator memberCreator = Member.creator(externalCredential.getProperty(TwilioConstants.TWILIO_SERVICE_SID_KEY), channelSId, memberId); Member member = memberCreator.create(); return member.getSid();

Step3: Now user A received onChannelJoined(Channel channel) method. Some time found blank channel friendly and unique name. When I log friendly name and unique name both are blank.

08-03 16:53:13.269 5638-5638/com.xx.xxD/ChatClientManager: onChannelJoined ===== 08-03 16:53:13.269 5638-5638/com.xx.xxD/ChatClientManager: Unique Name= 08-03 16:53:13.269 5638-5638/com.xx.xxD/ChatClientManager: getFriendlyName =

Even in iOS same steps we are following (void)chatClient:(TwilioChatClient )client channelAdded:(TCHChannel )channel get called with unique name and friendly name.

Scenario B:

Step1- User A make a request to application server for adding user B in Channel(Hello), server adding member by using below code:

Twilio.init(externalCredential.getProperty(TwilioConstants.TWILIO_ACCOUNT_SID_KEY), externalCredential.getProperty(TwilioConstants.TWILIO_AUTH_TOKEN_KEY));
MemberCreator memberCreator = Member.creator(externalCredential.getProperty(TwilioConstants.TWILIO_SERVICE_SID_KEY), channelSId, memberId); Member member = memberCreator.create(); return member.getSid();

Step2: User B received callback onChannelJoined(Channel channel) some time found blank friendly and unique name.

In previous version It was working fine. Programmable chat 0.12.1 version we were following same process at that time onChannelAdd(Channel channel) get called with all value.

Kindly look into that, is there any issues or I missed some thing. Quick response would appreciable.

Thanks

ajitdubey-mob-ibtech commented 7 years ago

Gentle Reminder

berkus commented 7 years ago

The non-blank values are available in onJoined/onAdded callbacks if you use the SDK version 1.0.9 (released July 25 - https://www.twilio.com/docs/api/chat/changelogs/android).

If you insist on using SDK 1.0.8 then you will have to wait for full channel synchronization before printing any values.

onChannelJoined instead of onChannelAdded is a minor fix, more closely following chat service status changed.

ajitdubey-mob-ibtech commented 7 years ago

@berkus Thanks I will check with updated version and confirm you.

ajitdubey-mob-ibtech commented 7 years ago

@berkus Now I m using 1.0.9 still getting the same blank values:

08-23 16:46:44.974 4851-4851/com.xxx.xxxD/ChatClientManager: Received onSynchronizationChanged callback 08-23 16:46:44.982 4851-4851/com.xxx.xxx D/ChatClientManager: onChannelJoined() ===== 08-23 16:46:44.983 4851-4851/com.xxx.xxx D/ChatClientManager: Unique Name= 08-23 16:46:44.983 4851-4851/com.xxx .xxx D/ChatClientManager: getFriendlyName = 08-23 16:46:44.984 4851-4851/com.xxx .xxx D/ChatClientManager: Received onSynchronizationChanged callback

Thanks,

berkus commented 7 years ago

Could you print the actual synchronisation status in your "onSynchronizationChanged callback" please?

ajitdubey-mob-ibtech commented 7 years ago

Actual synchronization status is:

08-23 18:45:19.923 20607-20607/com.xxx.xxxD/ChatClientManager: onChannelJoined() ===== 08-23 18:45:19.924 20607-20607/com.xxx.xxxD/ChatClientManager: Unique Name= 08-23 18:45:19.925 20607-20607/com.xxx.xxxD/ChatClientManager: getFriendlyName = 08-23 18:45:19.927 20607-20607/com.xxx.xxxD/ChatClientManager: Received onSynchronizationChanged callback "Status"=IDENTIFIER

berkus commented 7 years ago

And what about the previous one here?

08-23 16:46:44.974 4851-4851/com.xxx.xxxD/ChatClientManager: Received onSynchronizationChanged callback 08-23 16:46:44.982 4851-4851/com.xxx.xxx D/ChatClientManager: onChannelJoined() =====

ajitdubey-mob-ibtech commented 7 years ago

@berkus Same status print in previous one. 1. I don't know why some time onSynchronizationChanged get called before onChannelJoined() and two time onSynchronizationChanged get called after onChannelJoined(). 2. Some time first onChannelJoined() get called after that onSynchronizationChanged get called three times.

Now I print the friendly name in onSynchronizationChanged:

08-24 10:10:20.102 21996-21996/com.xxx.xxxD/ChatClientManager: onChannelJoined() ===== 08-24 10:10:20.102 21996-21996/com.xxx.xxxD/ChatClientManager: Unique Name= 08-24 10:10:20.102 21996-21996/com.xxx.xxxD/ChatClientManager: getFriendlyName = 08-24 10:10:20.102 21996-21996/com.xxx.xxxD/ChatClientManager: Received onSynchronizationChanged callback getFriendlyName =Test Group Status=IDENTIFIER 08-24 10:10:20.104 21996-21996/com.xxx.xxxD/ChatClientManager: Received onSynchronizationChanged callback getFriendlyName =Test Group Status=IDENTIFIER 08-24 10:10:20.843 21996-21996/com.xxx.xxxD/ChatClientManager: Received onSynchronizationChanged callback getFriendlyName =Test Group Status=ALL

I am trying to reproduce again and again and also keep observation in different network .

berkus commented 7 years ago

Interesting, please save full adb logs from the sessions - see https://github.com/twilio/twilio-chat-demo-android/blob/master/REPORT_BUGS.md for details - this will help us fix it. I'll open a ticket so we can investigate.

ajitdubey-mob-ibtech commented 7 years ago

@berkus Here is the captured log details:

09-07 12:25:20.419 10800-22840/com.xxx.xxx V/FA: Inactivity, disconnecting from the service
09-07 12:25:21.053 10800-10800/com.xxx.xxx D/Group Create req=: {"groupProfile":{"name":"Hello Gp","numberSelectionType":"AUTOMATIC","planType":"SHARED","requestId":375940439,"type":"PUBLIC","users":[363571660177014784]}}
09-07 12:25:21.075 10800-22910/com.xxx.xxx D/Netowrk Class: http://xxx.ngrok.io/gp-server/r/group/create
09-07 12:25:21.076 10800-22910/com.xxx.xxx D/aaa: application/json
09-07 12:25:21.076 10800-22910/com.xxx.xxx D/aaa: ecf5dc56f0ca8ec8c79feafbc49c103799376e44e1856b099a79feb60a9066d5
09-07 12:25:23.839 10800-10916/com.xxx.xxx D/TWC: TNWebsocket:        -2022426336 | 09/07/12:25:23.839 | DEBUG    | 6      | TNWebsocket | Receive message 937 bytes
09-07 12:25:23.839 10800-10916/com.xxx.xxx D/TWC: TNTwilsockClient:        -2022426336 | 09/07/12:25:23.839 | DEBUG    | 1      | TNTwilsockClient | onMessageReceived (937)
                                                                               TWILSOCK V3.0 195
                                                                               {"method":"notification","id":"TMdd24ff7a90a848d6a6155759c4a09bfc","payload_size":719,"payload_type":"application/json","message_type":"com.twilio.rtd.cds.map","notification_ctx_id":"dummyCtxId"}
                                                                               {"event_type":"map_item_added","event_protocol_version":3,"event":{"item_revision":"9","map_unique_name":"363675893287092224.channels","date_created":"2017-09-07T06:55:23.717Z","item_url":"https://cds.us1.twilio.com/v3/Services/ISffd15149604d4fae9f428b3571357590/Maps/MP621bd58507b24f94aacbb9032447cd5d/Items/CH3d5166a534ba4cee9f44434257d936d5","item_key":"CH3d5166a534ba4cee9f44434257d936d5","map_revision":"a","id":9,"map_sid":"MP621bd58507b24f94aacbb9032447cd5d","item_data":{"channelUrl":"https://cds.us1.twilio.com/v2/Services/ISffd15149604d4fae9f428b3571357590/Entities/ETf00ea96f12214a50a554a95a2a12891d","lastConsumedMessageIndex":null,"channel":"CH3d5166a534ba4cee9f44434257d936d5.channel","st
09-07 12:25:23.839 10800-10916/com.xxx.xxx I/TWC: TNTwilsockClient:        -2022426336 | 09/07/12:25:23.839 | INFO     | 1      | TNTwilsockClient | onMessageReceived, method = 4, id = TMdd24ff7a90a848d6a6155759c4a09bfc
09-07 12:25:23.839 10800-10916/com.xxx.xxx D/TWC: TNTwilsockClientImpl:        -2022426336 | 09/07/12:25:23.839 | DEBUG    | 2      | TNTwilsockClientImpl | proceedNotificationMessage TMdd24ff7a90a848d6a6155759c4a09bfc
09-07 12:25:23.840 10800-10916/com.xxx.xxx D/TWC: TNNotificationMgr:        -2022426336 | 09/07/12:25:23.840 | DEBUG    | 15     | TNNotificationMgr | virtual void rtd::TNNotificationMgr::ReceivedTargetedNotification(const rtd::TNBindingType&, const TNMessageType&, const ITNPayloadPtr&) type='twilsock', messageType='com.twilio.rtd.cds.map'
09-07 12:25:23.840 10800-10917/com.xxx.xxx D/TWC: Notification queue worker:        -2023470816 | 09/07/12:25:23.840 | DEBUG    | 17     | Notification queue worker | void rtd::Worker::route(const rtd::TNBindingType&, const TNMessageType&, const ITNPayloadPtr&) 'com.twilio.rtd.cds.map', channel: twilsock
09-07 12:25:23.840 10800-10899/com.xxx.xxx I/TWC: TNTwilsockClient:        -1968629472 | 09/07/12:25:23.840 | INFO     | 1      | TNTwilsockClient | sendSuccessReplyImpl >> Connected
09-07 12:25:23.840 10800-10899/com.xxx.xxx D/TWC: TNTwilsockClientImpl:        -1968629472 | 09/07/12:25:23.840 | DEBUG    | 2      | TNTwilsockClientImpl | sendSuccessReply
09-07 12:25:23.840 10800-10917/com.xxx.xxx I/TWC: Router:        -2023470816 | 09/07/12:25:23.840 | INFO     | 0      | Router | Message with type 'com.twilio.rtd.cds.map, from channel: twilsock' is being routed to 1 targets
09-07 12:25:23.840 10800-10899/com.xxx.xxx I/TWC: TNTwilsockClientImpl:        -1968629472 | 09/07/12:25:23.840 | INFO     | 2      | TNTwilsockClientImpl | sendSuccessReply, id = TMdd24ff7a90a848d6a6155759c4a09bfc
09-07 12:25:23.841 10800-10917/com.xxx.xxx D/TWC: IPM:        -2023470816 | 09/07/12:25:23.841 | DEBUG    | IPM | channels: item {CH3d5166a534ba4cee9f44434257d936d5} added MP621bd58507b24f94aacbb9032447cd5d
09-07 12:25:23.841 10800-10918/com.xxx.xxx D/TWC: TNWebsocket:        -2024515296 | 09/07/12:25:23.841 | DEBUG    | 6      | TNWebsocket | Sending frame via websocket (116)
                                                                          TWILSOCK V3.0 96
                                                                          {"id":"TMdd24ff7a90a848d6a6155759c4a09bfc","method":"reply","status":{"code":200,"status":"ok"}}
09-07 12:25:23.841 10800-10917/com.xxx.xxx D/TWC: IPM:        -2023470816 | 09/07/12:25:23.841 | DEBUG    | IPM | [TRvWI] inserted new channel to cache CH3d5166a534ba4cee9f44434257d936d5
09-07 12:25:23.841 10800-10917/com.xxx.xxx D/TWC: IPM:        -2023470816 | 09/07/12:25:23.841 | DEBUG    | IPM | [listener] on channel updated CH3d5166a534ba4cee9f44434257d936d5 1
09-07 12:25:23.842 10800-10917/com.xxx.xxx D/TWC: IPM:        -2023470816 | 09/07/12:25:23.842 | DEBUG    | IPM | [TRvWI] channel: set horizon index internally -1
09-07 12:25:23.842 10800-10917/com.xxx.xxx D/TWC: IPM:        -2023470816 | 09/07/12:25:23.842 | DEBUG    | IPM | [TRvWI] channel: initialize with status joined
09-07 12:25:23.842 10800-23569/com.xxx.xxx D/TWC: ChatClientListener(native):        -2109859552 | 09/07/12:25:23.842 | DEBUG    | ChatClientListener(native) | onChannelUpdated
09-07 12:25:23.842 10800-10917/com.xxx.xxx I/TWC: SyncDocument:        -2023470816 | 09/07/12:25:23.842 | INFO     | 94     | SyncDocument | constructed
09-07 12:25:23.842 10800-10917/com.xxx.xxx I/TWC: SyncDocument:        -2023470816 | 09/07/12:25:23.842 | INFO     | 94     | SyncDocument | Open: CH3d5166a534ba4cee9f44434257d936d5.channel
09-07 12:25:23.843 10800-10917/com.xxx.xxx I/TWC: TSDocumentOpenActivity:        -2023470816 | 09/07/12:25:23.842 | INFO     | 95     | TSDocumentOpenActivity | constructed
09-07 12:25:23.843 10800-10917/com.xxx.xxx I/TWC: TSDocumentOpenActivity:        -2023470816 | 09/07/12:25:23.843 | INFO     | 95     | TSDocumentOpenActivity | start 40
09-07 12:25:23.843 10800-10917/com.xxx.xxx I/TWC: SyncDocument:        -2023470816 | 09/07/12:25:23.843 | INFO     | 94     | SyncDocument | open (2) action id: 40 id: CH3d5166a534ba4cee9f44434257d936d5.channel
09-07 12:25:23.844 10800-10917/com.xxx.xxx D/TWC: IPM:        -2023470816 | 09/07/12:25:23.844 | DEBUG    | IPM | [TRvWI] channel: StateChannelNotInitialized->StateChannelInitializing
09-07 12:25:23.844 10800-23569/com.xxx.xxx D/TWC: EntityCache:        -2109859552 | 09/07/12:25:23.843 | DEBUG    | EntityCache | Creating new Java object
09-07 12:25:23.844 10800-23569/com.xxx.xxx D/jni_mate: Got method ID 0x89c26a80 for method <init>(J)V
09-07 12:25:23.844 10800-23569/com.xxx.xxx D/TWC: ChatClientListener(native):        -2109859552 | 09/07/12:25:23.844 | DEBUG    | ChatClientListener(native) | onChannelUpdated - channel sync
09-07 12:25:23.844 10800-10909/com.xxx.xxx I/TWC: TSDocumentOpenActivity:        -2015114976 | 09/07/12:25:23.844 | INFO     | 95     | TSDocumentOpenActivity | query [1] /v3/Documents/CH3d5166a534ba4cee9f44434257d936d5.channel
09-07 12:25:23.844 10800-10909/com.xxx.xxx I/TWC: TNHttpTransportClient:        -2015114976 | 09/07/12:25:23.844 | INFO     | 12     | TNHttpTransportClient | trying to send request to: https://cds.us1.twilio.com/v3/Documents/CH3d5166a534ba4cee9f44434257d936d5.channel
09-07 12:25:23.844 10800-10909/com.xxx.xxx D/TWC: TNHttpTransportClient:        -2015114976 | 09/07/12:25:23.844 | DEBUG    | 12     | TNHttpTransportClient | Host: cds.us1.twilio.com, path: /v3/Documents/CH3d5166a534ba4cee9f44434257d936d5.channel
09-07 12:25:23.846 10800-23569/com.xxx.xxx D/ClientInternalListener: onSynchronizationChanged channel CH3d5166a534ba4cee9f44434257d936d5|188057969
09-07 12:25:23.847 10800-10917/com.xxx.xxx D/TWC: IPM:        -2023470816 | 09/07/12:25:23.847 | DEBUG    | IPM | user channel CH3d5166a534ba4cee9f44434257d936d5 notifying 1
09-07 12:25:23.847 10800-10917/com.xxx.xxx D/TWC: IPM:        -2023470816 | 09/07/12:25:23.847 | DEBUG    | IPM | [listener] on channel added CH3d5166a534ba4cee9f44434257d936d5 1
09-07 12:25:23.847 10800-10917/com.xxx.xxx D/TWC: IPM:        -2023470816 | 09/07/12:25:23.847 | DEBUG    | IPM | user channels: item {CH3d5166a534ba4cee9f44434257d936d5} added done
09-07 12:25:23.848 10800-23572/com.xxx.xxx D/TWC: ChatClientListener(native):        -2111948512 | 09/07/12:25:23.848 | DEBUG    | ChatClientListener(native) | onChannelAdded
09-07 12:25:23.848 10800-23572/com.xxx.xxx D/TWC: EntityCache:        -2111948512 | 09/07/12:25:23.848 | DEBUG    | EntityCache | Returning Java object from cache
09-07 12:25:23.849 10800-23572/com.xxx.xxx D/TWC: ChatClientListener(native):        -2111948512 | 09/07/12:25:23.849 | DEBUG    | ChatClientListener(native) | onChannelAdded - joined
09-07 12:25:23.849 10800-23572/com.xxx.xxx D/ClientInternalListener: onChannelJoined sid|CH3d5166a534ba4cee9f44434257d936d5| 188057969
09-07 12:25:23.849 10800-10800/com.xxx.xxx D/ChatClientManager: onChannelJoined() =====
09-07 12:25:23.850 10800-10800/com.xxx.xxx D/TWC: IPM:        -1458584268 | 09/07/12:25:23.850 | DEBUG    | IPM | [TRvWI] channel: [api] get uniquename ()
09-07 12:25:23.850 10800-10800/com.xxx.xxx D/ChatClientManager: Unique Name=
09-07 12:25:23.850 10800-10800/com.xxx.xxx D/TWC: IPM:        -1458584268 | 09/07/12:25:23.850 | DEBUG    | IPM | [TRvWI] channel: [api] get friendlyname ()
09-07 12:25:23.850 10800-10800/com.xxx.xxx D/ChatClientManager: getFriendlyName =
09-07 12:25:23.850 10800-10800/com.xxx.xxx D/TWC: IPM:        -1458584268 | 09/07/12:25:23.850 | DEBUG    | IPM | [TRvWI] channel: [api] get friendlyname ()
09-07 12:25:23.850 10800-10800/com.xxx.xxx D/TWC: Channel(native):        -1458584268 | 09/07/12:25:23.850 | DEBUG    | Channel(native) | getSynchronizationStatus for channel sid|CH3d5166a534ba4cee9f44434257d936d5|
09-07 12:25:23.851 10800-10800/com.xxx.xxx D/ChatClientManager: Received onSynchronizationChanged callback getFriendlyName =
                                                                           Status=IDENTIFIER
09-07 12:25:23.851 10800-10800/com.xxx.xxx D/TWC: IPM:        -1458584268 | 09/07/12:25:23.851 | DEBUG    | IPM | [TRvWI] channel: [api] get uniquename ()
09-07 12:25:23.854 10800-10909/com.xxx.xxx D/TWC: TNTwilsockClient:        -2015114976 | 09/07/12:25:23.854 | DEBUG    | 1      | TNTwilsockClient | sendHttpMessage b5d87fe7a4074507ae6d62a5f06e7dee7dee
09-07 12:25:23.854 10800-10899/com.xxx.xxx I/TWC: TNTwilsockClient:        -1968629472 | 09/07/12:25:23.854 | INFO     | 1      | TNTwilsockClient | sendMessageImpl >> Connected b5d87fe7a4074507ae6d62a5f06e7dee7dee
09-07 12:25:23.854 10800-10909/com.xxx.xxx D/TWC: TNHttpTransportClient:        -2015114976 | 09/07/12:25:23.854 | DEBUG    | 12     | TNHttpTransportClient | id: b5d87fe7a4074507ae6d62a5f06e7dee7dee
09-07 12:25:23.854 10800-10899/com.xxx.xxx D/TWC: TNTwilsockClientImpl:        -1968629472 | 09/07/12:25:23.854 | DEBUG    | 2      | TNTwilsockClientImpl | sendMessageMessage
09-07 12:25:23.854 10800-10899/com.xxx.xxx I/TWC: TNTwilsockClientImpl:        -1968629472 | 09/07/12:25:23.854 | INFO     | 2      | TNTwilsockClientImpl | sendMessageMessage, id = b5d87fe7a4074507ae6d62a5f06e7dee7dee - present
09-07 12:25:23.855 10800-10918/com.xxx.xxx D/TWC: TNWebsocket:        -2024515296 | 09/07/12:25:23.855 | DEBUG    | 6      | TNWebsocket | Sending frame via websocket (1725)
                                                                          TWILSOCK V3.0 1701
                                                                          {"http_request":{"headers":{"Content-Length":"0","Content-Type":"application/json; charset=utf-8","Twilio-Sync-Client-Info":"{\"os\":\"Linux\",\"osVer\":\"3.18.31-perf-gb2364c0\",\"pl\":\"armv7l\",\"plVer\":\"4.15.0\",\"sdk\":\"cpp\",\"sdkVer\":\"4.15.0\"}","X-Twilio-Product-Id":"ip_messaging","X-Twilio-Token":"eyJjdHkiOiJ0d2lsaW8tZnBhO3Y9MSIsInR5cCI6IkpXVCIsImFsZyI6IkhTMjU2In0.eyJpc3MiOiJTSzBkZTI0NjlmYTVjZGRiODdiMTA4NzY4YmM5NzZlMzNmIiwiZXhwIjoxNTA0ODUyMjgwLCJncmFudHMiOnsiaWRlbnRpdHkiOiIzNjM2NzU4OTMyODcwOTIyMjQiLCJpcF9tZXNzYWdpbmciOnsic2VydmljZV9zaWQiOiJJU2ZmZDE1MTQ5NjA0ZDRmYWU5ZjQyOGIzNTcxMzU3NTkwIiwiZGVwbG95bWVudF9yb2xlX3NpZCI6bnVsbCwiZW5kcG9pbnRfaWQiOiJmb25lYXBwaXBtZXNzYWdpbmc6MzYzNjc1ODkzMjg3MDkyMjI0OmQySGNfZHVIbTVRIiwicHVzaF9jcmVkZW50aWFsX3NpZCI6IkNSMzIxOGNmNmQwOWU3YzdhZjQwOTMxYTk2OWU1MzFkY2MifX0sImp0aSI6IlNLMGRlMjQ2OWZhNWNkZGI4N2IxMDg3NjhiYzk3NmUzM2YtMTUwNDc2NTk1MiIsInN1YiI
09-07 12:25:23.929 10800-23579/com.xxx.xxx D/FirebaseMessagingListenerService: Received onMessageReceived()
09-07 12:25:23.931 10800-23579/com.xxx.xxx D/FirebaseMessagingListenerService: Bundle data: {channel_id=CH3d5166a534ba4cee9f44434257d936d5, adding_user=system, twi_message_type=twilio.channel.added_to_channel, channel_sid=CH3d5166a534ba4cee9f44434257d936d5, twi_message_id=RU905f5a1d6ac44db399f4c1dea68058d7, twi_body=You have been added to group 366478661890605056 by system, channel_title=366478661890605056}
09-07 12:25:23.931 10800-23579/com.xxx.xxx D/FirebaseMessagingListenerService: From: 8978840199
09-07 12:25:23.932 10800-23579/com.xxx.xxx D/TWC: TNNotificationMgr:        -2108815072 | 09/07/12:25:23.932 | DEBUG    | 15     | TNNotificationMgr | virtual void rtd::TNNotificationMgr::ReceivedNotification(const rtd::TNBindingType&, const TNRawMessage&) type='gcm'
09-07 12:25:23.936 10800-10917/com.xxx.xxx D/TWC: Notification queue worker:        -2023470816 | 09/07/12:25:23.936 | DEBUG    | 17     | Notification queue worker | void rtd::Worker::parseAndRoute(const rtd::TNBindingType&, const TNRawMessage&) '{"channel_id":"CH3d5166a534ba4cee9f44434257d936d5","message_id":"","author":"","message_sid":"","twi_sound":"","twi_message_type":"twilio.channel.added_to_channel","channel_sid":"CH3d5166a534ba4cee9f44434257d936d5","twi_message_id":"RU905f5a1d6ac44db399f4c1dea68058d7","twi_body":"You have been added to group 366478661890605056 by system","channel_title":"366478661890605056"}', channel: gcm
09-07 12:25:23.936 10800-10917/com.xxx.xxx D/TWC: Notification queue worker:        -2023470816 | 09/07/12:25:23.936 | DEBUG    | 17     | Notification queue worker | void rtd::Worker::route(const rtd::TNBindingType&, const TNMessageType&, const ITNPayloadPtr&) 'twilio.channel.added_to_channel', channel: gcm
09-07 12:25:23.936 10800-10917/com.xxx.xxx I/TWC: Router:        -2023470816 | 09/07/12:25:23.936 | INFO     | 0      | Router | Message with type 'twilio.channel.added_to_channel, from channel: gcm' is being routed to 1 targets
09-07 12:25:23.936 10800-10917/com.xxx.xxx D/TWC: IPM:        -2023470816 | 09/07/12:25:23.936 | DEBUG    | IPM | received twilsock notification twilio.channel.added_to_channel
09-07 12:25:23.936 10800-10917/com.xxx.xxx D/TWC: IPM:        -2023470816 | 09/07/12:25:23.936 | DEBUG    | IPM | [listener] on received notification
09-07 12:25:23.937 10800-23580/com.xxx.xxx D/TWC: ChatClientListener(native):        -2109884128 | 09/07/12:25:23.937 | DEBUG    | ChatClientListener(native) | onNotification
09-07 12:25:23.939 10800-10800/com.xxx.xxx D/ChatClientManager: onNotification===CH3d5166a534ba4cee9f44434257d936d5/
09-07 12:25:24.189 10800-10916/com.xxx.xxx D/TWC: TNWebsocket:        -2022426336 | 09/07/12:25:24.188 | DEBUG    | 6      | TNWebsocket | Receive message 1624 bytes
09-07 12:25:24.189 10800-10916/com.xxx.xxx D/TWC: TNTwilsockClient:        -2022426336 | 09/07/12:25:24.189 | DEBUG    | 1      | TNTwilsockClient | onMessageReceived (1624)
                                                                               TWILSOCK V3.0 491
                                                                               {"method":"reply","id":"b5d87fe7a4074507ae6d62a5f06e7dee7dee","payload_size":1110,"payload_type":"application/json","status":{"code":200,"status":"OK"},"http_status":{"code":200,"status":"OK"},"http_headers":{"Server":"nginx","Date":"Thu, 07 Sep 2017 06:55:24 GMT","Content-Type":"application/json","Content-Length":"1110","ETag":"\"0\"","Twilio-Request-Id":"RQ0bd4c7aaca68427ebba49567725877d6","Vary":"Accept-Encoding","X-Shenanigans":"none","Strict-Transport-Security":"max-age=15768000"}}
                                                                               {"data":{"messagesUrl":"https://cds.us1.twilio.com/v2/Services/ISffd15149604d4fae9f428b3571357590/Streams/ES455712d3f6dd4c2db56a10c2e941ddb5","roster":"CH3d5166a534ba4cee9f44434257d936d5.roster","dateCreated":"2017-09-07T06:55:22.689Z","uniqueName":"366478661890605056","createdBy":"system","messages":"CH3d5166a534ba4cee9f44434257d936d5.messages","attributes":"{}","rosterUrl":"https://cds.us1.twilio.com
09-07 12:25:24.190 10800-10916/com.xxx.xxx I/TWC: TNTwilsockClient:        -2022426336 | 09/07/12:25:24.190 | INFO     | 1      | TNTwilsockClient | onMessageReceived, method = 8, id = b5d87fe7a4074507ae6d62a5f06e7dee7dee
09-07 12:25:24.190 10800-10916/com.xxx.xxx D/TWC: TNTwilsockClientImpl:        -2022426336 | 09/07/12:25:24.190 | DEBUG    | 2      | TNTwilsockClientImpl | proceedReplyMessage b5d87fe7a4074507ae6d62a5f06e7dee7dee
09-07 12:25:24.190 10800-10899/com.xxx.xxx D/TWC: TNTwilsockClient:        -1968629472 | 09/07/12:25:24.190 | DEBUG    | 1      | TNTwilsockClient | Reply for 'b5d87fe7a4074507ae6d62a5f06e7dee7dee'
09-07 12:25:24.190 10800-10899/com.xxx.xxx I/TWC: TNTwilsockClient:        -1968629472 | 09/07/12:25:24.190 | INFO     | 1      | TNTwilsockClient | ReceivedSuccessMessageReply >> Connected
09-07 12:25:24.190 10800-10899/com.xxx.xxx D/TWC: TNHttpTwilsockMessageResult:        -1968629472 | 09/07/12:25:24.190 | DEBUG    | 0      | TNHttpTwilsockMessageResult | onSuccess: 200 - OK
09-07 12:25:24.190 10800-10899/com.xxx.xxx I/TWC: TSDocumentOpenActivity:        -1968629472 | 09/07/12:25:24.190 | INFO     | 95     | TSDocumentOpenActivity | response b5d87fe7a4074507ae6d62a5f06e7dee7dee status 200 body 1110 bytes
09-07 12:25:24.191 10800-10899/com.xxx.xxx I/TWC: SyncDocument:        -1968629472 | 09/07/12:25:24.191 | INFO     | 94     | SyncDocument | opened. Sid: ETf00ea96f12214a50a554a95a2a12891d name: CH3d5166a534ba4cee9f44434257d936d5.channel
09-07 12:25:24.191 10800-10899/com.xxx.xxx D/TWC: TSSubscriptions:        -1968629472 | 09/07/12:25:24.191 | DEBUG    | 21     | TSSubscriptions | Added new subscription for ETf00ea96f12214a50a554a95a2a12891d
09-07 12:25:24.192 10800-10899/com.xxx.xxx D/TWC: IPM:        -1968629472 | 09/07/12:25:24.192 | DEBUG    | IPM | [TRvWI] channel: object bound ETf00ea96f12214a50a554a95a2a12891d
09-07 12:25:24.192 10800-10899/com.xxx.xxx D/TWC: IPM:        -1968629472 | 09/07/12:25:24.192 | DEBUG    | IPM | [TRvWI] channel: StateChannelInitializing->StateChannelCollectionsInitializing
09-07 12:25:24.193 10800-10899/com.xxx.xxx I/TWC: TSDocumentOpenActivity:        -1968629472 | 09/07/12:25:24.192 | INFO     | 95     | TSDocumentOpenActivity | destructed
09-07 12:25:24.193 10800-23589/com.xxx.xxx D/TWC: IPM:        -2110928608 | 09/07/12:25:24.193 | DEBUG    | IPM | [TRvWI] channel {CH3d5166a534ba4cee9f44434257d936d5}: initializing members CH3d5166a534ba4cee9f44434257d936d5.roster
09-07 12:25:24.193 10800-23589/com.xxx.xxx D/TWC: IPM:        -2110928608 | 09/07/12:25:24.193 | DEBUG    | IPM | [TRvWI] members: got initialize
09-07 12:25:24.194 10800-23589/com.xxx.xxx D/TWC: IPM:        -2110928608 | 09/07/12:25:24.193 | DEBUG    | IPM | [TRvWI] members: StateNotInitialized->StateInitializing
09-07 12:25:24.194 10800-23589/com.xxx.xxx I/TWC: SyncMap:        -2110928608 | 09/07/12:25:24.194 | INFO     | 96     | SyncMap | constructed
09-07 12:25:24.194 10800-23589/com.xxx.xxx I/TWC: TSCollectionOpenActivity:        -2110928608 | 09/07/12:25:24.194 | INFO     | 97     | TSCollectionOpenActivity | constructed
09-07 12:25:24.194 10800-23589/com.xxx.xxx I/TWC: TSCollectionOpenActivity:        -2110928608 | 09/07/12:25:24.194 | INFO     | 97     | TSCollectionOpenActivity | start 41
09-07 12:25:24.195 10800-23589/com.xxx.xxx I/TWC: SyncMap:        -2110928608 | 09/07/12:25:24.195 | INFO     | 96     | SyncMap | open action id: 41 id: CH3d5166a534ba4cee9f44434257d936d5.roster
09-07 12:25:24.195 10800-23589/com.xxx.xxx D/TWC: IPM:        -2110928608 | 09/07/12:25:24.195 | DEBUG    | IPM | [TRvWI] channel {CH3d5166a534ba4cee9f44434257d936d5}: initializing messages CH3d5166a534ba4cee9f44434257d936d5.messages
09-07 12:25:24.195 10800-10912/com.xxx.xxx I/TWC: TSCollectionOpenActivity:        -2018248416 | 09/07/12:25:24.195 | INFO     | 97     | TSCollectionOpenActivity | query [1] /v3/Maps/CH3d5166a534ba4cee9f44434257d936d5.roster
09-07 12:25:24.195 10800-10912/com.xxx.xxx I/TWC: TNHttpTransportClient:        -2018248416 | 09/07/12:25:24.195 | INFO     | 12     | TNHttpTransportClient | trying to send request to: https://cds.us1.twilio.com/v3/Maps/CH3d5166a534ba4cee9f44434257d936d5.roster
09-07 12:25:24.195 10800-10912/com.xxx.xxx D/TWC: TNHttpTransportClient:        -2018248416 | 09/07/12:25:24.195 | DEBUG    | 12     | TNHttpTransportClient | Host: cds.us1.twilio.com, path: /v3/Maps/CH3d5166a534ba4cee9f44434257d936d5.roster
09-07 12:25:24.196 10800-23589/com.xxx.xxx D/TWC: IPM:        -2110928608 | 09/07/12:25:24.196 | DEBUG    | IPM | [TRvWI] messages: got initialize
09-07 12:25:24.196 10800-23589/com.xxx.xxx D/TWC: IPM:        -2110928608 | 09/07/12:25:24.196 | DEBUG    | IPM | [TRvWI] messages: StateNotInitialized->StateInitializing
09-07 12:25:24.197 10800-23589/com.xxx.xxx I/TWC: SyncList:        -2110928608 | 09/07/12:25:24.196 | INFO     | 98     | SyncList | constructed
09-07 12:25:24.197 10800-23589/com.xxx.xxx I/TWC: TSCollectionOpenActivity:        -2110928608 | 09/07/12:25:24.197 | INFO     | 99     | TSCollectionOpenActivity | constructed
09-07 12:25:24.197 10800-23589/com.xxx.xxx I/TWC: TSCollectionOpenActivity:        -2110928608 | 09/07/12:25:24.197 | INFO     | 99     | TSCollectionOpenActivity | start 42
09-07 12:25:24.197 10800-23589/com.xxx.xxx I/TWC: SyncList:        -2110928608 | 09/07/12:25:24.197 | INFO     | 98     | SyncList | open (2) action id: 42 id: CH3d5166a534ba4cee9f44434257d936d5.messages
09-07 12:25:24.197 10800-10901/com.xxx.xxx I/TWC: TSCollectionOpenActivity:        -1970718432 | 09/07/12:25:24.197 | INFO     | 99     | TSCollectionOpenActivity | query [1] /v3/Lists/CH3d5166a534ba4cee9f44434257d936d5.messages
09-07 12:25:24.197 10800-10901/com.xxx.xxx I/TWC: TNHttpTransportClient:        -1970718432 | 09/07/12:25:24.197 | INFO     | 12     | TNHttpTransportClient | trying to send request to: https://cds.us1.twilio.com/v3/Lists/CH3d5166a534ba4cee9f44434257d936d5.messages
09-07 12:25:24.206 10800-10899/com.xxx.xxx I/TWC: TNTwilsockClient:        -1968629472 | 09/07/12:25:24.206 | INFO     | 1      | TNTwilsockClient | sendMessageImpl >> Connected 096f2efb0e3f4ebf8a307cd3b12a4cbe4cbe
09-07 12:25:24.206 10800-10899/com.xxx.xxx D/TWC: TNTwilsockClientImpl:        -1968629472 | 09/07/12:25:24.206 | DEBUG    | 2      | TNTwilsockClientImpl | sendMessageMessage
09-07 12:25:24.207 10800-10899/com.xxx.xxx I/TWC: TNTwilsockClientImpl:        -1968629472 | 09/07/12:25:24.206 | INFO     | 2      | TNTwilsockClientImpl | sendMessageMessage, id = 096f2efb0e3f4ebf8a307cd3b12a4cbe4cbe - present
09-07 12:25:24.207 10800-10912/com.xxx.xxx D/TWC: TNTwilsockClient:        -2018248416 | 09/07/12:25:24.207 | DEBUG    | 1      | TNTwilsockClient | sendHttpMessage 096f2efb0e3f4ebf8a307cd3b12a4cbe4cbe
09-07 12:25:24.207 10800-10918/com.xxx.xxx D/TWC: TNWebsocket:        -2024515296 | 09/07/12:25:24.207 | DEBUG    | 6      | TNWebsocket | Sending frame via websocket (1719)
                                                                          TWILSOCK V3.0 1695
                                                                          {"http_request":{"headers":{"Content-Length":"0","Content-Type":"application/json; charset=utf-8","Twilio-Sync-Client-Info":"{\"os\":\"Linux\",\"osVer\":\"3.18.31-perf-gb2364c0\",\"pl\":\"armv7l\",\"plVer\":\"4.15.0\",\"sdk\":\"cpp\",\"sdkVer\":\"4.15.0\"}","X-Twilio-Product-Id":"ip_messaging","X-Twilio-Token":"eyJjdHkiOiJ0d2lsaW8tZnBhO3Y9MSIsInR5cCI6IkpXVCIsImFsZyI6IkhTMjU2In0.eyJpc3MiOiJTSzBkZTI0NjlmYTVjZGRiODdiMTA4NzY4YmM5NzZlMzNmIiwiZXhwIjoxNTA0ODUyMjgwLCJncmFudHMiOnsiaWRlbnRpdHkiOiIzNjM2NzU4OTMyODcwOTIyMjQiLCJpcF9tZXNzYWdpbmciOnsic2VydmljZV9zaWQiOiJJU2ZmZDE1MTQ5NjA0ZDRmYWU5ZjQyOGIzNTcxMzU3NTkwIiwiZGVwbG95bWVudF9yb2xlX3NpZCI6bnVsbCwiZW5kcG9pbnRfaWQiOiJmb25lYXBwaXBtZXNzYWdpbmc6MzYzNjc1ODkzMjg3MDkyMjI0OmQySGNfZHVIbTVRIiwicHVzaF9jcmVkZW50aWFsX3NpZCI6IkNSMzIxOGNmNmQwOWU3YzdhZjQwOTMxYTk2OWU1MzFkY2MifX0sImp0aSI6IlNLMGRlMjQ2OWZhNWNkZGI4N2IxMDg3NjhiYzk3NmUzM2YtMTUwNDc2NTk1MiIsInN1YiI
09-07 12:25:24.207 10800-10912/com.xxx.xxx D/TWC: TNHttpTransportClient:        -2018248416 | 09/07/12:25:24.207 | DEBUG    | 12     | TNHttpTransportClient | id: 096f2efb0e3f4ebf8a307cd3b12a4cbe4cbe
09-07 12:25:24.207 10800-10901/com.xxx.xxx D/TWC: TNHttpTransportClient:        -1970718432 | 09/07/12:25:24.207 | DEBUG    | 12     | TNHttpTransportClient | Host: cds.us1.twilio.com, path: /v3/Lists/CH3d5166a534ba4cee9f44434257d936d5.messages
09-07 12:25:24.213 10800-10901/com.xxx.xxx D/TWC: TNTwilsockClient:        -1970718432 | 09/07/12:25:24.213 | DEBUG    | 1      | TNTwilsockClient | sendHttpMessage 52df1b3514c44aaa85fadcdbab83ac84ac84
09-07 12:25:24.213 10800-10899/com.xxx.xxx I/TWC: TNTwilsockClient:        -1968629472 | 09/07/12:25:24.213 | INFO     | 1      | TNTwilsockClient | sendMessageImpl >> Connected 52df1b3514c44aaa85fadcdbab83ac84ac84
09-07 12:25:24.213 10800-10901/com.xxx.xxx D/TWC: TNHttpTransportClient:        -1970718432 | 09/07/12:25:24.213 | DEBUG    | 12     | TNHttpTransportClient | id: 52df1b3514c44aaa85fadcdbab83ac84ac84
09-07 12:25:24.213 10800-10899/com.xxx.xxx D/TWC: TNTwilsockClientImpl:        -1968629472 | 09/07/12:25:24.213 | DEBUG    | 2      | TNTwilsockClientImpl | sendMessageMessage
09-07 12:25:24.213 10800-10899/com.xxx.xxx I/TWC: TNTwilsockClientImpl:        -1968629472 | 09/07/12:25:24.213 | INFO     | 2      | TNTwilsockClientImpl | sendMessageMessage, id = 52df1b3514c44aaa85fadcdbab83ac84ac84 - present
09-07 12:25:24.213 10800-10918/com.xxx.xxx D/TWC: TNWebsocket:        -2024515296 | 09/07/12:25:24.213 | DEBUG    | 6      | TNWebsocket | Sending frame via websocket (1722)
                                                                          TWILSOCK V3.0 1698
                                                                          {"http_request":{"headers":{"Content-Length":"0","Content-Type":"application/json; charset=utf-8","Twilio-Sync-Client-Info":"{\"os\":\"Linux\",\"osVer\":\"3.18.31-perf-gb2364c0\",\"pl\":\"armv7l\",\"plVer\":\"4.15.0\",\"sdk\":\"cpp\",\"sdkVer\":\"4.15.0\"}","X-Twilio-Product-Id":"ip_messaging","X-Twilio-Token":"eyJjdHkiOiJ0d2lsaW8tZnBhO3Y9MSIsInR5cCI6IkpXVCIsImFsZyI6IkhTMjU2In0.eyJpc3MiOiJTSzBkZTI0NjlmYTVjZGRiODdiMTA4NzY4YmM5NzZlMzNmIiwiZXhwIjoxNTA0ODUyMjgwLCJncmFudHMiOnsiaWRlbnRpdHkiOiIzNjM2NzU4OTMyODcwOTIyMjQiLCJpcF9tZXNzYWdpbmciOnsic2VydmljZV9zaWQiOiJJU2ZmZDE1MTQ5NjA0ZDRmYWU5ZjQyOGIzNTcxMzU3NTkwIiwiZGVwbG95bWVudF9yb2xlX3NpZCI6bnVsbCwiZW5kcG9pbnRfaWQiOiJmb25lYXBwaXBtZXNzYWdpbmc6MzYzNjc1ODkzMjg3MDkyMjI0OmQySGNfZHVIbTVRIiwicHVzaF9jcmVkZW50aWFsX3NpZCI6IkNSMzIxOGNmNmQwOWU3YzdhZjQwOTMxYTk2OWU1MzFkY2MifX0sImp0aSI6IlNLMGRlMjQ2OWZhNWNkZGI4N2IxMDg3NjhiYzk3NmUzM2YtMTUwNDc2NTk1MiIsInN1YiI
09-07 12:25:24.563 10800-10916/com.xxx.xxx D/TWC: TNWebsocket:        -2022426336 | 09/07/12:25:24.563 | DEBUG    | 6      | TNWebsocket | Receive message 1418 bytes
09-07 12:25:24.563 10800-10916/com.xxx.xxx D/TWC: TNTwilsockClient:        -2022426336 | 09/07/12:25:24.563 | DEBUG    | 1      | TNTwilsockClient | onMessageReceived (1418)
                                                                               TWILSOCK V3.0 489
                                                                               {"method":"reply","id":"096f2efb0e3f4ebf8a307cd3b12a4cbe4cbe","payload_size":906,"payload_type":"application/json","status":{"code":200,"status":"OK"},"http_status":{"code":200,"status":"OK"},"http_headers":{"Server":"nginx","Date":"Thu, 07 Sep 2017 06:55:24 GMT","Content-Type":"application/json","Content-Length":"906","ETag":"\"1\"","Twilio-Request-Id":"RQ2d557d66483843aa9784b7404cd6b8e9","Vary":"Accept-Encoding","X-Shenanigans":"none","Strict-Transport-Security":"max-age=15768000"}}
                                                                               {"account_sid":"ACe0aecff6db699d4bb6939e5e8e3f5bed","service_sid":"ISffd15149604d4fae9f428b3571357590","sid":"MPa42a3df842304131b28273b9429dca40","unique_name":"CH3d5166a534ba4cee9f44434257d936d5.roster","revision":"1","last_event_id":0,"date_created":"2017-09-07T06:55:22.774Z","date_updated":"2017-09-07T06:55:23.658Z","created_by":"system","eventing":"reliable","type":"map","url":"https://cds.us1.twilio
09-07 12:25:24.563 10800-10916/com.xxx.xxx I/TWC: TNTwilsockClient:        -2022426336 | 09/07/12:25:24.563 | INFO     | 1      | TNTwilsockClient | onMessageReceived, method = 8, id = 096f2efb0e3f4ebf8a307cd3b12a4cbe4cbe
09-07 12:25:24.563 10800-10916/com.xxx.xxx D/TWC: TNTwilsockClientImpl:        -2022426336 | 09/07/12:25:24.563 | DEBUG    | 2      | TNTwilsockClientImpl | proceedReplyMessage 096f2efb0e3f4ebf8a307cd3b12a4cbe4cbe
09-07 12:25:24.563 10800-10916/com.xxx.xxx D/TWC: TNWebsocket:        -2022426336 | 09/07/12:25:24.563 | DEBUG    | 6      | TNWebsocket | Receive message 1426 bytes
09-07 12:25:24.563 10800-10916/com.xxx.xxx D/TWC: TNTwilsockClient:        -2022426336 | 09/07/12:25:24.563 | DEBUG    | 1      | TNTwilsockClient | onMessageReceived (1426)
                                                                               TWILSOCK V3.0 489
                                                                               {"method":"reply","id":"52df1b3514c44aaa85fadcdbab83ac84ac84","payload_size":914,"payload_type":"application/json","status":{"code":200,"status":"OK"},"http_status":{"code":200,"status":"OK"},"http_headers":{"Server":"nginx","Date":"Thu, 07 Sep 2017 06:55:24 GMT","Content-Type":"application/json","Content-Length":"914","ETag":"\"0\"","Twilio-Request-Id":"RQ29f6e7ffd4ea43d5a827536cac7b95d9","Vary":"Accept-Encoding","X-Shenanigans":"none","Strict-Transport-Security":"max-age=15768000"}}
                                                                               {"account_sid":"ACe0aecff6db699d4bb6939e5e8e3f5bed","service_sid":"ISffd15149604d4fae9f428b3571357590","sid":"ES455712d3f6dd4c2db56a10c2e941ddb5","unique_name":"CH3d5166a534ba4cee9f44434257d936d5.messages","revision":"0","last_event_id":-1,"date_created":"2017-09-07T06:55:22.745Z","date_updated":"2017-09-07T06:55:22.745Z","created_by":"system","eventing":"reliable","type":"list","url":"https://cds.us1.tw
09-07 12:25:24.563 10800-10899/com.xxx.xxx D/TWC: TNTwilsockClient:        -1968629472 | 09/07/12:25:24.563 | DEBUG    | 1      | TNTwilsockClient | Reply for '096f2efb0e3f4ebf8a307cd3b12a4cbe4cbe'
09-07 12:25:24.563 10800-10899/com.xxx.xxx I/TWC: TNTwilsockClient:        -1968629472 | 09/07/12:25:24.563 | INFO     | 1      | TNTwilsockClient | ReceivedSuccessMessageReply >> Connected
09-07 12:25:24.563 10800-10899/com.xxx.xxx D/TWC: TNHttpTwilsockMessageResult:        -1968629472 | 09/07/12:25:24.563 | DEBUG    | 0      | TNHttpTwilsockMessageResult | onSuccess: 200 - OK
09-07 12:25:24.563 10800-10899/com.xxx.xxx I/TWC: TSCollectionOpenActivity:        -1968629472 | 09/07/12:25:24.563 | INFO     | 97     | TSCollectionOpenActivity | response 096f2efb0e3f4ebf8a307cd3b12a4cbe4cbe status 200 body 906 bytes
09-07 12:25:24.563 10800-10916/com.xxx.xxx I/TWC: TNTwilsockClient:        -2022426336 | 09/07/12:25:24.563 | INFO     | 1      | TNTwilsockClient | onMessageReceived, method = 8, id = 52df1b3514c44aaa85fadcdbab83ac84ac84
09-07 12:25:24.563 10800-10916/com.xxx.xxx D/TWC: TNTwilsockClientImpl:        -2022426336 | 09/07/12:25:24.563 | DEBUG    | 2      | TNTwilsockClientImpl | proceedReplyMessage 52df1b3514c44aaa85fadcdbab83ac84ac84
09-07 12:25:24.563 10800-10899/com.xxx.xxx D/TWC: TSSubscriptions:        -1968629472 | 09/07/12:25:24.563 | DEBUG    | 21     | TSSubscriptions | Added new subscription for MPa42a3df842304131b28273b9429dca40
09-07 12:25:24.564 10800-10899/com.xxx.xxx D/TWC: IPM:        -1968629472 | 09/07/12:25:24.564 | DEBUG    | IPM | [TRvWI] members: object bound MPa42a3df842304131b28273b9429dca40
09-07 12:25:24.564 10800-10899/com.xxx.xxx D/TWC: IPM:        -1968629472 | 09/07/12:25:24.564 | DEBUG    | IPM | [1] querying all items from MPa42a3df842304131b28273b9429dca40
09-07 12:25:24.564 10800-10899/com.xxx.xxx I/TWC: TSCollectionItemQueryActivity(3):        -1968629472 | 09/07/12:25:24.564 | INFO     | 100    | TSCollectionItemQueryActivity(3) | constructed
09-07 12:25:24.564 10800-10899/com.xxx.xxx I/TWC: TSCollectionItemQueryActivity(3):        -1968629472 | 09/07/12:25:24.564 | INFO     | 100    | TSCollectionItemQueryActivity(3) | start 43
09-07 12:25:24.564 10800-10899/com.xxx.xxx I/TWC: SyncMap:        -1968629472 | 09/07/12:25:24.564 | INFO     | 96     | SyncMap | query page id: 43
09-07 12:25:24.564 10800-10899/com.xxx.xxx I/TWC: TSCollectionOpenActivity:        -1968629472 | 09/07/12:25:24.564 | INFO     | 97     | TSCollectionOpenActivity | destructed
09-07 12:25:24.564 10800-10910/com.xxx.xxx I/TWC: TSCollectionItemQueryActivity(3):        -2016159456 | 09/07/12:25:24.564 | INFO     | 100    | TSCollectionItemQueryActivity(3) | query [1] /v3/Services/ISffd15149604d4fae9f428b3571357590/Maps/MPa42a3df842304131b28273b9429dca40/Items?Order=asc
09-07 12:25:24.564 10800-10910/com.xxx.xxx I/TWC: TNHttpTransportClient:        -2016159456 | 09/07/12:25:24.564 | INFO     | 12     | TNHttpTransportClient | trying to send request to: https://cds.us1.twilio.com/v3/Services/ISffd15149604d4fae9f428b3571357590/Maps/MPa42a3df842304131b28273b9429dca40/Items?Order=asc
09-07 12:25:24.564 10800-10899/com.xxx.xxx D/TWC: TNTwilsockClient:        -1968629472 | 09/07/12:25:24.564 | DEBUG    | 1      | TNTwilsockClient | Reply for '52df1b3514c44aaa85fadcdbab83ac84ac84'
09-07 12:25:24.564 10800-10910/com.xxx.xxx D/TWC: TNHttpTransportClient:        -2016159456 | 09/07/12:25:24.564 | DEBUG    | 12     | TNHttpTransportClient | param: Order - asc
09-07 12:25:24.564 10800-10899/com.xxx.xxx I/TWC: TNTwilsockClient:        -1968629472 | 09/07/12:25:24.564 | INFO     | 1      | TNTwilsockClient | ReceivedSuccessMessageReply >> Connected
09-07 12:25:24.564 10800-10910/com.xxx.xxx D/TWC: TNHttpTransportClient:        -2016159456 | 09/07/12:25:24.564 | DEBUG    | 12     | TNHttpTransportClient | Host: cds.us1.twilio.com, path: /v3/Services/ISffd15149604d4fae9f428b3571357590/Maps/MPa42a3df842304131b28273b9429dca40/Items
09-07 12:25:24.564 10800-10899/com.xxx.xxx D/TWC: TNHttpTwilsockMessageResult:        -1968629472 | 09/07/12:25:24.564 | DEBUG    | 0      | TNHttpTwilsockMessageResult | onSuccess: 200 - OK
09-07 12:25:24.564 10800-10899/com.xxx.xxx I/TWC: TSCollectionOpenActivity:        -1968629472 | 09/07/12:25:24.564 | INFO     | 99     | TSCollectionOpenActivity | response 52df1b3514c44aaa85fadcdbab83ac84ac84 status 200 body 914 bytes
09-07 12:25:24.564 10800-10899/com.xxx.xxx D/TWC: TSSubscriptions:        -1968629472 | 09/07/12:25:24.564 | DEBUG    | 21     | TSSubscriptions | Added new subscription for ES455712d3f6dd4c2db56a10c2e941ddb5
09-07 12:25:24.564 10800-10899/com.xxx.xxx D/TWC: IPM:        -1968629472 | 09/07/12:25:24.564 | DEBUG    | IPM | [TRvWI] messages: object bound ES455712d3f6dd4c2db56a10c2e941ddb5
09-07 12:25:24.564 10800-10899/com.xxx.xxx D/TWC: IPM:        -1968629472 | 09/07/12:25:24.564 | DEBUG    | IPM | [TRvWI] messages: StateInitializing->StateMessagesInitialized
09-07 12:25:24.565 10800-10899/com.xxx.xxx I/TWC: TSCollectionOpenActivity:        -1968629472 | 09/07/12:25:24.565 | INFO     | 99     | TSCollectionOpenActivity | destructed
09-07 12:25:24.571 10800-10910/com.xxx.xxx D/TWC: TNTwilsockClient:        -2016159456 | 09/07/12:25:24.570 | DEBUG    | 1      | TNTwilsockClient | sendHttpMessage 6793c65d7e55455596b7b1e702f6425c425c
09-07 12:25:24.571 10800-10910/com.xxx.xxx D/TWC: TNHttpTransportClient:        -2016159456 | 09/07/12:25:24.571 | DEBUG    | 12     | TNHttpTransportClient | id: 6793c65d7e55455596b7b1e702f6425c425c
09-07 12:25:24.571 10800-10899/com.xxx.xxx I/TWC: TNTwilsockClient:        -1968629472 | 09/07/12:25:24.571 | INFO     | 1      | TNTwilsockClient | sendMessageImpl >> Connected 6793c65d7e55455596b7b1e702f6425c425c
09-07 12:25:24.571 10800-10899/com.xxx.xxx D/TWC: TNTwilsockClientImpl:        -1968629472 | 09/07/12:25:24.571 | DEBUG    | 2      | TNTwilsockClientImpl | sendMessageMessage
09-07 12:25:24.571 10800-10899/com.xxx.xxx I/TWC: TNTwilsockClientImpl:        -1968629472 | 09/07/12:25:24.571 | INFO     | 2      | TNTwilsockClientImpl | sendMessageMessage, id = 6793c65d7e55455596b7b1e702f6425c425c - present
09-07 12:25:24.571 10800-10918/com.xxx.xxx D/TWC: TNWebsocket:        -2024515296 | 09/07/12:25:24.571 | DEBUG    | 6      | TNWebsocket | Sending frame via websocket (1787)
                                                                          TWILSOCK V3.0 1763
                                                                          {"http_request":{"headers":{"Content-Length":"0","Content-Type":"application/json; charset=utf-8","Twilio-Sync-Client-Info":"{\"os\":\"Linux\",\"osVer\":\"3.18.31-perf-gb2364c0\",\"pl\":\"armv7l\",\"plVer\":\"4.15.0\",\"sdk\":\"cpp\",\"sdkVer\":\"4.15.0\"}","X-Twilio-Product-Id":"ip_messaging","X-Twilio-Token":"eyJjdHkiOiJ0d2lsaW8tZnBhO3Y9MSIsInR5cCI6IkpXVCIsImFsZyI6IkhTMjU2In0.eyJpc3MiOiJTSzBkZTI0NjlmYTVjZGRiODdiMTA4NzY4YmM5NzZlMzNmIiwiZXhwIjoxNTA0ODUyMjgwLCJncmFudHMiOnsiaWRlbnRpdHkiOiIzNjM2NzU4OTMyODcwOTIyMjQiLCJpcF9tZXNzYWdpbmciOnsic2VydmljZV9zaWQiOiJJU2ZmZDE1MTQ5NjA0ZDRmYWU5ZjQyOGIzNTcxMzU3NTkwIiwiZGVwbG95bWVudF9yb2xlX3NpZCI6bnVsbCwiZW5kcG9pbnRfaWQiOiJmb25lYXBwaXBtZXNzYWdpbmc6MzYzNjc1ODkzMjg3MDkyMjI0OmQySGNfZHVIbTVRIiwicHVzaF9jcmVkZW50aWFsX3NpZCI6IkNSMzIxOGNmNmQwOWU3YzdhZjQwOTMxYTk2OWU1MzFkY2MifX0sImp0aSI6IlNLMGRlMjQ2OWZhNWNkZGI4N2IxMDg3NjhiYzk3NmUzM2YtMTUwNDc2NTk1MiIsInN1YiI
09-07 12:25:24.693 10800-10903/com.xxx.xxx D/TWC: TSSubscriptions:        -1972819680 | 09/07/12:25:24.693 | DEBUG    | 21     | TSSubscriptions | Sending subscription request for action: establish
09-07 12:25:24.693 10800-10903/com.xxx.xxx I/TWC: TNHttpTransportClient:        -1972819680 | 09/07/12:25:24.693 | INFO     | 12     | TNHttpTransportClient | trying to send request to: https://cds.us1.twilio.com/v4/Subscriptions
09-07 12:25:24.693 10800-10903/com.xxx.xxx D/TWC: TNHttpTransportClient:        -1972819680 | 09/07/12:25:24.693 | DEBUG    | 12     | TNHttpTransportClient | Host: cds.us1.twilio.com, path: /v4/Subscriptions
09-07 12:25:24.708 10800-10903/com.xxx.xxx D/TWC: TNTwilsockClient:        -1972819680 | 09/07/12:25:24.708 | DEBUG    | 1      | TNTwilsockClient | sendHttpMessage 187bbf05cc284ba2be10219eb495dbffdbff
09-07 12:25:24.708 10800-10899/com.xxx.xxx I/TWC: TNTwilsockClient:        -1968629472 | 09/07/12:25:24.708 | INFO     | 1      | TNTwilsockClient | sendMessageImpl >> Connected 187bbf05cc284ba2be10219eb495dbffdbff
09-07 12:25:24.709 10800-10903/com.xxx.xxx D/TWC: TNHttpTransportClient:        -1972819680 | 09/07/12:25:24.708 | DEBUG    | 12     | TNHttpTransportClient | id: 187bbf05cc284ba2be10219eb495dbffdbff
09-07 12:25:24.709 10800-10899/com.xxx.xxx D/TWC: TNTwilsockClientImpl:        -1968629472 | 09/07/12:25:24.709 | DEBUG    | 2      | TNTwilsockClientImpl | sendMessageMessage
09-07 12:25:24.709 10800-10899/com.xxx.xxx I/TWC: TNTwilsockClientImpl:        -1968629472 | 09/07/12:25:24.709 | INFO     | 2      | TNTwilsockClientImpl | sendMessageMessage, id = 187bbf05cc284ba2be10219eb495dbffdbff - present
09-07 12:25:24.710 10800-10918/com.xxx.xxx D/TWC: TNWebsocket:        -2024515296 | 09/07/12:25:24.710 | DEBUG    | 6      | TNWebsocket | Sending frame via websocket (2082)
                                                                          TWILSOCK V3.0 1667
                                                                          {"http_request":{"headers":{"Content-Length":"391","Content-Type":"application/json; charset=utf-8","Twilio-Sync-Client-Info":"{\"os\":\"Linux\",\"osVer\":\"3.18.31-perf-gb2364c0\",\"pl\":\"armv7l\",\"plVer\":\"4.15.0\",\"sdk\":\"cpp\",\"sdkVer\":\"4.15.0\"}","X-Twilio-Product-Id":"ip_messaging","X-Twilio-Token":"eyJjdHkiOiJ0d2lsaW8tZnBhO3Y9MSIsInR5cCI6IkpXVCIsImFsZyI6IkhTMjU2In0.eyJpc3MiOiJTSzBkZTI0NjlmYTVjZGRiODdiMTA4NzY4YmM5NzZlMzNmIiwiZXhwIjoxNTA0ODUyMjgwLCJncmFudHMiOnsiaWRlbnRpdHkiOiIzNjM2NzU4OTMyODcwOTIyMjQiLCJpcF9tZXNzYWdpbmciOnsic2VydmljZV9zaWQiOiJJU2ZmZDE1MTQ5NjA0ZDRmYWU5ZjQyOGIzNTcxMzU3NTkwIiwiZGVwbG95bWVudF9yb2xlX3NpZCI6bnVsbCwiZW5kcG9pbnRfaWQiOiJmb25lYXBwaXBtZXNzYWdpbmc6MzYzNjc1ODkzMjg3MDkyMjI0OmQySGNfZHVIbTVRIiwicHVzaF9jcmVkZW50aWFsX3NpZCI6IkNSMzIxOGNmNmQwOWU3YzdhZjQwOTMxYTk2OWU1MzFkY2MifX0sImp0aSI6IlNLMGRlMjQ2OWZhNWNkZGI4N2IxMDg3NjhiYzk3NmUzM2YtMTUwNDc2NTk1MiIsInN1Y
09-07 12:25:24.885 10800-10916/com.xxx.xxx D/TWC: TNWebsocket:        -2022426336 | 09/07/12:25:24.885 | DEBUG    | 6      | TNWebsocket | Receive message 1410 bytes
09-07 12:25:24.885 10800-10916/com.xxx.xxx D/TWC: TNTwilsockClient:        -2022426336 | 09/07/12:25:24.885 | DEBUG    | 1      | TNTwilsockClient | onMessageReceived (1410)
                                                                               TWILSOCK V3.0 474
                                                                               {"method":"reply","id":"6793c65d7e55455596b7b1e702f6425c425c","payload_size":913,"payload_type":"application/json","status":{"code":200,"status":"OK"},"http_status":{"code":200,"status":"OK"},"http_headers":{"Server":"nginx","Date":"Thu, 07 Sep 2017 06:55:24 GMT","Content-Type":"application/json","Content-Length":"913","Twilio-Request-Id":"RQc2e1f7d1af894446bb242b0333c74942","Vary":"Accept-Encoding","X-Shenanigans":"none","Strict-Transport-Security":"max-age=15768000"}}
                                                                               {"items":[{"account_sid":"ACe0aecff6db699d4bb6939e5e8e3f5bed","service_sid":"ISffd15149604d4fae9f428b3571357590","revision":"0","last_event_id":0,"date_created":"2017-09-07T06:55:23.658Z","date_updated":"2017-09-07T06:55:23.658Z","created_by":"system","url":"https://cds.us1.twilio.com/v3/Services/ISffd15149604d4fae9f428b3571357590/Maps/MPa42a3df842304131b28273b9429dca40/Items/MB92149b0f7a2c4f76a3f36cbf0bc82acf","data":
09-07 12:25:24.886 10800-10916/com.xxx.xxx I/TWC: TNTwilsockClient:        -2022426336 | 09/07/12:25:24.886 | INFO     | 1      | TNTwilsockClient | onMessageReceived, method = 8, id = 6793c65d7e55455596b7b1e702f6425c425c
09-07 12:25:24.886 10800-10916/com.xxx.xxx D/TWC: TNTwilsockClientImpl:        -2022426336 | 09/07/12:25:24.886 | DEBUG    | 2      | TNTwilsockClientImpl | proceedReplyMessage 6793c65d7e55455596b7b1e702f6425c425c
09-07 12:25:24.886 10800-10899/com.xxx.xxx D/TWC: TNTwilsockClient:        -1968629472 | 09/07/12:25:24.886 | DEBUG    | 1      | TNTwilsockClient | Reply for '6793c65d7e55455596b7b1e702f6425c425c'
09-07 12:25:24.886 10800-10899/com.xxx.xxx I/TWC: TNTwilsockClient:        -1968629472 | 09/07/12:25:24.886 | INFO     | 1      | TNTwilsockClient | ReceivedSuccessMessageReply >> Connected
09-07 12:25:24.887 10800-10899/com.xxx.xxx D/TWC: TNHttpTwilsockMessageResult:        -1968629472 | 09/07/12:25:24.887 | DEBUG    | 0      | TNHttpTwilsockMessageResult | onSuccess: 200 - OK
09-07 12:25:24.887 10800-10899/com.xxx.xxx I/TWC: TSCollectionItemQueryActivity(3):        -1968629472 | 09/07/12:25:24.887 | INFO     | 100    | TSCollectionItemQueryActivity(3) | response 6793c65d7e55455596b7b1e702f6425c425c status 200 body 913 bytes
09-07 12:25:24.888 10800-10899/com.xxx.xxx I/TWC: TSCollectionItemQueryActivity(3):        -1968629472 | 09/07/12:25:24.888 | INFO     | 100    | TSCollectionItemQueryActivity(3) | destructed
09-07 12:25:24.888 10800-10949/com.xxx.xxx D/TWC: IPM:        -2052052704 | 09/07/12:25:24.888 | DEBUG    | IPM | [1] query: got page for MPa42a3df842304131b28273b9429dca40
09-07 12:25:24.888 10800-10949/com.xxx.xxx D/TWC: IPM:        -2052052704 | 09/07/12:25:24.888 | DEBUG    | IPM | [1] query done MPa42a3df842304131b28273b9429dca40
09-07 12:25:24.889 10800-10949/com.xxx.xxx D/TWC: IPM:        -2052052704 | 09/07/12:25:24.888 | DEBUG    | IPM | [TRvWI] members: query done, results count 1
09-07 12:25:24.889 10800-10949/com.xxx.xxx D/TWC: IPM:        -2052052704 | 09/07/12:25:24.889 | DEBUG    | IPM | [TRvWI] members: initializing, count: 1
09-07 12:25:24.890 10800-10949/com.xxx.xxx D/TWC: IPM:        -2052052704 | 09/07/12:25:24.890 | DEBUG    | IPM | [TRvWI] members: StateInitializing->StateMembersInitialized
09-07 12:25:24.891 10800-23623/com.xxx.xxx D/TWC: IPM:        -2111973088 | 09/07/12:25:24.891 | DEBUG    | IPM | [TRvWI] channel {CH3d5166a534ba4cee9f44434257d936d5}: collections initialized
09-07 12:25:24.891 10800-23623/com.xxx.xxx D/TWC: IPM:        -2111973088 | 09/07/12:25:24.891 | DEBUG    | IPM | [TRvWI] channel: StateChannelCollectionsInitializing->StateChannelCollections
09-07 12:25:24.892 10800-23625/com.xxx.xxx D/TWC: IPM:        -2110928608 | 09/07/12:25:24.892 | DEBUG    | IPM | [TRvWI] channel: executing handlers
09-07 12:25:24.892 10800-23625/com.xxx.xxx D/TWC: IPM:        -2110928608 | 09/07/12:25:24.892 | DEBUG    | IPM | [listener] on channel updated CH3d5166a534ba4cee9f44434257d936d5 3
09-07 12:25:24.893 10800-23626/com.xxx.xxx D/TWC: ChatClientListener(native):        -2109884128 | 09/07/12:25:24.893 | DEBUG    | ChatClientListener(native) | onChannelUpdated
09-07 12:25:24.894 10800-23626/com.xxx.xxx D/TWC: EntityCache:        -2109884128 | 09/07/12:25:24.894 | DEBUG    | EntityCache | Returning Java object from cache
09-07 12:25:24.895 10800-23626/com.xxx.xxx D/TWC: ChatClientListener(native):        -2109884128 | 09/07/12:25:24.894 | DEBUG    | ChatClientListener(native) | onChannelUpdated - channel sync
09-07 12:25:24.895 10800-23626/com.xxx.xxx D/ClientInternalListener: onSynchronizationChanged channel CH3d5166a534ba4cee9f44434257d936d5|188057969
09-07 12:25:24.896 10800-23626/com.xxx.xxx D/ClientInternalListener: onSynchronizationChanged channel listeners {com.xxx.xxx.twilio.ChatClientManager@6e1f9c6=Handler (android.os.Handler) {ac84bad}}
09-07 12:25:24.896 10800-23626/com.xxx.xxx D/ClientInternalListener: onSynchronizationChanged channel listener 115472838
09-07 12:25:24.896 10800-23626/com.xxx.xxx D/ClientInternalListener: onSynchronizationChanged handler not null.
09-07 12:25:24.896 10800-10800/com.xxx.xxx D/ClientInternalListener: onSynchronizationChanged calling listener
09-07 12:25:24.896 10800-10800/com.xxx.xxx D/TWC: IPM:        -1458584268 | 09/07/12:25:24.896 | DEBUG    | IPM | [TRvWI] channel: [api] get friendlyname (Hello Gp)
09-07 12:25:24.897 10800-10800/com.xxx.xxx D/TWC: Channel(native):        -1458584268 | 09/07/12:25:24.897 | DEBUG    | Channel(native) | getSynchronizationStatus for channel sid|CH3d5166a534ba4cee9f44434257d936d5|
09-07 12:25:24.897 10800-10800/com.xxx.xxx D/ChatClientManager: Received onSynchronizationChanged callback getFriendlyName =Hello Gp
                                                                           Status=ALL
09-07 12:25:25.079 10800-10916/com.xxx.xxx D/TWC: TNWebsocket:        -2022426336 | 09/07/12:25:25.079 | DEBUG    | 6      | TNWebsocket | Receive message 532 bytes
09-07 12:25:25.079 10800-10916/com.xxx.xxx D/TWC: TNTwilsockClient:        -2022426336 | 09/07/12:25:25.079 | DEBUG    | 1      | TNTwilsockClient | onMessageReceived (532)
                                                                               TWILSOCK V3.0 434
                                                                               {"method":"reply","id":"187bbf05cc284ba2be10219eb495dbffdbff","payload_size":75,"payload_type":"application/json;charset=utf-8","status":{"code":200,"status":"OK"},"http_status":{"code":202,"status":"Accepted"},"http_headers":{"Server":"nginx","Date":"Thu, 07 Sep 2017 06:55:25 GMT","Content-Type":"application/json;charset=utf-8","Content-Length":"75","Twilio-Request-Id":"RQb47437ebe60f425487d870e236f11934","X-Shenanigans":"none"}}
                                                                               {"estimated_delivery_in_ms":10000,"max_batch_size":1000,"ttl_in_s":2592000}
09-07 12:25:25.080 10800-10916/com.xxx.xxx I/TWC: TNTwilsockClient:        -2022426336 | 09/07/12:25:25.080 | INFO     | 1      | TNTwilsockClient | onMessageReceived, method = 8, id = 187bbf05cc284ba2be10219eb495dbffdbff
09-07 12:25:25.080 10800-10916/com.xxx.xxx D/TWC: TNTwilsockClientImpl:        -2022426336 | 09/07/12:25:25.080 | DEBUG    | 2      | TNTwilsockClientImpl | proceedReplyMessage 187bbf05cc284ba2be10219eb495dbffdbff
09-07 12:25:25.080 10800-10899/com.xxx.xxx D/TWC: TNTwilsockClient:        -1968629472 | 09/07/12:25:25.080 | DEBUG    | 1      | TNTwilsockClient | Reply for '187bbf05cc284ba2be10219eb495dbffdbff'
09-07 12:25:25.080 10800-10899/com.xxx.xxx I/TWC: TNTwilsockClient:        -1968629472 | 09/07/12:25:25.080 | INFO     | 1      | TNTwilsockClient | ReceivedSuccessMessageReply >> Connected
09-07 12:25:25.080 10800-10899/com.xxx.xxx D/TWC: TNHttpTwilsockMessageResult:        -1968629472 | 09/07/12:25:25.080 | DEBUG    | 0      | TNHttpTwilsockMessageResult | onSuccess: 202 - Accepted
09-07 12:25:25.081 10800-10899/com.xxx.xxx D/TWC: TSSubscriptions:        -1968629472 | 09/07/12:25:25.080 | DEBUG    | 21     | TSSubscriptions | Handling response from subscription server 1504767324693: {"estimated_delivery_in_ms":10000,"max_batch_size":1000,"ttl_in_s":2592000}
09-07 12:25:25.109 10800-10916/com.xxx.xxx D/TWC: TNWebsocket:        -2022426336 | 09/07/12:25:25.109 | DEBUG    | 6      | TNWebsocket | Receive message 443 bytes
09-07 12:25:25.109 10800-10916/com.xxx.xxx D/TWC: TNTwilsockClient:        -2022426336 | 09/07/12:25:25.109 | DEBUG    | 1      | TNTwilsockClient | onMessageReceived (443)
                                                                               TWILSOCK V3.0 190
                                                                               {"method":"notification","id":"TM87e8d183b0e6414d9527d9cbff4410b7","payload_size":230,"payload_type":"application/json","message_type":"twilio.sync.event","notification_ctx_id":"dummyCtxId"}
                                                                               {"event_type":"subscription_established","correlation_id":1504767324693,"event_protocol_version":3,"event":{"object_sid":"ETf00ea96f12214a50a554a95a2a12891d","object_type":"document","replay_status":"completed","last_event_id":0}}
09-07 12:25:25.109 10800-10916/com.xxx.xxx I/TWC: TNTwilsockClient:        -2022426336 | 09/07/12:25:25.109 | INFO     | 1      | TNTwilsockClient | onMessageReceived, method = 4, id = TM87e8d183b0e6414d9527d9cbff4410b7
09-07 12:25:25.109 10800-10916/com.xxx.xxx D/TWC: TNTwilsockClientImpl:        -2022426336 | 09/07/12:25:25.109 | DEBUG    | 2      | TNTwilsockClientImpl | proceedNotificationMessage TM87e8d183b0e6414d9527d9cbff4410b7
09-07 12:25:25.109 10800-10916/com.xxx.xxx D/TWC: TNNotificationMgr:        -2022426336 | 09/07/12:25:25.109 | DEBUG    | 15     | TNNotificationMgr | virtual void rtd::TNNotificationMgr::ReceivedTargetedNotification(const rtd::TNBindingType&, const TNMessageType&, const ITNPayloadPtr&) type='twilsock', messageType='twilio.sync.event'
09-07 12:25:25.109 10800-10899/com.xxx.xxx I/TWC: TNTwilsockClient:        -1968629472 | 09/07/12:25:25.109 | INFO     | 1      | TNTwilsockClient | sendSuccessReplyImpl >> Connected
09-07 12:25:25.109 10800-10899/com.xxx.xxx D/TWC: TNTwilsockClientImpl:        -1968629472 | 09/07/12:25:25.109 | DEBUG    | 2      | TNTwilsockClientImpl | sendSuccessReply
09-07 12:25:25.109 10800-10917/com.xxx.xxx D/TWC: Notification queue worker:        -2023470816 | 09/07/12:25:25.109 | DEBUG    | 17     | Notification queue worker | void rtd::Worker::route(const rtd::TNBindingType&, const TNMessageType&, const ITNPayloadPtr&) 'twilio.sync.event', channel: twilsock
09-07 12:25:25.109 10800-10899/com.xxx.xxx I/TWC: TNTwilsockClientImpl:        -1968629472 | 09/07/12:25:25.109 | INFO     | 2      | TNTwilsockClientImpl | sendSuccessReply, id = TM87e8d183b0e6414d9527d9cbff4410b7
09-07 12:25:25.109 10800-10917/com.xxx.xxx I/TWC: Router:        -2023470816 | 09/07/12:25:25.109 | INFO     | 0      | Router | Message with type 'twilio.sync.event, from channel: twilsock' is being routed to 1 targets
09-07 12:25:25.109 10800-10918/com.xxx.xxx D/TWC: TNWebsocket:        -2024515296 | 09/07/12:25:25.109 | DEBUG    | 6      | TNWebsocket | Sending frame via websocket (116)
                                                                          TWILSOCK V3.0 96
                                                                          {"id":"TM87e8d183b0e6414d9527d9cbff4410b7","method":"reply","status":{"code":200,"status":"ok"}}
09-07 12:25:25.110 10800-10916/com.xxx.xxx D/TWC: TNWebsocket:        -2022426336 | 09/07/12:25:25.110 | DEBUG    | 6      | TNWebsocket | Receive message 438 bytes
09-07 12:25:25.110 10800-10916/com.xxx.xxx D/TWC: TNTwilsockClient:        -2022426336 | 09/07/12:25:25.110 | DEBUG    | 1      | TNTwilsockClient | onMessageReceived (438)
                                                                               TWILSOCK V3.0 190
                                                                               {"method":"notification","id":"TM35894f6134464745ba63e3d623607c1a","payload_size":225,"payload_type":"application/json","message_type":"twilio.sync.event","notification_ctx_id":"dummyCtxId"}
                                                                               {"event_type":"subscription_established","correlation_id":1504767324693,"event_protocol_version":3,"event":{"object_sid":"MPa42a3df842304131b28273b9429dca40","object_type":"map","replay_status":"completed","last_event_id":0}}
09-07 12:25:25.110 10800-10916/com.xxx.xxx I/TWC: TNTwilsockClient:        -2022426336 | 09/07/12:25:25.110 | INFO     | 1      | TNTwilsockClient | onMessageReceived, method = 4, id = TM35894f6134464745ba63e3d623607c1a
09-07 12:25:25.110 10800-10916/com.xxx.xxx D/TWC: TNTwilsockClientImpl:        -2022426336 | 09/07/12:25:25.110 | DEBUG    | 2      | TNTwilsockClientImpl | proceedNotificationMessage TM35894f6134464745ba63e3d623607c1a
09-07 12:25:25.110 10800-10916/com.xxx.xxx D/TWC: TNNotificationMgr:        -2022426336 | 09/07/12:25:25.110 | DEBUG    | 15     | TNNotificationMgr | virtual void rtd::TNNotificationMgr::ReceivedTargetedNotification(const rtd::TNBindingType&, const TNMessageType&, const ITNPayloadPtr&) type='twilsock', messageType='twilio.sync.event'
09-07 12:25:25.110 10800-10916/com.xxx.xxx D/TWC: TNWebsocket:        -2022426336 | 09/07/12:25:25.110 | DEBUG    | 6      | TNWebsocket | Receive message 440 bytes
09-07 12:25:25.110 10800-10917/com.xxx.xxx D/TWC: Notification queue worker:        -2023470816 | 09/07/12:25:25.110 | DEBUG    | 17     | Notification queue worker | void rtd::Worker::route(const rtd::TNBindingType&, const TNMessageType&, const ITNPayloadPtr&) 'twilio.sync.event', channel: twilsock
09-07 12:25:25.110 10800-10899/com.xxx.xxx I/TWC: TNTwilsockClient:        -1968629472 | 09/07/12:25:25.110 | INFO     | 1      | TNTwilsockClient | sendSuccessReplyImpl >> Connected
09-07 12:25:25.110 10800-10916/com.xxx.xxx D/TWC: TNTwilsockClient:        -2022426336 | 09/07/12:25:25.110 | DEBUG    | 1      | TNTwilsockClient | onMessageReceived (440)
                                                                               TWILSOCK V3.0 190
                                                                               {"method":"notification","id":"TM295bb4cb431d4fdca0652b3ab8103a16","payload_size":227,"payload_type":"application/json","message_type":"twilio.sync.event","notification_ctx_id":"dummyCtxId"}
                                                                               {"event_type":"subscription_established","correlation_id":1504767324693,"event_protocol_version":3,"event":{"object_sid":"ES455712d3f6dd4c2db56a10c2e941ddb5","object_type":"list","replay_status":"completed","last_event_id":-1}}
09-07 12:25:25.110 10800-10917/com.xxx.xxx I/TWC: Router:        -2023470816 | 09/07/12:25:25.110 | INFO     | 0      | Router | Message with type 'twilio.sync.event, from channel: twilsock' is being routed to 1 targets
09-07 12:25:25.110 10800-10899/com.xxx.xxx D/TWC: TNTwilsockClientImpl:        -1968629472 | 09/07/12:25:25.110 | DEBUG    | 2      | TNTwilsockClientImpl | sendSuccessReply
09-07 12:25:25.110 10800-10899/com.xxx.xxx I/TWC: TNTwilsockClientImpl:        -1968629472 | 09/07/12:25:25.110 | INFO     | 2      | TNTwilsockClientImpl | sendSuccessReply, id = TM35894f6134464745ba63e3d623607c1a
09-07 12:25:25.110 10800-10916/com.xxx.xxx I/TWC: TNTwilsockClient:        -2022426336 | 09/07/12:25:25.110 | INFO     | 1      | TNTwilsockClient | onMessageReceived, method = 4, id = TM295bb4cb431d4fdca0652b3ab8103a16
09-07 12:25:25.110 10800-10916/com.xxx.xxx D/TWC: TNTwilsockClientImpl:        -2022426336 | 09/07/12:25:25.110 | DEBUG    | 2      | TNTwilsockClientImpl | proceedNotificationMessage TM295bb4cb431d4fdca0652b3ab8103a16
09-07 12:25:25.110 10800-10899/com.xxx.xxx I/TWC: TNTwilsockClient:        -1968629472 | 09/07/12:25:25.110 | INFO     | 1      | TNTwilsockClient | sendSuccessReplyImpl >> Connected
09-07 12:25:25.110 10800-10916/com.xxx.xxx D/TWC: TNNotificationMgr:        -2022426336 | 09/07/12:25:25.110 | DEBUG    | 15     | TNNotificationMgr | virtual void rtd::TNNotificationMgr::ReceivedTargetedNotification(const rtd::TNBindingType&, const TNMessageType&, const ITNPayloadPtr&) type='twilsock', messageType='twilio.sync.event'
09-07 12:25:25.110 10800-10899/com.xxx.xxx D/TWC: TNTwilsockClientImpl:        -1968629472 | 09/07/12:25:25.110 | DEBUG    | 2      | TNTwilsockClientImpl | sendSuccessReply
09-07 12:25:25.110 10800-10899/com.xxx.xxx I/TWC: TNTwilsockClientImpl:        -1968629472 | 09/07/12:25:25.110 | INFO     | 2      | TNTwilsockClientImpl | sendSuccessReply, id = TM295bb4cb431d4fdca0652b3ab8103a16
09-07 12:25:25.110 10800-10917/com.xxx.xxx D/TWC: Notification queue worker:        -2023470816 | 09/07/12:25:25.110 | DEBUG    | 17     | Notification queue worker | void rtd::Worker::route(const rtd::TNBindingType&, const TNMessageType&, const ITNPayloadPtr&) 'twilio.sync.event', channel: twilsock
09-07 12:25:25.110 10800-10917/com.xxx.xxx I/TWC: Router:        -2023470816 | 09/07/12:25:25.110 | INFO     | 0      | Router | Message with type 'twilio.sync.event, from channel: twilsock' is being routed to 1 targets
09-07 12:25:25.111 10800-10918/com.xxx.xxx D/TWC: TNWebsocket:        -2024515296 | 09/07/12:25:25.111 | DEBUG    | 6      | TNWebsocket | Sending frame via websocket (116)
                                                                          TWILSOCK V3.0 96
                                                                          {"id":"TM35894f6134464745ba63e3d623607c1a","method":"reply","status":{"code":200,"status":"ok"}}
09-07 12:25:25.111 10800-10918/com.xxx.xxx D/TWC: TNWebsocket:        -2024515296 | 09/07/12:25:25.111 | DEBUG    | 6      | TNWebsocket | Sending frame via websocket (116)
                                                                          TWILSOCK V3.0 96
                                                                          {"id":"TM295bb4cb431d4fdca0652b3ab8103a16","method":"reply","status":{"code":200,"status":"ok"}}

**09-07 12:25:26.976 10800-22910/com.xxx.xxx D/Netowrk Class: http://xxx.ngrok.io/gp-server/r/group/**
09-07 12:25:27.026 10800-22840/com.xxx.xxx V/FA: Recording user engagement, ms: 11631
09-07 12:25:27.027 10800-22840/com.xxx.xxx V/FA: Using measurement service
09-07 12:25:27.027 10800-22840/com.xxx.xxx V/FA: Connecting to remote service
09-07 12:25:27.030 10800-22840/com.xxx.xxx V/FA: Activity paused, time: 253739869
09-07 12:25:27.033 10800-22840/com.xxx.xxx D/FA: Logging event (FE): user_engagement(_e), Bundle[{firebase_event_origin(_o)=auto, engagement_time_msec(_et)=11631, firebase_screen_class(_sc)=ChoosePlanActivity, firebase_screen_id(_si)=-92615121144720565}]
09-07 12:25:27.037 10800-10800/com.xxx.xxx V/FA: onActivityCreated
09-07 12:25:27.043 10800-22840/com.xxx.xxx V/FA: Using measurement service
09-07 12:25:27.043 10800-22840/com.xxx.xxx V/FA: Connection attempt already in progress
09-07 12:25:27.064 10800-22840/com.xxx.xxx V/FA: Using measurement service
09-07 12:25:27.064 10800-22840/com.xxx.xxx V/FA: Connection attempt already in progress
09-07 12:25:27.065 10800-22840/com.xxx.xxx V/FA: Activity resumed, time: 253739908

09-07 12:25:27.072 10800-22840/com.xxx.xxx V/FA: Using measurement service
09-07 12:25:27.073 10800-22840/com.xxx.xxx V/FA: Connection attempt already in progress
09-07 12:25:27.073 10800-22840/com.xxx.xxx D/FA: Connected to remote service
09-07 12:25:27.073 10800-22840/com.xxx.xxx V/FA: Processing queued up service tasks: 4
09-07 12:25:28.116 10800-10800/com.xxx.xxx D/ChatClientManager: An error has occurred. Please try later.
09-07 12:25:32.093 10800-22840/com.xxx.xxx V/FA: Inactivity, disconnecting from the service
09-07 12:25:35.090 10800-10905/com.xxx.xxx D/TWC: TSSubscriptions:        -2010937056 | 09/07/12:25:35.090 | DEBUG    | TSSubscriptions | Extending poke timeout by 21ms for correlation ID 1504767324693
09-07 12:25:35.112 10800-10908/com.xxx.xxx D/TWC: TSSubscriptions:        -2014070496 | 09/07/12:25:35.112 | DEBUG    | TSSubscriptions | Removed 0 timed out subscriptions per correlation ID 1504767324693

berkus commented 7 years ago

You could use triple-` to format your paste.

ajitdubey-mob-ibtech commented 7 years ago

Ok, Thanks

@berkus Kindly add if any additional information you required

ajitdubey-mob-ibtech commented 7 years ago

@berkus Is there any update regarding the same issue. I think channel should not available until complete synchronization.

berkus commented 7 years ago

I will double check if this was addressed in a recent release and update you here.

berkus commented 7 years ago

Hi, 1.0.11 and 2.0.1 are released today and should contain some fixes that may be relevant to this issue. Could you please retest with these newer versions and report results?

ajitdubey-mob-ibtech commented 7 years ago

@berkus Sure, Thank you so much.

berkus commented 7 years ago

Any update?

berkus commented 7 years ago

So, for posterity:

This issue still remains in 1.x SDK series; amount of work to fix it there is non-trivial so it will not be fixed.
2.x series work correctly. Migrate to these as soon as possible.
Workaround for 1.x is to wait for channel onSynchronizationState update with at least METADATA status.

ajitdubey-mob-ibtech commented 7 years ago

@berkus I am back after a long leave, In coming week will give you update. Thanks for suggestion.

berkus commented 7 years ago

Ok, please be advised that this issue is unlikely to be fixed fully in the 1.x series, if possible - migrate to 2x. If not - you'll have to implement waiting for channel synchronization manually, basically by adding a listener to the channel with channel.addListener() and checking onSynchronizationChanged there - when the channel.SynchronizationStatus.isAtLeast(METADATA) then the channel has necessary info. Note that adding a channel listener will immediately call it's onSynchronizationChanged callback with the current channel status, so you don't have to duplicate checking code - just check in the channel listener and launch next action once METADATA is available.

twilio / twilio-chat-demo-android

onChannelJoined called with unsynchronized channel #14