sendMessage issue on reconnect

[smelfungus]

Hi there! We're currently integrating Twilio Programmable Chat solution on Android platform. We're implementing capabilities to send messages in offline mode with further delivery & caching and here we're facing strange problem. While trying to send delayed messages with onConnectionStateChange CONNECTED callback with next sequence:

Steps to Reproduce

1) Wait for onConnectionStateChange CONNECTED state 2) Get needed channel via ChatClient.getChannels().getChannel() onSuccess callback 3) Call Messages.sendMessage() for acquired channel

We're getting no callback of sendMessage() and no further attempts to send messages are working.

Code

    @Override
    public void onConnectionStateChange(ChatClient.ConnectionState connectionState) {
        Log.d(TAG, "onConnectionStateChange() called with: connectionState = [" + connectionState + "]");

        switch (connectionState) {
            case CONNECTING: {
                break;
            }
            case CONNECTED: {
                sendLocalMessages();
                break;
            }
            case DISCONNECTED: {
                break;
            }
            case DENIED: {
                break;
            }
            case FATAL_ERROR: {
                break;
            }
        }
    }

Where sendLocalMessages() delegates to:

        client
                .getChannels()
                .getChannel(
                        localChatMessage.getChatChannel().getSid(),
                        new CallbackListener<Channel>() {
                            @Override
                            public void onSuccess(Channel channel) {
                                Log.d(TAG, "onSuccess() called with: channel = [" + channel + "]");
                                sendMessage(channel, localChatMessage);
                            }

                            @Override
                            public void onError(ErrorInfo errorInfo) {
                                super.onError(errorInfo);
                                Log.d(TAG, "onError() called with: errorInfo = [" + errorInfo + "]");
                            }
                        }
                );

Where sendMessage(channel, localChatMessage) delegates to:

        messages
                .sendMessage(
                        Message
                                .options()
                                .withBody(body)
                                .withAttributes(jsonObject),
                        new CallbackListener<Message>() {
                            @Override
                            public void onSuccess(Message message) {
                                Log.d(TAG, "onSuccess() called with: message = [" + message + "]");
                            }

                            @Override
                            public void onError(ErrorInfo errorInfo) {
                                super.onError(errorInfo);
                                Log.d(TAG, "onError() called with: errorInfo = [" + errorInfo + "]");
                            }
                        }
                );

Actual Behavior

No current & further messages are sent

Reproduces how Often

No stable reproduction, fails in half of attempts to send message after reconnect

Logs

On send attempt:

03-26 10:51:59.693 16429-16429/com.example.application D/TWC: IPM:       486116788648 | 03/26/10:51:59.693 | DEBUG    | IPM | client [api] get channels
03-26 10:51:59.693 16429-16429/com.example.application D/TWC: EntityCache:       486116788648 | 03/26/10:51:59.693 | DEBUG    | EntityCache | Returning Java object from cache
03-26 10:51:59.693 16429-16429/com.example.application D/TWC: IPM:       486116788648 | 03/26/10:51:59.693 | DEBUG    | IPM | channels: [api] get channel CH26ff3d13a90d44b1aadae35d1f2a4169
          486116788648 | 03/26/10:51:59.693 | DEBUG    | IPM | [zvW18] got channel from cache CH26ff3d13a90d44b1aadae35d1f2a4169
          486116788648 | 03/26/10:51:59.693 | DEBUG    | IPM | channels: got from cache CH26ff3d13a90d44b1aadae35d1f2a4169
03-26 10:51:59.693 16429-16429/com.example.application D/TWC: EntityCache:       486116788648 | 03/26/10:51:59.693 | DEBUG    | EntityCache | Returning Java object from cache
03-26 10:51:59.693 16429-16429/com.example.application D/TWC: IPM:       486116788648 | 03/26/10:51:59.693 | DEBUG    | IPM | client [api] get channels
03-26 10:51:59.693 16429-16429/com.example.application D/TWC: EntityCache:       486116788648 | 03/26/10:51:59.693 | DEBUG    | EntityCache | Returning Java object from cache
03-26 10:51:59.694 16429-16429/com.example.application D/TWC: IPM:       486116788648 | 03/26/10:51:59.694 | DEBUG    | IPM | channels: [api] get channel CH26ff3d13a90d44b1aadae35d1f2a4169
          486116788648 | 03/26/10:51:59.694 | DEBUG    | IPM | [zvW18] got channel from cache CH26ff3d13a90d44b1aadae35d1f2a4169
          486116788648 | 03/26/10:51:59.694 | DEBUG    | IPM | channels: got from cache CH26ff3d13a90d44b1aadae35d1f2a4169
03-26 10:51:59.694 16429-16429/com.example.application D/TWC: EntityCache:       486116788648 | 03/26/10:51:59.694 | DEBUG    | EntityCache | Returning Java object from cache
03-26 10:51:59.694 16429-16429/com.example.application D/TWC: Channel(native):       486116788648 | 03/26/10:51:59.694 | DEBUG    | Channel(native) | getMessages for channel sid|CH26ff3d13a90d44b1aadae35d1f2a4169|
03-26 10:51:59.695 16429-16429/com.example.application D/TWC: IPM:       486116788648 | 03/26/10:51:59.695 | DEBUG    | IPM | [zvW18] channel: [api] get messages
03-26 10:51:59.695 16429-16429/com.example.application D/TWC: EntityCache:       486116788648 | 03/26/10:51:59.695 | DEBUG    | EntityCache | Returning Java object from cache
03-26 10:51:59.695 16429-16429/com.example.application D/TWC: IPM:       486116788648 | 03/26/10:51:59.695 | DEBUG    | IPM | [zvW18] messages: [api] getLastMessages, count 1
          486116788648 | 03/26/10:51:59.695 | DEBUG    | IPM | [215] querying last 1 items from ES70476ecf8d17466abd97cca4cf72a555
          486116788648 | 03/26/10:51:59.695 | DEBUG    | IPM | [215] initiating pagination for ES70476ecf8d17466abd97cca4cf72a555
03-26 10:51:59.695 16429-16603/com.example.application D/TWC: IPM:       483337577712 | 03/26/10:51:59.695 | DEBUG    | IPM | [215] query: got page for ES70476ecf8d17466abd97cca4cf72a555
          483337577712 | 03/26/10:51:59.695 | DEBUG    | IPM | [215] query done ES70476ecf8d17466abd97cca4cf72a555
          483337577712 | 03/26/10:51:59.695 | DEBUG    | IPM | [zvW18] messages: query done, results count 1
          483337577712 | 03/26/10:51:59.695 | DEBUG    | IPM | [zvW18] messages: got query range 173:173
03-26 10:51:59.696 16429-16429/com.example.application D/TWC: Channel(native):       486116788648 | 03/26/10:51:59.696 | DEBUG    | Channel(native) | getMessages for channel sid|CH26ff3d13a90d44b1aadae35d1f2a4169|
03-26 10:51:59.696 16429-16429/com.example.application D/TWC: IPM:       486116788648 | 03/26/10:51:59.696 | DEBUG    | IPM | [zvW18] channel: [api] get messages
03-26 10:51:59.696 16429-16429/com.example.application D/TWC: EntityCache:       486116788648 | 03/26/10:51:59.696 | DEBUG    | EntityCache | Returning Java object from cache
          486116788648 | 03/26/10:51:59.696 | DEBUG    | EntityCache | Returning Java object from cache
03-26 10:51:59.697 16429-16429/com.example.application D/TWC: IPM:       486116788648 | 03/26/10:51:59.697 | DEBUG    | IPM | [zvW18] messages: [api] send
          486116788648 | 03/26/10:51:59.697 | DEBUG    | IPM | [90482040-30ca-11e8-89ef-000000000000] commands: sending sendMessage
03-26 10:51:59.698 16429-19076/com.example.application D/TWC: IPM:       483353687280 | 03/26/10:51:59.698 | DEBUG    | IPM | [zvW18] messages: [api] setLastConsumedMessageIndex, index 173
          483353687280 | 03/26/10:51:59.698 | DEBUG    | IPM | [zvW18] channel: set horizon index internally 173
          483353687280 | 03/26/10:51:59.698 | DEBUG    | IPM | consumption: adding CH26ff3d13a90d44b1aadae35d1f2a4169/173
          483353687280 | 03/26/10:51:59.698 | DEBUG    | IPM | [90484e44-30ca-11e8-a44c-000000000000] commands: sending consumptionReportV2

Chat Android SDK

2.0.8

Android API

27

Android Device

Nexus 5X Pixel XL

Do you have any ideas of such behavior happening? Thank you!

[berkus]

Hi, this issue should be fixed in the next release which should be available soon.

I'll keep it open until we actually release the new version so you will get an update.

[berkus]

Please check with 2.0.11 and report if you still have the same issue.

[InI4]

2.0.11? I missed 2.0.9 and 2.0.10.

[berkus]

There wasn't neither .9 nor .10

[cac-penchan]

Hello, we have the same issue at 2.0.8, so we update the Twilio to 2.0.11. And this issue still can be reproduced in 2.0.11.

In previous version, Twilio client can receive new messages even if it cannot send message. Now with 2.0.11, when Twilio client failed to send message, it will also fail to receive new message.

Any suggestions for this issue? Thanks for your help.

[berkus]

@cac-penchan yeah, suggestion 1: please provide logs. See here for instructions.

[cac-penchan]

@berkus We just open the debug log and reproduce this issue.

Reproduce step:

1. Open the client.
2. Idle for few hours
3. Try to send the message to channel

Code

private void sendMessage(final String text) {
        if (mChannel == null) {
            Utils.log(TAG, "sendMessage: mChannel is empty");
            return;
        }

        if (isSendMessage) {
            Utils.log(TAG, "sendMessage: Block multiple sending message");
            return;
        }

        isSendMessage = true;

        final Messages messagesObject = mChannel.getMessages();
        messagesObject.sendMessage(Message.options().withBody(text), new CallbackListener<Message>() {
            @Override
            public void onSuccess(Message message) {
                mAdapter.notifyDataSetChanged();
                if (mMessages != null) {
                    mMessages.advanceLastConsumedMessageIndex(message.getMessageIndex());
                }
                mInputEdit.setText("");
                isSendMessage = false;
            }

            @Override
            public void onError(ErrorInfo errorInfo) {
                Utils.log(TAG,"Error sending message: " + errorInfo.toString());
                isSendMessage = false;
            }
        });
    }

Chat adk

2.0.11

Android API

26

Test Device

Android 8.1.0 Google Pixel XL

my_error_log.txt occur time: 05-30 14:57:08.324

[berkus]

Thanks, checking!

[berkus]

05-30 14:56:56.456  2971  2971 W System.err: org.json.JSONException: End of input at character 0 of 
05-30 14:56:56.456  2971  2971 W System.err:    at org.json.JSONTokener.syntaxError(JSONTokener.java:449)
05-30 14:56:56.456  2971  2971 W System.err:    at org.json.JSONTokener.nextValue(JSONTokener.java:97)
05-30 14:56:56.456  2971  2971 W System.err:    at org.json.JSONObject.<init>(JSONObject.java:159)
05-30 14:56:56.456  2971  2971 W System.err:    at org.json.JSONObject.<init>(JSONObject.java:176)
05-30 14:56:56.456  2971  2971 W System.err:    at com.twilio.chat.Message.getAttributes(Message.java:346)
05-30 14:56:56.456  2971  2971 W System.err:    at tw.com.m104.connect.adapter.ChannelListAdapter.parseChannelMessage(ChannelListAdapter.java:200)

I see a number of attribute parsing exceptions which you don't handle. I also see an NPE accessing ChatClient, but no logs before that so it's hard to see if this is the reason.

[berkus]

Comments re: the code (could be unrelated to the actual issue)

        final Messages messagesObject = mChannel.getMessages();
        messagesObject.sendMessage(Message.options().withBody(text), new CallbackListener<Message>() {
            @Override
            public void onSuccess(Message message) {
                mAdapter.notifyDataSetChanged();
                if (mMessages != null) {
                    mMessages.advanceLastConsumedMessageIndex(message.getMessageIndex());
                }

Is mMessages the same as messagesObject here? I would probably advanceLastConsumedMessageIndex before calling notifyDataSetChanged.

[cac-penchan]

For the JSONException, Our App use the attribute to recognize between system and user message. But sometimes the attribute might be empty and I have no method like hasAttribute to check the getAttribute() method. Is there any way to check the status of getAttribute?

And for the second part. Yes, the mMessage and messageObject is the same. And i will modify the order of advanceLastConsumedMessageIndex and notifyDataSetChanged().

[berkus]

Is there any way to check the status of getAttribute?

As specified by the interface, getAttribute may throw a JSONException, you could catch it.

[berkus]

Just an empty attribute shall actually properly parse as an empty JSONObject, so it looks like the attributes assigned to the message are invalid (improperly formatted or otherwise not a valid JSON).

[smelfungus]

@berkus talking about the original issue seems like there are no more reports about reproducing, thank you.

[cac-penchan]

@berkus We have make some test for this case, the same apk with different devices, and noticed that Android 8.0+ devices is more easier to reproduce this issue. We just prepare 5 different devices and launch our application all night. Two of the Device (Pixel XL), could send message to others but still received new message.

[cac-penchan]

Hi, @berkus We have got another log. We reproduce this issue while waking our device form about one hour idle. And we found some warning message form Twilio Client

06-04 14:32:31.098 28512-28599/? W/TWC: IPM:       500634535152 | 06/04/14:32:31.098 | WARNING  | IPM | error sending typing indicator, cancelled
06-04 14:32:41.497 28512-28597/? W/TWC: IPM:       500638414064 | 06/04/14:32:41.497 | WARNING  | IPM | error sending typing indicator, cancelled
06-04 14:32:59.262 28512-28696/? W/TWC: TNRegTransport:       500564174064 | 06/04/14:32:59.262 | WARNING  | 51     | TNRegTransport | Receive wrong answer: 422 - 
06-04 14:32:59.264 28512-28696/? W/TWC: TNRegTransport:       500564174064 | 06/04/14:32:59.264 | WARNING  | 51     | TNRegTransport | Notification exception during registration update: TNException: Couldn't update registration

Hope this information can help for this issue.

full error log my_error_log.txt

[berkus]

Thanks, investigating.

[berkus]

Question: how to you update the token?

Also, the log you have attached is not the same that you have pasted in the ticket: attached log does not contain any Chat SDK log lines.

[cac-penchan]

Hi, @berkus For Qusetion 1: Which token do you mean? We updated Twilio Token by AccessManager.TokenUpdateListener following by Chat Demo sample code

@Override
    public void onTokenWillExpire(AccessManager accessManager) {
        new GetAccessTokenAsyncTask().execute(username, urlString);
    }

    @Override
    public void onTokenExpired(AccessManager accessManager) {
        new GetAccessTokenAsyncTask().execute(username, urlString);
    }

    // AccessManager.TokenUpdateListener
    @Override
    public void onTokenUpdated(String token) {
        if (chatClient == null) {
            return;
        }
        chatClient.updateToken(token, new ToastStatusListener(
            "Twillo Client Update Token was successfull",
            "Twillo Client Update Token failed"));
    }

We also updated FCMToken while FCMToken is modified . And FCM Token is updated by registerFCMToken method. In our case, We can receive new message but no response while sending message. Is there any comment about this situation?

For the log, my_error_log.txt is dumped by logcat which followed by here And the warning message is clip form my Android Studio logcat. I will try to reproduce this issue again for another log.

[berkus]

In our case, We can receive new message but no response while sending message. Is there any comment about this situation?

So, the message is actually sent (you receive it on the other side) but no success callback, OR the message fails to send (you don't receive it on the other side) and you don't get any failure callback, OR the message fails to send (you don't receive it on the other side) and you get the error callback telling you about the sending error?

[cac-penchan]

It's the 2nd case, the message fails to send (you don't receive it on the other side) and you don't get any failure callback. In the same time, I think Twilio Client still keep alive, because our activity can receive messages form other user in the same chat room.

[berkus]

I'd be very interested in the full unabridged unedited adb log from that run, if it's reproducible for you.

[cac-penchan]

Hi @berkus We got the new log for this issue DDMS_logcat_Nexus6_7.1.1.txt

Reproduce:

1. Keep MessageActivity in idle.
2. The state of ChatClient become DENIED. (See log in 2018-06-15 11:08:14.866 )
3. Reconnect ChatClient and state become CONNECTED. (See log in 2018-06-15 11:09:27.696)
4. ChatClient can received message. But there is not any callback if user send a new message

[berkus]

Thanks, this is valuable!

Do you get DENIED because of expired token?

[berkus]

I see at least one problem with the tokens you use: it contains "endpoint_id" which it shouldn't have.

[cac-penchan]

2018-06-15 11:08:14.862 30915-31146/tw.com.m104.connect W/TWC: TNTwilsockClient:        -2135095008 | 06/15/11:08:14.862 | WARNING  | 1      | TNTwilsockClient | Reply status for init request is not success: 401, AUTHENTICATION_FAILED
2018-06-15 11:08:14.864 30915-31223/tw.com.m104.connect W/TWC: TNNotificationClient:        -2118125280 | 06/15/11:08:14.864 | WARNING  | 12     | TNNotificationClient | onTwilsockFatalError: 14 - AUTHENTICATION_FAILED
2018-06-15 11:08:14.866 30915-30915/tw.com.m104.connect E/Chat: onConnectionStateChange: DENIED

By the Debug message form Client. Token might be expired. But before this issue occured. I have monitered that Token had be updated for several times. TokenUpdateListener will remind ChatClient to get and update token if token is expired.

[berkus]

Hi, please try 4.0.0-rc11 and send your feedback.

This should be more robust to reconnect, although there's a known issue with expired token update.

[cac-penchan]

@berkus I have tested the 4.0.0-rc11, and it can work perfect!! Thank for your support.

[berkus]

Hey, great, grab rc12 while you're at it as it has updateToken() issue fixed.

I'm gonna close this one then, cheers!

[InI4]

This looks quite a bit like a problem I have seen. Is there any chance, to get such fixes in the Twilio 3 branch? I am trapped by Android SDK requirements and cannot go to 4.x ...

[berkus]

What is blocking you @InI4 ? 4.x should work on api as low as 18 afaik, do you need even lower?

[InI4]

So far we still wan't to support 17. Seems to still have an 2 digit market share.

[berkus]

Ok, unfortunately this is not possible today, but we are working towards enabling this.